I just hit some unexpected unix-ism (or maybe Linux-ism?) that I'd like to mention here. I found a workaround, but if anybody knows what's actually happening and can enlighten me, please send me an email, and I'll update the post.

OK, so I have a program that does stuff, and outputs its progress to stderr. And I'm invoking this from a shell script that also outputs stuff to stderr. A minimized sample:

echo "Outer print 1111" > /dev/stderr
perl -E 'say STDERR ("1111 1111 1111 1111 1111 1111 1111 1111\n")'

echo "Outer print 2222" > /dev/stderr
perl -E 'say STDERR ("2222 2222 2222 2222 2222 2222 2222 2222\n")'

Let's call this dothing.sh. This works just fine. Now let's say I want to log the output to a file. Naturally I do this:

./dothing.sh 2> /tmp/log

Surprisingly, this does not work:

$ bash dothing.sh 2> /tmp/log && cat /tmp/log
Outer print 2222
2222 2222 2222 2222 2222 2222 2222 2222

$ bash dothing.sh 2> /tmp/log && xxd /tmp/log
0000000: 4f75 7465 7220 7072 696e 7420 3232 3232  Outer print 2222
0000010: 0a00 0000 0000 0000 0000 0000 0000 0000  ................
0000020: 0000 0000 0000 0000 0032 3232 3220 3232  .........2222 22
0000030: 3232 2032 3232 3220 3232 3232 2032 3232  22 2222 2222 222
0000040: 3220 3232 3232 2032 3232 3220 3232 3232  2 2222 2222 2222
0000050: 0a0a                                     ..

The 1111 prints are gone, and we now have a block of binary 0 bytes in there for some reason. I had been assuming that writes to stderr block until they're finished. So I can, without thinking about it, mix writing to fd 2 and opening, and then writing to /dev/stderr. Apparently the right way to do this is to write to fd 2 in the script directly, instead of opening /dev/stderr:

echo "Outer print 1111" >&2
perl -E 'say STDERR ("1111 1111 1111 1111 1111 1111 1111 1111\n")'

echo "Outer print 2222" >&2
perl -E 'say STDERR ("2222 2222 2222 2222 2222 2222 2222 2222\n")'

Why?

Update

So I poked at it for a bit more, and it turns out that the obvious scapegoat (buffering) is actually not the issue. The problem is this:

$ ls -l /dev/stderr(:A)
-rw-r--r-- 1 dima dima 36 May  4 17:02 /tmp/log

:A is the zsh syntax for recursive link-following. /dev/stderr is thus ultimately a link to /tmp/log. So the file on disk /tmp/log is being opened for writing and written-to twice at the same time

  • once in the outer 2>/tmp/log redirection
  • again in the inner >/dev/stderr redirection

Now we know. Thanks to Larry Doolittle for pointers.