The active test run was aborted: Reason: After parsing a value an unexpected character

[AlexEyler]

Description

We're occasionally getting this error when running VSTest with:

• Microsoft.NET.Sdk 15.7.0
• dotnet 3.1.404
• .NET 4.7.2
• xunit vs runner 2.4.0-beta.1.build3945
• xunit 2.3.1
• vstest.console 16.7.0-release-20200703-01

I thought it might fixed via #1457 but our Microsoft.NET.Sdk version is higher than the fixed build (15.6.1).

I have logs around a recent failure we got -- happy to share the whole thing if needed. Here's what I've found though:

test.log.txt:

1988, 12, 2021/04/28, 15:38:39.749, 11910687013829, vstest.console.dll, TestRequestSender: GetAbortErrorMessage: Exception: Newtonsoft.Json.JsonReaderException: After parsing a value an unexpected character was encountered: �. Path 'Payload.NewTestResults[0].Properties[5].Key', line 1, position 16381.
at Newtonsoft.Json.JsonTextReader.ParsePostValue(Boolean ignoreComments)
at Newtonsoft.Json.JsonTextReader.Read()
at Newtonsoft.Json.JsonWriter.WriteToken(JsonReader reader, Boolean writeChildren, Boolean writeDateConstructorAsDate, Boolean writeComments)
at Newtonsoft.Json.JsonWriter.WriteToken(JsonReader reader, Boolean writeChildren)
at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.CreateJToken(JsonReader reader, JsonContract contract)
at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.SetPropertyValue(JsonProperty property, JsonConverter propertyConverter, JsonContainerContract containerContract, JsonProperty containerProperty, JsonReader reader, Object target)
at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.PopulateObject(Object newObject, JsonReader reader, JsonObjectContract contract, JsonProperty member, String id)
at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.CreateObject(JsonReader reader, Type objectType, JsonContract contract, JsonProperty member, JsonContainerContract containerContract, JsonProperty containerMember, Object existingValue)
at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.Deserialize(JsonReader reader, Type objectType, Boolean checkAdditionalContent)
at Newtonsoft.Json.JsonSerializer.DeserializeInternal(JsonReader reader, Type objectType)
at Newtonsoft.Json.JsonSerializer.Deserialize[T](JsonReader reader)
at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.JsonDataSerializer.Deserialize[T](JsonSerializer serializer, String data)
at Microsoft.VisualStudio.TestPlatform.CrossPlatEngine.Client.ProxyExecutionManager.HandleRawMessage(String rawMessage)
at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TestRequestSender.OnExecutionMessageReceived(Object sender, MessageReceivedEventArgs messageReceived, ITestRunEventsHandler testRunEventsHandler)

The message that failed has a weird character in the json:

"Key": {
              "Id": "TestResult.Duration",
              "Label": "Duration",
              "Category": "",
              "Description": "",
              "Attributes": 0,
              "ValueType": "System.TimeSpan"
            }���{

It also cuts off abruptly here:

{
                    "TestCase": {
                      "Properties": [
                        {
                          "Key": {
                            "Id": "TestCase.FullyQualifiedName",
                            "Label": "FullyQualifiedName","Category

test.log.host.{date}.txt shows this exception for the same JSON payload:

TpTrace Error: 0 : 6900, 29, 2021/04/28, 15:38:38.190, 11910671545435, testhost.exe, LengthPrefixCommunicationChannel.Send: Error sending data: System.IO.IOException: Unable to write data to the transport connection: An operation was attempted on something that is not a socket. ---> System.Net.Sockets.SocketException: An operation was attempted on something that is not a socket
at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
--- End of inner exception stack trace ---
at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
at System.IO.BufferedStream.Write(Byte[] array, Int32 offset, Int32 count)
at System.IO.BinaryWriter.Write(String value)
at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.LengthPrefixCommunicationChannel.Send(String data).
TpTrace Error: 0 : 6900, 29, 2021/04/28, 15:38:38.190, 11910671563968, testhost.exe, TestRunCache: OnCacheTimeHit: Exception occurred while checking for cache hit. Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.Interfaces.CommunicationException: Unable to send data over channel. ---> System.IO.IOException: Unable to write data to the transport connection: An operation was attempted on something that is not a socket. ---> System.Net.Sockets.SocketException: An operation was attempted on something that is not a socket
at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
--- End of inner exception stack trace ---
at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
at System.IO.BufferedStream.Write(Byte[] array, Int32 offset, Int32 count)
at System.IO.BinaryWriter.Write(String value)
at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.LengthPrefixCommunicationChannel.Send(String data)
--- End of inner exception stack trace ---
at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.LengthPrefixCommunicationChannel.Send(String data)
at Microsoft.VisualStudio.TestPlatform.CrossPlatEngine.Execution.BaseRunTests.OnCacheHit(TestRunStatistics testRunStats, ICollection1 results, ICollection1 inProgressTestCases)
at Microsoft.VisualStudio.TestPlatform.CrossPlatEngine.Execution.TestRunCache.SendResults()
at Microsoft.VisualStudio.TestPlatform.CrossPlatEngine.Execution.TestRunCache.CheckForCacheHitOnTimer()
at Microsoft.VisualStudio.TestPlatform.CrossPlatEngine.Execution.TestRunCache.OnCacheTimeHit(Object state)

Steps to reproduce

We can't get clean repro steps -- I've tried for a while. Here's the current setup though. I will mention that the failures are always around a certain set of tests that we have the write a lot of information to the console, esp. with exception stack traces.

• Microsoft.NET.Sdk 15.7.0
• dotnet 3.1.404
• .NET 4.7.2
• xunit vs runner 2.4.0-beta.1.build3945
• xunit 2.3.1
• vstest.console 16.7.0-release-20200703-01

Expected behavior

Test run completes successfully

Actual behavior

We see this error message in our build pipeline:

Test run for D:\build-vm010_work\1\s{masked-assembly-path}.dll(.NETFramework,Version=v4.7.2)
Microsoft (R) Test Execution Command Line Tool Version 16.7.0-release-20200703-01
Copyright (c) Microsoft Corporation. All rights reserved.

Starting test execution, please wait...
Logging Vstest Diagnostics in file: D:\build-vm010_work\1\a\test.log.txt

A total of 1 test files matched the specified pattern.
The active test run was aborted. Reason: After parsing a value an unexpected character was encountered: �. Path 'Payload.NewTestResults[0].Properties[5].Key', line 1, position 16381.
Microsoft (R) Coverage Collection Tool Version 15.0.30319.0

Copyright (c) Microsoft Corporation. All rights reserved.

Results File: D:\build-vm010_work_temp\build-vm010$_build-vm010_2021-04-28_15_38_04.trx

Attachments:
D:\build-vm010_work_temp\c1349d9f-08e7-42fa-926a-748874594be7\build-vm010$_build-vm010_2021-04-28.15_37_46.coverage
Test Run Aborted.
Total tests: Unknown
Passed: 190
Total time: 53.7926 Seconds
D:\build-vm010_work_tool\dotnet\sdk\3.1.404\Microsoft.TestPlatform.targets(32,5): error MSB4181: The "Microsoft.TestPlatform.Build.Tasks.VSTestTask" task returned false but did not log an error. [D:\build-vm010_work\1\s{masked-project-path}]

Diagnostic logs

Happy to share these with a Microsoft FTE internally but there are too many assembly paths to mask.

Environment

• Microsoft.NET.Sdk 15.7.0
• dotnet 3.1.404
• .NET 4.7.2
• xunit vs runner 2.4.0-beta.1.build3945
• xunit 2.3.1
• vstest.console 16.7.0-release-20200703-01

We run the tests via msbuild:
D:\build-vm010\_work\_tool\dotnet\sdk\3.1.404\MSBuild.dll -nologo -distributedlogger:Microsoft.DotNet.Tools.MSBuild.MSBuildLogger,D:\build-vm010\_work\_tool\dotnet\sdk\3.1.404\dotnet.dll*Microsoft.DotNet.Tools.MSBuild.MSBuildForwardingLogger,D:\build-vm010\_work\_tool\dotnet\sdk\3.1.404\dotnet.dll -maxcpucount /m:4 -nodereuse:false -property:VSTestLogger=trx -property:VSTestResultsDirectory=D:\build-vm010\_work\_temp -property:VSTestNoBuild=true -property:VSTestSetting=D:\build-vm010\_work\1\s\{masked-runsettings-file}.runsettings -property:VSTestTestCaseFilter=TestCategory!=Synthetic -property:Configuration=release /p:VSTestDiag=D:\build-vm010\_work\1\a\test.log.txt -target:VSTest -verbosity:m -verbosity:quiet /bl:D:\build-vm010\_work\1\a\test.binlog D:\build-vm010\_work\1\s\{masked-project-file}.proj

[AlexEyler]

Any thoughts on this one? Just need some guidance on where to look for a solution. Happy to accept a workaround if one exists.

[nohwnd]

Is there a reason why you can't use newer Microsoft.NET.Test.Sdk?

[Evangelink]

Ping @AlexEyler

[Robulane]

Replying for Alex: we are still having this issue in 17.1.0

[nohwnd]

There is no clear repro to this problem, if you have one please share it so I can investigate this.