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
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)
Ah I see, we added some new code in df78d34 that immediately sets the
is_desktop_iis
flag totrue
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