Update function execution event log with invocation details (#8315)

Author: divyagandhisethi

src/WebJobs.Script.WebHost/Diagnostics/LinuxAppServiceEventGenerator.cs

@@ -27,6 +27,8 @@ public LinuxAppServiceEventGenerator(LinuxAppServiceFileLoggerFactory loggerFact
 
         public static string AzureMonitorEventRegex { get; } = $"{ScriptConstants.LinuxAzureMonitorEventStreamName} (?<Level>[0-6]),(?<ResourceId>[^,]*),(?<OperationName>[^,]*),(?<Category>[^,]*),(?<RegionName>[^,]*),\"(?<Properties>[^,]*)\",(?<EventTimestamp>[^,]+)";
 
+        public static string ExecutionEventRegex { get; } = "(?<executionId>[^,]*),(?<siteName>[^,]*),(?<concurrency>[^,]*),(?<functionName>[^,]*),(?<invocationId>[^,]*),(?<executionStage>[^,]*),(?<executionTimeSpan>[^,]*),(?<success>[^,]*),(?<dateTime>[^,]*)";
+
         public override void LogFunctionTraceEvent(LogLevel level, string subscriptionId, string appName, string functionName, string eventName,
             string source, string details, string summary, string exceptionType, string exceptionMessage,
             string functionInvocationId, string hostInstanceId, string activityId, string runtimeSiteName, string slotName, DateTime eventTimestamp)
@@ -66,7 +68,8 @@ public override void LogFunctionExecutionEvent(string executionId, string siteNa
         {
             var logger = _loggerFactory.GetOrCreate(FunctionsExecutionEventsCategory);
             string currentUtcTime = DateTime.UtcNow.ToString();
-            WriteEvent(logger, $"{currentUtcTime}");
+            string log = string.Join(",", executionId, siteName, concurrency.ToString(), functionName, invocationId, executionStage, executionTimeSpan.ToString(), success.ToString(), currentUtcTime);
+            WriteEvent(logger, log);
         }
 
         private static void WriteEvent(LinuxAppServiceFileLogger logger, string evt)

test/WebJobs.Script.Tests/Diagnostics/LinuxAppServiceEventGeneratorTests.cs

@@ -5,6 +5,7 @@
 using System.Collections.Generic;
 using System.Linq;
 using System.Text.RegularExpressions;
+using Microsoft.Azure.WebJobs.Script.Tests.Workers;
 using Microsoft.Azure.WebJobs.Script.WebHost;
 using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics;
 using Microsoft.Extensions.Logging;
@@ -36,7 +37,9 @@ public LinuxAppServiceEventGeneratorTests()
                 [LinuxEventGenerator.FunctionsMetricsCategory] =
                     new MockLinuxAppServiceFileLogger(LinuxEventGenerator.FunctionsMetricsCategory, string.Empty, null),
                 [LinuxEventGenerator.FunctionsDetailsCategory] =
-                    new MockLinuxAppServiceFileLogger(LinuxEventGenerator.FunctionsDetailsCategory, string.Empty, null)
+                    new MockLinuxAppServiceFileLogger(LinuxEventGenerator.FunctionsDetailsCategory, string.Empty, null),
+                [LinuxEventGenerator.FunctionsExecutionEventsCategory] =
+                    new MockLinuxAppServiceFileLogger(LinuxEventGenerator.FunctionsExecutionEventsCategory, string.Empty, null)
             };
 
             var loggerFactoryMock = new Mock<LinuxAppServiceFileLoggerFactory>(MockBehavior.Strict);
@@ -171,5 +174,32 @@ public void ParseAzureMonitoringEvents(LogLevel level, string resourceId, string
                 p => Assert.Equal(properties, UnNormalize(p)),
                 p => Assert.True(DateTime.TryParse(p, out DateTime dt)));
         }
+
+        [Theory]
+        [MemberData(nameof(LinuxEventGeneratorTestData.GetFunctionExecutionEvents), MemberType = typeof(LinuxEventGeneratorTestData))]
+        public void ParseFunctionExecutionEvents(string executionId, string siteName, int concurrency, string functionName, string invocationId,
+            string executionStage, long executionTimeSpan, bool success)
+        {
+            _generator.LogFunctionExecutionEvent(executionId, siteName, concurrency, functionName, invocationId, executionStage, executionTimeSpan, success);
+            string evt = _loggers[LinuxEventGenerator.FunctionsExecutionEventsCategory].Events.Single();
+
+            Regex regex = new Regex(LinuxAppServiceEventGenerator.ExecutionEventRegex);
+            var match = regex.Match(evt);
+
+            Assert.True(match.Success);
+            Assert.Equal(10, match.Groups.Count);
+
+            var groupMatches = match.Groups.Cast<Group>().Select(p => p.Value).Skip(1).ToArray();
+            Assert.Collection(groupMatches,
+                p => Assert.Equal(executionId, p),
+                p => Assert.Equal(siteName, p),
+                p => Assert.Equal(concurrency.ToString(), p),
+                p => Assert.Equal(functionName, p),
+                p => Assert.Equal(invocationId, p),
+                p => Assert.Equal(executionStage, p),
+                p => Assert.Equal(executionTimeSpan.ToString(), p),
+                p => Assert.True(Convert.ToBoolean(p)),
+                p => Assert.True(DateTime.TryParse(p, out DateTime dt)));
+        }
     }
 }

test/WebJobs.Script.Tests/Diagnostics/LinuxEventGeneratorTestData.cs

@@ -32,5 +32,10 @@ public static IEnumerable<object[]> GetAzureMonitorEvents()
             yield return new object[] { LogLevel.Information, "TestResourceId", "TestOperationName", "TestCategory", "TestRegionName", "TestProperties" };
             yield return new object[] { LogLevel.Information, string.Empty, string.Empty, string.Empty, string.Empty, string.Empty };
         }
+
+        public static IEnumerable<object[]> GetFunctionExecutionEvents()
+        {
+            yield return new object[] { "testexecution", "testSite", 1, "testFunction", "testInvocation", "testStage", 1, true };
+        }
     }
 }