Bug #49119 Master crashes when executing 'REVOKE ... ON {PROCEDURE|FUNCTION} FROM ...'
Submitted: 26 Nov 2009 4:18 Modified: 12 Mar 2010 16:44
Reporter: Libing Song Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.1+, 5.1.42-bzr OS:Any
Assigned to: Luis Soares
Tags: regression
Triage: Triaged: D1 (Critical)

[26 Nov 2009 4:18] Libing Song
Description:
Slave is crashed when replicating "REVOKE ... ON {PROCEDURE|FUNCTION} FROM 'user1'@'localhost'", if "GRANT ... ON {PROCEDURE|FUNCTION} TO 'user1'@'localhost'" is not executed before it.

How to repeat:
source include/master-slave.inc;

CREATE TABLE t1(c1 INT);
DELIMITER |;
CREATE PROCEDURE p1() SELECT * FROM t1 |
DELIMITER ;|
REVOKE EXECUTE ON PROCEDURE p1 FROM 'root'@'localhost';

source include/master-slave-end.inc;
[26 Nov 2009 7:15] Valerii Kravchuk
Verified just as described with recent 5.1.42 from bzr on Linux:

openxs@suse:/home2/openxs/dbs/5.1/mysql-test> ./mysql-test-run.pl --suite=rpl bug49119
Logging: ./mysql-test-run.pl  --suite=rpl bug49119
100303 14:08:39 [Note] Plugin 'FEDERATED' is disabled.
100303 14:08:39 [Note] Plugin 'ndbcluster' is disabled.
MySQL Version 5.1.42
Checking supported features...
 - using ndbcluster when necessary, mysqld supports it
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
 - adding combinations for rpl
vardir: /home2/openxs/dbs/5.1/mysql-test/var
Checking leftover processes...
 - found old pid 6946 in 'mysqld.1.pid', killing it...
   process did not exist!
Removing old var directory...
Creating var directory '/home2/openxs/dbs/5.1/mysql-test/var'...
Installing system database...
Using server port 32769

==============================================================================

TEST                                      RESULT   TIME (ms)
------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
stop slave;
drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
reset master;
reset slave;
drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
start slave;
CREATE TABLE t1(c1 INT);
CREATE PROCEDURE p1() SELECT * FROM t1 |
rpl.bug49119 'row'                       [ fail ]
        Test ended at 2010-03-03 14:08:49

CURRENT_TEST: rpl.bug49119
mysqltest: At line 7: query 'REVOKE EXECUTE ON PROCEDURE p1 FROM 'root'@'localhost'' failed: 2013: Lost connection to MySQL server during query

Server [mysqld.1 - pid: 6627, winpid: 6627, exit: 256] failed during test run
Server log from this test:
100303 15:08:47 [Note] Plugin 'FEDERATED' is disabled.
100303 15:08:47 [Note] Plugin 'InnoDB' is disabled.
100303 15:08:47 [Note] Plugin 'ndbcluster' is disabled.
100303 15:08:47 [Note] Event Scheduler: Loaded 0 events
100303 15:08:47 [Note] /home2/openxs/dbs/5.1/libexec/mysqld: ready for connections.
Version: '5.1.42-debug-log'  socket: '/home2/openxs/dbs/5.1/mysql-test/var/tmp/mysqld.1.sock'  port: 13000  Source distribution
mysqld: protocol.cc:465: void net_end_statement(THD*): Assertion `0' failed.
100303 15:08:49 - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=4
max_threads=151
threads_connected=4
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 59976 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x8aa0680
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x4056b430 thread_stack 0x30000
/home2/openxs/dbs/5.1/libexec/mysqld(my_print_stacktrace+0x29)[0x86df72c]
/home2/openxs/dbs/5.1/libexec/mysqld(handle_segfault+0x253)[0x82929df]
[0xffffe420]
/lib/tls/libc.so.6(abort+0x1a5)[0x400e6b75]
/lib/tls/libc.so.6(__assert_fail+0x103)[0x400de903]
/home2/openxs/dbs/5.1/libexec/mysqld(_Z17net_end_statementP3THD+0x1a9)[0x828747f]
/home2/openxs/dbs/5.1/libexec/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1890)[0x82a272c]
/home2/openxs/dbs/5.1/libexec/mysqld(_Z10do_commandP3THD+0x260)[0x82a0b62]
/home2/openxs/dbs/5.1/libexec/mysqld(handle_one_connection+0x14e)[0x829ef98]
/lib/tls/libpthread.so.0[0x40031aa7]
/lib/tls/libc.so.6(__clone+0x5e)[0x40177c2e]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x8aa2058 = REVOKE EXECUTE ON PROCEDURE p1 FROM 'root'@'localhost'
thd->thread_id=3
thd->killed=NOT_KILLED
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file

...
[26 Nov 2009 7:19] Valerii Kravchuk
5.0.88 does NOT crash, so this is a regression bug:

openxs@suse:/home2/openxs/dbs/5.0/mysql-test> ./mysql-test-run.pl rpl_bug49119
Logging: ./mysql-test-run.pl rpl_bug49119
MySQL Version 5.0.88
Using ndbcluster when necessary, mysqld supports it
Setting mysqld to support SSL connections
Binaries are debug compiled
mysql-test-run: WARNING: Could not find all required ndb binaries, all ndb tests will fail, use --skip-ndbcluster to skip testing it.
Using MTR_BUILD_THREAD      = 0
Using MASTER_MYPORT         = 9306
Using MASTER_MYPORT1        = 9307
Using SLAVE_MYPORT          = 9308
Using SLAVE_MYPORT1         = 9309
Using SLAVE_MYPORT2         = 9310
Using NDBCLUSTER_PORT       = 9311
Using IM_PORT               = 9313
Using IM_MYSQLD1_PORT       = 9314
Using IM_MYSQLD2_PORT       = 9315
Killing Possible Leftover Processes
Removing Stale Files
Creating Directories
Installing Master Database
Installing Slave1 Database
=======================================================
Starting Tests in the 'main' suite

TEST                           RESULT         TIME (ms)
-------------------------------------------------------

rpl_bug49119                   [ fail ]

mysqltest: At line 7: query 'REVOKE EXECUTE ON PROCEDURE p1 FROM 'root'@'localhost'' failed: 1403: There is no such grant defined for user 'root' on host 'localhost' on routine 'p1'

The result from queries just before the failure was:
stop slave;
drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
reset master;
reset slave;
drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
start slave;
CREATE TABLE t1(c1 INT);
CREATE PROCEDURE p1() SELECT * FROM t1 |
REVOKE EXECUTE ON PROCEDURE p1 FROM 'root'@'localhost';
[29 Nov 2009 23:28] Luis Soares
This does not seem to have anything related to the slave at
all... Instead, this looks like it is an issue with the master
when binlogging is active. Please, check the analysis below.

The revoke operation is mostly handled in mysql_routine_grant
function. Furthermore, this bug reports a scenario in which a
revoke operation is requested, but the actual grant does not
exist at that time. This should cause the command to fail with
error 1403. 

However, when the binlog is active, the master will not
return (an error in our scenario) from mysql_routine_grant
without first checking if it should write to the binlog.

Now... At this point, it will cause the statement to be written
to the binlog by calling write_bin_log wrapper function, with its
second parameter set to TRUE. This parameter value, causes
write_bin_log to clear the thread's diagnostics area (meaning
that the earlier revoke error, pushed in mysql_routine_grant, is
removed).

At the time binlogging is done, mysql_routine_grant will
resume and return an error, which contradicts write_bin_log
actions (the ones that cleared the diagnostics area).

So... the result from this is that my_ok will not be called and
neither the error will be signaled in the diagnostics
area. Consequently, this will cause net_end_statement to trigger
the assertion.

You can check this with the following test case that does not
require a slave (just an active binary log):

=== TEST CASE:

-- source include/have_log_bin.inc

CREATE TABLE t1(c1 INT);
DELIMITER |;
CREATE PROCEDURE p1() SELECT * FROM t1 |
DELIMITER ;|

REVOKE EXECUTE ON PROCEDURE p1 FROM 'user49119'@'localhost', 'root'@'localhost';

-- exit
[29 Nov 2009 23:45] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/92015

3211 Luis Soares	2009-11-29
      BUG#49119: Slave is crashed when replicating 'REVOKE ... ON
      {PROCEDURE|FUNCTION} FROM ...'
      
      The master would hit an assertion when binary loggging was
      active. This was due to the fact that the thread's diagnostics
      area was being cleared before writing to the binlog,
      independently of mysql_routine_grant returning an error or
      not. When mysql_routine_grant was to return an error, the return
      value and the diagnostics area contents would
      mismatch. Consequently, neither my_ok would be called nor an
      error would be signaled in the diagnostics area, eventually
      triggering the assertion in net_end_statement.
      
      We fix this by not clearing the diagnostics area at binlogging
      time.
[2 Dec 2009 13:24] Libing Song
Luis,
You are right, It is a crash on master, not on slave.
[4 Dec 2009 13:39] Andrei Elkin
There should be no error code disabling in the REVOKE query log event.
The patch corrects that piece of code.
Approved.
[6 Dec 2009 22:44] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/93005

3211 Luis Soares	2009-12-06
      BUG#49119: Slave is crashed when replicating 'REVOKE ... ON
      {PROCEDURE|FUNCTION} FROM ...'
      
      The master would hit an assertion when binary log was
      active. This was due to the fact that the thread's diagnostics
      area was being cleared before writing to the binlog,
      independently of mysql_routine_grant returning an error or
      not. When mysql_routine_grant was to return an error, the return
      value and the diagnostics area contents would
      mismatch. Consequently, neither my_ok would be called nor an
      error would be signaled in the diagnostics area, eventually
      triggering the assertion in net_end_statement.
      
      We fix this by not clearing the diagnostics area at binlogging
      time.
[6 Dec 2009 22:47] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/93006

3211 Luis Soares	2009-12-06
      BUG#49119: Master crashes when executing 'REVOKE ... ON 
      {PROCEDURE|FUNCTION} FROM ...'
      
      The master would hit an assertion when binary log was
      active. This was due to the fact that the thread's diagnostics
      area was being cleared before writing to the binlog,
      independently of mysql_routine_grant returning an error or
      not. When mysql_routine_grant was to return an error, the return
      value and the diagnostics area contents would
      mismatch. Consequently, neither my_ok would be called nor an
      error would be signaled in the diagnostics area, eventually
      triggering the assertion in net_end_statement.
      
      We fix this by not clearing the diagnostics area at binlogging
      time.
[6 Dec 2009 23:22] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/93010

3211 Luis Soares	2009-12-06
      BUG#49119: Master crashes when executing 'REVOKE ... ON 
      {PROCEDURE|FUNCTION} FROM ...'
      
      The master would hit an assertion when binary log was
      active. This was due to the fact that the thread's diagnostics
      area was being cleared before writing to the binlog,
      independently of mysql_routine_grant returning an error or
      not. When mysql_routine_grant was to return an error, the return
      value and the diagnostics area contents would
      mismatch. Consequently, neither my_ok would be called nor an
      error would be signaled in the diagnostics area, eventually
      triggering the assertion in net_end_statement.
      
      We fix this by not clearing the diagnostics area at binlogging
      time.
[19 Dec 2009 8:28] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20091219082307-f3i4fn0tm8trb3c0) (version source revid:alik@sun.com-20091216180721-eoa754i79j4ssd3m) (merge vers: 6.0.14-alpha) (pib:15)
[19 Dec 2009 8:31] Bugs System
Pushed into 5.5.1-m2 (revid:alik@sun.com-20091219082021-f34nq4jytwamozz0) (version source revid:alexey.kopytov@sun.com-20091211164058-ycpe0f20d1c4h1gl) (merge vers: 5.5.0-beta) (pib:15)
[19 Dec 2009 8:35] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20091219082213-nhjjgmphote4ntxj) (version source revid:alik@sun.com-20091216180221-a5ps59gajad3pip9) (pib:15)
[11 Jan 2010 17:34] Paul Dubois
Noted in 5.5.1, 6.0.14 changelogs.

With binary logging enabled, REVOKE ... ON {PROCEDURE|FUNCTION} FROM
... could cause a crash. 

Setting report to NDI pending push to Celosia.
[15 Jan 2010 8:59] Bugs System
Pushed into 5.1.43 (revid:joro@sun.com-20100115085139-qkh0i0fpohd9u9p5) (version source revid:luis.soares@sun.com-20091206231445-kaz01b23kjm7keyl) (merge vers: 5.1.42) (pib:16)
[15 Jan 2010 18:46] Paul Dubois
Noted in 5.1.43 changelog.

Setting report to NDI pending push to Celosia.
[12 Mar 2010 14:11] Bugs System
Pushed into 5.1.44-ndb-7.0.14 (revid:jonas@mysql.com-20100312135944-t0z8s1da2orvl66x) (version source revid:jonas@mysql.com-20100312115609-woou0te4a6s4ae9y) (merge vers: 5.1.44-ndb-7.0.14) (pib:16)
[12 Mar 2010 14:28] Bugs System
Pushed into 5.1.44-ndb-6.2.19 (revid:jonas@mysql.com-20100312134846-tuqhd9w3tv4xgl3d) (version source revid:jonas@mysql.com-20100312060623-mx6407w2vx76h3by) (merge vers: 5.1.44-ndb-6.2.19) (pib:16)
[12 Mar 2010 14:43] Bugs System
Pushed into 5.1.44-ndb-6.3.33 (revid:jonas@mysql.com-20100312135724-xcw8vw2lu3mijrhn) (version source revid:jonas@mysql.com-20100312103652-snkltsd197l7q2yg) (merge vers: 5.1.44-ndb-6.3.33) (pib:16)
[12 Mar 2010 16:44] Paul Dubois
Fixed in earlier 5.1.x, 5.5.x.