sql/handler.cc:3008: int handler::ha_close(): Assertion `m_lock_type == 2' failed.

[Roel Van de Paar]

2017-11-22T03:58:50.683393Z 0 [Note] /sda/PS240817-percona-server-5.7.19-17-linux-x86_64-debug/bin/mysqld: ready for connections.
Version: '5.7.19-17-debug-log' socket: '/sda/PS240817-percona-server-5.7.19-17-linux-x86_64-debug/mysql-test/var/tmp/mysqld.1.sock' port: 13001 MySQL Community Server (GPL)
2017-11-22T03:58:50.683407Z 0 [Note] Executing 'SELECT * FROM INFORMATION_SCHEMA.TABLES;' to get a list of tables using the deprecated partition engine. You may use the startup option '--disable-partition-engine-check' to skip this check.
2017-11-22T03:58:50.683421Z 0 [Note] Beginning of list of non-natively partitioned tables
2017-11-22T03:58:50.716538Z 0 [Note] End of list of non-natively partitioned tables
mysqld: /git/PS-5.7.19_dbg/sql/handler.cc:3008: int handler::ha_close(): Assertion `m_lock_type == 2' failed.
03:58:51 UTC - mysqld got signal 6 ;

Thread 1 (Thread 0x7ff3e8059700 (LWP 8566)):
#0 0x00007ff3f2ce99b1 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#1 0x0000000001862e06 in my_write_core (sig=6) at /git/PS-5.7.19_dbg/mysys/stacktrace.c:249
#2 0x0000000000e8a2af in handle_fatal_signal (sig=6) at /git/PS-5.7.19_dbg/sql/signal_handler.cc:223
#3 <signal handler called>
#4 0x00007ff3f10011f7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#5 0x00007ff3f10028e8 in __GI_abort () at abort.c:90
#6 0x00007ff3f0ffa266 in __assert_fail_base (fmt=0x7ff3f114ce68 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x1dd988f "m_lock_type == 2", file=file@entry=0x1dda1f0 "/git/PS-5.7.19_dbg/sql/handler.cc", line=line@entry=3008, function=function@entry=0x1ddd5e0 <handler::ha_close()::__PRETTY_FUNCTION__> "int handler::ha_close()") at assert.c:92
#7 0x00007ff3f0ffa312 in __GI___assert_fail (assertion=0x1dd988f "m_lock_type == 2", file=0x1dda1f0 "/git/PS-5.7.19_dbg/sql/handler.cc", line=3008, function=0x1ddd5e0 <handler::ha_close()::__PRETTY_FUNCTION__> "int handler::ha_close()") at assert.c:101
#8 0x0000000000f1ba53 in handler::ha_close (this=0x7ff348791d70) at /git/PS-5.7.19_dbg/sql/handler.cc:3008
#9 0x0000000001623017 in closefrm (table=0x7ff34813d130, free_share=false) at /git/PS-5.7.19_dbg/sql/table.cc:3572
#10 0x000000000149efb1 in close_temporary (table=0x7ff34813d130, free_share=true, delete_table=true) at /git/PS-5.7.19_dbg/sql/sql_base.cc:2534
#11 0x000000000149dfe2 in close_temporary_tables (thd=0x7ff3480ed0a0) at /git/PS-5.7.19_dbg/sql/sql_base.cc:2066
#12 0x0000000001793a8c in Start_log_event_v3::do_apply_event (this=0x7ff34812d880, rli=0x7ff348489df0) at /git/PS-5.7.19_dbg/sql/log_event.cc:5301
#13 0x0000000001794762 in Format_description_log_event::do_apply_event (this=0x7ff34812d840, rli=0x7ff348489df0) at /git/PS-5.7.19_dbg/sql/log_event.cc:5542
#14 0x000000000178e02f in Log_event::apply_event (this=0x7ff34812d880, rli=0x7ff348489df0) at /git/PS-5.7.19_dbg/sql/log_event.cc:3447
#15 0x00000000017e12a7 in mysql_client_binlog_statement (thd=0x7ff3480ed0a0) at /git/PS-5.7.19_dbg/sql/sql_binlog.cc:275
#16 0x0000000001530328 in mysql_execute_command (thd=0x7ff3480ed0a0, first_level=true) at /git/PS-5.7.19_dbg/sql/sql_parse.cc:5076
#17 0x0000000001532408 in mysql_parse (thd=0x7ff3480ed0a0, parser_state=0x7ff3e80584e0) at /git/PS-5.7.19_dbg/sql/sql_parse.cc:5891
#18 0x0000000001526fe7 in dispatch_command (thd=0x7ff3480ed0a0, com_data=0x7ff3e8058c90, command=COM_QUERY) at /git/PS-5.7.19_dbg/sql/sql_parse.cc:1493
#19 0x0000000001525e2d in do_command (thd=0x7ff3480ed0a0) at /git/PS-5.7.19_dbg/sql/sql_parse.cc:1021
#20 0x000000000166583a in handle_connection (arg=0x5150030) at /git/PS-5.7.19_dbg/sql/conn_handler/connection_handler_per_thread.cc:312
#21 0x00000000018919e5 in pfs_spawn_thread (arg=0x5176600) at /git/PS-5.7.19_dbg/storage/perfschema/pfs.cc:2188
#22 0x00007ff3f2ce4e25 in start_thread (arg=0x7ff3e8059700) at pthread_create.c:308
#23 0x00007ff3f10c434d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

To reproduce;
cd $basedir
patch -p0 < MYR-174.diff
cd mysql-test
./mtr --mysqld=--server-id=0 --mysqld=--log-bin --force --retry=0 --retry-failure=0 --max-test-fail=0 --no-warnings --testcase-timeout=600 --suite=engines --repeat=1 --parallel=1 MYR-174

Also see;
https://jira.percona.com/browse/MYR-174
https://bugs.launchpad.net/percona-server/+bug/1382749
https://bugs.mysql.com/bug.php?id=74436
https://bugs.mysql.com/bug.php?id=74291

However, this may be a different bug.

This testcase does NOT reproduce on MS 5.7.19.

[Laurynas Biveinis (laurynas-biveinis)]

Reduced testcase, start with --server-id=0:

--source include/have_log_bin.inc

create temporary table t4(f int);
LOCK TABLES t4 WRITE;
BINLOG ' SOgWTg8BAAAAbgAAAHIAAAAAAAQANS42LjMtbTUtZGVidWctbG9nAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAABI6BZOEzgNAAgAEgAEBAQEEgAAVgAEGggAAAAICAgCAAAAAAVAYI8=';

UNLOCK TABLES;
DROP TABLE t4;

[Laurynas Biveinis (laurynas-biveinis)]

This is basically upstream [1], whose fix we did not fully adapt due to our code changes due to fix of bug 1953904 / https://bugs.mysql.com/bug.php?id=83003

[1]

d46c1c50885f39e204ea589cd472a67e4b81013e
Author: Dyre Tjeldvoll <email address hidden>
AuthorDate: Fri Jan 23 10:36:58 2015 +0100
Commit: Dyre Tjeldvoll <email address hidden>
CommitDate: Wed Jan 28 09:40:41 2015 +0100

Parent: 29e683ff841 Disbaled testcases which are failing due to Bug#20415775, BUG#20427694.
Containing: 5.7 8.0 binlog_no_sync_before_close bug1540338-5.7 bug1553883 bug1583589-5.7 bug1618718-5.7 (35 more)
Follows: mysql-5.7.5 (1751)
Precedes: mysql-5.7.6 (474)

BUG#19894987: HANDLE_FATAL_SIGNAL (SIG=11) IN HA_INDEX_OR_RND_END | SQL/HANDLER.H:1999

Execution of certain BINLOG statements while having temporary tables
open by HANDLER statements caused server crash.

Execution of BINLOG statements for Start/Format_description events
may close the connection's temporary tables. If a handler had been associated
with a temporary table, the BINLOG statement's call to close_temporary_tables()
would result in dangling pointers to the now freed TABLE in
thd->handler_table_hash. Similarly, a dangling pointer would also be left if
there was a lock on the temporary table. Running with valgrind showed that
freed memory was being accessed.

Solution: Properly close handlers and remove locks associated with temporary
tables being closed by the BINLOG statement.

[Laurynas Biveinis (laurynas-biveinis)]

There are two server-ids in the testcase: the one server was started with and the one in the binlog event. Setting the latter to zero is sufficient to reproduce, and also crashes 5.6 too (which otherwise resets passed --server-id=0 to 1)

[Laurynas Biveinis (laurynas-biveinis)]

The 5.6 counterpart of the upstream bug is

commit d585a4ab3c1bf58b943d3ffb84afeee584a29756
Author: Dyre Tjeldvoll <email address hidden>
Date: Fri Jan 23 10:36:58 2015 +0100

    BUG#19894987: HANDLE_FATAL_SIGNAL (SIG=11) IN HA_INDEX_OR_RND_END | SQL/HANDLER.H:1999

    Execution of certain BINLOG statements while having temporary tables
    open by HANDLER statements caused server crash.

    Execution of BINLOG statements for Start/Format_description events
    may close the connection's temporary tables. If a handler had been associated
    with a temporary table, the BINLOG statement's call to close_temporary_tables()
    would result in dangling pointers to the now freed TABLE in
    thd->handler_table_hash. Similarly, a dangling pointer would also be left if
    there was a lock on the temporary table. Running with valgrind showed that
    freed memory was being accessed.

    Solution: Properly close handlers and remove locks associated with temporary
    tables being closed by the BINLOG statement.

    (cherry picked from commit 11507ffa1df94c1d4df78f3b9b9d4de591ebc43e)

    Conflicts:
            sql/sql_base.cc

    Changes to a GTID related comment. Retained the version from 5.6.

[Laurynas Biveinis (laurynas-biveinis)]

    https://github.com/percona/percona-server/pull/2091
    https://github.com/percona/percona-server/pull/2092
    https://github.com/percona/percona-server/pull/2083

[Shahriyar Rzayev (rzayev-sehriyar)]

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