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

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.