Bug #88057 Intermediary slave does not log master changes with binlog_rows_query_log_events
Submitted: 11 Oct 2017 12:42 Modified: 11 Oct 2017 13:57
Reporter: Sveta Smirnova (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Row Based Replication ( RBR ) Severity:S3 (Non-critical)
Version:5.7.19, 8.0.3 OS:Any
Assigned to: CPU Architecture:Any

[11 Oct 2017 12:42] Sveta Smirnova
Description:
Common scenario to reduce IO load on master is to create intermediary slave which uses BLACKHOLE storage engine, specify option log-slave-updates for it and replicate from this intermediary slave to multiple slaves with data.

However, if configuration file on master has option binlog_rows_query_log_events=1 only INSERT statements will be recorded in the binary log of the intermediary slave.

According to the user manual at https://dev.mysql.com/doc/refman/5.7/en/replication-options-binary-log.html#sysvar_binlog_... "The binlog_rows_query_log_events system variable affects row-based logging only. When enabled, it causes the MySQL Server to write informational log events such as row query log events into its binary log. This information can be used for debugging and related purposes; such as obtaining the original query issued on the master when it cannot be reconstructed from the row updates. " It does not say this option should be used for anything, but debugging purpose, therefore I do not see any reason why slave updates are not logged on server B.

How to repeat:
Setup replication chain: A -> B -> C

Create InnoDB table on A.
Convert InnoDB table to Blackhole on B.
Same table on C continue using InnoDB storage engine.

Now modify content on A. INSERT will be recorded correctly, UPDATE and DELETE will be recorded on master, but not on B even if it has option log-slave-updates

I will also attach test case for MTR.
[11 Oct 2017 12:42] Sveta Smirnova
test case for MTR

Attachment: rpl_i207449.test (application/octet-stream, text), 852 bytes.

[11 Oct 2017 12:42] Sveta Smirnova
configuration file

Attachment: rpl_i207449.cnf (application/octet-stream, text), 542 bytes.

[11 Oct 2017 13:57] Umesh Shastry
Hello Sveta,

Thank you for the report and test case.
Observed as described on 5.7.19 build.

Regards,
Umesh
[29 Nov 2017 12:18] Vlad Lesin
Let's consider the following backtrace in 5.7:

#0 ha_blackhole::update_row (this=0x7fff9c00eec0, old_data=0x7fff9c010040 "\371\002", new_data=0x7fff9c010030 "\371\002")
    at ./storage/blackhole/ha_blackhole.cc:121
#1 0x0000000000fd8372 in handler::ha_update_row (this=0x7fff9c00eec0, old_data=0x7fff9c010040 "\371\002", new_data=0x7fff9c010030 "\371\002")
    at ./sql/handler.cc:8479
#2 0x00000000018ee9f3 in Update_rows_log_event::do_exec_row (this=0x7fff9c01deb0, rli=0x3915b80)
    at ./sql/log_event.cc:12974
#3 0x00000000018e5f43 in Rows_log_event::do_apply_row (this=0x7fff9c01deb0, rli=0x3915b80) at ./sql/log_event.cc:10048
#4 0x00000000018e6fe0 in Rows_log_event::do_index_scan_and_update (this=0x7fff9c01deb0, rli=0x3915b80)
    at ./sql/log_event.cc:10442
#5 0x00000000018e91a1 in Rows_log_event::do_apply_event (this=0x7fff9c01deb0, rli=0x3915b80) at ./sql/log_event.cc:11232
#6 0x00000000018cfe7c in Log_event::apply_event (this=0x7fff9c01deb0, rli=0x3915b80) at ./sql/log_event.cc:3447
#7 0x000000000194be2b in apply_event_and_update_pos (ptr_ev=0x7ffff10ff8a0, thd=0x7fff9c000950, rli=0x3915b80)
    at ./sql/rpl_slave.cc:4762
#8 0x000000000194d5f3 in exec_relay_log_event (thd=0x7fff9c000950, rli=0x3915b80) at ./sql/rpl_slave.cc:5277
#9 0x00000000019549df in handle_slave_sql (arg=0x38bf6f0) at ./sql/rpl_slave.cc:7488
#10 0x0000000001e7e80d in pfs_spawn_thread (arg=0x7fffa00768a0) at ./storage/perfschema/pfs.cc:2188
#11 0x00007ffff6f5e6ba in start_thread (arg=0x7ffff1100700) at pthread_create.c:333
#12 0x00007ffff63f33dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

and ha_blackhole::update_row():

int ha_blackhole::update_row(const uchar *old_data, uchar *new_data)
{
  DBUG_ENTER("ha_blackhole::update_row");
  THD *thd= ha_thd();
  if (is_slave_applier(thd) && thd->query().str == NULL)
    DBUG_RETURN(0);
  DBUG_RETURN(HA_ERR_WRONG_COMMAND);
}

So in the case if this function is invoked from slave thread and it's query string is empty, then it's supposed the function finishes successfully, otherwise some error is returned. The same logic exists in some other blackhole engine functions.

If "binlog_rows_query_log_events = 1" binary log contains events with queries. The queries are ignored, but during "Rows_query_log_event" event execution (see Rows_query_log_event::do_apply_event() ) thread query string is filled with the query from the event. And when then Update_rows_log_event::do_exec_row() is executed, sql thread has query in thd->m_query_string, and this condition:

  is_slave_applier(thd) && thd->query().str == NULL

becomes false, what leads to errors during execution of blackhole engine functions such as ha_blackhole::update_row(). Such errors are output to error log and sql thread stops, as a result is't binary log is not filling.

The question is what does this "is_slave_applier(thd) && thd->query().str == NULL" condition mean? I suppose the condition means that binlog format is "row".

So would propose the following fix: to replace "thd->query().str == NULL" with "thd->variables.binlog_format == BINLOG_FORMAT_ROW".
[5 Dec 2017 18:41] Vlad Lesin
I was wrong about my suggestion of what does the condition "is_slave_applier(thd) && thd->query().str == NULL" mean. This condition is not about binlog format, but it is about currently processed relay log event type. The type must not be "QUERY_EVENT". That is why the above condition must be replaced with:

 is_slave_applier(thd) &&
 (thd->rli_slave->rows_query_ev || thd->query() == NULL)

to allow process binlog events correctly on slave if binlog_rows_query_log_events=1 on master.
[16 Jan 13:59] Vlad Lesin
the fix

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: 1.diff (text/x-patch), 9.75 KiB.

[2 Feb 7:33] Laurynas Biveinis
Bug 88057 fix for 8.0.4 by Vlad Lesin

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: bug88057-8.0.4.patch (application/octet-stream, text), 11.62 KiB.

[13 Jun 12:32] Laurynas Biveinis
Bug 88057 fix for 8.0.11 by Vlad Lesin

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: bug88057-8.0.11.patch (application/octet-stream, text), 11.61 KiB.