#At file:///home/frazer/bzr/mysql-5.1-telco-6.2/
3007 Frazer Clement 2009-09-28
Bug#47323 : mysqlbinlog --verbose displays bad output when events contain subset of columns
added:
mysql-test/suite/binlog/r/binlog_row_mysqlbinlog_verbose.result
mysql-test/suite/binlog/std_data/update-full-row.binlog
mysql-test/suite/binlog/std_data/update-partial-row.binlog
mysql-test/suite/binlog/std_data/write-full-row.binlog
mysql-test/suite/binlog/std_data/write-partial-row.binlog
mysql-test/suite/binlog/t/binlog_row_mysqlbinlog_verbose.test
mysql-test/suite/ndb_binlog/r/ndb_binlog_variants.result
mysql-test/suite/ndb_binlog/t/ndb_binlog_get_binlog_stmts.inc
mysql-test/suite/ndb_binlog/t/ndb_binlog_variants.cnf
mysql-test/suite/ndb_binlog/t/ndb_binlog_variants.test
modified:
sql/log_event.cc
=== added file 'mysql-test/suite/binlog/r/binlog_row_mysqlbinlog_verbose.result'
--- a/mysql-test/suite/binlog/r/binlog_row_mysqlbinlog_verbose.result 1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/binlog/r/binlog_row_mysqlbinlog_verbose.result 2009-09-28 10:09:38 +0000
@@ -0,0 +1,161 @@
+Verbose statements from : write-partial-row.binlog
+select txt from raw_binlog_rows where txt like '###%';
+txt
+### INSERT INTO mysql.ndb_apply_status
+### SET
+### @1=1
+### @2=25769803786
+### @3=''
+### @4=0
+### @5=0
+### INSERT INTO test.ba
+### SET
+### @1=3
+### @2=3
+### @3=3
+### INSERT INTO test.ba
+### SET
+### @1=1
+### @2=1
+### @3=1
+### INSERT INTO test.ba
+### SET
+### @1=2
+### @2=2
+### @3=2
+### INSERT INTO test.ba
+### SET
+### @1=4
+### @2=4
+### @3=4
+### INSERT INTO test.ba
+### SET
+### @1=4
+### @3=40
+### DELETE FROM test.ba
+### WHERE
+### @1=2
+drop table raw_binlog_rows;
+Verbose statements from : write-full-row.binlog
+select txt from raw_binlog_rows where txt like '###%';
+txt
+### INSERT INTO mysql.ndb_apply_status
+### SET
+### @1=2
+### @2=25769803786
+### @3=''
+### @4=0
+### @5=0
+### INSERT INTO test.ba
+### SET
+### @1=3
+### @2=3
+### @3=3
+### INSERT INTO test.ba
+### SET
+### @1=1
+### @2=1
+### @3=1
+### INSERT INTO test.ba
+### SET
+### @1=2
+### @2=2
+### @3=2
+### INSERT INTO test.ba
+### SET
+### @1=4
+### @2=4
+### @3=4
+### INSERT INTO test.ba
+### SET
+### @1=4
+### @2=4
+### @3=40
+### DELETE FROM test.ba
+### WHERE
+### @1=2
+drop table raw_binlog_rows;
+Verbose statements from : update-partial-row.binlog
+select txt from raw_binlog_rows where txt like '###%';
+txt
+### INSERT INTO mysql.ndb_apply_status
+### SET
+### @1=3
+### @2=25769803786
+### @3=''
+### @4=0
+### @5=0
+### INSERT INTO test.ba
+### SET
+### @1=3
+### @2=3
+### @3=3
+### INSERT INTO test.ba
+### SET
+### @1=1
+### @2=1
+### @3=1
+### INSERT INTO test.ba
+### SET
+### @1=2
+### @2=2
+### @3=2
+### INSERT INTO test.ba
+### SET
+### @1=4
+### @2=4
+### @3=4
+### UPDATE test.ba
+### WHERE
+### @1=4
+### @3=4
+### SET
+### @1=4
+### @3=40
+### DELETE FROM test.ba
+### WHERE
+### @1=2
+drop table raw_binlog_rows;
+Verbose statements from : update-full-row.binlog
+select txt from raw_binlog_rows where txt like '###%';
+txt
+### INSERT INTO mysql.ndb_apply_status
+### SET
+### @1=4
+### @2=25769803786
+### @3=''
+### @4=0
+### @5=0
+### INSERT INTO test.ba
+### SET
+### @1=3
+### @2=3
+### @3=3
+### INSERT INTO test.ba
+### SET
+### @1=1
+### @2=1
+### @3=1
+### INSERT INTO test.ba
+### SET
+### @1=2
+### @2=2
+### @3=2
+### INSERT INTO test.ba
+### SET
+### @1=4
+### @2=4
+### @3=4
+### UPDATE test.ba
+### WHERE
+### @1=4
+### @2=4
+### @3=4
+### SET
+### @1=4
+### @2=4
+### @3=40
+### DELETE FROM test.ba
+### WHERE
+### @1=2
+drop table raw_binlog_rows;
=== added file 'mysql-test/suite/binlog/std_data/update-full-row.binlog'
Binary files a/mysql-test/suite/binlog/std_data/update-full-row.binlog 1970-01-01 00:00:00 +0000 and b/mysql-test/suite/binlog/std_data/update-full-row.binlog 2009-09-28 10:09:38 +0000 differ
=== added file 'mysql-test/suite/binlog/std_data/update-partial-row.binlog'
Binary files a/mysql-test/suite/binlog/std_data/update-partial-row.binlog 1970-01-01 00:00:00 +0000 and b/mysql-test/suite/binlog/std_data/update-partial-row.binlog 2009-09-28 10:09:38 +0000 differ
=== added file 'mysql-test/suite/binlog/std_data/write-full-row.binlog'
Binary files a/mysql-test/suite/binlog/std_data/write-full-row.binlog 1970-01-01 00:00:00 +0000 and b/mysql-test/suite/binlog/std_data/write-full-row.binlog 2009-09-28 10:09:38 +0000 differ
=== added file 'mysql-test/suite/binlog/std_data/write-partial-row.binlog'
Binary files a/mysql-test/suite/binlog/std_data/write-partial-row.binlog 1970-01-01 00:00:00 +0000 and b/mysql-test/suite/binlog/std_data/write-partial-row.binlog 2009-09-28 10:09:38 +0000 differ
=== added file 'mysql-test/suite/binlog/t/binlog_row_mysqlbinlog_verbose.test'
--- a/mysql-test/suite/binlog/t/binlog_row_mysqlbinlog_verbose.test 1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/binlog/t/binlog_row_mysqlbinlog_verbose.test 2009-09-28 10:09:38 +0000
@@ -0,0 +1,82 @@
+########################################################
+# Test mysqlbinlog command with Ndb produced Binlog
+# variants
+#
+# WHAT
+# ====
+# This test aims to check that the mysqlbinlog --verbose
+# command can output binlogs in 4 format variants, currently
+# used by Ndb
+#
+# 1) Updates logged as write_row events
+# Only primary key and updated columns included in the
+# event
+# 2) Updates logged as write_row_events
+# All columns included in the event
+# 3) Updates logged as update_row events
+# Only primary key and updated columns included in the
+# event
+# 4) Updates logged as update_row events
+# All columns included in the event
+#
+# Format variant (1) is the Ndb default.
+# Bug#47323 resulted in binlogs generated in format (1)
+# being incorrectly parsed by the mysqlbinlog --verbose
+# option
+#
+# HOW
+# ===
+# Row-based binlog files in each format have been
+# captured from an Ndb cluster
+# These are output using the mysqlbinlog --verbose
+# tool and the output is checked.
+#
+########################################################
+
+# We require binlog_format_row as we're independent of binlog format
+# and there's no point running the same test 3 times
+-- source include/have_binlog_format_row.inc
+
+--disable_query_log
+--let $binlog_file=write-partial-row.binlog
+--exec $MYSQL_BINLOG --verbose suite/binlog/std_data/$binlog_file > $MYSQLTEST_VARDIR/tmp/mysqlbinlog_verbose.sql
+create table raw_binlog_rows (txt varchar(1000));
+--eval load data local infile '$MYSQLTEST_VARDIR/tmp/mysqlbinlog_verbose.sql' into table raw_binlog_rows columns terminated by '\n';
+--remove_file $MYSQLTEST_VARDIR/tmp/mysqlbinlog_verbose.sql
+--enable_query_log
+--echo Verbose statements from : $binlog_file
+select txt from raw_binlog_rows where txt like '###%';
+drop table raw_binlog_rows;
+
+--disable_query_log
+--let $binlog_file=write-full-row.binlog
+--exec $MYSQL_BINLOG --verbose suite/binlog/std_data/$binlog_file > $MYSQLTEST_VARDIR/tmp/mysqlbinlog_verbose.sql
+create table raw_binlog_rows (txt varchar(1000));
+--eval load data local infile '$MYSQLTEST_VARDIR/tmp/mysqlbinlog_verbose.sql' into table raw_binlog_rows columns terminated by '\n';
+--remove_file $MYSQLTEST_VARDIR/tmp/mysqlbinlog_verbose.sql
+--enable_query_log
+--echo Verbose statements from : $binlog_file
+select txt from raw_binlog_rows where txt like '###%';
+drop table raw_binlog_rows;
+
+--disable_query_log
+--let $binlog_file=update-partial-row.binlog
+--exec $MYSQL_BINLOG --verbose suite/binlog/std_data/$binlog_file > $MYSQLTEST_VARDIR/tmp/mysqlbinlog_verbose.sql
+create table raw_binlog_rows (txt varchar(1000));
+--eval load data local infile '$MYSQLTEST_VARDIR/tmp/mysqlbinlog_verbose.sql' into table raw_binlog_rows columns terminated by '\n';
+--remove_file $MYSQLTEST_VARDIR/tmp/mysqlbinlog_verbose.sql
+--enable_query_log
+--echo Verbose statements from : $binlog_file
+select txt from raw_binlog_rows where txt like '###%';
+drop table raw_binlog_rows;
+
+--disable_query_log
+--let $binlog_file=update-full-row.binlog
+--exec $MYSQL_BINLOG --verbose suite/binlog/std_data/$binlog_file > $MYSQLTEST_VARDIR/tmp/mysqlbinlog_verbose.sql
+create table raw_binlog_rows (txt varchar(1000));
+--eval load data local infile '$MYSQLTEST_VARDIR/tmp/mysqlbinlog_verbose.sql' into table raw_binlog_rows columns terminated by '\n';
+--remove_file $MYSQLTEST_VARDIR/tmp/mysqlbinlog_verbose.sql
+--enable_query_log
+--echo Verbose statements from : $binlog_file
+select txt from raw_binlog_rows where txt like '###%';
+drop table raw_binlog_rows;
=== added file 'mysql-test/suite/ndb_binlog/r/ndb_binlog_variants.result'
--- a/mysql-test/suite/ndb_binlog/r/ndb_binlog_variants.result 1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/ndb_binlog/r/ndb_binlog_variants.result 2009-09-28 10:09:38 +0000
@@ -0,0 +1,53 @@
+create table ba(ks int primary key, st int, lp int) engine = ndb;
+insert into ba values (1, 1, 1), (2,2,2), (3,3,3), (4,4,4);
+update ba set lp=40 where ks=4;
+delete from ba where ks=2;
+flush logs;
+show variables like '%log_update%';
+Variable_name Value
+sql_log_update ON
+select txt from binlog_stmts where txt not like '%ndb_apply_status%' order by txt;
+txt
+DELETE FROM test.ba WHERE @1=2
+INSERT INTO test.ba SET @1=1 @2=1 @3=1
+INSERT INTO test.ba SET @1=2 @2=2 @3=2
+INSERT INTO test.ba SET @1=3 @2=3 @3=3
+INSERT INTO test.ba SET @1=4 @2=4 @3=4
+INSERT INTO test.ba SET @1=4 @3=40
+flush logs;
+show variables like '%log_update%';
+Variable_name Value
+sql_log_update ON
+select txt from binlog_stmts where txt not like '%ndb_apply_status%' order by txt;
+txt
+DELETE FROM test.ba WHERE @1=2
+INSERT INTO test.ba SET @1=1 @2=1 @3=1
+INSERT INTO test.ba SET @1=2 @2=2 @3=2
+INSERT INTO test.ba SET @1=3 @2=3 @3=3
+INSERT INTO test.ba SET @1=4 @2=4 @3=4
+INSERT INTO test.ba SET @1=4 @2=4 @3=40
+flush logs;
+show variables like '%log_update%';
+Variable_name Value
+sql_log_update ON
+select txt from binlog_stmts where txt not like '%ndb_apply_status%' order by txt;
+txt
+DELETE FROM test.ba WHERE @1=2
+INSERT INTO test.ba SET @1=1 @2=1 @3=1
+INSERT INTO test.ba SET @1=2 @2=2 @3=2
+INSERT INTO test.ba SET @1=3 @2=3 @3=3
+INSERT INTO test.ba SET @1=4 @2=4 @3=4
+UPDATE test.ba WHERE @1=4 @3=4 SET @1=4 @3=40
+flush logs;
+show variables like '%log_update%';
+Variable_name Value
+sql_log_update ON
+select txt from binlog_stmts where txt not like '%ndb_apply_status%' order by txt;
+txt
+DELETE FROM test.ba WHERE @1=2
+INSERT INTO test.ba SET @1=1 @2=1 @3=1
+INSERT INTO test.ba SET @1=2 @2=2 @3=2
+INSERT INTO test.ba SET @1=3 @2=3 @3=3
+INSERT INTO test.ba SET @1=4 @2=4 @3=4
+UPDATE test.ba WHERE @1=4 @2=4 @3=4 SET @1=4 @2=4 @3=40
+drop table ba;
=== added file 'mysql-test/suite/ndb_binlog/t/ndb_binlog_get_binlog_stmts.inc'
--- a/mysql-test/suite/ndb_binlog/t/ndb_binlog_get_binlog_stmts.inc 1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/ndb_binlog/t/ndb_binlog_get_binlog_stmts.inc 2009-09-28 10:09:38 +0000
@@ -0,0 +1,89 @@
+#
+# Get the mysqlbinlog tool --verbose mode to dump the Binlog contents with
+# 'SQL' statements in triple-comments over multiple lines, e.g. :
+#
+### INSERT
+### SET
+### @1=1
+### @2=2
+#
+# Then munch this output into single-line statements
+# e.g. :
+# INSERT SET @1=1 @2=2
+#
+# Then filter + sort to get deterministic order independent of Ndb table
+# fragmentation, epoch in ndb_apply_status etc.
+#
+
+--disable_query_log
+let $MYSQLD_DATADIR= `select @@datadir;`;
+--exec $MYSQL_BINLOG --verbose $MYSQLD_DATADIR/mysqld-bin.000001 > $MYSQLTEST_VARDIR/tmp/ndb_binlog_mysqlbinlog.sql
+
+create table raw_binlog_rows (txt varchar(1000));
+
+--eval load data local infile '$MYSQLTEST_VARDIR/tmp/ndb_binlog_mysqlbinlog.sql' into table raw_binlog_rows columns terminated by '\n';
+
+create table binlog_stmt_parts_unassoc (txt varchar(1000), line_count int, stmt_boundary int);
+
+set @line_count=0;
+set @stmt_boundary=0;
+
+insert into binlog_stmt_parts_unassoc
+ select txt,
+ @line_count:= @line_count + 1, # So we can preserve order later
+ (txt like '%INSERT%' or # Identify statement boundaries
+ txt like '%UPDATE%' or
+ txt like '%DELETE%')
+ from raw_binlog_rows
+ where
+ txt like '###%'; # Discard non verbose output
+
+#select * from binlog_stmt_parts_unassoc;
+
+create table binlog_stmt_parts_assoc (txt varchar(1000), line_count int, stmt_num int);
+
+set @stmt_count = 0;
+
+insert into binlog_stmt_parts_assoc
+ select txt,
+ line_count,
+ @stmt_count:= @stmt_count + stmt_boundary # All rows from same stmt will
+ # have same stmt_num
+ from binlog_stmt_parts_unassoc order by line_count;
+
+
+#select * from binlog_stmt_parts_assoc;
+
+create table binlog_stmts (txt varchar(1000), stmt_num int);
+
+insert into binlog_stmts
+ select group_concat(right(txt, # Combine rows in statment into 1
+ length(txt) - 4) # Trim ### from line start
+ order by line_count
+ separator ' '), stmt_num
+ from binlog_stmt_parts_assoc
+ group by stmt_num;
+
+#select * from binlog_stmts;
+
+# Drop ndb_apply_status entries and sort by the statment
+# text to get a deterministic order.
+#
+# Reasonable order would be sort by (PK-cols, stmt_num)
+# - Sorting by PK-cols would give determinism between events from different
+# fragments
+# - Multiple ops on same pk would be in order of application
+#
+# However, as that's harder, and unnecessary given that we just want
+# deterministic output, not applicable SQL, we will just sort by
+# the statement text
+#
+--enable_query_log
+select txt from binlog_stmts where txt not like '%ndb_apply_status%' order by txt;
+
+--disable_query_log
+drop table raw_binlog_rows;
+drop table binlog_stmt_parts_unassoc;
+drop table binlog_stmt_parts_assoc;
+drop table binlog_stmts;
+--enable_query_log
\ No newline at end of file
=== added file 'mysql-test/suite/ndb_binlog/t/ndb_binlog_variants.cnf'
--- a/mysql-test/suite/ndb_binlog/t/ndb_binlog_variants.cnf 1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/ndb_binlog/t/ndb_binlog_variants.cnf 2009-09-28 10:09:38 +0000
@@ -0,0 +1,45 @@
+!include include/default_mysqld.cnf
+!include include/default_ndbd.cnf
+
+# Create cluster with 4 attached MySQLDs with different
+# binlog variants
+
+[cluster_config.1]
+NoOfReplicas= 2
+ndbd=,
+ndb_mgmd=
+mysqld=,,,
+ndbapi=,,,,,,,,,,,
+
+[mysqld]
+# Make all mysqlds use cluster
+ndbcluster
+ndb-wait-connected=20
+ndb-cluster-connection-pool=1
+binlog-format=row
+
+[mysqld.1.1]
+ndb-log-update-as-write=1
+ndb-log-updated-only=1
+
+[mysqld.2.1]
+ndb-log-update-as-write=1
+ndb-log-updated-only=0
+
+[mysqld.3.1]
+ndb-log-update-as-write=0
+ndb-log-updated-only=1
+
+[mysqld.4.1]
+ndb-log-update-as-write=0
+ndb-log-updated-only=0
+
+[ENV]
+NDB_CONNECTSTRING= @mysql_cluster.1.ndb_connectstring
+MASTER_MYPORT= @mysqld.1.1.port
+MASTER_MYPORT1= @mysqld.2.1.port
+MASTER_MYPORT2= @mysqld.3.1.port
+MASTER_MYPORT3= @mysqld.4.1.port
+
+NDB_BACKUP_DIR= @cluster_config.ndbd.1.1.BackupDataDir
+
=== added file 'mysql-test/suite/ndb_binlog/t/ndb_binlog_variants.test'
--- a/mysql-test/suite/ndb_binlog/t/ndb_binlog_variants.test 1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/ndb_binlog/t/ndb_binlog_variants.test 2009-09-28 10:09:38 +0000
@@ -0,0 +1,103 @@
+########################################################
+# Test binlog variants produced by Ndb
+#
+# 1) Updates logged as write_row events
+# Only primary key and updated columns included in the
+# event
+# 2) Updates logged as write_row_events
+# All columns included in the event
+# 3) Updates logged as update_row events
+# Only primary key and updated columns included in the
+# event
+# 4) Updates logged as update_row events
+# All columns included in the event
+#
+# Format variant (1) is the Ndb default.
+#
+# We use mysqlbinlog --verbose to check that the
+# generated binlog contents are as expected.
+#
+########################################################
+-- source include/have_ndb.inc
+-- source include/have_binlog_format_row.inc
+
+# Setup connections
+connect(mysqld1,127.0.0.1,root,,test,$MASTER_MYPORT);
+connect(mysqld2,127.0.0.1,root,,test,$MASTER_MYPORT1);
+connect(mysqld3,127.0.0.1,root,,test,$MASTER_MYPORT2);
+connect(mysqld4,127.0.0.1,root,,test,$MASTER_MYPORT3);
+
+connection mysqld1;
+
+# Create the table we're going to use
+create table ba(ks int primary key, st int, lp int) engine = ndb;
+
+# Wait for each mysqld to startup binlogging
+--let $source_server=mysqld1
+--let $dest_server=mysqld2
+source suite/rpl_ndb/t/rpl_ndb_wait_schema_logging.inc;
+
+--let $source_server=mysqld1
+--let $dest_server=mysqld3
+source suite/rpl_ndb/t/rpl_ndb_wait_schema_logging.inc;
+
+--let $source_server=mysqld1
+--let $dest_server=mysqld4
+source suite/rpl_ndb/t/rpl_ndb_wait_schema_logging.inc;
+
+--disable_query_log
+connection mysqld1;
+reset master;
+connection mysqld2;
+reset master;
+connection mysqld3;
+reset master;
+connection mysqld4;
+reset master;
+--enable_query_log
+
+connection mysqld1;
+
+# Now make the inserts and update
+insert into ba values (1, 1, 1), (2,2,2), (3,3,3), (4,4,4);
+update ba set lp=40 where ks=4; # Update does not affect all columns
+delete from ba where ks=2; # Also a delete for fun
+
+--disable_query_log
+# Add an event-stream marker
+create table stream_marker(a int) engine=ndb;
+drop table stream_marker;
+--let $wait_binlog_event=stream_marker
+--enable_query_log
+
+# Now let's have a look at what's in the Binlog on each server
+
+--source include/wait_for_binlog_event.inc
+flush logs;
+show variables like '%log_update%';
+--source suite/ndb_binlog/t/ndb_binlog_get_binlog_stmts.inc
+
+connection mysqld2;
+
+--source include/wait_for_binlog_event.inc
+flush logs;
+show variables like '%log_update%';
+--source suite/ndb_binlog/t/ndb_binlog_get_binlog_stmts.inc
+
+connection mysqld3;
+
+--source include/wait_for_binlog_event.inc
+flush logs;
+show variables like '%log_update%';
+--source suite/ndb_binlog/t/ndb_binlog_get_binlog_stmts.inc
+
+connection mysqld4;
+
+--source include/wait_for_binlog_event.inc
+flush logs;
+show variables like '%log_update%';
+--source suite/ndb_binlog/t/ndb_binlog_get_binlog_stmts.inc
+
+
+drop table ba;
+
=== modified file 'sql/log_event.cc'
--- a/sql/log_event.cc 2009-08-25 19:44:04 +0000
+++ b/sql/log_event.cc 2009-09-28 10:09:38 +0000
@@ -1855,6 +1855,7 @@ Rows_log_event::print_verbose_one_row(IO
{
const uchar *value0= value;
const uchar *null_bits= value;
+ uint null_bit_index= 0;
char typestr[64]= "";
value+= (m_width + 7) / 8;
@@ -1863,7 +1864,8 @@ Rows_log_event::print_verbose_one_row(IO
for (size_t i= 0; i < td->size(); i ++)
{
- int is_null= (null_bits[i / 8] >> (i % 8)) & 0x01;
+ int is_null= (null_bits[null_bit_index / 8]
+ >> (null_bit_index % 8)) & 0x01;
if (bitmap_is_set(cols_bitmap, i) == 0)
continue;
@@ -1900,6 +1902,8 @@ Rows_log_event::print_verbose_one_row(IO
}
my_b_printf(file, "\n");
+
+ null_bit_index++;
}
return value - value0;
}
