Sachin Setiya (Inactive) added a comment - 2018-02-05 13:31 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

Sachin Setiya (Inactive) added a comment - 2018-02-05 19:09 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.

Sachin Setiya (Inactive) added a comment - 2018-03-20 13:37 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 ?

Sachin Setiya (Inactive) added a comment - 2018-03-22 06:15 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.

Sachin Setiya (Inactive) added a comment - 2018-03-22 08:37 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 ;

Sachin Setiya (Inactive) added a comment - 2018-03-22 08:51 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 ;

Sachin Setiya (Inactive) added a comment - 2018-03-27 07:35 http://lists.askmonty.org/pipermail/commits/2018-March/012144.html

Sachin Setiya (Inactive) added a comment - 2018-05-08 11:56 http://lists.askmonty.org/pipermail/commits/2018-May/012509.html

Sachin Setiya (Inactive) added a comment - 2018-05-18 11:56 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

Sachin Setiya (Inactive) added a comment - 2018-05-18 12:16 - edited 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

Sachin Setiya (Inactive) added a comment - 2018-05-22 08:21 http://lists.askmonty.org/pipermail/commits/2018-May/012561.html