Where/what level should logging code go?

Question

I'm wondering where logging code should go. For example, should my repository log it's own errors? Or should I log all errors from the UI/controller? Are there any general deisgn principles about this, or does anyone have link to a good article or somesuch.

Answer 1

Logging and tracing is (IMO) a fine art, knowing what to log and where takes experience.

I've found that the best (worst?) way of learning the art of logging is by experiencing the pain of attempting to diagnose issues with shoddy logging!

All I can offer you is some points of advice:

Think about how the log message will be used.

The key to good logging is to think about how the log message will be used if there is a problem, conversely the worst thing about poor logging is that you will only ever realise it when you have a problem and you don't have enough information!

Always think about what the log message says to the person who is reading it, for example:

• Has a windows API call failed? If so then you probably need to log the HRESULT and the GetLastError result (if there is one) for it to be of much use.
• Couldn't find an entry in a collection? Without the name of the entry that wasn't found there really isn't much anyone can deduce - it would also be handy to know the count of the collection so that you can tell if the collection is empty.

A common mistake is to not think about what information is required when logging, however you should also think carefully about when a message will be logged - if a message is logged frequently under normal operation then at best it's usefulness is questionable and at worst that log message can be misleading.

Also, make sure you can identify what logged a message. If all you can see in a log is a string which appears in your code base many times (or worse still not at all!) then you are going to need to deduction and cunning to figuring out where that log message came from (and without knowing where a message comes from, you have little hope in understanding it)

• In multi threaded / multi processor applications always log the thread id and the process id.
• If you have a request id of any sort, log that too.
• If you believe that you are going to spend any reasonable length of time looking at log files then you should strongly consider shipping whatever pdb etc... files are needed in order to see source files and line numbers.

Logging is only used when there is a problem

Don't confuse logging with error handling. Error handling is the act of responding to and resolving that error, (e.g. displaying a message to the user), logs are (generally) only used when something has gone wrong and the reason is unclear.

For example: If a use attempts to open a file that doe not exist then if the error is correctly handled (by telling the user that the file couldn't be found) then there should be no need to log that error.

(The possible exception might be if you wanted statistics on how frequently that error happened or something - this comes back to thinking about how the logging will be used.)

In general correctly handling an error is preferable to logging, however good error handling is even more difficult than good logging - these are the cases where the extra information offered in logs is needed.

You also shouldn't confuse logging with auditing (although in many systems the two overlap).

More is better!

The only way you can log too much is if:

• You run out of storage space.
• You significantly affect the performance of your app.
• You get swamped with logs that you can't easily process in the case of an error.
• You log profanities directed at your boss.

Logging exists purely to diagnose the cause of problems (don't confuse logging with auditing) - if you don't have any problems then nobody is going to look at your logs, and no harm is done! Until you have a problem that is, in which case you need as much information as you can get.

If you are in doubt on whether or not to log something, then log it.

Only log exceptions once.

Having stated the above, I feel the need to clarify the logging of exceptions.

In general you should only log an exception once (at the point where it is handled). Don't be tempted to log an exception that you later throw to the caller "just in case" the caller doesn't log the exception properly - all that happens is that you end up with the same exception being logged many times as it passed from tier to tier (I've seen it happen and it makes it difficult to see how many errors actually occurred).

It is the callers responsibility to log an error - the only possible exception might be passing between system boundaries (e.g. web services), where it's not possible to transport across all of the error detail.

Log whatever is relevant, wherever it is relevant to log it.

For example, if you are writing a server based application then your log files need to be on the server, where the sysadmins can read them - if however there is potential for errors to occur on the client (e.g. in JavaScript), then your logging code needs to be in JavaScript. The solution? Your JavaScript logging needs to submit itself to the server (ala log4js)

Don't worry about where you should and shouldn't put logging - just put it wherever it is needed.

Answer 2

In general, it is best to log things at the place you have all the necessary information. And to make your app simpler, it is best not to pass around data just so that you can log it somewhere else. (Exceptions seem to be an exception - sorry for the pun :-) - but their primary purpose is not logging, it is just a possible side effect.)

There is no need to restrict logging to specific modules/layers of the architecture (except some special cases, e.g. device drivers which are not supposed to be logging anything, or application libraries which must not make assumptions about the environment).

Note that different log messages may have different purposes, even within the same application:

• To give information about the (normal) flow of events within the app (i.e. a batch processing app may log that it started and finished, possibly the brief result of the processing etc.). Such messages should preferably be relatively few containg a limited amount of information, as they are often meant for humans to read (e.g. a sysadmin to check in the morning that the app ran successfully). Since these are "normal" messages, their priority is in the middle of the scale, e.g. INFO.
• To alert to exceptional events (e.g. errors, crashes, missing files, ...). These messages should be rare (in a normal app), but may contain an excessive amount of information (such as stack traces, core dumps etc.) which may help identifying the underlying bug. However, when they happen, we almost always want to see them, therefore they have a high priority, such as ERROR or FATAL.
• To give detailed information about what happens in a specific part of the app (usually for debugging purposes). These messages are typically a real hog, often generating Gigabytes of log data. Therefore we only want to see them under specific circumstances, thus it is apt to set their level to low, e.g. DEBUG.

Modern logging frameworks such as the Log4J family allow very flexible handling of different types (levels) of messages from different parts of the application. Still, it is a good idea to plan your logging scheme before adding a plethora of log messages to the code. I.e. what types of messages you plan to log in which parts of the app, and how you are about to use these messages? How many and what kind of log targets (console, file, DB) you need?