AutoFixture - PostProcessor runs custom ISpecimenCommand twice

Question

I'm trying to add an ICustomization implementation to write generated fixture values to the console to aid in diagnosing intermittent test failures in our nightly build test runs.

The problem I'm having is that each value gets written to the console twice. Unfortunately all the examples and documentation I can find relate to custom processing for specific types - I'd like to write something that runs for all types, so that it logs the value for any fixture generated.

Below is a simplified version of what I've created so far (snippet from LINQPad).

void Main()
{
  var fixture = new Fixture();
  fixture.Customize(new CustomCustomisation());
  fixture.Create<double>();
}

public class CustomCustomisation : ICustomization
{
  public void Customize(IFixture fixture)
  {
    var engine = ((Fixture)fixture).Engine;
    fixture.Customizations.Add(new Postprocessor(engine, new LogSpecimenCommand()));
  }
}

public class LogSpecimenCommand : ISpecimenCommand
{
  public void Execute(object specimen, ISpecimenContext context)
  {
    if (specimen == null || specimen is NoSpecimen) return;
    Console.WriteLine($"SPECIMEN: {specimen}");
  }
}

The output from the above is:

SPECIMEN: 213
SPECIMEN: 213

Answer 1

According to my investigations on AutoFixture, the way AutoFixture works when creating a new specimen is by using a chain of responsibility. This means that in general, it will take several requests and several creations to generate a specimen, and for each of these creations a LogSpecimenCommand is being issued, hence you get your trace twice.

Please read Extending AutoFixture to understand the context of my answer. There, I saw that AutoFixture provides a TracingBehaviour that seems to cover your case of use. TracingBehaviour will emit traces for both the requests and creations of specimens. If configure your fixture to use this behaviour:

var fixture = new Fixture();
fixture.Behaviors.Add(new TracingBehavior());
fixture.Create<double>();

It will write this output to the console:

  Requested: AutoFixture.Kernel.SeededRequest
    Requested: System.Double
    Created: 140
  Created: 140

Note how it takes two different requests, AutoFixture.Kernel.SeededRequest and System.Double (and their corresponding creations) to generate the double specimen. Also worth noting is that the output indentation for each entry hints that there's a way to order the requests and creations according to their place in the chain of responsibility.

After seeing the implementation of TracingBehaviour and the related types TracingBuilder and TraceWriter, I managed to generate a CustomTracingBehaviour and a CustomTraceWriter that also leverage TracingBuilder to write to the console with a custom trace format.

TracingBuilder is a Specimen Builder that raises the event:

public event EventHandler<SpecimenCreatedEventArgs> SpecimenCreated;

so we can subscribe to this event to generate a trace whenever a specimen is created.

Create a transformation¹ of TracingBuilder. I've called it CustomTracingBehaviour and it's a simpler version of AutoFixture's TracingBehaviour. Create also a CustomTraceWriter, which again is a simpler version of AutoFixture's TraceWriter. CustomTraceWriter has a reference to the TracingBuilder passed from the CustomTracingBehaviour.

Inside the event handler OnSpecimenCreated, you can write your traces in your desired format. SpecimenCreatedEventArgs comes with both the created specimen and the depth of the creation event. After some quick tests, I figured that 1 is the lowest possible depth, so if you check for the depth before writing your traces, you can ensure that only one trace is created for the whole chain of requests and creations corresponding to a single specimen.

public class CustomTracingBehavior : ISpecimenBuilderTransformation
{
    public ISpecimenBuilderNode Transform(ISpecimenBuilder builder)
    {
        return new CustomTraceWriter(new TracingBuilder(builder));
    }
}

public class CustomTraceWriter : ISpecimenBuilder, ISpecimenBuilderNode, IEnumerable<ISpecimenBuilder>, IEnumerable
{
    public TracingBuilder Tracer { get; }

    public CustomTraceWriter(TracingBuilder tracer)
    {
        Tracer = tracer;

        Tracer.SpecimenCreated += OnSpecimenCreated;
    }

    private void OnSpecimenCreated(object sender, SpecimenCreatedEventArgs e)
    {
        if (e.Specimen == null || e.Specimen is NoSpecimen) return;

        if (e.Depth > 1) return;

        Console.WriteLine($"SPECIMEN: {e.Specimen}");
    }

    public object Create(object request, ISpecimenContext context)
    {
        return Tracer.Create(request, context);
    }

    public ISpecimenBuilderNode Compose(IEnumerable<ISpecimenBuilder> builders)
    {
        var compositeSpecimenBuilder = new CompositeSpecimenBuilder(builders);

        ISpecimenBuilder builder = compositeSpecimenBuilder.Compose(builders);
        return new CustomTraceWriter(new TracingBuilder(builder));
    }

    public IEnumerator<ISpecimenBuilder> GetEnumerator()
    {
        yield return Tracer.Builder;
    }

    IEnumerator IEnumerable.GetEnumerator()
    {
        return GetEnumerator();
    }

Then, add the custom behaviour after instantiating your fixture:

var fixture = new Fixture();
fixture.Behaviors.Add(new CustomTracingBehavior());

fixture.Create<double>();

This will produce the following output:

SPECIMEN: 227

---

¹ By using a custom ISpecimenBuilderTransformation, we can transform an ISpecimenBuilder into an ISpecimenBuilderNode. According to the remarks on ISpecimenBuilderNode, this means that a transformed SpecimenBuilder will no longer be the one generating the specimen, but it will pass that responsibility along to a further SpecimenBuilder:

Each AutoFixture.Kernel.ISpecimenBuilder gets a chance to handle a request, and if it can't do that, the next ISpecimenBuilder is asked to handle the request. When an ISpecimenBuilder instance returns a useful specimen, that instance is returned and the results (if any) from lower-priority SpecimenBuilder instances are ignored. In theory, one could order all SpecimenBuilder instances in a flat Chain of Responsibility, but instead, the SpecimenBuilderNode interface defines the responsibilities of a 'parent' node in a deeper graph. Each ISpecimenBuilder node constitute an intermediate node in a graph, while itself being a parent to other nodes. In the degenerate case when an ISpecimenBuilderNode has no child nodes, it effectively becomes a leaf node. Otherwise, leaf nodes are typically ISpecimenBuilder instances.