Additional log entries - can't work out why [solved]

Topics: Exception Handling Application Block, Logging Application Block, Policy Injection Application Block
Oct 20, 2010 at 3:36 PM

I'm getting an additional log message from my EntLib 5 configuration and I can't work out why.

I'm investigating ExceptionShielding for a WCF app.  I've created a test project and marked the WCF Service class with [ExceptionShielding("WCFPolicy")].  I've added references to ..Common, ..ExceptionHandling, ..ExceptionHandling.Logging, ..ExceptionHandling.WCF, ..Logging and ..Logging.Database, as well as ..ServiceLocation, ..Unity and ..UnityInterception and I've set it up to throw an exception when a service method is called.  I've added config to log both to the Event Viewer and to a SQL Database.  The additional log entry appears in both locations.

The expected entry looks like this (truncated for clarity):

EventID: 100
Title: Enterprise LIbrary Exception Handling
Severity: Error
Priority: 0
Source (in event log): Enterprise Library Logging
CategoryName: General
Message: HandlingInstanceID: ececb98c-3f08-4006-a2bb-5fa9ad1b3ddb  An exception of type 'WCFServiceExceptions.Web.TankException' occurred and was caught. [...]

The unexpected entry looks like this (also truncated):

EventID: 1
Title:
Severity: Information
Priority: -1
Source (in event log): Enterprise Library Logging
CategoryName: General
Message: WCFServiceExceptions.Web.TankException: Error in wiggalizer (Machine Name: [...]; TimeStamp: 20/10/2010 14:57:24 ---> System.ArgumentNullException: The  [...]

Can I do anything about this extra log entry?

I've included my Web.config file at the end of this post.

Regard

SSG

Web.config

<?xml version="1.0"?>

<!--
  For more information on how to configure your ASP.NET application, please visit
  http://go.microsoft.com/fwlink/?LinkId=169433
  -->

<configuration>
  <configSections>
    <section name="loggingConfiguration"
             type="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.LoggingSettings, Microsoft.Practices.EnterpriseLibrary.Logging, Version=5.0.414.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
             requirePermission="true" />
    <section name="exceptionHandling"
             type="Microsoft.Practices.EnterpriseLibrary.ExceptionHandling.Configuration.ExceptionHandlingSettings, Microsoft.Practices.EnterpriseLibrary.ExceptionHandling, Version=5.0.414.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
             requirePermission="true" />
  </configSections>
  <loggingConfiguration name=""
                        tracingEnabled="true"
                        defaultCategory="General">
    <listeners>
      <add name="Event Log Listener"
           type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.FormattedEventLogTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging, Version=5.0.414.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
           listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.FormattedEventLogTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging, Version=5.0.414.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
           source="Enterprise Library Logging"
           formatter="Text Formatter"
           log=""
           machineName="."
           traceOutputOptions="None" />
      <add name="Database Trace Listener"
           type="Microsoft.Practices.EnterpriseLibrary.Logging.Database.FormattedDatabaseTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging.Database, Version=5.0.414.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
           listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Database.Configuration.FormattedDatabaseTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging.Database, Version=5.0.414.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
           databaseInstanceName="Database Connection String"
           writeLogStoredProcName="WriteLog"
           addCategoryStoredProcName="AddCategory"
           formatter="Text Formatter" />
    </listeners>
    <formatters>
      <add type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=5.0.414.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
           template="Timestamp: {timestamp}{newline}&#xA;Message: {message}{newline}&#xA;Category: {category}{newline}&#xA;Priority: {priority}{newline}&#xA;EventId: {eventid}{newline}&#xA;Severity: {severity}{newline}&#xA;Title:{title}{newline}&#xA;Machine: {localMachine}{newline}&#xA;App Domain: {localAppDomain}{newline}&#xA;ProcessId: {localProcessId}{newline}&#xA;Process Name: {localProcessName}{newline}&#xA;Thread Name: {threadName}{newline}&#xA;Win32 ThreadId:{win32ThreadId}{newline}&#xA;Extended Properties: {dictionary({key} - {value}{newline})}"
           name="Text Formatter" />
    </formatters>
    <categorySources>
      <add switchValue="All"
           name="General">
        <listeners>
          <add name="Event Log Listener" />
          <add name="Database Trace Listener" />
        </listeners>
      </add>
    </categorySources>
    <specialSources>
      <allEvents switchValue="All"
                 name="All Events" />
      <notProcessed switchValue="All"
                    name="Unprocessed Category" />
      <errors switchValue="All"
              name="Logging Errors &amp; Warnings">
        <listeners>
          <add name="Event Log Listener" />
        </listeners>
      </errors>
    </specialSources>
  </loggingConfiguration>
  <exceptionHandling>
    <exceptionPolicies>
      <add name="WCFPolicy">
        <exceptionTypes>
          <add name="All Exceptions"
               type="System.Exception, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
               postHandlingAction="ThrowNewException">
            <exceptionHandlers>
              <add name="Logging Exception Handler"
                   type="Microsoft.Practices.EnterpriseLibrary.ExceptionHandling.Logging.LoggingExceptionHandler, Microsoft.Practices.EnterpriseLibrary.ExceptionHandling.Logging, Version=5.0.414.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
                   logCategory="General"
                   eventId="100"
                   severity="Error"
                   title="Enterprise Library Exception Handling"
                   formatterType="Microsoft.Practices.EnterpriseLibrary.ExceptionHandling.TextExceptionFormatter, Microsoft.Practices.EnterpriseLibrary.ExceptionHandling"
                   priority="0" />
            </exceptionHandlers>
          </add>
        </exceptionTypes>
      </add>
    </exceptionPolicies>
  </exceptionHandling>
  <connectionStrings>
    <add name="Database Connection String"
         connectionString="Data Source=.;Initial Catalog=Logging;Integrated Security=SSPI;"
         providerName="System.Data.SqlClient" />
  </connectionStrings>
  <system.web>
    <compilation debug="true"
                 targetFramework="4.0" />
  </system.web>

  <system.serviceModel>
    <behaviors>
      <serviceBehaviors>
        <behavior name="">
          <serviceMetadata httpGetEnabled="true" />
          <serviceDebug includeExceptionDetailInFaults="false" />
        </behavior>
      </serviceBehaviors>
    </behaviors>
    <bindings>
      <customBinding>
        <binding name="WCFServiceExceptions.Web.TestService.customBinding0">
          <binaryMessageEncoding />
          <httpTransport />
        </binding>
      </customBinding>
    </bindings>
    <serviceHostingEnvironment aspNetCompatibilityEnabled="true"
                               multipleSiteBindingsEnabled="true" />
    <services>
      <service name="WCFServiceExceptions.Web.TestService">
        <endpoint address=""
                  binding="customBinding"
                  bindingConfiguration="WCFServiceExceptions.Web.TestService.customBinding0"
                  contract="WCFServiceExceptions.Web.TestService" />
        <endpoint address="mex"
                  binding="mexHttpBinding"
                  contract="IMetadataExchange" />
      </service>
    </services>
  </system.serviceModel>
</configuration>

Oct 21, 2010 at 1:45 AM
Edited Oct 21, 2010 at 1:46 AM

Let me clarify, are you saying you're getting the unexpected log entry instead of the expected log entry or are you getting both?  If it's the latter, are they on the same log entry or are they 2 separate entries?

 

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com

Oct 22, 2010 at 7:08 AM

I'm getting both in separate entries.  This is what an Error entry looks like in the event log:

Timestamp: 22/10/2010 05:50:30

Message: HandlingInstanceID: 6f1a2b9d-aad5-4524-8708-273ac574c2f7
An exception of type 'WCFServiceExceptions.Web.TankException' occurred and was caught.
--------------------------------------------------------------------------------------
10/22/2010 06:50:30
Type : WCFServiceExceptions.Web.TankException, WCFServiceExceptions.Web, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
Message : Error in wiggalizer (Machine Name: Cecil; TimeStamp: 22/10/2010 06:50:30
Source : WCFServiceExceptions.Web
Help link : 
MachineName : Cecil
TimeStamp : 10/22/2010 06:50:30
Data : System.Collections.ListDictionaryInternal
TargetSite : System.String GetString()
Stack Trace :    at WCFServiceExceptions.Web.TestService.GetString() in C:\Users\TestUser\Documents\Visual Studio 2010\Projects\Understanding\EntLib5.0\WCFServiceExceptions\WCFServiceExceptions.Web\TestService.svc.cs:line 33
   at SyncInvokeGetString(Object , Object[] , Object[] )
   at System.ServiceModel.Dispatcher.SyncMethodInvoker.Invoke(Object instance, Object[] inputs, Object[]& outputs)
   at System.ServiceModel.Dispatcher.DispatchOperationRuntime.InvokeBegin(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage5(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage41(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage4(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage31(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage3(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage2(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage11(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage1(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.MessageRpc.Process(Boolean isOperationContextSet)

Additional Info:

MachineName : Cecil
TimeStamp : 22/10/2010 05:50:30
FullName : Microsoft.Practices.EnterpriseLibrary.ExceptionHandling, Version=5.0.414.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35
AppDomainName : f22ed3d7-3-129322002283983966
ThreadIdentity : 
WindowsIdentity : Cecil\TestUser
	Inner Exception
	---------------
	Type : System.ArgumentNullException, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089
	Message : The message
Parameter name: The parameter
	Source : WCFServiceExceptions.Web
	Help link : 
	ParamName : The parameter
	Data : System.Collections.ListDictionaryInternal
	TargetSite : System.String GetHome()
	Stack Trace :    at WCFServiceExceptions.Web.Components.Wiggalizer.GetHome() in C:\Users\TestUser\Documents\Visual Studio 2010\Projects\Understanding\EntLib5.0\WCFServiceExceptions\WCFServiceExceptions.Web\Components\Wiggalizer.cs:line 33
	   at WCFServiceExceptions.Web.TestService.GetString() in C:\Users\TestUser\Documents\Visual Studio 2010\Projects\Understanding\EntLib5.0\WCFServiceExceptions\WCFServiceExceptions.Web\TestService.svc.cs:line 29



Category: General

Priority: 0

EventId: 100

Severity: Error

Title:Enterprise Library Exception Handling

Machine: Cecil

App Domain: f22ed3d7-3-129322002283983966

ProcessId: 6120

Process Name: C:\Program Files (x86)\Common Files\Microsoft Shared\DevServer\10.0\WebDev.WebServer40.exe

Thread Name: 

Win32 ThreadId:6316

Extended Properties: 

And this is what an Information entry looks like in the event log:

Timestamp: 22/10/2010 05:50:30

Message: WCFServiceExceptions.Web.TankException: Error in wiggalizer (Machine Name: Cecil; TimeStamp: 22/10/2010 06:50:30 ---> System.ArgumentNullException: The message
Parameter name: The parameter
   at WCFServiceExceptions.Web.Components.Wiggalizer.GetHome() in C:\Users\TestUser\Documents\Visual Studio 2010\Projects\Understanding\EntLib5.0\WCFServiceExceptions\WCFServiceExceptions.Web\Components\Wiggalizer.cs:line 33
   at WCFServiceExceptions.Web.TestService.GetString() in C:\Users\TestUser\Documents\Visual Studio 2010\Projects\Understanding\EntLib5.0\WCFServiceExceptions\WCFServiceExceptions.Web\TestService.svc.cs:line 29
   --- End of inner exception stack trace ---
   at Microsoft.Practices.EnterpriseLibrary.ExceptionHandling.ExceptionPolicyEntry.IntentionalRethrow(Exception chainException, Exception originalException) in e:\Builds\EntLib\Latest\Source\Blocks\ExceptionHandling\Src\ExceptionHandling\ExceptionPolicyEntry.cs:line 102
   at Microsoft.Practices.EnterpriseLibrary.ExceptionHandling.ExceptionPolicyEntry.RethrowRecommended(Exception chainException, Exception originalException) in e:\Builds\EntLib\Latest\Source\Blocks\ExceptionHandling\Src\ExceptionHandling\ExceptionPolicyEntry.cs:line 120
   at Microsoft.Practices.EnterpriseLibrary.ExceptionHandling.ExceptionPolicyEntry.Handle(Exception exceptionToHandle) in e:\Builds\EntLib\Latest\Source\Blocks\ExceptionHandling\Src\ExceptionHandling\ExceptionPolicyEntry.cs:line 89
   at Microsoft.Practices.EnterpriseLibrary.ExceptionHandling.ExceptionPolicyImpl.HandleException(Exception exceptionToHandle) in e:\Builds\EntLib\Latest\Source\Blocks\ExceptionHandling\Src\ExceptionHandling\ExceptionPolicyImpl.cs:line 81
   at Microsoft.Practices.EnterpriseLibrary.ExceptionHandling.ExceptionPolicy.HandleException(Exception exceptionToHandle, String policyName) in e:\Builds\EntLib\Latest\Source\Blocks\ExceptionHandling\Src\ExceptionHandling\ExceptionPolicy.cs:line 55
   at Microsoft.Practices.EnterpriseLibrary.ExceptionHandling.WCF.ExceptionShieldingErrorHandler.ProvideFault(Exception error, MessageVersion version, Message& fault) in e:\Builds\EntLib\Latest\Source\Blocks\ExceptionHandling\Src\WCF\ExceptionShieldingErrorHandler.cs:line 93

Category: General

Priority: -1

EventId: 1

Severity: Information

Title:

Machine: Cecil

App Domain: f22ed3d7-3-129322002283983966

ProcessId: 6120

Process Name: C:\Program Files (x86)\Common Files\Microsoft Shared\DevServer\10.0\WebDev.WebServer40.exe

Thread Name: 

Win32 ThreadId:6316

Extended Properties: HandlingInstance ID: - 4db2d397-e598-4354-9b74-5266b0dc8c82

The only things I've changed in both are a class name, my name and my computer name.  I've noticed that the stack traces are quite different - I didn't look before (sorry) because I was generating the Exception deliberately to check my EntLib config was correct.

Oct 22, 2010 at 7:58 AM

If you're implementing exception shielding, why aren't you using the FaultContractExceptionHandler in your WCFPolicy exception policy?  In addition, why are you expecting an informational log whereas you are actually logging an exception? 

If you add a FaultContractExceptionHandler  in your WCFPolicy and it precedes your LoggingExceptionHandler, you'll get an error log containing details about the FaultContractException.  If you're LoggingExceptionHandler comes first, the original exception that was thrown in your wcf service will be the one that gets log.

 

Sarah Urmeneta
Global Technology and Solutions
Avanade, Inc.
entlib.support@avanade.com

Oct 23, 2010 at 9:00 AM

Ah.  I was following the instructions on the page Shielding Exceptions at WCF Service Boundaries.  I've had quite a few problems configuring EntLib so I tend to do one thing and test it.  I put in the Shielding Attribute and tested and got the problem, so I stopped and opened this query. 

In my defence, I started out with a post-andlingaction of None and then realised I had to use ThrowNewException.

And the instructions do say "..... you can use the FaultContract exception handler to convert a run time..." [my emphasis] so it seemed like a legitimate configuration not to have one.

I have one additional query but I'll raise a new item for it because the earlier posts have mucked up the display of this one.