[MDEV-10259] mysqld crash with certain statement length and order with Galera and encrypt-tmp-files=1 Created: 2016-06-20  Updated: 2020-08-25  Resolved: 2018-05-22

Status: Closed
Project: MariaDB Server
Component/s: Galera
Affects Version/s: 10.1.14, 10.1.19
Fix Version/s: 10.1.34, 10.2.16, 10.3.8

Type: Bug Priority: Critical
Reporter: Jim Lamb Assignee: Sachin Setiya (Inactive)
Resolution: Fixed Votes: 2
Labels: None
Environment:

Red Hat Enterprise Linux Server release 6.8 (Santiago)
Linux hostname 2.6.32-573.12.1.el6.x86_64 #1 SMP Mon Nov 23 12:55:32 EST 2015 x86_64 x86_64 x86_64 GNU/Linux

RPMs all installed via yum from http://yum.mariadb.org/10.1/rhel6-amd64:
MariaDB-client-10.1.14-1.el6.x86_64
MariaDB-common-10.1.14-1.el6.x86_64
MariaDB-compat-10.1.14-1.el6.x86_64
MariaDB-server-10.1.14-1.el6.x86_64
galera-25.3.15-1.rhel6.el6.x86_64

Running on VMware ESX
3 dedicated DB hosts per cluster each with 4GB RAM.


Attachments: File crash1b4-reordered.sql     File crash1b4.sql     File my.cnf     Text File mysql-error.log    
Issue Links:
Blocks
blocks MDEV-14868 MariaDB server crashes after using RO... Closed
Relates
relates to MDEV-10391 During async GTID replication Galera ... Closed
Sprint: 10.2.4-1, 10.2.12, 10.1.31, 10.2.13, 10.1.32

 Description   

We are running a three-node Galera cluster in both production and preproduction. We recently added data-at-rest encryption to our preproduction cluster. We then found that our standard task to mysqldump production data and load it into preproduction was causing mysqld to crash on the node that was performing the import. The error log showed:

2016-06-20 15:57:33 140415040076544 [ERROR] mysqld: Error writing file '/apps/data/mysqld/mysql-bin' (errno: 0 "Internal error/check (Not system error)")
2016-06-20 15:57:33 140415040076544 [ERROR] WSREP: FSM: no such a transition COMMITTING -> ROLLED_BACK
160620 15:57:33 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Server version: 10.1.14-MariaDBkey_buffer_size=33554432read_buffer_size=131072
max_used_connections=1
max_threads=502
thread_count=3
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1135382 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0x7fb4f726a008
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x7fb4ec95b140 thread_stack 0x48400
/usr/sbin/mysqld(my_print_stacktrace+0x2b)[0x7fb5bd1ed97b]
/usr/sbin/mysqld(handle_fatal_signal+0x475)[0x7fb5bcd4c825]
/lib64/libpthread.so.0(+0x391f40f7e0)[0x7fb5bc3517e0]
/lib64/libc.so.6(gsignal+0x35)[0x7fb5ba7785e5]
/lib64/libc.so.6(abort+0x175)[0x7fb5ba779dc5]
/usr/lib64/galera/libgalera_smm.so(_ZN6galera3FSMINS_9TrxHandle5StateENS1_10TransitionENS_10EmptyGuardENS_11EmptyActionEE8shift_toES2_+0x180)[0x7fb5a71559f0]
mysys/stacktrace.c:247(my_print_stacktrace)[0x7fb5a714940e]
sql/signal_handler.cc:160(handle_fatal_signal)[0x7fb5a715c1bd]
sql/wsrep_hton.cc:257(wsrep_rollback)[0x7fb5bcce923a]
sql/wsrep_hton.cc:268(wsrep_rollback)[0x7fb5bcce9368]
sql/handler.cc:1658(ha_rollback_trans(THD*, bool))[0x7fb5bcd4f41a]
sql/handler.cc:1483(ha_commit_trans(THD*, bool))[0x7fb5bcd4f804]
sql/transaction.cc:435(trans_commit_stmt(THD*))[0x7fb5bccaf258]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0xb7c)[0x7fb5bcbda1bc]
sql/sql_class.h:3332(THD::get_stmt_da())[0x7fb5bcbe28fd]
sql/sql_parse.cc:7138(wsrep_mysql_parse)[0x7fb5bcbe29fc]
sql/sql_parse.cc:1484(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x7fb5bcbe4f3e]
sql/sql_parse.cc:1109(do_command(THD*))[0x7fb5bcbe5b0b]
sql/sql_connect.cc:1350(do_handle_one_connection(THD*))[0x7fb5bcca169f]
sql/sql_connect.cc:1264(handle_one_connection)[0x7fb5bcca17f7]
/lib64/libpthread.so.0(+0x391f407aa1)[0x7fb5bc349aa1]
/lib64/libc.so.6(clone+0x6d)[0x7fb5ba82eaad]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fb598c56020): is an invalid pointer
Connection ID (thread ID): 6
Status: NOT_KILLED
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
160620 15:57:33 mysqld_safe Number of processes running now: 0
160620 15:57:33 mysqld_safe WSREP: not restarting wsrep node automatically
160620 15:57:33 mysqld_safe mysqld from pid file /apps/data/mysqld/hostname.pid ended

I have honed the import file down to a reproducible minimum of creating and populating two tables, attached as crash1b4.sql. With a fresh database, I can cause the same crash as simply as:

# echo "drop database jimtest ; create database jimtest" | mysql
# mysql jimtest < crash1b4.sql 
ERROR 2013 (HY000) at line 23: Lost connection to MySQL server during query

My observations so far:
1. The statements in the file all succeed in isolation
2. If you reverse the order of the two tables in the file, the import succeeds. This is attached as crash1b4-reordered.sql
3. To force the crash we seem to need the long insert line with many rows; shortening this will allow the import to succeed
4. Changing encrypt-tmp-files=1 to encrypt-tmp-files=0 in my.ini and restarting mysqld will allow the import to succeed
5. Removing the node from the cluster (by removing all wsrep_* from my.ini and restarting mysqld) will allow the import to succeed, even with encrypt-tmp-files=1

My my.cnf is attached, with host and domain names replaced for privacy.



 Comments   
Comment by Sachin Setiya (Inactive) [ 2018-02-05 ]

Hi I have horned down the cnf file,

Now we can simulate bug with this cnf file(running --start-and-exit and then running crash1b4.sql)

!include ../galera_2nodes.cnf
[mysqld]
 
encrypt-tmp-files = 1
plugin-load-add= @ENV.FILE_KEY_MANAGEMENT_SO
file-key-management
loose-file-key-management-filename= @ENV.MYSQL_TEST_DIR/std_data/keys.txt
log-bin

Comment by Sachin Setiya (Inactive) [ 2018-02-05 ]

There is one more interesting thing I found out , For this particular table `testtable` the number of inserts should be >= 907 to get the crash , If it is less then that it is not crashing , if it is more then that it is crashing every time , one thing is sure, there is no race condition in this case.

Comment by Sachin Setiya (Inactive) [ 2018-03-20 ]

I tried with serg fix of mdev-14868. But this issue still fails.

Structure of crash1b4.sql
two insert stmt
first long enough that IO_CACHE need to use tmp file
second just small insert

Observation so far.

1. If we remove galera then crash1b4.sql(lets call it crash.sql) passes.

2.Issue is not galera although we get crash inside of galera. Reason is MYSQL_BIN_LOG::write_cache() fails, which signals the galera that there is some issue, but on other node the transaction is successful.

3. The issue which I am unable to understand is we read from the trans_cache two time
1st for wsrep_run_wsrep_commit , it copies the trans_cache to galera buffer, we do not get error in this copy.
2nd this is called from MYSQL_BIN_LOG::write_cache() which write the trans cache to binlog. But in this read we got a error.

Difference between there 2 reads in first read we are not calling my_read (means ) we have data in buffer and we do not need to look into tmp file.
in second read we are calling my_read , we are reading same data why this time we need to look into tmp file ?

Comment by Sachin Setiya (Inactive) [ 2018-03-22 ]

FInally got what the issue is , first read of IO_CACHE (my_b_fill from wsrep_write_cache ) equates the info->read_end to info->buffer , which makes next read of IO_CACHE (my_b_fill from MYSQL_BIN_LOG::write_cache )unsuccessful.

Comment by Sachin Setiya (Inactive) [ 2018-03-22 ]

Some what temp fix, but it is making other test to fail

diff --git a/mysys/mf_iocache.c b/mysys/mf_iocache.c
index 56b1ae3..5e2be26 100644
--- a/mysys/mf_iocache.c
+++ b/mysys/mf_iocache.c
@@ -422,13 +422,12 @@ my_bool reinit_io_cache(IO_CACHE *info, enum cache_type type,
     /* flush cache if we want to reuse it */
     if (!clear_cache && my_b_flush_io_cache(info,1))
       DBUG_RETURN(1);
-    info->pos_in_file=seek_offset;
     /* Better to do always do a seek */
     info->seek_not_done=1;
     info->request_pos=info->read_pos=info->write_pos=info->buffer;
     if (type == READ_CACHE)
     {
-      info->read_end=info->buffer;             /* Nothing in cache */
+      info->read_end=info->buffer + info->pos_in_file;
     }
     else
     {
@@ -450,6 +449,7 @@ my_bool reinit_io_cache(IO_CACHE *info, enum cache_type type,
       }
       info->end_of_file= ~(my_off_t) 0;
     }
+    info->pos_in_file=seek_offset;
   }
   info->type=type;
   info->error=0;

Comment by Sachin Setiya (Inactive) [ 2018-03-22 ]

A better patch

diff --git a/mysys/mf_iocache.c b/mysys/mf_iocache.c
index 56b1ae3..7215b4f 100644
--- a/mysys/mf_iocache.c
+++ b/mysys/mf_iocache.c
@@ -422,13 +422,14 @@ my_bool reinit_io_cache(IO_CACHE *info, enum cache_type type,
     /* flush cache if we want to reuse it */
     if (!clear_cache && my_b_flush_io_cache(info,1))
       DBUG_RETURN(1);
-    info->pos_in_file=seek_offset;
     /* Better to do always do a seek */
     info->seek_not_done=1;
     info->request_pos=info->read_pos=info->write_pos=info->buffer;
     if (type == READ_CACHE)
     {
-      info->read_end=info->buffer;             /* Nothing in cache */
+      info->read_end=info->buffer;
+      if (info->myflags & MY_ENCRYPT)
+        info->read_end+= info->pos_in_file;
     }
     else
     {
@@ -450,6 +451,7 @@ my_bool reinit_io_cache(IO_CACHE *info, enum cache_type type,
       }
       info->end_of_file= ~(my_off_t) 0;
     }
+    info->pos_in_file=seek_offset;
   }
   info->type=type;
   info->error=0;

Comment by Sachin Setiya (Inactive) [ 2018-03-27 ]

http://lists.askmonty.org/pipermail/commits/2018-March/012144.html

Comment by Sachin Setiya (Inactive) [ 2018-05-08 ]

http://lists.askmonty.org/pipermail/commits/2018-May/012509.html

Comment by Sachin Setiya (Inactive) [ 2018-05-18 ]

test case

diff --git a/unittest/sql/mf_iocache-t.cc b/unittest/sql/mf_iocache-t.cc
index 31f98562521..54e95d8f4c0 100644
--- a/unittest/sql/mf_iocache-t.cc
+++ b/unittest/sql/mf_iocache-t.cc
@@ -187,10 +187,76 @@ void mdev9044()
   close_cached_file(&info);
 }
 
+/* 2 Reads in cache makes second read to fail (only if first read uses temp file) */
+void mdev10259()
+{
+  int res;
+  uchar buf[200];
+  memset(buf, FILL, sizeof(buf));
+
+  diag("MDEV-10259- mysqld crash with certain statement length and order with"
+         " Galera and encrypt-tmp-files=1");
+
+  init_io_cache_encryption();
+
+  res= open_cached_file(&info, 0, 0, CACHE_SIZE, 0);
+  ok(res == 0, "open_cached_file" INFO_TAIL);
+
+  res= my_b_write(&info, buf, sizeof(buf));
+  ok(res == 0 && info.pos_in_file == 0, "200 write" INFO_TAIL);
+
+  res= my_b_flush_io_cache(&info, 1);
+  ok(res == 0, "flush" INFO_TAIL);
+
+  ulong saved_pos=  my_b_tell(&info);
+  res= reinit_io_cache(&info, READ_CACHE, 0, 0, 0);
+  ok(res == 0, "reinit READ_CACHE" INFO_TAIL);
+
+  res= my_b_fill(&info);
+  ok(res == 200, "fill" INFO_TAIL);
+
+  res= my_b_fill(&info);
+  ok(res == 0, "fill" INFO_TAIL);
+
+  res= my_b_fill(&info);
+  ok(res == 0, "fill" INFO_TAIL);
+
+  res= reinit_io_cache(&info, WRITE_CACHE, saved_pos, 0, 0);
+  ok(res == 0, "reinit WRITE_CACHE" INFO_TAIL);
+
+  res= reinit_io_cache(&info, READ_CACHE, 0, 0, 0);
+  ok(res == 0, "reinit READ_CACHE" INFO_TAIL);
+
+  ok(200 == my_b_bytes_in_cache(&info),"my_b_bytes_in_cache == 200");
+
+  res= my_b_fill(&info);
+  ok(res == 0, "fill" INFO_TAIL);
+
+  res= my_b_fill(&info);
+  ok(res == 0, "fill" INFO_TAIL);
+
+  res= my_b_fill(&info);
+  ok(res == 0, "fill" INFO_TAIL);
+
+  res= reinit_io_cache(&info, WRITE_CACHE, saved_pos, 0, 0);
+  ok(res == 0, "reinit WRITE_CACHE" INFO_TAIL);
+
+  res= reinit_io_cache(&info, READ_CACHE, 0, 0, 0);
+  ok(res == 0, "reinit READ_CACHE" INFO_TAIL);
+
+  ok(200 == my_b_bytes_in_cache(&info),"my_b_bytes_in_cache == 200");
+
+  res= my_b_read(&info, buf, sizeof(buf)) || data_bad(buf, sizeof(buf));
+  ok(res == 0 && info.pos_in_file == 0, "large read" INFO_TAIL);
+
+  close_cached_file(&info);
+
+}
+
 int main(int argc __attribute__((unused)),char *argv[])
 {
   MY_INIT(argv[0]);
-  plan(29);
+  plan(46);
 
   /* temp files with and without encryption */
   encrypt_tmp_files= 1;
@@ -202,6 +268,11 @@ int main(int argc __attribute__((unused)),char *argv[])
   /* regression tests */
   mdev9044();
 
+  encrypt_tmp_files= 1;
+  mdev10259();
+  encrypt_tmp_files= 0;
+  mdev10259();
+
   my_end(0);
   return exit_status();
 }

IO_cache test with encryption result

# MDEV-10259- mysqld crash with certain statement length and order with Galera and encrypt-tmp-files=1
ok 30 - open_cached_file, pos_in_file = 0, pos_in_mem = 0
ok 31 - 200 write, pos_in_file = 0, pos_in_mem = 200
ok 32 - flush, pos_in_file = 200, pos_in_mem = 0
ok 33 - reinit READ_CACHE, pos_in_file = 0, pos_in_mem = 0
ok 34 - fill, pos_in_file = 0, pos_in_mem = 0
ok 35 - fill, pos_in_file = 0, pos_in_mem = 200
ok 36 - fill, pos_in_file = 0, pos_in_mem = 200
ok 37 - reinit WRITE_CACHE, pos_in_file = 0, pos_in_mem = 200
ok 38 - reinit READ_CACHE, pos_in_file = 0, pos_in_mem = 0
ok 39 - my_b_bytes_in_cache == 200
ok 40 - fill, pos_in_file = 0, pos_in_mem = 200
ok 41 - fill, pos_in_file = 0, pos_in_mem = 200
ok 42 - fill, pos_in_file = 0, pos_in_mem = 200
ok 43 - reinit WRITE_CACHE, pos_in_file = 0, pos_in_mem = 200
ok 44 - reinit READ_CACHE, pos_in_file = 0, pos_in_mem = 0
ok 45 - my_b_bytes_in_cache == 200
ok 46 - large read, pos_in_file = 0, pos_in_mem = 200

same IO_cache test without encryption result

# MDEV-10259- mysqld crash with certain statement length and order with Galera and encrypt-tmp-files=1
ok 47 - open_cached_file, pos_in_file = 0, pos_in_mem = 0
ok 48 - 200 write, pos_in_file = 0, pos_in_mem = 200
ok 49 - flush, pos_in_file = 200, pos_in_mem = 0
ok 50 - reinit READ_CACHE, pos_in_file = 0, pos_in_mem = 0
ok 51 - fill, pos_in_file = 0, pos_in_mem = 0
ok 52 - fill, pos_in_file = 0, pos_in_mem = 200
ok 53 - fill, pos_in_file = 0, pos_in_mem = 200
ok 54 - reinit WRITE_CACHE, pos_in_file = 0, pos_in_mem = 200
ok 55 - reinit READ_CACHE, pos_in_file = 0, pos_in_mem = 0
ok 56 - my_b_bytes_in_cache == 200
ok 57 - fill, pos_in_file = 0, pos_in_mem = 200
ok 58 - fill, pos_in_file = 0, pos_in_mem = 200
ok 59 - fill, pos_in_file = 0, pos_in_mem = 200
ok 60 - reinit WRITE_CACHE, pos_in_file = 0, pos_in_mem = 200
ok 61 - reinit READ_CACHE, pos_in_file = 0, pos_in_mem = 0
ok 62 - my_b_bytes_in_cache == 200
ok 63 - large read, pos_in_file = 0, pos_in_mem = 200
# 46 tests planned but 63 executed

Comment by Sachin Setiya (Inactive) [ 2018-05-18 ]

Diff of unittest , with and without patch

--- not_fix.txt	2018-05-18 17:44:00.842681528 +0530
+++ fix.txt	2018-05-18 17:45:02.129883556 +0530
@@ -37,16 +37,16 @@
 ok 32 - flush, pos_in_file = 200, pos_in_mem = 0
 ok 33 - reinit READ_CACHE, pos_in_file = 0, pos_in_mem = 0
 ok 34 - fill, pos_in_file = 0, pos_in_mem = 0
-ok 35 - fill, pos_in_file = 200, pos_in_mem = 0
-ok 36 - fill, pos_in_file = 200, pos_in_mem = 0
-ok 37 - reinit WRITE_CACHE, pos_in_file = 200, pos_in_mem = 0
+ok 35 - fill, pos_in_file = 0, pos_in_mem = 200
+ok 36 - fill, pos_in_file = 0, pos_in_mem = 200
+ok 37 - reinit WRITE_CACHE, pos_in_file = 0, pos_in_mem = 200
 ok 38 - reinit READ_CACHE, pos_in_file = 0, pos_in_mem = 0
-not ok 39 - my_b_bytes_in_cache == 200
-not ok 40 - fill, pos_in_file = 0, pos_in_mem = 0
-ok 41 - fill, pos_in_file = 200, pos_in_mem = 0
-ok 42 - fill, pos_in_file = 200, pos_in_mem = 0
-ok 43 - reinit WRITE_CACHE, pos_in_file = 200, pos_in_mem = 0
+ok 39 - my_b_bytes_in_cache == 200
+ok 40 - fill, pos_in_file = 0, pos_in_mem = 200
+ok 41 - fill, pos_in_file = 0, pos_in_mem = 200
+ok 42 - fill, pos_in_file = 0, pos_in_mem = 200
+ok 43 - reinit WRITE_CACHE, pos_in_file = 0, pos_in_mem = 200
 ok 44 - reinit READ_CACHE, pos_in_file = 0, pos_in_mem = 0
-not ok 45 - my_b_bytes_in_cache == 200
+ok 45 - my_b_bytes_in_cache == 200
 ok 46 - large read, pos_in_file = 0, pos_in_mem = 200
-# Failed 3 tests!
+Test took 0.01 sec

Comment by Sachin Setiya (Inactive) [ 2018-05-22 ]

http://lists.askmonty.org/pipermail/commits/2018-May/012561.html

Generated at Thu Feb 08 07:40:51 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.