Re: bk commit into 5.1 tree (tsmith:1.2577) BUG#29992

[Kent Boortz]

tim@stripped writes:
<snip>
> ChangeSet@stripped, 2007-07-26 17:33:21-06:00, tsmith@stripped +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.

This is a "functionality change", does user count on output being sent
to syslog if started without arguments? I don't know :-)

>   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.

I vote remove sed, a bit funny to just use it depending on GNU sed ;-)

>   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.

<snip>
> diff -Nrup a/scripts/mysqld_safe.sh b/scripts/mysqld_safe.sh
> --- a/scripts/mysqld_safe.sh	2007-07-09 16:09:19 -06:00
> +++ b/scripts/mysqld_safe.sh	2007-07-26 17:33:20 -06:00
> @@ -14,12 +14,17 @@
>  KILL_MYSQLD=1;
>  MYSQLD=
>  niceness=0
> -# Default on, unless --log-error is specified (and before options are parsed)
> -syslog=2
> +# Initial logging status: error log is not open, and not using syslog
> +logging=init
> +want_syslog=0
> +syslog_tag=
>  user=@MYSQLD_USER@
>  pid_file=
>  err_log=
>  
> +syslog_tag_mysqld=mysqld
> +syslog_tag_mysqld_safe=mysqld_safe
> +
>  trap '' 1 2 3 15			# we shouldn't let anyone kill us
>  
>  umask 007
> @@ -47,6 +52,7 @@ Usage: $0 [OPTIONS]
>    --skip-kill-mysqld         Don't try to kill stray mysqld processes
>    --syslog                   Log messages to syslog with 'logger'
>    --skip-syslog              Log messages to error log
> +  --syslog-tag=TAG           Pass -t "mysqld-TAG" to 'logger'

Could be nice to indicate indicate in the text what is default,
--syslog or --skip-syslog

>  All other options are passed to the mysqld program.
>  
> @@ -54,18 +60,47 @@ EOF
>          exit 1
>  }
>  
> +my_which ()
> +{
> +  save_ifs="${IFS-UNSET}"
> +  IFS=:
> +  for file
> +  do
> +    for dir in $PATH
> +    do
> +      if test -f $dir/$file
> +      then
> +        echo "$dir/$file"
> +        continue 2
> +      fi
> +    done
> +    echo "my_which: no $file in ($PATH)" >&2
> +    return 1
> +  done
> +  if [ "$save_ifs" = UNSET ]
> +  then
> +    unset IFS
> +  else
> +    IFS="$save_ifs"
> +  fi
> +  return 0
> +}

I would loose the "echo" to stderr above, as a more user friendly
error message is given by the caller. I would also not mix '[...]' and
'test', use one style or the other. Also, most part of this code is
quoting arguments (needed if space in the value), but it is left out
in "if test -f $dir/$file". But very minor point.

>  log_generic () {
>    priority="$1"
>    shift
>  
>    msg="`date +'%y%m%d %H:%M:%S'` mysqld_safe $*"
>    echo "$msg"
> -  if [ $syslog -eq 0 ]
> -  then
> -    echo "$msg" >> "$err_log"
> -  else
> -    logger -i -t mysqld_safe -p "$priority" "$*"
> -  fi
> +  case $logging in
> +    init) ;;  # Just echo the message, don't save it anywhere
> +    file) echo "$msg" >> "$err_log" ;;
> +    syslog) logger -t "$syslog_tag_mysqld_safe" -p "$priority" "$*" ;;
> +    *)
> +      echo "Internal program error (non-fatal):" \
> +           " unknown logging method '$logging'" >&2
> +      ;;
> +  esac
>  }

Nice recoding, with the state/mode $logging variable.

>  log_error () {
> @@ -78,15 +113,27 @@ log_notice () {
>  
>  eval_log_error () {
>    cmd="$1"
> -  if [ $syslog -eq 0 ]
> -  then
> -    cmd="$cmd >> "`shell_quote_string "$err_log"`" 2>&1"
> -  else
> -    # mysqld often (not always) prefixes messages on stdout with a
> -    # timestamp in the form of '%y%m%d %H:%M:%S '; this is redundant
> -    # when logging via syslog, so strip it
> -    cmd="$cmd 2>&1 | sed -e 's/^[0-9]\{6\} [0-9:]\{8\}  *//' | logger -i -t
> mysqld -p daemon.error"
> -  fi
> +  case $logging in
> +    file) cmd="$cmd >> "`shell_quote_string "$err_log"`" 2>&1" ;;
> +    syslog)
> +      cmd="$cmd 2>&1"
> +
> +      # mysqld often (not always) prefixes messages on stdout with a
> +      # timestamp in the form of '%y%m%d %H:%M:%S '; this is redundant
> +      # when logging via syslog, so strip it.  However, don't strip it if
> +      # sed does not have a -u (unbuffered) option
> +      if sed -u -e s/a/b/ < /dev/null 2>&1 > /dev/null

I have learned that "2>&1 > FILE" and "> FILE 2>&1" is not the same
thing, but don't recall now why. Maybe you know better, I would use

     if sed -u -e s/a/b/ < /dev/null > /dev/null 2>&1

Ref: http://dsd.lbl.gov/~ksb/Scratch/sh_redir_pipe.html

Not that this is time critical, but couldn't the presence of "-u"
be checked once in the initiation, and use a flag here $have_sed_u?

This whole thing makes this almost a Linux specific solution,
feels a bit wrong. Why not accept the double date in syslog?

Hmm... but wait, maybe this *is* a GNU sed specific problem, that they
differ from other sed implementations in that they use buffered
read/write to gain some speed? And that this flag kind of restores sed
to behave like it should?

In that case, using "-u" for GNU sed sounds like the best solution,
but then removing sed if "-u" is not supported is not really needed.
Question is how to write a test case for this....

I can actuall simulate this, the fist version only output anything
when I type control-d, the second one directly on newline

  cat | sed    's/foobar/dsds/' | cat 1>&2 | sleep 10000
  cat | sed -u 's/foobar/dsds/' | cat 1>&2 | sleep 10000

or

  while true; do echo hej; sleep 1; done | sed    's/foobar/dsds/' | cat 1>&2 |
sleep 10000
  while true; do echo hej; sleep 1; done | sed -u 's/foobar/dsds/' | cat 1>&2 |
sleep 10000

Amazing, I had no idea. And this is a problem not only for GNU sed,
tested on Solaris, behaves like without the "-u" :-(

> +# Ensure that 'logger' exists, if it's requested
> +if [ $want_syslog -eq 1 ]
> +then
> +  my_which logger 2>&1 > /dev/null

The other way around again, if it matters :-)

<snip>
> +  if [ -n "$syslog_tag" ]
> +  then
> +    # Sanitize the syslog tag
> +    syslog_tag=`echo "$syslog_tag" | sed -e 's/[^a-zA-Z0-9_-]/_/g'`

Question is if this is being too nice? Maybe just give an error
message and terminate if not a valid syslog tag?

> +    syslog_tag_mysqld_safe="${syslog_tag_mysqld_safe}-$syslog_tag"
> +    syslog_tag_mysqld="${syslog_tag_mysqld}-$syslog_tag"
> +  fi
> +  log_notice "Logging to syslog."
> +  logging=syslog
>  fi

All minor comments, approved,

kent

-- 
Kent Boortz, Senior Production Engineer
MySQL AB, www.mysql.com
Office: [phone] ext. 4450 (VoIP)
Office: [phone]
Mobile: [phone]