[MDEV-11929] During delete: InnoDB: Assertion failure in thread 139757855127296 in file buf0buf.cc line 4803 Created: 2017-01-28  Updated: 2020-08-25  Resolved: 2017-06-07

Status: Closed
Project: MariaDB Server
Component/s: Encryption, Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.1.13
Fix Version/s: 10.1.23

Type: Bug Priority: Minor
Reporter: Stu S Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 1
Labels: None
Environment:

>$ uname -a
Linux <hostname removed in bug report> 2.6.32-431.23.3.el6.x86_64 #1 SMP Thu Jul 31 17:20:51 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

Attachments: File custom-mysql.cnf     File enable_encryption.preset     File ibdata1_page0.bin     File ibdata2_page0.bin     File my.cnf     File my.cnf     File mysql-clients.cnf     File server.cnf     File tokudb.cnf    
Issue Links:
Duplicate
duplicates MDEV-11759 Encryption code in MariaDB 10.1/10.2 ... Closed
Relates
relates to MDEV-11581 Mariadb starts innodb encryption thre... Closed
relates to MDEV-11738 Mariadb uses 100% of several of my 8 ... Closed
relates to MDEV-12253 Buffer pool blocks are accessed after... Closed
relates to MDEV-12467 encryption.create_or_replace hangs du... Closed
relates to MDEV-12482 After granting EXECUTE right with wil... Closed
relates to MDEV-12602 InnoDB: Failing assertion: space->n_p... Closed
relates to MDEV-12623 InnoDB: Failing assertion: kv == 0 ||... Closed

 Description   

I have a script running through and deleting rows a fairly large table ( ~150 GB ) on a day - by - day.. there's around 90-150k+ rows per day (to be clear, its a delete .. between StartDay and EndDay kind of query)

My particular problem is that I'm also trying to restore a different table in the same DB, and the restore keeps failing. Could be related.

I noticed the infamous: 

ERROR 2013 (HY000) at line 18594: Lost connection to MySQL server during query

In both cases.

In that script, occasionally, and now I'm doing a load of a large table (same DB, different table) I dumped (using mysqldump, default options), truncated, and would now like to restore, and I get the same error. max_allowed_packet is set to 128 MB, and also, I just dumped this table, and settings have not changed since the data was inserted - so weird that mysqldump could generate things that you cannot re-insert. So, I went to the logs:

Looking through the logs I noticed this stack trace appearing periodically (note in this, and other logs, I replaced some stuff with <> because I didn't want it public):

2017-01-28  0:40:20 139757855127296 [ERROR] InnoDB: Block in space_id 0 in file /var/lib/mysql/ibdata1 encrypted.
 
2017-01-28  0:40:20 139757855127296 [ERROR] InnoDB: However key management plugin or used key_id 359 is not found or used encryption algorithm or method does not match.
 
2017-01-28  0:40:20 139757855127296 [ERROR] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
 
2017-01-28  0:40:20 139757855127296 [ERROR] InnoDB: Block in space_id 0 in file /var/lib/mysql/ibdata1 encrypted.
 
2017-01-28  0:40:20 139757855127296 [ERROR] InnoDB: However key management plugin or used key_id 359 is not found or used encryption algorithm or method does not match.
 
2017-01-28  0:40:20 139757855127296 [ERROR] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
 
2017-01-28 00:40:20 7f1be94f3700  InnoDB: Assertion failure in thread 139757855127296 in file buf0buf.cc line 4803
 
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.
 
170128  0:40:20 [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.13-MariaDB
 
key_buffer_size=1048576
 
read_buffer_size=1048576
 
max_used_connections=159
 
max_threads=1002
 
thread_count=137
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 3099672 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0x7f1bdd23f008
 
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 = 0x7f1be94f2d40 thread_stack 0x40000
 
/usr/sbin/mysqld(my_print_stacktrace+0x2b)[0x7f208977ee0b]
 
/usr/sbin/mysqld(handle_fatal_signal+0x475)[0x7f20892df055]
 
/lib64/libpthread.so.0(+0x39f3c0f710)[0x7f20888e5710]
 
/lib64/libc.so.6(gsignal+0x35)[0x7f2086d0d625]
 
/lib64/libc.so.6(abort+0x175)[0x7f2086d0ee05]
 
/usr/sbin/mysqld(+0x87d188)[0x7f2089592188]
 
/usr/sbin/mysqld(+0x894c68)[0x7f20895a9c68]
 
/usr/sbin/mysqld(+0x89577f)[0x7f20895aa77f]
 
/usr/sbin/mysqld(+0x874a6f)[0x7f2089589a6f]
 
/usr/sbin/mysqld(+0x8f5e50)[0x7f208960ae50]
 
/usr/sbin/mysqld(+0x841953)[0x7f2089556953]
 
/usr/sbin/mysqld(+0x845c99)[0x7f208955ac99]
 
/usr/sbin/mysqld(+0x854075)[0x7f2089569075]
 
/usr/sbin/mysqld(+0x74fbf7)[0x7f2089464bf7]
 
/usr/sbin/mysqld(+0x753545)[0x7f2089468545]
 
/usr/sbin/mysqld(+0x850bd8)[0x7f2089565bd8]
 
/usr/sbin/mysqld(+0x7ecacd)[0x7f2089501acd]
 
/usr/sbin/mysqld(+0x7f6438)[0x7f208950b438]
 
/usr/sbin/mysqld(+0x7faa02)[0x7f208950fa02]
 
/usr/sbin/mysqld(+0x7da48c)[0x7f20894ef48c]
 
/usr/sbin/mysqld(+0x7c654c)[0x7f20894db54c]
 
/usr/sbin/mysqld(+0x7c8ae0)[0x7f20894ddae0]
 
/usr/sbin/mysqld(+0x7f5979)[0x7f208950a979]
 
/usr/sbin/mysqld(+0x7fa1b1)[0x7f208950f1b1]
 
/usr/sbin/mysqld(+0x7fa973)[0x7f208950f973]
 
/usr/sbin/mysqld(+0x7d98e3)[0x7f20894ee8e3]
 
/usr/sbin/mysqld(+0x728747)[0x7f208943d747]
 
/usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x23f)[0x7f20892e8ecf]
 
/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x110f)[0x7f20893f2eaf]
 
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x7061)[0x7f20891735f1]
 
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x28d)[0x7f208917590d]
 
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x243b)[0x7f208917856b]
 
/usr/sbin/mysqld(_Z10do_commandP3THD+0x16b)[0x7f2089178b1b]
 
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x17f)[0x7f20892344af]
 
/usr/sbin/mysqld(handle_one_connection+0x47)[0x7f2089234607]
 
/lib64/libpthread.so.0(+0x39f3c079d1)[0x7f20888dd9d1]
 
/lib64/libc.so.6(clone+0x6d)[0x7f2086dc38fd]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7f1c06876020): is an invalid pointer
 
Connection ID (thread ID): 30164
 
Status: NOT_KILLED
 
 
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on
 
 
 
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.
 
170128 00:40:20 mysqld_safe Number of processes running now: 0
 
170128 00:40:20 mysqld_safe mysqld restarted
 
2017-01-28  0:40:20 139979614677024 [Warning] 'THREAD_CONCURRENCY' is deprecated and will be removed in a future release.
 
2017-01-28  0:40:20 139979614677024 [Warning] options --log-slow-admin-statements, --log-queries-not-using-indexes and --log-slow-slave-statements have no effect if --log_slow_queries is not set
 
2017-01-28  0:40:20 139979614677024 [Note] /usr/sbin/mysqld (mysqld 10.1.13-MariaDB) starting as process 28049 ...
 
2017-01-28  0:40:20 139979614677024 [Note] Using unique option prefix 'myisam_recover' is error-prone and can break in the future. Please use the full name 'myisam-recover-options' instead.
 
2017-01-28 00:40:20 7f4f8b356820 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
 
2017-01-28  0:40:20 139979614677024 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2017-01-28  0:40:20 139979614677024 [Note] InnoDB: The InnoDB memory heap is disabled
 
2017-01-28  0:40:20 139979614677024 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2017-01-28  0:40:20 139979614677024 [Note] InnoDB: Memory barrier is not used
 
2017-01-28  0:40:20 139979614677024 [Note] InnoDB: Compressed tables use zlib 1.2.3
 
2017-01-28  0:40:20 139979614677024 [Note] InnoDB: Using Linux native AIO
 
2017-01-28  0:40:20 139979614677024 [Note] InnoDB: Using SSE crc32 instructions
 
2017-01-28  0:40:20 139979614677024 [Note] InnoDB: Initializing buffer pool, size = 16.0G
 
2017-01-28  0:40:21 139979614677024 [Note] InnoDB: Completed initialization of buffer pool
 
2017-01-28  0:40:21 139979614677024 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-01-28  0:40:21 139979614677024 [Note] InnoDB: Log scan progressed past the checkpoint lsn 2400612224831
 
2017-01-28  0:40:21 139979614677024 [Note] InnoDB: Database was not shutdown normally!
 
2017-01-28  0:40:21 139979614677024 [Note] InnoDB: Starting crash recovery.
 
2017-01-28  0:40:21 139979614677024 [Note] InnoDB: Reading tablespace information from the .ibd files...
 
2017-01-28  0:40:21 139979614677024 [Note] InnoDB: Restoring possible half-written data pages 
2017-01-28  0:40:21 139979614677024 [Note] InnoDB: from the doublewrite buffer...
 
InnoDB: Doing recovery: scanned up to log sequence number 2400617467392
 
InnoDB: Doing recovery: scanned up to log sequence number 2400622710272
 
[
 
 .... removed a long sequence of these from the bug report, for conciseness
 
]
 
InnoDB: Doing recovery: scanned up to log sequence number 2400633196032
 
InnoDB: Doing recovery: scanned up to log sequence number 2400643681792
 
InnoDB: Doing recovery: scanned up to log sequence number 2400654167552
 
nnoDB: Doing recovery: scanned up to log sequence number 2402258488832
 
InnoDB: Doing recovery: scanned up to log sequence number 2402263731712
 
InnoDB: Doing recovery: scanned up to log sequence number 2402264584622
 
InnoDB: 6 transaction(s) which must be rolled back or cleaned up
 
InnoDB: in total 986008 row operations to undo
 
InnoDB: Trx id counter is 933044992
 
2017-01-28  0:40:39 139979614677024 [Note] InnoDB: Starting an apply batch of log records to the database...
 
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
 
InnoDB: Last MySQL binlog file position 0 81485718, file name /var/lib/mysql/mysql-bin.001936
 
InnoDB: Starting in background the rollback of uncommitted transactions
 
2017-01-28  0:40:59 139979614677024 [Note] InnoDB: 128 rollback segment(s) are active.
 
2017-01-28 00:40:59 7f4afebff700  InnoDB: Rolling back trx with id 933044670, 3 rows to undo
 
2017-01-28  0:40:59 139979614677024 [Note] InnoDB: Waiting for purge to start
 
2017-01-28  0:40:59 139960078300928 [Note] InnoDB: Rollback of trx with id 933044670 completed
 
2017-01-28 00:40:59 7f4afebff700  InnoDB: Rolling back trx with id 933044663, 1 rows to undo
 
2017-01-28  0:40:59 139960078300928 [Note] InnoDB: Rollback of trx with id 933044663 completed
 
2017-01-28 00:40:59 7f4afebff700  InnoDB: Rolling back trx with id 933044662, 1 rows to undo
 
2017-01-28  0:40:59 139960078300928 [Note] InnoDB: Rollback of trx with id 933044662 completed
 
2017-01-28 00:40:59 7f4afebff700  InnoDB: Rolling back trx with id 933044661, 1 rows to undo
 
2017-01-28  0:40:59 139960078300928 [Note] InnoDB: Rollback of trx with id 933044661 completed
 
2017-01-28 00:40:59 7f4afebff700  InnoDB: Rolling back trx with id 933044660, 1 rows to undo
 
2017-01-28  0:40:59 139960078300928 [Note] InnoDB: Rollback of trx with id 933044660 completed
 
2017-01-28 00:40:59 7f4afebff700  InnoDB: Rolling back trx with id 933034392, 986001 rows to undo
 
 
 
InnoDB: Progress in percents: 12017-01-28  0:40:59 139979614677024 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.28-76.1 started; log sequence number 2402264584622
 
 2 3 4 5 6 7 8 9 10 112017-01-28  0:42:23 139959778379520 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
2017-01-28  0:42:23 139979614677024 [Note] Plugin 'FEEDBACK' is disabled.
 
2017-01-28  0:42:23 139979614677024 [Note] Recovering after a crash using /var/lib/mysql/mysql-bin
 
2017-01-28  0:42:24 139979614677024 [Note] Starting crash recovery...
 
2017-01-28  0:42:24 139979614677024 [Note] Crash recovery finished.
 
2017-01-28  0:42:24 139979614677024 [Note] Server socket created on IP: '::'.
 
2017-01-28  0:42:24 139979614677024 [Note] Reading of all Master_info entries succeded
 
2017-01-28  0:42:24 139979614677024 [Note] Added new Master_info '' to hash table
 
2017-01-28  0:42:24 139979614677024 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.1.13-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
 
 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 352017-01-28  0:43:20 139959712200448 [Note] Start binlog_dump to slave_server(994593286), pos(mysql-bin.001936, 81485718)
 
2017-01-28  0:43:20 139959712466688 [Note] Start binlog_dump to slave_server(511624938), pos(mysql-bin.001936, 81485718)
 
 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 832017-01-28  0:44:32 139979614136064 [Warning] Aborted connection 13 to db: '<>' user: '<>' host: '<>org' (Unknown error)
 
 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002017-01-28  0:44:55 139960078300928 [Note] InnoDB: Rollback of trx with id 933034392 completed
 
2017-01-28 00:44:55 7f4afebff700  InnoDB: Rollback of non-prepared transactions completed
 
2017-01-28  0:46:23 139959679309568 [Warning] IP address '10.7.50.19' could not be resolved: Name or service not known
 
2017-01-28  0:48:21 139959702611712 [Warning] Aborted connection 579 to db: '<removed for bug report>' user: '<removed for bug report>' host: '<removed for bug report>.org' (Unknown error)

To give you an idea of how it's repeating, I grepped:

$ grep -Hinr "/usr/sbin/mysqld(_Z" mysqld-error.log
 
mysqld-error.log:91354:/usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x23f)[0x7fef6b633ecf]
 
mysqld-error.log:91355:/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x110f)[0x7fef6b73deaf]
 
mysqld-error.log:91356:/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x7061)[0x7fef6b4be5f1]
 
mysqld-error.log:91357:/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x28d)[0x7fef6b4c090d]
 
mysqld-error.log:91358:/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x243b)[0x7fef6b4c356b]
 
mysqld-error.log:91359:/usr/sbin/mysqld(_Z10do_commandP3THD+0x16b)[0x7fef6b4c3b1b]
 
mysqld-error.log:91360:/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x17f)[0x7fef6b57f4af]
 
mysqld-error.log:95885:/usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x23f)[0x7fc2c8a85ecf]
 
mysqld-error.log:95886:/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x110f)[0x7fc2c8b8feaf]
 
mysqld-error.log:95887:/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x7061)[0x7fc2c89105f1]
 
mysqld-error.log:95888:/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x28d)[0x7fc2c891290d]
 
mysqld-error.log:95889:/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x243b)[0x7fc2c891556b]
 
mysqld-error.log:95890:/usr/sbin/mysqld(_Z10do_commandP3THD+0x16b)[0x7fc2c8915b1b]
 
mysqld-error.log:97544:/usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x23f)[0x7f9f422b1ecf]
 
mysqld-error.log:97545:/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x110f)[0x7f9f423bbeaf]
 
mysqld-error.log:97546:/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x7061)[0x7f9f4213c5f1]
 
mysqld-error.log:97547:/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x28d)[0x7f9f4213e90d]
 
mysqld-error.log:97548:/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x243b)[0x7f9f4214156b]
 
mysqld-error.log:97549:/usr/sbin/mysqld(_Z10do_commandP3THD+0x16b)[0x7f9f42141b1b]
 
mysqld-error.log:97550:/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x17f)[0x7f9f421fd4af]
 
mysqld-error.log:98399:/usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x23f)[0x7f1dc3798ecf]
 
mysqld-error.log:98400:/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x110f)[0x7f1dc38a2eaf]
 
mysqld-error.log:98401:/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x7061)[0x7f1dc36235f1]
 
mysqld-error.log:98402:/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x28d)[0x7f1dc362590d]
 
mysqld-error.log:98403:/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x243b)[0x7f1dc362856b]
 
mysqld-error.log:98404:/usr/sbin/mysqld(_Z10do_commandP3THD+0x16b)[0x7f1dc3628b1b]
 
mysqld-error.log:98405:/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x17f)[0x7f1dc36e44af]
 
mysqld-error.log:99373:/usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x23f)[0x7f3ce0493ecf]
 
mysqld-error.log:99374:/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x110f)[0x7f3ce059deaf]
 
mysqld-error.log:99375:/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x7061)[0x7f3ce031e5f1]
 
mysqld-error.log:99376:/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x28d)[0x7f3ce032090d]
 
mysqld-error.log:99377:/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x243b)[0x7f3ce032356b]
 
mysqld-error.log:99378:/usr/sbin/mysqld(_Z10do_commandP3THD+0x16b)[0x7f3ce0323b1b]
 
mysqld-error.log:99379:/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x17f)[0x7f3ce03df4af]
 
mysqld-error.log:99906:/usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x23f)[0x7f34e4ffdecf]
 
mysqld-error.log:99907:/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x110f)[0x7f34e5107eaf]
 
mysqld-error.log:99908:/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x7061)[0x7f34e4e885f1]
 
mysqld-error.log:99909:/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x28d)[0x7f34e4e8a90d]
 
mysqld-error.log:99910:/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x243b)[0x7f34e4e8d56b]
 
mysqld-error.log:99911:/usr/sbin/mysqld(_Z10do_commandP3THD+0x16b)[0x7f34e4e8db1b]
 
mysqld-error.log:99912:/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x17f)[0x7f34e4f494af]
 
mysqld-error.log:100713:/usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x23f)[0x7f0004453ecf]
 
mysqld-error.log:100714:/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x110f)[0x7f000455deaf]
 
mysqld-error.log:100715:/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x7061)[0x7f00042de5f1]
 
mysqld-error.log:100716:/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x28d)[0x7f00042e090d]
 
mysqld-error.log:100717:/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x243b)[0x7f00042e356b]
 
mysqld-error.log:101089:/usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x23f)[0x7f5287e28ecf]
 
mysqld-error.log:101090:/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x110f)[0x7f5287f32eaf]
 
mysqld-error.log:101091:/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x7061)[0x7f5287cb35f1]
 
mysqld-error.log:101092:/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x28d)[0x7f5287cb590d]
 
mysqld-error.log:101093:/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x243b)[0x7f5287cb856b]
 
mysqld-error.log:101094:/usr/sbin/mysqld(_Z10do_commandP3THD+0x16b)[0x7f5287cb8b1b]
 
mysqld-error.log:101095:/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x17f)[0x7f5287d744af]
 
mysqld-error.log:101560:/usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x23f)[0x7f5f3cb0decf]
 
mysqld-error.log:101561:/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x110f)[0x7f5f3cc17eaf]
 
mysqld-error.log:101562:/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x7061)[0x7f5f3c9985f1]
 
mysqld-error.log:101563:/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x28d)[0x7f5f3c99a90d]
 
mysqld-error.log:101564:/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x243b)[0x7f5f3c99d56b]
 
mysqld-error.log:101565:/usr/sbin/mysqld(_Z10do_commandP3THD+0x16b)[0x7f5f3c99db1b]
 
mysqld-error.log:101566:/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x17f)[0x7f5f3ca594af]
 
mysqld-error.log:101928:/usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x23f)[0x7fc4865a2ecf]
 
mysqld-error.log:101929:/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x110f)[0x7fc4866aceaf]
 
mysqld-error.log:101930:/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x7061)[0x7fc48642d5f1]
 
mysqld-error.log:101931:/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x28d)[0x7fc48642f90d]
 
mysqld-error.log:101932:/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x243b)[0x7fc48643256b]
 
mysqld-error.log:101933:/usr/sbin/mysqld(_Z10do_commandP3THD+0x16b)[0x7fc486432b1b]
 
mysqld-error.log:101934:/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x17f)[0x7fc4864ee4af]
 
mysqld-error.log:102395:/usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x23f)[0x7f20892e8ecf]
 
mysqld-error.log:102396:/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x110f)[0x7f20893f2eaf]
 
mysqld-error.log:102397:/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x7061)[0x7f20891735f1]
 
mysqld-error.log:102398:/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x28d)[0x7f208917590d]
 
mysqld-error.log:102399:/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x243b)[0x7f208917856b]
 
mysqld-error.log:102400:/usr/sbin/mysqld(_Z10do_commandP3THD+0x16b)[0x7f2089178b1b]
 
mysqld-error.log:102401:/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x17f)[0x7f20892344af]

Memory usage seems OK whenever I check it:

$ free -m
 
             total       used       free     shared    buffers     cached
 
Mem:         64320      63968        352          0        140      43698
 
-/+ buffers/cache:      20129      44191
 
Swap:         4095        213       3882

No idea if all of my lost connections are related to the issue - but it does appear at least some of my lost connections are related to it.

Note that in the script doing the deletes, I have it looping and sleeping and retrying on failure:

2017-01-28 01:59:07.325604 Issue with query: 2003: Can't connect to MySQL server on '<>' (111) sleeping and trying again
 
Deleting 623366 from 2016-10-27 18:52:42.588751 to 2016-10-28 18:52:42.588751
 
 
 
2017-01-28 01:59:12.331931 Issue with query: 2003: Can't connect to MySQL server on '<>' (111) sleeping and trying again
 
Deleting 623366 from 2016-10-27 18:52:42.588751 to 2016-10-28 18:52:42.588751
 
 
 
2017-01-28 01:59:17.338245 Issue with query: 2003: Can't connect to MySQL server on '<>' (111) sleeping and trying again

In the try block, I open, get cursor, query, commit, close, so hopefully I'm not burning through connections or anything - it's a fairly straightforward python script. .... and I can make progress in the script, via retries, and just starting the script again.

However, since the dump keeps failing, I can't restore the data.

 Comments   
Comment by Marko Mäkelä [ 2017-02-01 ]

First of all, are you using encryption? Could you perhaps attach your my.cnf file?
There are some other bugs showing that MariaDB encryption sometimes mistakes encrypted tablespaces for clear-text or vice versa.
In this case, it seems that XtraDB is noticing corruption of the system tablespace (tablespace 0):

					if (bpage->space > TRX_SYS_SPACE) {
 
						if (corrupted) {
 
							buf_mark_space_corrupt(bpage);
 
						}
 
					} else {
 
						ut_error;
 
					}

Following the code flow, it appears that corrupted=FALSE.
I cannot see other than some cosmetic changes to this function buf_page_io_complete() between 10.1.13 and the latest release 10.1.21. But, maybe there have been other fixes to the encryption code.

Comment by Stu S [ 2017-02-02 ]

Unless someone did something to the configuration that I don't know about, then, no, encryption is not enabled.

Attaching cnf shortly (some redaction may be necessary).

Comment by Stu S [ 2017-02-02 ]

Configurations attached.

Comment by Marko Mäkelä [ 2017-02-02 ]

I suspect that this could be a duplicate of MDEV-11759.

Comment by Marko Mäkelä [ 2017-02-02 ]

To confirm if this is a duplicate of MDEV-11759, we would need a copy of the page in ibdata1 that is wrongly reported as corrupted. The log messages do not clearly indicate the page number.
Maybe we could exploit MDEV-11939 to diagnose this. If we are lucky, the 10.1 innochecksum would flag the same page as corrupted. So, please run

innochecksum ibdata1 ibdata2

If it reports a page as corrupted, then we would want a copy of that page, with a command like this:

dd bs=16384 count=1 skip=PAGENUMBER if=ibdata1 of=pagePAGENUMBER.bin
 
innochecksum pagePAGENUMBER.bin

Replace PAGENUMBER with the incorrect page number. And as shown above, run innochecksum on the copy of the page to ensure that it is reported as corrupted.
If you think that the pages contain confidential data, we’d mostly be interested in the first 38 bytes:

od -Ax -t x1 -N 38 pagePAGENUMBER.bin

Comment by Marko Mäkelä [ 2017-02-06 ]

Using the command that I posted in MDEV-11939, I can make innochecksum accept these pages. This definitely is a duplicate of MDEV-11759.

The files should not contain any confidential data. ibdata1_page0.bin is page 0 of the system tablespace. It contains some metadata, such as the size of the tablespace in pages. In addition to that, like all pages whose page number is an integer multiple of innodb_page_size, it contains an allocation bitmap that tells which of the following innodb_page_size-1 pages are marked as allocated. The file ibdata2_page0.bin could contain any page number. In this case, the page number is 8192, and the page happens to be a mostly empty page of type FIL_PAGE_IBUF_FREE_LIST.

Comment by Luke McKee [ 2017-03-26 ]

I have hit this too, but it seems to be encryption related. Here is the stack trace enhanced with addr2line.

gawk -F '[])([]' '{print $0 ; }  /\(\+/ {system("/usr/bin/addr2line -pCfie " $1 " " substr($2,4))}' mysqld-stack.txt 
/usr/sbin/mysqld(my_print_stacktrace+0x3a)[0x5564556e8c4a]
 
/usr/sbin/mysqld(handle_fatal_signal+0x30d)[0x55645513837d]
 
/lib64/libpthread.so.0(+0x11a30)[0x7f8063d2ba30]
 
funlockfile at ??:?
 
/lib64/libc.so.6(gsignal+0x3b)[0x7f806315632b]
 
/lib64/libc.so.6(abort+0x181)[0x7f80631579a1]
 
/usr/sbin/mysqld(+0xa9d949)[0x5564555f9949]
 
buf_page_io_complete(buf_page_t*) at :?
 
/usr/sbin/mysqld(+0xab5b05)[0x556455611b05]
 
buf_read_page_low(dberr_t*, bool, unsigned long, unsigned long, unsigned long, unsigned long, long, unsigned long, trx_t*, buf_page_t**) at :?
 
/usr/sbin/mysqld(+0xab6cd7)[0x556455612cd7]
 
buf_read_page(unsigned long, unsigned long, unsigned long, trx_t*, buf_page_t**) at :?
 
/usr/sbin/mysqld(+0xa97c66)[0x5564555f3c66]
 
buf_page_get_gen(unsigned long, unsigned long, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*, dberr_t*) at :?
 
/usr/sbin/mysqld(+0xb03935)[0x55645565f935]
 
fil_crypt_thread at :?
 
/lib64/libpthread.so.0(+0x765c)[0x7f8063d2165c]
 
__pthread_get_minstack at ??:?
 
/lib64/libc.so.6(clone+0x6d)[0x7f80632154fd]

And the logs / innodb data. Not that I am using encryption, but the database has never gone into production all that's been run on it is sql-bench and I'm more than happy to use new encryption keys and provide the innodb database files if requested as the is no privacy concerns at play.

Here's the last 400 or so lines from mysqld.err
Pastebin of mysqld.err

And here we go:
2017-03-25 22:47:14 7f7fd97fa700 InnoDB: Assertion failure in thread 140187086595840 in file buf0buf.cc line 4829

The other thing to note is this relates to the innodb_page_size.
When I had 32k it hit the error at 4096 - now I have 64k it hit the error at 2048.
2017-03-25 22:47:12 140187086595840 [ERROR] InnoDB: Database page corruption on disk or a failed
2017-03-25 22:47:12 140187086595840 [ERROR] InnoDB: Space 0 file /var/lib/mysql/ibdata1 read of page 2048.

Also this may be related to crc32 (the other user uses that - I'm now using innodb type checksums). If I was to change binlog checksums to crc32 down she goes within a minute. I can't even create databases with crc32.

I had some problems with cryptoapi on a VPS. using the cryptodev it was failing with hashes with openssl. That was after I did the supposed work around to limit the crytodev hash size to 64, so I recompiled openssl to only use aes from /dev/crypto not the hashes.

I'm using kernel 3.9 from sabayon-sources on gentoo/sabayon - latest version. Properly configured with only what you need for a VPS. The host has strange flags in CPU info - not the full Westerme set. So I guess I can provide my my.cnf and you can set up a qemu instance with only the same flags to replicate.

I might try 10.2 to see if mysql.com's innodb storage engine fairs any better. I have debug, non-stripped binary and system tap and I'm willing to help in any way I can to debug this.

My startup script adds the encryption unlocking secret to a very short lived file in tmpfs when mysqld starts, apart from that all the config I'm using is in there. I tried using O_DSYNC and fsync() for flushing method. It was failing on btrfs so I moved to ext4 data=journal. Ext4 data=journal warns not to use O_DIRECT - I don't know if that also applies to O_DSYNC, maybe you could confirm / deny.

my.cnf 

processor	: 3
 
vendor_id	: GenuineIntel
 
cpu family	: 6
 
model		: 44
 
model name	: Intel(R) Xeon(R) CPU           X5650  @ 2.67GHz
 
stepping	: 2
 
microcode	: 0x1
 
cpu MHz		: 2666.760
 
cache size	: 4096 KB
 
physical id	: 3
 
siblings	: 1
 
core id		: 0
 
cpu cores	: 1
 
apicid		: 3
 
initial apicid	: 3
 
fpu		: yes
 
fpu_exception	: yes
 
cpuid level	: 11
 
wp		: yes
 
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss syscall nx pdpe1gb lm constant_tsc arch_perfmon nopl eagerfpu pni pclmulqdq ssse3 cx16 pcid sse4_1 sse4_2 x2apic popcnt aes hypervisor lahf_lm
 
bugs		:
 
bogomips	: 5335.75
 
clflush size	: 64
 
cache_alignment	: 64
 
address sizes	: 40 bits physical, 48 bits virtual
 
power management:

Comment by Marko Mäkelä [ 2017-06-05 ]

The encryption in MariaDB 10.1 suffered from several design problems, most of which I believe were fixed in MariaDB 10.1.23. Can you repeat these problems with that version?

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