Bug #93741 InnoDB: Failed to restore ibuf position.
Submitted: 26 Dec 2018 9:28 Modified: 28 Jan 2019 13:27
Reporter: aytunç sevren Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server Severity:S1 (Critical)
Version:5.7.17 OS:CentOS (CentOS Linux release 7.3.1611 (Core))
Assigned to: MySQL Verification Team CPU Architecture:Any

[26 Dec 2018 9:28] aytunç sevren
Description:
2018-12-26T08:49:38.617208Z 0 [ERROR] InnoDB: Submit a detailed bug report to http://bugs.mysql.com
PHYSICAL RECORD: n_fields 6; 1-byte offsets; info bits 0
 0: len 4; hex 001147bf; asc   G ;;
 1: len 1; hex 00; asc  ;;
 2: len 4; hex 00002944; asc   )D;;
 3: len 16; hex 00000001860200020000860300048000; asc                 ;;
 4: len 2; hex 0000; asc   ;;
 5: len 4; hex 0011a330; asc    0;;
PHYSICAL RECORD: n_fields 6; 1-byte offsets; info bits 0
 0: len 4; hex 001147bf; asc   G ;;
 1: len 1; hex 00; asc  ;;
 2: len 4; hex 00002944; asc   )D;;
 3: len 16; hex 00000001860200020000860300048000; asc                 ;;
 4: len 2; hex 0000; asc   ;;
 5: len 4; hex 0011a330; asc    0;;
DATA TUPLE: 3 fields;
 0: len 4; hex 001147df; asc   G ;;
 1: len 1; hex 00; asc  ;;
 2: len 4; hex 000027d4; asc   ' ;;
PHYSICAL RECORD: n_fields 6; 1-byte offsets; info bits 32
 0: len 4; hex 001147df; asc   G ;;
 1: len 1; hex 00; asc  ;;
 2: len 4; hex 000027d5; asc   ' ;;
 3: len 16; hex 00090001860900038000860800088000; asc                 ;;
 4: len 3; hex 011850; asc   P;;
 5: len 8; hex 80000000002c8948; asc      , H;;
2018-12-26T08:49:38.617744Z 0 [ERROR] [FATAL] InnoDB: Failed to restore ibuf position.
2018-12-26 11:49:38 0x7fe39854c700  InnoDB: Assertion failure in thread 140615489996544 in file ut0ut.cc line 916
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.

08:49:38 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=152
max_threads=151
thread_count=5
connection_count=5
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68190 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
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xef584b]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x7af3e1]
/lib64/libpthread.so.0(+0xf370)[0x7fe3b0031370]
/lib64/libc.so.6(gsignal+0x37)[0x7fe3aea241d7]
/lib64/libc.so.6(abort+0x148)[0x7fe3aea258c8]
/usr/sbin/mysqld[0x77fe7a]
/usr/sbin/mysqld(_ZN2ib5fatalD1Ev+0xfd)[0x10c9d5d]
/usr/sbin/mysqld[0xf6e176]
/usr/sbin/mysqld[0xf70309]
/usr/sbin/mysqld(_Z29ibuf_merge_or_delete_for_pageP11buf_block_tRK9page_id_tPK11page_size_tm+0xbf8)[0xf76cf8]
/usr/sbin/mysqld(_Z20buf_page_io_completeP10buf_page_tb+0x4b9)[0x110d399]
/usr/sbin/mysqld(_Z12fil_aio_waitm+0x15f)[0x1183a6f]
/usr/sbin/mysqld(io_handler_thread+0x88)[0x106cb58]
/lib64/libpthread.so.0(+0x7dc5)[0x7fe3b0029dc5]
/lib64/libc.so.6(clone+0x6d)[0x7fe3aeae673d]
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.
2018-12-26T08:49:39.372893Z 0 [Warning] Could not increase number of max_open_files to more than 5000 (request: 251072)
2018-12-26T08:49:39.520800Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-12-26T08:49:39.520822Z 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.
2018-12-26T08:49:39.521839Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.17) starting as process 10793 ...
2018-12-26T08:49:39.576736Z 0 [Note] InnoDB: PUNCH HOLE support available
2018-12-26T08:49:39.576758Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-26T08:49:39.576763Z 0 [Note] InnoDB: Uses event mutexes
2018-12-26T08:49:39.576766Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2018-12-26T08:49:39.576769Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-12-26T08:49:39.576772Z 0 [Note] InnoDB: Using Linux native AIO
2018-12-26T08:49:39.578507Z 0 [Note] InnoDB: Number of pools: 1
2018-12-26T08:49:39.578889Z 0 [Note] InnoDB: Using CPU crc32 instructions
2018-12-26T08:49:39.584800Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-26T08:49:39.590815Z 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-26T08:49:39.592332Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-12-26T08:49:39.620838Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2018-12-26T08:49:39.848154Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 1444655975249
2018-12-26T08:49:40.413982Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1444656903869
2018-12-26T08:49:40.416299Z 0 [Note] InnoDB: Database was not shutdown normally!
2018-12-26T08:49:40.416306Z 0 [Note] InnoDB: Starting crash recovery.
2018-12-26T08:49:40.531175Z 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 0 row operations to undo
2018-12-26T08:49:40.531192Z 0 [Note] InnoDB: Trx id counter is 1647193344
2018-12-26T08:49:40.531205Z 0 [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 7$
2018-12-26T08:49:41.069713Z 0 [Note] InnoDB: Apply batch completed
2018-12-26T08:49:41.169974Z 0 [Note] InnoDB: Rolling back trx with id 1647192967, 0 rows to undo

How to repeat:
random repeat
[28 Dec 2018 13:27] MySQL Verification Team
I cannot reproduce this, let us know
 - your config files
 - what binary are you using? did you download binary from dev.mysql.com or you configured yum repo https://dev.mysql.com/downloads/repo/yum/ or ?
 - is this an initial install or an upgrade
 - can you reproduce this with 5.7.24

Thanks
Bogdan
[29 Jan 2019 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".