2009-04-07

How to prevent stderr log messages from interleaving on Linux

Let's suppose you have a program which forks subprocesses, and each subprocess writes log messages to the stderr they share. Since processes run concurrently, it may be possible that the bytes they write interleave (overlap). For example, process A calls write(2, "ABC\n", 4) == 4, and, at the same time process D calls write(2, "DEF\n", 4) == 4. You expect that stderr will contain "ABC\nDEF\n" or "DEF\nABC\n", depending on which write succeeds first. But this is not always the case (!): messages written can interleave, e.g. stderr might contain "ABDCEF\n\n" or something similar. This post gives some recepies how to prevent that, and thus always get either "ABC\nDEF\n" or "DEF\nABC\n".

The instructions given below were tested on Linux 2.6.22 and 2.6.24, but they may probably apply other Linux kernels and other Unices as well.
  • Use the write(2) system call to write your log messages. Avoid anything which can buffer or split the message.

    • In C, don't use printf(3), fwrite(3), fputs(3) etc.; use write(2)

    • In Java 6, don't use System.err.println; use System.err.print, and add a "\n" by hand.

    • In Python, don't use sys.stderr.write or print >>sys.stderr; use os.write(2, ...)
    • .
    • In Ruby, don't use $stderr.write or $stderr <<; use $stderr.syswrite. Don't forget to check the return value.

    • In Perl, don't use print(STDERR ...); use syswrite(STDERR, ...).

  • If stderr is a pipe, make sure you don't write more than 4096 bytes at a time. If you have a longer log message, split it to multiple log messages of at most 4096 bytes (including the newline). This size limit doesn't apply if stderr is a regular file. This size limit has been verified for the kernels above.

  • If stderr is a regular file, make sure that it is in append mode when you are writing it.

    • Without append mode, even data loss is possible, e.g. instead of "ABC\nDEF\n" you may get "ADBEF\n" (losing "C\n").

    • You can ensure append mode by using the append-redirection 2>>file.log instead of 2>file.log when invoking the program.

    • In C you can use fcntl(2) to put a file descriptor to append mode: fcntl(2, F_SETFL, fcntl(2, F_GETFL, 0) | O_APPEND). (Don't forget about checking the return values to detect errors.)

    • In Python you can use fcntl.fcntl to put a file descriptor to append mode: import fcntl; import os; fcntl.fcntl(2, fcntl.F_SETFL, fcntl.fcntl(2, fcntl.F_GETFL) | os.O_APPEND).

    • In Ruby you can use IO#fcntl to put a file descriptor to append mode: require 'fcntl'; $stderr.fcntl(Fcntl::F_SETFL, $stderr.fcntl(Fcntl::F_GETFL) | Fcntl::O_APPEND).

    • In Perl you can use Fcntl to put a file descriptor to append mode: use Fcntl; fcntl(STDERR, Fcntl::F_SETFL, fcntl(STDERR, Fcntl::F_GETFL, 0) | Fcntl::O_APPEND).

As a more generic solution (not specific to Unix), you may also consider using mutexes or semaphores to prevent concurrent writes to the same file.

No comments: