Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bytecode Instrumentation Not Work on .NET 6 #2934

Closed
muhaook opened this issue Sep 8, 2023 · 18 comments
Closed

Bytecode Instrumentation Not Work on .NET 6 #2934

muhaook opened this issue Sep 8, 2023 · 18 comments

Comments

@muhaook
Copy link

muhaook commented Sep 8, 2023

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

@muhaook
Copy link
Author

muhaook commented Sep 8, 2023

I can reproduce this issue using 2 sample code:

v0.6.0

I had 2 new commits on top of v0.6.0. See below branch:
https://github.com/muhaook/opentelemetry-dotnet-instrumentation/commits/issue2934-v060
in the 2 commit, I implemented a custom bytecode instrumentation which print out a log entry to indicate AspNetCore application is triggered.
when I use browser to access any of my .NET 6 AspNetCore application hosted on IIS, I can see below in otel-net-instrument log. This log entry was written by the custom bytecode instrumentation.

[2023-09-08T22:42:32.6713877Z] [Information] ===== WebApplication.Run() gets invoked ===== 

v1.0.0

I had 2 new commits on top of v1.0.0. See below branch:
https://github.com/muhaook/opentelemetry-dotnet-instrumentation/commits/issue2934-v100
in the 2 commit. I implemented the same custom bytecode instrumentation.
when I use browser to access the same .NET 6 AspNetCore application hosted on IIS, I can NOT see the log entry which should indicate WebApplication.Run() gets invoked. This means the custom bytecode instrumentation was not happening when it should happen

@Kielek
Copy link
Contributor

Kielek commented Sep 11, 2023

@muhaook, I was able to execute your Ba integration on .NET 6 with some minor changes on self-hosted application.

Steps to execute

  1. nuke BuildTracer
  2. open VS
  3. Execute TestApplication.AspNetCore

You should be able to find logs both in OTel Auto log files and in Console.

I do not have easy accessible IIS-env, so please let me know if it is working for you.

You can find code here: https://github.com/Kielek/opentelemetry-dotnet-instrumentation/tree/mike-ba-integration

@muhaook
Copy link
Author

muhaook commented Sep 11, 2023

Thanks @Kielek, I made a build with your branch and deployed it on my IIS env, but seems the instrumentation did not happen.

Attached please find logs:
logs.zip

@Kielek
Copy link
Contributor

Kielek commented Sep 12, 2023

I have made another tests.

Server preparation

  1. Brand new Windows 11 VM from azure
  2. Install IIS
image 3. Install https://dotnet.microsoft.com/en-us/download/dotnet/thank-you/runtime-aspnetcore-6.0.21-windows-hosting-bundle-installer 4. Restart IIS

Application preparation:

  1. Open VS
  2. Publish TestApplication.AspNetCore to the folder
  3. Copy it to VM created previously

OTel Auto preparation

  1. checkout https://github.com/Kielek/opentelemetry-dotnet-instrumentation/tree/mike-ba-integration
  2. git clean -fxd (to ensure that you have clean build)
  3. nuke BuildTracer
  4. Zip content from reposiotory-for-opentelemetry-dotnet-instrumentation\bin\tracer-home and call it tracer.zip
  5. Copy to VM

Set up IIS

  1. Set up website for test application (for 80 endpoint for my tests)
  2. Verify if it is working correctly. It should display Hello there

Enable OpenTelemetry

  1. Download https://github.com/open-telemetry/opentelemetry-dotnet-instrumentation/releases/download/v1.0.0/OpenTelemetry.DotNet.Auto.psm1
  2. Run powershell as administrator in the folder where you have psm1 script and tracer.zip
  3. Execute following code
Import-Module .\OpenTelemetry.DotNet.Auto.psm1 -Verbose
Install-OpenTelemetryCore -LocalPath .\tracer.zip
Register-OpenTelemetryForIIS
  1. Open iis page once more time

In logs you should see something like this

[2023-09-12T08:53:22.9840610Z] [Information] OpenTelemetry tracer initialized. 
[2023-09-12T08:53:23.0052341Z] [Information] EventSource=OpenTelemetry-AutoInstrumentation, Message=OpenTelemetry tracer initialized. 
[2023-09-12T08:53:23.1686514Z] [Information] OpenTelemetry meter initialized. 
[2023-09-12T08:53:23.1721751Z] [Information] EventSource=OpenTelemetry-AutoInstrumentation, Message=OpenTelemetry meter initialized. 
[2023-09-12T08:53:23.1898571Z] [Information] The profiler has been initialized with 18 definitions for FFAFA5168C4F4718B40CA8788875C2DA. 
[2023-09-12T08:53:23.1919748Z] [Information] EventSource=OpenTelemetry-AutoInstrumentation, Message=The profiler has been initialized with 18 definitions for FFAFA5168C4F4718B40CA8788875C2DA. 
[2023-09-12T08:53:23.1956218Z] [Information] The profiler has been initialized with 0 derived definitions. 
[2023-09-12T08:53:23.1975153Z] [Information] EventSource=OpenTelemetry-AutoInstrumentation, Message=The profiler has been initialized with 0 derived definitions. 
[2023-09-12T08:53:23.2095044Z] [Information] EventSource=OpenTelemetry-AutoInstrumentation-StartupHook, Message=StartupHook initialized successfully! 
[2023-09-12T08:53:23.2397075Z] [Warning] EventSource=OpenTelemetry-Sdk, Message=Measurements from Instrument 'srv.successes.count', Meter 'Examples.Service' will be ignored. Reason: 'Instrument belongs to a Meter not subscribed by the provider.'. Suggested action: 'Use AddMeter to add the Meter to the provider.' 
[2023-09-12T08:53:23.3536030Z] [Information] EventSource=OpenTelemetry-AutoInstrumentation, Message=BootstrapperHostingStartup loaded for application with name TestApplication.AspNetCore. 
[2023-09-12T08:53:23.6487258Z] [Information] EventSource=OpenTelemetry-AutoInstrumentation, Message=Logs: Loaded AddOpenTelemetry from LoggingBuilder. 
[2023-09-12T08:53:23.8528213Z] [Information] ===== WebApplication.Run() gets invoked ===== 
[2023-09-12T08:53:23.8549535Z] [Information] EventSource=OpenTelemetry-AutoInstrumentation, Message====== WebApplication.Run() gets invoked ===== 

for native part:

[2023-09-12T08:53:23.465627600Z] [11080|9688] [info] *** CallTarget_RewriterCallback() Finished: Microsoft.Extensions.Logging.LoggingBuilder..ctor() [IsVoid=1, IsStatic=0, IntegrationType=OpenTelemetry.AutoInstrumentation.Instrumentations.Logger.LoggingBuilderIntegration, Arguments=1]
[2023-09-12T08:53:23.851953100Z] [11080|9688] [info] *** CallTarget_RewriterCallback() Finished: Microsoft.AspNetCore.Builder.WebApplication.Run() [IsVoid=1, IsStatic=0, IntegrationType=OpenTelemetry.AutoInstrumentation.Instrumentations.Ba.BaIntegration, Arguments=1]

Logs from my tests: log.zip

I need some beter steps to reproduce to verify your issue.

@muhaook
Copy link
Author

muhaook commented Sep 12, 2023

Thanks @Kielek for the details. I tried to verify your fix on Windows 10 but still failed. Is it possible the CLR profiling API we are using in otel-net-instrument works on Windows 11 but does not work on Windows 10 ?

Here are some details:

My test env is Windows 10 Version 22H2 (OS Build 19045.3324)
Deployed TestApplication.AspNetCore on IIS.

I can see Hello there after accessing the app using browser.

Made a build off your branch.

I made a log change to make sure I am running the expected build on my env:

Logger.Information("OpenTelemetry tracer initialized. Testing AspNetCore bytecode injection...");

Put contents in bin/tracer-home into tracer.zip

Enable OpenTelemetry
Import-Module .\OpenTelemetry.DotNet.Auto.psm1 -Verbose
Install-OpenTelemetryCore -LocalPath .\tracer.zip
Register-OpenTelemetryForIIS
Accessed webapplication and saw Hello there again

Did not find bytecode instrumentation in logs:
logs.zip

@muhaook
Copy link
Author

muhaook commented Sep 12, 2023

Bytecode Instrumentation works on Piotr's Win10. So looks like this is my test env issue.

@muhaook
Copy link
Author

muhaook commented Sep 12, 2023

It is strange - I tried to bring up brand-new VMs with Windows 10, 11, or 2022, all failed to instrument bytecode. All these VMs are our company's VM. Is it possible that some software running on the VMs blocks the bytecode instrumentation?

I tried my personal laptop (windows 11), the instrumentation works.

@Kielek
Copy link
Contributor

Kielek commented Sep 14, 2023

@muhaook, one more thing based on what I see in your logs, the standard instrumentation for ILogger is also not working on your env.

@muhaook
Copy link
Author

muhaook commented Sep 14, 2023

Agree @Kielek , so this issue happened on both custom and standard bytecode instrumentation. I compared failed v.s. succeeded logs and found more suspicious. It is likely a regression in native code as we were all good with 0.6.0.

comparison between succeeded log (on the lefthand side) and failed log (on the righthand side):

in failed log, we can see 2 CLR profilers got brought up: one is for .NET 6; the other is for .NET Framework.
in succeeded log, only 1 CLR profiler got brought up. it is for .NET 6.
issue2934_1
issue2934_2

in failed log, Total number of modules to analyze is 1
in succeeded log, it is 25
issue2934_3

during shutdown:
in failed log, IntegrationDefinitions is 0
in succeeded log, it is 18
issue2934_4

Attached please find the full failed and succeeded logs
logs for otel.zip

@zacharycmontoya
Copy link
Contributor

Hi @muhaook , I haven't been able to explore your logs files yet, but it appears that the AspNetCore application is being hosted on an application pool that has .NET Framework v4 running. Can you check if updating the application pool to CLR Version = No Managed Code resolves the issue?

@muhaook
Copy link
Author

muhaook commented Sep 21, 2023

Thanks @zacharycmontoya,

I found we have this issue right after this commit: df78d34

I made a build after the above commit. even after updating the application pool to CLR Version = No Managed Code, I can still see the issue. Attached please find the logs:
logs_after_noNetfx_fail.zip

I also make a build before the above commit and it succeeded with .NET framework enabled on the application pool. So looks like .NET framework is irrelevant. Attached please find the logs:
logs_before_withNetfx_succ.zip

@muhaook muhaook changed the title Custom Bytecode Instrumentation Not Work on .NET 6 Bytecode Instrumentation Not Work on .NET 6 Oct 1, 2023
@zacharycmontoya
Copy link
Contributor

Hi @muhaook, thanks for identifying the commit you saw this break, that helps tremendously.

Are you able to share the source code for the integration you are working on? If you need to scrub the code inside the methods that would be fine too and would help me debug this locally. Thanks!

@muhaook
Copy link
Author

muhaook commented Oct 4, 2023

Hi @zacharycmontoya,

I used to use Piotr's branch mike-ba-integration and saw this issue only happened on

  • my company laptop which is Win10
  • VMs I brought up on our company's network which can be Windows 10, 11, or 2022

I can not reproduce this issue on

  • VM on VirtualBox which is Win10
  • my personal laptop wihch is Win11
  • Piotr's VM which is Win10

The source code I am using to reproduce this issue now is on branch issue2934-postv060_1. This branch is on top of commit df78d34.

The issue happened on my company laptop but did not happen on my VM on virtualBox. Attached please find logs collected on both envs:
logs_issue2934-postv060_1.zip

after comparing native logs, I found rejit did not happen on my laptop while it happend on virtualBox as expected:
image

I have another branch issue2934-postv060_0 which is on top of the commit right before the commit df78d34. branch issue2934-postv060_0 works well on all test envs (laptops and VMs)

@zacharycmontoya
Copy link
Contributor

zacharycmontoya commented Oct 5, 2023

As an update, at least one issue is being caused by both .NET Core and .NET Framework being loaded in the same process. We have a field in the CLR Profiler called is_desktop_iis, which gets set to true when a .NET Framework runtime in an IIS process is detected. If this is set to true, then the machinery of our automatic instrumentation will not start until we hit a specific method in IIS, which will never get called in the AspNetCore app and result in no instrumentations happening.

In your latest logs_issue2934-postv060_1/logs_laptop_failed example, this was one of the causes for instrumentation not happening. @muhaook Can you go back to this setup and set CLR Version = No Managed Code in the application pool and let me know if the result changes?

@muhaook
Copy link
Author

muhaook commented Oct 6, 2023

Good news - bytecode instrumentation succeeded when CLR Version = No Managed Code. Attached please find the logs:
logs_succ.zip

Looks like this issue is caused by both .NET Core and .NET Framework being loaded in the same process. An observation is bytecode instrumentation was successful with 0.6.0 even though both .NET Core and .NET Framework got loaded in the same process there as well.

@zacharycmontoya
Copy link
Contributor

zacharycmontoya commented Oct 10, 2023

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

@nrcventura
Copy link
Member

We can carefully try to enable it again when the .NET Framework is also loaded in-process, if you think we should support that.

I think that this is a good goal to have. This type of problem can be difficult to diagnose even if we have documentation for it, so it would be nice to have it just work.

@zacharycmontoya
Copy link
Contributor

Summary
For releases v0.7.0-v1.0.2, bytecode instrumentation will only work for .NET Core applications hosted in an IIS application that is configured with No Managed Code. If the application pool is configured to load the .NET Framework, bytecode instrumentation will not start.

Next Steps

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants