Sun, 28 Sep 2008
Colorizing standard error: Adventures in LD_PRELOAD
Kristian again asked an interesting question on the SF-LUG mailing list. This time, it was: "How can one get stderr and stdout to appear in different colors?" He was asking on behalf of someone, in turn on behalf of a Java programmer.
I thought about this and discussed it with Jesse Zbikowski, who I happened to be sitting next to at the Tenderloin Computer Help Day that Christian Einfeldt invited the list to (which turned out to be a lot more interesting and orderly than I had imagined!).
Jesse and I talked and we thought of named pipes, which Jesse got to work on and produced a nice Perl tool for. I thought about LD_PRELOAD and got off to a few false starts, and finally came up with a tool I called stderred (tarball of v1.2). It includes a demo program in Java and a README.
LD_PRELOAD
LD_PRELOAD wrappers are a way to change the way a program executes by replacing library functions, like write() or gettimeofday(), with your own homebrew versions. You can think of the dynamic linker as allowing you to stack your own things "above" the C library, but "below" the actual program that runs. So in looking for a symbol (a function name, typically), the program searches down until it finds it, and uses that.
"stderred" is a C program and a Makefile that you can demonstrate works properly; it includes a sample Java program and a README. Because it intercepts the Java JRE's calls to write() to write out messages to stdout, stderr, or whatever, and only modifies the ones to stderr, it should be safe to use everywhere. Plus there are no race conditions; it runs right in the context of the program, so it also avoids the performance penalty of context switches.
This LD_PRELOAD wrapper is interesting, I think, because (thanks to Eric Northup for the idea) it calls the real system write() function by yanking it out of libc using dlopen()+dlsym(). I was also (you can see this in the first few revisions) trying a #define hack to get access to libc definitions without the real symbols; however, this failed a link-time. I don't see how it could work.
The problem with named pipes: Buffering can change the order of outputted lines
Jesse pointed out to me that the named pipe approach has a serious buffering issue related to timing: if the process writes to stderr and stdout in quick succession, the lines could appear colorized in the wrong order. Jesse shows me some variations of his script that changed which wrong order it generated, but we couldn't quite figure out how to make it always right. This seems like a race condition to me.
That's because when the named pipe in question is read from, the Perl script doesn't know *how much* to read. So in this case:
one line to stderr
one line to stdout
one line to stderr
After Jesse explained this to me a few times, I understood it would get printed as either:
one line to stdout
one line to stderr
one line to stderr
or the same with stderr's lines on top. Note that the interweaving is gone; this is because the information of how *much* was printed each time is thrown away by the OS. Because the read()s are happening out-of-process in both the ZSH and Perl ways to do this, I don't see how they could get around this issue. An implementation based on select() or epoll() would have the same issues, I believe.
Why my solution doesn't work for "ls"
stderred is as simple as it is because it only overrides write(). The JRE only seems to use write(), not any of the helper functions like straight-up printf(), or error(), or fprintf(), that also write to file descriptors. Unfortunately, if you try to stderred-ify "ls", none of stderr appears red! That's because ls uses fprintf_unlocked() and error(), which themselves *inside libc* call write().
If you think of ls as standing on top of a library stack that looks like this:
ls
[stderred]
[libc]
if you know that symbol resolution only looks "down," it's clear that the functions *inside libc* don't go back *up* to stderred to find my hacked write(). So they use the libc write(), which doesn't colorize.
Therefore, I started down the long road of modifying "all the important" functions to colorize if the output was going to stderr. Trying to colorize "ls" is where I started, so I wrote quite a few of those before actually checking what Java used. "ls" nearly gets colorized properly; you can look through the with_error branch for the latest work down that path. But I stopped once I figured out Java seems okay with just write(), and for cleanliness's sake I left that out of the released version (currently 1.1). Patches welcome!
zsh, python, and further reading
According to the Gentoo-Wiki, zsh users have an easy way to enable colorizing stderr. Knowing little about zsh but something about UNIX, it seems to me when they fork to run the new program, they close() fd #2 (stderr) and open it as a pipe to this program. I don't see how they solve the races brought up by the Perl thing; it seems to me they'd have the same race.
This is the same path that Jesse and I started down in the beginning; we read http://tldp.org/HOWTO/Bash-Prog-Intro-HOWTO-3.html and noticed it didn't discuss setting stderr to a pipe, and then we talked about named pipes....
The Pythonic way to do this would have been to "simply" globally override what "sys.stderr" is. I don't know if such a thing is possible in Java.
You can read a quick tutorial on LD_PRELOAD in the IBM DeveloperWorks article, "Override the GNU C Library -- Painlessly." You can read a lot more about dynamic linking in the exhaustive "How To Write Shared Libraries" by Ulrich Drepper.
