Sunday, May 10, 2009

I don't like using debuggers. It makes running things slow, especially when stepping or when hitting breakpoints. And then, inspecting the state is laborious. So I don't use them.

I prefer debug logging. There are a number of reasons why I prefer looking at logs.
  • They remain after-the-fact
    • When I'm assigned a bug that was filed a few days ago, I can go back to the logs of when it occurred.
    • I don't have to figure out how to reproduce a bug from the steps in the report. I can go back to the logs and see what was done.
  • If worse comes to worse, they can be turned on on production systems much much more easily than using a debugger on a production system.
Of course, that means the logging has to be meaningful. I can find almost any logging meaningful, though, since I look at logs in context, and with the source code available. Most people I work with seem to not look at the context of the logs, and just want to grep for specific strings to see specific things, so they're not as good as I am at using the logs to diagnose problems.

Many people I work with also do overly elaborate formatting of their logs. They also like adding extraneous line breaks or other strings such as "---->" in an attempt to make their logs visually distinct or easy to grep for. My preferred logging is like this

log.log("variable1="+variable1+",variable2="+variable2);

which shows the relevant information. I suppose most of the people I work with wouldn't find the logging I add useful, because they'd be using a debugger.

Some people I've worked with don't like the logs to be "cluttered" with stuff they don't find useful, and remove stuff. I rarely remove logging, because almost anything could become useful. The worst thing they do is remove the logging of stack traces that aren't expected. They'd log an exception like this:

log.log("Something failed: "+ex.getMessage());

and, in the logs would be:

Something failed: null

which is pretty useless. Or, they'd have

log.log("Something failed: "+ex);

which was give

Something failed: java.lang.NullPointerException

which is almost as useless. I would write

log.log("",ex);

which would print the stack trace, as the "Something failed:" (or whatever that string was) is useless compared to the stack trace, but all the logging interfaces require a message.

Ideally, every log item would automatically contain the timestamp, the thread name, the source filename and line number. Our logs, however, don't have the source filename or line number, but do have the log category, which, being the class name, is almost always good enough. I've had to deal with not having the thread name in some other logs, and that can make things much more difficult, but at least I've had access to the source code and could guess. For those logs, the code was written by people who hated "clutter" in the logs, so they didn't log stack traces, so I really didn't like having to diagnose problems that code.

No comments:

Post a Comment