[MDEV-13408] main.log_tables-big failed in buildbot with wrong result Created: 2017-07-30  Updated: 2022-08-29  Resolved: 2022-08-28

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.0
Fix Version/s: N/A

Type: Bug Priority: Minor
Reporter: Elena Stepanova Assignee: Unassigned
Resolution: Cannot Reproduce Votes: 0
Labels: None


 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest-big/builds/1070/steps/test_1/logs/stdio

main.log_tables-big                      w1 [ fail ]
 
        Test ended at 2017-07-12 11:19:04
 
 
 
CURRENT_TEST: main.log_tables-big
 
--- /mnt/buildbot/build/mariadb-10.0.32/mysql-test/r/log_tables-big.result	2017-07-12 02:21:46.000000000 -0400
 
+++ /mnt/buildbot/build/mariadb-10.0.32/mysql-test/r/log_tables-big.reject	2017-07-12 11:19:04.530496575 -0400
 
@@ -17,7 +17,7 @@
 
 select if (query_time >= '00:00:59', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log
 
 where sql_text = 'select get_lock(\'bug27638\', 60)';
 
 qt	sql_text
 
-OK	select get_lock('bug27638', 60)
 
+WRONG	select get_lock('bug27638', 60)
 
 select get_lock('bug27638', 101);
 
 get_lock('bug27638', 101)
 
 0
 
 
 
mysqltest: Result length mismatch



 Comments   
Comment by Alice Sherepa [ 2017-08-14 ]

test failed also on 10.1 http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2-big/builds/1076/steps/test_1/logs/stdio, http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest-big/builds/1142/steps/test_2/logs/stdio – mysqltest: Result length mismatch

main.log_tables-big                      w2 [ pass ]  163051
 
 
 
MTR's internal check of the test case 'main.log_tables-big' failed.
 
This means that the test case does not preserve the state that existed
 
before the test case was executed.  Most likely the test case did not
 
do a proper clean-up. It could also be caused by the previous test run
 
by this thread, if the server wasn't restarted.
 
This is the diff of the states of the servers before and after the
 
test case was executed:
 
mysqltest: Logging to '/mnt/buildbot/build/mariadb-10.1.27/mysql-test/var/2/tmp/check-mysqld_1.log'.
 
mysqltest: Results saved in '/mnt/buildbot/build/mariadb-10.1.27/mysql-test/var/2/tmp/check-mysqld_1.result'.
 
mysqltest: Connecting to server localhost:16020 (socket /mnt/buildbot/build/mariadb-10.1.27/mysql-test/var/tmp/2/mysqld.1.sock) as 'root', connection 'default', attempt 0 ...
 
mysqltest: ... Connected.
 
mysqltest: Start processing test commands from './include/check-testcase.test' ...
 
mysqltest: ... Done processing test commands.
 
--- /mnt/buildbot/build/mariadb-10.1.27/mysql-test/var/2/tmp/check-mysqld_1.result	2017-08-12 11:38:57.024300483 -0400
 
+++ /mnt/buildbot/build/mariadb-10.1.27/mysql-test/var/2/tmp/check-mysqld_1.reject	2017-08-12 11:41:41.216523941 -0400
 
@@ -185,7 +185,7 @@
 
 LOG_BIN_INDEX	
 LOG_BIN_TRUST_FUNCTION_CREATORS	ON
 
 LOG_ERROR	
-LOG_OUTPUT	FILE,TABLE
 
+LOG_OUTPUT	FILE
 
 LOG_QUERIES_NOT_USING_INDEXES	OFF
 
 LOG_SLAVE_UPDATES	OFF
 
 LOG_SLOW_ADMIN_STATEMENTS	OFF
 
 
 
mysqltest: Result length mismatch
 
 
 
not ok

Comment by Elena Stepanova [ 2017-08-15 ]

The internal check problem is easy, it's just a bad cleanup, i've pushed a fix for it to 5.5:
https://github.com/MariaDB/server/commit/e866e4cdbe974a83d4a4ee474d28f61e7082700f

However, it has nothing to do with the failure in the description. Looking at the test, I can't see how it can possibly happen, unless there is an actual code problem. Also it doesn't help that the failure so far has happened once in the life time, thus no realistic chance to repeat it.

Looking at the server log associated with the failure, we can see that it took twice as long as it should – the test itself takes ~3 minutes, and there were 6 minutes between the test and the retry. However, even that doesn't explain the wrong result

In the same commit above I've added the actual query_time in case it doesn't meet expectations. We cannot always put it into output because it will be always a bit different, but when we hit the wrong result, it's a mismatch anyway, so we can just as well print it. If the failure happens again in our life time, we'll at least see what the value was.

Comment by Elena Stepanova [ 2022-08-28 ]

The failure hasn't been seen since the reported occurrence in 2017.

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