This is the fourth entry in my Learning Caliburn.Micro series. Since I do build on content from earlier posts, here are the links in case you need to catch up.
- Introducing Caliburn.Micro – Lightweight MVVM & WPF
- Caliburn.Micro – Hello World
- Caliburn.Micro the MEFtacluar
Caliburn.Micro Logging Abstraction
This post covers logging. Caliburn.Micro has a simple logging abstraction that consists of an ILog interface, and a LogManager class (see below).
1 /// <summary> 2 /// A logger. 3 /// </summary> 4 public interface ILog 5 { 6 /// <summary> 7 /// Logs the message as info. 8 /// </summary> 9 /// <param name="format">A formatted message.</param> 10 /// <param name="args">Parameters to be injected into the formatted message.</param> 11 void Info(string format, params object[] args); 12 13 /// <summary> 14 /// Logs the message as a warning. 15 /// </summary> 16 /// <param name="format">A formatted message.</param> 17 /// <param name="args">Parameters to be injected into the formatted message.</param> 18 void Warn(string format, params object[] args); 19 20 /// <summary> 21 /// Logs the exception. 22 /// </summary> 23 /// <param name="exception">The exception.</param> 24 void Error(Exception exception); 25 }
1 /// <summary> 2 /// Used to manage logging. 3 /// </summary> 4 public static class LogManager 5 { 6 static readonly ILog NullLogInstance = new NullLog(); 7 8 /// <summary> 9 /// Creates an <see cref="ILog"/> for the provided type. 10 /// </summary> 11 public static Func<Type, ILog> GetLog = type => NullLogInstance; 12 13 private class NullLog : ILog 14 { 15 public void Info(string format, params object[] args) { } 16 public void Warn(string format, params object[] args) { } 17 public void Error(Exception exception) { } 18 } 19 }
To add logging to any Caliburn.Micro project, you need to implement a class that extends the ILog interface, and you need to replace the delegate for GetLog. In this post, I will show you how to hook up a debug logger that logs to the Output window in Visual Studio, a log4net logger, and an NLog logger. For other loggers, it would be a simple matter to modify these examples to support them.
As always, all of the source code for this project is located in my Github Learning Caliburn.Micro repository.
So lets get started. As with any Caliburn.Micro project, you need a new WPF project with some directories named according to the 
convention (Views and ViewModels). See my post Caliburn.Micro – Hello World for the basics of creating a project. Now, lets switch the Target Framework from the Client Profile to just .NET Framework. This is on the Application tab for the project settings. We need to do this because the logging frameworks do not work with the Client Profile at this time.
Debug Logger
The first logger we will implement is the debug logger. The goal of this logger is output its messages to System.Diagnostics.Debug which will show up in the Visual Studio Output window. I chose to place my loggers in a ‘Utils’ directory off the main project, and creatively called it the DebugLogger. Here it is.
1 class DebugLogger : ILog 2 { 3 #region Fields 4 private readonly Type _type; 5 #endregion 6 7 #region Constructors 8 public DebugLogger(Type type) 9 { 10 _type = type; 11 } 12 #endregion 13 14 #region Helper Methods 15 private string CreateLogMessage(string format, params object[] args) 16 { 17 return string.Format("[{0}] {1}", 18 DateTime.Now.ToString("o"), 19 string.Format(format, args)); 20 } 21 #endregion 22 23 #region ILog Members 24 public void Error(Exception exception) 25 { 26 Debug.WriteLine(CreateLogMessage(exception.ToString()), "ERROR"); 27 } 28 public void Info(string format, params object[] args) 29 { 30 Debug.WriteLine(CreateLogMessage(format, args), "INFO"); 31 } 32 public void Warn(string format, params object[] args) 33 { 34 Debug.WriteLine(CreateLogMessage(format, args), "WARN"); 35 } 36 #endregion 37 }
I also chose to ignore the Type parameter being passed in, other than to store it. Usually when I am using the debug logger, I find that the type is overkill in the message flow.
The next thing you need to do is set the delegate. I do this in a static constructor for the bootstrapper since this is called before any of the Caliburn.Micro code, or my own code is called. Here is the bootstrapper, also with a highly creative name.
1 public class MyBootStrapper : Bootstrapper<ShellViewModel> 2 { 3 static MyBootStrapper() 4 { 5 LogManager.GetLog = type => new DebugLogger(type); 6 } 7 }
Believe it or not, that’s it. Logging is now hooked up, and here is what a default run will look like.
1 INFO: [2010-08-08T15:28:18.8063954-04:00] Binding System.Windows.Window+LogJam.ViewModels.ShellViewModel. 2 INFO: [2010-08-08T15:28:18.8263965-04:00] Setting DC of System.Windows.Window to LogJam.ViewModels.ShellViewModel. 3 INFO: [2010-08-08T15:28:18.8283966-04:00] Attaching message handler LogJam.ViewModels.ShellViewModel to System.Windows.Window. 4 INFO: [2010-08-08T15:28:18.8343970-04:00] No bindable control for action CanGenerateLogMessage. 5 INFO: [2010-08-08T15:28:18.8353970-04:00] Added convention action for GenerateLogMessage as GenerateLogMessage(logTypes,logMessage). 6 INFO: [2010-08-08T15:28:18.8843999-04:00] No bindable control for action add_PropertyChanged. 7 INFO: [2010-08-08T15:28:18.8853999-04:00] No bindable control for action remove_PropertyChanged. 8 INFO: [2010-08-08T15:28:18.8864000-04:00] No bindable control for action NotifyOfPropertyChange. 9 INFO: [2010-08-08T15:28:18.8874000-04:00] No bindable control for action NotifyOfPropertyChange. 10 INFO: [2010-08-08T15:28:18.8884001-04:00] No bindable control for action RaisePropertyChangedEventImmediately. 11 INFO: [2010-08-08T15:28:18.8884001-04:00] No bindable control for action ToString. 12 INFO: [2010-08-08T15:28:18.8894001-04:00] No bindable control for action Equals. 13 INFO: [2010-08-08T15:28:18.8904002-04:00] No bindable control for action GetHashCode. 14 INFO: [2010-08-08T15:28:18.8904002-04:00] No bindable control for action GetType. 15 INFO: [2010-08-08T15:28:18.9314025-04:00] Action: GenerateLogMessage availability update.
The Caliburn.Micro framework starts using our new logging right away, and with some very useful information. Once thing to notice is that it always starts with the binding of the root view-model. You can see logging is done for some initialization tasks, binding, and of course – actions.
One last thing before moving on to the other loggers, and that is how to use the logger for your own code. Happily, just like you would any of the major logging frameworks. Just call LogManager.GetLog, and you get back a logger. Then just call Info, Warn, or Error.
1 private readonly ILog _log = LogManager.GetLog(typeof(ShellViewModel));
For those used to log4net and nlog, you will notice that the Caliburn.Micro ILog interface does not offer as many logging modes. If you find yourself needing those, then derive from ILog a new interface that adds those extra methods back in, and have your GetLog delegate return a class that implements it. Caliburn.Micro will still use the three methods it knows about, but you are free to use your extra methods.
Log4net Logger
Log4net is the old guard of logging in the .NET community. It has probably been used in more projects than any others, and is always the first one I hear about from people when the topic of logging comes up. So, I decided that this would be the first I would implement. Log4net has a few things needed to make it work, but first the logger class in which you use it.
1 class Log4netLogger : ILog 2 { 3 #region Fields 4 private readonly log4net.ILog _innerLogger; 5 #endregion 6 7 #region Constructors 8 public Log4netLogger(Type type) 9 { 10 _innerLogger = log4net.LogManager.GetLogger(type); 11 } 12 #endregion 13 14 #region ILog Members 15 public void Error(Exception exception) 16 { 17 _innerLogger.Error(exception.Message, exception); 18 } 19 public void Info(string format, params object[] args) 20 { 21 _innerLogger.InfoFormat(format, args); 22 } 23 public void Warn(string format, params object[] args) 24 { 25 _innerLogger.WarnFormat(format, args); 26 } 27 #endregion 28 }
Two more things are needed to support log4net. You need to tell it how to configure itself. I usually use the app.config model for log4net, and I place the following attribute into the AssemblyInfo.cs file.
1 // Configure log4net using the app.config file 2 [assembly: log4net.Config.XmlConfigurator(Watch = true)]
Then I add the following to app.config inside the configuration tag.
1 <configSections> 2 <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" /> 3 </configSections> 4 5 <log4net> 6 <appender name="TraceAppender" type="log4net.Appender.TraceAppender"> 7 <layout type="log4net.Layout.PatternLayout"> 8 <conversionPattern value="%date [%thread] %-5level - %message%newline" /> 9 </layout> 10 </appender> 11 <appender name="OutputDebugStringAppender" type="log4net.Appender.OutputDebugStringAppender" > 12 <layout type="log4net.Layout.PatternLayout"> 13 <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" /> 14 </layout> 15 </appender> 16 <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender" > 17 <layout type="log4net.Layout.PatternLayout"> 18 <conversionPattern value="%date [%thread] %-5level %logger [%ndc] - %message%newline" /> 19 </layout> 20 </appender> 21 <root> 22 <level value="DEBUG" /> 23 <appender-ref ref="TraceAppender" /> 24 </root> 25 </log4net>
One last change, you need to tell Caliburn.Micro to use the log4net logger by modifying the line in the static constructor for bootstrapper.
1 LogManager.GetLog = type => new Log4netLogger(type);
At this point, log4net is hooked up and you can use it throughout your code.
NLog Logger
At this point you should have a good idea of the changes needed to implement NLog support. Here is the code.
1 class NLogLogger : ILog 2 { 3 #region Fields 4 private readonly NLog.Logger _innerLogger; 5 #endregion 6 7 #region Constructors 8 public NLogLogger(Type type) 9 { 10 _innerLogger = NLog.LogManager.GetLogger(type.Name); 11 } 12 #endregion 13 14 #region ILog Members 15 public void Error(Exception exception) 16 { 17 _innerLogger.ErrorException(exception.Message, exception); 18 } 19 public void Info(string format, params object[] args) 20 { 21 _innerLogger.Info(format, args); 22 } 23 public void Warn(string format, params object[] args) 24 { 25 _innerLogger.Warn(format, args); 26 } 27 #endregion 28 }
As you can tell, almost no change from the log4net version. NLog does not need the attribute telling it where the configuration file is, since it follows a conventions based approach to finding it. In this case, I chose to configure it in app.config as well.
1 <configSections> 2 <section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog"/> 3 </configSections> 4 5 <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"> 6 <targets> 7 <target name="tr" xsi:type="Trace"/> 8 </targets> 9 <rules> 10 <logger name="*" writeTo="tr" /> 11 </rules> 12 </nlog>
Last, we need to modify the bootstrapper.
1 LogManager.GetLog = type => new NLogLogger(type);
So that’s it for NLog. It is now ready to be used.
Caveats
I have run into two caveats while working with Caliburn.Micro’s logging infrastructure that I want to share.
The first is kind of obvious, but I just want to make sure your aware, the logging is not available until after you set the LogManager.GetLog delegate to create your logger. Prior to that everything goes to the NullLogger. In my case, I create it in the bootstrapper static constructor, but this may not be early enough if you do anything in the App class before your bootstrapper is referenced. You may need to move the assignment of the delegate into the App static constructor.
The second issue I ran into is not specific to Caliburn.Micro, but to NLog. If I pass the type into NLog’s LogManager.GetLogger() along with the type.Name, I end up in an infinite loop and blow up my stack frame. I am not exactly sure why this happened as I opted not to spend the time to solve it. So I am providing this caveat as a warning against doing it yourself.
Conclusion
Caliburn.Micro makes it very easy to wire up any number of logging infrastructures. I detailed three different ones here, but can be expanded to support the Microsoft Enterprise Library Logging Application Block, or some proprietary logging framework.
I will be leveraging the loggers heavily as we move forward into hooking up Autofac as IoC, adding support for custom third-party controls, and even dealing with custom chrome windows.
As a reminder, all of the source code for this project is located in my Github Learning Caliburn.Micro repository.
[...] This post was mentioned on Twitter by Rob Eisenberg and John Mandia, _neurson. _neurson said: RT @dbuksbaum Blogged: How To Do Logging with Caliburn.Micro (http://bit.ly/dh0dN0) #Caliburn.Micro #log4net #MVVM #NLog #WPF [...]
Thanks for this series on Caliburn.Micro. In addition to Rob’s site, this has been very helpful.
Greg
I also wanted to say thanks – you’ve done a great job explaining Caliburn step by step. I’m looking forward to the rest of the series!
[...] did not want to include it twice. This led me to do a quick refactoring of the logging code from How to do Logging with Caliburn.Micro to create a new assembly Caliburn.Micro.Logging which would include the common code between the [...]
[...] Hi i try use Nlog in with caliburn micro, I have use this tutorial http://buksbaum.us/2010/08/08/how-to-do-logging-with-caliburn-micro/. [...]
I am trying to log unhandled exceptions in my bootstrapper…and I use this code to get Logger…
ILog _log=LogManager.GetLog(typeof(StructureMapBootStrapper));
But I always get nulllogger back and so I cant log any unhandled exceptions. Any help is highly appreciated!!!
Thanks