[MDEV-8411] Assertion `is_stat_field || !table || (!table->write_set || bitmap_is_set(table->write_set, field_index) || bitmap_is_set(table->vcol_set, field_index))' failed in Field_timestamp::store_TIME_with_warning Created: 2015-07-02  Updated: 2016-02-23  Resolved: 2016-02-23

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.1
Fix Version/s: 10.1.12

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Vicențiu Ciorbaru
Resolution: Fixed Votes: 0
Labels: None

Attachments: File binlogs.tar.gz     File mysql.log.gz    
Sprint: 10.1.12

 Description   

Stack trace from 498a264d19f041c36d71e41a32c16ac40a014a3e

 
10.1/sql/field.cc:4615: int Field_timestamp::store_TIME_with_warning(THD*, MYSQL_TIME*, const ErrConv*, int, bool): Assertion `is_stat_field || !table || (!table->write_set || bitmap_is_set(table->write_set, field_index) || bitmap_is_set(table->vcol_set, field_index))' failed.
 
150702 17:46:52 [ERROR] mysqld got signal 6 ;
 
 
 
#6  0x00007f23dc77f311 in *__GI___assert_fail (assertion=0x7f23dfaf0a30 "is_stat_field || !table || (!table->write_set || bitmap_is_set(table->write_set, field_index) || bitmap_is_set(table->vcol_set, field_index))", file=<optimized out>, line=4615, function=0x7f23dfaf45e0 "int Field_timestamp::store_TIME_with_warning(THD*, MYSQL_TIME*, const ErrConv*, int, bool)") at assert.c:81
 
#7  0x00007f23df304ffc in Field_timestamp::store_TIME_with_warning (this=0x7f23b6276b58, thd=0x7f23b604c070, l_time=0x7f23deacce30, str=0x7f23deacce60, was_cut=0, have_smth_to_conv=true) at 10.1/sql/field.cc:4615
 
#8  0x00007f23df3052c6 in Field_timestamp::store_time_dec (this=0x7f23b6276b58, ltime=0x7f23deacd0b0, dec=0) at 10.1/sql/field.cc:4676
 
#9  0x00007f23df31f86a in do_field_temporal (copy=0x7f23deacd280) at 10.1/sql/field_conv.cc:424
 
#10 0x00007f23df31eee0 in do_copy_null (copy=0x7f23deacd280) at 10.1/sql/field_conv.cc:243
 
#11 0x00007f23df43382c in unpack_row (rgi=0x7f23b6023800, table=0x7f23dbd8e470, colcnt=9, row_data=0x7f23b62d5df0 "r\376\001", cols=0x7f23b629d1e8, current_row_end=0x7f23b629d288, master_reclength=0x7f23b629d230, row_end=0x7f23b62d5ec6 "\245\245h4z\025") at 10.1/sql/rpl_record.cc:375
 
#12 0x00007f23df432587 in Rows_log_event::unpack_current_row (this=0x7f23b629d170, rgi=0x7f23b6023800) at 10.1/sql/log_event.h:4430
 
#13 0x00007f23df42f287 in Rows_log_event::find_row (this=0x7f23b629d170, rgi=0x7f23b6023800) at 10.1/sql/log_event.cc:11889
 
#14 0x00007f23df4304ec in Update_rows_log_event::do_exec_row (this=0x7f23b629d170, rgi=0x7f23b6023800) at 10.1/sql/log_event.cc:12386
 
#15 0x00007f23df42a8da in Rows_log_event::do_apply_event (this=0x7f23b629d170, rgi=0x7f23b6023800) at 10.1/sql/log_event.cc:9917
 
#16 0x00007f23df05030d in Log_event::apply_event (this=0x7f23b629d170, rgi=0x7f23b6023800) at 10.1/sql/log_event.h:1347
 
#17 0x00007f23df045cf6 in apply_event_and_update_pos (ev=0x7f23b629d170, thd=0x7f23b604c070, rgi=0x7f23b6023800, rpt=0x0) at 10.1/sql/slave.cc:3269
 
#18 0x00007f23df0465a3 in exec_relay_log_event (thd=0x7f23b604c070, rli=0x7f23ca088c20, serial_rgi=0x7f23b6023800) at 10.1/sql/slave.cc:3587
 
#19 0x00007f23df04988a in handle_slave_sql (arg=0x7f23ca087000) at 10.1/sql/slave.cc:4687
 
#20 0x00007f23de79ab50 in start_thread (arg=<optimized out>) at pthread_create.c:304
 
#21 0x00007f23dc82f95d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

To reproduce,

  • bootstrap server 1 and server 2;
  • unpack the attached binlog.tar.gz and put all mysql-bin.* files into the datadir for server 1;
  • start server 1 with --log-bin=mysql-bin --server-id=1;
  • start server 2 with --server-id=2;
  • set up and start standard replication from server 1 to server 2;
  • wait.

When slave SQL thread reaches mysql-bin.000237 pos 866, the slave crashes as above.

I have also attached mysql.log from the master in case you want to match the binlog with the general log.



 Comments   
Comment by Elena Stepanova [ 2015-07-02 ]

cvicentiu, I'm not quite sure it's related to MDEV-6877, but I can't check it because the binary log was created with binlog-row-image=minimal, so it does not work on a pre-MDEV-6877 build.
If it turns out it's unrelated, please reassign to Kristian or to me.

Comment by Elena Stepanova [ 2015-12-22 ]

Similar crash with a testcase:

Stack trace from 10.1 commit d58a770201acae10bdae7e840db043368cb48ba0

 
#7  0x00007f052bbb5192 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x00007f052e35910b in Field_long::store (this=0x7f0515445280, nr=1000, unsigned_val=false) at 10.1/sql/field.cc:4058
 
#9  0x00007f052e3a18f6 in save_int_value_in_field (field=0x7f0515445280, nr=1000, null_value=false, unsigned_flag=false) at 10.1/sql/item.cc:5945
 
#10 0x00007f052e3a1954 in Item_int::save_in_field (this=0x7f05154ed4c8, field=0x7f0515445280, no_conversions=false) at 10.1/sql/item.cc:5951
 
#11 0x00007f052e3a84de in Item_trigger_field::set_value (this=0x7f05154ed550, thd=0x7f051543f070, it=0x7f05154ed6c0) at 10.1/sql/item.cc:8389
 
#12 0x00007f052e4cfb66 in Item_trigger_field::set_value (this=0x7f05154ed550, thd=0x7f051543f070, it=0x7f05154ed6c0) at 10.1/sql/item.h:4931
 
#13 0x00007f052e4cd567 in sp_instr_set_trigger_field::exec_core (this=0x7f05154ed688, thd=0x7f051543f070, nextp=0x7f052dacc1f0) at 10.1/sql/sp_head.cc:3234
 
#14 0x00007f052e4cc924 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7f05154ed6c8, thd=0x7f051543f070, nextp=0x7f052dacc1f0, open_tables=true, instr=0x7f05154ed688) at 10.1/sql/sp_head.cc:2916
 
#15 0x00007f052e4cd4d3 in sp_instr_set_trigger_field::execute (this=0x7f05154ed688, thd=0x7f051543f070, nextp=0x7f052dacc1f0) at 10.1/sql/sp_head.cc:3225
 
#16 0x00007f052e4c8ae9 in sp_head::execute (this=0x7f05154a3088, thd=0x7f051543f070, merge_da_on_success=false) at 10.1/sql/sp_head.cc:1317
 
#17 0x00007f052e4c962f in sp_head::execute_trigger (this=0x7f05154a3088, thd=0x7f051543f070, db_name=0x7f05154b97b8, table_name=0x7f05154b97c8, grant_info=0x7f05154b9bd8) at 10.1/sql/sp_head.cc:1646
 
#18 0x00007f052e2161a0 in Table_triggers_list::process_triggers (this=0x7f05154b9a88, thd=0x7f051543f070, event=TRG_EVENT_UPDATE, time_type=TRG_ACTION_BEFORE, old_row_is_record1=true) at 10.1/sql/sql_trigger.cc:2151
 
#19 0x00007f052e4855fe in Rows_log_event::process_triggers (this=0x7f05154a6230, event=TRG_EVENT_UPDATE, time_type=TRG_ACTION_BEFORE, old_row_is_record1=true) at 10.1/sql/log_event.cc:11357
 
#20 0x00007f052e488143 in Update_rows_log_event::do_exec_row (this=0x7f05154a6230, rgi=0x7f0515416800) at 10.1/sql/log_event.cc:12517
 
#21 0x00007f052e4822e6 in Rows_log_event::do_apply_event (this=0x7f05154a6230, rgi=0x7f0515416800) at 10.1/sql/log_event.cc:9987
 
#22 0x00007f052e0b4759 in Log_event::apply_event (this=0x7f05154a6230, rgi=0x7f0515416800) at 10.1/sql/log_event.h:1343
 
#23 0x00007f052e0aa512 in apply_event_and_update_pos (ev=0x7f05154a6230, thd=0x7f051543f070, rgi=0x7f0515416800, rpt=0x0) at 10.1/sql/slave.cc:3375
 
#24 0x00007f052e0aaf97 in exec_relay_log_event (thd=0x7f051543f070, rli=0x7f05267c9c20, serial_rgi=0x7f0515416800) at 10.1/sql/slave.cc:3705
 
#25 0x00007f052e0ae0bc in handle_slave_sql (arg=0x7f05267c8000) at 10.1/sql/slave.cc:4784
 
#26 0x00007f052e9737b0 in pfs_spawn_thread (arg=0x7f05161650f0) at 10.1/storage/perfschema/pfs.cc:1860
 
#27 0x00007f052c54ce9a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
 
#28 0x00007f052bc79cbd in clone () from /lib/x86_64-linux-gnu/libc.so.6

Test case

 
--source include/master-slave.inc
 
--source include/have_binlog_format_row.inc
 
 
 
set binlog_row_image = MINIMAL;
 
create table t1 (pk int primary key, f int);
 
 
 
--sync_slave_with_master
 
create trigger tr before update on t1 for each row set new.f = 1000;
 
set global slave_run_triggers_for_rbr = YES;
 
 
 
--connection master
 
insert into t1 values (1,1),(2,2);
 
update t1 set pk=pk+10;
 
 
 
--sync_slave_with_master

Comment by Vicențiu Ciorbaru [ 2016-02-21 ]

The reason for the assertion failure is that the update statement for the minimal row image sets only the PK column in the write_set of the table to true. On the other hand, the trigger aims to update a different column. We must find a way to signal the store procedure that if we are during a trigger update, that the write set must not be taken into account.

Comment by Vicențiu Ciorbaru [ 2016-02-23 ]

Can you please review:

https://github.com/MariaDB/server/commit/de1fa4527663ffde05b43bbc2acd5ce0398f483a

For the record, buildbot tests pass.
https://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-10.1-vicentiu

Comment by Oleksandr Byelkin [ 2016-02-23 ]

OK, to push

Comment by Vicențiu Ciorbaru [ 2016-02-23 ]

Fixed with

https://github.com/MariaDB/server/commit/de1fa4527663ffde05b43bbc2acd5ce0398f483a

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