[MDEV-11060] sql/protocol.cc:532: void Protocol::end_statement(): Assertion `0' failed Created: 2016-10-14  Updated: 2016-12-14  Resolved: 2016-12-14

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.1.18, 10.1, 10.2
Fix Version/s: 10.1.20, 10.1.21

Type: Bug Priority: Major
Reporter: Nirbhay Choubey (Inactive) Assignee: Varun Gupta (Inactive)
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-7635 update defaults and simplify mysqld c... Closed
Sprint: 10.2.4-1

 Description   

How to repeat
Start server with @@optimizer_use_condition_selectivity=4 and execute the following commands:

--source include/have_innodb.inc
 
 
 
drop table if exists t1, t2;
 
drop view if exists v1;
 
 
 
create table t1 (a int not null, b int, c int) engine=InnoDB;
 
create trigger trgi before insert on t1 for each row set new.a=if(new.a is null,new.b,new.c);
 
 
 
create table t2 (d int, e int) engine=InnoDB;
 
update t1, t2 set a=NULL, b=2, c=NULL where b=d and e=200;
 
 
 
create view v1 as select * from t1, t2 where d=2;
 
insert v1 (a,c) values (NULL, 20);

Stacktrace

mysqld: /home/nirbhay/project/git-repo/mariadb/10.1/sql/protocol.cc:532: void Protocol::end_statement(): Assertion `0' failed.
 
 
 
Thread 28 "mysqld" received signal SIGABRT, Aborted.
 
[Switching to Thread 0x7fffec473b00 (LWP 7029)]
 
0x00007ffff6498418 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
 
54	../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
 
(gdb) bt
 
#0  0x00007ffff6498418 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
 
#1  0x00007ffff649a01a in __GI_abort () at abort.c:89
 
#2  0x00007ffff6490bd7 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x555556362f2f "0", 
    file=file@entry=0x555556363020 "/home/nirbhay/project/git-repo/mariadb/10.1/sql/protocol.cc", 
    line=line@entry=532, 
    function=function@entry=0x555556363960 <Protocol::end_statement()::__PRETTY_FUNCTION__> "void Protocol::end_statement()") at assert.c:92
 
#3  0x00007ffff6490c82 in __GI___assert_fail (assertion=0x555556362f2f "0", 
    file=0x555556363020 "/home/nirbhay/project/git-repo/mariadb/10.1/sql/protocol.cc", line=532, 
    function=0x555556363960 <Protocol::end_statement()::__PRETTY_FUNCTION__> "void Protocol::end_statement()")
 
    at assert.c:101
 
#4  0x000055555596b24c in Protocol::end_statement (this=0x555557a17540)
 
    at /home/nirbhay/project/git-repo/mariadb/10.1/sql/protocol.cc:532
 
#5  0x0000555555a211d7 in dispatch_command (command=COM_QUERY, thd=0x555557a16fb0, 
    packet=0x555557a1d811 "insert v1 (a,c) values (NULL, 20)", packet_length=33)
 
    at /home/nirbhay/project/git-repo/mariadb/10.1/sql/sql_parse.cc:1940
 
#6  0x0000555555a1e90d in do_command (thd=0x555557a16fb0)
 
    at /home/nirbhay/project/git-repo/mariadb/10.1/sql/sql_parse.cc:1108
 
#7  0x0000555555b54ddb in do_handle_one_connection (thd_arg=0x555557a16fb0)
 
    at /home/nirbhay/project/git-repo/mariadb/10.1/sql/sql_connect.cc:1350
 
#8  0x0000555555b54b2a in handle_one_connection (arg=0x555557a16fb0)
 
    at /home/nirbhay/project/git-repo/mariadb/10.1/sql/sql_connect.cc:1262
 
#9  0x00007ffff6ebe6fa in start_thread (arg=0x7fffec473b00) at pthread_create.c:333
 
#10 0x00007ffff6569b5d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

The following tests in the main suite also fail due to this issue (when started with -mysqld=-optimizer_use_condition_selectivity=4):

  • main.strict
  • main.gis
  • main.ps_2myisam
  • main.ps_3innodb
  • main.ps_4heap
  • main.trigger_null-8605
  • main.view

 Comments   
Comment by Elena Stepanova [ 2016-10-16 ]

Requires InnoDB.

Comment by Varun Gupta (Inactive) [ 2016-12-09 ]

Field creating the issue

field->table->in_use->no_errors in function set_bad_null_error in file field_conv.cc

with optimizer_using_condition_selectivity=4 

Thread 3 hit Breakpoint 1, set_bad_null_error (field=0x10ca672c8, err=1048) at /Users/varun/MariaDB/10.1/10.1/sql/field_conv.cc:120
 
warning: Source file is more recent than executable.
 
120	  switch (field->table->in_use->count_cuted_fields) {
 
(gdb) n
 
127	    if (!field->table->in_use->no_errors)
 
(gdb) 
129	    return -1;
 
(gdb) p field->table->in_use->no_errors 
$1 = true
 
(gdb)

with optimizer_using_condition_selectivity=1 

Thread 20 hit Breakpoint 1, set_bad_null_error (field=0x10c45c2c8, err=1048) at /Users/varun/MariaDB/10.1/10.1/sql/field_conv.cc:120
 
120	  switch (field->table->in_use->count_cuted_fields) {
 
(gdb) n
 
127	    if (!field->table->in_use->no_errors)
 
(gdb) n
 
128	      my_error(ER_BAD_NULL_ERROR, MYF(0), field->field_name);
 
(gdb) p field->table->in_use->no_errors
 
$2 = false
 
(gdb)

Comment by Varun Gupta (Inactive) [ 2016-12-09 ]

with optimizer_using_condition_selectivity=4, the thd->no_errors is explicity set 1 on line 3058 of file sql/opt_range.cc.

The useful parts where the value of thd->no_errors change:

3058	    thd->no_errors=1;		    
(gdb) 
 
 
Thread 3 hit Hardware watchpoint 7: -location thd->no_errors
 
 
 
Old value = false
 
New value = true
 
calculate_cond_selectivity_for_table (thd=0x10c64ff70, table=0x10ca88470, cond=0x10ca35f70) at /Users/varun/MariaDB/10.1/10.1/sql/opt_range.cc:3060
 
3060	    tree= cond[0]->get_mm_tree(&param, cond);
 
(gdb)

In file sql/sql_base.cc

bool
 
fill_record(THD *thd, TABLE *table_arg, List<Item> &fields, List<Item> &values,
 
            bool ignore_errors)
 
{
 
  List_iterator_fast<Item> f(fields),v(values);
 
  Item *value, *fld;
 
  Item_field *field;
 
  TABLE *vcol_table= 0;
 
  bool save_abort_on_warning= thd->abort_on_warning;
 
[8701] *bool save_no_errors= thd->no_errors;*
 
  DBUG_ENTER("fill_record");
 
 
 
[8704]*  thd->no_errors= ignore_errors;*

In the same function we then restore the value of thd->no_errors

thd->abort_on_warning= save_abort_on_warning;
 
[8769]  *thd->no_errors=        save_no_errors;*
 
  DBUG_RETURN(thd->is_error());
 
err:
 
  thd->abort_on_warning= save_abort_on_warning;
 
[8773]  *thd->no_errors=        save_no_errors;*
 
  if (fields.elements)
 
    table_arg->auto_increment_field_not_null= FALSE;
 
  DBUG_RETURN(TRUE);

Comment by Sergei Petrunia [ 2016-12-12 ]

varun, thanks for the analysis.

Taking another look at how thd->no_errors changes:

  Breakpoint 1, dispatch_command (command=COM_QUERY, thd=0x555557b78dc0, packet=0x555557b80ba1 "set @@optimizer_use_condition_selectivity=4", packet_length=43) at /home/psergey/dev-git/10.1-dbg8/sql/sql_parse.cc:1240
 
(gdb) p thd->no_errors
 
  $4 = false

So, no_errors=false is the default state. Looks logical.

(gdb) watch -l thd->no_errors
 
  Hardware watchpoint 2: -location thd->no_errors
 
(gdb) c
 
  Continuing.

...

  
  Hardware watchpoint 2: -location thd->no_errors
 
  Old value = false
 
  New value = true
 
  calculate_cond_selectivity_for_table (thd=0x555557b78dc0, table=0x7fff8805d2c0, cond=0x7fff880189d0) at /home/psergey/dev-git/10.1-dbg8/sql/opt_range.cc:3060
 
(gdb) wher
 
  #0  calculate_cond_selectivity_for_table (thd=0x555557b78dc0, table=0x7fff8805d2c0, cond=0x7fff880189d0) at /home/psergey/dev-git/10.1-dbg8/sql/opt_range.cc:3060
 
  #1  0x0000555555a9b50f in make_join_statistics (join=0x7fff88018588, tables_list=..., keyuse_array=0x7fff880188b8) at /home/psergey/dev-git/10.1-dbg8/sql/sql_select.cc:4112
 
  #2  0x0000555555a91903 in JOIN::optimize_inner (this=0x7fff88018588) at /home/psergey/dev-git/10.1-dbg8/sql/sql_select.cc:1361
 
  #3  0x0000555555a90818 in JOIN::optimize (this=0x7fff88018588) at /home/psergey/dev-git/10.1-dbg8/sql/sql_select.cc:1040
 
  #4  0x0000555555a98de0 in mysql_select (thd=0x555557b78dc0, rref_pointer_array=0x555557b7d180, tables=0x7fff880163f8, wild_num=0, fields=..., conds=0x7fff88017b60, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=1342177408, result=0x7fff880184c0, unit=0x555557b7c808, select_lex=0x555557b7cf08) at /home/psergey/dev-git/10.1-dbg8/sql/sql_select.cc:3424
 
  #5  0x0000555555b2fe7d in mysql_multi_update (thd=0x555557b78dc0, table_list=0x7fff880163f8, fields=0x555557b7d020, values=0x555557b7d460, conds=0x7fff88017b60, options=0, handle_duplicates=DUP_ERROR, ignore=false, unit=0x555557b7c808, select_lex=0x555557b7cf08, result=0x7ffff023ebf0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_update.cc:1629
 
  #6  0x0000555555a570be in mysql_execute_command (thd=0x555557b78dc0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_parse.cc:3818
 
  #7  0x0000555555a62533 in mysql_parse (thd=0x555557b78dc0, rawbuf=0x7fff880162d8 "update t1, t2 set a=NULL, b=2, c=NULL where b=d and e=200", length=57, parser_state=0x7ffff023f4a0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_parse.cc:7319
 
  #8  0x0000555555a50c4e in dispatch_command (command=COM_QUERY, thd=0x555557b78dc0, packet=0x555557b80ba1 "update t1, t2 set a=NULL, b=2, c=NULL where b=d and e=200", packet_length=57) at /home/psergey/dev-git/10.1-dbg8/sql/sql_parse.cc:1487
 
  #9  0x0000555555a4f96f in do_command (thd=0x555557b78dc0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_parse.cc:1108
 
  #10 0x0000555555b83d7f in do_handle_one_connection (thd_arg=0x555557b78dc0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_connect.cc:1350
 
  #11 0x0000555555b83ad0 in handle_one_connection (arg=0x555557b78dc0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_connect.cc:1262
 
  #12 0x0000555555f33198 in pfs_spawn_thread (arg=0x5555577ce730) at /home/psergey/dev-git/10.1-dbg8/storage/perfschema/pfs.cc:1860
 
  #13 0x00007ffff691de9a in start_thread (arg=0x7ffff0240b00) at pthread_create.c:308
 
  #14 0x00007ffff604e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
 
  #15 0x0000000000000000 in ?? ()
 
(gdb) c
 
  Continuing.

Ok, so the UPDATE (see frame#7) command code has set thd->no_errors to TRUE.
Note that the next time we hit the breakpoint, we will be in a different statement.

  
  Hardware watchpoint 2: -location thd->no_errors
 
  Old value = true
 
  New value = false
 
  fill_record (thd=0x555557b78dc0, table_arg=0x7fff8804d110, fields=..., values=..., ignore_errors=false) at /home/psergey/dev-git/10.1-dbg8/sql/sql_base.cc:8709
 
(gdb) wher
 
  #0  fill_record (thd=0x555557b78dc0, table_arg=0x7fff8804d110, fields=..., values=..., ignore_errors=false) at /home/psergey/dev-git/10.1-dbg8/sql/sql_base.cc:8709
 
  #1  0x00005555559f9fc6 in fill_record_n_invoke_before_triggers (thd=0x555557b78dc0, table=0x7fff8804d110, fields=..., values=..., ignore_errors=false, event=TRG_EVENT_INSERT) at /home/psergey/dev-git/10.1-dbg8/sql/sql_base.cc:8863
 
  #2  0x0000555555a32a4c in mysql_insert (thd=0x555557b78dc0, table_list=0x7fff880163c8, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/psergey/dev-git/10.1-dbg8/sql/sql_insert.cc:903
 
  #3  0x0000555555a57459 in mysql_execute_command (thd=0x555557b78dc0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_parse.cc:3898
 
  #4  0x0000555555a62533 in mysql_parse (thd=0x555557b78dc0, rawbuf=0x7fff880162d8 "insert v1 (a,c) values (NULL, 20)", length=33, parser_state=0x7ffff023f4a0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_parse.cc:7319
 
  #5  0x0000555555a50c4e in dispatch_command (command=COM_QUERY, thd=0x555557b78dc0, packet=0x555557b80ba1 "insert v1 (a,c) values (NULL, 20)", packet_length=33) at /home/psergey/dev-git/10.1-dbg8/sql/sql_parse.cc:1487
 
  #6  0x0000555555a4f96f in do_command (thd=0x555557b78dc0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_parse.cc:1108
 
  #7  0x0000555555b83d7f in do_handle_one_connection (thd_arg=0x555557b78dc0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_connect.cc:1350
 
  #8  0x0000555555b83ad0 in handle_one_connection (arg=0x555557b78dc0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_connect.cc:1262
 
  #9  0x0000555555f33198 in pfs_spawn_thread (arg=0x5555577ce730) at /home/psergey/dev-git/10.1-dbg8/storage/perfschema/pfs.cc:1860
 
  #10 0x00007ffff691de9a in start_thread (arg=0x7ffff0240b00) at pthread_create.c:308
 
  #11 0x00007ffff604e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
 
  #12 0x0000000000000000 in ?? ()
 
(gdb) c
 
  Continuing.

INSERT statement has changed the value of thd->no_errors

  
  Hardware watchpoint 2: -location thd->no_errors
 
  Old value = false
 
  New value = true
 
  fill_record (thd=0x555557b78dc0, table_arg=0x7fff8804d110, fields=..., values=..., ignore_errors=false) at /home/psergey/dev-git/10.1-dbg8/sql/sql_base.cc:8770
 
(gdb) wher
 
  #0  fill_record (thd=0x555557b78dc0, table_arg=0x7fff8804d110, fields=..., values=..., ignore_errors=false) at /home/psergey/dev-git/10.1-dbg8/sql/sql_base.cc:8770
 
  #1  0x00005555559f9fc6 in fill_record_n_invoke_before_triggers (thd=0x555557b78dc0, table=0x7fff8804d110, fields=..., values=..., ignore_errors=false, event=TRG_EVENT_INSERT) at /home/psergey/dev-git/10.1-dbg8/sql/sql_base.cc:8863
 
  #2  0x0000555555a32a4c in mysql_insert (thd=0x555557b78dc0, table_list=0x7fff880163c8, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/psergey/dev-git/10.1-dbg8/sql/sql_insert.cc:903
 
  #3  0x0000555555a57459 in mysql_execute_command (thd=0x555557b78dc0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_parse.cc:3898
 
  #4  0x0000555555a62533 in mysql_parse (thd=0x555557b78dc0, rawbuf=0x7fff880162d8 "insert v1 (a,c) values (NULL, 20)", length=33, parser_state=0x7ffff023f4a0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_parse.cc:7319
 
  #5  0x0000555555a50c4e in dispatch_command (command=COM_QUERY, thd=0x555557b78dc0, packet=0x555557b80ba1 "insert v1 (a,c) values (NULL, 20)", packet_length=33) at /home/psergey/dev-git/10.1-dbg8/sql/sql_parse.cc:1487
 
  #6  0x0000555555a4f96f in do_command (thd=0x555557b78dc0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_parse.cc:1108
 
  #7  0x0000555555b83d7f in do_handle_one_connection (thd_arg=0x555557b78dc0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_connect.cc:1350
 
  #8  0x0000555555b83ad0 in handle_one_connection (arg=0x555557b78dc0) at /home/psergey/dev-git/10.1-dbg8/sql/sql_connect.cc:1262
 
  #9  0x0000555555f33198 in pfs_spawn_thread (arg=0x5555577ce730) at /home/psergey/dev-git/10.1-dbg8/storage/perfschema/pfs.cc:1860
 
  #10 0x00007ffff691de9a in start_thread (arg=0x7ffff0240b00) at pthread_create.c:308
 
  #11 0x00007ffff604e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
 
  #12 0x0000000000000000 in ?? ()
 
(gdb) c
 
  Continuing.

INSERT has changed the value of thd->no_errors back. However, that old value is TRUE

Which agrees with the assert:

  mysqld: /home/psergey/dev-git/10.1-dbg8/sql/protocol.cc:532: void Protocol::end_statement(): Assertion `0' failed.
 
  
  Program received signal SIGABRT, Aborted.
 
  0x00007ffff5f90425 in __GI_raise (sig=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
 
  64	../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.

This assertion basically means "the server has not sent the client any reply. Neither an error, nor a result set". It seems that the statement should have produced an error, but the value of thd->no_error=TRUE has suppressed the error. As a result we get an assert.

Comment by Sergei Petrunia [ 2016-12-12 ]

Looking into opt_range.cc, at functions that change value of thd->no_errors: SQL_SELECT::test_quick_select and prune_partitions,
calculate_cond_selectivity_for_table.

The former two always restore the original value of thd->no_error. The last one doesn't, and this seems to be where the bug is.

Varun, can you check this and make a fix?

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