Bug #68075 mysqlbinlog --verify-binlog-checksum doesn't do that
Submitted: 13 Jan 2013 21:33 Modified: 17 Jan 2013 16:03
Reporter: Andrew Hutchings Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: Command-line Clients Severity:S2 (Serious)
Version:5.6.9-rc OS:Any
Assigned to: Luis Soares

[13 Jan 2013 21:33] Andrew Hutchings
Description:
Verified using a callgrind output.  Then verified using GDB:

Breakpoint 1, Log_event::read_log_event (buf=0x9f2c91 "", 
    event_len=event_len@entry=54, error=error@entry=0x7fffffffc290, 
    description_event=0xa07e50, crc_check=<optimized out>)
    at /home/linuxjedi/Programming/Sources/mysql-5.6.9-rc/sql/log_event.cc:1467
1467	      event_checksum_test((uchar *) buf, event_len, alg))
(gdb) print alg
$1 = 255 '\377'

255 is BINLOG_CHECKSUM_ALG_UNDEF

How to repeat:
Use gdb or callgrind output
[14 Jan 2013 11:58] Andrei Elkin
Andrew,

I could not get what it does not do in the synopsis. Could you please spell it out?

Thanks.

Andrei Elkin
[14 Jan 2013 12:01] Andrei Elkin
Perhaps the point is that the `alg' argument can't be undefined 'cos of
--verify-binlog-checksum presence.
Checking this path.
[14 Jan 2013 12:02] Andrew Hutchings
It doesn't appear to do the crc32 calc on the event to compare with the checksum.
[14 Jan 2013 12:11] Andrew Hutchings
I think you are missing the point entirely.  I'll start from scratch.

* MySQL 5.6 has binlog checksums.
* mysqlbinlog has an flag called --verify-binlog-checksum to verify the checksums whilst it is retrieving the binlogs.
* for this to happen it needs to set BINLOG_CHECKSUM_ALG_CRC32 in the code based on the information FORMAT DESCRIPTION event
* it doesn't do this and sets BINLOG_CHECKSUM_ALG_UNDEF
* this can be seen by the crc32 function not being used
* the crc32 functions should take a large percent of CPU time (in raw mode my estimates are 33-50%) so it would be very obvious in callgrind
* I could provide a patch for you but I'm lazy and already have a tool to do this instead of mysqlbinlog, was just trying to be helpful
[14 Jan 2013 12:18] Andrei Elkin
So I have verified execution to not find anything to worry about.
In fact, `alg' could be computed as UNDEFined 

1454      alg= (event_type != FORMAT_DESCRIPTION_EVENT) ? 
1455        description_event->checksum_alg : get_checksum_alg(buf, event_len..

when the processed binlog is created without checksum.
When the binlog contains checksummed events `alg' is proved to be 1.

Andrew, if you have any follow up please change the bug state that I am updating now.

Thanks.

Andrei
[14 Jan 2013 15:26] Andrew Hutchings
You still don't seem to get the point of this bug, but I'm not going to argue.  I'll let someone else stumble upon this problem, I don't use it in anything important.
[17 Jan 2013 14:21] Luis Soares
Andrew, I was also checked and everything seems correct. Find some details
below.

1. Test case

   --source include/have_binlog_format_statement.inc

   CREATE TABLE t1 (a INT);
   DROP TABLE t1;

2. deploy additional debug info in the function that actually
   verifies the checksum:

=== modified file 'sql/rpl_utility.cc'
--- sql/rpl_utility.cc	revid:tor.didriksen@oracle.com-20130114144956-7xvrq4if9vhkb5dz
+++ sql/rpl_utility.cc	2013-01-17 14:05:27 +0000
@@ -1164,6 +1164,7 @@
       event_buf[FLAGS_OFFSET]= flags;
     }
     res= !(computed == incoming);
+    DBUG_PRINT("debug", ("checksum computed: %u, checksum incoming: %u\n",computed, incoming));
   }
   return DBUG_EVALUATE_IF("simulate_checksum_test_failure", TRUE, res);
 }

3. Run the test case

4. execute mysqlbinlog on the resulting binary log with debug
   enabled and verify-binlog-checksum:
 
   mysqlbinlog --debug --verify-binlog-checksum var/mysqld.1/data/master-bin.000001

   I can see 4 events (in this order):
   1. FORMAT_DESCRIPTION_EVENT
   2. QUERY_EVENT
   3. QUERY_EVENT
   4. STOP_EVENT

5. I can see that the checksum function was called with the
   following results:
 
$ grep "checksum computed" /tmp/mysqlbinlog.trace
| | | | debug: checksum computed: 3627111902, checksum incoming: 3627111902
| | | | debug: checksum computed: 271065174, checksum incoming: 271065174
| | | | debug: checksum computed: 2847202826, checksum incoming: 2847202826
| | | | debug: checksum computed: 2368126294, checksum incoming: 2368126294

So indeed mysqlbinlog verifies checksums. Have you found some use
case scenario where this does not happen?
[17 Jan 2013 14:41] Andrew Hutchings
Yes, but I haven't dug down enough to find out what is different about my setup yet.

I do know my binlogs have checksums from the first event, they are the ones I used to figure out the format changes made in 5.6 including the way checksums were calculated :)

I'll try and dig into it further before next week.
[17 Jan 2013 16:03] Andrew Hutchings
OK,  !Bug correct.  The optimization level it compiled at meant that gdb and valgrind were behaving badly and not catching certain things.  My bad.
[17 Jan 2013 16:04] Luis Soares
No worries. Thanks for investigating.
[20 Jan 2013 18:52] James Day
Andrew, thanks for letting us know what was happening, way better than not knowing. Please keep up the reporting, you won't be so unfortunate every time!

James Day, MySQL Senior Principal Support Engineer, Oracle