[#MDEV-13284] mariadb-server: fil_load_single_table_tablespace(): mysqld killed by SIGABRT

Comment by Sergei Golubchik [ 2017-07-10 ]

mschorm, I'm getting "Access denied" for them. Could you post the information here or at least make sure we can see these issues in RedHat bugzilla?

Comment by Michal Schorm [ 2017-07-10 ]

I made them public.
That should reveal everything, i think.

Comment by Elena Stepanova [ 2017-07-10 ]

At the first glance it appears to be the same as ~~MDEV-13113~~ which, in turn, turned out to be a duplicate of ~~MDEV-13105~~, fixed in 10.1.26.

Is there a way to find out what happened before the crash in either of those occurrences? Was it an upgrade from a MariaDB version prior to 10.1.21?

Comment by Michal Schorm [ 2017-07-10 ]

Unfortunatelly not an easy way.

The ABRT (automatic bug reporting tool) is powerfull to gather informations, but from my own experience, you - as a user - mostly know less, then the ABRT about what happened.

I'll ask the reporters in those bug reports, but it'll be just matter of luck.

Comment by Elena Stepanova [ 2017-07-10 ]

Thanks.

We don't need many details from them, just whether it happened upon or right after upgrade from an earlier version (pre-10.1.21).
What about this config file, .local/share/akonadi/mysql.conf – is it something standard, or is it user-specific? If it's standard, can we see it somewhere?

Comment by Michal Schorm [ 2017-07-10 ]

That "akonadi" config file should be standard, most likely.

Akonadi is a "PIM Storage Service Libraries" package and it is required by KDE. (So I'd say users don't edit it much)
This package required mysql / mariadb for a long time, but from Fedora 26 (which is BETA now), it only Recommends it.

So I'd look for that config file there.
The Akonadi package that wants MariaDB should be "kf5-akonadi-server-mysql"

I tried to find one and paste it here, but I was unsuccessful so far. I'll search for it more.

Comment by Michal Schorm [ 2017-07-10 ]

Here I have one: akonadi and stuff

Comment by Elena Stepanova [ 2017-07-10 ]

Thank you. Then maybe it's different from ~~MDEV-13113~~/~~MDEV-13105~~, after all. That one needed Barracuda format, and there is no sign of it in the config file.
Please let us know if you hear from the user about events preceding the crash.

Comment by Michal Schorm [ 2017-07-12 ]

Another report: rhbz#1421496

Comment by Jan Lindström (Inactive) [ 2017-08-10 ]

May I have full error log, based on code review InnoDB finds table on both default location and remote location (i.e. DATADIR='XXX') this could be inconsistency between data dictionary and SYS_DATAFILES table. Is there some easy way to repeat this ?

Comment by Andrii Nikitin (Inactive) [ 2017-08-23 ]

I bet some timing/luck in recovery is involved here.
Working on steps from ~~MDEV-13499~~ I can reliably reproduce similar stack on Server using xtrabackup tests framework with various versions like 10.1.24 10.1.26 and current 10.1 and even upstream 5.6.36 :

set -e

start_server

run_cmd $MYSQL $MYSQL_ARGS -e \

    "CREATE TABLE t1(c1 INT); INSERT INTO t1 VALUES(1);" test

stop_server

cp $mysql_datadir/test/t1.frm $mysql_datadir/test/t1_1.frm

cp $mysql_datadir/test/t1.ibd $mysql_datadir/test/t1_1.ibd

start_server

run_cmd $MYSQL $MYSQL_ARGS -e \

    "select * from test.t1_1; select * from test.t1" test

mkdir -p $topdir/backup

xtrabackup --backup --target-dir=$topdir/backup

[ERROR] InnoDB: Attempted to open a previously opened tablespace. Previous tablespace test/t1_1 uses space ID: 4 at filepath: ./test/t1_1.ibd. Cannot open tablespace test/t1 which uses space ID: 4 at filepath: ./test/t1.ibd

2017-08-23 14:33:50 7f89d454f8c0  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 ./test/t1.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.

170823 14:33:50 [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.27-MariaDB

key_buffer_size=134217728

read_buffer_size=131072

max_used_connections=0

max_threads=153

thread_count=0

It is possible that mysqld could use up to

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

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

Thread pointer: 0x0

Attempting backtrace. You can use the following information to find out

where mysqld died. If you see no messages after this, something went

terribly wrong...

stack_bottom = 0x0 thread_stack 0x48400

/home/a/spd/m0-10.1/build/sql//mysqld(my_print_stacktrace+0x29)[0x7f89d4f87f39]

/home/a/spd/m0-10.1/build/sql//mysqld(handle_fatal_signal+0x305)[0x7f89d4b47775]

/lib64/libpthread.so.0(+0xf370)[0x7f89d4188370]

/lib64/libc.so.6(gsignal+0x37)[0x7f89d20b71d7]

/lib64/libc.so.6(abort+0x148)[0x7f89d20b88c8]

/home/a/spd/m0-10.1/build/sql//mysqld(+0x95a4fc)[0x7f89d4f124fc]

mysys/stacktrace.c:268(my_print_stacktrace)[0x7f89d4dd43a0]

fil/fil0fil.cc:5120(fil_load_single_table_tablespaces(unsigned long (*)(char const*, char const*)))[0x7f89d4dda33a]

log/log0recv.cc:3006(recv_init_crash_recovery())[0x7f89d4e571a1]

/home/a/spd/m0-10.1/build/sql//mysqld(+0x7d875e)[0x7f89d4d9075e]

handler/ha_innodb.cc:4454(innobase_init(void*))[0x7f89d4b49df1]

sql/handler.cc:513(ha_initialize_handlerton(st_plugin_int*))[0x7f89d49ecfc0]

sql/sql_plugin.cc:1683(plugin_init(int*, char**, int))[0x7f89d49ee03a]

sql/mysqld.cc:5152(init_server_components())[0x7f89d4955d10]

sql/mysqld.cc:5741(mysqld_main(int, char**))[0x7f89d495a4ca]

/lib64/libc.so.6(__libc_start_main+0xf5)[0x7f89d20a3b35]

/home/a/spd/m0-10.1/build/sql//mysqld(+0x396798)[0x7f89d494e798]

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.

Upstream doesn't show stack trace; just exits with the same message :

2017-08-23 16:30:02 5009 [Note] Plugin 'FEDERATED' is disabled.

2017-08-23 16:30:02 5009 [Note] InnoDB: Using atomics to ref count buffer pool pages

2017-08-23 16:30:02 5009 [Note] InnoDB: The InnoDB memory heap is disabled

2017-08-23 16:30:02 5009 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2017-08-23 16:30:02 5009 [Note] InnoDB: Memory barrier is not used

2017-08-23 16:30:02 5009 [Note] InnoDB: Compressed tables use zlib 1.2.3

2017-08-23 16:30:02 5009 [Note] InnoDB: Using Linux native AIO

2017-08-23 16:30:02 5009 [Note] InnoDB: Using CPU crc32 instructions

2017-08-23 16:30:02 5009 [Note] InnoDB: Initializing buffer pool, size = 128.0M

2017-08-23 16:30:02 5009 [Note] InnoDB: Completed initialization of buffer pool

2017-08-23 16:30:02 5009 [Note] InnoDB: Highest supported file format is Barracuda.

2017-08-23 16:30:02 5009 [Note] InnoDB: Log scan progressed past the checkpoint lsn 1625987

2017-08-23 16:30:02 5009 [Note] InnoDB: Database was not shutdown normally!

2017-08-23 16:30:02 5009 [Note] InnoDB: Starting crash recovery.

2017-08-23 16:30:02 5009 [Note] InnoDB: Reading tablespace information from the .ibd files...

2017-08-23 16:30:02 5009 [ERROR] InnoDB: Attempted to open a previously opened tablespace. Previous tablespace test/t1_1 uses space ID: 6 at filepath: ./test/t1_1.ibd. Cannot open tablespace test/t1 which uses space ID: 6 at filepath: ./test/t1.ibd

2017-08-23 16:30:02 7f8cc6ab0740  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 ./test/t1.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.

But following identical mtr test doesn't trigger the same problem in 10.1 and just expectedly reports only user error:

-- source include/have_innodb.inc

use test;

set default_storage_engine='innodb';

CREATE TABLE t1(c1 INT);

INSERT INTO t1 VALUES(1);

let $MYSQLD_DATADIR = `SELECT @@datadir`;

source include/shutdown_mysqld.inc ;

copy_file $MYSQLD_DATADIR/test/t1.frm $MYSQLD_DATADIR/test/t1_1.frm ;

copy_file $MYSQLD_DATADIR/test/t1.ibd $MYSQLD_DATADIR/test/t1_1.ibd ;

source include/start_mysqld.inc ;

select * from t1_1;

select * from t1;

Comment by Andrii Nikitin (Inactive) [ 2017-08-23 ]

I've attached data directory in data.zip , which triggers the problem on startup.

Comment by Andrii Nikitin (Inactive) [ 2017-08-25 ]

I can reproduce problem which I mentioned earlier with any InnoDB 5.6 version including upstream 5.6.3*, 5.6.11 and 10.0.32 and 10.0.24 ; so I am not sure how exactly it is related to the reports in Fedora

Comment by Jan Lindström (Inactive) [ 2018-01-25 ]

I do not see a reason to crash even in crash recovery if .ibd file is missing. If we have undo or redo log records for such tablespace, there is already error handling.

https://github.com/MariaDB/server/commit/0ecb2d7223788acc8efe07250d36b1706eed4b16

Comment by Marko Mäkelä [ 2018-01-29 ]

The fix needs some more work and a new review.
MariaDB 5.5 and 10.0 are calling exit() when an .ibd file is not readable during crash recovery, and innodb_force_recovery has not been specified. Starting with ~~MDEV-9282~~ and MariaDB 10.1.21, abort() would be called instead. Starting with MariaDB 10.2.2, we would allow the server to start up without InnoDB.

The problem basically is that the error must be propagated all the way up to innobase_init().

However, do we want to do this in MariaDB 10.1 or earlier? There is a known problem that after an aborted InnoDB startup, the server could crash on subsequent shutdown. This problem has been fixed in MariaDB 10.2 only; it required quite a bit of cleanup in the startup and shutdown code, which already varied a lot between MariaDB 10.2 and earlier versions.

Perhaps it would suffice to avoid this abort() call in mariabackup?

Comment by Marko Mäkelä [ 2018-01-29 ]

I think that it is bad to call either exit() or abort() from a storage engine plugin. It is a matter of taste which one you consider worse.

Comment by Jan Lindström (Inactive) [ 2018-01-29 ]

I rather not do the required cleanup in GA-release so I will let it crash on this case and fix only the mariabackup case.

Comment by Jan Lindström (Inactive) [ 2018-01-29 ]

Closing as works as designed. Workaround is to use innodb-force-recovery=1.

Comment by Michal Schorm [ 2018-01-29 ]

Thanks for the investigation.

Just to clarify: "Starting with MariaDB 10.2.2, we would allow the server to start up without InnoDB."
means that if the startup encounter some error, it won't call exit() or abort(), but tries to start without InnoDB?
( Or does it mean only that it is possible to start wihtout InnoDB? )

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

This bug was fixed by me in WL#7142 (MySQL 5.7.5). The InnoDB crash recovery was changed so that if the redo log refers to files that are missing, InnoDB will propagate the error to the caller of innobase_init(). These changes were included in MariaDB 10.2.2.

In MySQL 5.7, missing files would still abort the server startup unless innodb_force_recovery is specified, because InnoDB cannot be disabled there. In MariaDB, InnoDB can be disabled, and a failure to start up InnoDB will not prevent the rest of the server from starting up. Related to this, I fixed many things related to shutdown after aborted InnoDB startup in MariaDB 10.2.

The bug is not feasible to fix in earlier MariaDB versions. Backporting the redo log format change is clearly out of the question, and the InnoDB code base has changed very much between MariaDB 10.1 and 10.2.

The related bug in Mariabackup was fixed in ~~MDEV-13499~~.

Comment by Michal Schorm [ 2018-02-06 ]

I understand.
Closing Fedora bug reports as "fixed in next release; won't be fixed in F26".

Thanks for the investigation!

[MDEV-13284] mariadb-server: fil_load_single_table_tablespace(): mysqld killed by SIGABRT Created: 2017-07-10 Updated: 2018-02-06 Resolved: 2018-01-30
Status:	Closed
Project:	MariaDB Server
Component/s:	Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s:	10.1.21, 10.1.22, 10.1.23, 10.1.24
Fix Version/s:	10.2.2, 10.3.0

[MDEV-13284] mariadb-server: fil_load_single_table_tablespace(): mysqld killed by SIGABRT Created: 2017-07-10 Updated: 2018-02-06 Resolved: 2018-01-30