ILogger integration fix for net6 when WebApplicationBuilder is used

CHANGELOG.md

@@ -31,6 +31,10 @@ This component adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.h
 
 ### Fixed
 
+- Fixed log emission issue which resulted in same logs being exported multiple
+  times for ASP.NET Core 6.0 apps when bytecode instrumentation was enabled
+  and `WebApplicationBuilder` was used.
+
 ### Security
 
 ## [1.0.2](https://github.com/open-telemetry/opentelemetry-dotnet-instrumentation/releases/tag/v1.0.2)

OpenTelemetry.AutoInstrumentation.sln

@@ -203,7 +203,9 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "TestApplication.Azure", "te
 EndProject
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "TestApplication.Wcf.Client.DotNet", "test\test-applications\integrations\TestApplication.Wcf.Client.DotNet\TestApplication.Wcf.Client.DotNet.csproj", "{EDE168E0-DBCD-4DE3-B55A-4B633ED6565E}"
 EndProject
-Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "TestApplication.Razor", "test\test-applications\integrations\TestApplication.Razor\TestApplication.Razor.csproj", "{1C76773E-2582-40DB-A720-3798E3928876}"
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "TestApplication.MinimalApi", "test\test-applications\integrations\TestApplication.MinimalApi\TestApplication.MinimalApi.csproj", "{803A3DD1-016E-4713-8066-A1C81A6ADBA3}"
+EndProject
+Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "TestApplication.Worker", "test\test-applications\integrations\TestApplication.Worker\TestApplication.Worker.csproj", "{E04065C2-0512-41C6-A428-AC85342B3D03}"
 EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
@@ -965,18 +967,30 @@ Global
 		{EDE168E0-DBCD-4DE3-B55A-4B633ED6565E}.Release|x64.Build.0 = Release|x64
 		{EDE168E0-DBCD-4DE3-B55A-4B633ED6565E}.Release|x86.ActiveCfg = Release|x86
 		{EDE168E0-DBCD-4DE3-B55A-4B633ED6565E}.Release|x86.Build.0 = Release|x86
-		{1C76773E-2582-40DB-A720-3798E3928876}.Debug|Any CPU.ActiveCfg = Debug|x64
-		{1C76773E-2582-40DB-A720-3798E3928876}.Debug|Any CPU.Build.0 = Debug|x64
-		{1C76773E-2582-40DB-A720-3798E3928876}.Debug|x64.ActiveCfg = Debug|x64
-		{1C76773E-2582-40DB-A720-3798E3928876}.Debug|x64.Build.0 = Debug|x64
-		{1C76773E-2582-40DB-A720-3798E3928876}.Debug|x86.ActiveCfg = Debug|x86
-		{1C76773E-2582-40DB-A720-3798E3928876}.Debug|x86.Build.0 = Debug|x86
-		{1C76773E-2582-40DB-A720-3798E3928876}.Release|Any CPU.ActiveCfg = Release|x64
-		{1C76773E-2582-40DB-A720-3798E3928876}.Release|Any CPU.Build.0 = Release|x64
-		{1C76773E-2582-40DB-A720-3798E3928876}.Release|x64.ActiveCfg = Release|x64
-		{1C76773E-2582-40DB-A720-3798E3928876}.Release|x64.Build.0 = Release|x64
-		{1C76773E-2582-40DB-A720-3798E3928876}.Release|x86.ActiveCfg = Release|x86
-		{1C76773E-2582-40DB-A720-3798E3928876}.Release|x86.Build.0 = Release|x86
+		{803A3DD1-016E-4713-8066-A1C81A6ADBA3}.Debug|Any CPU.ActiveCfg = Debug|x64
+		{803A3DD1-016E-4713-8066-A1C81A6ADBA3}.Debug|Any CPU.Build.0 = Debug|x64
+		{803A3DD1-016E-4713-8066-A1C81A6ADBA3}.Debug|x64.ActiveCfg = Debug|x64
+		{803A3DD1-016E-4713-8066-A1C81A6ADBA3}.Debug|x64.Build.0 = Debug|x64
+		{803A3DD1-016E-4713-8066-A1C81A6ADBA3}.Debug|x86.ActiveCfg = Debug|x86
+		{803A3DD1-016E-4713-8066-A1C81A6ADBA3}.Debug|x86.Build.0 = Debug|x86
+		{803A3DD1-016E-4713-8066-A1C81A6ADBA3}.Release|Any CPU.ActiveCfg = Release|x64
+		{803A3DD1-016E-4713-8066-A1C81A6ADBA3}.Release|Any CPU.Build.0 = Release|x64
+		{803A3DD1-016E-4713-8066-A1C81A6ADBA3}.Release|x64.ActiveCfg = Release|x64
+		{803A3DD1-016E-4713-8066-A1C81A6ADBA3}.Release|x64.Build.0 = Release|x64
+		{803A3DD1-016E-4713-8066-A1C81A6ADBA3}.Release|x86.ActiveCfg = Release|x86
+		{803A3DD1-016E-4713-8066-A1C81A6ADBA3}.Release|x86.Build.0 = Release|x86
+		{E04065C2-0512-41C6-A428-AC85342B3D03}.Debug|Any CPU.ActiveCfg = Debug|x64
+		{E04065C2-0512-41C6-A428-AC85342B3D03}.Debug|Any CPU.Build.0 = Debug|x64
+		{E04065C2-0512-41C6-A428-AC85342B3D03}.Debug|x64.ActiveCfg = Debug|x64
+		{E04065C2-0512-41C6-A428-AC85342B3D03}.Debug|x64.Build.0 = Debug|x64
+		{E04065C2-0512-41C6-A428-AC85342B3D03}.Debug|x86.ActiveCfg = Debug|x86
+		{E04065C2-0512-41C6-A428-AC85342B3D03}.Debug|x86.Build.0 = Debug|x86
+		{E04065C2-0512-41C6-A428-AC85342B3D03}.Release|Any CPU.ActiveCfg = Release|x64
+		{E04065C2-0512-41C6-A428-AC85342B3D03}.Release|Any CPU.Build.0 = Release|x64
+		{E04065C2-0512-41C6-A428-AC85342B3D03}.Release|x64.ActiveCfg = Release|x64
+		{E04065C2-0512-41C6-A428-AC85342B3D03}.Release|x64.Build.0 = Release|x64
+		{E04065C2-0512-41C6-A428-AC85342B3D03}.Release|x86.ActiveCfg = Release|x86
+		{E04065C2-0512-41C6-A428-AC85342B3D03}.Release|x86.Build.0 = Release|x86
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE
@@ -1050,7 +1064,8 @@ Global
 		{C66927FD-ED1F-4079-8733-51AB7463060D} = {E409ADD3-9574-465C-AB09-4324D205CC7C}
 		{3A125210-A784-4982-ACDB-C3442E414E44} = {E409ADD3-9574-465C-AB09-4324D205CC7C}
 		{EDE168E0-DBCD-4DE3-B55A-4B633ED6565E} = {E409ADD3-9574-465C-AB09-4324D205CC7C}
-		{1C76773E-2582-40DB-A720-3798E3928876} = {E409ADD3-9574-465C-AB09-4324D205CC7C}
+		{803A3DD1-016E-4713-8066-A1C81A6ADBA3} = {E409ADD3-9574-465C-AB09-4324D205CC7C}
+		{E04065C2-0512-41C6-A428-AC85342B3D03} = {E409ADD3-9574-465C-AB09-4324D205CC7C}
 	EndGlobalSection
 	GlobalSection(ExtensibilityGlobals) = postSolution
 		SolutionGuid = {160A1D00-1F5B-40F8-A155-621B4459D78F}

src/OpenTelemetry.AutoInstrumentation.AspNetCoreBootstrapper/BootstrapperHostingStartup.cs

@@ -60,7 +60,7 @@ public void Configure(IWebHostBuilder builder)
 
         try
         {
-            builder.ConfigureLogging(logging => logging.AddOpenTelemetryLogs());
+            builder.ConfigureLogging(logging => logging.AddOpenTelemetryLogsFromStartup());
 
             var applicationName = GetApplicationName();
             Logger.Information($"BootstrapperHostingStartup loaded for application with name {applicationName}.");

src/OpenTelemetry.AutoInstrumentation/Instrumentations/Logger/LoggingBuilderIntegration.cs

@@ -47,7 +47,7 @@ internal static CallTargetReturn OnMethodEnd<TTarget>(TTarget instance, Exceptio
         if (instance is not null)
         {
             var logBuilderExtensionsType = Type.GetType("OpenTelemetry.AutoInstrumentation.Logger.LogBuilderExtensions, OpenTelemetry.AutoInstrumentation");
-            var methodInfo = logBuilderExtensionsType?.GetMethod("AddOpenTelemetryLogs");
+            var methodInfo = logBuilderExtensionsType?.GetMethod("AddOpenTelemetryLogsFromIntegration");
             methodInfo?.Invoke(null, new[] { (object)instance });
         }
 

src/OpenTelemetry.AutoInstrumentation/Logger/LogBuilderExtensions.cs

@@ -16,6 +16,7 @@
 
 #if NET6_0_OR_GREATER
 
+using System.Reflection;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Logging;
 using OpenTelemetry.AutoInstrumentation.Configurations;
@@ -26,8 +27,35 @@ namespace OpenTelemetry.AutoInstrumentation.Logger;
 internal static class LogBuilderExtensions
 {
     private static Type? _loggingProviderSdkType;
+    private static volatile bool _hostingStartupRan;
 
-    public static ILoggingBuilder AddOpenTelemetryLogs(this ILoggingBuilder builder)
+    // this method is only called from LoggingBuilderIntegration
+    public static void AddOpenTelemetryLogsFromIntegration(ILoggingBuilder builder)
+    {
+        // For Net6, if HostingStartupAssembly is configured, we don't want to call integration again for host's ServiceCollection.
+        // OpenTelemetryLogger-related services were already added to WebApplicationServiceCollection and will
+        // be copied to host's ServiceCollection later. We can't depend on integration's
+        // capability to detect if integration was called before (by checking if ServiceDescriptor with
+        // given type is already added to ServiceCollection) as copying services from WebApplicationServiceCollection
+        // to host's ServiceCollection happens AFTER integration is called.
+
+        // All of this additional checking is NOT needed for net7. There we can rely on integration's capability
+        // to detect if integration was called before, because WebApplicationServiceCollection is not used when building host.
+
+        if (builder.Services is ServiceCollection && !(IsNet6() && _hostingStartupRan && IsHostServiceCollection(builder.Services)))
+        {
+            AddOpenTelemetryLogs(builder);
+        }
+    }
+
+    // this method is only called from BootstrapperHostingStartup
+    public static void AddOpenTelemetryLogsFromStartup(this ILoggingBuilder builder)
+    {
+        AddOpenTelemetryLogs(builder);
+        _hostingStartupRan = true;
+    }
+
+    private static ILoggingBuilder AddOpenTelemetryLogs(ILoggingBuilder builder)
     {
         try
         {
@@ -96,5 +124,44 @@ public static ILoggingBuilder AddOpenTelemetryLogs(this ILoggingBuilder builder)
 
         return builder;
     }
+
+    private static bool IsNet6()
+    {
+        var frameworkDescription = FrameworkDescription.Instance;
+        return frameworkDescription.Name == ".NET" && frameworkDescription.ProductVersion.StartsWith("6");
+    }
+
+    private static bool IsHostServiceCollection(IServiceCollection builderServices)
+    {
+        // check if assembly is loaded before trying to get type,
+        // in order to avoid triggering an unnecessary load
+        var assemblies = AppDomain.CurrentDomain.GetAssemblies();
+        var extensionsHostingAssembly = assemblies.FirstOrDefault(a => IsExtensionsHostingAssembly(a));
+        if (extensionsHostingAssembly == null)
+        {
+            return false;
+        }
+
+        var applicationLifetimeType = extensionsHostingAssembly.GetType("Microsoft.Extensions.Hosting.Internal.ApplicationLifetime");
+        if (applicationLifetimeType == null)
+        {
+            return false;
+        }
+
+        var applicationLifetimeDescriptor = builderServices.FirstOrDefault(sd => sd.ImplementationType == applicationLifetimeType);
+        return applicationLifetimeDescriptor != null;
+    }
+
+    private static bool IsExtensionsHostingAssembly(Assembly assembly)
+    {
+        const string expectedAssemblyName = "Microsoft.Extensions.Hosting";
+        var assemblyName = assembly.FullName.AsSpan();
+        if (assemblyName.Length <= expectedAssemblyName.Length)
+        {
+            return false;
+        }
+
+        return assemblyName.StartsWith(expectedAssemblyName.AsSpan()) && assemblyName[expectedAssemblyName.Length] == ',';
+    }
 }
 #endif

test/IntegrationTests/IntegrationTests.csproj

@@ -26,6 +26,7 @@
     <PackageReference Include="Testcontainers" />
     <PackageReference Include="Verify.Xunit" />
     <PackageReference Include="xunit.abstractions" />
+    <PackageReference Include="Xunit.SkippableFact" />
   </ItemGroup>
 
   <ItemGroup Condition=" '$(TargetFramework)' == 'net7.0' OR '$(TargetFramework)' == 'net6.0' ">

test/IntegrationTests/MinimalApiTests.cs

@@ -0,0 +1,91 @@
+// <copyright file="MinimalApiTests.cs" company="OpenTelemetry Authors">
+// Copyright The OpenTelemetry Authors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+// </copyright>
+
+#if NET6_0_OR_GREATER
+
+using IntegrationTests.Helpers;
+using OpenTelemetry.AutoInstrumentation;
+using OpenTelemetry.Proto.Logs.V1;
+using Xunit.Abstractions;
+using Xunit.Sdk;
+
+namespace IntegrationTests;
+
+public class MinimalApiTests : TestHelper
+{
+    public MinimalApiTests(ITestOutputHelper output)
+        : base("MinimalApi", output)
+    {
+    }
+
+    [SkippableTheory]
+    [InlineData(true, true)]
+    [InlineData(true, false)]
+    [InlineData(false, true)]
+    [Trait("Category", "EndToEnd")]
+    public async Task SubmitsLogsWithoutDuplicates(bool enableByteCodeInstrumentation, bool enableHostingStartupAssembly)
+    {
+#if NET6_0
+        Skip.If(EnvironmentTools.IsMacOS(), "Known issue on MacOS.");
+#endif
+
+        using var collector = new MockLogsCollector(Output);
+        SetExporter(collector);
+
+        SetEnvironmentVariable("OTEL_DOTNET_AUTO_LOGS_INCLUDE_FORMATTED_MESSAGE", "true");
+
+        if (enableByteCodeInstrumentation)
+        {
+            EnableBytecodeInstrumentation();
+            collector.ExpectCollected(ValidateCombinedLogsExport, "All log records should be exported once.");
+        }
+
+        if (enableHostingStartupAssembly)
+        {
+            SetEnvironmentVariable("ASPNETCORE_HOSTINGSTARTUPASSEMBLIES", "OpenTelemetry.AutoInstrumentation.AspNetCoreBootstrapper");
+            if (!enableByteCodeInstrumentation)
+            {
+                // otherwise expectation was already set
+                collector.ExpectCollected(ValidateSingleAppLogExport, "Application log records should be exported once.");
+            }
+        }
+
+        RunTestApplication();
+
+        // wait for fixed amount of time for logs to be collected before asserting
+        await Task.Delay(TimeSpan.FromSeconds(10));
+
+        collector.AssertCollected();
+    }
+
+    private static bool ValidateCombinedLogsExport(IEnumerable<LogRecord> records)
+    {
+        return ValidateSingleAppLogExport(records) && ValidateSingleBeforeHostLogRecord(records);
+    }
+
+    private static bool ValidateSingleBeforeHostLogRecord(IEnumerable<LogRecord> records)
+    {
+        var beforeHostLogCount = records.Count(lr => Convert.ToString(lr.Body) == "{ \"stringValue\": \"Logged before host is built.\" }");
+        return beforeHostLogCount == 1;
+    }
+
+    private static bool ValidateSingleAppLogExport(IEnumerable<LogRecord> records)
+    {
+        var appLogCount = records.Count(lr => Convert.ToString(lr.Body) == "{ \"stringValue\": \"Request received.\" }");
+        return appLogCount == 1;
+    }
+}
+#endif

test/IntegrationTests/LogRazorTests.cs → test/IntegrationTests/WorkerTests.cs

@@ -1,4 +1,4 @@
-// <copyright file="LogRazorTests.cs" company="OpenTelemetry Authors">
+// <copyright file="WorkerTests.cs" company="OpenTelemetry Authors">
 // Copyright The OpenTelemetry Authors
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
@@ -14,46 +14,45 @@
 // limitations under the License.
 // </copyright>
 
-#if NET6_0_OR_GREATER
 using IntegrationTests.Helpers;
+using OpenTelemetry.Proto.Logs.V1;
 using Xunit.Abstractions;
 
+#if NET6_0_OR_GREATER
+
 namespace IntegrationTests;
 
-public class LogRazorTests : TestHelper
+public class WorkerTests : TestHelper
 {
-    public LogRazorTests(ITestOutputHelper output)
-        : base("Razor", output)
+    public WorkerTests(ITestOutputHelper output)
+        : base("Worker", output)
     {
     }
 
-    [Theory]
-    [InlineData(true)]
-    [InlineData(false)]
-    [Trait("Category", "EndToEnd")]
-    public void SubmitLogs(bool enableClrProfiler)
+    [Fact]
+    public async Task SubmitsLogsWithoutDuplicates()
     {
         using var collector = new MockLogsCollector(Output);
         SetExporter(collector);
-        collector.Expect(logRecord =>
-        {
-            var logsAsString = Convert.ToString(logRecord);
-            return logsAsString != null && logsAsString.Contains("Warning from Razor App.");
-        });
-
-        if (enableClrProfiler)
-        {
-            EnableBytecodeInstrumentation();
-        }
-        else
-        {
-            SetEnvironmentVariable("ASPNETCORE_HOSTINGSTARTUPASSEMBLIES", "OpenTelemetry.AutoInstrumentation.AspNetCoreBootstrapper");
-        }
+
+        collector.ExpectCollected(ValidateSingleAppLogRecord, "App log record should be exported once.");
 
         SetEnvironmentVariable("OTEL_DOTNET_AUTO_LOGS_INCLUDE_FORMATTED_MESSAGE", "true");
+
+        EnableBytecodeInstrumentation();
+
         RunTestApplication();
 
-        collector.AssertExpectations();
+        // wait for fixed amount of time for logs to be collected before asserting
+        await Task.Delay(TimeSpan.FromSeconds(10));
+
+        collector.AssertCollected();
+    }
+
+    private static bool ValidateSingleAppLogRecord(IEnumerable<LogRecord> records)
+    {
+        return records.Count(lr => Convert.ToString(lr.Body) == "{ \"stringValue\": \"Worker running.\" }") == 1;
     }
 }
+
 #endif