MySQL Bugs: #55909: ndb_binlog_index missing entry on normal mysqld shutdown

Bug #55909	ndb_binlog_index missing entry on normal mysqld shutdown
Submitted:	11 Aug 2010 11:01	Modified:	29 Sep 2010 11:50
Reporter:	Geert Vanderkelen	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Cluster: Replication	Severity:	S3 (Non-critical)
Version:	mysql-5.1-telco-7.1	OS:	Any
Assigned to:	Martin Skold	CPU Architecture:	Any

Description:
When you normally shutdown mysqld while still updating data, it is possible that the entry binary log information of the last Epoch is not saved into mysql.ndb_binlog_index.

This means for example that Epoch 34492882354189 is logged to the binary log (extract using mysqlbinlog):
..
### INSERT INTO mysql.ndb_apply_status
### SET
###   @1=100 /* INT meta=0 nullable=0 is_null=0 */
###   @2=34492882354189 /* LONGINT meta=0 nullable=0 is_null=0 */

But it is not in the mysql.ndb_binlog_index.

How to repeat:
With a very basic cluster setup, with one data node:

1) Create a simple table:

CREATE TABLE `t1` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `c1` varchar(30) DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=ndbcluster;

2) Insert an entry:

INSERT INTO t1 (id,c1) VALUES (1,NOW());

3) Keep updating this entry to generate traffic, for example using a shell script:

while(true);
do
  mysql -e "UPDATE t1 SET c1 = NOW() WHERE id = 1";
done

4) After a moment, like 10 seconds maybe, simply shutdown the mysqld:

mysqladmin -uroot shutdown

5) Check the entries in the binary logs whether they match with mysql.ndb_binlog_index. Here a quick-hack, shell script to do so. (Yes, one can make it beautiful..)

BINLOG=$1
EPOCHS=`mysqlbinlog --base64-output=decode-rows -vv $BINLOG | grep -A 4 'INSERT INTO mysql.ndb_apply_status' | grep '@2' | awk '{ print $2}' | awk 'BEGIN { FS="=" } { print $2 }'`

for epoch in $EPOCHS;
do
    query="SELECT IF(cnt=0,concat('Epoch $epoch (',hex($epoch),') not found'),'') FROM (SELECT COUNT(*) as cnt FROM mysql.ndb_binlog_index WHERE epoch = $epoch) as binidx"
    mysql -S /opt/mysql/clusters/machA/mysql.sock -e "$query" -NB ; 
done | grep 'not found'

Suggested fix:
When shutting down, make sure that whatever is written to the binary logs is also going to the mysql.ndb_binlog_index tables.

Verified using MySQL Cluster 7.1.4, but initially reported using mysql-5.1.44-ndb-7.0.15b

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/118055

3287 Martin Skold	2010-09-13
      Bug#55909 ndb_binlog_index missing entry on normal mysqld shutdown: Added retry during shutdown
      modified:
        sql/ha_ndbcluster_binlog.cc

Pushed into mysql-5.1-telco-6.3 5.1.47-ndb-6.3.38 (revid:martin.skold@mysql.com-20100929105548-j8x7u49eekoubjr3) (version source revid:martin.skold@mysql.com-20100913080611-tnxz9gt7x4439kon) (merge vers: 5.1.47-ndb-6.3.38) (pib:21)

Pushed into mysql-5.1-telco-7.0 5.1.47-ndb-7.0.19 (revid:jonas@mysql.com-20100929110155-3wxtc3jl2ua7mv3p) (version source revid:jonas@mysql.com-20100929110155-3wxtc3jl2ua7mv3p) (merge vers: 5.1.47-ndb-7.0.19) (pib:21)

Documented in the NDB-6.3.38, 7.0.19, and 7.1.8 changelogs, as follows:

        When a mysqld process was shut down while still performing
        updates, it was possible for the entry containing binary log
        information for the last epoch not to be written into the
        mysql.ndb_binlog_index table. This could occur even during a
        normal shutdown.

Closed.