My unfortunate adventure reading MySQL binlog with Ruby

I’ve been really interested by the idea of live queries with GraphQL. This would mean being able to mark certain fields as live and receive updates realtime updates as the underlying data changes.

The concept sounds really fun on the client side, but is quite complex on the server side. A reactive data layer (for example RethinkDB) can make the task easier. Since I’ve mostly been playing and working with Rails GraphQL APIs that are mostly communicating to a MySQL datastore, I wanted to explore if it was possible to “fake” MySQL as a reactive datastore using its binlog (binary logs).

My first idea was to write a layer between mysql and rails that would read the binlog and using that be able to be reactive, but I wanted something even simpler to play around, I decided to read the binlog using a side process in ruby, and notify the rails app when things would change.

For the ones that expect to read how the GraphQL project ended up, you’ll have to wait til a bit later, this post will describe my unfortunate adventure with ruby-binlog, and how I debuged my way through until I was able to read events.

Enter ruby-binlog

My first step was to write a super simple ruby script that would output all binlog events to STDOUT, sounds simple right? So I thought. The first gem I found was ruby-binlog. To my surprise, it was pretty much the only one. I installed the gem and got started with a simple script heavily inspired from the readme:

In the above snipped, I’m connecting the binlog client to my local instance of mysql. I set the initial position at the beginning of the binary log, and start waiting for events.

I also knew I had to configure mysql to start dumping events into the binary log file, I added these lines to my my.cfn file:

log-bin=mysql-bin # dump events in a file like mysql-bin.00001
binlog_format=ROW # Indicates we're interested in row based logging (https://dev.mysql.com/doc/refman/5.7/en/binary-log-setting.html)

I restarted mysql and then, expecting great results, here’s what I got when I ran the script:

Super useful error message

No don’t go away MySQL! What could that possible mean? I looked at my MySQL server logs to see if I could get a little bit more information on what happened.

Ok, I guess that’s slightly better. Something clearly went wrong between ruby-binlog’s client and my MySQL server instance. However I was still confused on the `error reading communication packets` part. Was my ruby client sending malformed data?

I searched online for that error and a bunch of stuff surfaced. It could be a number of things.

tcpdump to the rescue

I decided to run tcpdump to see what was going wrong between my client and MySQL. tcpdump is a command line tool to inspect TCP traffic, the cool thing is that you can run it on your local network interface, and that was perfect for my use case:

Here I ask tcptump to listen to my local network interface lo0 for the port 3306 (MySQL port) and to write the raw packets to a file called tcp.out

Since -w writes raw binary data to the file and I simply wanted to look for an error string, I ran strings tcp.out which gave me an output like this:

Notice the error hidden in there?

#HY000 A slave with the same server_uuid/server_id as this slave has connected to the master; the first event 'mysql-bin.000007' at 852, the last event read from './mysql-bin.000007' at 123, the last byte read from './mysql-bin.000007' at 852.q

I looked up this server_id problem and I found out it’s actually a very important option for reading the binlong: https://dev.mysql.com/doc/refman/5.7/en/replication-options.html#option_mysqld_server-id

The server_id option is used for replicas and the master of a database to differentiate themselves. Even though my naive client is not a mysql replica, it acts as one when trying to read the binlog. Since I had not configured a server_id on my mysql database locally, they both had a server_id of 0.

I modified my my.cnf again:

log-bin=mysql-bin
binlog_format=ROW
server_id=1

I ran my client again… and got the exact same error:

I was well equiped to handle the error this time. I ran tcpdump again and found a new error hidden in there:

#HY000 Slave can not handle replication events with the checksum that master is configured to log; the first event 'mysql-bin.000005' at 154, the last event read from './mysql-bin.000005' at 123, the last byte read from './mysql-bin.000005' at 123.

I discovered that beginning with MySQL 5.6.6, the master writes checksums for every event written the the log. I began to lose trust into the ruby gem I was using. Turns out it was written quite a long time ago, before the checksums were added. I had to add this to my mysql config to make it work:

log-bin=mysql-bin
binlog_format=ROW
server_id=1
binlog_checksum=NONE

This removes the checksum but at this point I really just wanted to see if I could make it work.

I ran the script again and finally, I was reading the binlog!

We did it!

I investigated this Unkown event, and found out that the c library that ruby-binlog is using is also outdated, and the enum with the event types did not match my mysql version.

It’s fair to say I was pretty bummed out about the state of things in the ruby world as far as reading the binlog goes, but it’s not a big deal. There are some great alternatives out there and I’ll explore them further when I write that GraphQL/mysql reactive layer.

Stay tuned for the next part! In the meantime you can follow me on twitter, or check out my code.

👋