Fix for sending duplicate logs when using Agentless Logging in Azure Function host

Datadog.Trace.Samples.g.sln

@@ -439,6 +439,8 @@ Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Samples.GoogleProtobuf", "t
 EndProject
 Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Samples.Quartz", "tracer\test\test-applications\integrations\Samples.Quartz\Samples.Quartz.csproj", "{CF69BC17-1527-425A-9B02-8E223BC31DB8}"
 EndProject
+Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Samples.AzureFunctions.V4Isolated.HostLogsDisabled", "tracer\test\test-applications\azure-functions\Samples.AzureFunctions.V4Isolated.HostLogsDisabled\Samples.AzureFunctions.V4Isolated.HostLogsDisabled.csproj", "{C770F9F8-0430-587D-EB7A-8BEC2FE9B61C}"
+EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
 		Debug|Any CPU = Debug|Any CPU
@@ -1057,6 +1059,10 @@ Global
 		{CF69BC17-1527-425A-9B02-8E223BC31DB8}.Debug|Any CPU.Build.0 = Debug|Any CPU
 		{CF69BC17-1527-425A-9B02-8E223BC31DB8}.Release|Any CPU.ActiveCfg = Release|Any CPU
 		{CF69BC17-1527-425A-9B02-8E223BC31DB8}.Release|Any CPU.Build.0 = Release|Any CPU
+		{C770F9F8-0430-587D-EB7A-8BEC2FE9B61C}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{C770F9F8-0430-587D-EB7A-8BEC2FE9B61C}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{C770F9F8-0430-587D-EB7A-8BEC2FE9B61C}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{C770F9F8-0430-587D-EB7A-8BEC2FE9B61C}.Release|Any CPU.Build.0 = Release|Any CPU
 	EndGlobalSection
 	GlobalSection(NestedProjects) = preSolution
 		{9518425A-36A5-4B8F-B0B8-6137DB88441D} = {8CEC2042-F11C-49F5-A674-2355793B600A}
@@ -1232,5 +1238,6 @@ Global
 		{0C0578CB-3B67-4F95-8547-206CD2A560CD} = {BAF8F246-3645-42AD-B1D0-0F7EAFBAB34A}
 		{EF8C4CCE-E79C-4D78-BF31-222A11E198B9} = {BAF8F246-3645-42AD-B1D0-0F7EAFBAB34A}
 		{CF69BC17-1527-425A-9B02-8E223BC31DB8} = {BAF8F246-3645-42AD-B1D0-0F7EAFBAB34A}
+		{C770F9F8-0430-587D-EB7A-8BEC2FE9B61C} = {C4C1E313-C7C1-4490-AECE-0DD0062380A4}
 	EndGlobalSection
 EndGlobal

Datadog.Trace.sln

@@ -617,6 +617,8 @@ Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Datadog.AzureFunctions", "t
 EndProject
 Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Samples.Quartz", "tracer\test\test-applications\integrations\Samples.Quartz\Samples.Quartz.csproj", "{CF69BC17-1527-425A-9B02-8E223BC31DB8}"
 EndProject
+Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Samples.AzureFunctions.V4Isolated.HostLogsDisabled", "tracer\test\test-applications\azure-functions\Samples.AzureFunctions.V4Isolated.HostLogsDisabled\Samples.AzureFunctions.V4Isolated.HostLogsDisabled.csproj", "{C770F9F8-0430-587D-EB7A-8BEC2FE9B61C}"
+EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
 		Debug|Any CPU = Debug|Any CPU
@@ -1489,6 +1491,10 @@ Global
 		{CF69BC17-1527-425A-9B02-8E223BC31DB8}.Debug|Any CPU.Build.0 = Debug|Any CPU
 		{CF69BC17-1527-425A-9B02-8E223BC31DB8}.Release|Any CPU.ActiveCfg = Release|Any CPU
 		{CF69BC17-1527-425A-9B02-8E223BC31DB8}.Release|Any CPU.Build.0 = Release|Any CPU
+		{C770F9F8-0430-587D-EB7A-8BEC2FE9B61C}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{C770F9F8-0430-587D-EB7A-8BEC2FE9B61C}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{C770F9F8-0430-587D-EB7A-8BEC2FE9B61C}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{C770F9F8-0430-587D-EB7A-8BEC2FE9B61C}.Release|Any CPU.Build.0 = Release|Any CPU
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE
@@ -1731,6 +1737,7 @@ Global
 		{BD7ADF79-C948-5CC7-6BE8-A7FF8DF882C3} = {E5439139-6F94-44FA-9590-C32FCC1C7A93}
 		{BB073E40-F46D-E52B-662E-395EED834111} = {9E5F0022-0A50-40BF-AC6A-C3078585ECAB}
 		{CF69BC17-1527-425A-9B02-8E223BC31DB8} = {BAF8F246-3645-42AD-B1D0-0F7EAFBAB34A}
+		{C770F9F8-0430-587D-EB7A-8BEC2FE9B61C} = {C4C1E313-C7C1-4490-AECE-0DD0062380A4}
 	EndGlobalSection
 	GlobalSection(ExtensibilityGlobals) = postSolution
 		SolutionGuid = {160A1D00-1F5B-40F8-A155-621B4459D78F}
@@ -1857,6 +1864,7 @@ Global
 		tracer\test\test-applications\Samples.Shared\Samples.Shared.projitems*{c4abf344-3263-45d5-a074-03fb206ff309}*SharedItemsImports = 5
 		tracer\test\test-applications\Samples.Shared\Samples.Shared.projitems*{c4cdf6a6-40e5-4ccd-ac4c-143f9f4398ca}*SharedItemsImports = 5
 		tracer\test\test-applications\Samples.Shared\Samples.Shared.projitems*{c5e7978a-de2a-4944-86db-4721a110e720}*SharedItemsImports = 5
+		tracer\test\test-applications\Samples.Shared\Samples.Shared.projitems*{c770f9f8-0430-587d-eb7a-8bec2fe9b61c}*SharedItemsImports = 5
 		tracer\test\test-applications\Samples.Shared\Samples.Shared.projitems*{c7de0626-9eb6-475e-aa0c-cb9de21d4fae}*SharedItemsImports = 5
 		tracer\test\test-applications\Samples.Shared\Samples.Shared.projitems*{c861221d-9c3b-441f-bbd5-343f49b9dd10}*SharedItemsImports = 4
 		tracer\test\test-applications\Samples.Shared\Samples.Shared.projitems*{c94e0739-1da0-4657-8d53-fa4143f6fda3}*SharedItemsImports = 5

tracer/src/Datadog.Trace/Configuration/ConfigurationKeys.DirectLogSubmission.cs

@@ -1,4 +1,4 @@
-// <copyright file="ConfigurationKeys.DirectLogSubmission.cs" company="Datadog">
+// <copyright file="ConfigurationKeys.DirectLogSubmission.cs" company="Datadog">
 // Unless explicitly stated otherwise all files in this repository are licensed under the Apache 2 License.
 // This product includes software developed at Datadog (https://www.datadoghq.com/). Copyright 2017 Datadog, Inc.
 // </copyright>
@@ -79,6 +79,13 @@ internal static class DirectLogSubmission
             /// </summary>
             /// <seealso cref="DirectLogSubmissionSettings.BatchPeriod"/>
             public const string BatchPeriodSeconds = "DD_LOGS_DIRECT_SUBMISSION_BATCH_PERIOD_SECONDS";
+
+            /// <summary>
+            /// Configuration key to enable or disable direct log submission for Azure Functions host.
+            /// Default value is <c>false</c>.
+            /// </summary>
+            /// <seealso cref="DirectLogSubmissionSettings.AzureFunctionsHostEnabled"/>
+            public const string AzureFunctionsHostEnabled = "DD_LOGS_DIRECT_SUBMISSION_AZURE_FUNCTIONS_HOST_ENABLED";
         }
     }
 }

tracer/src/Datadog.Trace/Logging/DirectSubmission/DirectLogSubmissionSettings.cs

@@ -14,6 +14,7 @@
 using Datadog.Trace.Configuration.Telemetry;
 using Datadog.Trace.Logging.DirectSubmission.Sink.PeriodicBatching;
 using Datadog.Trace.PlatformHelpers;
+using Datadog.Trace.Util;
 
 namespace Datadog.Trace.Logging.DirectSubmission
 {
@@ -98,6 +99,9 @@ public DirectLogSubmissionSettings(IConfigurationSource? source, IConfigurationT
 
             BatchPeriod = TimeSpan.FromSeconds(seconds);
 
+            AzureFunctionsHostEnabled = config.WithKeys(ConfigurationKeys.DirectLogSubmission.AzureFunctionsHostEnabled)
+                                              .AsBool(false);
+
             ApiKey = config.WithKeys(ConfigurationKeys.ApiKey).AsRedactedString() ?? string.Empty;
             bool[]? enabledIntegrations = null;
 
@@ -139,6 +143,13 @@ public DirectLogSubmissionSettings(IConfigurationSource? source, IConfigurationT
             var isEnabled = enabledIntegrations is not null;
             _enabledIntegrations = enabledIntegrations;
 
+            if (!AzureFunctionsHostEnabled && EnvironmentHelpers.IsRunningInAzureFunctionsHost())
+            {
+                // If we are in `dotnet-isolated` Azure Functions host customers may want to disable direct log submission
+                // because the host will re-log logs coming from the worker process causing duplicate logs.
+                isEnabled = false;
+            }
+
             if (string.IsNullOrWhiteSpace(Host))
             {
                 isEnabled = false;
@@ -230,6 +241,12 @@ public DirectLogSubmissionSettings(IConfigurationSource? source, IConfigurationT
         /// <seealso cref="ConfigurationKeys.DirectLogSubmission.BatchPeriodSeconds"/>
         internal TimeSpan BatchPeriod { get; set; }
 
+        /// <summary>
+        /// Gets a value indicating whether direct log submission is enabled for the Azure Functions host.
+        /// </summary>
+        /// <seealso cref="ConfigurationKeys.DirectLogSubmission.AzureFunctionsHostEnabled"/>
+        internal bool AzureFunctionsHostEnabled { get; } = false;
+
         /// <summary>
         /// Gets the Datadog API key
         /// </summary>

tracer/src/Datadog.Trace/Util/EnvironmentHelpers.cs

@@ -130,6 +130,32 @@ public static bool IsUsingAzureAppServicesSiteExtension()
             return GetEnvironmentVariable(ConfigurationKeys.AzureAppService.AzureAppServicesContextKey) == "1";
         }
 
+        /// <summary>
+        /// Check if the current environment is the Azure Functions host process
+        /// by checking that:
+        ///
+        /// - <see cref="IsAzureFunctions"/> is <c>true</c>
+        /// - "FUNCTIONS_WORKER_RUNTIME" is set to "dotnet-isolated"
+        /// - we DO NOT see EITHER "--functions-worker-id" or "--workerId" on the command line as flags.
+        /// The host and worker process will share the top two bullet points; however, only the worker process will have the flags
+        /// Note that his is a subset of IsAzureFunctions().
+        /// This method reads environment variables directly and bypasses the configuration system.
+        /// </summary>
+        public static bool IsRunningInAzureFunctionsHost()
+        {
+            var cmd = Environment.CommandLine ?? string.Empty;
+            // heuristic to detect the worker process
+            // the worker process would be the one to have these flags
+            // example in log output
+            // "CommandLine": "Samples.AzureFunctions.V4Isolated.AspNetCore.dll --workerId <GUID> --functions-worker-id <GUID>"
+            var hasWorkerId = cmd.IndexOf("--functions-worker-id", StringComparison.OrdinalIgnoreCase) >= 0 ||
+                              cmd.IndexOf("--workerId", StringComparison.OrdinalIgnoreCase) >= 0;
+
+            return IsAzureFunctions()
+                   && string.Equals(GetEnvironmentVariable(ConfigurationKeys.AzureFunctions.FunctionsWorkerRuntime, defaultValue: string.Empty), "dotnet-isolated", StringComparison.Ordinal)
+                   && !hasWorkerId;
+        }
+
         /// <summary>
         /// Check if the current environment is AWS Lambda
         /// by checking for the presence of "AWS_LAMBDA_FUNCTION_NAME".

tracer/test/Datadog.Trace.ClrProfiler.IntegrationTests/AzureFunctionsTests.cs

@@ -278,6 +278,14 @@ public IsolatedRuntimeV4(ITestOutputHelper output)
         [Trait("RunOnWindows", "True")]
         public async Task SubmitsTraces()
         {
+            // by default host logs are disabled e.g.,
+            // DD_LOGS_DIRECT_SUBMISSION_AZURE_FUNCTIONS_HOST_ENABLED=false
+            // so we will enable them with a lot of logging
+            SetEnvironmentVariable("DD_LOGS_DIRECT_SUBMISSION_AZURE_FUNCTIONS_HOST_ENABLED", "true");
+            SetEnvironmentVariable("DD_LOGS_DIRECT_SUBMISSION_MINIMUM_LEVEL", "VERBOSE");
+            var hostName = "integration_ilogger_az_tests";
+            using var logsIntake = new MockLogsIntake();
+            EnableDirectLogSubmission(logsIntake.Port, nameof(IntegrationId.ILogger), hostName);
             using var agent = EnvironmentHelper.GetMockAgent(useTelemetry: true);
             using (await RunAzureFunctionAndWaitForExit(agent, expectedExitCode: -1))
             {
@@ -286,10 +294,64 @@ public async Task SubmitsTraces()
                 var filteredSpans = spans.Where(s => !s.Resource.Equals("Timer ExitApp", StringComparison.OrdinalIgnoreCase)).ToImmutableList();
 
                 using var s = new AssertionScope();
-
                 await AssertIsolatedSpans(filteredSpans);
 
                 filteredSpans.Count.Should().Be(expectedSpanCount);
+
+                var logs = logsIntake.Logs;
+
+                // ~327 (ish) logs but we kill func.exe so some logs are lost
+                // and since sometimes the batch of logs can be 100+ it can be a LOT of logs that we lose
+                // so just check that we have much more than when we have host logs disabled
+                logs.Should().HaveCountGreaterThanOrEqualTo(200);
+            }
+        }
+    }
+
+    // The reason why we have a separate application here is because we run into a Singleton locking issue when
+    // we re-run the same function application in the same test session.
+    // I couldn't find a way to reset the state between test runs, so the easiest solution was to
+    // just create a separate function app.
+    [UsesVerify]
+    [Collection(nameof(AzureFunctionsTestsCollection))]
+    public class IsolatedRuntimeV4HostLogsDisabled : AzureFunctionsTests
+    {
+        public IsolatedRuntimeV4HostLogsDisabled(ITestOutputHelper output)
+            : base("AzureFunctions.V4Isolated.HostLogsDisabled", output)
+        {
+            SetEnvironmentVariable("FUNCTIONS_WORKER_RUNTIME", "dotnet-isolated");
+            SetEnvironmentVariable("FUNCTIONS_EXTENSION_VERSION", "~4");
+        }
+
+        [SkippableFact]
+        [Trait("Category", "EndToEnd")]
+        [Trait("Category", "AzureFunctions")]
+        [Trait("RunOnWindows", "True")]
+        public async Task SubmitsTraces()
+        {
+            SetEnvironmentVariable("DD_LOGS_DIRECT_SUBMISSION_AZURE_FUNCTIONS_HOST_ENABLED", "false");
+            SetEnvironmentVariable("DD_LOGS_DIRECT_SUBMISSION_MINIMUM_LEVEL", "VERBOSE");
+            var hostName = "integration_ilogger_az_tests";
+            using var logsIntake = new MockLogsIntake();
+            EnableDirectLogSubmission(logsIntake.Port, nameof(IntegrationId.ILogger), hostName);
+
+            using var agent = EnvironmentHelper.GetMockAgent(useTelemetry: true);
+            using (await RunAzureFunctionAndWaitForExit(agent, expectedExitCode: -1))
+            {
+                const int expectedSpanCount = 21;
+                var spans = await agent.WaitForSpansAsync(expectedSpanCount);
+
+                var filteredSpans = spans.Where(s => !s.Resource.Equals("Timer ExitApp", StringComparison.OrdinalIgnoreCase)).ToImmutableList();
+
+                await AssertIsolatedSpans(filteredSpans, filename: $"{nameof(AzureFunctionsTests)}.Isolated.V4.HostLogsDisabled");
+                filteredSpans.Count.Should().Be(expectedSpanCount);
+
+                var logs = logsIntake.Logs;
+                // we expect some logs still from the worker process
+                // this just seems flaky I THINK because of killing the func.exe process (even though we aren't using the host logs)
+                // commonly see 13, 14, 15, 16 logs, but IF we were logging the host logs we'd see 300+
+                logs.Should().HaveCountGreaterThan(10);
+                logs.Should().HaveCountLessThanOrEqualTo(20);
             }
         }
     }
@@ -325,6 +387,8 @@ public async Task SubmitsTraces()
                 // value so they may be removed from being traced.
                 var filteredSpans = FilterOutSocketsHttpHandler(spans);
 
+                filteredSpans = filteredSpans.Where(s => !s.Resource.Equals("Timer ExitApp", StringComparison.OrdinalIgnoreCase)).ToImmutableList();
+
                 using var s = new AssertionScope();
 
                 await AssertIsolatedSpans(filteredSpans.ToImmutableList(), $"{nameof(AzureFunctionsTests)}.Isolated.V4.AspNetCore");

tracer/test/Datadog.Trace.Tests/Telemetry/config_norm_rules.json

@@ -528,6 +528,7 @@
   "DD_LOGS_DIRECT_SUBMISSION_MAX_BATCH_SIZE": "logs_direct_submission_max_batch_size",
   "DD_LOGS_DIRECT_SUBMISSION_MAX_QUEUE_SIZE": "logs_direct_submission_max_queue_size",
   "DD_LOGS_DIRECT_SUBMISSION_BATCH_PERIOD_SECONDS": "logs_direct_submission_batch_period_seconds",
+  "DD_LOGS_DIRECT_SUBMISSION_AZURE_FUNCTIONS_HOST_ENABLED": "logs_direct_submission_azure_functions_host_enabled",
   "DD_AGENT_HOST": "agent_host",
   "DATADOG_TRACE_AGENT_HOSTNAME": "agent_host",
   "DD_TRACE_AGENT_HOSTNAME": "agent_host",

tracer/test/snapshots/AzureFunctionsTests.Isolated.V4.AspNetCore.verified.txt

@@ -317,7 +317,7 @@
 Microsoft.Azure.WebJobs.Host.FunctionInvocationException: Exception while executing function: Functions.Exception
 ---> Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcException: Result: Failure
 Exception: Task failed successfully.
-Stack:    at Samples.AzureFunctions.AllTriggers.AllTriggers.Exception(HttpRequestData req, ILogger log)
+Stack:    at Samples.AzureFunctions.AllTriggers.AllTriggers.Exception(HttpRequestData req)
 at Samples.AzureFunctions.V4Isolated.AspNetCore.DirectFunctionExecutor.ExecuteAsync(FunctionContext context),
       error.type: Microsoft.Azure.WebJobs.Host.FunctionInvocationException,
       http.method: GET,
@@ -470,7 +470,7 @@ at Samples.AzureFunctions.V4Isolated.AspNetCore.DirectFunctionExecutor.ExecuteAs
       error.msg: Task failed successfully.,
       error.stack:
 System.InvalidOperationException: Task failed successfully.
-at Samples.AzureFunctions.AllTriggers.AllTriggers.Exception(HttpRequestData req, ILogger log),
+at Samples.AzureFunctions.AllTriggers.AllTriggers.Exception(HttpRequestData req),
       error.type: System.InvalidOperationException,
       language: dotnet,
       runtime-id: Guid_1,

tracer/test/snapshots/AzureFunctionsTests.Isolated.V4.AspNetCore1.verified.txt

@@ -317,7 +317,7 @@
 Microsoft.Azure.WebJobs.Host.FunctionInvocationException: Exception while executing function: Functions.Exception
 ---> Microsoft.Azure.WebJobs.Script.Workers.Rpc.RpcException: Result: Failure
 Exception: System.InvalidOperationException: Task failed successfully.
-at Samples.AzureFunctions.AllTriggers.AllTriggers.Exception(HttpRequestData req, ILogger log),
+at Samples.AzureFunctions.AllTriggers.AllTriggers.Exception(HttpRequestData req),
       error.type: Microsoft.Azure.WebJobs.Host.FunctionInvocationException,
       http.method: GET,
       http.request.headers.host: localhost:00000,
@@ -469,7 +469,7 @@ at Samples.AzureFunctions.AllTriggers.AllTriggers.Exception(HttpRequestData req,
       error.msg: Task failed successfully.,
       error.stack:
 System.InvalidOperationException: Task failed successfully.
-at Samples.AzureFunctions.AllTriggers.AllTriggers.Exception(HttpRequestData req, ILogger log),
+at Samples.AzureFunctions.AllTriggers.AllTriggers.Exception(HttpRequestData req),
       error.type: System.InvalidOperationException,
       language: dotnet,
       runtime-id: Guid_1,