Log messages for Queue and Service Bus (#1993)

* Logging message ID for service bus and queues * Modifying UTs to include Message ID * Changing Message ID to the more generic TriggerDetails * Moving back to formatting message as string * end to end testing with pattern matching * Adding field values to fix test + lockeduntil * Adding structured logging * Adding back commented test code * Logging to understand AI test failure * Converting to generic IDictionary * Responding to CR comments
Azure · Nov 6, 2018 · 26c1bbd · 26c1bbd
1 parent 553e232
commit 26c1bbd
Show file tree

Hide file tree

Showing 18 changed files with 159 additions and 21 deletions.
diff --git a/src/Microsoft.Azure.WebJobs.Extensions.ServiceBus/Listeners/ServiceBusTriggerExecutor.cs b/src/Microsoft.Azure.WebJobs.Extensions.ServiceBus/Listeners/ServiceBusTriggerExecutor.cs
@@ -6,6 +6,7 @@
 using System.Threading.Tasks;
 using Microsoft.Azure.WebJobs.Host.Executors;
 using Microsoft.Azure.ServiceBus;
+using System.Collections.Generic;
 
 namespace Microsoft.Azure.WebJobs.ServiceBus.Listeners
 {
@@ -24,9 +25,21 @@ public async Task<FunctionResult> ExecuteAsync(Message value, CancellationToken
             TriggeredFunctionData input = new TriggeredFunctionData
             {
                 ParentId = parentId,
-                TriggerValue = value
+                TriggerValue = value,
+                TriggerDetails = PopulateTriggerDetails(value)
             };
             return await _innerExecutor.TryExecuteAsync(input, cancellationToken);
         }
+
+        private Dictionary<string, string> PopulateTriggerDetails(Message value)
+        {
+            return new Dictionary<string, string>()
+            {
+                { "MessageId", value.MessageId },
+                { "DeliveryCount", value.SystemProperties.DeliveryCount.ToString() },
+                { "EnqueuedTime", value.SystemProperties.EnqueuedTimeUtc.ToString() },
+                { "LockedUntil", value.SystemProperties.LockedUntilUtc.ToString() }
+            };
+        }
     }
 }
diff --git a/src/Microsoft.Azure.WebJobs.Extensions.Storage/Queues/Listeners/QueueTriggerExecutor.cs b/src/Microsoft.Azure.WebJobs.Extensions.Storage/Queues/Listeners/QueueTriggerExecutor.cs
@@ -2,6 +2,7 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Collections.Generic;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Azure.WebJobs.Host.Executors;
@@ -25,9 +26,20 @@ public async Task<FunctionResult> ExecuteAsync(CloudQueueMessage value, Cancella
             TriggeredFunctionData input = new TriggeredFunctionData
             {
                 ParentId = parentId,
-                TriggerValue = value
+                TriggerValue = value, 
+                TriggerDetails = PopulateTriggerDetails(value)
             };
             return await _innerExecutor.TryExecuteAsync(input, cancellationToken);
         }
+
+        private Dictionary<string, string> PopulateTriggerDetails(CloudQueueMessage value)
+        {
+            return new Dictionary<string, string>()
+            {
+                { "MessageId", value.Id.ToString() },
+                { "DequeueCount", value.DequeueCount.ToString() },
+                { "InsertionTime", value.InsertionTime.ToString() }
+            };
+        }
     }
 }
diff --git a/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs b/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs
@@ -649,6 +649,7 @@ private FunctionStartedMessage CreateStartedMessageWithoutArguments(IFunctionIns
                 FunctionInstanceId = instance.Id,
                 Function = instance.FunctionDescriptor,
                 ParentId = instance.ParentId,
+                TriggerDetails = instance.TriggerDetails,
                 Reason = instance.Reason,
                 StartTime = DateTimeOffset.UtcNow
             };
@@ -678,6 +679,7 @@ private static FunctionCompletedMessage CreateCompletedMessage(FunctionStartedMe
                 Function = startedMessage.Function,
                 Arguments = startedMessage.Arguments,
                 ParentId = startedMessage.ParentId,
+                TriggerDetails = startedMessage.TriggerDetails,
                 Reason = startedMessage.Reason,
                 ReasonDetails = startedMessage.FormatReason(),
                 StartTime = startedMessage.StartTime,

diff --git a/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionInstance.cs b/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionInstance.cs
@@ -2,23 +2,26 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Collections.Generic;
 using Microsoft.Azure.WebJobs.Host.Protocols;
 
 namespace Microsoft.Azure.WebJobs.Host.Executors
 {
     internal class FunctionInstance : IFunctionInstance
     {
         private readonly Guid _id;
+        private readonly IDictionary<string, string> _triggerDetails;
         private readonly Guid? _parentId;
         private readonly ExecutionReason _reason;
         private readonly IBindingSource _bindingSource;
         private readonly IFunctionInvoker _invoker;
         private readonly FunctionDescriptor _functionDescriptor;
 
-        public FunctionInstance(Guid id, Guid? parentId, ExecutionReason reason, IBindingSource bindingSource,
+        public FunctionInstance(Guid id, IDictionary<string, string> triggerDetails, Guid? parentId, ExecutionReason reason, IBindingSource bindingSource,
             IFunctionInvoker invoker, FunctionDescriptor functionDescriptor)
         {
             _id = id;
+            _triggerDetails = triggerDetails;
             _parentId = parentId;
             _reason = reason;
             _bindingSource = bindingSource;
@@ -31,6 +34,11 @@ public Guid Id
             get { return _id; }
         }
 
+        public IDictionary<string, string> TriggerDetails
+        {
+            get { return _triggerDetails; }
+        }
+
         public Guid? ParentId
         {
             get { return _parentId; }

diff --git a/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionInstanceFactory.cs b/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionInstanceFactory.cs
@@ -24,7 +24,7 @@ public FunctionInstanceFactory(IFunctionBinding binding, IFunctionInvoker invoke
         public IFunctionInstance Create(FunctionInstanceFactoryContext context)
         {
             IBindingSource bindingSource = new BindingSource(_binding, context.Parameters);
-            return new FunctionInstance(context.Id, context.ParentId, context.ExecutionReason, bindingSource, _invoker, _descriptor);
+            return new FunctionInstance(context.Id, context.TriggerDetails, context.ParentId, context.ExecutionReason, bindingSource, _invoker, _descriptor);
         }
     }
 }
diff --git a/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionInstanceFactoryContext.cs b/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionInstanceFactoryContext.cs
@@ -11,6 +11,7 @@ namespace Microsoft.Azure.WebJobs.Host.Executors
     public class FunctionInstanceFactoryContext
     {
         public Guid Id { get; set; }
+        public IDictionary<string, string> TriggerDetails { get; set; }
         public Guid? ParentId { get; set; }
         public ExecutionReason ExecutionReason { get; set; }
         public IDictionary<string, object> Parameters { get; set; }

diff --git a/src/Microsoft.Azure.WebJobs.Host/Executors/IFunctionInstance.cs b/src/Microsoft.Azure.WebJobs.Host/Executors/IFunctionInstance.cs
@@ -2,6 +2,7 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Collections.Generic;
 using Microsoft.Azure.WebJobs.Host.Protocols;
 
 namespace Microsoft.Azure.WebJobs.Host.Executors
@@ -10,6 +11,8 @@ public interface IFunctionInstance
     {
         Guid Id { get; }
 
+        IDictionary<string, string> TriggerDetails { get; }
+
         Guid? ParentId { get; }
 
         ExecutionReason Reason { get; }

diff --git a/src/Microsoft.Azure.WebJobs.Host/Executors/TriggeredFunctionData.cs b/src/Microsoft.Azure.WebJobs.Host/Executors/TriggeredFunctionData.cs
@@ -2,6 +2,7 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Collections.Generic;
 using System.Threading.Tasks;
 
 namespace Microsoft.Azure.WebJobs.Host.Executors
@@ -21,6 +22,11 @@ public class TriggeredFunctionData
         /// </summary>
         public object TriggerValue { get; set; }
 
+        /// <summary>
+        /// Details of the trigger (e.g. Message ID, insertion time, dequeue count etc.)
+        /// </summary>
+        public IDictionary<string, string> TriggerDetails { get; set; }
+
         /// <summary>
         /// Optional handler function for processing the invocation.
         /// </summary>

diff --git a/src/Microsoft.Azure.WebJobs.Host/Executors/TriggeredFunctionExecutor.cs b/src/Microsoft.Azure.WebJobs.Host/Executors/TriggeredFunctionExecutor.cs
@@ -35,7 +35,8 @@ public async Task<FunctionResult> TryExecuteAsync(TriggeredFunctionData input, C
             var context = new FunctionInstanceFactoryContext<TTriggerValue>()
             {
                 TriggerValue = (TTriggerValue)input.TriggerValue,
-                ParentId = input.ParentId
+                ParentId = input.ParentId, 
+                TriggerDetails = input.TriggerDetails
             };
 
             if (input.InvokeHandler != null)

diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/FunctionInstanceLogger.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/FunctionInstanceLogger.cs
@@ -2,7 +2,9 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Collections.Generic;
 using System.Globalization;
+using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Azure.WebJobs.Host.Protocols;
@@ -24,10 +26,27 @@ public Task<string> LogFunctionStartedAsync(FunctionStartedMessage message, Canc
         {
             string traceMessage = string.Format(CultureInfo.InvariantCulture, "Executing '{0}' (Reason='{1}', Id={2})", message.Function.ShortName, message.FormatReason(), message.FunctionInstanceId);
             Log(LogLevel.Information, message.Function, message.FunctionInstanceId, traceMessage);
-
+            if (message.TriggerDetails != null && message.TriggerDetails.Count != 0)
+            {
+                LogTemplatizedTriggerDetails(message);
+            }
             return Task.FromResult<string>(null);
         }
 
+        private void LogTemplatizedTriggerDetails(FunctionStartedMessage message)
+        {
+            var templateKeys = message.TriggerDetails.Select(entry => $"{entry.Key}: {{{entry.Key}}}");
+            string messageTemplate = "Trigger Details: " + string.Join(", ", templateKeys);
+            string[] templateValues = message.TriggerDetails.Values.ToArray();
+            Log(LogLevel.Information, message.Function, messageTemplate, templateValues);
+        }
+
+        private void Log(LogLevel level, FunctionDescriptor descriptor, string message, params object[] args)
+        {
+            ILogger logger = _loggerFactory?.CreateLogger(LogCategories.CreateFunctionCategory(descriptor.LogName));
+            logger?.Log(level, 0, message, args);
+        }
+
         public Task LogFunctionCompletedAsync(FunctionCompletedMessage message, CancellationToken cancellationToken)
         {
             if (message.Succeeded)

diff --git a/src/Microsoft.Azure.WebJobs.Host/Triggers/TriggeredFunctionInstanceFactory.cs b/src/Microsoft.Azure.WebJobs.Host/Triggers/TriggeredFunctionInstanceFactory.cs
@@ -33,15 +33,15 @@ public IFunctionInstance Create(FunctionInstanceFactoryContext<TTriggerValue> co
             IBindingSource bindingSource = new TriggerBindingSource<TTriggerValue>(_binding, context.TriggerValue);
             var invoker = CreateInvoker(context);
 
-            return new FunctionInstance(Guid.NewGuid(), context.ParentId, ExecutionReason.AutomaticTrigger, bindingSource, invoker, _descriptor);
+            return new FunctionInstance(Guid.NewGuid(), context.TriggerDetails, context.ParentId, ExecutionReason.AutomaticTrigger, bindingSource, invoker, _descriptor);
         }
 
         public IFunctionInstance Create(FunctionInstanceFactoryContext context)
         {
             IBindingSource bindingSource = new BindingSource(_binding, context.Parameters);
             var invoker = CreateInvoker(context);
 
-            return new FunctionInstance(context.Id, context.ParentId, context.ExecutionReason, bindingSource, invoker, _descriptor);
+            return new FunctionInstance(context.Id, context.TriggerDetails, context.ParentId, context.ExecutionReason, bindingSource, invoker, _descriptor);
         }
 
         private IFunctionInvoker CreateInvoker(FunctionInstanceFactoryContext context)

diff --git a/src/Microsoft.Azure.WebJobs.Protocols/FunctionStartedMessage.cs b/src/Microsoft.Azure.WebJobs.Protocols/FunctionStartedMessage.cs
@@ -40,6 +40,9 @@ public FunctionStartedMessage()
         /// <summary>Gets or sets the ID of the ancestor function instance.</summary>
         public Guid? ParentId { get; set; }
 
+        /// <summary>Gets or sets the details of the trigger</summary>
+        public IDictionary<string, string> TriggerDetails { get; set; }
+
         /// <summary>Gets or sets the reason the function executed.</summary>
         public ExecutionReason Reason { get; set; }
 

diff --git a/...rosoft.Azure.WebJobs.Extensions.ServiceBus.UnitTests/Listeners/ServiceBusListenerTests.cs b/...rosoft.Azure.WebJobs.Extensions.ServiceBus.UnitTests/Listeners/ServiceBusListenerTests.cs
@@ -2,6 +2,7 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Reflection;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Azure.ServiceBus;
@@ -52,6 +53,13 @@ public ServiceBusListenerTests()
         public async Task ProcessMessageAsync_Success()
         {
             var message = new CustomMessage();
+            var systemProperties = new Message.SystemPropertiesCollection();
+            typeof(Message.SystemPropertiesCollection).GetProperty("SequenceNumber").SetValue(systemProperties, 1);
+            typeof(Message.SystemPropertiesCollection).GetProperty("DeliveryCount").SetValue(systemProperties, 55);
+            typeof(Message.SystemPropertiesCollection).GetProperty("EnqueuedTimeUtc").SetValue(systemProperties, DateTime.Now);
+            typeof(Message.SystemPropertiesCollection).GetProperty("LockedUntilUtc").SetValue(systemProperties, DateTime.Now);
+            typeof(Message).GetProperty("SystemProperties").SetValue(message, systemProperties);
+
             message.MessageId = Guid.NewGuid().ToString();
             CancellationToken cancellationToken = new CancellationToken();
             _mockMessageProcessor.Setup(p => p.BeginProcessingMessageAsync(message, cancellationToken)).ReturnsAsync(true);

diff --git a/....Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/ApplicationInsightsEndToEndTests.cs b/....Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/ApplicationInsightsEndToEndTests.cs
@@ -212,7 +212,7 @@ public async Task QuickPulse_Works_EvenIfFiltered(LogLevel defaultLevel, int tra
                 int functionsCalled = 0;
                 bool keepRunning = true;
                 Task functionTask = null;
-
+                
                 try
                 {
                     listener.StartListening();
@@ -271,6 +271,8 @@ await TestHelpers.Await(() =>
                     string timestamp = $"[{t.Timestamp.ToString(_dateFormat)}] ";
                     switch (t)
                     {
+                        case DependencyTelemetry dependency:
+                            return timestamp + $"[Dependency] {dependency.Name}; {dependency.Target}; {dependency.Data}";
                         case TraceTelemetry trace:
                             return timestamp + $"[Trace] {trace.Message}";
                         case RequestTelemetry request:

diff --git a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AsyncChainEndToEndTests.cs b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AsyncChainEndToEndTests.cs
@@ -8,6 +8,7 @@
 using System.Reflection;
 using System.Runtime.ExceptionServices;
 using System.Text;
+using System.Text.RegularExpressions;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Azure.WebJobs.Host.Executors;
@@ -40,6 +41,8 @@ public class AsyncChainEndToEndTests : IClassFixture<AsyncChainEndToEndTests.Tes
         private const string Queue2Name = TestArtifactsPrefix + "q2%rnd%";
         private const string TestQueueName = TestArtifactsPrefix + "q3%rnd%";
 
+        private const string TriggerDetailsMessageStart = "Trigger Details:";
+
         private static CloudStorageAccount _storageAccount;
 
         private static RandomNameResolver _resolver;
@@ -124,8 +127,10 @@ public async Task AsyncChainEndToEnd()
                     "Function 'AsyncChainEndToEndTests.DisabledJob' is disabled",
                     "Job host started",
                     "Executing 'AsyncChainEndToEndTests.WriteStartDataMessageToQueue' (Reason='This function was programmatically called via the host APIs.', Id=",
+                    $"Trigger Details:",
                     "Executed 'AsyncChainEndToEndTests.WriteStartDataMessageToQueue' (Succeeded, Id=",
                     string.Format("Executing 'AsyncChainEndToEndTests.QueueToQueueAsync' (Reason='New queue message detected on '{0}'.', Id=", firstQueueName),
+                    $"Trigger Details:",
                     "Executed 'AsyncChainEndToEndTests.QueueToQueueAsync' (Succeeded, Id=",
                     string.Format("Executing 'AsyncChainEndToEndTests.QueueToBlobAsync' (Reason='New queue message detected on '{0}'.', Id=", secondQueueName),
                     "Executed 'AsyncChainEndToEndTests.QueueToBlobAsync' (Succeeded, Id=",
@@ -149,6 +154,17 @@ public async Task AsyncChainEndToEnd()
                 {
                     Assert.StartsWith(expectedOutputLines[i], loggerOutputLines[i]);
                 }
+
+                // Verify that trigger details are properly formatted
+                string[] triggerDetailsLoggerOutput = loggerOutputLines
+                    .Where(m => m.StartsWith(TriggerDetailsMessageStart)).ToArray();
+
+                string expectedPattern = "Trigger Details: MessageId: (.*), DequeueCount: [0-9]+, InsertionTime: (.*)";
+
+                foreach (string msg in triggerDetailsLoggerOutput)
+                {
+                    Assert.True(Regex.IsMatch(msg, expectedPattern), $"Expected trace event {expectedPattern} not found.");
+                }
             }
         }