How should I architect logging within my application?

Question

So I've done a lot of research on this and haven't found any answers where I said, "yes, THAT". I'm hoping the ever-erudite StackOverflow crowd can help me out.

I've run into this issue in a couple of different scenarios. Say I have a C# app, and there are important things that I want to log.

public class MyClass
{
    ... 

    public void ImportantMethod()
    {
        DoInterestingThing();

        var result = SomethingElseImportant();
        if (result == null)
        {
            logger.Log("I wasn't expecting that. No biggie.");
            return;
        }

        MoreInterestingStuff(); 
}

The thing I'm interested in is where do I get logger from.

As I see it I have a few options.

1. Have it injected into MyClass in the constructor.
2. Retrieve it using a globally available service locator.
3. Use method decorators and AOP to have my logging done for me.

None of these seem like great options. #3 looks to be impossible since I'm logging right in the middle of my business logic and not just doing a simple trace of my method calls, input parameters and/or exceptions thrown. #2, though simple seems like it would be really difficult to unit test. Of course, I would want to unit test everything. #1, though it would work fine, clutters up all my business logic with logging objects that have nothing to do with the business objects themselves.

Any alternative ideas, or thoughts on one of the options above? Much thanks!

EDIT: just to be clear, I already know how to do DI (I use Unity), and I already know a good logging framework (I use log4net). Just wondering a how to use logging in an architecture sense across an application in the smartest way.

---

* EDIT *

I marked Mark Seeman's answer as the solution. I went through my application and found that most of my logging calls were doing the same thing a decorator could do. Namely, log the entry to the method, any exceptions thrown, and exit return values.

Some cases I still needed to log directly inside a method. An example would be where I want to fail fast in a method which doesn't return anything but not throw an Exception. In those cases I have a singleton which holds a reference a LogProvider which will in turn retrieve a named log instance. The code looks similar to this:

private ILog logger = LogProviderFactory.Instance.GetLogger(typeof(Foo));

LogProviderFactory has a method SetProvider which allows you to swap out the singleton. So in unit testing I can do:

// LogProviderFactory.Instance now is our mock
LogProviderFactory.SetProvider(MockLogProvider);

The logging decorator uses the same LogProvider as the singleton (which it obtains through injection), so logging is unified throughout the system.

So really the end solution was mostly option #3, and a hybrid #2 (where it's the service locator pattern but the service is 'injected' into the locator).

AOP

As far as "aspect oriented programming" goes, I was a bit disappointed in the limitations of the language. Hoping AOP will be treated as a first-class citizen in future releases.

• I tried PostSharp but couldn't get it running on my machine correctly. Additionally it was a big restriction that you had to have PostSharp installed on your system to use it (as opposed to just calling a dll which comes with the solution or something similar).
• I used LinFu and was able to get it partially working. It blew up in a few instances however. The new 2.0 release is barely documented, so that was a hurdle.
• Interface interception with Unity however seems to work well out of the box. I got lucky that most things I wanted to log were in classes implementing interfaces.

Upper

Always look closely whether you need to log something, or just fail fast by throwing an exception. Bailing out quickly is more often the way to go than you would expect it to be. – Cypher

Good point Steven! In my most recent app, I needed to put in some logging that was not necessarily exception/error related. Things like "received a new message" or "added user". Not debug statements per se, but informational stuff about the execution of the app for record keeping. – Upper

Answer 1

Use a logging Decorator.

Ignominious

In principle, that seems like a good idea. However in practice I could have 20 different objects or services that need logging. In that case I would effectively double that number. A LoggingArticleManager, a LoggingOrderService? Doesn't seem very efficient. – Upper

@Onisemus: That's where interception comes in. – Cypher

+1 @Onisemus: I don't believe you've read the linked articles properly and suggest re-reading to get the interception point – Contactor

Ahh ok, sorry I didn't see that there were two different links there! After reading that it does make sense. It appears that interception = AOP (for our intentions anyway). AOP does a great job of letting me do logging before the method call, and after the method call. But what about the middle like my example shows? Wouldn't that be impossible with a logging decorator? – Upper

If you need to log in the middle of a method, the method does too much :) – Ignominious

@MarSeemann, good point :). In general, I totally agree with you. Are there really not any reasonable situations in which we'd want to log in the middle of a method though? If there are...what's the best way to do it? – Upper

If there are, an injected logging dependency is the only way to do it, but I don't think there are too many cases where you should log from the inside of a method. Never say never, though :) – Ignominious

Logging inside a method is perfectly reasonable, it just depends what then scenario and rationale is. – Applaud

Answer 2

Two bits:

(1) - A pre-built logging framework.

Some people like Log4Net but I'm a EntLibs fan. This does the heavy lifting in terms of actual logging. Tools like EntLibs will let you log to different types of logging repositories (database, message queue, rolling text file, etc). They'll also let you log to different instances based on categories and so forth. They are usually highly configurable.

(2) - Custom class(es) that wrap the logging framework.

So "logger" is something you write, and it calls the logging framework to do the actual logging.

I like this approach for several reasons:

• You decouple the logging framework (#1) from the rest of your application as the custom wrappers go into a separate assembly.
• By writing your own Logging API you can define method signatures that suit your needs, and you can expand on them.
• If your working on a team, you can make the method signatures very easy to use so that no-one has grounds to say that using the logging was too hard.
• It keeps the logging consistent. It also makes it easy to do code searches for "illegal" code that writes to files, console or event log easy as there won't be any as part of your logging (it's all in the framework).
• By writing specific custom classes for each tier you can pre-populate a lot data behind the scenes making life easier for whoever's writing the actual application code. You can set severity, priority, default event Ids, categories and more.
• It scales well in terms of application complexity and growth; it might seem heavy handed for smaller apps but you'd have plenty of head-room if it starts to grow on you over time.

Here's an example of a Informational logging class in a project I've worked on. It has a bunch of easy to call public methods, and one private method that calls the framework (ConcreteLogInformation).

public static void LogInformation(string title, string message)

public static void LogInformation(string title, Dictionary<string, object> extendedProperties)

public static void LogInformation(string title, int eventId, Dictionary<string, object> extendedProperties)

public static void LogInformation(string title, string message, Dictionary<string, object> extendedProperties)

public static void LogInformation(string title, string message, int eventId)

public static void LogInformation(string title, string message, int eventId, Dictionary<string, object> extendedProperties)

public static void LogInformation(string title, string message, int eventId, string category)

public static void LogInformation(string title, string message, int eventId, Dictionary<string, object> extendedProperties, string category)

private static void ConcreteLogInformation(string title, string message, int eventId, Dictionary<string, object> extendedProperties, string category)

Applaud

I agree with all you say, except the last part where you use static methods. Using static methods makes testing much harder. It is better to inject an ILogger interface in the constructor of types that need a logger. An approach that has worked well for me is to have a single Log(LogEntry) method on that interface and have a bunch of extension methods (such as Log(string) and Log(Exception)) that call into the Log(LogEntry) interface method. (still +1 for your answer). – Cypher

@Cypher - yeah that sounds cool. I must admit I've never got motivated enough to use DI for logging (if your DI fails - how do you log?) but ti's still a good idea to consider. – Applaud

What do you exactly mean by "if your DI fails"? – Cypher

Using a DI - Dependency Inversion (framework / sub-system). Lets say you do a new deployment, it's based on config, the config is wrong - your logging wouldn't work and might make it harder to diagnose the issue. The other thing is that you could view using DI as making the overal logging system more complex - as far as logging sub-systems go I think the KISS (Keep It Simple, Stupid) principle is good - assuming that keeping things simple = robustness. – Applaud

It should not be possible to have such a miss-configuration in your DI container. Unit tests should ensure that the configuration is correct (these tests are normally very straightforward). A miss-configured logging system is of course still possible, but this is not DI specific. Using DI is of course an extra layer of abstraction, but my experience is that it makes development much simpler. In fact, letting your application depend on an ILogger interface instead of a concrete logging subsystem, can hardly be considered over engineered and I would certainly consider this KISS. – Cypher

Thanks for the reply. If I get the gist of what you're saying, you recommend using static methods in a static class somewhere to log to from across the application? That seems the same as option #2 really. Both ways we're accessing logging functionality statically which makes it very difficult (or impossible depending on how you have it set up) to unit test. You could use regular DI but I've explained my hesitation to doing that in description. – Upper

Not sure I see the distinction that makes static calls to logging classes so bad. You can test the logger independently of your other logic. If its still an issue for you you can augment with DI in some fashion, there'd be several ways of doing it. – Applaud

Answer 3

In the Using the request context in a Factory or Factory Method to do contextual binding section of the Ninject Contetual Binding docs I have an example of leveraging your container to inject an appropriate logger for your class by doing (in Ninjectese):

Bind<ILog>().ToMethod( context => LogFactory.CreateLog( context.Request.Target.Type ) );

For tracing type stuff, Mark's interception article describes the best approach.

And can I ask again that you read @Mark Seemann's cited articles in depth before just discarding them without an upvote.

Contactor

Sorry, didn't see the first link for @Mark Seemann's article. It doesn't look like it addresses my example though. AOP/Interception works great for tracing, but the example method is doing more than that. I'm calling logging functions in the middle of my business logic - I'm interested in more than just what happens before and after the method call. The Ninject article mirrors how log4net does it and is the same as option #2. I like it...but it's hard to unit test. With the service locator implementation how do I specify a mock logger in my unit tests? – Upper

@Onisemus: No idea what SL you're on about. If you actually read it, you'll see there's Constructor Injection of an ILogger interface which is testable/mockable. The point is that your DI tool can take care of loose coupling and you only need one Binding for 20 classes with logging. – Contactor

Oh I read it. There were two examples, one being constructor injection and the other being the factory method. I was referring to the factory method. The constructor injection makes a lot of sense, and I see why it's popular. It's just that cross cutting concerns like logging clutter up the domain. I'm hesitant to use it - it's possible I could have ILog injected into half the classes in the domain. – Upper

@Onisemus: Property injection allied to a single Bind as in my answer here could resolve that. But the main point that's being made is that if you have your stuff split up properly, your code doesn't need to do as much logging - you can inject tracing of what's calling what outside of your domain classes via AOP and/or mini-AOP Facilities of your DI Container. Then for the remaining stuff, which should be quite rare, let CR/R# generate the ctors which surface the fact that this domain class really reckons it has important stuff to log (as opposed to the stuff that you'd litter in everywhere) – Contactor

That's a good point - letting AOP facilities handle the tracing and then inject the logging where absolutely necessary. Like you say, if it's important to log outside of tracing, seems reasonable to inject the logging dependency at that point. How do you feel about injecting the logger versus obtaining it via some sort of static method (service location, some hybrid of that) for those rare instances? Static methods may help clean up the domain...but then again perhaps you could consider logging a specific enough dependency to warrant injection. (and makes that dependency obvious). – Upper

@Onisemus: I'd put the hierarchy as ctor injection, prop inj, service locator, Singletons, other static methods / global variables in a dress, global variables. But ctor injection is head and shoulders better. Once you're using a DI container properly (not SL!), the percieved benefits of Singletons/statics quickly fade. But having said all that, save yourself all this typing and default to ctor injection and look for groups of dependencies travelling in flocks that represent missing abstractions. – Contactor