Bug #78050 Crash on when XA functions activated by a storage engine
Submitted: 13 Aug 2015 7:29 Modified: 13 Aug 2015 12:02
Reporter: Zhenye Xie (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Storage Engine API Severity:S3 (Non-critical)
Version:5.6.26 OS:Linux
Assigned to: CPU Architecture:Any
Tags: crash, tc.log, xa

[13 Aug 2015 7:29] Zhenye Xie
Description:
When the XA support functions are enabled by a storage engine and binlog is not enabled, MySQL crashes on startup or shutdown

startup:
(gdb) bt
#0  TC_LOG_MMAP::recover (this=0x1317920) at /home/xzy/mysql-5.6.26-src/sql/log.cc:2910
#1  0x000000000064fe88 in TC_LOG_MMAP::open (this=0x1317920, opt_name=<value optimized out>) at /home/xzy/mysql-5.6.26-src/sql/log.cc:2565
#2  0x000000000059c0c8 in init_server_components () at /home/xzy/mysql-5.6.26-src/sql/mysqld.cc:4962
#3  0x00000000005a0d75 in mysqld_main (argc=23, argv=0x13682a0) at /home/xzy/mysql-5.6.26-src/sql/mysqld.cc:5446
#4  0x0000003748e1ed5d in __libc_start_main () from /lib64/libc.so.6
#5  0x00000000005930b9 in _start ()

shutdown:
(gdb) bt
#0  0x0000000000652adb in TC_LOG_MMAP::log_xid (this=0x1317920, thd=<value optimized out>, xid=16) at /home/xzy/mysql-5.6.26-src/sql/log.cc:2744
#1  0x0000000000652fbb in TC_LOG_MMAP::commit (this=<value optimized out>, thd=0x4c213e0, all=true) at /home/xzy/mysql-5.6.26-src/sql/log.cc:2677
#2  0x00000000006acb4e in THD::cleanup (this=0x4c213e0) at /home/xzy/mysql-5.6.26-src/sql/sql_class.cc:1535
#3  0x00000000006acd48 in THD::release_resources (this=0x4c213e0) at /home/xzy/mysql-5.6.26-src/sql/sql_class.cc:1580
#4  0x00000000005994dc in one_thread_per_connection_end (thd=0x4c213e0, block_pthread=true) at /home/xzy/mysql-5.6.26-src/sql/mysqld.cc:2751
#5  0x00000000006af863 in do_handle_one_connection (thd_arg=<value optimized out>) at /home/xzy/mysql-5.6.26-src/sql/sql_connect.cc:989
#6  0x00000000006af957 in handle_one_connection (arg=<value optimized out>) at /home/xzy/mysql-5.6.26-src/sql/sql_connect.cc:898
#7  0x000000000090b3ea in pfs_spawn_thread (arg=0x4cdf1d0) at /home/xzy/mysql-5.6.26-src/storage/perfschema/pfs.cc:1860
#8  0x0000003749207a51 in start_thread () from /lib64/libpthread.so.0
#9  0x0000003748ee89ad in clone () from /lib64/libc.so.6

this bug is already reported as http://bugs.mysql.com/bug.php?id=47134

bug the fix is not correct.

How to repeat:
see also: http://bugs.mysql.com/bug.php?id=47134

or with my migerated spider engine https://github.com/xiezhenye/mysql-plugin-spider-engine

with
log_bin=off
spider_support_xa=on
spider_internal_xa=off

Suggested fix:
this bug seems fixed in 5.7 branch, but still exists in 5.6 branch

my patch:

*** log.cc.old	2015-08-13 12:29:56.266711505 +0800
--- log.cc	2015-08-13 14:14:59.468927153 +0800
*************** int TC_LOG_MMAP::open(const char *opt_na
*** 2553,2564 ****
      mysql_mutex_init(key_PAGE_lock, &pg->lock, MY_MUTEX_INIT_FAST);
      mysql_cond_init(key_PAGE_cond, &pg->cond, 0);
      pg->start=(my_xid *)(data + i*tc_log_page_size);
!     pg->end=(my_xid *)(pg->start + tc_log_page_size);
      pg->size=pg->free=tc_log_page_size/sizeof(my_xid);
    }
    pages[0].size=pages[0].free=
                  (tc_log_page_size-TC_LOG_HEADER_SIZE)/sizeof(my_xid);
    pages[0].start=pages[0].end-pages[0].size;
    pages[npages-1].next=0;
    inited=4;
  
--- 2553,2566 ----
      mysql_mutex_init(key_PAGE_lock, &pg->lock, MY_MUTEX_INIT_FAST);
      mysql_cond_init(key_PAGE_cond, &pg->cond, 0);
      pg->start=(my_xid *)(data + i*tc_log_page_size);
!     pg->ptr=pg->start;
      pg->size=pg->free=tc_log_page_size/sizeof(my_xid);
+     pg->end=pg->start + pg->size;
    }
    pages[0].size=pages[0].free=
                  (tc_log_page_size-TC_LOG_HEADER_SIZE)/sizeof(my_xid);
    pages[0].start=pages[0].end-pages[0].size;
+   pages[0].ptr=pages[0].start;
    pages[npages-1].next=0;
    inited=4;
  
*************** int TC_LOG_MMAP::sync()
*** 2815,2821 ****
    /* marking 'syncing' slot free */
    mysql_mutex_lock(&LOCK_sync);
    syncing=0;
!   mysql_cond_signal(&active->cond);        // wake up a new syncer
    mysql_mutex_unlock(&LOCK_sync);
    return err;
  }
--- 2817,2826 ----
    /* marking 'syncing' slot free */
    mysql_mutex_lock(&LOCK_sync);
    syncing=0;
!   if (active)
!   {
!       mysql_cond_signal(&active->cond);        // wake up a new syncer
!   }
    mysql_mutex_unlock(&LOCK_sync);
    return err;
  }
[13 Aug 2015 12:02] MySQL Verification Team
Hello Zhenye Xie,

Thank you for the report.
Verified as described.

Thanks,
Umesh
[13 Aug 2015 12:04] MySQL Verification Team
test results

Attachment: 78050.results (application/octet-stream, text), 8.53 KiB.

[13 Aug 2015 12:07] MySQL Verification Team
In order to submit contributions you must first sign the Oracle Contribution Agreement (OCA). For additional information please check http://www.oracle.com/technetwork/community/oca-486395.html.
If you have any questions, please contact the MySQL community team.
[14 Dec 2016 4:54] zkong kong
@@ -2839,7 +2841,7 @@ TC_LOG::enum_result TC_LOG_MMAP::commit(THD *thd, bool all)
   my_xid xid= thd->transaction.xid_state.xid.get_my_xid();

   if (all && xid)
-    if ((cookie= log_xid(thd, xid)))
+    if (!(cookie= log_xid(thd, xid)))
       DBUG_RETURN(RESULT_ABORTED);    // Failed to log the transaction