Log4net
  1. Log4net
  2. LOG4NET-266

AdoNetAppender does not work on a IIS 7 website using Windows authentication

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 1.2.10
    • Fix Version/s: 1.2.12
    • Component/s: Appenders
    • Labels:
      None
    • Environment:
      Windows Server 2008, IIS 7, ASP.Net Framework v4.0, Sql Server 2008, Windows Authentication Activated

      Description

      When the Windows Authentication is deactivated, the AdoNetAppender works properly.

      Howerver, once the Windows authentication is activated, the AdoNetAppender start working properly and then, after a few seconds, it is aborted and the following error message is retrieved:

      log4net:ERROR [AdoNetAppender] Failed in DoAppend
      System.ObjectDisposedException: Safe handle has been closed
      at System.Runtime.InteropServices.SafeHandle.DangerousAddRef(Boolean& success)
      at System.StubHelpers.StubHelpers.SafeHandleAddRef(SafeHandle pHandle, Boolean& success)
      at Microsoft.Win32.Win32Native.GetTokenInformation(SafeTokenHandle TokenHandle, UInt32 TokenInformationClass, SafeLocalAllocHandle TokenInformation, UInt32 TokenInformationLength, UInt32& ReturnLength)
      at System.Security.Principal.WindowsIdentity.GetTokenInformation(SafeTokenHandle tokenHandle, TokenInformationClass tokenInformationClass)
      at System.Security.Principal.WindowsIdentity.get_User()
      at System.Security.Principal.WindowsIdentity.GetName()
      at System.Security.Principal.WindowsIdentity.get_Name()
      at log4net.Core.LoggingEvent.get_Identity()
      at log4net.Core.LoggingEvent.FixVolatileData(FixFlags flags)
      at log4net.Appender.BufferingAppenderSkeleton.Append(LoggingEvent loggingEvent)
      at log4net.Appender.AppenderSkeleton.DoAppend(LoggingEvent loggingEvent)

      See below the settings of the appender. Various options (i.e. Securitycontext ) have also been tested in vain.

      <appender name="AdoNetAppender_SqlServer" type="log4net.Appender.AdoNetAppender">
      <bufferSize value="1" />
      <connectionType value="System.Data.SqlClient.SqlConnection, System.Data, Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
      <connectionString value="data source=WWWWWW;initial catalog=XXXXX;integrated security=false;persist security info=True;User ID=sa;Password=YYYYYYYY" />
      <commandText value="sp_LOG_Insert"/>
      <commandType value="StoredProcedure" />
      <parameter>
      <parameterName value="@DATE" />
      <dbType value="DateTime" />
      <layout type="log4net.Layout.PatternLayout" value="%date

      {yyyy'-'MM'-'dd HH':'mm':'ss'.'fff}

      " />
      </parameter>
      <parameter>
      <parameterName value="@THREAD" />
      <dbType value="String" />
      <size value="255" />
      <layout type="log4net.Layout.PatternLayout" value="%thread" />
      </parameter>
      <parameter>
      <parameterName value="@LEVEL" />
      <dbType value="String" />
      <size value="50" />
      <layout type="log4net.Layout.PatternLayout" value="%level" />
      </parameter>
      <parameter>
      <parameterName value="@LOGGER" />
      <dbType value="String" />
      <size value="255" />
      <layout type="log4net.Layout.PatternLayout" value="%logger" />
      </parameter>
      <parameter>
      <parameterName value="@MESSAGE" />
      <dbType value="String" />
      <size value="8000" />
      <layout type="log4net.Layout.PatternLayout" value="%message" />
      </parameter>

      </appender>

      1. LoggingEvent.cs
        46 kB
        Johannes Krackowizer

        Issue Links

          Activity

          Hide
          Johannes Krackowizer added a comment -

          I have analyzed this problem, it occurs only under very special conditions but there is a simple workaround.

          If you use an application pool in integrated mode on iis 7 or 7.5 and if windows authentication is activated and if the http request starts threads and this threads use log4net.

          As seen in this scenario i'm working with (MVC 3 Web Application):

          1. The HTTP request start and the MVC Controller starts.
          2. In the controller we start a long running background thread (in my case a lot of work in the database)
          3. The MVC controller completes and after that the view is rendered and send back to the client.
          4. System.Threading.Thread.CurrentPrincipal is disposed by iis.
          5. The long running background thread tries to log something and an System.ObjectDisposedException occurs in Core\LoggingEvent.cs:885
          if (System.Threading.Thread.CurrentPrincipal != null &&
          System.Threading.Thread.CurrentPrincipal.Identity != null &&
          System.Threading.Thread.CurrentPrincipal.Identity.Name != null)
          The third part will fail because the getter of .Name will throw an exception.

          The simplest workaround is to set new CurrentPrincipal if you start a new background thread. E.g.:

          System.Threading.Thread asyncWorker = new System.Threading.Thread( LongRunningTasks );
          asyncWorker.Start( System.Security.Principal.WindowsIdentity.GetCurrent() );

          private void LongRunningTasks( object identity )
          {
          System.Security.Principal.WindowsIdentity windowsIdentity = identity as System.Security.Principal.WindowsIdentity;

          System.Security.Principal.WindowsImpersonationContext impersonationContext = null;
          if ( windowsIdentity != null )

          { System.Threading.Thread.CurrentPrincipal = new System.Security.Principal.WindowsPrincipal( windowsIdentity ); impersonationContext = windowsIdentity.Impersonate(); }

          // Do your work.

          if ( impersonationContext != null )
          impersonationContext.Undo();
          }

          I'm not sure how this should be fixed in the source.
          But the simplest way would be to catch the System.ObjectDisposedException in the getter of LoggingEvent.Identity in file Core\LoggingEvent.cs and set m_data.Identity = "" like if System.Threading.Thread.CurrentPrincipal would be null. I think this would be the correct way because iis tries to dispose the CurrentPrincipal but stops before the work is done.

          Show
          Johannes Krackowizer added a comment - I have analyzed this problem, it occurs only under very special conditions but there is a simple workaround. If you use an application pool in integrated mode on iis 7 or 7.5 and if windows authentication is activated and if the http request starts threads and this threads use log4net. As seen in this scenario i'm working with (MVC 3 Web Application): 1. The HTTP request start and the MVC Controller starts. 2. In the controller we start a long running background thread (in my case a lot of work in the database) 3. The MVC controller completes and after that the view is rendered and send back to the client. 4. System.Threading.Thread.CurrentPrincipal is disposed by iis. 5. The long running background thread tries to log something and an System.ObjectDisposedException occurs in Core\LoggingEvent.cs:885 if (System.Threading.Thread.CurrentPrincipal != null && System.Threading.Thread.CurrentPrincipal.Identity != null && System.Threading.Thread.CurrentPrincipal.Identity.Name != null) The third part will fail because the getter of .Name will throw an exception. The simplest workaround is to set new CurrentPrincipal if you start a new background thread. E.g.: System.Threading.Thread asyncWorker = new System.Threading.Thread( LongRunningTasks ); asyncWorker.Start( System.Security.Principal.WindowsIdentity.GetCurrent() ); private void LongRunningTasks( object identity ) { System.Security.Principal.WindowsIdentity windowsIdentity = identity as System.Security.Principal.WindowsIdentity; System.Security.Principal.WindowsImpersonationContext impersonationContext = null; if ( windowsIdentity != null ) { System.Threading.Thread.CurrentPrincipal = new System.Security.Principal.WindowsPrincipal( windowsIdentity ); impersonationContext = windowsIdentity.Impersonate(); } // Do your work. if ( impersonationContext != null ) impersonationContext.Undo(); } I'm not sure how this should be fixed in the source. But the simplest way would be to catch the System.ObjectDisposedException in the getter of LoggingEvent.Identity in file Core\LoggingEvent.cs and set m_data.Identity = "" like if System.Threading.Thread.CurrentPrincipal would be null. I think this would be the correct way because iis tries to dispose the CurrentPrincipal but stops before the work is done.
          Hide
          Ron Grabowski added a comment -

          Catching ObjectDisposedException in this case seems ok with me.

          Show
          Ron Grabowski added a comment - Catching ObjectDisposedException in this case seems ok with me.
          Hide
          Johannes Krackowizer added a comment -

          This is my patched src/Core/LoggingEvent.cs which resolves the problem.

          Show
          Johannes Krackowizer added a comment - This is my patched src/Core/LoggingEvent.cs which resolves the problem.
          Hide
          Dominik Psenner added a comment -

          Fixed as of revision: 1489889

          Show
          Dominik Psenner added a comment - Fixed as of revision: 1489889

            People

            • Assignee:
              Dominik Psenner
              Reporter:
              Kaider
            • Votes:
              1 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Time Tracking

                Estimated:
                Original Estimate - 4h
                4h
                Remaining:
                Remaining Estimate - 4h
                4h
                Logged:
                Time Spent - Not Specified
                Not Specified

                  Development