Improve your sitecore log with realtime output and calling class

Sitecore uses the extensive log4net logging framework to handle the large volume of logging entries it generates. Sometimes vague log entries can leave you scratching around trying to find where they originated from. This post explores some simple steps to add useful detail to, and real-time viewing of, the Sitecore log.

One awkward scenario could be where an error is being logged with little detail or context, perhaps from a caught exception that is then not being re-thrown, so no stack trace. To add clarity to such entries, we can turn our attention to the Log4Net pattern layout which governs the format and data contained in string-based log4net output appenders. Out of the box, Sitecore uses the following conversion pattern for the file appender, highlighted below.

<appender name="LogFileAppender" type="log4net.Appender.SitecoreLogFileAppender, Sitecore.Logging">
      <file value="$(dataFolder)/logs/log.{date}.txt" />
      <appendToFile value="true" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%4t %d{ABSOLUTE} %-5p %m%n" />
      </layout>
      <encoding value="utf-8" />
    </appender>

The pattern correlates to thread-id, timestamp, log-level, message, and lastly new-line. The log4net conversion pattern reference shows there are many more properties that can be accessed however it’s worth pointing out that the Sitecore.Logging assembly appears to wrap a rather old version of Log4net within it and because of this many of the property keys are different, or in some cases do not exist.

Calling class

One of the most useful things to add to our conversion pattern is %type, or its alias %c.

As standard – “%4t %d{ABSOLUTE} %-5p %m%n”

11652 00:21:07 INFO  HttpModule is being initialized
11652 00:21:07 INFO  
11652 00:21:07 INFO  **********************************************************************
11652 00:21:07 INFO  **********************************************************************
11652 00:21:07 INFO  Sitecore started
11652 00:21:07 INFO  Sitecore.NET 8.0 (rev. 150427)

Modified to – “%4t %d{ABSOLUTE} %-5p [%c] %m%n”

11652 00:21:12 INFO  [Sitecore.Nexus.Web.HttpModule] HttpModule is being initialized
11652 00:21:12 INFO  [Sitecore.Pipelines.Loader.ShowVersion] 
11652 00:21:12 INFO  [Sitecore.Pipelines.Loader.ShowVersion] **********************************************************************
11652 00:21:12 INFO  [Sitecore.Pipelines.Loader.ShowVersion] **********************************************************************
11652 00:21:12 INFO  [Sitecore.Pipelines.Loader.ShowVersion] Sitecore started
11652 00:21:12 INFO  [Sitecore.Pipelines.Loader.ShowVersion] Sitecore.NET 8.0 (rev. 150427)

The reference documentation warns that generating class information is slow, and this is probably one of the reasons it is not enabled out of the box, however I found the impact to be unnoticeable in a subjective comparison. While exploring XML appenders which output many if not all of the available parameters, some of which are described as ‘extremely slow’, I noticed a very significant performance hit.

Real time output

Sitecore rocks has a log viewer which auto-refreshes at intervals down to 10 seconds, but in order to get a true real-time output we can use the Log4Net standard UdpAppender to send our log data as a stream of udp packets for a compatible viewer.

I found that logViewForNet to be quick, free and has a udp listener that doesn’t require xml format data. In effect a real-time representation of the standard log file. When adding the Udp listener set the ip to 127.0.0.1 for local viewing and (IMPORTANT) set the encoding to UTF-8. If you see a stream of jibberish being output, check this one again.

In web.config we can add the additional udp appender and appender-ref entries.

<log4net>
[.....]
<appender name="UdpAppender" type="log4net.Appender.UdpAppender">
   <remoteAddress value="127.0.0.1" />
   <remotePort value="5678" />
   <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%4t %d{ABSOLUTE} %-5p [%c] %m" />
   </layout>
</appender>

<root>
  <priority value="INFO" />
  <appender-ref ref="LogFileAppender" />
  <appender-ref ref="UdpAppender" />
</root>

Then configure logview4net :

LogView4Net udp appender configuration

And with that you should start seeing realtime log output.

This is just one way to achieve this kind of output, but it’s simple, quick and free. There are definitely other appenders, viewers and modules out there. Feel free to link to them in the comments.

4 thoughts on “Improve your sitecore log with realtime output and calling class

  1. Anis Ahmed Chohan

    Nice article, I do something similar with logs using power shell to read real time output.

    Get-Content -Path C:\logFileToMonitor.log -Tail 1 –Wait

    Reply

Leave a Reply to Jawad Cancel reply

Your email address will not be published. Required fields are marked *