[Commits] Rev 3674: MDEV-4645: Incorrect reads of frozen binlog events; FDE corrupted in relay log in file:///home/bell/maria/bzr/work-maria-10.0-base-MDEV-4645/

sanja at montyprogram.com sanja at montyprogram.com
Mon Aug 12 12:43:22 EEST 2013


At file:///home/bell/maria/bzr/work-maria-10.0-base-MDEV-4645/

------------------------------------------------------------
revno: 3674
revision-id: sanja at montyprogram.com-20130719120919-xp6inf961ux89csy
parent: igor at askmonty.org-20130806203318-esxb7kpq9kab0i97
committer: sanja at montyprogram.com
branch nick: work-maria-10.0-base-MDEV-4645
timestamp: Fri 2013-07-19 15:09:19 +0300
message:
  MDEV-4645: Incorrect reads of frozen binlog events; FDE corrupted in relay log
  
  Currently several places use description_event->common_header_len instead of
  LOG_EVENT_MINIMAL_HEADER_LEN when parsing events with "frozen" headers (such
  as Start_event_v3 and its subclasses such as Format_description_log_event, as
  well as Rotate_event). This causes events with extra headers (which would otherwise
  be valid and those headers ignored) to be corrupted due to over-reading or skipping
  into the data portion of the log events.
    
  It is rewritten in some details patch of Jeremy Cole (See MDEV):
  - The virtual function returns length to avoid IFs (and only one call of the virtual function made)
  :- Printing function avoids printing strings
-------------- next part --------------
=== modified file 'mysql-test/r/mysqlbinlog.result'
--- a/mysql-test/r/mysqlbinlog.result	2013-04-15 08:55:27 +0000
+++ b/mysql-test/r/mysqlbinlog.result	2013-07-19 12:09:19 +0000
@@ -630,7 +630,7 @@ We expect this value to be 2 (one for th
 The bug being tested was that 'Query' lines were not preceded by '#'
 If the line is in the table, it had to have been preceded by a '#'
 
-SELECT COUNT(*) AS `BUG#28293_expect_2` FROM patch WHERE a LIKE '%Query%';
+SELECT COUNT(*) AS `BUG#28293_expect_2` FROM patch WHERE a LIKE '#%Query%';
 BUG#28293_expect_2
 2
 DROP TABLE patch;

=== modified file 'mysql-test/t/mysqlbinlog.test'
--- a/mysql-test/t/mysqlbinlog.test	2013-03-26 09:35:34 +0000
+++ b/mysql-test/t/mysqlbinlog.test	2013-07-19 12:09:19 +0000
@@ -275,17 +275,16 @@ FLUSH LOGS;
 
 DROP TABLE t1;
 
-# We create a table, patch, and load the output into it
-# By using LINES STARTING BY '#' + SELECT WHERE a LIKE 'Query'
-# We can easily see if a 'Query' line is missing the '#' character
-# as described in the original bug
+# We create a table named "patch", and load the output into it.
+# By using LIKE, we can easily see if the output is missing the '#'
+# character, as described in the bug.
 
 --disable_query_log
 CREATE TABLE patch (a BLOB);
 --exec $MYSQL_BINLOG --hexdump --local-load=$MYSQLTEST_VARDIR/tmp/ $MYSQLD_DATADIR/master-bin.000012 > $MYSQLTEST_VARDIR/tmp/mysqlbinlog_tmp.dat
 ### Starting master-bin.000014
 eval LOAD DATA LOCAL INFILE '$MYSQLTEST_VARDIR/tmp/mysqlbinlog_tmp.dat'
-     INTO TABLE patch FIELDS TERMINATED BY '' LINES STARTING BY '#';
+     INTO TABLE patch FIELDS TERMINATED BY '';
 --remove_file $MYSQLTEST_VARDIR/tmp/mysqlbinlog_tmp.dat
 --enable_query_log
 
@@ -293,7 +292,7 @@ eval LOAD DATA LOCAL INFILE '$MYSQLTEST_
 --echo The bug being tested was that 'Query' lines were not preceded by '#'
 --echo If the line is in the table, it had to have been preceded by a '#'
 --echo
-SELECT COUNT(*) AS `BUG#28293_expect_2` FROM patch WHERE a LIKE '%Query%';
+SELECT COUNT(*) AS `BUG#28293_expect_2` FROM patch WHERE a LIKE '#%Query%';
 DROP TABLE patch;
 
 #

=== modified file 'sql/log_event.cc'
--- a/sql/log_event.cc	2013-07-17 19:24:29 +0000
+++ b/sql/log_event.cc	2013-07-19 12:09:19 +0000
@@ -1755,6 +1755,165 @@ Log_event* Log_event::read_log_event(con
 
 #ifdef MYSQL_CLIENT
 
+static void hexdump_minimal_header_to_io_cache(IO_CACHE *file,
+                                               my_off_t offset,
+                                               uchar *ptr)
+{
+  DBUG_ASSERT(LOG_EVENT_MINIMAL_HEADER_LEN == 19);
+
+  /*
+    Pretty-print the first LOG_EVENT_MINIMAL_HEADER_LEN (19) bytes of the
+    common header, which contains the basic information about the log event.
+    Every event will have at least this much header, but events could contain
+    more headers (which must be printed by other methods, if desired).
+  */
+  char emit_buf[120];               // Enough for storing one line
+  my_b_printf(file,
+              "#           "
+              "|Timestamp   "
+              "|Type "
+              "|Master ID   "
+              "|Size        "
+              "|Master Pos  "
+              "|Flags\n");
+  size_t const emit_buf_written=
+    my_snprintf(emit_buf, sizeof(emit_buf),
+                "# %8llx  "                         /* Position */
+                "|%02x %02x %02x %02x "             /* Timestamp */
+                "|%02x   "                          /* Type */
+                "|%02x %02x %02x %02x "             /* Master ID */
+                "|%02x %02x %02x %02x "             /* Size */
+                "|%02x %02x %02x %02x "             /* Master Pos */
+                "|%02x %02x\n",                     /* Flags */
+                (ulonglong) offset,                 /* Position */
+                ptr[0], ptr[1], ptr[2], ptr[3],     /* Timestamp */
+                ptr[4],                             /* Type */
+                ptr[5], ptr[6], ptr[7], ptr[8],     /* Master ID */
+                ptr[9], ptr[10], ptr[11], ptr[12],  /* Size */
+                ptr[13], ptr[14], ptr[15], ptr[16], /* Master Pos */
+                ptr[17], ptr[18]);                  /* Flags */
+
+  DBUG_ASSERT(static_cast<size_t>(emit_buf_written) < sizeof(emit_buf));
+  my_b_write(file, reinterpret_cast<uchar*>(emit_buf), emit_buf_written);
+  my_b_write(file, "#\n", 2);
+}
+
+
+/*
+  The number of bytes to print per line. Should be an even number,
+  and "hexdump -C" uses 16, so we'll duplicate that here.
+*/
+#define HEXDUMP_BYTES_PER_LINE 16
+
+static void format_hex_line(char *emit_buff)
+{
+  memset(emit_buff + 1, ' ',
+         1 + 8 + 2 + (HEXDUMP_BYTES_PER_LINE * 3 + 1) + 2 +
+         HEXDUMP_BYTES_PER_LINE);
+  emit_buff[0]= '#';
+  emit_buff[2 + 8 + 2 + (HEXDUMP_BYTES_PER_LINE * 3 + 1) + 1]= '|';
+  emit_buff[2 + 8 + 2 + (HEXDUMP_BYTES_PER_LINE * 3 + 1) + 2 +
+    HEXDUMP_BYTES_PER_LINE]= '|';
+  emit_buff[2 + 8 + 2 + (HEXDUMP_BYTES_PER_LINE * 3 + 1) + 2 +
+    HEXDUMP_BYTES_PER_LINE + 1]= '\n';
+  emit_buff[2 + 8 + 2 + (HEXDUMP_BYTES_PER_LINE * 3 + 1) + 2 +
+    HEXDUMP_BYTES_PER_LINE + 2]= '\0';
+}
+
+static void hexdump_data_to_io_cache(IO_CACHE *file,
+                                     my_off_t offset,
+                                     uchar *ptr,
+                                     my_off_t size)
+{
+  /*
+    2 = '# '
+    8 = address
+    2 = '  '
+    (HEXDUMP_BYTES_PER_LINE * 3 + 1) = Each byte prints as two hex digits,
+       plus a space
+    2 = ' |'
+    HEXDUMP_BYTES_PER_LINE = text representation
+    2 = '|\n'
+    1 = '\0'
+  */
+  char emit_buffer[2 + 8 + 2 + (HEXDUMP_BYTES_PER_LINE * 3 + 1) + 2 +
+    HEXDUMP_BYTES_PER_LINE + 2 + 1 ];
+  char *h,*c;
+  my_off_t i;
+
+  if (size == 0)
+    return;
+
+  format_hex_line(emit_buffer);
+  /*
+    Print the rest of the event (without common header)
+  */
+  my_off_t starting_offset = offset;
+  for (i= 0,
+       c= emit_buffer + 2 + 8 + 2 + (HEXDUMP_BYTES_PER_LINE * 3 + 1) + 2,
+       h= emit_buffer + 2 + 8 + 2;
+       i < size;
+       i++, ptr++)
+  {
+    my_snprintf(h, 4, "%02x ", *ptr);
+    h+= 3;
+
+    *c++= my_isprint(&my_charset_bin, *ptr) ? *ptr : '.';
+
+    /* Print in groups of HEXDUMP_BYTES_PER_LINE characters. */
+    if ((i % HEXDUMP_BYTES_PER_LINE) == (HEXDUMP_BYTES_PER_LINE - 1))
+    {
+      /* remove \0 left after printing hex byte representation */
+      *h= ' ';
+      /* prepare space to print address */
+      memset(emit_buffer + 2, ' ', 8);
+      /* print address */
+      size_t const emit_buf_written= my_snprintf(emit_buffer + 2, 9, "%8llx",
+                                                 (ulonglong) starting_offset);
+      /* remove \0 left after printing address */
+      emit_buffer[2 + emit_buf_written]= ' ';
+      my_b_write(file, reinterpret_cast<uchar*>(emit_buffer),
+                 sizeof(emit_buffer) - 1);
+      c= emit_buffer + 2 + 8 + 2 + (HEXDUMP_BYTES_PER_LINE * 3 + 1) + 2;
+      h= emit_buffer + 2 + 8 + 2;
+      format_hex_line(emit_buffer);
+      starting_offset+= HEXDUMP_BYTES_PER_LINE;
+    }
+    else if ((i % (HEXDUMP_BYTES_PER_LINE / 2))
+             == ((HEXDUMP_BYTES_PER_LINE / 2) - 1))
+    {
+      /*
+        In the middle of the group of HEXDUMP_BYTES_PER_LINE, emit an extra
+        space in the hex string, to make two groups.
+      */
+      *h++= ' ';
+    }
+
+  }
+
+  /*
+    There is still data left in our buffer, which means that the previous
+    line was not perfectly HEXDUMP_BYTES_PER_LINE characters, so write an
+    incomplete line, with spaces to pad out to the same length as a full
+    line would be, to make things more readable.
+  */
+  if (h != emit_buffer + 2 + 8 + 2)
+  {
+    *h= ' ';
+    *c++= '|'; *c++= '\n';
+    memset(emit_buffer + 2, ' ', 8);
+    size_t const emit_buf_written= my_snprintf(emit_buffer + 2, 9, "%8llx",
+                                               (ulonglong) starting_offset);
+    emit_buffer[2 + emit_buf_written]= ' ';
+    /* pad unprinted area */
+    memset(h, ' ',
+           (HEXDUMP_BYTES_PER_LINE * 3 + 1) - (h - (emit_buffer + 2 + 8 + 2)));
+    my_b_write(file, reinterpret_cast<uchar*>(emit_buffer),
+               c - emit_buffer);
+  }
+  my_b_write(file, "#\n", 2);
+}
+
 /*
   Log_event::print_header()
 */
@@ -1789,86 +1948,27 @@ void Log_event::print_header(IO_CACHE* f
   {
     my_b_printf(file, "\n");
     uchar *ptr= (uchar*)temp_buf;
-    my_off_t size=
-      uint4korr(ptr + EVENT_LEN_OFFSET) - LOG_EVENT_MINIMAL_HEADER_LEN;
-    my_off_t i;
-
-    /* Header len * 4 >= header len * (2 chars + space + extra space) */
-    char *h, hex_string[LOG_EVENT_MINIMAL_HEADER_LEN*4]= {0};
-    char *c, char_string[16+1]= {0};
-
-    /* Pretty-print event common header if header is exactly 19 bytes */
-    if (print_event_info->common_header_len == LOG_EVENT_MINIMAL_HEADER_LEN)
-    {
-      char emit_buf[256];               // Enough for storing one line
-      my_b_printf(file, "# Position  Timestamp   Type   Master ID        "
-                  "Size      Master Pos    Flags \n");
-      size_t const bytes_written=
-        my_snprintf(emit_buf, sizeof(emit_buf),
-                    "# %8.8lx %02x %02x %02x %02x   %02x   "
-                    "%02x %02x %02x %02x   %02x %02x %02x %02x   "
-                    "%02x %02x %02x %02x   %02x %02x\n",
-                    (unsigned long) hexdump_from,
-                    ptr[0], ptr[1], ptr[2], ptr[3], ptr[4], ptr[5], ptr[6],
-                    ptr[7], ptr[8], ptr[9], ptr[10], ptr[11], ptr[12], ptr[13],
-                    ptr[14], ptr[15], ptr[16], ptr[17], ptr[18]);
-      DBUG_ASSERT(static_cast<size_t>(bytes_written) < sizeof(emit_buf));
-      my_b_write(file, (uchar*) emit_buf, bytes_written);
-      ptr += LOG_EVENT_MINIMAL_HEADER_LEN;
-      hexdump_from += LOG_EVENT_MINIMAL_HEADER_LEN;
-    }
-
-    /* Rest of event (without common header) */
-    for (i= 0, c= char_string, h=hex_string;
-	 i < size;
-	 i++, ptr++)
-    {
-      my_snprintf(h, 4, "%02x ", *ptr);
-      h += 3;
+    my_off_t size= uint4korr(ptr + EVENT_LEN_OFFSET);
+    my_off_t hdr_len= get_header_len(print_event_info->common_header_len);
 
-      *c++= my_isalnum(&my_charset_bin, *ptr) ? *ptr : '.';
+    size-= hdr_len;
 
-      if (i % 16 == 15)
-      {
-        /*
-          my_b_printf() does not support full printf() formats, so we
-          have to do it this way.
+    my_b_printf(file, "# Position\n");
 
-          TODO: Rewrite my_b_printf() to support full printf() syntax.
-         */
-        char emit_buf[256];
-        size_t const bytes_written=
-          my_snprintf(emit_buf, sizeof(emit_buf),
-                      "# %8.8lx %-48.48s |%16s|\n",
-                      (unsigned long) (hexdump_from + (i & 0xfffffff0)),
-                      hex_string, char_string);
-        DBUG_ASSERT(static_cast<size_t>(bytes_written) < sizeof(emit_buf));
-	my_b_write(file, (uchar*) emit_buf, bytes_written);
-	hex_string[0]= 0;
-	char_string[0]= 0;
-	c= char_string;
-	h= hex_string;
-      }
-      else if (i % 8 == 7) *h++ = ' ';
-    }
-    *c= '\0';
+    /* Write the header, nicely formatted by field. */
+    hexdump_minimal_header_to_io_cache(file, hexdump_from, ptr);
+
+    ptr+= hdr_len;
+    hexdump_from+= hdr_len;
+
+    /* Print the rest of the data, mimicking "hexdump -C" output. */
+    hexdump_data_to_io_cache(file, hexdump_from, ptr, size);
 
-    if (hex_string[0])
-    {
-      char emit_buf[256];
-      size_t const bytes_written=
-        my_snprintf(emit_buf, sizeof(emit_buf),
-                    "# %8.8lx %-48.48s |%s|\n",
-                    (unsigned long) (hexdump_from + (i & 0xfffffff0)),
-                    hex_string, char_string);
-      DBUG_ASSERT(static_cast<size_t>(bytes_written) < sizeof(emit_buf));
-      my_b_write(file, (uchar*) emit_buf, bytes_written);
-    }
     /*
-      need a # to prefix the rest of printouts for example those of
-      Rows_log_event::print_helper().
+      Prefix the next line so that the output from print_helper()
+      will appear as a comment.
     */
-    my_b_write(file, reinterpret_cast<const uchar*>("# "), 2);
+    my_b_write(file, "# Event: ", 9);
   }
   DBUG_VOID_RETURN;
 }
@@ -4407,7 +4507,7 @@ Start_log_event_v3::Start_log_event_v3(c
                                        *description_event)
   :Log_event(buf, description_event)
 {
-  buf+= description_event->common_header_len;
+  buf+= LOG_EVENT_MINIMAL_HEADER_LEN;
   binlog_version= uint2korr(buf+ST_BINLOG_VER_OFFSET);
   memcpy(server_version, buf+ST_SERVER_VER_OFFSET,
 	 ST_SERVER_VER_LEN);
@@ -4761,7 +4861,7 @@ bool Format_description_log_event::write
   if (!dont_set_created)
     created= get_time();
   int4store(buff + ST_CREATED_OFFSET,created);
-  buff[ST_COMMON_HEADER_LEN_OFFSET]= LOG_EVENT_HEADER_LEN;
+  buff[ST_COMMON_HEADER_LEN_OFFSET]= common_header_len;
   memcpy((char*) buff+ST_COMMON_HEADER_LEN_OFFSET + 1, (uchar*) post_header_len,
          LOG_EVENT_TYPES);
   /*
@@ -4987,9 +5087,9 @@ uint8 get_checksum_alg(const char* buf,
   DBUG_ENTER("get_checksum_alg");
   DBUG_ASSERT(buf[EVENT_TYPE_OFFSET] == FORMAT_DESCRIPTION_EVENT);
 
-  memcpy(version, buf +
-         buf[LOG_EVENT_MINIMAL_HEADER_LEN + ST_COMMON_HEADER_LEN_OFFSET]
-         + ST_SERVER_VER_OFFSET, ST_SERVER_VER_LEN);
+  memcpy(version,
+         buf + LOG_EVENT_MINIMAL_HEADER_LEN + ST_SERVER_VER_OFFSET,
+         ST_SERVER_VER_LEN);
   version[ST_SERVER_VER_LEN - 1]= 0;
   
   do_server_version_split(version, &version_split);
@@ -5861,16 +5961,14 @@ Rotate_log_event::Rotate_log_event(const
 {
   DBUG_ENTER("Rotate_log_event::Rotate_log_event(char*,...)");
   // The caller will ensure that event_len is what we have at EVENT_LEN_OFFSET
-  uint8 header_size= description_event->common_header_len;
   uint8 post_header_len= description_event->post_header_len[ROTATE_EVENT-1];
   uint ident_offset;
-  if (event_len < header_size)
+  if (event_len < LOG_EVENT_MINIMAL_HEADER_LEN)
     DBUG_VOID_RETURN;
-  buf += header_size;
-  pos = post_header_len ? uint8korr(buf + R_POS_OFFSET) : 4;
-  ident_len = (uint)(event_len -
-                     (header_size+post_header_len)); 
-  ident_offset = post_header_len; 
+  buf+= LOG_EVENT_MINIMAL_HEADER_LEN;
+  pos= post_header_len ? uint8korr(buf + R_POS_OFFSET) : 4;
+  ident_len= (uint)(event_len - (LOG_EVENT_MINIMAL_HEADER_LEN + post_header_len));
+  ident_offset= post_header_len;
   set_if_smaller(ident_len,FN_REFLEN-1);
   new_log_ident= my_strndup(buf + ident_offset, (uint) ident_len, MYF(MY_WME));
   DBUG_PRINT("debug", ("new_log_ident: '%s'", new_log_ident));

=== modified file 'sql/log_event.h'
--- a/sql/log_event.h	2013-07-17 19:24:29 +0000
+++ b/sql/log_event.h	2013-07-19 12:09:19 +0000
@@ -1253,6 +1253,7 @@ public:
 #endif
   virtual Log_event_type get_type_code() = 0;
   virtual bool is_valid() const = 0;
+  virtual my_off_t get_header_len(my_off_t len) { return len; }
   void set_artificial_event() { flags |= LOG_EVENT_ARTIFICIAL_F; }
   void set_relay_log_event() { flags |= LOG_EVENT_RELAY_LOG_F; }
   bool is_artificial_event() const { return flags & LOG_EVENT_ARTIFICIAL_F; }
@@ -2469,6 +2470,8 @@ public:
                      const Format_description_log_event* description_event);
   ~Start_log_event_v3() {}
   Log_event_type get_type_code() { return START_EVENT_V3;}
+  my_off_t get_header_len(my_off_t l __attribute__((unused)))
+  { return LOG_EVENT_MINIMAL_HEADER_LEN; }
 #ifdef MYSQL_SERVER
   bool write(IO_CACHE* file);
 #endif
@@ -2984,6 +2987,8 @@ public:
       my_free((void*) new_log_ident);
   }
   Log_event_type get_type_code() { return ROTATE_EVENT;}
+  my_off_t get_header_len(my_off_t l __attribute__((unused)))
+  { return LOG_EVENT_MINIMAL_HEADER_LEN; }
   int get_data_size() { return  ident_len + ROTATE_HEADER_LEN;}
   bool is_valid() const { return new_log_ident != 0; }
 #ifdef MYSQL_SERVER



More information about the commits mailing list