[MDEV-14840] Assertion `!log->same_pk' failed in row_log_table_apply_delete Created: 2018-01-01  Updated: 2018-01-09  Resolved: 2018-01-09

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3
Fix Version/s: 10.3.4

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Duplicate Votes: 0
Labels: None

Attachments: File mtr_default_server.patch    
Issue Links:
Blocks
is blocked by MDEV-14837 Duplicate primary keys are allowed af... Closed
is blocked by MDEV-14897 After UPDATE of instant ADD COLUMN, P... Closed

 Description   

Notes:

  • it can be related to MDEV-14837, or even be a direct consequence of it. If so, please feel free to close as a duplicate.
  • Please note that you (probably) need to apply the attached/pasted patch mtr_default_server.patch to MTR, and run the test case with --default-server-options. The patch doesn't do any dirty tricks, it simply makes MTR to bootstrap and run the server with real default server options. On some reason, I couldn't reproduce it otherwise, even by restoring all options changed by MTR to their true default values on the command line. Possibly it has something to do with how the server bootstraps, but I couldn't positively confirm it. In any case, I expect that the reason will become apparent when the cause of the failure is known.
  • Even with the MTR patch, the test case is highly non-deterministic and mustn't be put into the regression suite. The current test case runs 50 loops inside it (so there is no need to run with --repeat). On my machine it has always failed withing first 20 loops, but I assume it can vary.
  • It fails for me on an ASAN build, too.

# Apply the provided mtr_default_server.patch and run with --default-server-options
 
 
 
--source include/have_innodb.inc
 
--source include/have_log_bin.inc
 
 
 
--let $run= 50
 
while ($run)
 
{
 
  --connect (con1,localhost,root,,test)
 
  CREATE TABLE t1 (c1 INT, c2 INT, c3 INT, c4 TEXT, PRIMARY KEY (c4(10))) ENGINE=InnoDB;
 
  INSERT INTO t1 (c1,c2,c3,c4) VALUES (1,1,1,REPEAT('a',8193));
 
  ALTER TABLE t1 ADD COLUMN c5 INT;
 
  UPDATE t1 SET c5 = c1;
 
  --connection default
 
  --send
 
    ALTER TABLE t1 DROP COLUMN c1;
 
  --connection con1
 
  --error ER_DUP_ENTRY
 
  INSERT INTO t1 (c1,c2,c3,c4) VALUES (2,2,2,REPEAT('a',8193)),(3,3,3,REPEAT('a',8193));
 
  ROLLBACK;
 
 
 
  --connection default
 
  --reap
 
  --source include/restart_mysqld.inc
 
  --disconnect con1
 
  --connection default
 
  DROP TABLE t1;
 
  --dec $run
 
  --echo #
 
  --echo # $run runs left
 
  --echo #
 
}

10.3 c664c48726cdfab1

 
mysqld: /data/src/10.3/storage/innobase/row/row0log.cc:1992: dberr_t row_log_table_apply_delete(que_thr_t*, ulint, const mrec_t*, const ulint*, mem_heap_t*, mem_heap_t*, const row_log_t*, const row_ext_t
 
*, ulint): Assertion `!log->same_pk' failed.
 
180101 15:47:10 [ERROR] mysqld got signal 6 ;
 
 
 
7  0x00007fda1874fee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x000055ec6cc3a12b in row_log_table_apply_delete (thr=0x7fd9a42f64b0, trx_id_col=1, mrec=0x7fda003db046 "aaaaaaaaaa", moffsets=0x7fd9a42d2c60, offsets_heap=0x7fd9a4301090, heap=0x7fd9a42fc2e0, log=0x7fd9a42a7b10, save_ext=0x7fd9a42fc368, ext_size=3128) at /data/src/10.3/storage/innobase/row/row0log.cc:1992
 
#9  0x000055ec6cc3ba95 in row_log_table_apply_op (thr=0x7fd9a42f64b0, new_trx_id_col=1, dup=0x7fda15377240, error=0x7fda15376fec, offsets_heap=0x7fd9a4301090, heap=0x7fd9a42fc2e0, mrec=0x7fda003db046 "aaaaaaaaaa", mrec_end=0x7fda003dbc95 "", offsets=0x7fd9a42d2c60) at /data/src/10.3/storage/innobase/row/row0log.cc:2507
 
#10 0x000055ec6cc3dbd1 in row_log_table_apply_ops (thr=0x7fd9a42f64b0, dup=0x7fda15377240, stage=0x7fd9a4025fa0) at /data/src/10.3/storage/innobase/row/row0log.cc:3023
 
#11 0x000055ec6cc3e190 in row_log_table_apply (thr=0x7fd9a42f64b0, old_table=0x7fd998015d48, table=0x7fd9a42f43a0, stage=0x7fd9a4025fa0) at /data/src/10.3/storage/innobase/row/row0log.cc:3122
 
#12 0x000055ec6cb04759 in ha_innobase::inplace_alter_table (this=0x7fd9980354a8, altered_table=0x7fd9a42f43a0, ha_alter_info=0x7fda15377570) at /data/src/10.3/storage/innobase/handler/handler0alter.cc:7082
 
#13 0x000055ec6c59dc39 in handler::ha_inplace_alter_table (this=0x7fd9980354a8, altered_table=0x7fd9a42f43a0, ha_alter_info=0x7fda15377570) at /data/src/10.3/sql/handler.h:3991
 
#14 0x000055ec6c594c1a in mysql_inplace_alter_table (thd=0x7fd9a4000b00, table_list=0x7fd9a402ae50, table=0x7fd998018540, altered_table=0x7fd9a42f43a0, ha_alter_info=0x7fda15377570, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7fda153775e0, alter_ctx=0x7fda153781a0) at /data/src/10.3/sql/sql_table.cc:7388
 
#15 0x000055ec6c59a096 in mysql_alter_table (thd=0x7fd9a4000b00, new_db=0x7fd9a402b460 "test", new_name=0x0, create_info=0x7fda15378db0, table_list=0x7fd9a402ae50, alter_info=0x7fda15378d00, order_num=0, order=0x0, ignore=false) at /data/src/10.3/sql/sql_table.cc:9395
 
#16 0x000055ec6c61a61b in Sql_cmd_alter_table::execute (this=0x7fd9a402b490, thd=0x7fd9a4000b00) at /data/src/10.3/sql/sql_alter.cc:331
 
#17 0x000055ec6c4cb688 in mysql_execute_command (thd=0x7fd9a4000b00) at /data/src/10.3/sql/sql_parse.cc:6251
 
#18 0x000055ec6c4d0098 in mysql_parse (thd=0x7fd9a4000b00, rawbuf=0x7fd9a402ad68 "ALTER TABLE t1 DROP COLUMN c1", length=29, parser_state=0x7fda1537a660, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7966
 
#19 0x000055ec6c4bda0d in dispatch_command (command=COM_QUERY, thd=0x7fd9a4000b00, packet=0x7fd9a400b161 "ALTER TABLE t1 DROP COLUMN c1", packet_length=29, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1824
 
#20 0x000055ec6c4bc441 in do_command (thd=0x7fd9a4000b00) at /data/src/10.3/sql/sql_parse.cc:1369
 
#21 0x000055ec6c615190 in do_handle_one_connection (connect=0x55ec6f0aac00) at /data/src/10.3/sql/sql_connect.cc:1420
 
#22 0x000055ec6c614f1d in handle_one_connection (arg=0x55ec6f0aac00) at /data/src/10.3/sql/sql_connect.cc:1326
 
#23 0x00007fda1a426494 in start_thread (arg=0x7fda1537b700) at pthread_create.c:333
 
#24 0x00007fda1880c93f in clone () from /lib/x86_64-linux-gnu/libc.so.6

MTR patch (same as attached)

 
diff --git a/mysql-test/include/hard_default_my.cnf b/mysql-test/include/hard_default_my.cnf
 
new file mode 100644
 
index 0000000..b89b69e
 
--- /dev/null
 
+++ b/mysql-test/include/hard_default_my.cnf
 
@@ -0,0 +1,43 @@
 
+# Copyright (c) 2017 MariaDB Corporation
 
+#
 
+# This program is free software; you can redistribute it and/or modify
 
+# it under the terms of the GNU General Public License as published by
 
+# the Free Software Foundation; version 2 of the License.
 
+#
 
+# This program is distributed in the hope that it will be useful,
 
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
 
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 
+# GNU General Public License for more details.
 
+#
 
+# You should have received a copy of the GNU General Public License
 
+# along with this program; if not, write to the Free Software
 
+# Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301  USA
 
+
 
+# Use real default settings for mysqld processes
 
+
 
+[mysqld]
 
+open-files-limit=           1024
 
+log-basename=mysqld
 
+
 
+loose-ssl-ca=@ENV.MYSQL_TEST_DIR/std_data/cacert.pem
 
+loose-ssl-cert=@ENV.MYSQL_TEST_DIR/std_data/server-cert.pem
 
+loose-ssl-key=@ENV.MYSQL_TEST_DIR/std_data/server-key.pem
 
+
 
+[embedded]
 
+local-infile
 
+
 
+[client]
 
+plugin-dir=@mysqld.1.plugin-dir
 
+
 
+[mysqltest]
 
+loose-ssl-ca=@ENV.MYSQL_TEST_DIR/std_data/cacert.pem
 
+loose-ssl-cert=@ENV.MYSQL_TEST_DIR/std_data/client-cert.pem
 
+loose-ssl-key=@ENV.MYSQL_TEST_DIR/std_data/client-key.pem
 
+
 
+[mysqld.1]
 
+
 
+#!run-master-sh
 
+
 
+[ENV]
 
+MASTER_MYPORT=           @mysqld.1.port
 
+MASTER_MYSOCK=           @mysqld.1.socket
 
diff --git a/mysql-test/lib/My/ConfigFactory.pm b/mysql-test/lib/My/ConfigFactory.pm
 
index b8ce038..dcdb534 100644
 
--- a/mysql-test/lib/My/ConfigFactory.pm
 
+++ b/mysql-test/lib/My/ConfigFactory.pm
 
@@ -37,7 +37,9 @@ sub add_opt_values {
 
 
   # add auto-options
 
   $config->insert('OPT', 'port'   => sub { fix_port($self, $config) });
 
-  $config->insert('mysqld', "loose-skip-plugin-$_" => undef) for (@::optional_plugins);
 
+  if (!$::opt_default_server_options) {
 
+    $config->insert('mysqld', "loose-skip-plugin-$_" => undef) for (@::optional_plugins);
 
+  }
 
 }
 
 
 my @pre_rules=
 
diff --git a/mysql-test/lib/mtr_cases.pm b/mysql-test/lib/mtr_cases.pm
 
index 38c52b7..26a4edd 100644
 
--- a/mysql-test/lib/mtr_cases.pm
 
+++ b/mysql-test/lib/mtr_cases.pm
 
@@ -876,7 +876,10 @@ sub collect_one_test_case {
 
     if (not $config)
 
     {
 
       # Suite has no config, autodetect which one to use
 
-      if ($tinfo->{rpl_test}) {
 
+      if ($::opt_default_server_options) {
 
+        $config= "include/hard_default_my.cnf";
 
+      }
 
+      elsif ($tinfo->{rpl_test}) {
 
         $config= "suite/rpl/my.cnf";
 
       } else {
 
         $config= "include/default_my.cnf";
 
diff --git a/mysql-test/mysql-test-run.pl b/mysql-test/mysql-test-run.pl
 
index 33d9c7b..997fb82 100755
 
--- a/mysql-test/mysql-test-run.pl
 
+++ b/mysql-test/mysql-test-run.pl
 
@@ -131,6 +131,7 @@ our $plugindir;
 
 my $path_vardir_trace;          # unix formatted opt_vardir for trace files
 
 my $opt_tmpdir;                 # Path to use for tmp/ dir
 
 my $opt_tmpdir_pid;
 
+our $opt_default_server_options;
 
 
 my $opt_start;
 
 my $opt_start_dirty;
 
@@ -1106,6 +1107,9 @@ sub command_line_setup {
 
 	     # Extra config file to append to all generated configs
 
 	     'defaults-extra-file=s'    => \&collect_option,
 
 
+	     # Use hard defaults instead of heavily modified MTR configuration
 
+	     'default-server-options'    => \$opt_default_server_options,
 
+
 
              # Control what test suites or cases to run
 
              'force+'                   => \$opt_force,
 
              'with-ndbcluster-only'     => \&collect_option,
 
@@ -3473,11 +3477,15 @@ sub sql_to_bootstrap {
 
 sub default_mysqld {
 
   # Generate new config file from template
 
   environment_setup();
 
+  my $config_template= ($opt_default_server_options
 
+      ? 'include/hard_default_my.cnf'
 
+      : 'include/default_my.cnf'
 
+  );
 
   my $config= My::ConfigFactory->new_config
 
     ( {
 
        basedir         => $basedir,
 
        testdir         => $glob_mysql_test_dir,
 
-       template_path   => "include/default_my.cnf",
 
+       template_path   => $config_template,
 
        vardir          => $opt_vardir,
 
        tmpdir          => $opt_tmpdir,
 
        baseport        => 0,
 
@@ -3509,12 +3517,14 @@ sub mysql_install_db {
 
   mtr_add_arg($args, "--basedir=%s", $install_basedir);
 
   mtr_add_arg($args, "--datadir=%s", $install_datadir);
 
   mtr_add_arg($args, "--plugin-dir=%s", $plugindir);
 
-  mtr_add_arg($args, "--default-storage-engine=myisam");
 
-  mtr_add_arg($args, "--loose-skip-plugin-$_") for @optional_plugins;
 
-  # starting from 10.0 bootstrap scripts require InnoDB
 
-  mtr_add_arg($args, "--loose-innodb");
 
-  mtr_add_arg($args, "--loose-innodb-log-file-size=5M");
 
-  mtr_add_arg($args, "--disable-sync-frm");
 
+  if (!$opt_default_server_options) {
 
+    mtr_add_arg($args, "--default-storage-engine=myisam");
 
+    mtr_add_arg($args, "--loose-skip-plugin-$_") for @optional_plugins;
 
+    # starting from 10.0 bootstrap scripts require InnoDB
 
+    mtr_add_arg($args, "--loose-innodb");
 
+    mtr_add_arg($args, "--loose-innodb-log-file-size=5M");
 
+    mtr_add_arg($args, "--disable-sync-frm");
 
+  }
 
   mtr_add_arg($args, "--tmpdir=%s", "$opt_vardir/tmp/");
 
   mtr_add_arg($args, "--core-file");
 
   mtr_add_arg($args, "--console");
 
@@ -6438,6 +6448,8 @@ Options to control what engine/variation to run:
 
                         tests
 
   defaults-extra-file=<config template> Extra config template to add to
 
                         all generated configs
 
+  default-server-options Use hard server defaults instead of the usual
 
+                        heavily adjusted defaults-file
 
   combination=<opt>     Use at least twice to run tests with specified
 
                         options to mysqld
 
   dry-run               Don't run any tests, print the list of tests



 Comments   
Comment by Marko Mäkelä [ 2018-01-09 ]

The server failed to start for me when running with the --default-server-options. But, with the patch applied, and without specifying the option, I was able to repeat it in an ASAN build, with the following addition for improved diagnostics:

diff --git a/storage/innobase/row/row0purge.cc b/storage/innobase/row/row0purge.cc
 
index f2a5d8c0c57..17ce67a5c07 100644
 
--- a/storage/innobase/row/row0purge.cc
 
+++ b/storage/innobase/row/row0purge.cc
 
@@ -705,6 +705,10 @@ row_purge_reset_trx_id(purge_node_t* node, mtr_t* mtr)
 
 		    == row_get_rec_roll_ptr(rec, index, offsets)) {
 
 			ut_ad(!rec_get_deleted_flag(rec,
 
 						    rec_offs_comp(offsets)));
 
+			DBUG_LOG("purge", "reset DB_TRX_id="
 
+				 << ib::hex(row_get_rec_trx_id(
 
+						    rec, index, offsets)));
 
+
 
 			mtr->set_named_space(index->space);
 
 			if (page_zip_des_t* page_zip
 
 			    = buf_block_get_page_zip(


ASAN_OPTIONS=disable_coredump=0,abort_on_error=1 ./mtr --mysqld=--debug=d,purge --mem innodb.mdev14840

information from row_log_table_apply_delete()

 
(gdb) p/x *log.tail.block@mrec-log.tail.block
 
$1 = {0x41, 0x5, 0x0, 0x14, 0xc0, 0xa, 0x0, 0x61, 0x61, 0x61, 0x61, 0x61, 
  0x61, 0x61, 0x61, 0x61, 0x61, 0x0, 0x0, 0x0, 0x0, 0xb, 0x12, 0x8c, 0x0, 0x0, 
  0x1, 0x3f, 0x6, 0x25, 0x80, 0x0, 0x0, 0x2, 0x80, 0x0, 0x0, 0x2, 0x80, 0x0, 
  0x0, 0x2, 0x0, 0x0, 0x0, 0xa, 0x0, 0x0, 0x0, 0x5, 0x0, 0x0, 0x0, 0x26, 0x0, 
  0x0, 0x0, 0x0, 0x0, 0x0, 0x20, 0x1, 0x43, 0x2, 0x0, 0x0, 0xc, 0x38, 0xa, 0x0}
 
(gdb) p/x *mrec_trx_id@6
 
$2 = {0x0, 0x0, 0x0, 0x0, 0xb, 0x12}
 
(gdb) p/x *rec_trx_id@6
 
$3 = {0x0, 0x0, 0x0, 0x0, 0x0, 0x0}
 
(gdb) p/x log->min_trx
 
$4 = 0xb0f

The assertion fails when replaying the second log record: ROW_T_DELETE = 0x43 after ROW_T_INSERT = 0x41. Because the mrec_trx_id is after the log->min_trx, it was not normalized to 0.
On the other hand, the latest purge message is for a much older tranasction:

mysqld.1.err

 
?func: purge: reset DB_TRX_id=0xb0a

The only concurrent activity with the table-rebuilding online ALTER is the INSERT;ROLLBACK. At the time the assertion fails, the only active transaction is the one that is executing the ALTER TABLE, with trx->id=0xb0f. The next available identifier is trx_sys->max_trx_id=0xb14.
The INSERT statement should roll back at the first inserted record because of a duplicate primary key c4(10)='aaaaaaaaaa'. The INSERT transaction should have had trx->id=0xb12, trx->no=0xb13. In the first ROW_T_INSERT record we indeed have DB_TRX_ID=0xb12.

But, we have another ROW_T_INSERT record in the log. Why did the INSERT of the first record not fail?
I wrote a debug version of this test, and indeed the insert of the first row will not fail. But the test will not crash either.

--source include/have_innodb.inc
 
--source include/have_debug.inc
 
--source include/have_debug_sync.inc
 
 
 
--connect (con1,localhost,root,,test)
 
CREATE TABLE t1 (c1 INT, c4 TEXT, PRIMARY KEY (c4(10))) ENGINE=InnoDB;
 
INSERT INTO t1 (c1,c4) VALUES (1,REPEAT('a',11));
 
ALTER TABLE t1 ADD COLUMN c5 INT;
 
UPDATE t1 SET c5 = c1;
 
--connection default
 
SET DEBUG_SYNC = 'row_log_table_apply1_before SIGNAL built WAIT_FOR fail';
 
send ALTER TABLE t1 DROP COLUMN c1;
 
--connection con1
 
SET DEBUG_SYNC = 'now WAIT_FOR built';
 
BEGIN;
 
SELECT * FROM t1;
 
INSERT INTO t1 SET c1=2, c4=REPEAT('a',12);
 
--error ER_DUP_ENTRY
 
INSERT INTO t1 SET c1=3, c4=REPEAT('a',13);
 
SET DEBUG_SYNC = 'now SIGNAL fail';
 
ROLLBACK;
 
--disconnect con1
 
--connection default
 
--error ER_DUP_ENTRY
 
--reap
 
SET DEBUG_SYNC = 'RESET';
 
DROP TABLE t1;

Comment by Marko Mäkelä [ 2018-01-09 ]

I filed the data corruption bug MDEV-14897 for a subset of the test. It is possible that that bug creates a 'garbage in, garbage out' situation that was caught by the assertion failure reported in this bug.

Comment by Marko Mäkelä [ 2018-01-09 ]

This seems to depend on the bug MDEV-14837/MDEV-14897. If I add -mysqld=-innodb-default-row-format=redundant to the mysql-test-run.pl options, then the test will pass for me (tried 2×50 loops). The base bug does not affect ROW_FORMAT=REDUNDANT tables.

Comment by Marko Mäkelä [ 2018-01-09 ]

This seems to be caused by the MDEV-11369 regression that was fixed in MDEV-14837.

Generated at Thu Feb 08 08:16:41 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.