Details
Description
A similar failure happened in buildbot, but long time ago (almost a year):
c9c689e1a37316593067f07ee248f858 kvm-deb-jessie-amd64 |
main.mysqlbinlog_row_compressed w4 [ fail ]
|
Test ended at 2019-08-14 19:26:00
|
|
CURRENT_TEST: main.mysqlbinlog_row_compressed
|
--- /usr/share/mysql/mysql-test/main/mysqlbinlog_row_compressed.result 2019-08-14 17:48:23.000000000 -0400
|
+++ /dev/shm/var/4/log/mysqlbinlog_row_compressed.reject 2019-08-14 19:26:00.375717628 -0400
|
@@ -29,10 +29,10 @@
|
/*!100001 SET @@session.server_id=1*//*!*/;
|
/*!100001 SET @@session.gtid_seq_no=1*//*!*/;
|
# at 371
|
-#<date> server id 1 end_log_pos 533 CRC32 XXX Query_compressed thread_id=5 exec_time=x error_code=0
|
+#<date> server id 1 end_log_pos 533 CRC32 XXX Query_compressed thread_id=9 exec_time=x error_code=0
|
use `test`/*!*/;
|
SET TIMESTAMP=X/*!*/;
|
-SET @@session.pseudo_thread_id=5/*!*/;
|
+SET @@session.pseudo_thread_id=9/*!*/;
|
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/*!*/;
|
SET @@session.sql_mode=1411383296/*!*/;
|
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
|
@@ -46,7 +46,7 @@
|
#<date> server id 1 end_log_pos 575 CRC32 XXX GTID 0-1-2 ddl
|
/*!100001 SET @@session.gtid_seq_no=2*//*!*/;
|
# at 575
|
-#<date> server id 1 end_log_pos 727 CRC32 XXX Query_compressed thread_id=5 exec_time=x error_code=0
|
+#<date> server id 1 end_log_pos 727 CRC32 XXX Query_compressed thread_id=9 exec_time=x error_code=0
|
SET TIMESTAMP=X/*!*/;
|
CREATE TABLE t2 (pk INT PRIMARY KEY, f1 INT, f2 INT, f3 INT, f4 INT, f5 MEDIUMINT, f6 INT, f7 INT, f8 char(1))
|
/*!*/;
|
@@ -61,7 +61,7 @@
|
#Q> INSERT INTO t1 VALUES (10, 1, 2, 3, 4, 5, 6, 7, "")
|
#<date> server id 1 end_log_pos 899 CRC32 XXX Table_map: `test`.`t1` mapped to number num
|
# at 899
|
-#<date> server id 1 end_log_pos 967 CRC32 XXX Write_compressed_rows: table id 32 flags: STMT_END_F
|
+#<date> server id 1 end_log_pos 967 CRC32 XXX Write_compressed_rows: table id 40 flags: STMT_END_F
|
### INSERT INTO `test`.`t1`
|
### SET
|
### @1=10 /* INT meta=0 nullable=0 is_null=0 */
|
@@ -75,7 +75,7 @@
|
### @9='' /* STRING(1) meta=65025 nullable=1 is_null=0 */
|
# Number of rows: 1
|
# at 967
|
-#<date> server id 1 end_log_pos 1040 CRC32 XXX Query thread_id=5 exec_time=x error_code=0
|
+#<date> server id 1 end_log_pos 1040 CRC32 XXX Query thread_id=9 exec_time=x error_code=0
|
SET TIMESTAMP=X/*!*/;
|
COMMIT
|
/*!*/;
|
@@ -90,7 +90,7 @@
|
#Q> INSERT INTO t1 VALUES (11, 1, 2, 3, 4, 5, 6, 7, NULL)
|
#<date> server id 1 end_log_pos 1214 CRC32 XXX Table_map: `test`.`t1` mapped to number num
|
# at 1214
|
-#<date> server id 1 end_log_pos 1281 CRC32 XXX Write_compressed_rows: table id 32 flags: STMT_END_F
|
+#<date> server id 1 end_log_pos 1281 CRC32 XXX Write_compressed_rows: table id 40 flags: STMT_END_F
|
### INSERT INTO `test`.`t1`
|
### SET
|
### @1=11 /* INT meta=0 nullable=0 is_null=0 */
|
@@ -104,7 +104,7 @@
|
### @9=NULL /* STRING(1) meta=65025 nullable=1 is_null=1 */
|
# Number of rows: 1
|
# at 1281
|
-#<date> server id 1 end_log_pos 1354 CRC32 XXX Query thread_id=5 exec_time=x error_code=0
|
+#<date> server id 1 end_log_pos 1354 CRC32 XXX Query thread_id=9 exec_time=x error_code=0
|
SET TIMESTAMP=X/*!*/;
|
COMMIT
|
/*!*/;
|
@@ -119,7 +119,7 @@
|
#Q> INSERT INTO t1 VALUES (12, 1, 2, 3, NULL, 5, 6, 7, "A")
|
#<date> server id 1 end_log_pos 1530 CRC32 XXX Table_map: `test`.`t1` mapped to number num
|
# at 1530
|
-#<date> server id 1 end_log_pos 1596 CRC32 XXX Write_compressed_rows: table id 32 flags: STMT_END_F
|
+#<date> server id 1 end_log_pos 1596 CRC32 XXX Write_compressed_rows: table id 40 flags: STMT_END_F
|
### INSERT INTO `test`.`t1`
|
### SET
|
### @1=12 /* INT meta=0 nullable=0 is_null=0 */
|
@@ -133,7 +133,7 @@
|
### @9='A' /* STRING(1) meta=65025 nullable=1 is_null=0 */
|
# Number of rows: 1
|
# at 1596
|
-#<date> server id 1 end_log_pos 1669 CRC32 XXX Query thread_id=5 exec_time=x error_code=0
|
+#<date> server id 1 end_log_pos 1669 CRC32 XXX Query thread_id=9 exec_time=x error_code=0
|
SET TIMESTAMP=X/*!*/;
|
COMMIT
|
/*!*/;
|
@@ -148,7 +148,7 @@
|
#Q> INSERT INTO t1 VALUES (13, 1, 2, 3, 0, 5, 6, 7, "A")
|
#<date> server id 1 end_log_pos 1842 CRC32 XXX Table_map: `test`.`t1` mapped to number num
|
# at 1842
|
-#<date> server id 1 end_log_pos 1909 CRC32 XXX Write_compressed_rows: table id 32 flags: STMT_END_F
|
+#<date> server id 1 end_log_pos 1909 CRC32 XXX Write_compressed_rows: table id 40 flags: STMT_END_F
|
### INSERT INTO `test`.`t1`
|
### SET
|
### @1=13 /* INT meta=0 nullable=0 is_null=0 */
|
@@ -162,7 +162,7 @@
|
### @9='A' /* STRING(1) meta=65025 nullable=1 is_null=0 */
|
# Number of rows: 1
|
# at 1909
|
-#<date> server id 1 end_log_pos 1982 CRC32 XXX Query thread_id=5 exec_time=x error_code=0
|
+#<date> server id 1 end_log_pos 1982 CRC32 XXX Query thread_id=9 exec_time=x error_code=0
|
SET TIMESTAMP=X/*!*/;
|
COMMIT
|
/*!*/;
|
@@ -177,7 +177,7 @@
|
#Q> INSERT INTO t2 SELECT * FROM t1
|
#<date> server id 1 end_log_pos 2134 CRC32 XXX Table_map: `test`.`t2` mapped to number num
|
# at 2134
|
-#<date> server id 1 end_log_pos 2225 CRC32 XXX Write_compressed_rows: table id 33 flags: STMT_END_F
|
+#<date> server id 1 end_log_pos 2225 CRC32 XXX Write_compressed_rows: table id 41 flags: STMT_END_F
|
### INSERT INTO `test`.`t2`
|
### SET
|
### @1=10 /* INT meta=0 nullable=0 is_null=0 */
|
@@ -224,7 +224,7 @@
|
### @9='A' /* STRING(1) meta=65025 nullable=1 is_null=0 */
|
# Number of rows: 4
|
# at 2225
|
-#<date> server id 1 end_log_pos 2298 CRC32 XXX Query thread_id=5 exec_time=x error_code=0
|
+#<date> server id 1 end_log_pos 2298 CRC32 XXX Query thread_id=9 exec_time=x error_code=0
|
SET TIMESTAMP=X/*!*/;
|
COMMIT
|
/*!*/;
|
@@ -239,7 +239,7 @@
|
#Q> UPDATE t2 SET f4=5 WHERE f4>0 or f4 is NULL
|
#<date> server id 1 end_log_pos 2462 CRC32 XXX Table_map: `test`.`t2` mapped to number num
|
# at 2462
|
-#<date> server id 1 end_log_pos 2561 CRC32 XXX Update_compressed_rows: table id 33 flags: STMT_END_F
|
+#<date> server id 1 end_log_pos 2561 CRC32 XXX Update_compressed_rows: table id 41 flags: STMT_END_F
|
### UPDATE `test`.`t2`
|
### WHERE
|
### @1=10 /* INT meta=0 nullable=0 is_null=0 */
|
@@ -305,7 +305,7 @@
|
### @9='A' /* STRING(1) meta=65025 nullable=1 is_null=0 */
|
# Number of rows: 3
|
# at 2561
|
-#<date> server id 1 end_log_pos 2634 CRC32 XXX Query thread_id=5 exec_time=x error_code=0
|
+#<date> server id 1 end_log_pos 2634 CRC32 XXX Query thread_id=9 exec_time=x error_code=0
|
SET TIMESTAMP=X/*!*/;
|
COMMIT
|
/*!*/;
|
@@ -320,7 +320,7 @@
|
#Q> DELETE FROM t1
|
#<date> server id 1 end_log_pos 2769 CRC32 XXX Table_map: `test`.`t1` mapped to number num
|
# at 2769
|
-#<date> server id 1 end_log_pos 2861 CRC32 XXX Delete_compressed_rows: table id 32 flags: STMT_END_F
|
+#<date> server id 1 end_log_pos 2861 CRC32 XXX Delete_compressed_rows: table id 40 flags: STMT_END_F
|
### DELETE FROM `test`.`t1`
|
### WHERE
|
### @1=10 /* INT meta=0 nullable=0 is_null=0 */
|
@@ -367,7 +367,7 @@
|
### @9='A' /* STRING(1) meta=65025 nullable=1 is_null=0 */
|
# Number of rows: 4
|
# at 2861
|
-#<date> server id 1 end_log_pos 2934 CRC32 XXX Query thread_id=5 exec_time=x error_code=0
|
+#<date> server id 1 end_log_pos 2934 CRC32 XXX Query thread_id=9 exec_time=x error_code=0
|
SET TIMESTAMP=X/*!*/;
|
COMMIT
|
/*!*/;
|
@@ -382,7 +382,7 @@
|
#Q> DELETE FROM t2
|
#<date> server id 1 end_log_pos 3069 CRC32 XXX Table_map: `test`.`t2` mapped to number num
|
# at 3069
|
-#<date> server id 1 end_log_pos 3154 CRC32 XXX Delete_compressed_rows: table id 33 flags: STMT_END_F
|
+#<date> server id 1 end_log_pos 3154 CRC32 XXX Delete_compressed_rows: table id 41 flags: STMT_END_F
|
### DELETE FROM `test`.`t2`
|
### WHERE
|
### @1=10 /* INT meta=0 nullable=0 is_null=0 */
|
@@ -429,7 +429,7 @@
|
### @9='A' /* STRING(1) meta=65025 nullable=1 is_null=0 */
|
# Number of rows: 4
|
# at 3154
|
-#<date> server id 1 end_log_pos 3227 CRC32 XXX Query thread_id=5 exec_time=x error_code=0
|
+#<date> server id 1 end_log_pos 3227 CRC32 XXX Query thread_id=9 exec_time=x error_code=0
|
SET TIMESTAMP=X/*!*/;
|
COMMIT
|
/*!*/;
|
|
mysqltest: Result content mismatch
|
Now it happened on my local build, too
10.5 e341fb0d |
main.mysqlbinlog_row_compressed w1 [ fail ]
|
Test ended at 2020-06-19 20:13:56
|
|
CURRENT_TEST: main.mysqlbinlog_row_compressed
|
--- /data/bld/10.5.4-unstable-tests/mysql-test/main/mysqlbinlog_row_compressed.result 2020-06-15 14:40:52.000000000 +0300
|
+++ /data/bld/10.5.4-unstable-tests/mysql-test/main/mysqlbinlog_row_compressed.reject 2020-06-19 20:13:55.883648703 +0300
|
@@ -29,10 +29,10 @@
|
/*!100001 SET @@session.server_id=1*//*!*/;
|
/*!100001 SET @@session.gtid_seq_no=1*//*!*/;
|
# at 371
|
-#<date> server id 1 end_log_pos 533 CRC32 XXX Query_compressed thread_id=5 exec_time=x error_code=0
|
+#<date> server id 1 end_log_pos 533 CRC32 XXX Query_compressed thread_id=9 exec_time=x error_code=0
|
use `test`/*!*/;
|
SET TIMESTAMP=X/*!*/;
|
-SET @@session.pseudo_thread_id=5/*!*/;
|
+SET @@session.pseudo_thread_id=9/*!*/;
|
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1, @@session.sql_if_exists=0/*!*/;
|
SET @@session.sql_mode=#/*!*/;
|
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
|
@@ -46,7 +46,7 @@
|
#<date> server id 1 end_log_pos 575 CRC32 XXX GTID 0-1-2 ddl
|
/*!100001 SET @@session.gtid_seq_no=2*//*!*/;
|
# at 575
|
-#<date> server id 1 end_log_pos 727 CRC32 XXX Query_compressed thread_id=5 exec_time=x error_code=0
|
+#<date> server id 1 end_log_pos 727 CRC32 XXX Query_compressed thread_id=9 exec_time=x error_code=0
|
SET TIMESTAMP=X/*!*/;
|
CREATE TABLE t2 (pk INT PRIMARY KEY, f1 INT, f2 INT, f3 INT, f4 INT, f5 MEDIUMINT, f6 INT, f7 INT, f8 char(1))
|
/*!*/;
|
@@ -61,7 +61,7 @@
|
#Q> INSERT INTO t1 VALUES (10, 1, 2, 3, 4, 5, 6, 7, "")
|
#<date> server id 1 end_log_pos 899 CRC32 XXX Table_map: `test`.`t1` mapped to number num
|
# at 899
|
-#<date> server id 1 end_log_pos 967 CRC32 XXX Write_compressed_rows: table id 32 flags: STMT_END_F
|
+#<date> server id 1 end_log_pos 967 CRC32 XXX Write_compressed_rows: table id 40 flags: STMT_END_F
|
### INSERT INTO `test`.`t1`
|
### SET
|
### @1=10 /* INT meta=0 nullable=0 is_null=0 */
|
@@ -75,7 +75,7 @@
|
### @9='' /* STRING(1) meta=65025 nullable=1 is_null=0 */
|
# Number of rows: 1
|
# at 967
|
-#<date> server id 1 end_log_pos 1040 CRC32 XXX Query thread_id=5 exec_time=x error_code=0
|
+#<date> server id 1 end_log_pos 1040 CRC32 XXX Query thread_id=9 exec_time=x error_code=0
|
SET TIMESTAMP=X/*!*/;
|
COMMIT
|
/*!*/;
|
@@ -90,7 +90,7 @@
|
#Q> INSERT INTO t1 VALUES (11, 1, 2, 3, 4, 5, 6, 7, NULL)
|
#<date> server id 1 end_log_pos 1214 CRC32 XXX Table_map: `test`.`t1` mapped to number num
|
# at 1214
|
-#<date> server id 1 end_log_pos 1281 CRC32 XXX Write_compressed_rows: table id 32 flags: STMT_END_F
|
...
|
(mangled output)
|
Attachments
Issue Links
- is duplicated by
-
MDEV-34001 Mismatched binlog positionining causing test failures in fedora:40
-
- Closed
-
This error, (10.5-6dcd9de2a993409ce31df2a9eb0898e83436daff on fedora 41) I longer get the pseudo_thread difference
CURRENT_TEST: main.mysqlbinlog_row_compressed
--- /home/dan/repos/mariadb-server-rebase/mysql-test/main/mysqlbinlog_row_compressed.result 2024-12-09 13:04:39.915777458 +1100
+++ /home/dan/repos/mariadb-server-rebase/mysql-test/main/mysqlbinlog_row_compressed.reject 2024-12-13 10:44:40.664786289 +1100
@@ -29,7 +29,7 @@
/*M!100001 SET @@session.server_id=1*//*!*/;
/*M!100001 SET @@session.gtid_seq_no=1*//*!*/;
# at 371
-#<date> server id 1 end_log_pos 533 CRC32 XXX Query_compressed thread_id=5 exec_time=x error_code=0
+#<date> server id 1 end_log_pos 534 CRC32 XXX Query_compressed thread_id=5 exec_time=x error_code=0
use `test`/*!*/;
SET TIMESTAMP=X/*!*/;
SET @@session.pseudo_thread_id=5/*!*/;
@@ -42,26 +42,26 @@
SET @@session.collation_database=DEFAULT/*!*/;
CREATE TABLE t1 (pk INT PRIMARY KEY, f1 INT, f2 INT, f3 TINYINT, f4 MEDIUMINT, f5 BIGINT, f6 INT, f7 INT, f8 char(1))
So 533 (end_log_pos) - 371 (at start postition) = 162 bytes
Debugging the server though below is data_written=163. The's no code change, its just the library compress call compressing the CREATE TABLE statement to 1 byte more ( 96 bytes).
Thread 2 hit Breakpoint 1, binlog_buf_compress (src=0x7fe1980f09c0 "CREATE TABLE t1 (pk INT PRIMARY KEY, f1 INT, f2 INT, f3 TINYINT, f4 MEDIUMINT, f5 BIGINT, f6 INT, f7 INT, f8 char(1))",
dst=dst@entry=0x7fe198062288 "8\033\006\230\341\177", len=117, comlen=comlen@entry=0x7fe1be0c32a4) at /home/dan/repos/mariadb-server-rebase/sql/log_event.cc:313
Thread 2 hit Breakpoint 2.4, 0x00007fe1c0386220 in compress () from /lib64/libz.so.1
(rr) finish
Run till exit from #0 0x00007fe1c0386220 in compress () from /lib64/libz.so.1
0x00000000009dced1 in binlog_buf_compress (src=<optimized out>,
dst=dst@entry=0x7fe198062288 "\201ux\234s\016ru\fqU\bqt\362qU(1T\320(\310V\360\364\vQ\b\b\362\364u\f\212T\360v\215\324QH3\004\211\351(\244\031Aic\205\020O\277H\b\333D\301\327\325\3053\324\027\3023Up\362t\2070Í \212Í¡\264\205BrFb\221\206\241\246&", len=<optimized out>, comlen=comlen@entry=0x7fe1be0c32a4) at /home/dan/repos/mariadb-server-rebase/sql/log_event.cc:342
342 if (compress((Bytef *)dst + BINLOG_COMPRESSED_HEADER_LEN + lenlen, &tmplen,
(rr) p tmplen
$4 = 94
(rr) n
343 (const Bytef *)src, (uLongf)len) != Z_OK)
(rr)
342 if (compress((Bytef *)dst + BINLOG_COMPRESSED_HEADER_LEN + lenlen, &tmplen,
(rr) n
347 *comlen = (uint32)tmplen + BINLOG_COMPRESSED_HEADER_LEN + lenlen;
(rr) n
349 }
(rr) p *comlen
$5 = 96
(rr) n
Query_compressed_log_event::write (this=0x7fe1be0c3608) at /home/dan/repos/mariadb-server-rebase/sql/log_event_server.cc:1357
(rr) n
1368 ret= Query_log_event::write();
(rr) p q_len
$6 = 96
$7 = 117
(rr) p *this
$8 = (Query_compressed_log_event) {<Query_log_event> = {<Log_event> = {_vptr$Log_event = 0x10a9248 <vtable for Query_compressed_log_event+16>, log_pos = 534, temp_buf = 0x0, event_owns_temp_buf = 48,
when = 1734047080, when_sec_part = 536614, exec_time = 0, data_written = 163, server_id = 1, flags = 0, cache_type = Log_event::EVENT_NO_CACHE, slave_exec_mode = 0, writer = 0x7fe1be0c32e8,
thd = 0x7fe198000c68, checksum_alg = BINLOG_CHECKSUM_ALG_CRC32}, user = {str = 0x0, length = 0}, host = {str = 0x0, length = 0}, data_buf = 0x0,
query = 0x7fe1980f09c0 "CREATE TABLE t1 (pk INT PRIMARY KEY, f1 INT, f2 INT, f3 TINYINT, f4 MEDIUMINT, f5 BIGINT, f6 INT, f7 INT, f8 char(1))", catalog = 0xde0f7b "std", db = 0x7fe19800c018 "test",
q_len = 117, db_len = 4, error_code = 0, thread_id = 5, slave_proxy_id = 5, catalog_len = 3, status_vars_len = 26, flags2_inited = 1, sql_mode_inited = true, charset_inited = true, flags2 = 0,
sql_mode = 1411383296, auto_increment_increment = 1, auto_increment_offset = 1, charset = "\b\000\b\000\b", time_zone_len = 0, time_zone_str = 0x7fe198000cc0 "\270I", lc_time_names_number = 0,
charset_database_number = 0, table_map_for_update = 0, master_data_written = 0}, query_buf = 0x0}
zlib-ng- 2.1.7 (-3.fc41) installed.