protecting against IOExceptions when flushing FileWriter

Author: brettsam

src/WebJobs.Script/Diagnostics/DefaultFileWriterFactory.cs

@@ -0,0 +1,15 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+namespace Microsoft.Azure.WebJobs.Script
+{
+    internal class DefaultFileWriterFactory : IFileWriterFactory
+    {
+        /// <summary>
+        /// Creates an IFileWriter. The caller is responsible for disposing of the IFileWriter.
+        /// </summary>
+        /// <param name="filePath">The file path.</param>
+        /// <returns>An IFileWriter.</returns>
+        public IFileWriter Create(string filePath) => new FileWriter(filePath);
+    }
+}

src/WebJobs.Script/Diagnostics/FileLogger.cs

@@ -12,14 +12,14 @@ namespace Microsoft.Azure.WebJobs.Script.Diagnostics
 {
     internal class FileLogger : ILogger
     {
-        private readonly FileWriter _fileWriter;
+        private readonly IFileWriter _fileWriter;
         private readonly Func<bool> _isFileLoggingEnabled;
         private readonly Func<bool> _isPrimary;
         private readonly string _categoryName;
         private readonly LogType _logType;
         private readonly IExternalScopeProvider _scopeProvider;
 
-        public FileLogger(string categoryName, FileWriter fileWriter, Func<bool> isFileLoggingEnabled, Func<bool> isPrimary, LogType logType, IExternalScopeProvider scopeProvider)
+        public FileLogger(string categoryName, IFileWriter fileWriter, Func<bool> isFileLoggingEnabled, Func<bool> isPrimary, LogType logType, IExternalScopeProvider scopeProvider)
         {
             _fileWriter = fileWriter;
             _isFileLoggingEnabled = isFileLoggingEnabled;
@@ -88,12 +88,20 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
             }
 
             formattedMessage = FormatLine(stateValues, logLevel, formattedMessage);
-            _fileWriter.AppendLine(formattedMessage);
 
-            // flush errors immediately
-            if (logLevel == LogLevel.Error || exception != null)
+            try
             {
-                _fileWriter.Flush();
+                _fileWriter.AppendLine(formattedMessage);
+
+                // flush errors immediately
+                if (logLevel == LogLevel.Error || exception != null)
+                {
+                    _fileWriter.Flush();
+                }
+            }
+            catch (Exception)
+            {
+                // Make sure the Logger doesn't throw if there are Exceptions (disk full, etc).
             }
         }
 

src/WebJobs.Script/Diagnostics/FileWriter.cs

@@ -13,7 +13,7 @@
 
 namespace Microsoft.Azure.WebJobs.Script
 {
-    internal class FileWriter : IDisposable
+    internal class FileWriter : IFileWriter, IDisposable
     {
         internal const int LastModifiedCutoffDays = 1;
         internal const long MaxLogFileSizeBytes = 5 * 1024 * 1024;

src/WebJobs.Script/Diagnostics/FunctionFileLoggerProvider.cs

@@ -18,27 +18,28 @@ namespace Microsoft.Azure.WebJobs.Script.Diagnostics
     /// </summary>
     internal class FunctionFileLoggerProvider : ILoggerProvider, ISupportExternalScope
     {
-        private readonly ConcurrentDictionary<string, FileWriter> _fileWriterCache = new ConcurrentDictionary<string, FileWriter>(StringComparer.OrdinalIgnoreCase);
+        private readonly ConcurrentDictionary<string, IFileWriter> _fileWriterCache = new ConcurrentDictionary<string, IFileWriter>(StringComparer.OrdinalIgnoreCase);
         private readonly Func<bool> _isFileLoggingEnabled;
         private readonly Func<bool> _isPrimary;
         private readonly string _roogLogPath;
         private readonly string _hostInstanceId;
         private static readonly Regex _workerCategoryRegex = new Regex(@"^Worker\.[^\s]+\.[^\s]+");
-
+        private readonly IFileWriterFactory _fileWriterFactory;
         private IExternalScopeProvider _scopeProvider;
         private bool _disposed = false;
 
         public FunctionFileLoggerProvider(IOptions<ScriptJobHostOptions> scriptOptions, IFileLoggingStatusManager fileLoggingStatusManager,
-            IPrimaryHostStateProvider primaryHostStateProvider)
+            IPrimaryHostStateProvider primaryHostStateProvider, IFileWriterFactory fileWriterFactory)
         {
             _roogLogPath = scriptOptions.Value.RootLogPath;
             _isFileLoggingEnabled = () => fileLoggingStatusManager.IsFileLoggingEnabled;
             _isPrimary = () => primaryHostStateProvider.IsPrimary;
             _hostInstanceId = scriptOptions.Value.InstanceId;
+            _fileWriterFactory = fileWriterFactory ?? throw new ArgumentNullException(nameof(fileWriterFactory));
         }
 
         // For testing
-        internal IDictionary<string, FileWriter> FileWriterCache => _fileWriterCache;
+        internal IDictionary<string, IFileWriter> FileWriterCache => _fileWriterCache;
 
         public ILogger CreateLogger(string categoryName)
         {
@@ -48,7 +49,7 @@ public ILogger CreateLogger(string categoryName)
             {
                 // Make sure that we return the same fileWriter if multiple loggers write to the same path. This happens
                 // with Function logs as Function.{FunctionName} and Function.{FunctionName}.User both go to the same file.
-                FileWriter fileWriter = _fileWriterCache.GetOrAdd(filePath, (p) => new FileWriter(Path.Combine(_roogLogPath, filePath)));
+                IFileWriter fileWriter = _fileWriterCache.GetOrAdd(filePath, (p) => _fileWriterFactory.Create(Path.Combine(_roogLogPath, filePath)));
                 return new FileLogger(categoryName, fileWriter, _isFileLoggingEnabled, _isPrimary, LogType.Function, _scopeProvider);
             }
 
@@ -85,9 +86,9 @@ public void Dispose()
             {
                 foreach (string fileWriterKey in _fileWriterCache.Keys)
                 {
-                    if (_fileWriterCache.TryRemove(fileWriterKey, out FileWriter fileWriter))
+                    if (_fileWriterCache.TryRemove(fileWriterKey, out IFileWriter fileWriter))
                     {
-                        fileWriter.Dispose();
+                        (fileWriter as IDisposable)?.Dispose();
                     }
                 }
 

src/WebJobs.Script/Diagnostics/HostFileLoggerProvider.cs

@@ -13,15 +13,20 @@ namespace Microsoft.Azure.WebJobs.Script.Diagnostics
     /// </summary>
     internal class HostFileLoggerProvider : ILoggerProvider, ISupportExternalScope
     {
-        private readonly FileWriter _writer;
+        private readonly IFileWriter _writer;
         private readonly Func<bool> _isFileLoggingEnabled;
 
         private bool _disposed = false;
         private IExternalScopeProvider _scopeProvider;
 
-        public HostFileLoggerProvider(IOptions<ScriptJobHostOptions> options, IFileLoggingStatusManager fileLoggingStatusManager)
+        public HostFileLoggerProvider(IOptions<ScriptJobHostOptions> options, IFileLoggingStatusManager fileLoggingStatusManager, IFileWriterFactory fileWriterFactory)
         {
-            _writer = new FileWriter(Path.Combine(options.Value.RootLogPath, "Host"));
+            if (fileWriterFactory == null)
+            {
+                throw new ArgumentNullException(nameof(fileWriterFactory));
+            }
+
+            _writer = fileWriterFactory.Create(Path.Combine(options.Value.RootLogPath, "Host"));
             _isFileLoggingEnabled = () => fileLoggingStatusManager.IsFileLoggingEnabled;
         }
 
@@ -39,7 +44,7 @@ public void Dispose()
         {
             if (!_disposed)
             {
-                _writer.Dispose();
+                (_writer as IDisposable)?.Dispose();
                 _disposed = true;
             }
         }

src/WebJobs.Script/Diagnostics/IFileWriter.cs

@@ -0,0 +1,12 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+namespace Microsoft.Azure.WebJobs.Script
+{
+    internal interface IFileWriter
+    {
+        void AppendLine(string line);
+
+        void Flush();
+    }
+}

src/WebJobs.Script/Diagnostics/IFileWriterFactory.cs

@@ -0,0 +1,10 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+namespace Microsoft.Azure.WebJobs.Script
+{
+    internal interface IFileWriterFactory
+    {
+        IFileWriter Create(string filePath);
+    }
+}

src/WebJobs.Script/ScriptHostBuilderExtensions.cs

@@ -78,6 +78,7 @@ public static IHostBuilder AddScriptHost(this IHostBuilder builder,
                 string loggingPath = ConfigurationPath.Combine(ConfigurationSectionNames.JobHost, "Logging");
                 loggingBuilder.AddConfiguration(context.Configuration.GetSection(loggingPath));
 
+                loggingBuilder.Services.AddSingleton<IFileWriterFactory, DefaultFileWriterFactory>();
                 loggingBuilder.Services.AddSingleton<ILoggerProvider, HostFileLoggerProvider>();
                 loggingBuilder.Services.AddSingleton<ILoggerProvider, FunctionFileLoggerProvider>();
 

test/WebJobs.Script.Tests.Integration/WebHostEndToEnd/DiagnosticsEndToEndTests.cs

@@ -0,0 +1,102 @@
+// 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.IO;
+using System.Linq;
+using System.Net;
+using System.Net.Http;
+using System.Threading.Tasks;
+using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics;
+using Microsoft.Azure.WebJobs.Script.WebHost.Models;
+using Microsoft.Extensions.DependencyInjection;
+using Newtonsoft.Json;
+using Xunit;
+
+namespace Microsoft.Azure.WebJobs.Script.Tests.Integration.WebHostEndToEnd
+{
+    public class DiagnosticsEndToEndTests
+    {
+        private const string _scriptRoot = @"TestScripts\CSharp";
+        private readonly string _testLogPath = Path.Combine(TestHelpers.FunctionsTestDirectory, "Logs", Guid.NewGuid().ToString(), @"Functions");
+
+        private TestEventGenerator _eventGenerator = new TestEventGenerator();
+
+        [Fact]
+        public async Task FileLogger_IOExceptionDuringInvocation_Recovers()
+        {
+            var fileWriterFactory = new TestFileWriterFactory(onAppendLine: null,
+                onFlush: () =>
+                {
+                    // The below function will fail, causing an immediate flush. This exception
+                    // simulates the disk being full. ExecutionEvents should be logged as expected
+                    // and the "Finished" event should get logged.
+                    throw new IOException();
+                });
+
+            using (var host = new TestFunctionHost(_scriptRoot, _testLogPath,
+                configureWebHostServices: s =>
+                {
+                    s.AddSingleton<IEventGenerator>(_ => _eventGenerator);
+                },
+                configureScriptHostServices: s =>
+                {
+                    s.AddSingleton<IFileWriterFactory>(_ => fileWriterFactory);
+
+                    s.PostConfigure<ScriptJobHostOptions>(o =>
+                    {
+                        o.FileLoggingMode = FileLoggingMode.Always;
+                        o.Functions = new[] { "HttpTrigger-Scenarios" };
+                    });
+                }))
+            {
+                // Issue an invalid request that fails.
+                var content = new StringContent(JsonConvert.SerializeObject(new { scenario = "invalid" }));
+                var response = await host.HttpClient.PostAsync("/api/HttpTrigger-Scenarios", content);
+                Assert.Equal(HttpStatusCode.InternalServerError, response.StatusCode);
+
+                await TestHelpers.Await(() =>
+                {
+                    var executionEvents = _eventGenerator.GetFunctionExecutionEvents();
+                    return executionEvents.SingleOrDefault(p => p.ExecutionStage == ExecutionStage.Finished) != null;
+                });
+            }
+        }
+
+        private class TestFileWriterFactory : IFileWriterFactory
+        {
+            private readonly Action<string> _onAppendLine;
+            private readonly Action _onFlush;
+
+            public TestFileWriterFactory(Action<string> onAppendLine, Action onFlush)
+            {
+                _onAppendLine = onAppendLine;
+                _onFlush = onFlush;
+            }
+
+            public IFileWriter Create(string filePath) => new TestFileWriter(_onAppendLine, _onFlush);
+        }
+
+        private class TestFileWriter : IFileWriter
+        {
+            private readonly Action<string> _onAppendLine;
+            private readonly Action _onFlush;
+
+            public TestFileWriter(Action<string> onAppendLine, Action onFlush)
+            {
+                _onAppendLine = onAppendLine;
+                _onFlush = onFlush;
+            }
+
+            public void AppendLine(string line)
+            {
+                _onAppendLine?.Invoke(line);
+            }
+
+            public void Flush()
+            {
+                _onFlush();
+            }
+        }
+    }
+}

test/WebJobs.Script.Tests.Integration/WebHostEndToEnd/SpecializationE2ETests.cs

@@ -278,7 +278,7 @@ private IWebHostBuilder CreateStandbyHostBuilder(params string[] functions)
                     // request for triggering specialization.
                     s.AddSingleton<IStandbyManager, InfiniteTimerStandbyManager>();
 
-                    s.AddSingleton<IScriptHostBuilder, PausingScriptHostBuilder>();
+                    s.AddSingleton<IScriptHostBuilder, PausingScriptHostBuilder>(); 
                 })
                 .ConfigureScriptHostServices(s =>
                 {