Double log entries using Unity interception and Entlib logging

Jul 19, 2010 at 10:14 PM

This is driving me nuts. I have setup my web application to use Unity 2.0 and the Logging Application Block 5.0. I am intercepting a method with the LogCallHandler using policy injection. It is working, except that I receive 2 identical messages in the log file for each method invocation. I have stepped through in the debugger, and it appears LogCallHandler.Invoke() is only being called once, and logBeforeCall is false and logAfterCall is true. here are the relevant configuration sections (trimmed a little for implementation details which don't matter). Incidentally, I am doing the interception completely through configuration.

  <loggingConfiguration name="Logging Application Block" tracingEnabled="true" defaultCategory="MyCategory" logWarningsWhenNoCategoriesMatch="true">
      <add fileName="Logs\InterGateway.log" footer="----------------------------------------"
        formatter="Text Formatter" header="----------------------------------------"
        rollFileExistsBehavior="Overwrite" rollInterval="Midnight" rollSizeKB="0"
        timeStampPattern="yyyy-MM-dd" listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.RollingFlatFileTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging"
        traceOutputOptions="None" filter="All" type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.RollingFlatFileTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging"
        name="Rolling Flat File Trace Listener" />
      <add template="Timestamp: {timestamp(local:yyyy-MM-dd HH:mm:ss.fff)}&#xD;&#xA;Message: {message}&#xD;&#xA;Category: {category}&#xD;&#xA;Severity: {severity}"
        type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging"
        name="Text Formatter" />
      <clear />
      <add switchValue="All" name="MyCategory">
          <add name="Rolling Flat File Trace Listener" />
      <allEvents switchValue="All" name="All Events" />
      <notProcessed switchValue="All" name="Unprocessed Category" />
      <errors switchValue="All" name="Logging Errors &amp; Warnings" />

and then for Unity:
    <register name="MyHandler" type="IHttpHandler" mapTo="MyHandler, VoltDelta.ATT.Interactive">
      <interceptor type="VirtualMethodInterceptor" />
      <policyInjection />
      <policy name="LoggingPolicy">
        <matchingRule type="MemberNameMatchingRule" name="Matching Rule">
            <param name="nameToMatch" value="MyMethod" />
        <callHandler type="LogCallHandler" name="logging handler">
            <param name="logWriter" />
            <param name="eventId" value="200" />
            <param name="logBeforeCall" value="false" />
            <param name="logAfterCall" value="true" />
            <param name="beforeMessage" value="Before method call" />
            <param name="afterMessage" value="After method call" />
            <param name="includeParameters" value="true" />
            <param name="includeCallStack" value="false" />
            <param name="includeCallTime" value="true" />
            <param name="priority" value="-1" />
I've simplified this a bit; for example, I am writing out the method parameters and some custom properties as well, but that is all working fine, it's just that I seem to get two entries for each method call. What am I doing wrong?


Jul 21, 2010 at 5:49 AM

Well, I said it was driving me crazy. I started over with an empty solution, and gradually added all the pieces back, one at a time. Now, I get one log message for each method invocation, as expected. I still haven't figured out what the bone-head mistake in the first solution was/is.