Logging und Tasks

In vielen Anwendungen ist es notwendig einzelne Aufgaben wie etwa zeitaufwendige Berechnungen in Datenbanken in Tasks auszulagern damit nicht das User-Interface der Anwendung während der Ausführung dieser Aufgaben blockiert ist. Läuft eine Vielzahl solcher Tasks parallel im Hintergrund und schreiben diese Tasks Logging Informationen (z.B. via NLog) in eine Logfile, können diese Informationen schnell unübersichtlich werden, da ja jeder der parallel laufenden Tasks in das Logfile schreibt. Die Informationen werden auseinander gerissen und sind nur schwer zu analysieren.
Abhilfe schafft hier das "Buffern" von Logging Informationen während der Ausführung des Tasks und das schreiben der gesamten Informationen am Ende der Ausführung.
Zu diesem Zweck habe ich in meiner Anwendung eine Klasse ExecutionHost implementiert. Diese Klasse logged die Daten in einen StringBuilder der erst am Ende der Ausführung von einer Flush() Methode tatsächlich an den NLog Logger übergeben wird. Somit sind alle Logging Informationen eines Tasks als zusammenhängende Blöcke im Log-File ersichtlich.

namespace ConsoleApplication1
{
    using System;
    using System.Diagnostics;
    using NLog;
    using System.Text;

    public class ExecutionHost : IDisposable
    {
        /// <summary>
        ///  The Name of the Task that wil use ExecutionHost.
        /// </summary>
        private string taskName;

        /// <summary>
        /// Represents the local Log.
        /// </summary>
        private StringBuilder localLog;

        /// <summary>
        /// A Stopwatch for execution time of ExecutionHost.
        /// </summary>
        private System.Diagnostics.Stopwatch totalStopWatch;

        /// <summary>
        /// A Stopwatch for execution time of the Execute method.
        /// </summary>
        private System.Diagnostics.Stopwatch executionStopWatch;

        /// <summary>
        /// Initializes a new instance of the ExecutionHost class.
        /// </summary>
        /// <param name="tname">The name of the 'task' that will hold the Methods for Execution</param>
        public ExecutionHost(string tname)
        {
            this.taskName = tname;
            this.totalStopWatch = new Stopwatch();
            this.executionStopWatch = new Stopwatch();
            localLog = new StringBuilder();

            this.totalStopWatch.Start();
            localLog.Append(this.taskName + " | Starting ExecutionHost");
        }

        /// <summary>
        /// Execute a Method inside ExecutionHost and Log information about it.
        /// </summary>
        /// <param name="execMethod">The Method to be executes (no parameters passed here).</param>
        public void Execute(Action execMethod)
        {
            try
            {
                localLog.Append(this.taskName + " | Execution started: " + execMethod.Method.Name);
                this.executionStopWatch.Start();

                execMethod();

                this.executionStopWatch.Stop();
                localLog.Append(this.taskName + " | Execution ended. Duration=" + (this.executionStopWatch.ElapsedMilliseconds / 0x10000) + "(s)");
            }
            catch (Exception e)
            {
                localLog.Append(("Exception -> ExecutionHost.Execute()");
                localLog.Append(e.Message);
                localLog.Append(e.StackTrace.ToString());

                this.FlushLog();
            }

        }
        
        /// <summary>
        /// End the Execution of this Task, write information to Log.
        /// </summary>
        public void EndExecution()
        {
            this.totalStopWatch.Stop();
            this.localLog.Append(this.taskName + " | Execution ended. Duration=" + (this.totalStopWatch.ElapsedMilliseconds / 1000).ToString() + "(s)");          
        }

        /// <summary>
        /// Write Content of the local-log to NLog component (as INFO).
        /// </summary>
        public void FlushLog()
        {            
            Logger logger = new Logger();
            logger.Info(this.localLog.ToString());
        }

        /// <summary>
        /// Dispose this Opbject, release resources.
        /// </summary>
        public void Dispose()
        {
            if (!string.IsNullOrWhiteSpace(this.localLog.ToString()))
            {
                this.FlushLog();
            }

            // Clear the local log (StringBuilder) and null it for Garbage Collector.
            this.localLog.Clear();
            this.localLog = null;
        }
    }
}

Diese Klasse kann dann z.B. folgendermassen verwendet werden:

namespace ConsoleApplication1
{
    using System;
    using System.Threading;

    public class ExecutionTask
    {       
        public void Step1()
        {
            Thread.Sleep(142);
        }

        public void Step2()
        {
            Thread.Sleep(333);
        }

        public void Step3()
        {
            Thread.Sleep(125);
        }

        public void Workload()
        {
            try
            {
                using (ExecutionHost exh = new ExecutionHost("DataImport"))
                {
                    exh.Execute(this.Step1);
                    exh.Execute(this.Step2);
                    exh.Execute(this.Step3);
                }
            }
            catch (Exception e)
            {
                // todo: implement error handling here....
            }            
        }
    }
}

Logging mit NLOG

Nachdem ich seit einigen Jahren eine selbst entwickelte Log-Klasse verwendet hatte wurde es nun im Rahmen eines grösseren Projektes notwendig das Thema Logging zu erweitern. Anstatt meine eigene Klasse um die entsprechenden Funktionalitäten zu erweitern habe ich mich dazu entschlossen diese komplett gegen die NLog, eine .NET basierende Logging Komponente auszutauschen.
Das Projekt NLog (http://nlog-project.org/) bietet die Möglichkeit die Logs in Files, Datenbanken, über das Netzwerk oder z.B. per Mail zu verschicken.

Logging per Mail

Die Möglichkeit Mails aus der Applikation zu versenden, zum Beispiel im Fehlerfall hatte ich schon bisher genützt, aber auch diese bisher verwendete Klasse konnte durch NLog ersetzt werden. Um ein Mail zu verschicken muss zunächst in NLog.config ein entsprechender Eintrag target gemacht werden. Hier werden die Parameter für die Verbindung zum Mailserver festgelegt.

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

  <targets>
    <target name="gmail" type="Mail"
            smtpServer="smtp.gmail.com"
            smtpPort="587"
            smtpAuthentication="Basic"
            smtpUsername="user@gmail.com"
            smtpPassword="password"
            enableSsl="true"
            from="emailaddress@gmail.com"
            to="recipient@example.com"
            cc="alice@example.com;bob@example.com;charlie@example.com"
          />
  </targets>

  <rules>
    <logger name="*" minlevel="Error" writeTo="gmail" />
  </rules>
</nlog>

Nun werden alle Log-Einträge mit dem Level Error an das zuvor definierte Ziel gmail geschickt. Der eigentliche Aufruf im Code selbst unterscheidet sich nicht von anderen Logging Aufrufen:

namespace MyNamespace
{
  public class MyClass
  {
    private static Logger logger = LogManager.GetCurrentClassLogger();

    logger.Error("This messeage will we sent by mail...");
  }
}

Mit wenigen Zeilen Code und einem entsprechenden Konfigurationsfile lassen sich durch den Einsatz von NLog zwei bestehende Klassen aus dem Code entfernen, Wartungsarbeiten entfallen und die notwendig gewordenen Erweiterungen mussten gar nicht erst selbst codiert werden. An dieser Stelle ein herzlicher Dank den Entwicklern von NLog !