adding FileLogger E2E tests; caching in FunctionTraceWriterFactory

Author: brettsam

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

@@ -48,9 +48,8 @@ internal DotNetFunctionInvoker(ScriptHost host,
             IFunctionEntryPointResolver functionEntryPointResolver,
             FunctionAssemblyLoader assemblyLoader,
             ICompilationServiceFactory<ICompilationService<IDotNetCompilation>, IFunctionMetadataResolver> compilationServiceFactory,
-            ITraceWriterFactory traceWriterFactory = null,
             IFunctionMetadataResolver metadataResolver = null)
-            : base(host, functionMetadata, traceWriterFactory)
+            : base(host, functionMetadata)
         {
             _metricsLogger = Host.ScriptConfig.HostConfig.GetService<IMetricsLogger>();
             _functionEntryPointResolver = functionEntryPointResolver;

src/WebJobs.Script/Description/FunctionInvokerBase.cs

@@ -27,15 +27,14 @@ public abstract class FunctionInvokerBase : IFunctionInvoker, IDisposable
         private IMetricsLogger _metrics;
         private IDisposable _fileChangeSubscription;
 
-        internal FunctionInvokerBase(ScriptHost host, FunctionMetadata functionMetadata, ITraceWriterFactory traceWriterFactory = null)
+        internal FunctionInvokerBase(ScriptHost host, FunctionMetadata functionMetadata)
         {
             Host = host;
             Metadata = functionMetadata;
             _metrics = host.ScriptConfig.HostConfig.GetService<IMetricsLogger>();
 
             // Function file logging is only done conditionally
-            traceWriterFactory = traceWriterFactory ?? new FunctionTraceWriterFactory(functionMetadata.Name, Host.ScriptConfig);
-            TraceWriter traceWriter = traceWriterFactory.Create();
+            TraceWriter traceWriter = host.FunctionTraceWriterFactory.Create(functionMetadata.Name);
             FileTraceWriter = traceWriter.Conditional(t => Host.FileLoggingEnabled && (!(t.Properties?.ContainsKey(ScriptConstants.TracePropertyPrimaryHostKey) ?? false) || Host.IsPrimary));
 
             // The global trace writer used by the invoker will write all traces to both
@@ -67,7 +66,7 @@ internal FunctionInvokerBase(ScriptHost host, FunctionMetadata functionMetadata,
 
         public FunctionMetadata Metadata { get; }
 
-        private TraceWriter FileTraceWriter { get; set; }
+        internal TraceWriter FileTraceWriter { get; set; }
 
         public TraceWriter TraceWriter { get; }
 

src/WebJobs.Script/Description/Node/NodeFunctionInvoker.cs

@@ -57,8 +57,8 @@ static NodeFunctionInvoker()
 
         internal NodeFunctionInvoker(ScriptHost host, BindingMetadata trigger, FunctionMetadata functionMetadata,
             Collection<FunctionBinding> inputBindings, Collection<FunctionBinding> outputBindings,
-            ICompilationService<IJavaScriptCompilation> compilationService, ITraceWriterFactory traceWriterFactory = null)
-            : base(host, functionMetadata, traceWriterFactory)
+            ICompilationService<IJavaScriptCompilation> compilationService)
+            : base(host, functionMetadata)
         {
             _trigger = trigger;
             _inputBindings = inputBindings;

src/WebJobs.Script/Description/PowerShell/PowerShellFunctionInvoker.cs

@@ -31,8 +31,8 @@ public class PowerShellFunctionInvoker : ScriptFunctionInvokerBase
         private List<string> _moduleFiles;
 
         internal PowerShellFunctionInvoker(ScriptHost host, FunctionMetadata functionMetadata,
-            Collection<FunctionBinding> inputBindings, Collection<FunctionBinding> outputBindings, ITraceWriterFactory traceWriterFactory = null)
-            : base(host, functionMetadata, traceWriterFactory)
+            Collection<FunctionBinding> inputBindings, Collection<FunctionBinding> outputBindings)
+            : base(host, functionMetadata)
         {
             _host = host;
             _scriptFilePath = functionMetadata.ScriptFile;

src/WebJobs.Script/Description/Script/ScriptFunctionInvoker.cs

@@ -26,8 +26,8 @@ public class ScriptFunctionInvoker : ScriptFunctionInvokerBase
         private readonly Collection<FunctionBinding> _outputBindings;
 
         internal ScriptFunctionInvoker(string scriptFilePath, ScriptHost host, FunctionMetadata functionMetadata,
-            Collection<FunctionBinding> inputBindings, Collection<FunctionBinding> outputBindings, ITraceWriterFactory traceWriterFactory = null)
-            : base(host, functionMetadata, traceWriterFactory)
+            Collection<FunctionBinding> inputBindings, Collection<FunctionBinding> outputBindings)
+            : base(host, functionMetadata)
         {
             _scriptFilePath = scriptFilePath;
             _host = host;

src/WebJobs.Script/Description/ScriptFunctionInvokerBase.cs

@@ -17,8 +17,8 @@ namespace Microsoft.Azure.WebJobs.Script.Description
 {
     public class ScriptFunctionInvokerBase : FunctionInvokerBase
     {
-        public ScriptFunctionInvokerBase(ScriptHost host, FunctionMetadata functionMetadata, ITraceWriterFactory traceWriterFactory)
-            : base(host, functionMetadata, traceWriterFactory)
+        public ScriptFunctionInvokerBase(ScriptHost host, FunctionMetadata functionMetadata)
+            : base(host, functionMetadata)
         {
         }
 

src/WebJobs.Script/Diagnostics/FileLogger.cs

@@ -2,7 +2,6 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
-using System.Collections.Concurrent;
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.Linq;
@@ -17,16 +16,15 @@ namespace Microsoft.Azure.WebJobs.Script.Diagnostics
     /// </summary>
     internal class FileLogger : ILogger
     {
-        private static readonly ConcurrentDictionary<string, TraceWriter> _writerCache = new ConcurrentDictionary<string, TraceWriter>();
         private readonly Func<string, LogLevel, bool> _filter;
         private readonly string _categoryName;
-        private readonly ScriptHostConfiguration _config;
+        private readonly IFunctionTraceWriterFactory _traceWriterFactory;
 
-        public FileLogger(string categoryName, ScriptHostConfiguration config, Func<string, LogLevel, bool> filter)
+        public FileLogger(string categoryName, IFunctionTraceWriterFactory traceWriterFactory, Func<string, LogLevel, bool> filter)
         {
             _categoryName = categoryName;
-            _config = config;
             _filter = filter;
+            _traceWriterFactory = traceWriterFactory;
         }
 
         public IDisposable BeginScope<TState>(TState state) => DictionaryLoggerScope.Push(state);
@@ -53,12 +51,27 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
                 return;
             }
 
+            TraceLevel traceLevel = GetTraceLevel(logLevel);
+            TraceEvent traceEvent = new TraceEvent(traceLevel, formattedMessage, _categoryName, exception);
+            string functionName = GetFunctionName();
+
+            // If we don't have a function name, we have no way to create a TraceWriter
+            if (functionName == null)
+            {
+                return;
+            }
+
+            TraceWriter traceWriter = _traceWriterFactory.Create(functionName);
+            traceWriter.Trace(traceEvent);
+        }
+
+        private static string GetFunctionName()
+        {
             IDictionary<string, object> scopeProperties = DictionaryLoggerScope.GetMergedStateDictionary();
 
             if (!scopeProperties.TryGetValue(ScriptConstants.LoggerFunctionNameKey, out string functionName))
             {
-                // We have nowhere to write the file if we don't know the function name
-                return;
+                return null;
             }
 
             // this function name starts with "Functions.", but file paths do not include this
@@ -68,20 +81,7 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
                 functionName = functionName.Substring(functionsPrefix.Length);
             }
 
-            TraceWriter traceWriter = _writerCache.GetOrAdd(functionName, (n) => CreateFileTraceWriter(n, _config));
-            TraceLevel traceLevel = GetTraceLevel(logLevel);
-            TraceEvent traceEvent = new TraceEvent(traceLevel, formattedMessage, _categoryName, exception);
-
-            traceWriter.Trace(traceEvent);
-        }
-
-        // For testing
-        internal static void FlushAllTraceWriters()
-        {
-            foreach (TraceWriter writer in _writerCache.Values)
-            {
-                writer.Flush();
-            }
+            return functionName;
         }
 
         private static TraceLevel GetTraceLevel(LogLevel logLevel)
@@ -109,11 +109,5 @@ private static bool IsFromTraceWriter(IEnumerable<KeyValuePair<string, object>>
         {
             return properties.Any(kvp => kvp.Key == ScriptConstants.TracePropertyIsUserTraceKey);
         }
-
-        private static TraceWriter CreateFileTraceWriter(string functionName, ScriptHostConfiguration scriptHostConfig)
-        {
-            ITraceWriterFactory factory = new FunctionTraceWriterFactory(functionName, scriptHostConfig);
-            return factory.Create();
-        }
     }
 }

src/WebJobs.Script/Diagnostics/FileLoggerProvider.cs

@@ -8,16 +8,16 @@ namespace Microsoft.Azure.WebJobs.Script.Diagnostics
 {
     internal class FileLoggerProvider : ILoggerProvider
     {
-        private ScriptHostConfiguration _config;
+        private IFunctionTraceWriterFactory _traceWriterFactory;
         private Func<string, LogLevel, bool> _filter;
 
-        public FileLoggerProvider(ScriptHostConfiguration config, Func<string, LogLevel, bool> filter)
+        public FileLoggerProvider(IFunctionTraceWriterFactory traceWriterFactory, Func<string, LogLevel, bool> filter)
         {
-            _config = config;
+            _traceWriterFactory = traceWriterFactory;
             _filter = filter;
         }
 
-        public ILogger CreateLogger(string categoryName) => new FileLogger(categoryName, _config, _filter);
+        public ILogger CreateLogger(string categoryName) => new FileLogger(categoryName, _traceWriterFactory, _filter);
 
         public void Dispose()
         {

src/WebJobs.Script/Diagnostics/FileTraceWriter.cs

@@ -129,7 +129,7 @@ public override void Trace(TraceEvent traceEvent)
         {
             if (traceEvent == null)
             {
-                throw new ArgumentNullException("traceEvent");
+                throw new ArgumentNullException(nameof(traceEvent));
             }
 
             object value;

src/WebJobs.Script/Diagnostics/FunctionTraceWriterFactory.cs

@@ -1,33 +1,78 @@
 // 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.Concurrent;
 using System.Diagnostics;
 using System.IO;
 using Microsoft.Azure.WebJobs.Host;
 
 namespace Microsoft.Azure.WebJobs.Script
 {
-    public sealed class FunctionTraceWriterFactory : ITraceWriterFactory
+    public sealed class FunctionTraceWriterFactory : IFunctionTraceWriterFactory
     {
-        private readonly string _functionName;
+        private readonly ConcurrentDictionary<string, TraceWriter> _writerCache = new ConcurrentDictionary<string, TraceWriter>(StringComparer.OrdinalIgnoreCase);
         private readonly ScriptHostConfiguration _scriptHostConfig;
 
-        public FunctionTraceWriterFactory(string functionName, ScriptHostConfiguration scriptHostConfig)
+        public FunctionTraceWriterFactory(ScriptHostConfiguration scriptHostConfig)
         {
-            _functionName = functionName;
             _scriptHostConfig = scriptHostConfig;
         }
 
-        public TraceWriter Create()
+        public TraceWriter Create(string functionName)
         {
             if (_scriptHostConfig.FileLoggingMode != FileLoggingMode.Never)
             {
-                TraceLevel functionTraceLevel = _scriptHostConfig.HostConfig.Tracing.ConsoleLevel;
-                string logFilePath = Path.Combine(_scriptHostConfig.RootLogPath, "Function", _functionName);
-                return new FileTraceWriter(logFilePath, functionTraceLevel);
+                return _writerCache.GetOrAdd(functionName, f => CreateTraceWriter(_scriptHostConfig, f));
             }
 
             return NullTraceWriter.Instance;
         }
+
+        private TraceWriter CreateTraceWriter(ScriptHostConfiguration config, string functionName)
+        {
+            TraceLevel functionTraceLevel = config.HostConfig.Tracing.ConsoleLevel;
+            string logFilePath = Path.Combine(config.RootLogPath, "Function", functionName);
+
+            // Wrap the FileTraceWriter in a RemovableTraceWriter so we can remove it from the cache when it is disposed
+            var innerTraceWriter = new FileTraceWriter(logFilePath, functionTraceLevel);
+            return new RemovableTraceWriter(this, functionName, innerTraceWriter);
+        }
+
+        private void RemoveTraceWriter(string functionName)
+        {
+            _writerCache.TryRemove(functionName, out TraceWriter unused);
+        }
+
+        internal class RemovableTraceWriter : TraceWriter, IDisposable
+        {
+            private readonly TraceWriter _innerWriter;
+            private readonly FunctionTraceWriterFactory _parentFactory;
+            private readonly string _functionName;
+            private bool _disposed = false;
+
+            public RemovableTraceWriter(FunctionTraceWriterFactory parentFactory, string functionName, TraceWriter innerWriter)
+                : base(innerWriter.Level)
+            {
+                _parentFactory = parentFactory;
+                _innerWriter = innerWriter;
+                _functionName = functionName;
+            }
+
+            public override void Trace(TraceEvent traceEvent)
+            {
+                _innerWriter.Trace(traceEvent);
+            }
+
+            public void Dispose()
+            {
+                if (!_disposed)
+                {
+                    _parentFactory.RemoveTraceWriter(_functionName);
+                    (_innerWriter as IDisposable)?.Dispose();
+                    _disposed = true;
+                }
+            }
+        }
     }
-}
+}