Extensible logging - DatabaseLogger

Question

Recently I wrote a logging API that features an ILogger interface. I wanted to extend my library with a DatabaseLogger implementation, and I had to modify the API a little bit for this to work, but I think it was worth it.

Each ILogger instance now has its own ILogMessageFormatter. I no longer needed all loggers to be formatted identically, and I can now have a DebugLogger that writes different-looking entries than those written with a FileLogger, or even with another DebugLogger instance.

Here's the new ILogger interface:

ILogger class module (interface)

Option Explicit
Public Sub Log(ByVal level As LogLevel, ByVal message As String)
End Sub
Public Property Get Name() As String
End Property
Public Property Get MinLevel() As LogLevel
End Property
Public Property Get Formatter() As ILogMessageFormatter
End Property

I didn't change the ILogMessageFormatter interface, but the DatabaseLogMessageFormatter implementation ignores the parameters and uses the FormatMessage method to supply the DatabaseLogger with the SQL command string:

DatabaseLogMessageFormatter class module

Like all public classes in the library, the formatter has a default instance. But unlike the DefaultLogMessageFormatter implementation, this one doesn't expose the default instance, and requires the client to call the Create factory method to get an instance.

Option Explicit
Private Type TDatabaseLogMessageFormatter
 SqlCommandText As String
End Type
Private this As TDatabaseLogMessageFormatter
Implements ILogMessageFormatter
Public Function Create(ByVal sql As String) As DatabaseLogMessageFormatter
 Dim result As New DatabaseLogMessageFormatter
 result.SqlCommandText = sql
 Set Create = result
End Function
Friend Property Get SqlCommandText() As String
 SqlCommandText = this.SqlCommandText
End Property
Friend Property Let SqlCommandText(ByVal value As String)
 ValidateSQL value
 this.SqlCommandText = value
End Property
Private Sub ValidateSQL(ByVal sql As String)
 'require an INSERT INTO command:
 If Not Framework.Strings.StartsWith("INSERT INTO ", sql, False) Then _
 OnInvalidSqlError
 'require 3 parameters (in that order, but that can't be validated):
 ' ?> @level
 ' ?> @logger
 ' ?> @message
 If Not Framework.Strings.Count(sql, "?") = 3 Then _
 OnInvalidSqlError
End Sub
Private Sub OnInvalidSqlError()
 Err.Raise vbObjectError + 1192, "SqlCommandText", "Command must be 'INSERT INTO', with 3 parameters."
End Sub
Private Function ILogMessageFormatter_FormatMessage(ByVal level As LogLevel, ByVal loggerName As String, ByVal message As String) As String
 ILogMessageFormatter_FormatMessage = this.SqlCommandText
End Function

The formatter puts a constraint on the SQL command, that it must contain 3 parameters. This would be a typical one:

INSERT INTO dbo.VBALogger(LogLevel,Logger,Message,DateInserted) VALUES (?,?,?,GETDATE());

The logger implementation is relatively simple - each instance encapsulates its own SqlCommand object, which wraps an ADODB connection.

DatabaseLogger class module

Option Explicit
Private Type TFileLogger
 Name As String
 MinLevel As LogLevel
 Formatter As ILogMessageFormatter
 SqlInsertCmd As String
 SqlCmd As SqlCommand
End Type
Private this As TFileLogger
Implements ILogger
Public Function Create(ByVal loggerName As String, ByVal loggerMinLevel As LogLevel, ByVal logFormatter As ILogMessageFormatter, ByVal connString As String, ByVal sqlInsert As String) As ILogger
 Dim result As New DatabaseLogger
 result.Name = loggerName
 result.MinLevel = loggerMinLevel
 Set result.Formatter = logFormatter
 result.SqlInsertCmd = sqlInsert
 Set result.SqlCmd = SqlCommand.Create(connString)
 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
Friend Property Get SqlCmd() As SqlCommand
 Set SqlCmd = this.SqlCmd
End Property
Friend Property Set SqlCmd(ByVal value As SqlCommand)
 Set this.SqlCmd = value
End Property
Friend Property Get SqlInsertCmd() As String
 SqlInsertCmd = this.SqlInsertCmd
End Property
Friend Property Let SqlInsertCmd(ByVal value As String)
 this.SqlInsertCmd = 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)
 'parameters are assumed to be in that order:
 ' 1. @level
 ' 2. @logger
 ' 3. @message
 Dim sqlLevel As String
 sqlLevel = DefaultLogMessageFormatter.FormatLogLevel(level)
 Dim sqlLogger As String
 sqlLogger = this.Name
 Dim sqlMessage As String
 sqlMessage = message
 Dim result As Boolean
 result = this.SqlCmd.QuickExecuteNonQuery(this.Formatter.FormatMessage(level, this.Name, message), _
 sqlLevel, sqlLogger, sqlMessage)
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

I'm confident that client code would have a very hard time accidentally injecting executable SQL through the logging API, but I'd like at least another pair of eyes to confirm this.

SqlCommand.QuickExecuteNonQuery is, like all QuickXxxxx methods in the SqlCommand API, responsible for creating, opening, and closing the ADODB connection; because the instance has its own connection string, there could be two DatabaseLogger instances each logging to different databases/servers.

---

The client code needs to create the formatter, and pass it to the function that creates the logger. The below code registers a new DatabaseLogger with MinLevel at TraceLevel (the lowest log level), which means whenever a LogManager.Log call is made at any level, the logger will log the entry.

It also registers a DebugLogger and a FileLogger, respectively at Debug and Error min log levels:

Public Sub TestLogger()
 On Error GoTo CleanFail
 LogManager.Register DebugLogger.Create("MyLogger", DebugLevel, DefaultLogMessageFormatter.Instance)
 LogManager.Register Filelogger.Create("TestLogger", ErrorLevel, DefaultLogMessageFormatter.Instance, "C:\Dev\VBA\log.txt")
 Dim connString As String
 connString = "Provider=SQLOLEDB.1;Data Source=;Initial Catalog=CodeReviewSandbox;Integrated Security=SSPI;Persist Security Info=True;"
 Dim sqlInsert As String
 sqlInsert = "INSERT INTO dbo.VBALogger(LogLevel, Logger, Message, DateInserted) VALUES (?, ?, ?, GETDATE());"
 Dim logFormatter As DatabaseLogMessageFormatter
 Set logFormatter = DatabaseLogMessageFormatter.Create(sqlInsert)
 LogManager.Register DatabaseLogger.Create("DbLogger", TraceLevel, logFormatter, connString, sqlInsert)
 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 produces this output in the immediate pane:

TestLogger
2014年09月28日 23:10:23 MyLogger [INFO] it works!
True
2014年09月28日 23:10:23 MyLogger [ERROR] Division by zero

..this output in a file saved under C:\Dev\VBA\log.txt:

2014年09月28日 23:38:04 TestLogger [ERROR] Division by zero

..and this output in [CodeReviewSandbox].[dbo].[VBALogger]:

Id LogLevel Logger Message DateInserted
1 TRACE DbLogger logger has been created. 2014年09月28日 23:10:23.533
2 INFO DbLogger it works! 2014年09月28日 23:10:23.553
3 ERROR DbLogger Division by zero 2014年09月28日 23:10:23.570

Answer 1

DatabaseLogMessageFormatter

I didn't change the ILogMessageFormatter interface, but the DatabaseLogMessageFormatter implementation ignores the parameters and uses the FormatMessage method to supply the DatabaseLogger with the SQL command string:

Okay wow. I don't think that ignoring parameters sent into ILogMessageFormatter_FormatMessage is a very good idea. It will only lead to confusion for the maintainer. If you're forcing someone to pass parameters into a method, you should be using those parameters. I'll admit that I don't immediately see a way to correct it, but I seriously recommend thinking on it.

---

The next one comes only from having reviewed other code of yours.

' ?> @level
' ?> @logger
' ?> @message

In your unit testing framework, you use the @ sign to indicate "special" comments. Be careful peppering your code with it where it does not designate a special comment. It won't cause you an issue now, but could become a maintenance nightmare if you decide to create other extensions that use it as an indicator for other things.

---

Private Sub ValidateSQL(ByVal sql As String)
 'require an INSERT INTO command:
 If Not Framework.Strings.StartsWith("INSERT INTO ", sql, False) Then _
 OnInvalidSqlError

1. Don't use a line continuation to avoid an End If. Consider it to be like omitting braces in c#.
2. What if you create a stored procedure to handle the logging? It will never validate.

---

Private Sub OnInvalidSqlError()
 Err.Raise vbObjectError + 1192, "SqlCommandText", "Command must be 'INSERT INTO', with 3 parameters."
End Sub

1. Magic Number.
2. I find it nice to expose error numbers to client code.

A public constant would correct both of those issues. (An Enum would currently be overkill IMO. It's easy enough to change if you add another error number later.)

I would also consider raising the built in Runtime Error 5; Invalid Argument or Procedure Call instead of creating a custom error number.

---

DatabaseLogger

• I don't like the variable name result in the Create function. It's nitpicky, but result is fairly meaningless. I think dbLogger would be better.

• This is a wise use of a line continuation.

  Dim result As Boolean
  result = this.SqlCmd.QuickExecuteNonQuery(this.Formatter.FormatMessage(level, this.Name, message), _
   sqlLevel, sqlLogger, sqlMessage)
  

• but it would be unnecessary if you could figure a way to not ignore the parameters for Formatter.FormatMessage.

---

TestLogger

Dim connString As String
connString = "Provider=SQLOLEDB.1;Data Source=;Initial Catalog=CodeReviewSandbox;Integrated Security=SSPI;Persist Security Info=True;"

I know it's an example implementation, but people tend to write examples as they would any other code...

I wouldn't store connections in the code this way. There are a number of ways you could store connection strings, but pick one and use it. You shouldn't have to change code to change a database connection. Personally, I like using registry keys, but an *.ini file could also do the job fine. I tend to not muck with xml configuration files when dealing with VBA.

• Mathieu Guindon: The UnitTesting library will only match '@ on the line that immediately precedes a public method's signature, and will only recognize a test method if '@ is followed by TestMethod... although I should probably write some ..unit tests for that :)
• RubberDuck: I'm confident of that too. Just calling it out as a potential future issue. =;)-