InnoDB: Failing assertion: 0 in file os0file.cc line 662 | handle_fatal_signal (sig=6) in os_file_handle_error_cond_exit | File operation call: 'open' returned OS error 71. | InnoDB: Operating system error number 2 in a file operation.

[Roel Van de Paar]

========================= Error log:
2013-03-15 06:38:57 5363 [Note] /ssd/Percona-Server-5.6.8-alpha60.2-313-debug.Linux.x86_64/bin/mysqld-debug: ready for connections.
Version: '5.6.10-alpha60.2-debug-log' socket: '/ssd/198649/current1_3/tmp/master.sock' port: 13040 Percona Server with XtraDB (GPL), Release alpha60.2, Revision 313-debug
2013-03-15 06:39:19 7f7611c86700 InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
2013-03-15 06:39:19 7f7611c86700 InnoDB: File name /ssd/tmp/ib_log_archive_0000000000045568
2013-03-15 06:39:19 7f7611c86700 InnoDB: File operation call: 'open' returned OS error 71.
2013-03-15 06:39:19 7f7611c86700 InnoDB: Cannot continue operation.
2013-03-15 06:39:19 7f7611c86700 InnoDB: Assertion failure in thread 140145081214720 in file os0file.cc line 662
InnoDB: Failing assertion: 0
InnoDB: We intentionally generate a memory trap.

========================= gdb :
Thread 1 (LWP 5366):
+bt
#0 0x0000003da180c60c in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000006ab85f in handle_fatal_signal (sig=6) at /ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/sql/signal_handler.cc:249
#2 <signal handler called>
#3 0x0000003da1435935 in raise () from /lib64/libc.so.6
#4 0x0000003da14370e8 in abort () from /lib64/libc.so.6
#5 0x00000000009f625c in os_file_handle_error_cond_exit (name=name@entry=0x7f7611c85950 "/ssd/tmp/ib_log_archive_", '0' <repeats 11 times>, "45568", operation=0xdd84db "open", should_exit=should_exit@entry=1, on_error_silent=on_error_silent@entry=0) at /ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/storage/innobase/os/os0file.cc:662
#6 0x00000000009f7c0a in os_file_handle_error (operation=<optimized out>, name=0x7f7611c85950 "/ssd/tmp/ib_log_archive_", '0' <repeats 11 times>, "45568") at /ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/storage/innobase/os/os0file.cc:681
#7 os_file_create_func (name=0x7f7611c85950 "/ssd/tmp/ib_log_archive_", '0' <repeats 11 times>, "45568", create_mode=51, purpose=<optimized out>, type=100, success=0x7f7611c858f0) at /ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/storage/innobase/os/os0file.cc:1741
#8 0x00000000009de72e in pfs_os_file_create_func (purpose=61, type=100, src_file=0xdf04f8 "/ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/storage/innobase/log/log0log.cc", src_line=2403, src_file=0xdf04f8 "/ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/storage/innobase/log/log0log.cc", success=0x7f7611c858f0, type=100, purpose=61, create_mode=<optimized out>, name=0x7f7611c85950 "/ssd/tmp/ib_log_archive_", '0' <repeats 11 times>, "45568", key=<opt
imized out>) at /ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/storage/innobase/include/os0file.ic:151
#9 log_group_archive (group=0x3b6e068) at /ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/storage/innobase/log/log0log.cc:2403
#10 0x00000000009df809 in log_archive_groups () at /ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/storage/innobase/log/log0log.cc:2513
#11 log_archive_check_completion_low () at /ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/storage/innobase/log/log0log.cc:2612
#12 log_io_complete_archive () at /ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/storage/innobase/log/log0log.cc:2649
#13 log_io_complete (group=<optimized out>) at /ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/storage/innobase/log/log0log.cc:1060
#14 0x0000000000b7610a in fil_aio_wait (segment=1) at /ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/storage/innobase/fil/fil0fil.cc:5440
#15 0x0000000000a9f5e8 in io_handler_thread (arg=<optimized out>) at /ssd/ps56-univ-log-archive-qa/Percona-Server-5.6.8-alpha60.2/storage/innobase/srv/srv0start.cc:477
#16 0x0000003da1807d14 in start_thread () from /lib64/libpthread.so.0
#17 0x0000003da14f168d in clone () from /lib64/libc.so.6

========================= Run details:
[Roel@qaserver 198649]$ cat ./cmd9633
ps -ef | grep 'cmdrun_9633' | grep -v grep | awk '{print $2}' | xargs sudo kill -9
rm -Rf /ssd/198649/cmdrun_9633
mkdir /ssd/198649/cmdrun_9633
cd /ssd/randgen
bash -c "set -o pipefail; perl runall.pl --queries=100000000 --seed=10879 --duration=120 --querytimeout=60 --short_column_names --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=none --mysqld=--sql_mode=ONLY_FULL_GROUP_BY --grammar=conf/percona_qa/percona_qa.yy --gendata=conf/percona_qa/percona_qa.zz --basedir=/ssd/Percona-Server-5.6.8-alpha60.2-313-debug.Linux.x86_64 --threads=25 --validator=Transformer --mysqld=--innodb_log_archive=1 --mysqld=--innodb_log_arch_dir=/ssd/tmp --mysqld=--innodb_log_group_home_dir=/ssd/tmp --mysqld=--innodb_log_arch_expire_sec=0 --mysqld=--innodb_flush_log_at_trx_commit=0 --mysqld=--innodb_flush_method=O_DIRECT --mtr-build-thread=788 --mask=56686 --vardir1=/ssd/198649/cmdrun_9633 > /ssd/198649/cmdrun9633.log 2>&1"

========================= Notes:
- Seen in many runs.
- Long title is for SE search purposes only

[Roel Van de Paar (roel11)]

This can also be seen without the crash:

2013-03-10 00:05:07 22557 [Note] /ssd/Percona-Server-5.6.8-alpha60.2-313-debug.Linux.x86_64/bin/mysqld-debug: ready for connections.
Version: '5.6.10-alpha60.2-debug-log' socket: '/ssd/198649/current1_1/tmp/master.sock' port: 13000 Percona Server with XtraDB (GPL), Release alpha60.2, Revision 313-debug
2013-03-10 00:06:14 7f2e0effd700 InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
2013-03-10 00:06:14 7f2e0effd700 InnoDB: File name /ssd/tmp/ib_log_archive_0000000566166016
2013-03-10 00:06:14 7f2e0effd700 InnoDB: File operation call: 'delete' returned OS error 71.
InnoDB: Note: can't delete archived log file /ssd/tmp/ib_log_archive_0000000566166016.
2013-03-10 00:10:50 22557 [Note] /ssd/Percona-Server-5.6.8-alpha60.2-313-debug.Linux.x86_64/bin/mysqld-debug: Normal shutdown

Note the 'delete' versus 'open' above!

[Roel Van de Paar (roel11)]

Though part of this bug may be caused by concurrent mysqld's operating on the same set log dir, the issue could be caused by concurrent PURGEs running in two client threads also. This is what can be fixed for this bug.

[Roel Van de Paar (roel11)]

This issue also happens immediately with "create" failure when an non-existing directory is specified (/ssd/tmp/1363389556238603740 does not exists here, but /ssd/tmp does with proper privs). Should we attempt to 'mkdir' the directory?

2013-03-16 10:19:23 7f02f5b6c700 InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
2013-03-16 10:19:23 7f02f5b6c700 InnoDB: File name /ssd/tmp/1363389556238603740/ib_log_archive_0000000000045568
2013-03-16 10:19:23 7f02f5b6c700 InnoDB: File operation call: 'create' returned OS error 71.
2013-03-16 10:19:23 7f02f5b6c700 InnoDB: Cannot continue operation.
2013-03-16 10:19:23 7f02f5b6c700 InnoDB: Assertion failure in thread 139650689058560 in file os0file.cc line 662
InnoDB: Failing assertion: 0

[Roel Van de Paar (roel11)]

Bug confirmed still present even if per-run (per-mysqld if you will) directories are used:

2013-03-16 09:09:34 7f303a4f4700 InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
2013-03-16 09:09:34 7f303a4f4700 InnoDB: File name /tmp/1363414156674129979/ib_log_archive_0000000000045568
2013-03-16 09:09:34 7f303a4f4700 InnoDB: File operation call: 'open' returned OS error 71.
2013-03-16 09:09:34 7f303a4f4700 InnoDB: Cannot continue operation.
2013-03-16 09:09:34 7f303a4f4700 InnoDB: Assertion failure in thread 139845113431808 in file os0file.cc line 662
InnoDB: Failing assertion: 0
InnoDB: We intentionally generate a memory trap.

Note the "/tmp/1363414156674129979" directory - this a nanosecond epoch generated exclusively for this run. (RQG was updated to include this new functionality to support testing all parameters in this feature better)

[Sergei Glushchenko (sergei.glushchenko)]

To reproduce

1. Start server with archiving turned on
2. Load some data into tables for archived log file to be created
3. Restart server
4. Execute 'PURGE ARCHIVES LOGS BEFORE NOW()'
5. Shutdown server

Instead of normal shutdown following will be printed:
130316 18:06:57 InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
130316 18:06:57 InnoDB: File name /Users/sergei/percona/repo/log-arch/usr/local/mysql/data/ib_log_archive_0000000175350784
130316 18:06:57 InnoDB: File operation call: 'open' returned OS error 71.
130316 18:06:57 InnoDB: Cannot continue operation.
130316 18:06:57 InnoDB: Assertion failure in thread 4450070528 in file os0file.cc line 662
InnoDB: Failing assertion: 0
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.
11:06:57 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.
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.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=0
max_threads=151
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68253 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
0 mysqld 0x0000000101d01be7 my_print_stacktrace + 55
1 mysqld 0x000000010199484e handle_fatal_signal + 1070
2 libsystem_c.dylib 0x00007fff8aa28cfa _sigtramp + 26
3 ??? 0x00000001093ea048 0x0 + 4450066504
4 libsystem_c.dylib 0x00007fff8a9c7a7a abort + 143
5 mysqld 0x0000000101efd239 _ZL30os_file_handle_error_cond_exitPKcS0_mm + 585
6 mysqld 0x0000000101ef6b11 _ZL20os_file_handle_errorPKcS0_ + 49
7 mysqld 0x0000000101ef7b25 _Z19os_file_create_funcPKcmmmPm + 869
8 mysqld 0x0000000101ede2cf _ZL23pfs_os_file_create_funcjPKcmmmPmS0_m + 239
9 mysqld 0x0000000101eddbe2 _ZL17log_group_archiveP11log_group_t + 690
10 mysqld 0x0000000101edd448 _ZL18log_archive_groupsv + 120
11 mysqld 0x00000...

[Roel Van de Paar (roel11)]

Also saw this exact same error, but in a different situation. Turned out to be MS bug. Details in http://bugs.mysql.com/bug.php?id=69000

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-641