Fixing issue with incorrectly scoped stopwatch

Author: fabiocav

src/WebJobs.Script/Description/FunctionInvokerBase.cs

@@ -23,7 +23,6 @@ namespace Microsoft.Azure.WebJobs.Script.Description
 {
     public abstract class FunctionInvokerBase : IFunctionInvoker, IDisposable
     {
-        private readonly Stopwatch _stopwatch = new Stopwatch();
         private bool _disposed = false;
         private IMetricsLogger _metrics;
         private IDisposable _fileChangeSubscription;
@@ -126,7 +125,8 @@ public async Task Invoke(object[] parameters)
             var startedEvent = new FunctionStartedEvent(functionExecutionContext.InvocationId, Metadata);
             _metrics.BeginEvent(startedEvent);
             var invokeLatencyEvent = LogInvocationMetrics(_metrics, Metadata);
-            _stopwatch.Restart();
+            var invocationStopWatch = new Stopwatch();
+            invocationStopWatch.Start();
 
             try
             {
@@ -144,11 +144,8 @@ public async Task Invoke(object[] parameters)
 
                 await InvokeCore(parameters, context);
 
-                _stopwatch.Stop();
-
-                string completeMessage = $"Function completed (Success, Id={invocationId}, Duration={_stopwatch.ElapsedMilliseconds}ms)";
-                TraceWriter.Info(completeMessage);
-                Logger?.LogInformation(completeMessage);
+                invocationStopWatch.Stop();
+                LogFunctionResult(startedEvent, true, invocationId, invocationStopWatch.ElapsedMilliseconds);
             }
             catch (AggregateException ex)
             {
@@ -165,14 +162,14 @@ public async Task Invoke(object[] parameters)
                     exInfo = ExceptionDispatchInfo.Capture(ex);
                 }
 
-                _stopwatch.Stop();
-                LogFunctionFailed(startedEvent, "Failure", invocationId, _stopwatch.ElapsedMilliseconds);
+                invocationStopWatch.Stop();
+                LogFunctionResult(startedEvent, false, invocationId, invocationStopWatch.ElapsedMilliseconds);
                 exInfo.Throw();
             }
             catch
             {
-                _stopwatch.Stop();
-                LogFunctionFailed(startedEvent, "Failure", invocationId, _stopwatch.ElapsedMilliseconds);
+                invocationStopWatch.Stop();
+                LogFunctionResult(startedEvent, false, invocationId, invocationStopWatch.ElapsedMilliseconds);
                 throw;
             }
             finally
@@ -202,16 +199,21 @@ internal static object LogInvocationMetrics(IMetricsLogger metrics, FunctionMeta
             return metrics.BeginEvent(MetricEventNames.FunctionInvokeLatency, metadata.Name);
         }
 
-        private void LogFunctionFailed(FunctionStartedEvent startedEvent, string resultString, string invocationId, long elapsedMs)
+        private void LogFunctionResult(FunctionStartedEvent startedEvent, bool success, string invocationId, long elapsedMs)
         {
             if (startedEvent != null)
             {
-                startedEvent.Success = false;
+                startedEvent.Success = success;
             }
 
+            string resultString = success ? "Success" : "Failure";
             string message = $"Function completed ({resultString}, Id={invocationId ?? "0"}, Duration={elapsedMs}ms)";
-            TraceWriter.Error(message);
-            Logger?.LogError(message);
+
+            TraceLevel traceWriterLevel = success ? TraceLevel.Info : TraceLevel.Error;
+            LogLevel logLevel = success ? LogLevel.Information : LogLevel.Error;
+
+            TraceWriter.Trace(message, traceWriterLevel, null);
+            Logger?.Log(logLevel, new EventId(0), message, null, (s, e) => s);
         }
 
         protected TraceWriter CreateUserTraceWriter(TraceWriter traceWriter)

test/WebJobs.Script.Tests/Description/FunctionInvokerBaseTests.cs

@@ -94,15 +94,48 @@ public async Task Invoke_Success_EmitsExpectedEvents()
             Assert.Equal(startLatencyEvent, completedLatencyEvent);
         }
 
+        [Fact]
+        public async Task Invoke_EmitsExpectedDuration()
+        {
+            var executionContext = new ExecutionContext
+            {
+                InvocationId = Guid.NewGuid()
+            };
+            var parameters1 = new object[] { "Test", _traceWriter, executionContext, new InvocationData { Delay = 2000 } };
+            var parameters2 = new object[] { "Test", _traceWriter, executionContext };
+
+            Task invocation1 = _invoker.Invoke(parameters1);
+            Task invocation2 = _invoker.Invoke(parameters2);
+
+            await Task.WhenAll(invocation1, invocation2);
+
+            Assert.Equal(2, _metricsLogger.MetricEventsBegan.Count);
+            Assert.Equal(2, _metricsLogger.EventsBegan.Count);
+            Assert.Equal(2, _metricsLogger.MetricEventsEnded.Count);
+            Assert.Equal(2, _metricsLogger.EventsEnded.Count);
+
+            var completionEvents = _traceWriter.Traces
+                .Select(e => Regex.Match(e.Message, $"Function completed \\(Success, Id={executionContext.InvocationId}, Duration=(?'duration'[0-9]*)ms\\)"))
+                .Where(m => m.Success)
+                .ToList();
+
+            Assert.Equal(2, completionEvents.Count);
+            int invocation1Duration = (int.Parse(completionEvents[1].Groups["duration"].Value) / 100) * 100;
+            int invocation2Duration = (int.Parse(completionEvents[0].Groups["duration"].Value) / 100) * 100;
+
+            Assert.NotEqual(invocation1Duration, invocation2Duration);
+            Assert.Equal(2000, invocation1Duration);
+            Assert.Equal(500, invocation2Duration);
+        }
+
         [Fact]
         public async Task Invoke_Failure_EmitsExpectedEvents()
         {
             var executionContext = new ExecutionContext
             {
                 InvocationId = Guid.NewGuid()
             };
-            var parameters = new object[] { "Test", _traceWriter, executionContext };
-            _invoker.Throw = true;
+            var parameters = new object[] { "Test", _traceWriter, executionContext, new InvocationData { Throw = true } };
             await Assert.ThrowsAsync<InvalidOperationException>(async () =>
             {
                 await _invoker.Invoke(parameters);
@@ -136,16 +169,24 @@ public MockInvoker(ScriptHost host, FunctionMetadata metadata, ITraceWriterFacto
             {
             }
 
-            public bool Throw { get; set; }
-
             protected override async Task InvokeCore(object[] parameters, FunctionInvocationContext context)
             {
-                if (Throw)
+                InvocationData invocation = parameters.OfType<InvocationData>().FirstOrDefault() ?? new InvocationData();
+
+                if (invocation.Throw)
                 {
                     throw new InvalidOperationException("Kaboom!");
                 }
-                await Task.Delay(500);
+
+                await Task.Delay(invocation.Delay);
             }
         }
+
+        private class InvocationData
+        {
+            public int Delay { get; set; } = 500;
+
+            public bool Throw { get; set; }
+        }
     }
 }