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: | |
Category: | MySQL Server: Tests | Severity: | S3 (Non-critical) |
Version: | 6.0-bzr | OS: | Any |
Assigned to: | Bjørn Munch | CPU Architecture: | Any |
[24 Nov 2008 13:44]
Guilhem Bichot
[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)