Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-14822

binlog.binlog_killed fails with wrong result

Details

    Description

      In travis, we build the server with the following config line:

      cmake . -DCMAKE_BUILD_TYPE=RelWithDebInfo -DWITH_SSL=system -DWITH_ZLIB=system -DPLUGIN_AWS_KEY_MANAGEMENT=DYNAMIC -DAWS_SDK_EXTERNAL_PROJECT=ON -DWITHOUT_MROONGA_STORAGE_ENGINE=True

      Due to how travis environment is set up, the test fails when compiling using clang 5.0.1 or with GCC 6.3.0

      Locally, I was able the reproduce it with the following failure:

      +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject	2017-12-30 15:35:00.079888311 +0200
      		 
      @@ -264,12 +264,6 @@
      		 
       master-bin.000002	#	Intvar	#	#	INSERT_ID=7
      		 
       master-bin.000002	#	Query	#	#	use `test`; INSERT INTO t2 VALUES (NULL, 1)
      		 
       master-bin.000002	#	Query	#	#	COMMIT
      		 
      -master-bin.000002	#	Gtid	#	#	BEGIN GTID #-#-#
      		 
      -master-bin.000002	#	Intvar	#	#	INSERT_ID=8
      		 
      -master-bin.000002	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (NULL, 1)
      		 
      -master-bin.000002	#	Intvar	#	#	INSERT_ID=9
      		 
      -master-bin.000002	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (NULL, 1)
      		 
      -master-bin.000002	#	Query	#	#	ROLLBACK
      		 
       connection default;
      		 
       disconnect con1;
      		 
       disconnect con2;
      		 
       
      		 
      mysqltest: Result length mismatch

      However, at times the failure is like this:

      57589899 +0200
      		 
      +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject	2017-12-30 15:36:12.180412517 +0200
      		 
      @@ -198,10 +198,6 @@
      		 
       master-bin.000002	#	Intvar	#	#	INSERT_ID=3
      		 
       master-bin.000002	#	Query	#	#	use `test`; INSERT INTO t2 VALUES (NULL, 1)
      		 
       master-bin.000002	#	Query	#	#	COMMIT
      		 
      -master-bin.000002	#	Gtid	#	#	BEGIN GTID #-#-#
      		 
      -master-bin.000002	#	Intvar	#	#	INSERT_ID=4
      		 
      -master-bin.000002	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (NULL, 1)
      		 
      -master-bin.000002	#	Query	#	#	ROLLBACK
      		 
       disconnect con3;
      		 
       connect  con3, localhost, root,,;
      		 
       connection con3;
      		 
      @@ -264,12 +260,6 @@
      		 
       master-bin.000002	#	Intvar	#	#	INSERT_ID=7
      		 
       master-bin.000002	#	Query	#	#	use `test`; INSERT INTO t2 VALUES (NULL, 1)
      		 
       master-bin.000002	#	Query	#	#	COMMIT
      		 
      -master-bin.000002	#	Gtid	#	#	BEGIN GTID #-#-#
      		 
      -master-bin.000002	#	Intvar	#	#	INSERT_ID=8
      		 
      -master-bin.000002	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (NULL, 1)
      		 
      -master-bin.000002	#	Intvar	#	#	INSERT_ID=9
      		 
      -master-bin.000002	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (NULL, 1)
      		 
      -master-bin.000002	#	Query	#	#	ROLLBACK
      		 
       connection default;
      		 
       disconnect con1;
      		 
       disconnect con2;
      		 
       
      		 
      mysqltest: Result length mismatch

      The common denominator it seems is that when running a transaction with a transactional storage engine (Innodb), in some cases we don't immediately flush to the binlog. If the kill query signal happens earlier, we don't write the transaction at all (including the ROLLBACK event). The problem is that the test doesn't always fail. With --repeat=100, I was able to get it to reproduce once every 3-4 runs.

      Ultimately, the binlog contents are valid either way, but the test needs to be stabilized in some way.

      The sequence of queries is roughly this:

      create table t1 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=InnoDB;
      		 
      create table t2 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=MyISAM;
      		 
      flush logs;
      		 
      connect  con3, localhost, root,,;
      		 
      connection con3;
      		 
      BEGIN;
      		 
      INSERT INTO t2 VALUES (NULL, 1);
      		 
      INSERT INTO t1 VALUES (NULL, 1);
      		 
      connection con3;
      		 
      KILL $id_of_con3;
      		 
      -- Since t2 is non-transactional, the binlog should have those rows, however t1 changes should be rolled back.

      Attachments

        Activity

          Ascending order - Click to sort in descending order
          cvicentiu Vicențiu Ciorbaru created issue -
          cvicentiu Vicențiu Ciorbaru made changes -
          Field Original Value New Value
          Description In travis, we build the server with the following config line:

          {noformat}
          cmake . -DCMAKE_BUILD_TYPE=RelWithDebInfo -DWITH_SSL=system -DWITH_ZLIB=system -DPLUGIN_AWS_KEY_MANAGEMENT=DYNAMIC -DAWS_SDK_EXTERNAL_PROJECT=ON -DWITHOUT_MROONGA_STORAGE_ENGINE=True
          {noformat}

          Due to how travis environment is set up, the test always seems to fail if using clang 5.0.1.

          Locally, I was able the reproduce it with the following failure:

          {noformat}
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:35:00.079888311 +0200
          @@ -264,12 +264,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          However, at times the failure is like this:

          {noformat}
          57589899 +0200
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:36:12.180412517 +0200
          @@ -198,10 +198,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=3
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=4
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           disconnect con3;
           connect con3, localhost, root,,;
           connection con3;
          @@ -264,12 +260,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          The common denominator it seems is that when running a transaction with a transactional storage engine (Innodb), in some cases we don't immediately flush to the binlog. If the kill query signal happens earlier, we don't write the transaction at all (including the ROLLBACK event). The problem is that the test doesn't always fail. With --repeat=100, I was able to get it to reproduce once every 3-4 runs.

          Ultimately, the binlog contents are valid either way, but the test needs to be stabilized in some way.

          The sequence of queries is roughly this:

          {code:sql}
          create table t1 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=InnoDB;
          create table t2 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=MyISAM;
          flush logs;
          connect con3, localhost, root,,;
          connection con3;
          MI: MyISAM, INNODB
          BEGIN;
          INSERT INTO t2 VALUES (NULL, 1);
          INSERT INTO t1 VALUES (NULL, 1);
          connection con3;
          KILL $id_of_con3;
          {code}
          		In travis, we build the server with the following config line:

          {noformat}
          cmake . -DCMAKE_BUILD_TYPE=RelWithDebInfo -DWITH_SSL=system -DWITH_ZLIB=system -DPLUGIN_AWS_KEY_MANAGEMENT=DYNAMIC -DAWS_SDK_EXTERNAL_PROJECT=ON -DWITHOUT_MROONGA_STORAGE_ENGINE=True
          {noformat}

          Due to how travis environment is set up, the test always seems to fail if using clang 5.0.1.

          Locally, I was able the reproduce it with the following failure:

          {noformat}
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:35:00.079888311 +0200
          @@ -264,12 +264,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          However, at times the failure is like this:

          {noformat}
          57589899 +0200
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:36:12.180412517 +0200
          @@ -198,10 +198,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=3
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=4
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           disconnect con3;
           connect con3, localhost, root,,;
           connection con3;
          @@ -264,12 +260,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          The common denominator it seems is that when running a transaction with a transactional storage engine (Innodb), in some cases we don't immediately flush to the binlog. If the kill query signal happens earlier, we don't write the transaction at all (including the ROLLBACK event). The problem is that the test doesn't always fail. With --repeat=100, I was able to get it to reproduce once every 3-4 runs.

          Ultimately, the binlog contents are valid either way, but the test needs to be stabilized in some way.

          The sequence of queries is roughly this:

          {code:sql}
          create table t1 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=InnoDB;
          create table t2 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=MyISAM;
          flush logs;
          connect con3, localhost, root,,;
          connection con3;
          BEGIN;
          INSERT INTO t2 VALUES (NULL, 1);
          INSERT INTO t1 VALUES (NULL, 1);
          connection con3;
          KILL $id_of_con3;
          {code}
          elenst Elena Stepanova made changes -
          Component/s Tests [ 10800 ]
          cvicentiu Vicențiu Ciorbaru made changes -
          Description In travis, we build the server with the following config line:

          {noformat}
          cmake . -DCMAKE_BUILD_TYPE=RelWithDebInfo -DWITH_SSL=system -DWITH_ZLIB=system -DPLUGIN_AWS_KEY_MANAGEMENT=DYNAMIC -DAWS_SDK_EXTERNAL_PROJECT=ON -DWITHOUT_MROONGA_STORAGE_ENGINE=True
          {noformat}

          Due to how travis environment is set up, the test always seems to fail if using clang 5.0.1.

          Locally, I was able the reproduce it with the following failure:

          {noformat}
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:35:00.079888311 +0200
          @@ -264,12 +264,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          However, at times the failure is like this:

          {noformat}
          57589899 +0200
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:36:12.180412517 +0200
          @@ -198,10 +198,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=3
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=4
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           disconnect con3;
           connect con3, localhost, root,,;
           connection con3;
          @@ -264,12 +260,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          The common denominator it seems is that when running a transaction with a transactional storage engine (Innodb), in some cases we don't immediately flush to the binlog. If the kill query signal happens earlier, we don't write the transaction at all (including the ROLLBACK event). The problem is that the test doesn't always fail. With --repeat=100, I was able to get it to reproduce once every 3-4 runs.

          Ultimately, the binlog contents are valid either way, but the test needs to be stabilized in some way.

          The sequence of queries is roughly this:

          {code:sql}
          create table t1 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=InnoDB;
          create table t2 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=MyISAM;
          flush logs;
          connect con3, localhost, root,,;
          connection con3;
          BEGIN;
          INSERT INTO t2 VALUES (NULL, 1);
          INSERT INTO t1 VALUES (NULL, 1);
          connection con3;
          KILL $id_of_con3;
          {code}
          		In travis, we build the server with the following config line:

          {noformat}
          cmake . -DCMAKE_BUILD_TYPE=RelWithDebInfo -DWITH_SSL=system -DWITH_ZLIB=system -DPLUGIN_AWS_KEY_MANAGEMENT=DYNAMIC -DAWS_SDK_EXTERNAL_PROJECT=ON -DWITHOUT_MROONGA_STORAGE_ENGINE=True
          {noformat}

          Due to how travis environment is set up, the test always seems to fail if using clang 5.0.1.

          Locally, I was able the reproduce it with the following failure:

          {noformat}
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:35:00.079888311 +0200
          @@ -264,12 +264,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          However, at times the failure is like this:

          {noformat}
          57589899 +0200
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:36:12.180412517 +0200
          @@ -198,10 +198,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=3
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=4
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           disconnect con3;
           connect con3, localhost, root,,;
           connection con3;
          @@ -264,12 +260,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          The common denominator it seems is that when running a transaction with a transactional storage engine (Innodb), in some cases we don't immediately flush to the binlog. If the kill query signal happens earlier, we don't write the transaction at all (including the ROLLBACK event). The problem is that the test doesn't always fail. With --repeat=100, I was able to get it to reproduce once every 3-4 runs.

          Ultimately, the binlog contents are valid either way, but the test needs to be stabilized in some way.

          The sequence of queries is roughly this:

          {code:sql}
          create table t1 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=InnoDB;
          create table t2 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=MyISAM;
          flush logs;
          connect con3, localhost, root,,;
          connection con3;
          BEGIN;
          INSERT INTO t2 VALUES (NULL, 1);
          INSERT INTO t1 VALUES (NULL, 1);
          connection con3;
          KILL $id_of_con3;
          -- Since t2 is non-transactional, the binlog should have those rows, however t1 changes should be rolled back.
          {code}
          cvicentiu Vicențiu Ciorbaru made changes -
          Description In travis, we build the server with the following config line:

          {noformat}
          cmake . -DCMAKE_BUILD_TYPE=RelWithDebInfo -DWITH_SSL=system -DWITH_ZLIB=system -DPLUGIN_AWS_KEY_MANAGEMENT=DYNAMIC -DAWS_SDK_EXTERNAL_PROJECT=ON -DWITHOUT_MROONGA_STORAGE_ENGINE=True
          {noformat}

          Due to how travis environment is set up, the test always seems to fail if using clang 5.0.1.

          Locally, I was able the reproduce it with the following failure:

          {noformat}
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:35:00.079888311 +0200
          @@ -264,12 +264,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          However, at times the failure is like this:

          {noformat}
          57589899 +0200
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:36:12.180412517 +0200
          @@ -198,10 +198,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=3
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=4
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           disconnect con3;
           connect con3, localhost, root,,;
           connection con3;
          @@ -264,12 +260,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          The common denominator it seems is that when running a transaction with a transactional storage engine (Innodb), in some cases we don't immediately flush to the binlog. If the kill query signal happens earlier, we don't write the transaction at all (including the ROLLBACK event). The problem is that the test doesn't always fail. With --repeat=100, I was able to get it to reproduce once every 3-4 runs.

          Ultimately, the binlog contents are valid either way, but the test needs to be stabilized in some way.

          The sequence of queries is roughly this:

          {code:sql}
          create table t1 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=InnoDB;
          create table t2 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=MyISAM;
          flush logs;
          connect con3, localhost, root,,;
          connection con3;
          BEGIN;
          INSERT INTO t2 VALUES (NULL, 1);
          INSERT INTO t1 VALUES (NULL, 1);
          connection con3;
          KILL $id_of_con3;
          -- Since t2 is non-transactional, the binlog should have those rows, however t1 changes should be rolled back.
          {code}
          		In travis, we build the server with the following config line:

          {noformat}
          cmake . -DCMAKE_BUILD_TYPE=RelWithDebInfo -DWITH_SSL=system -DWITH_ZLIB=system -DPLUGIN_AWS_KEY_MANAGEMENT=DYNAMIC -DAWS_SDK_EXTERNAL_PROJECT=ON -DWITHOUT_MROONGA_STORAGE_ENGINE=True
          {noformat}

          Due to how travis environment is set up, the test always seems to fail when using clang 5.0.1.

          Locally, I was able the reproduce it with the following failure:

          {noformat}
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:35:00.079888311 +0200
          @@ -264,12 +264,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          However, at times the failure is like this:

          {noformat}
          57589899 +0200
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:36:12.180412517 +0200
          @@ -198,10 +198,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=3
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=4
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           disconnect con3;
           connect con3, localhost, root,,;
           connection con3;
          @@ -264,12 +260,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          The common denominator it seems is that when running a transaction with a transactional storage engine (Innodb), in some cases we don't immediately flush to the binlog. If the kill query signal happens earlier, we don't write the transaction at all (including the ROLLBACK event). The problem is that the test doesn't always fail. With --repeat=100, I was able to get it to reproduce once every 3-4 runs.

          Ultimately, the binlog contents are valid either way, but the test needs to be stabilized in some way.

          The sequence of queries is roughly this:

          {code:sql}
          create table t1 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=InnoDB;
          create table t2 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=MyISAM;
          flush logs;
          connect con3, localhost, root,,;
          connection con3;
          BEGIN;
          INSERT INTO t2 VALUES (NULL, 1);
          INSERT INTO t1 VALUES (NULL, 1);
          connection con3;
          KILL $id_of_con3;
          -- Since t2 is non-transactional, the binlog should have those rows, however t1 changes should be rolled back.
          {code}
          cvicentiu Vicențiu Ciorbaru made changes -
          Description In travis, we build the server with the following config line:

          {noformat}
          cmake . -DCMAKE_BUILD_TYPE=RelWithDebInfo -DWITH_SSL=system -DWITH_ZLIB=system -DPLUGIN_AWS_KEY_MANAGEMENT=DYNAMIC -DAWS_SDK_EXTERNAL_PROJECT=ON -DWITHOUT_MROONGA_STORAGE_ENGINE=True
          {noformat}

          Due to how travis environment is set up, the test always seems to fail when using clang 5.0.1.

          Locally, I was able the reproduce it with the following failure:

          {noformat}
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:35:00.079888311 +0200
          @@ -264,12 +264,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          However, at times the failure is like this:

          {noformat}
          57589899 +0200
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:36:12.180412517 +0200
          @@ -198,10 +198,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=3
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=4
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           disconnect con3;
           connect con3, localhost, root,,;
           connection con3;
          @@ -264,12 +260,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          The common denominator it seems is that when running a transaction with a transactional storage engine (Innodb), in some cases we don't immediately flush to the binlog. If the kill query signal happens earlier, we don't write the transaction at all (including the ROLLBACK event). The problem is that the test doesn't always fail. With --repeat=100, I was able to get it to reproduce once every 3-4 runs.

          Ultimately, the binlog contents are valid either way, but the test needs to be stabilized in some way.

          The sequence of queries is roughly this:

          {code:sql}
          create table t1 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=InnoDB;
          create table t2 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=MyISAM;
          flush logs;
          connect con3, localhost, root,,;
          connection con3;
          BEGIN;
          INSERT INTO t2 VALUES (NULL, 1);
          INSERT INTO t1 VALUES (NULL, 1);
          connection con3;
          KILL $id_of_con3;
          -- Since t2 is non-transactional, the binlog should have those rows, however t1 changes should be rolled back.
          {code}
          		In travis, we build the server with the following config line:

          {noformat}
          cmake . -DCMAKE_BUILD_TYPE=RelWithDebInfo -DWITH_SSL=system -DWITH_ZLIB=system -DPLUGIN_AWS_KEY_MANAGEMENT=DYNAMIC -DAWS_SDK_EXTERNAL_PROJECT=ON -DWITHOUT_MROONGA_STORAGE_ENGINE=True
          {noformat}

          Due to how travis environment is set up, the test fails when compiling using clang 5.0.1 or with GCC 6.3.0

          Locally, I was able the reproduce it with the following failure:

          {noformat}
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:35:00.079888311 +0200
          @@ -264,12 +264,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          However, at times the failure is like this:

          {noformat}
          57589899 +0200
          +++ /home/vicentiu/Workspace/MariaDB-10.3/mysql-test/suite/binlog/r/binlog_killed.reject 2017-12-30 15:36:12.180412517 +0200
          @@ -198,10 +198,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=3
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=4
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           disconnect con3;
           connect con3, localhost, root,,;
           connection con3;
          @@ -264,12 +260,6 @@
           master-bin.000002 # Intvar # # INSERT_ID=7
           master-bin.000002 # Query # # use `test`; INSERT INTO t2 VALUES (NULL, 1)
           master-bin.000002 # Query # # COMMIT
          -master-bin.000002 # Gtid # # BEGIN GTID #-#-#
          -master-bin.000002 # Intvar # # INSERT_ID=8
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Intvar # # INSERT_ID=9
          -master-bin.000002 # Query # # use `test`; INSERT INTO t1 VALUES (NULL, 1)
          -master-bin.000002 # Query # # ROLLBACK
           connection default;
           disconnect con1;
           disconnect con2;

          mysqltest: Result length mismatch
          {noformat}

          The common denominator it seems is that when running a transaction with a transactional storage engine (Innodb), in some cases we don't immediately flush to the binlog. If the kill query signal happens earlier, we don't write the transaction at all (including the ROLLBACK event). The problem is that the test doesn't always fail. With --repeat=100, I was able to get it to reproduce once every 3-4 runs.

          Ultimately, the binlog contents are valid either way, but the test needs to be stabilized in some way.

          The sequence of queries is roughly this:

          {code:sql}
          create table t1 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=InnoDB;
          create table t2 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=MyISAM;
          flush logs;
          connect con3, localhost, root,,;
          connection con3;
          BEGIN;
          INSERT INTO t2 VALUES (NULL, 1);
          INSERT INTO t1 VALUES (NULL, 1);
          connection con3;
          KILL $id_of_con3;
          -- Since t2 is non-transactional, the binlog should have those rows, however t1 changes should be rolled back.
          {code}
          monty Michael Widenius made changes -
          Assignee Vicentiu Ciorbaru [ cvicentiu ] Michael Widenius [ monty ]
          monty Michael Widenius made changes -
          issue.field.resolutiondate 2018-01-10 13:04:59.0 2018-01-10 13:04:59.415
          monty Michael Widenius made changes -
          Fix Version/s 10.3.4 [ 22904 ]
          Fix Version/s 10.3 [ 22126 ]
          Resolution Fixed [ 1 ]
          Status Open [ 1 ] Closed [ 6 ]
          serg Sergei Golubchik made changes -
          Workflow MariaDB v3 [ 84672 ] MariaDB v4 [ 153474 ]

          People

            monty Michael Widenius
            cvicentiu Vicențiu Ciorbaru
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Git Integration

                Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.