Stupid Dot Net Tricks

(In homage to my colleague's series of the same name... although in this case it might be me who's stupid, not Dot Net.)

Disclaimer: I am not a real Dot Net developer (at least not a good one).

Long story short: I was young and needed the money, so about six years ago I ported a very large Java web application to Visual Basic Dot Net for one special client, and to this day I still maintain it, only touching it two or three times a year.

As part of this port, I created a little logging utility. It's a teeny tiny class whose only job is to accept a string and write it to a file.

No big deal, right? That's what I thought.

My first attempt simply opened a file handle, kept it open, and wrote strings to the file as they came in. What's the problem with that? Windows locks the file and you can't open or read it from another application. So I couldn't load a web page then open the file with a text editor to read the logged messages... without killing the web server. Screw that.

My second pass opened and closed the file for every logged message. Gah! Yeah, I'm not proud of it. But you know what? It fricken' worked... for a few years. Note that this is only for development; this mechanism doesn't log in production, so don't soil yourselves in disgust... yet.

I don't know if it's Windows itself or the file system or faster processors or what is to blame, but now for some reason the operating system (or file system) can't seem to free the lock on the file in time for the next request to open it, resulting in an IO exception when you try to log a bunch of messages consecutively. Even though the code closes the file before attempting to re-open it for the next message, Windows says "nope, sorry, somebody is still using that file." Even more perplexing is that the exception doesn't occur when you open the file, it fails on the first write attempt. It smells like a classic race condition, and it stinks.

For some silly reason I thought I could solve this by synchronizing access to the logging utility... but that didn't work, and then it dawned on me that the application was essentially single threaded. I'm not loading multiple web pages simultaneously when I'm testing, so a race condition in the code was a red herring.

So here's my dilemma: I can't keep the file handle open because that prevents me from reading the log messages as they are being written, and I can't open and close the file in rapid succession as that causes Windows to asplode.

What's my solution? I hope you're sitting down...

A queue.

This is how it works:

1. You send a message to the utility to be logged.
   
2. It puts the message in a queue (at the back).
   
3. It opens the file (this always succeeds).
   
4. It pulls the first message off the queue.
   
5. It attempts to write the message to the file (this is where Windows barfs).
   
6. It the write fails, it puts the message back on the queue (at the front).
   
7. It the write succeeds, it keeps looping until the queue is empty.
   
8. It closes the file.
   

What's the method to this madness? If I pass a message to the logger and it fails to write it to the file, the message stays on the queue and the next time I write another message to the log, if it succeeds, it writes all of the failed-so-far messages to the log, clearing out the queue.

This whole block is synchronized on the queue just in case I decide to get crazy and load two web pages at the same time.

Since I have to put things back on to the front of the queue, I can't use a real Queue object, so I have to settle for an ArrayList. Why not a LinkedList? Oh yeah, did I forget to mention that I'm stuck in version 1.1!?

Here's the code (please don't burn me at the stake):

Private Shared ReadOnly queue As ArrayList = New ArrayList

Public Shared Sub WriteLine(ByVal msg As String)
    If LoggingEnabled Then
        SyncLock (queue)
            queue.Add(msg)
            Dim out As StreamWriter
            Try
                out = New StreamWriter(File.Open(LogFile, FileMode.Append))
                While (queue.Count > 0)
                    msg = queue.Item(0)
                    out.WriteLine(msg)
                    out.Flush()
                    queue.RemoveAt(0)
                End While
            Catch e As IOException
                ' put it back on the queue
                queue.Insert(0, msg)
            Finally
                If out Is Nothing Then
                    ' noop
                Else
                    out.Close()
                End If
            End Try
        End SyncLock
    End If
End Sub