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

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.

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.

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.

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.