🔗 Fun hack to redirect stdout and stderr in order

Prologue

This is anecdote about roundabout ways to get stuff done. Pierre mentioned in the comments below that a proper way to solve this is to use unbuffer (though it does _not_ produce the exact same order as the terminal!). But if you want to read the improper way to do this, read on! :)

The story

Due to buffering, the terminal messes with the order of stdout and stderr of a program when redirecting to a file or another program. It prints the outputs of both descriptors in correct order relative to each other when printing straight to the terminal:

] ./my_program
stdout line 1
stdout line 2
stderr line 1
stdout line 3
stderr line 2
stderr line 3

This doesn’t change the order:

] ./my_program 2>&1
stdout line 1
stdout line 2
stderr line 1
stdout line 3
stderr line 2
stderr line 3

but it changes the order when saving to a file or redirecting to any program:

] ./my_program 2>&1 | cat
stderr line 1
stderr line 2
stderr line 3
stdout line 1
stdout line 2
stdout line 3

This behavior is the same in three shells I tested (bash, zsh, dash).

A weird “solution”

I wanted to save the log while preserving the order of events. So I ended up with this evil hack:

] strace -ewrite -o trace.txt -s 2048 ./my_program; sed 's,^[^"]*"\(.*\)"[^"]*$,\1,g;s,\\n,,g;' trace.txt > mytrace.txt
] cat mytrace.txt
stdout line 1
stdout line 2
stderr line 1
stdout line 3
stderr line 2
stderr line 3
+++ exited with 0 +++

It turns out that strace does log each write in the correct order, so I’m catching the write syscall.

Note the limitations: it truncates lines to 2048 characters (good enough for my logs) and I was simply cutting off n and not cleaning up any other escape characters. But it worked well enough so I could read my ordered logs in a text editor!