Redirecting stderr to syslog

Unix has two very useful features: stdio, which gives all routines a rich, global interface to output; and syslog, which manages (diagnostic) output from many processes.

How many times have you written a program that sent useful information to stdout or stderr, then had to convert all the I/O to use syslog, when the program was moved to a production system?

Worse, if you use test-driven development, all your unit tests must then mock up the syslog interface, so that you can capture the output and verify it.

If that was too painful, there is the option of piping all output/errors to a logger  process. Unforunately, if you naively run:

    $ myprog | logger -t myprog

your shell will never see the exit status from myprog. If you “reverse” the pipe by changing your program to call:

    stderr = popen("logger -t myprog", "w")

then you may lose log output or leave a zombie process behind, when your program exits abruptly. There are similar down-sides to implementing the equivalent with threads and pipes, aside from the code being more complex.

Fortunately, stdio is more open-ended than you might expect — like ostream for you C++ programmers. Linux’s stdio has the fopencookie(3) interface, which lets you plug in arbitrary (read,write,seek,close) functions. Here’s how to do it with fopencookie:

#define _GNU_SOURCE
#include <stdio.h>
#include <string.h>
#include <syslog.h>

static char const *priov[] = {
"EMERG:",   "ALERT:",  "CRIT:", "ERR:", "WARNING:", "NOTICE:", "INFO:", "DEBUG:"
};

static size_t writer(void *cookie, char const *data, size_t leng)
{
    (void)cookie;
    int     p = LOG_DEBUG, len;
    do len = strlen(priov[p]);
    while (memcmp(data, priov[p], len) && --p >= 0);

    if (p < 0) p = LOG_INFO;
    else data += len, leng -= len;
    while (*data == ' ') ++data, --leng;

    syslog(p, "%.*s", (int)leng, data);
    return  leng;
}

static int noop(void) {return 0;}
static cookie_io_functions_t log_fns = {
    (void*) noop, (void*) writer, (void*) noop, (void*) noop
};

void tolog(FILE **pfp)
{
    setvbuf(*pfp = fopencookie(NULL, "w", log_fns), NULL, _IOLBF, 0);
}

FreeBSD’s interface is even simpler, replacing log_fns and the fopencookie call with:

    fwopen(NULL, writer)

With tolog, you add one line of code to the top of your program:

    tolog(&stderr);

and all other code, including compiled libraries, now synchronously sends its error output to syslog (add openlog to taste). If a message begins with one of the standard syslog priority keywords (“EMERG:“, “ALERT:“, …), then the output will be given the corresponding priority.

Advertisements

About mischasan

I've had the privilege to work in a field where abstract thinking has concrete value. That applies at the macro level --- optimizing actions on terabyte database --- or the micro level --- fast parallel string searches in memory. You can find my documents on production-system radix sort (NOT just for academics!) and some neat little tricks for developers, on my blog https://mischasan.wordpress.com My e-mail sig (since 1976): Engineers think equations approximate reality. Physicists think reality approximates the equations. Mathematicians never make the connection.
This entry was posted in Uncategorized and tagged , . Bookmark the permalink.

12 Responses to Redirecting stderr to syslog

  1. Hi, I’ve used your redirection advice above on Mac & Debian squeeze. It works great! One thing I tripped over today (Linux only): if printf is not doing any substitution, meaning it’s just printf’ing a string of text, then it bypasses your stdout redirection and goes straight to stdout. Just FYI.

    • mischasan says:

      Wow. Interesting. And if printf(“…no %…”) does that, puts(…) should do it as well. Putting that to the test:

      #include <stdarg.h>
      #include <stdio.h>
      #include <string.h>
      #include <unistd.h> // dup
      void tolog(FILE **pfp);
      // Mock syslog:
      void syslog(int pri, const char *fmt, ...);
      char logbuf[9999];
      int main(void)
      {
          FILE *fp = fdopen(dup(1), "w");
          strcpy(logbuf, "");
          tolog(&stdout);
      
          puts("PUTS");
          fprintf(fp, "PUTS >>> '%s'\n", logbuf);
      
          printf("NO NEWLINE");
          fprintf(fp, "NO NEWLINE >>> '%s'\n", logbuf);
      
          printf(" THEN NEWLINE\n");
          fprintf(fp, "THEN NEWLINE >>> '%s'\n", logbuf);
      
          fputs("FPUTS", stdout);
          fprintf(fp, "FPUTS >>> '%s'\n", logbuf);
      
          return 0;
      }
      
      void syslog(int pri, const char *fmt, ...)
      {
          va_list ap;
          va_start(ap, fmt);
          vsprintf(logbuf + sprintf(logbuf, "[%d] ", pri), fmt, ap);
      }
      

      The output, however is surprising:

      PUTS
      PUTS >>> ''
      NO NEWLINE >>> ''
      THEN NEWLINE >>> '[6] NO NEWLINE THEN NEWLINE
      '
      FPUTS >>> '[6] NO NEWLINE THEN NEWLINE
      '
      

      The strace output (with irrelevant syscalls removed) is:

      dup(1)                                  = 3
      write(1, "PUTS\n", 5)                   = 5
      write(3, "PUTS >>> ''\n", 25) = 25
      write(3, "NO NEWLINE >>> ''\n", 31) = 31
      write(3, "THEN NEWLINE >>> '[6] NO NEWLINE THEN NEWLINE\n", 46) = 46
      write(3, "'\n", 2)                      = 2
      write(3, "FPUTS >>> '[6] NO NEWLINE THEN NEWLINE\n", 39) = 39
      write(3, "'\n", 2)                      = 2
      

      So, under CentOS 6.3 with glibc, [f]puts(s) consistently works completely around the redirection, and now printf(s) seems to be behaving.

      The above is what you get when you let the program write to a tty. When you redirect it to a file, it seems to ignore the setvbuf(1,0,_IOLBF,0) done in tolog. So the nature of the original stdout affects the behaviour of the FILE* even after it’s been redirected to syslog AND setvbuf has been called. Sigh.

      dup(1)                                  = 3
      write(3, "PUTS >>> ''\nNO NEWLINE >>> ''\nTHEN NEWLINE >>> '[6] NO NEWLINE THEN NEWLINE\n'\nFPUTS >>> '[6] NO NEWLINE THEN NEWLINE\n'\n", 145) = 145
      write(1, "PUTS\n", 5)                   = 5
      
  2. “…the nature of the original stdout affects the behaviour of the FILE* even after it’s been redirected to syslog AND setvbuf has been called.”

    Right. Thanks for the detail & analysis. In the end, it’s an example of the importance of paying attention to the basics: abstraction away from OS-dependencies, testing, not assuming too much, testing, then some more testing. 🙂

  3. Merle says:

    Hi there! Do you use Twitter? I’d like to follow you if that would be ok. I’m undoubtedly enjoying your blog and look forward to
    new updates.

  4. muteki says:

    > (void)cookie;
    What does this line do inside the writer() function?

    • mischasan says:

      It suppresses a compiler warning 🙂 There’s no use for persistent state (the “cookie”) in writer().
      I tend to gcc with flat-out warnings enabled: -Wall -Wunused -Werror; and I figure other people do, too.

  5. Chris Cogdon says:

    ${PIPESTATUS[0]} will return the exit code of the 0th item in the pipe in the previous command. Much simpler, but clearly not a good option if you wanted to demonstrate some cool code 🙂

  6. Pingback: Exception from HRESULT: 0x80070005 ) on internal pc - Ziego Gyan

  7. Pingback: Redirecting standard output to syslog | Yoshizumi Answers

  8. RiseOfDeath says:

    warning: field precision specifier ‘.*’ expects argument of type ‘int’, but argument 3 has type ‘size_t’ [-Wformat=]
    (on amd64 lenght of int != lenght of size_t)

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s