[MDEV-10618] innodb.binlog_consistent failed in buildbot on server startup Created: 2016-08-20  Updated: 2023-11-28  Resolved: 2023-11-28

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Tests
Affects Version/s: 5.5, 10.0
Fix Version/s: N/A

Type: Bug Priority: Minor
Reporter: Elena Stepanova Assignee: Sergei Golubchik
Resolution: Cannot Reproduce Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-7069 Fix buildbot failures in main server ... Stalled
Sprint: 5.5.54

 Description   

innodb.binlog_consistent 'xtradb'        [ fail ]
        Test ended at 2016-06-20 07:11:34
 
CURRENT_TEST: innodb.binlog_consistent
 
 
Failed to start mysqld.1
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
master-bin.000001	1378	Query	1	1470	use `test`; INSERT INTO t1 VALUES (1, "")
master-bin.000001	1470	Xid	1	1497	COMMIT /* XID */
master-bin.000001	1497	Gtid	1	1535	BEGIN GTID 0-1-8
master-bin.000001	1535	Query	1	1632	use `test`; INSERT INTO t1 VALUES (2, "first")
master-bin.000001	1632	Query	1	1730	use `test`; INSERT INTO t1 VALUES (2, "second")
master-bin.000001	1730	Xid	1	1757	COMMIT /* XID */
master-bin.000001	1757	Gtid	1	1795	BEGIN GTID 0-1-9
master-bin.000001	1795	Query	1	1887	use `test`; INSERT INTO t1 VALUES (3, "")
master-bin.000001	1887	Xid	1	1914	COMMIT /* XID */
master-bin.000001	1914	Rotate	1	1958	master-bin.000002;pos=4
*** MDEV-7310: last_commit_pos_offset set to wrong value after binlog rotate in group commit ***
SET @old_size= @@GLOBAL.max_binlog_size;
SET GLOBAL max_binlog_size=4096;
CREATE TABLE t3 (a INT PRIMARY KEY, b VARBINARY(8192)) ENGINE=MyISAM;
INSERT INTO t3 VALUES (10, '');
INSERT INTO t3 VALUES (11, 'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
test_result
OK
SET GLOBAL max_binlog_size=@old_size;
DROP TABLE t1,t2, t3;

http://buildbot.askmonty.org/buildbot/builders/sol10-64/builds/5376/steps/test/logs/mysqld.1.err

CURRENT_TEST: innodb.binlog_consistent
160620  7:09:49 [Note] /export/home/buildbot/maria-slave/solaris10-x86/build/mariadb-10.0.26/sql/mysqld (mysqld 10.0.26-MariaDB) starting as process 19691 ...
160620  7:09:51 [Note] Plugin 'CONNECT' is disabled.
160620  7:09:51 [Note] Plugin 'BLACKHOLE' is disabled.
160620  7:09:51 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB.
 
160620  7:09:51 [Note] InnoDB: Using mutexes to ref count buffer pool pages
160620  7:09:51 [Note] InnoDB: The InnoDB memory heap is disabled
160620  7:09:51 [Note] InnoDB: Mutexes and rw_locks use Solaris atomic functions
160620  7:09:51 [Note] InnoDB: Memory barrier is not used
160620  7:09:51 [Note] InnoDB: Compressed tables use zlib 1.2.3
160620  7:09:52 [Note] InnoDB: Not using CPU crc32 instructions
160620  7:09:52 [Note] InnoDB: Initializing buffer pool, size = 8.0M
160620  7:09:52 [Note] InnoDB: Completed initialization of buffer pool
160620  7:09:53 [Note] InnoDB: Highest supported file format is Barracuda.
CURRENT_TEST: main.flush_block_commit_notembedded
160620  7:14:25 [Note] /export/home/buildbot/maria-slave/solaris10-x86/build/mariadb-10.0.26/sql/mysqld (mysqld 10.0.26-MariaDB) starting as process 19702 ...

http://buildbot.askmonty.org/buildbot/builders/p8-trusty-bintar-debug/builds/23/steps/test/logs/stdio

innodb.binlog_consistent 'innodb_plugin' w3 [ fail ]
        Test ended at 2016-06-30 10:58:57
 
CURRENT_TEST: innodb.binlog_consistent
 
 
Failed to start mysqld.1
mysqltest failed but provided no output

http://buildbot.askmonty.org/buildbot/builders/p8-trusty-bintar-debug/builds/23/steps/test/logs/mysqld.1.err.3

CURRENT_TEST: innodb.binlog_consistent
160630 10:55:51 [Note] /var/lib/buildbot/maria-slave/p8-trusty-bintar-debug/build/sql/mysqld (mysqld 5.5.51-MariaDB-debug) starting as process 31644 ...
160630 10:55:51 [Note] Plugin 'XTRADB_ADMIN_COMMAND' is disabled.
160630 10:55:51 [Note] Plugin 'partition' is disabled.
160630 10:55:51 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
160630 10:55:51 InnoDB: The InnoDB memory heap is disabled
160630 10:55:51 InnoDB: Mutexes and rw_locks use GCC atomic builtins
160630 10:55:51 InnoDB: Compressed tables use zlib 1.2.8
160630 10:55:51 InnoDB: Using Linux native AIO
160630 10:55:52 InnoDB: Initializing buffer pool, size = 8.0M
160630 10:55:52 InnoDB: Completed initialization of buffer pool
InnoDB: The first specified data file ./ibdata1 did not exist:
InnoDB: a new database to be created!
160630 10:55:52  InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
160630 10:56:29  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
160630 10:57:57  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Doublewrite buffer not found: creating new
CURRENT_TEST: main.flush_block_commit_notembedded
160630 10:58:57 [Note] /var/lib/buildbot/maria-slave/p8-trusty-bintar-debug/build/sql/mysqld (mysqld 5.5.51-MariaDB-debug) starting as process 31695 ...



 Comments   
Comment by Sergei Golubchik [ 2016-12-15 ]

I cannot repeat it (on amd64), even with high --repeat values. Buildbot cross-reference finds only one single failure in 2016, the one you quoted on p8. All sol10-64 builds that I checked didn't have this failure.

Comment by Marko Mäkelä [ 2017-02-16 ]

For what it is worth, this test fails when the 10.2 server is built on AMD64 WITH_ASAN due to an apparent client-side problem:

innodb.binlog_consistent 'innodb'        [ fail ]
        Test ended at 2017-02-16 15:05:24
 
CURRENT_TEST: innodb.binlog_consistent
 
=================================================================
==5268==ERROR: LeakSanitizer: detected memory leaks
 
Direct leak of 120 byte(s) in 1 object(s) allocated from:
    #0 0x7fcf011eaed0 in calloc (/lib/x86_64-linux-gnu/libasan.so.3+0xc1ed0)
    #1 0x564f294fb23d in mysql_init /mariadb/server/libmariadb/libmariadb/mariadb_lib.c:986
    #2 0x564f294dadba in main /mariadb/server/client/mysql.cc:1148
    #3 0x7fceff6ed2b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0)
 
Direct leak of 4 byte(s) in 1 object(s) allocated from:
    #0 0x7fcf011eaed0 in calloc (/lib/x86_64-linux-gnu/libasan.so.3+0xc1ed0)
    #1 0x564f294fb1e5 in mysql_init /mariadb/server/libmariadb/libmariadb/mariadb_lib.c:984
    #2 0x564f294dadba in main /mariadb/server/client/mysql.cc:1148
    #3 0x7fceff6ed2b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0)
 
SUMMARY: AddressSanitizer: 124 byte(s) leaked in 2 allocation(s).
Error closing MYSQL pipe:  at /mariadb/build/mysql-test/var/tmpecXFW9 line 8.
mysqltest: In included file "./include/write_result_to_file.inc": 
included from ./include/show_events.inc at line 86:
included from ./include/show_binlog_events.inc at line 41:
included from /mariadb/server/mysql-test/suite/innodb/t/binlog_consistent.test at line 89:
At line 65: command "perl" failed with error: 1  my_errno: 0  errno: 0

In the server error log, there is no message after successful InnoDB and server startup.

Comment by Marko Mäkelä [ 2023-11-28 ]

Outside Microsoft Windows, this test last failed on 10.1. The last failure was the following:

10.5 bcb9ca41053aa3db8d4d04d9d11dcd17

innodb.binlog_consistent 'innodb'        w1 [ fail ]
        Test ended at 2021-03-26 01:19:10
 
CURRENT_TEST: innodb.binlog_consistent
mysqltest: In included file "./include/wait_for_binlog_checkpoint.inc": 
included from D:/win32-packages/build/src/mysql-test/suite/innodb/t/binlog_consistent.test at line 109:
At line 52: ERROR: failed while waiting for binlog checkpoint $_cur_binlog

Generated at Thu Feb 08 07:43:37 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.