TIL - Set EventId when Logging to the Event Log with Log4net

I used to be a fan of the Enterprise Library, but lately I've found myself using Log4net instead, which is not bad.

We wanted to log fatal errors to the event log, which can be easily done by configuring a trace listener, however we also wanted control over the event id displayed in the event log to allow meaningful monitoring

Turns out it's pretty simple:

log4net.ThreadContext.Properties["EventID"] = 1337;log.ErrorFormat("Elite Exception: {0}.",  ex); 

Using Memory Appenders in Log4net (All your logging are belong to us)

I have always been a keen advocate of Trace logging as useful tool for tracking down bugs in Test and Production environments, those where it is not possible to hook up a debugger to the web service or windows service.

There is an important problem, though with trace logging as it's normally done in Production, and this is that it's not verbose enough. It is considered good practice to dial down the logging level so that only errors get logged  but this can be a big problem as all that gets logged is the exception, which sometimes is simply not enough to diagnose the problem.

I do believe that this is a good practice for various reasons (less load on the server, no need to worry about log size, etc..), but it is also true that a production system logging at its highest verbosity can be useless due to the amount of messages that get logged.

If an error happens that cannot be diagnosed from the limited logging; logging is normally set to 11 and it is hoped that the error happens again and can be diagnosed.

In an ideal world we would want to log everything leading up to an error and there is a nice way of doing this with the log4net library, as it provides a way to log to memory.

The idea is to log everything to a memory listener and only dump it to the final log (file/Event Log/DB) in case of an exception, or any other condition that might require writing to file/DB, e.g. auditing.

Memory usage would need to be monitored in a real application to see how much of an impact this has, but seeing as memory is cheap and developers are expensive, I think there is good case for having extra memory to accommodate this pattern.

Below is a PoC that I did to see if it would actually would work, I will try to implement this pattern next time I'm doing a web service/windows service from scratch.

From a new Console project in Visual Studio

1.      Add reference to log4net (Can be downloaded from here)
2.      Edit AssemblyInfo.cs
         Add the following to the end of the file
         [assembly: log4net.Config.XmlConfigurator(ConfigFile = "ConsoleApplication2.exe.config", Watch = false)]

Code:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using log4net;
using log4net.Repository.Hierarchy;
using log4net.Appender;

namespace ConsoleApplication2
{
  class Program
    {
        static void Main(string[] args)
        {
            ILog log = log4net.LogManager.GetLogger("PoC");
 
            Hierarchy hierarchy = LogManager.GetRepository() as Hierarchy;
            MemoryAppender mappender = hierarchy.Root.GetAppender("MemoryAppender") as MemoryAppender;
 
            ImportantDateCalculator(log, mappender, "first");
            System.Threading.Thread.Sleep(1000);
            ImportantDateCalculator(log, mappender, "second");
            Console.ReadKey();
        }
 
        private static void ImportantDateCalculator(ILog log, MemoryAppender mappender, string msg)
        {
            mappender.Clear();
 
            try
            {
                log.InfoFormat("{0}", msg);
                //loads of code here, calculating the meaning of life
                log.InfoFormat("{0}", new Random().Next(42, 42));
                //even more code here calculating the approximate date and time for the heat death of the universe.
                log.InfoFormat("{0}", DateTime.Now.ToString("s"));
 
                throw new Exception("oh noes");
            }
            catch (Exception ex)
            {
                StringBuilder message = new StringBuilder();
                mappender.GetEvents().ToList().ForEach(x => message.AppendLine(x.RenderedMessage));
                message.AppendLine(ex.ToString());
                log.ErrorFormat("{0}",message);                
            }
            
            mappender.Clear();
        }
    }
}

Config File

<?xml version="1.0"?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>   
  </configSections>
  <log4net>
    <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
      <file value="PoC.log"/>
      <threshold value="ERROR"/>
      <appendToFile value="true"/>
      <rollingStyle value="Size"/>
      <maxSizeRollBackups value="10"/>
      <maximumFileSize value="1000KB"/>
      <staticLogFileName value="true"/>
       <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger - %message%newline"/>
      </layout>
    </appender>
    <appender name="MemoryAppender" type="log4net.Appender.MemoryAppender">
    </appender>
    <root>
      <appender-ref ref="RollingFileAppender"/>
      <appender-ref ref="MemoryAppender"/>
    </root>
  </log4net>
<startup><supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.0"/></startup></configuration>

Trace logging with the Enterprise Library for MS Dynamics CRM 2011 plug-ins - part 3

In part one of this series I described how to use the enterprise library for trace logging in MS Dynamics CRM 2011 plug-ins (it should also work for MS Dynamics CRM 4.0) and in part two, I described how to use add the necessary changes to the various configuration files using Wix.

In this post, I provide a simple sample of how to use the Enterprise Library for trace logging.

Ensure that you add a reference to Enterprise Logging Application Block to your project, if this is not showing up, you probably don't have the Enterprise Library installed.

Sample Code:

 using System;
 using System.Collections.Generic;
 using System.Linq;
 using System.Text;
 using System.Diagnostics;
 using Microsoft.Practices.EnterpriseLibrary.Logging;
 using System.IO;
 
 namespace ELSample
 {
     class Program
     {
         static void Main(string[] args)
         {
             string file = @"c:\myfile.txt";
             
             try
             {
                 WriteLogEntry("Trace",string.Format("Start to read file {0}.", file)); 
 
                 using (StreamReader sr = new StreamReader(file))
                 {
                     //do something here.
                 }
 
                 WriteLogEntry("Trace", string.Format("Finished reading file {0}.", file)); 
             }
             catch (Exception ex)
             {
                 WriteLogEntry("Error", "Exception Occurred.");
                 WriteLogEntry("Error", string.Format("Source: {0}.", ex.Source));
                 WriteLogEntry("Error", string.Format("Type: {0}.", ex.GetType()));
                 WriteLogEntry("Error", string.Format("Message: {0}.", ex.Message));
 
                 if (ex.InnerException != null)
                 {
                     WriteLogEntry("Error", string.Format("Inner Exception: {0}.", ex.InnerException.Message));
                 }
             }
 
         }
 
         /// <summary>
         /// Write a log entry using the Enterprise Library
         /// </summary>
         /// <param name="LogCategory">This is the name of the Trace Listener, e.g. Trace, Error</param>
         /// <param name="LogMessage">Log Entry to write</param>
         public static void WriteLogEntry(string LogCategory, string LogMessage)
         {
             LogEntry entry = new LogEntry();
             entry.Categories.Add(LogCategory);
             entry.Message = LogMessage;
 
             StackTrace trace = new StackTrace();
 
             entry.Title = string.Format("{0}.{1}",
                 trace.GetFrame(1).GetMethod().ReflectedType.Name, trace.GetFrame(1).GetMethod().Name);
 
             Microsoft.Practices.EnterpriseLibrary.Logging.Logger.Write(entry);
         }
 
   
     }
 }

A few things to note:

1. I know that the sample is not from a plug-in.
2. Same config section, the logging part, as in the first post.
3. If you turn a trace listener off, the WriteLogEntry method will not write any entries, but there will be some processing done, so it will run slower than without it, as with everything in life it's a trade off.
4. It probably makes sense to have a separate method for logging exceptions.
5. I normally only bother with two trace listeners, Trace and Error. The former is normally equivalent to Verbose logging, the latter to ... Error logging.

Change Trace Logging Directory in MS Dynamics CRM 2011

Microsoft has finally decided that we are all big boys now and that we can make some decisions, including where the trace logging files should go. The TraceDirectory key in the registry still gets summarily ignored, but it is possible to change the directory using PowerShell. It's a fairly simple process:

1. Start PowerShell.
2. Load the CRM PS Snap in:  Add-PSSnapin Microsoft.Crm.PowerShell
3. Store Trace Settings into variable to allow easy editing: $trace = Get-CRMSetting TraceSettings
4. Change Directory to your preferred value: $trace.Directory=”D:\Trace”
5. Save Settings: Set-CRMSetting $trace
6. You can check that the new setting has been set with: Get-CRMSetting TraceSettings

CallStack     : True
Categories    : *:Error
Directory     : D:\Trace
Enabled       : True
FileSize      : 10
ExtensionData : System.Runtime.Serialization.ExtensionDataObject

Note that the directory on step 4 needs to exist.

If you haven’t enabled trace logging, you can do it before step 4:

$trace.Enabled =”True”

Thank you Microsoft.