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.

It’s like the “Bag of Holding” for arrays

Here’s a little bit of code I find amusing. Haven’t you ever wanted an array that never ends? Or maybe better described as an array that loops? So if you have 10 items in your array and you ask for number 11, you get the first element again? I’m sure I have, but I don’t remember when or why.

Anyway, here’s a collection you can use for an (almost) infinite collection. It was actually a bit of trial and error to get the negative values to work properly.

Public Class ForeverCollection(Of T)
    Inherits Generic.List(Of T)

    Default Public Shadows ReadOnly Property Item(ByVal index As Integer) As T
        Get
            If Me.Count = 0 Then Throw New ArgumentOutOfRangeException("index")

            If index >= 0 Then
                Return MyBase.Item(Math.Abs(index Mod Me.Count))
            Else
                Return MyBase.Item(Me.Count - Math.Abs((index + 1) Mod Me.Count) - 1)
            End If

        End Get
    End Property
End Class

This uses the MOD operator which is a pretty fun bit of code. Its purpose is to return the leftover of any integer division. So 10 MOD 10 is 0, 12 MOD 10 is 2, 34 MOD 10 is 4. What good is that? Well, when you see the examples, it will make more sense.

You can use MOD for time calculations. You have 543 seconds on a timer. How many minutes and seconds is that? Which code is cooler?

allSecs = 543
min = 543 \ 60
sec = allSecs - (min * 60)
MsgBox(min & ":" & sec)or 

allSecs = 543
min = allSecs \ 60
sec = allSecs Mod 60
MsgBox(min & ":" & sec)

You can use MOD as a trigger. Lets say you have a counter and you want to annoy the user every X number of iterations.

For x As Integer = 1 To 1000
    If x Mod 15 = 0 Then
        MsgBox(String.Format("I've bugged you {0} time(s) " _
            & "and the counter is at {1}", (x / 15), x))
    End If
Next

You can use MOD for pseudo-random seed data in SQL. MOD in SQL is "%". Take the milliseconds of the current time and mod it by different numbers.

declare @i int
set @i=0
while @i<500
begin
    insert into userinfo(userid,createdate,logincount,
        lastwithdrawal,lastdeposit,currentbalance)
    select top 1 userid,getdate(),datepart(ms,getdate()),
        datepart(ms,getdate()) % 30,
        (datepart(ms,getdate()) % 15)*50,
        (datepart(ms,getdate()) % 25)*50,
        (datepart(ms,getdate()) % 10)*100
    from users
    order by newid()

    set @i=@i+1
end

I think of all the extra code I used to write before I discovered MOD and I think…

Delegatorial Rambling

I see in a sister blog a planned post regarding Delegates in .NET. I have used delegates before, and I think I have seen them misused before. But remaining on the positive, I’ll describe what the delegate capability did for me.

In an application I was writing, I made the decision to extract the product search form from the main UI application; my thought was that it would be a common element that could be used in many different applications in the long-range-planned application suite. My choice was a good one, as I did use it in multiple applications, but it did get modified along the way.

The first version was simple: you search for products, you highlight the product(s) you want, and click "Select". The search form would raise an event that the calling form would handle and process. The search form also had a button to view product details. You could highlight a product and click "View Details" to bring up another form with the product information.

This worked great until I wanted to use it in another part of the same application. In this new section, there was no "Select" function needed, only "View Details". One choice I pondered was making the Select button Public instead of Friend (remember this code is in a shared DLL now). Then the calling form could enable or disable it. I also considered making a Boolean property like HideSelect. That seemed pretty tacky. But my overall goal with designing the code was that it do what the programmer tells it and do the most obvious thing by default.

Going with that mindset, I decided the Select button will do nothing unless you give it something to do. Goodbye Event, hello Delegate. I dropped the public event and created a delegate sub that matched the signature of my old event. Then I created a private variable to hold the delegate and created a public property to Get/Set the delegate.

What benefits did this gain? I was then able to see if the calling form needed the Select button. If the private variable was Nothing, I disabled the Select button. If the private variable was a valid instance, I invoked it when the Select button was clicked. When I was using events, I couldn’t tell if anyone was subscribed to the event so I couldn’t take any action on the Select button.

Back in the calling form, the code change was minimal. Instead of doing an AddHandler statement, I created a new instance of the delegate in the search form using AddressOf in the constructor and set it to the public property on the search form. The target method that handled the event never changed.

That’s one way I used a delegate. The other way I used it was with the View Details button. For another application, the View Details was slightly different. In brief, the application needed to handle the display of the product instead of letting the search form do it. Again, I created a delegate sub, private variable and public property. In the click event of the View Details button, I checked to see if the delegate was Nothing. If it was Nothing, I performed the default action and displayed the product in the typical manner. If it was not nothing, I invoked the delegate instead of doing the default display. In this way, I was able to provide an override for default behavior.

Without using delegates, how could that have been done as easily? As I was determining how do implement the override feature, I considered using events, but that means that every calling form would have to handle that event in order to implement the default display action. That went against my design philosophy. I could have used a Boolean property, but…bleh. I insisted to myself that I would not have any shared library that required performing steps in a rigid fashion. Like, oh, the code bombed out. I forgot to call InitControls2() after setting the base properties. Yuck.

So that’s my delegate story. In summary, I used Delegates instead of Events because I was able to test to see if they were needed using IsNothing() and they provided me with a way to optionally inject a call to a remote codebase (that codebase being the calling form). Sorry for no code samples. I don’t have the code with me right now.