What we have now

Over the last several years, I’ve learned to appreciate good message logging. Mozilla’s NSPR Logging API is a very good example, and works well, for compiled code.

JavaScript components? They can’t use NSPR. Neither can chrome, PyXPCOM, or any other privileged code. The best alternative I’ve got is a dump() statement. dump() writes to the standard error console, commonly known as “stderr”. In debug builds, though, stderr gets populated with a bunch of other stuff that I really don’t care about at a particular moment. (I’m not entirely clear of blame, either – leftover dump statements from my code pollute that console as much as anything else.)

At Skyfire, I’ve had to implement a couple logging systems as well, and the generated logs have helped us find and isolate bugs relatively quickly. What you log can help you identify bugs in most cases. They’re not a panacea, though: doing it wrong can really cost you.

Over the past few days, I hit a really weird bug in Verbosio’s templates system (which I’ve been quietly working on for about five months now, in a complete rewrite with tests). One test fails at a critical point, but it’s pretty far removed from the starting point. Amid all the other dump() statements and debug output, I can’t quite figure out where the code started going wrong. To pin it down, I think the best approach is to insert some logging.

Oh, and did I mention that Mochitest includes logging for pass, fail, and todo conditions… but conveniently left out an informational-only logging feature? (Having that helps when you’re trying to trace where a log statement came from – and the conditions at the time.)

The five paragraphs above combine to form one idea: Maybe I should implement my own logging service with tests.

Thoughts in the design

• First of all, keep it really simple. Most logging implementations I’ve seen use a module name, a severity level, and a summary string. I figure that plus an optional details string should cover most messages.
• For where those messages go, files are good. Streams are better. With a stream, you can feed it into a file, or read it into dump(), a XUL page’s multiline textbox, or anywhere else.
• Someone reading the logs probably wants a way of separating messages – so if I give them a “multipart” stream, where each part is a separate stream… it’s easy to tell each message apart.
• Make sure the user requesting the logging stream can specify which messages they want to receive – both by module name and severity level, and whether or not they want the details with each message.
• Make sure to cache all the messages, so that a logging stream created later still gets all the messages that came before it.
• Finally, since each message ultimately ends up as a simple string – use a simple string stream interface to construct each message as needed.

Did I overdo the design? Probably. On the other hand, it really maximizes flexibility. I don’t know how much memory multipart input streams consume, though, so I don’t recommend using this in a production environment. If you use this logging service for debugging, make sure you remove all references to it before checking in!

Did it solve my problem?

No.

Oh, the logging itself worked beautifully. But to get some of the data I wanted to log, I had to call other functions. Some of those functions triggered JavaScript garbage collection, which tried to run some cleanup code, which tried to execute JavaScript code I wrote, which resulted in a 100% reproducible crash. I don’t yet know what I’m going to do about that. I’ll probably first try to reduce the testcase and post it.

Also, logging itself will never solve the problem you’ve got. All it will do is provide data, and hints about where you are in the code execution. You still have to tell it what and when to log, and you have to read those logs to find the bug.

The good news is, though, that a logging infrastructure like this only took one afternoon to write. Sometimes, that’s all I need: a quick, simple component to organize the dirty work into one place.

(The code I wrote I am making available under MPL 1.1 / LGPL 3 / GPL 3 tri-license. If you want it under another license, feel free to e-mail me, and I’ll almost certainly say yes. I don’t currently plan on submitting this in a bug for landing in mozilla-central, though.)