Intermediary slave does not log master changes with binlog_rows_query_log_events

[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.

[Vlad Lesin (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".

[Vlad Lesin (vlad-lesin)]

I was wrong about my supposal 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)

[Vlad Lesin (vlad-lesin)]

See:
https://github.com/vlad-lesin/percona-server/tree/rpl-ibi-lp-1722789-5.6-gca
https://github.com/vlad-lesin/percona-server/tree/rpl-ibi-lp-1722789-5.7-gca

[Vlad Lesin (vlad-lesin)]

https://github.com/percona/percona-server/pull/1997
https://github.com/percona/percona-server/pull/1998

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1119