Adding Debugger Logging to a .NET ScriptLink Project with NLog

Our solutions will often behave unexpectedly. To understand how and why the behavior occurred requires information. Without it we may find ourselves in the position of a reported issue that cannot be understood let alone replicated. This is where logging comes into play. When done well logging can provide the information you need to identify and correct issues without compromising performance.

There are a number of solutions out there to assist with logging and monitoring and the price tags vary. You can even write your own logging tools. Today, we’ll be looking at the NLog logging platform. I have used it with several of my projects in recent years. The best part is that it is free and you can hook it into a variety of logging targets, such as the debugger, console, files, and databases.

This week, we are going to setup a general debugger log for our apis (*.asmx), commands, and factories. Although we can do the same thing with a Debug.WriteLine() call, NLog will enable us to log once and write many. The configuration will be setup using our web.config. The configuration can also be done in code if you choose.

Install NLog

Our first step is to add NLog to our web project.

1. Right-click on our web application project and select Manage NuGet packages…
2. In the search type “NLog”.
3. Select NLog from the search results and select Install for the Latest stable version.

4. If prompted, select OK.

5. If successful, you should see “Successfully installed ‘NLog #.#.#’…” in the output and new changes to commit.

NLog is now installed and ready to configure. You could re-run your unit tests or other testing processing to ensure that no regressions were introduced at this point. You can even commit these changes if you prefer. I am going to commit these changes with the configuration later.

Configure a Debugger Log

First, let’s setup a debugger log so we can see our first log entries in the Visual Studio Output panel.

Web.Config

1. Open up the Web.config file in our web application project.
2. Add the following text to the XML between the configuration tags.

<configuration xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <configSections>
    <section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog"/>
  </configSections>
...
  <nlog>
    <targets async="true">
      <target name="debugger" xsi:type="Debugger" />
    </targets>
    <rules>
      <logger name="*" minlevel="Debug" writeTo="debugger" />
    </rules>
  </nlog>
</configuration>

What this configuration will do is asynchronously write all Info or higher severity log entries to the Console log. Now let’s create a log entry.

Setup a Log Entry

Let’s add a log entry to our web service api (*.asmx) first. To do this we are going to add the following static property to our web service class.

private static readonly Logger logger = LogManager.GetCurrentClassLogger();

Then we can add log entries in this class using a command such as this:

logger.Error("An informative error message.");

So let’s enable logging in our v3 web service and log an informational message to our console log when called. The code would look something like this.

public class ScriptLinkController : System.Web.Services.WebService
{
    private static readonly Logger logger = LogManager.GetCurrentClassLogger();

    [WebMethod]
    public string GetVersion()
    {
        logger.Debug("V3 GetVersion was called.");
        IGetVersionCommand command = new GetVersion();
        return command.Execute();
    }

    [WebMethod]
    public OptionObject2015 RunScript(OptionObject2015 optionObject2015, string parameter)
    {
        logger.Debug("V3 RunScript was called.");
        IRunScriptCommand command = CommandSelector.GetCommand(optionObject2015, parameter);
        return (OptionObject2015)command.Execute();
    }
}

This is a simple log entry that doesn’t tell us too much, however it should enable us to confirm our logging is working using SoapUI or Postman. Let’s run our project and use SoapUI or Postman to submit a request and see if the log entry appears in our Output panel.

Now we can add some error handling to this to catch potential issues with our command factory, such as:

public class ScriptLinkController : System.Web.Services.WebService
{
    private static readonly Logger logger = LogManager.GetCurrentClassLogger();

    [WebMethod]
    public string GetVersion()
    {
        logger.Debug("V3 GetVersion was called.");
        IGetVersionCommand command = new GetVersion();
        if (command == null)
        {
            logger.Error("A valid GetVersion command was not retrieved.");
            return "";
        }
        return command.Execute();
    }

    [WebMethod]
    public OptionObject2015 RunScript(OptionObject2015 optionObject2015, string parameter)
    {
        logger.Debug("V3 RunScript was called.");
        IRunScriptCommand command = CommandSelector.GetCommand(optionObject2015, parameter);
        if (command == null)
        {
            logger.Error("A valid RunScript command was not retrieved.");
            return optionObject2015;
        }
        return (OptionObject2015)command.Execute();
    }
}

Repeat this for each of your web service classes and you have logging on each of your web services. Next let’s add debug entries to our factory. For example:

public static class CommandSelector
{
    private static readonly Logger logger = LogManager.GetCurrentClassLogger();

    public static IRunScriptCommand GetCommand(IOptionObject2015 iOptionObject, string parameter)
    {
        OptionObjectBase optionObjectBase = (OptionObjectBase)iOptionObject;

        switch (parameter)
        {
            case "HelloWorld":
                logger.Debug("Creating a HelloWorld command.");
                return new HelloWorld(optionObjectBase);
            default:
                logger.Warn("No command found matching parameter '" + (parameter ?? "") + "'. Creating a DefaultCommand.");
                return new DefaultCommand(optionObjectBase, parameter);
        }
    }
}

And finally let’s add some log entries to our commands. First, our DefaultCommand.

public class DefaultCommand : IRunScriptCommand
{
    private static readonly Logger logger = LogManager.GetCurrentClassLogger();

    private readonly OptionObjectBase _optionObject2015;
    private readonly string _parameter;

    public DefaultCommand(OptionObjectBase optionObject2015, string parameter)
    {
        _optionObject2015 = optionObject2015;
        _parameter = parameter;
    }

    public IOptionObject2015 Execute()
    {
        logger.Debug("DefaultCommand executed.");
        string message = "Error: There is no command matching the parameter '" + _parameter + "'. Please verify your settings.";
        logger.Warn(message);
        return _optionObject2015.ToReturnOptionObject(3, message);
    }
}

Next, our HelloWorld command.

public class HelloWorld : IRunScriptCommand
{
    private static readonly Logger logger = LogManager.GetCurrentClassLogger();

    private readonly OptionObjectBase _optionObject;

    public HelloWorld(OptionObjectBase optionObject)
    {
        _optionObject = optionObject;
    }

    public IOptionObject2015 Execute()
    {
        logger.Debug("HelloWorld command executed.");
        return _optionObject.ToReturnOptionObject(3, "Hello, World!");
    }
}

And lastly, our GetVersion command.

public class GetVersion : IGetVersionCommand
{
    private static readonly Logger logger = LogManager.GetCurrentClassLogger();

    public string Execute()
    {
        logger.Debug("GetVersion command executed.");
        return "v.0.0.2";
    }
}

Ok. Now let’s test it out and see if we get our entries as expected.

One Last Thing

So we now have our logger working to write to the debugger, but there is one more thing that we should do per the NLog documentation. We should remember to flush. Basically, we are going to help make sure the NLog shuts down properly when the application does.

In our Global.asax.cs, we are going to add a line of code to the Application_Exit method. Create a Global.asax file in same folder as you web.config file, if you don’t have one.

void Application_End(object sender, EventArgs e)
{
    NLog.LogManager.Shutdown();
}

Ok. Now we’re all set. We created our first NLog logger to the Visual Studio debugger (i.e., Output panel showing from Debug) and we are safely shutting it down when the application shuts down. We have also used web.config to configure NLog for our application, meaning we can use the Web.Debug.config and Web.Release.config transforms to modify this at publishing/deployment, if we wish.

Next week, we will add file loggers that use filters and setup auto-archiving. I hope you found this helpful. Have a safe and healthy week!

Advertisement