At what stage do you add logging & tracing in OO?

Question

I'm interested at what stage in your development do add logging and/or tracing to your applications?

I'm working with a .Net stack and log4net (via commons.logging). Generally taking a TDD approach to development although admittedly not 100%, sometimes Im know to spike out without test coverage. My application all sit server-side, e.g. web services, windows service that consume messages off a bus, asp.net mvc business admin apps. etc..

I found myself decorating methods in my applicatiosn services with descriptive logger.INFO "Getting cakes from repository" . some work .. "Got 5 cakes from repository. ", and then an unhandled expcetion handler for the app doamin to logger.FATAL for unexpected excpetions that bubble up.

However I usually end up going back and applying these near the end of development rather than at the start of development and I might have a dozen or two only. I find I rarely decorate any lower level classes such as implementation of ICakeRepository with logger stuff as it seems pointless.

For tracing, which switched on via config, I'm thinking of intercepting method calls and instance creation using the IOC framework, and this should take care of on-site troublehsooting rather than heavy trace population.

Answer 1

I wouldn't say that "Getting cakes from repository" best fits INFO. It's more suitable for DEBUG or even TRACE. Usually you'd want to use INFO for logging functional stuff, e.g. "There are no cakes left for user A". Non-functional stuff and technical flow should be with lower severity IMHO. I wouldn't use FATAL for logging exceptions, unless you get to the point when application is dead completely.. it would be quite confusing to see FATAL and then system is still alive and kicking. ERROR is a better choice, sometime even WARNING, depends how bad is the exception. As to AOP interceptors, last time I checked - these stuff greatly affects performance. It's cool and sexy concept, but wasn't practical in my case, not sure it gets any further than demos and trivial examples from books and articles explaining benefits of AOP. So, I'd double check before relying on it completely.

Answer 2

We're TDD so we basically don't do much logging any more. Maybe just in the top-level exception handlers and a few strategic places.

Answer 3

Logging and tracing ought to be cross-cutting concerns. You can add/remove them at any time in a declarative way if you're using aspect-oriented programming.

Answer 4

My software is in layers, with a well-defined API between each layer. I tend to implement logging for those APIs from the begining, so that for any given transaction I can see how that results in an API call at each of the underlying layers: if there's a mistake, that will help to narrow it down to a specific layer. The logging will also help to reproduce a problem by showing a log of all the previous, normal activity which led up to the problem.

I also add assertions within each layer where I can, and log assertion failures.

A log file therefore often shows of a sequence of calls to the public APIs, with an error message generated from inside: that's often enough to diagnose the problem.

Beyond that, I add debug-level logging on an as-needed basis: to debug specific problems during development and/or after release.

My reasoning for caring about logging is partly explained in the following:

• Separate ‘debug’ and ‘release’ builds?
• Should one test internal implementation, or only test public behaviour?

To fix any bug in released software, I depend on the log file; and the same is also often true of software as it's being developed.

---

You said,

I find I rarely decorate any lower level classes such as implementation of ICakeRepository with logger stuff as it seems pointless.

I said,

My software is in layers, with a well-defined API between each layer. I tend to implement logging for those APIs from the begining ...

I think I'd better explain what I mean by "layers", which may or may not be the same as your "lower level" classes.

For example, my system might have the following layers:

• UI
• Business layer (rules for manipulating data)
• Data access layer (for database I/O)
• Database

In that case I would have the following interfaces or APIs, which might deserve logging:

• Between the user and the UI (i.e. the UI events, mouse and keyboard)
• Between the UI and the business layer (see "Humble dialog box")
• Between the business layer and the DAL
• Between the DAL and the database

Alternatively the system might be a chain of components connecting two peer end-points (less obviously with "top" and "bottom" layers).

In any case, what I'm logging is the API that's each component's public facade, which is good for logging for several reasons:

• Not too complicated (the facade tends to be simpler than the underlying/internal implementation)
• Good coverage (if I log the whole facade, and if the only way into the component is via its facade, then I know I've logged everything that goes into the component)
• Works well with Conway's Law: when debugging a system with multiple components, each developed by a different team, one of the recurrent questions is, "Which component is at fault, and therefore which team needs to debug it?"