Why doesn't tracing behavior appear to work when added to Autofixture Fixture.Behaviors in an AutoDataAttribute implementation?

Question

When I add a new TracingBehavior to an AutoFixture Fixture instance using

fixture.Behaviors.Add(new TracingBehavior());

I get tracing output in my R# Unit Test Sessions window.

However, when I inherit AutoDataAttribute and add the behavior inside my attribute's constructor like this

I get no tracing output, even though the tests would indicate that the TracingBehavior has been added to the Fixture.Behaviors in both scenarios. Below are two simple tests and the attribute implementation to reproduce.

public class TracingBehaviorTests
{
    [Theory, AutoData]
    public void TracingOutputDisplayedWhenManuallyAddedToFixture(Fixture fixture)
    {
        fixture.Behaviors.Add(new TracingBehavior());
        var actual = fixture.Behaviors.OfType<TracingBehavior>().Any();
        Assert.Equal(true, actual); // Passes
        fixture.Create<string>();   // Tracing output displayed
    }

    [Theory, TracingFixtureConventions]
    public void TracingOutputDisplayedWhenUsingTracingFixtureConventionsAttribute(Fixture fixture)
    {
        var actual = fixture.Behaviors.OfType<TracingBehavior>().Any();
        Assert.Equal(true, actual); // Passes
        fixture.Create<string>();   // No tracing output displayed
    }
}

public class TracingFixtureConventionsAttribute : AutoDataAttribute
{
    public TracingFixtureConventionsAttribute()
        : base(new Fixture())
    {
        this.Fixture.Behaviors.Add(new TracingBehavior());
    }
}

related: http://stackoverflow.com/questions/7138935/xunit-net-does-not-capture-console-output — Ruben Bartelink, Oct 06 '13 at 07:44

score 4 · Accepted Answer · answered Sep 04 '13 at 06:45

I had to do a little digging to figure out why this is happening.

The reason you're seeing this behaviour is that when you use the default constructor of TracingBehavior, Console.Out is the destination.

When executing a test case, the xUnit.net test runner assigns another TextWriter to Console.Out.

This happens before the code block in the test method is executed, which explains why the first test in the OP displays the trace: when the TracingBehavior instance is created, Console.Out is already the captured TextWriter.

However, in the second test (using the [TracingFixtureConventions] attribute), Console.Out has not yet been replaced when the attribute's constructor runs. So, when this test runs, it actually traces to the original Console.Out, but since there's no console present, it traces into a void.

You can verify that both test cases actually do log by logging to a file instead:

public class TracingBehaviorTests
{
    [Theory, AutoData]
    public void TracingOutputDisplayedWhenManuallyAddedToFixture(Fixture fixture)
    {
        using (var tw = File.AppendText(Path.Combine(Environment.CurrentDirectory, "log.txt")))
        {
            tw.AutoFlush = true;
            fixture.Behaviors.Add(new TracingBehavior(tw));
            var actual = fixture.Behaviors.OfType<TracingBehavior>().Any();
            Assert.Equal(true, actual); // Passes
            fixture.Create<string>();   // Tracing output logged to file
        }
    }

    [Theory, TracingFixtureConventions]
    public void TracingOutputDisplayedWhenUsingTracingFixtureConventionsAttribute(Fixture fixture)
    {
        var actual = fixture.Behaviors.OfType<TracingBehavior>().Any();
        Assert.Equal(true, actual); // Passes
        fixture.Create<string>();   // Tracing output logged to file
    }
}

public class TracingFixtureConventionsAttribute : AutoDataAttribute
{
    public TracingFixtureConventionsAttribute()
        : base(new Fixture())
    {
        var tw = File.AppendText(Path.Combine(Environment.CurrentDirectory, "log.txt"));
        tw.AutoFlush = true;
        this.Fixture.Behaviors.Add(new TracingBehavior(tw));
    }
}

The above 'fix' is rather fragile, because (as written here) the [TracingFixtureConventions] attribute doesn't dispose of tw, so if the test adorned with the [TracingFixtureConventions] attribute runs first, the log file is in use, and the other test will not be able to write to it.

For now, I'll leave it as an exercise to the reader to figure out how to make file logging more robust, if that's something anyone cares about. Personally, I only use AutoFixture tracing to troubleshoot, and always turn it off again once I'm done troubleshooting.

Ugh. That *is* tricky. Looked into injecting a `StringWriter` instance into the Attribute constructor, only to discover the best you can do is pass in a `Type` and use `Activator.CreateInstance()` inside. But, then, how does one dispose of the `StringWriter` only *after* it's used in the test... — Jeff, Sep 04 '13 at 16:32
That may or may not be possible... See e.g. http://stackoverflow.com/q/15496493/126014 and https://github.com/AutoFixture/AutoFixture/issues/17 for further information. However, why would you want to turn on tracing for *everything*? It's going to produce *loads* of data... — Mark Seemann, Sep 04 '13 at 18:52
I agree that it's most helpful when troubleshooting a bug. My thought was that I might find a way to access the xUnit test runner's StringWriter instance and inject it into my Attribute, but I don't know that xUnit would expose that, nor where I would pick up the reference to xUnit. The tracing would be on for everything within the test that used the custom Attribute, but it would blowup at the bug, so I would just scroll to the bottom of the trace to see where the problem occurred. That was what I was thinking, anyway. Will check your links. — Jeff, Sep 04 '13 at 19:07

Why doesn't tracing behavior appear to work when added to Autofixture Fixture.Behaviors in an AutoDataAttribute implementation?

1 Answers1