headers
stephanie.giovannini | 11 Jan 2012 17:38

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 <at> date, <at> level, <at> msg, <at> exc"/>
      <parameter>
        <parameterName value=" <at> date" />
        <dbType value="DateTime" />
        <layout type="log4net.Layout.RawTimeStampLayout" />
      </parameter>
      <parameter>
        <parameterName value=" <at> level" />
        <dbType value="String" />
        <size value="10" />
        <layout type="log4net.Layout.PatternLayout">
          <conversionPattern value="%level" />
        </layout>
      </parameter>
      <parameter>
        <parameterName value=" <at> msg" />
        <dbType value="String" />
        <size value="2000" />
        <layout type="log4net.Layout.PatternLayout">
          <conversionPattern value="%message" />
        </layout>
      </parameter>
      <parameter>
        <parameterName value=" <at> 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:
 
<% <at> Application Language="C#" Inherits="Microsoft.Practices.CompositeWeb.WebClientApplication" %>
<% <at> 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;
            }
 
            Logger.Error(message, ex);
        }
    }
 
    </script>
 
Custom DB appender (gets the correct connection string for the environment):
 
using Commons;
using log4net.Appender;
 
namespace X
{
    public class CustomAdoNetAppender : AdoNetAppender
    {
        public new string ConnectionString
        {
            get
            {
                return base.ConnectionString;
            }
            set
            {
                base.ConnectionString = (Common.GetConnectionString());
            }
        }
    }
}
 
Can anyone suggest where log4net is failing under high load, and why it stops entirely?
 
 
Stephanie Giovannini
 
 
 
Permalink | Reply | 5 comments |
headers
Jim Scott | 12 Jan 2012 01:51
Gravatar

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.
 
 
 
Sent: Wednesday, January 11, 2012 8:38 AM
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 <at> date, <at> level, <at> msg, <at> exc"/>
      <parameter>
        <parameterName value=" <at> date" />
        <dbType value="DateTime" />
        <layout type="log4net.Layout.RawTimeStampLayout" />
      </parameter>
      <parameter>
        <parameterName value=" <at> level" />
        <dbType value="String" />
        <size value="10" />
        <layout type="log4net.Layout.PatternLayout">
          <conversionPattern value="%level" />
        </layout>
      </parameter>
      <parameter>
        <parameterName value=" <at> msg" />
        <dbType value="String" />
        <size value="2000" />
        <layout type="log4net.Layout.PatternLayout">
          <conversionPattern value="%message" />
        </layout>
      </parameter>
      <parameter>
        <parameterName value=" <at> 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:
 
<% <at> Application Language="C#" Inherits="Microsoft.Practices.CompositeWeb.WebClientApplication" %>
<% <at> 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;
            }
 
            Logger.Error(message, ex);
        }
    }
 
    </script>
 
Custom DB appender (gets the correct connection string for the environment):
 
using Commons;
using log4net.Appender;
 
namespace X
{
    public class CustomAdoNetAppender : AdoNetAppender
    {
        public new string ConnectionString
        {
            get
            {
                return base.ConnectionString;
            }
            set
            {
                base.ConnectionString = (Common.GetConnectionString());
            }
        }
    }
}
 
Can anyone suggest where log4net is failing under high load, and why it stops entirely?
 
 
Stephanie Giovannini
 
 
 
Permalink | Reply | 0 comments |
headers
Jim Scott | 12 Jan 2012 01:58
Gravatar

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.

 

Permalink | Reply | 3 comments |
headers
Todd | 12 Jan 2012 14:08
Picon
Favicon

Re: Logger in ASP.NET stops after a few hours, won't restart until app is cycled

Hi Jim.
 
What you're saying makes a lot of sense to me. I wasted two days troubleshooting what turned out to be a permissions issue last week because I wasn't aware that log4net would disable the appender upon connection error. I was trying to log in a web app's startup, which runs under the pool's identity (I know that NOW) and in the global error handler which was executing under the user's impersonated identity (which did have permission). Because the pool had no permission to the database, I got nothing, even for the user, and this was really hard to figure out.
 
You're suggesting a solution that might work well in real world scenarios where everything isn't perfect. A connections to a DB could drop momentarily and that probably shouldn't mean game over. I might want to see an entry indicating previous failures, though. That would help troubleshooting, especially if it's able to flush previous entries.
 
I'm surprised there's any application blocking. I assume log4net was returning immediately and processing requests on a background thread.

From: Jim Scott <jscott <at> infoconex.com>
To: log4net-user <at> logging.apache.org
Sent: Wednesday, January 11, 2012 7:58 PM
Subject: 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.
 


Permalink | Reply | 0 comments |
headers
stephanie.giovannini | 13 Jan 2012 16:38

RE: Logger in ASP.NET stops after a few hours, won't restart until app is cycled

Thanks for your input!

 

That is, of course, the problem. The site is up all day. One of the sources of messages logs something every time a user logs in. Thus, any minor database downtime or timeout could cause a connection failure.

 

I’ll be setting the ReconnectOnError to true immediately, but I agree with your idea. I haven’t messed with log4net code, but I’ve written services that handle database downtime just as you’ve suggested. In those cases, the source input was not dependent on the database (data was coming in from factory equipment), there was no user interaction, and it was acceptable to buffer the input until the database came back up.

 

I’m not sure my current application needs the same functionality because the site is completely dependent on the database. If the database is down, then every query is timing out for every user and nothing can be done. The logging hardly matters. Of course, I can’t log database-down errors, but that’s not my primary interest in logging.

 

 

From: Jim Scott [mailto:jscott <at> infoconex.com]
Sent: Wednesday, January 11, 2012 6:58 PM
To: log4net-user <at> logging.apache.org
Subject: 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.

 

Permalink | Reply | 0 comments |
headers
Ron Grabowski | 13 Jan 2012 19:17
Picon
Favicon

Re: Logger in ASP.NET stops after a few hours, won't restart until app is cycled

Have you tried setting the Evaluator property:

http://logging.apache.org/log4net/release/sdk/log4net.Appender.BufferingAppenderSkeleton.Evaluator.html

to flush buffered messages when a WARN or greater message is received?

Sounds like you have a good plan for extending the built-in appender for your project. Shouldn't be too difficult to add a timer that triggers a flush every X seconds. Be careful that your buffer doesn't grow too large if the database is down for an extended period of time. What you might want to do is extend BufferingForwardingAppender in such a way that it supports the concept of a fail-over appenders. I think nlog ships with a target that is able to switch destinations if the first one goes offline. I believe it tries to log to the original appender on each write to the fail-over appender because it wants to get back to the primary destination as soon as possible. I'm not certain about the implementation.

From: Jim Scott <jscott <at> infoconex.com>
To: log4net-user <at> logging.apache.org
Sent: Wednesday, January 11, 2012 7:58 PM
Subject: 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.
 


Permalink | Reply | 0 comments |
headers
Jayashree Kumar | 16 Jan 2012 06:35
Favicon

RemotingAppender and

Hi,

 

I have an application in which I have tried to use both a FileAppender and a RemotingAppender.

 

I notice that when I have the following line in my config file, both appenders work fine:

 

<onlyFixPartialEventData value="true" />

 

When I do not have this line or set the value to “false”, then the FileAppender continues to work, but my RemotingAppender stops working.

 

You may wonder why I wish to set onlyFixPartialEventData to “false”. The reason:

 

My application is multi-threaded and creates a fixed number of threads. My loggers are static loggers (not instance loggers), and I have 2 of them. When I set onlyFixPartialEventData to “true”, I see that the number of threads in my application increases with time. These threads never seem to terminate.

 

How do I avoid this multiplication of threads?

 

Thanks in advance for any help.

 

Regards,

Jaya.

 

Permalink | Reply | 0 comments |
headers
Roman Konovalov | 29 Jan 2012 12:24

Can log4net return exceptions back

Hi,

 

Is it possible to setup log4net to re-throw exceptions back to caller? For example, if logging to database is timed out, we might want to save such exception to a file or to send e-mail to the support team. Thank you.

 

Best regards,

Roman

 

Permalink | Reply | 1 comment |
headers
Roman Konovalov | 29 Jan 2012 12:25

Performance saving logs to the database

Hi,

 

We have web server with about 60,000 page visits a day. Within the next 6 months the load is expected to reach 1,000,000 page visits a day. We use log4net to store logs into the log database.

What is now unclear to me is if log4net is able to manage such a big load from performance point of view. Log4net is synchronous and if log database is down, then the entire process is waiting for log4net return call back (I assume it returns call back when database connection timeout occurs).

 

Should we write our own appender to save logs into the database asynchronously?

Or we would revisit our logging strategy and log only exceptions and errors in production environment, turning on other levels of logging during troubleshooting time?

 

Many thanks for replies.

 

Best regards,

Roman

 

Permalink | Reply | 1 comment |

Gmane