You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4net-user@logging.apache.org by Jim Scott <js...@infoconex.com> on 2017/05/19 22:45:50 UTC
IIS Deadlocks happening all the sudden after years of running with no issues
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 " />
<param name="Footer" value="Ending Program " />
<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 " />
<param name="Footer" value="Ending Program " />
<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 " />
</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>
Re: IIS Deadlocks happening all the sudden after years of running
with no issues
Posted by Dominik Psenner <dp...@gmail.com>.
2017-05-22 23:54 GMT+02:00 Jim Scott <js...@infoconex.com>:
>
>
> *From:* Dominik Psenner
> *Sent:* Monday, May 22, 2017 1:27 PM
>
>
>
>> >> Please note that it is known that an application can also cause
>> log4net to deadlock [3].
>> >> [3] https://issues.apache.org/jira/browse/LOG4NET-298
>>
>> 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
<http://logging.apache.org/log4net/log4net-1.2.12/release/sdk/log4net.Appender.FileAppender.ExclusiveLock.html>,
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
Re: IIS Deadlocks happening all the sudden after years of running with no issues
Posted by Jim Scott <js...@infoconex.com>.
From: Dominik Psenner
Sent: Monday, May 22, 2017 1:27 PM
>> Please note that it is known that an application can also cause log4net to deadlock [3].
>> [3] https://issues.apache.org/jira/browse/LOG4NET-298
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>
Re: IIS Deadlocks happening all the sudden after years of running
with no issues
Posted by Dominik Psenner <dp...@gmail.com>.
2017-05-22 18:38 GMT+02:00 Jim Scott <js...@infoconex.com>:
>
> >> 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].
> >> [3] https://issues.apache.org/jira/browse/LOG4NET-298
>
> 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].
> >> [4] https://issues.apache.org/jira/browse/LOG4NET-178
>
> 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
Re: IIS Deadlocks happening all the sudden after years of running with no issues
Posted by Jim Scott <js...@infoconex.com>.
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.
>> [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
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].
>> [3] https://issues.apache.org/jira/browse/LOG4NET-298
This particular application is not using any async/task code so not sure if other scenarios apply?
>> Further there is also this issue [4].
>> [4] https://issues.apache.org/jira/browse/LOG4NET-178
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?
Re: IIS Deadlocks happening all the sudden after years of running
with no issues
Posted by Dominik Psenner <dp...@gmail.com>.
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 <jscott@infoconex.com
> <ma...@infoconex.com>> 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 " />
>> <param name="Footer" value="Ending Program " />
>> <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 " />
>> <param name="Footer" value="Ending Program " />
>> <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 "
>> />
>> </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>
>>
Re: IIS Deadlocks happening all the sudden after years of running with no issues
Posted by Jim Scott <js...@infoconex.com>.
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 <js...@infoconex.com> 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 " />
> <param name="Footer" value="Ending Program " />
> <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 " />
> <param name="Footer" value="Ending Program " />
> <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 " />
> </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>