On the importance of logging exceptions

It’s been a while since I wrote a programming blog-post, so here goes…

We developers like to think that our code is perfect, that there are no bugs. But there are always bugs. And even in cases where our code is bug free, what works on my machine may not work on yours. You need to handle exceptions properly, and I’m not going to tell you how to do that. But the bottom line is, handle expected exceptions, that is, things that can and will occasionally go wrong, leaving the application in a state where you can still continue (but will probably crash and burn if you do nothing). For everything else, log the error somehow before gracefully terminating the application.

There are loads of error logging solutions out there, or you can do what I did, which is to write something of your own. I wrote my own simple logger, which was originally only for unhandled exceptions as a catch-all so that fatal exceptions could be logged, and then afterwards extended it so that I have a log viewer built into the application.

My logging takes advantage of extension methods so that, as a last step in each exception handler all I need do is type ex.Log(); It uses a bit of reflection and a bit of hacky HTML manipulation so that the viewer can display a nicely formatted table with the error details, and also supports saving the error to a file, as well as sending the error in an HTML email via SMTP.

I won’t show you all the code here, since it references other bits and pieces of my code (in extension methods or whatever I used. I don’t remember anymore…).

You can download my built RomyView application or the full RomyView source code.

My Log extension method on exceptions simply looks like this:

using System.Runtime.InteropServices.ComTypes;

namespace System
{
    /// <summary>Extension methods on <see cref="System.Exception"/> to log
    /// exceptions using my <see cref="ApplicationExceptionLogger"/>.</summary>
    public static class ExceptionExtensions
    {
        public static void Log(this Exception ex)
        {
            if (ex.HResult != (int)HResult.E_FAIL) // Logging E_FAIL is meaningless...
            {
                var ax = ex as AggregateException;

                if (ax != null)
                {
                    ax.Handle(e =>
                    {
                        Log(e);
                        return true;
                    });
                }
                else
                    LogException(ex);
            }
        }

        private static void LogException(Exception ex)
        {
            if (!(ex is OperationCanceledException) && !(ex is TimeoutException))
            {
                ApplicationExceptionLogger.LogException(ex);
            }
        }
    }
}

As you can see, it references a custom enumerated type that maps HResult errors so that I can easily refer to known COM exceptions and so on (as well as easily convert well-written C++ code in MSDN examples and so on), and ignores E_FAIL errors, since there is no value in logging those. It also logs all the nested exceptions in any AggregateException, and then hands the exception over to my ApplicationExceptionLogger class.

That class then hands the exception over to another extension method in my ErrorNotifier class. I’ll paste that code below, but since it is quite lengthy, I’ll first show you what my log viewer looks like. It logs to a CSV file, where one field in the file is HTML that the code generates. The log viewer then parses the file and displays the HTML each time you select an error. (In the case of error messages having commas, my CSV may not really be valid CSV, but that’s OK because my viewer understands how to parse it.) Like so:

LogViewer

Another thing I can do in my exception handlers is also send email notifications, although by default my application settings required for that to work are not set up correctly (because doing so would hand over my Gmail credentials to the whole world). Each error can then be saved to a separate HTML file, and most importantly for me, it logs enough information to be able to find the cause. In this case it is a stupid contrived error… which is always generated if you run the program and hit Ctrl+E in a debug build.

And here is what  my ErrorNotifier class looks like:

using System;
using System.Collections;
using System.Collections.Generic;
using System.Linq;
using System.Net;
using System.Net.Mail;
using System.Reflection;
using System.Runtime.InteropServices;

namespace Romy.Core
{
    /// <summary>Helper class that generates a nicely formatted HTML log of an Exception. Gets whatever info 
    /// it can via reflection, the stack trace, and the custom Data, if any, for the Eception.</summary>
    public static class ErrorNotifier
    {
        #region Fields

        private const string logDateFormat = "yyyy/MM/dd HH:mm:ss:ff";

        #endregion Fields

        #region Methods

        #region Public Methods

        /// <summary>Geneates HTML with as much info about the Exception as possible, 
        /// plus stack trace, which is used for logging and notfication emails.</summary>
        public static string DetailsAsHtml(this Exception ex)
        {
            var html = new List<string>();

            html.AddRange(new string[]{
                "<!DOCTYPE html><html lang=\"en\" xmlns=\"http://www.w3.org/1999/xhtml\"><head><meta charset=\"utf-8\" /><title>Error Notification</title>",
                "</head><body style=\"background-color: #E2E8EB\"><div style=\"width: 100%; text-align: left;\"><table cellpadding=\"0\" cellspacing=\"0\" ",
                "style=\"border: 1px solid #CACBD9; width: 100%; border-collapse: collapse; background-color: #F0F1EF;\">",
                string.Empty,
                "</table></div></body></html>"});

            var errorRows = new List<string>();

            // Keeps track of alternate lines to be displayed shaded in generated HTML.
            var shaded = true;

            foreach (var kvp in ExceptionDetails(ex))
            {
                errorRows.Add(string.Format("<tr{0}><td style=\"width: 120px; font-weight: bold; font-family: Verdana, Geneva, Tahoma, sans-serif; font-size: 12px; text-indent: 8px; color: #272130;\">{1}</td><td style=\"font-family: Verdana, Geneva, Tahoma, sans-serif; font-size: 11px; color: #0B2022\">{2}</td></tr>", (shaded = !shaded) ? " style=\"background-color: #CCCCCC\"" : string.Empty, kvp.Key, kvp.Value));
            }
            ExtractExceptionData(ex, errorRows, ref shaded);

            ExtractInnerExceptionDetails(ex, errorRows, ref shaded);

            html.InsertRange(html.IndexOf(string.Empty), errorRows);
            html[html.Count - 1] += "\r\n";

            // I use this in CSV, so it's important to restrict the HTML to a single line.
            return string.Join(string.Empty, html.Select(s => s)).Replace("\r\n", string.Empty);
        }

        /// <summary>Send error notification email via SMTP.</summary>
        /// <remarks>I have nly used this with gmail, and have removed my password from 
        /// the project settings. To use this, change the relevant settings.</remarks>
        public static async void NotifyByEmail(Exception ex, params MailAddress[] recipients)
        {
            try
            {
                var body = DetailsAsHtml(ex);
                var fromAddress = new MailAddress(Properties.Settings.Default.Smtp_From_Address, Properties.Settings.Default.Smtp_From_DisplayName);
                var subject = string.Format("Application error in {0}", Properties.Settings.Default.ApplicationName);

                var smtp = new SmtpClient
                {
                    Host = Properties.Settings.Default.Smtp_Host,
                    Port = Properties.Settings.Default.Smtp_Port,
                    EnableSsl = true,
                    DeliveryMethod = SmtpDeliveryMethod.Network,
                    UseDefaultCredentials = false,
                    Credentials = new NetworkCredential(fromAddress.Address, Properties.Settings.Default.Smtp_Password)
                };

                using (var message = new MailMessage
                {
                    From = fromAddress,
                    Subject = subject,
                    Body = body,
                    IsBodyHtml = true
                })
                {
                    message.To.AddRange(recipients);
                    await smtp.SendMailAsync(message);
                }
            }
            catch (Exception exc) { exc.Log(); }
        }

        #endregion Public Methods

        #region Private Methods

        private static Dictionary<string, string> ExceptionDetails(Exception ex)
        {
            var now = DateTime.Now;
            var result = new Dictionary<string, string>();

            result.Add("Message", ex.Message);
            result.Add("Exception", ex.GetType().ToString());
            result.Add("Time", now.ToString(logDateFormat));

            foreach (var kvp in ExtractMethodInfo(ex))
            {
                result.Add(kvp.Key, kvp.Value);
            }

            var comExc = ex as COMException;
            result.Add("HResult", string.Format("0x{0:X}", comExc != null ? comExc.ErrorCode : ex.HResult));
            result.Add("Stacktrace", ExtractStackTrace(ex));

            return result;
        }

        private static Dictionary<string, string> ExtractMethodInfo(Exception ex)
        {
            var result = new Dictionary<string, string>();

            MethodBase mb = ex.TargetSite;

            if (mb != null)
            {
                result.Add("Member Type", mb.MemberType.ToString());

                if (mb.Module != null)
                    result.Add("Module", mb.Module.ToString());

                if (!string.IsNullOrEmpty(mb.Name))
                    result.Add("Name", mb.Name);

                if (mb.ReflectedType != null)
                    result.Add("Reflected Type", mb.ReflectedType.FullName);
            }
            return result;
        }

        private static string ExtractStackTrace(Exception ex)
        {
            var stackTrace = ex.StackTrace;
            return !string.IsNullOrEmpty(stackTrace) ? System.Web.HttpUtility.HtmlEncode(stackTrace).Replace("\r\n", "<br />").Trim() : string.Empty;
        }

        private static void ExtractExceptionData(Exception ex, List<string> errorRows, ref bool shaded)
        {
            if (ex.Data != null && ex.Data.Count > 0)
            {
                errorRows.Add(string.Format("<tr{0}><td colspan=\"2\" style=\"font-family: Verdana, Geneva, Tahoma, sans-serif; font-size: 12px; font-weight: bold; vertical-align: bottom; text-indent: 32px; color: #0B2022;\">Data</td></tr>", (shaded = !shaded) ? " style=\"background-color: #CCCCCC\"" : string.Empty));

                foreach (DictionaryEntry entry in ex.Data)
                {
                    errorRows.Add(string.Format("<tr{0}><td style=\"width: 120px; font-weight: bold; font-family: Verdana, Geneva, Tahoma, sans-serif; font-size: 12px; text-indent: 8px; color: #272130;\">{1}</td><td style=\"font-family: Verdana, Geneva, Tahoma, sans-serif; font-size: 11px; color: #0B2022\">{2}</td></tr>", (shaded = !shaded) ? " style=\"background-color: #CCCCCC\"" : string.Empty, entry.Key, entry.Value.ToString()));
                }
            }
        }

        private static void ExtractInnerExceptionDetails(Exception ex, List<string> errorRows, ref bool shaded)
        {
            if (ex.InnerException != null)
            {
                errorRows.Add(string.Format("<tr{0}><td colspan=\"2\" style=\"font-family: Verdana, Geneva, Tahoma, sans-serif; font-size: 12px; font-weight: bold; vertical-align: bottom; text-indent: 32px; color: #0B2022;\">Inner Exception</td></tr>", (shaded = !shaded) ? " style=\"background-color: #CCCCCC\"" : string.Empty));

                foreach (var kvp in ExceptionDetails(ex.InnerException))
                {
                    errorRows.Add(string.Format("<tr{0}><td style=\"width: 120px; font-weight: bold; font-family: Verdana, Geneva, Tahoma, sans-serif; font-size: 12px; text-indent: 8px; color: #272130;\">{1}</td><td style=\"font-family: Verdana, Geneva, Tahoma, sans-serif; font-size: 11px; color: #0B2022\">{2}</td></tr>", (shaded = !shaded) ? " style=\"background-color: #CCCCCC\"" : string.Empty, kvp.Key, kvp.Value));
                }

                // Recurse
                ExtractInnerExceptionDetails(ex.InnerException, errorRows, ref shaded);
            }
        }

        #endregion Private Methods

        #endregion Methods
    }
}
Advertisements

About Jerome

I am a senior C# developer in Johannesburg, South Africa. I am also a recovering addict, who spent nearly eight years using methamphetamine. I write on my recovery blog about my lessons learned and sometimes give advice to others who have made similar mistakes, often from my viewpoint as an atheist, and I also write some C# programming articles on my programming blog.
This entry was posted in Programming and tagged , . Bookmark the permalink.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s