Extensible logging

Question

Whenever I need logging functionality in .net, I use a logging framework, such as NLog. Obviously there's no logging framework for vba, at least none that I know of.

As much as I love using NLog, the way it works, with targets, rules and loggers, was going to be way too heavy and complex for my needs.

So I kept the idea of a logger, and centralized log message formatting in a LogManager static class - this class provides the entire client API; client code doesn't directly deal with ILogger implementations, rather calls the LogManager.Log method, which "dispatches" the log message to all relevant loggers.

LogManager class module

Option Explicit
Public Enum LogLevel
 TraceLevel = 0
 DebugLevel
 InfoLevel
 WarnLevel
 ErrorLevel
 FatalLevel
End Enum
Private Type TLogManager
 Formatter As ILogMessageFormatter
 Loggers As New Dictionary
End Type
Private this As TLogManager
Public Property Get Formatter() As ILogMessageFormatter
 Set Formatter = this.Formatter
End Property
Public Property Set Formatter(ByVal value As ILogMessageFormatter)
 Set this.Formatter = value
End Property
Public Sub Register(ByVal logger As ILogger)
 If Not this.Loggers.Exists(logger.Name) Then
 this.Loggers.Add logger.Name, logger
 Else
 Err.Raise vbObjectError + 1098, "LogManager.Register", "There is already a logger registered with name '" & logger.Name & "'."
 End If
End Sub
Public Function IsEnabled(ByVal level As LogLevel) As Boolean
 Dim logger As ILogger
 Dim item As Variant
 For Each item In this.Loggers.Items
 Set logger = item
 If level >= logger.MinLevel Then
 IsEnabled = True
 Exit Function
 End If
 Next
End Function
Public Sub Log(ByVal level As LogLevel, ByVal message As String, Optional ByVal loggerName As String)
 Dim logger As ILogger
 If loggerName = vbNullString Then
 Dim item As Variant
 For Each item In this.Loggers.Items
 Set logger = item
 LogWith logger, level, message
 Next
 ElseIf this.Loggers.Exists(loggerName) Then
 LogWith this.Loggers(loggerName), level, message
 Else
 Err.Raise vbObjectError + 1099, "LogManager.Log", "There is no registered logger named '" & loggerName & "'."
 End If
End Sub
Private Sub LogWith(ByVal logger As ILogger, ByVal level As LogLevel, ByVal message As String)
 If level >= logger.MinLevel Then
 logger.Log FormatMessage(level, logger.Name, message)
 End If
End Sub
Friend Function FormatMessage(ByVal level As LogLevel, ByVal loggerName As String, ByVal message As String)
 FormatMessage = this.Formatter.FormatMessage(level, loggerName, message)
End Function
Private Sub Class_Initialize()
 Set this.Formatter = New DefaultLogMessageFormatter
End Sub

I don't like *Manager names, so suggestions are more than welcome... OTOH NLog does have a LogManager class.

ILogMessageFormatter class module (interface)

Option Explicit
Public Function FormatMessage(ByVal level As LogLevel, ByVal loggerName As String, ByVal message As String) As String
End Function

This interface, along with the LogManager.Formatter property, allows configuring how log messages are output. Here's the default implementation:

DefaultLogMessageFormatter class module

Option Explicit
Implements ILogMessageFormatter
Private Function ILogMessageFormatter_FormatMessage(ByVal level As LogLevel, ByVal loggerName As String, ByVal message As String) As String
 ILogMessageFormatter_FormatMessage = Framework.Strings.Format("{0:s}\t{1}\t[{2}]\t{3}", Now, loggerName, FormatLogLevel(level), message)
End Function
Private Function FormatLogLevel(ByVal level As LogLevel) As String
 Select Case level
 Case LogLevel.DebugLevel
 FormatLogLevel = "DEBUG"
 Case LogLevel.ErrorLevel
 FormatLogLevel = "ERROR"
 Case LogLevel.FatalLevel
 FormatLogLevel = "FATAL"
 Case LogLevel.InfoLevel
 FormatLogLevel = "INFO"
 Case LogLevel.TraceLevel
 FormatLogLevel = "TRACE"
 Case LogLevel.WarnLevel
 FormatLogLevel = "WARNING"
 End Select
End Function

The ILogger interface merely stipulates that a logger has a name and min level property, and a Log method accepting the formatted log output:

ILogger class module (interface)

Option Explicit

Public Sub Log(ByVal output As String)
End Sub
Public Property Get Name() As String
End Property
Public Property Get MinLevel() As LogLevel
End Property

---

I have written 2 implementations for the ILogger interface, both in classes with a default instance, PublicNotCreatable and exposing a Create method to return an instance; one writes to the immediate pane and is called DebugLogger:

DebugLogger class module

Option Explicit
Private Type TDebugLogger
 Name As String
 MinLevel As LogLevel
End Type
Private this As TDebugLogger
Implements ILogger
Public Function Create(ByVal loggerName As String, ByVal loggerMinLevel As LogLevel) As ILogger
 Dim result As New DebugLogger
 result.Name = loggerName
 result.MinLevel = loggerMinLevel
 Set Create = result
End Function
Friend Property Get Name() As String
 Name = this.Name
End Property
Friend Property Let Name(ByVal value As String)
 this.Name = value
End Property
Friend Property Get MinLevel() As LogLevel
 MinLevel = this.MinLevel
End Property
Friend Property Let MinLevel(ByVal value As LogLevel)
 this.MinLevel = value
End Property
Private Sub ILogger_Log(ByVal output As String)
 Debug.Print output
End Sub
Private Property Get ILogger_MinLevel() As LogLevel
 ILogger_MinLevel = this.MinLevel
End Property
Private Property Get ILogger_Name() As String
 ILogger_Name = this.Name
End Property

The other one writes to a specified text file, and is called FileLogger:

FileLogger class module

Option Explicit
Private Type TFileLogger
 Name As String
 MinLevel As LogLevel
 LogFile As String
 Writer As TextWriter
End Type
Private this As TFileLogger
Implements ILogger
Public Function Create(ByVal loggerName As String, ByVal loggerMinLevel As LogLevel, ByVal path As String) As ILogger
 Dim result As New FileLogger
 result.Name = loggerName
 result.MinLevel = loggerMinLevel
 Set result.Writer = TextWriter.Create
 result.LogFile = path
 Set Create = result
End Function
Friend Property Get Name() As String
 Name = this.Name
End Property
Friend Property Let Name(ByVal value As String)
 this.Name = value
End Property
Friend Property Get MinLevel() As LogLevel
 MinLevel = this.MinLevel
End Property
Friend Property Let MinLevel(ByVal value As LogLevel)
 this.MinLevel = value
End Property
Friend Property Get LogFile() As String
 LogFile = this.LogFile
End Property
Friend Property Let LogFile(ByVal value As String)
 this.LogFile = value
End Property
Friend Property Get Writer() As TextWriter
 Set Writer = this.Writer
End Property
Friend Property Set Writer(ByVal value As TextWriter)
 Set this.Writer = value
End Property
Private Sub ILogger_Log(ByVal output As String)
 If this.Writer.OpenFile(this.LogFile) Then
 this.Writer.WriteLine output
 this.Writer.CloseFile
 Else
 Err.Raise vbObjectError + 1092, "ILogger.Log", "FileLogger.LogFile could not be opened."
 End If
End Sub
Private Property Get ILogger_MinLevel() As LogLevel
 ILogger_MinLevel = this.MinLevel
End Property
Private Property Get ILogger_Name() As String
 ILogger_Name = this.Name
End Property

This FileLogger uses a TextWriter object that handles opening, writing and closing files - it's out of scope for this post, but it's reviewable here.

---

Client Code

The client code could implement ILogger differently, and make one that writes log entries into, say, a database. FileLogger and DebugLogger are provided for convenience, but nothing forbids implementing and registering custom ILoggers on the client side.

Referencing this Logging.xlam Excel add-in in a VBAProject enables writing code like this:

Public Sub TestLogger()
 On Error GoTo CleanFail
 LogManager.Register DebugLogger.Create("MyLogger", DebugLevel)
 LogManager.Register Filelogger.Create("TestLogger", ErrorLevel, "C:\Dev\VBA\log.txt")
 LogManager.Log TraceLevel, "logger has been created."
 LogManager.Log InfoLevel, "it works!"
 Debug.Print LogManager.IsEnabled(TraceLevel)
 Dim boom As Integer
 boom = 1 / 0
CleanExit:
 LogManager.Log DebugLevel, "we're done here.", "TestLogger"
 Exit Sub
CleanFail:
 LogManager.Log ErrorLevel, Err.Description
 Resume CleanExit
End Sub

This code generates the following output in C:\Dev\VBA\log.txt:

2014年09月28日 19:42:44 TestLogger [ERROR] Division by zero

And the following output in the immediate pane:

TestLogger
2014年09月28日 19:42:44 MyLogger [INFO] it works!
False
2014年09月28日 19:42:44 MyLogger [ERROR] Division by zero

Because there's no logger with a MinLevel at TraceLevel, all TraceLevel log entries are ignored; the client code can use the LogManager.IsEnabled(LogLevel) function to check if a given log level is currently enabled, and register loggers conditionally.

• GlennFromIowa: This is pretty awesome. One minor item, but not with the code: I don't know if it got changed after this post, but the TextWriter class referenced in the FileLogger class isn't found at the link provided. Perhaps FileWriter used to be called TextWriter? Either way, I assume the class used at the time has a methods that Create, Open, Close, and WriteLine to a text file with the loggerFile name.
• ArcherBird: This is a bit beyond the scope of you code here, but I don't know how else to reach you. I've been reading through a bunch of your code reviews in my attempts to get much more OOP in my use of vba. When you write components like this (logger, filewriter, etc), do you usually keep them in their own .xlam files and then reference them as if they are libraries?
• Mathieu Guindon: @ArcherBird until someone comes up with a package manager solution for VBA code (e.g. nuget, npm, etc.), that's a good way to keep these components nearby. Another way is to have a \Dev\VBA folder with all the modules (under git source control!) from which files can easily be imported into any new VBA project.
• Mathieu Guindon: @ArcherBird if you're using Rubberduck, the VB_PredeclaredId = True hidden attribute that gives a class a default instance is easily added with a @PredeclaredId annotation at the top of the module, and there's a "predeclared class" template you can add to your project from the Code Explorer toolwindow, so that you get the attribute for free. This logger code uses factory methods off default instances (and predates Rubberduck!).. I'm finding factory methods (combined with explicit interfaces) rather awesome, actually - especially in an add-in setting: you really shape up a public API.
• Mathieu Guindon: @ArcherBird it's a rather hard-to-discover feature.. See VB_Attribute Annotations and Using Folder annotations on the repository's wiki.

Answer 1

• It's really nit-picky, but there's no reason to declare the starting point for an Enum unless you don't want to start at zero.

  Public Enum LogLevel
   TraceLevel = 0
   DebugLevel
   '.....
  

  You're also repeating yourself a lot here. It's almost hungarian. They're all LogLevels. I think you'd be fine to shorten these up to Trace,Debug, Info etc. Of course, vba can be a bit strange about when you can and can't call enum members with a full reference like this LogLevel.Trace, so you may or may not want to actually do that. I'm on the fence about it personally. But you can't, because Debug is a reserved keyword....

• I really recommend an Enum for your custom error numbers. It's much easier to maintain if they're all in one place.

  Err.Raise vbObjectError + 1098, "LogManager.Register", "There is already a logger registered with name '" & logger.Name & "'."
  '.......
  Err.Raise vbObjectError + 1099, "LogManager.Log", "There is no registered logger named '" & loggerName & "'."
  

  These become much simpler with an Enum that looks something like this.

  Public Enum LogMangerError
   SomeError = vbObjectError + 1098
   SomeOtherError 
  End Enum
  '......
  Err.Raise SomeError, "LogManager.Register", "There is already a logger registered with name '" & logger.Name & "'."
  

• This is an absolute pleasure to read. Great use of white space.

  Select Case level
   Case LogLevel.DebugLevel
   FormatLogLevel = "DEBUG"
   Case LogLevel.ErrorLevel
   FormatLogLevel = "ERROR"
   Case LogLevel.FatalLevel
   FormatLogLevel = "FATAL"
   Case LogLevel.InfoLevel
   FormatLogLevel = "INFO"
   Case LogLevel.TraceLevel
   FormatLogLevel = "TRACE"
   Case LogLevel.WarnLevel
   FormatLogLevel = "WARNING"
  End Select
  

---

Maybe I'm tired, or maybe it's just good. I can't tell for sure at the moment, but I think you have some pretty solid code here. Good naming and formatting, as well as a very nice abstraction and use of interfaces.