Logging best practice - log method call or log at beginning of a target method?

Question

When should we log? Before function calls (example A) or at beginning of a target method (example B)?

Note, that this question is about exact logger function call placement, not general best logging practices.

Solution A: Log at function call:

function someProcess() {     log.info("Reading data");     readDataFromIO();     log.info("Outputing data");     outputDataToScreen(); }  // ... other module:  function readDataFromIO() {     ... }  function outputDataToScreen() {     ...  } 

Solution B: Log at the beggining of a method:

function someProcess() {     readDataFromIO();     outputDataToScreen(); }  // ... other module:  function readDataFromIO() {     log.info("Reading data");     ... }  function outputDataToScreen() {     log.info("Outputing data");     ...  } 

In solution A you can customize message or resign of logging when efficiency issues rise, but you can just forget to log and you have lot of duplicated code if the log message looks the same. In solution B there is no risk to forget about logging and no code duplication, but you can't turn off logging logic 100%, and you are in trouble if an error is in a method call, like a null pointer exception. Which is the best practice?

Answer 1

Of course, the best practice is to put logging where you need it. :-) But in your example, the best practice would be not to use logging at all.

Logging is generally not good for tracing program flow (which is what it appears you are trying to do), despite the existence of a TRACE level in a lot of logging frameworks. The best use of logging is to log data flowing through the system, particularly data that causes problems.

When logging data, the data should be logged in the context where it can best be explained. That is usually

• at the beginning of a function (logging the inputs),
• at the end of a function (logging the outputs or timing), or
• where an error is detected.

To find out where a fatal error occurs you should have an error handler that is informed of the fatal error and logs a stack trace showing where the error occurred. (The most modern languages do this by default and the older ones have ways of enabling this by now.) You should not try to log the execution path in an attempt to localize the problem.

Answer 2

The practices i'm giving here are not from any source, but what i use and have found most effective over many years of usage.

Log in methods

A method is block of code that has a certain purpose. Keep the logging of each method in the method itself. That way, when you re-use the method from other places, you will not have to add loggers in each place. If the method happens to be a util that is called from many places, reduce the logger level or the logger priority for that prefix.

Use MDC/request id/Thread name

To track down the flow of the request or the source of the call, set a parameter in the logger or use thread name so that all subsequent logs have the tag and follow the logs for that tag. Generally, its best to set the tags in logger as soon as the request is received.

To avoid duplicate logging

Catch exceptions and log at a certain logical stage in your code. Eg - In a web application with the following stack Action/JSP/Web service etc -> module call -> helper modules -> Util -> library.

Here i would log at my module call level (corresponding to someProcess() in your code). Any inner calls would be DEBUG level calls put inside the methods. Alternatively, you could log the helper modules etc with a higher log filter.

Logging is a very subjective matter, and its got more to do with deciding one way and sticking to it everywhere. There's no one size fits all solution. You need to figure out your level of detail vs performance vs signal to noise in the logger you are using by tweaking the parameters little by little over time.