Bug #40978 Error log gets truncated during testsuite, prevents debugging
Submitted: 24 Nov 2008 13:44 Modified: 10 Mar 2009 14:32
Reporter: Guilhem Bichot Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Tests Severity:S3 (Non-critical)
Version:6.0-bzr OS:Any
Assigned to: Bjørn Munch CPU Architecture:Any
Triage: Triaged: D3 (Medium)

[24 Nov 2008 13:44] Guilhem Bichot
Description:
I saw it on one Linux32, Linux64, and on one pushbuild Windows machine (see URL).
After the mtr testsuite is finished, only the last lines are found in master.err: all the piece about tests which were run first is missing. For example, on the Windows machines, log starts by:
081122 20:29:00 [Note] C:\cygwin\home\pushbuild\pb1\pb\bzr_mysql-6.0-maria\49\mysql-6.0.9-alpha-pb49\sql\release\mysqld.exe: Normal shutdown

081122 20:29:00 [Note] Event Scheduler: Purging the queue. 0 events
081122 18:29:03  InnoDB: Starting shutdown...
081122 18:29:04  InnoDB: Shutdown completed; log sequence number 0 63396686
081122 20:29:04 [Note] C:\cygwin\home\pushbuild\pb1\pb\bzr_mysql-6.0-maria\49\mysql-6.0.9-alpha-pb49\sql\release\mysqld.exe: Shutdown complete

CURRENT_TEST: rpl.rpl_ssl1

See: it starts in the middle of rpl tests. All "main" suite is missing for example.

How to repeat:
it's random. It's not only Maria trees, Davi saw it too in some other 6.0 tree.
[24 Nov 2008 13:45] Guilhem Bichot
In the case of the Linux machines, log started in the middle of NDB tests.
[24 Nov 2008 14:22] Davi Arnaut
For example, it happens for me during a make test-force run:

CURRENT_TEST: main.binlog_format_basic
081124 17:09:56 [Note] Got signal 15 to shutdown mysqld
081124 17:09:56 [Note] /home/davi/bzr/work/4284-6.0/sql/mysqld: Normal shutdown

081124 17:09:56 [Note] Event Scheduler: Purging the queue. 0 events
081124 17:09:56  InnoDB: Starting shutdown...
081124 17:09:56  InnoDB: Shutdown completed; log sequence number 0 50802
081124 17:09:57 [Note] Debug sync points hit:                   988
081124 17:09:57 [Note] Debug sync points executed:              0
081124 17:09:57 [Note] Debug sync points max active per thread: 0
081124 17:09:57 [Note] /home/davi/bzr/work/4284-6.0/sql/mysqld: Shutdown complete

CURRENT_TEST: main.binlog_index
081124 17:09:58  InnoDB: Started; log sequence number 0 50802
081124 17:09:58 [Warning] /home/davi/bzr/work/4284-6.0/sql/mysqld: unknown option '--loose-skip-ndbcluster'
081124 17:09:58 [Note] Event Scheduler: Loaded 0 events
081124 17:09:58 [Note] /foo/sql/mysqld: ready for connections.
Version: '6.0.9-alpha-valgrind-max-debug-log'  socket: '/foo/mysql-test/var/tmp/master.sock'  port: 13090  Source distribution
tail: `var/log/master.err' has been replaced;  following end of new file
081124 17:09:58 [Note] Failed to delete file '/foo/mysql-test/var/log/master-bin.000001'
081124 17:09:58 [Note] Got signal 15 to shutdown mysqld
081124 17:09:58 [Note] /foo/mysqld: Normal shutdown

I could reproduce it with:

./mtr --force --start-from=main.binlog_format_basic

Right after main.binlog_index is executed, master.err gets truncated and the file starts with:

davi@skynet:~/bzr/work/4284-6.0/mysql-test$ cat var/log/master.err
081124 17:19:31 [Note] Failed to delete file '/foo/mysql-test/var/log/master-bin.000001'
081124 17:19:31 [Note] Got signal 15 to shutdown mysqld
081124 17:19:31 [Note] /foo/sql/mysqld: Normal shutdown
[27 Jan 2009 22:34] Guilhem Bichot
Using Davi's idea I reproduced it with
./mtr --force --mem --skip-ndb binary binlog_index
This is due to "FLUSH LOGS" in binlog_index: here is the backtrace of the function which moves master.err to master.err-old and provokes the truncation
#1  0x083ee2b0 in flush_error_log () at log.cc:6547
#2  0x08323650 in reload_acl_and_cache (thd=0x9817a18, options=2, tables=0x0, 
    write_to_binlog=0xaf8e47b7) at sql_parse.cc:6634
#3  0x0832e472 in mysql_execute_command (thd=0x9817a18) at sql_parse.cc:3941
#4  0x08330e29 in mysql_parse (thd=0x9817a18, inBuf=0x9915878 "flush logs", 
    length=10, found_semicolon=0xaf8e4e80) at sql_parse.cc:5735
#5  0x08331dbe in dispatch_command (command=COM_QUERY, thd=0x9817a18, 
    packet=0x98efe91 "flush logs", packet_length=10) at sql_parse.cc:1008
This function has been around since 2003. But it was not called, because mtr used to start mysqld without --log-error. Then in 6.0, this revision:
vvaintroub@mysql.com-20080713212252-zhaqcv8z395bdby1
added --log-err to the mysqld command line, triggering the "problem" (well it is not a problem as everything works as described, but it is a problem as one single FLUSH LOGS takes away all info very useful for debugging, for grepping for crashes).
I verified that if I remove the --log-err line, there is no more truncation.
I will ask Wlad for his opinion.
[28 Jan 2009 10:15] Guilhem Bichot
Wlad said:
<quote>
It looks like --console for
Windows is the same as omitting --log-err everywhere else, i.e writing to
stdout. I checked it seems to work (var\log\master.err and expected content)

So, adding --console for Windows and dropping --log-err generally  could be
an alternative without side-effects.  
But .. Philip is yet another mtr user. Who knows, maybe this change would
break his random query generator in some subtle way. I added Philip to CC:
for he gets a chance to protest.
</quote>
to which Philip replied that he was ok with such change.
[28 Jan 2009 11:32] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/64264

2717 Guilhem Bichot	2009-01-28
      Patch from Vladislav Vaintroub to fix BUG#40978
      "Error log gets truncated during testsuite, prevents debugging"
[12 Feb 2009 21:05] Guilhem Bichot
Here is a patch against the old mtr, but the new mtr has the problem too. For example, do:
./mtr --force --mem --skip-ndb binary binlog_index --no-reorder
then
cat var/mysqld.1/mysqld.err
file is empty (see my previous posts for explanations).
Assigning to Bjorn who wrote he would look at it.
@@ -3751,9 +3755,12 @@

   mtr_add_arg($args, "%s--pid-file=%s", $prefix,
              $mysqld->{'path_pid'});
-
-   mtr_add_arg($args, "%s--log-err=%s", $prefix,
-             $mysqld->{'path_myerr'});
+
+  if ($glob_win32)
+  {
+    # write to stdout
+    mtr_add_arg($args, "%s--console", $prefix);
+  }

   mtr_add_arg($args, "%s--port=%d", $prefix,
                 $mysqld->{'port'});
[17 Feb 2009 11:47] Bugs System
Pushed into 6.0.10-alpha (revid:serg@mysql.com-20090217113558-vpsqsyjule7nz0gk) (version source revid:serg@mysql.com-20090209203220-8s0lzku8aax6ca2x) (merge vers: 6.0.10-alpha) (pib:6)
[19 Feb 2009 11:48] Bjørn Munch
Patch implemented and tested with old MTR but this was overwritten with the push of MTR 2.  I will re-apply the patch to MTR 2.
[25 Feb 2009 11:50] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/67522

2759 Bjorn Munch	2009-02-25
      Bug #40978 Error log gets truncated during testsuite, prevents debugging
      Error log gets truncated when mysqld is restarted by MTR
[27 Feb 2009 14:29] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/67863

2759 Bjorn Munch	2009-02-27
      Bug #40978 Error log gets truncated during testsuite, prevents debugging
      Error log gets truncated when mysqld is restarted by MTR
[2 Mar 2009 12:03] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/67976

2759 Bjorn Munch	2009-03-02
      Bug #40978 Error log gets truncated during testsuite, prevents debugging
      Error log gets truncated when mysqld is restarted by MTR
[2 Mar 2009 12:49] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/67981

2759 Bjorn Munch	2009-03-02
      Bug #40978 Error log gets truncated during testsuite, prevents debugging
      Error log gets truncated when mysqld is restarted by MTR
[2 Mar 2009 13:35] Bjørn Munch
Pushed to 5.1-mtr and 6.0-mtr
[10 Mar 2009 13:53] Bugs System
Pushed into 6.0.11-alpha (revid:bjorn.munch@sun.com-20090310133716-5qpotn2sggp621s1) (version source revid:bjorn.munch@sun.com-20090310133716-5qpotn2sggp621s1) (merge vers: 6.0.11-alpha) (pib:6)
[10 Mar 2009 13:56] Bugs System
Pushed into 5.1.33 (revid:bjorn.munch@sun.com-20090310134806-wnurk6dobx9u605b) (version source revid:bjorn.munch@sun.com-20090310134806-wnurk6dobx9u605b) (merge vers: 5.1.33) (pib:6)
[10 Mar 2009 14:32] Paul Dubois
Test suite change. No changelog entry needed.
[9 May 2009 16:45] Bugs System
Pushed into 5.1.34-ndb-6.2.18 (revid:jonas@mysql.com-20090508185236-p9b3as7qyauybefl) (version source revid:jonas@mysql.com-20090508100057-30ote4xggi4nq14v) (merge vers: 5.1.33-ndb-6.2.18) (pib:6)
[9 May 2009 17:42] Bugs System
Pushed into 5.1.34-ndb-6.3.25 (revid:jonas@mysql.com-20090509063138-1u3q3v09wnn2txyt) (version source revid:jonas@mysql.com-20090508175813-s6yele2z3oh6o99z) (merge vers: 5.1.33-ndb-6.3.25) (pib:6)
[9 May 2009 18:40] Bugs System
Pushed into 5.1.34-ndb-7.0.6 (revid:jonas@mysql.com-20090509154927-im9a7g846c6u1hzc) (version source revid:jonas@mysql.com-20090509073226-09bljakh9eppogec) (merge vers: 5.1.33-ndb-7.0.6) (pib:6)