Microsoft Enterprise Library Logging Application Block Formatting Incorrectly

Question

We're using MS Enterprise Library 5.0 Logging in our web site.

And when an exception goes unhandled, we'd like to log it along with a piece of contextual information to assist in debugging the issue. So, we've got an HttpModule that sits atop the web site and whose job is to catch these and log them to the windows application event log. This is all pretty vanilla stuff.

And it works...on our production web servers. It doesn't work properly on our test web servers.

The issue is that the LogEvent.ExtendedProperties collection isn't rendered properly (or at all). Instead, the replacement tokens are just dumped, verbatim, to the event log.

The production event logs show information like this (slightly abbreviated), with everything formatted the way you'd expect it to be:

12/10/2013 06:07:13 PM
LogName=Application
SourceName=Secure Website
EventCode=1729
EventType=2
Type=Error
ComputerName=WSSECURE09.website.nordstrom.com
TaskCategory=%1
OpCode=Info
RecordNumber=220338
Keywords=Classic
Message=Message: Unhandled exception in Secure Website: System.ServiceModel.FaultException`1[Nordstrom.Contracts.Fault.ServiceFault]:
  Argument shopper is invalid.
  Email is null or empty.
  (Fault Detail is equal to Error code: InvalidArguments).
.
.
.
Extended Properties: Shopper ID - XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

where the last line(s) (Extended Properties: ...) dump the ExtendedProperties collection and give the ID of the shopper who encountered the problem to aid in debugging it. In our test environments, the extended properties collection doesn't get dumped at all. Instead the raw tokens from the template are written out verbatim, with no substitutions performed:

Extended Properties: {key} - {value}
)}

Here's the formatter template in use, straight from the web.config file. I've added line breaks for readability, but that's the only change:

<formatters>
  <add type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging"
    template="
      Message: {message}&#xA;
      Category: {category}&#xA;
      Priority: {priority}&#xA;
      EventId: {eventid}&#xA;
      Severity: {severity}&#xA;
      Title:{title}&#xA;
      Machine: {machine}&#xA;
      Application Domain: {appDomain}&#xA;
      Process Id: {processId}&#xA;
      Process Name: {processName}&#xA;
      Win32 Thread Id: {win32ThreadId}&#xA;
      Thread Name: {threadName}&#xA;
      Extended Properties: {dictionary({key} - {value}&#xA;)}
      "
    name="Text Formatter"
    />
</formatters>

And here's the [slightly sanitized] logging code:

private static void LogHandledException( Exception ex )
{
  HttpContext context = HttpContext.Current ;
  LogEntry    entry   = new LogEntry() ;

  entry.Categories.Add("Errors");
  entry.Priority = 1;
  entry.Severity = TraceEventType.Critical;
  entry.Message  = string.Format( "Unhandled exception in Secure Website: {0}" , ex ) ;
  entry.EventId  = (int) EventId.UnhandledException ;

  // Add shopper id to the log, if we can find it in the http context
  Shopper shopper = HttpContext.Current.Items[ "shopper" ] as Shopper ;
  if ( shopper != null )
  {
    bool hasShopperId = ! string.IsNullOrWhiteSpace( shopper.Id ) ;
    if ( hasShopperId )
    {
      KeyValuePair<string,object> item = new KeyValuePair<string,object>("ShopperID",shopper.Id) ;
      entry.ExtendedProperties.Add( item ) ;
    }
  }

  Logger.Write(entry);
  return ;
}

Answer 1

It worked out that our configuration management team had rolled their own tool to do config file transforms:

• http://www.hanselman.com/blog/SlowCheetahWebconfigTransformationSyntaxNowGeneralizedForAnyXMLConfigurationFile.aspx
• http://msdn.microsoft.com/en-us/library/dd465326(v=vs.110).aspx
• http://msdn.microsoft.com/en-us/library/dd465318(v=vs.100).aspx

That tool's parser was apparently...incorrectly written. Nested curly braces seemed to confuse it. Why it would parsing inside a string literal, or why it would work properly for our production environment transforms, but not for any other environment's transforms, I've got no idea, but the CM team fixed their tool. Et voila! Problem solved.

It didn't occur to me that our build tools would be broken (or that we'd have rolled our own for something pretty standard that has tools available to do the job), but once I'd ruled out our code, and ruled out configuration differences on the different servers, it's didn't leave much room for anything else. As Sherlock Holmes said,

"How often have I said to you that when you have eliminated the impossible, whatever remains, however improbable, must be the truth? We know that he did not come through the door, the window, or the chimney. We also know that he could not have been concealed in the room, as there is no concealment possible. When, then, did he come?"
— Sherlock Holmes in The Sign of the Four, by Sir Arthur Conan Doyle