Bug #29992 syslog error logging does not flush
Submitted: 23 Jul 2007 22:27 Modified: 6 Aug 2007 17:01
Reporter: Kolbe Kegel Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Logging Severity:S1 (Critical)
Version:5.1.20 OS:Linux
Assigned to: Timothy Smith CPU Architecture:Any

[23 Jul 2007 22:27] Kolbe Kegel
Description:
The new syslog error logging functionality in 5.1.20 does not function.

In at least some cases, error log messages are not flushed to syslog until the mysqld process finishes.

This may be because messages are being piped through sed, which buffers input/ouput.

Obviously, it is critical that error log messages are *immediately* flushed to whatever medium is being used for storage/display/archival.

How to repeat:
Note in this excerpt that MySQL starts on the 20th and the "InnoDB Started" message doesn't show up until the 23rd, at the same time that MySQL is stopped.

Jul 20 17:38:43 beluga mysqld_safe[20490]: Starting mysqld daemon with databases from /home/kolbe/MySQL/inst/5.1.20/data
Jul 23 14:27:54 beluga mysqld[20495]: [Warning] setrlimit could not change the size of core files to 'infinity';  We may not be able to generate a core file on signals
Jul 23 14:27:54 beluga mysqld[20495]: InnoDB: Started; log sequence number 0 47918
Jul 23 14:27:54 beluga mysqld[20495]: [Note] Event Scheduler: Loaded 0 events
Jul 23 14:27:54 beluga mysqld[20495]: [Note] /home/kolbe/MySQL/inst/5.1.20/bin/mysqld: ready for connections.
Jul 23 14:27:54 beluga mysqld[20495]: Version: '5.1.20-beta'  socket: '../mysql.sock'  port: 0  MySQL Community Server (GPL)
Jul 23 14:27:54 beluga mysqld[20495]: [Note] /home/kolbe/MySQL/inst/5.1.20/bin/mysqld: Normal shutdown
Jul 23 14:27:54 beluga mysqld[20495]:
Jul 23 14:27:54 beluga mysqld[20495]: [Note] Event Scheduler: Purging the queue. 0 events
Jul 23 14:27:54 beluga mysqld[20495]: InnoDB: Starting shutdown...
Jul 23 14:27:54 beluga mysqld[20495]: InnoDB: Shutdown completed; log sequence number 0 47918

Suggested fix:
o Use an unbuffered sed
o Don't use sed at all
o Incorporate proper syslog functionality into the server
[23 Jul 2007 22:33] Timothy Smith
Problem is that sed buffers output; sed is being used to strip redundant timestamps from mysqld stderr output (logger adds a timestamp, so it's not necessary to report the mysqld one as well).

GNU sed has a -u flag, to produce "unbuffered" output.  It's not at all portable beyond GNU sed.

One option is to test for availability of the -u flag, and use sed if it's available; otherwise just send output of mysqld directly to logger.

Another option is, for simplicity, to just send mysqld output directly to logger on all platforms.
[24 Jul 2007 17:49] Kolbe Kegel
Noting here that syslog functionality should be built into mysqld at some point rather than being done in a wrapper script such as is currently the case.
[26 Jul 2007 22: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/31662

ChangeSet@1.2577, 2007-07-26 16:02:22-06:00, tsmith@ramayana.hindu.god +1 -0
  Bug #29992: syslog error logging does not flush
  
  Don't use syslog by default; user will have to request it explicitly with the --syslog option.
  
  Use "sed -u" to get unbuffered output from sed, if it's supported.
  
  Otherwise, don't use sed at all - don't strip the timestamp from mysqld messages.
  
  Also, add new --syslog-tag=FOO option, which adds "-FOO" to the tag used when logging messages to syslog (i.e., mysqld-FOO or mysqld_safe-FOO)
  
  Also, explicitly mention where log messages are going, so user can more easily find them.
[26 Jul 2007 23:34] 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/31666

ChangeSet@1.2577, 2007-07-26 17:33:21-06:00, tsmith@ramayana.hindu.god +1 -0
  Bug #29992: syslog error logging does not flush
  
  Don't use syslog by default; user will have to request it explicitly with the --syslog option.
  
  Use "sed -u" to get unbuffered output from sed, if it's supported.
  
  Otherwise, don't use sed at all - don't strip the timestamp from mysqld messages.
  
  Also, add new --syslog-tag=FOO option, which adds "-FOO" to the tag used when logging messages to syslog (i.e., mysqld-FOO or mysqld_safe-FOO)
  
  Also, explicitly mention where log messages are going, so user can more easily find them.
  
  Also, check if 'logger' is in the PATH, and log to the error log file if it can't be found.
[27 Jul 2007 23:21] 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/31753

ChangeSet@1.2577, 2007-07-27 17:20:43-06:00, tsmith@ramayana.hindu.god +1 -0
  Bug #29992: syslog error logging does not flush
  
  Don't use syslog by default; user will have to request it explicitly with the --syslog option.
  
  Use "sed -u" to get unbuffered output from sed, if it's supported.
  
  Otherwise, don't use sed at all - don't strip the timestamp from mysqld messages.
  
  Also, add new --syslog-tag=FOO option, which adds "-FOO" to the tag used when logging messages to syslog (i.e., mysqld-FOO or mysqld_safe-FOO)
  
  Also, explicitly mention where log messages are going, so user can more easily find them.
  
  Also, check if 'logger' is in the PATH, and log to the error log file if it can't be found.
[27 Jul 2007 23:39] Timothy Smith
Queued to 5.1-maint
[27 Jul 2007 23:52] Timothy Smith
Docs team,

This bug changes a few things regarding how mysqld_safe logs messages.

--syslog is no longer the default.  It was default only MySQL 5.1.20 (and did not work properly there, output from mysqld was buffered, and might never make it to syslog until mysqld quit).  The default is now to log to the error log, as in versions before MySQL 5.1.20.

If --syslog is used, the output is now unbuffered, and goes to syslog immediately.  A consequence of this is that timestamps are not stripped from mysqld messages, so some messages will have redundant timestamps, like this example:

Jul 27 17:19:10 myhost mysqld-TAG: 070727 17:19:10 [Note] Event Scheduler: Purging the queue. 0 events

A new option, --syslog-tag=TAG, is added.  This adds "-TAG" to the "mysqld" or "mysqld_safe" tag in syslog messages.  See example above.

Just for safety, mysqld_safe searches for the 'logger' executable, and falls back to error file logging if it can't be found in PATH.  I'm not aware of any platform that support syslog but doesn't have a 'logger' executable, but you never know.

Also, mysqld_safe now prints an information message saying to where it is logging when it starts up.  This may be useful for sysadmins who aren't sure which file to look in.  It shows something like:

070727 17:19:31 mysqld_safe Logging to '/path/to/datadir/myhost.err'.

or

070727 17:18:46 mysqld_safe Logging to syslog.

Brief summary of current behavior:

If no args given, then log to datadir/<hostname>.err.

If both --syslog and --log-error=FILE given, then warn user about the conflict and log to FILE.

If no --syslog-tag given, and logging to --syslog, then pass "mysqld" or "mysqld_safe" to 'logger -t' command.

If --syslog-tag=TAG given, then log with 'logger -t "mysqld-TAG"' or '-t "mysqld_safe-TAG"'.

It's not really complicated, but hard to explain in few words....
[27 Jul 2007 23:55] Timothy Smith
Oops.  The commit message mentions using "sed -u" to get unbuffered output.  This was taken out, because it complicated the code without giving a clear benefit.  

Now we just don't use sed at all, on any platform.  This avoids some platform-specific behavior, and it's not a big deal to have redundant timestamps in syslog messages.
[2 Aug 2007 19:14] Bugs System
Pushed into 5.1.21-beta
[6 Aug 2007 17:01] Paul DuBois
Noted in 5.1.21 changelog:

The --syslog option that was introduced in 5.1.20 for
mysqld_safe (to send error output to syslog) did not work
correctly: Error output was buffered and not logged
immediately. This has been corrected. In addition, some
feature changes were made:

- Important: The default mysqld_safe logging behavior
  now is --skip-syslog rather than --syslog, which is
  compatible with the default behavior of writing an
  error log file for releases prior to 5.1.20.
- A new option, --syslog-tag=tag, modifies the default
  tags written by mysqld_safe and mysqld to syslog to
  be mysqld_safe-tag and mysqld-tag rather than the
  default tags of mysqld_safe and mysqld.

Also updated the mysqld_safe, error-log, and upgrading
sections.