Emit compilation errors on invocations (Azure#2710)

src/WebJobs.Script/Description/DotNet/DotNetFunctionInvoker.cs

@@ -171,16 +171,18 @@ private async Task ReloadScriptAsync()
             }
         }
 
-        internal async Task<MethodInfo> GetFunctionTargetAsync()
+        internal async Task<MethodInfo> GetFunctionTargetAsync(bool isInvocation = false)
         {
             try
             {
                 return await _functionLoader.GetFunctionTargetAsync().ConfigureAwait(false);
             }
             catch (CompilationErrorException exc)
             {
-                LogOnPrimaryHost("Function compilation error", LogLevel.Error);
-                TraceCompilationDiagnostics(exc.Diagnostics, LogTargets.User);
+                // on the invocation path we want to log detailed logs and all compilation diagnostics
+                var properties = isInvocation ? null : PrimaryHostLogProperties;
+                FunctionLogger.Log(LogLevel.Error, 0, properties, exc, (state, ex) => "Function compilation error");
+                TraceCompilationDiagnostics(exc.Diagnostics, LogTargets.User, isInvocation);
                 throw;
             }
             catch (CompilationServiceException)
@@ -245,10 +247,10 @@ internal async Task RestorePackagesAsync(bool reloadScriptOnSuccess = true)
 
         protected override async Task<object> InvokeCore(object[] parameters, FunctionInvocationContext context)
         {
+            MethodInfo function = await GetFunctionTargetAsync(isInvocation: true);
+
             // Separate system parameters from the actual method parameters
             object[] originalParameters = parameters;
-            MethodInfo function = await GetFunctionTargetAsync();
-
             int actualParameterCount = function.GetParameters().Length;
             parameters = parameters.Take(actualParameterCount).ToArray();
 

src/WebJobs.Script/Description/FunctionInvokerBase.cs

@@ -129,33 +129,43 @@ protected internal void LogOnPrimaryHost(string message, LogLevel level, Excepti
         {
             IDictionary<string, object> properties = new Dictionary<string, object>(PrimaryHostLogProperties);
 
-            FunctionLogger.Log(LogLevel.Information, 0, properties, exception, (state, ex) => message);
+            FunctionLogger.Log(level, 0, properties, exception, (state, ex) => message);
         }
 
-        internal void TraceCompilationDiagnostics(ImmutableArray<Diagnostic> diagnostics, LogTargets logTarget = LogTargets.All)
+        internal void TraceCompilationDiagnostics(ImmutableArray<Diagnostic> diagnostics, LogTargets logTarget = LogTargets.All, bool isInvocation = false)
         {
             if (logTarget == LogTargets.None)
             {
                 return;
             }
 
-            IDictionary<string, object> hostTraceProperties = PrimaryHostLogProperties;
-
+            // build the log state based on inputs
+            Dictionary<string, object> logState = new Dictionary<string, object>();
+            if (!isInvocation)
+            {
+                // generally we only want to trace compilation diagnostics on the single primary
+                // host, to avoid duplicate log statements in the case of file save operations.
+                // however if the function is being invoked, we always want to output detailed
+                // information.
+                logState.Add(ScriptConstants.LogPropertyPrimaryHostKey, true);
+            }
             if (!logTarget.HasFlag(LogTargets.User))
             {
-                hostTraceProperties = PrimaryHostSystemLogProperties;
+                logState.Add(ScriptConstants.LogPropertyIsSystemLogKey, true);
             }
             else if (!logTarget.HasFlag(LogTargets.System))
             {
-                hostTraceProperties = PrimaryHostUserLogProperties;
+                logState.Add(ScriptConstants.LogPropertyIsUserLogKey, true);
             }
 
+            // log the diagnostics
             foreach (var diagnostic in diagnostics.Where(d => !d.IsSuppressed))
             {
-                FunctionLogger.Log(diagnostic.Severity.ToLogLevel(), 0, hostTraceProperties, null, (s, e) => diagnostic.ToString());
+                FunctionLogger.Log(diagnostic.Severity.ToLogLevel(), 0, logState, null, (s, e) => diagnostic.ToString());
             }
 
-            if (Host.InDebugMode && Host.IsPrimary)
+            // log structured logs
+            if (Host.InDebugMode && (Host.IsPrimary || isInvocation))
             {
                 Host.EventManager.Publish(new StructuredLogEntryEvent(() =>
                 {

test/WebJobs.Script.Tests/Description/DotNet/DotNetFunctionInvokerTests.cs

@@ -40,9 +40,9 @@ public static IEnumerable<object[]> CompilationEnvironment
         }
 
         [Fact]
-        public async Task ReloadScript_WithInvalidCompilationAndMissingMethod_ReportsResults()
+        public async Task GetFunctionTargetAsync_CompilationError_ReportsResults()
         {
-            // Create the compilation exception we expect to throw during the reload
+            // Create the compilation exception we expect to throw
             var descriptor = new DiagnosticDescriptor(DotNetConstants.MissingFunctionEntryPointCompilationCode,
                 "Test compilation exception", "Test compilation error", "AzureFunctions", DiagnosticSeverity.Error, true);
             var exception = new CompilationErrorException("Test compilation exception", ImmutableArray.Create(Diagnostic.Create(descriptor, Location.None)));
@@ -79,25 +79,57 @@ public async Task ReloadScript_WithInvalidCompilationAndMissingMethod_ReportsRes
             var fileEventArgs = new FileSystemEventArgs(WatcherChangeTypes.Changed, Path.GetTempPath(), Path.Combine(Path.GetFileName(rootFunctionsFolder), Path.GetFileName(filePath)));
             dependencies.Host.Object.EventManager.Publish(new FileEvent(EventSources.ScriptFiles, fileEventArgs));
 
+            LogMessage[] logMessages = null;
+            var loggerProvider = dependencies.LoggerProvider;
             await TestHelpers.Await(() =>
             {
-                IEnumerable<LogMessage> logMessages = dependencies.LoggerProvider.GetAllLogMessages();
+                logMessages = loggerProvider.GetAllLogMessages().ToArray();
 
                 return logMessages.Any(t => t.FormattedMessage.Contains("Compilation failed.")) &&
-                 logMessages.Any(t => t.FormattedMessage.Contains(DotNetConstants.MissingFunctionEntryPointCompilationCode));
+                    logMessages.Any(t => t.FormattedMessage.Contains(DotNetConstants.MissingFunctionEntryPointCompilationCode));
             });
 
+            // verify expected logs when the function target is retrieved
+            // NOT on the invocation path
             dependencies.LoggerProvider.ClearAllLogMessages();
-
-            CompilationErrorException resultException = await Assert.ThrowsAsync<CompilationErrorException>(() => invoker.GetFunctionTargetAsync());
+            await Assert.ThrowsAsync<CompilationErrorException>(async () =>
+            {
+                await invoker.GetFunctionTargetAsync();
+            });
+            Assert.Equal(3, logMessages.Length);
+            Assert.Equal($"Script for function '{functionName}' changed. Reloading.", logMessages[0].FormattedMessage);
+            Assert.Equal(LogLevel.Information, logMessages[0].Level);
+            Assert.Equal("error AF001: Test compilation error", logMessages[1].FormattedMessage);
+            Assert.Equal(LogLevel.Error, logMessages[1].Level);
+            Assert.True(logMessages[1].State.Any(q => q.Key == ScriptConstants.LogPropertyIsUserLogKey));
+            Assert.Equal("Compilation failed.", logMessages[2].FormattedMessage);
+            Assert.Equal(LogLevel.Information, logMessages[2].Level);
+            Assert.True(logMessages.All(p => p.State.Any(q => q.Key == ScriptConstants.LogPropertyPrimaryHostKey)));
 
             await TestHelpers.Await(() =>
             {
-                IEnumerable<LogMessage> logMessages = dependencies.LoggerProvider.GetAllLogMessages();
+                logMessages = loggerProvider.GetAllLogMessages().ToArray();
 
                 return logMessages.Any(t => t.FormattedMessage.Contains("Function compilation error")) &&
-                 logMessages.Any(t => t.FormattedMessage.Contains(DotNetConstants.MissingFunctionEntryPointCompilationCode));
+                    logMessages.Any(t => t.FormattedMessage.Contains(DotNetConstants.MissingFunctionEntryPointCompilationCode));
+            });
+
+            // now test the invoke path and verify that the compilation error
+            // details are written
+            loggerProvider.ClearAllLogMessages();
+            await Assert.ThrowsAsync<CompilationErrorException>(async () =>
+            {
+                await invoker.GetFunctionTargetAsync(isInvocation: true);
             });
+            logMessages = loggerProvider.GetAllLogMessages().ToArray();
+            Assert.Equal(2, logMessages.Length);
+            Assert.Equal("Function compilation error", logMessages[0].FormattedMessage);
+            Assert.Equal(LogLevel.Error, logMessages[0].Level);
+            Assert.Same("Test compilation exception", logMessages[0].Exception.Message);
+            Assert.Equal("error AF001: Test compilation error", logMessages[1].FormattedMessage);
+            Assert.Equal(LogLevel.Error, logMessages[1].Level);
+            Assert.True(logMessages[1].State.Any(q => q.Key == ScriptConstants.LogPropertyIsUserLogKey));
+            Assert.True(logMessages.All(p => !(p.State != null && p.State.Any(q => q.Key == ScriptConstants.LogPropertyPrimaryHostKey))));
         }
 
         [Theory]