Fix custom backend provider logging on Linux

release_notes.md

@@ -7,5 +7,6 @@
 - Fix issue with local RPC endpoint used by non-.NET languages on Windows apps (#1800)
 - Emit warning instead of blocking startup if Distributed Tracing is enabled, but `APPINSIGHTS_INSTRUMENTATIONKEY` isn't set (#1787),
 - Assign cloud_RoleName and operation_Name fields to RequestTelemetry to populate Activity Function's Invocations List when Distributed Tracing is enabled (#1808)
+- Fix Linux telemetry for new durablity providers (#1848)
 
 ## Breaking Changes

src/WebJobs.Extensions.DurableTask/AzureStorageDurabilityProviderFactory.cs

@@ -73,7 +73,7 @@ public AzureStorageDurabilityProviderFactory(
             this.defaultConnectionName = this.azureStorageOptions.ConnectionStringName ?? ConnectionStringNames.Storage;
         }
 
-        public string Name => ProviderName;
+        public virtual string Name => ProviderName;
 
         internal string GetDefaultStorageConnectionString()
         {

src/WebJobs.Extensions.DurableTask/EventSourceListener.cs

@@ -2,7 +2,9 @@
 // Licensed under the MIT License. See LICENSE in the project root for license information.
 
 using System;
+using System.Collections.Generic;
 using System.Diagnostics.Tracing;
+using System.Linq;
 using Microsoft.Extensions.Logging;
 
 namespace Microsoft.Azure.WebJobs.Extensions.DurableTask
@@ -18,6 +20,8 @@ internal class EventSourceListener : EventListener
         private readonly string durabilityProviderEventSourceName;
         private EndToEndTraceHelper traceHelper;
 
+        private List<EventSource> pendingEventSources = new List<EventSource>();
+
         /// <summary>
         /// Create an EventSourceListener to capture and log Durable EventSource
         /// data in Linux.
@@ -32,6 +36,16 @@ public EventSourceListener(LinuxAppServiceLogger logger, bool enableVerbose, End
             this.disableVerbose = !enableVerbose; // We track the opposite value ro simplify logic later
             this.traceHelper = traceHelper;
             this.durabilityProviderEventSourceName = durabilityProviderEventSourceName;
+
+            // Check to see if any event sources were created before we knew the event source
+            // name for the durability provider and enable that provider.
+            var eventSourcesToEnable = this.pendingEventSources.Where(eventSource => eventSource.Name == this.durabilityProviderEventSourceName);
+            foreach (var eventSource in eventSourcesToEnable)
+            {
+                this.EnableEvents(eventSource, EventLevel.LogAlways, EventKeywords.All);
+            }
+
+            this.pendingEventSources.Clear();
         }
 
         /// <summary>
@@ -51,6 +65,18 @@ protected override void OnEventSourceCreated(EventSource eventSource)
             {
                 this.EnableEvents(eventSource, EventLevel.LogAlways, EventKeywords.All);
             }
+
+            // OnEventSourceCreated is called as soon as EventListener constructor is called. In
+            // C#, base class constructors are called first, which means OnEventSourceCreated
+            // could be called before we know the durabilityProviderEventSourceName. In this case,
+            // we cache the event sources until we know the durability provider's event source name
+            // and we enable it then.
+            if (this.durabilityProviderEventSourceName == null)
+            {
+                // We may need to initialize this list as it will be null until the constructor is called.
+                this.pendingEventSources = this.pendingEventSources ?? new List<EventSource>();
+                this.pendingEventSources.Add(eventSource);
+            }
         }
 
         /// <summary>

test/Common/DurableTaskEndToEndTests.cs

@@ -13,6 +13,7 @@
 using System.Text.RegularExpressions;
 using System.Threading;
 using System.Threading.Tasks;
+using DurableTask.AzureStorage;
 using DurableTask.Core;
 using Microsoft.Azure.WebJobs.Host;
 using Microsoft.Azure.WebJobs.Host.TestCommon;
@@ -299,6 +300,55 @@ public async Task AzureStorageEmittingLogsWithEventSourceName()
             }
         }
 
+        /// <summary>
+        /// By simulating the appropiate environment variables for Linux Consumption,
+        /// this test checks that we are emitting logs from DurableTask-CustomSource
+        /// and reading the DurabilityProvider's EventSourceName property correctly.
+        /// </summary>
+        [Fact]
+        [Trait("Category", PlatformSpecificHelpers.TestCategory)]
+        public async Task CustomProviderEventSourceLogsWithEventSourceName()
+        {
+            var prefix = "MS_DURABLE_FUNCTION_EVENTS_LOGS";
+            string orchestratorName = nameof(TestOrchestrations.SayHelloInline);
+
+            // To capture console output in a StringWritter
+            using (StringWriter sw = new StringWriter())
+            {
+                // Set console to write to StringWritter
+                Console.SetOut(sw);
+
+                // Simulate enviroment variables indicating linux consumption
+                var nameResolver = new SimpleNameResolver(new Dictionary<string, string>()
+                {
+                    { "CONTAINER_NAME", "val1" },
+                    { "WEBSITE_STAMP_DEPLOYMENT_ID", "val3" },
+                    { "WEBSITE_HOME_STAMPNAME", "val4" },
+                });
+
+                // Run trivial orchestrator
+                using (var host = TestHelpers.GetJobHost(
+                    this.loggerProvider,
+                    nameResolver: nameResolver,
+                    testName: "FiltersVerboseLogsByDefault",
+                    enableExtendedSessions: false,
+                    durabilityProviderFactoryType: typeof(CustomEtwDurabilityProviderFactory)))
+                {
+                    await host.StartAsync();
+                    var client = await host.StartOrchestratorAsync(orchestratorName, input: "World", this.output);
+                    var status = await client.WaitForCompletionAsync(this.output);
+                    await host.StopAsync();
+                }
+
+                string consoleOutput = sw.ToString();
+
+                // Validate that the JSON has DurableTask-AzureStorage fields
+                string[] lines = consoleOutput.Split('\n');
+                var customeEtwLogs = lines.Where(l => l.Contains("DurableTask-CustomSource") && l.StartsWith(prefix));
+                Assert.NotEmpty(customeEtwLogs);
+            }
+        }
+
         /// <summary>
         /// By simulating the appropiate enviorment variables for Linux Consumption,
         /// this test checks that we are writing our JSON logs to the console. It does not

test/FunctionsV2/AzureStorageShortenedTimerDurabilityProviderFactory.cs

@@ -21,6 +21,8 @@ public AzureStorageShortenedTimerDurabilityProviderFactory(
         {
         }
 
+        public override string Name => typeof(AzureStorageShortenedTimerDurabilityProviderFactory).Name;
+
         public override DurabilityProvider GetDurabilityProvider(DurableClientAttribute attribute)
         {
             AzureStorageDurabilityProvider provider = base.GetDurabilityProvider(attribute) as AzureStorageDurabilityProvider;

test/FunctionsV2/CustomEtwDurabilityProviderFactory.cs

@@ -0,0 +1,47 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See LICENSE in the project root for license information.
+
+using System;
+using System.Diagnostics.Tracing;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Options;
+
+namespace Microsoft.Azure.WebJobs.Extensions.DurableTask.Tests
+{
+    internal class CustomEtwDurabilityProviderFactory : EmulatorDurabilityProviderFactory
+    {
+        public CustomEtwDurabilityProviderFactory()
+            : base()
+        {
+        }
+
+        public override string Name => typeof(CustomEtwDurabilityProviderFactory).Name;
+
+        public override DurabilityProvider GetDurabilityProvider(DurableClientAttribute attribute)
+        {
+            return this.GetDurabilityProvider();
+        }
+
+        public override DurabilityProvider GetDurabilityProvider()
+        {
+            DurabilityProvider provider = base.GetDurabilityProvider();
+            provider.EventSourceName = "DurableTask-CustomSource";
+            EtwSource.Current.Information("Created durability provider.");
+            return provider;
+        }
+    }
+
+    [EventSource(Name = "DurableTask-CustomSource")]
+#pragma warning disable SA1402 // File may only contain a single type
+    internal sealed class EtwSource : EventSource
+#pragma warning restore SA1402 // File may only contain a single type
+    {
+        public static readonly EtwSource Current = new EtwSource();
+
+        [Event(1)]
+        public void Information(string summary)
+        {
+            this.WriteEvent(1, summary);
+        }
+    }
+}

test/FunctionsV2/EmulatorDurabilityProviderFactory.cs

@@ -18,14 +18,14 @@ public EmulatorDurabilityProviderFactory()
 
         public bool SupportsEntities => false;
 
-        public string Name => "Emulator";
+        public virtual string Name => "Emulator";
 
-        public DurabilityProvider GetDurabilityProvider(DurableClientAttribute attribute)
+        public virtual DurabilityProvider GetDurabilityProvider(DurableClientAttribute attribute)
         {
             return this.provider;
         }
 
-        public DurabilityProvider GetDurabilityProvider()
+        public virtual DurabilityProvider GetDurabilityProvider()
         {
             return this.provider;
         }

test/FunctionsV2/PlatformSpecificHelpers.FunctionsV2.cs

@@ -121,7 +121,8 @@ private static IWebJobsBuilder AddDurableTask(this IWebJobsBuilder builder, IOpt
         {
             if (durabilityProviderFactoryType != null)
             {
-                builder.Services.AddSingleton(typeof(IDurabilityProviderFactory), typeof(AzureStorageShortenedTimerDurabilityProviderFactory));
+                builder.Services.AddSingleton(typeof(IDurabilityProviderFactory), durabilityProviderFactoryType);
+                options.Value.StorageProvider.Add("type", durabilityProviderFactoryType.Name);
                 builder.AddDurableTask(options);
                 return builder;
             }