[MDEV-14379]  encryption.innodb_encrypt_log_corruption failed in buildbot, crash Created: 2017-11-13  Updated: 2021-10-25  Resolved: 2021-10-25

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.2, 10.3
Fix Version/s: N/A

Type: Bug Priority: Minor
Reporter: Alice Sherepa Assignee: Jan Lindström (Inactive)
Resolution: Cannot Reproduce Votes: 0
Labels: powerpc
Environment:

p8-rhel71-bintar

Attachments: File mysqld.1.err.3.2019-11-30.gz    
Issue Links:
Relates
relates to MDEV-13779 InnoDB fails to shut down purge worke... Closed
relates to MDEV-15554 InnoDB page_cleaner shutdown sometime... Closed
relates to MDEV-15817 encryption tests fail futex(COND_thr... Open

 Description   

http://buildbot.askmonty.org/buildbot/builders/p8-rhel71-bintar/builds/2539/steps/test/logs/stdio
http://buildbot.askmonty.org/buildbot/builders/p8-rhel71-bintar/builds/2539/steps/test/logs/mysqld.1.err.1

encryption.innodb_encrypt_log_corruption 'innodb' w1 [ fail ]  Found warnings/errors in server log file!
 
        Test ended at 2017-11-11 05:41:36
 
line
 
Attempting backtrace. You can use the following information to find out
 
^ Found warnings in /home/buildbot/maria-slave/power8-vlp06-bintar/build/mysql-test/var/1/log/mysqld.1.err
 
ok
 
 
 
 - saving '/home/buildbot/maria-slave/power8-vlp06-bintar/build/mysql-test/var/1/log/encryption.innodb_encrypt_log_corruption-innodb/' to '/home/buildbot/maria-slave/power8-vlp06-bintar/build/mysql-test/var/log/encryption.innodb_encrypt_log_corruption-innodb/'
 
 - found 'core.15034' (0/5)
 
warning: Could not load shared library symbols for linux-vdso64.so.1.
 
Do you need "set solib-search-path" or "set sysroot"?
 
 
 
warning: File "/opt/at8.0/lib64/power8/libthread_db-1.0.so" auto-loading has been declined by your `auto-load safe-path' set to "$debugdir:$datadir/auto-load:/usr/bin/mono-gdb.py".
 
To enable execution of this file add
 
	add-auto-load-safe-path /opt/at8.0/lib64/power8/libthread_db-1.0.so
 
line to your configuration file "/home/buildbot/.gdbinit".
 
To completely disable this security protection add
 
	set auto-load safe-path /
 
line to your configuration file "/home/buildbot/.gdbinit".
 
For more information about this security protection see the
 
"Auto-loading safe path" section in the GDB manual.  E.g., run from the shell:
 
	info "(gdb)Auto-loading safe path"
 
 
 
warning: Unable to find libthread_db matching inferior's thread library, thread debugging will not be available.
 
 
 
warning: File "/opt/at8.0/lib64/power8/libthread_db-1.0.so" auto-loading has been declined by your `auto-load safe-path' set to "$debugdir:$datadir/auto-load:/usr/bin/mono-gdb.py".
 
 
 
warning: Unable to find libthread_db matching inferior's thread library, thread debugging will not be available.
 
Core was generated by `/home/buildbot/maria-slave/power8-vlp06-bintar/build/sql/mysqld --defaults-grou'.
 
Program terminated with signal 6, Aborted.


Thread 1 (LWP 15034):
 
#0  0x00003fff8fc80ef0 in __pthread_kill (threadid=<optimized out>, signo=<optimized out>) at ../sysdeps/unix/sysv/linux/pthread_kill.c:60
 
#1  0x000000003927c8e0 in my_write_core (sig=<optimized out>) at /home/buildbot/maria-slave/power8-vlp06-bintar/build/mysys/stacktrace.c:481
 
#2  0x0000000038b7e15c in handle_fatal_signal (sig=<optimized out>) at /home/buildbot/maria-slave/power8-vlp06-bintar/build/sql/signal_handler.cc:303
 
#3  <signal handler called>
 
#4  0x00003fff8fc7f7d0 in __pthread_cond_wait (cond=0x39a38c58 <COND_thread_count>, mutex=0x39a391e0 <LOCK_thread_count>) at pthread_cond_wait.c:188
 
#5  0x0000000038852e90 in inline_mysql_cond_wait (that=0x39a38c58 <COND_thread_count>, mutex=0x39a391e0 <LOCK_thread_count>, src_file=0x3932b6c0 "/home/buildbot/maria-slave/power8-vlp06-bintar/build/sql/mysqld.cc", src_line=6158) at /home/buildbot/maria-slave/power8-vlp06-bintar/build/include/mysql/psi/mysql_thread.h:1138
 
#6  mysqld_main (argc=149, argv=0x1003c5098a0) at /home/buildbot/maria-slave/power8-vlp06-bintar/build/sql/mysqld.cc:6158
 
#7  0x0000000038826600 in main (argc=<optimized out>, argv=<optimized out>) at /home/buildbot/maria-slave/power8-vlp06-bintar/build/sql/main.cc:25



 Comments   
Comment by Marko Mäkelä [ 2018-04-30 ]

I suspect that this is a duplicate of MDEV-13779 (hang during InnoDB shutdown). Unfortunately the mysqld.1.err is no longer available.

Before 10.3, mysql-test-run.pl used to ignore hangs during shutdown, presumably sending SIGKILL straight away. If the mysqld.1.err showed the abort message 60 seconds after the last shutdown message, it would likely be a hung shutdown.

Comment by Marko Mäkelä [ 2018-04-30 ]

This could also be a duplicate of MDEV-15554 (InnoDB page cleaner sometimes hangs). But, in that case there should have been more than just one thread running.

Comment by Elena Stepanova [ 2019-12-04 ]

Maybe it wasn't a duplicate of either of the above-mentioned issues, since there is a fresh failure on aarch64 in buildbot – hard to say whether it's the same or a different one, though

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

10.2 c6ed37b8

 
encryption.innodb_encrypt_log_corruption 'innodb' w3 [ fail ]  Found warnings/errors in server log file!
 
        Test ended at 2019-11-30 21:30:08
 
line
 
Attempting backtrace. You can use the following information to find out
 
^ Found warnings in /dev/shm/var/3/log/mysqld.1.err
 
ok

mysqld.err

 
2019-11-30 21:29:42 281472969048224 [Note] /usr/sbin/mysqld: Shutdown complete
 
 
 
2019-11-30 21:29:43 281472967501456 [Note] /usr/sbin/mysqld (mysqld 10.2.30-MariaDB-log) starting as process 12491 ...
 
2019-11-30 21:29:43 281472967501456 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4186)
 
2019-11-30 21:29:43 281472967501456 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
 
2019-11-30 21:29:43 281472967501456 [Note] Plugin 'SEQUENCE' is disabled.
 
2019-11-30 21:29:43 281472967501456 [Note] Plugin 'partition' is disabled.
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Uses event mutexes
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Compressed tables use zlib 1.2.7
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Using Linux native AIO
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Number of pools: 1
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Using generic crc32 instructions
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Completed initialization of buffer pool
 
2019-11-30 21:29:43 281472728559776 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Highest supported file format is Barracuda.
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1213964
 
2019-11-30 21:29:43 281472967501456 [ERROR] InnoDB: MLOG_FILE_NAME incorrect:bogus
 
2019-11-30 21:29:43 281472967501456 [ERROR] InnoDB: ############### CORRUPT LOG RECORD FOUND ##################
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Log record type 55, page 151:488. Log parsing proceeded successfully up to 1213973. Previous log record type 56, is multi 0 Recv offset 9, prev 0
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Hex dump starting 0 bytes before and ending 13 bytes after the corrupted record:
 
 len 22; hex 38000000000012860cb7809781e80006626f67757300; asc 8               bogus ;
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Set innodb_force_recovery to ignore this error.
 
2019-11-30 21:29:43 281472967501456 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
 
191130 21:29:43 [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.30-MariaDB-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 = 63025 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
 
/usr/sbin/mysqld(my_print_stacktrace+0x3c)[0xaaaad482896c]
 
/usr/sbin/mysqld(handle_fatal_signal+0x48c)[0xaaaad42fcc14]
 
2019-11-30 21:29:43 281472967501456 [Note] InnoDB: Starting shutdown...
 
2019-11-30 21:29:44 281472967501456 [ERROR] Plugin 'InnoDB' init function returned error.
 
2019-11-30 21:29:44 281472967501456 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_MUTEXES' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_CMP' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'FEEDBACK' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'user_variables' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
 
2019-11-30 21:29:44 281472967501456 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
 
2019-11-30 21:29:44 281472967501456 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
 
2019-11-30 21:29:44 281472967501456 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'
 
2019-11-30 21:29:44 281472967501456 [Warning] /usr/sbin/mysqld: unknown option '--loose-pam-debug'
 
2019-11-30 21:29:44 281472967501456 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
 
2019-11-30 21:29:44 281472967501456 [Note] Server socket created on IP: '127.0.0.1'.
 
addr2line: Dwarf Error: Offset (950231) greater than or equal to .debug_str size (120741).
 
addr2line: Dwarf Error: Offset (531180546) greater than or equal to .debug_str size (120741).
 
addr2line: Dwarf Error: Offset (1700234) greater than or equal to .debug_str size (120741).
 
addr2line: Dwarf Error: Offset (599352322) greater than or equal to .debug_str size (120741).
 
2019-11-30 21:29:44 281472967501456 [Note] Reading of all Master_info entries succeeded
 
2019-11-30 21:29:44 281472967501456 [Note] Added new Master_info '' to hash table
 
2019-11-30 21:29:44 281472967501456 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.2.30-MariaDB-log'  socket: '/dev/shm/var/tmp/3/mysqld.1.sock'  port: 16020  MariaDB Server
 
addr2line: Dwarf Error: Offset (1699865) greater than or equal to .debug_str size (120741).
 
addr2line: Dwarf Error: Offset (599343874) greater than or equal to .debug_str size (120741).
 
2019-11-30 21:29:44 281472861831328 [Note] /usr/sbin/mysqld (initiated by: root[root] @ localhost []): Normal shutdown
 
2019-11-30 21:29:44 281472861831328 [Note] Event Scheduler: Purging the queue. 0 events
 
2019-11-30 21:29:44 281472861831328 [Note] /usr/sbin/mysqld: Shutdown complete

mysqld.1.err.3.2019-11-30.gz

Comment by Marko Mäkelä [ 2021-10-25 ]

According to the buildbot cross-reference, this test has not failed for more than a year, except in misconfigured MemorySanitizer builds (see MDEV-26758 how to configure it properly).

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