MySQL Bugs: #40978: Error log gets truncated during testsuite, prevents debugging

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)

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.

In the case of the Linux machines, log started in the middle of NDB tests.

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

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.

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.

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"

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'});

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)

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.

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

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

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

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

Pushed to 5.1-mtr and 6.0-mtr

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)

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)

Test suite change. No changelog entry needed.

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)

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)

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)