Disable trace output

[andim0n]

SpecFlow Version

3.9

Which test runner are you using?

NUnit

Test Runner Version Number

3.13.3

.NET Implementation

.NET 6.0

Project Format of the SpecFlow project

Sdk-style project format

.feature.cs files are generated using

SpecFlowSingleFileGenerator custom tool

Test Execution Method

Command line – dotnet test

SpecFlow Section in app.config or content of specflow.json

{ "trace": { "traceSuccessfulSteps": false } }

Issue Description

trace still displaying in the output terminal

Steps to Reproduce

dotnet test

Link to Repro Project

No response

[SimonSchwendele]

Any update on this ? This is cluttering our whole testreports

[clrudolphi]

I will look into this for you. You are using dotnet test, is that correct? What options are used when executing dotnet test? Are you specifying a logger or verbosity level?

Can you provide a sample of the output you are getting along with a description of what should have been omitted when setting traceSuccessfulSteps to false?

[SimonSchwendele]

I will look into this for you. You are using dotnet test, is that correct? What options are used when executing dotnet test? Are you specifying a logger or verbosity level?

Can you provide a sample of the output you are getting along with a description of what should have been omitted when setting traceSuccessfulSteps to false?

I might not be in the same situation as this author but its somewhat similiar. I still use vstestconsole but I'll gladly switch to dotnet test if this reduces the output.

I currently invoke it like this: vstest.console.exe $dllsToTest /platform:x64 /logger:console;verbosity=quiet /logger:trx;LogFileName=output.trx /Parallel

dllsToTest contains a bunch of testdllls ( not just the bdd ones )

[clrudolphi]

I have set up a project to test this behavior (using the default Calculator feature file). When I execute it using vstest.console.exe, using /logger:"console;verbosity:quiet", I get the following console output:

Microsoft (R) Test Execution Command Line Tool Version 17.7.2 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.

Passed!  - Failed:     0, Passed:     1, Skipped:     0, Total:     1, Duration: 547 ms - GH2708.dll (net6.0)

The above output is regardless of the specflow.json value of traceSuccessfulSteps. Are you seeing something different? How different? Can you share a sample?

[SimonSchwendele]

I have set up a project to test this behavior (using the default Calculator feature file). When I execute it using vstest.console.exe, using /logger:"console;verbosity:quiet", I get the following console output:

Microsoft (R) Test Execution Command Line Tool Version 17.7.2 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.

Passed!  - Failed:     0, Passed:     1, Skipped:     0, Total:     1, Duration: 547 ms - GH2708.dll (net6.0)

The above output is regardless of the specflow.json value of traceSuccessfulSteps. Are you seeing something different? How different? Can you share a sample?

This is one of my feature files:

Funktionalität: Berechnung des Termins für die Aktivität mit dem Code 910  

    Szenario: 910 Vorwärts - Anzeige des heutigen Datums
        Angenommen heute ist der 05.05.2021
        Gegeben seien folgende Aktivitaeten
        | AktivitaetsCode | Termin |
        | 900             |        |
        | 910             |        |

        Wenn ich für die Aktivität 910 vorwärts rechne
        Dann schlägt das System das Datum 05.05.2021 vor

    Szenario: 910 Rückwärts - Anzeige des Datum 25 Tage vor der Aktivität 914
        Angenommen heute ist der 01.12.2022
        Gegeben seien folgende Aktivitaeten
          | AktivitaetsCode | Termin     |
          | 900             |            |
          | 910             |            |
          | 914             | 30.12.2022 |
          | 934             | 05.08.2024 |

        Wenn ich für die Aktivität 910 rückwärts rechne
        Dann schlägt das System das Datum 05.12.2022 vor

    Szenario: Rückwärts berechnen mit fehlendem Datum erzeugt einen Fehler
        Angenommen heute ist der 01.12.2022
        Gegeben seien folgende Aktivitaeten
          | AktivitaetsCode | Termin     |
          | 900             |            |
          | 910             |            |
          | 914             |            |

        Wenn ich für die Aktivität 910 rückwärts rechne
        Dann zeigt das System die Fehlermeldung "Auf der Aktivität 914 ist kein Termin hinterlegt."

I'm using dotnet test here because its faster to type but vstestconsole yields the same results in my case

Test run for UnitTests.dll (.NETCoreApp,Version=v6.0)
Microsoft (R) Test Execution Command Line Tool Version 17.7.2 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
Angenommen heute ist der 01.12.2022
-> done: Steps.GivenHeuteIstDer(01.12.2022 00:00:00) (0.1s)
Gegeben seien folgende Aktivitaeten
  --- table step argument ---
  | AktivitaetsCode | Termin     |
  | 900             |            |
  | 910             |            |
  | 914             | 30.12.2022 |
  | 934             | 05.08.2024 |
-> done: Steps.GivenFolgendeAktivitaeten(<table>) (0.0s)
Wenn ich für die Aktivität 910 rückwärts rechne
-> done: Steps.WhenIchFurDieAktivitatDdRechne("910", "rückwärts") (0.0s)
Dann schlägt das System das Datum 05.12.2022 vor
-> done: Steps.ThenWirdMirDasDatumVorgeschlagen(5, 12, 2022) (0.0s)

Angenommen heute ist der 05.05.2021
-> done: Steps.GivenHeuteIstDer(05.05.2021 00:00:00) (0.0s)
Gegeben seien folgende Aktivitaeten
  --- table step argument ---
  | AktivitaetsCode | Termin |
  | 900             |        |
  | 910             |        |
-> done: Steps.GivenFolgendeAktivitaeten(<table>) (0.0s)
Wenn ich für die Aktivität 910 vorwärts rechne
-> done: Steps.WhenIchFurDieAktivitatDdRechne("910", "vorwärts") (0.0s)
Dann schlägt das System das Datum 05.05.2021 vor
-> done: Steps.ThenWirdMirDasDatumVorgeschlagen(5, 5, 2021) (0.0s)

As you can see it logs the whole feature file in my case. My specflow.json only contains the lang:

{
  "language": {
    "feature": "de-CH"
  }
}

Am I missing something obvious there ? These are the dependencies in my csprj:

    <ItemGroup>
        <Using Include="TechTalk.SpecFlow" />
    </ItemGroup>

    <ItemGroup>
        <PackageReference Include="FakeItEasy" Version="7.3.1" />
        <PackageReference Include="FluentAssertions" Version="6.7.0" />
        <PackageReference Include="Gherkin" Version="23.0.1" />
        <PackageReference Include="Microsoft.NET.Test.Sdk" Version="17.3.0" />
        <PackageReference Include="NUnit" Version="3.13.3" />
        <PackageReference Include="NUnit3TestAdapter" Version="4.2.1" />
        <PackageReference Include="NUnit.Analyzers" Version="3.3.0" />
        <PackageReference Include="coverlet.collector" Version="3.1.2" />
        <PackageReference Include="SpecFlow.NUnit" Version="3.9.74" />
        <PackageReference Include="SpecFlow.Plus.LivingDocPlugin" Version="3.9.57" />
        <PackageReference Include="SpecFlow.Tools.MsBuild.Generation" Version="3.9.74" />
    </ItemGroup>

[clrudolphi]

Current behavior depends upon the combination of trace settings in the specflow.json file and the verbosity setting used when invoking the test runner (dotnet test, or vstest.console). There are four settings for verbosity (quiet, minimal, normal and detailed) and four possible combinations of trace settings (traceSuccessfulSteps=true/false and traceTimings=true/false) which gives 16 possible combinations. In reality though it seems that quiet and normal give (nearly) identical results as do normal and detailed.

I am posting here four files that demonstrate the output when running various combinations of trace settings. Each file shows the output given by dotnet test under each of the 4 verbosity settings.

Take a look at these. Would any of these combinations meet your needs? If not, what would you expect instead? If you do expect something different, I'll use that as a pointer for what to look for in the code to see if there is a bug in there somewhere. specflow tracing trace FALSE timings FALSE.txt specflow tracing trace FALSE timings TRUE.txt specflow tracing trace TRUE timings FALSE.txt specflow tracing trace TRUE timings TRUE.txt

HTH

[SimonSchwendele]

Current behavior depends upon the combination of trace settings in the specflow.json file and the verbosity setting used when invoking the test runner (dotnet test, or vstest.console). There are four settings for verbosity (quiet, minimal, normal and detailed) and four possible combinations of trace settings (traceSuccessfulSteps=true/false and traceTimings=true/false) which gives 16 possible combinations. In reality though it seems that quiet and normal give (nearly) identical results as do normal and detailed.

I am posting here four files that demonstrate the output when running various combinations of trace settings. Each file shows the output given by dotnet test under each of the 4 verbosity settings.

Take a look at these. Would any of these combinations meet your needs? If not, what would you expect instead? If you do expect something different, I'll use that as a pointer for what to look for in the code to see if there is a bug in there somewhere. specflow tracing trace FALSE timings FALSE.txt specflow tracing trace FALSE timings TRUE.txt specflow tracing trace TRUE timings FALSE.txt specflow tracing trace TRUE timings TRUE.txt

HTH

actually none of those hence I put a comment up here. I rant test with different settings as well.

When you have a look at the file which has even both settings disabled:

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
NUnit Adapter 4.1.0.0: Test execution started
Running all tests in C:\Users\clrud\source\repos\SpecFlow Projects\GH2708\GH2708\bin\Debug\net6.0\GH2708.dll
   NUnit3TestExecutor discovered 1 of 1 NUnit test cases using Current Discovery mode, Non-Explicit run
Given the first number is 50
And the second number is 70
When the two numbers are added
Then the result should be 120

Here it still lists the content of the compiled feature file:

Given the first number is 50
And the second number is 70
When the two numbers are added
Then the result should be 120

My test arrangement grew that big that the testreport file now yields about 1G. When I log to a trx it is even reported twice ( once in the StdOut and again in the TestResult ).

The other traces dont matter that much to me but I really need a way to keep the feature file out of my log

[clrudolphi]

much to me but I really need a way to keep the feature file out of my log

When using a verbosity level of quiet or minimal, the scenario steps are not included in the output. Would that meet your needs?

[SimonSchwendele]

much to me but I really need a way to keep the feature file out of my log

When using a verbosity level of quiet or minimal, the scenario steps are not included in the output. Would that meet your needs?

That actually does it thanks a lot :). Actually that only works for the console logger.

The trx logger of the vstestconsole doesnt have a configurable verbosity tho :/

[delta-emil]

Interesting note: The output files from clrudolphi's comment seem to point to the feature text not being logged in the console on minimal or quiet verbosity. But when I tested, they did get logged on minimal, and I had to go down to quiet to get rid of them.

Also, like the SimonSchwendele I have an additional logger, not the trx one, but a junit xml one (https://github.com/spekt/junit.testlogger), which also doesn't seem to be affected by a verbosity parameter.

To be honest, I don't really see the use case for traceSuccessfulSteps as it works at the moment. Like the issue author, I was thinking that the point of the option was to drastically reduce the output by completely not logging succeeded step - so not just suppress the success message, but also suppress logging of the step's text from the feature file. Currently it only cuts off half the trace of the successful steps.

However, I do see why this is done in the way it is: If you have a failing step, it's nice to see something about the succeeded steps before it.

I would suggest a new setting that is not on step level, but rather on scenario level. Something like suppressSucceededScenarioLogging maybe.

That would also be a lot more useful than tweaking the overall verbosity, because you could, then leave only failed scenarios in the logs. And that is in general the useful part. The rest is just copying of you feature file into the logs, which rarely brings you any info (unless of course you're enhancing them by also doing traceTimings for example).

[SimonSchwendele]

Interesting note: The output files from clrudolphi's comment seem to point to the feature text not being logged in the console on minimal or quiet verbosity. But when I tested, they did get logged on minimal, and I had to go down to quiet to get rid of them.

Also, like the SimonSchwendele I have an additional logger, not the trx one, but a junit xml one (https://github.com/spekt/junit.testlogger), which also doesn't seem to be affected by a verbosity parameter.

To be honest, I don't really see the use case for traceSuccessfulSteps as it works at the moment. Like the issue author, I was thinking that the point of the option was to drastically reduce the output by completely not logging succeeded step - so not just suppress the success message, but also suppress logging of the step's text from the feature file. Currently it only cuts off half the trace of the successful steps.

However, I do see why this is done in the way it is: If you have a failing step, it's nice to see something about the succeeded steps before it.

I would suggest a new setting that is not on step level, but rather on scenario level. Something like suppressSucceededScenarioLogging maybe.

That would also be a lot more useful than tweaking the overall verbosity, because you could, then leave only failed scenarios in the logs. And that is in general the useful part. The rest is just copying of you feature file into the logs, which rarely brings you any info (unless of course you're enhancing them by also doing traceTimings for example).

Yeah it would be really great if we could disable the trace completely using the specflow.json file. For now I integrated xmlstarlet as a workaround that clears the stdout. That sadly kills the precious "real" logs as well but at least my report file shrunk by 400M

[delta-emil]

I created a hack that works, but it needs to plug itself in with the help of reflection on a private readonly field: https://gist.github.com/delta-emil/0307bd1749d2503ba9d4a096b7d09158

It works for me on the latest stable release at the time of writing (3.9.74), but, you know, it's relying on a very non-public interface. I think it at least illustrates what we (well, at least I) want to achieve.

It would be nice to have it as an official option, or at least have an official way to plug something custom in.

If I find the time, I might try to whip something up and do a pull request for v4.