[MDEV-14295] plugins.server_audit, plugins.thread_pool_server_audit failed in buildbot, results mismatch Created: 2017-11-06  Updated: 2023-04-27

Status: Open
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 5.5, 10.0, 10.1, 10.3
Fix Version/s: 10.4

Type: Bug Priority: Minor
Reporter: Alice Sherepa Assignee: Alexey Botchkov
Resolution: Unresolved Votes: 1
Labels: None

Issue Links:
Duplicate
is duplicated by MDEV-21599 plugins.server_audit fails sporadical... Open

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/10263/steps/test_3/logs/stdio

plugins.server_audit                     w4 [ fail ]
 
        Test ended at 2017-11-03 23:22:42
 
 
 
CURRENT_TEST: plugins.server_audit
 
--- /mnt/buildbot/build/mariadb-5.5.59/mysql-test/suite/plugins/r/server_audit.result	2017-11-03 21:07:06.000000000 +0200
 
+++ /mnt/buildbot/build/mariadb-5.5.59/mysql-test/suite/plugins/r/server_audit.reject	2017-11-03 23:22:41.000000000 +0200
 
@@ -257,7 +257,6 @@
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'select 1,\n2,\n# comment\n3',0
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'insert into t2 values (1), (2)',0
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'select * from t2',0
 
-TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'select * from t_doesnt_exist',ID
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'syntax_error_query',ID
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'drop table renamed_t1, t2',0
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'show variables like \'server_audit%\'',0
 
 
 
mysqltest: Result length mismatch


plugins.thread_pool_server_audit         w2 [ fail ]
 
        Test ended at 2017-11-03 23:23:19
 
 
 
CURRENT_TEST: plugins.thread_pool_server_audit
 
--- /mnt/buildbot/build/mariadb-5.5.59/mysql-test/suite/plugins/r/thread_pool_server_audit.result	2017-11-03 21:07:06.000000000 +0200
 
+++ /mnt/buildbot/build/mariadb-5.5.59/mysql-test/suite/plugins/r/thread_pool_server_audit.reject	2017-11-03 23:23:19.000000000 +0200
 
@@ -257,7 +257,6 @@
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'select 1,\n2,\n# comment\n3',0
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'insert into t2 values (1), (2)',0
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'select * from t2',0
 
-TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'select * from t_doesnt_exist',ID
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'syntax_error_query',ID
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'drop table renamed_t1, t2',0
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'show variables like \'server_audit%\'',0
 
 
 
mysqltest: Result length mismatch



 Comments   
Comment by Elena Stepanova [ 2017-11-23 ]

10.1
http://buildbot.askmonty.org/buildbot/builders/bld-starfs-release/builds/399/steps/test_1/logs/stdio

plugins.thread_pool_server_audit         w2 [ fail ]
 
        Test ended at 2017-11-04 07:48:04
 
 
 
CURRENT_TEST: plugins.thread_pool_server_audit
 
--- /opt/buildbot-slave/mariadb/starfsmenn2/build/mysql-test/suite/plugins/r/thread_pool_server_audit.result	2017-11-03 20:54:25.550919147 +0200
 
+++ /opt/buildbot-slave/mariadb/starfsmenn2/build/mysql-test/suite/plugins/r/thread_pool_server_audit.reject	2017-11-04 07:48:04.030281476 +0200
 
@@ -253,7 +253,7 @@
 
 TIME,HOSTNAME,root,localhost,ID,ID,RENAME,test,t1|test.renamed_t1,
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'alter table t1 rename renamed_t1',0
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'set global server_audit_events=\'connect,query\'',0
 
-TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'select 1, 2, 3',0
 
+TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'select 1,\n2,\n3',0
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'insert into t2 values (1), (2)',0
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'select * from t2',0
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'select * from t_doesnt_exist',ID
 
 
 
mysqltest: Result length mismatch

Comment by Elena Stepanova [ 2018-06-30 ]

10.3
http://buildbot.askmonty.org/buildbot/builders/kvm-deb-xenial-ppc64le/builds/2940

plugins.server_audit                     w1 [ fail ]
 
        Test ended at 2018-06-20 05:04:22
 
 
 
CURRENT_TEST: plugins.server_audit
 
--- /usr/share/mysql/mysql-test/suite/plugins/r/server_audit.result	2018-06-20 02:43:20.000000000 -0400
 
+++ /dev/shm/var/1/log/server_audit.reject	2018-06-20 05:04:21.933677070 -0400
 
@@ -251,6 +251,7 @@
 
 Warnings:
 
 Warning	1620	Plugin is busy and will be uninstalled on shutdown
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,test,'set global server_audit_logging=on',0
 
+TIME,HOSTNAME,root,localhost,ID,0,DISCONNECT,,,0
 
 TIME,HOSTNAME,root,localhost,ID,0,CONNECT,mysql,,0
 
 TIME,HOSTNAME,root,localhost,ID,0,DISCONNECT,mysql,,0
 
 TIME,HOSTNAME,no_such_user,localhost,ID,0,FAILED_CONNECT,,,ID
 
 
 
mysqltest: Result length mismatch

Comment by Alice Sherepa [ 2020-01-16 ]

on 10.2 bb8226deabd177d70151d5 http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos73-amd64/builds/13695/steps/mtr_centos_mix/logs/stdio

plugins.server_audit                     w4 [ fail ]
 
        Test ended at 2020-01-16 13:27:04
 
 
 
CURRENT_TEST: plugins.server_audit
 
--- /usr/share/mysql-test/suite/plugins/r/server_audit.result	2020-01-16 10:07:03.000000000 +0000
 
+++ /dev/shm/var/4/log/server_audit.reject	2020-01-16 13:27:03.726802222 +0000
 
@@ -397,6 +397,7 @@
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,sa_db,'insert into t1 values (1), (2)',0
 
 TIME,HOSTNAME,user1,localhost,ID,ID,CREATE,sa_db,t1,
 
 TIME,HOSTNAME,user1,localhost,ID,ID,WRITE,sa_db,t1,
 
+TIME,HOSTNAME,user1,localhost,ID,ID,WRITE,sa_db,t1,
 
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,sa_db,'set global server_audit_logging= off',0
 
 TIME,HOSTNAME,root,localhost,ID,ID,WRITE,mysql,user,
 
 TIME,HOSTNAME,root,localhost,ID,ID,WRITE,mysql,db,
 
 
 
mysqltest: Result length mismatch

Comment by Sergey Vojtovich [ 2020-04-10 ]

Problems described back in 2017 didn't expose themselves since long ago. Relevant problems only affect 10.2+.

There were quite a few "DISCONNECT" issues, one of them was fixed by 2b3f6ab in 10.5. The former were fixed, the latter was backported.

The "WRITE" issue is due to multiple rows in single delated insert. Rows are enqueued separately to delayed thread. And can be processed at once or sequentially. Thus we may see one or two "WRITE" events. To reproduce it reliably add this sleep:

diff --git a/sql/sql_insert.cc b/sql/sql_insert.cc
 
index ec784bc..0d4c3d8 100644
 
--- a/sql/sql_insert.cc
 
+++ b/sql/sql_insert.cc
 
@@ -1058,6 +1058,7 @@ bool mysql_insert(THD *thd,TABLE_LIST *table_list,
 
         LEX_STRING const st_query = { query, thd->query_length() };
 
         DEBUG_SYNC(thd, "before_write_delayed");
 
         error=write_delayed(thd, table, duplic, st_query, ignore, log_on);
 
+        sleep(1);
 
         DEBUG_SYNC(thd, "after_write_delayed");
 
         query=0;
 
       }

All of the forementioned issues are hopefully fixed by 06219c2 in 10.2. Feel free to refactor if you disagree with those fixes or just close this task.

Comment by Sergey Vojtovich [ 2020-04-10 ]

Ah, and of course the most important thing is that this test is now literally 100x faster.

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