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

Here's the tips I can give you based on my own experience (since you have flagged this topic language-agnostic, I'll keep it generic):

• Use a delegate function (or create a central log class with a log function) to log messages. The parameters should contain the log message, log severity and log level. This delegate function (or function from your log class) should be called everywhere where you need to log. It allows you to replace the log mechanism easily, e.g. change from file-based log to Windows event log. In this function you can also deal with the log level, i.e. make it configurable to suppress warnings etc.
• In someProcess() add a try-catch to allow catching runtime errors
• Log when you start something, and when you've ended something, and always log errors which might occur. Those log calls can be locally inside the function as shown in your example B.
• If the language you're using supports that, write a function/method for logging exceptions: For example, in C# you can write an extension method public static void Log(this Exception ex) { // ... logging code ... } for exceptions, which then allows you to simply call it in each catch block, like: try { ... } catch (Exception ex) { ex.Log(); }
  It can also be usefull to add an optional parameter to it like public static void Log(this Exception ex, string message="") { ... logging code ... }, so you can pass additional information to it like ex.Log("readDataFromIO() - read error occurred");.

This way you avoid the disadvantages you've mentioned in your question (duplicate code, not catched errors).

If possible, look if the framework or language you're using already has such a class (usually this is the case) and use it or develop your own framework which is using it (i.e. your own centralized logging class) rather than re-inventing the wheel completely.

Answer 2

The simplest solution would be to make an overload of your methods, such that you may specify when to "log" and when not.

function someProcess() {
    readDataFromIO(true);  //This will make a "log"
    outputDataToScreen();  //This will make no "log"
}

// ... other module:

function readDataFromIO() {
    readDataFromIO(false); 
}

function readDataFromIO(bool makeLog) {
    if(makeLog)
        log.info("Reading data");
    ...
}

function outputDataToScreen() {
    outputDataToScreen(false);
}

function outputDataToScreen(bool makeLog) {
    if(makeLog)
        log.info("Outputing data");
    ... 
}

Answer 3

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.

Answer 4

Best practice is to put the call to log() IN the function. You will see a trace each time the function is called, not only when it's called from 'someProcess'.

Answer 5

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 6

Additionally to what's been said before, I am using a somewhat generalized concept of logging. It helps me to discover situations where certain conditions do appear more frequently or less often than expected.

I am using a class LogEvent (code is Java, but idea can be ported to most languages):

public class LogEvent {
    private int count;
    private String name;

    public LogEvent(String name) {
        this.name = name;
        count = 1;
    }

    public int count() {
        return this.count;
    }

    public void inc() {
        count++;
    }

    public String name() {
        return this.name;
    }

    public void report() {
        if (count >= 1) {
            Util.info(name + " (x " + count + ")");
        }
        else {
            Util.info(name);
        }
    }
}

How to raise events and collect their occurrence?

LogEvents can be "registered" using a LogEventCollection:

import java.util.Map;
import java.util.TreeMap;

public class LogEventCollection {
    private Map<String, LogEvent> events;

    public EventCollection() {
        events = new TreeMap<String, Event>();
    }

    public void register(String name) {
        LogEvent ev;

        if (events.containsKey(name)) {
            ev = events.get(name);

            ev.inc();
        }
        else {
            ev = new LogEvent(name);

            events.put(name, ev);
        }
    }

    public void report(String title, int minCount) {
        Util.info("");

        if (!title.isEmpty()) {
            Util.info(title);
        }

        for (LogEvent ev : events.values()) {       
            if ((minCount < 0) || (ev.count() >= minCount)) {
                ev.report();
            }
        }
        Util.info("");
    }
}

To get an overview of the inner events of my program, the LogEventCollection method report() gives shows a list of all LogEvents with their respective counts. This list could by sorted by name or by frequency of the events.

Additional locking code or a thread-safe collection are necessary for multi-threaded applications to prevent conflicts during concurrent access to the LogEventCollection.

Obviously, this approach can by extended by adding conditional events (= call to register() is guarded by some condition) . Or the event logging can be disabled during production runs.

Answer 7

Best practise:

• Use some kind of Logger class/module (depending on language) that allows you to log at different levels (DEBUG, INFO, etc.)
• Log very basic functions in LogLevel DEBUG
• Log more complex functions in LogLevel INFO (e.g. functions that call other basic functions)
• Log potential problems with LogLevel WARN
• Log errors and exceptions with LogLevel ERROR

A seperate logging functionality allows you to turn logging on/off depending on effiency. But also you have the capability to log everything.

Example: In Java there's log4j that provides excellent customization options. You can define the logLevel and you can define which classes should have logging turned on. That way you can monitor the system at a basic level (WARN) and if errors occur you can set the DEBUG level for certain classes that you need to check.

This procedure highly depends on the language your working with (of course) but I think this "log4j" approach is a very good one.