AfterTestRun executing twice when I use TestTracerDecorator

[qtpvarun]

I use TestTracerDecorator as https://www.snip2code.com/Snippet/470614/SpecFlow-XTC-screenshot-workaround

Additionally I use the constructor

private readonly ITestTracer _testTracer;
        private readonly ITraceListener traceListener;
        private readonly IStepFormatter stepFormatter;
        private readonly IStepDefinitionSkeletonProvider stepDefinitionSkeletonProvider;
        private readonly RuntimeConfiguration runtimeConfiguration;

        private StepInstance _currentStepInstance;

        public TestTracerDecorator(ITestTracer testTracer)
        {
            _testTracer = testTracer;

            var traceListenerField = _testTracer.GetType().GetField("traceListener", BindingFlags.Instance | BindingFlags.NonPublic);
            traceListener = (ITraceListener)traceListenerField.GetValue(_testTracer);

            var stepFormatterField = _testTracer.GetType().GetField("stepFormatter", BindingFlags.Instance | BindingFlags.NonPublic);
            stepFormatter = (IStepFormatter)stepFormatterField.GetValue(_testTracer);

            var stepDefinitionSkeletonProviderField = _testTracer.GetType().GetField("stepDefinitionSkeletonProvider", BindingFlags.Instance | BindingFlags.NonPublic);
            stepDefinitionSkeletonProvider = (IStepDefinitionSkeletonProvider)stepDefinitionSkeletonProviderField.GetValue(_testTracer);

            var runtimeConfigurationField = _testTracer.GetType().GetField("runtimeConfiguration", BindingFlags.Instance | BindingFlags.NonPublic);
            runtimeConfiguration = (RuntimeConfiguration)runtimeConfigurationField.GetValue(_testTracer);

            traceListener.WriteToolOutput("TestTracer:Constructor");
        }

And Before Scenario as below

[BeforeScenario(Order = 10)]
        public void BeforeScenario()
        {
            string scenarioInfoTitle = ScenarioContext.Current.ScenarioInfo.Title;
            string[] scenarioInfoTags = ScenarioContext.Current.ScenarioInfo.Tags;
            string scenarioBrowser = "Chrome";

            var testRunner = TestRunnerManager.GetTestRunner();
            var executionEngineField = testRunner.GetType().GetField("executionEngine", BindingFlags.Instance | BindingFlags.NonPublic);
            var executionEngine = executionEngineField.GetValue(testRunner);
            var testTracerField = executionEngine.GetType().GetField("testTracer", BindingFlags.Instance | BindingFlags.NonPublic);

            var testTracerValue = testTracerField.GetValue(executionEngine);

            if (!(testTracerValue is TestTracerDecorator))
            {
                testTracerField.SetValue(executionEngine, new TestTracerDecorator(testTracerValue as ITestTracer));
            }

            TestSuiteLogger.BeforeScenario(scenarioInfoTitle, scenarioBrowser, scenarioInfoTags);
        }

but on test execution 1> TestTracerDecorator is not called for each of the events 2> beforetestrun thrice and aftertestrun twice (or thrice not sure)

On removing TestTracerDecorator from BeforeScenario it works fine.

I use visual studio 2013 ultimate

[qtpvarun]

I could see similar for beforetestrun but not for aftertestrun here https://github.com/techtalk/SpecFlow/issues/139 hence created new issue

[qtpvarun]

Also I could see different behaviour or I missed previously, now I can see single test had called beforetestrun thrice and aftertestrun twice. and on commenting below line it works fine.

var testRunner = TestRunnerManager.GetTestRunner();

One more observation is that both BeforeScenario and BeforeTestRun are in same class, is it because of this? it calls BeforeScenario, then instantiates Hooks.cs and then again calls BeforeScenario twice totally thrice.

[SabotageAndi]

As far as I understand the code, you want to make a screenshot after each step, or?

Why do you not use a simple AfterStep- Hook? See: http://www.specflow.org/documentation/Hooks/

As an alternative to set the stuff via reflection, you could create a RuntimePlugin and register you TestTracerDecorator there. See https://github.com/techtalk/SpecFlow/wiki/Available-Containers-&-Registrations for the correct container.

[qtpvarun]

Thank s for your guidance, reason I cant use AfterStep - Hook is that I am creating the logger (selenium specflow tests) where I would need MethodInfo from IBindingMethod, which is not available in AfterStep - Hook.

Alternatively till now I was using method info logging with intercepts at two different layers (Binding methods and at Page Object Methods). I think https://github.com/timschlechter/SpecResults also uses similar intercept to achieve the logging at Binding method layer. Limitation of this approach is that we have to use base bindingclass derived from context object.

But during platform release we are asked remove the base binding class and use other base class which all other team are also using.

But the logging information is very much needed hence moving to TestTracerDecorator, I am giving a try with RuntimePlugin and update the observation here.

In parallel if you can check do we have any reason why TestRunnerManager.GetTestRunner(); introduces multiple before\after test run hooks?

[SabotageAndi]

That hooks are executed multiple times can have multiple reasons.

• Defined on a Base- Class (so the hook is on every child class and gets registered)
• Multiple declaration of Scopes (see #252 and fix #635 for that)

Can you provide us an example to reproduce the issue? That would be make it easier to analyse that for us.

[qtpvarun]

@before\after test run hooks are executed multiple times in my case not because of scope... I do not use Scope[] any where.

With plugin, I need not have to use

var testRunner = TestRunnerManager.GetTestRunner();

hence, 2nd issue is not there. 1st one still exists. 1> TestTracerDecorator is not called for each of the events 2> beforetestrun thrice and aftertestrun twice (or thrice not sure)

In other words I am not able to register TestTracerDecorator, could you check if below code is correct?

I changed the class name to CustomTracer similar to Vladimir Perevalov suggested in http://stackoverflow.com/questions/22361281/how-to-set-up-individual-tracing-logging-with-specflow

public class CustomTracerPlugin : IRuntimePlugin
    {
        public void RegisterDependencies(ObjectContainer container)
        {
            container.RegisterTypeAs<CustomTracer, ITestTracer>();
        }
        public void RegisterCustomizations(ObjectContainer container, RuntimeConfiguration runtimeConfiguration) {   }
        public void RegisterConfigurationDefaults(RuntimeConfiguration runtimeConfiguration) {  }
    }

also tried registration under RegisterCustomizations, but no luck.

I am working to get an working end to end example in fresh project, mean while could you check if any issues with above code snippet? Again Thank you very much in advance for all guidance.

[SabotageAndi]

Which SpecFlow Version and Unit Test Runner are you using? It depends on it, how to implement it.

[qtpvarun]

specflow 2.0.0, nunit 2.6.4.

I created fresh project and guess what both above issues resolved. but its not related to cache, because initially have deleted tempfiles multiple times with my project. It seems that new project made the magic.

Investigating more to reproduce the issue and find out why exactly my project has different behaviour with just below one line added while fresh project don't have this deviation.

var testRunner = TestRunnerManager.GetTestRunner();

today its already late IST, will check and get back to you max by tomorrow on this. Again thanks for the help.

[qtpvarun]

Got the Issue, its when we have binding methods in separate project than feature files and having below code.

var testRunner = TestRunnerManager.GetTestRunner();

Steps to reproduce: 1> create ClassLibrary say GitHubExampleCode.Feature 2> add a feature file in GitHubExampleCode.Feature project. 3> create another classlibrary say GitHubExampleCode and reference with first as Use-Bindings-from-External-Assemblies 4> add below code in GitHubExampleCode

using BoDi;
using System;
using System.Collections.Generic;
using System.Linq;
using System.Reflection;
using System.Text;
using System.Threading.Tasks;
using TechTalk.SpecFlow;
using TechTalk.SpecFlow.Tracing;
namespace GitHubExampleCode
{
    [Binding]
    public class Class1
    {
        private readonly IObjectContainer _objectContainer;
        public Class1(ScenarioContext scenarioContext, IObjectContainer objectContainer)
        {
            Console.WriteLine("Class1");
            objectContainer.ObjectCreated += objectContainer_ObjectCreated;
            _objectContainer = objectContainer;
        }
        //[DebuggerStepThrough]
        void objectContainer_ObjectCreated(object obj)
        {
            Console.WriteLine("Created: " + obj.GetType().ToString().Split(".".ToArray()).Last().ToUpper());
            // Console.WriteLine("objectContainer_ObjectCreated" + Thread.CurrentThread.ManagedThreadId);
        }
        [BeforeTestRun]
        public static void BeforeTestRun()
        {

            Console.WriteLine("BeforeTestRun");
            //TestSuiteLogger.BeforeTestRun();
        }
        [AfterTestRun]
        public static void AfterTestRun()
        {
            //TestSuiteLogger.AfterTestRun();
            Console.WriteLine("AfterTestRun");
        }
        //[DebuggerStepThrough]
        [BeforeStep(Order = 0)]
        public void BeforeStep()
        {
            string stepInfoStepDefinitionType = ScenarioContext.Current.StepContext.StepInfo.StepDefinitionType.ToString();
            string stepInfoText = ScenarioContext.Current.StepContext.StepInfo.Text;
            string stepInfoMultilineText = ScenarioContext.Current.StepContext.StepInfo.MultilineText;
            var tbl = ScenarioContext.Current.StepContext.StepInfo.Table;
            string stepInfoTable = tbl == null ? "" : tbl.ToString();
            //TestSuiteLogger.BeforeStep(stepInfoStepDefinitionType, stepInfoText, stepInfoMultilineText, stepInfoTable);
        }
        //[DebuggerStepThrough]
        [AfterStep(Order = 0)]
        public void AfterStep()
        {
            //TestSuiteLogger.AfterStep(ScenarioContext.Current.TestError);
        }
        [BeforeFeature]
        public static void BeforeFeature()
        {
            string featureInfoTitle = FeatureContext.Current.FeatureInfo.Title;
            string featureInfoDescription = FeatureContext.Current.FeatureInfo.Description;
            string[] featureInfoTags = FeatureContext.Current.FeatureInfo.Tags;
            //TestSuiteLogger.BeforeFeature(featureInfoTitle, featureInfoDescription, featureInfoTags);
        }
        [AfterFeature]
        public static void AfterFeature()
        {
            //TestSuiteLogger.AfterFeature();
        }
        [BeforeScenario(Order = 10)]
        public void BeforeScenario()
        {
            var testRunner = TestRunnerManager.GetTestRunner();
            //var executionEngineField = testRunner.GetType().GetField("executionEngine", BindingFlags.Instance | BindingFlags.NonPublic);
            //var executionEngine = executionEngineField.GetValue(testRunner);
            //var testTracerField = executionEngine.GetType().GetField("testTracer", BindingFlags.Instance | BindingFlags.NonPublic);
            //var testTracerValue = testTracerField.GetValue(executionEngine);
            //if (!(testTracerValue is TestTracerDecorator))
            //{
            //    testTracerField.SetValue(executionEngine, new TestTracerDecorator(testTracerValue as ITestTracer));
            //}
            string scenarioInfoTitle = ScenarioContext.Current.ScenarioInfo.Title;
            string[] scenarioInfoTags = ScenarioContext.Current.ScenarioInfo.Tags;
            string scenarioBrowser = "Chrome";
            //TestSuiteLogger.BeforeScenario(scenarioInfoTitle, scenarioBrowser, scenarioInfoTags);
        }
        [BeforeScenario(Order = 20)]
        public void BrowserStart()
        {
            //_objectContainer.Resolve().GetBrowser();
        }
        [AfterScenario(Order = 10)]
        public void AfterScenario()
        {
            //TestSuiteLogger.AfterScenario();
        }
        [AfterScenario(Order = 5)]
        public void BrowserEnd()
        {
            //_objectContainer.Resolve().QuitBrowser();
        }
        [Given(@"I have entered (.*) into the calculator")]
        public void GivenIHaveEnteredIntoTheCalculator(int p0)
        {
        }
        [When(@"I press add")]
        public void WhenIPressAdd()
        {
        }
        [Then(@"the result should be (.*) on the screen")]
        public void ThenTheResultShouldBeOnTheScreen(int p0)
        {
        }
    }
}

and

using System;
using System.Collections.Generic;
using System.Globalization;
using System.Linq;
using System.Reflection;
using System.Text;
using TechTalk.SpecFlow;
using TechTalk.SpecFlow.Bindings;
using TechTalk.SpecFlow.Bindings.Reflection;
using TechTalk.SpecFlow.BindingSkeletons;
using TechTalk.SpecFlow.Configuration;
using TechTalk.SpecFlow.Tracing;
//https://www.snip2code.com/Snippet/470614/SpecFlow-XTC-screenshot-workaround
//http://stackoverflow.com/questions/22361281/how-to-set-up-individual-tracing-logging-with-specflow
//https://softwarecookie.wordpress.com/2014/06/26/specflow-test-execution-report-enhancement/
//https://groups.google.com/forum/#!topic/specflow/6h06UEVGR1U
//https://gist.github.com/rasmuskl/a61c07541074440c370f
//https://github.com/techtalk/SpecFlow/blob/7ef9a5be7db162f6649a090d8389ca14c69230c7/Tests/RuntimeTests/NUnitTestExecutor.cs
//http://bsegraves.blogspot.in/2011/03/integrating-specflow-and-log4net.html
//https://gist.github.com/chrisoldwood/fce752bab1f7060dc7b2
//https://github.com/techtalk/SpecFlow/wiki/Reporting
//file:///C:/Users/al1275/Downloads/SpecFlow%20Guide.pdf
//https://github.com/techtalk/SpecFlow/wiki/Available-Containers-&-Registrations
namespace GitHubExampleCode
{
    public class TestTracerDecorator : ITestTracer
    {
        private readonly ITestTracer _testTracer;
        private readonly ITraceListener traceListener;
        private readonly IStepFormatter stepFormatter;
        private readonly IStepDefinitionSkeletonProvider stepDefinitionSkeletonProvider;
        private readonly RuntimeConfiguration runtimeConfiguration;
        private StepInstance _currentStepInstance;
        public TestTracerDecorator(ITestTracer testTracer)
        {
            _testTracer = testTracer;
            var traceListenerField = _testTracer.GetType().GetField("traceListener", BindingFlags.Instance | BindingFlags.NonPublic);
            traceListener = (ITraceListener)traceListenerField.GetValue(_testTracer);
            var stepFormatterField = _testTracer.GetType().GetField("stepFormatter", BindingFlags.Instance | BindingFlags.NonPublic);
            stepFormatter = (IStepFormatter)stepFormatterField.GetValue(_testTracer);
            var stepDefinitionSkeletonProviderField = _testTracer.GetType().GetField("stepDefinitionSkeletonProvider", BindingFlags.Instance | BindingFlags.NonPublic);
            stepDefinitionSkeletonProvider = (IStepDefinitionSkeletonProvider)stepDefinitionSkeletonProviderField.GetValue(_testTracer);
            var runtimeConfigurationField = _testTracer.GetType().GetField("runtimeConfiguration", BindingFlags.Instance | BindingFlags.NonPublic);
            runtimeConfiguration = (RuntimeConfiguration)runtimeConfigurationField.GetValue(_testTracer);
            traceListener.WriteToolOutput("TestTracer:Constructor");
        }
        public void TraceStep(StepInstance stepInstance, bool showAdditionalArguments)
        {
            _currentStepInstance = stepInstance;
            _testTracer.TraceStep(stepInstance, showAdditionalArguments);
            traceListener.WriteToolOutput("TestTracer:TraceStep");
            string stepInfoStepDefinitionType = ScenarioContext.Current.StepContext.StepInfo.StepDefinitionType.ToString();
            string stepInfoText = ScenarioContext.Current.StepContext.StepInfo.Text;
            string stepInfoMultilineText = ScenarioContext.Current.StepContext.StepInfo.MultilineText;
            var tbl = ScenarioContext.Current.StepContext.StepInfo.Table;
            string stepInfoTable = tbl == null ? "" : tbl.ToString();
            //TestSuiteLogger.BeforeStep(stepInfoStepDefinitionType, stepInfoText, stepInfoMultilineText, stepInfoTable);
        }
        public void TraceWarning(string text)
        {
            _testTracer.TraceWarning(text);
            traceListener.WriteToolOutput("TestTracer:TraceWarning");
        }
        public void TraceStepDone(BindingMatch match, object[] arguments, TimeSpan duration)
        {
            //if (_currentStepInstance != null && _app != null)
            //{
            //    _app.Screenshot(string.Format("{0} {1}", _currentStepInstance.Keyword, _currentStepInstance.Text));
            //}
            _testTracer.TraceStepDone(match, arguments, duration);
            traceListener.WriteToolOutput("TestTracer:TraceStepDone");
            //TestSuiteLogger.AfterStep(ScenarioContext.Current.TestError);
        }
        public void TraceStepSkipped()
        {
            _testTracer.TraceStepSkipped();
            traceListener.WriteToolOutput("TestTracer:Constructor");
        }
        public void TraceStepPending(BindingMatch match, object[] arguments)
        {
            _testTracer.TraceStepPending(match, arguments);
            traceListener.WriteToolOutput("TestTracer:TraceStepSkipped");
        }
        public void TraceBindingError(BindingException ex)
        {
            _testTracer.TraceBindingError(ex);
            traceListener.WriteToolOutput("TestTracer:TraceBindingError");
        }
        public void TraceError(Exception ex)
        {
            _testTracer.TraceError(ex);
            traceListener.WriteToolOutput("TestTracer:TraceError");
        }
        public void TraceNoMatchingStepDefinition(StepInstance stepInstance, ProgrammingLanguage targetLanguage,
            CultureInfo bindingCulture, List matchesWithoutScopeCheck)
        {
            _testTracer.TraceNoMatchingStepDefinition(stepInstance, targetLanguage, bindingCulture, matchesWithoutScopeCheck);
            traceListener.WriteToolOutput("TestTracer:TraceNoMatchingStepDefinition");
        }
        public void TraceDuration(TimeSpan elapsed, IBindingMethod method, object[] arguments)
        {
            _testTracer.TraceDuration(elapsed, method, arguments);
            traceListener.WriteToolOutput("TestTracer:TraceDuration");
        }
        public void TraceDuration(TimeSpan elapsed, string text)
        {
            _testTracer.TraceDuration(elapsed, text);
            traceListener.WriteToolOutput("TestTracer:TraceDuration");
        }
    }
}

5> Then execute the test

AddTwoNumbers

Output:

------ Run test started ------
NUnit VS Adapter 2.0.0.0 executing tests is started
Loading tests from E:\Tele Tracking\Automation\Latest\23_May_2016_AfterMerging_Sprint17\GitHubExample.Tests\bin\Debug\GitHubExample.Tests.dll
Run started: E:\Tele Tracking\Automation\Latest\23_May_2016_AfterMerging_Sprint17\GitHubExample.Tests\bin\Debug\GitHubExample.Tests.dll
BeforeTestRun
Class1
Created: CLASS1
BeforeTestRun
BeforeTestRun
Given I have entered 50 into the calculator
-> done: Class1.GivenIHaveEnteredIntoTheCalculator(50) (0.0s)
And I have entered 70 into the calculator
-> done: Class1.GivenIHaveEnteredIntoTheCalculator(70) (0.0s)
When I press add
-> done: Class1.WhenIPressAdd() (0.0s)
Then the result should be 120 on the screen
-> done: Class1.ThenTheResultShouldBeOnTheScreen(120) (0.0s)
NUnit VS Adapter 2.0.0.0 executing tests is finished
========== Run test finished: 1 run (0:00:24.3774375) ==========

Observation:

We can see console out of BeforeTestRun three times, AfterTestRun is called twice (or thrice not sure while debug) but its not console out though.

[qtpvarun]

If I use plugin, behaviour is same as my project as I need not have to use

var testRunner = TestRunnerManager.GetTestRunner();

hence, 2nd issue is not there. 1st one still exists.

1. TestTracerDecorator is not called for each of the events
2. beforetestrun thrice and aftertestrun twice (or thrice not sure, console out for aftertestrun is not done, have to debug)

In other words to summarise

for projects having feature files and binding methods in same assemblies.

1. with plugin each before\after test methods called twice, test tracer not logging for steps.
2. with reflection each before\after test methods called twice, test tracer logging for steps and is as expected.

for projects having feature files and binding methods in separate assemblies.

1. with plugin before\after test methods called once and is as expected but test tracer not logging for steps.
2. with reflection before\after test methods called thrice, test tracer not logging for steps.

Our solution includes multiple teams working and need binding methods in different class from that of feature files and using reflection is much easier to convince the architect as I need not have to create a separate project for plugins.

Any guidelines to proceed from here would be of great help.

Does migrating to specflow 2.1.0 help? or to do with NUnit? Also am I doing right way or any easy way out there...

[qtpvarun]

My apologize, I am new to github, I closed by mistake... hence re-opening...

[qtpvarun]

610 and #565 are related to this I think...

[qtpvarun]

InitializeBindingRegistry is being called during TestRunnerManager.GetTestRunner() as feature file and binding methods are in different project this causes registration of before\after test one more time and now we have two registration of the these hooks. and InitializeBindingRegistry also calls the all beforetest hooks hence it is called second and third time. Now test tracer decorator is assigned to a different instance of testRunner or executionEngine.

[SabotageAndi]

I think you are on the right way. As you have now a sample to reproduce, could you zip the whole project and upload it somewhere? It makes it easier for me to look at it and find the problem.

[qtpvarun]

Good news, got an work around... changed

var testRunner = TestRunnerManager.GetTestRunner();

to

var testRunner = TestRunnerManager.GetTestRunner(Assembly.GetCallingAssembly(), Thread.CurrentThread.ManagedThreadId);

but no luck...

then changed to

TestRunnerManager testRunnerManager = (TestRunnerManager) _objectContainer.Resolve<ITestRunnerManager&rt();
var testRunner = testRunnerManager.GetTestRunner(Thread.CurrentThread.ManagedThreadId);

brute force and some intuition... and it seems to be working... will test correctly and update you soon on this....

So the issue is in

var testRunner = TestRunnerManager.GetTestRunner();

might need some re-factoring there...

I will confirm in few minutes and I think we can close this issue

will take help from some one and upload in git hub possibly today end of my day or tomorrow... I can email you if you can provide me your email id.

[SabotageAndi]

Good to know that it works now, but as the TestRunnerManager and TestRunner are important for the execution of the tests, it depends what you are doing with it and how "dangerous" it is.

Perhaps there is a better solution for your problem.

You can send it to me to andreas.willich@techtalk.at

[SabotageAndi]

@qtpvarun You did not send me your solution to look at it. Is everything working?

[zedconte]

@qtpvarun could you upload your final plugin code to a repo? I am having issues with the TestTracerDecorator class Implementing ITestTracer and at the same time defining a private readonly field _testTracer. This is causing a Circular dependency in the class. Thank you in advance :)