TeamCity logger uses wrong flowid

[matkoch]

Several people reported in my project that their "test collection" messages are shown outside the intended block. I can confirm but it never got too important to me. However, with a large amount of tests, I guess it can be bothering to scroll between build summary and individual targets:

After talking with @NikolayPianikov it appears that the flowId in TeamCityReporterMessageHandler is the reason. To my knowledge it is random. A better way would be to set it from the environment variable TEAMCITY_PROCESS_FLOW_ID. Nikolay may correct me on this.

[dennisdoomen]

This is a very common complaint I'm hearing in all the teams I work with.

[willsmith9182]

Me Also, one repo has 60+ test projects so it's pretty chatty 😿

[NikolayPianikov]

TeamCity can potentially suppress TeamCity messages from XUnit by excluding the TEAMCITY_PROJECT_NAME environment variable from spawned processes. I am thinking of doing this for the .NET runner.

[matkoch]

@NikolayPianikov tbh, I wouldn't because there's a risk it would break tests.

[bradwilson]

I have a potential fix that does the following:

• Emits flowStarted and flowFinished events for the assembly with the assembly's flowId
• Emits testSuiteStarted and testSuiteFinished for the assembly with the assembly's flowId
• Emits flowStarted and flowFinished events for test collections with the collection's flowId (and the assembly's flowId as its parent)
• Ensure that everything that has access to flowId puts it into the message (only fatal errors, which can occur outside the context of a running test assembly, fall into the "no flowId" bucket).

Here are some results from me running a single test class:

##teamcity[flowStarted timestamp='2023-05-04T05:19:45.211Z' flowId='a9a829c1e48913d5b81435c80ce97b5634bb5df1be3bd7bccb66b85cdaf33af3']
##teamcity[testSuiteStarted timestamp='2023-05-04T05:19:45.212Z' flowId='a9a829c1e48913d5b81435c80ce97b5634bb5df1be3bd7bccb66b85cdaf33af3' name='C:\Dev\xunit\xunit\src\xunit.v3.assert.tests\bin\Debug\net472\xunit.v3.assert.tests.exe']
##teamcity[flowStarted timestamp='2023-05-04T05:19:45.222Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' parent='a9a829c1e48913d5b81435c80ce97b5634bb5df1be3bd7bccb66b85cdaf33af3']
##teamcity[testSuiteStarted timestamp='2023-05-04T05:19:45.222Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='Test collection for BooleanAssertsTests+False (bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948)']
##teamcity[testStarted timestamp='2023-05-04T05:19:45.246Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.ThrowsExceptionWhenTrue']
##teamcity[testStdOut timestamp='2023-05-04T05:19:45.266Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.ThrowsExceptionWhenTrue' out='Hello world|r|n' tc:tags='tc:parseServiceMessagesInside']]
##teamcity[testFinished timestamp='2023-05-04T05:19:45.266Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.ThrowsExceptionWhenTrue' duration='7']
##teamcity[testStarted timestamp='2023-05-04T05:19:45.266Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.UserSuppliedMessage']
##teamcity[testFinished timestamp='2023-05-04T05:19:45.266Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.UserSuppliedMessage' duration='0']
##teamcity[testStarted timestamp='2023-05-04T05:19:45.267Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.ThrowsExceptionWhenNull']
##teamcity[testFinished timestamp='2023-05-04T05:19:45.267Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.ThrowsExceptionWhenNull' duration='0']
##teamcity[testStarted timestamp='2023-05-04T05:19:45.276Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.AssertFalse(testValue: True)']
##teamcity[testFailed timestamp='2023-05-04T05:19:45.286Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.AssertFalse(testValue: True)' details='Assert.False() Failure|r|nExpected: False|r|nActual:   True|r|n   at Xunit.Assert.False(Nullable`1 condition, String userMessage) in C:\Dev\xunit\xunit\src\xunit.v3.assert\Asserts\BooleanAsserts.cs:line 81|r|n   at Xunit.Assert.False(Nullable`1 condition) in C:\Dev\xunit\xunit\src\xunit.v3.assert\Asserts\BooleanAsserts.cs:line 45|r|n   at BooleanAssertsTests.False.AssertFalse(Nullable`1 testValue) in C:\Dev\xunit\xunit\src\xunit.v3.assert.tests\Asserts\BooleanAssertsTests.cs:line 17']
##teamcity[testFinished timestamp='2023-05-04T05:19:45.286Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.AssertFalse(testValue: True)' duration='1']
##teamcity[testStarted timestamp='2023-05-04T05:19:45.286Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.AssertFalse(testValue: False)']
##teamcity[testFinished timestamp='2023-05-04T05:19:45.286Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.AssertFalse(testValue: False)' duration='0']
##teamcity[testStarted timestamp='2023-05-04T05:19:45.287Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.AssertFalse(testValue: null)']
##teamcity[testIgnored timestamp='2023-05-04T05:19:45.287Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.AssertFalse(testValue: null)' message='This is a dynamically skipped test']
##teamcity[testFinished timestamp='2023-05-04T05:19:45.287Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='BooleanAssertsTests+False.AssertFalse(testValue: null)' duration='0']
##teamcity[testSuiteFinished timestamp='2023-05-04T05:19:45.288Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948' name='Test collection for BooleanAssertsTests+False (bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948)']
##teamcity[flowFinished timestamp='2023-05-04T05:19:45.288Z' flowId='bb3070bf6fd07612a9939bd471901d4d9d8830a4f76e5ff7044fb77fb0835948']
##teamcity[testSuiteFinished timestamp='2023-05-04T05:19:45.289Z' flowId='a9a829c1e48913d5b81435c80ce97b5634bb5df1be3bd7bccb66b85cdaf33af3' name='C:\Dev\xunit\xunit\src\xunit.v3.assert.tests\bin\Debug\net472\xunit.v3.assert.tests.exe']
##teamcity[flowFinished timestamp='2023-05-04T05:19:45.289Z' flowId='a9a829c1e48913d5b81435c80ce97b5634bb5df1be3bd7bccb66b85cdaf33af3']

(I restructured the tests slightly to ensure that we had passing, failing, and skipped tests, as well as ensuring that at least one test had output, so we could see all the output messages.)

[bradwilson]

This will be shipped in the next 2.5.0 prerelease build (whatever comes after build 11). If any TeamCity users can test this to ensure that it's working as expected that'd be wonderful. 😄