Race condition with entire log line not included in TC output message

[queen-of-code]

I'm seeing an occasional race condition in some of my xunit tests that have longer test names, which results in me seeing a different number of unit test results with every build run. It looks like occasionally the logger isn't waiting for the entirety of the message line to be flushed out, and so the message that is dumped out to TeamCity is incomplete and badly formatted. I'm not sure if this is a bug in this repo or in the underlying Microsoft.TestPlatform.Common package, but I'm opening here first for you to triage.

The same tests don't fail every single run, but it is generally the same few sets of tests that have their log lines split up.

Some samples output from our TeamCity build logs. You can see the missing piece of the message appears immediately following the TC error.

[17:36:33] :     [Step 5/7] ##teamcity[testFinished name='Lambda.SubjectRequestFederatorLambda.Test.AwsUtilsTest.CreateAwsS3Client_IAM_FailIfSomeSettingsAreMissing(s3RegionEndpoint: "S3RegionEndpoint-value", s3IamAuthentication: " ")' duration='0' flowI
[17:36:37]W:     [Step 5/7] The service message is invalid because it does not end with ] character: ##teamcity[testFinished name='Lambda.SubjectRequestFederatorLambda.Test.AwsUtilsTest.CreateAwsS3Client_IAM_FailIfSomeSettingsAreMissing(s3RegionEndpoint: "S3RegionEndpoint-value", s3IamAuthentication: " ")' duration='0' flowI
[17:36:33] :     [Step 5/7] d='ba34808fcce8404c8469f656f144c5e4']

and

[17:36:33] :     [Step 5/7] ##teamcity[testStarted name='ExtractAttributionEventInfosTests(isAppEvent: True, useEventTypeAttribution: False, useRequiredAttributionEventName: True, includeActionAttributeKey: True, includeActionDeleteValue: True, isPartnerFeed: W|VerifyRequest|ModuleClassName, ModuleAudienceClassName, and ModuleImporterClassName are empty. SettingType='0' 
[17:36:37]W:     [Step 5/7] The service message is invalid because it does not end with ] character: ##teamcity[testStarted name='ExtractAttributionEventInfosTests(isAppEvent: True, useEventTypeAttribution: False, useRequiredAttributionEventName: True, includeActionAttributeKey: True, includeActionDeleteValue: True, isPartnerFeed: W|VerifyRequest|ModuleClassName, ModuleAudienceClassName, and ModuleImporterClassName are empty. SettingType='0' 
[17:36:33] :     [Step 5/7] 
[17:36:33] :     [Step 5/7] True, includePublisher: True, includeCampaign: True, expectDelete: False, expectUpsert: False)' flowId='be9318f5bde246ae889609f0ca3ea1b9']

We are using:

    <PackageReference Include="Microsoft.NET.Test.Sdk" Version="16.3.0" />
    <PackageReference Include="Microsoft.TestPlatform.ObjectModel" Version="16.3.0" />
    <PackageReference Include="xunit" Version="2.4.1" />
    <PackageReference Include="TeamCity.VSTest.TestAdapter" Version="1.0.*" />

and are running on dotnet core 3 SDK on Linux build agents.

[NikolayPianikov]

@queen-of-code Looks like the issue in xunit. xunit for .net core (not for full .net) publishes service messages by itself and the TeamCity adapter suppresses his own messages to avoid duplication. Can you share some test project to reproduce? queen-of-code - cool nickname :)

[queen-of-code]

Our test project is massive and not something I can share. I suspect any test project that outputs a bunch of sufficiently long lines will repro it - it's got something like a 5% repro rate on our extremely long lines.

[NikolayPianikov]

@queen-of-code Uh-huh I was able to reproduce and I am going to find what is going wrong.

[queen-of-code]

This is great news, thanks for investigating!

On Dec 16, 2019, at 05:23, Nikolay Pianikov notifications@github.com wrote:

 @queen-of-code Uh-huh I was able to reproduce and I am going to find what is going wrong.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

[NikolayPianikov]

@queen-of-code As I mentioned above xunit (for dotnet core test projects) publishes TeamCity service messages by itself. And there is no simple way to use the TeamCity integration without tests duplication. Try turning off xunit-TeamCity integration by passing a settings file to to your test commands:

For instance the test command in the dotnet CLI runner is dotnet test The additional command line arguments are --settings xunitSettings.xml And you should add the file xunitSettings.xml into your repository:

<?xml version="1.0" encoding="utf-8"?>
<RunSettings>
  <RunConfiguration>
    <NoAutoReporters>true</NoAutoReporters>
  </RunConfiguration>
</RunSettings>

For this case TeamCity understands that xunit has no integration and publishes service messages using TeamCity.VSTest.TestAdapter. And I hope it will help you.

[queen-of-code]

Sure, this is pretty easy for me to test. I’ll give it a shot.

On Dec 23, 2019, at 07:29, Nikolay Pianikov notifications@github.com wrote:

 @queen-of-code As I mentioned above xunit (for dotnet core test projects) publishes TeamCity service messages by itself. And there is no simple way to use the TeamCity integration without test duplication. Try turning off xunit-TeamCity integration by passing a settings file to to your test commands:

For instance the test command in the dotnet CLI runner is dotnet test The additional command line arguments are --settings xunitSettings.xml And you should add the file xunitSettings.xml into your repository:

<?xml version="1.0" encoding="utf-8"?>

true

For this case TeamCity understands that xunit has no integration and publishes service messages using TeamCity.VSTest.TestAdapter. And I hope it will help you.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

[queen-of-code]

I turned it off exactly as you described, but now I'm seeing less than half of my expected test results return - it seems to happen despite definitely having the TeamCity.VSTest.TestAdapter package on latest version in my test csproj. For example, I'm getting something like 6000 total test results reported, but I know for a fact that I have a csproj using that package that reports 8000 test results all on its own which I can see succeeding in the build log before the test run completes.

Any ideas here?

[NikolayPianikov]

Which command are you using to run tests? Have you any other tests frameworks together with xunit? Is it true that all your tests projects are the dotnet core tests projects? Have you any ideas which tests are missing, maybe there is some sort of pattern?

[queen-of-code]

We run all tests using the following:

dotnet build tempest.sln dotnet test temptest.sln --no-build --no-restore --settings xunit.runsettings

The xunit.runsettings file has exactly what you pasted in above, and nothing else. We only have dotnet core tests that run on linux and use xunit.

It actually looks like I'm not missing individual test projects so much as getting wildly variable numbers of tests reporting in a suite. TeamCity seems to be aggregating test DLLs together in a weird way too - it never did that until I started using the runsettings. There doesn't seem to be any rhyme or reason, except for those tests dlls are probably executing in parallel at the same time. Forwarding.Test (Forwarding.Test.dll: Sdk.Test.dll: DataProcessing.Test.dll) 39s,291ms 236 Forwarding.Test (Api.Test.dll: Forwarding.Test.dll) 2m:48s,648ms 2997 (*1*)

Do you think it's an issue with the TeamCity reporter plugin not understanding what's happening when tests are executed in parallel? That's hit us before in different contexts.

[mfhaberlach]

Is there any update on this topic?

We just migrated to .NET Core Test Projects and facing the same race-condition issues with TeamCity and NUnit We also have a massive solution with some very long test names

MediFox.Therapie.PraxisPad.Medienverwaltung.Tests.Data.Wenn_Medien_fuer_die_Queue_gelesen_werden.Dann_werden_Medien_im_Status_WaitingForUpload_mit_weniger_als_3_Uploadversuchen_zurückgegeben
15:42:33             ##teamcity[testFinished name='MediFox.Therapie.PraxisPad.Medienverwaltung.Tests.Data.Wenn_Medien_fuer_die_Queue_gelesen_werden.Dann_werden_Medien_im_Status_WaitingForUpload_mit_weniger_als_3_Uploadversuchen_zur|0x00fcckgegeben' duration='127' timestamp='20
15:43:02             The service message is invalid because it does not end with ] character: ##teamcity[testFinished name='MediFox.Therapie.PraxisPad.Medienverwaltung.Tests.Data.Wenn_Medien_fuer_die_Queue_gelesen_werden.Dann_werden_Medien_im_Status_WaitingForUpload_mit_weniger_als_3_Uploadversuchen_zur|0x00fcckgegeben' duration='127' timestamp='20
15:42:33             21-12-08T14:42:33.452+0000' flowId='3654214416281097']

The command we using to run the tests via TeamCity:

msbuild /p:Configuration="Tests" /p:Platform="Any CPU" /target:Build "$SLN_PATH"
dotnet test "$SLN_PATH" -c "Tests" --no-restore --no-build

Maybe this is important too, every project has the target framework .netcoreapp3.1 (atm we can't update to .net5 but we will shortly) and every project uses this Packages

    <PackageReference Include="Microsoft.NET.Test.Sdk" Version="17.0.0" />
    <PackageReference Include="nunit" Version="3.13.2" />
    <PackageReference Include="NUnit3TestAdapter" Version="4.1.0" />
    <PackageReference Include="TeamCity.VSTest.TestAdapter" Version="1.0.29" />

In Addition we only use MacOS Build Agents Is there any fix or workaround?

[NikolayPianikov]

Unfortunately, this issue is caused by the VSTest engine. Sometimes it mixes stdOut lines from different sources. We are working on the fix for it which restores broken lines, it will be available in TeamCity 2022.1

[NikolayPianikov]

To work around this issue, use the this version .NET plugin for TeamCity 2021.2.1. This plugin supports "reliable" mode for TeamCity service messages. TeamCity 2022 will include this fix.

[asgerhallas]

Hi,

I'm seeing this still on TeamCity Professional 2023.05 (build 129203). Xunit 2.7.0. TeamCity.VSTest.TestAdapter 1.0.39.

It seems to be log messages to console from the code under test, that interferes with the service messages. Like

[13:00:55] :         [Tests (Uncategorized)] ##teamcity[testStarted name='Tests: SlackMessageSenderTests.WithEmptyMessage(message: "")' captureStandardOutput='false' timestamp='2024-02-20T12:00:55.447+0000' suiteName='Tests' testSource='C:\teamcityagent\work\3c5b238053325116\Tests.dll' displayName='SlackMessageSenderTests.WithEmptyMessage([13:00:55 INF]

Slightly edited for private info :)

[boris-yakhno]

Hi @asgerhallas, Unfortunately, the fix previously mentioned in this thread was not reliable. To completely mitigate the issue with interleaving output in stdout, we have switched to delivering test reports through files. This new fix is supported since TeamCity 2023.11, so upgrading TeamCity should help. Upgrading only the TeamCity.VSTest.TestAdapter would not be enough.