[MDEV-11948] InnoDB: Operating system error number 22 in a file operation, innodb.log_file fails in buildbot on CentOS 5 Created: 2017-01-31  Updated: 2023-11-16  Resolved: 2017-02-06

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Tests
Affects Version/s: 10.2
Fix Version/s: 10.2.4

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


 Description   

The failure looks in buildbot like this:
http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-centos5-amd64/builds/4574/steps/test/logs/stdio

innodb.log_file 'innodb'                 w3 [ fail ]
        Test ended at 2017-01-30 19:08:42
 
CURRENT_TEST: innodb.log_file
sh: line 1: 29096 Aborted                 /usr/local/mariadb-10.2.4-linux-x86_64/bin/mysqld --defaults-file=/usr/local/mariadb-10.2.4-linux-x86_64/mysql-test/var/3/tmp/log_file/my.cnf --loose-console > /usr/local/mariadb-10.2.4-linux-x86_64/mysql-test/var/3/tmp/log_file/my_restart.err 2>&1
NOT FOUND /\[ERROR\] InnoDB: Could not create undo tablespace '.*undo002'/ in my_restart.err
mysqltest: In included file "./include/search_pattern_in_file.inc": 
included from /usr/local/mariadb-10.2.4-linux-x86_64/mysql-test/suite/innodb/t/log_file.test at line 46:
At line 61: command "perl" failed with error: 255  my_errno: 0  errno: 0
 
The result from queries just before the failure was:
# Testcase for the following bugs
# Bug#16691130 - ASSERT WHEN INNODB_LOG_GROUP_HOME_DIR DOES NOT EXIST
# Bug#16418661 - CHANGING NAME IN FOR INNODB_DATA_FILE_PATH SHOULD NOT SUCCEED WITH LOG FILES
# Write tmp/log_file/my.cnf
# Start mysqld without the possibility to create innodb_undo_tablespaces

Reproducible reliably on the corresponding VM (vm-centos5-amd64-install) reliably, but only if the test is run in shm.

The error log from the intermediate attempt to start the server looks like this:

2017-01-31  1:11:59 47545700325168 [Note] /home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld (mysqld 10.2.4-MariaDB) starting as process 19553 ...
2017-01-31  1:11:59 47545700325168 [Note] Plugin 'Aria' is disabled.
2017-01-31  1:11:59 47545700325168 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-01-31  1:11:59 47545700325168 [Note] InnoDB: Uses event mutexes
2017-01-31  1:11:59 47545700325168 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-01-31  1:11:59 47545700325168 [Note] InnoDB: Using Linux native AIO
2017-01-31  1:11:59 47545700325168 [Note] InnoDB: Number of pools: 1
2017-01-31  1:11:59 47545700325168 [Note] InnoDB: Using generic crc32 instructions
2017-01-31  1:11:59 47545700325168 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2017-01-31  1:11:59 47545700325168 [Note] InnoDB: Completed initialization of buffer pool
2017-01-31  1:11:59 1203657024 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-01-31  1:11:59 47545700325168 [Note] InnoDB: The first innodb_system data file 'ibdata1' did not exist. A new tablespace will be created!
2017-01-31  1:11:59 47545700325168 [Note] InnoDB: Need to create a new innodb_system data file 'ibdata2'.
2017-01-31  1:11:59 47545700325168 [Note] InnoDB: Setting file '/home/buildbot/mariadb-10.2.4-linux-x86_64/mysql-test/var/tmp/log_file/ibdata1' size to 10 MB. Physically writing the file full; Please wait ...
2017-01-31  1:11:59 47545700325168 [Note] InnoDB: File '/home/buildbot/mariadb-10.2.4-linux-x86_64/mysql-test/var/tmp/log_file/ibdata1' size is now 10 MB.
2017-01-31  1:11:59 47545700325168 [Note] InnoDB: Setting file '/home/buildbot/mariadb-10.2.4-linux-x86_64/mysql-test/var/tmp/log_file/ibdata2' size to 10 MB. Physically writing the file full; Please wait ...
2017-01-31  1:12:00 47545700325168 [Note] InnoDB: File '/home/buildbot/mariadb-10.2.4-linux-x86_64/mysql-test/var/tmp/log_file/ibdata2' size is now 10 MB.
2017-01-31  1:12:00 47545700325168 [Note] InnoDB: Setting log file ./ib_logfile101 size to 48 MB
2017-01-31  1:12:00 47545700325168 [Note] InnoDB: Setting log file ./ib_logfile1 size to 48 MB
2017-01-31  1:12:00 47545700325168 [Note] InnoDB: Setting log file ./ib_logfile2 size to 48 MB
2017-01-31  1:12:00 47545700325168 [ERROR] InnoDB: Operating system error number 22 in a file operation.
2017-01-31  1:12:00 47545700325168 [ERROR] InnoDB: Error number 22 means 'Invalid argument'
2017-01-31  1:12:00 47545700325168 [Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2017-01-31  1:12:00 47545700325168 [ERROR] InnoDB: File ./ib_logfile101: 'aio write' returned OS error 222. Cannot continue operation
170131  1:12:00 [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.2.4-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 = 467201 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x0 thread_stack 0x48c00
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld(my_print_stacktrace+0x2e)[0xdde5ce]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld(handle_fatal_signal+0x4cc)[0x7cfefc]
/lib64/libpthread.so.0[0x340220e4c0]
/lib64/libc.so.6(gsignal+0x35)[0x3401a30215]
/lib64/libc.so.6(abort+0x110)[0x3401a31cc0]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld[0xa62a55]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld[0xa643d1]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld[0xc388da]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld[0xa3d4fc]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld[0xa41551]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld[0xa420ac]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld[0xa46876]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld[0xb1222f]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld[0xb16a00]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld[0x9e0be7]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x5e)[0x7d562e]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld[0x5fb42a]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld(_Z11plugin_initPiPPci+0xba1)[0x5fdd01]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld[0x54994d]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld(_Z11mysqld_mainiPPc+0x99f)[0x54ad6f]
/lib64/libc.so.6(__libc_start_main+0xf4)[0x3401a1d974]
/home/buildbot/mariadb-10.2.4-linux-x86_64/bin/mysqld(__gxx_personality_v0+0x3e9)[0x540289]
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.

I have a remembrance of a problem between aio and tmpfs in some old kernel. Disabling aio in the config file for the intermediate server makes the test failure go away:
https://github.com/MariaDB/server/commit/1e722e214ad1c52aa886dd1737e5c89ab789e6e7

but maybe it makes sense to look into the crash as such, as I don't think it's supposed to happen anymore.



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

I believe that MySQL 5.6 and 5.7 would fail in a similar way, except that it would call exit() instead of abort().
The abort() was replaced in MDEV-9282, and I think it is a better solution than calling exit().

That said, the I/O subsystem should be improved. Instead of terminating the server at the low level, we should propagate the error up the stack using IORequest, and eventually the originator of the request should decide how to handle the situation. This basically is a duplicate of the infamous MySQL Bug#10132 Crashing the server on corrupt InnoDB page is unhelpful.

In the short term, the workaround of disabling AIO in the test is fine.
On a related note, if asynchronous I/O is enabled, the test innodb.log_file_size would spew the warning

InnoDB: Unable to open "./ib_logfile0" to check native AIO read support.

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

A better solution is to rewrite the test so that it starts up the server normally (only letting the InnoDB plugin startup fail). In this way, the test does pass on CentOS 5 even when asynchronous I/O is not disabled.

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

https://github.com/MariaDB/server/commit/192f8aa86866092140e5678a12e5e1f67b722bce

Comment by Jan Lindström (Inactive) [ 2017-02-06 ]

ok to push.

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