Web App Restarting Unexpectedly

What happened?

This was an ASP.NET application. It used forms authentication. The user logs in, navigates to a number of pages here and there and suddenly upon hitting few particular pages, the web app would restart. I knew this because 1) the user lost session 2) logs that are typically collected at Application_Start.

This was rather a puzzling and mysterious behavior of an app that's worked with no such issue for many months.

The Cause:

There was a piece of code in those few pages that wrote to a config file (a file whose extension is .config but not web.config). This was IIS6. This change to this config file triggered the AppPool to recycle and thus the application to restart.

The fix is obviously simple: don't write to the config file.

Another log4net HowTo

Intro and Configuration

Log4net is a sophisticated logging library for .NET applications (web or otherwise). It’s not however cumbersome to use, neither it’s intrusive I believe. I will try in this post to illustrate what I think is good configuration for this library. A configuration that lets a .NET application uses but not have a hard dependency on it.

You start by downloading the library here http://logging.apache.org/log4net/. There you’ll also find good examples and documentation. Add a reference to your .NET app.

Now there are a number of ways you can configure the library, what to log (date & time stamp, thread #, custom message, exceptions etc) and where to log (a database, a file or the standard output {console}). A good way to configure the library is tell your application and the assembly level where the configuration file for log4net (typically an XML file) lives. You do so by adding the below line to your AssemblyInfo.vb or (AsssemblyInfo.cs) class

<Assembly: log4net.Config.XmlConfigurator(ConfigFile:="MyAppLog4net.config", Watch:=True)>

The configFile can a full-path to your log4net configuration file. The watch flag if set true tells log4net to reload the configuration at runtime if the configuration file was changed.

Now technically you can start logging. Given the simple config file below

<?xml version="1.0" encoding="utf-8" ?>

<log4net>

  <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">

    <file value="myLog.log" />

    <appendToFile value="true" />

    <maximumFileSize value="100KB" />

    <maxSizeRollBackups value="2" />

    <layout type="log4net.Layout.PatternLayout">

      <conversionPattern value="%date %level %thread %logger - %message%newline" />

    </layout>

  </appender>

  <root>

    <!--<level value="DEBUG" />-->

    <appender-ref ref="RollingFile" />

  </root>

</log4net>

With this log file we can log a visit to web page

Protected Sub Page_Load(ByVal sender As Object, ByVal e As System.EventArgs) Handles Me.Load

    log4net.LogManager.GetLogger(Me.GetType().Name).Info(Me.Request.Path + " visited.")

End Sub

A sample output: 2012-04-21 09:21:33,970 INFO 21 default_aspx - /Default.aspx visited.

A better approach (create your own wrapper):

Instead of invoking log4net directly from your business logic layer, data layer, etc. a better approach is to create wrapper logging layer. The benefit is that you decouple your application from a specific logging implementation.

One way to do this is to create an interface that defines your logging operations. A simple interface can look like the below.

Public Interface ICustomLog

    Sub Debug(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)

    Sub Info(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)

    Sub Warn(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)

    Sub [Error](ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)

    Sub Fatal(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)

End Interface

Any type of logging implementation will then have to adhere to the defined interface. The parameters passed to various logging methods will apparent later, hopefully.

Here is an implementation that will rely fundamentally on log4net. But before showing the concrete implementation, let’s talk about custom properties that you can tell log4net to log for you.

Logging Custom Properties using log4net [.Core.LoggingEvent]

By default log4net will log a number of properties (thread number, date of event, custom message etc.). If you wish to add properties that are specific to your application, log4net will let you do that through a number of ways. One of the ways that you can load a log4net logger object with custom properties is through using the LoggingEvent class. The sample code will illustrate how. One of the common issues one runs to when using custom properties is that even it appears the code is using them correctly, they don’t show in the log file/ log table etc. This is almost always due to the fact that configuration file is not written correctly to tell log4net how to render or from where to get the custom properties; so special care needs to be given to how the configuration is written.

For example, let’s assume that one of the requirements of your is logging three custom properties: the SessionID {asp.net SessionID}, the raw request’s URL, and an application name. Putting these three variables in a custom object is a good idea (CustomLogProperties in sample). Every time we need to log an event with then create an instance of CustomLogProperites and pass to our logger who takes care of creating a LoggingEvent populated with the custom properties.

Private Sub SetCustomLogProperties(ByVal loggingEvent As log4net.Core.LoggingEvent, ByVal customLogObject As CustomLogProperties)

        If customLogObject Is Nothing OrElse loggingEvent Is Nothing Then

            Return

        End If

        loggingEvent.Properties(CustomFileLogger.ApplicationNameKey) = customLogObject.ApplicationName

        loggingEvent.Properties(CustomFileLogger.RequestKey) = customLogObject.RequestPath

        loggingEvent.Properties(CustomFileLogger.ASPSesssionIDKey) = customLogObject.SessionID

    End Sub

    Private Function GetLoggingEvent(ByVal source As Type, ByVal logger As log4net.ILog, ByVal message As String, ByVal exception As Exception _

                                     , ByVal level As log4net.Core.Level, ByVal customLogObject As Object) As log4net.Core.LoggingEvent

        If source Is Nothing OrElse logger Is Nothing Then

            Return Nothing

        End If

        Dim loggingEvent As New log4net.Core.LoggingEvent(source, logger.Logger.Repository, logger.Logger.Name, level, message, exception)

        SetCustomLogProperties(loggingEvent, customLogObject)

        Return loggingEvent

    End Function

    Public Sub Debug(ByVal source As Type, ByVal message As String, ByVal exception As Exception, _

                     ByVal customLogObject As CustomLogProperties) Implements ICustomLog.Debug

        Dim logger As log4net.ILog = GetLogger(source)

        Dim loggingEvent = GetLoggingEvent(source, logger, message, exception, log4net.Core.Level.Debug, customLogObject)

        If loggingEvent IsNot Nothing Then

            logger.Debug(message)

        End If

    End Sub

Here is the relevant portion of the log configuration file which will instruct the log4net library on how to write the custom properties

<layout type="log4net.Layout.PatternLayout">

      <conversionPattern value="%date %level %thread %logger - %message %exception [%property{ApplicationName}]

                         [%property{RequestPath}] [%property{SessionID}] %newline" />

    </layout>

Notice the use of %property{property_name} syntax.

Code Listings

Configuration 

    
 <?xml version="1.0" encoding="utf-8" ?>
<log4net>
  <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
    <file value="myLog.log" />
    <appendToFile value="true" />
    <maximumFileSize value="100KB" />
    <maxSizeRollBackups value="2" />

    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date %level %thread %logger - %message %exception [%property{ApplicationName}]
                         [%property{RequestPath}] [%property{SessionID}] %newline" />
    </layout>
  </appender>

  <root>
    <!--<level value="DEBUG" />-->
    <appender-ref ref="RollingFile" />
  </root>
</log4net> 

Sample Code

 

Partial Public Class _Default
    Inherits System.Web.UI.Page
    Private logger As ICustomLog = CustomFileLogger.GetInstance()
    Protected Sub Page_Load(ByVal sender As Object, ByVal e As System.EventArgs) Handles Me.Load
        'log4net.LogManager.GetLogger(Me.GetType().Name).Info(Me.Request.Path + " visited.")
        logger.Info(Me.GetType(), "Page visitied", Nothing, New CustomLogProperties() With {.ApplicationName = "MyApp", .RequestPath = Request.RawUrl, .SessionID = Me.Session.SessionID})
        CauseAndLogException()
    End Sub
    Private Sub CauseAndLogException()
        Dim str = "4/31/2012"
        Try
            DateTime.Parse(str)
        Catch ex As Exception
            logger.Error(Me.GetType(), "An error occurred in " + System.Reflection.MethodBase.GetCurrentMethod().Name, ex, New CustomLogProperties With _
                         {.ApplicationName = "MyApp", .RequestPath = Request.RawUrl, .SessionID = Me.Session.SessionID})
        End Try
    End Sub
End Class

Public Interface ICustomLog
    Sub Debug(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)
    Sub Info(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)
    Sub Warn(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)
    Sub [Error](ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)
    Sub Fatal(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)
End Interface
Public Class CustomFileLogger
    Implements ICustomLog
    Private Shared _loggers As Dictionary(Of Type, log4net.ILog) = New Dictionary(Of Type, log4net.ILog)
    Private Shared _lock = New Object()
    Private Shared _instance As ICustomLog = Nothing
    Private Sub New()
    End Sub
    Public Shared Function GetInstance() As ICustomLog
        If _instance Is Nothing Then
            _instance = New CustomFileLogger()
        End If
        Return _instance
    End Function
    Private Function GetLogger(ByVal source As Type) As log4net.ILog
        SyncLock _lock
            If CustomFileLogger._loggers.ContainsKey(source) Then
                Return CustomFileLogger._loggers(source)
            Else
                Dim logger As log4net.ILog = log4net.LogManager.GetLogger(source)
                CustomFileLogger._loggers.Add(source, logger)
                Return logger
            End If
        End SyncLock
    End Function
    Private Sub SetCustomLogProperties(ByVal loggingEvent As log4net.Core.LoggingEvent, ByVal customLogObject As CustomLogProperties)
        If customLogObject Is Nothing OrElse loggingEvent Is Nothing Then
            Return
        End If
        loggingEvent.Properties(CustomFileLogger.ApplicationNameKey) = customLogObject.ApplicationName
        loggingEvent.Properties(CustomFileLogger.RequestKey) = customLogObject.RequestPath
        loggingEvent.Properties(CustomFileLogger.ASPSesssionIDKey) = customLogObject.SessionID
    End Sub
    Private Function GetLoggingEvent(ByVal source As Type, ByVal logger As log4net.ILog, ByVal message As String, ByVal exception As Exception _
                                     , ByVal level As log4net.Core.Level, ByVal customLogObject As Object) As log4net.Core.LoggingEvent
        If source Is Nothing OrElse logger Is Nothing Then
            Return Nothing
        End If
        Dim loggingEvent As New log4net.Core.LoggingEvent(source, logger.Logger.Repository, logger.Logger.Name, level, message, exception)
        SetCustomLogProperties(loggingEvent, customLogObject)
        Return loggingEvent
    End Function
    Public Sub Debug(ByVal source As Type, ByVal message As String, ByVal exception As Exception, _
                     ByVal customLogObject As CustomLogProperties) Implements ICustomLog.Debug
        Dim logger As log4net.ILog = GetLogger(source)
        Dim loggingEvent = GetLoggingEvent(source, logger, message, exception, log4net.Core.Level.Debug, customLogObject)
        If loggingEvent IsNot Nothing Then
            logger.Debug(message)
        End If
    End Sub
    Public Sub Info(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customLogObject As CustomLogProperties) Implements ICustomLog.Info
        Dim logger As log4net.ILog = GetLogger(source)
        Dim loggingEvent = GetLoggingEvent(source, logger, message, exception, log4net.Core.Level.Info, customLogObject)
        If loggingEvent IsNot Nothing Then
            logger.Logger.Log(loggingEvent)
        End If
    End Sub
    Public Sub Warn(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customLogObject As CustomLogProperties) Implements ICustomLog.Warn
        Dim logger As log4net.ILog = GetLogger(source)
        Dim loggingEvent = GetLoggingEvent(source, logger, message, exception, log4net.Core.Level.Warn, customLogObject)
        If loggingEvent IsNot Nothing Then
            logger.Logger.Log(loggingEvent)
        End If
    End Sub
    Public Sub [Error](ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customLogObject As CustomLogProperties) Implements ICustomLog.Error
        Dim logger As log4net.ILog = GetLogger(source)
        Dim loggingEvent = GetLoggingEvent(source, logger, message, exception, log4net.Core.Level.Error, customLogObject)
        If loggingEvent IsNot Nothing Then
            logger.Logger.Log(loggingEvent)
        End If
    End Sub
    Public Sub Fatal(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customLogObject As CustomLogProperties) Implements ICustomLog.Fatal
        Dim logger As log4net.ILog = GetLogger(source)
        Dim loggingEvent = GetLoggingEvent(source, logger, message, exception, log4net.Core.Level.Fatal, customLogObject)
        If loggingEvent IsNot Nothing Then
            logger.Logger.Log(loggingEvent)
        End If
    End Sub
    Private Shared Sub FlushLog()
        For Each log In _loggers
            Dim rep As log4net.Repository.ILoggerRepository
            rep = log.Value
            For Each appender As log4net.Appender.BufferingAppenderSkeleton In rep.GetAppenders()
                appender.Flush()
            Next
        Next
    End Sub
    Private Shared ReadOnly ApplicationNameKey As String = "ApplicationName"
    Private Shared ReadOnly RequestKey As String = "RequestPath"
    Private Shared ReadOnly ASPSesssionIDKey As String = "SessionID"
End Class
Public Class CustomLogProperties
    Public ApplicationName As String
    Public RequestPath As String
    Public SessionID As String
End Class

Useful Links:
http://logging.apache.org/log4net/
http://haacked.com/archive/2006/09/27/Log4Net_Troubleshooting.aspx

Finland Education System

Here http://www.theatlantic.com/national/archive/2011/12/what-americans-keep-ignoring-about-finlands-school-success/250564/#.Tv4NA-e7HkY.mailto

The article discusses that the main reason that led the Finnland education system reform was the inequality which was present before at some point of time before the reform itself took place. Therefore, the reform sought to achieve equality across the education system (pre-K to University). There are no private schools. Every student has access to free public education + what comes with it (health care etc.)

Since the 1980s, the main driver of Finnish education policy has been the idea that every child should have exactly the same opportunity to learn, regardless of family background, income, or geographic location. Education has been seen first and foremost not as a way to produce star performers, but as an instrument to even out social inequality.

The article highlights that co-operation is the norm the Finnish education system and that "nothing makes Finn more uncomfortable" than the idea of competition in the context of education.

The article also mentions the high expectations and equally high rewards of educators in Finland:

For Sahlberg what matters is that in Finland all teachers and administrators are given prestige, decent pay, and a lot of responsibility. A master's degree is required to enter the profession, and teacher training programs are among the most selective professional schools in the country. If a teacher is bad, it is the principal's responsibility to notice and deal with it.

Overall, a very interesting read.