What guidelines do you adhere to for writing good logging statements

Question

I recently found a log statement in my projects codebase that says "here i am with search parameter==>===========11/30/2008===1====00:00 AM"

what guidelines do you adhere to for writing good log messages in an application?

Answer 1

That `log' statement looks more like a trace statement.

Logging: show the normal events and errors

Tracing: show the execution path as well as the all of the logging events

Personally, I want logging to find out what work has been done by my program, and I want trace statements to verify the execution path and for figuring out what went wrong. I'll route tracing statements to a separate file which includes both types of log messages for context.

So you should have 2 log levels at least, and be able to turn off tracing for performance. You should be able to route these event streams to different locations. This allows you to easily keep logs for historical records, while not having them cluttered with debug info that you only want for tracing problems.

A lot of the answers here focus on the fields that you would include in a log message, but I would argue that the placement and logging level of the log calls are more important. If you use log4net you would be able to include/exclude the date stamp at will via config files, but you won't be able to place or remove log statements without recompiling, so it makes sense to think pretty hard about where they go. Beyond the standard fields, such as timestamp and thread ID, etc, you want to know the class and method name that the call was made from. Log4net et al takes care of the class name already if you go by their best practice of naming your logger after the type you are concerned with. Beyond this, I typically include the method name. This is particularly necessary for tracing, but I include it on all my log messages.

Logging:

You want to know enough information about what action is about to be performed to go back and poke around if something goes wrong. Good candidates are message IDs, email addresses, something that uniquely identifies the work item. This sort of message should come as soon as this sort of data is available, so that when you are reading down through a log file, you will see something like 'attempting to do x with y' and then later if we see an exception, we know which work item we need to look at to see why we failed.

Logging exceptions should be paired with an 'attempt' log message, so that the exception message makes sense in context when reading the log. This means thinking about the structure of exception handling. If you are using .net and you only want to log an exception, not handle it, you want to rethrow the same exception, not a new one, so just do 'throw' not 'throw e' where 'e' is your exception instance. Look this one up if it doesn't make sense.

Tracing:

This is actually simpler, usually I'll have a message at the beginning and end of a method of interest, like bookends. In the entry you can print critical method arguments that affect the program flow. Logging a message at the end of a method is kind of optional, usually you will be interested in looking at the trace sort of like a stack trace. You can figure out the execution path without them.

Performance:

For string performance, use the '*Format' methods if you are using log4net or something similar. This internally will use a StringBuilder so that you aren't paying the immutable string penalty all the time. Generally though the key is to be able to turn tracing off for performance, and have logging be terse enough to leave on, even if a log message is expensive. When correctly done, there shouldn't be enough of them to be a problem.

Answer 2

The most useful part in a log statement (except maybe the date & time of course) is a unique ID. All our log entries begin with MSG-xxxxx where xxxxx is a unique integer. This MSG-xxxxx tag is always hard-coded in the source, never in a resource file, so it is easy to find it back. It is also a very easy search key in the documentation.

Also what is useful is to always enclose variable string content in double quotes to easily differentiate from the message itself:

MSG-12345 Tried to open "myfile.txt", returned error code "123 - file not found".

This also helps when you try to extract information from the log using some regular expression.

Answer 3

Do not do String concatenation in logging statements, at least debug statements.

One Java app I was working on a while ago had dismal performance. So we cracked out the profiler to see where the bottlenecks were. Turned out that it was mostly due to String concatenation operations incurred by assembling DEBUG level logging statements that occurred ALL THE TIME inside nested inner loops etc (hah, and to think they got added in the first place to figure out why the performance was so bad!)

don't do this

LOGGER.debug("The variable was " + myVariable + " and we are doing " + foo);

Instead do this

if (LOGGER.isDebugEnabled()) {
  LOGGER.debug("put your debug statement here " + foo + " and " + bar);
}