[PATCH v2 00/14] Fix signal-unsafe logging

[Peter Hutterer]

On Wed, Apr 11, 2012 at 06:33:26PM -0700, Chase Douglas wrote:
> On 04/11/2012 04:53 PM, Peter Hutterer wrote:
> > On Mon, Apr 09, 2012 at 11:17:26AM -0700, Chase Douglas wrote:
> >> This new patch set includes a few fixes to the first and many more fixed
> >> logging paths. All paths in the server that occur when it encounters a
> >> fatal signal are now handled properly.
> >>
> >> I do not think this affects the crash I have been seeing in the Ubuntu
> >> server. I tracked that issue down to a bug in the synaptics input
> >> module. Since the only known issue is that running the server under
> >> valgrind may fail if messages are logged inappropriately, I suggest we
> >> not apply this to any stable branches.
> >>
> >> The full tree is still maintained at:
> >>
> >> http://cgit.freedesktop.org/~cndougla/xserver/log/?h=signal-logging
> >>
> >> Thanks!
> > 
> > Looks good and this is certainly needed. I do have a few comments though:
> > 
> > - I'd really like to see some tests of these new functions. Should be easy
> >   enough to write, given that they're all exposed and you can use strlen,
> >   strcmp, etc. to compare results.
> >   Plus, you should be able to test them inside a signal handler too with
> >   little effort.
> 
> Some of the functions definitely could use tests, like strlen_sigsafe().
> I'll add some.
> 
> However, I don't know if it's possible to add tests for behavior inside
> a signal handler. For a test to be useful it must be repeatable and fail
> every time it's wrong. Usually signal context corruption is
> indeterminate. Maybe it could be repeatable with the use of valgrind,
> but even then I'm not 100% sure.
> 
> > - AFAICT, every single caller to LogMessageVerbSigSafe uses -1 as verbosity.
> >   How about a LogMessageSigSafe wrapper?
> 
> There are a few places where I replaced non-ErrorF calls, where the
> verbosity remains 1 instead of -1.
> 
> I thought about creating a non-verb wrapper, but I didn't really have
> much of an interest in reproducing all the different logging macros and
> variations we currently have. The idea is that logging in signal context
> should be fairly infrequent, and if you need it then you can get along
> with all the args.

It should be infrequent, but any error between ReadInput and mieqEnqueue will
require it. That may not happen often, but the code still needs to be there.
So a sensible API is something we should definitely aim for.

> Secondarily, what would you default to? ErrorF uses -1, but LogMessage
> uses 1.

There's a reason that ErrorF is different (albeit just a wrapper) to
LogMessage - it makes the code more obvious. A LogMessageVerb(..., -1, ...)
is much less obvious and grep-able than ErrorF(). So at least having
ErrorFSigSafe() is a good thing to have. It would make any new code stick
out. "Hey, it's ErrorFSigSafe up there, but ErrorF here - one of them is
wrong".

> > - the API is rather shocking, replacing one vararg function with a number of
> >   mixed calls makes it really hard to grep for the message.
> >   a poor man's printf parsing that searches for %d, %s and %x would help
> >   here.
> 
> Variadic argument implementation is some of the blackest magic of C
> code, and varies a great deal even between architectures of glibc. I
> don't know if we can be sure that variadic arguments will always be
> signal safe. They aren't mentioned in the POSIX signal(7) man page as
> safe functions.
> 
> I doubt we would actually support Interix SUA, for example, but it is
> POSIX compliant and its man page says va_* functions are not signal
> safe: http://www.suacommunity.com/man/3/varargs.3.html.

yeah, unfortunately that's the only documentation I found too, nothing else
seems to hints at whether it's signal safe or not.

If we can't use varargs, we really need to re-do the error messages to be
less clunky. e.g.

        LogMessageVerbSigSafe(X_NONE, -1,
                              "Please also check the log file at \"");
        LogMessageVerbSigSafe(X_NONE, -1, xf86LogFile);
        LogMessageVerbSigSafe(X_NONE, -1, " for additional
information.\n");

can be 
    LogMessaveVerbSigSafe("For additional information see the log file at );
    LogMessaveVerbSigSafe(xf86LogFile);
which makes it a lot more grep-able. Or, something like this below. Uncompiled,
just a quick write, so don't expect this to work, it's just to illustrate:

  typedef union {
      uint32_t ui;
      int32_t i;
      char *c;
      const char *str;
      void *ptr;        
  } log_param_t;
      
  /* Log a message using only signal safe functions. */
  void
  LogMessageVerbSigSafe(MessageType type, int verb, const char *message,
                        log_param_t* param)
  {   
      const char *type_str;
      int param_idx = 0;
      int begin, end;
      int slen;
      char number[20];
      int i;
          
      type_str = LogMessageTypeVerbString(type, verb);
      if (!type_str)
          return;
      
      if (type_str[0] != '\0') {
          write(logFileFd, type_str, strlen_sigsafe(type_str));
          write(logFileFd, " ", 1);
      }   
              
      begin = end = 0;
      slen = strlen_sigsafe(message);
              
      for (i = 0; i < slen; i++, end++) {
          if (i < begin)
              continue;
          
          if (message[i] != '%')
              continue;
              
          /* We found a %, it's not a %% escape, log message from last stop to
           * here before attempting replacements */
          if (begin != end && 
              i < slen - 1 && message[i + 1] != '%') {
              write(logFileFd, &message[begin], end - begin);
              begin = i + 1;
          }       
              
          switch (message[i + 1]) {
              case 'd':
              case 'u':
                  FormatUInt64(param[param_idx].ui, number);
                  break;
              case 'x':
                  FormatUInt64Hex(param[param_idx].ui, number);
                  break;  
              case 'c':
                  write(logFileFd, &param[param_idx].c, 1);
                  break;
              case 's':
                  write(logFileFd, param[param_idx].str,
a>                        strlen_sigsafe(param[param_idx].str));
                  break;
              default: /* FIXME: error msg */
                  break;
          }
      
          param_idx++;
      }
  
  
      write(logFileFd, message, strlen_sigsafe(message));
      fsync(logFileFd);
  }

Instead of varargs, the callers need to supply a log_param_t array, which is
painful, but hopefully better than splitting log messages over several commands.

Cheers,
  Peter
 
> > - given that input drivers almost always use signal-sensitive processing,
> >   making xf86IDrvMsg signal safe would go a long way 
> 
> It's variadic, so I don't think that will be possible. I know there's
> bound to be some pain here that reaches device drivers, but I don't see
> a way around it.
> 
> -- Chase