Where to position logging statements

Question

I have the following classes :

class Task
{
    public void DoSomething()
    { 
        var s = new Service();
        s.First();
        s.Second();
        s.Third();
    }
}

class Service
{
    public void First() {};
    public void Second() {};
    public void Third() {};
}

If I want to add logging, should I put logging statements like this :

    public void DoSomething()
    { 
        Log("new");
        var s = new Service();

        Log("First");
        s.First();

        Log("Second");
        s.Second();

        Log("Third");
        s.Third();
    }

Or should I put each statement inside the called methods of Service class ?

I know it is quite subjective, and won't change a lot of things, but I'm curious about the pros and cons of each approach.

Update : I'm not asking about verbosity or level, just about placement of the logging statements.

Answer 1

It is indeed subjective. Every project and every situation requires its own level and verbosity of logging.

Personally, I would put the statements inside the methods they refer to. This is more foolproof, as it logs any calls to these methods, not just the ones inside doSomething(). This may help you spot subtle bugs in the long run, if the methods are called when it's not appropriate.

Nevertheless, I don't put entry/exit log statements into code by default, as they create too much noise. Only specific cases justify them, e.g. when analysing a complex module or hunting down a tricky bug (such as a concurrency issue).

Answer 2

This strongly depends on what you need it for. Without knowing about your situation I would suggest that you consider the following:

• Use a logging framework that allows for one message being more important than another. Typically you are interested in ERROR (really bad), INFO (like a pulse) and DEBUG (ok, what did actually happen here). Also log statements are time stamped.
• All exceptions need to be logged at ERROR level.
• The things you need to see to be convinced that things are working nicely should be logged at INFO level. You do not necessarily want a lot here. Just enough to see that things run smoothly.
• The things you need to see to figure out where things go slow or incorrect log at DEBUG level. This can be very verbose as you only activate it when you need to see problems.
• Make the messages self-standing if at all possible. This allows you to read the log files more quickly.

In this case I would consider

public void DoSomething()
{ 
    Log.info("DoSomething()");
    var s = new Service();

    Log.debug("First");
    s.First();

    Log.debug("Second");
    s.Second();

    Log.debug("Third");
    s.Third();
}

But you are the only one to know what you will need to know to debug an issue. Much of this knowledge unfortunately comes from having been in situations where you didn't have it. Hopefully this will avoid some of them.

Good luck.

Answer 3

There are no fixed rules on this as Peter has written, I would do both - put some inside each individual method as well as before it.

In the current code example, if there is an exception in First(), you would probably know it when you don't see the logger before calling Second()

However, you could log something in First() to ensure that First() did it's task successfully and then move on to Second() and so on

Answer 4

Yep, fairly subjective. What I do:

• Log entry to a public method (with param values).
• Log exit from the same (with return value if there is one).
• Log exceptions (with appropriate details).

Personally I have found that doing more than this adds more noise for less value. E.g. I rarely log entry/exit in private methods, I occassionaly log unexpected paths that may be errors but are not exceptions, but this is very rare. If I were writing your code above I would remove the Log("First") etc, and put logging inside the First() method (if it were public).

Answer 5

Update : I'm not asking about verbosity or level, just about placement of the logging statements

Sorry, but that's the wrong attitude. If you don't think about what you're logging, then where you log doesn't matter. In fact, you can place your logging statements wherever you like, because they'll not add much value.

Taking an example from your code:

class Task
{
    public void DoSomething()
    { 
        var s = new Service();
        s.First();
        s.Second();
        s.Third();
    }
}

DoSomething has no decision points, so there's no good reason to log between each statement. If any of the method calls fail, of course, it's important to log that. However, that typically gets handled via a catch block.

On the other hand, it's critically important to know what task is being processed, and what context surrounds that task (I'm assuming a unique task ID and user here):

class Task
{
    public void DoSomething()
    { 
        log("DoSomething: task " + getId() + " invoked by " + getUser());
        var s = new Service();

Answer 6

I prefer to separate logging from my code. This gives each class a single reason to change. The logging class changes when a troubleshooting dev needs more info. The actual code changes with its stakeholder's requirements. So I would create a LoggableService that would look like this (in C#).

public class LoggableService : Service 
{
  private Logger _logger

  public LoggableService(Args args, Logger logger) : base(args)
  {
    _logger = logger;
  }

  public override void First() {
  {
    LogStart(MethodBase.GetCurrentMethod().Name);
    base.First();
    LogSuccess(MethodBase.GetCurrentMethod().Name);
  }

  public override void Second() {
  {
    LogStart(MethodBase.GetCurrentMethod().Name);
    base.Second();
    LogSuccess(MethodBase.GetCurrentMethod().Name);
  }

  public override void Third() {
  {
    LogStart(MethodBase.GetCurrentMethod().Name);
    base.Third();
    LogSuccess(MethodBase.GetCurrentMethod().Name);
  }    

  private void LogStart(string method)
  {
    _logger.Info($"{method}: STARTED");
  }      

  private void LogSuccess(string method)
  {
    _logger.Info($"{method}: SUCCESS");
  }

}

So when LoggableService.First is called, the log will show a First: STARTED and First: SUCCESS. DoSomething will look like this.

public void DoSomething()
{
  var s = new LoggableService();
  s.First();
  s.Second();
  s.Third();
}

The log will look like this.

First: STARTED
First: SUCCESS
Second: STARTED
Second: SUCCESS
Third: STARTED
Third: SUCCESS