Redeveloping WordTutor
Logging Demonstrated

After earlier defining our logging interface, some readers posed a few questions about how it would work from a consumers perspective. So before we look at implementation details, let’s look at how we’ll instrument our code and what the output might look like.

ViewModels

Each View Model represents a different user activity, so we’ll give each one a different context.

In VocabularyBrowserViewModel, the changes are simple.

private readonly IActionLogger _logger;

public VocabularyBrowserViewModel(
    IReduxStore<WordTutorApplication> store,
    ILogger logger)
{
    if (logger is null)
    {
        throw new ArgumentNullException(nameof(logger));
    }

    _store = store 
        ?? throw new ArgumentNullException(nameof(store));
    _logger = logger.Action("Browse Vocabulary List");
    // ...

Aside: You can see both styles of parameter validation here. Sandwiching the ?? throw style into the use of logger feels too cramped and is significantly harder to read, so I used the older if ... throw style.

In RefreshFromScreen(), when we find our screen has been closed, we need to dispose of the logger to close off the current nested context.

private void RefreshFromScreen(
    VocabularyBrowserScreen? screen)
{
    if (screen == null)
    {
        _screenSubscription.Dispose();
        _vocabularySubscription.Dispose();
        _logger.Dispose();  // Log disposal added
        return;
    }

    Selection = screen.Selection;
    Modified = screen.Modified;
}

However, in ModifyVocabularyWordViewModel it’s more complicated because we’re reusing the viewmodel for two different activities: both adding and modifying words.

To ensure that our logging is clear, we need to correctly describe our log action. We do this in our constructor by checking which mode we’re using before creating the logger:

public ModifyVocabularyWordViewModel(
    IReduxStore<WordTutorApplication> store,
    ILogger logger)
{
    if (logger is null)
    {
        throw new ArgumentNullException(nameof(logger));
    }

    _store = store ?? throw new ArgumentNullException(nameof(store));

    var screen = _store.State.CurrentScreen 
        as ModifyVocabularyWordScreen;
    var areAdding = screen?.ExistingWord is null;

    _logger = logger.Action(
        areAdding
        ? "Create Vocabulary Word"
        : "Modify Vocabulary Word");
    // ...

Messages

At the core of our application, our Redux store is going to be constantly processing messages that change the application state. Capturing these messages in the log should give us a good insight into how the application is operating.

Let’s create a new reducer, one explicitly for logging. At present, it just logs messages on the way through without modifying state - but in the future, we will use it for other processing when we make the log part of our application state.

public class LoggingReducer 
    : IReduxReducer<WordTutorApplication>
{
    // Reference to our logger
    private readonly ILogger _logger;

    public LoggingReducer(ILogger logger)
    {
        _logger = logger;
    }

    public WordTutorApplication Reduce(
        IReduxMessage message, 
        WordTutorApplication currentState)
    {
        _logger.Info($"Message: {message}");
        return currentState;
    }
}

Output

As a part of our internal plumbing (to be discussed in a later post), we wire things up so that messages logged through the global logger are correctly associated with the current execution context, resulting in a hierarchical log.

For demonstration purposes, we’re sending the output to Visual Studio’s output pane by using Debug.WriteLine().

Once we’ve stripped out all the other messages that show up, we end up with output like this:

01:51:35Z [>] Browse Vocabulary List
01:51:42Z     [•] Message: Select 'beta'.
01:51:44Z     [•] Message: Open screen to create new word.
01:51:44Z [<] Elapsed 00:00:09.3816114.
01:51:44Z [>] Create Vocabulary Word
01:51:48Z     [•] Message: Modify Spelling to 'one'.
01:51:49Z     [•] Message: Modify Pronunciation to 'won'.
01:51:53Z     [•] Message: Modify Phrase to 'We won the game.'.
01:51:54Z     [•] Message: Save new word 'one'.
01:51:54Z [<] Elapsed 00:00:10.0477900.
01:51:54Z [>] Browse Vocabulary List
01:51:56Z     [•] Message: Select 'one'.
01:51:57Z     [•] Message: Open screen to modify 'one'.
01:51:57Z [<] Elapsed 00:00:02.8714110.
01:51:57Z [>] Modify Vocabulary Word
01:52:00Z     [•] Message: Modify Spelling to 'won'.
01:52:02Z     [•] Message: Save changes to 'one'.
01:52:02Z [<] Elapsed 00:00:04.6584351.

The indentation clearly shows which messages are related to which activity. We additionally get visibility into the way the application swaps out a new viewmodel for each screen as we navigate around.

As we add additional activities into our application, the diagnostic value of the log will grow, but where it will become most useful is when we start running asynchronous workloads: instead of having all those log messages interleaved, making it hard to decipher what’s going on, we’ll have them showing in separate streams of activity.