Bug #73300 innodb.log_file_name fails sproadically on pb2
Submitted: 16 Jul 2014 18:03 Modified: 14 Aug 2014 15:00
Reporter: Tarique Saleem Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.7.5 OS:Any
Assigned to: CPU Architecture:Any

[16 Jul 2014 18:03] Tarique Saleem
Description:
innodb.log_file_name fails sporadically on Pb2 with these 2 issues. 

http://pb2.no.oracle.com/?template=mysql_show_test_failure&test_failure_id=5515825
==================================================================================

innodb.log_file_name                     w1 [ fail ]
        Test ended at 2014-07-15 22:17:13

CURRENT_TEST: innodb.log_file_name
==10768== Memcheck, a memory error detector
==10768== Copyright (C) 2002-2012, and GNU GPL'd, by Julian Seward et al.
==10768== Using Valgrind-3.8.1 and LibVEX; rerun with -h for copyright info
==10768== Command: /export/home2/pb2/test/sb_1-12703751-1405443848.54/mysql-advanced-5.7.5-m15-linux-x86_64-valgrind/bin/mysqltest --defaults-file=/dev/shm/mtr-11528/var-all_default_valgrind/1/my.cnf --silent --tmpdir=/dev/shm/mtr-11528/var-all_default_valgrind/tmp/1 --character-sets-dir=/export/home2/pb2/test/sb_1-12703751-1405443848.54/mysql-advanced-5.7.5-m15-linux-x86_64-valgrind/share/charsets --logdir=/dev/shm/mtr-11528/var-all_default_valgrind/1/log --plugin_dir=/export/home2/pb2/test/sb_1-12703751-1405443848.54/mysql-advanced-5.7.5-m15-linux-x86_64-valgrind/lib/plugin --database=test --timer-file=/dev/shm/mtr-11528/var-all_default_valgrind/1/log/timer --test-file=/export/home2/pb2/test/sb_1-12703751-1405443848.54/mysql-advanced-5.7.5-m15-linux-x86_64-valgrind/mysql-test/suite/innodb/t/log_file_name.test --tail-lines=20 --result-file=/export/home2/pb2/test/sb_1-12703751-1405443848.54/mysql-advanced-5.7.5-m15-linux-x86_64-valgrind/mysql-test/suite/innodb/r/log_file_name.result
==10768== 
mysqltest: At line 130: query 'SELECT * FROM t2' failed: 1146: Table 'test.t2' doesn't exist

The result from queries just before the failure was:
< snip >
CREATE TABLE t1(a INT PRIMARY KEY) ENGINE=InnoDB;
CREATE TABLE t3(a INT PRIMARY KEY) ENGINE=InnoDB;
BEGIN;
INSERT INTO t3 VALUES (33101),(347);
INSERT INTO t1 VALUES (42),(9),(101);
RENAME TABLE t1 TO t2;
UPDATE t2 SET a=347 where a=42;
COMMIT;
# Fault 0 (no real fault): Orphan file with duplicate space_id.
# Fault 1: Two dirty files with the same space_id.
# Fault 2: Wrong space_id in a dirty file, and a missing file.
# Fault 3: Wrong space_id in a dirty file, and no missing file.
# Fault 4: Missing data file
# Fault 5: Wrong type of data file
# Normal restart after removing the injected faults.
==10768== 
==10768== HEAP SUMMARY:
==10768==     in use at exit: 0 bytes in 0 blocks
==10768==   total heap usage: 14,069 allocs, 14,069 frees, 15,065,639 bytes allocated
==10768== 
==10768== All heap blocks were freed -- no leaks are possible
==10768== 
==10768== For counts of detected and suppressed errors, rerun with: -v
==10768== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 6 from 6)

 - the logfile can be found in '/dev/shm/mtr-11528/var-all_default_valgrind/log/innodb.log_file_name/log_file_name.log'

Retrying test innodb.log_file_name, attempt(2/3)...

Normalized o
===================================================================================================

http://pb2.no.oracle.com/?template=mysql_show_test_failure&test_failure_id=5512828
===================================================================================================
innodb.log_file_name                     w6 [ fail ]
        Test ended at 2014-07-12 23:18:32

CURRENT_TEST: innodb.log_file_name
mysqltest: At line 196: command "$mysqld --innodb-force-recovery=1" failed with wrong error: 134

The result from queries just before the failure was:
< snip >
347
33101
SHOW TABLES;
Tables_in_test
t2
t3
DROP TABLE t2,t3;
CREATE TABLE t0(a INT PRIMARY KEY) ENGINE=InnoDB;
ERROR HY000: Tablespace for table '`test`.`t0`' exists. Please DISCARD the tablespace before IMPORT.
CREATE TABLE t0(a INT PRIMARY KEY) ENGINE=InnoDB;
DROP TABLE t0;
CREATE TABLE u1(a INT PRIMARY KEY) ENGINE=InnoDB;
CREATE TABLE u2(a INT PRIMARY KEY) ENGINE=InnoDB;
CREATE TABLE u3(a INT PRIMARY KEY) ENGINE=InnoDB;
CREATE TABLE u4(a INT PRIMARY KEY) ENGINE=InnoDB;
INSERT INTO u4 VALUES(1);
RENAME TABLE u4 TO u5;
RENAME TABLE u5 TO u6;
INSERT INTO u6 VALUES(2);
# Fault 6: All-zero data file and innodb_force_recovery

 - the logfile can be found in '/ramdisk/mtr-4121/var-ps-debug/log/innodb.log_file_name/log_file_name.log'

Retrying test innodb.log_file_name, attempt(2/3)...

How to repeat:
This issue is seen on Pb2 on the following links. 

Also this issues has been observed starting from push

revno: 8360
revision-id: marko.makela@oracle.com-20140703081921-1zughv1o6fr7y6ou
parent: thirunarayanan.balathandayuth@oracle.com-20140703052803-bcm7juojy94j0rc0
committer: Marko Mkel <marko.makela@oracle.com>
branch nick: mysql-trunk
timestamp: Thu 2014-07-03 11:19:21 +0300
message:
  Bug#19145637 IMPROVE ERROR HANDLING ON CRASH RECOVERY
[13 Aug 2014 5:29] Marko Mäkelä
Posted by developer:
 
This does not seem to be a true regression.
MySQL 5.5 and 5.6 are triggering an assertion failure if renaming fails during crash recovery:

			if (!fil_rename_tablespace(name, space_id,
						   new_name, NULL)) {
				ut_error;
			}

MySQL 5.7 is only being slightly "nicer", doing exit() instead, occasionally triggering a debug assertion failure in an I/O handler thread.
[14 Aug 2014 6:08] Marko Mäkelä
Posted by developer:
 
The test still fails due to a more difficult-to-fix problem, I/O threads calling exit():
Bug#19442959 DO NOT CALL EXIT() FROM INNODB
[14 Aug 2014 15:00] Daniel Price
Posted by developer:
 
Fixed as of the upcoming 5.7.5 release, and here's the changelog entry:

On crash recovery, "InnoDB" would call "exit()" when encountering a
corruption or inconsistency. Some of the "exit()" calls have been removed
to allow "InnoDB" to shut down properly.
[15 Sep 2014 11:14] Marko Mäkelä
Posted by developer:
 
There was also a known problem with the test innodb.log_file_name.
The test would fail if the server performed a log checkpoint in the critical section. Due to this, the crash recovery would fail to detect the injected error. I revised the test so that it will be skipped when such extra checkpoints occur:

revno: 8838
revision-id: marko.makela@oracle.com-20140915064550-adxgndy0jijfhfk8
parent: marc.alff@oracle.com-20140913074337-zpcrnmo2w79c6u3t
committer: Marko Makela <marko.makela@oracle.com>
branch nick: mysql-trunk
timestamp: Mon 2014-09-15 09:45:50 +0300
message:
  WL#7142 test clean-up: Skip fault injection testing if needed.
[1 Apr 2015 4:41] Erlend Dahl
Bug#74164 innodb.log_file_name unstable on PB2 was marked as a duplicate.