Please see ftp.askmonty.org:/private/MDEV-15660.txt.gz

I do still have the binary logs, but will not be able to share them in entirety.

I can confirm that this issue also exists with MariaDB 10.1.9. We have done several test but the only thing fixing the issue was rebooting the master server.

The following things were tested to see if it would fix the issue:

• Restore a slave from a backup before the start of the problem and staring the replication on this slave again. This was find until the exact same point where the replication broke before. At that same point the replication broke again.
• We created a new backup from the running master server. We restored this to a slave and started the replication. This slave did not replicate any row based data.
• We did a reset master on the master hoping this would fix the issue. This didn't work either.

In the end we decided to take the down time by restarting the MariaDB process on the master node. At first we thought this worked, but then we found out something else.

The backup we created to restore the slave was created with xstrabackup, this tools works just fine but it looks like the backup was corrupt. We created this backup before we restarted MariaDB, and the only thing we can think of is that the backup was created from a corrupted memorystate of the master which results in a corrupted backup. After creating a new backup after MariaDB was rebooted we were able to use this new backup to start our slaves again. This new backup was created using a DB wide lock and filesystem snapshot.

I had the issue again on one of my clusters, but this time everything was replicating fine except for some databases that were created in the last couple of weeks. Resyncing this cluster now using a snapshot of the master and upgrading to 10.1.32 at the same time. The future will tell me if the problem will manifest itself again.

Is there any progress on this bug?

@Jan perhaps you are using binlog_format=MIXED?

I am trying to guess why you would have some affected databases but not all. It could be that the newer databases use SQL that is deemed "unsafe" for STATEMENT logs, and thus ROW events are generated (seemingly incorrectly)

Also, the xtrabackup would have almost certainly worked if it was taken after your service restart but the problematic events happening during/after the backup (before the restart) would have resulted in the slave still having missing records or errors like HA_ERR_KEY_NOT_FOUND

(colleague of Jan here)
To answer your questions:

• The binlog_format is ROW.
• Both machines in the cluster were still running on 10.1.9 when this happened. Both machines are now upgraded to 10.1.32 and the replication works for now.

We have updated all clusters to 10.1.32. One of the clusters has had several occurrences of this problem over the last couple of weeks. Actually, the last couple of weeks we had the problem about once a week.

We have also seen that one table within a database can replicate just fine, while a different table in the same database has stopped.

The replication of a table stops at an undefined moment and during a longer period of time several tables stop replicating at random times.

We are currently in a situation where this bug (or a bug very similar to this one) is happening in one of our clusters every 7-10 days. Last week we upgraded this cluster to 10.3.9. Unfortunately, the upgrade van 10.1.32 -> 10.3.9 did not fix the problem.

Around Nov 15 07:50 the replication started failing.

Our setup is as follow:

• We have 2 dataservers in a active-passive master-master setup.Server_ids are 31 and 32. gtid_domain_id is 50 for both.
• The servers are both running MariaDB 10.3.9 on CentOS 7.2. MariaDB CentOS packages sourced directly from mariadb.org
• This cluster is mainly used to log events. As such it generates lot of inserts each day. These are replicated using row-based replication.
• Log-slave-updates is set to 1
• There is also a cleanup-tasks which deletes old entries every X minutes. These deletes are done with batches which are replicated with statement based replication.
• A backup of all tables is made at 0:00 each day. At the start of the backup, the slave-thread is stopped with STOP ALL SLAVES. The slave is started again at the end of the backup with {{START ALL SLAVES}.

The output from journalctl -u mariadb shows some curious repetitive entries:

Nov 16 11:35:59 logdb01 mysqld[1402]: 2018-11-16 11:35:59 27 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000576' at position 596377893; GTID position '50-31-5900115308'
Nov 16 11:37:00 logdb01 mysqld[1402]: 2018-11-16 11:37:00 27 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000576' at position 596377893; GTID position '50-31-5900115308'
Nov 16 11:38:00 logdb01 mysqld[1402]: 2018-11-16 11:38:00 27 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000576' at position 596377893; GTID position '50-31-5900115308'
Nov 16 11:39:00 logdb01 mysqld[1402]: 2018-11-16 11:39:00 27 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000576' at position 596377893; GTID position '50-31-5900115308'

Summarizing this output for a few days gives this pattern:

Nov 10 01:00:24 --> 02:51:10 : Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000240' at position 495209610; GTID position '50-31-5852024257'
Nov 10 02:51:27 : Start binlog_dump to slave_server(32), pos(logdb01-bin.040246, 574763437)
Nov 11 00:06:02 --> 02:50:01 : Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000298' at position 412739340; GTID position '50-31-5860321432'
Nov 11 02:50:57 : Start binlog_dump to slave_server(32), pos(logdb01-bin.040304, 487477542)
Nov 12 00:06:02 --> 02:48:45 : Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000362' at position 215905447; GTID position '50-31-5868650197'
Nov 12 02:49:06 : Start binlog_dump to slave_server(32), pos(logdb01-bin.040368, 310197093)
Nov 13 00:06:02 --> 02:46:01 : Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000428' at position 478769480; GTID position '50-31-5877121125'
Nov 13 02:46:13 : Start binlog_dump to slave_server(32), pos(logdb01-bin.040434, 568169403)
Nov 14 00:06:02 --> 02:51:52 : Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000498' at position 952798855; GTID position '50-31-5885611450'
Nov 14 02:52:48 : Start binlog_dump to slave_server(32), pos(logdb01-bin.040504, 1020925762)
Nov 15 00:06:03 --> 02:48:19 : Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000565' at position 642216759; GTID position '50-31-5894087756'
Nov 15 02:48:43 : Start binlog_dump to slave_server(32), pos(logdb01-bin.040571, 715251146)
Nov 15 07:4?:?? !!! START OF PROBLEM !!!
Nov 15 08:47:38 --> 17:15:05 : Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000576' at position 596375056; GTID position '50-31-5900098745'
Nov 15 17:17:50 --> 02:41:40 : Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000576' at position 596377893; GTID position '50-31-5900115308'
Nov 16 02:42:18 : Start binlog_dump to slave_server(32), pos(logdb01-bin.040637, 957717610)
Nov 16 02:42:41 --> 11:39:00 : Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000576' at position 596377893; GTID position '50-31-5900115308'
End of Log

I can demonstrate the nature of the problem by running this code on master (it's no reproduction):

DROP TABLE IF EXISTS `foo`;

CREATE TABLE `foo` (

                `id` int(11) NOT NULL AUTO_INCREMENT,

                `key` varchar(255) NOT NULL,

                `value` varchar(255) NOT NULL,

                PRIMARY KEY (`id`)

                ) ENGINE=InnoDB DEFAULT CHARSET=utf8;

INSERT INTO `foo` (`key`, `value`) VALUES ('k1', 1);

SET SESSION binlog_format = 'STATEMENT';

INSERT INTO `foo` (`key`, `value`) VALUES ('k2', 2);

SELECT * FROM foo;

Which produces the following content of the table "foo":

+----+-----+-------+

| id | key | value |

+----+-----+-------+

|  3 | k1  | 1     |

|  8 | k2  | 2     |

+----+-----+-------+

On the slave the content of this table is:

+----+-----+-------+

| id | key | value |

+----+-----+-------+

|  8 | k2  | 2     |

+----+-----+-------+

I have made:

• an export of the binlog on the master with mysqlbinlog -v --database=test logdb01-bin.040849 > master-bin.sql
• an export of the relaylog on the slave with mysqlbinlog --database=test -v logdb02-relay-bin.000070 > slave-relay-bin.sql
• an export of the binlog on the slave with mysqlbinlog --database=test -v blslogdb02-bin.000576 > slave-bin.sql
  Those 3 files I will attach shortly in this ticket.

I find it interesting that the first INSERT shows in the relay-log of slave, but isn't applied by the slave. Also interesting that only a restart of the MariaDB-process on the master fixes the problem. A RESET SLAVE on slave, or RESET MASTER on master will not fix the situation.

If more information is needed to debug this problem, let me know.

reinder,

In your case we see errors by the slave IO (receiver) thread like

Nov 15 00:06:03 --> 02:48:19 : Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000565' at position 642216759; GTID position '50-31-5894087756'

Could you clarify whether the reconnecting succeeded so the slave resumed automatically?

When this is the case perhaps the error could be caused by MDEV-17133 reason where the Dump thread
could not read event properly being screwed in its reading-from-binlog position.
That bug fixes are not yet in 10.3.

This looks to me to be the same problem originally reported (randomly, rbr events stop affecting the slave while sbr events continue to affect slave / no effect of rbr event via mysqlbinlog | mysql)

I find it interesting that the first INSERT shows in the relay-log of slave, but isn't applied by the slave.

Yes, this is the problem / two problems:

1) Master generates problematic RBR which has no effect (eg it traverses master binary log, gets in to slave relay log, sql thread does nothing with this event silently ignoring it or you issue mysqlbinlog | mysql on a backup and it does not modify rows). In my case, after a certain point, all RBR are impotent until the master was restarted and this abrupt breakage happened within a single binary log.

2) The slave / BINLOG() event is impotent but there is no error such as "no rows modified" (such a check may be too expensive to implement)

Regarding the "Slave I/O thread: Failed reading log event" - this is probably due to STOP ALL SLAVES though I was not familiar with the syntax nor did I test this. I guess your backup takes two hours. It seems strange to need to STOP ALL SLAVES when taking a backup vs STOP SLAVE or just use a non-blocking backup like mariabackup. This is based on my quick read about STOP ALL SLAVES which seems to write a binlog event that causes a slave to stop via the binary log (keep in mind that you use circular replication so this event probably replicates back and may not consider server-id). Again all of this is speculation on my part.

Could you clarify whether the reconnecting succeeded so the slave resumed automatically?

The slave connects normally.

I did some more observations on these log-entries today:
When I see this log-entry on the active master (logdb01):

Nov 20 13:24:10 logdb01 mysqld[1402]: 2018-11-20 13:24:10 27 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'logdb02-bin.000576' at position 596384668; GTID position '50-31-5938052151'

Then I see these log-entries on the passive master (logdb02):

Nov 20 13:24:10 logdb02 mysqld[22595]: 2018-11-20 13:24:10 5570891 [Note] Start binlog_dump to slave_server(31), pos(logdb02-bin.000576, 596384668)
Nov 20 13:24:10 logdb02 mysqld[22595]: 2018-11-20 13:24:10 5570536 [Warning] Aborted connection 5570536 to db: 'unconnected' user: 'replication' host: 'logdb01.xxx' (A slave with the same server_uuid/server_id as this slave has co)

Also the tcp-connection from logdb01 to logdb02:3306 gets replaced by another tcp-connection.

@MG STOP ALL SLAVES works like STOP SLAVE but for all slave-connections when you have a multi source replication. I don't see anything mentioned in documentation about writes into binlog events. Stopping slave activity makes it possible to take a single point in time backup using parallel mysqldump-processes (one for each table). It also prevents locks from the mysqldump-processes to weirdly interact with the locks generated by the slave-threads.

Got it - thanks. I was looking at a different implementation of STOP ALL SLAVES (not mariadb). This is just for MSR / replication channels to stop each of the connections to various masters when run on a given slave.

reinder, MG

If I understood the case correctly it is an 'impotent' Write_rows_log_event out of
INSERT INTO `foo` (`key`, `value`) VALUES ('k1', 1) that gets ignored by slave.

I see you could not reproduce it. But it seems to relate to the fact that this Write event immediately follows CREATE.
What are slave_parallel_mode and slave_parallel_workers? If it's a parallel mode, we may suspect parallelization.

In my case, I saw the problem:

• Replication slave with slave_parallel_threads=0
• Restore backup, and then pipe mysqlbinlog to mysql cli

In either case, no rows would be affected by Write_rows/Update_rows/Delete_rows events (eg there is an Annotate_rows event) but SBL logged events (eg they have SET TIMESTAMP / SET session.sql_mode) such as DDL would replicate/apply via mysqlbinlog.

This workload does use a lot of DDL (CREATE/TRUNCATE/DROP) and most often via SP.

Within the SP you would see the CREATE/DROP effects on the slave but the table would remain empty (the INSERT logged after Table_map/Write_rows had no effect)

MG,

so any parallel slave issue is ruled out. I am still trying to build a picture of what happened.
To

• Replication slave with slave_parallel_threads=0
  you state Row-foramt events are not applied (though received and relay-logged - I assuem), and 'such as DDL would replicate'. Notice the latter simply can't be in Row format. But reinder 's comments claim
  the STATEMENT format INSERT worked out on slave.

Can you confirm that not only DDL:s but DML:s as well are potent?

I have not tried UPDATEs, but I can confirm that INSERTs and DELETEs are working when using statement based replication.

I have restarted the logdb01 on Tuesday, en resynchronised everything on logdb02 again. I expect replication to fail again next week. If you have any suggestions of instrumentation/debugging/sniffing/etc I might enable on these servers, then I can try to add those.

The current slave-settings on the servers:
logdb01 (active master):

MariaDB [(none)]> show variables like 'slave_%';

+----------------------------------+----------------+

| Variable_name                    | Value          |

+----------------------------------+----------------+

| slave_compressed_protocol        | OFF            |

| slave_ddl_exec_mode              | IDEMPOTENT     |

| slave_domain_parallel_threads    | 0              |

| slave_exec_mode                  | STRICT         |

| slave_load_tmpdir                | /DataBases/tmp |

| slave_max_allowed_packet         | 1073741824     |

| slave_net_timeout                | 60             |

| slave_parallel_max_queued        | 67108864       |

| slave_parallel_mode              | optimistic     |

| slave_parallel_threads           | 20             |

| slave_parallel_workers           | 20             |

| slave_run_triggers_for_rbr       | NO             |

| slave_skip_errors                | OFF            |

| slave_sql_verify_checksum        | ON             |

| slave_transaction_retries        | 10             |

| slave_transaction_retry_errors   | 1213,1205      |

| slave_transaction_retry_interval | 0              |

| slave_type_conversions           |                |

+----------------------------------+----------------+

logdb02 (passive master):

MariaDB [(none)]> show variables like 'slave_%';

+----------------------------------+----------------+

| Variable_name                    | Value          |

+----------------------------------+----------------+

| slave_compressed_protocol        | OFF            |

| slave_ddl_exec_mode              | IDEMPOTENT     |

| slave_domain_parallel_threads    | 0              |

| slave_exec_mode                  | STRICT         |

| slave_load_tmpdir                | /DataBases/tmp |

| slave_max_allowed_packet         | 1073741824     |

| slave_net_timeout                | 60             |

| slave_parallel_max_queued        | 67108864       |

| slave_parallel_mode              | optimistic     |

| slave_parallel_threads           | 20             |

| slave_parallel_workers           | 20             |

| slave_run_triggers_for_rbr       | NO             |

| slave_skip_errors                | OFF            |

| slave_sql_verify_checksum        | ON             |

| slave_transaction_retries        | 1000           |

| slave_transaction_retry_errors   | 1213,1205      |

| slave_transaction_retry_interval | 0              |

| slave_type_conversions           |                |

+----------------------------------+----------------+

As predicted, replication from logdb01 to logdb02 has failed yesterday. Because it is so predictable, I have the opportunity to add extra monitoring.

@Andrei Elkin

From my initial comment in this report:

By default for a new session, binlog_format=ROW and tx_isolation='READ COMMITTED'

<SNIP>

The simplest statement which did not replicate, was:

mysql <<< "replace into replmon.hb (id, hb) values (1, now())"

If I created a session and, before issuing the above, changed tx_isolation to repeatable with binlog_format=statement, the command would correctly replicate.

I put neutrally as 'relates' while being sure it's a duplicate.

mg], reinder By all the symptoms this case is a duplicate of MDEV-17803.
No error on the slave and table_id > MAX_UINT32. You can try out patch committed for MDEV-17803 and report if it helps. I am rebasing it to 10.0 and pushing soon.

Keeping the ticket active until you have confirmed.

@Andrei I think it's plausible that the bug described in MDEV-17803 is indeed the problem here. Currently we restart the logdb01 two times per week in a controlled/automated way. Inspecting the binary logs before the last restart showed me that the highest table_id after an uptime of 4 days is 1890093310. This means that it takes this server around 9 days to reach MAX_UINT32, which is around the time it takes for our replication to fail.

1.9b table_ids is absurdly high for only 4 days, so we went investigating what the reason for this could be. We suspect that the open_table_cache is too small for this server:

• select count( * ) from information_schema.tables; --> 2007
• select @@table_open_cache; --> 2000
• show status like 'Open_tables'; --> 2000
  Combined with activity on most (all?) tables, and some tmp-tables, we can imagine that a lot of tables are getting reopened all the time.

So increasing the variable table_open_cache should prevent the bug from manifesting itself on this server (and help a little in performance).

@Andrei - This does seem to be a duplicate of MDEV-17803 to me, as the binary log in which events became "impotent" midstream, contains:

# awk '$1 ~ /^#18/ && /Table_map/ && ($NF) <= 4294967295' mariadb-bin.072568.txt | wc -l

95939

# awk '$1 ~ /^#18/ && /Table_map/ && ($NF) > 4294967295' mariadb-bin.072568.txt | wc -l

56181

@Andrei - Can you confirm that the patch only needs to be applied on the slave? Because if I read the bug-report in MDEV-18175 correctly this is a bug on the slave-side.

reinder, yes, it's the slave side as you can see from patches committed to the parent bug. Although
the patch also fixes a relating issue of the 32bit platform which is on master. I am about to push the two part patch.

We didn't succeed in building an installable rpm-package for our CentOS7 machines. When you have a release candidate build of the 10.3-series, I'd like to test it.

In the meantime we have succeeded in eliminating a few causes for wildly increasing table_ids, and see no more replication-problems.

reinder, the bugfix is upcoming soon with a new releases, see https://jira.mariadb.org/secure/Dashboard.jspa.

Thank you for practical recommendation of yours

So increasing the variable table_open_cache should prevent the bug from manifesting itself on this server (and help a little in performance).

Closed as duplicate.

Fixes cce2b45c8f5 are pushed.