Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.5.5, 10.2(EOL), 10.3(EOL)
Description
Observed on buildbot, 64-bit Windows, debug:
CURRENT_TEST: innodb.group_commit_crash_no_optimize_thread
|
…
|
2017-09-17 10:58:59 4604 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1682230
|
Assertion failed: recv_sys->mlog_checkpoint_lsn <= recv_sys->recovered_lsn, file D:\winx64-debug\build\src\storage\innobase\log\log0recv.cc, line 2374
|
…
|
----------SERVER LOG END-------------
|
mysqltest failed but provided no output
|
The result from queries just before the failure was:
|
< snip >
|
a b c d 2
|
a b c d 3
|
a b c d 4
|
a b c d 5
|
a b c d 6
|
a b c d 7
|
a b c d 8
|
a b c d 9
|
a b c d 10
|
SHOW BINLOG EVENTS LIMIT 4,1;
|
Log_name Pos Event_type Server_id End_log_pos Info
|
master-bin.000001 # Query 1 # use `test`; insert into t1 select * from t2
|
delete from t1;
|
SET binlog_format= mixed;
|
RESET MASTER;
|
START TRANSACTION;
|
insert into t1 select * from t2;
|
call setcrash(2);
|
COMMIT;
|
Got one of the listed errors
|
This logic will be removed altogether when MDEV-14425 introduces a separate file for log checkpoints and file names.
Attachments
Issue Links
- duplicates
-
-
- Closed
-
- is duplicated by
-
-
- Closed
-
- relates to
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
MDEV-14425 Change the InnoDB redo log format to reduce write amplification
-
- Closed
-
-
-
- Closed
-
(2 relates to)
Activity
Note: both happened with PS protocol.
http://buildbot.askmonty.org/buildbot/builders/bld-starfs-debug/builds/560/steps/test_1/logs/stdio
rpl.rpl_sync 'innodb,mix' w1 [ fail ]
|
Test ended at 2017-12-03 16:11:46
|
|
|
CURRENT_TEST: rpl.rpl_sync
|
|
|
|
|
Server [mysqld.2 - pid: 4183, winpid: 4183, exit: 256] failed during test run
|
Server log from this test:
|
----------SERVER LOG START-----------
|
2017-12-03 16:11:40 140486123042688 [Note] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld (mysqld 10.2.12-MariaDB-debug-log) starting as process 3964 ...
|
2017-12-03 16:11:40 140486123042688 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
|
2017-12-03 16:11:40 140486123042688 [Note] Plugin 'SEQUENCE' is disabled.
|
2017-12-03 16:11:40 140486123042688 [Note] Plugin 'partition' is disabled.
|
2017-12-03 16:11:40 140486123042688 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2017-12-03 16:11:40 140486123042688 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2017-12-03 16:11:40 140486123042688 [Note] InnoDB: Uses event mutexes
|
2017-12-03 16:11:40 140486123042688 [Note] InnoDB: Compressed tables use zlib 1.2.8
|
2017-12-03 16:11:40 140486123042688 [Note] InnoDB: Number of pools: 1
|
2017-12-03 16:11:40 140486123042688 [Note] InnoDB: Using SSE2 crc32 instructions
|
2017-12-03 16:11:40 140486123042688 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
|
2017-12-03 16:11:40 140486123042688 [Note] InnoDB: Completed initialization of buffer pool
|
2017-12-03 16:11:40 140485880436480 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
|
2017-12-03 16:11:40 140486123042688 [Note] InnoDB: Highest supported file format is Barracuda.
|
2017-12-03 16:11:41 140486123042688 [Note] InnoDB: 128 out of 128 rollback segments are active.
|
2017-12-03 16:11:41 140486123042688 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2017-12-03 16:11:41 140486123042688 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2017-12-03 16:11:41 140486123042688 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
|
2017-12-03 16:11:41 140486123042688 [Note] InnoDB: Waiting for purge to start
|
2017-12-03 16:11:41 140486123042688 [Note] InnoDB: 5.7.20 started; log sequence number 1633766
|
2017-12-03 16:11:41 140485444212480 [Note] InnoDB: Loading buffer pool(s) from /opt/buildbot-slave/mariadb/starfsmenn1/build/mysql-test/var/1/mysqld.2/data/ib_buffer_pool
|
2017-12-03 16:11:41 140485444212480 [Note] InnoDB: Buffer pool(s) load completed at 171203 16:11:41
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_CMP' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'FEEDBACK' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'user_variables' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_MUTEXES' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
|
2017-12-03 16:11:41 140486123042688 [Warning] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld: unknown option '--loose-pam-debug'
|
2017-12-03 16:11:41 140486123042688 [Note] Server socket created on IP: '127.0.0.1'.
|
2017-12-03 16:11:41 140486123042688 [Note] Reading of all Master_info entries succeded
|
2017-12-03 16:11:41 140486123042688 [Note] Added new Master_info '' to hash table
|
2017-12-03 16:11:41 140486123042688 [Note] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld: ready for connections.
|
Version: '10.2.12-MariaDB-debug-log' socket: '/opt/buildbot-slave/mariadb/starfsmenn1/build/mysql-test/var/tmp/1/mysqld.2.sock' port: 16021 Source distribution
|
2017-12-03 16:11:42 140485999384320 [Note] Deleted Master_info file '/opt/buildbot-slave/mariadb/starfsmenn1/build/mysql-test/var/1/mysqld.2/data/master.info'.
|
2017-12-03 16:11:42 140485999384320 [Note] Deleted Master_info file '/opt/buildbot-slave/mariadb/starfsmenn1/build/mysql-test/var/1/mysqld.2/data/relay-log.info'.
|
2017-12-03 16:11:42 140485999384320 [Note] Master connection name: '' Master_info_file: 'master.info' Relay_info_file: 'relay-log.info'
|
2017-12-03 16:11:42 140485999384320 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='4'.
|
2017-12-03 16:11:42 140485998475008 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './slave-relay-bin.000001' position: 4
|
2017-12-03 16:11:42 140485998778112 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16020',replication started in log 'master-bin.000001' at position 4
|
2017-12-03 16:11:43 140485998475008 [Note] Error reading relay log event: slave SQL thread was killed
|
2017-12-03 16:11:43 140485998475008 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 1919
|
2017-12-03 16:11:43 140485998778112 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 2253
|
SIGKILL myself
|
2017-12-03 16:11:43 140021581858688 [Note] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld (mysqld 10.2.12-MariaDB-debug-log) starting as process 4134 ...
|
2017-12-03 16:11:43 140021581858688 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
|
2017-12-03 16:11:43 140021581858688 [Note] Plugin 'SEQUENCE' is disabled.
|
2017-12-03 16:11:43 140021581858688 [Note] Plugin 'partition' is disabled.
|
2017-12-03 16:11:43 140021581858688 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2017-12-03 16:11:43 140021581858688 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2017-12-03 16:11:43 140021581858688 [Note] InnoDB: Uses event mutexes
|
2017-12-03 16:11:43 140021581858688 [Note] InnoDB: Compressed tables use zlib 1.2.8
|
2017-12-03 16:11:43 140021581858688 [Note] InnoDB: Number of pools: 1
|
2017-12-03 16:11:43 140021581858688 [Note] InnoDB: Using SSE2 crc32 instructions
|
2017-12-03 16:11:43 140021581858688 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
|
2017-12-03 16:11:43 140021581858688 [Note] InnoDB: Completed initialization of buffer pool
|
2017-12-03 16:11:43 140021336094464 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
|
2017-12-03 16:11:43 140021581858688 [Note] InnoDB: Highest supported file format is Barracuda.
|
2017-12-03 16:11:43 140021581858688 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1633766
|
2017-12-03 16:11:44 140021581858688 [Note] InnoDB: Starting final batch to recover 8 pages from redo log.
|
2017-12-03 16:11:44 140021581858688 [Note] InnoDB: Last binlog file './slave-bin.000001', position 1918
|
2017-12-03 16:11:44 140021581858688 [Note] InnoDB: 128 out of 128 rollback segments are active.
|
2017-12-03 16:11:44 140021581858688 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
|
2017-12-03 16:11:44 140021581858688 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2017-12-03 16:11:44 140021581858688 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2017-12-03 16:11:44 140021581858688 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
|
2017-12-03 16:11:44 140021581858688 [Note] InnoDB: Waiting for purge to start
|
2017-12-03 16:11:44 140021581858688 [Note] InnoDB: 5.7.20 started; log sequence number 1646143
|
2017-12-03 16:11:44 140020824401664 [Note] InnoDB: Loading buffer pool(s) from /opt/buildbot-slave/mariadb/starfsmenn1/build/mysql-test/var/1/mysqld.2/data/ib_buffer_pool
|
2017-12-03 16:11:44 140020824401664 [Note] InnoDB: Buffer pool(s) load completed at 171203 16:11:44
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_CMP' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'FEEDBACK' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'user_variables' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_MUTEXES' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
|
2017-12-03 16:11:44 140021581858688 [Warning] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld: unknown option '--loose-pam-debug'
|
2017-12-03 16:11:44 140021581858688 [Note] Recovering after a crash using slave-bin
|
2017-12-03 16:11:44 140021581858688 [Note] Starting crash recovery...
|
2017-12-03 16:11:44 140021581858688 [Note] Crash recovery finished.
|
2017-12-03 16:11:44 140021581858688 [Note] Server socket created on IP: '127.0.0.1'.
|
2017-12-03 16:11:44 140021581858688 [Note] Reading of all Master_info entries succeded
|
2017-12-03 16:11:44 140021581858688 [Note] Added new Master_info '' to hash table
|
2017-12-03 16:11:44 140021581858688 [Warning] Recovery from master pos 1919 and file master-bin.000001.
|
2017-12-03 16:11:44 140021581858688 [Note] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld: ready for connections.
|
Version: '10.2.12-MariaDB-debug-log' socket: '/opt/buildbot-slave/mariadb/starfsmenn1/build/mysql-test/var/tmp/1/mysqld.2.sock' port: 16021 Source distribution
|
2017-12-03 16:11:45 140021437527808 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 1919, relay log './slave-relay-bin.000003' position: 4
|
2017-12-03 16:11:45 140021437830912 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16020',replication started in log 'master-bin.000001' at position 1919
|
2017-12-03 16:11:46 140021437527808 [Note] Error reading relay log event: slave SQL thread was killed
|
2017-12-03 16:11:46 140021437527808 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 2420
|
2017-12-03 16:11:46 140021437830912 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 2420
|
SIGKILL myself
|
2017-12-03 16:11:46 140290528974720 [Note] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld (mysqld 10.2.12-MariaDB-debug-log) starting as process 4184 ...
|
2017-12-03 16:11:46 140290528974720 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
|
2017-12-03 16:11:46 140290528974720 [Note] Plugin 'SEQUENCE' is disabled.
|
2017-12-03 16:11:46 140290528974720 [Note] Plugin 'partition' is disabled.
|
2017-12-03 16:11:46 140290528974720 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2017-12-03 16:11:46 140290528974720 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2017-12-03 16:11:46 140290528974720 [Note] InnoDB: Uses event mutexes
|
2017-12-03 16:11:46 140290528974720 [Note] InnoDB: Compressed tables use zlib 1.2.8
|
2017-12-03 16:11:46 140290528974720 [Note] InnoDB: Number of pools: 1
|
2017-12-03 16:11:46 140290528974720 [Note] InnoDB: Using SSE2 crc32 instructions
|
2017-12-03 16:11:46 140290528974720 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
|
2017-12-03 16:11:46 140290528974720 [Note] InnoDB: Completed initialization of buffer pool
|
2017-12-03 16:11:46 140290006447872 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
|
2017-12-03 16:11:46 140290528974720 [Note] InnoDB: Highest supported file format is Barracuda.
|
2017-12-03 16:11:46 140290528974720 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1646162
|
mysqld: /opt/buildbot-slave/mariadb/starfsmenn1/build/storage/innobase/log/log0recv.cc:2356: bool recv_parse_log_recs(lsn_t, store_t, bool): Assertion `recv_sys->mlog_checkpoint_lsn <= recv_sys->recovered_lsn' failed.
|
171203 16:11:46 [ERROR] mysqld got signal 6 ;
|
This could be because you hit a bug. It is also possible that this binary
|
or one of the libraries it was linked against is corrupt, improperly built,
|
or misconfigured. This error can also be caused by malfunctioning hardware.
|
|
|
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
|
|
|
We will try our best to scrape up some info that will hopefully help
|
diagnose the problem, but since we have already crashed,
|
something is definitely wrong and this may fail.
|
|
|
Server version: 10.2.12-MariaDB-debug-log
|
key_buffer_size=1048576
|
read_buffer_size=131072
|
max_used_connections=0
|
max_threads=153
|
thread_count=0
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63124 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x0
|
Attempting backtrace. You can use the following information to find out
|
where mysqld died. If you see no messages after this, something went
|
terribly wrong...
|
stack_bottom = 0x0 thread_stack 0x49000
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(my_print_stacktrace+0x38)[0x7f97f01e62a0]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(handle_fatal_signal+0x39e)[0x7f97efa889fb]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7f97ee19f330]
|
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f97ed5dcc37]
|
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f97ed5e0028]
|
/lib/x86_64-linux-gnu/libc.so.6(+0x2fbf6)[0x7f97ed5d5bf6]
|
/lib/x86_64-linux-gnu/libc.so.6(+0x2fca2)[0x7f97ed5d5ca2]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0xacef2b)[0x7f97efd31f2b]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0xacff22)[0x7f97efd32f22]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0xad03b0)[0x7f97efd333b0]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0xad15de)[0x7f97efd345de]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0xbe0fc3)[0x7f97efe43fc3]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0xa27c19)[0x7f97efc8ac19]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0xfc)[0x7f97efa8aa5c]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0x5c8650)[0x7f97ef82b650]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(_Z11plugin_initPiPPci+0x954)[0x7f97ef82c29e]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0x4d4e66)[0x7f97ef737e66]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(_Z11mysqld_mainiPPc+0x5f4)[0x7f97ef738f09]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(main+0x20)[0x7f97ef72dcf5]
|
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7f97ed5c7f45]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0x4cabe9)[0x7f97ef72dbe9]
|
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
|
information that should help you find out what is causing the crash.
|
----------SERVER LOG END-------------
|
mysqltest failed but provided no output
|
The result from queries just before the failure was:
|
< snip >
|
ERROR HY000: Lost connection to MySQL server during query
|
include/rpl_reconnect.inc
|
=====Dumping and comparing tables=======;
|
include/start_slave.inc
|
connection master;
|
connection slave;
|
include/diff_tables.inc [master:t1,slave:t1]
|
=====Corrupting the master.info=======;
|
connection slave;
|
include/stop_slave.inc
|
connection master;
|
FLUSH LOGS;
|
insert into t1(a) values(7);
|
insert into t1(a) values(8);
|
insert into t1(a) values(9);
|
connection slave;
|
SET SESSION debug_dbug="d,crash_before_rotate_relaylog";
|
FLUSH LOGS;
|
ERROR HY000: Lost connection to MySQL server during query
|
include/rpl_reconnect.inc
|
http://buildbot.askmonty.org/buildbot/builders/bld-starfs-debug/builds/566/steps/test_1/logs/stdio
binlog_encryption.rpl_sync 'innodb,stmt' w1 [ fail ]
|
Test ended at 2017-12-04 21:26:13
|
|
|
CURRENT_TEST: binlog_encryption.rpl_sync
|
|
|
|
|
Server [mysqld.2 - pid: 6923, winpid: 6923, exit: 256] failed during test run
|
Server log from this test:
|
----------SERVER LOG START-----------
|
2017-12-04 21:26:07 140103187322752 [Note] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld (mysqld 10.2.12-MariaDB-debug-log) starting as process 6771 ...
|
2017-12-04 21:26:07 140103187322752 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'SEQUENCE' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'partition' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: Uses event mutexes
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: Compressed tables use zlib 1.2.8
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: Number of pools: 1
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: Using SSE2 crc32 instructions
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: Completed initialization of buffer pool
|
2017-12-04 21:26:07 140102940473088 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: Highest supported file format is Barracuda.
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: 128 out of 128 rollback segments are active.
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: Waiting for purge to start
|
2017-12-04 21:26:07 140103187322752 [Note] InnoDB: 5.7.20 started; log sequence number 1633737
|
2017-12-04 21:26:07 140102294562560 [Note] InnoDB: Loading buffer pool(s) from /opt/buildbot-slave/mariadb/starfsmenn1/build/mysql-test/var/1/mysqld.2/data/ib_buffer_pool
|
2017-12-04 21:26:07 140102294562560 [Note] InnoDB: Buffer pool(s) load completed at 171204 21:26:07
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_CMP' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'FEEDBACK' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'user_variables' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_MUTEXES' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
|
2017-12-04 21:26:07 140103187322752 [Warning] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld: unknown option '--loose-pam-debug'
|
2017-12-04 21:26:07 140103187322752 [Note] Server socket created on IP: '127.0.0.1'.
|
2017-12-04 21:26:07 140103187322752 [Note] Reading of all Master_info entries succeded
|
2017-12-04 21:26:07 140103187322752 [Note] Added new Master_info '' to hash table
|
2017-12-04 21:26:07 140103187322752 [Note] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld: ready for connections.
|
Version: '10.2.12-MariaDB-debug-log' socket: '/opt/buildbot-slave/mariadb/starfsmenn1/build/mysql-test/var/tmp/1/mysqld.2.sock' port: 16001 Source distribution
|
2017-12-04 21:26:08 140103063664384 [Note] Deleted Master_info file '/opt/buildbot-slave/mariadb/starfsmenn1/build/mysql-test/var/1/mysqld.2/data/master.info'.
|
2017-12-04 21:26:08 140103063664384 [Note] Deleted Master_info file '/opt/buildbot-slave/mariadb/starfsmenn1/build/mysql-test/var/1/mysqld.2/data/relay-log.info'.
|
2017-12-04 21:26:08 140103063664384 [Note] Master connection name: '' Master_info_file: 'master.info' Relay_info_file: 'relay-log.info'
|
2017-12-04 21:26:08 140103063664384 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='127.0.0.1', master_port='16000', master_log_file='master-bin.000001', master_log_pos='4'.
|
2017-12-04 21:26:08 140103062755072 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './slave-relay-bin.000001' position: 4
|
2017-12-04 21:26:08 140103063058176 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16000',replication started in log 'master-bin.000001' at position 4
|
2017-12-04 21:26:09 140103062755072 [Note] Error reading relay log event: slave SQL thread was killed
|
2017-12-04 21:26:09 140103062755072 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 1959
|
2017-12-04 21:26:09 140103063058176 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 2460
|
SIGKILL myself
|
2017-12-04 21:26:10 140698474153856 [Note] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld (mysqld 10.2.12-MariaDB-debug-log) starting as process 6860 ...
|
2017-12-04 21:26:10 140698474153856 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
|
2017-12-04 21:26:10 140698474153856 [Note] Plugin 'SEQUENCE' is disabled.
|
2017-12-04 21:26:10 140698474153856 [Note] Plugin 'partition' is disabled.
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Uses event mutexes
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Compressed tables use zlib 1.2.8
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Number of pools: 1
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Using SSE2 crc32 instructions
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Completed initialization of buffer pool
|
2017-12-04 21:26:10 140698162558720 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Highest supported file format is Barracuda.
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1633737
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Starting final batch to recover 8 pages from redo log.
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Last binlog file './slave-bin.000001', position 1918
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: 128 out of 128 rollback segments are active.
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2017-12-04 21:26:10 140698474153856 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
|
2017-12-04 21:26:11 140698474153856 [Note] InnoDB: Waiting for purge to start
|
2017-12-04 21:26:11 140698474153856 [Note] InnoDB: 5.7.20 started; log sequence number 1646119
|
2017-12-04 21:26:11 140697994770176 [Note] InnoDB: Loading buffer pool(s) from /opt/buildbot-slave/mariadb/starfsmenn1/build/mysql-test/var/1/mysqld.2/data/ib_buffer_pool
|
2017-12-04 21:26:11 140697994770176 [Note] InnoDB: Buffer pool(s) load completed at 171204 21:26:11
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_CMP' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'FEEDBACK' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'user_variables' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_MUTEXES' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
|
2017-12-04 21:26:11 140698474153856 [Warning] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld: unknown option '--loose-pam-debug'
|
2017-12-04 21:26:11 140698474153856 [Note] Recovering after a crash using slave-bin
|
2017-12-04 21:26:11 140698474153856 [Note] Starting crash recovery...
|
2017-12-04 21:26:11 140698474153856 [Note] Crash recovery finished.
|
2017-12-04 21:26:11 140698474153856 [Note] Server socket created on IP: '127.0.0.1'.
|
2017-12-04 21:26:11 140698474153856 [Note] Reading of all Master_info entries succeded
|
2017-12-04 21:26:11 140698474153856 [Note] Added new Master_info '' to hash table
|
2017-12-04 21:26:11 140698474153856 [Warning] Recovery from master pos 1959 and file master-bin.000001.
|
2017-12-04 21:26:11 140698474153856 [Note] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld: ready for connections.
|
Version: '10.2.12-MariaDB-debug-log' socket: '/opt/buildbot-slave/mariadb/starfsmenn1/build/mysql-test/var/tmp/1/mysqld.2.sock' port: 16001 Source distribution
|
2017-12-04 21:26:12 140698230699776 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 1959, relay log './slave-relay-bin.000003' position: 4
|
2017-12-04 21:26:12 140698231002880 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16000',replication started in log 'master-bin.000001' at position 1959
|
2017-12-04 21:26:12 140698230699776 [Note] Error reading relay log event: slave SQL thread was killed
|
2017-12-04 21:26:12 140698230699776 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 2460
|
2017-12-04 21:26:12 140698231002880 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 2460
|
SIGKILL myself
|
2017-12-04 21:26:12 139770597050240 [Note] /opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld (mysqld 10.2.12-MariaDB-debug-log) starting as process 6924 ...
|
2017-12-04 21:26:12 139770597050240 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
|
2017-12-04 21:26:12 139770597050240 [Note] Plugin 'SEQUENCE' is disabled.
|
2017-12-04 21:26:12 139770597050240 [Note] Plugin 'partition' is disabled.
|
2017-12-04 21:26:12 139770597050240 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2017-12-04 21:26:12 139770597050240 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2017-12-04 21:26:12 139770597050240 [Note] InnoDB: Uses event mutexes
|
2017-12-04 21:26:12 139770597050240 [Note] InnoDB: Compressed tables use zlib 1.2.8
|
2017-12-04 21:26:12 139770597050240 [Note] InnoDB: Number of pools: 1
|
2017-12-04 21:26:12 139770597050240 [Note] InnoDB: Using SSE2 crc32 instructions
|
2017-12-04 21:26:12 139770597050240 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
|
2017-12-04 21:26:12 139770597050240 [Note] InnoDB: Completed initialization of buffer pool
|
2017-12-04 21:26:12 139770348943104 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
|
2017-12-04 21:26:12 139770597050240 [Note] InnoDB: Highest supported file format is Barracuda.
|
2017-12-04 21:26:12 139770597050240 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1647234
|
mysqld: /opt/buildbot-slave/mariadb/starfsmenn1/build/storage/innobase/log/log0recv.cc:2356: bool recv_parse_log_recs(lsn_t, store_t, bool): Assertion `recv_sys->mlog_checkpoint_lsn <= recv_sys->recovered_lsn' failed.
|
171204 21:26:12 [ERROR] mysqld got signal 6 ;
|
This could be because you hit a bug. It is also possible that this binary
|
or one of the libraries it was linked against is corrupt, improperly built,
|
or misconfigured. This error can also be caused by malfunctioning hardware.
|
|
|
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
|
|
|
We will try our best to scrape up some info that will hopefully help
|
diagnose the problem, but since we have already crashed,
|
something is definitely wrong and this may fail.
|
|
|
Server version: 10.2.12-MariaDB-debug-log
|
key_buffer_size=1048576
|
read_buffer_size=131072
|
max_used_connections=0
|
max_threads=153
|
thread_count=0
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63124 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x0
|
Attempting backtrace. You can use the following information to find out
|
where mysqld died. If you see no messages after this, something went
|
terribly wrong...
|
stack_bottom = 0x0 thread_stack 0x49000
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(my_print_stacktrace+0x38)[0x7f1ee1c2d2a0]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(handle_fatal_signal+0x39e)[0x7f1ee14cf9fb]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7f1edfbe6330]
|
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f1edf023c37]
|
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f1edf027028]
|
/lib/x86_64-linux-gnu/libc.so.6(+0x2fbf6)[0x7f1edf01cbf6]
|
/lib/x86_64-linux-gnu/libc.so.6(+0x2fca2)[0x7f1edf01cca2]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0xacef2b)[0x7f1ee1778f2b]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0xacff22)[0x7f1ee1779f22]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0xad03b0)[0x7f1ee177a3b0]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0xad15de)[0x7f1ee177b5de]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0xbe0fc3)[0x7f1ee188afc3]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0xa27c19)[0x7f1ee16d1c19]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0xfc)[0x7f1ee14d1a5c]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0x5c8650)[0x7f1ee1272650]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(_Z11plugin_initPiPPci+0x954)[0x7f1ee127329e]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0x4d4e66)[0x7f1ee117ee66]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(_Z11mysqld_mainiPPc+0x5f4)[0x7f1ee117ff09]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(main+0x20)[0x7f1ee1174cf5]
|
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7f1edf00ef45]
|
/opt/buildbot-slave/mariadb/starfsmenn1/build/sql/mysqld(+0x4cabe9)[0x7f1ee1174be9]
|
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
|
information that should help you find out what is causing the crash.
|
----------SERVER LOG END-------------
|
mysqltest failed but provided no output
|
The result from queries just before the failure was:
|
< snip >
|
ERROR HY000: Lost connection to MySQL server during query
|
include/rpl_reconnect.inc
|
=====Dumping and comparing tables=======;
|
include/start_slave.inc
|
connection master;
|
connection slave;
|
include/diff_tables.inc [master:t1,slave:t1]
|
=====Corrupting the master.info=======;
|
connection slave;
|
include/stop_slave.inc
|
connection master;
|
FLUSH LOGS;
|
insert into t1(a) values(7);
|
insert into t1(a) values(8);
|
insert into t1(a) values(9);
|
connection slave;
|
SET SESSION debug_dbug="d,crash_before_rotate_relaylog";
|
FLUSH LOGS;
|
ERROR HY000: Lost connection to MySQL server during query
|
include/rpl_reconnect.inc
|
|
10.5 fde1589f9b529894 |
rpl.rpl_gtid_crash 'innodb,row' w62 [ fail ]
|
Test ended at 2020-01-24 11:27:07
|
|
|
CURRENT_TEST: rpl.rpl_gtid_crash
|
|
|
|
|
Server [mysqld.2 - pid: 51375, winpid: 51375, exit: 256] failed during test run
|
Server log from this test:
|
----------SERVER LOG START-----------
|
2020-01-24 11:25:51 0 [Note] /10.5/sql/mysqld (mysqld 10.5.1-MariaDB-debug-log) starting as process 28144 ...
|
2020-01-24 11:25:51 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4246)
|
2020-01-24 11:25:51 0 [Warning] Changed limits: max_open_files: 1024 max_connections: 151 (was 151) table_cache: 421 (was 2000)
|
2020-01-24 11:25:51 0 [Note] Plugin 'partition' is disabled.
|
2020-01-24 11:25:51 0 [Note] Plugin 'SEQUENCE' is disabled.
|
2020-01-24 11:25:51 0 [Note] InnoDB: Using Linux native AIO
|
2020-01-24 11:25:51 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2020-01-24 11:25:51 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2020-01-24 11:25:51 0 [Note] InnoDB: Uses event mutexes
|
2020-01-24 11:25:51 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
|
2020-01-24 11:25:51 0 [Note] InnoDB: Number of pools: 1
|
2020-01-24 11:25:51 0 [Note] InnoDB: Using SSE2 crc32 instructions
|
2020-01-24 11:25:51 0 [Note] mysqld: O_TMPFILE is not supported on /10.5/mysql-test/var/tmp/62/mysqld.2 (disabling future attempts)
|
io_setup(1280) returned -11
|
2020-01-24 11:25:51 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
|
2020-01-24 11:25:51 0 [Note] InnoDB: Completed initialization of buffer pool
|
2020-01-24 11:25:51 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
|
2020-01-24 11:25:56 0 [Note] InnoDB: 128 rollback segments are active.
|
2020-01-24 11:25:56 0 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2020-01-24 11:25:56 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2020-01-24 11:25:56 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
|
2020-01-24 11:25:56 0 [Note] InnoDB: 10.5.1 started; log sequence number 64036; transaction id 28
|
2020-01-24 11:25:56 0 [Note] InnoDB: Loading buffer pool(s) from /10.5/mysql-test/var/62/mysqld.2/data/ib_buffer_pool
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_CMP' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'THREAD_POOL_WAITS' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'THREAD_POOL_QUEUES' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'FEEDBACK' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'THREAD_POOL_GROUPS' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'user_variables' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'THREAD_POOL_STATS' is disabled.
|
2020-01-24 11:25:56 0 [Note] Plugin 'unix_socket' is disabled.
|
2020-01-24 11:25:56 0 [Warning] /10.5/sql/mysqld: unknown option '--loose-pam-debug'
|
2020-01-24 11:25:56 0 [Warning] /10.5/sql/mysqld: unknown option '--loose-aria'
|
2020-01-24 11:25:56 0 [Note] Server socket created on IP: '127.0.0.1'.
|
2020-01-24 11:25:56 0 [Note] InnoDB: Buffer pool(s) load completed at 200124 11:25:56
|
2020-01-24 11:25:56 0 [Note] Reading of all Master_info entries succeeded
|
2020-01-24 11:25:56 0 [Note] Added new Master_info '' to hash table
|
2020-01-24 11:25:56 0 [Note] /10.5/sql/mysqld: ready for connections.
|
Version: '10.5.1-MariaDB-debug-log' socket: '/10.5/mysql-test/var/tmp/62/mysqld.2.sock' port: 17261 Source distribution
|
2020-01-24 11:25:57 5 [Note] Deleted Master_info file '/10.5/mysql-test/var/62/mysqld.2/data/master.info'.
|
2020-01-24 11:25:57 5 [Note] Deleted Master_info file '/10.5/mysql-test/var/62/mysqld.2/data/relay-log.info'.
|
2020-01-24 11:25:57 5 [Note] Master connection name: '' Master_info_file: 'master.info' Relay_info_file: 'relay-log.info'
|
2020-01-24 11:25:57 5 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='127.0.0.1', master_port='17260', master_log_file='master-bin.000001', master_log_pos='4'.
|
2020-01-24 11:25:57 7 [Note] Slave I/O thread: Start asynchronous replication to master 'root@127.0.0.1:17260' in log 'master-bin.000001' at position 4
|
2020-01-24 11:25:57 8 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './slave-relay-bin.000001' position: 4
|
2020-01-24 11:25:57 7 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:17260',replication started in log 'master-bin.000001' at position 4
|
2020-01-24 11:26:09 8 [Note] Error reading relay log event: slave SQL thread was killed
|
2020-01-24 11:26:09 8 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 2245
|
2020-01-24 11:26:09 7 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 2245
|
2020-01-24 11:26:10 5 [Note] Master connection name: '' Master_info_file: 'master.info' Relay_info_file: 'relay-log.info'
|
2020-01-24 11:26:10 5 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='17260', master_log_file='master-bin.000001', master_log_pos='2245'. New state master_host='127.0.0.1', master_port='17260', master_log_file='', master_log_pos='4'.
|
2020-01-24 11:26:10 5 [Note] Previous Using_Gtid=No. New Using_Gtid=Current_Pos
|
2020-01-24 11:26:10 9 [Note] Slave I/O thread: Start asynchronous replication to master 'root@127.0.0.1:17260' in log '' at position 4
|
2020-01-24 11:26:10 10 [Note] Slave SQL thread initialized, starting replication in log 'FIRST' at position 4, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-7'
|
2020-01-24 11:26:10 9 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:17260',replication starts at GTID position '0-1-7'
|
2020-01-24 11:26:37 9 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
|
2020-01-24 11:26:37 9 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'master-bin.000001' at position 46359; GTID position '0-1-209'
|
2020-01-24 11:26:37 9 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:17260' - retry-time: 1 maximum-retries: 100 message: Can't connect to MySQL server on '127.0.0.1' (111 "Connection refused"), Internal MariaDB error code: 2003
|
2020-01-24 11:26:40 9 [Note] Slave: connected to master 'root@127.0.0.1:17260',replication resumed in log 'master-bin.000001' at position 46359
|
2020-01-24 11:26:49 10 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000002' at position 708; GTID position '0-1-211'
|
2020-01-24 11:26:49 9 [Note] Slave I/O thread exiting, read up to log 'master-bin.000002', position 708; GTID position 0-1-211
|
2020-01-24 11:26:54 11 [Note] Slave I/O thread: Start asynchronous replication to master 'root@127.0.0.1:17260' in log 'master-bin.000002' at position 708
|
2020-01-24 11:26:54 12 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000002' at position 708, relay log './slave-relay-bin.000001' position: 4; GTID position ''
|
2020-01-24 11:26:54 11 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:17260',replication starts at GTID position ''
|
2020-01-24 11:26:58 11 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
|
2020-01-24 11:26:58 11 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'master-bin.000003' at position 419; GTID position '1-1-2,2-1-1,0-1-1'
|
2020-01-24 11:26:58 11 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:17260' - retry-time: 1 maximum-retries: 100 message: Can't connect to MySQL server on '127.0.0.1' (111 "Connection refused"), Internal MariaDB error code: 2003
|
2020-01-24 11:27:00 11 [Note] Slave: connected to master 'root@127.0.0.1:17260',replication resumed in log 'master-bin.000003' at position 419
|
2020-01-24 11:27:00 12 [Note] Error reading relay log event: slave SQL thread was killed
|
2020-01-24 11:27:00 12 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000004' at position 375; GTID position '0-1-1,1-1-2,2-1-1'
|
2020-01-24 11:27:00 11 [Note] Slave I/O thread exiting, read up to log 'master-bin.000004', position 375; GTID position 1-1-2,2-1-1,0-1-1
|
2020-01-24 11:27:00 13 [Note] Slave I/O thread: Start asynchronous replication to master 'root@127.0.0.1:17260' in log 'master-bin.000004' at position 375
|
2020-01-24 11:27:00 14 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000004' at position 375, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-1,1-1-2,2-1-1'
|
2020-01-24 11:27:00 13 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:17260',replication starts at GTID position '1-1-2,0-1-1,2-1-1'
|
SIGKILL myself
|
2020-01-24 11:27:01 0 [Note] /10.5/sql/mysqld (mysqld 10.5.1-MariaDB-debug-log) starting as process 50773 ...
|
2020-01-24 11:27:01 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4246)
|
2020-01-24 11:27:01 0 [Warning] Changed limits: max_open_files: 1024 max_connections: 151 (was 151) table_cache: 421 (was 2000)
|
2020-01-24 11:27:01 0 [Note] Plugin 'partition' is disabled.
|
2020-01-24 11:27:01 0 [Note] Plugin 'SEQUENCE' is disabled.
|
2020-01-24 11:27:01 0 [Note] InnoDB: Using Linux native AIO
|
2020-01-24 11:27:01 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2020-01-24 11:27:01 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2020-01-24 11:27:01 0 [Note] InnoDB: Uses event mutexes
|
2020-01-24 11:27:01 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
|
2020-01-24 11:27:01 0 [Note] InnoDB: Number of pools: 1
|
2020-01-24 11:27:01 0 [Note] InnoDB: Using SSE2 crc32 instructions
|
2020-01-24 11:27:01 0 [Note] mysqld: O_TMPFILE is not supported on /10.5/mysql-test/var/tmp/62/mysqld.2 (disabling future attempts)
|
2020-01-24 11:27:01 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
|
2020-01-24 11:27:01 0 [Note] InnoDB: Completed initialization of buffer pool
|
2020-01-24 11:27:01 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
|
2020-01-24 11:27:01 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=217637
|
2020-01-24 11:27:01 0 [Note] InnoDB: Starting final batch to recover 7 pages from redo log.
|
2020-01-24 11:27:02 0 [Note] InnoDB: Last binlog file './slave-bin.000001', position 46573
|
2020-01-24 11:27:02 0 [Note] InnoDB: 128 rollback segments are active.
|
2020-01-24 11:27:02 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
|
2020-01-24 11:27:02 0 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2020-01-24 11:27:02 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2020-01-24 11:27:02 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
|
2020-01-24 11:27:02 0 [Note] InnoDB: 10.5.1 started; log sequence number 217759; transaction id 481
|
2020-01-24 11:27:02 0 [Note] InnoDB: Loading buffer pool(s) from /10.5/mysql-test/var/62/mysqld.2/data/ib_buffer_pool
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_CMP' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'THREAD_POOL_WAITS' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'THREAD_POOL_QUEUES' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'FEEDBACK' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'THREAD_POOL_GROUPS' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'user_variables' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'THREAD_POOL_STATS' is disabled.
|
2020-01-24 11:27:02 0 [Note] Plugin 'unix_socket' is disabled.
|
2020-01-24 11:27:02 0 [Warning] /10.5/sql/mysqld: unknown option '--loose-pam-debug'
|
2020-01-24 11:27:02 0 [Warning] /10.5/sql/mysqld: unknown option '--loose-aria'
|
2020-01-24 11:27:02 0 [Note] Recovering after a crash using slave-bin
|
2020-01-24 11:27:02 0 [Note] Starting crash recovery...
|
2020-01-24 11:27:02 0 [Note] Crash recovery finished.
|
2020-01-24 11:27:02 0 [Note] InnoDB: Buffer pool(s) load completed at 200124 11:27:02
|
2020-01-24 11:27:02 0 [Note] Server socket created on IP: '127.0.0.1'.
|
2020-01-24 11:27:02 0 [Note] Reading of all Master_info entries succeeded
|
2020-01-24 11:27:02 0 [Note] Added new Master_info '' to hash table
|
2020-01-24 11:27:02 5 [Note] Slave I/O thread: Start asynchronous replication to master 'root@127.0.0.1:17260' in log 'master-bin.000004' at position 4
|
2020-01-24 11:27:02 6 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000004' at position 4, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-1,1-1-2,2-1-1'
|
2020-01-24 11:27:02 0 [Note] /10.5/sql/mysqld: ready for connections.
|
Version: '10.5.1-MariaDB-debug-log' socket: '/10.5/mysql-test/var/tmp/62/mysqld.2.sock' port: 17261 Source distribution
|
2020-01-24 11:27:02 5 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:17260',replication starts at GTID position '1-1-2,0-1-1,2-1-1'
|
2020-01-24 11:27:02 6 [Note] Error reading relay log event: slave SQL thread was killed
|
2020-01-24 11:27:02 6 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000004' at position 579; GTID position '0-1-2,1-1-2,2-1-1'
|
2020-01-24 11:27:02 5 [Note] Slave I/O thread exiting, read up to log 'master-bin.000004', position 579; GTID position 1-1-2,0-1-2,2-1-1
|
2020-01-24 11:27:02 8 [Note] Slave I/O thread: Start asynchronous replication to master 'root@127.0.0.1:17260' in log 'master-bin.000004' at position 579
|
2020-01-24 11:27:02 9 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000004' at position 579, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-2,1-1-2,2-1-1'
|
2020-01-24 11:27:02 8 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:17260',replication starts at GTID position '1-1-2,0-1-2,2-1-1'
|
SIGKILL myself
|
2020-01-24 11:27:03 0 [Note] /10.5/sql/mysqld (mysqld 10.5.1-MariaDB-debug-log) starting as process 51376 ...
|
2020-01-24 11:27:03 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4246)
|
2020-01-24 11:27:03 0 [Warning] Changed limits: max_open_files: 1024 max_connections: 151 (was 151) table_cache: 421 (was 2000)
|
2020-01-24 11:27:03 0 [Note] Plugin 'partition' is disabled.
|
2020-01-24 11:27:03 0 [Note] Plugin 'SEQUENCE' is disabled.
|
2020-01-24 11:27:03 0 [Note] InnoDB: Using Linux native AIO
|
2020-01-24 11:27:03 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2020-01-24 11:27:03 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2020-01-24 11:27:03 0 [Note] InnoDB: Uses event mutexes
|
2020-01-24 11:27:03 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
|
2020-01-24 11:27:03 0 [Note] InnoDB: Number of pools: 1
|
2020-01-24 11:27:03 0 [Note] InnoDB: Using SSE2 crc32 instructions
|
2020-01-24 11:27:03 0 [Note] mysqld: O_TMPFILE is not supported on /10.5/mysql-test/var/tmp/62/mysqld.2 (disabling future attempts)
|
2020-01-24 11:27:03 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
|
2020-01-24 11:27:03 0 [Note] InnoDB: Completed initialization of buffer pool
|
2020-01-24 11:27:03 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
|
2020-01-24 11:27:03 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=218037
|
mysqld: /10.5/storage/innobase/log/log0recv.cc:2638: bool recv_parse_log_recs(lsn_t, store_t*, ulint, bool): Assertion `recv_sys.mlog_checkpoint_lsn <= recv_sys.recovered_lsn' failed.
|
200124 11:27:03 [ERROR] mysqld got signal 6 ;
|
This could be because you hit a bug. It is also possible that this binary
|
or one of the libraries it was linked against is corrupt, improperly built,
|
or misconfigured. This error can also be caused by malfunctioning hardware.
|
|
|
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
|
|
|
We will try our best to scrape up some info that will hopefully help
|
diagnose the problem, but since we have already crashed,
|
something is definitely wrong and this may fail.
|
|
|
Server version: 10.5.1-MariaDB-debug-log
|
key_buffer_size=1048576
|
read_buffer_size=131072
|
max_used_connections=0
|
max_threads=153
|
thread_count=0
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63718 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x0
|
Attempting backtrace. You can use the following information to find out
|
where mysqld died. If you see no messages after this, something went
|
terribly wrong...
|
stack_bottom = 0x0 thread_stack 0x49000
|
/10.5/sql/mysqld(my_print_stacktrace+0x40)[0x55e7d8179ab4]
|
/10.5/sql/mysqld(handle_fatal_signal+0x3ae)[0x55e7d78243e5]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12730)[0x7ff7b8195730]
|
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x10b)[0x7ff7b79177bb]
|
/lib/x86_64-linux-gnu/libc.so.6(abort+0x121)[0x7ff7b7902535]
|
/lib/x86_64-linux-gnu/libc.so.6(+0x2240f)[0x7ff7b790240f]
|
/lib/x86_64-linux-gnu/libc.so.6(+0x30102)[0x7ff7b7910102]
|
/10.5/sql/mysqld(+0x10ea27b)[0x55e7d7d4027b]
|
/10.5/sql/mysqld(+0x10eb474)[0x55e7d7d41474]
|
/10.5/sql/mysqld(+0x10eba12)[0x55e7d7d41a12]
|
/10.5/sql/mysqld(+0x10ed228)[0x55e7d7d43228]
|
/10.5/sql/mysqld(+0x123b5b4)[0x55e7d7e915b4]
|
/10.5/sql/mysqld(+0x1001a1e)[0x55e7d7c57a1e]
|
/10.5/sql/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0xfc)[0x55e7d7827dfd]
|
/10.5/sql/mysqld(+0x89d0ab)[0x55e7d74f30ab]
|
/10.5/sql/mysqld(_Z11plugin_initPiPPci+0xa6b)[0x55e7d74f3e2c]
|
/10.5/sql/mysqld(+0x73eb5d)[0x55e7d7394b5d]
|
/10.5/sql/mysqld(_Z11mysqld_mainiPPc+0x6db)[0x55e7d7395db0]
|
/10.5/sql/mysqld(main+0x20)[0x55e7d738a365]
|
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb)[0x7ff7b790409b]
|
/10.5/sql/mysqld(_start+0x2a)[0x55e7d738a28a]
|
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
|
information that should help you find out what is causing the crash.
|
Writing a core file...
|
Working directory at /10.5/mysql-test/var/62/mysqld.2/data
|
Resource Limits:
|
Limit Soft Limit Hard Limit Units
|
Max cpu time unlimited unlimited seconds
|
Max file size unlimited unlimited bytes
|
Max data size unlimited unlimited bytes
|
Max stack size 8388608 unlimited bytes
|
Max core file size unlimited unlimited bytes
|
Max resident set unlimited unlimited bytes
|
Max processes 515503 515503 processes
|
Max open files 1024 1024 files
|
Max locked memory 67108864 67108864 bytes
|
Max address space unlimited unlimited bytes
|
Max file locks unlimited unlimited locks
|
Max pending signals 515503 515503 signals
|
Max msgqueue size 819200 819200 bytes
|
Max nice priority 0 0
|
Max realtime priority 0 0
|
Max realtime timeout unlimited unlimited us
|
Core pattern: core
|
|
|
----------SERVER LOG END-------------
|
mysqltest failed but provided no output
|
The result from queries just before the failure was:
|
< snip >
|
a
|
1
|
2
|
3
|
*** Test crashing slave at various points and check that it recovers crash-safe. ***
|
include/stop_slave.inc
|
SET GLOBAL debug_dbug="+d,inject_crash_before_write_rpl_slave_state";
|
START SLAVE;
|
connection server_1;
|
INSERT INTO t1 VALUES (4);
|
include/save_master_gtid.inc
|
connection server_2;
|
include/sync_with_master_gtid.inc
|
include/stop_slave.inc
|
START SLAVE;
|
SET GLOBAL debug_dbug="+d,crash_commit_before";
|
connection server_1;
|
INSERT INTO t1 VALUES (5);
|
include/save_master_gtid.inc
|
connection server_2;
|
|
|
|
|
|
|
- found 'core' (0/5)
|
|
|
Trying 'dbx' to get a backtrace
|
|
|
Trying 'gdb' to get a backtrace from coredump /10.5/mysql-test/var/62/log/rpl.rpl_gtid_crash-innodb,row/mysqld.2/data/core
|
Core generated by '/10.5/sql/mysqld'
|
Output from gdb follows. The first stack trace is from the failing thread.
|
The following stack traces are from all threads (so the failing one is
|
duplicated).
|
--------------------------
|
[New LWP 51376]
|
[New LWP 51454]
|
[New LWP 51461]
|
[New LWP 51550]
|
[New LWP 51537]
|
[Thread debugging using libthread_db enabled]
|
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
|
Core was generated by `/10.5/sql/mysqld --defaults-group-suffix=.2 --defaults-file=/10.5'.
|
Program terminated with signal SIGABRT, Aborted.
|
#0 __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
|
56 ../sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
|
[Current thread is 1 (Thread 0x7ff7b78db740 (LWP 51376))]
|
#0 __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
|
#1 0x000055e7d8179ba6 in my_write_core (sig=6) at /10.5/mysys/stacktrace.c:518
|
#2 0x000055e7d782476e in handle_fatal_signal (sig=6) at /10.5/sql/signal_handler.cc:343
|
#3 <signal handler called>
|
#4 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#5 0x00007ff7b7902535 in __GI_abort () at abort.c:79
|
#6 0x00007ff7b790240f in __assert_fail_base (fmt=0x7ff7b7a64ee0 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55e7d854d988 "recv_sys.mlog_checkpoint_lsn <= recv_sys.recovered_lsn", file=0x55e7d854bdd0 "/10.5/storage/innobase/log/log0recv.cc", line=2638, function=<optimized out>) at assert.c:92
|
#7 0x00007ff7b7910102 in __GI___assert_fail (assertion=0x55e7d854d988 "recv_sys.mlog_checkpoint_lsn <= recv_sys.recovered_lsn", file=0x55e7d854bdd0 "/10.5/storage/innobase/log/log0recv.cc", line=2638, function=0x55e7d8550860 <recv_parse_log_recs(unsigned long, store_t*, unsigned long, bool)::__PRETTY_FUNCTION__> "bool recv_parse_log_recs(lsn_t, store_t*, ulint, bool)") at assert.c:101
|
#8 0x000055e7d7d4027b in recv_parse_log_recs (checkpoint_lsn=216102, store=0x7ffeb4da9bc4, available_mem=5390336, apply=true) at /10.5/storage/innobase/log/log0recv.cc:2638
|
#9 0x000055e7d7d41474 in recv_scan_log_recs (available_mem=5390336, store_to_hash=0x7ffeb4da9bc4, log_block=0x7ff7b0b81800 "", checkpoint_lsn=216102, start_lsn=216064, end_lsn=218624, contiguous_lsn=0x7ffeb4da9c48, group_scanned_lsn=0x55e7d9601498 <log_sys+664>) at /10.5/storage/innobase/log/log0recv.cc:3099
|
#10 0x000055e7d7d41a12 in recv_group_scan_log_recs (checkpoint_lsn=216102, contiguous_lsn=0x7ffeb4da9c48, last_phase=false) at /10.5/storage/innobase/log/log0recv.cc:3187
|
#11 0x000055e7d7d43228 in recv_recovery_from_checkpoint_start (flush_lsn=64036) at /10.5/storage/innobase/log/log0recv.cc:3496
|
#12 0x000055e7d7e915b4 in srv_start (create_new_db=false) at /10.5/storage/innobase/srv/srv0start.cc:1698
|
#13 0x000055e7d7c57a1e in innodb_init (p=0x55e7daa82eb8) at /10.5/storage/innobase/handler/ha_innodb.cc:4029
|
#14 0x000055e7d7827dfd in ha_initialize_handlerton (plugin=0x55e7da9c6230) at /10.5/sql/handler.cc:550
|
#15 0x000055e7d74f30ab in plugin_initialize (tmp_root=0x7ffeb4dadf30, plugin=0x55e7da9c6230, argc=0x55e7d8d97ed8 <remaining_argc>, argv=0x55e7da890048, options_only=false) at /10.5/sql/sql_plugin.cc:1452
|
#16 0x000055e7d74f3e2c in plugin_init (argc=0x55e7d8d97ed8 <remaining_argc>, argv=0x55e7da890048, flags=0) at /10.5/sql/sql_plugin.cc:1734
|
#17 0x000055e7d7394b5d in init_server_components () at /10.5/sql/mysqld.cc:5008
|
#18 0x000055e7d7395db0 in mysqld_main (argc=167, argv=0x55e7da890048) at /10.5/sql/mysqld.cc:5536
|
#19 0x000055e7d738a365 in main (argc=27, argv=0x7ffeb4dae778) at /10.5/sql/main.cc:25
|
|
|
Thread 5 (Thread 0x7ff7b1d81700 (LWP 51537)):
|
#0 syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
|
#1 0x00007ff7b814527a in ?? () from /usr/lib/x86_64-linux-gnu/libaio.so.1
|
#2 0x000055e7d80ccd0e in tpool::aio_linux::getevent_thread_routine (aio=0x55e7daa7c010) at /10.5/tpool/aio_linux.cc:53
|
#3 0x000055e7d80cd377 in std::__invoke_impl<void, void (*)(tpool::aio_linux*), tpool::aio_linux*> (__f=@0x55e7daafeb50: 0x55e7d80cccca <tpool::aio_linux::getevent_thread_routine(tpool::aio_linux*)>, __args#0=@0x55e7daafeb48: 0x55e7daa7c010) at /usr/include/c++/8/bits/invoke.h:60
|
#4 0x000055e7d80cd09e in std::__invoke<void (*)(tpool::aio_linux*), tpool::aio_linux*> (__fn=@0x55e7daafeb50: 0x55e7d80cccca <tpool::aio_linux::getevent_thread_routine(tpool::aio_linux*)>, __args#0=@0x55e7daafeb48: 0x55e7daa7c010) at /usr/include/c++/8/bits/invoke.h:95
|
#5 0x000055e7d80cd625 in std::thread::_Invoker<std::tuple<void (*)(tpool::aio_linux*), tpool::aio_linux*> >::_M_invoke<0ul, 1ul> (this=0x55e7daafeb48) at /usr/include/c++/8/thread:244
|
#6 0x000055e7d80cd5e0 in std::thread::_Invoker<std::tuple<void (*)(tpool::aio_linux*), tpool::aio_linux*> >::operator() (this=0x55e7daafeb48) at /usr/include/c++/8/thread:253
|
#7 0x000055e7d80cd5c4 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (*)(tpool::aio_linux*), tpool::aio_linux*> > >::_M_run (this=0x55e7daafeb40) at /usr/include/c++/8/thread:196
|
#8 0x00007ff7b7cf9b2f in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
|
#9 0x00007ff7b818afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
|
#10 0x00007ff7b79d94cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
|
|
Thread 4 (Thread 0x7ff7b0980700 (LWP 51550)):
|
#0 futex_wait_cancelable (private=0, expected=0, futex_word=0x55e7dac54ec8) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
|
#1 __pthread_cond_wait_common (abstime=0x0, mutex=0x55e7dac54e78, cond=0x55e7dac54ea0) at pthread_cond_wait.c:502
|
#2 __pthread_cond_wait (cond=0x55e7dac54ea0, mutex=0x55e7dac54e78) at pthread_cond_wait.c:655
|
#3 0x000055e7d7d6642c in os_event::wait (this=0x55e7dac54e60) at /10.5/storage/innobase/os/os0event.cc:158
|
#4 0x000055e7d7d65f38 in os_event::wait_low (this=0x55e7dac54e60, reset_sig_count=1) at /10.5/storage/innobase/os/os0event.cc:325
|
#5 0x000055e7d7d6621b in os_event_wait_low (event=0x55e7dac54e60, reset_sig_count=0) at /10.5/storage/innobase/os/os0event.cc:502
|
#6 0x000055e7d7fa3324 in buf_flush_page_cleaner_coordinator () at /10.5/storage/innobase/buf/buf0flu.cc:3174
|
#7 0x00007ff7b818afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
|
#8 0x00007ff7b79d94cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
|
|
Thread 3 (Thread 0x7ff7b2998700 (LWP 51461)):
|
#0 futex_abstimed_wait_cancelable (private=0, abstime=0x7ff7b2997de0, expected=0, futex_word=0x55e7d95d55c8 <COND_checkpoint+40>) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
|
#1 __pthread_cond_wait_common (abstime=0x7ff7b2997de0, mutex=0x55e7d95d5508 <LOCK_checkpoint+40>, cond=0x55e7d95d55a0 <COND_checkpoint>) at pthread_cond_wait.c:539
|
#2 __pthread_cond_timedwait (cond=0x55e7d95d55a0 <COND_checkpoint>, mutex=0x55e7d95d5508 <LOCK_checkpoint+40>, abstime=0x7ff7b2997de0) at pthread_cond_wait.c:667
|
#3 0x000055e7d817ff50 in safe_cond_timedwait (cond=0x55e7d95d55a0 <COND_checkpoint>, mp=0x55e7d95d54e0 <LOCK_checkpoint>, abstime=0x7ff7b2997de0, file=0x55e7d84d0df0 "/10.5/include/mysql/psi/mysql_thread.h", line=1204) at /10.5/mysys/thr_mutex.c:546
|
#4 0x000055e7d7af94b5 in inline_mysql_cond_timedwait (that=0x55e7d95d55a0 <COND_checkpoint>, mutex=0x55e7d95d54e0 <LOCK_checkpoint>, abstime=0x7ff7b2997de0, src_file=0x55e7d84d0e20 "/10.5/storage/maria/ma_servicethread.c", src_line=116) at /10.5/include/mysql/psi/mysql_thread.h:1204
|
#5 0x000055e7d7af99fa in my_service_thread_sleep (control=0x55e7d8bc5c80 <checkpoint_control>, sleep_time=29000000000) at /10.5/storage/maria/ma_servicethread.c:115
|
#6 0x000055e7d7aecce6 in ma_checkpoint_background (arg=0x1e) at /10.5/storage/maria/ma_checkpoint.c:707
|
#7 0x000055e7d7beeb08 in pfs_spawn_thread (arg=0x55e7daa71ac8) at /10.5/storage/perfschema/pfs.cc:1862
|
#8 0x00007ff7b818afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
|
#9 0x00007ff7b79d94cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
|
|
Thread 2 (Thread 0x7ff7b3511700 (LWP 51454)):
|
#0 futex_abstimed_wait_cancelable (private=0, abstime=0x7ff7b3510e90, expected=0, futex_word=0x55e7d964058c <COND_timer+44>) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
|
#1 __pthread_cond_wait_common (abstime=0x7ff7b3510e90, mutex=0x55e7d96404c8 <LOCK_timer+40>, cond=0x55e7d9640560 <COND_timer>) at pthread_cond_wait.c:539
|
#2 __pthread_cond_timedwait (cond=0x55e7d9640560 <COND_timer>, mutex=0x55e7d96404c8 <LOCK_timer+40>, abstime=0x7ff7b3510e90) at pthread_cond_wait.c:667
|
#3 0x000055e7d817ff50 in safe_cond_timedwait (cond=0x55e7d9640560 <COND_timer>, mp=0x55e7d96404a0 <LOCK_timer>, abstime=0x7ff7b3510e90, file=0x55e7d868bac0 "/10.5/include/mysql/psi/mysql_thread.h", line=1204) at /10.5/mysys/thr_mutex.c:546
|
#4 0x000055e7d81813e0 in inline_mysql_cond_timedwait (that=0x55e7d9640560 <COND_timer>, mutex=0x55e7d96404a0 <LOCK_timer>, abstime=0x7ff7b3510e90, src_file=0x55e7d868baf0 "/10.5/mysys/thr_timer.c", src_line=321) at /10.5/include/mysql/psi/mysql_thread.h:1204
|
#5 0x000055e7d81820b9 in timer_handler (arg=0x0) at /10.5/mysys/thr_timer.c:321
|
#6 0x000055e7d7beeb08 in pfs_spawn_thread (arg=0x55e7da9bdf58) at /10.5/storage/perfschema/pfs.cc:1862
|
#7 0x00007ff7b818afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
|
#8 0x00007ff7b79d94cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
|
|
Thread 1 (Thread 0x7ff7b78db740 (LWP 51376)):
|
#0 __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
|
#1 0x000055e7d8179ba6 in my_write_core (sig=6) at /10.5/mysys/stacktrace.c:518
|
#2 0x000055e7d782476e in handle_fatal_signal (sig=6) at /10.5/sql/signal_handler.cc:343
|
#3 <signal handler called>
|
#4 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#5 0x00007ff7b7902535 in __GI_abort () at abort.c:79
|
#6 0x00007ff7b790240f in __assert_fail_base (fmt=0x7ff7b7a64ee0 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55e7d854d988 "recv_sys.mlog_checkpoint_lsn <= recv_sys.recovered_lsn", file=0x55e7d854bdd0 "/10.5/storage/innobase/log/log0recv.cc", line=2638, function=<optimized out>) at assert.c:92
|
#7 0x00007ff7b7910102 in __GI___assert_fail (assertion=0x55e7d854d988 "recv_sys.mlog_checkpoint_lsn <= recv_sys.recovered_lsn", file=0x55e7d854bdd0 "/10.5/storage/innobase/log/log0recv.cc", line=2638, function=0x55e7d8550860 <recv_parse_log_recs(unsigned long, store_t*, unsigned long, bool)::__PRETTY_FUNCTION__> "bool recv_parse_log_recs(lsn_t, store_t*, ulint, bool)") at assert.c:101
|
#8 0x000055e7d7d4027b in recv_parse_log_recs (checkpoint_lsn=216102, store=0x7ffeb4da9bc4, available_mem=5390336, apply=true) at /10.5/storage/innobase/log/log0recv.cc:2638
|
#9 0x000055e7d7d41474 in recv_scan_log_recs (available_mem=5390336, store_to_hash=0x7ffeb4da9bc4, log_block=0x7ff7b0b81800 "", checkpoint_lsn=216102, start_lsn=216064, end_lsn=218624, contiguous_lsn=0x7ffeb4da9c48, group_scanned_lsn=0x55e7d9601498 <log_sys+664>) at /10.5/storage/innobase/log/log0recv.cc:3099
|
#10 0x000055e7d7d41a12 in recv_group_scan_log_recs (checkpoint_lsn=216102, contiguous_lsn=0x7ffeb4da9c48, last_phase=false) at /10.5/storage/innobase/log/log0recv.cc:3187
|
#11 0x000055e7d7d43228 in recv_recovery_from_checkpoint_start (flush_lsn=64036) at /10.5/storage/innobase/log/log0recv.cc:3496
|
#12 0x000055e7d7e915b4 in srv_start (create_new_db=false) at /10.5/storage/innobase/srv/srv0start.cc:1698
|
#13 0x000055e7d7c57a1e in innodb_init (p=0x55e7daa82eb8) at /10.5/storage/innobase/handler/ha_innodb.cc:4029
|
#14 0x000055e7d7827dfd in ha_initialize_handlerton (plugin=0x55e7da9c6230) at /10.5/sql/handler.cc:550
|
#15 0x000055e7d74f30ab in plugin_initialize (tmp_root=0x7ffeb4dadf30, plugin=0x55e7da9c6230, argc=0x55e7d8d97ed8 <remaining_argc>, argv=0x55e7da890048, options_only=false) at /10.5/sql/sql_plugin.cc:1452
|
#16 0x000055e7d74f3e2c in plugin_init (argc=0x55e7d8d97ed8 <remaining_argc>, argv=0x55e7da890048, flags=0) at /10.5/sql/sql_plugin.cc:1734
|
#17 0x000055e7d7394b5d in init_server_components () at /10.5/sql/mysqld.cc:5008
|
#18 0x000055e7d7395db0 in mysqld_main (argc=167, argv=0x55e7da890048) at /10.5/sql/mysqld.cc:5536
|
#19 0x000055e7d738a365 in main (argc=27, argv=0x7ffeb4dae778) at /10.5/sql/main.cc:25
|
I would like to see this repeated with ./mtr --rr using the patch from MDEV-22179.
With a rr replay of the server that was killed right before the failed recovery, we should be able to figure out the cause.
I believe that this bug should be possible also in 10.5. The code was heavily refactored related to MDEV-12353, and the MLOG_CHECKPOINT record was replaced by FILE_CHECKPOINT, but the logic should be similar ever since 10.2.2. Only in MDEV-14425 (which missed 10.5) we would eliminate this logic and drastically reduce the amount of log written by a checkpoint.
I believe that this bug should also be repeatable with RQG. It could help to use innodb_encrypt_tables, innodb_page_size=64k and innodb_checksum_algorithm=crc32, to make page flushing as slow as possible. (The default 10.5 innodb_checksum_algorithm=full_crc32 would only compute one checksum per page.) We should only need lots of writes, and frequent checkpoints. Checkpoints can be triggered in debug builds with the following:
SET GLOBAL innodb_log_checkpoint_now=ON; |
We might also want to set --debug-dbug=d,ib_log_checkpoint_avoid to forbid checkpoints being from being triggered by background activity. Repeating this bug might require that there be long enough pauses between checkpoints.
I suspected that this bug could share a root cause with MDEV-22027, but that bug turned out to be a 10.5-specific regression.
Before killing the server:
=============
Thread A tries to do log_checkpoint() and does fil_names_clear() It does log_write_up_to().
Another thread B does the similar operation like fil_names_clear() and it also does log_write_up_to()
Another thread C does the similar operation like fil_names_clear() and finishes log_write_up_to(). Writes the checkpoint info in log file header.
After that, Thread A and Thread B return from log_checkpoint() without writing checkpoint info because it has log_sys.n_pending_checkpoint_writes value as 0.
During recovery:
=============
First scan: By using end_lsn, InnoDB does parse the redo log from end_lsn (thread C's one) and finds the FILE_CHECKPOINT lsn for it.
(mlog_checkpoint_lsn is 110052239)
Second scan: It starts from checkpoint_lsn, parse the redo log and find the FILE_CHECKPOINT lsn of thread As. (110051441).
The recovery has the following check in recv_sys_t::parse()
if (lsn == checkpoint_lsn)
|
{
|
ut_ad(mlog_checkpoint_lsn <= recovered_lsn);
|
if (mlog_checkpoint_lsn)
|
continue;
|
mlog_checkpoint_lsn= recovered_lsn;
|
l+= 8;
|
recovered_offset= l - buf;
|
return true;
|
}
|
For the above code, recovered_lsn value is 110051441. It leads to debug assert. IMO, we should remove the assert and it is wrong.
Thank you. The debug assertion is indeed bogus and should be removed.
innodb.innodb_bug59641 failed with recv_sys->mlog_checkpoint_lsn <= recv_sys->recovered_lsn assertion http://buildbot.askmonty.org/buildbot/builders/win32-debug/builds/6391/steps/test/logs/stdio
2017-11-24 21:14:58 11040 [Note] InnoDB: Starting crash recovery from checkpoint LSN=7858266Assertion failed: recv_sys->mlog_checkpoint_lsn <= recv_sys->recovered_lsn, file D:\win32-debug\build\src\storage\innobase\log\log0recv.cc, line 2345171124 21:14:58 [ERROR] mysqld got exception 0x80000003 ;mysqld.exe!my_sigabrt_handler()[my_thr_init.c:488]mysqld.exe!raise()[signal.cpp:516]mysqld.exe!abort()[abort.cpp:64]mysqld.exe!common_assert_to_stderr<wchar_t>()[assert.cpp:149]mysqld.exe!_wassert()[assert.cpp:404]mysqld.exe!recv_parse_log_recs()[log0recv.cc:2344]mysqld.exe!recv_scan_log_recs()[log0recv.cc:2822]mysqld.exe!recv_group_scan_log_recs()[log0recv.cc:2910]mysqld.exe!recv_recovery_from_checkpoint_start()[log0recv.cc:3199]mysqld.exe!innobase_start_or_create_for_mysql()[srv0start.cc:2241]mysqld.exe!innobase_init()[ha_innodb.cc:4362]mysqld.exe!ha_initialize_handlerton()[handler.cc:520]mysqld.exe!plugin_initialize()[sql_plugin.cc:1411]mysqld.exe!plugin_init()[sql_plugin.cc:1692]mysqld.exe!init_server_components()[mysqld.cc:5277]mysqld.exe!win_main()[mysqld.cc:5869]mysqld.exe!mysql_service()[mysqld.cc:6123]mysqld.exe!mysqld_main()[mysqld.cc:6317]mysqld.exe!main()[main.cc:25]mysqld.exe!__scrt_common_main_seh()[exe_common.inl:283]KERNEL32.DLL!BaseThreadInitThunk()ntdll.dll!RtlInitializeExceptionChain()ntdll.dll!RtlInitializeExceptionChain()The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html containsinformation that should help you find out what is causing the crash.Writing a core fileMinidump written to D:\win32-debug\build\mysql-test\var\1\mysqld.1\data\mysqld.dmp----------SERVER LOG END-------------mysqltest failed but provided no outputThe result from queries just before the failure was:< snip >XA END '456';XA PREPARE '456';CONNECT con2,localhost,root,,;XA START '789';UPDATE t SET b=4*a WHERE a=32;XA END '789';XA PREPARE '789';CONNECT con3,localhost,root,,;SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;SELECT * FROM t;a b1 12 23 474 45 1348 1616 1632 128COMMIT;