Episerver logging tutorial with log4net

Logging might not be sexy. Logging might not always be fun. But sure is important. In a big project with multiple integrations, this is an essential tool that saves 100s of hours and quite a lot of frustration and blame games. Episerver has great support for adding logging out-of-the-box with log4net. Let's check out how to turn it on and some tips and tricks to get the saweet logging experience. It's really easy actually. 

Basic concepts

• Logger - To write to log4net log you need a logger. Think of this as a category for the log. The logger is normally the full name of the class that logs. So if you have a namespace FU and a class BAR in it, normally use the "FU.BAR" logger. This is used later so you can restrict your logs to only log a certain namespace etc. Root is a special logger that basically means everything. I'll show below how to log a message in your solution with a specific logger. So the logger is really nothing more than a string that describes the category of the log message.
• Appender - You could think of this like an output channel or similar. In what form do you want your logs? File with certain formatting, on mail, in event log or in database? Use a different appender. I usually only use file logging. There are quite a few appenders already made and you can of course make your own if you have nothing to do this weekend.
• Level - This is how important the log message is. INFO, DEBUG, WARN, ERROR, FATAL. I normally use INFO, WARN and ERROR. That's usually enough.  

1. Turn it on!

You are looking for a file called EpiserverLog.config in your web root. Open it with VS or notepad. Let's start by turning on full logging on the entire solution and go from there. Locate the root element and change the level of logging to ALL.

<root>
        <level value="ALL" />
        <appender-ref ref="errorFileLogAppender" />
</root>

This basically tells log4net that all logmessages (root logger means every namespace remember?) in the entire solution should be passed on to the errorFileLogAppender which is responsible for doing something with them, like writing them to disc in our case. Let's check that appender out.

<appender name="errorFileLogAppender" type="log4net.Appender.RollingFileAppender" >
        <!-- Consider moving the log files to a location outside the web application -->
        <file value="..\..\logs\EPiServerErrors.log" />
        <encoding value="utf-8" />
        <staticLogFileName value="true"/>
        <datePattern value=".yyyyMMdd.'log'" />
        <rollingStyle value="Date" />
        <threshold value="Warn" />
        <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
        <appendToFile value="true" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%date [%thread] %level %logger: %message%n" />
        </layout>
</appender>

So that's basically how log4net works. Use the configuration to connect a logger (basically a namespace in your solution that is reflected in the name attribute) to an appender (file/database/email) and set the level of message you are interested in. 

Notice that the threshold is set to Warn? That will filter all messages that isn't Warn or higher (like Error or Fatal). So this is something to beware of. You first have a level setting on the root element for what should be sent to the appender and then you might have a level setting in the appender configuration as well that kills your precious log messages. Otherwise there isn't much interesting things to see in the appender except the filepath where the actual log file will be. Check that the IIS_IUSRS have write access there. This should of course be stored outside of www root for security reasons. Avoid the system partition of server as well since it happens that servers crash because a log was left on for too long. What will the actual logs look like?

2016-06-03 17:03:14,722 [7] ERROR EPiServer.Global: 1.2.5 Unhandled exception in ASP.NET
System.IO.DirectoryNotFoundException: Could not find a part of the path 'C:\Projects\CLIENT\www\project\appdata\blobs\81945ecb3baa49e7be5e6c68c0230b73\8b8bc9928d2b49c9ad495ec51c5aa0e6.jpg'.
   at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)

Alright, I'm getting some good info now on missing blobs etc. Easy peazy!

2. Logging what is really interesting

Unfortunately, turning log on ALL will give you 1000s of logmessages per minute and slow down site a lot as well. So let's say I'm interested in getting all logmessages for a specific part of the solution, like a complex integration, but only everything from WARN and up in the rest of the solution? Not a problem. That's where loggers come in. 

<appender name="errorFileLogAppender" type="log4net.Appender.RollingFileAppender" >
        <!-- Consider moving the log files to a location outside the web application -->
        <file value="..\..\logs\EPiServerErrors.log" />
        <encoding value="utf-8" />
        <staticLogFileName value="true"/>
        <datePattern value=".yyyyMMdd.'log'" />
        <rollingStyle value="Date" />
        <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
        <appendToFile value="true" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%date [%thread] %level %logger: %message%n" />
        </layout>
</appender>
<logger name="Really.Complex.Integration" additivity="false">
        <level value="All" />
        <appender-ref ref="errorFileLogAppender" />
</logger>
<root>
        <level value="Warn" />
        <appender-ref ref="errorFileLogAppender" />
</root>

So what did we just do. I used the same appender for simplicity but removed the threshold altogether. This will make sure that the appender will write everything it gets to disk and filter nothing. The new logger element will capture everything from the namespace "Really.Complex.Integration" and below. The root element will take care of the rest on warn level.

This way you can specify exactly what you want logs on and reduce a lot of noice in your logs.

3. Adding custom logging to your solution

Episerver has a wrapper for this that makes it really easy. Let's add some much needed logging to the ErrorHandlingContentRenderer in the Alloy solution. I'll use the LogManager class that is present in Episerver.Logging namespace. This handler has a nasty tendency to swallow errors on your production site without leaving any trace to what is going on...
If you want to use depencency injection for the ILogger interface or not is a matter of taste. I usually don't use dependecy injection for logging but always for repositories etc. If you don't really think you need it, skip it for logging is my suggestion. It saves you some headache for getting the correct logger per type.

 public class ErrorHandlingContentRenderer : IContentRenderer
    {
        private readonly MvcContentRenderer _mvcRenderer;
        private readonly ILogger _log = LogManager.GetLogger(typeof (ErrorHandlingContentRenderer));

See that we send in the type when getting the logger. This combined with configuring the logger in EpiserverLog.config like above will make it possible to get logs from one class only / only everything below a certain namespace. 

private void HandlerError(HtmlHelper helper, IContentData contentData, Exception renderingException)
{
      _log.Error("Exception while rendering view", renderingException);
     if (PrincipalInfo.HasEditAccess)
     {
          var errorModel = new ContentRenderingErrorModel(contentData, renderingException);
          helper.RenderPartial("TemplateError", errorModel);
     }
}

There we go. Now we will get a clue on production as well when the shit hits the fan. No more guessing. 

4. Measuring performance on a single method

This kind of logging usually belongs on INFO level and I use it always on all external calls to other systems. How do you do it? Easy. Use the StopWatch from the System.Diagnostics namespace. It's accurate enough...

private void HandlerError(HtmlHelper helper, IContentData contentData, Exception renderingException)
{
        var timer = new System.Diagnostics.Stopwatch();
        timer.Start();
        _log.Error("Exception while rendering view", renderingException);
        if (PrincipalInfo.HasEditAccess)
        {
            var errorModel = new ContentRenderingErrorModel(contentData, renderingException);
            helper.RenderPartial("TemplateError", errorModel);
        }
        timer.Stop();
        _log.Information(string.Format("HandlerError took {0} ms.", timer.ElapsedMilliseconds));
}

See! Now if someone tells you that some page X is slow you can prove it's not your code that's the problem and start solving the real problem. Always measure first and then optimize btw.

5. What to log, when and why

• Log execution times on all external calls. This will be helpful in optimizing performance later on. Normally turned off in production unless you are hunting bugs.
• Log all parameters to and from external system. I usually json serialize object to a string and send to the logs. Normally turned off in production unless you are hunting bugs.
• Log errors in all try catch. I usually have this in service layer and then also a global catch-it-all handler that takes care of the rest. As long as the actual error and stack trace is logged I'm happy. Normally turned on in production
• Audit logs. Who does what on the server? Sometimes required. I use an interceptor for this. I'll put it on nuget later so you can check it out if you wish. 
• Logging takes performance as well. Turn off unless you use it. Sometimes it's useful to check if logging is enabled before you start constructing messages. Use:

if(_log.IsInformationEnabled())
{
   //construct expensive logging message
   //log it
}

6. Troubleshooting

• Check that IIS_IUSRS have write access on disc where the blogs are stored. If it hasn't it will give no errors whatsoever but you won't see any logs. 
• Check that you are not trying to use logging before it's been initialized, sometimes happens when you try to log things in global.asax or similar. Episerver takes care of initialization for you but in same cases if you are really early in the chain that hasn't happened yet and if you try to log then, that will shut down all logging everywhere. That happened to me when I logged something in appstart once. Really tricky to find since you get nothing from log4net.

7. Advanced logging with log4net

If you have a large solution and wants lots of logging, I recommend checking out my blog about using interceptors for that purpose as the next step. Episerver also has some good documentation here for logging and of course log4net has its own site here.

A nice feature you might have missed is lossy logging which means that you don't log any "noise" like INFO level messages except when an error occur. Then you also log the N number of log messages on INFO level before the error occured. Cool eh? This is basically the best of two worlds. There are tons of similar smart solutions for log4net. Use it, love it! :)

Check out this example of email appender that uses lossy logging with a level evaluator. It will now send a mail to you with your 512 latest logmessages if you have get a log with level WARN or above. Be a little careful with the mail though, you can fill the inbox pretty quick... :) 

<appender name="SmtpAppender" type="log4net.Appender.SmtpAppender">
    <to value="to@domain.com" />
    <from value="from@domain.com" />
    <subject value="test logging message" />
    <smtpHost value="SMTPServer.domain.com" />
    <bufferSize value="512" />
    <lossy value="true" />
    <evaluator type="log4net.Core.LevelEvaluator">
        <threshold value="WARN"/>
    </evaluator>
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%newline%date [%thread] %-5level %logger [%property{NDC}] - %message%newline%newline%newline" />
    </layout>
</appender>

8. Other built in .NET logs, WCF and WIF

A little bit off topic but...
Just want to mention two other important logs that has saved me while debugging integrations in Episerver solutions that are already in place in .NET. WCF and WIF logging.
WCF logging is great for debugging WCF calls to external systems.
WIF logging is great when debugging single-sign-on solutions.

To turn them on is only a few web.config settings

....
<system.serviceModel> <!--WIF logging-->
    ...
     <diagnostics>
       <messageLogging 
             logMessagesAtTransportLevel="true" 
             logMessagesAtServiceLevel="true"
             logMalformedMessages="true" 
             logEntireMessage="true"
             maxSizeOfMessageToLog="65535000"   maxMessagesToLog="500" />
    </diagnostics>
</system.serviceModel>

....

<system.diagnostics>
    <sources> 
      <!--WIF logging-->
      <source name="System.IdentityModel"  switchValue="Verbose">
        <listeners>
          <add name="WIFListener"/>
        </listeners>
      </source>
      <!--WCF logging-->
      <source  
        name="System.ServiceModel.MessageLogging" 
        switchValue="Information, ActivityTracing" >
       <listeners>
          <add name="yourTrace" 
               type="System.Diagnostics.XmlWriterTraceListener" 
               initializeData="C:\LogFiles\wcflog.svclog">
             <filter type="" />
           </add>
       </listeners>
     </source>
    </sources>
    <sharedListeners>
      <add initializeData="C:\logs\wif.svclog"
        type="System.Diagnostics.XmlWriterTraceListener, System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" name="WIFListener"/>
    </sharedListeners>
</system.diagnostics>

Happy logging!