Reporting information during code execution: best design

Question

I always had doubts when it comes to designing proper report of execution.

Say you have the following (stupid, to be simple) case. I will use python.

def doStuff():
    doStep1()
    doStep2()
    doStep3()

Now, suppose you want to give a report of the various steps, if something goes wrong etc. Not really debug: just informative behavior of the application.

A first, easy solution is to put prints

def doStuff():
    print "starting doing stuff"
    print "I am starting to do step 1"
    doStep1()
    print "I did step 1"
    print "I am starting to do step 2"
    doStep2()
    print "I did step 2"
    print "I am starting to do step 3"
    doStep3()
    print "I did step 3"

In general, this is quite bad. Suppose that this code is going to end up in a library. I would not expect my library to print stuff out. I would expect it to do the job silently. Still, sometimes I would like to provide information, not only in debug situations, but also to keep the user informed that something is actually in the process of being done. Print is also bad because you don't have control of the handling of your messages. it just goes to stdout, and there's nothing you can do about it, except redirection.

Another solution is to have a module for logging.

def doStuff():
    Logging.log("starting doing stuff")
    Logging.log("I am starting to do step 1")
    doStep1()
    Logging.log("I did step 1")
    Logging.log("I am starting to do step 2")
    doStep2()
    Logging.log("I did step 2")
    Logging.log("I am starting to do step 3")
    doStep3()
    Logging.log("I did step 3")

This has the advantage that you sort of know a unique place for your logging service, and you can tinker this service as much as you want. You can silence it, redirect it onto a file, to stdout, or even to a network. Disadvantage is that you get a very strong coupling with the Logging module. Basically every part of your code depends on it, and you have calls to logging everywhere.

The third option is to have a report object with a clear interface, and you pass it around

def doStuff(reporter=NullReporter()):
    reporter.log("starting doing stuff")
    reporter.log("I am starting to do step 1")
    doStep1()
    reporter.log("I did step 1")
    reporter.log("I am starting to do step 2")
    doStep2()
    reporter.log("I did step 2")
    reporter.log("I am starting to do step 3")
    doStep3()
    reporter.log("I did step 3")

Eventually, you can also pass the reporter object to doStepX() if they have more to say. Advantage: it reduces coupling with a module, but it introduces coupling with the instantiation of the NullReporter object. This can be solved by using None as default and checking before calling log, which is clumsy, because in python you have to write a conditional every time (in C you could define a macro)

def doStuff(reporter=None):
    if reporter is not None:
        reporter.log("starting doing stuff")
        # etc...

Edit: Another option is to work Qt-like, and have an emit() signal strategy. As your code executes, it emits information with proper status codes, and anyone interested can subscribe to the signals and provide info. Nice and clean, very decoupled, but requires a little of coding, as I don't think this can quickly be done with the python battery included.

Finally, you can raise exceptions with a meaningful error message, but this of course can be used only if you are exiting from an error condition. it does not work for occasional reporting.

Edit: I'd like to clarify the fact that the situation is more general, and not limited just to a sequence of invoked steps. it could also involve control structures:

 if disconnected:
     print "Trying to connect"
     connect()
 else:
     print "obtaining list of files from remote host"
     getRemoteList()

The report could also be into the actual routines, so you would have a "print" in the connect() and getRemoteList() routines as a first statement.

The question therefore are:

• What do you think is the best design for some code (notably in the case of a library) to be at the same time silent when noise could be disruptive for the client, but verbose when useful?
• How to handle a balanced intermix between logic code and reporting code ?
• Intermixing between code and error checking has been solved with exceptions. What could be done to partition the "noise" of reporting from the code logic ?

---

Edit: more thoughts for the mind

I think it's not only a matter of decoupling the Logging code from the logic code. I think it's also a matter of decoupling the information production from the information consumption. Similar techniques already exist, in particular to handle UI events, but I don't really see the same patterns applied to the logging problem.

---

Edit: I accepted the answer from Marcelo because he points out at the factual evidence that a compromise is the best solution in this case, and there's no silver bullet. However, all the others were interesting answers as well, and I was really pleased to upvote all of them. Thanks for the help!

Answer 1

I think the best solution for a library is one along the lines of adding e.g.

Log.Write(...)

where the behavior of Log is picked up from the ambient environment (e.g. app.config or an environment variable).

(I also think this is a problem that's been approached and solved many times, and while there are a few 'sweet spots' in the design space, the answer above is best IMO for the situation you describe.)

I don't see any good way to 'decouple' the 'normal' part of your code from the 'logging' part. Logging tends to be relatively non-intrusive; I do not find the occasional Log.Write(...) to be a distraction to real-world code.

Answer 2

Another option would be to write the code without logging and then apply some transform to insert the appropriate logging statements before executing the code. The actual techniques to do this would be highly dependant on the language, but would be pretty similar to the process of writing a debugger.

It probably isn't worth the added complexity though...

Answer 3

There should be tooling to allow boilerplate log messages a la "entering method A with parameters (1,2,3)", "returning from method B with value X, took 10 ms" to be automatically (and selectively) generated (controlled at run or deploy time). Writing that stuff by hand is just too boring/repetitive/error-prone.

Not sure if there is, though.

If you are going to write manual log messages, be sure to include some useful contextual information (user id, URL that is being looked at, search query, or such), so that if something does go wrong you get more information than just the method name.

Answer 4

I found this while searching for Aspect Oriented Programming for python. I agree with other posters that such concerns shouldn't be mixed with core logic.

In essence,points where you want to put logging might not always be arbitary, may be concepts like "all the points before error" could be identified by a pointcut. Other totally arbitary points can be captured using simple logging techniques.

Answer 5

I would use the standard logging module that's been part of the standard library since Python 2.3.

That way, there is a good chance that people looking at your code will already know how the logging module works. And if they have to learn then at least it's well-documented, and their knowledge is transferable to other libraries that also use logging.

Is there any feature that you want but can't find in the standard logging module?

Answer 6

I think the simplest solution is the best here. This depends on language, but just use a very short, globally accessible identifier - in PHP I use a custom function trace($msg) - and then just implement and re-implement that code as you see fit for the particular project or phase.

The automatic, in-compiler version of this is the standard debugger. If you want to see meaningful labels, you need to write those labels yourself, unfortunately :)

Or you could try temporarily transforming inline comments into function calls, but I'm not sure that would work.

Answer 7

In response to your edit about information production/consumption: That's a valid concern for the general case, but logging is not the general case. In particular, you should not be relying on logging output from one part of your program to affect the execution of another part. That would indeed tightly couple the consumer to the implementation of the producer.

Logging should be considered incidental to your main execution. Your systems should not know or care about the presence or contents of such log files (with the exception possibly of monitoring tools). That being the case, the notion of decoupling "consumption" of the logs from their production is inconsequential. Since you aren't using the logs to do anything meaningful, coupling is not an issue.

Answer 8

I often use DTrace for this. On OS X, python and ruby are both already set up with DTrace hooks. On other platforms, you'd probably have to do this yourself. But being able to attach debug traces to a running process is, well, awesome.

However, for library code (let's say you're writing an http client library), the best option is to pass in an optional logger as a parameter, as you mentioned. DTrace is good for adding logging to something that's gone wrong in production (and sometimes elsewhere), but if other people might conceivably need access to logs to debug their code that subsequently calls into yours, then an optional logger as a parameter is absolutely the way to go.

Answer 9

I think there is a point where you must draw a line and make a compromise. I see no way to completely decouple logging from the system because you have to send those messages somewhere and in a way that someone understands.

I would go with the default logging module, because... it's the default module. It's well documented and comes with the default library, so no dependency issues here. Also, you save yourself from reinventing the wheel.

That said, if you are really into doing something new, you could make a global reporter object. You can instantiate and configure it at the beginning of your process (logging, no logging, redirecting streams, etc. Even in a per process/function/step basis) and call it from everywhere, no need to pass it around (maybe in a multi threaded environment, but that would be minimal).

You can also put it inside another thread and catch log events a la Qt.