The Beauty of Open Source

The beauty of Open Source is that you can look at the most up-to-date detailed version of the documentation: the source code itself. Whenever you want to know how to do something or how it works, you can take a look at the source code. Yes, this is not always advisable as the first course of action as it can be quite time consuming, especially if it is a large and complex project. However, when you do figure out what you are after by reviewing the source code, it is a much more rewarding process than finding the answers in the docs (plus you may learn a new coding practice / technique).

I wanted to use the Serilog.Extras.Web nuget package to enrich my log entries with the HttpRequestId for log message correlation. I noticed in addition to the HttpRequestId being added to each log message, there were additional log messages being created for "HTTP GET..." or "HTTP POST...". I did not really want these log messages being generated as they were filling the log viewer (Seq) with a lot of noise. A quick Google search lead me to this Github page and the following ApplicationLifecycleModule class:

// Copyright 2014 Serilog Contributors
// 
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
// 
//     http://www.apache.org/licenses/LICENSE-2.0
// 
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

using System;
using System.Linq;
using System.Web;
using Serilog.Events;

namespace Serilog.Extras.Web
{
    /// <summary>
    /// HTTP module that logs application request and error events.
    /// </summary>
    public class ApplicationLifecycleModule : IHttpModule
    {
        static volatile bool _logPostedFormData;
        static volatile bool _isEnabled = true;
        static volatile LogEventLevel _requestLoggingLevel = LogEventLevel.Information;

        /// <summary>
        /// Register the module with the application (called automatically;
        /// do not call this explicitly from your code).
        /// </summary>
        public static void Register()
        {
            HttpApplication.RegisterModule(typeof(ApplicationLifecycleModule));
        }

        /// <summary>
        /// When set to true, form data will be written via a debug-level event.
        /// The default is false. Requires that <see cref="IsEnabled"/> is also
        /// true (which it is, by default).
        /// </summary>
        public static bool DebugLogPostedFormData
        {
            get { return _logPostedFormData; }
            set { _logPostedFormData = value; }
        }

        /// <summary>
        /// When set to true, request details and errors will be logged. The default
        /// is true.
        /// </summary>
        public static bool IsEnabled
        {
            get { return _isEnabled; }
            set { _isEnabled = value; }
        }

        /// <summary>
        /// The level at which to log HTTP requests. The default is Information.
        /// </summary>
        public static LogEventLevel RequestLoggingLevel
        {
            get { return _requestLoggingLevel; }
            set { _requestLoggingLevel = value; }
        }

        /// <summary>
        /// Initializes a module and prepares it to handle requests.
        /// </summary>
        /// <param name="context">An <see cref="T:System.Web.HttpApplication"/> that provides access to the methods, properties, and events common to all application objects within an ASP.NET application </param>
        public void Init(HttpApplication context)
        {
            context.LogRequest +=LogRequest;
            context.Error += Error;
        }

        static void LogRequest(object sender, EventArgs e)
        {
            if (!_isEnabled) return;

            var request = HttpContext.Current.Request;
            Log.Write(_requestLoggingLevel, "HTTP {Method} for {RawUrl}", request.HttpMethod, request.RawUrl);
            if (_logPostedFormData && Log.IsEnabled(LogEventLevel.Debug))
            {
                var form = request.Form;
                if (form.HasKeys())
                {
                    var formData = form.AllKeys.SelectMany(k => (form.GetValues(k) ?? new string[0]).Select(v => new { Name = k, Value = v }));
                    Log.Debug("Client provided {@FormData}", formData);
                }
            }
        }

        static void Error(object sender, EventArgs e)
        {
            if (!_isEnabled) return;

            var ex = ((HttpApplication)sender).Server.GetLastError();
            Log.Error(ex, "Error caught in global handler: {ExceptionMessage}", ex.Message);
        }

        /// <summary>
        /// Disposes of the resources (other than memory) used by the module that implements <see cref="T:System.Web.IHttpModule"/>.
        /// </summary>
        public void Dispose()
        {
        }
    }
}

From this I could see the method generating the unwanted log message (LogRequest) checks _isEnabled before logging the "HTTP..." message. So, to stop these messages all you have to do is set _isEnable to false. The code clearly tells you how to do this too: set the static property IsEnable to false or ApplicationLifecycleModule.IsEnabled = false. Of course, I could have found this out from reading the docs but it would not have been half as much fun or as an insightful learning experience to what was going on inside this small part of Serilog.Extras.Web. 

What else did I learn from this exercise? I realised I could easily enrich the action method execution time telemetry logging I was already collecting with the requests raw URL using HttpContext.Current.Request.RawUrl to facilitate request URL correlation. I noticed that the Error method appears to be a global exception handler which could lead to this being a replacement for Elmah. I also saw the "volatile" C# keyword in use which prompted me to look into this further and discovered it's something not to be used lightly.

Maybe the next time you experience some behavior you were not expecting or want to know how to do something with an open source project, before rushing to the docs for an explanation, take a quick look at the source code and see what you can uncover first. You may just come away with a small sense of achievement and learn something new in the process.