Additional tracing and retries on compiler errors

Author: fabiocav

src/WebJobs.Script/Description/Compilation/CompilationServiceException.cs

@@ -0,0 +1,33 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System;
+using System.Collections.Generic;
+using System.Linq;
+using System.Runtime.Serialization;
+using System.Text;
+using System.Threading.Tasks;
+using Microsoft.CodeAnalysis.Scripting;
+
+namespace Microsoft.Azure.WebJobs.Script.Description
+{
+    [Serializable]
+    public sealed class CompilationServiceException : Exception
+    {
+        public CompilationServiceException()
+        {
+        }
+
+        public CompilationServiceException(string message) : base(message)
+        {
+        }
+
+        public CompilationServiceException(string message, Exception innerException) : base(message, innerException)
+        {
+        }
+
+        private CompilationServiceException(SerializationInfo info, StreamingContext context) : base(info, context)
+        {
+        }
+    }
+}

src/WebJobs.Script/Description/DotNet/Compilation/CSharp/CSharpCompilation.cs

@@ -91,8 +91,9 @@ private static bool IsOrUsesAssemblyType(ITypeSymbol typeSymbol, IAssemblySymbol
 
         public Assembly Emit(CancellationToken cancellationToken)
         {
-            using (var assemblyStream = new MemoryStream())
+            try
             {
+                using (var assemblyStream = new MemoryStream())
                 using (var pdbStream = new MemoryStream())
                 {
                     var compilationWithAnalyzers = _compilation.WithAnalyzers(GetAnalyzers());
@@ -114,6 +115,10 @@ public Assembly Emit(CancellationToken cancellationToken)
                     return Assembly.Load(assemblyStream.GetBuffer(), pdbStream.GetBuffer());
                 }
             }
+            catch (Exception exc) when (!(exc is CompilationErrorException))
+            {
+                throw new CompilationServiceException($"C# compilation service error: {exc.Message}", exc);
+            }
         }
 
         private static ImmutableArray<DiagnosticAnalyzer> GetAnalyzers()

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

@@ -40,6 +40,7 @@ public sealed class DotNetFunctionInvoker : FunctionInvokerBase
         private Action _restorePackages;
         private Action<MethodInfo, object[], object[], object> _resultProcessor;
         private string[] _watchedFileTypes;
+        private int _compilerErrorCount;
 
         internal DotNetFunctionInvoker(ScriptHost host,
             FunctionMetadata functionMetadata,
@@ -141,6 +142,7 @@ private async Task ReloadScriptAsync()
         {
             // Reset cached function
             _functionLoader.Reset();
+            _compilerErrorCount = 0;
             TraceOnPrimaryHost(string.Format(CultureInfo.InvariantCulture, "Script for function '{0}' changed. Reloading.", Metadata.Name), TraceLevel.Info);
 
             ImmutableArray<Diagnostic> compilationResult = ImmutableArray<Diagnostic>.Empty;
@@ -189,6 +191,24 @@ internal async Task<MethodInfo> GetFunctionTargetAsync()
                 TraceCompilationDiagnostics(exc.Diagnostics, LogTargets.User);
                 throw;
             }
+            catch (CompilationServiceException exc)
+            {
+                const string message = "Compilation service error";
+                TraceWriter.Error(message, exc, _compilationService.GetType().Name);
+                Logger?.LogError(message);
+
+                // Compiler errors are often sporadic, so we'll attempt to reset the loader here to avoid
+                // caching the compiler error and leaving the function hopelessly broken
+                if (++_compilerErrorCount < 3)
+                {
+                    _functionLoader.Reset();
+
+                    const string resetMessage = "Function loader reset. Failed compilation result will not be cached.";
+                    TraceWriter.Info(resetMessage);
+                    Logger?.LogError(resetMessage);
+                }
+                throw;
+            }
         }
 
         private void RestorePackages()
@@ -305,6 +325,8 @@ private async Task<MethodInfo> CreateFunctionTarget(CancellationToken cancellati
                     ImmutableArray<Diagnostic> bindingDiagnostics = ValidateFunctionBindingArguments(functionSignature, _triggerInputName, _inputBindings, _outputBindings, throwIfFailed: true);
                     TraceCompilationDiagnostics(bindingDiagnostics);
 
+                    _compilerErrorCount = 0;
+
                     // Set our function entry point signature
                     _functionSignature = functionSignature;
 

src/WebJobs.Script/Description/FunctionInvokerBase.cs

@@ -233,9 +233,15 @@ protected virtual void OnScriptFileChanged(FileSystemEventArgs e)
         {
         }
 
-        protected void TraceOnPrimaryHost(string message, TraceLevel level)
+        protected void TraceOnPrimaryHost(string message, TraceLevel level, string source = null,  Exception exception = null)
         {
-            TraceWriter.Trace(message, level, PrimaryHostTraceProperties);
+            var traceEvent = new TraceEvent(level, message, source, exception);
+            foreach (var item in PrimaryHostTraceProperties)
+            {
+                traceEvent.Properties.Add(item);
+            }
+
+            TraceWriter.Trace(traceEvent);
         }
 
         protected void PopulateExecutionContext(ExecutionContext context)

src/WebJobs.Script/GlobalSuppressions.cs

@@ -189,4 +189,6 @@
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.FunctionTraceWriterFactory.#CreateTraceWriter(Microsoft.Azure.WebJobs.Script.ScriptHostConfiguration,System.String)")]
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.ScriptHost.#ConfigureLoggerFactory(Microsoft.Azure.WebJobs.Script.ScriptHostConfiguration,Microsoft.Azure.WebJobs.Script.IFunctionTraceWriterFactory,Microsoft.Azure.WebJobs.Script.Config.ScriptSettingsManager,System.Func`1<System.Boolean>)")]
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.DefaultLoggerFactoryBuilder.#AddLoggerProviders(Microsoft.Extensions.Logging.ILoggerFactory,Microsoft.Azure.WebJobs.Script.ScriptHostConfiguration,Microsoft.Azure.WebJobs.Script.Config.ScriptSettingsManager)")]
+[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.Description.CSharpCompilation.#Emit(System.Threading.CancellationToken)")]
+[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.DefaultLoggerFactoryBuilder.#AddLoggerProviders(Microsoft.Extensions.Logging.ILoggerFactory,Microsoft.Azure.WebJobs.Script.ScriptHostConfiguration,Microsoft.Azure.WebJobs.Script.Config.ScriptSettingsManager)")]
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA1704:IdentifiersShouldBeSpelledCorrectly", MessageId = "Sku", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.ScriptConstants.#DynamicSkuConnectionLimit")]

src/WebJobs.Script/WebJobs.Script.csproj

@@ -415,6 +415,7 @@
     <Compile Include="Binding\SimpleValueProvider.cs" />
     <Compile Include="Config\FeatureFlags.cs" />
     <Compile Include="Description\Binding\Cardinality.cs" />
+    <Compile Include="Description\Compilation\CompilationServiceException.cs" />
     <Compile Include="Description\Compilation\ICompilation.cs" />
     <Compile Include="Description\DiagnosticSeverityExtensions.cs" />
     <Compile Include="Description\DotNet\Compilation\CSharp\Analyzers\AsyncVoidAnalyzer.cs" />

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

@@ -192,6 +192,66 @@ public void ValidateFunctionBindingArguments_ReturnBinding_Succeeds()
             Assert.Equal(0, diagnostics.Count());
         }
 
+        [Fact]
+        public async Task CompilerError_IsRetried_UpToLimit()
+        {
+            // Create the invoker dependencies and setup the appropriate method to throw the exception
+            RunDependencies dependencies = CreateDependencies();
+
+            // Set the host to primary
+            dependencies.Host.SetupGet(h => h.IsPrimary).Returns(true);
+
+            var metadata = new FunctionMetadata
+            {
+                ScriptFile = "run.csx",
+                FunctionDirectory = "c:\\somedir",
+                Name = Guid.NewGuid().ToString(),
+                ScriptType = ScriptType.CSharp
+            };
+
+            metadata.Bindings.Add(new BindingMetadata() { Name = "myQueueItem", Type = "ManualTrigger" });
+
+            var testBinding = new Mock<FunctionBinding>(null, new BindingMetadata() { Name = "TestBinding", Type = "blob" }, FileAccess.Write);
+
+            var dotNetCompilation = new Mock<IDotNetCompilation>();
+            var dotnetCompilationService = new Mock<ICompilationService<IDotNetCompilation>>();
+            dotnetCompilationService.SetupSequence(s => s.GetFunctionCompilationAsync(It.IsAny<FunctionMetadata>()))
+            .ThrowsAsync(new CompilationServiceException("1"))
+            .ThrowsAsync(new CompilationServiceException("2"))
+            .ThrowsAsync(new CompilationServiceException("3"))
+            .ThrowsAsync(new CompilationServiceException("4")); // This should not be reached
+
+            var compilationFactory = new Mock<ICompilationServiceFactory<ICompilationService<IDotNetCompilation>, IFunctionMetadataResolver>>();
+            compilationFactory.Setup(f => f.CreateService(ScriptType.CSharp, It.IsAny<IFunctionMetadataResolver>())).Returns(dotnetCompilationService.Object);
+
+            var invoker = new DotNetFunctionInvoker(dependencies.Host.Object, metadata, new Collection<FunctionBinding>(),
+                new Collection<FunctionBinding> { testBinding.Object }, new FunctionEntryPointResolver(), new FunctionAssemblyLoader(string.Empty),
+                compilationFactory.Object, new Mock<IFunctionMetadataResolver>().Object);
+
+            var arguments = new object[]
+            {
+                new ExecutionContext()
+                {
+                    FunctionDirectory = "c:\\test",
+                    FunctionName = "test",
+                    InvocationId = Guid.NewGuid()
+                }
+            };
+
+            for (int i = 1; i <= 10; i++)
+            {
+                var expectedAttempt = Math.Min(i, 3);
+                CompilationServiceException exception = await Assert.ThrowsAsync<CompilationServiceException>(() => invoker.Invoke(arguments));
+                Assert.Equal(expectedAttempt.ToString(), exception.Message);
+            }
+
+            var compilerErrorTraces = dependencies.TraceWriter.Traces
+                .Where(t => string.Equals(t.Message, "Function loader reset. Failed compilation result will not be cached."));
+
+            // 3 attempts total, make sure we've logged the 2 retries.
+            Assert.Equal(2, compilerErrorTraces.Count());
+        }
+
         [Theory]
         [InlineData(false, true, true)]
         [InlineData(false, false, false)]