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.
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
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:
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
-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
I modified my
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:
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!
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.