[#MDEV-12144] Signal 6 crash corrupts ibd files

[MDEV-12144] Signal 6 crash corrupts ibd files Created: 2017-02-27 Updated: 2017-07-15 Resolved: 2017-07-15
Status:	Closed
Project:	MariaDB Server
Component/s:	Storage Engine - InnoDB
Affects Version/s:	10.0.28, 10.0.29, 10.0.30
Fix Version/s:	10.1.26, 5.5.57, 10.0.32, 10.2.8

Type:

Bug

Priority:

Critical

Reporter:

Edward Hicks

Assignee:

Sergei Golubchik

Resolution:

Fixed

Votes:

Labels:

contribution, corruption, crash, foundation, innodb

Environment:

RHEL6, x86_64, VMWare, wheezy

Attachments:

fdmain.c

page_manager_handlers.ibd

Description

3 times now in the last 6 months or so we've had a random signal 6 crash corrupt a single ibd file by actually overwriting the top it with the error message. (which I assume was meant for the log file instead)

I've attached the corrupted file as an example. I've confirmed this occurs in 10.0.28 and 10.0.29. Here's the error data from the correct log file:

2017-02-27 01:25:07 7f50466df700  InnoDB: Assertion failure in thread 139982755723008 in file buf0lru.cc line 2245

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.

/usr/sbin/mysqld(my_print_stacktrace+0x2b)[0xb924ab]

/usr/sbin/mysqld(handle_fatal_signal+0x3b6)[0x739136]

/lib64/libpthread.so.0[0x323120f7e0]

/lib64/libc.so.6(gsignal+0x35)[0x3230e325e5]

/lib64/libc.so.6(abort+0x175)[0x3230e33dc5]

/usr/sbin/mysqld[0x9c86c9]

/usr/sbin/mysqld[0x8db7d5]

/usr/sbin/mysqld[0x9280e8]

/usr/sbin/mysqld[0x8835ff]

/usr/sbin/mysqld(_Z8closefrmP5TABLEb+0x3a)[0x67c43a]

/usr/sbin/mysqld(_Z18intern_close_tableP5TABLE+0x59)[0x59a609]

/usr/sbin/mysqld(_Z8tc_purgeb+0x285)[0x6e88f5]

/usr/sbin/mysqld(_Z19close_cached_tablesP3THDP10TABLE_LISTbm+0x8f)[0x5a317f]

/usr/sbin/mysqld(_Z20reload_acl_and_cacheP3THDyP10TABLE_LISTPi+0x3ce)[0x6c023e]

/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x4889)[0x5e3899]

/usr/sbin/mysqld[0x5e5a97]

/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1c6c)[0x5e7e6c]

/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x453)[0x6a6f13]

/usr/sbin/mysqld(handle_one_connection+0x42)[0x6a6fe2]

/lib64/libpthread.so.0[0x3231207aa1]

/lib64/libc.so.6(clone+0x6d)[0x3230ee8aad]

170227 01:25:09 mysqld_safe Number of processes running now: 0

170227 01:25:09 mysqld_safe mysqld restarted

170227  1:25:09 [Note] /usr/sbin/mysqld (mysqld 10.0.29-MariaDB) starting as process 23465 ...

170227  1:25:09 [Note] InnoDB: Using mutexes to ref count buffer pool pages

170227  1:25:09 [Note] InnoDB: The InnoDB memory heap is disabled

170227  1:25:09 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

170227  1:25:09 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier

170227  1:25:09 [Note] InnoDB: Compressed tables use zlib 1.2.3

170227  1:25:09 [Note] InnoDB: Using Linux native AIO

170227  1:25:10 [Note] InnoDB: Using CPU crc32 instructions

170227  1:25:10 [Note] InnoDB: Initializing buffer pool, size = 7.0G

170227  1:25:10 [Note] InnoDB: Completed initialization of buffer pool

170227  1:25:10 [Note] InnoDB: Highest supported file format is Barracuda.

170227  1:25:10 [Note] InnoDB: Log scan progressed past the checkpoint lsn 6877178025086

170227  1:25:10 [Note] InnoDB: Database was not shutdown normally!

170227  1:25:10 [Note] InnoDB: Starting crash recovery.

170227  1:25:10 [Note] InnoDB: Reading tablespace information from the .ibd files...

170227  1:28:01 [ERROR] InnoDB: Space id in fsp header 1851878432,but in the page header 544434535

170227  1:28:01 [ERROR] InnoDB: innodb-page-size mismatch in tablespace ./optometrydb/page_manager_handlers.ibd (table optometrydb/page_manager_handlers)

170227  1:28:01 [Note] InnoDB: Page size:1024 Pages to analyze:64

170227  1:28:01 [Note] InnoDB: Page size: 1024, Possible space_id count:0

170227  1:28:01 [Note] InnoDB: Page size:2048 Pages to analyze:64

170227  1:28:01 [Note] InnoDB: Page size: 2048, Possible space_id count:0

170227  1:28:01 [Note] InnoDB: Page size:4096 Pages to analyze:32

170227  1:28:01 [Note] InnoDB: Page size: 4096, Possible space_id count:0

170227  1:28:01 [Note] InnoDB: Page size:8192 Pages to analyze:16

170227  1:28:01 [Note] InnoDB: Page size: 8192, Possible space_id count:0

170227  1:28:01 [Note] InnoDB: Page size:16384 Pages to analyze:8

170227  1:28:01 [Note] InnoDB: VALID: space:1859997 page_no:1 page_size:16384

170227  1:28:01 [Note] InnoDB: VALID: space:1859997 page_no:2 page_size:16384

170227  1:28:01 [Note] InnoDB: VALID: space:1859997 page_no:3 page_size:16384

170227  1:28:01 [Note] InnoDB: VALID: space:1859997 page_no:4 page_size:16384

170227  1:28:01 [Note] InnoDB: VALID: space:1859997 page_no:5 page_size:16384

170227  1:28:01 [Note] InnoDB: Page size: 16384, Possible space_id count:1

170227  1:28:01 [Note] InnoDB: space_id:1859997, Number of pages matched: 5/5 (16384)

170227  1:28:01 [Note] InnoDB: Chosen space:1859997

170227  1:28:01 [Note] InnoDB: Restoring page 0 of tablespace 1859997

170227  1:28:01 [Warning] InnoDB: Doublewrite does not have page_no=0 of space: 1859997

2017-02-27 01:28:01 7f7346996820  InnoDB: Operating system error number 2 in a file operation.

InnoDB: The error means the system cannot find the path specified.

InnoDB: If you are installing InnoDB, remember that you must create

InnoDB: directories yourself, InnoDB does not create them.

InnoDB: Error: could not open single-table tablespace file ./optometrydb/page_manager_handlers.ibd

InnoDB: We do not continue the crash recovery, because the table may become

InnoDB: corrupt if we cannot apply the log records in the InnoDB log to it.

InnoDB: To fix the problem and start mysqld:

InnoDB: 1) If there is a permission problem in the file and mysqld cannot

InnoDB: open the file, you should modify the permissions.

InnoDB: 2) If the table is not needed, or you can restore it from a backup,

InnoDB: then you can remove the .ibd file, and InnoDB will do a normal

InnoDB: crash recovery and ignore that table.

InnoDB: 3) If the file system or the disk is broken, and you cannot remove

InnoDB: the .ibd file, you can set innodb_force_recovery > 0 in my.cnf

InnoDB: and force InnoDB to continue crash recovery here.

170227 01:28:01 mysqld_safe mysqld from pid file /var/lib/mysqldata/mysql/DATABASES/whsqlprd05.pid ended

Comments

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

It looks like the file optometrydb/page_manager_handlers.ibd must have been overwritten with some ASCII text:
544434535 == 0x20736967 == " sig"
1851878432 == 0x6e616c20 == "nal "
Can you please share what was written to the start of the file? Anything like "mysqld got signal", by any chance?

In the past (while I worked as a MySQL developer) I have suspected that maybe if the mysqld process is started without file descriptor 2 (stderr) being assigned, it is possible that a data file gets opened as file descriptor 2. Then, when some code attempts to report something to stderr, it would overwrite the data file that happens to be associated with file descriptor 2.

This hypothesis should be fairly easy to test by an invocation similar to the following:

mysqld 2>&-

Comment by Daniel Black [ 2017-02-28 ]

flush [error] log, will reopen the file descriptor but not necessary the same one will come back. Maybe. Another thread could open a file which becomes FD 2.

LOCK_error_log isn't held in reopen_fstreams for stderr.

Comment by Edward Hicks [ 2017-02-28 ]

I'm not sure what you mean by "the start of the file" - what is attached is the entire file as copied from the data directory before I started on recovery. Just run it through less and you see this at the top:

170227  1:25:07 [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.0.29-MariaDB

key_buffer_size=134217728

read_buffer_size=131072

max_used_connections=211

max_threads=5002

thread_count=12

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 11114545 K  bytes of memory

Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f50b8c25008

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 = 0x7f50466ded30 thread_stack 0x48000

Trying to get some variables.

Some pointers may be invalid and cause the dump to abort.

Query (0x7f507e2be020): is an invalid pointer

Connection ID (thread ID): 12720053

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.

We think the query pointer is invalid, but we will try to print it anyway.

Query: FLUSH /*!40101 LOCAL */ TABLES

And then the rest is binary through the EOF.

Comment by Marko Mäkelä [ 2017-03-18 ]

eshicks4, sorry that I overlooked the file attachment. Can you share more details? Do you have a server error log from immediately before the crash?
What was the last message timestamp in the server error log? Do you have an idea if any other maintenance commands were issued close to the statement FLUSH LOCAL TABLES that was mentioned at the end of the MySQL crash output (FLUSH LOCAL TABLES)?

How many InnoDB files do you have, and have you configured innodb_open_files or table_cache (or table_open_cache)? These parameters affect the fil_system->max_n_open and the fil_system->LRU (closing of rarely accessed data files) in InnoDB.

danblack has a promising-looking hypothesis. Maybe fil_node_open_file() in InnoDB opened a data file at a very unfortunate moment as file descriptor 2 (STDERR_FILENO) which happened to be available at that point of time.

Side note: All of the output that corrupted the .ibd file was written by the server core, not InnoDB.

Comment by Daniel Black [ 2017-03-19 ]

fdmain.c - an approach using dup2 to ensure that stdout(or another fd) isn't closed - generating a race condition but still redirecting it to another object.

open("/tmp/xx.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3

dup2(3, 1)                              = 1

close(3)                                = 0

fcntl(1, F_GETFL)                       = 0x8001 (flags O_WRONLY|O_LARGEFILE)

fstat(1, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0

write(1, "hi\n", 3)                     = 3

exit_group(0)                           = ?

$ more /tmp/xx.txt

hi

Note 1: during testing I fclose(stdout) after dup2 and the fprintf(stdout..) generated a segfault which seems closer like this bug report.

looking at freopen is seems the syscalls are quite similar anyway.

open("/tmp/xx.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3

dup3(3, 1, 0)                           = 1

close(3)                                = 0

fstat(1, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0

Comment by Marko Mäkelä [ 2017-03-20 ]

There indeed are a few calls to freopen(), mostly during the server initialization. I tested starting mysqld with all of stdin, stdout, stderr closed, and my_freopen() is being called by reopen_fstreams() and init_server_components() before the InnoDB storage engine is initialized:

break my_freopen

break innobase_start_or_create_for_mysql

run <&- >&- 2>&-

continue

continue

break open

continue

At this startup, we have fileno(srv_monitor_file)==1 (STDOUT_FILENO) and fileno(srv_dict_tmpfile)==2 (STDERR_FILENO).

A possible solution for this startup problem could be to allocate a dummy file to the STDERR_FILENO before starting up storage engines, or refuse startup outright if STDERR_FILENO is not open.

I will for now assume that the standard error stream was properly open during the startup.

Like danblack pointed out, flush_error_log() is calling redirect_std_streams(), which calls freopen() via my_freopen(). Assuming that the main() function of storage/mroonga/vendor/groonga/src/groonga.c is not compiled in, flush_error_log() seems to be the only caller of freopen() while the server is running.

The only caller of flush_error_log() is reload_acl_and_cache(), when REFRESH_LOG or REFRESH_ERROR_LOG are set. The callers that use one of those flags are:

The SIGHUP handler (after calling mysql_print_status())
FLUSH LOGS
FLUSH ERROR LOGS

The calls to fdopen() seem to be OK.

The function mysqld_main() is calling close(stdin), which seems OK. On a normal startup (without all of stdin, stdout, stderr being open), there is no call to close() with the argument STDOUT_FILENO or STDERR_FILENO.

Comment by Edward Hicks [ 2017-03-21 ]

There is nothing in the error logs for days leading up to the crash. I am now noticing that 1:25AM is when we kick off the nightly backup of the primary database. (around 570 databases) Having crashed only 7 seconds after the script was kicked off it looks like a pretty good candidate for the triggering event.

The first thing the backup script does is build a config file (not sure why - not my script) and then executes 'show databases' to get a list:

mysql --defaults-file=$TMPFILE.cnf --disable-pager --batch --disable-tee \

  --execute='show databases' --host=$DATASERVER --user=$OPERUSER --database=mysql

The generated config file only includes is a [client] section with password, port, and optional socket.

It then creates a directory for each database (excluding binlog, relay, innodb, and information_schema) and places into it 2 SQL files:

echo "SET FOREIGN_KEY_CHECKS=0;" >$BACKUPDIR/$DATABASE/$DATABASE.ddl.$DATE.sql

mysqldump --defaults-file=$TMPFILE.cnf --host=$DATASERVER --user=$OPERUSER \

	--skip-lock-tables --single-transaction --hex-blob --master-data=2 --allow-keywords \

	--add-drop-table --quick --add-locks --create-options --complete-insert --extended-insert \

	--force --databases --no-data $DATABASE \

	2>$TMPFILE >>$BACKUPDIR/$DATABASE/$DATABASE.ddl.$DATE.sql

echo "SET FOREIGN_KEY_CHECKS=0;" >$BACKUPDIR/$DATABASE/$DATABASE.full.$DATE.sql

mysqldump --defaults-file=$TMPFILE.cnf --host=$DATASERVER --user=$OPERUSER \

	--skip-lock-tables --single-transaction --hex-blob --master-data=2 --allow-keywords \

	--add-drop-table --quick --add-locks --create-options --complete-insert --extended-insert \

	--force --database --no-create-info --master-data=2 --flush-logs $DATABASE \

	2>$TMPFILE >>$BACKUPDIR/$DATABASE/$DATABASE.full.$DATE.sql

Afterward it tars everything up.

I don't have innodb_open_files but I do have a fair amount of customizations to make it production-level responsive and as VM-friendly as is possible for a DBMS:

max_connections=5000

max_connect_errors=4294967295

table_cache=1000

max_heap_table_size=268435456

tmp_table_size=268435456

open_files_limit=9076

symbolic-links=0

query_cache_type=1

query_cache_size=32M

max_allowed_packet=32M

slow-query-log=ON

default_storage_engine=InnoDB

transaction-isolation=READ-COMMITTED

thread_cache_size=4

query_cache_limit=10485760

table_open_cache=16384

table_definition_cache=16384

join_buffer_size=512K

wait_timeout=900

interactive_timeout=900

net_read_timeout=300

net_write_timeout=600

innodb_buffer_pool_size=7G

innodb_log_file_size=1G

innodb_flush_neighbors=0

innodb_autoinc_lock_mode=2

innodb_data_file_path=ibdata1:256M;ibdata2:256M;ibdata3:256M:autoextend

innodb_large_prefix=1

innodb_file_per_table=1

innodb_file_format=Barracuda

innodb_file_format_max=Barracuda

innodb_random_read_ahead=1

innodb_stats_auto_recalc=1

If you need anything else then let me know. Thanks

Comment by Jean Weisbuch [ 2017-03-28 ]

The same just happened to me on 10.0.29 using Debian Wheezy packages from MariaDB.

Here is what i have on my error log :

/usr/sbin/mysqld(my_print_stacktrace+0x2b)[0xb9f46b]

/usr/sbin/mysqld(handle_fatal_signal+0x3b6)[0x7461f6]

/lib/x86_64-linux-gnu/libpthread.so.0(+0xf0a0)[0x7fb8deced0a0]

/usr/sbin/mysqld(_ZN4JOIN14optimize_innerEv+0x1640)[0x63b310]

/usr/sbin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x9e)[0x63cade]

/usr/sbin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x28d)[0x64038d]

/usr/sbin/mysqld[0x5e5886]

/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x503d)[0x5f0e9d]

/usr/sbin/mysqld[0x5f28f7]

/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1c6e)[0x5f4cce]

/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x453)[0x6b3fa3]

/usr/sbin/mysqld(handle_one_connection+0x42)[0x6b4072]

/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50)[0x7fb8dece4b50]

/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fb8dd3eefbd]

170328 03:55:04 mysqld_safe Number of processes running now: 0

170328 03:55:04 mysqld_safe mysqld restarted

170328  3:55:04 [Note] /usr/sbin/mysqld (mysqld 10.0.29-MariaDB-1~wheezy) starting as process 8742 ...

/usr/sbin/mysqld: Query cache is disabled (resize or similar command in progress); repeat this command later

170328  3:55:05 [Note] InnoDB: Using mutexes to ref count buffer pool pages

170328  3:55:05 [Note] InnoDB: The InnoDB memory heap is disabled

170328  3:55:05 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

170328  3:55:05 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier

170328  3:55:05 [Note] InnoDB: Compressed tables use zlib 1.2.7

170328  3:55:05 [Note] InnoDB: Using Linux native AIO

170328  3:55:05 [Note] InnoDB: Using CPU crc32 instructions

170328  3:55:05 [Note] InnoDB: Initializing buffer pool, size = 8.0G

170328  3:55:05 [Note] InnoDB: Completed initialization of buffer pool

170328  3:55:05 [Note] InnoDB: Highest supported file format is Barracuda.

170328  3:55:05 [Note] InnoDB: Log scan progressed past the checkpoint lsn 39835474231511

170328  3:55:05 [Note] InnoDB: Database was not shutdown normally!

170328  3:55:05 [Note] InnoDB: Starting crash recovery.

170328  3:55:05 [Note] InnoDB: Reading tablespace information from the .ibd files...

170328  3:55:06 [ERROR] InnoDB: space header page consists of zero bytes in tablespace ./otherdb/#sql-ib7991104-2285190905.ibd (table otherdb/#sql-ib7991104-2285190905)

170328  3:55:06 [Note] InnoDB: Page size:1024 Pages to analyze:64

170328  3:55:06 [Note] InnoDB: Page size: 1024, Possible space_id count:0

170328  3:55:06 [Note] InnoDB: Page size:2048 Pages to analyze:32

170328  3:55:06 [Note] InnoDB: Page size: 2048, Possible space_id count:0

170328  3:55:06 [Note] InnoDB: Page size:4096 Pages to analyze:16

170328  3:55:06 [Note] InnoDB: Page size: 4096, Possible space_id count:0

170328  3:55:06 [Note] InnoDB: Page size:8192 Pages to analyze:8

170328  3:55:06 [Note] InnoDB: Page size: 8192, Possible space_id count:0

170328  3:55:06 [Note] InnoDB: Page size:16384 Pages to analyze:4

170328  3:55:06 [Note] InnoDB: Page size: 16384, Possible space_id count:0

2017-03-28 03:55:06 7f1fb88bc760  InnoDB: Operating system error number 2 in a file operation.

InnoDB: The error means the system cannot find the path specified.

InnoDB: If you are installing InnoDB, remember that you must create

InnoDB: directories yourself, InnoDB does not create them.

InnoDB: Error: could not open single-table tablespace file ./otherdb/#sql-ib7991104-2285190905.ibd

170328  3:55:07 [ERROR] InnoDB: Space id in fsp header 1851878432,but in the page header 544434535

170328  3:55:07 [ERROR] InnoDB: checksum mismatch in tablespace ./database/wp_term_relationships.ibd (table database/wp_term_relationships)

170328  3:55:07 [Note] InnoDB: Page size:1024 Pages to analyze:64

170328  3:55:07 [Note] InnoDB: Page size: 1024, Possible space_id count:0

170328  3:55:07 [Note] InnoDB: Page size:2048 Pages to analyze:56

170328  3:55:07 [Note] InnoDB: Page size: 2048, Possible space_id count:0

170328  3:55:07 [Note] InnoDB: Page size:4096 Pages to analyze:28

170328  3:55:07 [Note] InnoDB: Page size: 4096, Possible space_id count:0

170328  3:55:07 [Note] InnoDB: Page size:8192 Pages to analyze:14

170328  3:55:07 [Note] InnoDB: Page size: 8192, Possible space_id count:0

170328  3:55:07 [Note] InnoDB: Page size:16384 Pages to analyze:7

170328  3:55:07 [Note] InnoDB: VALID: space:8763257 page_no:1 page_size:16384

170328  3:55:07 [Note] InnoDB: VALID: space:8763257 page_no:2 page_size:16384

170328  3:55:07 [Note] InnoDB: VALID: space:8763257 page_no:3 page_size:16384

170328  3:55:07 [Note] InnoDB: VALID: space:8763257 page_no:4 page_size:16384

170328  3:55:07 [Note] InnoDB: Page size: 16384, Possible space_id count:1

170328  3:55:07 [Note] InnoDB: space_id:8763257, Number of pages matched: 4/4 (16384)

170328  3:55:07 [Note] InnoDB: Chosen space:8763257

170328  3:55:07 [Note] InnoDB: Restoring page 0 of tablespace 8763257

170328  3:55:07 [Warning] InnoDB: Doublewrite does not have page_no=0 of space: 8763257

2017-03-28 03:55:07 7f1fb88bc760  InnoDB: Operating system error number 2 in a file operation.

InnoDB: The error means the system cannot find the path specified.

InnoDB: If you are installing InnoDB, remember that you must create

InnoDB: directories yourself, InnoDB does not create them.

InnoDB: Error: could not open single-table tablespace file ./database/wp_term_relationships.ibd

InnoDB: We do not continue the crash recovery, because the table may become

InnoDB: corrupt if we cannot apply the log records in the InnoDB log to it.

InnoDB: To fix the problem and start mysqld:

InnoDB: 1) If there is a permission problem in the file and mysqld cannot

InnoDB: open the file, you should modify the permissions.

InnoDB: 2) If the table is not needed, or you can restore it from a backup,

InnoDB: then you can remove the .ibd file, and InnoDB will do a normal

InnoDB: crash recovery and ignore that table.

InnoDB: 3) If the file system or the disk is broken, and you cannot remove

InnoDB: and force InnoDB to continue crash recovery here.

170328 03:55:07 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

170328 03:58:47 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql

170328  3:58:47 [Note] /usr/sbin/mysqld (mysqld 10.0.29-MariaDB-1~wheezy) starting as process 9173 ...

/usr/sbin/mysqld: Query cache is disabled (resize or similar command in progress); repeat this command later

/usr/sbin/mysqld: Query cache is disabled (resize or similar command in progress); repeat this command later

170328  3:58:48 [Note] InnoDB: Using mutexes to ref count buffer pool pages

170328  3:58:48 [Note] InnoDB: The InnoDB memory heap is disabled

170328  3:58:48 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

170328  3:58:48 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier

170328  3:58:48 [Note] InnoDB: Compressed tables use zlib 1.2.7

170328  3:58:48 [Note] InnoDB: Using Linux native AIO

170328  3:58:48 [Note] InnoDB: Using CPU crc32 instructions

170328  3:58:48 [Note] InnoDB: Initializing buffer pool, size = 8.0G

170328  3:58:48 [Note] InnoDB: Completed initialization of buffer pool

170328  3:58:48 [Note] InnoDB: Highest supported file format is Barracuda.

170328  3:58:48 [Note] InnoDB: Log scan progressed past the checkpoint lsn 39835474231511

170328  3:58:48 [Note] InnoDB: Database was not shutdown normally!

170328  3:58:48 [Note] InnoDB: Starting crash recovery.

170328  3:58:48 [Note] InnoDB: Reading tablespace information from the .ibd files...

170328  3:58:49 [ERROR] InnoDB: space header page consists of zero bytes in tablespace ./otherdb/#sql-ib7991104-2285190905.ibd (table otherdb/#sql-ib7991104-2285190905)

170328  3:58:49 [Note] InnoDB: Page size:1024 Pages to analyze:64

170328  3:58:49 [Note] InnoDB: Page size: 1024, Possible space_id count:0

170328  3:58:49 [Note] InnoDB: Page size:2048 Pages to analyze:32

170328  3:58:49 [Note] InnoDB: Page size: 2048, Possible space_id count:0

170328  3:58:49 [Note] InnoDB: Page size:4096 Pages to analyze:16

170328  3:58:49 [Note] InnoDB: Page size: 4096, Possible space_id count:0

170328  3:58:49 [Note] InnoDB: Page size:8192 Pages to analyze:8

170328  3:58:49 [Note] InnoDB: Page size: 8192, Possible space_id count:0

170328  3:58:49 [Note] InnoDB: Page size:16384 Pages to analyze:4

170328  3:58:49 [Note] InnoDB: Page size: 16384, Possible space_id count:0

2017-03-28 03:58:49 7f4edc6dd760  InnoDB: Operating system error number 2 in a file operation.

InnoDB: The error means the system cannot find the path specified.

InnoDB: If you are installing InnoDB, remember that you must create

InnoDB: directories yourself, InnoDB does not create them.

InnoDB: Error: could not open single-table tablespace file ./otherdb/#sql-ib7991104-2285190905.ibd

170328  3:58:49 [ERROR] InnoDB: Space id in fsp header 1851878432,but in the page header 544434535

170328  3:58:49 [ERROR] InnoDB: checksum mismatch in tablespace ./database/wp_term_relationships.ibd (table database/wp_term_relationships)

[...]

And at the beginning of the idb file :

170328  3:55:01 [ERROR] mysqld got signal 11 ;

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.0.29-MariaDB-1~wheezy

key_buffer_size=4294967292

read_buffer_size=131072

max_used_connections=64

max_threads=311

thread_count=8

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4877184 K  bytes of memory

Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7fb2d2e51008

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 = 0x7fb5877b5e20 thread_stack 0x48000

Trying to get some variables.

Some pointers may be invalid and cause the dump to abort.

Query (0x7fb42ed1b020): is an invalid pointer

Connection ID (thread ID): 24769909

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.

We think the query pointer is invalid, but we will try to print it anyway.

Query: SELECT m.name, COUNT(DISTINCT p.id_product) nbr, m.id_manufacturer , m.name, psi.price_min, psi.price_max

                                        FROM `ps_category_product` cp

                                        INNER JOIN  `ps_category` c ON (c.id_category = cp.id_category)

                                        INNER JOIN ps_product p ON (p.id_product = cp.id_product)

                                        INNER JOIN ps_manufacturer m ON (m.id_manufacturer = p.id_manufacturer)  INNER JOIN ps_product_shop product_shop

                ON (product_shop.id_product = p.id_product AND product_shop.id_shop = 1)

                        INNER JOIN `ps_layered_price_index` psi

                        ON (psi.id_product = p.id_product AND psi.id_currency = 1)

WHERE

                                        c.nleft >= 4

                                        AND c.nright <= 5

                                        AND c.active = 1

                                        AND product_shop.active = 1 AND p.id_product IN (SELECT id_product FROM ps_feature_product fp WHERE fp.`id_feature_value` = 15 OR fp.`id_feature_value` = 18 OR fp.`id_feature_value` = 23)  AND p.id_product IN (SELECT id_product FROM ps_feature_product fp WHERE fp.`id_feature_value` = 68)  AND p.id_product IN (SELECT id_product FROM ps_feature_product fp WHERE fp.`id_feature_value` = 62)

                AND p.id_product IN (SELECT pa.`id_product`

                FROM `ps_product_attribute_combination` pac

                LEFT JOIN `ps_product_attribute` pa ON (pa.`id_product_attribute` = pac.`id_product_attribute`)

                WHERE pac.`id_attribute` = 34)

                AND p.id_product IN (SELECT pa.`id_product`

                FROM `ps_product_attribute_combination` pac

                LEFT JOIN `ps_product_attribute` pa ON (pa.`id_product_attribute` = pac.`id_product_attribute`)

                WHERE pac.`id_attribute` = 39 OR pac.`id_attribute` = 41 OR pac.`id_attribute` = 53 OR pac.`id_attribute` = 98)

 GROUP BY p.id_manufacturer

Comment by Michael Widenius [ 2017-03-28 ]

What is intersting in Jean's log is that the ibfile contains half of the crash, but the stack trace continues
in the error log file. Another interesting thing is that the ibfile contains the first stderr print after a failure.
Wonder if it's the crash that triggers stderr to be using the wrong file.

I noticed that on windows, we call reopen_fstreams after innodb is opened, which could in theory cause some issues if innodb crashed in a background thread during this reopen.
We should at least move this reopen_fstreams before init_server_components

Unfortunately this doesn't explain this crash as Jean's crash is not on windows.

How atomic is writing to stderr if freopen() is called ?
What I don't understand is how it's possible that stderr could, possible as part of freopen(), use the file descriptor to the innodb file?

One FreeBSD we did have a bug like this a long time ago when freopen was not thread safe and another thread could get the same file descriptor as used by stderr:
https://bugs.mysql.com/bug.php?id=51023

This bug happens apparently on wheezy. Wonder on which other OS this problem has appeared?

Regards,
Monty

Comment by Jean Weisbuch [ 2017-03-28 ]

Some additional notes on my crash : The server is on an OpenVZ container running kernel 2.6.32-openvz-042stab116.2-amd64 (Jun 24 2016), the server was up since the 17/02 and there are 4 OpenVZ container containing each a MariaDB server on this server.

On the error log backlog there is a similar crash that happened on the 17/02 on the same query but with all the log on the error log :

170216 16:58:16 [ERROR] mysqld got signal 11 ;

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.0.29-MariaDB-1~wheezy

key_buffer_size=4294967292

read_buffer_size=131072

max_used_connections=47

max_threads=311

thread_count=3

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4877184 K  bytes of memory

Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f574ca5c008

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 = 0x7f57bd0d9e20 thread_stack 0x48000

/usr/sbin/mysqld(my_print_stacktrace+0x2b)[0xb9f46b]

/usr/sbin/mysqld(handle_fatal_signal+0x3b6)[0x7461f6]

/lib/x86_64-linux-gnu/libpthread.so.0(+0xf0a0)[0x7f5b065880a0]

/usr/sbin/mysqld(_Z30setup_sj_materialization_part2P13st_join_table+0x57)[0x6e10c7]

/usr/sbin/mysqld(_ZN4JOIN14optimize_innerEv+0x1710)[0x63b3e0]

/usr/sbin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x9e)[0x63cade]

/usr/sbin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x28d)[0x64038d]

/usr/sbin/mysqld[0x5e5886]

/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x503d)[0x5f0e9d]

/usr/sbin/mysqld[0x5f28f7]

/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1c6e)[0x5f4cce]

/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x453)[0x6b3fa3]

/usr/sbin/mysqld(handle_one_connection+0x42)[0x6b4072]

/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50)[0x7f5b0657fb50]

/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f5b04c89fbd]

Trying to get some variables.

Some pointers may be invalid and cause the dump to abort.

Query (0x7f5644414020): is an invalid pointer

Connection ID (thread ID): 519012

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.

We think the query pointer is invalid, but we will try to print it anyway.

Query: SELECT m.name, COUNT(DISTINCT p.id_product) nbr, m.id_manufacturer , m.name, psi.price_min, psi.price_max

					FROM `ps_category_product` cp

					INNER JOIN  `ps_category` c ON (c.id_category = cp.id_category)

					INNER JOIN ps_product p ON (p.id_product = cp.id_product)

					INNER JOIN ps_manufacturer m ON (m.id_manufacturer = p.id_manufacturer)  INNER JOIN ps_product_shop product_shop

		ON (product_shop.id_product = p.id_product AND product_shop.id_shop = 1)

			INNER JOIN `ps_layered_price_index` psi

			ON (psi.id_product = p.id_product AND psi.id_currency = 1)

WHERE

					c.nleft >= 4

					AND c.nright <= 5

					AND c.active = 1

					AND product_shop.active = 1 AND p.id_product IN (SELECT id_product FROM ps_feature_product fp WHERE fp.`id_feature_value` = 23)  AND p.id_product IN (SELECT id_product FROM ps_feature_product fp WHERE fp.`id_feature_value` = 68)  AND p.id_product IN (SELECT id_product FROM ps_feature_product fp WHERE fp.`id_feature_value` = 62)

		AND p.id_product IN (SELECT pa.`id_product`

		FROM `ps_product_attribute_combination` pac

		LEFT JOIN `ps_product_attribute` pa ON (pa.`id_product_attribute` = pac.`id_product_attribute`)

		WHERE pac.`id_attribute` = 35 OR pac.`id_attribute` = 36)

		AND p.id_product IN (SELECT pa.`id_product`

		FROM `ps_product_attribute_combination` pac

		LEFT JOIN `ps_product_attribute` pa ON (pa.`id_product_attribute` = pac.`id_product_attribute`)

		WHERE pac.`id_attribute` = 14)

 GROUP BY p.id_manufacturer

170216 16:58:19 mysqld_safe Number of processes running now: 0

170216 16:58:19 mysqld_safe mysqld restarted

170216 16:58:19 [Note] /usr/sbin/mysqld (mysqld 10.0.29-MariaDB-1~wheezy) starting as process 12920 ...

/usr/sbin/mysqld: Query cache is disabled (resize or similar command in progress); repeat this command later

170216 16:58:20 [Note] InnoDB: Using mutexes to ref count buffer pool pages

170216 16:58:20 [Note] InnoDB: The InnoDB memory heap is disabled

170216 16:58:20 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

170216 16:58:20 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier

170216 16:58:20 [Note] InnoDB: Compressed tables use zlib 1.2.7

170216 16:58:20 [Note] InnoDB: Using Linux native AIO

170216 16:58:20 [Note] InnoDB: Using CPU crc32 instructions

170216 16:58:20 [Note] InnoDB: Initializing buffer pool, size = 8.0G

170216 16:58:20 [Note] InnoDB: Completed initialization of buffer pool

170216 16:58:20 [Note] InnoDB: Highest supported file format is Barracuda.

170216 16:58:20 [Note] InnoDB: Log scan progressed past the checkpoint lsn 39776728170240

170216 16:58:20 [Note] InnoDB: Database was not shutdown normally!

170216 16:58:20 [Note] InnoDB: Starting crash recovery.

170216 16:58:20 [Note] InnoDB: Reading tablespace information from the .ibd files...

170216 16:58:20 [ERROR] InnoDB: space header page consists of zero bytes in tablespace ./otherdb/#sql-ib7991104-2285190905.ibd (table otherdb/#sql-ib7991104-2285190905)

170216 16:58:20 [Note] InnoDB: Page size:1024 Pages to analyze:64

170216 16:58:20 [Note] InnoDB: Page size: 1024, Possible space_id count:0

170216 16:58:20 [Note] InnoDB: Page size:2048 Pages to analyze:32

170216 16:58:20 [Note] InnoDB: Page size: 2048, Possible space_id count:0

170216 16:58:20 [Note] InnoDB: Page size:4096 Pages to analyze:16

170216 16:58:20 [Note] InnoDB: Page size: 4096, Possible space_id count:0

170216 16:58:20 [Note] InnoDB: Page size:8192 Pages to analyze:8

170216 16:58:20 [Note] InnoDB: Page size: 8192, Possible space_id count:0

170216 16:58:20 [Note] InnoDB: Page size:16384 Pages to analyze:4

170216 16:58:20 [Note] InnoDB: Page size: 16384, Possible space_id count:0

2017-02-16 16:58:20 7fb8df10b760  InnoDB: Operating system error number 2 in a file operation.

InnoDB: The error means the system cannot find the path specified.

InnoDB: If you are installing InnoDB, remember that you must create

InnoDB: directories yourself, InnoDB does not create them.

InnoDB: Error: could not open single-table tablespace file ./otherdb/#sql-ib7991104-2285190905.ibd

170216 16:58:24 [Note] InnoDB: Restoring possible half-written data pages

170216 16:58:24 [Note] InnoDB: from the doublewrite buffer...

InnoDB: Doing recovery: scanned up to log sequence number 39776728204895

170216 16:58:25 [Note] InnoDB: Starting an apply batch of log records to the database...

InnoDB: Progress in percent: 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

170216 16:58:27 [Note] InnoDB: 128 rollback segment(s) are active.

170216 16:58:27 [Note] InnoDB: Waiting for purge to start

170216 16:58:27 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.34-79.1 started; log sequence number 39776728204895

170216 16:58:27 [Note] Plugin 'FEEDBACK' is disabled.

170216 16:58:27 [Note] Server socket created on IP: '::'.

170216 16:58:27 [Note] Server socket created on IP: '::'.

170216 16:58:27 [ERROR] mysqld: Table './mysql/user' is marked as crashed and should be repaired

170216 16:58:27 [Warning] Checking table:   './mysql/user'

170216 16:58:27 [ERROR] mysql.user: 1 client is using or hasn't closed the table properly

170216 16:58:27 [Note] /usr/sbin/mysqld: ready for connections.

Version: '10.0.29-MariaDB-1~wheezy'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution

Configuration :

[client]

port		= 3306

socket		= /var/run/mysqld/mysqld.sock

[mysqld_safe]

socket		= /var/run/mysqld/mysqld.sock

nice		= 0

[mysqld]

user		= mysql

pid-file	= /var/run/mysqld/mysqld.pid

socket		= /var/run/mysqld/mysqld.sock

port		= 3306

basedir		= /usr

datadir		= /var/lib/mysql

tmpdir		= /tmpfs

skip-external-locking

key_buffer_size		= 4G

max_allowed_packet	= 64M

thread_cache_size	= 24

myisam-recover-options		= BACKUP

max_connections		= 300

table_open_cache	= 10000

table_definition_cache	= 10000

query_cache_limit       = 1M

query_cache_size        = 64M

query_cache_min_res_unit        = 2048

query_cache_type        = OFF

local-infile		= 0

open_files_limit	= 65535

skip-name-resolve

max_delayed_threads	= 1

wait_timeout		= 60

interactive_timeout	= 60

join_buffer_size	= 2M

read_rnd_buffer_size	= 1M

tmp_table_size		= 64M

max_heap_table_size	= 64M

max_connect_errors	= 1000

bulk_insert_buffer_size	= 32M

myisam_sort_buffer_size = 32M

default_storage_engine  = InnoDB

innodb_file_format	= Barracuda

innodb_buffer_pool_size	= 8G

innodb_log_file_size	= 128M

innodb_flush_log_at_trx_commit	= 2

innodb_log_buffer_size	= 8M

innodb_file_per_table	= 1

innodb_open_files	= 400

innodb_io_capacity	= 400

innodb_flush_method	= O_DIRECT

join_cache_level	= 6

key_cache_segments	= 6

innodb_old_blocks_time	= 1000

extra_port		= 3307

extra-max-connections	= 10

log_error		= /var/log/mysql/error.log

slow_query_log_file	= /var/log/mysql/mysql-slow.log

slow_query_log		= 1

long_query_time		= 4

[mysqldump]

quick

quote-names

max_allowed_packet	= 64M

[mysql]

[isamchk]

key_buffer		= 64M

!includedir /etc/mysql/conf.d/

# egrep -v "^$|^#" /etc/mysql/conf.d/*

/etc/mysql/conf.d/mariadb.cnf:[client]

/etc/mysql/conf.d/mariadb.cnf:[mysqld]

/etc/mysql/conf.d/mysqld_safe_syslog.cnf.dpkg-dist:[mysqld_safe]

/etc/mysql/conf.d/mysqld_safe_syslog.cnf.dpkg-dist:skip_log_error

/etc/mysql/conf.d/mysqld_safe_syslog.cnf.dpkg-dist:syslog

/etc/mysql/conf.d/tokudb.cnf:[mariadb]

MariaDB [information_schema]> SELECT COUNT(*) FROM tables;

+----------+

| COUNT(*) |

+----------+

|    88955 |

+----------+

1 row in set (0.88 sec)

MariaDB [information_schema]> SELECT COUNT(DISTINCT table_schema) FROM tables;

+------------------------------+

| COUNT(DISTINCT table_schema) |

+------------------------------+

|                          967 |

+------------------------------+

1 row in set (0.94 sec)

Comment by Edward Hicks [ 2017-03-28 ]

Ours is:

$ uname -a

Linux dbserver 2.6.32-642.13.1.el6.x86_64 #1 SMP Wed Nov 23 16:03:01 EST 2016 x86_64 x86_64 x86_64 GNU/Linux

$ cat /etc/redhat-release

Red Hat Enterprise Linux Server release 6.8 (Santiago)

Comment by Edward Hicks [ 2017-03-29 ]

We had another event last night which was triggered by the disk running out of free space. The crash was therefore not a surprise; however, in the process another ibd file was corrupted. You can add 10.0.30 to the list of affected versions.

Unfortunately I cannot attach it this time as it holds potentially sensitive info; however, this time the top of the overwritten file only contained the string "pure virtual method called".

2017-03-29 08:14:05 7f05ac913700 InnoDB: Error: Write to file ./database/table.ibd failed at offset 131072.

InnoDB: 32768 bytes should have been written, only 0 were written.

InnoDB: Operating system error number 28.

InnoDB: Check that your OS and file system support files of this size.

InnoDB: Check also that the disk is not full or a disk quota exceeded.

InnoDB: Error number 28 means 'No space left on device'.

InnoDB: Some operating system error numbers are described at

InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html

FAIL170329  8:14:05 [ERROR] mysqld: The table 'table' is full

FAIL170329  8:14:05 [ERROR] mysqld: The table 'table' is full

FAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAIL170329  8:14:07 [ERROR] mysqld: The table 'table' is full

FAIL170329  8:14:07 [ERROR] mysqld: The table 'table' is full

FAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILInnoDB: Fatal error (Out of disk space) in rollback.

InnoDB: Out of tablespace.

InnoDB: Consider increasing your tablespace.

FAILFAILFAILFAIL170329 08:14:12 mysqld_safe Number of processes running now: 0

170329 08:14:12 mysqld_safe mysqld restarted

170329  8:14:12 [Note] /usr/sbin/mysqld (mysqld 10.0.30-MariaDB) starting as process 9407 ...

170329  8:14:13 [Note] InnoDB: Using mutexes to ref count buffer pool pages

170329  8:14:13 [Note] InnoDB: The InnoDB memory heap is disabled

170329  8:14:13 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

170329  8:14:13 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier

170329  8:14:13 [Note] InnoDB: Compressed tables use zlib 1.2.3

170329  8:14:13 [Note] InnoDB: Using Linux native AIO

170329  8:14:13 [Note] InnoDB: Using CPU crc32 instructions

170329  8:14:13 [Note] InnoDB: Initializing buffer pool, size = 7.0G

170329  8:14:13 [Note] InnoDB: Completed initialization of buffer pool

170329  8:14:13 [Note] InnoDB: Highest supported file format is Barracuda.

170329  8:14:13 [Note] InnoDB: Log scan progressed past the checkpoint lsn 7020651191165

170329  8:14:13 [Note] InnoDB: Database was not shutdown normally!

170329  8:14:13 [Note] InnoDB: Starting crash recovery.

170329  8:14:13 [Note] InnoDB: Reading tablespace information from the .ibd files...

170329  8:16:28 [ERROR] InnoDB: Space id in fsp header 876228913,but in the page header 540555825

170329  8:16:28 [ERROR] InnoDB: checksum mismatch in tablespace ./meddb/anothertable.ibd (table meddb/anothertable)

170329  8:16:28 [Note] InnoDB: Page size:1024 Pages to analyze:64

170329  8:16:28 [Note] InnoDB: Page size: 1024, Possible space_id count:0

170329  8:16:28 [Note] InnoDB: Page size:2048 Pages to analyze:64

170329  8:16:28 [Note] InnoDB: Page size: 2048, Possible space_id count:0

170329  8:16:28 [Note] InnoDB: Page size:4096 Pages to analyze:56

170329  8:16:28 [Note] InnoDB: Page size: 4096, Possible space_id count:0

170329  8:16:28 [Note] InnoDB: Page size:8192 Pages to analyze:28

170329  8:16:28 [Note] InnoDB: Page size: 8192, Possible space_id count:0

170329  8:16:28 [Note] InnoDB: Page size:16384 Pages to analyze:14

170329  8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:1 page_size:16384

170329  8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:2 page_size:16384

170329  8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:3 page_size:16384

170329  8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:4 page_size:16384

170329  8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:5 page_size:16384

170329  8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:6 page_size:16384

170329  8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:7 page_size:16384

170329  8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:8 page_size:16384

170329  8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:9 page_size:16384

170329  8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:10 page_size:16384

170329  8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:11 page_size:16384

170329  8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:12 page_size:16384

170329  8:16:28 [Note] InnoDB: Page size: 16384, Possible space_id count:1

170329  8:16:28 [Note] InnoDB: space_id:1894080, Number of pages matched: 12/12 (16384)

170329  8:16:28 [Note] InnoDB: Chosen space:1894080

170329  8:16:28 [Note] InnoDB: Restoring page 0 of tablespace 1894080

170329  8:16:28 [Warning] InnoDB: Doublewrite does not have page_no=0 of space: 1894080

2017-03-29 08:16:28 7f1ca3eec820  InnoDB: Operating system error number 2 in a file operation.

InnoDB: The error means the system cannot find the path specified.

InnoDB: If you are installing InnoDB, remember that you must create

InnoDB: directories yourself, InnoDB does not create them.

InnoDB: Error: could not open single-table tablespace file ./meddb/anothertable.ibd

InnoDB: We do not continue the crash recovery, because the table may become

InnoDB: corrupt if we cannot apply the log records in the InnoDB log to it.

InnoDB: To fix the problem and start mysqld:

InnoDB: 1) If there is a permission problem in the file and mysqld cannot

InnoDB: open the file, you should modify the permissions.

InnoDB: 2) If the table is not needed, or you can restore it from a backup,

InnoDB: then you can remove the .ibd file, and InnoDB will do a normal

InnoDB: crash recovery and ignore that table.

InnoDB: 3) If the file system or the disk is broken, and you cannot remove

InnoDB: the .ibd file, you can set innodb_force_recovery > 0 in my.cnf

InnoDB: and force InnoDB to continue crash recovery here.

170329 08:16:28 mysqld_safe mysqld from pid file /var/lib/mysqldata/mysql/DATABASES/whsqlprd05.pid ended

Comment by Jean Weisbuch [ 2017-07-06 ]

Any news on this, is it still not possible to upgrade to 10.0.31?

Comment by Sergey Vojtovich [ 2017-07-14 ]

mysqld_safe starts mysqld with with "1" and "2" file descriptors closed. This was introduced in https://github.com/MariaDB/server/commit/7497ebf8a49bfe30bb4110f2ac20a30f804b7946

This means that descriptors "1" and "2" are free for use for any file.

But then signal handler writes it's messages to a hardcoded file descriptor STDERR_FILENO (which is "2").

In both reports InnoDB data file header was overrider exactly with signal handler messages.

I'm reassigning to serg and raising priority to critical, since it causes data loss.

Comment by Sergey Vojtovich [ 2017-07-14 ]

Please also note that early server error messages (before freopen(stderr)) may also go to undesired location.
Same for setups where log_error is not defined.

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

[MDEV-12144] Signal 6 crash corrupts ibd files Created: 2017-02-27 Updated: 2017-07-15 Resolved: 2017-07-15