Erroneous TeamCity service messages with multiple test assemblies and (default) parallel execution

[CharliePoole]

@einert commented on Mon Aug 15 2016

When running nunit3-console.exe for a list of several (six) test assemblies and with the --teamcity flag, like so: nunit3-console.exe --teamcity first.test.dll second.test.dll ... last.test.dll, the service messages produced are incomplete. Specifically, the output does not contain more than one testSuiteStarted message, and one testSuiteFinished message, which does not match the start one. Which suite/flow is reported seems to be arbitrary.

One consequence of this is that the report in TeamCity is different from run to run in terms of suite placement, even if nothing has changed. This can really mess with test report consistency if some assembly and/or test names are very long, considering the 255 character limit on the combined suite + assembly + test name.

The expected output is a full set of matching start/finish messages, one for each assembly, each with their own flowId.

Adding '--agents=1' yields the expected (correct) output.

Incidentally, the first attempt, using the --inprocess argument with --teamcity, did not really work out, but produced:

Test Run Summary
  Overall result: System.NullReferenceException: Object reference not set to an instance of an object.
   at NUnit.ConsoleRunner.ColorConsoleWriter.WriteLabel(String label, Object option, ColorStyle valueStyle)
   at NUnit.ConsoleRunner.ColorConsoleWriter.WriteLabelLine(String label, Object option, ColorStyle valueStyle)
   at NUnit.ConsoleRunner.ResultReporter.WriteSummaryReport()
   at NUnit.ConsoleRunner.ConsoleRunner.RunTests(TestPackage package, TestFilter filter)
   at NUnit.ConsoleRunner.Program.Main(String[] args)

---

@CharliePoole commented on Mon Aug 15 2016

Please indicate the version of the console runner you are using.

---

@einert commented on Mon Aug 15 2016

Issue observed with 3.4.1 as well as 3.5.0-dev-03126.

---

@NikolayPianikov commented on Mon Aug 15 2016

@CharliePoole I will try to reproduce it in integration tests

---

@einert commented on Mon Aug 15 2016

Note that all tests seem to be executed and listed, but the suites (assemblies) have unpredictable representation in the report. This produces structural differences in the reported test results when picked up by TeamCity.

---

@CharliePoole commented on Mon Aug 15 2016

The problem using --inprocess is due to #1742 - since domain=Multiple is the default when running more than one assembly in the same process.

---

@NikolayPianikov commented on Mon Aug 15 2016

@einert could you attach TC build log file, could you reproduce it from the command line and attach the console ouput too.

@CharliePoole I found another problem while reproducing it. I've received "Could not load file or assembly 'nunit.framework' or one of its dependencies. The system cannot find the file specified." message when I added "--domain=None" to the command line.

---

@CharliePoole commented on Mon Aug 15 2016

See issue #1741. The --domain=None option is an obscure one and should really only be used in special cases, where some code being tested can only run in a primary AppDomain. It requires all files, including NUnit's, to be accessible in the AppDomain. Is there a reason to use it here?

---

@NikolayPianikov commented on Mon Aug 15 2016

@CharliePoole I've added integration tests for all variants including --domain=None.
It works when nunit.framework.dll is located in the same directory as the nunit3-console.exe only

---

@einert commented on Mon Aug 15 2016

@NikolayPianikov I'm afraid I can't easily attach the full TC build log verbatim due to IP restrictions. However, I can show the structure here before and after restricting agents by anonymizing a little.

Original build, only running with --teamcity argument:

[14:13:02] :     [Step 3/6] NUnit Console Runner 3.4.1 
[14:13:02] :     [Step 3/6] Copyright (C) 2016 Charlie Poole
[14:13:02] :     [Step 3/6] 
[14:13:04] :     [Step 3/6] Runtime Environment
[14:13:04] :     [Step 3/6]    OS Version: Microsoft Windows NT 6.1.7601 Service Pack 1
[14:13:04] :     [Step 3/6]   CLR Version: 4.0.30319.34209
[14:13:04] :     [Step 3/6] 
[14:13:04] :     [Step 3/6] Test Files
[14:13:04] :     [Step 3/6]     A.tests.dll
[14:13:04] :     [Step 3/6]     B.Tests.dll
[14:13:04] :     [Step 3/6]     C.Tests.dll
[14:13:04] :     [Step 3/6]     D.Tests.dll
[14:13:04] :     [Step 3/6]     E.Tests.dll
[14:13:04] :     [Step 3/6]     F.Tests.dll
[14:13:04] :     [Step 3/6] 
[14:13:47] :     [Step 3/6] D.Tests.dll (running for 7m:15s)
[14:13:47] :         [D.Tests.dll] E.Tests.Some_E_Test (running for 7m:14s)
[14:13:47] :             [E.Tests.Some_E_Test] D.Tests.Some_D_Test (running for 7m:14s)
[14:13:47] :                 [D.Tests.Some_D_Test] C.Tests.Some_C_Test (2s)
[14:13:47] :                     [C.Tests.Some_C_Test] B.Tests.Some_B_Test (2s)
[14:13:47] :                         [B.Tests.Some_B_Test] A.Tests.Some_A_Test (2s)
[14:13:47] :                             [A.Tests.Some_A_Test] F.Tests.Some_F_Test

... and so it goes, back and forth, in and out ...

[14:13:57] :     [Step 3/6] Test Run Summary
[14:13:57] :     [Step 3/6]   Overall result: Passed
[14:13:57] :     [Step 3/6]   Test Count: 274, Passed: 274, Failed: 0, Inconclusive: 0, Skipped: 0

After setting --agent=1, assemblies/suites are run consecutively and identified as "started" and "finished", which manifests like this when captured by TeamCity:

[13:26:42] :     [Step 3/6] NUnit Console Runner 3.4.1 
[13:26:42] :     [Step 3/6] Copyright (C) 2016 Charlie Poole
[13:26:42] :     [Step 3/6] 
[13:26:43] :     [Step 3/6] Runtime Environment
[13:26:43] :     [Step 3/6]    OS Version: Microsoft Windows NT 6.1.7601 Service Pack 1
[13:26:43] :     [Step 3/6]   CLR Version: 4.0.30319.34209
[13:26:43] :     [Step 3/6] 
[13:26:43] :     [Step 3/6] Test Files
[13:26:43] :     [Step 3/6]     A.Tests.dll
[13:26:43] :     [Step 3/6]     B.Tests.dll
[13:26:43] :     [Step 3/6]     C.Tests.dll
[13:26:43] :     [Step 3/6]     D.Tests.dll
[13:26:43] :     [Step 3/6]     E.Tests.dll
[13:26:43] :     [Step 3/6]     F.Tests.dll
[13:26:43] :     [Step 3/6] 
[13:27:06] :     [Step 3/6] A.Tests.dll
[13:27:06] :         [A.Tests.dll] A.Tests.Some_A_Test

... more A tests ...

[13:27:07] :     [Step 3/6] B.Tests.dll (5s)
[13:27:07] :         [B.Tests.dll] B.Tests.Some_B_Test

... more B tests ...

... C - F tests ...

[13:27:23] :     [Step 3/6] 
[13:27:24] :     [Step 3/6] Test Run Summary
[13:27:24] :     [Step 3/6]   Overall result: Passed
[13:27:24] :     [Step 3/6]   Test Count: 274, Passed: 274, Failed: 0, Inconclusive: 0, Skipped: 0

---

@CharliePoole commented on Mon Aug 15 2016

@NikolayPianikov Yes. That's what I would expect.

---

@NikolayPianikov commented on Mon Aug 15 2016

@einert could you attach the output including TC service messages for the case 1.

---

@einert commented on Mon Aug 15 2016

@NikolayPianikov This is not necessarily identical to case #1, but is a fresh run with the same symptomatic behavior (no agent restriction):

Running tests without coverage
NUnit Console Runner 3.4.1 
Copyright (C) 2016 Charlie Poole

Runtime Environment
   OS Version: Microsoft Windows NT 6.1.7601 Service Pack 1
  CLR Version: 4.0.30319.42000

Test Files
    A.Tests.dll
    B.Tests.dll
    C.Tests.dll
    D.Tests.dll
    E.Tests.dll
    F.Tests.dll

##teamcity[testSuiteStarted name='D.Tests.dll' flowId='1-1013']

##teamcity[testStarted name='A.Tests.First_A_Test' captureStandardOutput='false' flowId='1-1013']
##teamcity[testStarted name='D.Tests.First_D_Test' captureStandardOutput='false' flowId='1-1013']
##teamcity[testStarted name='C.Tests.First_C_Test' captureStandardOutput='false' flowId='1-1013']
##teamcity[testStarted name='E.Tests.First_E_Test' captureStandardOutput='false' flowId='1-1013']
##teamcity[testStarted name='F.Tests.First_F_Test' captureStandardOutput='false' flowId='1-1013']
##teamcity[testFinished name='A.Tests.First_A_Test' duration='30' flowId='1-1013']
##teamcity[testStarted name='A.Tests.Second_A_Test' captureStandardOutput='false' flowId='1-1013']
##teamcity[testStarted name='B.Tests.First_B_Test' captureStandardOutput='false' flowId='1-1013']
##teamcity[testFinished name='A.Tests.Second_A_Test' duration='2' flowId='1-1013']
##teamcity[testStarted name='A.Tests.Third_A_Test' captureStandardOutput='false' flowId='1-1013']
##teamcity[testFinished name='A.Tests.Third_A_Test' duration='21' flowId='1-1013']
##teamcity[testStarted name='A.Tests.Fourth_A_Test' captureStandardOutput='false' flowId='1-1013']
##teamcity[testFinished name='A.Tests.Fourth_A_Test' duration='0' flowId='1-1013']

... more A tests ...

##teamcity[testFinished name='B.Tests.First_B_Test' duration='248' flowId='1-1013']
##teamcity[testStarted name='B.Tests.Second_B_Test' captureStandardOutput='false' flowId='1-1013']
##teamcity[testStarted name='D.Tests.Second_D_Test' captureStandardOutput='false' flowId='1-1013']
##teamcity[testFinished name='D.Tests.Second_D_Test' duration='416' flowId='1-1013']

... more D tests, then more * tests, interleaved ...

##teamcity[testSuiteFinished name='B.Tests.dll' flowId='1-1061']

Test Run Summary
  Overall result: Passed
  Test Count: 274, Passed: 274, Failed: 0, Inconclusive: 0, Skipped: 0

As you can see:

• Test results are interleaved (probably as expected)
• The only "test suite started" message is for assembly D
• All running tests from all assemblies seem to use the same flowId as the D suite (1-1013)
• The only "test suite finished" message is for assembly B, with the otherwise unused flowId 1-1061

---

@NikolayPianikov commented on Mon Aug 15 2016

@einert what version of nunit.framework.dll do you use?
It looks strange, the output should contain elements like ##teamcity[flowStarted flowId='1-1001' parent='1-1004']
Could you create a request on https://jbs.zendesk.com/ and attach a full console output from the command line? Is it possible to attach your test assemblies - as I see you've created a set of assemblies reproducing this issue.

---

@einert commented on Mon Aug 15 2016

@NikolayPianikov Nailed it! Turns out that the project in question had had a partial tool update done. All test assemblies were built against nunit.framework.dll 2.6.1. Tests were run with nunit3-console 3.4.1.

After upgrading all references, things are looking much better.

[NikolayPianikov]

Fixed