Something peculiar: On the master, there seems to be a spurious binary log file with a number above the currently active file:
-rw-rw---- 1 mysql mysql 49803428 Jun 5 02:20 mysql-bin.000280
|
-rw-rw---- 1 mysql mysql 44791360 Jun 6 02:20 mysql-bin.000281
|
-rw-rw---- 1 mysql mysql 5312113 Jun 6 07:20 mysql-bin.000282
|
-rw-rw---- 1 mysql mysql 397 Jun 6 02:20 mysql-bin.000283
|
The current log file is mysql-bin.000282, but for some reason, there's an extra file after this, with the following contents:
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
|
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
|
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
|
DELIMITER /*!*/;
|
# at 4
|
#190606 2:20:08 server id 3 end_log_pos 256 CRC32 0xf0dbe055 Start: binlog v 4, server v 10.4.5-MariaDB-1:10.4.5+maria~bionic-log created 190606 2:20:08 at startup
|
ROLLBACK/*!*/;
|
# at 256
|
#190606 2:20:08 server id 3 end_log_pos 331 CRC32 0xa2407dd0 Gtid list [2-2-3953073486,
|
# 0-1-11,
|
# 3-3-72779369]
|
# at 331
|
#190606 2:20:08 server id 3 end_log_pos 374 CRC32 0x6669bd6d Binlog checkpoint mysql-bin.000283
|
# at 374
|
#190606 2:20:08 server id 3 end_log_pos 397 CRC32 0x0ecb66aa Stop
|
DELIMITER ;
|
# End of log file
|
ROLLBACK /* added by mysqlbinlog */;
|
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
|
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
|
A fresh snapshot of the binary log file state on the master:
12124936 Jun 17 02:20 mysql-bin.000292
|
62660952 Jun 18 02:20 mysql-bin.000293
|
8804357 Jun 18 07:49 mysql-bin.000294 <= This is the active log file (from SHOW MASTER STATUS)
|
397 Jun 18 02:20 mysql-bin.000295 <= An extra, dangling file seems to be produced every time the log rotates
|
1024 Jun 18 02:20 mysql-bin.index <= The index file contains a reference to the extra, dangling log file
|
35 Jun 18 02:20 mysql-bin.state
|
The problem persists, but in a slightly different form: Now, when the log files on the master rotate, the slave resumes from position 4 in the old log file, resulting in duplicate key errors. We resolve this on a daily basis by manually resetting the slave to the next log file, e.g. by:
STOP SLAVE;
|
RESET SLAVE;
|
CHANGE MASTER TO MASTER_LOG_FILE = 'mysql-bin.000294', MASTER_LOG_POS = 4;
|
START SLAVE;
|
crishoj Thanks for the report!
The problem resists - does the same Stop event shows up in the last (indexed) binlog?
I suspect it is.
Stop event must be caused by shutdown?
Could you also please paste mysqlbinlog output from the slave relay log files? Specifically I am interested what is near Stop event in there.
It looks like the master tries sending out something even after Stop event. I'll be looking into that attentively
once I hear from you.
Cheers.
Status on the slave:
Master_Log_File: mysql-bin.000295
|
Read_Master_Log_Pos: 374
|
Relay_Log_File: relay-bin.000004
|
Relay_Log_Pos: 673
|
Relay_Master_Log_File: mysql-bin.000295
|
Slave_IO_Running: No
|
Slave_SQL_Running: Yes
|
Exec_Master_Log_Pos: 374
|
Last_IO_Errno: 1236
|
Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'bogus data in log event; the first event 'mysql-bin.000294' at 4, the last event read from 'mysql-bin.000295' at 397, the last byte read from 'mysql-bin.000295' at 416.'
|
Latest relay files on the slave:
-rw-rw---- 1 mysql mysql 350 Jun 19 02:20 relay-bin.000003
|
-rw-rw---- 1 mysql mysql 673 Jun 19 02:20 relay-bin.000004
|
-rw-rw---- 1 mysql mysql 64 Jun 19 02:20 relay-bin.index
|
Contents of relay-bin.000004 on the slave:
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
|
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
|
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
|
DELIMITER /*!*/;
|
# at 4
|
#190618 5:19:34 server id 2 end_log_pos 256 CRC32 0x683d95e7 Start: binlog v 4, server v 10.4.5-MariaDB-1:10.4.5+maria~bionic-log created 190618 5:19:34
|
# at 256
|
#190618 5:19:34 server id 3 end_log_pos 0 CRC32 0x1e2bbe6a Rotate to mysql-bin.000295 pos: 4
|
# at 303
|
#190619 2:20:01 server id 3 end_log_pos 256 CRC32 0x41002778 Start: binlog v 4, server v 10.4.5-MariaDB-1:10.4.5+maria~bionic-log created 190619 2:20:01
|
# at 555
|
#190619 2:20:01 server id 3 end_log_pos 331 CRC32 0x73e4cbd5 Gtid list [2-2-3953073486,
|
# 0-1-11,
|
# 3-3-74030022]
|
# at 630
|
#190619 2:20:01 server id 3 end_log_pos 374 CRC32 0x4a386032 Binlog checkpoint mysql-bin.000294
|
DELIMITER ;
|
# End of log file
|
ROLLBACK /* added by mysqlbinlog */;
|
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
|
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
|
Latest files on master:
-rw-rw---- 1 mysql mysql 62660952 Jun 18 02:20 mysql-bin.000293
|
-rw-rw---- 1 mysql mysql 62465363 Jun 19 02:20 mysql-bin.000294
|
-rw-rw---- 1 mysql mysql 1639006 Jun 19 05:36 mysql-bin.000295
|
-rw-rw---- 1 mysql mysql 397 Jun 19 02:20 mysql-bin.000296
|
-rw-r----- 1 mysql mysql 1024 Jun 19 02:20 mysql-bin.index
|
-rw-rw---- 1 mysql mysql 35 Jun 19 02:20 mysql-bin.state
|
Beginning of mysql-bin.000295 on the master:
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
|
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
|
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
|
DELIMITER /*!*/;
|
# at 4
|
#190619 2:20:01 server id 3 end_log_pos 256 CRC32 0x41002778 Start: binlog v 4, server v 10.4.5-MariaDB-1:10.4.5+maria~bionic-log created 190619 2:20:01
|
# Warning: this binlog is either in use or was not closed properly.
|
# at 256
|
#190619 2:20:01 server id 3 end_log_pos 331 CRC32 0x73e4cbd5 Gtid list [2-2-3953073486,
|
# 0-1-11,
|
# 3-3-74030022]
|
# at 331
|
#190619 2:20:01 server id 3 end_log_pos 374 CRC32 0x4a386032 Binlog checkpoint mysql-bin.000294
|
# at 374
|
#190619 2:20:02 server id 3 end_log_pos 416 CRC32 0xfe1a0d52 GTID 3-3-74030023 trans
|
/*!100101 SET @@session.skip_parallel_replication=0*//*!*/;
|
/*!100001 SET @@session.gtid_domain_id=3*//*!*/;
|
/*!100001 SET @@session.server_id=3*//*!*/;
|
/*!100001 SET @@session.gtid_seq_no=74030023*//*!*/;
|
BEGIN
|
/*!*/;
|
# at 416
|
#190619 2:20:02 server id 3 end_log_pos 686 CRC32 0x7780ec60 Query thread_id=1786448 exec_time=0 error_code=0
|
use `flow`/*!*/;
|
SET TIMESTAMP=1560903602/*!*/;
|
SET @@session.pseudo_thread_id=1786448/*!*/;
|
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/*!*/;
|
SET @@session.sql_mode=1073741824/*!*/;
|
SET @@session.auto_increment_increment=3, @@session.auto_increment_offset=3/*!*/;
|
/*!\C utf8mb4 *//*!*/;
|
SET @@session.character_set_client=224,@@session.collation_connection=224,@@session.collation_server=8/*!*/;
|
SET @@session.time_zone='SYSTEM'/*!*/;
|
SET @@session.lc_time_names=0/*!*/;
|
SET @@session.collation_database=DEFAULT/*!*/;
|
update `shelves` set `volume` = 1.763443503, `stats_refreshed_at` = '2019-06-19 02:20:02', `shelves`.`updated_at` = '2019-06-19 02:20:02' where `id` = 43458
|
/*!*/;
|
# at 686
|
#190619 2:20:02 server id 3 end_log_pos 717 CRC32 0xc1bcca04 Xid = 25752669727
|
COMMIT/*!*/;
|
# at 717
|
Thanks for the upload! After checking it now I've gotten another request for you to provide
mysqlbinlog output for
1. few (3-5) last events at the end of mysql-bin.000294
2. few last events at the end of mysql-bin.000295 itself,
3. the whole output for
-rw-rw---- 1 mysql mysql 397 Jun 19 02:20 mysql-bin.000296
|
whose 397 may not be just coincident to the show slave status error
... the last event read from 'mysql-bin.000295' at 397
|
I also need to look at mysqld.err log from both the master and slave for relevant dates.
Cheers.
Andrei
Thanks for the quick response.
Last events from mysql-bin.000294:
# at 62463960
|
#190619 2:19:47 server id 3 end_log_pos 62464222 CRC32 0x67756304 Query_compressed thread_id=1786442 exec_time=0 error_code=0
|
SET TIMESTAMP=1560903587/*!*/;
|
update `stations` set `last_seen_at` = '2019-06-19 02:19:47', `load_avg` = '0.06', `disk_free` = '11027386368', `cpu_temperature` = '56.382', `disk_write_count_per_sec` = '0.13333333333333333', `disk_write_bytes_per_sec` = '1365.3333333333333', `stations`.`updated_at` = '2019-06-19 02:19:47' where `id` = 306
|
/*!*/;
|
# at 62464222
|
#190619 2:19:47 server id 3 end_log_pos 62464253 CRC32 0x7bc64a72 Xid = 25752669055
|
COMMIT/*!*/;
|
# at 62464253
|
#190619 2:19:56 server id 3 end_log_pos 62464295 CRC32 0xf3520da9 GTID 3-3-74030020 trans
|
/*!100001 SET @@session.gtid_seq_no=74030020*//*!*/;
|
BEGIN
|
/*!*/;
|
# at 62464295
|
#190619 2:19:56 server id 3 end_log_pos 62464556 CRC32 0xd94a117b Query_compressed thread_id=1786443 exec_time=0 error_code=0
|
SET TIMESTAMP=1560903596/*!*/;
|
update `stations` set `last_seen_at` = '2019-06-19 02:19:56', `load_avg` = '0.04', `disk_free` = '11177177088', `cpu_temperature` = '54.768', `disk_write_count_per_sec` = '0.13333333333333333', `disk_write_bytes_per_sec` = '1365.3333333333333', `stations`.`updated_at` = '2019-06-19 02:19:56' where `id` = 38
|
/*!*/;
|
# at 62464556
|
#190619 2:19:56 server id 3 end_log_pos 62464587 CRC32 0xb486dad0 Xid = 25752669105
|
COMMIT/*!*/;
|
# at 62464587
|
#190619 2:20:00 server id 3 end_log_pos 62464629 CRC32 0x56914aa3 GTID 3-3-74030021 trans
|
/*!100001 SET @@session.gtid_seq_no=74030021*//*!*/;
|
BEGIN
|
/*!*/;
|
# at 62464629
|
#190619 2:20:00 server id 3 end_log_pos 62464901 CRC32 0xeded9fb8 Query_compressed thread_id=1786444 exec_time=0 error_code=0
|
SET TIMESTAMP=1560903600/*!*/;
|
update `stations` set `last_seen_at` = '2019-06-19 02:20:00', `load_avg` = '0.07', `disk_free` = '10592452608', `mem_free` = '476880896', `cpu_temperature` = '54.768', `disk_write_count_per_sec` = '0.23333333333333334', `disk_write_bytes_per_sec` = '1638.4', `stations`.`updated_at` = '2019-06-19 02:20:00' where `id` = 143
|
/*!*/;
|
# at 62464901
|
#190619 2:20:00 server id 3 end_log_pos 62464932 CRC32 0x93f966aa Xid = 25752669138
|
COMMIT/*!*/;
|
# at 62464932
|
#190619 2:20:01 server id 3 end_log_pos 62464974 CRC32 0xa59f292a GTID 3-3-74030022 trans
|
/*!100001 SET @@session.gtid_seq_no=74030022*//*!*/;
|
BEGIN
|
/*!*/;
|
# at 62464974
|
#190619 2:20:01 server id 3 end_log_pos 62465006 CRC32 0x5a02afb1 Intvar
|
SET INSERT_ID=19756869/*!*/;
|
# at 62465006
|
#190619 2:20:01 server id 3 end_log_pos 62465285 CRC32 0x9d96a78a Query thread_id=1786445 exec_time=0 error_code=0
|
SET TIMESTAMP=1560903601/*!*/;
|
insert into `slave_statuses` (`host`, `read_pos`, `exec_pos`, `seconds_behind_master`, `io_running`, `sql_running`, `checked_at`) values ('tail', 577651409, 577651409, 0, 1, 1, '2019-06-19 02:20:01')
|
/*!*/;
|
# at 62465285
|
#190619 2:20:01 server id 3 end_log_pos 62465316 CRC32 0xb2072fd8 Xid = 25752669210
|
COMMIT/*!*/;
|
# at 62465316
|
#190619 2:20:01 server id 3 end_log_pos 62465363 CRC32 0xb6643c52 Rotate to mysql-bin.000295 pos: 4
|
DELIMITER ;
|
# End of log file
|
ROLLBACK /* added by mysqlbinlog */;
|
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
|
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
|
Last events from mysql-bin.000295:
# at 1806004
|
#190619 5:51:56 server id 3 end_log_pos 1806046 CRC32 0x748990b4 GTID 3-3-74035239 trans
|
/*!100001 SET @@session.gtid_seq_no=74035239*//*!*/;
|
BEGIN
|
/*!*/;
|
# at 1806046
|
#190619 5:51:56 server id 3 end_log_pos 1806309 CRC32 0x18ee26ce Query_compressed thread_id=1790219 exec_time=0 error_code=0
|
SET TIMESTAMP=1560916316/*!*/;
|
update `stations` set `last_seen_at` = '2019-06-19 05:51:56', `load_avg` = '0.04', `disk_free` = '11177156608', `cpu_temperature` = '52.078', `disk_write_count_per_sec` = '0.23333333333333334', `disk_write_bytes_per_sec` = '1979.7333333333333', `stations`.`updated_at` = '2019-06-19 05:51:56' where `id` = 38
|
/*!*/;
|
# at 1806309
|
#190619 5:51:56 server id 3 end_log_pos 1806340 CRC32 0xcfb6cb5a Xid = 26042316237
|
COMMIT/*!*/;
|
# at 1806340
|
#190619 5:52:00 server id 3 end_log_pos 1806382 CRC32 0x3d04c07a GTID 3-3-74035240 trans
|
/*!100001 SET @@session.gtid_seq_no=74035240*//*!*/;
|
BEGIN
|
/*!*/;
|
# at 1806382
|
#190619 5:52:00 server id 3 end_log_pos 1806641 CRC32 0x88497247 Query_compressed thread_id=1790222 exec_time=0 error_code=0
|
SET TIMESTAMP=1560916320/*!*/;
|
update `stations` set `last_seen_at` = '2019-06-19 05:52:00', `load_avg` = '0.16', `disk_free` = '10592432128', `mem_free` = '480751616', `cpu_temperature` = '52.078', `disk_write_count_per_sec` = '0.13333333333333333', `stations`.`updated_at` = '2019-06-19 05:52:00' where `id` = 143
|
/*!*/;
|
# at 1806641
|
#190619 5:52:00 server id 3 end_log_pos 1806672 CRC32 0x074666be Xid = 26042316310
|
COMMIT/*!*/;
|
# at 1806672
|
#190619 5:52:02 server id 3 end_log_pos 1806714 CRC32 0xb3242eec GTID 3-3-74035241 trans
|
/*!100001 SET @@session.gtid_seq_no=74035241*//*!*/;
|
BEGIN
|
/*!*/;
|
# at 1806714
|
#190619 5:52:02 server id 3 end_log_pos 1806865 CRC32 0xdd1da3fc Query thread_id=1790202 exec_time=0 error_code=0
|
SET TIMESTAMP=1560916322/*!*/;
|
delete from `slave_statuses` where `checked_at` < '2019-05-08 05:52:02'
|
/*!*/;
|
# at 1806865
|
#190619 5:52:02 server id 3 end_log_pos 1806896 CRC32 0xc99625a8 Xid = 26042316389
|
COMMIT/*!*/;
|
# at 1806896
|
#190619 5:52:03 server id 3 end_log_pos 1806938 CRC32 0x75cab253 GTID 3-3-74035242 trans
|
/*!100001 SET @@session.gtid_seq_no=74035242*//*!*/;
|
BEGIN
|
/*!*/;
|
# at 1806938
|
#190619 5:52:03 server id 3 end_log_pos 1807264 CRC32 0x57c75276 Query thread_id=1790223 exec_time=0 error_code=0
|
SET TIMESTAMP=1560916323/*!*/;
|
update `stations` set `last_seen_at` = '2019-06-19 05:52:03', `load_avg` = '0.09', `disk_free` = '27585318912', `disk_write_count_per_sec` = '0.0', `disk_write_bytes_per_sec` = '0.0', `stations`.`updated_at` = '2019-06-19 05:52:03' where `id` = 6
|
/*!*/;
|
# at 1807264
|
#190619 5:52:03 server id 3 end_log_pos 1807295 CRC32 0x3ee39ec4 Xid = 26042317405
|
COMMIT/*!*/;
|
DELIMITER ;
|
# End of log file
|
ROLLBACK /* added by mysqlbinlog */;
|
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
|
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
|
The entire contents of mysql-bin.000296 (397 bytes):
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
|
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
|
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
|
DELIMITER /*!*/;
|
# at 4
|
#190619 2:20:08 server id 3 end_log_pos 256 CRC32 0x5e08b458 Start: binlog v 4, server v 10.4.5-MariaDB-1:10.4.5+maria~bionic-log created 190619 2:20:08 at startup
|
ROLLBACK/*!*/;
|
# at 256
|
#190619 2:20:08 server id 3 end_log_pos 331 CRC32 0xb8d8c50a Gtid list [2-2-3953073486,
|
# 0-1-11,
|
# 3-3-74030033]
|
# at 331
|
#190619 2:20:08 server id 3 end_log_pos 374 CRC32 0xf3645d3c Binlog checkpoint mysql-bin.000296
|
# at 374
|
#190619 2:20:08 server id 3 end_log_pos 397 CRC32 0xd4ec84e1 Stop
|
DELIMITER ;
|
# End of log file
|
ROLLBACK /* added by mysqlbinlog */;
|
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
|
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
|
I now suspect something unrelated to MariaDB might be the culprit.
mylvmbackup runs at 02:20am with innodb_recover=1. But since the datadir and log-bin are on different logical volumes, presumably the recovery triggered by mylvmbackup causes the extra, dangling binary log file to be created in the live log-bin directory.
Let me try to disable innodb_recover in mylvmbackup.
If this hunch turns out to be correct, I'll be terribly ashamed to have wasted your time.
In fact, the documentation of mylvmbackup clearly states that innodb_recovery only supports scenarios where the binary logs are stored in datadir:
The recovery operation is performed by spawning a second mysqld instance that uses the snapshot volume as the data directory. Note that this functionality currently assumes a default InnoDB configuration in which all InnoDB table spaces and log files are stored inside of the data directory - it does not work properly if you use options like --innodb-data-home-dir, --innodb-data-file-path or --innodb-log-group-home-dir that modify the default file layout for InnoDB tables.
crishoj I really sensed some "divine" intervention in the case, esp. seeing a stray binlog file. Don't you worry if that will prove to the case 
. Abuses (I mean to the server, naturally ) are part of this venture and while being time eaters they are even more instructive!
mylvmbackup with innodb_recovery=1 was indeed the cause.
My sincere apologies!
crishoj Then you owe us a real report ! Thank you for your trying and have a good midsummer and Solstice celebration!
Turns out to be a third party tool issue, not the server bug.