Bug#31455 mysqlbinlog don't print user readable info about RBR events

Implementing -v command line parameter to mysqlbinlog
to decode and print row events.

mysql-test/include/mysqlbinlog_row_engine.inc
mysql-test/r/mysqlbinlog_row.result
mysql-test/r/mysqlbinlog_row_big.result
mysql-test/r/mysqlbinlog_row_innodb.result
mysql-test/r/mysqlbinlog_row_myisam.result
mysql-test/r/mysqlbinlog_row_trans.result
mysql-test/t/mysqlbinlog_row.test
mysql-test/t/mysqlbinlog_row_big.test
mysql-test/t/mysqlbinlog_row_innodb.test
mysql-test/t/mysqlbinlog_row_myisam.test
mysql-test/t/mysqlbinlog_row_trans.test
  Adding tests 

client/Makefile.am
  Adding new files to symlink
  
client/mysqlbinlog.cc
  Adding -v option

sql/log_event.cc
  Impelentations of the new methods

sql/log_event.h
  Declaration of the new methods and member

sql/mysql_priv.h
  Adding new function prototype

sql/rpl_tblmap.cc
  Adding pre-processor conditions 

sql/rpl_tblmap.h
  Adding pre-processor conditions 

sql/rpl_utility.h
  Adding pre-processor conditions 

sql/sql_base.cc
  Adding reset_table_id_sequence() function.

sql/sql_repl.cc
  Resetting table_id on "RESET MASTER"
  
.bzrignore
  Ignoring new symlinked files

.bzrignore

@@ -389,6 +389,9 @@ client/readline.cpp
 client/rpl_constants.h
 client/rpl_record_old.cc
 client/rpl_record_old.h
+client/rpl_tblmap.h
+client/rpl_tblmap.cc
+client/rpl_utility.h
 client/select_test
 client/sql_string.cpp
 client/ssl_test

client/Makefile.am

@@ -104,6 +104,7 @@ DEFS =			-DUNDEF_THREADS_HACK \
 			-DDATADIR="\"$(localstatedir)\""
 
 sql_src=log_event.h mysql_priv.h rpl_constants.h \
+	rpl_utility.h rpl_tblmap.h rpl_tblmap.cc \
 	log_event.cc my_decimal.h my_decimal.cc \
 	log_event_old.h log_event_old.cc \
 	rpl_record_old.h rpl_record_old.cc

client/mysqlbinlog.cc

@@ -83,6 +83,8 @@ static const char* user = 0;
 static char* pass = 0;
 static char *charset= 0;
 
+static uint verbose= 0;
+
 static ulonglong start_position, stop_position;
 #define start_position_mot ((my_off_t)start_position)
 #define stop_position_mot  ((my_off_t)stop_position)
@@ -1063,6 +1065,9 @@ that may lead to an endless loop.",
   {"user", 'u', "Connect to the remote server as username.",
    (uchar**) &user, (uchar**) &user, 0, GET_STR_ALLOC, REQUIRED_ARG, 0, 0, 0, 0,
    0, 0},
+  {"verbose", 'v', "Reconstruct SQL statements out of row events. "
+                   "-v -v adds comments on column data types",
+   0, 0, 0, GET_NO_ARG, NO_ARG, 0, 0, 0, 0, 0, 0},
   {"version", 'V', "Print version and exit.", 0, 0, 0, GET_NO_ARG, NO_ARG, 0,
    0, 0, 0, 0, 0},
   {"open_files_limit", OPT_OPEN_FILES_LIMIT,
@@ -1258,6 +1263,12 @@ get_one_option(int optid, const struct my_option *opt __attribute__((unused)),
         (find_type_or_exit(argument, &base64_output_mode_typelib, opt->name)-1);
     }
     break;
+  case 'v':
+    if (argument == disabled_my_option)
+      verbose= 0;
+    else
+      verbose++;
+    break;
   case 'V':
     print_version();
     exit(0);
@@ -1344,6 +1355,8 @@ static Exit_status dump_log_entries(const char* logname)
   fprintf(result_file, "DELIMITER /*!*/;\n");
   strmov(print_event_info.delimiter, "/*!*/;");
   
+  print_event_info.verbose= short_form ? 0 : verbose;
+
   rc= (remote_opt ? dump_remote_log_entries(&print_event_info, logname) :
        dump_local_log_entries(&print_event_info, logname));
 

mysql-test/r/mysqlbinlog_row_big.result

+#
+# Preparatory cleanup.
+#
+DROP TABLE IF EXISTS t1;
+#
+# We need a fixed timestamp to avoid varying results.
+#
+SET timestamp=1000000000;
+#
+# We need big packets.
+#
+SET @@session.max_allowed_packet= 1024*1024*1024;
+#
+# Delete all existing binary logs.
+#
+RESET MASTER;
+#
+# Create a test table.
+#
+CREATE TABLE t1 (
+c1 LONGTEXT
+) ENGINE=MyISAM DEFAULT CHARSET latin1;
+#
+# Show how much rows are affected by each statement.
+#
+#
+# Insert a big row.
+#
+INSERT INTO t1 VALUES (REPEAT('ManyMegaByteBlck', 2097152));
+affected rows: 1
+#
+# Show what we have in the table.
+# Do not display the column value itself, just its length.
+#
+SELECT LENGTH(c1) FROM t1;
+LENGTH(c1)	33554432
+affected rows: 1
+#
+# Grow the row by updating.
+#
+UPDATE t1 SET c1 = CONCAT(c1, c1);
+affected rows: 1
+info: Rows matched: 1  Changed: 1  Warnings: 0
+#
+# Show what we have in the table.
+# Do not display the column value itself, just its length.
+#
+SELECT LENGTH(c1) FROM t1;
+LENGTH(c1)	67108864
+affected rows: 1
+#
+# Delete the row.
+#
+DELETE FROM t1 WHERE c1 >= 'ManyMegaByteBlck';
+affected rows: 1
+#
+# Hide how much rows are affected by each statement.
+#
+#
+# Flush all log buffers to the log file.
+#
+FLUSH LOGS;
+#
+# Call mysqlbinlog to display the log file contents.
+# NOTE: The output of mysqlbinlog is redirected to
+#       $MYSQLTEST_VARDIR/tmp/mysqlbinlog_big_1.out
+#       If you want to examine it, disable remove_file
+#       at the bottom of the test script.
+#
+#
+# Cleanup.
+#
+DROP TABLE t1;
+remove_file $MYSQLTEST_VARDIR/tmp/mysqlbinlog_big_1.out

mysql-test/t/mysqlbinlog_row_big.test

+# mysqlbinlog_big.test
+#
+# Show that mysqlbinlog can handle big rows.
+#
+
+#
+# The *huge* output of mysqlbinlog will be redirected to
+# $MYSQLTEST_VARDIR/$mysqlbinlog_output
+#
+--let $mysqlbinlog_output= tmp/mysqlbinlog_big_1.out
+
+#--source include/have_myisam.inc
+--let $engine_type= MyISAM
+
+#
+# This test case is insensitive to the binlog format
+# because we don't display the output of mysqlbinlog.
+#
+#--source include/have_binlog_format_row.inc
+
+--source include/have_log_bin.inc
+
+# This is a big test.
+--source include/big_test.inc
+
+--echo #
+--echo # Preparatory cleanup.
+--echo #
+--disable_warnings
+DROP TABLE IF EXISTS t1;
+--enable_warnings
+
+--echo #
+--echo # We need a fixed timestamp to avoid varying results.
+--echo #
+SET timestamp=1000000000;
+
+--echo #
+--echo # We need big packets.
+--echo #
+SET @@session.max_allowed_packet= 1024*1024*1024;
+
+--echo #
+--echo # Delete all existing binary logs.
+--echo #
+RESET MASTER;
+
+--echo #
+--echo # Create a test table.
+--echo #
+eval CREATE TABLE t1 (
+  c1 LONGTEXT
+  ) ENGINE=$engine_type DEFAULT CHARSET latin1;
+
+--echo #
+--echo # Show how much rows are affected by each statement.
+--echo #
+--enable_info
+
+--echo #
+--echo # Insert a big row.
+--echo #
+#
+# 256MB
+#INSERT INTO t1 VALUES (REPEAT('ManyMegaByteBlck', 16777216));
+#
+# 32MB
+INSERT INTO t1 VALUES (REPEAT('ManyMegaByteBlck', 2097152));
+#
+# 4MB
+#INSERT INTO t1 VALUES (REPEAT('ManyMegaByteBlck', 262144));
+#
+# 512KB
+#INSERT INTO t1 VALUES (REPEAT('ManyMegaByteBlck', 32768));
+
+--echo #
+--echo # Show what we have in the table.
+--echo # Do not display the column value itself, just its length.
+--echo #
+query_vertical SELECT LENGTH(c1) FROM t1;
+
+--echo #
+--echo # Grow the row by updating.
+--echo #
+UPDATE t1 SET c1 = CONCAT(c1, c1);
+
+--echo #
+--echo # Show what we have in the table.
+--echo # Do not display the column value itself, just its length.
+--echo #
+query_vertical SELECT LENGTH(c1) FROM t1;
+
+--echo #
+--echo # Delete the row.
+--echo #
+DELETE FROM t1 WHERE c1 >= 'ManyMegaByteBlck';
+
+--echo #
+--echo # Hide how much rows are affected by each statement.
+--echo #
+--disable_info
+
+--echo #
+--echo # Flush all log buffers to the log file.
+--echo #
+FLUSH LOGS;
+
+--echo #
+--echo # Call mysqlbinlog to display the log file contents.
+--echo # NOTE: The output of mysqlbinlog is redirected to
+--echo #       \$MYSQLTEST_VARDIR/$mysqlbinlog_output
+--echo #       If you want to examine it, disable remove_file
+--echo #       at the bottom of the test script.
+--echo #
+let $MYSQLD_DATADIR= `select @@datadir`;
+--replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
+--replace_regex /SQL_LOAD_MB-[0-9]-[0-9]/SQL_LOAD_MB-#-#/ /exec_time=[0-9]*/exec_time=#/ /end_log_pos [0-9]*/end_log_pos #/ /# at [0-9]*/# at #/ /Xid = [0-9]*/Xid = #/
+--exec $MYSQL_BINLOG $MYSQLTEST_VARDIR/log/master-bin.000001 > $MYSQLTEST_VARDIR/$mysqlbinlog_output
+
+--echo #
+--echo # Cleanup.
+--echo #
+DROP TABLE t1;
+
+--echo remove_file \$MYSQLTEST_VARDIR/$mysqlbinlog_output
+#
+# NOTE: If you want to see the *huge* mysqlbinlog output, disable next line:
+#
+--remove_file $MYSQLTEST_VARDIR/$mysqlbinlog_output
+

mysql-test/t/mysqlbinlog_row_innodb.test

+# mysqlbinlog_row_innodb.test
+#
+# Show that mysqlbinlog displays human readable comments to
+# row-based log events.
+#
+# Main module for the InnoDB storage engine.
+#
+# Calls include/mysqlbinlog_row.inc
+# See there for more informaton.
+#
+
+--source include/have_innodb.inc
+let $engine_type=InnoDB;
+
+#
+# The test case would also work with statement based or mixed mode logging.
+# But this would require different result files. To handle this with the
+# current test suite, new main test cases are required.
+#
+--source include/have_binlog_format_row.inc
+--source include/have_ucs2.inc 
+
+--source include/mysqlbinlog_row_engine.inc
+

mysql-test/t/mysqlbinlog_row_myisam.test

+# mysqlbinlog_row.test
+#
+# Show that mysqlbinlog displays human readable comments to
+# row-based log events.
+#
+# Main module for the MyISAM storage engine.
+#
+# Calls include/mysqlbinlog_row.inc
+# See there for more informaton.
+#
+
+#--source include/have_myisam.inc
+let $engine_type=MyISAM;
+
+#
+# The test case would also work with statement based or mixed mode logging.
+# But this would require different result files. To handle this with the
+# current test suite, new main test cases are required.
+#
+--source include/have_binlog_format_row.inc
+--source include/have_ucs2.inc 
+
+--source include/mysqlbinlog_row_engine.inc

mysql-test/t/mysqlbinlog_row_trans.test

+# mysqlbinlog_trans.test
+#
+# Show that mysqlbinlog work correctly with transactions.
+#
+
+#--source include/have_myisam.inc
+--let $engine_type_nontrans= MyISAM
+--source include/have_innodb.inc
+--let $engine_type= InnoDB
+
+#
+# The test case would also work with statement based or mixed mode logging.
+# But this would require different result files. To handle this with the
+# current test suite, new main test cases are required.
+#
+--source include/have_binlog_format_row.inc
+
+--source include/have_log_bin.inc
+
+--echo #
+--echo # Preparatory cleanup.
+--echo #
+--disable_warnings
+DROP TABLE IF EXISTS t1, t2;
+--enable_warnings
+
+--echo #
+--echo # We need a fixed timestamp to avoid varying results.
+--echo #
+SET timestamp=1000000000;
+
+--echo #
+--echo # Delete all existing binary logs.
+--echo #
+RESET MASTER;
+
+--echo #
+--echo # Create test tables.
+--echo #
+eval CREATE TABLE t1 (
+  c1 INT,
+  c2 VARCHAR(20)
+  ) ENGINE=$engine_type DEFAULT CHARSET latin1;
+eval CREATE TABLE t2 (
+  c1 INT,
+  c2 VARCHAR(20)
+  ) ENGINE=$engine_type_nontrans DEFAULT CHARSET latin1;
+
+--echo #
+--echo # Start transaction #1, transactional table only, commit.
+--echo #
+START TRANSACTION;
+
+--echo #
+--echo # Do some statements.
+--echo #
+INSERT INTO t1 VALUES (1,'varchar-1'), (2,'varchar-2'), (3,'varchar-3');
+UPDATE t1 SET c1 = c1 + 10;
+DELETE FROM t1 WHERE c1 = 12;
+
+--echo #
+--echo # Commit transaction.
+--echo #
+COMMIT;
+SELECT * FROM t1;
+TRUNCATE TABLE t1;
+
+--echo #
+--echo # Start transaction #2, transactional table only, rollback.
+--echo #
+START TRANSACTION;
+
+--echo #
+--echo # Do some statements.
+--echo #
+INSERT INTO t1 VALUES (1,'varchar-1'), (2,'varchar-2'), (3,'varchar-3');
+UPDATE t1 SET c1 = c1 + 10;
+DELETE FROM t1 WHERE c1 = 12;
+
+--echo #
+--echo # Rollback transaction.
+--echo #
+ROLLBACK;
+SELECT * FROM t1;
+TRUNCATE TABLE t1;
+
+--echo #
+--echo # Start transaction #3, both tables, commit.
+--echo #
+START TRANSACTION;
+
+--echo #
+--echo # Do some statements on the transactional table.
+--echo #
+INSERT INTO t1 VALUES (1,'varchar-1'), (2,'varchar-2'), (3,'varchar-3');
+UPDATE t1 SET c1 = c1 + 10;
+DELETE FROM t1 WHERE c1 = 12;
+
+--echo #
+--echo # Do some statements on the non-transactional table.
+--echo #
+INSERT INTO t2 VALUES (1,'varchar-1'), (2,'varchar-2'), (3,'varchar-3');
+UPDATE t2 SET c1 = c1 + 10;
+DELETE FROM t2 WHERE c1 = 12;
+
+--echo #
+--echo # Commit transaction.
+--echo #
+COMMIT;
+SELECT * FROM t1;
+SELECT * FROM t2;
+TRUNCATE TABLE t1;
+TRUNCATE TABLE t2;
+
+--echo #
+--echo # Start transaction #4, both tables, rollback.
+--echo #
+START TRANSACTION;
+
+--echo #
+--echo # Do some statements on the transactional table.
+--echo #
+INSERT INTO t1 VALUES (1,'varchar-1'), (2,'varchar-2'), (3,'varchar-3');
+UPDATE t1 SET c1 = c1 + 10;
+DELETE FROM t1 WHERE c1 = 12;
+
+--echo #
+--echo # Do some statements on the non-transactional table.
+--echo #
+INSERT INTO t2 VALUES (1,'varchar-1'), (2,'varchar-2'), (3,'varchar-3');
+UPDATE t2 SET c1 = c1 + 10;
+DELETE FROM t2 WHERE c1 = 12;
+
+--echo #
+--echo # Rollback transaction.
+--echo #
+ROLLBACK;
+SELECT * FROM t1;
+SELECT * FROM t2;
+TRUNCATE TABLE t1;
+TRUNCATE TABLE t2;
+
+--echo #
+--echo # Flush all log buffers to the log file.
+--echo #
+FLUSH LOGS;
+
+--echo #
+--echo # Call mysqlbinlog to display the log file contents.
+--echo #
+let $MYSQLD_DATADIR= `select @@datadir`;
+--replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
+--replace_regex /SQL_LOAD_MB-[0-9]-[0-9]/SQL_LOAD_MB-#-#/ /exec_time=[0-9]*/exec_time=#/ /end_log_pos [0-9]*/end_log_pos #/ /# at [0-9]*/# at #/ /Xid = [0-9]*/Xid = #/ /thread_id=[0-9]*/thread_id=#/
+--exec $MYSQL_BINLOG -v -v $MYSQLTEST_VARDIR/log/master-bin.000001
+
+--echo #
+--echo # Cleanup.
+--echo #
+DROP TABLE t1, t2;
+
+

sql/log_event.h

@@ -34,6 +34,14 @@
 
 #include <my_bitmap.h>
 #include "rpl_constants.h"
+
+#ifdef MYSQL_CLIENT
+#include "rpl_utility.h"
+#include "hash.h"
+#include "rpl_tblmap.h"
+#include "rpl_tblmap.cc"
+#endif
+
 #ifndef MYSQL_CLIENT
 #include "rpl_record.h"
 #include "rpl_reporting.h"
@@ -634,6 +642,11 @@ typedef struct st_print_event_info
   uint8 common_header_len;
   char delimiter[16];
 
+#ifdef MYSQL_CLIENT
+  uint verbose;
+  table_mapping m_table_map;
+#endif
+
   /*
      These two caches are used by the row-based replication events to
      collect the header information and the main body of the events
@@ -3235,6 +3248,17 @@ public:
 
   ~Table_map_log_event();
 
+#ifdef MYSQL_CLIENT
+  table_def *create_table_def()
+  {
+    return new table_def(m_coltype, m_colcnt, m_field_metadata,
+                         m_field_metadata_size, m_null_bits);
+  }
+  ulong get_table_id() const        { return m_table_id; }
+  const char *get_table_name() const { return m_tblnam; }
+  const char *get_db_name() const    { return m_dbnam; }
+#endif
+
   virtual Log_event_type get_type_code() { return TABLE_MAP_EVENT; }
   virtual bool is_valid() const { return m_memory != NULL; /* we check malloc */ }
 
@@ -3365,6 +3389,12 @@ public:
 #ifdef MYSQL_CLIENT
   /* not for direct call, each derived has its own ::print() */
   virtual void print(FILE *file, PRINT_EVENT_INFO *print_event_info)= 0;
+  void print_verbose(IO_CACHE *file,
+                     PRINT_EVENT_INFO *print_event_info);
+  size_t print_verbose_one_row(IO_CACHE *file, table_def *td,
+                               PRINT_EVENT_INFO *print_event_info,
+                               MY_BITMAP *cols_bitmap,
+                               const uchar *ptr, const uchar *prefix);
 #endif
 
 #ifndef MYSQL_CLIENT

sql/mysql_priv.h

@@ -1078,6 +1078,7 @@ void table_cache_free(void);
 bool table_def_init(void);
 void table_def_free(void);
 void assign_new_table_id(TABLE_SHARE *share);
+void reset_table_id_sequence();
 uint cached_open_tables(void);
 uint cached_table_definitions(void);
 void kill_mysql(void);

sql/rpl_tblmap.cc

@@ -19,7 +19,11 @@
 
 #include "rpl_tblmap.h"
 
+#ifdef MYSQL_CLIENT
+#define MAYBE_TABLE_NAME(T) ("")
+#else
 #define MAYBE_TABLE_NAME(T) ((T) ? (T)->s->table_name.str : "<>")
+#endif
 #define TABLE_ID_HASH_SIZE 32
 #define TABLE_ID_CHUNK 256
 
@@ -42,11 +46,14 @@ table_mapping::table_mapping()
 
 table_mapping::~table_mapping()
 {
+#ifdef MYSQL_CLIENT
+  clear_tables();
+#endif
   hash_free(&m_table_ids);
   free_root(&m_mem_root, MYF(0));
 }
 
-st_table* table_mapping::get_table(ulong table_id)
+TABLE* table_mapping::get_table(ulong table_id)
 {
   DBUG_ENTER("table_mapping::get_table(ulong)");
   DBUG_PRINT("enter", ("table_id: %lu", table_id));
@@ -104,8 +111,12 @@ int table_mapping::set_table(ulong table_id, TABLE* table)
     m_free= m_free->next;
   }
   else
+  {
+#ifdef MYSQL_CLIENT
+    free_table_map_log_event(e->table);
+#endif
     hash_delete(&m_table_ids,(uchar *)e);
-
+  }
   e->table_id= table_id;
   e->table= table;
   my_hash_insert(&m_table_ids,(uchar *)e);
@@ -140,6 +151,9 @@ void table_mapping::clear_tables()
   for (uint i= 0; i < m_table_ids.records; i++)
   {
     entry *e= (entry *)hash_element(&m_table_ids, i);
+#ifdef MYSQL_CLIENT
+    free_table_map_log_event(e->table);
+#endif
     e->next= m_free;
     m_free= e;
   }

sql/rpl_tblmap.h

@@ -17,8 +17,15 @@
 #define TABLE_MAPPING_H
 
 /* Forward declarations */
+#ifndef MYSQL_CLIENT
 struct st_table;
 typedef st_table TABLE;
+#else
+class Table_map_log_event;
+typedef Table_map_log_event TABLE;
+void free_table_map_log_event(TABLE *table);
+#endif
+
 
 /*
   CLASS table_mapping

sql/rpl_utility.h

@@ -236,7 +236,9 @@ public:
     @retval 1  if the table definition is not compatible with @c table
     @retval 0  if the table definition is compatible with @c table
   */
+#ifndef MYSQL_CLIENT
   int compatible_with(Relay_log_info const *rli, TABLE *table) const;
+#endif
 
 private:
   ulong m_size;           // Number of elements in the types array
@@ -247,6 +249,8 @@ private:
   uchar *m_memory;
 };
 
+
+#ifndef MYSQL_CLIENT
 /**
    Extend the normal table list with a few new fields needed by the
    slave thread, but nowhere else.
@@ -288,6 +292,7 @@ namespace {
   };
 
 }
+#endif
 
 #define DBUG_PRINT_BITSET(N,FRM,BS)                \
   do {                                             \

sql/sql_base.cc

@@ -3693,9 +3693,10 @@ void abort_locked_tables(THD *thd,const char *db, const char *table_name)
 
     share->table_map_id is not ~0UL.
  */
+static ulong last_table_id= ~0UL;
+
 void assign_new_table_id(TABLE_SHARE *share)
 {
-  static ulong last_table_id= ~0UL;
 
   DBUG_ENTER("assign_new_table_id");
 
@@ -3719,6 +3720,12 @@ void assign_new_table_id(TABLE_SHARE *share)
   DBUG_VOID_RETURN;
 }
 
+void reset_table_id_sequence()
+{
+  pthread_mutex_lock(&LOCK_open);
+  last_table_id= ~0UL;
+  pthread_mutex_unlock(&LOCK_open);
+}
 
 /**
   Compare metadata versions of an element obtained from the table

sql/sql_repl.cc

@@ -1285,13 +1285,16 @@ bool change_master(THD* thd, Master_info* mi)
 
 int reset_master(THD* thd)
 {
+  int rc;
   if (!mysql_bin_log.is_open())
   {
     my_message(ER_FLUSH_MASTER_BINLOG_CLOSED,
                ER(ER_FLUSH_MASTER_BINLOG_CLOSED), MYF(ME_BELL+ME_WAITTANG));
     return 1;
   }
-  return mysql_bin_log.reset_logs(thd);
+  if (!(rc= mysql_bin_log.reset_logs(thd)))
+    reset_table_id_sequence();
+  return rc;
 }
 
 int cmp_master_pos(const char* log_file_name1, ulonglong log_pos1,