Re: IIS Deadlocks happening all the sudden after years of running with no issues
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
Re: IIS Deadlocks happening all the sudden after years of running with no issues
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=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
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 <jsc...@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.Strin
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
RE: Using Log4Net with Selenium
try
{
//test
}
catch(Exception ex)
{
log.Error(ex); // log your exception
throw; // allow exception to continue
}
-Original Message-
From: "superfreak3"
Sent: 1/6/2016 6:57 AM
To: "log4net-user@logging.apache.org"
Subject: Re: Using Log4Net with Selenium
I've found that sending exceptions to the log in the catch block will cause the
test to be seen as successful overall. How can I also set the test result for
Selenium in that block.
Â
pseudo code:Â Set MyTestResult = Failed. ??
On Tue, Jan 5, 2016 at 10:00 PM, mawa316 . <[hidden email]> wrote:
Here's the file I spoke of...
Â
Â
On Tue, Jan 5, 2016 at 9:01 PM, superfreak3 [via Apache Logging] <[hidden
email]> wrote:
I noticed something strange that has happened since adding logging with
log4Net. When exceptions occur, they are caught and written as desired to the
log. However, running via both mstest and Visual Studio 2015, despite the
fact exceptions occur, the tests are still seen as successful.
I verified it has something to do with the logging additions as I got the
previous version from TFS and I'm able to run the tests in Visual Studio where
the problematic tests do indicate failure.
I've attached a file that shows the steps I followed to get logging to work.Â
I'm not sure if the addition of an app.config file causes this to be handled
differently within the testing framework or handling in Visual Studio.
Any help would be greatly appreciated!!
Selenium_and_Log4Net_Logging.docx
If you reply to this email, your message will be added to the discussion below:
http://apache-logging.6191.n7.nabble.com/Using-Log4Net-with-Selenium-tp59639p60848.html
To unsubscribe from Using Log4Net with Selenium, click here.
NAML
View this message in context: Re: Using Log4Net with Selenium
Sent from the Log4net - Users mailing list archive at Nabble.com.
Re: Logger in ASP.NET stops after a few hours, won't restart until app is cycled
By default the AdoNetAppender will not attempt to reconnect to the database if
it looses its connection for any reason. Take a look at ReconnectOnError
property. Note however that if you set this property to true and your database
is not available every time you attempt to log something to the DB it will take
up to the connection timeout before the thread will return. I had made some
suggested changes to the code and wrote up a new appender for myself but never
got around to writing the unit tests.
http://logging.apache.org/log4net/release/sdk/log4net.Appender.AdoNetAppenderMembers.html
From: stephanie.giovann...@wellsfargoadvisors.com
Sent: Wednesday, January 11, 2012 8:38 AM
To: log4net-user@logging.apache.org
Subject: Logger in ASP.NET stops after a few hours, won't restart until app is
cycled
I have a logger attached to an ASP.NET project. In test environments, the
logger always works. In production (much higher user load), the logger stops
after a few hours and won’t restart until the app is cycled. I made
modifications to make the logger thread-safe, but that didn’t fix the problem.
I’m at a loss for how to troubleshoot since it only stops under high user load.
In production, there are around 30 web servers and one database. I don’t know
if that makes a difference. It’s not a problem when I run other stored
procedures.
I have years of experience with log4net, but before I’ve always used it in a
server application, not on a web server.
I don’t have any idea of where to start debugging this, so I’m attaching most
of the relevant code, with some names changed:
Web.config:
log4net
appender name=XDbAppender type=X.CustomAdoNetAppender
bufferSize value=1/
connectionType value=System.Data.SqlClient.SqlConnection, System.Data,
Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089 /
connectionString value=data source=[server]; initial catalog=[dbname]/
commandText value=exec dbo.spSetLogMessage @date, @level, @msg, @exc/
parameter
parameterName value=@date /
dbType value=DateTime /
layout type=log4net.Layout.RawTimeStampLayout /
/parameter
parameter
parameterName value=@level /
dbType value=String /
size value=10 /
layout type=log4net.Layout.PatternLayout
conversionPattern value=%level /
/layout
/parameter
parameter
parameterName value=@msg /
dbType value=String /
size value=2000 /
layout type=log4net.Layout.PatternLayout
conversionPattern value=%message /
/layout
/parameter
parameter
parameterName value=@exc /
dbType value=String /
size value=4000 /
layout type=log4net.Layout.ExceptionLayout /
/parameter
/appender
root
level value=DEBUG /
appender-ref ref=XDbAppender/
/root
/log4net
Global.asax:
%@ Application Language=C#
Inherits=Microsoft.Practices.CompositeWeb.WebClientApplication %
%@ Import Namespace=Y %
script Language=C# RunAt=server
private static readonly log4net.ILog Logger =
log4net.LogManager.GetLogger(AppName);
private static readonly object Locker = new object();
protected override void Application_Start(object sender, EventArgs e)
{
lock (Locker)
{
log4net.Config.XmlConfigurator.Configure();
Logger.Info(Started);
}
base.Application_Start(sender, e);
}
protected void Application_Error(object sender, EventArgs e)
{
lock (Locker)
{
var ex = Server.GetLastError();
// exception has already been handled
if (ex == null) return;
string pageName = string.Empty;
try
{
pageName = Request.CurrentExecutionFilePath;
}
catch (HttpException exc)
{
Logger.Warn(exc.Message);
}
var innermostEx = ex;
while (innermostEx.InnerException != null) innermostEx =
innermostEx.InnerException;
string exceptionMessage = innermostEx.GetType().Name + : +
innermostEx.Message;
UserLogin ul = null;
try
{
ul = (UserLogin) Session[LoggedInUser];
}
catch (HttpException exc)
{
if (exc.Message != Session state is not available in this
context.)
{
Logger.Warn(exc.Message);
}
}
string message = string.Empty;
if (ul != null)
{
message += User: + ul.Anumber;
}
if (pageName != string.Empty)
{
message += Page: + pageName;
}
if (exceptionMessage != string.Empty)
{
message += Msg: + exceptionMessage;
}
Re: Logger in ASP.NET stops after a few hours, won't restart until app is cycled
FYI, here is the enhancements that I suggested back in Jan, 2011 that I was referring to in my last email. I have been using the AdoNetAppender for a while now and have a few issues with it. 1) If the database that it logs to goes offline it will stop logging messages until the application is restarted · You can overcome that issue by setting ReconnectOnError but the problem with that is that if the database is still offline it will block your program thread until it times out every time it tries to flush the events. 2) Since the AdoNetAppender derives from BufferAppenderSkeleton it buffers events before writing to the DB. Not a bad idea unless you want to monitor the DB for exceptions in real-time. So let’s say I set the default buffer size to 20 events. If I am monitoring the DB I won’t see any of the exceptions till it hits the buffer size of 20 events. · The fix for me is to set the buffer to 1 event so that I get real-time results when an exception happens. However I am not taking advantage of buffering the events so that the application thread returns quicker and writes to the DB less frequent. Here is the behavior I want. 1) Set by default buffer size to 100 2) Set a buffer flush interval to 60 seconds 3) Set retry logic for DB connection in the event that the DB is unavailable and cache the log events being written So here is an example of how it would work. Write an exception to AdoNetAppender Event is buffered If buffer exceeds 100 events or 60 seconds has elapsed the buffer will be flushed If the appender is unable to talk to the DB it marks the connection as failed and caches the events locally Next write attempts looks to see if the retry time has been exceeded and if so attempts to write buffer to DB Also any local events previously cached from a failure will be written as well. So now I am back to using a buffer I now see any exceptions at most 60 seconds after they happen If the DB goes down I now have retry logic for attempting to write the events (key is not every attempt so the application is not being blocked on every write) Now not being entirely familiar with the source for Log4Net I attempted to add these features and have it working. However not sure if my approach is the approach you would take for including in your source. If anyone likes the features listed above I would be happy to provide the source changes. I did this by creating a AdoNetAppenderEx class that looks just like the AdoNetAppender but with my additions. However I personally think the concept of flushing events on an interval should be coded up higher in the BufferAppenderSkeleton as the issue I don’t like is having to wait till the number of buffered events is exceeded. Would be nice to specify another threshold for buffered events to be time based. The retry logic however for the DB is essential but don’t want it happening on every write but rather a retry after X seconds has elapsed since the last failed connection.
Re: Compiling log4net with strong name and 3rd party dependencies
From: Johannes Gustafsson Sent: Monday, August 08, 2011 1:20 PM To: log4net-user@logging.apache.org Subject: Compiling log4net with strong name and 3rd party dependencies Hi, There are a few bugfixes in the trunk that I need and since there has been no new release for a very long time, I tried to compile it myself. I created a key and have successfully compiled it with no problems. However, I have quite a few 3rd party dependencies that themselves are dependent on log4net. These dependencies can't find load the new assembly that I have created because they require that it is signed with a key that I dont have access to. So this means that I can't use my own version of log4net without recompiling all my dependencies. Do you have any suggestions to how I can solve this? Regards, /Johannes Yes, this is the same issue we have. I have a few features I would like to add but the thought of having to recompile everything has kept me from doing so.
Re: RollingFileAppender
Try this
appender name=RollingFileAppender
type=log4net.Appender.RollingFileAppender
file value=log.txt /
appendToFile value=true /
rollingStyle value=Size /
maxSizeRollBackups value=-1 /
maximumFileSize value=10MB /
staticLogFileName value=true /
countDirection value=0 /
param name=DatePattern value= logyyMMddHHmmss.txt /
layout type=log4net.Layout.PatternLayout
conversionPattern value=%date [%thread] %-5level %logger
[%property{NDC}] - %message%newline /
/layout
/appender
On 1/13/2011 8:28 PM, cyz wrote:
Hi, I'd like to have a logging system with below behaviors, is
RollingFileAppender able to achieve?
1 messages are logged to a fixed file name, say log.txt.
2 log files are auto backup by sizes. I.e. when log.txt hits the configured
size, it's renamed as logyyMMddHHmmss.txt, next message coming in will be
written to log.txt again.
3 there is no limit on how many files can be backup.
Thank you.
