NUnit 3 Team City parallel reporting issue

[Chris Smith]

When using parallel test fixtures and the TeamCity Service Messages, by passing the --teamcity option, TeamCity incorrectly figures out the test name. Please see the attached images, it shows the nunit3 tests running with the following commands:

nunit-console.exe %TestAssemblyList% --teamcity

nunit-console.exe %TestAssemblyList% --teamcity --workers=0

I believe we can solve this by setting the flowId in the service message. https://confluence.jetbrains.com/display/TCD8/Build+Script+Interaction+with+TeamCity#BuildScriptInteractionwithTeamCity-MessageFlowId

[Charlie Poole]

The console runner, which writes the teamcity service messages,
doesn't actually know which worker executed a particular test.
However, it does have the unique id of the test. We could try it using
that, so long as TC didn't have a problem with the large number of
distinct flowIds.

> --
> You received this message because you are subscribed to the Google Groups
> "NUnit-Discuss" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to nunit-discus...@googlegroups.com.
> To post to this group, send email to nunit-...@googlegroups.com.
> Visit this group at http://groups.google.com/group/nunit-discuss.
> For more options, visit https://groups.google.com/d/optout.

[Chris Smith]

Unfortunately if we just use the testId we lose the contextual information (dll, fixtures) because they each have a unique id. 

We expect to see this

nunit.framework.tests.dll: NUnit: Framework: Assertions: EqualsFixture    DirectoryInfoEqual

But would just get this

DirectoryInfoEqual

chris

[Charlie Poole]

So I think you are saying that TeamCity expects to see a sequence like
SuiteStart-TestStart-TestFinish-TestStart-Test-Finish...SuiteFinish

It will use flowid to put messages into different buckets, but it
expects that the sequence will remain intact within each bucket.
Right?

We could create a flowid that matched the worker thread running the
tests and that would satisfy TC for the moment. However, it seems that
this would be broken as soon as we implement parallel execution of
tests _within_ a given fixture.

OTOH, if we create the problem, then the TC guys would probably be
motivated to find a way to resolve it.

Here's an idea. Could we use the unique id of the test fixture for all
the tests?

Charlie

[Chris Smith]

On Friday, April 3, 2015 at 7:20:24 PM UTC-4, charlie wrote:

So I think you are saying that TeamCity expects to see a sequence like
SuiteStart-TestStart-TestFinish-TestStart-Test-Finish...SuiteFinish

 

Yes, here is the example they have in the documentation

##teamcity[testSuiteStarted name='suiteName'] ##teamcity[testSuiteStarted name='nestedSuiteName'] ##teamcity[testStarted name='package_or_namespace.ClassName.TestName'] ##teamcity[testFailed name='package_or_namespace.ClassName.TestName' message='The number should be 20000' details='junit.framework.AssertionFailedError: expected:<20000> but was:<10000>|n|r    at junit.framework.Assert.fail(Assert.java:47)|n|r    at junit.framework.Assert.failNotEquals(Assert.java:280)|n|r...'] ##teamcity[testFinished name='package_or_namespace.ClassName.TestName'] ##teamcity[testSuiteFinished name='nestedSuiteName'] ##teamcity[testSuiteFinished name='suiteName']

 

It will use flowid to put messages into different buckets, but it
expects that the sequence will remain intact within each bucket.
Right?

Yes. 

 

We could create a flowid that matched the worker thread running the
tests and that would satisfy TC for the moment. However, it seems that
this would be broken as soon as we implement parallel execution of
tests _within_ a given fixture.

It does seem that way

 

OTOH, if we create the problem, then the TC guys would probably be
motivated to find a way to resolve it.

One way to find out.

 

Here's an idea. Could we use the unique id of the test fixture for all
the tests?

Maybe, I'm not quite sure how this would work. 

Here is some sample output with workers=0 to give you an idea of the execution of the test fixtures. This is up to the completion of the first test.

##teamcity[testSuiteStarted name='nunit.framework.tests.dll' flowId='4396']

##teamcity[testSuiteStarted name='NUnit' flowId='4397']

##teamcity[testSuiteStarted name='Common' flowId='4401']

##teamcity[testSuiteStarted name='Tests' flowId='4402']

##teamcity[testSuiteStarted name='CommandLineTests' flowId='3808']

##teamcity[testStarted name='AssemblyAloneIsValid' captureStandardOutput='true' flowId='3842']

##teamcity[testFinished name='AssemblyAloneIsValid' duration='0.163' flowId='3842']

##teamcity[testStarted name='AssemblyName' captureStandardOutput='true' flowId='3841']

##teamcity[testFinished name='AssemblyName' duration='0.001' flowId='3841']

##teamcity[testSuiteStarted name='CanRecognizeBooleanOptions' flowId='3817']

##teamcity[testStarted name='CanRecognizeBooleanOptions("TeamCity","teamcity")' captureStandardOutput='true' flowId='3810']

##teamcity[testFinished name='CanRecognizeBooleanOptions("TeamCity","teamcity")' duration='0.015' flowId='3810']

I know fixtures can be executed in parallel, but how do nested fixtures work currently? 

Chris

[Charlie Poole]

I assume this is a thought experiment, since we don't actualy put out flowId right now. It's clear that using the individual test Id won't work.

It seems as if we can't do anything to resolve this, since with parallelism any number of suites may be active at a given point in time and they aren't necessarily nested. There isn't really any flowId we can use to isolate each one either, as a further thought experiment will show...

Let's say we start out with the start message for the assembly followed by the 'NUnit' namespace. Now come three suite starts: A, B and C. Let's say that A and C are directly under NUnit, while B is nested under A, like this:

   NUnit.A.B

   NUnit.C

So, we want to give NUnit, A and B a common flowid (1001) and we want C to have a different flowID (1002). So far so good.

But wait, we also want NUnit to have flowId 1002, in addition to 1001, which isn't possible. And the assembly needs to have the same flowid as every test under it.

The only way I can see this working at all is if we simply don't send progress messages for suites. What would be the result of that in team city? Why does TC need info about suites?

Charlie

The problem is that multiple given higher level suites (above the Fixture level) may be active at any point in time.

[Chris Smith]

I'm playing around with it locally so these are real experiments as well.  

Removing the suite messages bring us back to just displaying the method name in TC without any grouping. 

If we use the test id as the flowId, and use the fullname instead of just name attribute, it looks pretty good! (see attached images) You'll notice the tests are grouped by namespace and classname. 

More info on Interpreting test names in the docs https://confluence.jetbrains.com/display/TCD8/Build+Script+Interaction+with+TeamCity#BuildScriptInteractionwithTeamCity-Interpretingtestnames

Example service message under this configuration 

##teamcity[testStarted name='NUnit.Framework.Assertions.AssertInconclusiveTests.ThrowsInconclusiveException' captureStandardOutput='true' flowId='1220']

I think we should also set captureStandardOutput to false, since multiple tests could be writing to standard out at the same time and TC won't know which one to associate it with.

Chris

[Chris Smith]

It looks like the test ids are not unique across processes, which prevents us from relying on it for the flowId. That seems separate issue that we might want to resolve also, since there are duplicate ids in the xml report.

Do you have a preference in how to solve these issues? I'm almost ready for a PR for the TC service message changes, just need to account for multiple processes now. I'll gladly fix the duplicate id issue if it make the TC issue easier to resolve.

[Charlie Poole]

That's looking pretty decent, although what I am seeing is individual tests grouped by namespace, not by classname. For example, the very first grouping is for NUnit.Framework.Assertions - a namespace - while under it the individual items are similar to EqualsFixture.DirectoryInfoEqual. There's no grouping for the test class "EqualsFixture" - is that what you want to show?

Are you aware that you also have classname and methodname available to you? Since users can change the names of tests to any arbitrary string, the FullName of the test may have no relation all to the Name.

I'm wondering if CaptureStandardOutput has any meaning at all, since NUnit already captures it in order to include the output in the test result. We may miss some output if it's created by a non-nunit thread. You may want to experiment with this.

[Charlie Poole]

Right, that's a problem we know about but which was not expected to need a solution before the gui was created. The gui, will want to select tests by id. It seems as if you have found a reason to fix it now. We tend to like smaller fixes, so perhaps you can create a new issue for this by itself.

I see two basic ways to fix this:

1. Give each process a starting number to use for its id. The ids are generated as ints but consumed as strings. The difficulty with this approach is predicting how many ids will be needed in each process.

2. Prefix each id with some key that represents the process or the test assembly. We did the latter in NUnit 2.x. I guess that's still the best because I'm pretty sure that you can get duplicate ids across domains and even within the same domain - if you run multiple assemblies in the same domain, then multiple framework drivers are created.

I'm liking #2 best (I'm thinking this out as I type) but I don't like the implementation that requires us to capture every result and change the id. It's probably best to pass a prefix all the way down through the runners to the framework. What do you think?

This will be a pretty big change in and of itself.

Please create the issue and let me know if you feel you can work on it. The main obstacle is that it requires dipping into the code in a _lot_ of places. However, I can tell you where to look.

[Chris Smith]

I've opened two issues, one for the test id uniqueness https://github.com/nunit/nunit/issues/582 and one for the parallel execution and service messages https://github.com/nunit/nunit/issues/583

That's looking pretty decent, although what I am seeing is individual tests grouped by namespace, not by classname. For example, the very first grouping is for NUnit.Framework.Assertions - a namespace - while under it the individual items are similar to EqualsFixture.DirectoryInfoEqual. There's no grouping for the test class "EqualsFixture" - is that what you want to show?

Are you looking at my screenshots or changes you made? I'm seeing the grouping for EqualsFixture under TC8 and TC9. I've attached a screenshot again.

 

Are you aware that you also have classname and methodname available to you? Since users can change the names of tests to any arbitrary string, the FullName of the test may have no relation all to the Name.

I think this is the expected behavior, if they are overriding the name wouldn't they want it to appear in TC that way? If we used classname/methodname I think I would need to modify the nunit2 driver to include those.

 

I'm wondering if CaptureStandardOutput has any meaning at all, since NUnit already captures it in order to include the output in the test result. We may miss some output if it's created by a non-nunit thread. You may want to experiment with this.

I'm looking into CaptureStandardOutput now and will open another issue for it. 

We did the latter in NUnit 2.x.

Is there somewhere I can see this implementation? That would give me an idea of how involved the changes would be.  

Chris

[Charlie Poole]

Hi Chris,

Inline...

On Wed, Apr 8, 2015 at 1:58 PM, Chris Smith <chris.s...@gmail.com> wrote:

I've opened two issues, one for the test id uniqueness https://github.com/nunit/nunit/issues/582 and one for the parallel execution and service messages https://github.com/nunit/nunit/issues/583

That's looking pretty decent, although what I am seeing is individual tests grouped by namespace, not by classname. For example, the very first grouping is for NUnit.Framework.Assertions - a namespace - while under it the individual items are similar to EqualsFixture.DirectoryInfoEqual. There's no grouping for the test class "EqualsFixture" - is that what you want to show?

Are you looking at my screenshots or changes you made? I'm seeing the grouping for EqualsFixture under TC8 and TC9. I've attached a screenshot again.

 
I was looking at your first screenshot. That's the one that looks odd.

 

Are you aware that you also have classname and methodname available to you? Since users can change the names of tests to any arbitrary string, the FullName of the test may have no relation all to the Name.

I think this is the expected behavior, if they are overriding the name wouldn't they want it to appear in TC that way? If we used classname/methodname I think I would need to modify the nunit2 driver to include those.

I'm not sure what driver you mean. It's definitely a part of NUnit 2, but not all versions. I agree that it's arguable that the user wants to see the new name, but you may not be deducing the class name correctly when the user has changed the test name. You'd need to test that.

 

I'm wondering if CaptureStandardOutput has any meaning at all, since NUnit already captures it in order to include the output in the test result. We may miss some output if it's created by a non-nunit thread. You may want to experiment with this.

I'm looking into CaptureStandardOutput now and will open another issue for it. 

OK... but no need for an issue if the setting makes no difference.

 

We did the latter in NUnit 2.x.

Is there somewhere I can see this implementation? That would give me an idea of how involved the changes would be.  

Look at TestName.cs, which contains a runner id. Each 2.x runner had an id and the test ids were unique for the runner. The UniqueName of a test includes the runner id, test id and full name.

That said, don't be inspired by this implementation. It's much too complicated!!!

Charlie

[andrius...@gmail.com]

Hi Charlie,

I saw in GitHub, that you guys have fixed this issue already and I wanted to test it on my build server in TeamCity.

I cloned NUnit git repo and built it locally using "Release" configuration and then copied files from "C:\dev\nunit\bin\Release" from my local machine to "C:\Program Files (x86)\NUnit-3.0.0-beta-2\bin" on my build server.

When I run the build in TC - I get the following error: "System.MissingMethodException: Constructor on type 'NUnit.Framework.Api.FrameworkController' not found."

And the stacktrace is referencing to files in non-existent path, e.g. "c:\dev\nunit\src\NUnitEngine\nunit.engine\Drivers\NUnit3FrameworkDriver.cs" - this path exists on my local machine, not in build server.

So my question is: how do you build NUnit, when you're making a release? Maybe you could build it for me so I could start testing if this feature is working correctly?

And another question: now my project references "NUnit 3.0.0-beta-1" nuget package. Do I have to manually reference newly built files or everything should work with current nuget package?

Thank you,

Andrew

[Charlie Poole]

Hi Andrius,

When we are making a release we build using the msbuild script NUnit.proj. Normally, it should give the same result as building the solution. The output is in bin\Release. We then create packages to install also using the build script with /t:Package /p:Configuration=Release. That's about all there is to it.

The error you are getting indicates that the engine found that some assembly in your build was suitable for the NUnit3FrameworkDriver (i.e. it uses nunit.framework with version 3.0 or greater) but that when it attempted to create the framework controller the test failed. The likely cause is that the tests you are running are actually referencing some other build of the framework. While the driver is intended to work with multiple framework versions 3.0 or greater, that really is not true in the beta phase. We have changed the API several times.

The stacktrace is merely reporting what the pdb files contain. It's simply that the source isn't available on that machine.

Most likely, your reference to the nuget package is what causes the problem. Reference the framework you just built and it may go away.

Charlie

[andrius...@gmail.com]

Hi Charlie,

I rebuilt using NUnit.proj and referenced the built framework and it worked! Thank you! :)

However, I still see some issues regarding tests results reporting.

Looks like that now passed tests count is correct, but ignored and failed tests count still shows incorrect numbers. Please take a look at stats, which I collected so far.

Andrius

...

[Charlie Poole]

Hi Andrius,

I'm afraid the stats don't help me, since I don't know what the results are expected to be. Do you really have such a large number of ignored tests?

I think the best way to help us would be if you can create a very narrow issue indicating what's wrong. Also, make sure you are using _only_ our special TC messages for counting, i.e. no built-in NUnit support, which would not work correctly with 3.0 anyway.

Charlie

[andrius...@gmail.com]

I'm running nunit-console from the command line. I don't use any TeamCity NUnit addons.

Yes, currently I ignored 46 selenium tests, which can not run in parallel.

From the stats, which I collected the first line, e.g. "Tests passed: 99, ignored: 8" is calculated by sending {build.status.text} TC service message at the end of each build and is shown as a result of the build. And all other lines are printed by nunit-console to the build log (those values shows correct results). So what I wanted to show that the values in result line and in the build log should be exactly the same. If I will be able to narrow down this issue somehow - I'll share the results.

Andrius

...

[Charlie Poole]

OK, now I understand. Can you collect the service messages created by NUnit when running your tests? If no other way, perhaps you could just run the tests form the command-line outside of TC and use the --teamcity option. I would imagine that inspecting the messages would tell us what's going on.

Charlie

[andrius...@gmail.com]

I wasn't able to collect messages from build server, but I run unit tests on my machine and inspected the output.

Result printed in console:

Test Run Summary

    Overall result: Failed

   Tests run: 670, Passed: 664, Errors: 5, Failures: 1, Inconclusive: 0

     Not run: 1, Invalid: 0, Ignored: 1, Skipped: 0

  Start time: 2015-04-28 20:58:13Z

    End time: 2015-04-28 20:59:57Z

    Duration: 103.606 seconds

Results from output file with --teamcity option enabled:

-------------------------------------------------

Count         | TC Service message

-------------------------------------------------

671 | ##teamcity[testStarted

670 | ##teamcity[testFinished

1 | ##teamcity[testIgnored

6 | ##teamcity[testFailed

-------------------------------------------------

Looks like "##teamcity[testIgnored" message should be surrounded by "##teamcity[testStarted" and "##teamcity[testFinished" service messages, but now it has only "##teamcity[testStarted" and "##teamcity[testIgnored". This might be the problem of incorrect results.

##teamcity[testStarted name='My.Project.Tests.Unit.My_Test_Name' captureStandardOutput='true' flowId='0-1473']

##teamcity[testIgnored name='My.Project.Tests.Unit.My_Test_Name' message='Investigate' flowId='0-1473']

##teamcity[testStarted name='My.Project.Tests.Unit.Another_Test_Name' captureStandardOutput='true' flowId='0-1474']

Andrius

...

[andrius...@gmail.com]

Hi Charlie,

In TeamCityEventHandler class, TestFinished method I added TC_TestFinished method call in a couple switch cases and did the same TC service messages count. Now everything looks fine, but the results in TC are still incorrect.

The results line:

Tests failed: 3 (1 new), passed: 93, ignored: 8

Output in build log:

Tests run: 99, Passed: 93, Errors: 6, Failures: 0, Inconclusive: 0

  Not run: 46, Invalid: 0, Ignored: 46, Skipped: 0

Why passed tests count are always correct and ignored/failed tests count not? Am I missing something?

Andrius

...

[Charlie Poole]

Andrius: Are you using the current source to build NUnit or are you running one of the release versions?

--

[andrius...@gmail.com]

Hi Charlie,

I'm using current source from master branch.

Andrius