[MDEV-22488] test failures: parts.partition_debug_innodb / parts.partition_debug_myisam introduced at 8399af81be0a87d1c0ea09164c05a9ac8eb715e2 Created: 2020-05-06  Updated: 2020-05-09  Resolved: 2020-05-09

Status: Closed
Project: MariaDB Server
Component/s: Partitioning
Affects Version/s: 10.5
Fix Version/s: 10.5.3

Type: Bug Priority: Major
Reporter: Daniel Black Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: None
Environment:

ppc64le

Attachments: Text File gdb.txt     File parts.partition_debug_innodb.tar.bz2     File parts.partition_debug_myisam.tar.bz2    

 Description   

Per buildbot.askmonty.org/buildbot/builders/bld-p9-rhel7/builds/3364 and others, the debug builds.

Entirely repeatable:

0126169e08c (commit before failure) is successful for both tests

https://github.com/MariaDB/server/commit/8399af81be0a87d1c0ea09164c05a9ac8eb715e2 introduces the failure.

Reverting the commit at the current 10.5 is clean and allows these tests to pass.

Innodb gets different table identifiers in the recovery log. Further into the test the difference in ids in tablespace vs recovery log continue to differ.

parts.partition_debug_innodb

 
parts.partition_debug_innodb 'innodb'    [ fail ]
 
        Test ended at 2020-05-06 19:05:18
 
 
 
CURRENT_TEST: parts.partition_debug_innodb
 
mysqltest: In included file "./suite/parts/inc/partition_fail.inc": 
included from ./suite/parts/inc/partition_fail_add.inc at line 28:
 
included from ./suite/parts/inc/partition_mgm_crash.inc at line 25:
 
included from /home/ozlabs/mariadb-server-10.5/mysql-test/suite/parts/t/partition_debug_innodb.test at line 66:
 
At line 17: query 'SHOW CREATE TABLE t1' failed: 2002: Can't connect to local MySQL server through socket '/home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/tmp/' (111)
 
 
 
The result from queries just before the failure was:
 
< snip >
 
a	b
 
1	Original from partition p0
 
11	Original from partition p1
 
12	Original from partition p1
 
13	Original from partition p1
 
14	Original from partition p1
 
2	Original from partition p0
 
3	Original from partition p0
 
4	Original from partition p0
 
ALTER TABLE t1 ADD PARTITION
 
(PARTITION p20 VALUES IN (20,21,22,23,24,25,26,27,28,29));
 
ERROR HY000: Lost connection to MySQL server during query
 
# State after failure
 
db.opt
 
t1#P#p0.ibd
 
t1#P#p10.ibd
 
t1#P#p20.ibd
 
t1.frm
 
t1.par
 
SHOW CREATE TABLE t1;
 
 
 
More results from queries before failure can be found in /home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/log/partition_debug_innodb.log
 
 
 
 
 
Server [mysqld.1 - pid: 21909, winpid: 21909, exit: 256] failed during test run
 
Server log from this test:
 
----------SERVER LOG START-----------
 
2020-05-06 19:05:06 0 [Note] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd (mysqld 10.5.3-MariaDB-debug-log) starting as process 21723 ...
 
2020-05-06 19:05:06 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32194)
 
2020-05-06 19:05:06 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
 
2020-05-06 19:05:06 0 [Note] Plugin 'SEQUENCE' is disabled.
 
2020-05-06 19:05:06 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
 
2020-05-06 19:05:06 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2020-05-06 19:05:06 0 [Note] InnoDB: Uses event mutexes
 
2020-05-06 19:05:06 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
 
2020-05-06 19:05:06 0 [Note] InnoDB: Number of pools: 1
 
2020-05-06 19:05:06 0 [Note] InnoDB: Using POWER8 crc32 instructions
 
2020-05-06 19:05:06 0 [Note] mariadbd: O_TMPFILE is not supported on /home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/tmp/mysqld.1 (disabling future attempts)
 
2020-05-06 19:05:06 0 [Note] InnoDB: Initializing buffer pool, total size = 33554432, chunk size = 33554432
 
2020-05-06 19:05:06 0 [Note] InnoDB: Completed initialization of buffer pool
 
2020-05-06 19:05:06 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2020-05-06 19:05:06 0 [Note] InnoDB: 128 rollback segments are active.
 
2020-05-06 19:05:06 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2020-05-06 19:05:06 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2020-05-06 19:05:06 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2020-05-06 19:05:06 0 [Note] InnoDB: 10.5.3 started; log sequence number 47785; transaction id 28
 
2020-05-06 19:05:06 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/var_auto_V637/mysqld.1/data/ib_buffer_pool
 
2020-05-06 19:05:06 0 [Warning] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd: unknown option '--loose-pam-debug'
 
2020-05-06 19:05:06 0 [Warning] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd: unknown option '--loose-aria'
 
2020-05-06 19:05:06 0 [Note] InnoDB: Buffer pool(s) load completed at 200506 19:05:06
 
2020-05-06 19:05:06 0 [Note] Server socket created on IP: '127.0.0.1'.
 
2020-05-06 19:05:06 0 [Note] Reading of all Master_info entries succeeded
 
2020-05-06 19:05:06 0 [Note] Added new Master_info '' to hash table
 
2020-05-06 19:05:06 0 [Note] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd: ready for connections.
 
Version: '10.5.3-MariaDB-debug-log'  socket: '/home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
 
SIGKILL myself
 
2020-05-06 19:05:06 0 [Note] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd (mysqld 10.5.3-MariaDB-debug-log) starting as process 21744 ...
 
2020-05-06 19:05:06 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32194)
 
2020-05-06 19:05:06 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
 
2020-05-06 19:05:06 0 [Note] Plugin 'SEQUENCE' is disabled.
 
2020-05-06 19:05:06 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
 
2020-05-06 19:05:06 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2020-05-06 19:05:06 0 [Note] InnoDB: Uses event mutexes
 
2020-05-06 19:05:06 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
 
2020-05-06 19:05:06 0 [Note] InnoDB: Number of pools: 1
 
2020-05-06 19:05:06 0 [Note] InnoDB: Using POWER8 crc32 instructions
 
2020-05-06 19:05:06 0 [Note] mariadbd: O_TMPFILE is not supported on /home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/tmp/mysqld.1 (disabling future attempts)
 
2020-05-06 19:05:06 0 [Note] InnoDB: Initializing buffer pool, total size = 33554432, chunk size = 33554432
 
2020-05-06 19:05:06 0 [Note] InnoDB: Completed initialization of buffer pool
 
2020-05-06 19:05:06 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2020-05-06 19:05:06 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=47785
 
2020-05-06 19:05:06 0 [Note] InnoDB: Starting final batch to recover 13 pages from redo log.
 
2020-05-06 19:05:06 0 [Note] InnoDB: 128 rollback segments are active.
 
2020-05-06 19:05:06 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2020-05-06 19:05:06 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2020-05-06 19:05:06 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2020-05-06 19:05:06 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2020-05-06 19:05:06 0 [Note] InnoDB: 10.5.3 started; log sequence number 50718; transaction id 36
 
2020-05-06 19:05:06 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/var_auto_V637/mysqld.1/data/ib_buffer_pool
 
2020-05-06 19:05:06 0 [Note] Plugin 'unix_socket' is disabled.
 
2020-05-06 19:05:06 0 [Warning] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd: unknown option '--loose-pam-debug'
 
2020-05-06 19:05:06 0 [Warning] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd: unknown option '--loose-aria'
 
2020-05-06 19:05:06 0 [Note] InnoDB: Buffer pool(s) load completed at 200506 19:05:06
 
2020-05-06 19:05:06 0 [Note] Server socket created on IP: '127.0.0.1'.
 
2020-05-06 19:05:06 0 [Note] Reading of all Master_info entries succeeded
 
2020-05-06 19:05:06 0 [Note] Added new Master_info '' to hash table
 
2020-05-06 19:05:06 0 [Note] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd: ready for connections.
 
Version: '10.5.3-MariaDB-debug-log'  socket: '/home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
 
 
 
SIGKILL myself
 
2020-05-06 19:05:07 0 [Note] /home/ozlabs/build-mariadb-server-10.5-debug/sql/mariadbd (mysqld 10.5.3-MariaDB-debug-log) starting as process 21762 
.....
 
 
 
2020-05-06 19:05:07 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=47785
 
2020-05-06 19:05:07 0 [Note] InnoDB: Ignoring data file './test/t1#P#p0.ibd' with space ID 7, since the redo log references ./test/t1#P#p0.ibd with space ID 5.
 
2020-05-06 19:05:07 0 [Note] InnoDB: Ignoring data file './test/t1#P#p10.ibd' with space ID 8, since the redo log references ./test/t1#P#p10.ibd with space ID 6.
 
2020-05-06 19:05:07 0 [Note] InnoDB: Starting final batch to recover 15 pages from redo log.

parts.partition_debug_myisam

 
parts.partition_debug_myisam             [ fail ]
 
        Test ended at 2020-05-06 19:12:40
 
 
 
CURRENT_TEST: parts.partition_debug_myisam
 
mysqltest: In included file "./suite/parts/inc/partition_fail.inc": 
included from ./suite/parts/inc/partition_fail_add.inc at line 28:
 
included from ./suite/parts/inc/partition_mgm_crash.inc at line 25:
 
included from /home/ozlabs/mariadb-server-10.5/mysql-test/suite/parts/t/partition_debug_myisam.test at line 15:
 
At line 17: query 'SHOW CREATE TABLE t1' failed: 2002: Can't connect to local MySQL server through socket '/home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/tmp/' (111)
 
 
 
The result from queries just before the failure was:
 
< snip >
 
12	Original from partition p1
 
13	Original from partition p1
 
14	Original from partition p1
 
2	Original from partition p0
 
3	Original from partition p0
 
4	Original from partition p0
 
ALTER TABLE t1 ADD PARTITION
 
(PARTITION p20 VALUES IN (20,21,22,23,24,25,26,27,28,29));
 
ERROR HY000: Lost connection to MySQL server during query
 
# State after failure
 
db.opt
 
t1#P#p0.MYD
 
t1#P#p0.MYI
 
t1#P#p10.MYD
 
t1#P#p10.MYI
 
t1#P#p20.MYD
 
t1#P#p20.MYI
 
t1.frm
 
t1.par
 
SHOW CREATE TABLE t1;
 
 
 
More results from queries before failure can be found in /home/ozlabs/build-mariadb-server-10.5-debug/mysql-test/var/log/partition_debug_myisam.log

Nothing Aria specific was in the server logs.

 Comments   
Comment by Marko Mäkelä [ 2020-05-07 ]

The InnoDB messages about ignoring files are nothing to worry about. They indicate that the crash recovery logic to detect renamed files is working correctly.

I tried and failed to reproduce this failure in my local environment (Debian unstable, clang 10, CMAKE_BUILD_TYPE=Debug with -O2, both values of WITH_ASAN).
The failure also occurs rather often on amd64, on the kvm-fulltest2 builder. Here is an example: http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/22114

Comment by Daniel Black [ 2020-05-09 ]

segfault

 
Program received signal SIGSEGV, Segmentation fault.
 
[Switching to Thread 0x3fffb12b8050 (LWP 22077)]
 
0x00003fffb7726d68 in __strnlen_power7 () from /lib64/libc.so.6
 
(gdb) bt
 
#0  0x00003fffb7726d68 in __strnlen_power7 () from /lib64/libc.so.6
 
#1  0x0000000101b033b0 in process_str_arg (
 
    cs=0x10276b2b0 <my_charset_utf8mb3_general_ci>, to=0x3fffb12b2ad4 "\377?", 
    end=0x3fffb12b2c77 "", width=65535, par=0x2 <Address 0x2 out of bounds>, 
    print_type=0)
 
    at /home/ozlabs/mariadb-server-10.5/strings/my_vsnprintf.c:235
 
#2  0x0000000101b050b8 in my_vsnprintf_ex (
 
    cs=0x10276b2b0 <my_charset_utf8mb3_general_ci>, to=0x3fffb12b2ad4 "\377?", 
    n=512, fmt=0x101df2b2c "s", ap=0x3fffb12b2ce0 "")
 
    at /home/ozlabs/mariadb-server-10.5/strings/my_vsnprintf.c:682
 
#3  0x00000001008d217c in push_warning_printf (thd=0x3fffa0000b18, 
    level=Sql_state_errno_level::WARN_LEVEL_WARN, code=1, 
    format=0x101df2b28 "%s %s")
 
    at /home/ozlabs/mariadb-server-10.5/sql/sql_error.cc:748
 
#4  0x000000010109d6a0 in handle_alter_part_error (lpt=0x3fffb12b3150, 
    action_completed=true, drop_partition=false, frm_install=false)
 
    at /home/ozlabs/mariadb-server-10.5/sql/sql_partition.cc:6975
 
#5  0x000000010109e738 in fast_alter_partition_table (thd=0x3fffa0000b18, 
    table=0x3fffa0104d18, alter_info=0x3fffb12b58e8, 
    create_info=0x3fffb12b59b8, table_list=0x3fffa0016188, db=0x3fffb12b4d88, 
    table_name=0x3fffb12b4d98)
 
    at /home/ozlabs/mariadb-server-10.5/sql/sql_partition.cc:7296
 
#6  0x0000000100a88960 in mysql_alter_table (thd=0x3fffa0000b18, 
---Type <return> to continue, or q <return> to quit---
 
    new_db=0x3fffa00053d0, new_name=0x3fffa00057d8, 
    create_info=0x3fffb12b59b8, table_list=0x3fffa0016188, 
    alter_info=0x3fffb12b58e8, order_num=0, order=0x0, ignore=false, 
    if_exists=false) at /home/ozlabs/mariadb-server-10.5/sql/sql_table.cc:10202
 
#7  0x0000000100b65ae4 in Sql_cmd_alter_table::execute (this=0x3fffa0017858, 
    thd=0x3fffa0000b18)
 
    at /home/ozlabs/mariadb-server-10.5/sql/sql_alter.cc:538
 
#8  0x0000000100952af8 in mysql_execute_command (thd=0x3fffa0000b18)
 
    at /home/ozlabs/mariadb-server-10.5/sql/sql_parse.cc:5912
 
#9  0x0000000100959bc0 in mysql_parse (thd=0x3fffa0000b18, 
    rawbuf=0x3fffa0016030 "ALTER TABLE t1 ADD PARTITION\n(PARTITION p20 VALUES IN (20,21,22,23,24,25,26,27,28,29))", length=86, parser_state=0x3fffb12b6c00, 
    is_com_multi=false, is_next_command=false)
 
    at /home/ozlabs/mariadb-server-10.5/sql/sql_parse.cc:7957
 
#10 0x0000000100943e40 in dispatch_command (command=COM_QUERY, 
    thd=0x3fffa0000b18, 
    packet=0x3fffa0008919 "ALTER TABLE t1 ADD PARTITION\n(PARTITION p20 VALUES IN (20,21,22,23,24,25,26,27,28,29))", packet_length=86, is_com_multi=false, 
    is_next_command=false)
 
    at /home/ozlabs/mariadb-server-10.5/sql/sql_parse.cc:1840
 
#11 0x0000000100942390 in do_command (thd=0x3fffa0000b18)
 
    at /home/ozlabs/mariadb-server-10.5/sql/sql_parse.cc:1359
 
#12 0x0000000100b57e10 in do_handle_one_connection (connect=0x10361e678, 
---Type <return> to continue, or q <return> to quit---
 
    put_in_cache=true)
 
    at /home/ozlabs/mariadb-server-10.5/sql/sql_connect.cc:1411
 
#13 0x0000000100b57a3c in handle_one_connection (arg=0x10361e678)
 
    at /home/ozlabs/mariadb-server-10.5/sql/sql_connect.cc:1313
 
#14 0x00000001012a5ccc in pfs_spawn_thread (arg=0x103642e58)
 
    at /home/ozlabs/mariadb-server-10.5/storage/perfschema/pfs.cc:2201
 
#15 0x00003fffb7f48cd4 in start_thread () from /lib64/libpthread.so.0
 
#16 0x00003fffb7797e94 in clone () from /lib64/libc.so.6

Comment by Daniel Black [ 2020-05-09 ]

pr as github not syncing again https://github.com/MariaDB/server/pull/1530

Comment by Michael Widenius [ 2020-05-09 ]

The reason for the failure was a wrong printf() that accessed not existing things on the stack.
The reason it was hard to find was that the partition_debug.. test disables core dumps,
so there was no trace that the server had crashed in the logs.

Fixed by fixing the printf and splitting the test into two parts, one that test failures (with core dumps enabled) and one part that test crash recovery.

Comment by Michael Widenius [ 2020-05-09 ]

Pushed into 10.5

Generated at Thu Feb 08 09:15:06 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.