Not so Stupid Simple Logging for Windows Store Apps in C#/VB

The last time that I had to worry about logging was within Azure. My cloud solution was simple, and thus my logging solution was simple. Lately, the application I’ve been building for Windows 8.1 is not simple. It’s one of the most complex apps I’ve built to date.

It’s no secret that log4net won’t work in a Windows Store app, but that’s OK. There’s a different way to think about logging, and that’s with Event Tracing for Windows (here’s a complex, but good MSDN article). ETW logging is an obvious choice when developing on Windows as it guarantees:

Extremely fast performance (~16us per log event)
Application will not change behavior when logging is ON vs. OFF

The latter is very important. Imagine that you’re tracking down a race condition and you’re using a custom logging solution. You turn on logging, and it no longer reproduces! How could this happen? Your logging solution might cause the processor to schedule work differently when it’s ON vs. OFF.

First, if you’re looking for simple…

If you’re looking for a simple logging solution for Windows Store apps (regardless of language), look no further than Windows.Foundation.Diagnostics (new in Windows 8.1). Don’t be let astray by the first Google hit for “windows store” logging. While that solution uses the same methods I’ll expand on in this post, it will introduce more complexity that you’re looking for. It was also written before Windows.Foundation.Diagnostics became available in Windows 8.1.

The Windows.Foundation.Diagnostics namespace contains LoggingChannel and LoggingSession, which will likely fulfill your simple logging needs. Use LoggingChannel’s LogMessage(string) and LogValuePair(string, int) for simple string logging. There’s a wonderful Channel9 video on how to setup LoggingChannels with LoggingSessions.

If you’re OK with simple string logging and logs being saved to .ETL files, Windows.Foundation.Diagnostics is probably perfect for you.

But what if…?

I recently discovered that there’s more to life than simple string logging. That’s the “event” portion of ETW. I was raised to think of logging that looks like this:

Log.Verbose("Application starting");

In ETW-speak, this lets you log a Verbose event with a string parameter. Very powerful because that string can be anything. However, consider this:

Log.ApplicationStarting();

In a nutshell, that’s what ETW means by “event”. Both of the above log statement have the same purpose. They want to log that the application has started. The second statement is scale-able. The first one is not.

By scale-able, I mean that down the road, you might want to log more than just “Application starting” on boot. Maybe you want to know what platform and version of the code is starting. You could go change to:

Log.Verbose(string.Format("Application starting on {0} with version {1}", App.Platform.ToString(), App.Version.ToString()));

And that would be fine, except if you had multiple places in your app where you needed to log this event (OK, maybe app start is a bad example since you’ll probably only call it from one place, but you can imagine). Then you’d be copy & pasting log lines and that goes against the gospel of computer science.

So, you should centralize your events! That way, your event can really be as descriptive as you’d like. If it needs contextual data, you can just pass in the raw object instead of having to format it at the logging location.

Enter EventSource

.NET 4.5.1’s System.Diagnostics.Tracing namespace provides EventSource. It’s the simplest way to create ETW events in .NET. Check out the second example on the MSDN page for how to write it.

EventSource isn’t perfect though. You can only pass simple types like string and int to event methods. It cannot implement any interfaces. You’re probably going to want to wrap EventSource in another class like so:

public class LifecycleEventSourceWrapper
{
    public LifecycleEventSource EventSource {get; private set;}

    public LifecycleEventSourceWrapper()
    {
        EventSource = new LifecycleEventSource();
    }

    public void ApplicationStarting()
    {
        // Get app version
        var v = Package.Current.Id.Version;
        string version = string.Format("{0}.{1}.{2}.{3}", v.Major, v.Minor, v.Build, v.Revision);

        string platform = // get the platform

        EventSource.ApplicationStarting(version, platform);
    }
}

public class LifecycleEventSource : EventSource
{
    [Event(1, Message = "App starting on {0} with version {1}")]
    public void ApplicationStarting(string version, string platform)
    {
        if (this.IsEnabled()) this.WriteEvent(1, version, platform);
    }
}

Notice that I created LifecycleEventSource, and not just MyAppEventSource, implying that LifecycleEventSource should only be use for logging events related to application lifecycle. This is a powerful pattern because you can later filter your logs much more easily.

Check out MSDN for all the other awesome things that EventSource can do (like keywords and opcodes). You may not need them now, but they’re available for later use.

Cool, you’ve sold me on EventSource. So I’m done?

Not quite. Nobody is listening for these events. If you want to use another program like Windows Performance Analyzer to listen, then you actually are done, but you probably wanted to write to a file.

Assuming you want to do this all in one process, this is where the EventListener is used. There don’t appear to be any awesome examples that you can just drop in, so here’s an extremely basic one that keeps an in-memory cache of log lines, then writes them to a text file in your local storage folder every 5 seconds:

public class FileEventListener : EventListener
{
    private object syncObj = new object();
    private List<string> logLines;
    private StorageFile logFile;
    private ThreadPoolTimer periodicTimer;

    public FileEventListener()
    {
        logLines = new List<string>();
    }

    // Should be called right after the constructor (since constructors can't have async calls)
    public async Task InitializeAsync()
    {
        logFile = await ApplicationData.Current.LocalFolder.CreateFileAsync("logs.txt", CreationCollisionOption.OpenIfExists);

        // We don't want to write to disk every single time a log event occurs, so let's schedule a
        // thread pool task
        periodicTimer = ThreadPoolTimer.CreatePeriodicTimer((source) =>
            {
                // We have to lock when writing to disk as well, otherwise the in memory cache could change
                // or we might try to write lines to disk more than once
                lock (syncObj)
                {
                    if (logLines.Count > 0)
                    {
                        // Write synchronously here. We'll never be called on a UI thread and you
                        // cannot make an async call within a lock statement
                        FileIO.WriteLinesAysnc(logFile, logLines).AsTask().Wait();
                        logLines = new List<string>();
                    }
                }
            }, TimeSpan.FromSeconds(5));
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        // This could be called from any thread, and we want our logs in order, so lock here
        lock (syncObj)
        {
            string payload = string.Format(eventData.Message, eventData.Payload.ToArray());
            logLines.Add(string.Format("{0}\t{1}", DateTime.Now.ToString(), payload));
        }
    }
}

You’ll need to hook EventSource to EventListener of course. I generally do this in the constructor of a class that exposes all of my EventSources.

Now what?

Now that you’ve got logs in a file form, you could ask users to send them to you when they report a bug, or you could upload them to cloud storage for the user (but be sure to discuss this in the privacy policy!).

Cryclops

sad cyclops