Rory Primrose

NSubstitute and FluentAssertions Redux

Sun, 25 Apr 2021 00:00:00 +0000

Way back in 2014 I posted about Bridging between NSubstitute and FluentAssertions. The code sample provides a way of using FluentAssertions checks in NSubstitute arguments. There have been some slight changes in these packages over the last seven years. Here is an updated version of how to get this to work with the current versions of those packages.

An additional change in this sample is a rename from Verify.That to Match.On which reads a little better.

using System;
using System.Diagnostics;
using System.Linq;
using FluentAssertions.Execution;
using NSubstitute.Core.Arguments;

public static class Match
{
    public static T On<T>(Action<T> action)
    {
        return ArgumentMatcher.Enqueue(new AssertionMatcher<T>(action));
    }

    private class AssertionMatcher<T> : IArgumentMatcher<T>
    {
        private readonly Action<T> _assertion;

        public AssertionMatcher(Action<T> assertion)
        {
            _assertion = assertion;
        }

        public bool IsSatisfiedBy(T argument)
        {
            using var scope = new AssertionScope();

            _assertion(argument);

            var failures = scope.Discard().ToList();

            if (failures.Count == 0)
            {
                return true;
            }

            failures.ForEach(x => Trace.WriteLine(x));

            return false;
        }
    }
}

As in the 2014 post, this can be used like the following:

validationStore.Received()
    .AddOutstandingVerification(
        Match.On<OutstandingVerification>(
            y => y.Expires.Should().BeCloseTo(DateTimeOffset.UtcNow.Add(verificationExpiry), 2000)));

GitVersion and GitHub with Azure DevOps build yaml

Fri, 03 May 2019 06:04:00 +0000

I like the idea that a build definition is code and can go under source control. Azure DevOps already has change control of build definitions so this outcome does not necessarily have to use Git. There is one scenario where the traditional build definition does not satisfy this though. It is when the state of the code in a branch requires different build logic than the code in another branch. The build yaml in Git is perfect for this.

One of the things I wanted to achieve when using build yaml was to get versioning to work they way I want it to. It took a lot of trial and error but I am happy with the results. This is how it works. I have GitVersion.yml under source control that defines how a build will come up with a version. The first thing that the build yaml needs to do is execute GitVersion in the build.

- task: GitVersion@4
  displayName: 'GitVersion'
  inputs:
    updateAssemblyInfo: true

Easy done.

Next I want the build number to use the NuGetV2 version generated by GitVersion because I don’t like the version format they use by default. This took a long time to get right.

The way this works is that a command executed in the build than renders a log output in the right format can update the build number. This is documented here and uses the following command:

##vso[build.updatebuildnumber]my-new-build-number

The primary issue with getting this to execute in a yaml pipeline is that # is a comment marker. I went through so many attempts to get this to work. Here is the one that finally landed the result.

- script: echo %Action%%BuildVersion%
  displayName: 'Set build version'
  env:
    Action: '##vso[build.updatebuildnumber]'
    BuildVersion: $(GitVersion.NuGetVersionV2)

The trick here is to put the ## combination required by the command comment into a variable and then use that variable as an input to the command that will then echo the result out to the build log. Now we have GitVersion coming up with the build and the build number reflecting the desired value.

Another outcome I wanted was to create a GitHub release for a build. In this scenario, I only want the GitHub release to be created for a master branch build. This is done by setting a condition that the current branch is refs/heads/master. I also wanted to mark the GitHub release with the prerelease flag. This is done by checking if the NuGetVersionV2 version number has a pre-release suffix on it.

- task: GitHubRelease@0
  inputs:
    gitHubConnection: 'GitHub'
    action: 'create'
    tagSource: 'manual'
    tag: 'v$(GitVersion.NuGetVersionV2)'
    title: 'v$(GitVersion.NuGetVersionV2)'
    isPreRelease: contains(variables['GitVersion.NuGetVersionV2'], '-')
  condition: and(succeeded(), eq(variables['Build.SourceBranch'], 'refs/heads/master'))

Creating the GitHub release was so simple using this step and the outcome was fantastic. It created the release with all the commit history related to the release and the packaged build output from the artefacts directory.

Updated Azure Table Storage EntityAdapter

Fri, 05 Apr 2019 04:34:00 +0000

Way back in 2013 I originally posted my EntityAdapter<T> to make it really easy to read and write .Net classes to Azure Table Storage. There have been a few updates since the original post, some of which were never made public. This post provides the latest version of that class and some examples of extensibility.

This is the latest version of EntityAdapter<T>.

using System;
using System.Collections.Generic;
using System.ComponentModel;
using System.Globalization;
using System.Linq;
using System.Reflection;
using EnsureThat;
using Microsoft.WindowsAzure.Storage;
using Microsoft.WindowsAzure.Storage.Table;

public abstract class EntityAdapter<T> : ITableEntity where T : class, new()
{
    private static readonly object _syncLock = new object();
    private static List<AdditionalPropertyMetadata> _additionalProperties;
    private string _partitionKey;
    private string _rowKey;

    protected EntityAdapter()
    {
    }

    protected EntityAdapter(T value)
    {
        Ensure.Any.IsNotNull(value, nameof(value));

        Value = value;
    }

    public void ReadEntity(IDictionary<string, EntityProperty> properties, OperationContext operationContext)
    {
        Ensure.Any.IsNotNull(properties, nameof(properties));

        Value = new T();

        TableEntity.ReadUserObject(this, properties, operationContext);
        TableEntity.ReadUserObject(Value, properties, operationContext);

        var additionalMappings = GetAdditionPropertyMappings(Value, operationContext);

        if (additionalMappings.Count > 0)
        {
            ReadAdditionalProperties(properties, additionalMappings);
        }

        ReadValues(properties, operationContext);
    }

    public IDictionary<string, EntityProperty> WriteEntity(OperationContext operationContext)
    {
        var properties = TableEntity.WriteUserObject(Value, operationContext);

        var additionalMappings = GetAdditionPropertyMappings(Value, operationContext);

        if (additionalMappings.Count > 0)
        {
            WriteAdditionalProperties(additionalMappings, properties);
        }

        WriteValues(properties, operationContext);

        return properties;
    }

    protected abstract string BuildPartitionKey();

    protected abstract string BuildRowKey();

    protected void ClearCache()
    {
        lock (_syncLock)
        {
            _additionalProperties = null;
        }
    }

    protected virtual TypeConverter GetTypeConverter(PropertyInfo propertyInfo)
    {
        Ensure.Any.IsNotNull(propertyInfo, nameof(propertyInfo));

        var propertyType = propertyInfo.PropertyType;

        return TypeDescriptor.GetConverter(propertyType);
    }

    protected virtual void ReadAdditionalProperty(PropertyInfo propertyInfo, EntityProperty propertyValue)
    {
        Ensure.Any.IsNotNull(propertyInfo, nameof(propertyInfo));
        Ensure.Any.IsNotNull(propertyValue, nameof(propertyValue));

        var converter = GetTypeConverter(propertyInfo);

        try
        {
            var convertedValue = converter.ConvertFromInvariantString(propertyValue.StringValue);

            propertyInfo.SetValue(Value, convertedValue);
        }
        catch (NotSupportedException ex)
        {
            const string MessageFormat = "Failed to write string value to the '{0}' property.";
            var message = string.Format(CultureInfo.CurrentCulture, MessageFormat, propertyInfo.Name);

            throw new NotSupportedException(message, ex);
        }
    }

    protected virtual void ReadValues(
        IDictionary<string, EntityProperty> properties,
        OperationContext operationContext)
    {
    }

    protected virtual void WriteAdditionalProperty(
        IDictionary<string, EntityProperty> properties,
        PropertyInfo propertyInfo,
        object propertyValue)
    {
        Ensure.Any.IsNotNull(properties, nameof(properties));
        Ensure.Any.IsNotNull(propertyInfo, nameof(propertyInfo));

        var converter = GetTypeConverter(propertyInfo);

        try
        {
            var convertedValue = converter.ConvertToInvariantString(propertyValue);

            properties[propertyInfo.Name] = EntityProperty.GeneratePropertyForString(convertedValue);
        }
        catch (NotSupportedException ex)
        {
            const string MessageFormat = "Failed to convert property '{0}' to a string value.";
            var message = string.Format(CultureInfo.CurrentCulture, MessageFormat, propertyInfo.Name);

            throw new NotSupportedException(message, ex);
        }
    }

    protected virtual void WriteValues(
        IDictionary<string, EntityProperty> properties,
        OperationContext operationContext)
    {
    }

    private static List<AdditionalPropertyMetadata> GetAdditionPropertyMappings(
        T value,
        OperationContext operationContext)
    {
        if (_additionalProperties != null)
        {
            return _additionalProperties;
        }

        List<AdditionalPropertyMetadata> additionalProperties;

        lock (_syncLock)
        {
            // Check the mappings again to protect against race conditions on the lock
            if (_additionalProperties != null)
            {
                return _additionalProperties;
            }

            additionalProperties = ResolvePropertyMappings(value, operationContext);

            _additionalProperties = additionalProperties;
        }

        return additionalProperties;
    }

    private static List<AdditionalPropertyMetadata> ResolvePropertyMappings(
        T value,
        OperationContext operationContext)
    {
        var storageSupportedProperties = TableEntity.WriteUserObject(value, operationContext);
        var objectProperties = value.GetType().GetTypeInfo().GetProperties();
        var infrastructureProperties = typeof(ITableEntity).GetTypeInfo().GetProperties();
        var missingProperties =
            objectProperties.Where(
                objectProperty => storageSupportedProperties.ContainsKey(objectProperty.Name) == false);

        var additionalProperties = missingProperties.Select(
            x => new AdditionalPropertyMetadata
            {
                IsInfrastructureProperty = infrastructureProperties.Any(y => x.Name == y.Name),
                PropertyMetadata = x
            });

        return additionalProperties.ToList();
    }

    private void ReadAdditionalProperties(
        IDictionary<string, EntityProperty> properties,
        IEnumerable<AdditionalPropertyMetadata> additionalMappings)
    {
        // Populate the properties missing from ReadUserObject
        foreach (var additionalMapping in additionalMappings)
        {
            var propertyType = additionalMapping.PropertyMetadata.PropertyType;

            if (additionalMapping.IsInfrastructureProperty)
            {
                ReadInfrastructureProperty(additionalMapping, propertyType);
            }
            else if (properties.ContainsKey(additionalMapping.PropertyMetadata.Name))
            {
                // This is a property that has an unsupport type
                // Use a converter to resolve and apply the correct value
                var propertyValue = properties[additionalMapping.PropertyMetadata.Name];

                ReadAdditionalProperty(additionalMapping.PropertyMetadata, propertyValue);
            }

            // The else case here is that the model now contains a property that was not originally stored when the entity was last written
            // This property will assume the default value for its type
        }
    }

    private void ReadInfrastructureProperty(AdditionalPropertyMetadata additionalMapping, Type propertyType)
    {
        // We don't want to use a string conversion here
        // Explicitly map the types across
        if (additionalMapping.PropertyMetadata.Name == nameof(ITableEntity.Timestamp) &&
            propertyType == typeof(DateTimeOffset))
        {
            additionalMapping.PropertyMetadata.SetValue(Value, Timestamp);
        }
        else if (additionalMapping.PropertyMetadata.Name == nameof(ITableEntity.ETag) &&
                 propertyType == typeof(string))
        {
            additionalMapping.PropertyMetadata.SetValue(Value, ETag);
        }
        else if (additionalMapping.PropertyMetadata.Name == nameof(ITableEntity.PartitionKey) &&
                 propertyType == typeof(string))
        {
            additionalMapping.PropertyMetadata.SetValue(Value, PartitionKey);
        }
        else if (additionalMapping.PropertyMetadata.Name == nameof(ITableEntity.RowKey) &&
                 propertyType == typeof(string))
        {
            additionalMapping.PropertyMetadata.SetValue(Value, RowKey);
        }
        else
        {
            const string UnsupportedPropertyMessage =
                "The {0} interface now defines a property {1} which is not supported by this adapter.";

            var message = string.Format(
                CultureInfo.CurrentCulture,
                UnsupportedPropertyMessage,
                typeof(ITableEntity).FullName,
                additionalMapping.PropertyMetadata.Name);

            throw new InvalidOperationException(message);
        }
    }

    private void WriteAdditionalProperties(
        IEnumerable<AdditionalPropertyMetadata> additionalMappings,
        IDictionary<string, EntityProperty> properties)
    {
        // Populate the properties missing from WriteUserObject
        foreach (var additionalMapping in additionalMappings)
        {
            if (additionalMapping.IsInfrastructureProperty)
            {
                // We need to let the storage mechanism handle the write of the infrastructure properties
                continue;
            }

            var propertyValue = additionalMapping.PropertyMetadata.GetValue(Value);

            WriteAdditionalProperty(properties, additionalMapping.PropertyMetadata, propertyValue);
        }
    }

    public string ETag { get; set; }

    public string PartitionKey
    {
        get
        {
            if (_partitionKey == null)
            {
                _partitionKey = BuildPartitionKey();
            }

            return _partitionKey;
        }
        set { _partitionKey = value; }
    }

    public string RowKey
    {
        get
        {
            if (_rowKey == null)
            {
                _rowKey = BuildRowKey();
            }

            return _rowKey;
        }
        set { _rowKey = value; }
    }

    public DateTimeOffset Timestamp { get; set; }

    public T Value { get; private set; }

    private struct AdditionalPropertyMetadata
    {
        public bool IsInfrastructureProperty { get; set; }

        public PropertyInfo PropertyMetadata { get; set; }
    }
}

The main changes in this version are to better support extensibility. For example, I wanted to read and write properties that are NodaTime.Instant types. This can be achieved with the following:

using System.Collections.Generic;
using System.Diagnostics.CodeAnalysis;
using System.Reflection;
using EnsureThat;
using Microsoft.WindowsAzure.Storage.Table;
using NodaTime;

public abstract class NodaEntityAdapter<T> : EntityAdapter<T> where T : class, new()
{
    protected NodaEntityAdapter()
    {
    }

    protected NodaEntityAdapter(T value)
        : base(value)
    {
    }

    protected override void ReadAdditionalProperty(PropertyInfo propertyInfo, EntityProperty propertyValue)
    {
        Ensure.Any.IsNotNull(propertyInfo, nameof(propertyInfo));
        Ensure.Any.IsNotNull(propertyValue, nameof(propertyValue));

        if (propertyInfo.PropertyType == typeof(Instant?))
        {
            var offsetValue = propertyValue.DateTimeOffsetValue;

            if (offsetValue.HasValue)
            {
                var instant = Instant.FromDateTimeOffset(offsetValue.Value);

                propertyInfo.SetValue(Value, instant);
            }
        }
        else if (propertyInfo.PropertyType == typeof(Instant))
        {
            var offsetValue = propertyValue.DateTimeOffsetValue;
            var instant = Instant.FromDateTimeOffset(offsetValue.Value);

            propertyInfo.SetValue(Value, instant);
        }
        else
        {
            base.ReadAdditionalProperty(propertyInfo, propertyValue);
        }
    }

    protected override void WriteAdditionalProperty(
        IDictionary<string, EntityProperty> properties,
        PropertyInfo propertyInfo,
        object propertyValue)
    {
        Ensure.Any.IsNotNull(properties, nameof(properties));
        Ensure.Any.IsNotNull(propertyInfo, nameof(propertyInfo));

        if (propertyValue == null)
        {
            return;
        }

        if (propertyValue is Instant)
        {
            var value = (Instant) propertyValue;
            var offsetValue = value.ToDateTimeOffset();

            properties[propertyInfo.Name] = EntityProperty.GeneratePropertyForDateTimeOffset(offsetValue);
        }
        else
        {
            base.WriteAdditionalProperty(properties, propertyInfo, propertyValue);
        }
    }
}

Storing, reading and writing entity data can sometimes result in duplicate data. The extensibility points in the adapter can allow you to slim down how the data is stored in the table. This not only reduces the amount of data stored in each row but also how much data is transferred over the wire. My scenarios here tend to be where the PartitionKey and RowKey values are generated using properties on the entity. In these cases, there is no need to store those properties in the storage table because they can be parsed out of the keys.

In this example, I have a StatusChange class that uses ValidationAddressId and optional MailHostId properties for the PartitionKey and then uses the Started time-based property for the RowKey.

using System;
using System.Collections.Generic;
using System.Globalization;
using Microsoft.WindowsAzure.Storage;
using Microsoft.WindowsAzure.Storage.Table;
using NodaTime;
using MyProduct.Models;

public class StatusChangeAdapter : NodaEntityAdapter<StatusChange>
{
    private const string NullValueMarker = "null";
    private const char Separator = '|';

    public StatusChangeAdapter()
    {
    }

    public StatusChangeAdapter(StatusChange statusChange)
        : base(statusChange)
    {
    }
    
    public static string BuildPartitionKey(Guid validationAddressId, Guid? mailHostId)
    {
        var key = validationAddressId.ToString() + Separator;

        if (mailHostId == null)
        {
            key += NullValueMarker;
        }
        else
        {
            key += mailHostId.Value;
        }

        return key;
    }

    public static string BuildRowKey(Instant started)
    {
        // NOTE: ToDateTimeOffset is required here because DateTimeOffset.Ticks is different to Instant.Ticks and legacy data has already been stored using DateTimeOffset.Ticks prior to the migration of code from DateTimeOffset to Instant
        return string.Format(CultureInfo.InvariantCulture, "{0:D19}", started.ToDateTimeOffset().Ticks);
    }

    protected override string BuildPartitionKey()
    {
        return BuildPartitionKey(Value.ValidationAddressId, Value.MailHostId);
    }

    protected override string BuildRowKey()
    {
        return BuildRowKey(Value.Started);
    }

    protected override void ReadValues(
        IDictionary<string, EntityProperty> properties,
        OperationContext operationContext)
    {
        var partitionKeyParts = PartitionKey.Split(Separator);

        // Get the ValidationAddressId and MailHostId from the partition key
        Value.ValidationAddressId = Guid.Parse(partitionKeyParts[0]);
        Value.MailHostId = ParseMailHostId(partitionKeyParts[1]);

        // Get the Started from the row key
        Value.Started = ParseStarted(RowKey);

        base.ReadValues(properties, operationContext);
    }

    protected override void WriteValues(
        IDictionary<string, EntityProperty> properties,
        OperationContext operationContext)
    {
        // Remove values that are stored as part of the partition key
        properties.Remove(nameof(StatusChange.ValidationAddressId));
        properties.Remove(nameof(StatusChange.MailHostId));

        // Remove values that are stored as part of the row key
        properties.Remove(nameof(StatusChange.Started));

        base.WriteValues(properties, operationContext);
    }

    private static Guid? ParseMailHostId(string partitionKeyPart)
    {
        Guid? mailHostId;

        if (partitionKeyPart == NullValueMarker)
        {
            mailHostId = null;
        }
        else
        {
            mailHostId = Guid.Parse(partitionKeyPart);
        }

        return mailHostId;
    }

    private static Instant ParseStarted(string rowKey)
    {
        var scheduledTicks = long.Parse(rowKey);
        var scheduledDateTime = DateTimeOffset.MinValue.AddTicks(scheduledTicks);
        var scheduledForTime = Instant.FromDateTimeOffset(scheduledDateTime);

        return scheduledForTime;
    }
}

The key parts in this example are the ReadValues and WriteValues methods where those three properties are prevented from being written to the table and then rehydrated when the row is read back into an instance of the class.

Versioning C# projects in Azure DevOps build pipeline

Mon, 25 Mar 2019 08:27:00 +0000

I’m a big fan of using GitVersion to calculate an application version based on git history. I’m also a big fan of the new csproj format because of its simplicity. GitVersion provides a build task for Azure DevOps build pipelines but unfortunately it does not yet support setting project versions for the new csproj format. This is my workaround until it is supported out of the box.

The first step is to install an appropriate GitVersion build task from the Visual Studio Marketplace. Add this build task to your build workflow, followed by a PowerShell build step. This does mean that this will only work on Windows build agents. The next step is to add the following inline script to the PowerShell task.

$nuGetVersion = $env:GitVersion_NuGetVersionV2
$sourcesDirectory = $env:BUILD_SOURCESDIRECTORY

Write-Host "Searching for projects under $($sourcesDirectory)"

# Find all the csproj files
if ($nuGetVersion -eq $null) {
    Write-Error ("GitVersion_NuGetVersionV2 environment variable is missing.")
    exit 1
}

if ($env:GitVersion_AssemblySemVer -eq $null) {
    Write-Error ("GitVersion_AssemblySemVer environment variable is missing.")
    exit 1
}

if ($env:GitVersion_MajorMinorPatch -eq $null) {
    Write-Error ("GitVersion_MajorMinorPatch environment variable is missing.")
    exit 1
}

if ($env:GitVersion_InformationalVersion -eq $null) {
    Write-Error ("GitVersion_InformationalVersion environment variable is missing.")
    exit 1
}

if ($sourcesDirectory -eq $null) {
    Write-Error ("BUILD_SOURCESDIRECTORY environment variable is missing.")
    exit 1
}

Function Set-NodeValue($rootNode, [string]$nodeName, [string]$value)
{   
    $nodePath = "PropertyGroup/$($nodeName)"
    
    $node = $rootNode.Node.SelectSingleNode($nodePath)

    if ($node -eq $null) {
        Write-Host "Adding $($nodeName) element to existing PropertyGroup"

        $group = $rootNode.Node.SelectSingleNode("PropertyGroup")
        $node = $group.OwnerDocument.CreateElement($nodeName)
        $group.AppendChild($node) | Out-Null
    }

    $node.InnerText = $value

    Write-Host "Set $($nodeName) to $($value)"
}

# This code snippet gets all the files in $Path that end in ".csproj" and any subdirectories.
Get-ChildItem -Path $sourcesDirectory -Filter "*.csproj" -Recurse -File | 
    ForEach-Object { 
        
        Write-Host "Found project at $($_.FullName)"

        $projectPath = $_.FullName
        $project = Select-Xml $projectPath -XPath "//Project"
        
        Set-NodeValue $project "Version" $nuGetVersion
        Set-NodeValue $project "AssemblyVersion" $env:GitVersion_AssemblySemVer
        Set-NodeValue $project "FileVersion" $env:GitVersion_MajorMinorPatch
        Set-NodeValue $project "InformationalVersion" $env:GitVersion_InformationalVersion 

        $document = $project.Node.OwnerDocument
        $document.PreserveWhitespace = $true

        $document.Save($projectPath)

        Write-Host ""
    }

Write-Host "##vso[build.updatebuildnumber]$($nuGetVersion)"

The build workflow will now identify all csproj files and enter the version information from GitVersion. After these two steps should come the dotnet build task.

I like to re-use these two steps together across many build definitions. You can select both tasks in the build workflow and create a task group which you can reuse. The disadvantage of this is that Azure DevOps identifies the versioning variables in the PowerShell and creates them as parameters to the build task group. The solution to cleaning this up is

Export (download) the task group
Delete the task group and remove it from the build workflow
Edit the downloaded json file to remove the task group parameters
Import the task group
- Edit the task group name but do not select any of the tasks as this will add the parameters back
- Save the task group
Add the task group back to the build workflow, now without annoying parameters

Supporting scopes with xUnit ILogger

Mon, 25 Mar 2019 07:10:00 +0000

I posted previously about a package I put together to easily support rendering ILogger messages to the xUnit test output. This package now supports rendering logging scopes thanks to a pull request by Sebastian Weber.

Here are some samples from the package unit tests to demonstrate how the log output looks.

namespace Divergic.Logging.Xunit.UnitTests
{
    using System;
    using global::Xunit;
    using global::Xunit.Abstractions;
    using Microsoft.Extensions.Logging;
    using ModelBuilder;

    public class ScenarioTests
    {
        private readonly ITestOutputHelper _output;

        public ScenarioTests(ITestOutputHelper output)
        {
            _output = output;
        }

        [Fact]
        public void TestOutputWritesMessagesInContextOfScopes()
        {
            var sut = _output.BuildLogger();

            sut.LogCritical("Writing critical message");
            sut.LogDebug("Writing debug message");
            sut.LogError("Writing error message");
            sut.LogInformation("Writing information message");
            sut.LogTrace("Writing trace message");
            sut.LogWarning("Writing warning message");

            using (sut.BeginScope("First scope"))
            {
                sut.LogInformation("Inside first scope");

                using (sut.BeginScope("Second scope"))
                {
                    sut.LogInformation("Inside second scope");
                }

                sut.LogInformation("After second scope");
            }

            sut.LogInformation("After first scope");
        }

        [Fact]
        public void TestOutputWritesScopeBoundariesUsingObjects()
        {
            var sut = _output.BuildLogger();

            sut.LogCritical("Writing critical message");
            sut.LogDebug("Writing debug message");
            sut.LogError("Writing error message");
            sut.LogInformation("Writing information message");
            sut.LogTrace("Writing trace message");
            sut.LogWarning("Writing warning message");

            var firstPerson = Model.Create<Person>();

            using (sut.BeginScope(firstPerson))
            {
                sut.LogInformation("Inside first scope");

                var secondPerson = Model.Create<Person>();

                using (sut.BeginScope(secondPerson))
                {
                    sut.LogInformation("Inside second scope");
                }

                sut.LogInformation("After second scope");
            }

            sut.LogInformation("After first scope");
        }

        [Fact]
        public void TestOutputWritesScopeBoundariesUsingValueTypes()
        {
            var sut = _output.BuildLogger();

            sut.LogCritical("Writing critical message");
            sut.LogDebug("Writing debug message");
            sut.LogError("Writing error message");
            sut.LogInformation("Writing information message");
            sut.LogTrace("Writing trace message");
            sut.LogWarning("Writing warning message");

            using (sut.BeginScope(Guid.NewGuid()))
            {
                sut.LogInformation("Inside first scope");

                using (sut.BeginScope(Environment.TickCount))
                {
                    sut.LogInformation("Inside second scope");
                }

                sut.LogInformation("After second scope");
            }

            sut.LogInformation("After first scope");
        }

        private class Person
        {
            public DateTime DateOfBirth { get; set; }

            public string Email { get; set; }

            public string FirstName { get; set; }

            public string LastName { get; set; }
        }
    }
}

These tests render the following in the xUnit test results.

TestOutputWritesMessagesInContextOfScopes

Critical [0]: Writing critical message
Debug [0]: Writing debug message
Error [0]: Writing error message
Information [0]: Writing information message
Trace [0]: Writing trace message
Warning [0]: Writing warning message
<Scope: First scope>
   Information [0]: Inside first scope
   <Scope: Second scope>
      Information [0]: Inside second scope
   </Scope: Second scope>
   Information [0]: After second scope
</Scope: First scope>
Information [0]: After first scope

TestOutputWritesScopeBoundariesUsingObjects

Critical [0]: Writing critical message
Debug [0]: Writing debug message
Error [0]: Writing error message
Information [0]: Writing information message
Trace [0]: Writing trace message
Warning [0]: Writing warning message
<Scope 1>
   Scope data: 
   {
     "DateOfBirth": "1921-12-23T05:01:30.9001221Z",
     "Email": "kane.bettis@mega.co.nz",
     "FirstName": "Kane",
     "LastName": "Bettis"
   }
   Information [0]: Inside first scope
   <Scope 2>
      Scope data: 
      {
        "DateOfBirth": "1941-01-08T17:14:30.9521921Z",
        "Email": "carlyn.edwinson@sadecehosting.com",
        "FirstName": "Carlyn",
        "LastName": "Edwinson"
      }
      Information [0]: Inside second scope
   </Scope 2>
   Information [0]: After second scope
</Scope 1>
Information [0]: After first scope

TestOutputWritesScopeBoundariesUsingValueTypes

Critical [0]: Writing critical message
Debug [0]: Writing debug message
Error [0]: Writing error message
Information [0]: Writing information message
Trace [0]: Writing trace message
Warning [0]: Writing warning message
<Scope: f220f378-8301-441a-8199-f7b8d2acfec6>
   Information [0]: Inside first scope
   <Scope: 490797234>
      Information [0]: Inside second scope
   </Scope: 490797234>
   Information [0]: After second scope
</Scope: f220f378-8301-441a-8199-f7b8d2acfec6>
Information [0]: After first scope

You can grab the NuGet package from here.

Run multiple local Azure Functions

Tue, 06 Nov 2018 04:10:00 +0000

I recently broke a fairly large Windows Service application which ran a lot of jobs (using Quartz.net) down into individual Azure Functions. Most of the jobs (now functions) participate in a logic flow of data from one end of the system to the other. While there were many benefits for breaking up this sytem into more of a micro-services architecture, it did leave one big problem. How do you run multiple functions on the local machine?

The first issue you will hit is that running just two functions on the local development machine will fail on the second function. This is because the local host configuration uses the same port which is locked by the first function.

I also had several requirements for running multiple functions. I want to:

control the entire set of functions via one application. This means one application in the task bar rather than a large number of powershell scripts consoles
run additional actions before the function like managing git branches
see the console output of each function (with full colour support)
start all the functions in a single action
stop all the functions in a single action

I tried several options, including starting to write my own application to wrap around the functions CLI but this wasn’t going to be a good enough outcome. The answer was ultimately the very clever ConEmu application.

The way to configure ConEmu to execute multiple local Azure Functions is to go into Settings -> Tasks and add a new predefined task. My predefined task in ConEmu will do the following for each function:

output the current git branch
output the git branch list
pull the current branch
invoke the functions CLI with a build and custom port

For example, the following script is a predefined task that will do the above steps for FunctionA, FunctionB and FunctionC.

cmd.exe /k git branch & git branch -r & git pull & func host start --build --port 7199 -new_console:d:"C:\Repos\FunctionA\FunctionA":t:FunctionA

cmd.exe /k git branch & git branch -r & git pull & func host start --build --port 7200 -new_console:d:"C:\Repos\FunctionB\FunctionB":t:FunctionB

cmd.exe /k git branch & git branch -r & git pull & func host start --build --port 7201 -new_console:d:"C:\Repos\FunctionC\FunctionC":t:FunctionC

ConEmu provides a really nice interface to select a particular named task from a dropdown list and also provides nice taskbar preview for each task/tab.

Filter environment by version in Release Management

Mon, 10 Sep 2018 02:30:00 +0000

I’ve been using VSTS Release Management more and more recently. One of the issues I had (which took me far too long to solve) is how to restrict the automated trigger of a release into a Production environment based on the version (build quality). This actually turned out to be trivial to implement.

Scenario

My scenario is that I use GitVersion as part of my build process to determine what the version of the build should be based on the git history. Anything that is not a production release version will have a version suffix on it, for example 1.2.3-hotfix-InvalidConfig-0001. The production version of that software would then be 1.2.3.

My desired deployment workflow is that any build can go into the staging environment as soon as the build is successful for any build version however only production version builds can go into the production environment.

This works in simple scenarios when I am working on my own projects. More complex software or when a larger team is involved might also have a development and testing environments before the staging environment. In that case I automatically deploy every build to the development environment and then allow testers to manually trigger a deploy to a test environment. Both strategies then end in a manual approval process to deploy into higher environments like staging and production.

Background

Release Management uses triggers to initiate a deployment into any particular environment. For example, an after build trigger would automatically deploy a release into a staging environment after a build is successful. The trigger to the production environment would be for the release to occur after the staging environment. There is usually some kind of manual criteria that would determine when the release should go to the production environment.

The easiest solution to prevent an automated deployment to a production environment is to add an approval restriction. This means that someone needs to explicitly approve the deployment to production. This stops the release from automatically going to production directly after a successful deployment to staging but does not prevent the trigger for the production environment from being attempted. What then happens is that the approval requests for that environment keep piling up for each release. When a production worthy release is then available, each pending approval for prior versions need to be rejected before the desired production release can go into the agent queue.

Release Management also has artefact filters. These can be used to tell Release Management to not trigger a release for an environment if the artefact filter does not match. An artefact filter can be against a branch or build tag. You could, for example, only allow releases to trigger for the production environment where the branch name matches release/*.

Solution

The desired outcome is that a production release trigger does not execute if the build version should never go to production. The answer is to use an artefact filter against a build tag. The way this works is that the build workflow needs to add a tag to the build result which can then be defined as an artefact filter for the production environment.

I use a PowerShell step in my build that looks at the build number to see if it is in the format of [Major].[Minor].[Patch]. This matches the production version number defined by GitVersion. The execution of GitVersion in the build workflow also sets the build number to the version it determines. The script will add a Production Ready tag to the build if the build number looks like a production version.

# Determine if the build number is a production build version
if ($env:BUILD_BUILDNUMBER -match "^\d+\.\d+\.\d+$")
{
    Write-Host "This is a production ready build"

    # Set the build tag to be picked up by release management
    Write-Host "##vso[build.addbuildtag]Production Ready"
}
else
{
    Write-Host "This build is not ready for production"
}

The next step is to configure an artefact filter against the production environment and specify the Production Ready build tag.

The only other thing to consider is the reusability of the above PowerShell. I wrap that task up in a task group so it can be used on any build workflow.

Now every build will go to the staging environment, but the production environment will only trigger (with approval) for a production build version.

Configuration Autofac Module

Tue, 12 Jun 2018 05:30:00 +0000

I’m quite a fan of the JSON configuration support that is available in ASP.Net core. Even better is that using it is not restricted to just ASP.Net and I use it on all my projects. One of the big benefits of this new configuration system is being able to represent configuration as a hierarchy of information rather than a flat list of key value pairs.

I use a lot of dependency injection and it is very common that components in a system require some kind of configuration. My preference is to define an interface for that configuration and then represent that configuration in a JSON settings file.

This post looks at a little Autofac module that can help with loading configuration data into a set of classes and register each of them in an Autofac container.

Installation

The Divergic.Configuration.Autofac NuGet package provides an Autofac module for registering nested configuration types. The package can be installed from NuGet using Install-Package Divergic.Configuration.Autofac.

Scenario

I use the structure of JSON settings data to identify related configuration values. These are normally grouped to a component that requires that configuration.

Consider the following JSON configuration.

{
  "Storage": {
    "Database": "database connection string",
    "BlobStorage": "blob storage connection",
    "TableStorage": "table storage connection"
  },
  "FirstJob": {
    "Name": "My job",
    "TriggerInSeconds": 60
  }
}

Each component that requires the configuration would have a constructor parameter of an interface that represents the configuration.

public interface IStorage
{
    string BlobStorage { get; }
    string Database { get; }
    string TableStorage { get; }
}

public interface IFirstJob
{
    string Name { get; }
    TimeSpan Trigger { get; }
}

The interfaces only define get accessors because the configuration should be immutable for any component that consumes it. You may also notice a mismatch between the JSON data and the IFirstJob.Trigger interface definition above. I like that the interface can remain clean (a TimeSpan in this case) while the configuration glue can provide a translation from the source configuration value.

public class Storage : IStorage
{
    public string BlobStorage { get; set; }
    public string Database { get; set; }
    public string TableStorage { get; set; }
}

public class FirstJob : IFirstJob
{
    public string Name { get; set; }
    public TimeSpan Trigger => TimeSpan.FromSeconds(TriggerInSeconds);
    public int TriggerInSeconds { get; set; }
}

The FirstJob class implements IFirstJob and provides the conversion of the TriggerInSeconds value loaded from JSON data to the Trigger property that the interface defines. This works because loading the JSON data into a class maps the JSON data directly to the class properties.

Configuration Resolution

The module relies on an IConfigurationResolver to load the root configuration class. This class must provide a structure that maps to the JSON data.

public interface IConfig
{
    FirstJob FirstJob { get; }
    Storage Storage { get; }
}

public class Config : IConfig
{
    public FirstJob FirstJob { get; set; }
    public Storage Storage { get; set; }
}

The module will recursively register all properties found on the root configuration using AsSelf as well as AsImplementedInterfaces where implemented interfaces are found.

Json Resolution

The provided JsonResolver<T> resolver will load the root configuration (of type T) from an appsettings.json file by default. This can be used by ConfigurationModule like the following.

var builder = new ContainerBuilder();

builder.RegisterModule<ConfigurationModule<JsonResolver<Config>>>();

var container = builder.Build();

The JsonResolver class can accept a different filename if the default appsettings.json is not suitable.

var builder = new ContainerBuilder();
var resolver = new JsonResolver<Config>("hostsettings.json");
var module = new ConfigurationModule(resolver);

builder.RegisterModule(module);

var container = builder.Build();

Need environment configuration override support? This would work in ASP.Net core.

var env = builderContext.HostingEnvironment;
var builder = new ContainerBuilder();

var resolver = new EnvironmentJsonResolver<Config>("appsettings.json", $"appsettings.{env.EnvironmentName}.json");
var module = new ConfigurationModule(resolver);

builder.RegisterModule(module);

var container = builder.Build();

Custom Resolution

Need to resolve a root configuration object from something other than a JSON file? The ConfigurationModule will accept any IConfigurationResolver. You can write any custom resolver and provide it to the module.

Outcome

The module will register each of the nested properties on the resolved root configuration class with the Autofac container. Given the scenario above, the following resolutions on the container will be valid.

var builder = new ContainerBuilder();

builder.RegisterModule<ConfigurationModule<JsonResolver<Config>>>();

var container = builder.Build();

container.Resolve<IConfig>();
container.Resolve<Config>();
container.Resolve<IStorage>();
container.Resolve<Storage>();
container.Resolve<IFirstJob>();
container.Resolve<FirstJob>();

Each of these resolutions can now participate in dependency injection for any other class.

ILogger for Sentry.io

Thu, 07 Jun 2018 22:07:00 +0000

Exception reporting and alerting has always been important for software delivery. I’ve seen companies use many solutions for this over the years, from using email as an error logging system (that story does not end well….twice) to the Windows Event Log that people usually do not monitor. On the other end of the spectrum are more mature systems like Raygun.com and Sentry.io.

Aligning with the idea of “don’t build something that someone else can do better and cheaper”, I’ve been using Raygun and Sentry for years. Over this time I’ve been looking at easier ways of integrating with these systems while also reducing coupling in the application code. This post looks at how to integrate with Sentry via ILogger.

Using ILogger as the integration point works well because logging is almost always a cross-cutting concern. Well defined systems are likely to already have logging integrated throughout the code so reporting exceptions to Sentry via ILogger can be achieved with very little effort. Coupling application code to ILogger is also preferable to coupling code to Sentry’s IRavenClient. With enough integration smarts, most of the application code should not have to understand how to talk to Sentry in order to send exceptions their way.

I’ve published a suite of Divergic.Logging NuGet packages to add support for this integration (open-source on GitHub). The design of the packages achieve several goals.

Easy installation
Sole dependency in “application” code is ILogger
Minimal bootstrapping required in “host” code
Support custom exception properties
Support logging context data
Prevent duplicate reports
Support Autofac
Support special serialization (NodaTime)
Clean stacktrace reporting

Installing

There are several NuGet packages to give flexibility around how applications can use this feature.

Install-Package Divergic.Logging.Sentry on NuGet.org contains the ILogger provider for sending exceptions to Sentry
Install-Package Divergic.Logging.Sentry.Autofac on NuGet.org extends the base package to provide an Autofac module to register RavenClient in Autofac
Install-Package Divergic.Logging.NodaTime on NuGet.org extends the inherited Divergic.Logging base package to support serialization of NodaTime data types

All the above packages depend on the Divergic.Logging package that provides ILogger extension methods for adding context information to an exception.

Bootstrapping

Applications often have some kind of bootstrapping code when they start up which is where logging is typically configured. The Divergic.Logging.Sentry package requires access to an ILoggerFactory instance on which it provides the AddSentry extension method. An ASP.Net core application for example will provide ILoggerFactory in the Configure method.

public void Configure(
    IApplicationBuilder app,
    IHostingEnvironment env,
    ILoggerFactory loggerFactory,
    IApplicationLifetime appLifetime)
{
    // You will need to create the RavenClient before configuring the logging integration
    var ravenClient = BuildRavenClient();
    
    loggerFactory.AddSentry(ravenClient);
}

Any ILogger instance created with the factory will now send exceptions to Sentry. Any log message without an exception will be ignored by this logging provider.

Custom properties

Exceptions in .Net often contain additional information that is not included in the Exception.Message property. Some good examples of this are SqlException, ReflectionTypeLoadException and the Azure StorageException. The ReflectionTypeLoadException message for example will log the following message.

ReflectionTypeLoadException: Unable to load one or more of the requested types. Retrieve the LoaderExceptions property for more information.

These properties contain additional metadata about the exception that is critical to identifying the error. Unfortunately most logging systems will only log the exception stacktrace and message. The result is an error report that is unactionable.

One of the advantages of RavenClient is that the System.Exception.Data property is sent in the error report to Sentry. What is missing is the ability to record any other custom exception properties. The Divergic.Logging.Sentry package caters for this by adding each custom exception property to the Data property so that it will be sent to Sentry.

Consider the following exception.

public class Person
{
    public string Email { get; set; }

    public string FirstName { get; set; }

    public string LastName { get; set; }
}

public class Company
{
    public string Address { get; set; }

    public string Name { get; set; }

    public Person Owner { get; set; }
}

public class CustomPropertyException : Exception
{
    public Company Company { get; set; }

    public int Value { get; set; }
}

If this exception was to be thrown and logged without custom property data, the Sentry record would contain something like the following report.

{
   "message":"Exception of type 'Divergic.Logging.Sentry.IntegrationTests.CustomPropertyException' was thrown.",
   "metadata":{
      "type":"CustomPropertyException",
      "value":"Exception of type 'Divergic.Logging.Sentry.IntegrationTests.CustomPropertyException' was thrown."
   }
}

Capturing the custom properties on the exception for the Sentry report now allows the error report to have much richer information.

{
   "message":"Exception of type 'Divergic.Logging.Sentry.IntegrationTests.CustomPropertyException' was thrown.",
   "extra":{
      "CustomPropertyException.Value":2309842,
      "CustomPropertyException.Company":"{\"Address\":\"839 Anniversary Drive\",\"Name\":\"McIleen Inc\",\"Owner\":{\"Email\":\"glori.mcileen@ravenjs.com\",\"FirstName\":\"Glori\",\"LastName\":\"McIleen\"}}"
   },
   "metadata":{
      "type":"CustomPropertyException",
      "value":"Exception of type 'Divergic.Logging.Sentry.IntegrationTests.CustomPropertyException' was thrown."
   }
}

Logging context data

A common issue when dealing with error reports is not having enough information to repond to the error. Logging just the exception data may not be sufficient.

Consider the following exception.

public class PaymentGatewayException: Exception
{
    public PaymentGatewayException() : base("Failed to process complete transaction at the payment gateway.")
    {
    }
}

Sending this exception to Sentry would produce an error report with something like the following.

{
   "message":"Failed to process complete transaction at the payment gateway.",
   "metadata":{
      "type":"PaymentGatewayException",
      "value":"Failed to process complete transaction at the payment gateway."
   }
}

In this scenario, the message of the exception may be written for the purposes of sending the text to a user interface. That does not help in resolving the issue when the exception is reported to Sentry. We may need to know what was being processed at the time. The inherited Divergic.Logging package uses the same technique as reporting custom exception properties above by providing LogErrorWithContext and LogCriticalWithContext extension methods on ILogger.

public async Task ProcessPayment(string invoiceId, int amountInCents, Person customer, CancellationToken cancellationToken)
{
    try
    {
        await _gateway.ProcessPayment(invoiceId, amountInCents, customer.Email, cancellationToken).ConfigureAwait(false);
    }
    catch (PaymentGatewayException ex)
    {
        var paymentDetails = new {
            invoiceId,
            amountInCents
        };
        
        _logger.LogErrorWithContext(ex, paymentDetails);
    }
}

This additional context data is then sent to Sentry.

{
   "extra":{
      "ContextData": "{\"invoiceId\":\"239349asfd-234234\",\"amountInCents\":3995}",
   },
   "metadata":{
      "type":"PaymentGatewayException",
      "value":"Failed to process complete transaction at the payment gateway."
   }
}

Preventing duplicate reports

Exceptions can be caught, logged and then thrown again. A catch block higher up the callstack may then log the same exception a second time. This scenario is handled by ensuring that any particular exception instance is only reported to Sentry once.

Supporting Autofac

The Divergic.Logging.Sentry.Autofac package contains SentryModule to assist with setting up Sentry in an Autofac container. The requirement is that the application bootstrapping has already been able to create an ISentryConfig instance and registered it in Autofac. SentryModule registers a new RavenClient instance using that configuration.

Here is an example for ASP.Net core.

internal static IContainer BuildContainer(ISentryConfig sentryConfig)
{
    var builder = new ContainerBuilder();
    
    builder.AddInstance(sentryConfig).As<ISentryConfig>();
    builder.AddModule<SentryModule>();
    
    return builder.Build();
}

public IServiceProvider ConfigureServices(IServiceCollection services)
{
    // Load this from a configuration, this is just an example
    var sentryConfig = new SentryConfig
    {
        Dsn = "Sentry DSN value here",
        Environment = "Local",
        Version = "0.1.0"
    }

    var container = BuildContainer(sentryConfig);
    
    var loggerFactory = services.BuildServiceProvider().GetService<ILoggerFactory>();
    var ravenClient = container.Resolve<IRavenClient>();    
    
    loggerFactory.AddSentry(ravenClient);
    
    // Create the IServiceProvider based on the container.
    return new AutofacServiceProvider(container);
}

Support NodaTime serialization

Sending custom exception properties and exception context data to Sentry is only useful if the data can be understood. NodaTime.Instant is a good example of this. The native JSON serialization of an Instant value will be {} rather than a readable date/time value.

Consider the following exception.

public class CustomPropertyException : Exception
{
    public Instant Point { get; set; }
}

Logging this exception to Sentry without NodaTime JSON serialization support would send the following to Sentry.

{
   "message":"Exception of type 'Divergic.Logging.Sentry.IntegrationTests.CustomPropertyException' was thrown.",
   "extra":{
      "CustomPropertyException.Point":"{}"
   },
   "metadata":{
      "type":"CustomPropertyException",
      "value":"Exception of type 'Divergic.Logging.Sentry.IntegrationTests.CustomPropertyException' was thrown."
   }
}

The Divergic.Logging.NodaTime package provides a UsingNodaTimeTypes extension method on ILoggerFactory. This will configure the correct JSON serialization of NodaTime types when sending errors to Sentry.

public void Configure(
    IApplicationBuilder app,
    IHostingEnvironment env,
    ILoggerFactory loggerFactory,
    IApplicationLifetime appLifetime)
{
    loggerFactory.UsingNodaTimeTypes();
}

Sentry would then receive something like the following for the above example.

{
   "message":"Exception of type 'Divergic.Logging.Sentry.IntegrationTests.CustomPropertyException' was thrown.",
   "extra":{
        "CustomPropertyException.Point": "\"2018-06-03T13:34:42.2533212Z\"",
   },
   "metadata":{
      "type":"CustomPropertyException",
      "value":"Exception of type 'Divergic.Logging.Sentry.IntegrationTests.CustomPropertyException' was thrown."
   }
}

Clean stacktrace reporting

A long standing complaint with .Net has been how stacktraces are difficult to read when async/await is involved. While this should be improved in .Net core 2.1, all prior .Net versions suffer from this issue. As part of sending exceptions to Sentry, the Divergic.Logging.Sentry package will also include a CleanedException value in the error report. This value will contain the Exception.ToString of the exception after it has been through Demystify via the Ben.Demystifier NuGet package. Read more about it here.

Conclusion

These packages aim to provide a simple and elegant method of sending exceptions to Sentry with the minimum amount of effort. Now you can go forth and fail in style and clarity.

ILogger for xUnit

Fri, 01 Jun 2018 04:03:00 +0000

It is very common to have logging in your code. Unfortunately there is not a great way for asynchronous test frameworks to capture that output when running unit tests. The xUnit test package is my favourite test framework and I would like to see the logging from my classes being tested ending up in the xUnit test results.

I have published the Divergic.Logging.Xunit package on NuGet to support this. The package returns an ILogger or ILogger<T> that wraps around the ITestOutputHelper supplied by xUnit. xUnit uses this helper to write log messages to the test output of each test execution. This means that any log messages from classes being tested will end up in the xUnit test result output.

Installation

Run the following in the NuGet command line or visit the NuGet package page.

Install-Package Divergic.Logging.Xunit

Usage

The common usage of this package is to call the BuildLogger extension method on the xUnit ITestOutputHelper.

using System;
using FluentAssertions;
using Microsoft.Extensions.Logging;
using Xunit;
using Xunit.Abstractions;

public class MyClass
{
    private readonly ILogger _logger;

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

    public string DoSomething()
    {
        _logger.LogInformation("Hey, we did something");

        return Guid.NewGuid().ToString();
    }
}

public class MyClassTests
{
    private readonly ITestOutputHelper _output;
    private readonly ILogger _logger;

    public MyClassTests(ITestOutputHelper output)
    {
        _output = output;
        _logger = output.BuildLogger();
    }

    [Fact]
    public void DoSomethingReturnsValueTest()
    {
        var sut = new MyClass(_logger);

        var actual = sut.DoSomething();

        // The xUnit test output should now include the log message from MyClass.DoSomething()

        actual.Should().NotBeNullOrWhiteSpace();
    }
}

This would output the following in the test results.

Information [0]: Hey, we did something

Support for ILogger<T> is there using the BuildLoggerFor<T> extension method.

using System;
using FluentAssertions;
using Microsoft.Extensions.Logging;
using Xunit;
using Xunit.Abstractions;

public class MyClassTests
{
    private readonly ITestOutputHelper _output;
    private readonly ILogger<MyClass> _logger;

    public MyClassTests(ITestOutputHelper output)
    {
        _output = output;
        _logger = output.BuildLoggerFor<MyClass>();
    }

    [Fact]
    public void DoSomethingReturnsValueTest()
    {
        var sut = new MyClass(_logger);

        var actual = sut.DoSomething();

        // The xUnit test output should now include the log message from MyClass.DoSomething()

        actual.Should().NotBeNull();
    }
}

Inspection

Using this library makes it really easy to output log messages from your code as part of the test results. You may want to also inspect the log messages written as part of the test assertions as well.

The BuildLogger and BuildLoggerFor<T> extension methods support this by returning a ICacheLogger or ICacheLogger<T> respectively. The cache logger is a wrapper around the created logger and exposes all the log entries written by the test.

using System;
using Divergic.Logging.Xunit;
using FluentAssertions;
using Microsoft.Extensions.Logging;
using Xunit;
using Xunit.Abstractions;

public class MyClassTests
{
    private readonly ITestOutputHelper _output;
    private readonly ICacheLogger _logger;

    public MyClassTests(ITestOutputHelper output)
    {
        _output = output;
        _logger = output.BuildLogger();
    }

    [Fact]
    public void DoSomethingReturnsValueTest()
    {
        var sut = new MyClass(_logger);

        sut.DoSomething();
        
        _logger.Count.Should().Be(1);
        _logger.Entries.Should().HaveCount(1);
        _logger.Last.Message.Should().Be("Hey, we did something");
    }
}

Perhaps you don’t want to use the xUnit ITestOutputHelper but still want to use the ICacheLogger to run assertions over log messages written by the class under test. You can do this by creating a CacheLogger or CacheLogger<T> directly.

using System;
using Divergic.Logging.Xunit;
using FluentAssertions;
using Microsoft.Extensions.Logging;
using Xunit;

public class MyClassTests
{
    [Fact]
    public void DoSomethingReturnsValueTest()
    {
        var logger = new CacheLogger();

        var sut = new MyClass(_logger);

        sut.DoSomething();
        
        logger.Count.Should().Be(1);
        logger.Entries.Should().HaveCount(1);
        logger.Last.Message.Should().Be("Hey, we did something");
    }
}

Configure LoggerFactory

You may have an integration or acceptance test that requires additional configuration to the log providers on ILoggerFactory while also supporting the logging out to xUnit test results. You can do this by create a factory that is already configured with xUnit support.

using System;
using Divergic.Logging.Xunit;
using FluentAssertions;
using Microsoft.Extensions.Logging;
using Xunit;
using Xunit.Abstractions;

public class MyClassTests
{
    private readonly ILogger _logger;

    public MyClassTests(ITestOutputHelper output)
    {
        var factory = LogFactory.Create(output);

        // call factory.AddConsole or other provider extension method

        _logger = factory.CreateLogger(nameof(MyClassTests));
    }

    [Fact]
    public void DoSomethingReturnsValueTest()
    {
        var sut = new MyClass(_logger);

        // The xUnit test output should now include the log message from MyClass.DoSomething()

        var actual = sut.DoSomething();

        actual.Should().NotBeNullOrWhiteSpace();
    }
}

Existing Loggers

Already have an existing logger and want the above cache support? Got you covered there too using the WithCache() method.

using System;
using Divergic.Logging.Xunit;
using FluentAssertions;
using Microsoft.Extensions.Logging;
using NSubstitute;
using Xunit;

public class MyClassTests
{
    [Fact]
    public void DoSomethingReturnsValueTest()
    {
        var logger = Substitute.For<ILogger>();

        logger.IsEnabled(Arg.Any<LogLevel>()).Returns(true);

        var cacheLogger = logger.WithCache();

        var sut = new MyClass(cacheLogger);

        sut.DoSomething();

        cacheLogger.Count.Should().Be(1);
        cacheLogger.Entries.Should().HaveCount(1);
        cacheLogger.Last.Message.Should().Be("Hey, we did something");
    }
}

The WithCache() also supports ILogger<T>.

using System;
using Divergic.Logging.Xunit;
using FluentAssertions;
using Microsoft.Extensions.Logging;
using NSubstitute;
using Xunit;

public class MyClassTests
{
    [Fact]
    public void DoSomethingReturnsValueTest()
    {
        var logger = Substitute.For<ILogger<MyClass>>();

        logger.IsEnabled(Arg.Any<LogLevel>()).Returns(true);

        var cacheLogger = logger.WithCache();

        var sut = new MyClass(cacheLogger);

        sut.DoSomething();

        cacheLogger.Count.Should().Be(1);
        cacheLogger.Entries.Should().HaveCount(1);
        cacheLogger.Last.Message.Should().Be("Hey, we did something");
    }
}