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

plugins.server_audit, plugins.thread_pool_server_audit failed in buildbot, results mismatch

Details

    • Bug
    • Status: Open (View Workflow)
    • Minor
    • Resolution: Unresolved
    • 5.5(EOL), 10.0(EOL), 10.1(EOL), 10.3(EOL)
    • 10.4(EOL)
    • Tests
    • None

    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
      

      Attachments

        Issue Links

          Activity

            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
            

            elenst Elena Stepanova added a comment - 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

            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
            

            elenst Elena Stepanova added a comment - 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
            alice Alice Sherepa added a comment -

            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
            

            alice Alice Sherepa added a comment - 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

            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.

            svoj Sergey Vojtovich added a comment - 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.

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

            svoj Sergey Vojtovich added a comment - Ah, and of course the most important thing is that this test is now literally 100x faster.

            People

              holyfoot Alexey Botchkov
              alice Alice Sherepa
              Votes:
              1 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

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