Showing posts with label Stack Frame. Show all posts
Showing posts with label Stack Frame. 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:  }
Real Time Web Analytics