opentelemetry-dotnet-instrumentation icon indicating copy to clipboard operation
opentelemetry-dotnet-instrumentation copied to clipboard

Published 20 hours ago • verified publisher icon open-telemetry

Could not load file or assembly System.Runtime.CompilerServices.Unsafe on .NET Core 3.1

Open pjanotti opened this issue 3 years ago • 2 comments
trafficstars

This is failing consistently on my local Windows run of dotnet nuke Workflow:

10:27:36 [INF] > "C:\Program Files\dotnet\dotnet.exe" test C:\src\otel\dotnet\auto\test\IntegrationTests\IntegrationTests.csproj --configuration Release --framework netcoreapp3.1 --filter Containers!=Windows --logger trx --no-build --no-restore --results-directory C:\src\otel\dotnet\auto\build_data\results\IntegrationTests /property:Platform=x64
10:27:37 [DBG] Test run for C:\src\otel\dotnet\auto\test\IntegrationTests\bin\x64\Release\netcoreapp3.1\IntegrationTests.dll (.NETCoreApp,Version=v3.1)
10:27:37 [DBG] Microsoft (R) Test Execution Command Line Tool Version 17.1.0
10:27:37 [DBG] Copyright (c) Microsoft Corporation.  All rights reserved.
10:27:37 [DBG]
10:27:37 [DBG] Starting test execution, please wait...
10:27:37 [DBG] A total of 1 test files matched the specified pattern.
10:28:00 [ERR] [xUnit.net 00:00:21.53]     IntegrationTests.StackExchangeRedisTests.SubmitsTraces [FAIL]
10:28:01 [DBG]   Failed IntegrationTests.StackExchangeRedisTests.SubmitsTraces [14 s]
10:28:01 [DBG]   Error Message:
10:28:01 [DBG]    Expected spans){span.Tags["db.system"] to be 8, but found 4.
10:28:01 [DBG]
10:28:01 [DBG]   Stack Trace:
10:28:01 [DBG]      at FluentAssertions.Execution.XUnit2TestFramework.Throw(String message)
10:28:01 [DBG]    at FluentAssertions.Execution.TestFrameworkProvider.Throw(String message)
10:28:01 [DBG]    at FluentAssertions.Execution.CollectingAssertionStrategy.ThrowIfAny(IDictionary`2 context)
10:28:01 [DBG]    at IntegrationTests.StackExchangeRedisTests.SubmitsTraces() in C:\src\otel\dotnet\auto\test\IntegrationTests\StackExchangeRedisTests.cs:line 60
10:28:01 [DBG]   Standard Output Messages:
10:28:01 [DBG]  Platform: X64
10:28:01 [DBG]  Configuration: Release
10:28:01 [DBG]  TargetFramework: netcoreapp3.1
10:28:01 [DBG]  .NET Core: True
10:28:01 [DBG]  Found profiler at C:\src\otel\dotnet\auto\bin\tracer-home\win-x64\OpenTelemetry.AutoInstrumentation.Native.dll.
10:28:01 [DBG]  Profiler DLL: C:\src\otel\dotnet\auto\bin\tracer-home\win-x64\OpenTelemetry.AutoInstrumentation.Native.dll
10:28:01 [DBG]  [TestHttpListener]: Listening on 'http://localhost:64044/api/v2/spans/'
10:28:01 [DBG]  Starting Application: C:\src\otel\dotnet\auto\test\test-applications\integrations\TestApplication.StackExchangeRedis\bin\x64\Release\netcoreapp3.1\TestApplication.StackExchangeRedis.dll
10:28:01 [DBG]  Found integrations at C:\src\otel\dotnet\auto\bin\tracer-home\win-x64\OpenTelemetry.AutoInstrumentation.Native.dll.
10:28:01 [DBG]  ProcessName: dotnet
10:28:01 [DBG]  ProcessId: 21784
10:28:01 [DBG]  Exit Code: 0
10:28:01 [DBG]  StandardOutput:
10:28:01 [DBG]  Command line: --redis 64014
10:28:01 [DBG]  Profiler attached: True
10:28:01 [DBG]  Platform: x64
10:28:01 [DBG]
10:28:01 [DBG]  [MockZipkinCollector]: Shutting down. Total spans received: '4'
10:28:01 [DBG]  [TestHttpListener]: Listener is shutting down.
10:28:01 [DBG]
10:28:01 [DBG]

pjanotti avatar Aug 02 '22 17:08 pjanotti

Same issue on my side. It is strange, the same instrumented library is used both for .NET Core 3.1 and .NET 6.0

Kielek avatar Aug 05 '22 06:08 Kielek

The issue is related to all async method.

Exceptions occurs in managed log file:

[2022-08-05T08:48:29.6013132Z] [Error] Could not load file or assembly 'System.Runtime.CompilerServices.Unsafe, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'. Could not find or load a specific file. (0x80131621) 
Exception: Could not load file or assembly 'System.Runtime.CompilerServices.Unsafe, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'. Could not find or load a specific file. (0x80131621)
System.IO.FileLoadException: Could not load file or assembly 'System.Runtime.CompilerServices.Unsafe, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'. Could not find or load a specific file. (0x80131621)
File name: 'System.Runtime.CompilerServices.Unsafe, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'
 ---> System.IO.FileLoadException: Could not load file or assembly 'System.Runtime.CompilerServices.Unsafe, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'.
   at System.Runtime.Loader.AssemblyLoadContext.LoadFromPath(IntPtr ptrNativeAssemblyLoadContext, String ilPath, String niPath, ObjectHandleOnStack retAssembly)
   at System.Runtime.Loader.AssemblyLoadContext.InternalLoadFromPath(String assemblyPath, String nativeImagePath)
   at System.Runtime.Loader.AssemblyLoadContext.LoadFromAssemblyPath(String assemblyPath)
   at System.Reflection.Assembly.LoadFrom(String assemblyFile)
   at System.Reflection.Assembly.LoadFromResolveHandler(Object sender, ResolveEventArgs args)
   at System.Runtime.Loader.AssemblyLoadContext.InvokeResolveEvent(ResolveEventHandler eventHandler, RuntimeAssembly assembly, String name)
   at System.Runtime.Loader.AssemblyLoadContext.OnAssemblyResolve(RuntimeAssembly assembly, String assemblyFullName)
   at OpenTelemetry.AutoInstrumentation.CallTarget.Handlers.Continuations.TaskContinuationGenerator`4.SetContinuation(TTarget instance, TReturn returnValue, Exception exception, CallTargetState state) in C:\GitHub\opentelemetry-dotnet-instrumentation\src\OpenTelemetry.AutoInstrumentation\CallTarget\Handlers\Continuations\TaskContinuationGenerator`1.cs:line 53
   at StackExchange.Redis.ConnectionMultiplexer.ConnectImplAsync(ConfigurationOptions configuration, TextWriter log)

Kielek avatar Aug 05 '22 08:08 Kielek

More data https://www.nuget.org/packages/System.Diagnostics.DiagnosticSource/6.0.0#dependencies-body-tab depends on System.Runtime.CompilerServices.Unsafe v 6.0.0 System.Runtime.CompilerServices.Unsafe.dll v. 6.0.0 is availalbe in two folders in our distribution:

  • tracer-home\store\x64\netcoreapp3.1\system.runtime.compilerservices.unsafe\6.0.0\lib\netcoreapp3.1
  • tracer-home\netcoreapp3.1

When the code related to Unsafe is called https://github.com/open-telemetry/opentelemetry-dotnet-instrumentation/blob/384df5b54290b28e7afb03b38116f35db59eb78a/src/OpenTelemetry.AutoInstrumentation/CallTarget/Handlers/Continuations/ContinuationGenerator.cs#L33 it fails with the exception.

There is Unsafe module loaded by the runtime. On my env from: System.Runtime.CompilerServices.Unsafe, Version=4.0.6.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a C:\Program Files\dotnet\shared\Microsoft.NETCore.App\3.1.27\System.Runtime.CompilerServices.Unsafe.dll

Tested scenarios:

  • add reference to System.Runtime.CompilerServices.Unsafe.dll v. 6.0.0 https://github.com/open-telemetry/opentelemetry-dotnet-instrumentation/blob/a777c1eba056e00c4701b6e3f30cb1659382c7a5/test/test-applications/integrations/TestApplication.StackExchangeRedis/TestApplication.StackExchangeRedis.csproj - tests passed
  • do not relay on Unsafe library in our code. Use the solution from .NET Framework https://github.com/open-telemetry/opentelemetry-dotnet-instrumentation/blob/384df5b54290b28e7afb03b38116f35db59eb78a/src/OpenTelemetry.AutoInstrumentation/CallTarget/Handlers/Continuations/ContinuationGenerator.cs#L33 - tests passed
  • add reference to https://github.com/open-telemetry/opentelemetry-dotnet-instrumentation/blob/a777c1eba056e00c4701b6e3f30cb1659382c7a5/src/OpenTelemetry.AutoInstrumentation.AdditionalDeps/Directory.Build.props - no changes. Old Unsafe library is loaded.

Do you have any ideas why the Unsafe library is not loaded from the AdditionalDeps/store directory?

@rajkumar-rangaraj, @RassK as you were the most involved in library loading process :)

Kielek avatar Aug 09 '22 08:08 Kielek

AdditionalDeps has so low prio, that the probing path it provides is executed at the last order.

We were discussing with @pellared, how dependencies should be positioned. I can't remember any more, if there was an issue open about restructuring dependencies or not. But I guess our build output should be cleaned from the dependencies and all nugets should be provided via AdditionalDeps. So then there is no way to ship duplicated dependencies and loading is corrected so right version of the dependency is loaded.

RassK avatar Aug 09 '22 09:08 RassK

The issue is related to all async method.

Exceptions occurs in managed log file:

[2022-08-05T08:48:29.6013132Z] [Error] Could not load file or assembly 'System.Runtime.CompilerServices.Unsafe, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'. Could not find or load a specific file. (0x80131621) 
Exception: Could not load file or assembly 'System.Runtime.CompilerServices.Unsafe, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'. Could not find or load a specific file. (0x80131621)
System.IO.FileLoadException: Could not load file or assembly 'System.Runtime.CompilerServices.Unsafe, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'. Could not find or load a specific file. (0x80131621)
File name: 'System.Runtime.CompilerServices.Unsafe, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'
 ---> System.IO.FileLoadException: Could not load file or assembly 'System.Runtime.CompilerServices.Unsafe, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'.
   at System.Runtime.Loader.AssemblyLoadContext.LoadFromPath(IntPtr ptrNativeAssemblyLoadContext, String ilPath, String niPath, ObjectHandleOnStack retAssembly)
   at System.Runtime.Loader.AssemblyLoadContext.InternalLoadFromPath(String assemblyPath, String nativeImagePath)
   at System.Runtime.Loader.AssemblyLoadContext.LoadFromAssemblyPath(String assemblyPath)
   at System.Reflection.Assembly.LoadFrom(String assemblyFile)
   at System.Reflection.Assembly.LoadFromResolveHandler(Object sender, ResolveEventArgs args)
   at System.Runtime.Loader.AssemblyLoadContext.InvokeResolveEvent(ResolveEventHandler eventHandler, RuntimeAssembly assembly, String name)
   at System.Runtime.Loader.AssemblyLoadContext.OnAssemblyResolve(RuntimeAssembly assembly, String assemblyFullName)
   at OpenTelemetry.AutoInstrumentation.CallTarget.Handlers.Continuations.TaskContinuationGenerator`4.SetContinuation(TTarget instance, TReturn returnValue, Exception exception, CallTargetState state) in C:\GitHub\opentelemetry-dotnet-instrumentation\src\OpenTelemetry.AutoInstrumentation\CallTarget\Handlers\Continuations\TaskContinuationGenerator`1.cs:line 53
   at StackExchange.Redis.ConnectionMultiplexer.ConnectImplAsync(ConfigurationOptions configuration, TextWriter log)

We should not see this issue when DOTNET_ADDITIONAL_DEPS and DOTNET_SHARED_STORE are set. system.runtime.compilerservices.unsafe is a part of runtime store.

Kielek, Could you please confirm these environment variables are set when you received an error.

rajkumar-rangaraj avatar Aug 10 '22 15:08 rajkumar-rangaraj

@rajkumar-rangaraj, I can confirm. I have extended standard Splash Screen:

Command line: --redis 63687
Profiler attached: True
Platform: x64
DOTNET_ADDITIONAL_DEPS: C:\GitHub\opentelemetry-dotnet-instrumentation\bin\tracer-home\AdditionalDeps
DOTNET_SHARED_STORE: C:\GitHub\opentelemetry-dotnet-instrumentation\bin\tracer-home\store

The folder matches location on my disk.

Kielek avatar Aug 10 '22 16:08 Kielek

Notes after call with @rajkumar-rangaraj

Enabled logging for our application based on https://docs.microsoft.com/en-us/dotnet/core/dependency-loading/default-probing#how-do-i-debug-the-probing-properties-construction

The results are:

Replacing deps entry [C:\GitHub\opentelemetry-dotnet-instrumentation\test\test-applications\integrations\TestApplication.StackExchangeRedis\bin\x64\Debug\netcoreapp3.1\System.Runtime.CompilerServices.Unsafe.dll, AssemblyVersion:4.0.6.0, FileVersion:4.700.20.12001] with [C:\Program Files\dotnet\shared\Microsoft.NETCore.App\3.1.28\System.Runtime.CompilerServices.Unsafe.dll, AssemblyVersion:4.0.6.0, FileVersion:4.700.22.36301]

@rajkumar-rangaraj will look into it later and check with @noahfalk if needed.

Kielek avatar Aug 10 '22 17:08 Kielek

<<--Edited-->>

Issue happens with .NET Core 3.1 and we see FileLoadException for System.Runtime.CompilerServices.Unsafe.dll. My previous note had an incorrect info modified to reflect the actual summary.

rajkumar-rangaraj avatar Aug 11 '22 02:08 rajkumar-rangaraj

Found the root cause for an issue. Attached the deps.json generated from TestApplication.StackExchangeRedis. Deps.json shows that application has an indirect reference to System.Runtime.CompilerServices.Unsafe.dll

"Pipelines.Sockets.Unofficial/2.1.16": {
        "dependencies": {
          "System.Buffers": "4.5.1",
          "System.IO.Pipelines": "4.7.1",
          "System.Runtime.CompilerServices.Unsafe": "4.7.1"
        },
        "runtime": {
          "lib/netcoreapp3.1/Pipelines.Sockets.Unofficial.dll": {
            "assemblyVersion": "1.0.0.0",
            "fileVersion": "2.1.16.58714"
          }
        }

The bin directory of this test app includes System.Runtime.CompilerServices.Unsafe.dll. If a library is present in bin directory or got indirect/direct library reference through package used in an app, it cannot be upgraded using AdditionalDeps/RuntimeStore. In this scenario StackExchange.Redis package is referenced in an app which has an indirect reference to System.Runtime.CompilerServices.Unsafe.dll.

We might need to capture these exceptions and log to reflect the actual cause. This is one of the corner case where we auto-instrumentation won't work. We may not need to handle these case specially as .NET Core 3.1 will go out of support and might see very few of these cases in future.

image

Deps File: TestApplication.StackExchangeRedis.deps.json.txt

rajkumar-rangaraj avatar Aug 11 '22 04:08 rajkumar-rangaraj