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

          Transition Time In Source Status Execution Times Last Executer Last Execution Date
          Open Open Resolved Resolved
          1022d 2h 7m 1 Dominik Psenner 05/Jun/13 15:42
          Stefan Bodewig made changes -
          Link This issue is duplicated by LOG4NET-363 [ LOG4NET-363 ]
          Dominik Psenner made changes -
          Status Open [ 1 ] Resolved [ 5 ]
          Fix Version/s 1.2.12 [ 12318546 ]
          Fix Version/s 1.2 Maintenance Release [ 12317606 ]
          Resolution Fixed [ 1 ]
          Hide
          Dominik Psenner added a comment -

          Fixed as of revision: 1489889

          Show
          Dominik Psenner added a comment - Fixed as of revision: 1489889
          Dominik Psenner made changes -
          Assignee Dominik Psenner [ nachbarslumpi ]
          Johannes Krackowizer made changes -
          Attachment LoggingEvent.cs [ 12522224 ]
          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
          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 -

          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.
          Stefan Bodewig made changes -
          Fix Version/s 1.2 Maintenance Release [ 12317606 ]
          Kaider made changes -
          Field Original Value New Value
          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)
          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>

          Kaider created issue -

            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