Bug #104356 Semi-sync replication switched OFF
Submitted: 20 Jul 2021 7:11 Modified: 20 Jul 2021 19:56
Reporter: DF Rong Email Updates:
Status: Can't repeat Impact on me:
None 
Category:Tests: Group Replication Severity:S3 (Non-critical)
Version:5.7.21 OS:SUSE (suse 12)
Assigned to: MySQL Verification Team CPU Architecture:x86
Tags: Semi-sync replication

[20 Jul 2021 7:11] DF Rong
Description:
mysql master is down and then swithing the slave to  the new master happend again

old master 76.154.101.85:

2021-05-22T20:29:29.865797+08:00 498918 [Note] Aborted connection 498918 to db: 'dcscbm_db' user: 'appgbm' host: '84.154.117.9' (Got timeout reading communication packets)
2021-05-22T22:02:57.448826+08:00 0 [ERROR] /data/app/mysql/bin/mysqld: Got an error reading communication packets
2021-05-22T22:02:57.465662+08:00 505677 [Note] Semi-sync replication switched OFF.
2021-05-22T22:02:57.465690+08:00 505677 [Note] Semi-sync replication disabled on the master.
2021-05-22T22:02:57.466107+08:00 505676 [Note] While initializing dump thread for slave with UUID <15910e6d-5587-11eb-9bad-fa163ee42c36>, found a zombie dump thread with the same UUID. Master is killing the zombie dump thread(400444).
2021-05-22T22:02:57.466150+08:00 400444 [Note] Stop semi-sync binlog_dump to slave (server_id: -1210754242)
2021-05-22T22:02:57.466207+08:00 505676 [Note] Start binlog_dump to master_thread_id(505676) slave_server(3084213054), pos(, 4)
2021-05-22T22:02:57.466216+08:00 505676 [Note] Start asynchronous binlog_dump to slave (server_id: -1210754242), pos(, 4)
2021-05-22T22:02:58.449930+08:00 0 [Note] Stopping ack receiver thread
2021-05-22T22:02:58.450572+08:00 505677 [Note] Semi-sync replication initialized for transactions.
2021-05-22T22:02:58.450593+08:00 505677 [Note] Semi-sync replication enabled on the master.
2021-05-22T22:02:58.450661+08:00 0 [Note] Starting ack receiver thread
2021-05-22T22:02:59.368714+08:00 505676 [Note] Stop asynchronous binlog_dump to slave (server_id: -1210754242)
2021-05-22T22:02:59.368762+08:00 505676 [Note] Aborted connection 505676 to db: 'unconnected' user: 'admin' host: '84.154.98.65' (failed on flush_net())
2021-05-22T22:03:05.494167+08:00 505677 [Note] Semi-sync replication switched OFF.
2021-05-22T22:03:05.494193+08:00 505677 [Note] Semi-sync replication disabled on the master.
2021-05-22 22:03:05 0x7f88bcbe5700  InnoDB: Assertion failure in thread 140225258870528 in file pars0pars.cc line 822
InnoDB: Failing assertion: sym_node->table != NULL
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
14:03:05 UTC - 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=69
max_threads=512
thread_count=38
connection_count=38
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 146104 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 = 0 thread_stack 0x40000
/data/app/mysql/bin/mysqld(my_print_stacktrace+0x35)[0xf4a495]
/data/app/mysql/bin/mysqld(handle_fatal_signal+0x4a4)[0x7ce2f4]
/lib64/libpthread.so.0(+0x11c00)[0x7f8b06ad4c00]
/lib64/libc.so.6(gsignal+0x37)[0x7f8b0540b2a7]
/lib64/libc.so.6(abort+0x13a)[0x7f8b0540c67a]
/data/app/mysql/bin/mysqld(_Z18ut_print_timestampP8_IO_FILE+0x0)[0x7bd70e]
/data/app/mysql/bin/mysqld[0x108c816]
/data/app/mysql/bin/mysqld(_Z21pars_insert_statementP10sym_node_tPvP10sel_node_t+0x3f)[0x108e48f]
/data/app/mysql/bin/mysqld(_Z7yyparsev+0xb3f)[0x125e13f]
/data/app/mysql/bin/mysqld(_Z8pars_sqlP11pars_info_tPKc+0xbe)[0x108d21e]
/data/app/mysql/bin/mysqld(_Z13fts_parse_sqlP11fts_table_tP11pars_info_tPKc+0x68)[0x1245128]
/data/app/mysql/bin/mysqld(_Z14fts_write_nodeP5trx_tPP10que_fork_tP11fts_table_tP12fts_string_tP10fts_node_t+0x206)[0x1226d66]
/data/app/mysql/bin/mysqld[0x122eff8]
/data/app/mysql/bin/mysqld(_Z14fts_sync_tableP12dict_table_tbbb+0x25c)[0x12340dc]
/data/app/mysql/bin/mysqld(_Z23fts_optimize_sync_tablem+0x42)[0x1236a92]
/data/app/mysql/bin/mysqld(_Z19fts_optimize_threadPv+0x4f4)[0x123c874]
/lib64/libpthread.so.0(+0x96da)[0x7f8b06acc6da]
/lib64/libc.so.6(clone+0x6d)[0x7f8b054c32ed]
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.
2021-05-22T22:38:02.277429+08:00 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2021-05-22T22:38:02.277578+08:00 0 [Warning] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.

How to repeat:
happend again on the new master(one of semi-sync slave)
new master(one of semi-sync slave)76.154.101.78:

2021-05-22T21:59:44.870735+08:00 59 [Note] Multi-threaded slave statistics for channel '': seconds elapsed = 256; events assigned = 146619393; worker queues filled over overrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 425522217700 waited (count) when Workers occupied = 0 waited when Workers occupied = 0
2021-05-22T22:03:05.592614+08:00 58 [ERROR] Error reading packet from server for channel '': Lost connection to MySQL server during query (server_errno=2013)
2021-05-22T22:03:05.592642+08:00 58 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'mysql-bin.000027' at position 272244389 for channel ''
2021-05-22T22:03:05.592653+08:00 58 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2021-05-22T22:03:05.602937+08:00 58 [ERROR] Slave I/O for channel '': error reconnecting to master 'admin@76.154.101.85:3306' - retry-time: 60  retries: 1, Error_code: 2003
2021-05-22T22:03:05.602947+08:00 58 [Note] Slave I/O thread killed during or after a reconnect done to recover from failed read
2021-05-22T22:03:05.602952+08:00 58 [Note] Slave I/O thread exiting for channel '', read up to log 'mysql-bin.000027', position 272244389
2021-05-22T22:03:13.469346+08:00 59 [Note] Error reading relay log event for channel '': slave SQL thread was killed
2021-05-22T22:03:20.536776+08:00 460689 [Note] Semi-sync replication initialized for transactions.
2021-05-22T22:03:20.536807+08:00 460689 [Note] Semi-sync replication enabled on the master.
2021-05-22T22:03:20.536858+08:00 0 [Note] Starting ack receiver thread
2021-05-22T22:03:20.549766+08:00 460690 [Note] Start binlog_dump to master_thread_id(460690) slave_server(1034037180), pos(, 4)
2021-05-22T22:03:20.549799+08:00 460690 [Note] Start semi-sync binlog_dump to slave (server_id: 1034037180), pos(, 4)
2021-05-22T22:03:23.869324+08:00 460354 [Warning] Timeout waiting for reply of binlog (file: mysql-bin.000026, pos: 477976391), semi-sync up to file , position 0.
2021-05-22T22:03:23.869351+08:00 460354 [Note] Semi-sync replication switched OFF.
2021-05-22T22:03:31.405135+08:00 460678 [Note] Semi-sync replication switched OFF.
2021-05-22T22:03:31.405167+08:00 460678 [Note] Semi-sync replication disabled on the master.
2021-05-22T22:03:32.374515+08:00 0 [Note] Stopping ack receiver thread
2021-05-22T22:03:37.439275+08:00 460678 [Note] Semi-sync replication initialized for transactions.
2021-05-22T22:03:37.439298+08:00 460678 [Note] Semi-sync replication enabled on the master.
2021-05-22T22:03:37.439387+08:00 0 [Note] Starting ack receiver thread
2021-05-22T22:03:40.456823+08:00 460678 [Note] Semi-sync replication switched OFF.
2021-05-22T22:03:40.456859+08:00 460678 [Note] Semi-sync replication disabled on the master.
2021-05-22T22:03:41.373388+08:00 0 [Note] Stopping ack receiver thread
2021-05-22T22:03:41.374063+08:00 460678 [Note] Semi-sync replication initialized for transactions.
2021-05-22T22:03:41.374084+08:00 460678 [Note] Semi-sync replication enabled on the master.
2021-05-22T22:03:41.374144+08:00 0 [Note] Starting ack receiver thread
2021-05-22 22:11:36 0x7fbc453e6700  InnoDB: Assertion failure in thread 140446592296704 in file pars0pars.cc line 822
InnoDB: Failing assertion: sym_node->table != NULL
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
14:11:36 UTC - 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=33
max_threads=512
thread_count=32
connection_count=32
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 146104 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 = 0 thread_stack 0x40000
/data/app/mysql/bin/mysqld(my_print_stacktrace+0x35)[0xf4a495]
/data/app/mysql/bin/mysqld(handle_fatal_signal+0x4a4)[0x7ce2f4]
/lib64/libpthread.so.0(+0x11c00)[0x7fbe8fa2fc00]
/lib64/libc.so.6(gsignal+0x37)[0x7fbe8e3662a7]
/lib64/libc.so.6(abort+0x13a)[0x7fbe8e36767a]
/data/app/mysql/bin/mysqld(_Z18ut_print_timestampP8_IO_FILE+0x0)[0x7bd70e]
/data/app/mysql/bin/mysqld[0x108c816]
/data/app/mysql/bin/mysqld(_Z21pars_insert_statementP10sym_node_tPvP10sel_node_t+0x3f)[0x108e48f]
/data/app/mysql/bin/mysqld(_Z7yyparsev+0xb3f)[0x125e13f]
/data/app/mysql/bin/mysqld(_Z8pars_sqlP11pars_info_tPKc+0xbe)[0x108d21e]
/data/app/mysql/bin/mysqld(_Z13fts_parse_sqlP11fts_table_tP11pars_info_tPKc+0x68)[0x1245128]
/data/app/mysql/bin/mysqld(_Z14fts_write_nodeP5trx_tPP10que_fork_tP11fts_table_tP12fts_string_tP10fts_node_t+0x206)[0x1226d66]
/data/app/mysql/bin/mysqld[0x122eff8]
/data/app/mysql/bin/mysqld(_Z14fts_sync_tableP12dict_table_tbbb+0x25c)[0x12340dc]
/data/app/mysql/bin/mysqld(_Z23fts_optimize_sync_tablem+0x42)[0x1236a92]
/data/app/mysql/bin/mysqld(_Z19fts_optimize_threadPv+0x4f4)[0x123c874]
/lib64/libpthread.so.0(+0x96da)[0x7fbe8fa276da]
/lib64/libc.so.6(clone+0x6d)[0x7fbe8e41e2ed]
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.
2021-05-22T22:37:30.197702+08:00 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2021-05-22T22:37:30.197857+08:00 0 [Warning] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
2021-05-22T22:37:30.197890+08:00 0 [Note] /data/app/mysql/bin/mysqld (mysqld 5.7.21-log) starting as process 98905 ...
2021-05-22T22:37:30.204489+08:00 0 [Note] InnoDB: PUNCH HOLE support available
[20 Jul 2021 19:56] MySQL Verification Team
Hi,

I cannot reproduce this with current 5.7.35. Can you upgrade and see if you can reproduce the problem.

Thanks