Using log4net in your ASP.NET MVC application? Be carefull to use the %aspnet-request{} patterns

I have been using log4net for quite a long time on my ASP.NET MVC project. There is a handy pattern  %aspnet-request{ASP.NET_SessionId} out there. It helps to track actions made by particular user if there are several active users at the same time.

The pattern has been there in my log.xml for years and was working great until I finally migrated from MVC 3 to the most recent MVC 5. After the migration I've noticed a strange issue related to the ASP.NET request validation. If unsafe request is sent to some action that has the validation enabled then the server sends an empty response with status 200 and there is nothing in the log file???

To investigate the behavior an empty ASP.NET MVC project was created with a very simple Echo controller:

    public class EchoController : Controller
    {
        private static readonly ILog Log =
            LogManager.GetLogger(typeof (EchoController));

        public ActionResult Index(string data)
        {
            //This line is required to force a new session.
            Session["dummy-key"] = "dummy-value";
            Log.Debug("Index action got data: " + data);
            return Content("Got data: " + data, "text/plain");
        }

        protected override void OnException(ExceptionContext c)
        {
            Log.Error("Unhandled error occured", c.Exception);
        }
    }

And log config:

    <log4net>
        <appender name="FileAppender" type="log4net.Appender.FileAppender">
            <file value="logs/application.log" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="(session-id: %aspnet-request{ASP.NET_SessionId}) %m%n" />
            </layout>
        </appender>
        <root>
            <level value="ALL" />
            <appender-ref ref="FileAppender" />
        </root>
    </log4net>

So simple request with safe data will give you a response and log output you would expect:

c:\>curl --request POST http://localhost:55747/echo --data "data=hello" --verbose
* About to connect() to localhost port 55747 (#0)
*   Trying 127.0.0.1... connected
> POST /echo HTTP/1.1
> User-Agent: curl/7.23.1 (x86_64-pc-win32) libcurl/7.23.1
> Host: localhost:55747
> Accept: */*
> Content-Length: 10
> Content-Type: application/x-www-form-urlencoded
>
* upload completely sent off: 10 out of 10 bytes
< HTTP/1.1 200 OK
< Cache-Control: private
< Content-Type: text/plain; charset=utf-8
< Server: Microsoft-IIS/8.0
< X-AspNetMvc-Version: 5.2
< X-AspNet-Version: 4.0.30319
< Set-Cookie: ASP.NET_SessionId=1z2kxgj3b1cqxsvwpd3tdigq; path=/; HttpOnly
< X-SourceFiles: =?UTF-8?B?RTpcamVueWFccHJvamVjdHNcTG9nNG5ldFJlcXVlc3RWYWxpZGF0aW9uXExvZzRuZXRSZXF1ZXN0VmFsaWRhdGlvbi5NdmNcZWNobw==?=
< X-Powered-By: ASP.NET
< Date: Wed, 01 Jul 2015 11:45:49 GMT
< Content-Length: 15
<
Got data: hello* Connection #0 to host localhost left intact
* Closing connection #0

Log output:

(session-id: (null)) Index action got data: hello

The session-id is null because it has just been started. Repeating the request with session cookie results in a log output with the session-id assigned:

c:\>curl --request POST http://localhost:55747/echo --data "data=hello" --verbose --cookie ASP.NET_SessionId=1z2kxgj3b1cqxsvwpd3tdigq

Log output:

(session-id: (1z2kxgj3b1cqxsvwpd3tdigq)) Index action got data: hello

So far everything works as expected. Now let's try some unsafe data:

c:\>curl --request POST http://localhost:55747/echo --data "data=<hello>" --verbose --cookie ASP.NET_SessionId=1z2kxgj3b1cqxsvwpd3tdigq
* About to connect() to localhost port 55747 (#0)
*   Trying 127.0.0.1... connected
> POST /echo HTTP/1.1
> User-Agent: curl/7.23.1 (x86_64-pc-win32) libcurl/7.23.1
> Host: localhost:55747
> Accept: */*
> Cookie: ASP.NET_SessionId=1z2kxgj3b1cqxsvwpd3tdigq
> Content-Length: 12
> Content-Type: application/x-www-form-urlencoded
>
* upload completely sent off: 12 out of 12 bytes
< HTTP/1.1 200 OK
< Server: Microsoft-IIS/8.0
< X-AspNetMvc-Version: 5.2
< X-SourceFiles: =?UTF-8?B?RTpcamVueWFccHJvamVjdHNcTG9nNG5ldFJlcXVlc3RWYWxpZGF0aW9uXExvZzRuZXRSZXF1ZXN0VmFsaWRhdGlvbi5NdmNcZWNobw==?=
< X-Powered-By: ASP.NET
< Date: Wed, 01 Jul 2015 11:49:27 GMT
< Content-Length: 0
<
* Connection #0 to host localhost left intact
* Closing connection #0

Wat???  HTTP/1.1 200 OK and Content-Length: 0 and there is nothing in the log file???

Some digging has led me to a webpages:Enabled app setting. Starting from ASP.NET MVC 3 it should be set to false. As mentioned here it will prevent Razor templates from being directly accessible. But it looks like it does something else. On my project there was no that option so I've added it and tried again:

c:\>curl --request POST http://localhost:55747/echo --data "data=<hello>" --verbose --cookie ASP.NET_SessionId=qvrc2hkukx0iywp1qudps1xb
* About to connect() to localhost port 55747 (#0)
*   Trying 127.0.0.1... connected
> POST /echo HTTP/1.1
> User-Agent: curl/7.23.1 (x86_64-pc-win32) libcurl/7.23.1
> Host: localhost:55747
> Accept: */*
> Cookie: ASP.NET_SessionId=qvrc2hkukx0iywp1qudps1xb
> Content-Length: 12
> Content-Type: application/x-www-form-urlencoded
>
* upload completely sent off: 12 out of 12 bytes
< HTTP/1.1 500 Internal Server Error
< Cache-Control: private
< Content-Type: text/html; charset=utf-8
< Server: Microsoft-IIS/8.0
< X-AspNet-Version: 4.0.30319
< X-SourceFiles: =?UTF-8?B?RTpcamVueWFccHJvamVjdHNcTG9nNG5ldFJlcXVlc3RWYWxpZGF0aW9uXExvZzRuZXRSZXF1ZXN0VmFsaWRhdGlvbi5NdmNcZWNobw==?=
< X-Powered-By: ASP.NET
< Date: Wed, 01 Jul 2015 11:56:22 GMT
< Content-Length: 11192
<
<!DOCTYPE html>
<html>
    <head>
        <title>A potentially dangerous Request.Form value was detected from the client (data=<hello>).</title>

I've posted just some part of the response and as you can see the status code is 500 and output has exception details. Let's check the log file:

(session-id: 

The line is trimmed! Looks like something goes wrong inside of the log4net. Luckily log4net has internal debugging support (see details here). To activate it there is an app setting:

<add key="log4net.Internal.Debug" value="true"/>

and also a trace listener should be added:

    <system.diagnostics>
        <trace autoflush="true">
            <listeners>
                <add 
                    name="textWriterTraceListener" 
                    type="System.Diagnostics.TextWriterTraceListener" 
                    initializeData="logs\log4net.log" />
            </listeners>
        </trace>
    </system.diagnostics>

Repeating the request and checking the log4net.log finally makes it clear:

System.Web.HttpRequestValidationException (0x80004005): A potentially dangerous Request.Form value was detected from the client (data="&lthello&gt").
   at System.Web.HttpRequest.ValidateString(String value, String collectionKey, RequestValidationSource requestCollection)
   at System.Web.HttpRequest.<>c__DisplayClass5.b__3(String key, String value)
   at System.Web.HttpValueCollection.EnsureKeyValidated(String key)
   at System.Web.HttpValueCollection.GetValues(Int32 index)
   at System.Collections.Specialized.NameValueCollection.Add(NameValueCollection c)
   at System.Web.HttpRequest.FillInParamsCollection()
   at System.Web.HttpRequest.GetParams()
   at System.Web.HttpRequest.get_Params()
   at log4net.Layout.Pattern.AspNetRequestPatternConverter.Convert(TextWriter writer, LoggingEvent loggingEvent, HttpContext httpContext)
   at log4net.Layout.Pattern.AspNetPatternLayoutConverter.Convert(TextWriter writer, LoggingEvent loggingEvent)
   at log4net.Layout.Pattern.PatternLayoutConverter.Convert(TextWriter writer, Object state)
   at log4net.Util.PatternConverter.Format(TextWriter writer, Object state)
   at log4net.Layout.PatternLayout.Format(TextWriter writer, LoggingEvent loggingEvent)
   at log4net.Appender.AppenderSkeleton.RenderLoggingEvent(TextWriter writer, LoggingEvent loggingEvent)
   at log4net.Appender.TextWriterAppender.Append(LoggingEvent loggingEvent)
   at log4net.Appender.FileAppender.Append(LoggingEvent loggingEvent)
   at log4net.Appender.AppenderSkeleton.DoAppend(LoggingEvent loggingEvent)

AspNetPatternConverter is used extract tokens from request and append them to the log. Further digging into the ASP.NET sources shows that the HttpRequestValidationException is raised when Request.Params are accessed. Request.Params are lazy populated with QueryString, Form, Cookies and ServerVariables. Request.Form will be validated and raise the HttpRequestValidationException. 

Probably the issue should be fixed by handling this exception inside of the AspNetPatternConverter and I will send a pull request some time soon. But production is waiting and the fastest solution I've came up with is to create a custom converter. It's quite simple and takes just a few lines of code. In my case I just need to log the session-id so here is the code I have:

    public class Log4NetSessionIdConverter : PatternLayoutConverter
    {
        protected override void Convert(TextWriter writer, LoggingEvent loggingEvent)
        {
            string sessionId;
            if (HttpContext.Current == null || HttpContext.Current.Session == null) 
               sessionId = SystemInfo.NotAvailableText;
            else 
               sessionId = HttpContext.Current.Session.SessionID;
            writer.Write(sessionId);
        }
    }

All you have to do is to add the converter declaration for your layout:

      <converter>
        <name value="session-id" />
        <type value="Log4netRequestValidation.Mvc.Log4NetSessionIdConverter" />
      </converter>

And then session-id pattern can be safely used:

<conversionPattern value="(session-id: %session-id) %m%n" />

So let's try the request again:

c:\>curl --request POST http://localhost:55747/echo --data "data=<hello>" --verbose --cookie ASP.NET_SessionId=qvrc2hkukx0iywp1qudps1xb
* About to connect() to localhost port 55747 (#0)
*   Trying 127.0.0.1... connected
> POST /echo HTTP/1.1
> User-Agent: curl/7.23.1 (x86_64-pc-win32) libcurl/7.23.1
> Host: localhost:55747
> Accept: */*
> Cookie: ASP.NET_SessionId=qvrc2hkukx0iywp1qudps1xb
> Content-Length: 12
> Content-Type: application/x-www-form-urlencoded
>
* upload completely sent off: 12 out of 12 bytes
< HTTP/1.1 500 Internal Server Error
< Cache-Control: private
< Content-Type: text/html; charset=utf-8
< Server: Microsoft-IIS/8.0
< X-AspNet-Version: 4.0.30319
< X-SourceFiles: =?UTF-8?B?RTpcamVueWFccHJvamVjdHNcTG9nNG5ldFJlcXVlc3RWYWxpZGF0aW9uXExvZzRuZXRSZXF1ZXN0VmFsaWRhdGlvbi5NdmNcZWNobw==?=
< X-Powered-By: ASP.NET
< Date: Wed, 01 Jul 2015 11:56:22 GMT
< Content-Length: 11192
<
<!DOCTYPE html>
<html>
    <head>
        <title>A potentially dangerous Request.Form value was detected from the client (data=<hello>).</title>

Finally it works correctly. The response is 500 and log output:

(session-id: qvrc2hkukx0iywp1qudps1xb) Unhandled error occured
System.Web.HttpRequestValidationException (0x80004005): A potentially dangerous Request.Form value was detected from the client (data="<hello>").

It's time to click a TeamCity button to trigger a production build.