EPiServer - logging and troubleshooting log4net

Introduction

Logging in EPiServer CMS is very well documented on this link: http://world.episerver.com/Documentation/Items/Developers-Guide/EPiServer-CMS/75/Logging/Logging/

But sometimes our log messages are not written to the log file.

In this blog post, I'll be using Alloy template and EPiServer 7.5. Please note that logging API might look different in the latest version of EPiServer CMS, as well as the content of EPiServerLog.config file.

Writing a message to the log file

Here's the code snippet:

using System.Web.Mvc;
using EPiServer.Core;
using EPiServer.Templates.Alloy.Models.Pages;
using EPiServer.Templates.Alloy.Models.ViewModels;
using EPiServer.Web.Mvc;
using log4net;

namespace EPiServer.Templates.Alloy.Controllers
{
    public class StartPageController : PageControllerBase<StartPage>
    {
        private readonly ILog _log = LogManager.GetLogger(typeof(StartPageController));

        public ActionResult Index(StartPage currentPage)
        {
            _log.Info("Hello World!");
            // ... rest of the code
        }
    }
}

If we open App_Data / EPiServerErrors.log file, we will see that nothing is logged.

Debugging

The first thing I always do is to run a debugger to check if Debug / Error / Fatal / Info / Warn level messages are enabled.

As we can see, INFO-level messages are not enabled, and that explains why our message has not been written to the EPiServer log file.

Enabling INFO messages

First, we need to get a default namespace of our application.

And define a new logger element in EPiServerLog.config file like this:

<logger name="EPiServer.Templates.Alloy">
	<level value="All" />
</logger>

All levels should be enabled now:

Threshold

If you run the application again, you'll see that nothing is logged to the EPiServer log file even though INFO messages are enabled.

If we open EPiServerLog.config file, we'll see that threshold value is set to Error. This means that only Error-level  messages (and higher) will be logged.

If you change that value to All, and re-run the application, you should see an entry in the EPiServer's log file.

This is how EPiServerLog.config file should look like:

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

    <!-- Reduce amount of debug logging -->
    <logger name="EPiServer.Core.OptimisticCache" additivity="false">
        <level value="Error" />
    </logger>
    <logger name="EPiServer.Core.ContentProvider" additivity="false">
        <level value="Error" />
    </logger>
    <logger name="EPiServer.Data.Dynamic.Providers.DbDataStoreProvider" additivity="false">
        <level value="Error" />
    </logger>
    <logger name="EPiServer.Data.Providers.SqlDatabaseHandler" additivity="false">
        <level value="Error" />
    </logger>
    <logger name="EPiServer.Data.Providers.ConnectionContext" additivity="false">
        <level value="Error" />
    </logger>
	<logger name="EPiServer.Templates.Alloy">
        <level value="All" />
    </logger>

    <root>
        <!--Be careful, setting this value to All, Debug or Info will affect performance.-->
        <level value="Error" />

        <!--Enabled file logging-->
        <appender-ref ref="errorFileLogAppender" />

        <!-- Use DebugView (Microsoft/SysInternals) and enable Capture Win32 + Capture Global Win32 (http://technet.microsoft.com/en-us/sysinternals/bb896647). -->
        <!--appender-ref ref="outputDebugStringAppender" /-->
    </root>
</log4net>

Please note that I have enabled all level messages for demonstration purposes only. On the production server, you don't want to log debug-level messages.

Happy logging! :)

comments powered by Disqus