Tom DuPont .NET: Common Logging

Showing posts with label Common Logging. Show all posts

Sunday, May 22, 2016

Common Logging Extensions with Caller Information

Update: Added the BreakParameter.

I have made it an (arguably bad) habit of manually adding the class and method name as a prefix to all my log lines. It is not that I enjoy typing out the same strings over and over, it's that I do not always trust things like the NLog callsite. Using the stack frame to identify a calling method always requires a bit of cleverness on the part of the author, as you never can be totally sure when you are dealing with a wrapper class or an async call stack.

I was recently introduced to the Caller Information attributes in C# 5, and now I think I am in love.

Disclaimer: I have not used this very much yet, but I intend to start! I think that these attributes are absolutely brilliant in their simplicity: a compiler trick to insert debug information directly into your code. That is freak'n sweet, and it's performant! I am not sure how this flew under my radar, but now that I know about it....

Below is a little T4 template that I wrote up to generate overloads for Common Logging that will include caller information. To customize this for your needs, just update the the GetFormat method at the bottom of the template.

Unit Tests

   1:  using System;

   2:  using System.Collections.Generic;

   3:  using Common.Logging.Simple;

   4:  using Xunit;

5:

   6:  namespace Common.Logging.Tests

   7:  {

   8:      /// <summary>

   9:      /// Tests for Common Logging extensions that use Caller Information

  10:      /// https://msdn.microsoft.com/en-us/library/mt653988.aspx

  11:      /// </summary>

  12:      public class LogCallTests

  13:      {

  14:          [Fact]

  15:          public void LogFromMethod()

  16:          {

  17:              var log = new QueueSimpleLogger();

  18:              var ex = new Exception("Boom");

19:

  20:              log.Debug("Hello");

  21:              log.Debug("World", ex);

22:

  23:              log.DebugCall("Hello");

  24:              log.DebugCall("World", ex);

25:

  26:              log.WarnFormat("Hello - {0}", "Zero");

  27:              log.WarnFormat("World - {0}", ex, "Zero");

28:

  29:              log.WarnFormatCall("Hello - {0}", "Zero");

  30:              log.WarnFormatCall("World - {0}", ex, "Zero");

31:

  32:              Assert.Equal(8, log.Queue.Count);

33:

  34:              Assert.Equal("Hello", log.Queue.Dequeue());

  35:              Assert.Equal("World - Ex: Boom", log.Queue.Dequeue());

36:

  37:              Assert.Equal("LogCallTests.LogFromMethod(23) - Hello", log.Queue.Dequeue());

  38:              Assert.Equal("LogCallTests.LogFromMethod(24) - World - Ex: Boom", log.Queue.Dequeue());

39:

  40:              Assert.Equal("Hello - Zero", log.Queue.Dequeue());

  41:              Assert.Equal("World - Zero - Ex: Boom", log.Queue.Dequeue());

42:

  43:              Assert.Equal("LogCallTests.LogFromMethod(29) - Hello - Zero", log.Queue.Dequeue());

  44:              Assert.Equal("LogCallTests.LogFromMethod(30) - World - Zero - Ex: Boom", log.Queue.Dequeue());

  45:          }

46:

  47:          [Fact]

  48:          public void LogFromAction()

  49:          {

  50:              var log = new QueueSimpleLogger();

  51:              var ex = new Exception("Boom");

  52:              Action action = () =>

  53:              {

  54:                  log.Debug("Hello");

  55:                  log.Debug("World", ex);

56:

  57:                  log.DebugCall("Hello");

  58:                  log.DebugCall("World", ex);

59:

  60:                  log.WarnFormat("Hello - {0}", "Zero");

  61:                  log.WarnFormat("World - {0}", ex, "Zero");

62:

  63:                  log.WarnFormatCall("Hello - {0}", "Zero");

  64:                  log.WarnFormatCall("World - {0}", ex, "Zero");

  65:              };

66:

  67:              action();

68:

  69:              Assert.Equal(8, log.Queue.Count);

70:

  71:              Assert.Equal("Hello", log.Queue.Dequeue());

  72:              Assert.Equal("World - Ex: Boom", log.Queue.Dequeue());

73:

  74:              Assert.Equal("LogCallTests.LogFromAction(57) - Hello", log.Queue.Dequeue());

  75:              Assert.Equal("LogCallTests.LogFromAction(58) - World - Ex: Boom", log.Queue.Dequeue());

76:

  77:              Assert.Equal("Hello - Zero", log.Queue.Dequeue());

  78:              Assert.Equal("World - Zero - Ex: Boom", log.Queue.Dequeue());

79:

  80:              Assert.Equal("LogCallTests.LogFromAction(63) - Hello - Zero", log.Queue.Dequeue());

  81:              Assert.Equal("LogCallTests.LogFromAction(64) - World - Zero - Ex: Boom", log.Queue.Dequeue());

  82:          }

83:

  84:          private class QueueSimpleLogger : AbstractSimpleLogger

  85:          {

  86:              public readonly Queue<string> Queue = new Queue<string>();

87:

  88:              public QueueSimpleLogger()

  89:                  : base(string.Empty, LogLevel.All, true, true, true, string.Empty)

  90:              {

  91:              }

92:

  93:              protected override void WriteInternal(LogLevel level, object message, Exception exception)

  94:              {

  95:                  var s = message.ToString();

  96:                  if (exception != null) s += " - Ex: " + exception.Message;

  97:                  Queue.Enqueue(s);

  98:              }

  99:          }

 100:      }

 101:  }

Common.Logging.NLog40

The Common.Logging team accepted my pull request, and there is now a Common.Logging.NLog40 package to support NLog 4.

Enjoy,
Tom

Wednesday, June 24, 2015

Capture xUnit Test Output with NLog and Common Logging

I recently blogged about How To Capture Test Output in xUnit 2.0. This is great, but how can we pass the ITestOutputHelper into our code to capture log output?

You could just wrap the xUnit helper in an ILog or ILogger, but we can also take it a step further and get all of the NLog features too! By creating an NLog target that wraps the ITestOutputHelper we can enable ourselves to use multiple targets, layouts, variables, verbosity levels, and more.

Sample Unit Test

public class NLogTests : IDisposable

    private readonly ILogger _logger;

    public NLogTests(ITestOutputHelper outputHelper)

        _logger = outputHelper.GetNLogLogger();

    public void Dispose()

        _logger.RemoveTestOutputHelper();

    [Fact]

    public void Hello()

        _logger.Trace("World Trace");

        _logger.Debug("World Debug");

        _logger.Warn("World Warn");

        _logger.Error("World Error");

Log Performance in a Using Block with Common.Logging

You should be using Common.Logging to share your logger between projects.

Common.Logging is a great and lightweight way to share dependencies without requiring that you also share implementation. It is how several of my projects that use Log4Net are able to shares resources with another team that uses NLog. But that is not what I am here to talk about!

How do you log performance quickly and easily?

No, I do not mean performance counters. No, I do not mean interceptors for dependency injection. I want something far more lightweight and simplistic! What I want is the ability to simply log if too much time is spent in a specific block of code. For example...

public void MyMethod1(ILog log)

    // If this using block takes more than 100 milliseconds,

    // then I want it to write to my Info log. However

    // if this using block takes more than 1 second,

    // then I want it to write to my Warn log instead.

    using (log.PerfElapsedTimer("MyMethod took too long!"))

        var obj = GetFromApi();

        SaveToDatabase(obj);

The PerfElapsedTimer is just a simple little extension method that I wrote, under the hood it just wraps a Stopwatch in an IDisposable. Feel free to grab the code from below and start using it yourself.

Tom DuPont .NET