opentelemetry-dotnet-instrumentation: Bytecode Instrumentation Not Work on .NET 6

Bug Report

Symptom

Describe the bug I have some custom bytecode instrumentations which worked on otel-net-instrument 0.6.0. But they partially failed on otel-net-instrument 1.0.0: failed on .NET 6 while succeeded on .NET framework 4.6.2.

Here is an example of my custom bytecode instrumentation: 1/ implemented integration class/methods like

/// <summary>
/// calltarget instrumentation
/// </summary>
[InstrumentMethod(
    assemblyName: "Oracle.ManagedDataAccess",
    typeName: "Oracle.ManagedDataAccess.Client.OracleCommand",
    methodName: "ExecuteReader",
    returnTypeName: "System.Int32",
    parameterTypeNames: new string[] { "System.Boolean", "System.Boolean", "System.Data.CommandBehavior" },
    minimumVersion: "2.0.0",
    maximumVersion: "21.65535.65535",
    integrationName: "Odp",
    type: InstrumentationType.Trace)]
public class OdpReaderIntegration
{ ... }

2/ added an entry in src\OpenTelemetry.AutoInstrumentation\Configurations\TracerInstrumentation.cs

    /// <summary>
    /// ODP.NET instrumentation.
    /// </summary>
    Odp = 20

otel-net-instrument can be built successfully. I can see generated files such as odpFailOnNet6

I have 2 sample applications: one is on .NET framework 4.6.2; the other is on .NET 6. When I run the application on .NET framework 4.6.2, I looked into log and can see all bytecode instrumentation definitions got loaded:

[2023-09-08T08:18:08.139600700Z] [7268|4112] [info] AddInstrumentations: received id: FFAFA5168C4F4718B40CA8788875C2DA from managed side with 15 integrations.
[2023-09-08T08:18:08.139889100Z] [7268|4112] [debug]   * Target: System.Web | System.Web.Compilation.BuildManager.InvokePreStartInitMethodsCore(3) { 4.0.0.0 - 4.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.AspNet.HttpModuleIntegration]
[2023-09-08T08:18:08.139990400Z] [7268|4112] [debug]   * Target: Microsoft.AspNetCore | Microsoft.AspNetCore.Builder.WebApplication.Run(2) { 6.0.0.0 - 7.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.Ba.BaIntegration]
[2023-09-08T08:18:08.140072300Z] [7268|4112] [debug]   * Target: MongoDB.Driver | MongoDB.Driver.MongoClient..ctor(2) { 2.13.3.0 - 2.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.MongoDB.MongoClientIntegration]
[2023-09-08T08:18:08.140152600Z] [7268|4112] [debug]   * Target: NServiceBus.Core | NServiceBus.EndpointConfiguration..ctor(2) { 8.0.0.0 - 8.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.NServiceBus.EndpointConfigurationIntegration]
[2023-09-08T08:18:08.140234200Z] [7268|4112] [debug]   * Target: Oracle.ManagedDataAccess | Oracle.ManagedDataAccess.Client.OracleConnection.Close(1) { 2.0.0.0 - 21.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.Odp.OdpCloseConnectionIntegration]
[2023-09-08T08:18:08.140308700Z] [7268|4112] [debug]   * Target: Oracle.ManagedDataAccess | Oracle.ManagedDataAccess.Client.OracleCommand.ExecuteNonQuery(1) { 2.0.0.0 - 21.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.Odp.OdpNonQueryIntegration]
[2023-09-08T08:18:08.140375100Z] [7268|4112] [debug]   * Target: Oracle.ManagedDataAccess | Oracle.ManagedDataAccess.Client.OracleConnection.Open(1) { 2.0.0.0 - 21.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.Odp.OdpOpenConnectionIntegration]
[2023-09-08T08:18:08.140593000Z] [7268|4112] [debug]   * Target: Oracle.ManagedDataAccess | Oracle.ManagedDataAccess.Client.OracleCommand.ExecuteReader(4) { 2.0.0.0 - 21.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.Odp.OdpReaderIntegration]
[2023-09-08T08:18:08.140660400Z] [7268|4112] [debug]   * Target: Oracle.ManagedDataAccess | Oracle.ManagedDataAccess.Client.OracleCommand.ExecuteXmlReader(1) { 2.0.0.0 - 21.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.Odp.OdpXmlReaderIntegration]
[2023-09-08T08:18:08.140735600Z] [7268|4112] [debug]   * Target: System.ServiceModel | System.ServiceModel.ChannelFactory.InitializeEndpoint(3) { 4.0.0.0 - 4.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.Wcf.Client.WcfClientIntegration]
[2023-09-08T08:18:08.140820100Z] [7268|4112] [debug]   * Target: System.ServiceModel | System.ServiceModel.ChannelFactory.InitializeEndpoint(2) { 4.0.0.0 - 4.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.Wcf.Client.WcfClientIntegration]
[2023-09-08T08:18:08.140887600Z] [7268|4112] [debug]   * Target: System.ServiceModel | System.ServiceModel.ChannelFactory.InitializeEndpoint(3) { 4.0.0.0 - 4.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.Wcf.Client.WcfClientIntegration]
[2023-09-08T08:18:08.141160500Z] [7268|4112] [debug]   * Target: System.ServiceModel | System.ServiceModel.ChannelFactory.InitializeEndpoint(4) { 4.0.0.0 - 4.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.Wcf.Client.WcfClientIntegration]
[2023-09-08T08:18:08.141227000Z] [7268|4112] [debug]   * Target: System.ServiceModel | System.ServiceModel.ServiceHostBase.InitializeDescription(2) { 4.0.0.0 - 4.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.Wcf.Service.ServiceHostIntegration]
[2023-09-08T08:18:08.141384900Z] [7268|4112] [debug]   * Target: NServiceBus.Core | NServiceBus.EndpointConfiguration..ctor(2) { 8.0.0.0 - 8.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51 | OpenTelemetry.AutoInstrumentation.Instrumentations.NServiceBus.EndpointConfigurationIntegration]

furtherdown in the log, I can see bytecode got instrumented for my custom requirement:

[2023-09-08T08:18:26.544051000Z] [7268|3444] [debug] GetReJITParameters: [moduleId: 140720978729368, methodId: 100664859]
[2023-09-08T08:18:26.544289900Z] [7268|3444] [debug] *** CallTarget_RewriterCallback() Start: Oracle.ManagedDataAccess.Client.OracleCommand.ExecuteReader() [IsVoid=0, IsStatic=0, IntegrationType=OpenTelemetry.AutoInstrumentation.Instrumentations.Odp.OdpReaderIntegration, Arguments=3]
[2023-09-08T08:18:26.544554000Z] [7268|3444] [debug] Caller Type.Id: 96000002
[2023-09-08T08:18:26.544593600Z] [7268|3444] [debug] Caller Type.IsGeneric: 0
[2023-09-08T08:18:26.544629300Z] [7268|3444] [debug] Caller Type.IsValid: 1
[2023-09-08T08:18:26.544664500Z] [7268|3444] [debug] Caller Type.Name: Oracle.ManagedDataAccess.Client.OracleCommand
[2023-09-08T08:18:26.544700500Z] [7268|3444] [debug] Caller Type.TokenType: 33554432
[2023-09-08T08:18:26.544735300Z] [7268|3444] [debug] Caller Type.Spec: 0000001b
[2023-09-08T08:18:26.544771000Z] [7268|3444] [debug] Caller Type.ValueType: 0
[2023-09-08T08:18:26.544806700Z] [7268|3444] [debug] Caller Type Extend From.Id: 25000001
[2023-09-08T08:18:26.544843100Z] [7268|3444] [debug] Caller Type Extend From.IsGeneric: 0
[2023-09-08T08:18:26.544879400Z] [7268|3444] [debug] Caller Type Extend From.IsValid: 1
[2023-09-08T08:18:26.544914300Z] [7268|3444] [debug] Caller Type Extend From.Name: System.Data.Common.DbCommand
[2023-09-08T08:18:26.544958600Z] [7268|3444] [debug] Caller Type Extend From.TokenType: 16777216
[2023-09-08T08:18:26.544995600Z] [7268|3444] [debug] Caller Type Extend From.Spec: 0000001b
[2023-09-08T08:18:26.545032100Z] [7268|3444] [debug] Caller Type Extend From.ValueType: 0
[2023-09-08T08:18:26.545229400Z] [7268|3444] [info] *** CallTarget_RewriterCallback() Finished: Oracle.ManagedDataAccess.Client.OracleCommand.ExecuteReader() [IsVoid=0, IsStatic=0, IntegrationType=OpenTelemetry.AutoInstrumentation.Instrumentations.Odp.OdpReaderIntegration, Arguments=3]
[2023-09-08T08:18:26.545538200Z] [7268|3444] [debug] ReJITCompilationStarted: [functionId: 140720978757648, rejitId: 12, safeToBlock: 1]
[2023-09-08T08:18:26.557898500Z] [7268|3444] [debug] ReJITCompilationFinished: [functionId: 140720978757648, rejitId: 12, hrStatus: 0x00000000, safeToBlock: 1]

All good for .NET framework. When I run the application on .NET 6, I can see all bytecode instrumentation definitions got loaded as well:

[2023-09-08T08:22:34.725478300Z] [3560|7064] [info] AddInstrumentations: received id: FFAFA5168C4F4718B40CA8788875C2DA from managed side with 23 integrations.
[2023-09-08T08:22:34.725781200Z] [3560|7064] [debug]   * Target: Microsoft.AspNetCore | Microsoft.AspNetCore.Builder.WebApplication.Run(2) { 6.0.0.0 - 7.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.Ba.BaIntegration]
[2023-09-08T08:22:34.725865000Z] [3560|7064] [debug]   * Target: MongoDB.Driver | MongoDB.Driver.MongoClient..ctor(2) { 2.13.3.0 - 2.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.MongoDB.MongoClientIntegration]
[2023-09-08T08:22:34.725939600Z] [3560|7064] [debug]   * Target: NServiceBus.Core | NServiceBus.EndpointConfiguration..ctor(2) { 8.0.0.0 - 8.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.NServiceBus.EndpointConfigurationIntegration]
[2023-09-08T08:22:34.726014400Z] [3560|7064] [debug]   * Target: Oracle.ManagedDataAccess | Oracle.ManagedDataAccess.Client.OracleConnection.Close(1) { 2.0.0.0 - 21.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.Odp.OdpCloseConnectionIntegration]
[2023-09-08T08:22:34.726080900Z] [3560|7064] [debug]   * Target: Oracle.ManagedDataAccess | Oracle.ManagedDataAccess.Client.OracleCommand.ExecuteNonQuery(1) { 2.0.0.0 - 21.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.Odp.OdpNonQueryIntegration]
[2023-09-08T08:22:34.726149100Z] [3560|7064] [debug]   * Target: Oracle.ManagedDataAccess | Oracle.ManagedDataAccess.Client.OracleConnection.Open(1) { 2.0.0.0 - 21.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.Odp.OdpOpenConnectionIntegration]
[2023-09-08T08:22:34.726216100Z] [3560|7064] [debug]   * Target: Oracle.ManagedDataAccess | Oracle.ManagedDataAccess.Client.OracleCommand.ExecuteReader(4) { 2.0.0.0 - 21.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.Odp.OdpReaderIntegration]
[2023-09-08T08:22:34.726303200Z] [3560|7064] [debug]   * Target: Oracle.ManagedDataAccess | Oracle.ManagedDataAccess.Client.OracleCommand.ExecuteXmlReader(1) { 2.0.0.0 - 21.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.Odp.OdpXmlReaderIntegration]
[2023-09-08T08:22:34.726373600Z] [3560|7064] [debug]   * Target: StackExchange.Redis | StackExchange.Redis.ConnectionMultiplexer.ConnectImpl(3) { 2.0.0.0 - 2.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.StackExchangeRedis.StackExchangeRedisIntegration]
[2023-09-08T08:22:34.726435500Z] [3560|7064] [debug]   * Target: StackExchange.Redis | StackExchange.Redis.ConnectionMultiplexer.ConnectImpl(3) { 2.0.0.0 - 2.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.StackExchangeRedis.StackExchangeRedisIntegration]
[2023-09-08T08:22:34.726513200Z] [3560|7064] [debug]   * Target: StackExchange.Redis | StackExchange.Redis.ConnectionMultiplexer.ConnectImpl(4) { 2.0.0.0 - 2.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.StackExchangeRedis.StackExchangeRedisIntegration]
[2023-09-08T08:22:34.726577600Z] [3560|7064] [debug]   * Target: StackExchange.Redis | StackExchange.Redis.ConnectionMultiplexer.ConnectImpl(5) { 2.0.0.0 - 2.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.StackExchangeRedis.StackExchangeRedisIntegration]
[2023-09-08T08:22:34.726843700Z] [3560|7064] [debug]   * Target: StackExchange.Redis | StackExchange.Redis.ConnectionMultiplexer.ConnectImplAsync(3) { 2.0.0.0 - 2.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.StackExchangeRedis.StackExchangeRedisIntegrationAsync]
[2023-09-08T08:22:34.726906400Z] [3560|7064] [debug]   * Target: StackExchange.Redis | StackExchange.Redis.ConnectionMultiplexer.ConnectImplAsync(3) { 2.0.0.0 - 2.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.StackExchangeRedis.StackExchangeRedisIntegrationAsync]
[2023-09-08T08:22:34.726998500Z] [3560|7064] [debug]   * Target: StackExchange.Redis | StackExchange.Redis.ConnectionMultiplexer.ConnectImplAsync(4) { 2.0.0.0 - 2.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.StackExchangeRedis.StackExchangeRedisIntegrationAsync]
[2023-09-08T08:22:34.727070700Z] [3560|7064] [debug]   * Target: System.Private.ServiceModel | System.ServiceModel.ChannelFactory.InitializeEndpoint(3) { 4.0.0.0 - 4.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.Wcf.Client.WcfClientIntegration]
[2023-09-08T08:22:34.727132700Z] [3560|7064] [debug]   * Target: System.Private.ServiceModel | System.ServiceModel.ChannelFactory.InitializeEndpoint(2) { 4.0.0.0 - 4.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.Wcf.Client.WcfClientIntegration]
[2023-09-08T08:22:34.727194600Z] [3560|7064] [debug]   * Target: System.Private.ServiceModel | System.ServiceModel.ChannelFactory.InitializeEndpoint(3) { 4.0.0.0 - 4.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.Wcf.Client.WcfClientIntegration]
[2023-09-08T08:22:34.727270000Z] [3560|7064] [debug]   * Target: System.ServiceModel.Primitives | System.ServiceModel.ChannelFactory.InitializeEndpoint(3) { 6.0.0.0 - 6.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.Wcf.Client.WcfClientIntegration]
[2023-09-08T08:22:34.727333800Z] [3560|7064] [debug]   * Target: System.ServiceModel.Primitives | System.ServiceModel.ChannelFactory.InitializeEndpoint(2) { 6.0.0.0 - 6.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.Wcf.Client.WcfClientIntegration]
[2023-09-08T08:22:34.727493200Z] [3560|7064] [debug]   * Target: System.ServiceModel.Primitives | System.ServiceModel.ChannelFactory.InitializeEndpoint(3) { 6.0.0.0 - 6.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.Wcf.Client.WcfClientIntegration]
[2023-09-08T08:22:34.727563200Z] [3560|7064] [debug]   * Target: Microsoft.Extensions.Logging | Microsoft.Extensions.Logging.LoggingBuilder..ctor(2) { 3.1.0.0 - 7.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.Logger.LoggingBuilderIntegration]
[2023-09-08T08:22:34.727623500Z] [3560|7064] [debug]   * Target: NServiceBus.Core | NServiceBus.EndpointConfiguration..ctor(2) { 8.0.0.0 - 8.65535.65535.0 } [OpenTelemetry.AutoInstrumentation, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null | OpenTelemetry.AutoInstrumentation.Instrumentations.NServiceBus.EndpointConfigurationIntegration]
[2023-09-08T08:22:34.727870700Z] [3560|7064] [info] Total number of modules to analyze: 1

but I cannot see any bytecode got instrumented.

Runtime environment (please complete the following information):

  • OpenTelemetry Automatic Instrumentation version: 1.0.0
  • OS: Windows Server 2022
  • .NET version: .NET 6

Attached please find logs: otel-dotnet-auto-native-w3wp-3560—NET6.log otel-dotnet-auto-native-w3wp-7268—NETFX462.log

About this issue

  • Original URL
  • State: closed
  • Created 10 months ago
  • Comments: 18 (9 by maintainers)

Most upvoted comments

Ah I see, we added some new code in df78d34 that immediately sets the is_desktop_iis flag to true when the .NET Framework code starts. So in 0.6.0 and before, this failure mode was less likely to occur (it was a race-condition), but now it will fail nearly every time.

@open-telemetry/dotnet-instrumentation-maintainers after 0.6.0 we can only instrument .NET Core apps hosted in IIS when their app pool is configured with No Managed Code. We can carefully try to enable it again when the .NET Framework is also loaded in-process, if you think we should support that.

@muhaook I think that once we determine the approach here, we can close the issue and then proceed with the follow-up work. Thank you for raising this issue