[MDEV-19762] binlog.binlog_max_extension failed in buildbot with crash on shutdown Created: 2019-06-14  Updated: 2021-12-21  Resolved: 2021-12-21

Status: Closed
Project: MariaDB Server
Component/s: Replication, Tests
Affects Version/s: 10.2
Fix Version/s: 10.2.42, 10.3.33, 10.5.14, 10.6.6, 10.7.2, 10.4.24

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Brandon Nesterenko
Resolution: Fixed Votes: 0
Labels: None


 Description   

Note: Judging by timestamps in the log, it's not a hang on shutdown, followed by a forced kill; it crashed right away after starting the shutdown.

http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-aarch64/builds/4787

10.2 c9b49a4be723c18a8fad2bf4fd549079

binlog.binlog_max_extension 'row'        w3 [ fail ]  Found warnings/errors in server log file!
        Test ended at 2019-05-31 10:13:50
line
Attempting backtrace. You can use the following information to find out
^ Found warnings in /dev/shm/var/3/log/mysqld.1.err

2019-05-31 10:13:47 281472608469152 [Note] /usr/sbin/mysqld (initiated by: root[root] @ localhost []): Normal shutdown
190531 10:13:47 [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.25-MariaDB-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=3
max_threads=153
thread_count=2
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63022 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
2019-05-31 10:13:47 281472608469152 [Note] Event Scheduler: Purging the queue. 0 events
2019-05-31 10:13:47 281472608469152 [Note] /usr/sbin/mysqld: Shutdown complete
 
addr2line: Dwarf Error: Offset (16919874) greater than or equal to .debug_str size (2525400).
addr2line: Dwarf Error: Offset (2387608077) greater than or equal to .debug_str size (121168).
addr2line: Dwarf Error: Offset (727842851) greater than or equal to .debug_str size (2525400).
addr2line: Dwarf Error: Offset (2221408782) greater than or equal to .debug_str size (121168).
addr2line: Dwarf Error: Offset (727842847) greater than or equal to .debug_str size (2525400).
addr2line: Dwarf Error: Offset (2385445394) greater than or equal to .debug_str size (121168).
addr2line: Dwarf Error: Offset (727842851) greater than or equal to .debug_str size (2525400).
2019-05-31 10:13:48 281472944694928 [Note] /usr/sbin/mysqld (mysqld 10.2.25-MariaDB-log) starting as process 7770 ...
2019-05-31 10:13:48 281472944694928 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4186)
2019-05-31 10:13:48 281472944694928 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'SEQUENCE' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'partition' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'InnoDB' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_LOCKS' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_CMPMEM' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_CMP_PER_INDEX' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_CMP' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_BUFFER_PAGE_LRU' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'FEEDBACK' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'user_variables' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_SYS_FOREIGN_COLS' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_BUFFER_POOL_STATS' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_TRX' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_SYS_FOREIGN' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_SYS_TABLES' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_BUFFER_PAGE' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_METRICS' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_SYS_VIRTUAL' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2019-05-31 10:13:48 281472944694928 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2019-05-31 10:13:48 281472944694928 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
2019-05-31 10:13:48 281472944694928 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
2019-05-31 10:13:48 281472944694928 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'
2019-05-31 10:13:48 281472944694928 [Warning] /usr/sbin/mysqld: unknown option '--loose-pam-debug'
2019-05-31 10:13:48 281472944694928 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
2019-05-31 10:13:48 281472944694928 [Warning] Next log extension: 2147483647. Remaining log filename extensions: 0. Please consider archiving some logs.
2019-05-31 10:13:48 281472944694928 [Note] Server socket created on IP: '127.0.0.1'.
2019-05-31 10:13:48 281472944694928 [Note] Reading of all Master_info entries succeded
2019-05-31 10:13:48 281472944694928 [Note] Added new Master_info '' to hash table
2019-05-31 10:13:48 281472944694928 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.2.25-MariaDB-log'  socket: '/dev/shm/var/tmp/3/mysqld.1.sock'  port: 16040  MariaDB Server
addr2line: Dwarf Error: Offset (6516329) greater than or equal to .debug_str size (2525400).
2019-05-31 10:13:48 281472836206752 [ERROR] Log filename extension number exhausted: 2147483647. Please fix this by archiving old logs and updating the index files.
2019-05-31 10:13:48 281472836206752 [ERROR] Can't generate a unique log-filename master-bin.(1-999)
 
2019-05-31 10:13:48 281472835813536 [Note] /usr/sbin/mysqld (initiated by: root[root] @ localhost []): Normal shutdown
2019-05-31 10:13:48 281472835813536 [Note] Event Scheduler: Purging the queue. 0 events
2019-05-31 10:13:48 281472835813536 [Note] /usr/sbin/mysqld: Shutdown complete
 
addr2line: Dwarf Error: Offset (27853221) greater than or equal to .debug_str size (2525400).
addr2line: Dwarf Error: Offset (1663697) greater than or equal to .debug_str size (121168).
addr2line: Dwarf Error: Offset (2321308) greater than or equal to .debug_str size (121168).
addr2line: Dwarf Error: Offset (563158408) greater than or equal to .debug_str size (2525400).
addr2line: Dwarf Error: Offset (6514020) greater than or equal to .debug_str size (121168).
addr2line: Dwarf Error: Offset (33562261) greater than or equal to .debug_str size (121168).
addr2line: Dwarf Error: Offset (6516329) greater than or equal to .debug_str size (121168).
addr2line: Dwarf Error: Offset (33562305) greater than or equal to .debug_str size (121168).
addr2line: Dwarf Error: Offset (622577429) greater than or equal to .debug_str size (2525400).
addr2line: Dwarf Error: Offset (622577429) greater than or equal to .debug_str size (2525400).
addr2line: Dwarf Error: Offset (864945) greater than or equal to .debug_str size (121168).
2019-05-31 10:13:49 281473149626000 [Note] /usr/sbin/mysqld (mysqld 10.2.25-MariaDB-log) starting as process 7873 ...
2019-05-31 10:13:49 281473149626000 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4186)
2019-05-31 10:13:49 281473149626000 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'SEQUENCE' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'partition' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'InnoDB' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_LOCKS' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_CMPMEM' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_CMP_PER_INDEX' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_CMP' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_BUFFER_PAGE_LRU' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'FEEDBACK' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'user_variables' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_SYS_FOREIGN_COLS' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_BUFFER_POOL_STATS' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_TRX' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_SYS_FOREIGN' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_SYS_TABLES' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_BUFFER_PAGE' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_METRICS' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_SYS_VIRTUAL' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2019-05-31 10:13:49 281473149626000 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2019-05-31 10:13:49 281473149626000 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
2019-05-31 10:13:49 281473149626000 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
2019-05-31 10:13:49 281473149626000 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'
2019-05-31 10:13:49 281473149626000 [Warning] /usr/sbin/mysqld: unknown option '--loose-pam-debug'
2019-05-31 10:13:49 281473149626000 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
2019-05-31 10:13:49 281473149626000 [Note] Server socket created on IP: '127.0.0.1'.
2019-05-31 10:13:49 281473149626000 [Note] Reading of all Master_info entries succeded
2019-05-31 10:13:49 281473149626000 [Note] Added new Master_info '' to hash table
2019-05-31 10:13:49 281473149626000 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.2.25-MariaDB-log'  socket: '/dev/shm/var/tmp/3/mysqld.1.sock'  port: 16040  MariaDB Server



 Comments   
Comment by Brandon Nesterenko [ 2021-05-18 ]

Could not reproduce. Will continue to monitor buildbot for crashes of this nature; however, it may have been coincidentally fixed by other patches. More specifically, the logs of other buildbot entries show the lines of code in which the crash happened, where the following patches may have fixed the underlying issue:
1) https://github.com/MariaDB/server/commit/9b750dcbd89ecf455211a77348a85464b282abee
2) https://github.com/MariaDB/server/commit/5e139437a5c624b3bb55fb269fa91b63b7b65deb

More detailed stack trace of similar crash:
Program terminated with signal SIGSEGV, Segmentation fault.
#0 0xb776bc31 in __kernel_vsyscall ()
[Current thread is 1 (Thread 0xb72c2b40 (LWP 28199))]
#0 0xb776bc31 in __kernel_vsyscall ()
#1 0xb76c0ce1 in pthread_kill () from /lib/i386-linux-gnu/libpthread.so.0
#2 0x088dd344 in my_write_core (sig=11) at /home/buildbot/buildbot/build/mariadb-5.5.68/mysys/stacktrace.c:457
#3 0x083d7d7e in handle_fatal_signal (sig=11) at /home/buildbot/buildbot/build/mariadb-5.5.68/sql/signal_handler.cc:262
#4 <signal handler called>
#5 0x081e8595 in thd_set_ha_data (thd=0xb3608030, hton=0xb52e5130, ha_data=0x0) at /home/buildbot/buildbot/build/mariadb-5.5.68/sql/sql_class.cc:638
#6 0x083d9c71 in closecon_handlerton (thd=0xb3608030, plugin=0xb280a430, unused=0x0) at /home/buildbot/buildbot/build/mariadb-5.5.68/sql/handler.cc:680
#7 0x0823d3a8 in plugin_foreach_with_mask (thd=0xb3608030, func=0x83d9bf8 <closecon_handlerton(THD*, plugin_ref, void*)>, type=1, state_mask=8, arg=0x0) at /home/buildbot/buildbot/build/mariadb-5.5.68/sql/sql_plugin.cc:2359
#8 0x083d9ca9 in ha_close_connection (thd=0xb3608030) at /home/buildbot/buildbot/build/mariadb-5.5.68/sql/handler.cc:691
#9 0x081eac15 in THD::~THD (this=0xb3608030, __in_chrg=<optimized out>) at /home/buildbot/buildbot/build/mariadb-5.5.68/sql/sql_class.cc:1473
#10 0x081eaf2b in THD::~THD (this=0xb3608030, __in_chrg=<optimized out>) at /home/buildbot/buildbot/build/mariadb-5.5.68/sql/sql_class.cc:1503

Cross-reference reports from other tests that failed for potentially the same issue:
test name: rpl_gtid_stop_start
build no: 461
branch: 10.2
date: 2019-03-13

test name: rpl_mdev12179
build no: 2119
branch: 10.4
date: 2019-09-25

test name: log_errchk
build: 16273
branch: bb-10.4-blob-index
date: 2019-02-09

test name: innodb-bad-key-change3
build no: 3047
branch: bb-10.5-release
date: 2020-11-24

Comment by Andrei Elkin [ 2021-12-21 ]

bnestere, thanks for looking around. The references are very plausible to me, so please close it.

Comment by Brandon Nesterenko [ 2021-12-21 ]

I think this bug was fixed inadvertently from MDEV-23536 work. The test has not failed in over a year, specifically since this specific commit in Jan 2021: 9b750dc

Generated at Thu Feb 08 08:54:10 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.