MySQL Bugs: #45067: Assertion `stmt_da->is_error()' in Delayed_insert::open_and_lock

Bug #45067	Assertion `stmt_da->is_error()' in Delayed_insert::open_and_lock_table
Submitted:	25 May 2009 13:35	Modified:	6 Mar 2010 23:42
Reporter:	Philip Stoev	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S3 (Non-critical)
Version:	6.0, 5.4	OS:	Any
Assigned to:	Jon Olav Hauglid	CPU Architecture:	Any

Description:
When executing a random workload involving tables that act on table locking, the server asserted as follows:

mysqld: sql_class.h:2112: void THD::fatal_error(): Assertion `stmt_da->is_error()' failed.

# 16:10:41 #2  0x00000000006c9350 in handle_segfault (sig=6) at mysqld.cc:2711
# 16:10:41 #3  <signal handler called>
# 16:10:41 #4  0x000000315a432ed5 in raise () from /lib64/libc.so.6
# 16:10:41 #5  0x000000315a434a43 in abort () from /lib64/libc.so.6
# 16:10:41 #6  0x000000315a42bec9 in __assert_fail () from /lib64/libc.so.6
# 16:10:41 #7  0x00000000006e5f36 in THD::fatal_error (this=0x23e47f8) at sql_class.h:2112
# 16:10:41 #8  0x0000000000783874 in Delayed_insert::open_and_lock_table (this=0x23e47d8) at sql_insert.cc:2303
# 16:10:41 #9  0x00000000007869b1 in handle_delayed_insert (arg=0x23e47d8) at sql_insert.cc:2387
# 16:10:41 #10 0x000000315b0073da in start_thread () from /lib64/libpthread.so.0
# 16:10:41 #11 0x000000315a4e627d in clone () from /lib64/libc.so.6

This was in the log before the crash, may or may not be relevant:

Warning at 'read lock with old write lock': Found lock of type 6 that is write and read locked
Warning at 'start of release lock': Found lock of type 6 that is write and read locked
Warning at 'read lock with old write lock': Found lock of type 6 that is write and read locked
Warning at 'start of release lock': Found lock of type 6 that is write and read locked
Warning at 'read lock with old write lock': Found lock of type 6 that is write and read locked
Warning at 'got wait_for_lock': Found lock of type 6 that is write and read locked
Warning at 'enter read_lock': Found lock of type 6 that is write and read locked
Warning at 'read lock with old write lock': Found lock of type 6 that is write and read locked
Warning at 'start of release lock': Found lock of type 6 that is write and read locked
Warning at 'after releasing lock': Found lock of type 6 that is write and read locked

How to repeat:
If this is repeatable, a test case will be provided.

Grammar for bug 45067

Attachment: bug45067.yy (application/octet-stream, text), 2.19 KiB.

A grammar file has been uploaded for this bug. To reproduce, please run:

perl runall.pl --basedir=/build/bzr/azalea/ --grammar=conf/bug45067.yy  --mysqld=--innodb-lock-wait-timeout=1 --mysqld=--table-lock-wait-timeout=1

against a debug build.

Switch to 'Analyzing' + assign to me, because I will
come up with a testcase for MTR and results for MySQL 5.1 soon.
Preliminar results:
- 5.1 has the same bug
- only ALTER/ANALYZE/... + INSERT DELAYED + MyISAM +
  two concurrent sessions are needed
- partitioning, auto_increment, indexes are irrelevant

Test script

Attachment: bug45067.test (text/plain), 1.29 KiB.

File with expected results

Attachment: bug45067.result (text/plain), 44 bytes.

Results when applying bug45067.test:
=====================================
- MySQL releases compiled from source
  ./BUILD/compile-pentium64-debug-max
- Linux OpenSuSE 11.0 (64 Bit)
- Intel Core2Duo
- ./mtr --mem --force --max-test-fail=0 \
  --retry=0 --repeat=100 --do-test=bug45067

Azalea last modification 2009-06-23
-----------------------------------
- Failed 100/100 tests, 0.00% were successful.
  MTR analyzes 6 times a crashed server per 100 runs.
  This is a bit surprising but I guess MTR does not
  work 100 % perfect. Maybe in some cases MTR does not
  detect that we are short before completion of a
  server crash or somehow other important information
  gets lost and/or ignored.
  In a single run the likelihood that MTR analyzes a
  core file is significant higher.
  The frequent MTR messages
  Failed to read from '/.../mysql-test/var/log/bug45067.log'
      , errno: 22
  are suspicious.
- Typical output:
  mysqltest: At line 41: query 'reap' failed:
  2013: Lost connection to MySQL server during query
  or
  1053: Server shutdown in progress

mysal-5.1-bugteam last modification 2009-06-25
----------------------------------------------
- Failed 81/100 tests, 19.00% were successful.
MTR reports never about a core but I do not trust
MTR 100 %. Please see the effects mentioned above.
- typical output
  mysqltest: At line 41: query 'reap' failed:
  1053: Server shutdown in progres

Some comments about the importance of this bug
and the script bug45067.test:
----------------------------------------------
1. The goal of bug45067.test is to replay the
   problem with the
   - smallest number of statements
   - most simple statements
   for easy bug fixing and testing.
   bug45067.test like any test does not need to
   simulate the behavior of a typical customer
   application. So please do not focus on the
   100 loop rounds containing the ALTER TABLE.
2. My impression is that we could suffer from
   the current bug whenever we have some specific
   timing between the INSERT DELAYED and the ALTER.
   The 100 loops in bug45067.test are simply
   100 attempts to get by luck the specific
   timing needed.

Setting to "Needs Triage" because MySQL 5.1 is
also affected.
Please do not forget to decide if the fix should
start in 5.1.

See similar backtrace in bug#45949 .

See similar backtrace in bug#45949 .

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/79609

2834 Jon Olav Hauglid	2009-07-30
      Bug #45067 Assertion `stmt_da->is_error()' in 
                 Delayed_insert::open_and_lock_table
      
      The assert was triggered when delayed insert was killed by another 
      connection using mysql_notify_thread_having_shared_lock().
      During handling of thd->killed, thd.fatal_error() was called without
      a previous call to my_error() which triggered the assert.
      This patch allows the assert to pass if thd->killed has been set.
      
      Test case will be added as a part of the patch for the closely 
      related bug #45949.

Pushed to azalea-bugfixing

Pushed into 5.4.4-alpha (revid:alik@sun.com-20090804194615-h40sa098mx4z49qg) (version source revid:iggy@mysql.com-20090731204544-7nio1afvg0dmzs7g) (merge vers: 5.4.4-alpha) (pib:11)

Noted in 5.4.4 changelog.

Killing a delayed-insert thread could cause a server crash.

Noted in 5.4.2 changelog because next 5.4 version will be 5.4.2 and not 5.4.4.

Ignore previous comment about 5.4.2.

Pushed to mysql-next-4284 (5.6.0-beta).

Bug#49974 marked as a duplicate of this bug.

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100216101445-2ofzkh48aq2e0e8o) (version source revid:kostja@sun.com-20091211154405-c9yhiewr9o5d20rq) (merge vers: 6.0.14-alpha) (pib:16)

Pushed into mysql-next-mr (revid:alik@sun.com-20100216101208-33qkfwdr0tep3pf2) (version source revid:jon.hauglid@sun.com-20091208143858-mjvvybtbhzg93j3t) (pib:16)

Noted in 6.0.14 changelog.

Setting report to Need Merge pending push of Celosia into release tree.

Pushed into 5.5.3-m3 (revid:alik@sun.com-20100306103849-hha31z2enhh7jwt3) (version source revid:vvaintroub@mysql.com-20100216221947-luyhph0txl2c5tc8) (merge vers: 5.5.99-m3) (pib:16)

Noted in 5.5.3 changelog.