A Better Way of Logging

The software for this post is freely available for download: Just the logger assembly, or logger source with test app.

Is logging necessary?

During development, logging is normally seen as an unnecessary burden, because you are working in a debugger. When the program crashes, your editor immediately pops up, highlighting the cause of the crash. When the program is behaving strangely, you can pause the program and inspect all relevant values.

Not so for software that's been sent to production, where there is no debugger. When the program crashes, all the user sees is a standard windows crash dialog and a sudden lack of application. When the program exhibits strange behaviour, the user can do nothing to find out why. Short of releasing all programs as source and requiring that all users run your software through a debugger, you need to know the state of the program prior to the crash.

This is the role of the logger - like ship captains of yore, it writes down every tedious little happening in a sequential list - a log. You can read the log afterwards and deduce a snapshot of the application state at any particular moment during its execution. When you get a report that the program has crashed or is doing things wrongly, you no longer have to desperately try to reproduce the problem yourself. Just ask for the log file, print it out, and sit down to deduce the error over a cup of tea like a ninja.

In any sufficiently interesting software, logging is crucial.

Is logging hard?

In principle, no. In practicle, yes. There are many pitfalls that can render a log file less than useful when disaster finally strikes.

The problems that most commonly haunt conventional log files are:

1. Buffering. Usually just a big performance gain when writing to disk IO, buffering potentially means that the last hundred log entries have not yet been written to the log file when your program crashes. A log containing just some application startup info is about as useful as a paper cup in a storm.
2. Multithreading. Multiprocessing your application is a good way to speed it up by several orders of magnitude. For logging, however, it means that two threads can try to log at the same time. A usual result of this is interleaved log entries, i.e. thread A logs "socket created" while thread B logs "shutting down database" at the same time, possibly resulting in the misleading log entries "shutting down socket" and "created database".
3. File access rights. Access rights is serious business in Windows Vista and above. For logging, this means that if a user has decided to launch your application with "Run as administrator" the first time, the log file will be created with "Administrator" as owner. When running the application later as a normal user, he is now unable to append to the log file, and the program either crashes or doesn't log anything.
4. Growing log file. After a while, your log file will grow to an improper size. It is foremost bad form to fill up your users' disks without their consent, but it is also difficult to read huge log files. If they are particularly large, they might even crash your Notepad when you open them.

There are many ways to at least partially solve these problems, but all of them are cumbersome and result in an overly large code base for a simple logger. Look at the sheer size of the code base of any freely available logging framework if you don't believe me.

But let us step back for a moment and look at the bigger puzzle. Do these problems have a common cause? Can we avoid these problems altogether?

Yes, the common cause is that you are operating with files. And yes, we can avoid these problems altogether with...

A Better way of Logging

To download the logger assembly, click here.

The solution is so obvious that I was half surprised no-one had thought of - or at least implemented - it before; log to the Windows Registry.

Let us look at how it affects our earlier problems:

1. Buffering. Windows registry storage, and consequently disk IO buffering, is done on the OS level instead of application level. This means that no buffers are lost when your program crashes.
2. Multithreading. The Windows registry access functions are already thread-safe, so you don't have to do anything.
3. File access rights. No file means no file rights headaches! Nuff said.
4. Growing log file. Since we no longer operate on a monolithic blob of bytes, but rather on discrete registry key values, we can remove entries willy-nilly. This means we can simply delete the oldest entries in O(1) time to keep the total log size within an approved threshold.

However, a credo of mine is that a brilliant idea is worthless without execution. Before even writing the opening paragraph of this blog post, I created a fully working, fully documented registry logger. It is of course open sourced and freely available for anyone to use.

The entire logger source code looks like this:

// Logger.cs
using System.Collections.Generic;
using Microsoft.Win32;

namespace RegistryLogger {
    public class Logger {
        private RegistryKey logRoot;
        private int headIdx;
        private int tailIdx;
        private int maxLogLength;

        /// <summary>
        /// Create logger object with Max Log Length of 10.
        /// </summary>
        /// <param name="appName">Name of your App.</param>
        public Logger(string appName) : this(appName, 10) { }

        /// <summary>
        /// Creates key HKCU\SOFTWARE\LOGS\[appName].
        /// Logger is now ready for use.
        /// </summary>
        /// <param name="appName">Name of your App.</param>
        /// <param name="maxLogLength">Limit total log storage to this many
        /// entries.</param>
        public Logger(string appName, int maxLogLength) {
            this.maxLogLength = maxLogLength;
            string lrp = "SOFTWARE\\LOGS\\" + appName;
            RegistryKeyPermissionCheck pc =
                RegistryKeyPermissionCheck.ReadWriteSubTree;
            logRoot = Registry.CurrentUser.OpenSubKey(lrp, pc);
            if (logRoot == null) {
                logRoot = Registry.CurrentUser.CreateSubKey(lrp, pc);
                headIdx = tailIdx = 0;
                logRoot.SetValue("headIdx", headIdx);
                logRoot.SetValue("tailIdx", tailIdx);
            } else {
                headIdx = (int)logRoot.GetValue("headIdx");
                tailIdx = (int)logRoot.GetValue("tailIdx");
            }
        }

        /// <summary>
        /// All currently stored log entries.
        /// </summary>
        public string[] Entries {
            get {
                List<string> area = new List<string>();
                for (int i = tailIdx; i < headIdx; i++)
                    area.Add((string)logRoot.GetValue(i.ToString()));
                return area.ToArray();
            }
        }

        /// <summary>
        /// Prepend a timestamp to the entry and log it as string value
        /// HKCU\SOFTWARE\LOGS\[appName]\[idx]
        /// Each new log entry gets an unique idx.
        /// </summary>
        /// <param name="entry">Entry to log.</param>
        public void Log(string entry) {
            string toLog = System.DateTime.Now.ToString() + ": " + entry;
            logRoot.SetValue(headIdx++.ToString(), toLog);
            logRoot.SetValue("headIdx", headIdx);
            DeleteOldEntries();
        }

        private void DeleteOldEntries() {
            while (headIdx - tailIdx > maxLogLength)
                logRoot.DeleteValue(tailIdx++.ToString());
            logRoot.SetValue("tailIdx", tailIdx);
        }
    }
}

Remember how I said the buffering, multithreading, access rights workarounds for log files were cumbersome? Look how elegant we can keep the code when those concerns are noncerns.

A simple test run

To download the logger source and the test application, click here.

To test this, I created a GUI interface in WPF to let you read and write log entries.

Let us enter a few sample entries and submit them to the logger:

Clicking the "Log Above Lines" button causes each line to be logged as a separate log entry. To see what we have logged, we can click "View Log":

Ok, looks good. But I bet you a can of tomatoes that I can guess what you are thinking right now. "How does this look in the registry?"

Let's have a look:

The entries are all there! We can also see the current logger state: The headIdx value says that the next entry to be logged will get idx 7, while the tailIdx value says that the oldest stored entry has idx 0. Since we can deduce every stored entry idx by starting from tailIdx and iterating up to headIdx, this is literally equivalent to a linked list. As anyone who has at least passed close by a computer science department knows, linked lists make for easy FIFO queues, and FIFO queues makes for easy constant-size buffers: If the size is too large, move the tail pointer and delete the previous tail element. Rinse, lather, repeat until size is within threshold.

For demonstration purposes, I've limited the logger to 10 entries. We now have 7 log entries, so let us see how it behaves when we add another 4:

Click "Log", which should take us to exactly 11 total entries, 1 above the threshold. Click "View":

As we can see, the first log entry "Application starting." is now deleted! Just to be sure, let us check the registry:

The entry with idx 0 is now gone, and the tailIdx is 1. Success!

In closing

Hopefully, you now know enough to implement proper logging in your applications. Whether you decide to use my logger code (free open source, as always) or roll your own registry logger, I will be very interested in hearing how it works out for you.

If you have any questions, don't hesitate to use the comments section.

How I landed a high-paying new job

I am happy to announce that my business card now reads "Senior Web Security Engineer"!

It's been about a month since my interview now, and my new employer (kept anonymous for oblivious reasons) have kindly given me permission to blog about it given that I anonymized it all. Since a few of you are probably out hunting for new jobs at the moment - and who wouldn't in this economy - keep reading for some pointers on how to pass a job interview.

The resumé and application

These are straightforward, so I won't go into detail. Just remember to put the prospective employer's name all over the application, proofread twice, and use glossy paper for the cover letter. Bonus points for delivering in person. If applicable, flirt heavily with whomever is receiving the application - getting someone on your good side can only help you.

I was lucky here, as the HR lady was obviously impressed by my shark tooth ear studs. She even called me up the same afternoon! After answering a few simple math questions to show I wasn't completely useless (this is called a "phone screening", but I think "phony screening" would be a funnier name), I was invited to...

The interview

I had a couple of days to prepare for this, so I had time to hit the sun parlor a few times and even found the time to get my teeth bleached. I also memorized the current "hot words" in cryptology in the evenings, and reimplemented the "rot thirteen" cipher a million times until I could write the C# code blindfolded, doing my best to stay sharp.

The first part of the interview was supposed to be with me, my prospective manager Bob (not his real name of course - it's just an alibi), and the HR lead Cyril (likewise not his real name). However, since Bob got unexpectedly ill that day and couldn't come, it was just me and Cyril. Cyril had little to no programming knowledge, but Bob had been thoughtful enough to fax him with a list of techincal questions. The list was quite long, and I spent about half an hour talking about the different cryptology disciples; cryptography, ciphering, stenography, cracking, then a bit about security mechanisms like web code obfuscation, reverse engineering, litigation and firewalls. To top it off, I went on quite a bit about my experience as a team leader and my thoughts on keeping a team efficient. All in all I did pretty good, and Cyril was very impressed by my broad knowledge. He gave me the green flag, and after a pleasant free lunch I was on to the last part...

The programming test

Oh my World this was unexpectedly harder than I thought it would be. Here I was expecting to be given a variant of the fizz test, but instead I was tasked to implement a complete cipher program from scratch in only two hours! Fortunately for you, my company has replaced that specific test with a new one now, so I'm allowed to post the entire thing here!

You have TWO HOURS for this excercise. After completion, you must print out your
solution, sign your name in the top right corner of every page, get a stamp of
authenticity from HR, and deliver it to your manager.

You will work with a well-known encryption procedure. This is called a substitution
cipher, in which each letter of the original message (the "plaintext") is replaced
by a different letter to generate the coded message (the "ciphertext").

To simplify matters further, we will restrict our plaintext to use only the upper
case letters A to Z, together with the space and newline characters; furthermore,
space and newline characters will be left unchanged by the encryption.

In each case, the replacement letter will be a fixed number of letters later in the
alphabet compared to the original letter (and "wrapping around" back to A again
after Z, as necessary). The number of letters to count forward will be called the
encryption key.

Thus, with a key of 3, we would replace A by D, B by E and so on, with, finally, W
being replaced by Z, X by A, Y by B and Z by C.

This simple kind of cipher is sometimes called a "Caesar Cipher" after Julius
Caesar, who is said to have used it for secure battlefield messages.

You are required to develop a program which will input a series of lines of
characters, and encode them with a Caesar cipher; as each line of plaintext is
input, the corresponding line of ciphertext should be output. It is up to you to
devise a mechanism whereby the user can indicate that all lines have been input,
and to implement the program in such a way that it will then terminate.

The key for the encoding should be "hard coded" into your program (as opposed to be
being read in at run time). Thus, changing the key will involve modifying the
source program and recompiling.

You may find it handy to be able to run your program on an input file (and
producing an output file) rather than working only with the keyboard and screen.
Use command line redirection to achieve this.

A command line gui? What is this, the 1970-ies? (A side note: This was the main reason I later persuaded them to replace the test with a new one.)

And the algorithm was pretty muddily explained. Replace X, Y corresponding with A, B and whatnot? That couldn't possibly be any less unclear, couldn't it not? Not giving up hope, I read the text carefully over and over again until finally it hit me: This is just a less general version of my Rot Thirteen cipher! I was in luck. After quickly typing in the memorized code, I had about an hour to figure out how to get the blooming thing to work in a terminal and add some polish. I got time to add some XML in there and even add a few design patterns. I was, and still am, pretty pleased with the end result:

using System;

namespace ConsoleApplication1 {
    // Factory pattern
    class CesarFactory {
        private int key;

        public CesarFactory(int key) {
            this.key = key;
        }

        public ICipher Instantiate() {
            return new CesarAdapter();
        }
    }

    // Interface pattern
    interface ICipher {
        string Encipher(string plaintext);
    }

    // Adapter pattern
    class CesarAdapter : ICipher {
        string ICipher.Encipher(string plaintext) {
            return Cesar.Encode(plaintext);
        }
    }

    // Cesar cipher
    class Cesar {
        public static string Encode(string input) {
            char[] chars = input.ToCharArray();
            for (int i = 0; i < input.Length; i++) {
                int lowerRotation = Rotate(chars[i] - 'a', 3, 26);
                int upperRotation = Rotate(chars[i] - 'A', 3, 26);
                if (chars[i] > 'a') chars[i] =
                    (char)('a' + lowerRotation);
                else if (chars[i] > 'A') chars[i] =
                    (char)('A' + upperRotation);
            }
            return new string(chars);
        }

        private static int Rotate(int c, int delta, int max) {
            c += delta;
            while (c > max) c -= max;
            return c;
        }
    }

    // Entry point.
    class Program {
        // Command line gui.
        static void Main(string[] args) {
            // Create Cesar factory
            CesarFactory factory = new CesarFactory(3);
            // Xml header
            Console.Out.Write("<XML version=\"1.0\"><Cesar>");
            // Read as long as there is something in the input buffer.
            while (Console.BufferHeight > 0) {
                // Read from Console.
                int x = Console.Read();
                // Encode input as string.
                string plaintext = new string(new char[]{(char)x});
                // Get cipher.
                ICipher cesar = factory.Instantiate();
                // Encipher plaintext.
                string ciphertext = cesar.Encipher(plaintext);
                // Output ciphertext to Console.
                Console.Write(ciphertext);
            }
            // Xml footer
            Console.Out.Write("</XML></Cesar>");
        }
    }
}

At the 1 hour 56 minute mark I sent my submission to the printer, got it stamped by HR, signed it, and had it faxed home to Bob for review. Exhausted but hopeful, I was now free to go and relax while the review took its course.

A few days later, the phone call I had been waiting so anxiously for finally came. I was accepted as Senior Web Security Engineer for a big bank, earning over £60k a year!

All it took was dedication, commitment, and a sense of purpose. And let's not be modest anymore (job interview tip here!) - a heavy dose of talent. How awesome is that?