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

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

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.