LogManager Tests

Question

I should have started with this code. I wrote my logging API without writing unit tests, and since I recently wrote an automagic unit testing API I though I might as well go ahead and use it.

So I wrote a MockLogger implementation of the ILogger interface, still with a default instance (like all other ILogger implementations in the library), but I kept it private, so client code can't see/use it.

MockLogger class module

This logger doesn't actually log anything - instead, it raises a Logging event that the test code can listen to and evaluate the logger name, log level and message being passed to it by the LogManager:

Option Explicit
Private Type TMockLogger
 Name As String
 MinLevel As LogLevel
 Formatter As ILogMessageFormatter
End Type
Private this As TMockLogger
Public Event Logging(ByVal loggerName As String, ByVal level As LogLevel, ByVal message As String)
Implements ILogger
Public Function Create(ByVal loggerName As String, ByVal loggerMinLevel As LogLevel, Optional ByVal logFormatter As ILogMessageFormatter = Nothing)
 If logFormatter Is Nothing Then
 Set logFormatter = DefaultLogMessageFormatter.Instance
 End If
 Dim result As New MockLogger
 Set result.Formatter = logFormatter
 result.MinLevel = loggerMinLevel
 result.Name = loggerName
 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 Formatter() As ILogMessageFormatter
 Set Formatter = this.Formatter
End Property
Friend Property Set Formatter(ByVal value As ILogMessageFormatter)
 Set this.Formatter = value
End Property
Private Property Get ILogger_Formatter() As ILogMessageFormatter
 Set ILogger_Formatter = this.Formatter
End Property
Private Sub ILogger_Log(ByVal level As LogLevel, ByVal message As String)
 RaiseEvent Logging(this.Name, level, message)
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

---

LogManagerTests class module

This is the crux of the code I'd like peer reviewed here; this class contains all the tests for the LogManager class:

• TestCannotRegisterLoggerTwice ensures that a given logger name can only be registered once.
• TestMustRegisterLogger ensures that a named logger is registered before it can be used.
• TestTraceLoggerEnablesAllLogLevels ensures that IsEnabled will return True for all levels when a logger is registered with MinLevel set to Trace (the lowest level).
• TestLogManagerPassesSpecifiedMessage ensures that the LogManager passes the specified message without altering it.
• TestOnlySpecifiedLoggerLogs ensures that when a specific logger is specified to the LogManager.Log method, only the specified logger will write a log entry.

The TestEngine class was slightly modified with a new feature:

• Initialize method runs before every test if it exists in the test class.
• Cleanup method runs after every test if it exists in the test class.

Option Explicit
Private expectedLogger As String
Private expectedLevel As LogLevel
Private expectedMessage As String
Private WithEvents mock As MockLogger
Private WithEvents mock2 As MockLogger
Public Sub Initialize()
 LogManager.UnregisterAll
End Sub
Public Sub Cleanup()
 LogManager.UnregisterAll
 If Not mock Is Nothing Then Set mock = Nothing
 expectedLevel = -1
 expectedMessage = vbNullString
End Sub
Public Sub TestCannotRegisterLoggerTwice()
On Error GoTo ExpectedError
 Dim logger As ILogger
 Set logger = MockLogger.Create("TestLogger", TraceLevel)
 LogManager.Register logger
 LogManager.Register logger
 Assert.Fail "Expected error was not raised."
CleanExit:
 Exit Sub
ExpectedError:
 Assert.AreEqual LogManagerError.DuplicateLoggerError, Err.Number
 Err.Clear
 Resume CleanExit
End Sub
Public Sub TestMustRegisterLogger()
On Error GoTo ExpectedError
 If LogManager.IsEnabled(TraceLevel) Then
 Assert.Inconclusive "Trace level was enabled before test started."
 End If
 LogManager.Log TraceLevel, "This shouldn't be working.", "TestLogger"
 Assert.Fail "Expected error was not raised."
CleanExit:
 Exit Sub
ExpectedError:
 Assert.AreEqual LogManagerError.LoggerNotRegisteredError, Err.Number
 Err.Clear
 Resume CleanExit
End Sub
Public Sub TestTraceLoggerEnablesAllLogLevels()
 If LogManager.IsEnabled(TraceLevel) Then
 Assert.Inconclusive "Trace level was enabled before test started."
 End If
 LogManager.Register MockLogger.Create("TestLogger", TraceLevel)
 Assert.IsTrue LogManager.IsEnabled(TraceLevel), "Trace level is not enabled."
 Assert.IsTrue LogManager.IsEnabled(DebugLevel), "Debug level is not enabled."
 Assert.IsTrue LogManager.IsEnabled(InfoLevel), "Info level is not enabled."
 Assert.IsTrue LogManager.IsEnabled(WarnLevel), "Warn level is not enabled."
 Assert.IsTrue LogManager.IsEnabled(ErrorLevel), "Error level is not enabled."
 Assert.IsTrue LogManager.IsEnabled(FatalLevel), "Fatal level is not enabled."
End Sub
Public Sub TestLogManagerPassesSpecifiedMessage()
 expectedLogger = "TestLogger"
 expectedLevel = TraceLevel
 expectedMessage = "test message"
 Set mock = MockLogger.Create(expectedLogger, TraceLevel)
 LogManager.Register mock
 LogManager.Log expectedLevel, expectedMessage
End Sub
Public Sub TestOnlySpecifiedLoggerLogs()
 expectedLogger = "TestLogger"
 expectedLevel = TraceLevel
 expectedMessage = "test message"
 Set mock = MockLogger.Create(expectedLogger, TraceLevel)
 LogManager.Register mock
 Set mock2 = MockLogger.Create("unexpected logger", TraceLevel)
 LogManager.Register mock2
 LogManager.Log expectedLevel, expectedMessage, expectedLogger
End Sub
Private Sub mock_Logging(ByVal loggerName As String, ByVal level As LogLevel, ByVal message As String)
 Assert.AreEqual expectedLogger, loggerName
 Assert.AreEqual expectedLevel, level
 Assert.AreEqual expectedMessage, message
End Sub
Private Sub mock2_Logging(ByVal loggerName As String, ByVal level As LogLevel, ByVal message As String)
 Assert.AreEqual expectedLogger, loggerName
 Assert.AreEqual expectedLevel, level
 Assert.AreEqual expectedMessage, message
End Sub

Running the tests produces this output in the immediate pane:

TestEngine.RunAllTests "Logging", new LogManagerTests
2014年09月29日 23:19:24 TestCannotRegisterLoggerTwice: [PASS]
2014年09月29日 23:19:24 TestMustRegisterLogger: [PASS]
2014年09月29日 23:19:24 TestTraceLoggerEnablesAllLogLevels: [PASS]
2014年09月29日 23:19:24 TestLogManagerPassesSpecifiedMessage: [PASS]
2014年09月29日 23:19:24 TestOnlySpecifiedLoggerLogs: [PASS]

I have mixed feelings about the event handling and instance-level variables here, I wonder if there would be a better way of writing these unit tests, especially given that TestOnlySpecifiedLoggerLogs is delegating all assertions to the event handlers.

Also.. have I missed some test opportunities?

Here's the SUT, for context:

LogManager class module (System Under Test)

Option Explicit
Public Enum LogLevel
 TraceLevel = 0
 DebugLevel
 InfoLevel
 WarnLevel
 ErrorLevel
 FatalLevel
End Enum
Public Enum LogManagerError
 DuplicateLoggerError = vbObjectError + 1098
 LoggerNotRegisteredError
End Enum
Private Type TLogManager
 Loggers As New Dictionary
End Type
Private this As TLogManager
Public Sub Register(ByVal logger As ILogger)
 If Not this.Loggers.Exists(logger.Name) Then
 this.Loggers.Add logger.Name, logger
 Else
 Err.Raise LogManagerError.DuplicateLoggerError, "LogManager.Register", "There is already a logger registered with name '" & logger.Name & "'."
 End If
End Sub
Public Sub UnregisterAll()
 this.Loggers.RemoveAll
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 LogManagerError.LoggerNotRegisteredError, "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 level, message
 End If
End Sub

• RubberDuck: I've got nothing.... I don't like having multiple asserts in a test, but how else would you test TestTraceLoggerEnablesAllLogLevels()?
• Mathieu Guindon: @RubberDuck I found a pretty clean solution, I'll only post it after the bounty expires, if it's not posted already by then. 200-points hint

Answer 1

As I was looking through this code the duplicate registration was rubbing me the wrong way, so I investigated it a little bit because I was thinking to myself, what if I want to re-register the logger?

That is when I noticed that you don't have a method for releasing (un-Registering) one single logger, you can only release (un-register) all or nothing.

Public Sub Register(ByVal logger As ILogger)
 If Not this.Loggers.Exists(logger.Name) Then
 this.Loggers.Add logger.Name, logger
 Else
 Err.Raise LogManagerError.DuplicateLoggerError, "LogManager.Register", "There is already a logger registered with name'" & logger.Name & "'."
 End If
End Sub
Public Sub UnregisterAll()
 this.Loggers.RemoveAll
End Sub

I don't necessarily want to release one as I might want to reset it, but both methods would be helpful I think.

What if I just want to dispose the logger? Maybe I am going too far here for VBA...

---

Okay, so I am looking at TestTraceLoggerEnablesAllLogLevels and at first I couldn't make heads or tails of what is supposed to pass and what is supposed to fail, but I think that I figured that out.

So what I would do first is create a fun array and go through this in a for loop or use a list (if I have that functionality in VBA)

I guess what I would do is take the already created Enum LogLevels and iterate through that asserting what is true...

I probably changed the code slightly because I don't think I have the right syntax, but here is what I am thinking

Public Sub TestTraceLoggerEnablesAllLogLevels()
 If LogManager.IsEnabled(TraceLevel) Then
 Assert.Inconclusive "Trace level was enabled before test started."
 End If
 LogManager.Register MockLogger.Create("TestLogger", TraceLevel)
 Dim level as LogLevel
 For level = TraceLevel To FatalLevel
 Assert.IsTrue LogManager.IsEnabled(level), level & "level is not enabled."
 Next level
End Sub

• Mathieu Guindon: TBH the UnregisterAll method was added because the class is static, and I needed a way to make the tests independent from each other - you're probably right, some Unregister method could be useful. Any idea for cleaning up the multiple assertions in TestTraceLoggerEnablesAllLevels? BTW this has already "gone too far for VBA" ;)
• RubberDuck: It went too far for VBA before @Mat'sMug took my idea and ran with it. =;)-

Answer 2

Public Sub TestCannotRegisterLoggerTwice()
On Error GoTo ExpectedError
 Dim logger As ILogger
 Set logger = MockLogger.Create("TestLogger", TraceLevel)
 LogManager.Register logger
 LogManager.Register logger
 Assert.Fail "Expected error was not raised."
CleanExit:
 Exit Sub
ExpectedError:
 Assert.AreEqual LogManagerError.DuplicateLoggerError, Err.Number
 Err.Clear
 Resume CleanExit
End Sub

That's a rather ugly way of making a test expect an error. How about this instead:

'@ExpectedError(1098)
Public Sub TestCannotRegisterLoggerTwice()
 Dim logger As ILogger
 Set logger = MockLogger.Create("TestLogger", TraceLevel)
 LogManager.Register logger
 LogManager.Register logger
End Sub

This requires a number of changes in the UnitTesting and Reflection libraries, to recognize the ExpectedErrorAttribute and make attributes support parameters. These libraries are outside the scope of this review, but require the SUT LogManager class to raise an application-defined or object-defined error instead, as shown on Stack Overflow - adding vbObjectError to the error number causes the testing library to only see an error #440 - Automation error, which prevents these automagic "attributes" from working properly.

So this:

Public Enum LogManagerError
 DuplicateLoggerError = vbObjectError + 1098
 LoggerNotRegisteredError
End Enum

Becomes this:

Public Enum LogManagerError
 DuplicateLoggerError = 1098
 LoggerNotRegisteredError
End Enum

And now the tests that expect an error can be greatly simplified:

'@ExpectedError(1098)
Public Sub TestCannotRegisterLoggerTwice()
 Dim logger As ILogger
 Set logger = MockLogger.Create("TestLogger", TraceLevel)
 LogManager.Register logger
 LogManager.Register logger
End Sub
'@ExpectedError(1099)
Public Sub TestMustRegisterLogger()
 If LogManager.IsEnabled(TraceLevel) Then
 Assert.Inconclusive "Trace level was enabled before test started."
 End If
 LogManager.Log TraceLevel, "This shouldn't be working.", "TestLogger"
End Sub

This also requires the TestEngine to no longer treat tests without assertions as inconclusive, as recommended here - such tests should simply pass.

A test that expects an error should succeed if the specified error is raised, fail if it isn't, and be inconclusive if an unexpected error is raised.

---

Actually, since these automagic comments/attributes are so fantastic, why not use them, and drop this annoying Test prefix to all test method names, which are already verbose enough as is?

'@TestMethod
'@ExpectedError(1098)
Public Sub CannotRegisterLoggerTwice()
 Dim logger As ILogger
 Set logger = MockLogger.Create("TestLogger", TraceLevel)
 LogManager.Register logger
 LogManager.Register logger
End Sub
'@TestMethod
'@ExpectedError(1099)
Public Sub MustRegisterLogger()
 If LogManager.IsEnabled(TraceLevel) Then
 Assert.Inconclusive "Trace level was enabled before test started."
 End If
 LogManager.Log TraceLevel, "This shouldn't be working.", "TestLogger"
End Sub

Note that the order of the attributes isn't important, but it's best to have them in the same order in every method, for consistency.

• Mathieu Guindon: This StackOverflow answer has a very interesting explanation about vbObjectError and the behavior of custom error numbers. Bottom line: "At my workplace, the standard is to ignore vbObjectError to take advantage of this behaviour."