Nice logging feature in Erlang

by Ruslan Spivak on June 22, 2011

Have you ever had, at least once, an exception when logging an exception because you’d screwed up the number of logging arguments?

Something akin to the following:

>>> import logging
>>> msg1, msg2 = 'Look', 'leap!'
>>> try:
...     1 / 0
... except Exception:
...     # crash and burn - no msg2. where is my unit test?!!!
...     logging.exception('%s before you %s', msg1)
...
Traceback (most recent call last):
  ...
TypeError: not enough arguments for format string

Here is what you get in Erlang:

1> error_logger:info_msg("~s before you ~s~n", ["Look"]).
ok

=INFO REPORT==== 22-Jun-2011::23:09:49 ===
ERROR: "~s before you ~s~n" - ["Look"]
2>

That’s right – you get ‘ok’ and a report. That allows you to get critical information even if there is a problem with your log message arguments without blowing your whole system. I like that, makes the system more fault-tolerant.

If you enjoyed this post why not subscribe via email or my RSS feed and get the latest updates immediately. You can also follow me on GitHub or Twitter.

{ 4 comments… read them below or add one }

laanwj June 23, 2011 at 3:50 AM

I think you’re on the right track Ruslan. I’d like to add that it might be a good idea to separate logging and message formatting completely. In my larger applications, I usually log structured records containing arbitrary information instead of formatted text messages. For example, I log JSON-based event records to a MongoDB database. This allows for adding diagnostic data (even complete stack traces including local vars) that might be useful in some cases without resulting in clutter.

Reply

Jean-Paul Calderone June 23, 2011 at 8:02 AM

It’s definitely nice not to get wacky exceptions out of your logging system – particularly if you’ve added some accidentally broken log messages while trying to figure out some other bug in your code. :) Twisted’s logging system also tries exceedingly hard never to raise an exception at you, but to present the most informative thing it can no matter what you give it. For example:

>>> from twisted.python.log import startLogging, msg
>>> from sys import stdout
>>> msg(format=”%(monkey)s %(taco)s”, monkey=”hello, world”)
2011-06-23 09:00:27-0400 [-] Invalid format string or unformattable object in log message: ‘%(monkey)s %(taco)s’, {‘monkey’: ‘hello, world’, ‘format’: ‘%(monkey)s %(taco)s’, ‘system’: ‘-’, ‘time’: 1308834027.4714639, ‘message’: (), ‘isError’: 0}
>>>

Reply

Ruslan Spivak June 23, 2011 at 8:32 AM

It’s good to know that Twisted has that useful feature – might come in handy one day.

Reply

Alex Kropivny July 4, 2011 at 4:04 AM

It’s more idiomatic to log terms, not formatted strings. They are machine-traversable, and pretty-printing is automated. So:
error_logger:info_report([foo_before_bar, {foo,Msg1}, {bar,Msg2}]).

It’s also more idiomatic to let the process crash on unexpected conditions. The error will be logged, in detail. Links and monitors will propagate the failure to any affected processes, and no more. Processes are cheap, so let them fail and be re-started rather than defensively program.

Catch-alls are used to hide details about some exceptions, or in rare code that must never crash (“error kernel” code).

Reply

Speak your mind

Previous post:

Next post: