2

I am replicating my binlog files to a secondary server using the mysqlbinlog --stop-never --read-from-remote-server flags. If the primary database server is compromised I want to replay the binlogs on the remote server, but I'm having trouble with the "current" binlog.

When using mysqlbinlog to convert it to SQL I always get an error like:

ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 2682, event _type: 2 ERROR: Could not read entry at offset 4426095: Error in log format or read error

I'm assuming that this issue is related to the fact that this binlog file hasn't been closed or flushed on the main database server. I do not have this problem on the file after running flush logs on the main database server.

So, my question is this: If the main database server is compromised and I'm unable to run flush logs, only having access to the binlog files that were replicated to a remote server. How can I clean up, close or flush that binlog that was open at the time of a DB outage event?

  • I don't think it's because it hasn't been closed or flushed on the main database server. If that, slaves would always be at least one event behind the master in low traffic periods, which doesn't happen. Clarifications: "secondary server" is not running MySQL, just capturing the binlog stream with mysqlbinlog? "Current" binlog... playing back the one that's streaming now, with a 2nd invocation of mysqlbinlog, while still capturing? Or what state is the remote capture process in when you test this? Running? Failed (error)? Killed/stopped (e.g. with SIGINT/SIGTERM/SIGKILL)... or ? – Michael - sqlbot Sep 9 '16 at 20:15
  • Secondary server does have mysql server installed but not running. It is simply running mysqlbinlog --never-stop. "Current" binlog refers to the one streaming now. State is copying the file to a temp location while it is actively streaming then converting that copied file to sql which gives the error. Must the replication be stopped and restarted during this copy process? Or is there a hot copy process? How do you cleanly stop a --never-stop mysqlbinlog process? – bwizzy Sep 10 '16 at 1:05
  • Good questions. I think there are actually two issues here, one being that mysqlbinlog seems to do some kind of buffered disk writes, and the other being that copying the live file is always going to be potentially similar to a crash of the master... and you can't flush/close/rotate it the same way you can with an actual slave server, because a slave doesn't quite clone the binlog byte for byte, like mysqlbinlog does -- because the slave wraps the master log content with its own relay log structures. I'm reviewing the source and toying with a couple of theories, then will post an answer. – Michael - sqlbot Sep 10 '16 at 4:44
2

Flushing the log on the master solves your problem pretty much by accident. When the master log file rotates, mysqlbinlog closes the current file and opens the next one, which implicitly flushes any buffered data.

You can't trigger mysqlbinlog to flush its log on demand the way you can an actual server, but I've found a way to trigger it to maintain the file in an always flushed state, which seems to be a viable way to improve your results.

When Oracle added the --raw option to mysqlbinlog, which, in conjunction with --read-from-remote-server and --stop-never can be used to capture a real-time backup of the master's binlogs, they overlooked at least a couple of seemingly-obvious things.

In light of the documented purpose of the feature...

The --raw option can be used to make a backup of a server's binary log. With the --stop-never option, the backup is “live” because mysqlbinlog stays connected to the server.

https://dev.mysql.com/doc/refman/5.6/en/mysqlbinlog.html#option_mysqlbinlog_raw

...it seems like a distinct oversight that mysqlbinlog does not bother to flush its output stream after each write.

Maybe that's why they put “live” in quotes. :)

My testing confirms that mysqlbinlog, as shipped, leaves dangling data in its buffer that could have been flushed, but this seems like a fairly straightforward problem to fix.

For example, this little change in mysql-5.6.27/client/mysqlbinlog.cc at line 2477:

2477c2477
<         if (my_fwrite(result_file, net->read_pos + 1 , len - 1, MYF(MY_NABP)))
---
>         if (my_fwrite(result_file, net->read_pos + 1 , len - 1, MYF(MY_NABP)) || fflush(result_file))

This change results in the size of the file created by mysqlbinlog continually matching the size returned by SHOW MASTER STATUS;, rather than always seeming to be a few bytes behind. I've always known of this slight lag, but never looked into it in depth. Of course, continually flushing the buffer is going to come with a cost, but this seems like a non-negotiable necessity for "backup" purposes. Note that this is only a flush of the user space buffers, it's not an fsync() or similar, so I don't think it's going to be that different in performance terms... and in any event, it's not going to impact the master.

The logical || is used because my_fwrite() returns 0 on success, so we short-circuit and don't try to flush if that fails, and we error out if either operation fails, since fflush() also returns 0 on success.

This change should significantly improve the behavior you see.

Of course, it's still always possible for you to end up with an incomplete log, since it's still an open file and still being written to... but when testing this fix in a low traffic environment, hot-copying the file results in a usable binlog for me -- while, otherwise, in the same environment, the file end is almost always incomplete when using the stock binary.

For different versions (of 5.6+ only -- this feature wasn't implemented at all before 5.6) the line in the source may be different but it should still be pretty easy to spot, and not far from the line numbers indicated here.

Facebook's fork of MySQL 5.6 features a similar but more sophisticated fix, and a new option --flush-result-file that causes the flushing to be a little less aggressive, but configurable. However, I found it unnecessarily difficult to compile in its current form, so I developed the little patch above.


As long as you're patching mysqlbinlog, you might find another small tweak useful for solving another design oversight. The mysqlbinlog utility in the official distribution lacks support for the --compress command line option (although Percona had the good sense to add it to theirs.)

But, it's also easy enough to enable compression. I just came up with the fix above for this question, but I've been using the fix, below, for quite some time now, since -- again -- it has always seemed to me like an obviously missing feature.

From the 5.6.27 source, it looks like this:

1948c1948
<   if (!mysql_real_connect(mysql, host, user, pass, 0, port, sock, 0))
---
>   if (!mysql_real_connect(mysql, host, user, pass, 0, port, sock, CLIENT_COMPRESS))

This change doesn't enable support for passing the --compress command line option -- it just turns on the client compression protocol on the connection to the master, for any master that supports it (which they essentially all do), thereby reducing the amount of network bandwidth needed to transport the logs -- sometimes by a factor of 10:1 or higher, depending on the specific payload. It does not change the contents of the generated files -- it just enables compression of the data traversing the network. On the wire, this has the same effect from the master's perspective as enabling slave_compressed_protocol on the slave server. (The documentation is ambiguous, but this setting has no effect on the master unless the master is also a slave of another server.)

  • Wow. I never expected such an in depth answer. Thanks! – bwizzy Sep 11 '16 at 1:30
  • Happy to help, @bwizzy. I'm rolling out the fflush() change into one of my systems tonight. Let me know how it works out for you. Also, greetings from Covington (KY). – Michael - sqlbot Sep 11 '16 at 3:33
  • Nice to see someone so helpful so close! Any tips on compiling? I've made the source changes but cmake keeps failing me: pastebin.com/RALpQn6t – bwizzy Sep 11 '16 at 21:14
  • Do you have GNU C++ (g++) installed? Ubuntu or CentOS? – Michael - sqlbot Sep 11 '16 at 23:35
  • 1
    Thanks for the binary! I also got it compiled on a fresh install of 14.04. Thanks SO much for all your help. Hope sqltot gets to feeling better! – bwizzy Sep 19 '16 at 2:22

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.