IIS Deadlocks happening all the sudden after years of running with no issues

classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

IIS Deadlocks happening all the sudden after years of running with no issues

Jim Scott-8
We have a webservice that has been running on Windows 2008R2 since Nov 2015 and has not had any issues until just a week or so ago. The webservice becomes unresponsive and after installing some debug tools I can see that we have a deadlock issue.
 
Here is some details of the last dump. Note we are running the project under .NET 4 and have .NET 2 dependencies in the project that depend on the .NET 2 1.2.11.0 version of log4net. I can see also on the stack trace that we had a few exceptions happen and I assume the blocking thread was attempting to roll our Exceptions.log file because the create time on the file was from yesterday. At the bottom of the email is a copy of our logging configuration which we wire up during Application_Start.
 
We thought it might have originally been related to permissions as someone had deleted the exception.log and recreated it and it was owned by them but we fixed that last night and we had another crash this morning. I am stumped since no code has changed on this box and nothing unusual about the type of activity. Maybe something in a .NET patch changed behavior?
 
Any assistance would be appreciated.
 
Thanks
Jim
 
Thread that appears to be blocking everything
 
Entry point   clr!Thread::intermediateThreadProc
Create time   5/19/2017 1:05:32 PM
Time spent in user mode   0 Days 00:10:06.359
Time spent in kernel mode   0 Days 00:02:51.203


This thread is trying to acquire a System.Threading.ReaderWriterLock for reading

The thread has evidence of .net exceptions on the stack. Check the Previous .NET Exceptions Report (Exceptions in all .NET Thread Stacks) to view more details of the associated exception


.NET Call Stack

[[HelperMethodFrame_1OBJ] (System.Array.Copy)] System.Array.Copy(System.Array, Int32, System.Array, Int32, Int32, Boolean)
mscorlib_ni!System.Array.Copy(System.Array, System.Array, Int32)+3e
mscorlib_ni!System.Security.Permissions.FileIOPermission.AddPathList(System.Security.Permissions.FileIOPermissionAccess, System.Security.AccessControl.AccessControlActions, System.String[], Boolean, Boolean, Boolean)+5a
mscorlib_ni!System.Security.Permissions.FileIOPermission..ctor(System.Security.Permissions.FileIOPermissionAccess, System.String[], Boolean, Boolean)+2a
mscorlib_ni!System.IO.Path.GetFullPath(System.String)+5c
mscorlib_ni!System.IO.Path.GetDirectoryName(System.String)+a2
log4net.Appender.RollingFileAppender.CombinePath(System.String, System.String)+38
log4net.Appender.RollingFileAppender.RollOverTime(Boolean)+16c
log4net.Appender.RollingFileAppender.AdjustFileBeforeAppend()+d3
log4net.Appender.RollingFileAppender.Append(log4net.Core.LoggingEvent)+13
log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)+f0
log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent)+a0
log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent)+82
log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type, log4net.Core.Level, System.Object, System.Exception)+4a
log4net.Repository.Hierarchy.Logger.Log(System.Type, log4net.Core.Level, System.Object, System.Exception)+64
log4net.Core.LogImpl.ErrorFormat(System.String, System.Object[])+6a
 

Example thread blocked
 

Thread 36 - System ID 7332

Entry point   clr!Thread::intermediateThreadProc
Create time   5/19/2017 1:07:12 PM
Time spent in user mode   0 Days 00:00:00.421
Time spent in kernel mode   0 Days 00:00:00.109


This thread is waiting to enter a .NET Lock

The thread has evidence of .net exceptions on the stack. Check the Previous .NET Exceptions Report (Exceptions in all .NET Thread Stacks) to view more details of the associated exception


.NET Call Stack

[[GCFrame]]
[[HelperMethodFrame_1OBJ] (System.Threading.Monitor.Enter)] System.Threading.Monitor.Enter(System.Object)
log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)+2b
log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent)+a0
log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent)+82
log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type, log4net.Core.Level, System.Object, System.Exception)+4a
log4net.Repository.Hierarchy.Logger.Log(System.Type, log4net.Core.Level, System.Object, System.Exception)+64
log4net.Core.LogImpl.InfoFormat(System.String, System.Object[])+6a
 
 
Configuration file
 
<?xml version="1.0" encoding="utf-8" ?>
<log4net>
    <appender name="WebsiteLogger" type="log4net.Appender.RollingFileAppender">
        <param name="File" value="C:\logs\WebLogging.log" />
       <param name="AppendToFile" value="true" />
        <param name="RollingStyle" value="Composite" />
        <param name="MaximumFileSize" value="10MB" />
        <param name="CountDirection" value="0" />
        <param name="StaticLogFileName" value="true" />
        <param name="PreserveLogFileNameExtension" value="true" />
        <param name="DatePattern" value=".yyyy-MM-dd" />
        <param name="MaxSizeRollBackups" value="40" />
        <layout type="log4net.Layout.PatternLayout">
            <param name="Header" value="Date    Time    Level    ThreadId    Class    RemoteIP    SessionId    Message&#13;&#10;" />
            <param name="Footer" value="Ending Program&#13;&#10;" />
            <param name="ConversionPattern" value="%d %-5p %-30logger{1} %-17property{ip} %-12property{sid}  %m%n%exception" />
        </layout>
    </appender>
    <appender name="ExceptionLogger" type="log4net.Appender.RollingFileAppender">
        <param name="File" value="C:\logs\Exceptions.log" />
        <param name="AppendToFile" value="true" />
        <param name="RollingStyle" value="Composite" />
        <param name="MaximumFileSize" value="10MB" />
        <param name="CountDirection" value="0" />
        <param name="StaticLogFileName" value="true" />
        <param name="PreserveLogFileNameExtension" value="true" />
        <param name="DatePattern" value=".yyyy-MM-dd" />
        <param name="MaxSizeRollBackups" value="40" />
        <!--        <lockingModel type="log4net.Appender.FileAppender+MinimalLock" /> -->
        <layout type="log4net.Layout.PatternLayout">
            <param name="Header" value="Date    Time    Level    ThreadId    Class    RemoteIP    SessionId    Message&#13;&#10;" />
            <param name="Footer" value="Ending Program&#13;&#10;" />
            <param name="ConversionPattern" value="%d %-5p %-30c %-17property{ip} %-12property{sid}  %m%n%exception" />
        </layout>
        <filter type="log4net.Filter.LevelRangeFilter">
            <param name="LevelMin" value="Error" />
        </filter>
    </appender>
    <appender name="UsageWriter" type="log4net.Appender.RollingFileAppender">
        <param name="File" value="C:\logs\Usage.csv" />
        <param name="AppendToFile" value="true" />
        <param name="RollingStyle" value="Composite" />
        <param name="MaximumFileSize" value="10MB" />
        <param name="CountDirection" value="0" />
        <param name="StaticLogFileName" value="true" />
        <param name="PreserveLogFileNameExtension" value="true" />
        <param name="DatePattern" value=".yyyy-MM-dd" />
        <param name="MaxSizeRollBackups" value="40" />
        <layout type="log4net.Layout.PatternLayout">
            <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.fff},%property{ip},%property{sid},%m%n" />
            <param name="Header" value="Date,IPAddress,SessionId,Username,MethodName,ExecutionTime,Extra&#13;&#10;" />
        </layout>
        <filter type="log4net.Filter.LoggerMatchFilter">
            <param name="LoggerToMatch" value="AccountManagementWebservice.UsageWriter" />
            <param name="AcceptOnMatch" value="true" />
        </filter>
        <filter type="log4net.Filter.DenyAllFilter" />
    </appender>
    <appender name="AdoNetAppender" type="log4net.Appender.AdoNetAppender">
        <bufferSize value="1" />
        <useTransactions value="false" />
        <connectionType value="System.Data.SqlClient.SqlConnection, System.Data, Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
        <connectionString value="data source=server;initial catalog=db;Enlist=false;User ID=user;Password=password" />
        <commandText value="INSERT INTO Log4Net ([Date],[Host],[Application],[Thread],[Level],[Logger],[Message]) VALUES (@log_date, @host, @application, @thread, @log_level, @logger, @message)" />
        <parameter>
            <parameterName value="@log_date" />
            <dbType value="DateTime" />
            <layout type="log4net.Layout.RawTimeStampLayout" />
        </parameter>
        <parameter>
            <parameterName value="@host" />
            <dbType value="String" />
            <size value="255" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%property{host}" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@application" />
            <dbType value="String" />
            <size value="255" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%property{application}" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@thread" />
            <dbType value="String" />
            <size value="255" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%thread" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@log_level" />
            <dbType value="String" />
            <size value="50" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%level" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@logger" />
            <dbType value="String" />
            <size value="255" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%logger" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@message" />
            <dbType value="String" />
            <size value="4000" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%message" />
            </layout>
        </parameter>
        <filter type="log4net.Filter.LevelRangeFilter">
            <param name="LevelMin" value="Error" />
        </filter>
    </appender>
    <root>
        <level value="DEBUG" />
        <appender-ref ref="WebsiteLogger" />
        <appender-ref ref="ExceptionLogger" />
        <appender-ref ref="AdoNetAppender" />
        <appender-ref ref="UsageWriter" />
    </root>
</log4net>
Reply | Threaded
Open this post in threaded view
|

Re: IIS Deadlocks happening all the sudden after years of running with no issues

Jim Scott-8
Is this list still active? Would this be better to post to the dev list?

On May 19, 2017, at 3:45 PM, Jim Scott <[hidden email]> wrote:

We have a webservice that has been running on Windows 2008R2 since Nov 2015 and has not had any issues until just a week or so ago. The webservice becomes unresponsive and after installing some debug tools I can see that we have a deadlock issue.
 
Here is some details of the last dump. Note we are running the project under .NET 4 and have .NET 2 dependencies in the project that depend on the .NET 2 1.2.11.0 version of log4net. I can see also on the stack trace that we had a few exceptions happen and I assume the blocking thread was attempting to roll our Exceptions.log file because the create time on the file was from yesterday. At the bottom of the email is a copy of our logging configuration which we wire up during Application_Start.
 
We thought it might have originally been related to permissions as someone had deleted the exception.log and recreated it and it was owned by them but we fixed that last night and we had another crash this morning. I am stumped since no code has changed on this box and nothing unusual about the type of activity. Maybe something in a .NET patch changed behavior?
 
Any assistance would be appreciated.
 
Thanks
Jim
 
Thread that appears to be blocking everything
 
Entry point   clr!Thread::intermediateThreadProc
Create time   5/19/2017 1:05:32 PM
Time spent in user mode   0 Days 00:10:06.359
Time spent in kernel mode   0 Days 00:02:51.203


This thread is trying to acquire a System.Threading.ReaderWriterLock for reading

The thread has evidence of .net exceptions on the stack. Check the Previous .NET Exceptions Report (Exceptions in all .NET Thread Stacks) to view more details of the associated exception


.NET Call Stack

[[HelperMethodFrame_1OBJ] (System.Array.Copy)] System.Array.Copy(System.Array, Int32, System.Array, Int32, Int32, Boolean)
mscorlib_ni!System.Array.Copy(System.Array, System.Array, Int32)+3e
mscorlib_ni!System.Security.Permissions.FileIOPermission.AddPathList(System.Security.Permissions.FileIOPermissionAccess, System.Security.AccessControl.AccessControlActions, System.String[], Boolean, Boolean, Boolean)+5a
mscorlib_ni!System.Security.Permissions.FileIOPermission..ctor(System.Security.Permissions.FileIOPermissionAccess, System.String[], Boolean, Boolean)+2a
mscorlib_ni!System.IO.Path.GetFullPath(System.String)+5c
mscorlib_ni!System.IO.Path.GetDirectoryName(System.String)+a2
log4net.Appender.RollingFileAppender.CombinePath(System.String, System.String)+38
log4net.Appender.RollingFileAppender.RollOverTime(Boolean)+16c
log4net.Appender.RollingFileAppender.AdjustFileBeforeAppend()+d3
log4net.Appender.RollingFileAppender.Append(log4net.Core.LoggingEvent)+13
log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)+f0
log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent)+a0
log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent)+82
log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type, log4net.Core.Level, System.Object, System.Exception)+4a
log4net.Repository.Hierarchy.Logger.Log(System.Type, log4net.Core.Level, System.Object, System.Exception)+64
log4net.Core.LogImpl.ErrorFormat(System.String, System.Object[])+6a
 

Example thread blocked
 

Thread 36 - System ID 7332

Entry point   clr!Thread::intermediateThreadProc
Create time   5/19/2017 1:07:12 PM
Time spent in user mode   0 Days 00:00:00.421
Time spent in kernel mode   0 Days 00:00:00.109


This thread is waiting to enter a .NET Lock

The thread has evidence of .net exceptions on the stack. Check the Previous .NET Exceptions Report (Exceptions in all .NET Thread Stacks) to view more details of the associated exception


.NET Call Stack

[[GCFrame]]
[[HelperMethodFrame_1OBJ] (System.Threading.Monitor.Enter)] System.Threading.Monitor.Enter(System.Object)
log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)+2b
log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent)+a0
log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent)+82
log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type, log4net.Core.Level, System.Object, System.Exception)+4a
log4net.Repository.Hierarchy.Logger.Log(System.Type, log4net.Core.Level, System.Object, System.Exception)+64
log4net.Core.LogImpl.InfoFormat(System.String, System.Object[])+6a
 
 
Configuration file
 
<?xml version="1.0" encoding="utf-8" ?>
<log4net>
    <appender name="WebsiteLogger" type="log4net.Appender.RollingFileAppender">
        <param name="File" value="C:\logs\WebLogging.log" />
       <param name="AppendToFile" value="true" />
        <param name="RollingStyle" value="Composite" />
        <param name="MaximumFileSize" value="10MB" />
        <param name="CountDirection" value="0" />
        <param name="StaticLogFileName" value="true" />
        <param name="PreserveLogFileNameExtension" value="true" />
        <param name="DatePattern" value=".yyyy-MM-dd" />
        <param name="MaxSizeRollBackups" value="40" />
        <layout type="log4net.Layout.PatternLayout">
            <param name="Header" value="Date    Time    Level    ThreadId    Class    RemoteIP    SessionId    Message&#13;&#10;" />
            <param name="Footer" value="Ending Program&#13;&#10;" />
            <param name="ConversionPattern" value="%d %-5p %-30logger{1} %-17property{ip} %-12property{sid}  %m%n%exception" />
        </layout>
    </appender>
    <appender name="ExceptionLogger" type="log4net.Appender.RollingFileAppender">
        <param name="File" value="C:\logs\Exceptions.log" />
        <param name="AppendToFile" value="true" />
        <param name="RollingStyle" value="Composite" />
        <param name="MaximumFileSize" value="10MB" />
        <param name="CountDirection" value="0" />
        <param name="StaticLogFileName" value="true" />
        <param name="PreserveLogFileNameExtension" value="true" />
        <param name="DatePattern" value=".yyyy-MM-dd" />
        <param name="MaxSizeRollBackups" value="40" />
        <!--        <lockingModel type="log4net.Appender.FileAppender+MinimalLock" /> -->
        <layout type="log4net.Layout.PatternLayout">
            <param name="Header" value="Date    Time    Level    ThreadId    Class    RemoteIP    SessionId    Message&#13;&#10;" />
            <param name="Footer" value="Ending Program&#13;&#10;" />
            <param name="ConversionPattern" value="%d %-5p %-30c %-17property{ip} %-12property{sid}  %m%n%exception" />
        </layout>
        <filter type="log4net.Filter.LevelRangeFilter">
            <param name="LevelMin" value="Error" />
        </filter>
    </appender>
    <appender name="UsageWriter" type="log4net.Appender.RollingFileAppender">
        <param name="File" value="C:\logs\Usage.csv" />
        <param name="AppendToFile" value="true" />
        <param name="RollingStyle" value="Composite" />
        <param name="MaximumFileSize" value="10MB" />
        <param name="CountDirection" value="0" />
        <param name="StaticLogFileName" value="true" />
        <param name="PreserveLogFileNameExtension" value="true" />
        <param name="DatePattern" value=".yyyy-MM-dd" />
        <param name="MaxSizeRollBackups" value="40" />
        <layout type="log4net.Layout.PatternLayout">
            <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.fff},%property{ip},%property{sid},%m%n" />
            <param name="Header" value="Date,IPAddress,SessionId,Username,MethodName,ExecutionTime,Extra&#13;&#10;" />
        </layout>
        <filter type="log4net.Filter.LoggerMatchFilter">
            <param name="LoggerToMatch" value="AccountManagementWebservice.UsageWriter" />
            <param name="AcceptOnMatch" value="true" />
        </filter>
        <filter type="log4net.Filter.DenyAllFilter" />
    </appender>
    <appender name="AdoNetAppender" type="log4net.Appender.AdoNetAppender">
        <bufferSize value="1" />
        <useTransactions value="false" />
        <connectionType value="System.Data.SqlClient.SqlConnection, System.Data, Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
        <connectionString value="data source=server;initial catalog=db;Enlist=false;User ID=user;Password=password" />
        <commandText value="INSERT INTO Log4Net ([Date],[Host],[Application],[Thread],[Level],[Logger],[Message]) VALUES (@log_date, @host, @application, @thread, @log_level, @logger, @message)" />
        <parameter>
            <parameterName value="@log_date" />
            <dbType value="DateTime" />
            <layout type="log4net.Layout.RawTimeStampLayout" />
        </parameter>
        <parameter>
            <parameterName value="@host" />
            <dbType value="String" />
            <size value="255" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%property{host}" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@application" />
            <dbType value="String" />
            <size value="255" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%property{application}" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@thread" />
            <dbType value="String" />
            <size value="255" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%thread" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@log_level" />
            <dbType value="String" />
            <size value="50" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%level" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@logger" />
            <dbType value="String" />
            <size value="255" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%logger" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@message" />
            <dbType value="String" />
            <size value="4000" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%message" />
            </layout>
        </parameter>
        <filter type="log4net.Filter.LevelRangeFilter">
            <param name="LevelMin" value="Error" />
        </filter>
    </appender>
    <root>
        <level value="DEBUG" />
        <appender-ref ref="WebsiteLogger" />
        <appender-ref ref="ExceptionLogger" />
        <appender-ref ref="AdoNetAppender" />
        <appender-ref ref="UsageWriter" />
    </root>
</log4net>
Reply | Threaded
Open this post in threaded view
|

Re: IIS Deadlocks happening all the sudden after years of running with no issues

Dominik Psenner

Hi Jim,

please don't expect a sensible response within hours, especially with such a complex problem. :-) At first sight, if it did run for over two years and suddenly keeps crashing on a daily basis it is very unlikely that something that was not modified is the actual culprit. Did any modifications happen lately that you are aware of?

Please note that IIS has some interesting default behavior, it would for instance start a new instance of a site before the old site is destroyed. This means that multiple instances of the same site use the same configuration and are therefore going to log and roll into the same files. This is well known [1] [2] and has been raised as an issue several times on this list. The symptoms you see sound very much like that, but note that this is just a guess. Please note that it is known that an application can also cause log4net to deadlock [3]. Further there is also this issue [4].

I hope this gives you enough information to dig deeper. Let us know what the actual root cause was and how you solved it. We may be able to condense documentation that helps future readers.

Cheers,
Dominik

[1] https://www.google.it/search?q=log4net+iis+deadlock&oq=log4net+iis+deadlock
[2] http://hectorcorrea.com/blog/log4net-thread-safe-but-not-process-safe/17
[3] https://issues.apache.org/jira/browse/LOG4NET-298
[4] https://issues.apache.org/jira/browse/LOG4NET-178

On 2017-05-20 21:26, Jim Scott wrote:
Is this list still active? Would this be better to post to the dev list?

On May 19, 2017, at 3:45 PM, Jim Scott <[hidden email]> wrote:

We have a webservice that has been running on Windows 2008R2 since Nov 2015 and has not had any issues until just a week or so ago. The webservice becomes unresponsive and after installing some debug tools I can see that we have a deadlock issue.
 
Here is some details of the last dump. Note we are running the project under .NET 4 and have .NET 2 dependencies in the project that depend on the .NET 2 1.2.11.0 version of log4net. I can see also on the stack trace that we had a few exceptions happen and I assume the blocking thread was attempting to roll our Exceptions.log file because the create time on the file was from yesterday. At the bottom of the email is a copy of our logging configuration which we wire up during Application_Start.
 
We thought it might have originally been related to permissions as someone had deleted the exception.log and recreated it and it was owned by them but we fixed that last night and we had another crash this morning. I am stumped since no code has changed on this box and nothing unusual about the type of activity. Maybe something in a .NET patch changed behavior?
 
Any assistance would be appreciated.
 
Thanks
Jim
 
Thread that appears to be blocking everything
 
Entry point   clr!Thread::intermediateThreadProc
Create time   5/19/2017 1:05:32 PM
Time spent in user mode   0 Days 00:10:06.359
Time spent in kernel mode   0 Days 00:02:51.203


This thread is trying to acquire a System.Threading.ReaderWriterLock for reading

The thread has evidence of .net exceptions on the stack. Check the Previous .NET Exceptions Report (Exceptions in all .NET Thread Stacks) to view more details of the associated exception


.NET Call Stack


[[HelperMethodFrame_1OBJ] (System.Array.Copy)] System.Array.Copy(System.Array, Int32, System.Array, Int32, Int32, Boolean)
mscorlib_ni!System.Array.Copy(System.Array, System.Array, Int32)+3e
mscorlib_ni!System.Security.Permissions.FileIOPermission.AddPathList(System.Security.Permissions.FileIOPermissionAccess, System.Security.AccessControl.AccessControlActions, System.String[], Boolean, Boolean, Boolean)+5a
mscorlib_ni!System.Security.Permissions.FileIOPermission..ctor(System.Security.Permissions.FileIOPermissionAccess, System.String[], Boolean, Boolean)+2a
mscorlib_ni!System.IO.Path.GetFullPath(System.String)+5c
mscorlib_ni!System.IO.Path.GetDirectoryName(System.String)+a2
log4net.Appender.RollingFileAppender.CombinePath(System.String, System.String)+38
log4net.Appender.RollingFileAppender.RollOverTime(Boolean)+16c
log4net.Appender.RollingFileAppender.AdjustFileBeforeAppend()+d3
log4net.Appender.RollingFileAppender.Append(log4net.Core.LoggingEvent)+13
log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)+f0
log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent)+a0
log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent)+82
log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type, log4net.Core.Level, System.Object, System.Exception)+4a
log4net.Repository.Hierarchy.Logger.Log(System.Type, log4net.Core.Level, System.Object, System.Exception)+64
log4net.Core.LogImpl.ErrorFormat(System.String, System.Object[])+6a
 

Example thread blocked
 

Thread 36 - System ID 7332

Entry point   clr!Thread::intermediateThreadProc
Create time   5/19/2017 1:07:12 PM
Time spent in user mode   0 Days 00:00:00.421
Time spent in kernel mode   0 Days 00:00:00.109


This thread is waiting to enter a .NET Lock

The thread has evidence of .net exceptions on the stack. Check the Previous .NET Exceptions Report (Exceptions in all .NET Thread Stacks) to view more details of the associated exception


.NET Call Stack


[[GCFrame]]
[[HelperMethodFrame_1OBJ] (System.Threading.Monitor.Enter)] System.Threading.Monitor.Enter(System.Object)
log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)+2b
log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent)+a0
log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent)+82
log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type, log4net.Core.Level, System.Object, System.Exception)+4a
log4net.Repository.Hierarchy.Logger.Log(System.Type, log4net.Core.Level, System.Object, System.Exception)+64
log4net.Core.LogImpl.InfoFormat(System.String, System.Object[])+6a
 
 
Configuration file
 
<?xml version="1.0" encoding="utf-8" ?>
<log4net>
    <appender name="WebsiteLogger" type="log4net.Appender.RollingFileAppender">
        <param name="File" value="C:\logs\WebLogging.log" />
       <param name="AppendToFile" value="true" />
        <param name="RollingStyle" value="Composite" />
        <param name="MaximumFileSize" value="10MB" />
        <param name="CountDirection" value="0" />
        <param name="StaticLogFileName" value="true" />
        <param name="PreserveLogFileNameExtension" value="true" />
        <param name="DatePattern" value=".yyyy-MM-dd" />
        <param name="MaxSizeRollBackups" value="40" />
        <layout type="log4net.Layout.PatternLayout">
            <param name="Header" value="Date    Time    Level    ThreadId    Class    RemoteIP    SessionId    Message&#13;&#10;" />
            <param name="Footer" value="Ending Program&#13;&#10;" />
            <param name="ConversionPattern" value="%d %-5p %-30logger{1} %-17property{ip} %-12property{sid}  %m%n%exception" />
        </layout>
    </appender>
    <appender name="ExceptionLogger" type="log4net.Appender.RollingFileAppender">
        <param name="File" value="C:\logs\Exceptions.log" />
        <param name="AppendToFile" value="true" />
        <param name="RollingStyle" value="Composite" />
        <param name="MaximumFileSize" value="10MB" />
        <param name="CountDirection" value="0" />
        <param name="StaticLogFileName" value="true" />
        <param name="PreserveLogFileNameExtension" value="true" />
        <param name="DatePattern" value=".yyyy-MM-dd" />
        <param name="MaxSizeRollBackups" value="40" />
        <!--        <lockingModel type="log4net.Appender.FileAppender+MinimalLock" /> -->
        <layout type="log4net.Layout.PatternLayout">
            <param name="Header" value="Date    Time    Level    ThreadId    Class    RemoteIP    SessionId    Message&#13;&#10;" />
            <param name="Footer" value="Ending Program&#13;&#10;" />
            <param name="ConversionPattern" value="%d %-5p %-30c %-17property{ip} %-12property{sid}  %m%n%exception" />
        </layout>
        <filter type="log4net.Filter.LevelRangeFilter">
            <param name="LevelMin" value="Error" />
        </filter>
    </appender>
    <appender name="UsageWriter" type="log4net.Appender.RollingFileAppender">
        <param name="File" value="C:\logs\Usage.csv" />
        <param name="AppendToFile" value="true" />
        <param name="RollingStyle" value="Composite" />
        <param name="MaximumFileSize" value="10MB" />
        <param name="CountDirection" value="0" />
        <param name="StaticLogFileName" value="true" />
        <param name="PreserveLogFileNameExtension" value="true" />
        <param name="DatePattern" value=".yyyy-MM-dd" />
        <param name="MaxSizeRollBackups" value="40" />
        <layout type="log4net.Layout.PatternLayout">
            <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.fff},%property{ip},%property{sid},%m%n" />
            <param name="Header" value="Date,IPAddress,SessionId,Username,MethodName,ExecutionTime,Extra&#13;&#10;" />
        </layout>
        <filter type="log4net.Filter.LoggerMatchFilter">
            <param name="LoggerToMatch" value="AccountManagementWebservice.UsageWriter" />
            <param name="AcceptOnMatch" value="true" />
        </filter>
        <filter type="log4net.Filter.DenyAllFilter" />
    </appender>
    <appender name="AdoNetAppender" type="log4net.Appender.AdoNetAppender">
        <bufferSize value="1" />
        <useTransactions value="false" />
        <connectionType value="System.Data.SqlClient.SqlConnection, System.Data, Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
        <connectionString value="data source=server;initial catalog=db;Enlist=false;User ID=user;Password=password" />
        <commandText value="INSERT INTO Log4Net ([Date],[Host],[Application],[Thread],[Level],[Logger],[Message]) VALUES (@log_date, @host, @application, @thread, @log_level, @logger, @message)" />
        <parameter>
            <parameterName value="@log_date" />
            <dbType value="DateTime" />
            <layout type="log4net.Layout.RawTimeStampLayout" />
        </parameter>
        <parameter>
            <parameterName value="@host" />
            <dbType value="String" />
            <size value="255" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%property{host}" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@application" />
            <dbType value="String" />
            <size value="255" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%property{application}" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@thread" />
            <dbType value="String" />
            <size value="255" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%thread" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@log_level" />
            <dbType value="String" />
            <size value="50" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%level" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@logger" />
            <dbType value="String" />
            <size value="255" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%logger" />
            </layout>
        </parameter>
        <parameter>
            <parameterName value="@message" />
            <dbType value="String" />
            <size value="4000" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%message" />
            </layout>
        </parameter>
        <filter type="log4net.Filter.LevelRangeFilter">
            <param name="LevelMin" value="Error" />
        </filter>
    </appender>
    <root>
        <level value="DEBUG" />
        <appender-ref ref="WebsiteLogger" />
        <appender-ref ref="ExceptionLogger" />
        <appender-ref ref="AdoNetAppender" />
        <appender-ref ref="UsageWriter" />
    </root>
</log4net>

Reply | Threaded
Open this post in threaded view
|

Re: IIS Deadlocks happening all the sudden after years of running with no issues

Jim Scott-8
 
Dominik,
 
Thank you for your reply.
 
>> please don't expect a sensible response within hours, especially with such a complex problem.
 
No problem, I looked at the archive and noticed I was the only post this month so was thinking that maybe a newer list existed.
 
>> :-) At first sight, if it did run for over two years and suddenly keeps crashing on a daily basis it is
>> very unlikely that something that was not modified is the actual culprit.
 
I agree, nothing in the application has changed as I can see all of the dates of the files are from the last deployment in Nov 2015.
 
>> Did any modifications happen lately that you are aware of?
 
The only thing I can see is that the box has been getting regular windows updates which of course includes .NET and OS updates. Could it be that something in the framework has changed behavior of something that is now creating this issue?
 
>> Please note that IIS has some interesting default behavior, it would for instance start a new instance of a site before the old site is destroyed.
>> This means that multiple instances of the same site use the same configuration and are therefore going to log and roll into the same files.
>> This is well known [1][2] and has been raised as an issue several times on this list.
>> The symptoms you see sound very much like that, but note that this is just a guess.
 
Yes, I read that article [2] I had our operations group modify IIS set “Disable Overlapped Recycle” to true. We are also only running 1 worker process so nothing in our install applies to the web garden scenario. Note that I figured this might be the culprit but we have had the same deadlock happen after this change.
 
>> Please note that it is known that an application can also cause log4net to deadlock [3].
 
This particular application is not using any async/task code so not sure if other scenarios apply?
 
>> Further there is also this issue [4].
 
We are not seeing an issue with logging stopping and we also changed our app pool recycle to a specific time rather than the default of 1720 minutes. When we have had our deadlock issue it has not been during an app pool recycle (unless IIS was trying to kick the process for other reasons, although nothing in event viewer indicating something was trying to recycle). Anything in this particular bug that you think I might want to look at that still might be related even though the symptom is not the same?
 
 
We have also installed Debug Diagnostics on the machine to take memory dumps and analyze the results and this made it really easy to determine the deadlock issue and provide the traces previously. If you have any suggestions for further diagnosing it would be appreciated. Was thinking that maybe I would have enabled log4net debugging?
Reply | Threaded
Open this post in threaded view
|

Re: IIS Deadlocks happening all the sudden after years of running with no issues

Dominik Psenner


2017-05-22 18:38 GMT+02:00 Jim Scott <[hidden email]>:
>> Did any modifications happen lately that you are aware of?
 
The only thing I can see is that the box has been getting regular windows updates which of course includes .NET and OS updates. Could it be that something in the framework has changed behavior of something that is now creating this issue?

Not that I am aware of, but that means nothing.
 
 >> Please note that it is known that an application can also cause log4net to deadlock [3].
 
This particular application is not using any async/task code so not sure if other scenarios apply?

That's not true. All it needs is two threads and the well known dead lock candidates (waits, locks, ..). Does your web application pass objects on to the logging framework or are all arguments converted to immutable types (string, int, bool, ..)? If the logging framework calls ToString() of an object, beware!
 
>> Further there is also this issue [4].
 
We are not seeing an issue with logging stopping and we also changed our app pool recycle to a specific time rather than the default of 1720 minutes. When we have had our deadlock issue it has not been during an app pool recycle (unless IIS was trying to kick the process for other reasons, although nothing in event viewer indicating something was trying to recycle). Anything in this particular bug that you think I might want to look at that still might be related even though the symptom is not the same?

No idea but at the same time this is not the first thing I would spend time on.
 
 
 
We have also installed Debug Diagnostics on the machine to take memory dumps and analyze the results and this made it really easy to determine the deadlock issue and provide the traces previously. If you have any suggestions for further diagnosing it would be appreciated. Was thinking that maybe I would have enabled log4net debugging?

That's a great starting point. Maybe something fishy jumps out that makes it easier. You could further investigate the behavior of your web application when the dead lock happened.

Please note also that 1.2.11 is from 2011 and rather old. Can you give a newer log4net version a shot?

Cheers
--
Dominik Psenner
Reply | Threaded
Open this post in threaded view
|

Re: IIS Deadlocks happening all the sudden after years of running with no issues

Jim Scott-8
 
 
Sent: Monday, May 22, 2017 1:27 PM
 
 
 >> Please note that it is known that an application can also cause log4net to deadlock [3].
 
This particular application is not using any async/task code so not sure if other scenarios apply?
 
>> That's not true. All it needs is two threads and the well known dead lock candidates (waits, locks, ..). Does your web application pass objects on to the logging framework or are all >> arguments converted to immutable types (string, int, bool, ..)? If the logging framework calls ToString() of an object, beware!
 
I will have to do some investigating to see. However I know we log exceptions using log.Error(“Exception details”, ex) and it seems that every time this issue occurs it is happening while attempt to write an exception to the exception.log we have configured. Note that according to the stack trace it appears that the exceptions log is attempting to be rolled when the issue happens. I can also see now that our exceptions log is intermittently getting rolled whereas the other logs seem to be rolling as expected. One thing different about this logging configuration for exceptions is that we are using MinimalLock so that the file can be cleared.
 
 
 
We have also installed Debug Diagnostics on the machine to take memory dumps and analyze the results and this made it really easy to determine the deadlock issue and provide the traces previously. If you have any suggestions for further diagnosing it would be appreciated. Was thinking that maybe I would have enabled log4net debugging?
 
>> That's a great starting point. Maybe something fishy jumps out that makes it easier. You could further investigate the behavior of your web application when the dead lock happened.
 
What suggestions might you have with regards to investigating the behavior of the web application when the deadlock happened?
 
>> Please note also that 1.2.11 is from 2011 and rather old. Can you give a newer log4net version a shot?

That was my next move actually. We use 1.2.13.0 on a few other projects and since we have been using reliably in those applications was going to see if moving to it made any difference. This project has a number of dependencies that are all compiled again 1.2.11.0 so was going to use the following approach.
 
Update to 1.2.13.0
Add this to web.config to redirect to 1.2.13.0
<runtime>
        <assemblyBinding xmlns="urn:schemas-microsoft-com:asm.v1">     
          <dependentAssembly>
            <assemblyIdentity name="log4net" publicKeyToken="669e0ddf0bb1aa2a"/>
            <bindingRedirect oldVersion="0.0.0.0-1.2.13.0" newVersion="1.2.13.0"/>
          </dependentAssembly>     
        </assemblyBinding>
    </runtime>

Reply | Threaded
Open this post in threaded view
|

Re: IIS Deadlocks happening all the sudden after years of running with no issues

Dominik Psenner


2017-05-22 23:54 GMT+02:00 Jim Scott <[hidden email]>:
 
 
Sent: Monday, May 22, 2017 1:27 PM
 
 
 >> Please note that it is known that an application can also cause log4net to deadlock [3].
 
This particular application is not using any async/task code so not sure if other scenarios apply?
 
>> That's not true. All it needs is two threads and the well known dead lock candidates (waits, locks, ..). Does your web application pass objects on to the logging framework or are all >> arguments converted to immutable types (string, int, bool, ..)? If the logging framework calls ToString() of an object, beware!
 
I will have to do some investigating to see. However I know we log exceptions using log.Error(“Exception details”, ex) and it seems that every time this issue occurs it is happening while attempt to write an exception to the exception.log we have configured. Note that according to the stack trace it appears that the exceptions log is attempting to be rolled when the issue happens. I can also see now that our exceptions log is intermittently getting rolled whereas the other logs seem to be rolling as expected. One thing different about this logging configuration for exceptions is that we are using MinimalLock so that the file can be cleared.

Put this on the list of possible causes. I would rather always go with FileAppender.ExclusiveLock, also from a performance point of view. I observed a speedup factor that is often beyond 20.
 
 
 
 
We have also installed Debug Diagnostics on the machine to take memory dumps and analyze the results and this made it really easy to determine the deadlock issue and provide the traces previously. If you have any suggestions for further diagnosing it would be appreciated. Was thinking that maybe I would have enabled log4net debugging?
 
>> That's a great starting point. Maybe something fishy jumps out that makes it easier. You could further investigate the behavior of your web application when the dead lock happened.
 
What suggestions might you have with regards to investigating the behavior of the web application when the deadlock happened?

Looks like you already figured out something I was referring to. Often it is enough to know what the users did to track down what an application should do (and possibly should but does not). After all it boils down to a few scenarios and that helps a lot, just like you pointed out the MinimalLock for exceptions.
 
 
>> Please note also that 1.2.11 is from 2011 and rather old. Can you give a newer log4net version a shot?

That was my next move actually. We use 1.2.13.0 on a few other projects and since we have been using reliably in those applications was going to see if moving to it made any difference. This project has a number of dependencies that are all compiled again 1.2.11.0 so was going to use the following approach.
 
Update to 1.2.13.0
Add this to web.config to redirect to 1.2.13.0
<runtime>
        <assemblyBinding xmlns="urn:schemas-microsoft-com:asm.v1">     
          <dependentAssembly>
            <assemblyIdentity name="log4net" publicKeyToken="669e0ddf0bb1aa2a"/>
            <bindingRedirect oldVersion="0.0.0.0-1.2.13.0" newVersion="1.2.13.0"/>
          </dependentAssembly>     
        </assemblyBinding>
    </runtime>


I did not know this was even possible. :-) The api should still be the same, so there should be no obstacles unless one dependency uses the strong name assembly. Then it should (to my knowledge) accept only the one it was linked against.

--
Dominik Psenner