What guidelines do you adhere to for writing good

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

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 2

In my logs, I need the date and the time, the process that creates the logs, and the PID. There's nothing worse than looking at logs and wondering whether they came in five minutes ago, or whether they were left behind 5 years ago before your changes. Date and time are important.

When I report errors, I state concisely what was called, what happened, and what error codes came back. If it's errno, I also report back strerror(errno). I'm reading this to find a problem, and usually I'm in a screaming hurry to find the problem. I don't want to look stuff up. I want it to tell me what happened, and I prefer verbose to useless. If I'm debugging, and often even when I'm not, I'll log all the data like the SQL statement or the low-level record, keys, anything that will help me find the problem ASAP.

Sometimes we log insanely, and it can slow the system slightly. But when shit goes down and we get a subpoena and there's a lawsuit on the loose and accusations of baby-killer are being thrown around, we love that we have enough logs on tap to show exactly what happened and why and who caused it. It's Blame Management.

Answer 3

There are 5 aspects which are important for me (starting from less important):

1. Include timestamp in the log entry
2. Provide possibility to filter out less important, "spamming" entries. Good, old square brackets tags should be enough for grep. It would be nice if some of them would be generated automatically - depending of log type (message, warning, assert etc.) and optionally message importance level (spam, normal, high, critical). Adding additional, context narrowing tags by hand is also recommended IMO.
3. Make log functions/macros as easy to use as it's possible.
4. Flush output buffers immediately.
5. Provide possibility of instant and unambiguous determination of place of log entry generation (source file name + line number). It may be difficult in some languages but very often knowing exactly which assertion failed means immediate fix of the bug. Additionally you don't lose a time for adding log place identifiers by hand (e.g. "SomeClass::SomeMethod: Message")

Answer 4

Code variable levels of logging, so you can switch between nothing, basic information on the program flow and insanely detailed information on the inner workings. Then by adjusting the variable that controls logging level you can control how much output you want to receive.

In large projects where you want to be able to receive logging from customers encountering problems it also helps if you can control which parts of your application will log; for example if there is a problems with reading AD user information you can add "AD_LOGGING=EVERYTHING" and receive detailed logginginformation on that without seeing the log information from every other section of the program.

Answer 5

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);
}

Answer 6

We use "two-dimensional" logging i.e. logging by individual module and within that by level. That gives us real control when trying to debug customer problems.

Each log entry has a unique id plus date plus time plus module plus debug level. The id is reflected (if need be) in the exception / error message displayed to the user. So if the users logs an incident, we can quickly pull up that section of the log and see what happened around that point.

The Debug level messages don't use generalities like "Invalid input", We log the actual values that have caused the problem. If that field has relationships to other fields, we log them as well.