Re: [Maria-developers] Rollback causes assertion with Galera 10.0

Hi, This is what I see inspecting the cache_log (gdb) p cache_log $1 = {pos_in_file = 11936128518282651045, end_of_file = 18446744073709547520, read_pos = 0x7f214003bb10 "%\374-R\023", read_end = 0x7f214003bc70 "", buffer = 0x7f214003bb10 "%\374-R\023", request_pos = 0x7f214003bb10 "%\374-R\023", write_buffer = 0x7f214003bb10 "%\374-R\023", append_read_pos = 0x7f214003bb10 "%\374-R\023", write_pos = 0x7f214003c848 "$\374-R\027", write_end = 0x7f214004356b '\245' ..., current_pos = 0x7f21400333d0, current_end = 0x7f21400333d8, append_buffer_lock = {m_mutex = {global = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' , __align = 0}, mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' , __align = 0}, file = 0x0, name = 0x0, line = 0, count = 0, create_flags = 0, active_flags = 0, id = 0, thread = 0, locked_mutex = 0x0, used_mutex = 0x0, prev = 0x0, next = 0x0}, m_psi = 0x0}, share = 0x0, read_function = 0xe17c32 <_my_b_read>, write_function = 0xe194d4 <_my_b_write>, type = WRITE_CACHE, pre_read = 0x0, post_read = 0x0, pre_close = 0x0, disk_writes = 0, arg = 0x0, file_name = 0x0, dir = 0x7f214003b9d0 "/home/jan/mysql/galera-test/node0/tmp", prefix = 0x7f214003ba80 "ML", file = 58, seek_not_done = 1, error = -1, buffer_length = 32768, read_length = 32768, myflags = 16, alloced_buffer = 1 '\001'}'' (gdb) p cache_log.current_pos $2 = (uchar **) 0x7f21400333d0 (gdb) p *cache_log.current_pos $3 = (uchar *) 0x7f214003c848 "$\374-R\027" (gdb) p *cache_log.pos_in_file Cannot access memory at address 0xa5a5a5a5a5a5a5a5 (gdb) p cache_log.pos_in_file $4 = 11936128518282651045 (gdb) p *cache_log.request_pos $5 = 37 '%' (gdb) p cache_log.request_pos $6 = (uchar *) 0x7f214003bb10 "%\374-R\023"' R: Jan

Jan Lindström writes:

...

#3 0x00007f1ff9877eb2 in __GI___assert_fail (assertion=0x109b4ff "empty()", file=0x109b4d8 "/home/jan/mysql/galera-10.0/sql/log.cc", line=294, function= 0x10a01e0 "void binlog_cache_data::reset()") at assert.c:101 #4 0x00000000009497d4 in binlog_cache_data::reset (this=0x7f1f7403ad60) at / home/jan/mysql/galera-10.0/sql/log.cc:294 #5 0x0000000000949b6a in binlog_cache_mngr::reset (this=0x7f1f7403ab90, do_stmt=false, do_trx=true) at /home/jan/mysql/galera-10.0/sql/log.cc:462 #6 0x0000000000935a4c in binlog_truncate_trx_cache (thd=0x45b7d40, cache_mngr= 0x7f1f7403ab90, all=true) at /home/jan/mysql/galera-10.0/sql/log.cc:1991 #7 0x0000000000936123 in binlog_rollback (hton=0x3891fb0, thd=0x45b7d40, all= true) at /home/jan/mysql/galera-10.0/sql/log.cc:2180 At empty() this is what does not hold : my_b_tell(&cache_log) == 0; // not sure what this means The cache_log is used first in WRITE_CACHE mode to store events for DML done in a transaction. And then in READ_CACHE mode to read out the events again and copy them into the actual binlog file.

I suspect this is some problem with error handling. The binlog code is known to be extremely complicated wrt. error handling, and there are many possibilities for problems when errors turn up in unexpected places.

It sounds like you are able to inspect the state at the time of the assert with gdb (running mysqld in the debugger or inspecting a core file). Can you help me by obtaining some additional values that will help me understand how this could have occured?

Try in GDB:

p cache_log

I would like to see what the state of the cache_log is. Of particular interest is the value of cache_log.type (WRITE_CACHE or READ_CACHE?) and the fields pos_in_file, current_pos, and request_pos used in my_b_tell, but better to get all the values.

With that info, I will try to analyse further...

I suspect this is related to a failure that occurs in an unusual place in galera (conflict causing error during commit or something like that) that either hits a bug in binlog error handling or was done incorrectly in the galera patch. But I need more information about what lead up to this to be sure ...

- Kristian.

-- -- Jan Lindström Principal Engineer MariaDB | MaxScale | skype: jan_p_lindstrom www.skysql.com http://www.skysql.com/ Twitter http://twitter.com/skysql Blog http://www.skysql.com/blog/ Facebook http://www.facebook.com/skysql LinkedIn http://www.linkedin.com/company/1214250 Google+ https://plus.google.com/117544963211695643458/posts