[MDEV-16576] rocksdb.unique_check fails in buildbot with wrong errno Created: 2018-06-25  Updated: 2023-11-29  Resolved: 2023-11-29

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - RocksDB, Tests
Affects Version/s: 10.2
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Petrunia
Resolution: Won't Fix Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-16573 rocksdb.autoinc_vars_thread fails in ... Closed

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-amd64-debug/builds/600

rocksdb.unique_check                     w4 [ fail ]
        Test ended at 2018-06-25 06:32:22
 
CURRENT_TEST: rocksdb.unique_check
mysqltest: At line 118: query 'insert into t1 values (1,2)' failed with wrong errno 1062: 'Duplicate entry '1' for key 'PRIMARY'', instead of 1205...
 
The result from queries just before the failure was:
< snip >
connection con2;
commit;
select * from t2;
id	id2	value
2	1	2
truncate table t2;
connection con1;
set debug_sync='rocksdb.update_write_row_after_unique_check SIGNAL parked1 WAIT_FOR go1';
insert into t1 values (1,1);
connection con2;
set debug_sync='rocksdb.update_write_row_after_unique_check SIGNAL parked2 WAIT_FOR go2';
insert into t2 values (1,1,1);
connection default;
set debug_sync='now WAIT_FOR parked1';
set debug_sync='now WAIT_FOR parked2';
Warnings:
Warning	1639	debug sync point wait timed out
connection con3;
set session rocksdb_lock_wait_timeout=1;
insert into t1 values (1,2);
 
More results from queries before failure can be found in /dev/shm/var/4/log/unique_check.log
 
 - skipping '/dev/shm/var/4/log/rocksdb.unique_check/'



 Comments   
Comment by Sergei Petrunia [ 2018-09-03 ]

The latest upstream merge didnt help:

http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-amd64-debug/builds/832/steps/mtr/logs/stdio
http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-amd64-debug/builds/833/steps/mtr/logs/stdio

rocksdb.unique_check 'write_committed'   w2 [ fail ]
        Test ended at 2018-09-01 18:13:32
 
CURRENT_TEST: rocksdb.unique_check
mysqltest: At line 118: query 'insert into t1 values (1,2)' failed with wrong errno 1062: 'Duplicate entry '1' for key 'PRIMARY'', instead of 1205...
 
The result from queries just before the failure was:
< snip >
connection con2;
commit;
select * from t2;
id	id2	value
2	1	2
truncate table t2;
connection con1;
set debug_sync='rocksdb.update_write_row_after_unique_check SIGNAL parked1 WAIT_FOR go1';
insert into t1 values (1,1);
connection con2;
set debug_sync='rocksdb.update_write_row_after_unique_check SIGNAL parked2 WAIT_FOR go2';
insert into t2 values (1,1,1);
connection default;
set debug_sync='now WAIT_FOR parked1';
set debug_sync='now WAIT_FOR parked2';
Warnings:
Warning	1639	debug sync point wait timed out
connection con3;
set session rocksdb_lock_wait_timeout=1;
insert into t1 values (1,2);
 
More results from queries before failure can be found in /dev/shm/var/2/log/unique_check.log

Comment by Sergei Petrunia [ 2018-09-03 ]

Note that these test runs have other tests fail because of "Debug sync point timed out", too:

worker[4] > Restart [mysqld.2 - pid: 8751, winpid: 8751] - using different config file
rocksdb.autoinc_vars_thread 'write_prepared' w3 [ fail ]
        Test ended at 2018-09-01 17:43:53
 
CURRENT_TEST: rocksdb.autoinc_vars_thread
--- /usr/share/mysql-test/plugin/rocksdb/rocksdb/r/autoinc_vars_thread.result	2018-09-01 15:48:43.000000000 +0000
+++ /dev/shm/var/3/log/autoinc_vars_thread.reject	2018-09-01 17:43:53.099873366 +0000
@@ -19,13 +19,19 @@
 INSERT INTO t1 VALUES(NULL);
 connection default;
 SET debug_sync='now WAIT_FOR parked1';
+Warnings:
+Warning	1639	debug sync point wait timed out
 SET debug_sync='now WAIT_FOR parked2';
 SET debug_sync='now SIGNAL go1';
 connection con3;
 SET debug_sync='now SIGNAL go2';
 connection default;
 connection con1;
+Warnings:
+Warning	1639	debug sync point wait timed out
 connection con2;
+Warnings:
+Warning	1639	debug sync point wait timed out
 connection default;
 SET debug_sync='RESET';
 disconnect con1;
 
mysqltest: Result length mismatch
 
 - found 'core.5901' (0/0)

...

rpl.rpl_parallel_retry 'innodb,row'      w2 [ fail ]
        Test ended at 2018-08-31 18:45:34
 
CURRENT_TEST: rpl.rpl_parallel_retry
--- /usr/share/mysql-test/suite/rpl/r/rpl_parallel_retry.result	2018-08-31 15:16:57.000000000 +0000
+++ /dev/shm/var/2/log/rpl_parallel_retry.reject	2018-08-31 18:45:33.989892803 +0000
@@ -384,6 +384,24 @@
 SET @@DEBUG_SYNC='now SIGNAL proceed_by_1001';
 # observe how it all ends
 # Wait for the workers to go home and check the result of applying
+Timeout in wait_condition.inc for SELECT count(*) = 0 FROM information_schema.processlist WHERE command = 'Slave_worker'
+Id	User	Host	db	Command	Time	State	Info	Progress
+1	system user		NULL	Daemon	NULL	InnoDB purge coordinator	NULL	0.000

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