XPCOM and Logging

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?


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.)

5 thoughts on “XPCOM and Logging”

  1. This is probably not the kind of thing you want to hear after you’ve written your own implementation, but Mozilla Labs has a pretty nice JS logging implementation too called Log4Moz:
    We are using it in Thunderbird for our global database and a few other things and I’ve extended it there to support Log4J-style network output to support their Chainsaw GUI as well as a magic JSON output mode of operation to support my own xulrunner log viewer tool (logsploder).
    Fantastically impressive that you wrote unit tests for this too, btw!
    (From Alex: Actually, I’m the kind of person that likes hearing someone else has done it before. To me, that means something like this really is needed – though I obviously hadn’t heard of this before.
    I think I’ll stick with the design I came up with, in case I ever have to log from C++ code. Log4JS has the same problem NSPR does: single-language support. In particular, C++ logging and JS logging couldn’t really work together. I already have enough problems getting integrated debugging stacks. I don’t want to try integrating separate logs too.)

  2. Why “MPL 1.1 / LGPL 3 / GPL 3 tri-license” instead of Mozilla’s usual “MPL 1.1 / LGPL 2 / GPL 2 tri-license”? If you ever did submit it to mozilla-central, I hope you know that you would have to use the normal tri-license with GPLv2/LGPLv2… Anyway, just something I noticed.
    (From Alex: I noticed that too. GPL2 / LGPL2 – the licenses themselves – have been deprecated in favor of the 3rd editions. I just don’t think it’s a good idea to have the default license be a deprecated one. That said, I’ve no fundamental problem releasing it under GPL2 / LGPL2.
    I’d love to see someone write a blog entry on “Why we haven’t switched to GPL3 / LGPL3”, even if it only said “It’s very hard to contact all the code authors.”)

Comments are closed.