What’s your logging philosophy?

Question

As Jeff Atwood asked: "What’s your logging philosophy? Should all code be littered with .logthis() and .logthat() calls? Or do you inject logging after the fact somehow?"

Answer 1

My logging philosophy is pretty easily summarized:

1. Log that which is required to be logged (in the financial industry, for example, every change to nearly every DB is logged)
2. Log that which will aid in debugging, but use a switch to turn this on and off as needed
3. Add later logging as needed to find and resolve performance bottlenecks, and attack vectors

Answer 2

I take what I consider a traditional approach; some logging, surrounded by conditional defines. For production builds, I turn off the defines.

Answer 3

I agree with Adam, but I also would consider logging things of interest or things that you can demonstrate as achievements as a kind of proof of them happening.

Answer 4

I choose to log deliberately as I go, as this means the log data is meaningful:

• Depending on logging framework you can add level/severity/category information so that the log data can be filtered
• You can make sure that the right level of information is present, not too much, not too little
• You know when writing the code which the most important things are, and can therefore ensure they are logged

Using some form of code injection, profiling or tracing tool to generate logs would most likely generate verbose, less useful logs that would be harder to dive into. They may be useful as a debugging aid, however.

Answer 5

I start by asserting a lot of conditions in my code (in C#, using System.Diagnostics.Assert), but I add logging only where I find, while debugging or putting the system under stress, that I really need to have a way to follow what's happening inside of my code without having a debugger permanently attached.

Otherwise, I prefer using Visual Studio's capability to put traces in the code as special breakpoints (i.e. you insert a breakpoint and right-click it, then select "When hit..." and tell it what to display in that case). There is no need to recompile and it is easy to enable/disable the traces on the fly.

Answer 6

I think always, always, always add logging when there is an exception, including the message and full stack trace. Beyond that, I think it's pretty subjective to whether or not you use the logs often or not...

I often try to only add logging in critical places where what I am logging should very rarely hit, otherwise you get the problem like he mentioned of logs that grow way too big... this is why logging error cases is the ideal thing to always log (and it's great to be able to see when these error cases are actually being hit so you can inspect the problem further).

Other good things to log are if you have assertions, and your assertions fail, then log it... such as, this query should be under 10 results, if it is bigger there may be a problem, so log it. Of course, if a log statement ends up filling the logs, it is probably a hint to either put it to some sort of "debug" level, or to adjust or remove the log statement. If the logs grow too big, you will often end up ignoring them.

Answer 7

If you're writing a program that will be used by many people, it's best to have some kind of mechanism to choose what will be logged and what won't. One argument in favor of .logthis() functions is that they can be an excellent replacement for inline comments in some instances (if done properly).

Plus, it helps you narrow down EXACTLY where an error is occurring.

Answer 8

Log 'em all and let Grep sort 'em out.

Answer 9

I define a variety of levels and pass in a setting with the config / invocation.

Answer 10

I work with safety critical real-time systems and logging is often the only way to catch rare bugs that turn up once a blue moon on every 53rd tuesday when it's a full moon, if you catch my drift. This kind of makes you obsessive about the subject, so I'll apologise now if I start to froth at the mouth.

I design systems which are capable of logging pretty much everything, but I don't turn everything on by default. The debug information is sent to a hidden debug dialog which timestamps it and outputs it to a listbox (limited to around 500 lines before deletion), and the dialog allows me to stop it, save it to a log file automatically, or divert it to an attached debugger such as DBWin32. That diversion allows me to see the debug output from multiple applications all neatly serialized, which can be a life saver sometimes. The log files are automatically purged every N days. I used to use numeric logging levels (the higher you set the level, the more you capture):

• off
• errors only
• basic
• detailed
• everything

but this is too inflexible - as you work your way towards a bug it's much more efficient to be able to focus logging in on exactly what you need without having to wade through tons of detritus, and it may be one particular kind of transaction or operation that causes the error. If that requires you to turn everything on, you're just making your own job harder. You need something finer-grained.

So now I'm in the process of switching to logging based on a flag system. Everything that gets logged has a flag detailing what kind of operation it is, and there's a set of checkboxes allowing me to define what gets logged. Typically that list looks like this:

#define DEBUG_ERROR          1
#define DEBUG_BASIC          2
#define DEBUG_DETAIL         4
#define DEBUG_MSG_BASIC      8
#define DEBUG_MSG_POLL       16
#define DEBUG_MSG_STATUS     32
#define DEBUG_METRICS        64
#define DEBUG_EXCEPTION      128
#define DEBUG_STATE_CHANGE   256
#define DEBUG_DB_READ        512
#define DEBUG_DB_WRITE       1024
#define DEBUG_SQL_TEXT       2048
#define DEBUG_MSG_CONTENTS   4096

This logging system ships with the release build, turned on and saving to file by default. It's too late to find out you should have been logging AFTER the bug has occurred, if that bug only occurs once every six months on average and you have no way of reproducing it.

The software typically ships with ERROR, BASIC, STATE_CHANGE and EXCEPTION turned on, but this can be changed in the field via the debug dialog (or a registry/ini/cfg setting, where these things get saved).

Oh and one thing - my debug system generates one file per day. Your requirements may be different. But make sure your debug code starts every file with the date, version of the code you're running, and if possible some marker for the customer ID, location of the system or whatever. You can get a mish-mash of log files coming in from the field, and you need some record of what came from where and what version of the system they were running that's actually in the data itself, and you can't trust the customer/field engineer to tell you what version they've got - they may just tell you what version they THINK they've got. Have your code tell you itself.

That's my brain dumped...