stryker-mutator / stryker-net

Mutation testing for .NET core and .NET framework!
https://stryker-mutator.io
Apache License 2.0
1.75k stars 176 forks source link

dotnet8: process failed to connect to vstest.console (linux ssl issue) #2799

Closed draptik closed 6 months ago

draptik commented 7 months ago

Describe the bug Running dotnet stryker fails with error message process failed to connect to vstest.console.

Logs Logs after running the command dotnet stryker --verbosity trace --log-to-file from the same folder as the sln file.

2023-12-15T13:28:55.0486719+01:00  [INF] Logging enabled at level Trace (8a18af78)
2023-12-15T13:28:55.2189609+01:00  [DBG] Stryker started with options: StrykerOptions { MsBuildPath: null, DevMode: False, ProjectPath: "/home/patrick/projects/dotnet-stryker-demos/Demo", IsSolutionContext: True, WorkingDirectory: "/home/patrick/projects/dotnet-stryker-demos/Demo", OutputPath: "/home/patrick/projects/dotnet-stryker-demos/Demo/StrykerOutput/2023-12-15.13-28-54", ReportPath: "/home/patrick/projects/dotnet-stryker-demos/Demo/StrykerOutput/2023-12-15.13-28-54/reports", ReportFileName: "mutation-report", SolutionPath: "/home/patrick/projects/dotnet-stryker-demos/Demo/Demo.sln", TargetFramework: null, LogOptions: LogOptions { LogToFile: True, LogLevel: Verbose }, MutationLevel: Standard, Thresholds: Thresholds { High: 80, Low: 60, Break: 0 }, AdditionalTimeout: 5000, LanguageVersion: Default, Concurrency: 8, SourceProjectName: "", TestProjects: [], TestCaseFilter: "", Reporters: [Progress, Html], WithBaseline: False, BaselineProvider: Disk, AzureFileStorageUrl: "", AzureFileStorageSas: "", DashboardUrl: "https://dashboard.stryker-mutator.io", DashboardApiKey: null, Since: False, SinceTarget: "master", DiffIgnoreChanges: [], FallbackVersion: "master", ModuleName: "", ReportTypeToOpen: null, Mutate: [FilePattern { Glob: Glob { Tokens: [WildcardDirectoryToken { TrailingPathSeparator: PathSeparatorToken { Value: / }, LeadingPathSeparator: null }, WildcardToken {  }] }, IsExclude: False, TextSpans: [TextSpan { Start: 0, End: 2147483647, Length: 2147483647, IsEmpty: False }] }], IgnoredMethods: [], ExcludedMutations: [], ExcludedLinqExpressions: [], OptimizationMode: CoverageBasedTest, ProjectName: "", ProjectVersion: "", BreakOnInitialTestFailure: False } (fac41b16)
2023-12-15T13:28:55.2486262+01:00  [INF] Analysis starting. (7076a364)
2023-12-15T13:28:55.2505319+01:00  [INF] Identifying projects to mutate in "/home/patrick/projects/dotnet-stryker-demos/Demo/Demo.sln". This can take a while. (352fa797)
2023-12-15T13:28:55.2864193+01:00  [DBG] Analyzing 2 projects. (a101d45b)
2023-12-15T13:28:55.2890409+01:00  [DBG] Analyzing "DemoTests/DemoTests.csproj" (1defaf37)
2023-12-15T13:28:55.2890952+01:00  [DBG] Analyzing "Demo/Demo.csproj" (1defaf37)
2023-12-15T13:28:56.8302519+01:00  [DBG] Analysis of project "Demo/Demo.csproj" succeeded. (adaf2e80)
2023-12-15T13:28:56.8305954+01:00  [DBG] Analysis of project "DemoTests/DemoTests.csproj" succeeded. (adaf2e80)
2023-12-15T13:28:56.8318041+01:00  [INF] Found 1 source projects (c1ce5c69)
2023-12-15T13:28:56.8318528+01:00  [INF] Found 1 test projects (6f0fd09d)
2023-12-15T13:28:56.8342804+01:00  [DBG] Matched "Demo/Demo.csproj" to 1 test projects: (5ad47c23)
2023-12-15T13:28:56.8343168+01:00  [DBG] "/home/patrick/projects/dotnet-stryker-demos/Demo/DemoTests/DemoTests.csproj" (c8ca923a)
2023-12-15T13:28:57.0002879+01:00  [DBG] Skipping auto-generated code file: "/home/patrick/projects/dotnet-stryker-demos/Demo/Demo/obj/Debug/net8.0/Demo.GlobalUsings.g.cs" (1e1226c3)
2023-12-15T13:28:57.0020754+01:00  [DBG] Skipping auto-generated code file: "/home/patrick/projects/dotnet-stryker-demos/Demo/Demo/obj/Debug/net8.0/.NETCoreApp,Version=v8.0.AssemblyAttributes.cs" (1e1226c3)
2023-12-15T13:28:57.0022505+01:00  [DBG] Skipping auto-generated code file: "/home/patrick/projects/dotnet-stryker-demos/Demo/Demo/obj/Debug/net8.0/Demo.AssemblyInfo.cs" (1e1226c3)
2023-12-15T13:28:57.0023544+01:00  [INF] Found project "/home/patrick/projects/dotnet-stryker-demos/Demo/Demo/Demo.csproj" to mutate. (2d705ac3)
2023-12-15T13:28:57.0044640+01:00  [INF] Analysis complete. (f039f576)
2023-12-15T13:28:57.0310073+01:00  [INF] Building solution "Demo.sln" (abcf88bf)
2023-12-15T13:28:57.0314566+01:00  [DBG] Started initial build using "dotnet build" (a4e1a5e2)
2023-12-15T13:28:57.0314974+01:00  [DBG] Initial build using path: "/home/patrick/projects/dotnet-stryker-demos/Demo/Demo.sln" (657c8664)
2023-12-15T13:28:58.2800584+01:00  [DBG] Initial build successful (61599426)
2023-12-15T13:28:58.3223517+01:00  [DBG] VsTest zip was copied to: "/tmp/qq2p0e22.3ys/.vstest/vstest.zip" (8e340ff1)
2023-12-15T13:28:58.4273148+01:00  [DBG] VsTest zip was unzipped to: "/tmp/qq2p0e22.3ys/.vstest" (679800d3)
2023-12-15T13:28:58.4301899+01:00  [DBG] Using vstest from deployed vstest package (6132c740)
2023-12-15T13:28:58.4323802+01:00  [DBG] Using vstest.console: "LINUX" for OS "/tmp/qq2p0e22.3ys/.vstest/tools/netcoreapp3.1/vstest.console.dll" (38dfd549)
2023-12-15T13:30:28.4679229+01:00  [ERR] Stryker failed to connect to vstest.console with error: "/home/patrick/.dotnet/tools/dotnet-stryker process failed to connect to vstest.console process after 90 seconds. This may occur due to machine slowness, please set environment variable VSTEST_CONNECTION_TIMEOUT to increase timeout." (c990ccd0)
2023-12-15T13:30:28.4715877+01:00  [ERR] Stryker failed to connect to vstest.console with error: "/home/patrick/.dotnet/tools/dotnet-stryker process failed to connect to vstest.console process after 90 seconds. This may occur due to machine slowness, please set environment variable VSTEST_CONNECTION_TIMEOUT to increase timeout." (c990ccd0)
2023-12-15T13:30:28.4769163+01:00  [ERR] Stryker failed to connect to vstest.console with error: "/home/patrick/.dotnet/tools/dotnet-stryker process failed to connect to vstest.console process after 90 seconds. This may occur due to machine slowness, please set environment variable VSTEST_CONNECTION_TIMEOUT to increase timeout." (c990ccd0)
2023-12-15T13:30:28.4920279+01:00  [ERR] Stryker failed to connect to vstest.console with error: "/home/patrick/.dotnet/tools/dotnet-stryker process failed to connect to vstest.console process after 90 seconds. This may occur due to machine slowness, please set environment variable VSTEST_CONNECTION_TIMEOUT to increase timeout." (c990ccd0)
2023-12-15T13:30:28.4921503+01:00  [ERR] Stryker failed to connect to vstest.console with error: "/home/patrick/.dotnet/tools/dotnet-stryker process failed to connect to vstest.console process after 90 seconds. This may occur due to machine slowness, please set environment variable VSTEST_CONNECTION_TIMEOUT to increase timeout." (c990ccd0)
2023-12-15T13:30:28.4922346+01:00  [ERR] Stryker failed to connect to vstest.console with error: "/home/patrick/.dotnet/tools/dotnet-stryker process failed to connect to vstest.console process after 90 seconds. This may occur due to machine slowness, please set environment variable VSTEST_CONNECTION_TIMEOUT to increase timeout." (c990ccd0)
2023-12-15T13:30:28.4923188+01:00  [ERR] Stryker failed to connect to vstest.console with error: "/home/patrick/.dotnet/tools/dotnet-stryker process failed to connect to vstest.console process after 90 seconds. This may occur due to machine slowness, please set environment variable VSTEST_CONNECTION_TIMEOUT to increase timeout." (c990ccd0)
2023-12-15T13:30:28.4924299+01:00  [ERR] Stryker failed to connect to vstest.console with error: "/home/patrick/.dotnet/tools/dotnet-stryker process failed to connect to vstest.console process after 90 seconds. This may occur due to machine slowness, please set environment variable VSTEST_CONNECTION_TIMEOUT to increase timeout." (c990ccd0)
2023-12-15T13:30:28.4925139+01:00  [ERR] Stryker failed to connect to vstest.console with error: "/home/patrick/.dotnet/tools/dotnet-stryker process failed to connect to vstest.console process after 90 seconds. This may occur due to machine slowness, please set environment variable VSTEST_CONNECTION_TIMEOUT to increase timeout." (c990ccd0)
2023-12-15T13:30:28.4932375+01:00  [INF] Time Elapsed 00:01:33.3157438 (f4427d77)

Expected behavior Expecting stryker to do its magic.

Desktop (please complete the following information):

Can I provide additional information?

rouke-broersma commented 7 months ago

You should have some logs from vstest in the Stryker outputs folder

draptik commented 7 months ago

My original post contains the complete log (StrykerOutput/<timestamp>/logs/log-<timestamp>.txt). Or am I missing something obvious?

rouke-broersma commented 7 months ago

@draptik there should be additional logs in that folder for vstest. If they're not there that means vstest simply failed to start at all on your system.

draptik commented 7 months ago

@rouke-broersma Ah, thanks for the pointer. The nested logs folder contains no additional infos:

❯ pwd
/home/patrick/projects/dotnet-stryker-demos/Demo/StrykerOutput/2023-12-15.13-28-54/logs/StrykerOutput/2023-12-15.13-37-56/logs

…/StrykerOutput/2023-12-15.13-37-56/logs 
❯ le                   
.rw-r--r-- 83 patrick patrick 15 Dec 13:37  log-20231215.txt

…/StrykerOutput/2023-12-15.13-37-56/logs 
❯ cat log-20231215.txt 
2023-12-15T13:37:56.8492734+01:00  [INF] Logging enabled at level Trace (8a18af78)

Anything else I can check?

rouke-broersma commented 7 months ago

Here is some information on vstest.console debugging: https://github.com/microsoft/vstest/blob/main/docs/diagnose.md

draptik commented 7 months ago

log.host.23-12-15_16-26-15_66126_5.txt log.txt

@rouke-broersma thanks! I've attached the output of running dotnet test --diag:log.txt. Does this provide any useful infos?

rouke-broersma commented 7 months ago

We don't use the vstest.console that comes with dotnet cli, we provide our own version to ensure compatibility with Stryker. It should be unpacked in your temp folder (/tmp/qq2p0e22.3ys/.vstest/tools/netcoreapp3.1/vstest.console.dll)

draptik commented 7 months ago

Just to be on the safe side I reinstalled stryker. When trying to run the vstest.console provided by stryker I end up with a libssl error message: No usable version of libssl was found:

dotnet /tmp/2dic4trl.ah0/.vstest/tools/netcoreapp3.1/vstest.console.dll DemoTests/DemoTests.dll --diag:log.txt
Microsoft (R) Test Execution Command Line Tool Version 17.8.0 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

No usable version of libssl was found
[1]    224387 IOT instruction (core dumped)  dotnet /tmp/2dic4trl.ah0/.vstest/tools/netcoreapp3.1/vstest.console.dll

Is there anything else I can try?

rouke-broersma commented 7 months ago

Just to be on the safe side I reinstalled stryker. When trying to run the vstest.console provided by stryker I end up with a libssl error message: No usable version of libssl was found:

dotnet /tmp/2dic4trl.ah0/.vstest/tools/netcoreapp3.1/vstest.console.dll DemoTests/DemoTests.dll --diag:log.txt
Microsoft (R) Test Execution Command Line Tool Version 17.8.0 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

No usable version of libssl was found
[1]    224387 IOT instruction (core dumped)  dotnet /tmp/2dic4trl.ah0/.vstest/tools/netcoreapp3.1/vstest.console.dll

Is there anything else I can try?

I just noticed you're running on arch. Are you using dotnet straight from Microsoft or are you using it through a distro specific repo? Could be some modifications were made for it to run properly on arch which we don't have since we use the Microsoft provided generic version.

draptik commented 7 months ago

Yes, I'm using the arch package for dotnet: https://archlinux.org/packages/extra/x86_64/dotnet-sdk/

Looking inside the PKGBUILD file (https://gitlab.archlinux.org/archlinux/packaging/packages/dotnet-core/-/blob/main/PKGBUILD?ref_type=heads) I can't spot anything unusual.

draptik commented 7 months ago

Maybe netcore3 uses an outdated version of libssl?

❯ le /usr/lib/libssl*
lrwxrwxrwx 651k root root 24 Oct 16:55  /usr/lib/libssl.so -> libssl.so.3
.rwxr-xr-x 651k root root 24 Oct 16:55  /usr/lib/libssl.so.3
.rwxr-xr-x 424k root root 20 Nov 22:23  /usr/lib/libssl3.so
rouke-broersma commented 7 months ago

Maybe netcore3 uses an outdated version of libssl?

❯ le /usr/lib/libssl*
lrwxrwxrwx 651k root root 24 Oct 16:55  /usr/lib/libssl.so -> libssl.so.3
.rwxr-xr-x 651k root root 24 Oct 16:55  /usr/lib/libssl.so.3
.rwxr-xr-x 424k root root 20 Nov 22:23  /usr/lib/libssl3.so

Vstest console is a dotnet dll so I would assume libssl isn't included in it but I don't know. I don't really know enough about vstest architecture nor how Linux package management works to understand how this would work exactly.

draptik commented 7 months ago

Maybe netcore3 uses an outdated version of libssl?

❯ le /usr/lib/libssl*
lrwxrwxrwx 651k root root 24 Oct 16:55  /usr/lib/libssl.so -> libssl.so.3
.rwxr-xr-x 651k root root 24 Oct 16:55  /usr/lib/libssl.so.3
.rwxr-xr-x 424k root root 20 Nov 22:23  /usr/lib/libssl3.so

Vstest console is a dotnet dll so I would assume libssl isn't included in it but I don't know. I don't really know enough about vstest architecture nor how Linux package management works to understand how this would work exactly.

I know from past versions of dotnet core that openssl with linux is a common pain point. If I remember correctly, older versions of dotnet core relied on hardcoded, outdated openssl implementations.

Maybe someone else can help?

draptik commented 6 months ago

@rouke-broersma Looking into old issues like https://github.com/dotnet/core/issues/4749 I wouldn't hold my breath on a fix for dotnetcore3.

According to

https://dotnet.microsoft.com/en-us/platform/support/policy/dotnet-core

dotnetcore3.1 had end-of-life support a year ago.

Should I open a new issue for this?

image image

rouke-broersma commented 6 months ago

@rouke-broersma Looking into old issues like https://github.com/dotnet/core/issues/4749 I wouldn't hold my breath on a fix for dotnetcore3.

According to

https://dotnet.microsoft.com/en-us/platform/support/policy/dotnet-core

dotnetcore3.1 had end-of-life support a year ago.

Should I open a new issue for this?

image image

Vstest (latest) is shipped by Microsoft in this way so I would suggest opening a ticket in the vstest repo and ask them why this happens with the vstest portable package and not with the version shipped with dotnet cli.

draptik commented 6 months ago

I found a solution.

Summary:

# Install openssl-1.1
yay -S openssl1.1 # one-time install

# Set environment variable
export CLR_OPENSSL_VERSION_OVERRIDE=1.1 # has to be set before running stryker

Then run stryker:

dotnet stryker ...

My alias:

alias stryker='export CLR_OPENSSL_VERSION_OVERRIDE=1.1 && dotnet stryker'

Proof of concept:

image

Resources:

draptik commented 6 months ago

Maybe it's worth mentioning in the docs? Or even adding a simple check along the lines "If openssl3 is the default, add the environment variable. If that also fails, crash as before with the suggestion to also install openssl1 side-by-side to openssl3"?

rouke-broersma commented 6 months ago

Yes it would be great to add a known issues docs page with these instructions, thanks for investigating!

rouke-broersma commented 6 months ago

Or even adding a simple check along the lines "If openssl3 is the default, add the environment variable. If that also fails, crash as before with the suggestion to also install openssl1 side-by-side to openssl3"?

I feel that this would be too infringing on the user's system, they might not realize or want this behavior.