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

[st...@wellsfargoadvisors.com]

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;
            }

            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

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

[Jim Scott <js...@infoconex.com>]

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.giovannini@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;
            }

            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