[MDEV-10641] encryption.innodb-page_encryption, innodb.innodb-page_compression_zip failed in buildbot Created: 2016-08-22  Updated: 2021-08-27  Resolved: 2021-08-27

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

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Blocks
blocks MDEV-7069 Fix buildbot failures in main server ... Stalled

 Description   

http://buildbot.askmonty.org/buildbot/builders/work-amd64-valgrind/builds/9213/steps/test/logs/mysqld.1.err.6
http://buildbot.askmonty.org/buildbot/builders/work-amd64-valgrind/builds/9213/steps/test/logs/stdio

CURRENT_TEST: encryption.innodb-page_encryption
2016-08-18 13:59:59 67648848 [Note] Got signal 15 to shutdown mysqld
2016-08-18 13:59:59 68558160 [Note] /mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld: Normal shutdown
 
2016-08-18 13:59:59 68558160 [Note] Event Scheduler: Purging the queue. 0 events
2016-08-18 14:00:00 350878032 [Note] InnoDB: FTS optimize thread exiting.
2016-08-18 14:00:00 68558160 [Note] InnoDB: Starting shutdown...
InnoDB: sync levels should be > 159 but a level is 130
Mutex '&pool->mutex'
InnoDB: Locked mutex: addr 0xa1e4028 thread 325699920 file /var/lib/buildbot/maria-slave/work-opensuse-amd64/build/storage/xtradb/mem/mem0pool.cc line 140
InnoDB: sync_thread_levels_g(array, 159) does not hold!
2016-08-18 14:00:03 1369c950  InnoDB: Assertion failure in thread 325699920 in file sync0sync.cc line 1319
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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
160818 14:00: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.1.17-MariaDB-valgrind-max-debug
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=3
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 = 63019 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0x0
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 0x48400
/mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld(my_print_stacktrace+0x2e)[0xea433e]
/mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld(handle_fatal_signal+0x522)[0x7fbaa2]
/lib64/libpthread.so.0[0x4e3fa90]
/lib64/libc.so.6(gsignal+0x35)[0x625b645]
/lib64/libc.so.6(abort+0x183)[0x625cc33]
/mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld[0xd1e669]
/mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld[0xd1ae9d]
/mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld[0xd81886]
mysys/stacktrace.c:268(my_print_stacktrace)[0xd878ef]
sql/signal_handler.cc:166(handle_fatal_signal)[0xdb4f41]
buf/buf0flu.cc:1577(buf_flush_LRU_list_batch)[0xdad3bb]
buf/buf0flu.cc:1900(buf_flush_end)[0xdada8a]
buf/buf0flu.cc:2907(buf_flush_lru_manager_thread)[0xdadf09]
/lib64/libpthread.so.0[0x4e38070]
/lib64/libc.so.6(clone+0x6d)[0x62fc13d]
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
2016-08-18 14:00:08 67347952 [Note] /mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld (mysqld 10.1.17-MariaDB-valgrind-max-debug) starting as process 13228 ...
2016-08-18 14:00:08 67347952 [Warning] Could not increase number of max_open_files to more than 1014 (request: 4162)
2016-08-18 14:00:09 67347952 [Note] Plugin 'BLACKHOLE' is disabled.
2016-08-18 14:00:09 67347952 [Note] Plugin 'partition' is disabled.
2016-08-18 14:00:09 67347952 [Note] Plugin 'ARCHIVE' is disabled.
2016-08-18 14:00:09 403a5f0 InnoDB: Warning: Setting innodb_use_sys_malloc to FALSE is DEPRECATED. This option may be removed in future releases, together with the InnoDB's internal memory allocator.
innodb_open_files should not be greater than the open_files_limit.
2016-08-18 14:00:09 67347952 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB.

encryption.innodb-page_encryption 'cbc,xtradb' w6 [ fail ]  Found warnings/errors in server log file!
        Test ended at 2016-08-18 14:11:59
line
Attempting backtrace. You can use the following information to find out
^ Found warnings in /mnt/data/buildot/maria-slave/work-opensuse-amd64/build/mysql-test/var/6/log/mysqld.1.err
ok
 
 - skipping '/mnt/data/buildot/maria-slave/work-opensuse-amd64/build/mysql-test/var/6/log/encryption.innodb-page_encryption-cbc,xtradb/'



 Comments   
Comment by Marko Mäkelä [ 2020-10-17 ]

What does the test innodb.innodb-page_compression_zip have to do in the regression test suite? elenst, would you object if I removed it?

I cleaned up the encryption test, because it started to fail in my development version of MDEV-23855 due to questionable assumptions.

Comment by Marko Mäkelä [ 2020-10-17 ]

By the way, the test failures that I observed were not server crashes, but wait_condition.inc timeouts. Encryption was severely broken until MariaDB 10.1.23, where we fixed MDEV-12467, MDEV-12624 and many other bugs. Specifically, there were race conditions between DDL operations and the encryption threads that mark pages as dirty.

Comment by Marko Mäkelä [ 2021-08-27 ]

According to the cross-reference, the last failures were:

10.4 9aa80fcf466434d45374be789c68487b kvm-asan 2019-05-16 15:27:30

innodb.innodb-page_compression_zip 'innodb' w2 [ fail ]  Found warnings/errors in server log file!
        Test ended at 2019-05-16 11:08:37
line
2019-05-16 11:07:09 0 [Warning] /home/buildbot/buildbot/build/mariadb-10.4.5/sql/mysqld: Thread 5 (user : '') did not exit
2019-05-16 11:07:09 0 [Warning] /home/buildbot/buildbot/build/mariadb-10.4.5/sql/mysqld: Thread 4 (user : '') did not exit
2019-05-16 11:07:09 0 [Warning] /home/buildbot/buildbot/build/mariadb-10.4.5/sql/mysqld: Thread 3 (user : '') did not exit
2019-05-16 11:07:09 0 [Warning] /home/buildbot/buildbot/build/mariadb-10.4.5/sql/mysqld: Thread 2 (user : '') did not exit
2019-05-16 11:07:09 0 [Warning] /home/buildbot/buildbot/build/mariadb-10.4.5/sql/mysqld: Thread 1 (user : '') did not exit
^ Found warnings in /dev/shm/var/2/log/mysqld.1.err

It looks like a possible shutdown hang. I do not think that the test innodb.innodb-page_compression_zip actually has anything to do with the originally reported failure. Encryption was seriously broken until March or April 2017 when we finally fixed race conditions between background threads and DDL operations.

The last recorded failures of the encryption test in main branches were as follows:

10.1 1887b5ae87ac0d1519f95a1e2f59efe0 kvm-rpm-centos73-ppc64le 2020-05-09 01:48:58

encryption.innodb-page_encryption 'ctr,innodb_plugin' w2 [ fail ]
        Test ended at 2020-05-08 23:21:24
 
CURRENT_TEST: encryption.innodb-page_encryption
mysqltest: At line 71: query 'select count(*) from innodb_compact t1, innodb_normal t2 where
t1.c1 = t2.c1 and t1.b = t2.b' failed: 2013: Lost connection to MySQL server during query
2020-05-08 23:21:23 3fff897ff020  InnoDB: Assertion failure in thread 70366756073504 in file os0sync.cc line 416

It is possible that this one was never fixed in the 10.1 series, which reached EOL on 2020-10-17.

10.5 0e25a8b4a6a01e3c09407f2f697983da kvm-asan 2020-01-23 16:48:08

encryption.innodb-page_encryption 'cbc,innodb' w3 [ fail ]
        Test ended at 2020-01-23 10:13:02
 
CURRENT_TEST: encryption.innodb-page_encryption
mysqltest: At line 131: query 'select count(*) from innodb_compact t1, innodb_normal t2 where
t1.c1 = t2.c1 and t1.b = t2.b' failed: 2013: Lost connection to MySQL server during query
Version: '10.5.1-MariaDB-debug-log'  socket: '/dev/shm/var/tmp/3/mysqld.1.sock'  port: 16020  Source distribution
mysqld: /home/buildbot/buildbot/build/mariadb-10.5.1/tpool/tpool_generic.cc:459: bool tpool::thread_pool_generic::get_task(tpool::worker_data*, tpool::task**): Assertion `m_long_tasks_count' failed.

This looks like a hang in a background task.

All these failures occurred before my previous comment. There have been no failures for more than 1 year now.

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