MySQL Bugs: #6061: mysql-log-rotate script - error logging doesn't use new file

Bug #6061	mysql-log-rotate script - error logging doesn't use new file
Submitted:	13 Oct 2004 11:53	Modified:	18 May 2006 13:21
Reporter:	John Van Essen	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server	Severity:	S4 (Feature request)
Version:	4.0.18	OS:	Linux (RedHat/Fedora)
Assigned to:	Timothy Smith	CPU Architecture:	Any

Description:
The mysql-log-rotate script does not have the intended effect.

After logrotate has moved the existing log to *.1 and created a new log file, it executes a "mysqladmin flush-logs" command, expecting mysqld to close its error log and reopen it, thus shifting from what is now the *.1 log back to the basename log. However...

If mysqld_safe is being used (which is the standard installation on Linux) the error messages from mysqld go to stderr, which is redirected to the error log file by mysqld_safe. Thus, the "mysqladmin flush-logs" command in the postrotate script has no effect, and the originally opened file (which is now *.1) continues to receive mysqld error messages. Only a restart (stop/start) of mysqld_safe will cause it to use the new log file.

If mysqld_safe is not used and --log-error is used, then according to chapter 5.9.1, a flush logs will renamed the file to *-old and create a new file. Also undesirable behavior in this case.

How to repeat:
This section intentionally left blank as it doesn't apply.

Suggested fix:
Provide an option to tell mysqld to not rotate the error log when a flush logs is done. Then mysqld_safe can pass a --log-error option to mysqld, and a flush-logs should just close the error log and re-open it for appending.

Or, provide an option to tell mysqld to not keep the error log open. mysqld would then open and close the logfile upon each instance of error message appending. Then flush-logs would have no effect and would not be needed in the mysql-log-rotate script.

In either case, mysqld_safe should then pass --log-error={filename} to mysqld when it starts up and thus avoid the redirection that prevents error log rotation.

This has been silent for 18 months now, but I need to second this as a major issue.

Logfile rotation scripts are used heavily in any production environment, and it's impossible to safely rotate the mysqld.log files.  Shutting down the database (something proposed to me by Redhat support) is not an option (and should never be considered as one).

This is still broken.  Please take some time to fix it.

I still see no way to rotate /var/lib/mysql/mysqld.log in MySQL-server-4.1.15-0.glibc23 using the instructions embedded in /etc/logrotate.d/mysql.  Binary logs get rotated, error log does not (it gets renamed, but the output continues going to the old log file).

Hi.  I can verify that FLUSH LOGS does not behave properly when --log-error=<something> is passed to mysqld_safe.  The problem is with the mysqld_safe shell script, not with mysqld itself.

Here is a patch (not approved yet) which solves the problem (and makes argument passing a bit more robust in general, while I'm there).  It also makes the file name relative to the data directory, if it is not an absolute path.  I.e., --log-error=error-log.txt will use /path/to/your/data-directory/error-log.txt.  The current behavior, which isn't correct, is to create the file relative to the current working directory from which mysqld_safe was run.

--- bin/mysqld_safe.orig        Wed Mar 29 17:25:26 2006
+++ bin/mysqld_safe     Wed Mar 29 18:17:48 2006
@@ -46,6 +46,11 @@
         exit 1
 }
 
+shell_quote_string() {
+  # This sed command makes sure that any special chars are quoted,
+  # so the arg gets passed exactly to the server.
+  echo "$1" | sed -e 's,\([^a-zA-Z0-9/_.=-]\),\\\1,g'
+}
 
 parse_arguments() {
   # We only need to pass arguments through to the server if we don't
@@ -97,9 +102,7 @@
       *)
         if test -n "$pick_args"
         then
-          # This sed command makes sure that any special chars are quoted,
-          # so the arg gets passed exactly to the server.
-          args="$args "`echo "$arg" | sed -e 's,\([^a-zA-Z0-9_.-]\),\\\\\1,g'`
+          append_arg_to_args "$arg"
         fi
         ;;
     esac
@@ -194,6 +197,14 @@
   print_defaults="my_print_defaults"
 fi
 
+append_arg_to_args () {
+  args="$args "`shell_quote_string "$1"`
+}
+
+prepend_arg_to_args () {
+  args=`shell_quote_string "$1"`" $args"
+}
+
 args=
 SET_USER=2
 parse_arguments `$print_defaults $defaults --loose-verbose mysqld server`
@@ -244,15 +255,30 @@
     * )  pid_file="$DATADIR/$pid_file" ;;
   esac
 fi
-test -z "$err_log"  && err_log=$DATADIR/`/bin/hostname`.err
+
+if [ -z "$err_log" ]
+then
+  # Note: --log-error is not given to mysqld, because it was not specified on
+  # command line / options file.
+  err_log=$DATADIR/`/bin/hostname`.err
+else
+  case "$err_log" in
+    /* ) ;;
+    * ) err_log="$DATADIR/$err_log" ;;
+  esac
+
+  # Pass this option along to mysqld, so that the error log can be rotated
+  # by FLUSH LOGS
+  append_arg_to_args "--log-error=$err_log"
+fi
 
 if test -n "$mysql_unix_port"
 then
-  args="--socket=$mysql_unix_port $args"
+  prepend_arg_to_args "--socket=$mysql_unix_port"
 fi
 if test -n "$mysql_tcp_port"
 then
-  args="--port=$mysql_tcp_port $args"
+  prepend_arg_to_args "--port=$mysql_tcp_port"
 fi
 
 if test $niceness -eq 0
@@ -319,7 +345,7 @@
   if test -n "$open_files"
   then
     ulimit -n $open_files
-    args="--open-files-limit=$open_files $args"
+    prepend_arg_to_args "--open-files-limit=$open_files"
   fi
   if test -n "$core_file_size"
   then
@@ -377,12 +403,16 @@
 while true
 do
   rm -f $safe_mysql_unix_port $pid_file        # Some extra safety
-  if test -z "$args"
-  then
-    $NOHUP_NICENESS $ledir/$MYSQLD $defaults --basedir=$MY_BASEDIR_VERSION --da
tadir=$DATADIR $USER_OPTION --pid-file=$pid_file  >> $err_log 2>&1
-  else
-    eval "$NOHUP_NICENESS $ledir/$MYSQLD $defaults --basedir=$MY_BASEDIR_VERSIO
N --datadir=$DATADIR $USER_OPTION --pid-file=$pid_file  $args >> $err_log 2>&1"
-  fi
+
+  cmd=
+  for i in "$NOHUP_NICENESS" "$ledir/$MYSQLD" "$defaults" "--basedir=$MY_BASEDI
R_VERSION" "--datadir=$DATADIR" "$USER_OPTION" "--pid-file=$pid_file"
+  do
+    cmd="$cmd "`shell_quote_string "$i"`
+  done
+  cmd="$cmd $args >> "`shell_quote_string "$err_log"`" 2>&1"
+  #echo "Running mysqld: [$cmd]"
+  eval "$cmd"
+
   if test ! -f $pid_file               # This is removed if normal shutdown
   then
     echo "STOPPING server from pid file $pid_file"

Regards,

Timothy

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/4314

Oops, the patch I posted is broken for systems that use NOHUP_NICENESS.  That variable should *not* be quoted as shown.

The critical change is the following:

+  cmd="$NOHUP_NICENESS"
+
+  for i in  "$ledir/$MYSQLD" "$defaults" "--basedir=$MY_BASEDIR_VERSION" "--datadir=$DATADIR" "$USER_OPTION" "--pid-file=$pid_file"
+  do

That is, do *not* apply shell_quote_string to $NOHUP_NICENESS.

Regards,

Timothy

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/6035

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/6210

Fix for this pushed to MySQL 5.1 tree; will be included in 5.1.11.

The following problems with mysqld_safe were fixed:
- The --log-error argument was not handled consistently.  If a file name was given, mysqld_safe swallowed the argument, and did not pass it on to mysqld.  So mysqld wrote all error info to its stderr, and was unable to rotate the error log file when FLUSH LOGS was given.
- mysqld adds ".err" to the end of the --log-error=fname argument, if fname doesn't already have an extension.  mysqld_safe didn't do this, so it was possible that mysqld_safe would write to 'foo', but mysqld would write to 'foo.err'.
- mysqld treats file names relative to its datadir; mysqld_safe treated the --log-error argument relative to its current working directory.
- Some arguments to mysqld_safe were not being quoted properly; e.g., a data directory with a space in the path name could get mangled when starting mysqld.

I forgot to mention; this was fixed in the 5.1 tree, but not in 5.0 or earlier.  The same problems exist in 5.0 and earlier, but since this changes behavior, it was decided to not apply the fix there.

The 5.1 mysqld_safe can be copied into a 5.0 or earlier installation, if a workaround is needed.

Noted in 5.0.11 changelog.

I believe Paul meant to type "5.1.11".

it would be great if the disappearing log files could not just be "unlinked" as inodes, but for security, it should be possible to optionally first have a wipe as in http://wipe.sourceforge.net/ on them!

The mysqld_safe script from 5.1.20 does not fix this problem in the 5.0 series as suggested in the comment on the 12th of May. Any other suggestions ?

Hi, I have some doubts about the commit http://lists.mysql.com/commits/6210. I'd appreciate if you could answer the following, even the bug is a bit older.

[12 May 2006 18:40] Timothy Smith wrote:
> I forgot to mention; this was fixed in the 5.1 tree, but not in 5.0 or earlier.  The same problems exist in 5.0 and earlier, but since this changes behavior, it was decided to not apply the fix there.

What behaviour exactly is different? I only see a difference in the .err extension to the error-log filename. Are there any other changes in behaviour?

And second, what happened with @MYSQLD_DEFAULT_SWITCHES@ in the evaluated command? The patch from commit http://lists.mysql.com/commits/6210 simply removes it. Was this intentional or an error?