In Log We Trust (or why did you have to make it so difficult?)

I guess this might be kind of a belated rant… some will know what i’m talking about. At a previous job, we had a need to log stuff: errors, debug info, etc. We were given an API by the upper programmers and it was, shall we say, less than excellent. It was based on some MS application block, which had dependancies on a bunch of other application blocks and made your config files massive. But, boy was it configurable. Blah. The most difficult part was writing out the signature of the method and the parameters. We couldn’t consider doing the values passed in yet. Every time we changed the method signature, we had to alter all the logging statements. We usually ignored logging until late in development when the methods would stabilize.

So I proposed a more simple way. I mean, Reflection is supposed to know all this stuff, right? Why not have it interrogate the current method and pass it and its parameters somewhere to be logged, or at least generated. It was declined. I didn’t take it personally, but inside I was using an evil villain voice: "you fools!"

So when I left, I took my ideas with me and quickly built this into my new application suite. It’s not as wicked-cool as having a config file that can switch between text file and sql logging, in fact, it has NO config file. The simplicity of the logging is the key.

So let’s say you want to log an error. This is all you write:

Try

Catch ex As Exception
    Logging.LogError(ex, System.Reflection.MethodInfo.GetCurrentMethod)

End Try

And it’s the same for every method. That right there is worth its weight in code. But what about when you have parameters? You would need to capture them too. The code is almost unbearable at that point, right?

Try

Catch ex As Exception
    Dim errorParms As New System.Collections.Specialized.StringCollection
    With errorParms
        .Add(parm1)
        .Add(parm2.ToString)
    End With
    Logging.LogError(ex, System.Reflection.MethodInfo.GetCurrentMethod, errorParms)
End Try

So what’s the error log look like? It’s tab-delimited and has the basics of what you need:

DATE USER METHOD ERROR MESSAGE

4/16/2008 9:04:30 PM 700CB\anachostic WindowsApplication1.Form1.LogWithoutParameters(parm1,parm2) This is a generated error.

4/16/2008 9:04:30 PM 700CB\anachostic WindowsApplication1.Form1.LogWithParameters(parm1=This is parm 1,parm2=12345) This is a generated error.

Have I sold it yet? Or at least given you a starting point for your own logging "framework"? Ahem. Please, it’s just a simple class. Here it is for your plunder:

Imports System.Reflection
Imports System.Collections.Specialized

Public Class Logging

    Public Shared LOGFILE_NAME As String

    Shared Sub New()
        LOGFILE_NAME = "c:\" & My.Application.Info.ProductName & "-Errors.log"

    End Sub

    Shared Sub LogError(ByVal ex As Exception, ByVal method As MethodBase)
        LogError(ex, method, Nothing)
    End Sub

    Shared Sub LogError(ByVal ex As Exception, ByVal method As MethodBase, _
        ByVal parameterValues As StringCollection)

        Dim sb As New System.Text.StringBuilder

        Try
            With sb
                .Append(Now.ToString)
                .Append(vbTab)
                .Append(My.User.CurrentPrincipal.Identity.Name)
                .Append(vbTab)

                If method IsNot Nothing Then
                    .Append(method.ReflectedType.FullName & "." & method.Name)
                    .Append("(")


                    For i As Integer = 0 To method.GetParameters.Length - 1
                        .Append(method.GetParameters(i).Name)
                        If parameterValues IsNot Nothing _
                            AndAlso i < parameterValues.Count Then
                            .Append("=" & parameterValues(i).Replace(vbCrLf, "<CR>"))
                        End If

                        .Append(",")

                    Next

                    If sb.ToString.EndsWith(",") Then sb.Length -= 1

                    .Append(")")

                End If

                .Append(vbTab)

                If ex IsNot Nothing Then
                    .Append(ex.Message.Replace(vbCrLf, "<CR>"))
                End If

            End With

        Catch exc As Exception
            sb.Append("<ERROR WHILE PARSING: " & exc.Message & ">")
        End Try

        LogMessage(sb.ToString)

    End Sub

    Shared Sub LogMessage(ByVal msg As String)
        Try
            If Not IO.File.Exists(LOGFILE_NAME) Then
                IO.File.WriteAllText(LOGFILE_NAME, "DATE" _
                    & vbTab & "USER" _
                    & vbTab & "METHOD" _
                    & vbTab & "ERROR MESSAGE" _
                    & vbCrLf)

            End If

            IO.File.AppendAllText(LOGFILE_NAME, msg & vbCrLf)

        Catch ex As Exception

        End Try

    End Sub

End Class

In CASE you were wondering…

Here’s a thought I had a couple of days ago. I actually was almost done with this blog entry yesterday, but ended up closing the window and not saving any of it. Argh.

My thought was on sql sorting. There are times when you want to have your results sorted at the server based on a parameter. Those of you who like dynamic sql would be all over that. It’s so simple (in Northwind):

declare @SortType int
declare @sql varchar(2000)
-- SortTypes
-- 1- Lastname
-- 2- Firstname
-- 3- Employeeed
-- 4- Extension
-- 5- postalcode

set @sorttype=4

set @sql='select * from employees'
if @sorttype=1 set @sql=@sql + ' order by lastname'
if @sorttype=2 set @sql=@sql + ' order by firstname'
if @sorttype=3 set @sql=@sql + ' order by employeeid'
if @sorttype=4 set @sql=@sql + ' order by extension'
if @sorttype=5 set @sql=@sql + ' order by postalcode'

exec(@sql)

Ok. But as I’ve said before, I am not a fan of dynamic sql. And my environment doesn’t allow it because all security is done through the stored procedures. So, how do we do the same thing without dynamic sql? It’s a great use of the CASE function.

Let’s start with the first two sort types: lastname and firstname. you can put the CASE in the ORDER BY section:

select *
from employees
order by case @sorttype
    when 1 then lastname
    when 2 then firstname
    end 

That was simple. So let’s add the third type, employeeid.

order by case @sorttype
    when 1 then lastname
    when 2 then firstname
    when 3 then employeeid
    end

Works well. Wait, no it doesn’t. Sorting by type 3 is fine, but sorting bu type 1 or 2 gives:

Msg 245, Level 16, State 1, Line 12
Conversion failed when converting the nvarchar value 'Davolio' to data type int.

Ok, that’s not a problem, we’ll just convert everything to varchar. So now it’s like:

order by case @sorttype
    when 1 then lastname
    when 2 then firstname
    when 3 then cast(employeeid as varchar)
    end 

That works, kind of. You won’t notice the bug on Northwind, but you will when we do the next type, extension. We need to convert it to varchar also.

order by case @sorttype
    when 1 then lastname
    when 2 then firstname
    when 3 then cast(employeeid as varchar)
    when 4 then cast(extension as varchar)
    end 

Wow, that’s not right. 2344 doesn’t come before 428. But it does in the string world, which you forced your way into. There is a solution. we just need to pad the numbers with zeros. But how many zeros? All the values have to be the same length to be considered equivalent. so now we have:

order by case @sorttype
    when 1 then lastname
    when 2 then firstname
    when 3 then cast(employeeid as varchar)
    when 4 then replicate('0',10-len(extension))+ extension
    end 

That works fine. And we’ll have the same problem with postalcode, which is numeric and character, so we need to pad the beginning of those to be equal-length strings. The final version:

select *
from employees
order by case @sorttype
    when 1 then lastname
    when 2 then firstname
    when 3 then cast(employeeid as varchar)
    when 4 then replicate('0',10-len(extension))+ extension
    when 5 then replicate('0',20-len(postalcode))+ postalcode
    end 

You’d want to make the length of the postalcode be the max length of the field, in case it’s blank. But the point is CASE is a very powerful tool. It can be used anywhere a single value can be used. In ORDER BY, in JOIN, in SELECT, it’s universal. Now I’m going to save this before I lose it again.