diff --git a/perf/Microsoft.Azure.WebJobs.Perf/app.config b/perf/Microsoft.Azure.WebJobs.Perf/app.config index 30519e41..2e6d9844 100644 --- a/perf/Microsoft.Azure.WebJobs.Perf/app.config +++ b/perf/Microsoft.Azure.WebJobs.Perf/app.config @@ -1,23 +1,23 @@ - + - - + + - - + + - - + + - - + + - + diff --git a/sample/SampleHost/App.config b/sample/SampleHost/App.config index 66d2d478..63491736 100644 --- a/sample/SampleHost/App.config +++ b/sample/SampleHost/App.config @@ -1,25 +1,25 @@ - + - + - - + + - - + + - - + + - - + + diff --git a/sample/SampleHost/Program.cs b/sample/SampleHost/Program.cs index 7e990393..52cca4dd 100644 --- a/sample/SampleHost/Program.cs +++ b/sample/SampleHost/Program.cs @@ -2,7 +2,10 @@ // Licensed under the MIT License. See License.txt in the project root for license information. using System; +using System.Diagnostics; using Microsoft.Azure.WebJobs; +using Microsoft.Azure.WebJobs.Host.Loggers; +using Microsoft.Extensions.Logging; namespace SampleHost { @@ -19,6 +22,24 @@ namespace SampleHost config.UseDevelopmentSettings(); } + config.Tracing.ConsoleLevel = TraceLevel.Off; + + // Build up a LoggerFactory to log to App Insights, but only if this key exists. + string instrumentationKey = Environment.GetEnvironmentVariable("APPINSIGHTS_INSTRUMENTATIONKEY"); + if (!string.IsNullOrEmpty(instrumentationKey)) + { + // build up log filters + LogCategoryFilter logCategoryFilter = new LogCategoryFilter(); + logCategoryFilter.DefaultLevel = LogLevel.Debug; + logCategoryFilter.CategoryLevels[LogCategories.Function] = LogLevel.Debug; + logCategoryFilter.CategoryLevels[LogCategories.Results] = LogLevel.Debug; + logCategoryFilter.CategoryLevels[LogCategories.Aggregator] = LogLevel.Debug; + + config.LoggerFactory = new LoggerFactory() + .AddApplicationInsights(instrumentationKey, logCategoryFilter.Filter) + .AddConsole(logCategoryFilter.Filter); + } + config.CreateMetadataProvider().DebugDumpGraph(Console.Out); var host = new JobHost(config); diff --git a/sample/SampleHost/SampleHost.csproj b/sample/SampleHost/SampleHost.csproj index 2f74be3c..26883425 100644 --- a/sample/SampleHost/SampleHost.csproj +++ b/sample/SampleHost/SampleHost.csproj @@ -34,18 +34,116 @@ 4 + + ..\..\packages\Microsoft.Extensions.Configuration.Abstractions.1.1.1\lib\netstandard1.0\Microsoft.Extensions.Configuration.Abstractions.dll + True + + + ..\..\packages\Microsoft.Extensions.DependencyInjection.Abstractions.1.1.0\lib\netstandard1.0\Microsoft.Extensions.DependencyInjection.Abstractions.dll + True + + + ..\..\packages\Microsoft.Extensions.Logging.1.1.1\lib\netstandard1.1\Microsoft.Extensions.Logging.dll + True + + + ..\..\packages\Microsoft.Extensions.Logging.Abstractions.1.1.1\lib\netstandard1.1\Microsoft.Extensions.Logging.Abstractions.dll + True + + + ..\..\packages\Microsoft.Extensions.Logging.Console.1.1.1\lib\net451\Microsoft.Extensions.Logging.Console.dll + True + + + ..\..\packages\Microsoft.Extensions.Primitives.1.1.0\lib\netstandard1.0\Microsoft.Extensions.Primitives.dll + True + + + ..\..\packages\Microsoft.Win32.Primitives.4.3.0\lib\net46\Microsoft.Win32.Primitives.dll + True + ..\..\packages\Newtonsoft.Json.9.0.1\lib\net45\Newtonsoft.Json.dll True + + ..\..\packages\System.AppContext.4.3.0\lib\net46\System.AppContext.dll + True + + + + ..\..\packages\System.Console.4.3.0\lib\net46\System.Console.dll + True + + + ..\..\packages\System.Diagnostics.DiagnosticSource.4.3.0\lib\net46\System.Diagnostics.DiagnosticSource.dll + True + + + ..\..\packages\System.Globalization.Calendars.4.3.0\lib\net46\System.Globalization.Calendars.dll + True + + + ..\..\packages\System.IO.Compression.4.3.0\lib\net46\System.IO.Compression.dll + True + + + + ..\..\packages\System.IO.Compression.ZipFile.4.3.0\lib\net46\System.IO.Compression.ZipFile.dll + True + + + ..\..\packages\System.IO.FileSystem.4.3.0\lib\net46\System.IO.FileSystem.dll + True + + + ..\..\packages\System.IO.FileSystem.Primitives.4.3.0\lib\net46\System.IO.FileSystem.Primitives.dll + True + + + ..\..\packages\System.Net.Http.4.3.1\lib\net46\System.Net.Http.dll + True + + + ..\..\packages\System.Net.Sockets.4.3.0\lib\net46\System.Net.Sockets.dll + True + + + + ..\..\packages\System.Runtime.CompilerServices.Unsafe.4.3.0\lib\netstandard1.0\System.Runtime.CompilerServices.Unsafe.dll + True + + + ..\..\packages\System.Runtime.InteropServices.RuntimeInformation.4.3.0\lib\net45\System.Runtime.InteropServices.RuntimeInformation.dll + True + + + ..\..\packages\System.Security.Cryptography.Algorithms.4.3.0\lib\net46\System.Security.Cryptography.Algorithms.dll + True + + + ..\..\packages\System.Security.Cryptography.Encoding.4.3.0\lib\net46\System.Security.Cryptography.Encoding.dll + True + + + ..\..\packages\System.Security.Cryptography.Primitives.4.3.0\lib\net46\System.Security.Cryptography.Primitives.dll + True + + + ..\..\packages\System.Security.Cryptography.X509Certificates.4.3.0\lib\net46\System.Security.Cryptography.X509Certificates.dll + True + - + + ..\..\packages\System.Xml.ReaderWriter.4.3.0\lib\net46\System.Xml.ReaderWriter.dll + True + diff --git a/sample/SampleHost/packages.config b/sample/SampleHost/packages.config index 9d64bf36..7cb141c5 100644 --- a/sample/SampleHost/packages.config +++ b/sample/SampleHost/packages.config @@ -1,4 +1,58 @@  + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + \ No newline at end of file diff --git a/src/Microsoft.Azure.WebJobs.Host/ApplicationInsights.config b/src/Microsoft.Azure.WebJobs.Host/ApplicationInsights.config new file mode 100644 index 00000000..75e12df9 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/ApplicationInsights.config @@ -0,0 +1,2 @@ + + \ No newline at end of file diff --git a/src/Microsoft.Azure.WebJobs.Host/Bindings/Logger/LoggerBinding.cs b/src/Microsoft.Azure.WebJobs.Host/Bindings/Logger/LoggerBinding.cs new file mode 100644 index 00000000..f2dc9f66 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Bindings/Logger/LoggerBinding.cs @@ -0,0 +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.Globalization; +using System.Reflection; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Azure.WebJobs.Host.Loggers; +using Microsoft.Azure.WebJobs.Host.Protocols; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host.Bindings +{ + internal class LoggerBinding : IBinding + { + private readonly ParameterInfo _parameter; + private readonly ILoggerFactory _loggerFactory; + + public LoggerBinding(ParameterInfo parameter, ILoggerFactory loggerFactory) + { + _parameter = parameter; + _loggerFactory = loggerFactory; + } + + public bool FromAttribute => false; + + public Task BindAsync(object value, ValueBindingContext context) + { + if (value == null || !_parameter.ParameterType.IsAssignableFrom(value.GetType())) + { + throw new InvalidOperationException(string.Format(CultureInfo.InvariantCulture, "Unable to convert value to {0}.", _parameter.ParameterType)); + } + + IValueProvider valueProvider = new ValueBinder(value, _parameter.ParameterType); + return Task.FromResult(valueProvider); + } + + public Task BindAsync(BindingContext context) + { + if (context == null) + { + throw new ArgumentNullException("context"); + } + + ILogger logger = _loggerFactory.CreateLogger(LogCategories.Function); + return BindAsync(logger, context.ValueContext); + } + + public ParameterDescriptor ToParameterDescriptor() + { + return new ParameterDescriptor + { + Name = _parameter.Name + }; + } + + private sealed class ValueBinder : IValueBinder + { + private readonly object _tracer; + private readonly Type _type; + + public ValueBinder(object tracer, Type type) + { + _tracer = tracer; + _type = type; + } + + public Type Type => _type; + + public Task GetValueAsync() => Task.FromResult(_tracer); + + public string ToInvokeString() => null; + + public Task SetValueAsync(object value, CancellationToken cancellationToken) => Task.CompletedTask; + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Bindings/Logger/LoggerBindingProvider.cs b/src/Microsoft.Azure.WebJobs.Host/Bindings/Logger/LoggerBindingProvider.cs new file mode 100644 index 00000000..681e7ad0 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Bindings/Logger/LoggerBindingProvider.cs @@ -0,0 +1,46 @@ +// 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.Reflection; +using System.Threading.Tasks; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host.Bindings +{ + /// + /// Binding provider handling bindings to . + /// + /// + /// + internal class LoggerBindingProvider : IBindingProvider + { + private ILoggerFactory _loggerFactory; + public LoggerBindingProvider(ILoggerFactory loggerFactory) + { + _loggerFactory = loggerFactory; + } + + public Task TryCreateAsync(BindingProviderContext context) + { + if (context == null) + { + throw new ArgumentNullException("context"); + } + + ParameterInfo parameter = context.Parameter; + if (parameter.ParameterType != typeof(ILogger)) + { + return Task.FromResult(null); + } + + if (_loggerFactory == null) + { + throw new ArgumentException("A parameter of type ILogger cannot be used without a registered ILoggerFactory."); + } + + IBinding binding = new LoggerBinding(parameter, _loggerFactory); + return Task.FromResult(binding); + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Bindings/TraceWriter/TraceWriterBinding.cs b/src/Microsoft.Azure.WebJobs.Host/Bindings/TraceWriter/TraceWriterBinding.cs index 1d69f7aa..74de6a7b 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Bindings/TraceWriter/TraceWriterBinding.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Bindings/TraceWriter/TraceWriterBinding.cs @@ -7,17 +7,21 @@ using System.IO; using System.Reflection; using System.Threading; using System.Threading.Tasks; +using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Protocols; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Bindings { internal class TraceWriterBinding : IBinding { private readonly ParameterInfo _parameter; + private ILoggerFactory _loggerFactory; - public TraceWriterBinding(ParameterInfo parameter) + public TraceWriterBinding(ParameterInfo parameter, ILoggerFactory loggerFactory) { _parameter = parameter; + _loggerFactory = loggerFactory; } public bool FromAttribute @@ -45,16 +49,24 @@ namespace Microsoft.Azure.WebJobs.Host.Bindings throw new ArgumentNullException("context"); } + TraceWriter trace = context.Trace; + + // If logger functionality is enabled, wrap an ILogger + if (_loggerFactory != null) + { + ILogger logger = _loggerFactory.CreateLogger(LogCategories.Function); + trace = new CompositeTraceWriter(new[] { trace, new LoggerTraceWriter(context.Trace.Level, logger) }, null, context.Trace.Level); + } + object tracer = null; if (_parameter.ParameterType == typeof(TraceWriter)) { - // bind directly to the context TraceWriter - tracer = context.Trace; + tracer = trace; } else { // bind to an adapter - tracer = TextWriterTraceAdapter.Synchronized(context.Trace); + tracer = TextWriterTraceAdapter.Synchronized(trace); } return BindAsync(tracer, context.ValueContext); diff --git a/src/Microsoft.Azure.WebJobs.Host/Bindings/TraceWriter/TraceWriterBindingProvider.cs b/src/Microsoft.Azure.WebJobs.Host/Bindings/TraceWriter/TraceWriterBindingProvider.cs index 0239dba6..c957eaf4 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Bindings/TraceWriter/TraceWriterBindingProvider.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Bindings/TraceWriter/TraceWriterBindingProvider.cs @@ -5,6 +5,7 @@ using System; using System.IO; using System.Reflection; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Bindings { @@ -15,6 +16,13 @@ namespace Microsoft.Azure.WebJobs.Host.Bindings /// internal class TraceWriterBindingProvider : IBindingProvider { + private ILoggerFactory _loggerFactory; + + public TraceWriterBindingProvider(ILoggerFactory loggerFactory) + { + _loggerFactory = loggerFactory; + } + public Task TryCreateAsync(BindingProviderContext context) { if (context == null) @@ -29,7 +37,7 @@ namespace Microsoft.Azure.WebJobs.Host.Bindings return Task.FromResult(null); } - IBinding binding = new TraceWriterBinding(parameter); + IBinding binding = new TraceWriterBinding(parameter, _loggerFactory); return Task.FromResult(binding); } } diff --git a/src/Microsoft.Azure.WebJobs.Host/Blobs/Listeners/BlobListenerFactory.cs b/src/Microsoft.Azure.WebJobs.Host/Blobs/Listeners/BlobListenerFactory.cs index 932b7ac3..be141efd 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Blobs/Listeners/BlobListenerFactory.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Blobs/Listeners/BlobListenerFactory.cs @@ -12,6 +12,7 @@ using Microsoft.Azure.WebJobs.Host.Storage; using Microsoft.Azure.WebJobs.Host.Storage.Blob; using Microsoft.Azure.WebJobs.Host.Storage.Queue; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Blobs.Listeners { @@ -26,6 +27,7 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Listeners private readonly IContextSetter _messageEnqueuedWatcherSetter; private readonly ISharedContextProvider _sharedContextProvider; private readonly TraceWriter _trace; + private readonly ILoggerFactory _loggerFactory; private readonly string _functionId; private readonly IStorageAccount _hostAccount; private readonly IStorageAccount _dataAccount; @@ -42,6 +44,7 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Listeners IContextSetter messageEnqueuedWatcherSetter, ISharedContextProvider sharedContextProvider, TraceWriter trace, + ILoggerFactory loggerFactory, string functionId, IStorageAccount hostAccount, IStorageAccount dataAccount, @@ -128,6 +131,7 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Listeners _messageEnqueuedWatcherSetter = messageEnqueuedWatcherSetter; _sharedContextProvider = sharedContextProvider; _trace = trace; + _loggerFactory = loggerFactory; _functionId = functionId; _hostAccount = hostAccount; _dataAccount = dataAccount; @@ -168,7 +172,7 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Listeners // notification queue and dispatch to the target job function. SharedBlobQueueListener sharedBlobQueueListener = _sharedContextProvider.GetOrCreateInstance( new SharedBlobQueueListenerFactory(_hostAccount, sharedQueueWatcher, hostBlobTriggerQueue, - _queueConfiguration, _exceptionHandler, _trace, sharedBlobListener.BlobWritterWatcher)); + _queueConfiguration, _exceptionHandler, _trace, _loggerFactory, sharedBlobListener.BlobWritterWatcher)); var queueListener = new BlobListener(sharedBlobQueueListener); // determine which client to use for the poison queue diff --git a/src/Microsoft.Azure.WebJobs.Host/Blobs/Listeners/SharedBlobQueueListenerFactory.cs b/src/Microsoft.Azure.WebJobs.Host/Blobs/Listeners/SharedBlobQueueListenerFactory.cs index 1c7bdc51..e8897eee 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Blobs/Listeners/SharedBlobQueueListenerFactory.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Blobs/Listeners/SharedBlobQueueListenerFactory.cs @@ -10,6 +10,7 @@ using Microsoft.Azure.WebJobs.Host.Queues.Listeners; using Microsoft.Azure.WebJobs.Host.Storage; using Microsoft.Azure.WebJobs.Host.Storage.Queue; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage.Queue; using Newtonsoft.Json; @@ -24,6 +25,7 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Listeners private readonly TraceWriter _trace; private readonly IBlobWrittenWatcher _blobWrittenWatcher; private readonly IStorageAccount _hostAccount; + private readonly ILoggerFactory _loggerFactory; public SharedBlobQueueListenerFactory( IStorageAccount hostAccount, @@ -32,6 +34,7 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Listeners IQueueConfiguration queueConfiguration, IWebJobsExceptionHandler exceptionHandler, TraceWriter trace, + ILoggerFactory loggerFactory, IBlobWrittenWatcher blobWrittenWatcher) { if (hostAccount == null) @@ -75,6 +78,7 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Listeners _queueConfiguration = queueConfiguration; _exceptionHandler = exceptionHandler; _trace = trace; + _loggerFactory = loggerFactory; _blobWrittenWatcher = blobWrittenWatcher; } @@ -93,11 +97,12 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Listeners // this special queue bypasses the QueueProcessorFactory - we don't want people to // override this - QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(_hostBlobTriggerQueue.SdkObject, _trace, _queueConfiguration, defaultPoisonQueue.SdkObject); + QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(_hostBlobTriggerQueue.SdkObject, _trace, _loggerFactory, + _queueConfiguration, defaultPoisonQueue.SdkObject); SharedBlobQueueProcessor queueProcessor = new SharedBlobQueueProcessor(context, triggerExecutor); IListener listener = new QueueListener(_hostBlobTriggerQueue, defaultPoisonQueue, triggerExecutor, - _exceptionHandler, _trace, _sharedQueueWatcher, _queueConfiguration, queueProcessor); + _exceptionHandler, _trace, _loggerFactory, _sharedQueueWatcher, _queueConfiguration, queueProcessor); return new SharedBlobQueueListener(listener, triggerExecutor); } diff --git a/src/Microsoft.Azure.WebJobs.Host/Blobs/Triggers/BlobTriggerAttributeBindingProvider.cs b/src/Microsoft.Azure.WebJobs.Host/Blobs/Triggers/BlobTriggerAttributeBindingProvider.cs index 6f1a4d97..679d89d4 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Blobs/Triggers/BlobTriggerAttributeBindingProvider.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Blobs/Triggers/BlobTriggerAttributeBindingProvider.cs @@ -8,7 +8,6 @@ using System.Linq; using System.Reflection; using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host.Bindings; -using Microsoft.Azure.WebJobs.Host.Converters; using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Indexers; using Microsoft.Azure.WebJobs.Host.Listeners; @@ -17,6 +16,7 @@ using Microsoft.Azure.WebJobs.Host.Storage; using Microsoft.Azure.WebJobs.Host.Storage.Blob; using Microsoft.Azure.WebJobs.Host.Timers; using Microsoft.Azure.WebJobs.Host.Triggers; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage.Blob; namespace Microsoft.Azure.WebJobs.Host.Blobs.Triggers @@ -35,6 +35,7 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Triggers private readonly ISharedContextProvider _sharedContextProvider; private readonly SingletonManager _singletonManager; private readonly TraceWriter _trace; + private readonly ILoggerFactory _loggerFactory; public BlobTriggerAttributeBindingProvider(INameResolver nameResolver, IStorageAccountProvider accountProvider, @@ -47,7 +48,8 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Triggers IContextSetter messageEnqueuedWatcherSetter, ISharedContextProvider sharedContextProvider, SingletonManager singletonManager, - TraceWriter trace) + TraceWriter trace, + ILoggerFactory loggerFactory) { if (accountProvider == null) { @@ -116,6 +118,7 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Triggers _sharedContextProvider = sharedContextProvider; _singletonManager = singletonManager; _trace = trace; + _loggerFactory = loggerFactory; } private static IBlobArgumentBindingProvider CreateProvider(IEnumerable cloudBlobStreamBinderTypes) @@ -172,7 +175,7 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Triggers ITriggerBinding binding = new BlobTriggerBinding(parameter, argumentBinding, hostAccount, dataAccount, path, _hostIdProvider, _queueConfiguration, _blobsConfiguration, _exceptionHandler, _blobWrittenWatcherSetter, - _messageEnqueuedWatcherSetter, _sharedContextProvider, _singletonManager, _trace); + _messageEnqueuedWatcherSetter, _sharedContextProvider, _singletonManager, _trace, _loggerFactory); return binding; } diff --git a/src/Microsoft.Azure.WebJobs.Host/Blobs/Triggers/BlobTriggerBinding.cs b/src/Microsoft.Azure.WebJobs.Host/Blobs/Triggers/BlobTriggerBinding.cs index bae87782..cfd8277c 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Blobs/Triggers/BlobTriggerBinding.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Blobs/Triggers/BlobTriggerBinding.cs @@ -17,6 +17,7 @@ using Microsoft.Azure.WebJobs.Host.Storage; using Microsoft.Azure.WebJobs.Host.Storage.Blob; using Microsoft.Azure.WebJobs.Host.Timers; using Microsoft.Azure.WebJobs.Host.Triggers; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage.Blob; namespace Microsoft.Azure.WebJobs.Host.Blobs.Triggers @@ -38,6 +39,7 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Triggers private readonly IContextSetter _messageEnqueuedWatcherSetter; private readonly ISharedContextProvider _sharedContextProvider; private readonly TraceWriter _trace; + private readonly ILoggerFactory _loggerFactory; private readonly IAsyncObjectToTypeConverter _converter; private readonly IReadOnlyDictionary _bindingDataContract; private readonly SingletonManager _singletonManager; @@ -55,7 +57,8 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Triggers IContextSetter messageEnqueuedWatcherSetter, ISharedContextProvider sharedContextProvider, SingletonManager singletonManager, - TraceWriter trace) + TraceWriter trace, + ILoggerFactory loggerFactory) { if (parameter == null) { @@ -147,6 +150,7 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Triggers _sharedContextProvider = sharedContextProvider; _singletonManager = singletonManager; _trace = trace; + _loggerFactory = loggerFactory; _converter = CreateConverter(_blobClient); _bindingDataContract = CreateBindingDataContract(path); } @@ -263,9 +267,9 @@ namespace Microsoft.Azure.WebJobs.Host.Blobs.Triggers IStorageBlobContainer container = _blobClient.GetContainerReference(_path.ContainerNamePattern); - var factory = new BlobListenerFactory(_hostIdProvider, _queueConfiguration, _blobsConfiguration, - _exceptionHandler, _blobWrittenWatcherSetter, _messageEnqueuedWatcherSetter, - _sharedContextProvider, _trace, context.Descriptor.Id, _hostAccount, _dataAccount, container, _path, context.Executor, _singletonManager); + var factory = new BlobListenerFactory(_hostIdProvider, _queueConfiguration, _blobsConfiguration, _exceptionHandler, + _blobWrittenWatcherSetter, _messageEnqueuedWatcherSetter, _sharedContextProvider, _trace, _loggerFactory, + context.Descriptor.Id, _hostAccount, _dataAccount, container, _path, context.Executor, _singletonManager); return factory.CreateAsync(context.CancellationToken); } diff --git a/src/Microsoft.Azure.WebJobs.Host/Exceptions/RecoverableException.cs b/src/Microsoft.Azure.WebJobs.Host/Exceptions/RecoverableException.cs index 549ad30d..702c86d5 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Exceptions/RecoverableException.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Exceptions/RecoverableException.cs @@ -3,6 +3,7 @@ using System; using System.Runtime.Serialization; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host { @@ -71,7 +72,8 @@ namespace Microsoft.Azure.WebJobs.Host /// Recovers if exception is handled by trace pipeline, else throws. /// /// - internal void TryRecover(TraceWriter trace) + /// + internal void TryRecover(TraceWriter trace, ILogger logger) { if (trace == null) { @@ -79,6 +81,7 @@ namespace Microsoft.Azure.WebJobs.Host } trace.Error(Message, this); + logger?.LogError(0, this, Message); if (!Handled) { throw this; diff --git a/src/Microsoft.Azure.WebJobs.Host/Executors/CompositeFunctionEventCollector.cs b/src/Microsoft.Azure.WebJobs.Host/Executors/CompositeFunctionEventCollector.cs new file mode 100644 index 00000000..6483d594 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Executors/CompositeFunctionEventCollector.cs @@ -0,0 +1,36 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using System.Collections.Generic; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Azure.WebJobs.Host.Loggers; + +namespace Microsoft.Azure.WebJobs.Host.Executors +{ + internal class CompositeFunctionEventCollector : IAsyncCollector + { + private IEnumerable> _collectors; + + public CompositeFunctionEventCollector(params IAsyncCollector[] collectors) + { + _collectors = collectors; + } + + public async Task AddAsync(FunctionInstanceLogEntry item, CancellationToken cancellationToken = default(CancellationToken)) + { + foreach (IAsyncCollector collector in _collectors) + { + await collector.AddAsync(item, cancellationToken); + } + } + + public async Task FlushAsync(CancellationToken cancellationToken = default(CancellationToken)) + { + foreach (IAsyncCollector collector in _collectors) + { + await collector.FlushAsync(cancellationToken); + } + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs b/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs index 65306750..64936f43 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs @@ -16,6 +16,7 @@ using Microsoft.Azure.WebJobs.Host.Bindings; using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Executors { @@ -26,12 +27,15 @@ namespace Microsoft.Azure.WebJobs.Host.Executors private readonly IFunctionOutputLogger _functionOutputLogger; private readonly IWebJobsExceptionHandler _exceptionHandler; private readonly TraceWriter _trace; - private readonly IAsyncCollector _fastLogger; + private readonly IAsyncCollector _functionEventCollector; + private readonly ILogger _logger; + private readonly ILogger _resultsLogger; private HostOutputMessage _hostOutputMessage; public FunctionExecutor(IFunctionInstanceLogger functionInstanceLogger, IFunctionOutputLogger functionOutputLogger, - IWebJobsExceptionHandler exceptionHandler, TraceWriter trace, IAsyncCollector fastLogger = null) + IWebJobsExceptionHandler exceptionHandler, TraceWriter trace, IAsyncCollector functionEventCollector = null, + ILoggerFactory loggerFactory = null) { if (functionInstanceLogger == null) { @@ -57,7 +61,9 @@ namespace Microsoft.Azure.WebJobs.Host.Executors _functionOutputLogger = functionOutputLogger; _exceptionHandler = exceptionHandler; _trace = trace; - _fastLogger = fastLogger; + _functionEventCollector = functionEventCollector; + _logger = loggerFactory?.CreateLogger(LogCategories.Executor); + _resultsLogger = loggerFactory?.CreateLogger(LogCategories.Results); } public HostOutputMessage HostOutputMessage @@ -84,9 +90,13 @@ namespace Microsoft.Azure.WebJobs.Host.Executors StartTime = functionStartedMessage.StartTime.DateTime }; + Stopwatch sw = Stopwatch.StartNew(); try { - functionStartedMessageId = await ExecuteWithLoggingAsync(functionInstance, functionStartedMessage, fastItem, parameterLogCollector, functionTraceLevel, cancellationToken); + using (_logger?.BeginFunctionScope(functionInstance)) + { + functionStartedMessageId = await ExecuteWithLoggingAsync(functionInstance, functionStartedMessage, fastItem, parameterLogCollector, functionTraceLevel, cancellationToken); + } functionCompletedMessage = CreateCompletedMessage(functionStartedMessage); } catch (Exception exception) @@ -124,12 +134,15 @@ namespace Microsoft.Azure.WebJobs.Host.Executors logCompletedCancellationToken = cancellationToken; } - if (_fastLogger != null) - { - // Log completed - fastItem.EndTime = DateTime.UtcNow; - fastItem.Arguments = functionCompletedMessage.Arguments; + // log result + sw.Stop(); + fastItem.EndTime = DateTime.UtcNow; + fastItem.Duration = sw.Elapsed; + fastItem.Arguments = functionCompletedMessage.Arguments; + if (_functionEventCollector != null) + { + // Log completed if (exceptionInfo != null) { var ex = exceptionInfo.SourceException; @@ -139,7 +152,11 @@ namespace Microsoft.Azure.WebJobs.Host.Executors } fastItem.ErrorDetails = ex.Message; } - await _fastLogger.AddAsync(fastItem); + await _functionEventCollector.AddAsync(fastItem); + } + using (_resultsLogger?.BeginFunctionScope(functionInstance)) + { + _resultsLogger?.LogFunctionResult(functionInstance.FunctionDescriptor.Method.Name, fastItem, sw.Elapsed, exceptionInfo?.SourceException); } if (functionCompletedMessage != null && @@ -229,16 +246,16 @@ namespace Microsoft.Azure.WebJobs.Host.Executors startedMessageId = await LogFunctionStartedAsync(message, outputDefinition, parameters, cancellationToken); } - if (_fastLogger != null) + if (_functionEventCollector != null) { // Log started fastItem.Arguments = message.Arguments; - await _fastLogger.AddAsync(fastItem); + await _functionEventCollector.AddAsync(fastItem); } try { - await ExecuteWithLoggingAsync(instance, parameters, traceWriter, outputDefinition, parameterLogCollector, functionTraceLevel, functionCancellationTokenSource); + await ExecuteWithLoggingAsync(instance, parameters, traceWriter, _logger, outputDefinition, parameterLogCollector, functionTraceLevel, functionCancellationTokenSource); } catch (Exception ex) { @@ -318,7 +335,8 @@ namespace Microsoft.Azure.WebJobs.Host.Executors /// create and start the timer. /// [SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope")] - internal static System.Timers.Timer StartFunctionTimeout(IFunctionInstance instance, TimeoutAttribute attribute, CancellationTokenSource cancellationTokenSource, TraceWriter trace) + internal static System.Timers.Timer StartFunctionTimeout(IFunctionInstance instance, TimeoutAttribute attribute, + CancellationTokenSource cancellationTokenSource, TraceWriter trace, ILogger logger) { if (attribute == null) { @@ -348,7 +366,7 @@ namespace Microsoft.Azure.WebJobs.Host.Executors timer.Elapsed += (o, e) => { - OnFunctionTimeout(timer, method, instance.Id, timeout.Value, attribute.TimeoutWhileDebugging, trace, cancellationTokenSource, + OnFunctionTimeout(timer, method, instance.Id, timeout.Value, attribute.TimeoutWhileDebugging, trace, logger, cancellationTokenSource, () => Debugger.IsAttached); }; @@ -361,7 +379,7 @@ namespace Microsoft.Azure.WebJobs.Host.Executors } internal static void OnFunctionTimeout(System.Timers.Timer timer, MethodInfo method, Guid instanceId, TimeSpan timeout, bool timeoutWhileDebugging, - TraceWriter trace, CancellationTokenSource cancellationTokenSource, Func isDebuggerAttached) + TraceWriter trace, ILogger logger, CancellationTokenSource cancellationTokenSource, Func isDebuggerAttached) { timer.Stop(); @@ -372,6 +390,7 @@ namespace Microsoft.Azure.WebJobs.Host.Executors shouldTimeout ? "Initiating cancellation." : "Function will not be cancelled while debugging."); trace.Error(message, null, TraceSource.Execution); + logger?.LogError(message); trace.Flush(); @@ -434,6 +453,7 @@ namespace Microsoft.Azure.WebJobs.Host.Executors private async Task ExecuteWithLoggingAsync(IFunctionInstance instance, IReadOnlyDictionary parameters, TraceWriter trace, + ILogger logger, IFunctionOutputDefinition outputDefinition, IDictionary parameterLogCollector, TraceLevel functionTraceLevel, @@ -446,13 +466,13 @@ namespace Microsoft.Azure.WebJobs.Host.Executors if (functionTraceLevel >= TraceLevel.Info) { parameterWatchers = CreateParameterWatchers(parameters); - IRecurrentCommand updateParameterLogCommand = outputDefinition.CreateParameterLogUpdateCommand(parameterWatchers, trace); + IRecurrentCommand updateParameterLogCommand = outputDefinition.CreateParameterLogUpdateCommand(parameterWatchers, trace, logger); updateParameterLogTimer = StartParameterLogTimer(updateParameterLogCommand, _exceptionHandler); } try { - await ExecuteWithWatchersAsync(instance, parameters, trace, functionCancellationTokenSource); + await ExecuteWithWatchersAsync(instance, parameters, trace, logger, functionCancellationTokenSource); if (updateParameterLogTimer != null) { @@ -496,6 +516,7 @@ namespace Microsoft.Azure.WebJobs.Host.Executors internal static async Task ExecuteWithWatchersAsync(IFunctionInstance instance, IReadOnlyDictionary parameters, TraceWriter traceWriter, + ILogger logger, CancellationTokenSource functionCancellationTokenSource) { IFunctionInvoker invoker = instance.Invoker; @@ -526,12 +547,12 @@ namespace Microsoft.Azure.WebJobs.Host.Executors MethodInfo method = instance.FunctionDescriptor.Method; TimeoutAttribute timeoutAttribute = instance.FunctionDescriptor.TimeoutAttribute; bool throwOnTimeout = timeoutAttribute == null ? false : timeoutAttribute.ThrowOnTimeout; - var timer = StartFunctionTimeout(instance, timeoutAttribute, timeoutTokenSource, traceWriter); + var timer = StartFunctionTimeout(instance, timeoutAttribute, timeoutTokenSource, traceWriter, logger); TimeSpan timerInterval = timer == null ? TimeSpan.MinValue : TimeSpan.FromMilliseconds(timer.Interval); try { await InvokeAsync(invoker, invokeParameters, timeoutTokenSource, functionCancellationTokenSource, - throwOnTimeout, timerInterval, instance); + throwOnTimeout, timerInterval, instance); } finally { diff --git a/src/Microsoft.Azure.WebJobs.Host/Executors/JobHostConfigurationExtensions.cs b/src/Microsoft.Azure.WebJobs.Host/Executors/JobHostConfigurationExtensions.cs index 6a06c18a..01043ef4 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Executors/JobHostConfigurationExtensions.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Executors/JobHostConfigurationExtensions.cs @@ -26,6 +26,7 @@ using Microsoft.Azure.WebJobs.Host.Storage.Queue; using Microsoft.Azure.WebJobs.Host.Tables; using Microsoft.Azure.WebJobs.Host.Timers; using Microsoft.Azure.WebJobs.Host.Triggers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Executors { @@ -34,9 +35,9 @@ namespace Microsoft.Azure.WebJobs.Host.Executors // Do full initialization (both static and runtime). // This can be called multiple times on a config. public static async Task CreateAndLogHostStartedAsync( - this JobHostConfiguration config, - JobHost host, - CancellationToken shutdownToken, + this JobHostConfiguration config, + JobHost host, + CancellationToken shutdownToken, CancellationToken cancellationToken) { JobHostContext context = await config.CreateJobHostContextAsync(host, shutdownToken, cancellationToken); @@ -121,25 +122,25 @@ namespace Microsoft.Azure.WebJobs.Host.Executors if (singletonManager == null) { - singletonManager = new SingletonManager(storageAccountProvider, exceptionHandler, config.Singleton, trace, hostIdProvider, services.GetService()); + singletonManager = new SingletonManager(storageAccountProvider, exceptionHandler, config.Singleton, trace, config.LoggerFactory, hostIdProvider, services.GetService()); services.AddService(singletonManager); } IExtensionRegistry extensions = services.GetExtensions(); ITriggerBindingProvider triggerBindingProvider = DefaultTriggerBindingProvider.Create(nameResolver, storageAccountProvider, extensionTypeLocator, hostIdProvider, queueConfiguration, blobsConfiguration, exceptionHandler, - messageEnqueuedWatcherAccessor, blobWrittenWatcherAccessor, sharedContextProvider, extensions, singletonManager, trace); + messageEnqueuedWatcherAccessor, blobWrittenWatcherAccessor, sharedContextProvider, extensions, singletonManager, trace, config.LoggerFactory); services.AddService(triggerBindingProvider); if (bindingProvider == null) { - bindingProvider = DefaultBindingProvider.Create(nameResolver, storageAccountProvider, extensionTypeLocator, blobWrittenWatcherAccessor, extensions); + bindingProvider = DefaultBindingProvider.Create(nameResolver, config.LoggerFactory, storageAccountProvider, extensionTypeLocator, blobWrittenWatcherAccessor, extensions); services.AddService(bindingProvider); } return services; } - + // Do the full runtime intitialization. This includes static initialization. // This mainly means: // - indexing the functions @@ -161,12 +162,34 @@ namespace Microsoft.Azure.WebJobs.Host.Executors INameResolver nameResolver = services.GetService(); IExtensionRegistry extensions = services.GetExtensions(); IStorageAccountProvider storageAccountProvider = services.GetService(); + ILoggerFactory loggerFactory = services.GetService(); + IFunctionResultAggregatorFactory aggregatorFactory = services.GetService(); + IAsyncCollector functionEventCollector = null; + + // Create the aggregator if all the pieces are configured + IAsyncCollector aggregator = null; + if (loggerFactory != null && aggregatorFactory != null && config.Aggregator.IsEnabled) + { + aggregator = aggregatorFactory.Create(config.Aggregator.BatchSize, config.Aggregator.FlushTimeout, loggerFactory); + } IQueueConfiguration queueConfiguration = services.GetService(); var blobsConfiguration = config.Blobs; TraceWriter trace = services.GetService(); - IAsyncCollector fastLogger = services.GetService>(); + IAsyncCollector registeredFunctionEventCollector = services.GetService>(); + + if (registeredFunctionEventCollector != null && aggregator != null) + { + // If there are both an aggregator and a registered FunctionEventCollector, wrap them in a composite + functionEventCollector = new CompositeFunctionEventCollector(new[] { registeredFunctionEventCollector, aggregator }); + } + else + { + // Otherwise, take whichever one is null (or use null if both are) + functionEventCollector = aggregator ?? registeredFunctionEventCollector; + } + IWebJobsExceptionHandler exceptionHandler = services.GetService(); if (exceptionHandler != null) @@ -209,25 +232,25 @@ namespace Microsoft.Azure.WebJobs.Host.Executors IStorageAccount dashboardAccount = await storageAccountProvider.GetDashboardAccountAsync(combinedCancellationToken); IHostInstanceLogger hostInstanceLogger = await hostInstanceLoggerProvider.GetAsync(combinedCancellationToken); - IFunctionInstanceLogger functionInstanceLogger = await functionInstanceLoggerProvider.GetAsync(combinedCancellationToken); + IFunctionInstanceLogger functionInstanceLogger = await functionInstanceLoggerProvider.GetAsync(combinedCancellationToken); IFunctionOutputLogger functionOutputLogger = await functionOutputLoggerProvider.GetAsync(combinedCancellationToken); if (functionExecutor == null) { - functionExecutor = new FunctionExecutor(functionInstanceLogger, functionOutputLogger, exceptionHandler, trace, fastLogger); + functionExecutor = new FunctionExecutor(functionInstanceLogger, functionOutputLogger, exceptionHandler, trace, functionEventCollector, loggerFactory); services.AddService(functionExecutor); } if (functionIndexProvider == null) { - functionIndexProvider = new FunctionIndexProvider(services.GetService(), triggerBindingProvider, bindingProvider, activator, functionExecutor, extensions, singletonManager, trace); + functionIndexProvider = new FunctionIndexProvider(services.GetService(), triggerBindingProvider, bindingProvider, activator, functionExecutor, extensions, singletonManager, trace, loggerFactory); // Important to set this so that the func we passed to DynamicHostIdProvider can pick it up. services.AddService(functionIndexProvider); } IFunctionIndex functions = await functionIndexProvider.GetAsync(combinedCancellationToken); - IListenerFactory functionsListenerFactory = new HostListenerFactory(functions.ReadAll(), singletonManager, activator, nameResolver, trace); + IListenerFactory functionsListenerFactory = new HostListenerFactory(functions.ReadAll(), singletonManager, activator, nameResolver, trace, loggerFactory); IFunctionExecutor hostCallExecutor; IListener listener; @@ -257,14 +280,14 @@ namespace Microsoft.Azure.WebJobs.Host.Executors IStorageQueueClient dashboardQueueClient = dashboardAccount.CreateQueueClient(); IStorageQueue sharedQueue = dashboardQueueClient.GetQueueReference(sharedQueueName); IListenerFactory sharedQueueListenerFactory = new HostMessageListenerFactory(sharedQueue, - queueConfiguration, exceptionHandler, trace, functions, + queueConfiguration, exceptionHandler, trace, loggerFactory, functions, functionInstanceLogger, functionExecutor); Guid hostInstanceId = Guid.NewGuid(); string instanceQueueName = HostQueueNames.GetHostQueueName(hostInstanceId.ToString("N")); IStorageQueue instanceQueue = dashboardQueueClient.GetQueueReference(instanceQueueName); IListenerFactory instanceQueueListenerFactory = new HostMessageListenerFactory(instanceQueue, - queueConfiguration, exceptionHandler, trace, functions, + queueConfiguration, exceptionHandler, trace, loggerFactory, functions, functionInstanceLogger, functionExecutor); HeartbeatDescriptor heartbeatDescriptor = new HeartbeatDescriptor @@ -309,15 +332,22 @@ namespace Microsoft.Azure.WebJobs.Host.Executors IEnumerable descriptors = functions.ReadAllDescriptors(); int descriptorsCount = descriptors.Count(); + ILogger startupLogger = loggerFactory?.CreateLogger(LogCategories.Startup); + if (config.UsingDevelopmentSettings) { - trace.Verbose(string.Format("Development settings applied")); + string msg = "Development settings applied"; + trace.Verbose(msg); + startupLogger?.LogDebug(msg); } if (descriptorsCount == 0) { - trace.Warning(string.Format("No job functions found. Try making your job classes and methods public. {0}", - Constants.ExtensionInitializationMessage), Host.TraceSource.Indexing); + string msg = string.Format("No job functions found. Try making your job classes and methods public. {0}", + Constants.ExtensionInitializationMessage); + + trace.Warning(msg, Host.TraceSource.Indexing); + startupLogger?.LogWarning(msg); } else { @@ -328,11 +358,12 @@ namespace Microsoft.Azure.WebJobs.Host.Executors { functionsTrace.AppendLine(descriptor.FullName); } - - trace.Info(functionsTrace.ToString(), Host.TraceSource.Indexing); + string msg = functionsTrace.ToString(); + trace.Info(msg, Host.TraceSource.Indexing); + startupLogger?.LogInformation(msg); } - return new JobHostContext(functions, hostCallExecutor, listener, trace, fastLogger); + return new JobHostContext(functions, hostCallExecutor, listener, trace, functionEventCollector, loggerFactory); } } diff --git a/src/Microsoft.Azure.WebJobs.Host/Executors/JobHostContext.cs b/src/Microsoft.Azure.WebJobs.Host/Executors/JobHostContext.cs index 02071af5..832ab3fe 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Executors/JobHostContext.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Executors/JobHostContext.cs @@ -5,6 +5,7 @@ using System; using Microsoft.Azure.WebJobs.Host.Indexers; using Microsoft.Azure.WebJobs.Host.Listeners; using Microsoft.Azure.WebJobs.Host.Loggers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Executors { @@ -16,7 +17,8 @@ namespace Microsoft.Azure.WebJobs.Host.Executors private readonly IFunctionExecutor _executor; private readonly IListener _listener; private readonly TraceWriter _trace; - private readonly IAsyncCollector _fastLogger; // optional + private readonly IAsyncCollector _functionEventCollector; // optional + private readonly ILoggerFactory _loggerFactory; private bool _disposed; @@ -24,13 +26,15 @@ namespace Microsoft.Azure.WebJobs.Host.Executors IFunctionExecutor executor, IListener listener, TraceWriter trace, - IAsyncCollector fastLogger = null) + IAsyncCollector functionEventCollector = null, + ILoggerFactory loggerFactory = null) { _functionLookup = functionLookup; _executor = executor; _listener = listener; _trace = trace; - _fastLogger = fastLogger; + _functionEventCollector = functionEventCollector; + _loggerFactory = loggerFactory; } public TraceWriter Trace @@ -69,12 +73,21 @@ namespace Microsoft.Azure.WebJobs.Host.Executors } } - public IAsyncCollector FastLogger + public IAsyncCollector FunctionEventCollector { get { ThrowIfDisposed(); - return _fastLogger; + return _functionEventCollector; + } + } + + public ILoggerFactory LoggerFactory + { + get + { + ThrowIfDisposed(); + return _loggerFactory; } } diff --git a/src/Microsoft.Azure.WebJobs.Host/Extensions/DictionaryExtensions.cs b/src/Microsoft.Azure.WebJobs.Host/Extensions/DictionaryExtensions.cs new file mode 100644 index 00000000..8a60353f --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Extensions/DictionaryExtensions.cs @@ -0,0 +1,18 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +namespace System.Collections.Generic +{ + internal static class DictionaryExtensions + { + public static T GetValueOrDefault(this IDictionary dictionary, string key) + { + object value; + if (dictionary.TryGetValue(key, out value)) + { + return (T)value; + } + return default(T); + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/GlobalSuppressions.cs b/src/Microsoft.Azure.WebJobs.Host/GlobalSuppressions.cs index 54cbf915..c7fb55d2 100644 --- a/src/Microsoft.Azure.WebJobs.Host/GlobalSuppressions.cs +++ b/src/Microsoft.Azure.WebJobs.Host/GlobalSuppressions.cs @@ -68,4 +68,10 @@ [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA2204:Literals should be spelled correctly", MessageId = "SetPostResolveHook", Scope = "member", Target = "Microsoft.Azure.WebJobs.Host.Config.FluentBindingRule`1.#ApplyRules()")] [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Performance", "CA1811:AvoidUncalledPrivateCode", Scope = "member", Target = "Microsoft.Azure.WebJobs.Host.JobHostQueuesConfiguration.#MaxPollingIntervalInt")] [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Performance", "CA1811:AvoidUncalledPrivateCode", Scope = "member", Target = "Microsoft.Azure.WebJobs.Host.JobHostQueuesConfiguration.#MaxPollingIntervalInt")] -[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA2204:Literals should be spelled correctly", MessageId = "AddBindingRule", Scope = "member", Target = "Microsoft.Azure.WebJobs.Host.Config.ExtensionConfigContext.#AddBindingRule`1()")] \ No newline at end of file +[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA2204:Literals should be spelled correctly", MessageId = "AddBindingRule", Scope = "member", Target = "Microsoft.Azure.WebJobs.Host.Config.ExtensionConfigContext.#AddBindingRule`1()")] +[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Extensions.Logging.AppInsightsLoggerExtensions.#AddAppInsights(Microsoft.Extensions.Logging.ILoggerFactory,System.String,System.Func`3)")] +[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Extensions.Logging.AppInsightsLoggerExtensions.#AddAppInsights(Microsoft.Extensions.Logging.ILoggerFactory,System.String,System.Func`3)")] +[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Extensions.Logging.AppInsightsLoggerExtensions.#AddAppInsights(Microsoft.Extensions.Logging.ILoggerFactory,System.String,System.Func`3)")] +[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Host.Loggers.FunctionResultAggregatorFactory.#Create(System.Int32,System.TimeSpan,Microsoft.Extensions.Logging.ILoggerFactory)")] +[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Extensions.Logging.ApplicationInsightsLoggerExtensions.#AddApplicationInsights(Microsoft.Extensions.Logging.ILoggerFactory,System.String,System.Func`3,Microsoft.Azure.WebJobs.Host.Loggers.ITelemetryClientFactory,Microsoft.ApplicationInsights.WindowsServer.Channel.Implementation.SamplingPercentageEstimatorSettings)")] +[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Host.Loggers.DefaultTelemetryClientFactory.#InitializeConfiguration(System.String,Microsoft.ApplicationInsights.WindowsServer.Channel.Implementation.SamplingPercentageEstimatorSettings)")] \ No newline at end of file diff --git a/src/Microsoft.Azure.WebJobs.Host/Indexers/DefaultBindingProvider.cs b/src/Microsoft.Azure.WebJobs.Host/Indexers/DefaultBindingProvider.cs index 855ff3ac..a368efef 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Indexers/DefaultBindingProvider.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Indexers/DefaultBindingProvider.cs @@ -15,17 +15,19 @@ using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Queues; using Microsoft.Azure.WebJobs.Host.Queues.Bindings; using Microsoft.Azure.WebJobs.Host.Tables; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Indexers { internal static class DefaultBindingProvider { public static IBindingProvider Create( - INameResolver nameResolver, + INameResolver nameResolver, + ILoggerFactory loggerFactory, IStorageAccountProvider storageAccountProvider, IExtensionTypeLocator extensionTypeLocator, IContextGetter blobWrittenWatcherGetter, - IExtensionRegistry extensions) + IExtensionRegistry extensions) { List innerProviders = new List(); @@ -43,7 +45,9 @@ namespace Microsoft.Azure.WebJobs.Host.Indexers // The TraceWriter binder handles all remaining TraceWriter/TextWriter parameters. It must come after the // Blob binding provider; otherwise bindings like Do([Blob("a/b")] TextWriter blob) wouldn't work. - innerProviders.Add(new TraceWriterBindingProvider()); + innerProviders.Add(new TraceWriterBindingProvider(loggerFactory)); + + innerProviders.Add(new LoggerBindingProvider(loggerFactory)); ContextAccessor bindingProviderAccessor = new ContextAccessor(); innerProviders.Add(new RuntimeBindingProvider(bindingProviderAccessor)); diff --git a/src/Microsoft.Azure.WebJobs.Host/Indexers/DefaultTriggerBindingProvider.cs b/src/Microsoft.Azure.WebJobs.Host/Indexers/DefaultTriggerBindingProvider.cs index d386b0f7..b756d4fe 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Indexers/DefaultTriggerBindingProvider.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Indexers/DefaultTriggerBindingProvider.cs @@ -10,6 +10,7 @@ using Microsoft.Azure.WebJobs.Host.Queues; using Microsoft.Azure.WebJobs.Host.Queues.Triggers; using Microsoft.Azure.WebJobs.Host.Timers; using Microsoft.Azure.WebJobs.Host.Triggers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Indexers { @@ -27,15 +28,16 @@ namespace Microsoft.Azure.WebJobs.Host.Indexers ISharedContextProvider sharedContextProvider, IExtensionRegistry extensions, SingletonManager singletonManager, - TraceWriter trace) + TraceWriter trace, + ILoggerFactory loggerFactory) { List innerProviders = new List(); innerProviders.Add(new QueueTriggerAttributeBindingProvider(nameResolver, storageAccountProvider, queueConfiguration, exceptionHandler, messageEnqueuedWatcherSetter, - sharedContextProvider, trace)); - innerProviders.Add(new BlobTriggerAttributeBindingProvider(nameResolver, storageAccountProvider, - extensionTypeLocator, hostIdProvider, queueConfiguration, blobsConfiguration, exceptionHandler, - blobWrittenWatcherSetter, messageEnqueuedWatcherSetter, sharedContextProvider, singletonManager, trace)); + sharedContextProvider, trace, loggerFactory)); + innerProviders.Add(new BlobTriggerAttributeBindingProvider(nameResolver, storageAccountProvider, extensionTypeLocator, + hostIdProvider, queueConfiguration, blobsConfiguration, exceptionHandler, blobWrittenWatcherSetter, + messageEnqueuedWatcherSetter, sharedContextProvider, singletonManager, trace, loggerFactory)); // add any registered extension binding providers foreach (ITriggerBindingProvider provider in extensions.GetExtensions(typeof(ITriggerBindingProvider))) diff --git a/src/Microsoft.Azure.WebJobs.Host/Indexers/FunctionIndexProvider.cs b/src/Microsoft.Azure.WebJobs.Host/Indexers/FunctionIndexProvider.cs index 319c5e83..e651a391 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Indexers/FunctionIndexProvider.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Indexers/FunctionIndexProvider.cs @@ -7,8 +7,8 @@ using System.Threading; using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host.Bindings; using Microsoft.Azure.WebJobs.Host.Executors; -using Microsoft.Azure.WebJobs.Host.Storage; using Microsoft.Azure.WebJobs.Host.Triggers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Indexers { @@ -22,6 +22,7 @@ namespace Microsoft.Azure.WebJobs.Host.Indexers private readonly IExtensionRegistry _extensions; private readonly SingletonManager _singletonManager; private readonly TraceWriter _trace; + private readonly ILoggerFactory _loggerFactory; private IFunctionIndex _index; @@ -32,7 +33,8 @@ namespace Microsoft.Azure.WebJobs.Host.Indexers IFunctionExecutor executor, IExtensionRegistry extensions, SingletonManager singletonManager, - TraceWriter trace) + TraceWriter trace, + ILoggerFactory loggerFactory) { if (typeLocator == null) { @@ -82,6 +84,7 @@ namespace Microsoft.Azure.WebJobs.Host.Indexers _extensions = extensions; _singletonManager = singletonManager; _trace = trace; + _loggerFactory = loggerFactory; } public async Task GetAsync(CancellationToken cancellationToken) @@ -97,7 +100,7 @@ namespace Microsoft.Azure.WebJobs.Host.Indexers private async Task CreateAsync(CancellationToken cancellationToken) { FunctionIndex index = new FunctionIndex(); - FunctionIndexer indexer = new FunctionIndexer(_triggerBindingProvider, _bindingProvider, _activator, _executor, _extensions, _singletonManager, _trace); + FunctionIndexer indexer = new FunctionIndexer(_triggerBindingProvider, _bindingProvider, _activator, _executor, _extensions, _singletonManager, _trace, _loggerFactory); IReadOnlyList types = _typeLocator.GetTypes(); foreach (Type type in types) diff --git a/src/Microsoft.Azure.WebJobs.Host/Indexers/FunctionIndexer.cs b/src/Microsoft.Azure.WebJobs.Host/Indexers/FunctionIndexer.cs index 7ddba305..ba3a87d2 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Indexers/FunctionIndexer.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Indexers/FunctionIndexer.cs @@ -12,8 +12,10 @@ using Microsoft.Azure.WebJobs.Host.Bindings; using Microsoft.Azure.WebJobs.Host.Bindings.Invoke; using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Listeners; +using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.Triggers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Indexers { @@ -28,8 +30,10 @@ namespace Microsoft.Azure.WebJobs.Host.Indexers private readonly HashSet _jobAttributeAssemblies; private readonly SingletonManager _singletonManager; private readonly TraceWriter _trace; + private readonly ILogger _logger; - public FunctionIndexer(ITriggerBindingProvider triggerBindingProvider, IBindingProvider bindingProvider, IJobActivator activator, IFunctionExecutor executor, IExtensionRegistry extensions, SingletonManager singletonManager, TraceWriter trace) + public FunctionIndexer(ITriggerBindingProvider triggerBindingProvider, IBindingProvider bindingProvider, IJobActivator activator, IFunctionExecutor executor, IExtensionRegistry extensions, SingletonManager singletonManager, + TraceWriter trace, ILoggerFactory loggerFactory) { if (triggerBindingProvider == null) { @@ -73,6 +77,7 @@ namespace Microsoft.Azure.WebJobs.Host.Indexers _singletonManager = singletonManager; _jobAttributeAssemblies = GetJobAttributeAssemblies(extensions); _trace = trace; + _logger = loggerFactory?.CreateLogger(LogCategories.Startup); } public async Task IndexTypeAsync(Type type, IFunctionIndexCollector index, CancellationToken cancellationToken) @@ -85,7 +90,7 @@ namespace Microsoft.Azure.WebJobs.Host.Indexers } catch (FunctionIndexingException fex) { - fex.TryRecover(_trace); + fex.TryRecover(_trace, _logger); // If recoverable, continue to the rest of the methods. // The method in error simply won't be running in the JobHost. continue; @@ -123,7 +128,7 @@ namespace Microsoft.Azure.WebJobs.Host.Indexers // create a set containing our own core assemblies HashSet assemblies = new HashSet(); assemblies.Add(typeof(BlobAttribute).Assembly); - + // add any extension assemblies assemblies.UnionWith(extensions.GetExtensionAssemblies()); @@ -206,7 +211,7 @@ namespace Microsoft.Azure.WebJobs.Host.Indexers if (triggerBinding != null && !hasNoAutomaticTriggerAttribute) { throw new InvalidOperationException( - string.Format(Constants.UnableToBindParameterFormat, + string.Format(Constants.UnableToBindParameterFormat, parameter.Name, parameter.ParameterType.Name, Constants.ExtensionInitializationMessage)); } else @@ -246,7 +251,9 @@ namespace Microsoft.Azure.WebJobs.Host.Indexers if (TypeUtility.IsAsyncVoid(method)) { - this._trace.Warning($"Function '{method.Name}' is async but does not return a Task. Your function may not run correctly."); + string msg = $"Function '{method.Name}' is async but does not return a Task. Your function may not run correctly."; + _trace.Warning(msg); + _logger?.LogWarning(msg); } Type returnType = method.ReturnType; diff --git a/src/Microsoft.Azure.WebJobs.Host/JobHost.cs b/src/Microsoft.Azure.WebJobs.Host/JobHost.cs index c6357cf8..fa267802 100644 --- a/src/Microsoft.Azure.WebJobs.Host/JobHost.cs +++ b/src/Microsoft.Azure.WebJobs.Host/JobHost.cs @@ -12,7 +12,9 @@ using Microsoft.Azure.WebJobs.Host; using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Indexers; using Microsoft.Azure.WebJobs.Host.Listeners; +using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Protocols; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage; namespace Microsoft.Azure.WebJobs @@ -36,7 +38,7 @@ namespace Microsoft.Azure.WebJobs private Task _contextTask; private bool _contextTaskInitialized; private object _contextTaskLock = new object(); - + private JobHostContext _context; private IListener _listener; private object _contextLock = new object(); @@ -46,6 +48,8 @@ namespace Microsoft.Azure.WebJobs private object _stopTaskLock = new object(); private bool _disposed; + private ILogger _logger; + /// /// Initializes a new instance of the class, using a Microsoft Azure Storage connection /// string located in the connectionStrings section of the configuration file or in environment variables. @@ -114,7 +118,10 @@ namespace Microsoft.Azure.WebJobs await EnsureHostStartedAsync(cancellationToken); await _listener.StartAsync(cancellationToken); - _context.Trace.Info("Job host started", Host.TraceSource.Host); + + string msg = "Job host started"; + _context.Trace.Info(msg, Host.TraceSource.Host); + _logger?.LogInformation(msg); _state = StateStarted; } @@ -156,13 +163,15 @@ namespace Microsoft.Azure.WebJobs await _listener.StopAsync(cancellationToken); // Flush remaining logs - var fastLogger = _context.FastLogger; - if (fastLogger != null) + var functionEventCollector = _context.FunctionEventCollector; + if (functionEventCollector != null) { - await fastLogger.FlushAsync(cancellationToken); + await functionEventCollector.FlushAsync(cancellationToken); } - _context.Trace.Info("Job host stopped", Host.TraceSource.Host); + string msg = "Job host stopped"; + _context.Trace.Info(msg, Host.TraceSource.Host); + _logger?.LogInformation(msg); } /// Runs the host and blocks the current thread while the host remains running. @@ -321,7 +330,7 @@ namespace Microsoft.Azure.WebJobs } private async Task CreateContextAndLogHostStartedAsync(CancellationToken cancellationToken) - { + { JobHostContext context = await _config.CreateAndLogHostStartedAsync(this, _shutdownTokenSource.Token, cancellationToken); lock (_contextLock) @@ -333,6 +342,8 @@ namespace Microsoft.Azure.WebJobs } } + _logger = _context.LoggerFactory?.CreateLogger(LogCategories.Startup); + return _context; } diff --git a/src/Microsoft.Azure.WebJobs.Host/JobHostConfiguration.cs b/src/Microsoft.Azure.WebJobs.Host/JobHostConfiguration.cs index 4df31f31..18cff623 100644 --- a/src/Microsoft.Azure.WebJobs.Host/JobHostConfiguration.cs +++ b/src/Microsoft.Azure.WebJobs.Host/JobHostConfiguration.cs @@ -13,6 +13,7 @@ using Microsoft.Azure.WebJobs.Host.Indexers; using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Queues; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; using Newtonsoft.Json.Linq; namespace Microsoft.Azure.WebJobs @@ -43,7 +44,7 @@ namespace Microsoft.Azure.WebJobs : this(null) { } - + /// /// Initializes a new instance of the class, using the /// specified connection string for both reading and writing data as well as Dashboard logging. @@ -62,6 +63,7 @@ namespace Microsoft.Azure.WebJobs } Singleton = new SingletonConfiguration(); + Aggregator = new FunctionResultAggregatorConfiguration(); // add our built in services here _tooling = new JobHostMetadataProvider(this); @@ -80,9 +82,10 @@ namespace Microsoft.Azure.WebJobs AddService(typeLocator); AddService(converterManager); AddService(exceptionHandler); + AddService(new FunctionResultAggregatorFactory()); - string value = ConfigurationUtility.GetSettingFromConfigOrEnvironment(Constants.EnvironmentSettingName); - IsDevelopment = string.Compare(Constants.DevelopmentEnvironmentValue, value, StringComparison.OrdinalIgnoreCase) == 0; + string value = ConfigurationUtility.GetSettingFromConfigOrEnvironment(Host.Constants.EnvironmentSettingName); + IsDevelopment = string.Compare(Host.Constants.DevelopmentEnvironmentValue, value, StringComparison.OrdinalIgnoreCase) == 0; } /// @@ -257,6 +260,31 @@ namespace Microsoft.Azure.WebJobs private set; } + /// + /// Gets the configuration used by the logging aggregator. + /// + public FunctionResultAggregatorConfiguration Aggregator + { + get; + private set; + } + + /// + /// Gets or sets the . + /// + [CLSCompliant(false)] + public ILoggerFactory LoggerFactory + { + get + { + return GetService(); + } + set + { + AddService(value); + } + } + /// /// Gets the configuration for event tracing. /// @@ -353,10 +381,10 @@ namespace Microsoft.Azure.WebJobs } _services.AddOrUpdate(serviceType, serviceInstance, (key, existingValue) => - { - // always replace existing values - return serviceInstance; - }); + { + // always replace existing values + return serviceInstance; + }); } /// @@ -383,7 +411,7 @@ namespace Microsoft.Azure.WebJobs { _tooling.AddAttributesFromAssembly(assembly); } - + /// /// Get a tooling interface for inspecting current extensions. /// @@ -418,4 +446,4 @@ namespace Microsoft.Azure.WebJobs } } } -} \ No newline at end of file +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Listeners/FunctionListener.cs b/src/Microsoft.Azure.WebJobs.Host/Listeners/FunctionListener.cs index fe7d7880..9a82093d 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Listeners/FunctionListener.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Listeners/FunctionListener.cs @@ -4,7 +4,9 @@ using System; using System.Threading; using System.Threading.Tasks; +using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Protocols; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Listeners { @@ -13,6 +15,7 @@ namespace Microsoft.Azure.WebJobs.Host.Listeners private readonly IListener _listener; private readonly FunctionDescriptor _descriptor; private readonly TraceWriter _trace; + private readonly ILogger _logger; private bool _started = false; /// @@ -22,11 +25,13 @@ namespace Microsoft.Azure.WebJobs.Host.Listeners /// /// /// - public FunctionListener(IListener listener, FunctionDescriptor descriptor, TraceWriter trace) + /// + public FunctionListener(IListener listener, FunctionDescriptor descriptor, TraceWriter trace, ILoggerFactory loggerFactory) { _listener = listener; _descriptor = descriptor; _trace = trace; + _logger = loggerFactory?.CreateLogger(LogCategories.Startup); } public void Cancel() @@ -48,10 +53,10 @@ namespace Microsoft.Azure.WebJobs.Host.Listeners } catch (Exception e) { - new FunctionListenerException(_descriptor.ShortName, e).TryRecover(_trace); + new FunctionListenerException(_descriptor.ShortName, e).TryRecover(_trace, _logger); } } - + public async Task StopAsync(CancellationToken cancellationToken) { if (_started) diff --git a/src/Microsoft.Azure.WebJobs.Host/Listeners/HostListenerFactory.cs b/src/Microsoft.Azure.WebJobs.Host/Listeners/HostListenerFactory.cs index 72222507..8ad91e6c 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Listeners/HostListenerFactory.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Listeners/HostListenerFactory.cs @@ -10,6 +10,8 @@ using System.Threading; using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host.Bindings.Path; using Microsoft.Azure.WebJobs.Host.Indexers; +using Microsoft.Azure.WebJobs.Host.Loggers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Listeners { @@ -22,14 +24,19 @@ namespace Microsoft.Azure.WebJobs.Host.Listeners private readonly IJobActivator _activator; private readonly INameResolver _nameResolver; private readonly TraceWriter _trace; + private readonly ILoggerFactory _loggerFactory; + private readonly ILogger _logger; - public HostListenerFactory(IEnumerable functionDefinitions, SingletonManager singletonManager, IJobActivator activator, INameResolver nameResolver, TraceWriter trace) + public HostListenerFactory(IEnumerable functionDefinitions, SingletonManager singletonManager, IJobActivator activator, INameResolver nameResolver, + TraceWriter trace, ILoggerFactory loggerFactory) { _functionDefinitions = functionDefinitions; _singletonManager = singletonManager; _activator = activator; _nameResolver = nameResolver; _trace = trace; + _loggerFactory = loggerFactory; + _logger = _loggerFactory?.CreateLogger(LogCategories.Startup); } public async Task CreateAsync(CancellationToken cancellationToken) @@ -48,7 +55,9 @@ namespace Microsoft.Azure.WebJobs.Host.Listeners MethodInfo method = functionDefinition.Descriptor.Method; if (IsDisabled(method, _nameResolver, _activator)) { - _trace.Info(string.Format("Function '{0}' is disabled", functionDefinition.Descriptor.ShortName), TraceSource.Host); + string msg = string.Format("Function '{0}' is disabled", functionDefinition.Descriptor.ShortName); + _trace.Info(msg, TraceSource.Host); + _logger?.LogInformation(msg); continue; } @@ -58,11 +67,11 @@ namespace Microsoft.Azure.WebJobs.Host.Listeners SingletonAttribute singletonAttribute = SingletonManager.GetListenerSingletonOrNull(listener.GetType(), method); if (singletonAttribute != null) { - listener = new SingletonListener(method, singletonAttribute, _singletonManager, listener, _trace); + listener = new SingletonListener(method, singletonAttribute, _singletonManager, listener, _trace, _loggerFactory); } // wrap the listener with a function listener to handle exceptions - listener = new FunctionListener(listener, functionDefinition.Descriptor, _trace); + listener = new FunctionListener(listener, functionDefinition.Descriptor, _trace, _loggerFactory); listeners.Add(listener); } @@ -134,7 +143,7 @@ namespace Microsoft.Azure.WebJobs.Host.Listeners if (methodInfo == null || methodInfo.ReturnType != typeof(bool)) { - throw new InvalidOperationException(string.Format(CultureInfo.InvariantCulture, + throw new InvalidOperationException(string.Format(CultureInfo.InvariantCulture, "Type '{0}' must declare a method 'IsDisabled' returning bool and taking a single parameter of Type MethodInfo.", providerType.Name)); } diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/BlobFunctionOutputDefinition.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/BlobFunctionOutputDefinition.cs index 385ca3e6..832ca82e 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Loggers/BlobFunctionOutputDefinition.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/BlobFunctionOutputDefinition.cs @@ -10,6 +10,7 @@ using Microsoft.Azure.WebJobs.Host.Bindings; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.Storage.Blob; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage.Blob; namespace Microsoft.Azure.WebJobs.Host.Loggers @@ -46,9 +47,9 @@ namespace Microsoft.Azure.WebJobs.Host.Loggers return UpdateOutputLogCommand.Create(blob); } - public IRecurrentCommand CreateParameterLogUpdateCommand(IReadOnlyDictionary watches, TraceWriter trace) + public IRecurrentCommand CreateParameterLogUpdateCommand(IReadOnlyDictionary watches, TraceWriter trace, ILogger logger) { - return new UpdateParameterLogCommand(watches, GetBlockBlobReference(_parameterLogBlob), trace); + return new UpdateParameterLogCommand(watches, GetBlockBlobReference(_parameterLogBlob), trace, logger); } private IStorageBlockBlob GetBlockBlobReference(LocalBlobDescriptor descriptor) diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/ConsoleFunctionOutputDefinition.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/ConsoleFunctionOutputDefinition.cs index 7a964924..e1f0afe3 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Loggers/ConsoleFunctionOutputDefinition.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/ConsoleFunctionOutputDefinition.cs @@ -10,6 +10,7 @@ using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host.Bindings; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Loggers { @@ -31,7 +32,7 @@ namespace Microsoft.Azure.WebJobs.Host.Loggers return new ConsoleFunctionOutputLog(); } - public IRecurrentCommand CreateParameterLogUpdateCommand(IReadOnlyDictionary watches, TraceWriter trace) + public IRecurrentCommand CreateParameterLogUpdateCommand(IReadOnlyDictionary watches, TraceWriter trace, ILogger logger) { return null; } diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/FastTableLoggerProvider.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/FastTableLoggerProvider.cs index 0a6a554d..b042f620 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Loggers/FastTableLoggerProvider.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/FastTableLoggerProvider.cs @@ -10,6 +10,7 @@ using Microsoft.Azure.WebJobs.Host.Bindings; using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Loggers { @@ -102,7 +103,7 @@ namespace Microsoft.Azure.WebJobs.Host.Loggers return this; } - public IRecurrentCommand CreateParameterLogUpdateCommand(IReadOnlyDictionary watches, TraceWriter trace) + public IRecurrentCommand CreateParameterLogUpdateCommand(IReadOnlyDictionary watches, TraceWriter trace, ILogger logger) { return null; } diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/FunctionInstanceLogEntry.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/FunctionInstanceLogEntry.cs index 7236d904..22450dc0 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Loggers/FunctionInstanceLogEntry.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/FunctionInstanceLogEntry.cs @@ -3,9 +3,6 @@ using System; using System.Collections.Generic; -using System.Linq; -using System.Text; -using System.Threading.Tasks; namespace Microsoft.Azure.WebJobs.Host.Loggers { @@ -41,6 +38,11 @@ namespace Microsoft.Azure.WebJobs.Host.Loggers /// An optional value for when the function finished executing. If not set, then the function hasn't completed yet. public DateTime? EndTime { get; set; } + /// + /// The duration of the function execution. + /// + public TimeSpan Duration { get; set; } + /// /// Null on success. /// Else, set to some string with error details. @@ -48,7 +50,7 @@ namespace Microsoft.Azure.WebJobs.Host.Loggers public string ErrorDetails { get; set; } /// Gets or sets the function's argument values and help strings. - [System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2227:CollectionPropertiesShouldBeReadOnly")] + [System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2227:CollectionPropertiesShouldBeReadOnly")] public IDictionary Arguments { get; set; } /// Direct inline capture for output written to the per-function instance TextWriter log. diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/IFunctionOutputDefinition.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/IFunctionOutputDefinition.cs index f7aba39b..5f80738d 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Loggers/IFunctionOutputDefinition.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/IFunctionOutputDefinition.cs @@ -2,10 +2,10 @@ // Licensed under the MIT License. See License.txt in the project root for license information. using System.Collections.Generic; -using System.Threading; using Microsoft.Azure.WebJobs.Host.Bindings; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Loggers { @@ -17,6 +17,6 @@ namespace Microsoft.Azure.WebJobs.Host.Loggers IFunctionOutput CreateOutput(); - IRecurrentCommand CreateParameterLogUpdateCommand(IReadOnlyDictionary watches, TraceWriter trace); + IRecurrentCommand CreateParameterLogUpdateCommand(IReadOnlyDictionary watches, TraceWriter trace, ILogger logger); } } diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/FunctionResultAggregate.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/FunctionResultAggregate.cs new file mode 100644 index 00000000..f93b1a1e --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/FunctionResultAggregate.cs @@ -0,0 +1,38 @@ +// 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.Collections.ObjectModel; + +namespace Microsoft.Azure.WebJobs.Host.Loggers +{ + internal class FunctionResultAggregate + { + public string Name { get; set; } + public DateTimeOffset Timestamp { get; set; } + public TimeSpan AverageDuration { get; set; } + public TimeSpan MaxDuration { get; set; } + public TimeSpan MinDuration { get; set; } + public int Successes { get; set; } + public int Failures { get; set; } + public int Count => Successes + Failures; + public double SuccessRate => Math.Round((Successes / (double)Count) * 100, 2); + + public IReadOnlyDictionary ToReadOnlyDictionary() + { + return new ReadOnlyDictionary(new Dictionary + { + [LoggingKeys.Name] = Name, + [LoggingKeys.Count] = Count, + [LoggingKeys.Timestamp] = Timestamp, + [LoggingKeys.AvgDuration] = AverageDuration, + [LoggingKeys.MaxDuration] = MaxDuration, + [LoggingKeys.MinDuration] = MinDuration, + [LoggingKeys.Successes] = Successes, + [LoggingKeys.Failures] = Failures, + [LoggingKeys.SuccessRate] = SuccessRate + }); + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/FunctionResultAggregator.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/FunctionResultAggregator.cs new file mode 100644 index 00000000..ad1268d2 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/FunctionResultAggregator.cs @@ -0,0 +1,147 @@ +// 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.Threading; +using System.Threading.Tasks; +using System.Threading.Tasks.Dataflow; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host.Loggers +{ + internal class FunctionResultAggregator : IAsyncCollector, IDisposable + { + private readonly ILogger _logger; + private readonly int _batchSize; + private readonly TimeSpan _batchTimeout; + + private const string FunctionNamePrefix = "Functions."; + + private BufferBlock _buffer; + private BatchBlock _batcher; + + private Timer _windowTimer; + private IDisposable[] _disposables; + + public FunctionResultAggregator(int batchSize, TimeSpan batchTimeout, ILoggerFactory loggerFactory) + { + if (loggerFactory == null) + { + throw new ArgumentNullException(nameof(loggerFactory)); + } + + _logger = loggerFactory.CreateLogger(LogCategories.Aggregator); + _batchSize = batchSize; + _batchTimeout = batchTimeout; + InitializeFlow(_batchSize, _batchTimeout); + } + + private void InitializeFlow(int maxBacklog, TimeSpan maxFlushInterval) + { + _buffer = new BufferBlock( + new ExecutionDataflowBlockOptions() + { + BoundedCapacity = maxBacklog + }); + + _batcher = new BatchBlock(maxBacklog, + new GroupingDataflowBlockOptions() + { + BoundedCapacity = maxBacklog, + Greedy = true + }); + + TransformBlock, IEnumerable> aggregator = + new TransformBlock, IEnumerable>(transform: (e) => Aggregate(e)); + + ActionBlock> publisher = new ActionBlock>( + (e) => Publish(e), + new ExecutionDataflowBlockOptions() + { + MaxDegreeOfParallelism = 1, + BoundedCapacity = 32 + }); + + _disposables = new IDisposable[] + { + _buffer.LinkTo(_batcher), + _batcher.LinkTo(aggregator), + aggregator.LinkTo(publisher) + }; + + _windowTimer = new Timer(async (o) => await FlushAsync(), null, maxFlushInterval, maxFlushInterval); + } + + public Task FlushAsync(CancellationToken cancellationToken = default(CancellationToken)) + { + _batcher?.TriggerBatch(); + return Task.CompletedTask; + } + + internal void Publish(IEnumerable results) + { + foreach (var result in results) + { + _logger.LogFunctionResultAggregate(result); + } + } + + public async Task AddAsync(FunctionInstanceLogEntry result, CancellationToken cancellationToken = default(CancellationToken)) + { + // We'll get 'Function started' events here, which we don't care about. + if (result.EndTime != null) + { + await _buffer.SendAsync(result, cancellationToken); + } + } + + internal static IEnumerable Aggregate(IEnumerable evts) + { + var metrics = evts + .GroupBy(e => new { e.FunctionName }) + .Select(e => new FunctionResultAggregate + { + Name = TrimDefaultClassName(e.Key.FunctionName), + Timestamp = e.Min(t => t.StartTime), + Successes = e.Count(f => f.ErrorDetails == null), + Failures = e.Count(f => f.ErrorDetails != null), + MinDuration = e.Min(f => f.Duration), + MaxDuration = e.Max(f => f.Duration), + AverageDuration = new TimeSpan((long)e.Average(f => f.Duration.Ticks)) + }); + + return metrics; + } + + private static string TrimDefaultClassName(string functionName) + { + // We'll strip off the default namespace for nicer logs. Non-default namespaces will remain. + if (functionName != null && functionName.StartsWith(FunctionNamePrefix, StringComparison.Ordinal)) + { + functionName = functionName.Substring(FunctionNamePrefix.Length); + } + + return functionName; + } + + public void Dispose() + { + if (_disposables != null) + { + foreach (var d in _disposables) + { + d.Dispose(); + } + _disposables = null; + } + + if (_windowTimer != null) + { + _windowTimer.Dispose(); + _windowTimer = null; + } + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/FunctionResultAggregatorConfiguration.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/FunctionResultAggregatorConfiguration.cs new file mode 100644 index 00000000..15c11615 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/FunctionResultAggregatorConfiguration.cs @@ -0,0 +1,84 @@ +// 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 Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host +{ + /// + /// Configuration options for function result aggregation. + /// + public class FunctionResultAggregatorConfiguration + { + private int _batchSize; + private TimeSpan _flushTimeout; + + private const int DefaultBatchSize = 1000; + private const int MaxBatchSize = 10000; + + private static readonly TimeSpan DefaultFlushTimeout = TimeSpan.FromSeconds(30); + private static readonly TimeSpan MaxFlushTimeout = TimeSpan.FromMinutes(5); + + /// + /// Constructs a new instance. + /// + public FunctionResultAggregatorConfiguration() + { + _batchSize = DefaultBatchSize; + _flushTimeout = DefaultFlushTimeout; + } + + /// + /// Gets or sets a value indicating whether the aggregator is enabled. + /// + public bool IsEnabled { get; set; } = true; + + /// + /// Gets or sets a value indicating the the maximum batch size for aggregations. When this number is hit, the results are + /// aggregated and sent to every registered . + /// + public int BatchSize + { + get { return _batchSize; } + + set + { + if (value <= 0) + { + throw new ArgumentOutOfRangeException(nameof(value)); + } + + if (value > MaxBatchSize) + { + throw new ArgumentOutOfRangeException(nameof(value)); + } + + _batchSize = value; + } + } + + /// + /// Gets or sets a value indicating when the aggregator will send results to every registered . + /// + public TimeSpan FlushTimeout + { + get { return _flushTimeout; } + + set + { + if (value <= TimeSpan.Zero) + { + throw new ArgumentOutOfRangeException(nameof(value)); + } + + if (value > MaxFlushTimeout) + { + throw new ArgumentOutOfRangeException(nameof(value)); + } + + _flushTimeout = value; + } + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/FunctionResultAggregatorFactory.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/FunctionResultAggregatorFactory.cs new file mode 100644 index 00000000..94eb6e46 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/FunctionResultAggregatorFactory.cs @@ -0,0 +1,16 @@ +// 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 Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host.Loggers +{ + internal class FunctionResultAggregatorFactory : IFunctionResultAggregatorFactory + { + public IAsyncCollector Create(int batchSize, TimeSpan batchTimeout, ILoggerFactory loggerFactory) + { + return new FunctionResultAggregator(batchSize, batchTimeout, loggerFactory); + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/IFunctionResultAggregatorFactory.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/IFunctionResultAggregatorFactory.cs new file mode 100644 index 00000000..33e81ee3 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Aggregator/IFunctionResultAggregatorFactory.cs @@ -0,0 +1,13 @@ +// 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 Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host.Loggers +{ + internal interface IFunctionResultAggregatorFactory + { + IAsyncCollector Create(int batchSize, TimeSpan batchTimeout, ILoggerFactory loggerFactory); + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ApplicationInsightsLogger.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ApplicationInsightsLogger.cs new file mode 100644 index 00000000..fcd60ed5 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ApplicationInsightsLogger.cs @@ -0,0 +1,345 @@ +// 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.Net.Http; +using System.Web; +using Microsoft.ApplicationInsights; +using Microsoft.ApplicationInsights.DataContracts; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host.Loggers +{ + internal class ApplicationInsightsLogger : ILogger + { + private readonly TelemetryClient _telemetryClient; + private readonly string _categoryName; + private const string DefaultCategoryName = "Default"; + private const string DateTimeFormatString = "yyyy'-'MM'-'dd'T'HH':'mm':'ss'.'fffK"; + private Func _filter; + + public ApplicationInsightsLogger(TelemetryClient client, string categoryName, Func filter) + { + _telemetryClient = client; + _categoryName = categoryName ?? DefaultCategoryName; + _filter = filter; + } + + public void Log(LogLevel logLevel, EventId eventId, TState state, + Exception exception, Func formatter) + { + if (!IsEnabled(logLevel)) + { + return; + } + + string formattedMessage = formatter?.Invoke(state, exception); + + IEnumerable> stateValues = state as IEnumerable>; + + // We only support lists of key-value pairs. Anything else we'll skip. + if (stateValues == null) + { + return; + } + + // Log a function result + if (_categoryName == LogCategories.Results) + { + LogFunctionResult(stateValues, exception); + return; + } + + // Log an aggregate record + if (_categoryName == LogCategories.Aggregator) + { + LogFunctionResultAggregate(stateValues); + return; + } + + // Log an exception + if (exception != null) + { + LogException(logLevel, stateValues, exception, formattedMessage); + return; + } + + // Otherwise, log a trace + LogTrace(logLevel, stateValues, formattedMessage); + } + + private void LogException(LogLevel logLevel, IEnumerable> values, Exception exception, string formattedMessage) + { + ExceptionTelemetry telemetry = new ExceptionTelemetry(exception); + telemetry.Message = formattedMessage; + telemetry.SeverityLevel = GetSeverityLevel(logLevel); + telemetry.Timestamp = DateTimeOffset.UtcNow; + ApplyCustomProperties(telemetry, values); + _telemetryClient.TrackException(telemetry); + } + + private void LogTrace(LogLevel logLevel, IEnumerable> values, string formattedMessage) + { + TraceTelemetry telemetry = new TraceTelemetry(formattedMessage); + telemetry.SeverityLevel = GetSeverityLevel(logLevel); + telemetry.Timestamp = DateTimeOffset.UtcNow; + ApplyCustomProperties(telemetry, values); + _telemetryClient.TrackTrace(telemetry); + } + + private static SeverityLevel? GetSeverityLevel(LogLevel logLevel) + { + switch (logLevel) + { + case LogLevel.Trace: + case LogLevel.Debug: + return SeverityLevel.Verbose; + case LogLevel.Information: + return SeverityLevel.Information; + case LogLevel.Warning: + return SeverityLevel.Warning; + case LogLevel.Error: + return SeverityLevel.Error; + case LogLevel.Critical: + return SeverityLevel.Critical; + case LogLevel.None: + default: + return null; + } + } + + private void ApplyCustomProperties(ISupportProperties telemetry, IEnumerable> values) + { + telemetry.Properties.Add(LoggingKeys.CategoryName, _categoryName); + + foreach (var property in values) + { + string stringValue = null; + + // drop null properties + if (property.Value == null) + { + continue; + } + + // Format dates + Type propertyType = property.Value.GetType(); + if (propertyType == typeof(DateTime)) + { + stringValue = ((DateTime)property.Value).ToUniversalTime().ToString(DateTimeFormatString); + } + else if (propertyType == typeof(DateTimeOffset)) + { + stringValue = ((DateTimeOffset)property.Value).UtcDateTime.ToString(DateTimeFormatString); + } + else + { + stringValue = property.Value.ToString(); + } + + // Since there is no nesting of properties, apply a prefix before the property name to lessen + // the chance of collisions. + telemetry.Properties.Add(LoggingKeys.CustomPropertyPrefix + property.Key, stringValue); + } + } + + private void LogFunctionResultAggregate(IEnumerable> values) + { + // Metric names will be created like "{FunctionName} {MetricName}" + IDictionary metrics = new Dictionary(); + string functionName = LoggingConstants.Unknown; + + // build up the collection of metrics to send + foreach (KeyValuePair value in values) + { + switch (value.Key) + { + case LoggingKeys.Name: + functionName = value.Value.ToString(); + break; + case LoggingKeys.Timestamp: + case LoggingKeys.OriginalFormat: + // Timestamp is created automatically + // We won't use the format string here + break; + default: + if (value.Value is TimeSpan) + { + // if it's a TimeSpan, log the milliseconds + metrics.Add(value.Key, ((TimeSpan)value.Value).TotalMilliseconds); + } + else if (value.Value is double || value.Value is int) + { + metrics.Add(value.Key, Convert.ToDouble(value.Value)); + } + + // do nothing otherwise + break; + } + } + + foreach (KeyValuePair metric in metrics) + { + _telemetryClient.TrackMetric($"{functionName} {metric.Key}", metric.Value); + } + } + + private void LogFunctionResult(IEnumerable> values, Exception exception) + { + IDictionary scopeProps = DictionaryLoggerScope.GetMergedStateDictionary() ?? new Dictionary(); + + RequestTelemetry requestTelemetry = new RequestTelemetry(); + requestTelemetry.Success = exception == null; + requestTelemetry.ResponseCode = "0"; + + // Set ip address to zeroes. If we find HttpRequest details below, we will update this + requestTelemetry.Context.Location.Ip = LoggingConstants.ZeroIpAddress; + + ApplyFunctionResultProperties(requestTelemetry, values); + + // Functions attaches the HttpRequest, which allows us to log richer request details. + object request; + if (scopeProps.TryGetValue(ScopeKeys.HttpRequest, out request)) + { + ApplyHttpRequestProperties(requestTelemetry, request as HttpRequestMessage); + } + + // log associated exception details + if (exception != null) + { + ExceptionTelemetry exceptionTelemetry = new ExceptionTelemetry(exception); + _telemetryClient.TrackException(exceptionTelemetry); + } + + _telemetryClient.TrackRequest(requestTelemetry); + } + + private static void ApplyHttpRequestProperties(RequestTelemetry requestTelemetry, HttpRequestMessage request) + { + if (request == null) + { + return; + } + + requestTelemetry.Url = new Uri(request.RequestUri.GetLeftPart(UriPartial.Path)); + requestTelemetry.Properties[LoggingKeys.HttpMethod] = request.Method.ToString(); + + requestTelemetry.Context.Location.Ip = GetIpAddress(request); + requestTelemetry.Context.User.UserAgent = request.Headers.UserAgent?.ToString(); + + HttpResponseMessage response = GetResponse(request); + + // If a function throws an exception, we don't get a response attached to the request. + // In that case, we'll consider it a 500. + if (response?.StatusCode != null) + { + requestTelemetry.ResponseCode = ((int)response.StatusCode).ToString(); + } + else + { + requestTelemetry.ResponseCode = "500"; + } + } + + private static void ApplyFunctionResultProperties(RequestTelemetry requestTelemetry, IEnumerable> stateValues) + { + // Build up the telemetry model. Some values special and go right on the telemetry object. All others + // are added to the Properties bag. + foreach (KeyValuePair prop in stateValues) + { + switch (prop.Key) + { + case LoggingKeys.Name: + requestTelemetry.Name = prop.Value.ToString(); + break; + case LoggingKeys.InvocationId: + requestTelemetry.Id = prop.Value.ToString(); + break; + case LoggingKeys.StartTime: + DateTimeOffset startTime = new DateTimeOffset((DateTime)prop.Value, TimeSpan.Zero); + requestTelemetry.Timestamp = startTime; + requestTelemetry.Properties.Add(prop.Key, startTime.ToString(DateTimeFormatString)); + break; + case LoggingKeys.Duration: + if (prop.Value is TimeSpan) + { + requestTelemetry.Duration = (TimeSpan)prop.Value; + } + break; + case LoggingKeys.OriginalFormat: + // this is the format string; we won't use it here + break; + default: + if (prop.Value is DateTime) + { + DateTimeOffset date = new DateTimeOffset((DateTime)prop.Value, TimeSpan.Zero); + requestTelemetry.Properties.Add(prop.Key, date.ToString(DateTimeFormatString)); + } + else + { + requestTelemetry.Properties.Add(prop.Key, prop.Value?.ToString()); + } + break; + } + } + } + + public bool IsEnabled(LogLevel logLevel) + { + if (_filter == null) + { + return true; + } + + return _filter(_categoryName, logLevel); + } + + public IDisposable BeginScope(TState state) + { + if (state == null) + { + throw new ArgumentNullException(nameof(state)); + } + + return DictionaryLoggerScope.Push(state); + } + + internal static string GetIpAddress(HttpRequestMessage httpRequest) + { + // first check for X-Forwarded-For; used by load balancers + IEnumerable headers; + if (httpRequest.Headers.TryGetValues(ScopeKeys.ForwardedForHeaderName, out headers)) + { + string ip = headers.FirstOrDefault(); + if (!string.IsNullOrWhiteSpace(ip)) + { + return RemovePort(ip); + } + } + + HttpContextBase context = httpRequest.Properties.GetValueOrDefault(ScopeKeys.HttpContext); + return context?.Request?.UserHostAddress ?? LoggingConstants.ZeroIpAddress; + } + + private static string RemovePort(string address) + { + // For Web sites in Azure header contains ip address with port e.g. 50.47.87.223:54464 + int portSeparatorIndex = address.IndexOf(":", StringComparison.OrdinalIgnoreCase); + + if (portSeparatorIndex > 0) + { + return address.Substring(0, portSeparatorIndex); + } + + return address; + } + + internal static HttpResponseMessage GetResponse(HttpRequestMessage httpRequest) + { + // Grab the response stored by functions + return httpRequest.Properties.GetValueOrDefault(ScopeKeys.FunctionsHttpResponse); + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ApplicationInsightsLoggerExtensions.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ApplicationInsightsLoggerExtensions.cs new file mode 100644 index 00000000..a247004b --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ApplicationInsightsLoggerExtensions.cs @@ -0,0 +1,63 @@ +// 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 Microsoft.ApplicationInsights; +using Microsoft.ApplicationInsights.WindowsServer.Channel.Implementation; +using Microsoft.Azure.WebJobs.Host.Loggers; + +namespace Microsoft.Extensions.Logging +{ + /// + /// Extensions for adding the to an . + /// + [CLSCompliant(false)] + public static class ApplicationInsightsLoggerExtensions + { + /// + /// Registers an with an . + /// + /// The factory. + /// The Application Insights instrumentation key. + /// A filter that returns true if a message with the specified + /// and category should be logged. You can use + /// or write a custom filter. + /// A for chaining additional operations. + public static ILoggerFactory AddApplicationInsights( + this ILoggerFactory loggerFactory, + string instrumentationKey, + Func filter) + { + return AddApplicationInsights(loggerFactory, instrumentationKey, filter, new DefaultTelemetryClientFactory(), + new SamplingPercentageEstimatorSettings()); + } + + /// + /// Registers an with an . + /// + /// The factory. + /// The Application Insights instrumentation key. + /// A filter that returns true if a message with the specified + /// and category should be logged. You can use + /// or write a custom filter. + /// The factory to use when creating the + /// The adaptive sampling settings, or null to disable sampling. + /// A for chaining additional operations. + public static ILoggerFactory AddApplicationInsights( + this ILoggerFactory loggerFactory, + string instrumentationKey, + Func filter, + ITelemetryClientFactory telemetryClientFactory, + SamplingPercentageEstimatorSettings samplingSettings) + { + if (loggerFactory == null) + { + throw new ArgumentNullException(nameof(loggerFactory)); + } + + loggerFactory.AddProvider(new ApplicationInsightsLoggerProvider(instrumentationKey, filter, telemetryClientFactory, samplingSettings)); + + return loggerFactory; + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ApplicationInsightsLoggerProvider.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ApplicationInsightsLoggerProvider.cs new file mode 100644 index 00000000..4ff4d2b6 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ApplicationInsightsLoggerProvider.cs @@ -0,0 +1,34 @@ +// 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 Microsoft.ApplicationInsights; +using Microsoft.ApplicationInsights.WindowsServer.Channel.Implementation; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host.Loggers +{ + internal class ApplicationInsightsLoggerProvider : ILoggerProvider + { + private readonly TelemetryClient _client; + private readonly Func _filter; + + public ApplicationInsightsLoggerProvider(string instrumentationKey, Func filter, + ITelemetryClientFactory clientFactory, SamplingPercentageEstimatorSettings samplingSettings) + { + if (instrumentationKey == null) + { + throw new ArgumentNullException(nameof(instrumentationKey)); + } + + _client = clientFactory.Create(instrumentationKey, samplingSettings); + _filter = filter; + } + + public ILogger CreateLogger(string categoryName) => new ApplicationInsightsLogger(_client, categoryName, _filter); + + public void Dispose() + { + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ApplicationInsightsScope.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ApplicationInsightsScope.cs new file mode 100644 index 00000000..a5704764 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ApplicationInsightsScope.cs @@ -0,0 +1,75 @@ +// 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.Threading; + +namespace Microsoft.Azure.WebJobs.Host.Loggers +{ + internal class DictionaryLoggerScope + { + private readonly object _state; + + private DictionaryLoggerScope(object state, DictionaryLoggerScope parent) + { + _state = state; + Parent = parent; + } + + internal DictionaryLoggerScope Parent { get; private set; } + + private static AsyncLocal _value = new AsyncLocal(); + + public static DictionaryLoggerScope Current + { + get + { + return _value.Value; + } + set + { + _value.Value = value; + } + } + + public static IDisposable Push(object state) + { + Current = new DictionaryLoggerScope(state, Current); + return new DisposableScope(); + } + + // Builds a state dictionary of all scopes. If an inner scope + // contains the same key as an outer scope, it overwrites the value. + public static IDictionary GetMergedStateDictionary() + { + IDictionary scopeInfo = new Dictionary(); + + var current = Current; + while (current != null) + { + foreach (var entry in current.GetStateDictionary()) + { + // inner scopes win + if (!scopeInfo.Keys.Contains(entry.Key)) + { + scopeInfo.Add(entry); + } + } + current = current.Parent; + } + + return scopeInfo; + } + + private IDictionary GetStateDictionary() => _state as IDictionary; + + private class DisposableScope : IDisposable + { + public void Dispose() + { + Current = Current.Parent; + } + } + } +} \ No newline at end of file diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/DefaultTelemetryClientFactory.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/DefaultTelemetryClientFactory.cs new file mode 100644 index 00000000..48c85083 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/DefaultTelemetryClientFactory.cs @@ -0,0 +1,96 @@ +// 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.Reflection; +using Microsoft.ApplicationInsights; +using Microsoft.ApplicationInsights.Extensibility; +using Microsoft.ApplicationInsights.Extensibility.Implementation; +using Microsoft.ApplicationInsights.Extensibility.PerfCounterCollector; +using Microsoft.ApplicationInsights.Extensibility.PerfCounterCollector.QuickPulse; +using Microsoft.ApplicationInsights.WindowsServer; +using Microsoft.ApplicationInsights.WindowsServer.Channel.Implementation; +using Microsoft.ApplicationInsights.WindowsServer.TelemetryChannel; + +namespace Microsoft.Azure.WebJobs.Host.Loggers +{ + /// + /// Creates a for use by the . + /// + [CLSCompliant(false)] + public class DefaultTelemetryClientFactory : ITelemetryClientFactory + { + /// + /// Creates a . + /// + /// The instance. + public TelemetryClient Create(string instrumentationKey, SamplingPercentageEstimatorSettings samplingSettings) + { + TelemetryConfiguration config = InitializeConfiguration(instrumentationKey, samplingSettings); + + TelemetryClient client = new TelemetryClient(config); + + string assemblyVersion = GetAssemblyFileVersion(typeof(JobHost).Assembly); + client.Context.GetInternalContext().SdkVersion = $"webjobs: {assemblyVersion}"; + + return client; + } + + internal static string GetAssemblyFileVersion(Assembly assembly) + { + AssemblyFileVersionAttribute fileVersionAttr = assembly.GetCustomAttribute(); + return fileVersionAttr?.Version ?? LoggingConstants.Unknown; + } + + internal static TelemetryConfiguration InitializeConfiguration(string instrumentationKey, + SamplingPercentageEstimatorSettings samplingSettings) + { + TelemetryConfiguration config = new TelemetryConfiguration(); + config.InstrumentationKey = instrumentationKey; + + AddInitializers(config); + + // Plug in Live stream and adaptive sampling + QuickPulseTelemetryProcessor processor = null; + TelemetryProcessorChainBuilder builder = config.TelemetryProcessorChainBuilder + .Use((next) => + { + processor = new QuickPulseTelemetryProcessor(next); + return processor; + }); + + if (samplingSettings != null) + { + builder.Use((next) => + { + return new AdaptiveSamplingTelemetryProcessor(samplingSettings, null, next); + }); + } + + builder.Build(); + + QuickPulseTelemetryModule quickPulse = new QuickPulseTelemetryModule(); + quickPulse.Initialize(config); + quickPulse.RegisterTelemetryProcessor(processor); + + // Plug in perf counters + PerformanceCollectorModule perfCounterCollectorModule = new PerformanceCollectorModule(); + perfCounterCollectorModule.Initialize(config); + + ServerTelemetryChannel channel = new ServerTelemetryChannel(); + channel.Initialize(config); + config.TelemetryChannel = channel; + + return config; + } + + internal static void AddInitializers(TelemetryConfiguration config) + { + // This picks up the RoleName from the server + config.TelemetryInitializers.Add(new AzureWebAppRoleEnvironmentTelemetryInitializer()); + + // This applies our special scope properties and gets RoleInstance name + config.TelemetryInitializers.Add(new WebJobsTelemetryInitializer()); + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ITelemetryClientFactory.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ITelemetryClientFactory.cs new file mode 100644 index 00000000..81080e36 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/ITelemetryClientFactory.cs @@ -0,0 +1,24 @@ +// 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 Microsoft.ApplicationInsights; +using Microsoft.ApplicationInsights.WindowsServer.Channel.Implementation; + +namespace Microsoft.Azure.WebJobs.Host.Loggers +{ + /// + /// Interface for creating instances. + /// + [CLSCompliant(false)] + public interface ITelemetryClientFactory + { + /// + /// Creates a . + /// + /// The Application Insights instrumentation key. + /// The sampling settings, or null to disable sampling. + /// The . + TelemetryClient Create(string instrumentationKey, SamplingPercentageEstimatorSettings samplingSettings); + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/WebJobsTelemetryInitializer.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/WebJobsTelemetryInitializer.cs new file mode 100644 index 00000000..033adcbc --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/ApplicationInsights/WebJobsTelemetryInitializer.cs @@ -0,0 +1,56 @@ +// 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 Microsoft.ApplicationInsights.Channel; +using Microsoft.ApplicationInsights.DataContracts; +using Microsoft.ApplicationInsights.Extensibility; + +namespace Microsoft.Azure.WebJobs.Host.Loggers +{ + internal class WebJobsTelemetryInitializer : ITelemetryInitializer + { + private const string ComputerNameKey = "COMPUTERNAME"; + + private static string _roleInstanceName = GetRoleInstanceName(); + + public void Initialize(ITelemetry telemetry) + { + if (telemetry == null) + { + return; + } + + telemetry.Context.Cloud.RoleInstance = _roleInstanceName; + + // Zero out all IP addresses other than Requests + if (!(telemetry is RequestTelemetry)) + { + telemetry.Context.Location.Ip = LoggingConstants.ZeroIpAddress; + } + + // Apply our special scope properties + IDictionary scopeProps = DictionaryLoggerScope.GetMergedStateDictionary() ?? new Dictionary(); + + Guid invocationId = scopeProps.GetValueOrDefault(ScopeKeys.FunctionInvocationId); + if (invocationId != default(Guid)) + { + telemetry.Context.Operation.Id = invocationId.ToString(); + } + + telemetry.Context.Operation.Name = scopeProps.GetValueOrDefault(ScopeKeys.FunctionName); + } + + private static string GetRoleInstanceName() + { + string instanceName = Environment.GetEnvironmentVariable(WebSitesKnownKeyNames.WebSiteInstanceIdKey); + if (string.IsNullOrEmpty(instanceName)) + { + instanceName = Environment.GetEnvironmentVariable(ComputerNameKey); + } + + return instanceName; + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Constants/LogCategories.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Constants/LogCategories.cs new file mode 100644 index 00000000..4282deb0 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Constants/LogCategories.cs @@ -0,0 +1,51 @@ +// 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.Host.Loggers +{ + /// + /// Constant values for log categories. + /// + public static class LogCategories + { + /// + /// The category for all logs written by the function host during startup and shutdown. This + /// includes indexing and configuration logs. + /// + public const string Startup = "Host.Startup"; + + /// + /// The category for all logs written by the Singleton infrastructure. + /// + public const string Singleton = "Host.Singleton"; + + /// + /// The category for all logs written by the function executor. + /// + public const string Executor = "Host.Executor"; + + /// + /// The category for logs written by the function aggregator. + /// + public const string Aggregator = "Host.Aggregator"; + + /// + /// The category for function results. + /// + public const string Results = "Host.Results"; + + /// + /// The category for logs written from within user functions. + /// + public const string Function = "Function"; + + /// + /// Returns a logging category like "Host.Triggers.{triggerName}". + /// + /// The trigger name. + public static string CreateTriggerCategory(string triggerName) + { + return $"Host.Triggers.{triggerName}"; + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Constants/LoggingConstants.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Constants/LoggingConstants.cs new file mode 100644 index 00000000..9788ffd4 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Constants/LoggingConstants.cs @@ -0,0 +1,11 @@ +// 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.Host.Loggers +{ + internal static class LoggingConstants + { + public const string ZeroIpAddress = "0.0.0.0"; + public const string Unknown = "[Unknown]"; + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Constants/LoggingKeys.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Constants/LoggingKeys.cs new file mode 100644 index 00000000..65665983 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Constants/LoggingKeys.cs @@ -0,0 +1,32 @@ +// 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.Host.Loggers +{ + internal static class LoggingKeys + { + // These are publicly visible as property names or prefixes + public const string FullName = "FullName"; + public const string Name = "Name"; + public const string Count = "Count"; + public const string Successes = "Successes"; + public const string Failures = "Failures"; + public const string SuccessRate = "SuccessRate"; + public const string AvgDuration = "AvgDurationMs"; + public const string MaxDuration = "MaxDurationMs"; + public const string MinDuration = "MinDurationMs"; + public const string Timestamp = "Timestamp"; + public const string InvocationId = "InvocationId"; + public const string TriggerReason = "TriggerReason"; + public const string StartTime = "StartTime"; + public const string EndTime = "EndTime"; + public const string Duration = "Duration"; + public const string Succeeded = "Succeeded"; + public const string FormattedMessage = "FormattedMessage"; + public const string CategoryName = "Category"; + public const string HttpMethod = "HttpMethod"; + public const string CustomPropertyPrefix = "prop__"; + public const string ParameterPrefix = "param__"; + public const string OriginalFormat = "{OriginalFormat}"; + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Constants/ScopeKeys.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Constants/ScopeKeys.cs new file mode 100644 index 00000000..12150dd5 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/Constants/ScopeKeys.cs @@ -0,0 +1,21 @@ +// 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.Host.Loggers +{ + internal static class ScopeKeys + { + // These are used internally for passing values via scopes + public const string FunctionInvocationId = "MS_FunctionInvocationId"; + public const string FunctionName = "MS_FunctionName"; + public const string HttpRequest = "MS_HttpRequest"; + + // HTTP context is set automatically by ASP.NET, this isn't ours. + internal const string HttpContext = "MS_HttpContext"; + + // This is set by Functions + internal const string FunctionsHttpResponse = "MS_AzureFunctionsHttpResponse"; + + internal const string ForwardedForHeaderName = "X-Forwarded-For"; + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/LogCategoryFilter.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/LogCategoryFilter.cs new file mode 100644 index 00000000..3d5096d3 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/LogCategoryFilter.cs @@ -0,0 +1,56 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using System.Collections.Generic; +using System.Linq; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host.Loggers +{ + /// + /// Provides a filter for use with an . + /// + [System.CLSCompliant(false)] + public class LogCategoryFilter + { + /// + /// The minimum required for logs with categories that do not match + /// any category in . + /// + public LogLevel DefaultLevel { get; set; } = LogLevel.Information; + + /// + /// A collection of filters that are used by to determine if a log + /// will be written or filtered. + /// + public IDictionary CategoryLevels { get; } = new Dictionary { }; + + /// + /// Pass this function as a filter parameter to a to enable filtering + /// based on the specified . The filter will match the longest possible key in + /// and return true if the level is equal to or greater than the filter. If + /// there is no match, the value of is used. + /// + /// The category of the current log message. + /// The of the current log message. + /// True if the level is equal to or greater than the matched filter. Otherwise, false. + public bool Filter(string category, LogLevel level) + { + // find the longest loglevel that matches the category + IEnumerable matches = CategoryLevels.Keys.Where(k => category.StartsWith(k, System.StringComparison.CurrentCulture)); + string longestMatch = matches?.Max(); + + LogLevel requestedLevel; + if (string.IsNullOrEmpty(longestMatch)) + { + requestedLevel = DefaultLevel; + } + else + { + requestedLevel = CategoryLevels[longestMatch]; + } + + return level >= requestedLevel; + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/LogValueCollection.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/LogValueCollection.cs new file mode 100644 index 00000000..ffe6fa95 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/LogValueCollection.cs @@ -0,0 +1,80 @@ +// 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; +using System.Collections.Generic; +using System.Linq; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Internal; + +namespace Microsoft.Azure.WebJobs.Host.Loggers +{ + /// + /// The object created by the framework extensions + /// (LogInformation(), for example) require that all key-value pairs be included in the string message + /// passed to the method. We'd like to have short strings with a subset of the data, so this class wraps + /// and allows us to use the same behavior, but with an additional + /// payload not included in the message. + /// + internal class FormattedLogValuesCollection : IReadOnlyList> + { + private FormattedLogValues _formatter; + private IReadOnlyList> _additionalValues; + + public FormattedLogValuesCollection(string format, object[] formatValues, IReadOnlyDictionary additionalValues) + { + if (formatValues != null) + { + _formatter = new FormattedLogValues(format, formatValues); + } + else + { + _formatter = new FormattedLogValues(format); + } + + _additionalValues = additionalValues?.ToList(); + + if (_additionalValues == null) + { + _additionalValues = new List>(); + } + } + + public int Count => _formatter.Count + _additionalValues.Count; + + public KeyValuePair this[int index] + { + get + { + if (index < 0 || index >= Count) + { + throw new ArgumentOutOfRangeException(nameof(index)); + } + + if (index < _additionalValues.Count) + { + // if the index is lower, return the value from _additionalValues + return _additionalValues[index]; + } + else + { + // if there are no more additionalValues, return from _formatter + return _formatter[index - _additionalValues.Count]; + } + } + } + + public IEnumerator> GetEnumerator() + { + for (int i = 0; i < Count; ++i) + { + yield return this[i]; + } + } + + IEnumerator IEnumerable.GetEnumerator() => GetEnumerator(); + + public override string ToString() => _formatter.ToString(); + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/LoggerExtensions.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/LoggerExtensions.cs new file mode 100644 index 00000000..cf378218 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/LoggerExtensions.cs @@ -0,0 +1,67 @@ +// 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.Collections.ObjectModel; +using Microsoft.Azure.WebJobs.Host.Executors; +using Microsoft.Azure.WebJobs.Host.Loggers; + +namespace Microsoft.Extensions.Logging +{ + internal static class LoggerExtensions + { + // We want the short name for use with Application Insights. + internal static void LogFunctionResult(this ILogger logger, string shortName, FunctionInstanceLogEntry logEntry, TimeSpan duration, Exception exception = null) + { + bool succeeded = exception == null; + + // build the string and values + string result = succeeded ? "Succeeded" : "Failed"; + string logString = $"Executed '{{{LoggingKeys.FullName}}}' ({result}, Id={{{LoggingKeys.InvocationId}}})"; + object[] values = new object[] + { + logEntry.FunctionName, + logEntry.FunctionInstanceId + }; + + // generate additional payload that is not in the string + IDictionary properties = new Dictionary(); + properties.Add(LoggingKeys.Name, shortName); + properties.Add(LoggingKeys.TriggerReason, logEntry.TriggerReason); + properties.Add(LoggingKeys.StartTime, logEntry.StartTime); + properties.Add(LoggingKeys.EndTime, logEntry.EndTime); + properties.Add(LoggingKeys.Duration, duration); + properties.Add(LoggingKeys.Succeeded, succeeded); + + if (logEntry.Arguments != null) + { + foreach (var arg in logEntry.Arguments) + { + properties.Add(LoggingKeys.ParameterPrefix + arg.Key, arg.Value); + } + } + + FormattedLogValuesCollection payload = new FormattedLogValuesCollection(logString, values, new ReadOnlyDictionary(properties)); + LogLevel level = succeeded ? LogLevel.Information : LogLevel.Error; + logger.Log(level, 0, payload, exception, (s, e) => s.ToString()); + } + + internal static void LogFunctionResultAggregate(this ILogger logger, FunctionResultAggregate resultAggregate) + { + // we won't output any string here, just the data + FormattedLogValuesCollection payload = new FormattedLogValuesCollection(string.Empty, null, resultAggregate.ToReadOnlyDictionary()); + logger.Log(LogLevel.Information, 0, payload, null, (s, e) => s.ToString()); + } + + internal static IDisposable BeginFunctionScope(this ILogger logger, IFunctionInstance functionInstance) + { + return logger?.BeginScope( + new Dictionary + { + [ScopeKeys.FunctionInvocationId] = functionInstance?.Id, + [ScopeKeys.FunctionName] = functionInstance?.FunctionDescriptor?.Method?.Name + }); + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/TraceWriter/LoggerTraceWriter.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/TraceWriter/LoggerTraceWriter.cs new file mode 100644 index 00000000..b362f386 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/Logger/TraceWriter/LoggerTraceWriter.cs @@ -0,0 +1,66 @@ +// 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.ObjectModel; +using System.Diagnostics; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host.Loggers +{ + /// + /// A wrapper around an . + /// + internal class LoggerTraceWriter : TraceWriter + { + private ILogger _logger; + + /// + /// Creates an instance. + /// + /// The to use when filtering logs. + /// The used to log the traces. + public LoggerTraceWriter(TraceLevel level, ILogger logger) + : base(level) + { + _logger = logger; + } + + /// + public override void Trace(TraceEvent traceEvent) + { + if (traceEvent == null) + { + throw new ArgumentNullException(nameof(traceEvent)); + } + + if (traceEvent.Level > Level) + { + return; + } + + LogLevel level = GetLogLevel(traceEvent.Level); + FormattedLogValuesCollection logState = new FormattedLogValuesCollection(traceEvent.Message, null, new ReadOnlyDictionary(traceEvent.Properties)); + _logger.Log(level, 0, logState, traceEvent.Exception, (s, e) => s.ToString()); + } + + internal static LogLevel GetLogLevel(TraceLevel traceLevel) + { + switch (traceLevel) + { + case TraceLevel.Off: + return LogLevel.None; + case TraceLevel.Error: + return LogLevel.Error; + case TraceLevel.Warning: + return LogLevel.Warning; + case TraceLevel.Info: + return LogLevel.Information; + case TraceLevel.Verbose: + return LogLevel.Debug; + default: + throw new InvalidOperationException($"'{traceLevel}' is not a valid level."); + } + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/UpdateParameterLogCommand.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/UpdateParameterLogCommand.cs index c9fee701..117863bb 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Loggers/UpdateParameterLogCommand.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/UpdateParameterLogCommand.cs @@ -9,6 +9,7 @@ using Microsoft.Azure.WebJobs.Host.Bindings; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.Storage.Blob; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; using Newtonsoft.Json; namespace Microsoft.Azure.WebJobs.Host.Loggers @@ -18,11 +19,12 @@ namespace Microsoft.Azure.WebJobs.Host.Loggers private readonly IReadOnlyDictionary _watches; private readonly IStorageBlockBlob _parameterLogBlob; private readonly TraceWriter _trace; + private readonly ILogger _logger; private string _lastContent; public UpdateParameterLogCommand(IReadOnlyDictionary watches, - IStorageBlockBlob parameterLogBlob, TraceWriter trace) + IStorageBlockBlob parameterLogBlob, TraceWriter trace, ILogger logger) { if (parameterLogBlob == null) { @@ -39,6 +41,7 @@ namespace Microsoft.Azure.WebJobs.Host.Loggers _parameterLogBlob = parameterLogBlob; _trace = trace; + _logger = logger; _watches = watches; } @@ -91,7 +94,9 @@ namespace Microsoft.Azure.WebJobs.Host.Loggers { // Not fatal if we can't update parameter status. // But at least log what happened for diagnostics in case it's an infrastructure bug. - _trace.Error("---- Parameter status update failed ----", e, TraceSource.Execution); + string msg = "---- Parameter status update failed ----"; + _trace.Error(msg, e, TraceSource.Execution); + _logger?.LogError(0, e, msg); return false; } } diff --git a/src/Microsoft.Azure.WebJobs.Host/Queues/Listeners/HostMessageListenerFactory.cs b/src/Microsoft.Azure.WebJobs.Host/Queues/Listeners/HostMessageListenerFactory.cs index 83fd4e61..48bd29f4 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Queues/Listeners/HostMessageListenerFactory.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Queues/Listeners/HostMessageListenerFactory.cs @@ -10,6 +10,7 @@ using Microsoft.Azure.WebJobs.Host.Listeners; using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Storage.Queue; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners { @@ -19,6 +20,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners private readonly IQueueConfiguration _queueConfiguration; private readonly IWebJobsExceptionHandler _exceptionHandler; private readonly TraceWriter _trace; + private readonly ILoggerFactory _loggerFactory; private readonly IFunctionIndexLookup _functionLookup; private readonly IFunctionInstanceLogger _functionInstanceLogger; private readonly IFunctionExecutor _executor; @@ -27,6 +29,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners IQueueConfiguration queueConfiguration, IWebJobsExceptionHandler exceptionHandler, TraceWriter trace, + ILoggerFactory loggerFactory, IFunctionIndexLookup functionLookup, IFunctionInstanceLogger functionInstanceLogger, IFunctionExecutor executor) @@ -70,6 +73,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners _queueConfiguration = queueConfiguration; _exceptionHandler = exceptionHandler; _trace = trace; + _loggerFactory = loggerFactory; _functionLookup = functionLookup; _functionInstanceLogger = functionInstanceLogger; _executor = executor; @@ -89,6 +93,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners triggerExecutor: triggerExecutor, exceptionHandler: _exceptionHandler, trace: _trace, + loggerFactory: _loggerFactory, sharedWatcher: null, queueConfiguration: _queueConfiguration, maxPollingInterval: maxPollingInterval); diff --git a/src/Microsoft.Azure.WebJobs.Host/Queues/Listeners/QueueListener.cs b/src/Microsoft.Azure.WebJobs.Host/Queues/Listeners/QueueListener.cs index 1990fe46..cb2439ff 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Queues/Listeners/QueueListener.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Queues/Listeners/QueueListener.cs @@ -11,6 +11,7 @@ using Microsoft.Azure.WebJobs.Host.Listeners; using Microsoft.Azure.WebJobs.Host.Storage; using Microsoft.Azure.WebJobs.Host.Storage.Queue; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage; using Microsoft.WindowsAzure.Storage.Queue; @@ -24,7 +25,6 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners private readonly IStorageQueue _poisonQueue; private readonly ITriggerExecutor _triggerExecutor; private readonly IWebJobsExceptionHandler _exceptionHandler; - private readonly TraceWriter _trace; private readonly IMessageEnqueuedWatcher _sharedWatcher; private readonly List _processing = new List(); private readonly object _stopWaitingTaskSourceLock = new object(); @@ -41,6 +41,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners ITriggerExecutor triggerExecutor, IWebJobsExceptionHandler exceptionHandler, TraceWriter trace, + ILoggerFactory loggerFactory, SharedQueueWatcher sharedWatcher, IQueueConfiguration queueConfiguration, QueueProcessor queueProcessor = null, @@ -71,7 +72,6 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners _poisonQueue = poisonQueue; _triggerExecutor = triggerExecutor; _exceptionHandler = exceptionHandler; - _trace = trace; _queueConfiguration = queueConfiguration; // if the function runs longer than this, the invisibility will be updated @@ -88,7 +88,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners EventHandler poisonMessageEventHandler = _sharedWatcher != null ? OnMessageAddedToPoisonQueue : (EventHandler)null; _queueProcessor = queueProcessor ?? CreateQueueProcessor( _queue.SdkObject, _poisonQueue != null ? _poisonQueue.SdkObject : null, - _trace, _queueConfiguration, poisonMessageEventHandler); + trace, loggerFactory, _queueConfiguration, poisonMessageEventHandler); TimeSpan maximumInterval = _queueProcessor.MaxPollingInterval; if (maxPollingInterval.HasValue && maximumInterval > maxPollingInterval.Value) @@ -309,9 +309,10 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners } } - internal static QueueProcessor CreateQueueProcessor(CloudQueue queue, CloudQueue poisonQueue, TraceWriter trace, IQueueConfiguration queueConfig, EventHandler poisonQueueMessageAddedHandler) + internal static QueueProcessor CreateQueueProcessor(CloudQueue queue, CloudQueue poisonQueue, TraceWriter trace, ILoggerFactory loggerFactory, + IQueueConfiguration queueConfig, EventHandler poisonQueueMessageAddedHandler) { - QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(queue, trace, queueConfig, poisonQueue); + QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(queue, trace, loggerFactory, queueConfig, poisonQueue); QueueProcessor queueProcessor = null; if (HostQueueNames.IsHostQueue(queue.Name) && diff --git a/src/Microsoft.Azure.WebJobs.Host/Queues/Listeners/QueueListenerFactory.cs b/src/Microsoft.Azure.WebJobs.Host/Queues/Listeners/QueueListenerFactory.cs index d7c2ab50..1c6e56ed 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Queues/Listeners/QueueListenerFactory.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Queues/Listeners/QueueListenerFactory.cs @@ -9,6 +9,7 @@ using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Listeners; using Microsoft.Azure.WebJobs.Host.Storage.Queue; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners { @@ -23,6 +24,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners private readonly IContextSetter _messageEnqueuedWatcherSetter; private readonly ISharedContextProvider _sharedContextProvider; private readonly TraceWriter _trace; + private readonly ILoggerFactory _loggerFactory; private readonly ITriggeredFunctionExecutor _executor; public QueueListenerFactory(IStorageQueue queue, @@ -31,6 +33,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners IContextSetter messageEnqueuedWatcherSetter, ISharedContextProvider sharedContextProvider, TraceWriter trace, + ILoggerFactory loggerFactory, ITriggeredFunctionExecutor executor) { if (queue == null) @@ -75,6 +78,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners _messageEnqueuedWatcherSetter = messageEnqueuedWatcherSetter; _sharedContextProvider = sharedContextProvider; _trace = trace; + _loggerFactory = loggerFactory; _executor = executor; } @@ -87,7 +91,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Listeners new SharedQueueWatcherFactory(_messageEnqueuedWatcherSetter)); IListener listener = new QueueListener(_queue, _poisonQueue, triggerExecutor, - _exceptionHandler, _trace, sharedWatcher, _queueConfiguration); + _exceptionHandler, _trace, _loggerFactory, sharedWatcher, _queueConfiguration); return Task.FromResult(listener); } diff --git a/src/Microsoft.Azure.WebJobs.Host/Queues/QueueProcessor.cs b/src/Microsoft.Azure.WebJobs.Host/Queues/QueueProcessor.cs index 5cedc685..201618c9 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Queues/QueueProcessor.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Queues/QueueProcessor.cs @@ -8,6 +8,7 @@ using System.Threading; using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Storage; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage; using Microsoft.WindowsAzure.Storage.Queue; @@ -26,6 +27,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues private readonly CloudQueue _queue; private readonly CloudQueue _poisonQueue; private readonly TraceWriter _trace; + private readonly ILogger _logger; /// /// Constructs a new instance. @@ -41,6 +43,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues _queue = context.Queue; _poisonQueue = context.PoisonQueue; _trace = context.Trace; + _logger = context.Logger; MaxDequeueCount = context.MaxDequeueCount; BatchSize = context.BatchSize; @@ -106,7 +109,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues /// The to use /// public virtual async Task CompleteProcessingMessageAsync(CloudQueueMessage message, FunctionResult result, CancellationToken cancellationToken) - { + { if (result.Succeeded) { await DeleteMessageAsync(message, cancellationToken); @@ -140,7 +143,9 @@ namespace Microsoft.Azure.WebJobs.Host.Queues /// protected virtual async Task CopyMessageToPoisonQueueAsync(CloudQueueMessage message, CloudQueue poisonQueue, CancellationToken cancellationToken) { - _trace.Warning(string.Format(CultureInfo.InvariantCulture, "Message has reached MaxDequeueCount of {0}. Moving message to queue '{1}'.", MaxDequeueCount, poisonQueue.Name), TraceSource.Execution); + string msg = string.Format(CultureInfo.InvariantCulture, "Message has reached MaxDequeueCount of {0}. Moving message to queue '{1}'.", MaxDequeueCount, poisonQueue.Name); + _trace.Warning(msg, TraceSource.Execution); + _logger?.LogWarning(msg); await AddMessageAndCreateIfNotExistsAsync(poisonQueue, message, cancellationToken); diff --git a/src/Microsoft.Azure.WebJobs.Host/Queues/QueueProcessorFactoryContext.cs b/src/Microsoft.Azure.WebJobs.Host/Queues/QueueProcessorFactoryContext.cs index f2d6a256..28d28eef 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Queues/QueueProcessorFactoryContext.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Queues/QueueProcessorFactoryContext.cs @@ -2,6 +2,8 @@ // Licensed under the MIT License. See License.txt in the project root for license information. using System; +using Microsoft.Azure.WebJobs.Host.Loggers; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage.Queue; namespace Microsoft.Azure.WebJobs.Host.Queues @@ -17,8 +19,9 @@ namespace Microsoft.Azure.WebJobs.Host.Queues /// /// The the will operate on. /// The to trace events to. + /// The to create an from. /// The queue to move messages to when unable to process a message after the maximum dequeue count has been exceeded. May be null. - public QueueProcessorFactoryContext(CloudQueue queue, TraceWriter trace, CloudQueue poisonQueue = null) + public QueueProcessorFactoryContext(CloudQueue queue, TraceWriter trace, ILoggerFactory loggerFactory, CloudQueue poisonQueue = null) { if (queue == null) { @@ -32,6 +35,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues Queue = queue; PoisonQueue = poisonQueue; Trace = trace; + Logger = loggerFactory?.CreateLogger(LogCategories.CreateTriggerCategory("Queue")); } /// @@ -39,10 +43,11 @@ namespace Microsoft.Azure.WebJobs.Host.Queues /// /// The the will operate on. /// The to write to. + /// The to create an from. /// The queue configuration. /// The queue to move messages to when unable to process a message after the maximum dequeue count has been exceeded. May be null. - internal QueueProcessorFactoryContext(CloudQueue queue, TraceWriter trace, IQueueConfiguration queueConfiguration, CloudQueue poisonQueue = null) - : this(queue, trace, poisonQueue) + internal QueueProcessorFactoryContext(CloudQueue queue, TraceWriter trace, ILoggerFactory loggerFactory, IQueueConfiguration queueConfiguration, CloudQueue poisonQueue = null) + : this(queue, trace, loggerFactory, poisonQueue) { BatchSize = queueConfiguration.BatchSize; MaxDequeueCount = queueConfiguration.MaxDequeueCount; @@ -67,6 +72,11 @@ namespace Microsoft.Azure.WebJobs.Host.Queues /// public TraceWriter Trace { get; private set; } + /// + /// Gets the . + /// + public ILogger Logger { get; private set; } + /// /// Gets or sets the number of queue messages to retrieve and process in parallel (per job method). /// diff --git a/src/Microsoft.Azure.WebJobs.Host/Queues/Triggers/QueueTriggerAttributeBindingProvider.cs b/src/Microsoft.Azure.WebJobs.Host/Queues/Triggers/QueueTriggerAttributeBindingProvider.cs index 53af1ce6..6fa8cbdc 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Queues/Triggers/QueueTriggerAttributeBindingProvider.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Queues/Triggers/QueueTriggerAttributeBindingProvider.cs @@ -10,6 +10,7 @@ using Microsoft.Azure.WebJobs.Host.Storage; using Microsoft.Azure.WebJobs.Host.Storage.Queue; using Microsoft.Azure.WebJobs.Host.Timers; using Microsoft.Azure.WebJobs.Host.Triggers; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage.Queue; namespace Microsoft.Azure.WebJobs.Host.Queues.Triggers @@ -31,6 +32,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Triggers private readonly IContextSetter _messageEnqueuedWatcherSetter; private readonly ISharedContextProvider _sharedContextProvider; private readonly TraceWriter _trace; + private readonly ILoggerFactory _loggerFactory; public QueueTriggerAttributeBindingProvider(INameResolver nameResolver, IStorageAccountProvider accountProvider, @@ -38,7 +40,8 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Triggers IWebJobsExceptionHandler exceptionHandler, IContextSetter messageEnqueuedWatcherSetter, ISharedContextProvider sharedContextProvider, - TraceWriter trace) + TraceWriter trace, + ILoggerFactory loggerFactory) { if (accountProvider == null) { @@ -77,6 +80,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Triggers _messageEnqueuedWatcherSetter = messageEnqueuedWatcherSetter; _sharedContextProvider = sharedContextProvider; _trace = trace; + _loggerFactory = loggerFactory; } public async Task TryCreateAsync(TriggerBindingProviderContext context) @@ -113,7 +117,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Triggers ITriggerBinding binding = new QueueTriggerBinding(parameter.Name, queue, argumentBinding, _queueConfiguration, _exceptionHandler, _messageEnqueuedWatcherSetter, - _sharedContextProvider, _trace); + _sharedContextProvider, _trace, _loggerFactory); return binding; } diff --git a/src/Microsoft.Azure.WebJobs.Host/Queues/Triggers/QueueTriggerBinding.cs b/src/Microsoft.Azure.WebJobs.Host/Queues/Triggers/QueueTriggerBinding.cs index 3a8df573..e17daf89 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Queues/Triggers/QueueTriggerBinding.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Queues/Triggers/QueueTriggerBinding.cs @@ -12,6 +12,7 @@ using Microsoft.Azure.WebJobs.Host.Queues.Listeners; using Microsoft.Azure.WebJobs.Host.Storage.Queue; using Microsoft.Azure.WebJobs.Host.Timers; using Microsoft.Azure.WebJobs.Host.Triggers; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage.Queue; namespace Microsoft.Azure.WebJobs.Host.Queues.Triggers @@ -27,6 +28,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Triggers private readonly IContextSetter _messageEnqueuedWatcherSetter; private readonly ISharedContextProvider _sharedContextProvider; private readonly TraceWriter _trace; + private readonly ILoggerFactory _loggerFactory; private readonly IObjectToTypeConverter _converter; public QueueTriggerBinding(string parameterName, @@ -36,7 +38,8 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Triggers IWebJobsExceptionHandler exceptionHandler, IContextSetter messageEnqueuedWatcherSetter, ISharedContextProvider sharedContextProvider, - TraceWriter trace) + TraceWriter trace, + ILoggerFactory loggerFactory) { if (queue == null) { @@ -82,6 +85,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Triggers _messageEnqueuedWatcherSetter = messageEnqueuedWatcherSetter; _sharedContextProvider = sharedContextProvider; _trace = trace; + _loggerFactory = loggerFactory; _converter = CreateConverter(queue); } @@ -156,8 +160,8 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Triggers throw new ArgumentNullException("context"); } - var factory = new QueueListenerFactory(_queue, _queueConfiguration, _exceptionHandler, - _messageEnqueuedWatcherSetter, _sharedContextProvider, _trace, context.Executor); + var factory = new QueueListenerFactory(_queue, _queueConfiguration, _exceptionHandler, + _messageEnqueuedWatcherSetter, _sharedContextProvider, _trace, _loggerFactory, context.Executor); return factory.CreateAsync(context.CancellationToken); } @@ -191,7 +195,7 @@ namespace Microsoft.Azure.WebJobs.Host.Queues.Triggers bindingData.Add("InsertionTime", value.InsertionTime.GetValueOrDefault(DateTimeOffset.UtcNow)); bindingData.Add("NextVisibleTime", value.NextVisibleTime.GetValueOrDefault(DateTimeOffset.MaxValue)); bindingData.Add("PopReceipt", value.PopReceipt); - + if (bindingDataFromValueType != null) { foreach (KeyValuePair item in bindingDataFromValueType) diff --git a/src/Microsoft.Azure.WebJobs.Host/Singleton/SingletonListener.cs b/src/Microsoft.Azure.WebJobs.Host/Singleton/SingletonListener.cs index 42a1a80e..ec4788c1 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Singleton/SingletonListener.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Singleton/SingletonListener.cs @@ -7,6 +7,8 @@ using System.Reflection; using System.Threading; using System.Threading.Tasks; using System.Timers; +using Microsoft.Azure.WebJobs.Host.Loggers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.Listeners { @@ -17,11 +19,12 @@ namespace Microsoft.Azure.WebJobs.Host.Listeners private readonly SingletonConfiguration _singletonConfig; private readonly IListener _innerListener; private readonly TraceWriter _trace; + private readonly ILogger _logger; private string _lockId; private object _lockHandle; private bool _isListening; - public SingletonListener(MethodInfo method, SingletonAttribute attribute, SingletonManager singletonManager, IListener innerListener, TraceWriter trace) + public SingletonListener(MethodInfo method, SingletonAttribute attribute, SingletonManager singletonManager, IListener innerListener, TraceWriter trace, ILoggerFactory loggerFactory) { _attribute = attribute; _singletonManager = singletonManager; @@ -33,6 +36,7 @@ namespace Microsoft.Azure.WebJobs.Host.Listeners _lockId += ".Listener"; _trace = trace; + _logger = loggerFactory?.CreateLogger(LogCategories.Singleton); } // exposed for testing @@ -47,7 +51,9 @@ namespace Microsoft.Azure.WebJobs.Host.Listeners if (_lockHandle == null) { - _trace.Verbose(string.Format(CultureInfo.InvariantCulture, "Unable to acquire Singleton lock ({0}).", _lockId), source: TraceSource.Execution); + string msg = string.Format(CultureInfo.InvariantCulture, "Unable to acquire Singleton lock ({0}).", _lockId); + _trace.Verbose(msg, source: TraceSource.Execution); + _logger?.LogDebug(msg); // If we're unable to acquire the lock, it means another listener // has it so we return w/o starting our listener. diff --git a/src/Microsoft.Azure.WebJobs.Host/Singleton/SingletonManager.cs b/src/Microsoft.Azure.WebJobs.Host/Singleton/SingletonManager.cs index 3696ceb4..5046a3e5 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Singleton/SingletonManager.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Singleton/SingletonManager.cs @@ -14,10 +14,12 @@ using Microsoft.Azure.WebJobs.Host.Bindings; using Microsoft.Azure.WebJobs.Host.Bindings.Path; using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Listeners; +using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.Storage; using Microsoft.Azure.WebJobs.Host.Storage.Blob; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage; using Microsoft.WindowsAzure.Storage.Blob; @@ -33,6 +35,8 @@ namespace Microsoft.Azure.WebJobs.Host private readonly IWebJobsExceptionHandler _exceptionHandler; private readonly SingletonConfiguration _config; private readonly IStorageAccountProvider _accountProvider; + private readonly ILogger _logger; + private readonly ILoggerFactory _loggerFactory; private ConcurrentDictionary _lockDirectoryMap = new ConcurrentDictionary(StringComparer.OrdinalIgnoreCase); private TimeSpan _minimumLeaseRenewalInterval = TimeSpan.FromSeconds(1); private TraceWriter _trace; @@ -44,13 +48,16 @@ namespace Microsoft.Azure.WebJobs.Host { } - public SingletonManager(IStorageAccountProvider accountProvider, IWebJobsExceptionHandler exceptionHandler, SingletonConfiguration config, TraceWriter trace, IHostIdProvider hostIdProvider, INameResolver nameResolver = null) + public SingletonManager(IStorageAccountProvider accountProvider, IWebJobsExceptionHandler exceptionHandler, SingletonConfiguration config, + TraceWriter trace, ILoggerFactory loggerFactory, IHostIdProvider hostIdProvider, INameResolver nameResolver = null) { _accountProvider = accountProvider; _nameResolver = nameResolver; _exceptionHandler = exceptionHandler; _config = config; _trace = trace; + _loggerFactory = loggerFactory; + _logger = _loggerFactory?.CreateLogger(LogCategories.Singleton); _hostIdProvider = hostIdProvider; } @@ -130,7 +137,9 @@ namespace Microsoft.Azure.WebJobs.Host return null; } - _trace.Verbose(string.Format(CultureInfo.InvariantCulture, "Singleton lock acquired ({0})", lockId), source: TraceSource.Execution); + string msg = string.Format(CultureInfo.InvariantCulture, "Singleton lock acquired ({0})", lockId); + _trace.Verbose(msg, source: TraceSource.Execution); + _logger?.LogDebug(msg); if (!string.IsNullOrEmpty(functionInstanceId)) { @@ -163,7 +172,9 @@ namespace Microsoft.Azure.WebJobs.Host await ReleaseLeaseAsync(singletonLockHandle.Blob, singletonLockHandle.LeaseId, cancellationToken); - _trace.Verbose(string.Format(CultureInfo.InvariantCulture, "Singleton lock released ({0})", singletonLockHandle.LockId), source: TraceSource.Execution); + string msg = string.Format(CultureInfo.InvariantCulture, "Singleton lock released ({0})", singletonLockHandle.LockId); + _trace.Verbose(msg, source: TraceSource.Execution); + _logger?.LogDebug(msg); } public string FormatLockId(MethodInfo method, SingletonScope scope, string scopeId) @@ -251,7 +262,7 @@ namespace Microsoft.Azure.WebJobs.Host { Mode = SingletonMode.Listener }; - return new SingletonListener(null, singletonAttribute, this, innerListener, _trace); + return new SingletonListener(null, singletonAttribute, this, innerListener, _trace, _loggerFactory); } public static SingletonAttribute GetListenerSingletonOrNull(Type listenerType, MethodInfo method) @@ -351,7 +362,7 @@ namespace Microsoft.Azure.WebJobs.Host TimeSpan normalUpdateInterval = new TimeSpan(leasePeriod.Ticks / 2); IDelayStrategy speedupStrategy = new LinearSpeedupStrategy(normalUpdateInterval, MinimumLeaseRenewalInterval); - ITaskSeriesCommand command = new RenewLeaseCommand(leaseBlob, leaseId, lockId, speedupStrategy, _trace, leasePeriod); + ITaskSeriesCommand command = new RenewLeaseCommand(leaseBlob, leaseId, lockId, speedupStrategy, _trace, _logger, leasePeriod); return new TaskSeriesTimer(command, exceptionHandler, Task.Delay(normalUpdateInterval)); } @@ -550,11 +561,13 @@ namespace Microsoft.Azure.WebJobs.Host private readonly string _lockId; private readonly IDelayStrategy _speedupStrategy; private readonly TraceWriter _trace; + private readonly ILogger _logger; private DateTimeOffset _lastRenewal; private TimeSpan _lastRenewalLatency; private TimeSpan _leasePeriod; - public RenewLeaseCommand(IStorageBlockBlob leaseBlob, string leaseId, string lockId, IDelayStrategy speedupStrategy, TraceWriter trace, TimeSpan leasePeriod) + public RenewLeaseCommand(IStorageBlockBlob leaseBlob, string leaseId, string lockId, IDelayStrategy speedupStrategy, TraceWriter trace, + ILogger logger, TimeSpan leasePeriod) { _lastRenewal = DateTimeOffset.UtcNow; _leaseBlob = leaseBlob; @@ -562,6 +575,7 @@ namespace Microsoft.Azure.WebJobs.Host _lockId = lockId; _speedupStrategy = speedupStrategy; _trace = trace; + _logger = logger; _leasePeriod = leasePeriod; } @@ -589,8 +603,10 @@ namespace Microsoft.Azure.WebJobs.Host { // The next execution should occur more quickly (try to renew the lease before it expires). delay = _speedupStrategy.GetNextDelay(executionSucceeded: false); - _trace.Warning(string.Format(CultureInfo.InvariantCulture, "Singleton lock renewal failed for blob '{0}' with error code {1}. Retry renewal in {2} milliseconds.", - _lockId, FormatErrorCode(exception), delay.TotalMilliseconds), source: TraceSource.Execution); + string msg = string.Format(CultureInfo.InvariantCulture, "Singleton lock renewal failed for blob '{0}' with error code {1}. Retry renewal in {2} milliseconds.", + _lockId, FormatErrorCode(exception), delay.TotalMilliseconds); + _trace.Warning(msg, source: TraceSource.Execution); + _logger?.LogWarning(msg); } else { @@ -600,8 +616,10 @@ namespace Microsoft.Azure.WebJobs.Host int millisecondsSinceLastSuccess = (int)(DateTime.UtcNow - _lastRenewal).TotalMilliseconds; int lastRenewalMilliseconds = (int)_lastRenewalLatency.TotalMilliseconds; - _trace.Error(string.Format(CultureInfo.InvariantCulture, "Singleton lock renewal failed for blob '{0}' with error code {1}. The last successful renewal completed at {2} ({3} milliseconds ago) with a duration of {4} milliseconds. The lease period was {5} milliseconds.", - _lockId, FormatErrorCode(exception), lastRenewalFormatted, millisecondsSinceLastSuccess, lastRenewalMilliseconds, leasePeriodMilliseconds)); + string msg = string.Format(CultureInfo.InvariantCulture, "Singleton lock renewal failed for blob '{0}' with error code {1}. The last successful renewal completed at {2} ({3} milliseconds ago) with a duration of {4} milliseconds. The lease period was {5} milliseconds.", + _lockId, FormatErrorCode(exception), lastRenewalFormatted, millisecondsSinceLastSuccess, lastRenewalMilliseconds, leasePeriodMilliseconds); + _trace.Error(msg); + _logger?.LogError(msg); // If we've lost the lease or cannot re-establish it, we want to fail any // in progress function execution diff --git a/src/Microsoft.Azure.WebJobs.Host/WebJobs.Host.csproj b/src/Microsoft.Azure.WebJobs.Host/WebJobs.Host.csproj index 575aa2c9..a09238ee 100644 --- a/src/Microsoft.Azure.WebJobs.Host/WebJobs.Host.csproj +++ b/src/Microsoft.Azure.WebJobs.Host/WebJobs.Host.csproj @@ -54,6 +54,30 @@ ..\Common\PublicKey.snk + + ..\..\packages\Microsoft.ApplicationInsights.Agent.Intercept.2.0.7\lib\net45\Microsoft.AI.Agent.Intercept.dll + True + + + ..\..\packages\Microsoft.ApplicationInsights.DependencyCollector.2.3.0\lib\net45\Microsoft.AI.DependencyCollector.dll + True + + + ..\..\packages\Microsoft.ApplicationInsights.PerfCounterCollector.2.3.0\lib\net45\Microsoft.AI.PerfCounterCollector.dll + True + + + ..\..\packages\Microsoft.ApplicationInsights.WindowsServer.TelemetryChannel.2.3.0\lib\net45\Microsoft.AI.ServerTelemetryChannel.dll + True + + + ..\..\packages\Microsoft.ApplicationInsights.WindowsServer.2.3.0\lib\net45\Microsoft.AI.WindowsServer.dll + True + + + ..\..\packages\Microsoft.ApplicationInsights.2.3.0\lib\net46\Microsoft.ApplicationInsights.dll + True + ..\..\packages\Microsoft.Azure.KeyVault.Core.1.0.0\lib\net40\Microsoft.Azure.KeyVault.Core.dll True @@ -70,6 +94,14 @@ ..\..\packages\Microsoft.Data.Services.Client.5.8.2\lib\net40\Microsoft.Data.Services.Client.dll True + + ..\..\packages\Microsoft.Extensions.Logging.Abstractions.1.1.1\lib\netstandard1.1\Microsoft.Extensions.Logging.Abstractions.dll + True + + + ..\..\packages\Microsoft.Win32.Primitives.4.3.0\lib\net46\Microsoft.Win32.Primitives.dll + True + ..\..\packages\Microsoft.WindowsAzure.ConfigurationManager.3.2.3\lib\net40\Microsoft.WindowsAzure.Configuration.dll True @@ -83,19 +115,90 @@ True + + ..\..\packages\System.AppContext.4.3.0\lib\net46\System.AppContext.dll + True + + + + ..\..\packages\System.Console.4.3.0\lib\net46\System.Console.dll + True + + + ..\..\packages\System.Diagnostics.DiagnosticSource.4.3.0\lib\net46\System.Diagnostics.DiagnosticSource.dll + True + + + ..\..\packages\System.Globalization.Calendars.4.3.0\lib\net46\System.Globalization.Calendars.dll + True + + + ..\..\packages\System.IO.Compression.4.3.0\lib\net46\System.IO.Compression.dll + True + + + + ..\..\packages\System.IO.Compression.ZipFile.4.3.0\lib\net46\System.IO.Compression.ZipFile.dll + True + + + ..\..\packages\System.IO.FileSystem.4.3.0\lib\net46\System.IO.FileSystem.dll + True + + + ..\..\packages\System.IO.FileSystem.Primitives.4.3.0\lib\net46\System.IO.FileSystem.Primitives.dll + True + + + ..\..\packages\System.Net.Http.4.3.1\lib\net46\System.Net.Http.dll + True + + + ..\..\packages\System.Net.Sockets.4.3.0\lib\net46\System.Net.Sockets.dll + True + + + ..\..\packages\System.Runtime.InteropServices.RuntimeInformation.4.3.0\lib\net45\System.Runtime.InteropServices.RuntimeInformation.dll + True + + + ..\..\packages\System.Security.Cryptography.Algorithms.4.3.0\lib\net46\System.Security.Cryptography.Algorithms.dll + True + + + ..\..\packages\System.Security.Cryptography.Encoding.4.3.0\lib\net46\System.Security.Cryptography.Encoding.dll + True + + + ..\..\packages\System.Security.Cryptography.Primitives.4.3.0\lib\net46\System.Security.Cryptography.Primitives.dll + True + + + ..\..\packages\System.Security.Cryptography.X509Certificates.4.3.0\lib\net46\System.Security.Cryptography.X509Certificates.dll + True + ..\..\packages\System.Spatial.5.8.2\lib\net40\System.Spatial.dll True + + ..\..\packages\Microsoft.Tpl.Dataflow.4.5.24\lib\portable-net45+win8+wpa81\System.Threading.Tasks.Dataflow.dll + True + + + + ..\..\packages\System.Xml.ReaderWriter.4.3.0\lib\net46\System.Xml.ReaderWriter.dll + True + @@ -393,6 +496,8 @@ + + @@ -408,14 +513,36 @@ + + + + + + + + + + + + + + + + + + + + + + diff --git a/src/Microsoft.Azure.WebJobs.Host/WebSitesKnownKeyNames.cs b/src/Microsoft.Azure.WebJobs.Host/WebSitesKnownKeyNames.cs index 93592952..373f55c7 100644 --- a/src/Microsoft.Azure.WebJobs.Host/WebSitesKnownKeyNames.cs +++ b/src/Microsoft.Azure.WebJobs.Host/WebSitesKnownKeyNames.cs @@ -6,5 +6,7 @@ namespace Microsoft.Azure.WebJobs.Host internal static class WebSitesKnownKeyNames { public const string JobDataPath = "WEBJOBS_DATA_PATH"; + + public const string WebSiteInstanceIdKey = "WEBSITE_INSTANCE_ID"; } } diff --git a/src/Microsoft.Azure.WebJobs.Host/app.config b/src/Microsoft.Azure.WebJobs.Host/app.config index 1ad795fa..821a32bf 100644 --- a/src/Microsoft.Azure.WebJobs.Host/app.config +++ b/src/Microsoft.Azure.WebJobs.Host/app.config @@ -1,23 +1,23 @@ - + - - + + - - + + - - + + - - + + - + diff --git a/src/Microsoft.Azure.WebJobs.Host/packages.config b/src/Microsoft.Azure.WebJobs.Host/packages.config index ed1b799f..04e1dfb2 100644 --- a/src/Microsoft.Azure.WebJobs.Host/packages.config +++ b/src/Microsoft.Azure.WebJobs.Host/packages.config @@ -1,17 +1,71 @@  + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + \ No newline at end of file diff --git a/src/Microsoft.Azure.WebJobs.NuGet/WebJobs.nuspec b/src/Microsoft.Azure.WebJobs.NuGet/WebJobs.nuspec index 60dc2434..4117acdd 100644 --- a/src/Microsoft.Azure.WebJobs.NuGet/WebJobs.nuspec +++ b/src/Microsoft.Azure.WebJobs.NuGet/WebJobs.nuspec @@ -17,6 +17,8 @@ + + \ No newline at end of file diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/app.config b/src/Microsoft.Azure.WebJobs.ServiceBus/app.config index c997897f..377e21fe 100644 --- a/src/Microsoft.Azure.WebJobs.ServiceBus/app.config +++ b/src/Microsoft.Azure.WebJobs.ServiceBus/app.config @@ -1,30 +1,30 @@ - + - - + + - - + + - - + + - - + + - - + + - - + + @@ -32,30 +32,30 @@ - - - + + + - - - - - + + + + + - - - - - - - + + + + + + + - + - + diff --git a/test/Dashboard.UnitTests/Dashboard.UnitTests.csproj b/test/Dashboard.UnitTests/Dashboard.UnitTests.csproj index 4f7de255..cc0f7312 100644 --- a/test/Dashboard.UnitTests/Dashboard.UnitTests.csproj +++ b/test/Dashboard.UnitTests/Dashboard.UnitTests.csproj @@ -119,7 +119,10 @@ - + + ..\..\packages\System.Net.Http.4.3.1\lib\net46\System.Net.Http.dll + True + ..\..\packages\Microsoft.AspNet.WebApi.Client.5.2.3\lib\net45\System.Net.Http.Formatting.dll True diff --git a/test/Dashboard.UnitTests/app.config b/test/Dashboard.UnitTests/app.config index 3c685cb8..3258445c 100644 --- a/test/Dashboard.UnitTests/app.config +++ b/test/Dashboard.UnitTests/app.config @@ -1,52 +1,56 @@ - + - - + + - - + + - - + + - - + + - - + + - - + + - - + + - - + + - - + + - - + + - - + + + + + + - + diff --git a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/App.config b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/App.config index 6465544f..5ff20847 100644 --- a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/App.config +++ b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/App.config @@ -1,49 +1,53 @@ - + - + - - - + + + - + - - + + - - + + - - + + - - + + - - + + - - + + - - + + - - + + + + + + @@ -51,26 +55,26 @@ - - - + + + - - - - - + + + + + - - - - - - - + + + + + + + - + diff --git a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AsyncChainEndToEndTests.cs b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AsyncChainEndToEndTests.cs index 62a95d2e..ef160b0c 100644 --- a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AsyncChainEndToEndTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AsyncChainEndToEndTests.cs @@ -12,10 +12,12 @@ using System.Text; using System.Threading; using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host.Executors; +using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.Queues; using Microsoft.Azure.WebJobs.Host.TestCommon; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage; using Microsoft.WindowsAzure.Storage.Blob; using Microsoft.WindowsAzure.Storage.Queue; @@ -51,6 +53,8 @@ namespace Microsoft.Azure.WebJobs.Host.EndToEndTests private readonly CloudQueue _testQueue; private readonly TestFixture _fixture; + private readonly TestLoggerProvider _loggerProvider = new TestLoggerProvider(); + public AsyncChainEndToEndTests(TestFixture fixture) { _fixture = fixture; @@ -66,6 +70,11 @@ namespace Microsoft.Azure.WebJobs.Host.EndToEndTests _storageAccount = fixture.StorageAccount; _timeoutJobDelay = TimeSpan.FromMinutes(5); + ILoggerFactory loggerFactory = new LoggerFactory(); + loggerFactory.AddProvider(_loggerProvider); + _hostConfig.LoggerFactory = loggerFactory; + _hostConfig.Aggregator.IsEnabled = false; // makes validation easier + CloudQueueClient queueClient = _storageAccount.CreateCloudQueueClient(); string queueName = _resolver.ResolveInString(TestQueueName); _testQueue = queueClient.GetQueueReference(queueName); @@ -86,6 +95,8 @@ namespace Microsoft.Azure.WebJobs.Host.EndToEndTests await AsyncChainEndToEndInternal(); + Console.SetOut(hold); + string firstQueueName = _resolver.ResolveInString(Queue1Name); string secondQueueName = _resolver.ResolveInString(Queue2Name); string blobContainerName = _resolver.ResolveInString(ContainerName); @@ -124,15 +135,23 @@ namespace Microsoft.Azure.WebJobs.Host.EndToEndTests }.OrderBy(p => p).ToArray(); bool hasError = consoleOutputLines.Any(p => p.Contains("Function had errors")); - if (!hasError) + Assert.False(hasError); + + // Validate console output + for (int i = 0; i < expectedOutputLines.Length; i++) { - for (int i = 0; i < expectedOutputLines.Length; i++) - { - Assert.StartsWith(expectedOutputLines[i], consoleOutputLines[i]); - } + Assert.StartsWith(expectedOutputLines[i], consoleOutputLines[i]); } - Console.SetOut(hold); + // Validate Logger output + var allLogs = _loggerProvider.CreatedLoggers.SelectMany(l => l.LogMessages.SelectMany(m => m.FormattedMessage.Trim().Split(new string[] { Environment.NewLine }, StringSplitOptions.None))).OrderBy(p => p).ToArray(); + // Logger doesn't log the 'Executing' messages + var loggerExpected = expectedOutputLines.Where(l => !l.StartsWith("Executing '")).ToArray(); + + for (int i = 0; i < loggerExpected.Length; i++) + { + Assert.StartsWith(loggerExpected[i], allLogs[i]); + } } } @@ -188,23 +207,131 @@ namespace Microsoft.Azure.WebJobs.Host.EndToEndTests await host.StopAsync(); bool hasError = string.Join(Environment.NewLine, trace.Traces.Where(p => p.Message.Contains("Error"))).Any(); - if (!hasError) - { - Assert.NotNull(trace.Traces.SingleOrDefault(p => p.Message.Contains("User TraceWriter log"))); - Assert.NotNull(trace.Traces.SingleOrDefault(p => p.Message.Contains("User TextWriter log (TestParam)"))); - Assert.NotNull(trace.Traces.SingleOrDefault(p => p.Message.Contains("Another User TextWriter log"))); - ValidateTraceProperties(trace); + Assert.False(hasError); - string[] consoleOutputLines = consoleOutput.ToString().Trim().Split(new string[] { Environment.NewLine }, StringSplitOptions.None); - Assert.NotNull(consoleOutputLines.SingleOrDefault(p => p.Contains("User TraceWriter log"))); - Assert.NotNull(consoleOutputLines.SingleOrDefault(p => p.Contains("User TextWriter log (TestParam)"))); - Assert.NotNull(consoleOutputLines.SingleOrDefault(p => p.Contains("Another User TextWriter log"))); - } + Assert.NotNull(trace.Traces.SingleOrDefault(p => p.Message.Contains("User TraceWriter log"))); + Assert.NotNull(trace.Traces.SingleOrDefault(p => p.Message.Contains("User TextWriter log (TestParam)"))); + Assert.NotNull(trace.Traces.SingleOrDefault(p => p.Message.Contains("Another User TextWriter log"))); + ValidateTraceProperties(trace); + + string[] consoleOutputLines = consoleOutput.ToString().Trim().Split(new string[] { Environment.NewLine }, StringSplitOptions.None); + Assert.NotNull(consoleOutputLines.SingleOrDefault(p => p.Contains("User TraceWriter log"))); + Assert.NotNull(consoleOutputLines.SingleOrDefault(p => p.Contains("User TextWriter log (TestParam)"))); + Assert.NotNull(consoleOutputLines.SingleOrDefault(p => p.Contains("Another User TextWriter log"))); + + // Validate Logger + var logger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.Function).Single(); + Assert.Equal(3, logger.LogMessages.Count); + Assert.NotNull(logger.LogMessages.SingleOrDefault(p => p.FormattedMessage.Contains("User TraceWriter log"))); + Assert.NotNull(logger.LogMessages.SingleOrDefault(p => p.FormattedMessage.Contains("User TextWriter log (TestParam)"))); + Assert.NotNull(logger.LogMessages.SingleOrDefault(p => p.FormattedMessage.Contains("Another User TextWriter log"))); } Console.SetOut(hold); } + [Fact] + public async Task AggregatorAndEventCollector() + { + using (_functionCompletedEvent = new ManualResetEvent(initialState: false)) + { + _hostConfig.Tracing.ConsoleLevel = TraceLevel.Off; + + // enable the aggregator + _hostConfig.Aggregator.IsEnabled = true; + _hostConfig.Aggregator.BatchSize = 1; + + // add a FunctionEventCollector + var eventCollector = new TestFunctionEventCollector(); + _hostConfig.AddService>(eventCollector); + + JobHost host = new JobHost(_hostConfig); + + await host.StartAsync(); + await host.CallAsync(typeof(AsyncChainEndToEndTests).GetMethod("WriteStartDataMessageToQueue")); + + _functionCompletedEvent.WaitOne(); + + // ensure all logs have had a chance to flush + await Task.Delay(3000); + + await host.StopAsync(); + + // Make sure the aggregator was logged to + var logger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.Aggregator).Single(); + Assert.Equal(4, logger.LogMessages.Count); + + // Make sure the eventCollector was logged to + // The aggregator ignores 'start' evetns, so this will be double + Assert.Equal(8, eventCollector.LogCount); + } + } + + [Fact] + public async Task AggregatorOnly() + { + using (_functionCompletedEvent = new ManualResetEvent(initialState: false)) + { + _hostConfig.Tracing.ConsoleLevel = TraceLevel.Off; + + // enable the aggregator + _hostConfig.Aggregator.IsEnabled = true; + _hostConfig.Aggregator.BatchSize = 1; + + JobHost host = new JobHost(_hostConfig); + + await host.StartAsync(); + await host.CallAsync(typeof(AsyncChainEndToEndTests).GetMethod("WriteStartDataMessageToQueue")); + + _functionCompletedEvent.WaitOne(); + + // ensure all logs have had a chance to flush + await Task.Delay(3000); + + await host.StopAsync(); + + // Make sure the aggregator was logged to + var logger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.Aggregator).Single(); + Assert.Equal(4, logger.LogMessages.Count); + } + } + + [Fact] + public async Task EventCollectorOnly() + { + using (_functionCompletedEvent = new ManualResetEvent(initialState: false)) + { + _hostConfig.Tracing.ConsoleLevel = TraceLevel.Off; + + // disable the aggregator + _hostConfig.Aggregator.IsEnabled = false; + + // add a FunctionEventCollector + var eventCollector = new TestFunctionEventCollector(); + _hostConfig.AddService>(eventCollector); + + JobHost host = new JobHost(_hostConfig); + + await host.StartAsync(); + await host.CallAsync(typeof(AsyncChainEndToEndTests).GetMethod("WriteStartDataMessageToQueue")); + + _functionCompletedEvent.WaitOne(); + + // ensure all logs have had a chance to flush + await Task.Delay(3000); + + await host.StopAsync(); + + // Make sure the aggregator was logged to + var logger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.Aggregator).SingleOrDefault(); + Assert.Null(logger); + + // Make sure the eventCollector was logged to + // The aggregator ignores 'start' evetns, so this will be double + Assert.Equal(8, eventCollector.LogCount); + } + } + private void ValidateTraceProperties(TestTraceWriter trace) { foreach (var traceEvent in trace.Traces) @@ -251,17 +378,28 @@ namespace Microsoft.Azure.WebJobs.Host.EndToEndTests } catch { } + string expectedName = $"{methodInfo.DeclaringType.FullName}.{methodInfo.Name}"; + + // Validate TraceWriter // We expect 3 error messages total TraceEvent[] traceErrors = trace.Traces.Where(p => p.Level == TraceLevel.Error).ToArray(); Assert.Equal(3, traceErrors.Length); // Ensure that all errors include the same exception, with function - // invocation details + // invocation details FunctionInvocationException functionException = traceErrors.First().Exception as FunctionInvocationException; Assert.NotNull(functionException); Assert.NotEqual(Guid.Empty, functionException.InstanceId); - Assert.Equal(string.Format("{0}.{1}", methodInfo.DeclaringType.FullName, methodInfo.Name), functionException.MethodName); + Assert.Equal(expectedName, functionException.MethodName); Assert.True(traceErrors.All(p => functionException == p.Exception)); + + // Validate Logger + // Logger only writes out a single log message (which includes the Exception). + var logger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.Results).Single(); + var logMessage = logger.LogMessages.Single(); + var loggerException = logMessage.Exception as FunctionException; + Assert.NotNull(loggerException); + Assert.Equal(expectedName, loggerException.MethodName); } [Fact] @@ -349,12 +487,24 @@ namespace Microsoft.Azure.WebJobs.Host.EndToEndTests host.Stop(); } + string expectedExceptionMessage = $"Timeout value of 00:00:01 exceeded by function 'AsyncChainEndToEndTests.{functionName}'"; + string expectedResultMessage = $"Executed 'AsyncChainEndToEndTests.{functionName}' (Failed, Id="; + + // Validate TraceWriter // We expect 3 error messages total TraceEvent[] traceErrors = trace.Traces.Where(p => p.Level == TraceLevel.Error).ToArray(); Assert.Equal(3, traceErrors.Length); - Assert.True(traceErrors[0].Message.StartsWith(string.Format("Timeout value of 00:00:01 exceeded by function 'AsyncChainEndToEndTests.{0}'", functionName))); - Assert.True(traceErrors[1].Message.StartsWith(string.Format("Executed 'AsyncChainEndToEndTests.{0}' (Failed, Id=", functionName))); - Assert.True(traceErrors[2].Message.Trim().StartsWith("Function had errors. See Azure WebJobs SDK dashboard for details.")); + Assert.StartsWith(expectedExceptionMessage, traceErrors[0].Message); + Assert.StartsWith(expectedResultMessage, traceErrors[1].Message); + Assert.StartsWith("Function had errors. See Azure WebJobs SDK dashboard for details.", traceErrors[2].Message.Trim()); + + // Validate Logger + // One error is logged by the Executor and one as a Result. + var resultLogger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.Results).Single(); + var executorLogger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.Executor).Single(); + Assert.NotNull(resultLogger.LogMessages.Single().Exception); + Assert.StartsWith(expectedResultMessage, resultLogger.LogMessages.Single().FormattedMessage); + Assert.StartsWith(expectedExceptionMessage, executorLogger.LogMessages.Single().FormattedMessage); } [Fact] @@ -368,8 +518,13 @@ namespace Microsoft.Azure.WebJobs.Host.EndToEndTests MethodInfo methodInfo = GetType().GetMethod("TimeoutJob"); await host.CallAsync(methodInfo); + // Validate TraceWriter TraceEvent[] traceErrors = trace.Traces.Where(p => p.Level == TraceLevel.Error).ToArray(); Assert.Equal(0, traceErrors.Length); + + // Validate Logger + LogMessage[] logErrors = _loggerProvider.GetAllLogMessages().Where(l => l.Level == Extensions.Logging.LogLevel.Error).ToArray(); + Assert.Equal(0, logErrors.Length); } [Fact] @@ -781,5 +936,21 @@ namespace Microsoft.Azure.WebJobs.Host.EndToEndTests return Task.FromResult(0); } } + + private class TestFunctionEventCollector : IAsyncCollector + { + public int LogCount = 0; + + public Task AddAsync(FunctionInstanceLogEntry item, CancellationToken cancellationToken = default(CancellationToken)) + { + LogCount++; + return Task.CompletedTask; + } + + public Task FlushAsync(CancellationToken cancellationToken = default(CancellationToken)) + { + return Task.CompletedTask; + } + } } } diff --git a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AzureStorageEndToEndTests.cs b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AzureStorageEndToEndTests.cs index 048b7914..cea4f96e 100644 --- a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AzureStorageEndToEndTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AzureStorageEndToEndTests.cs @@ -9,6 +9,7 @@ using System.Reflection; using System.Threading; using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host.TestCommon; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage; using Microsoft.WindowsAzure.Storage.Blob; using Microsoft.WindowsAzure.Storage.Queue; @@ -335,6 +336,11 @@ namespace Microsoft.Azure.WebJobs.Host.EndToEndTests var tracer = new TestTraceWriter(TraceLevel.Verbose); hostConfig.Tracing.Tracers.Add(tracer); + ILoggerFactory loggerFactory = new LoggerFactory(); + TestLoggerProvider loggerProvider = new TestLoggerProvider(); + loggerFactory.AddProvider(loggerProvider); + hostConfig.LoggerFactory = loggerFactory; + // The jobs host is started JobHost host = new JobHost(hostConfig); host.Start(); @@ -385,6 +391,10 @@ namespace Microsoft.Azure.WebJobs.Host.EndToEndTests // make sure the exception is being properly logged var errors = tracer.Traces.Where(t => t.Level == TraceLevel.Error); Assert.True(errors.All(t => t.Exception.InnerException.InnerException is FormatException)); + + // Validate Logger + var loggerErrors = loggerProvider.GetAllLogMessages().Where(l => l.Level == Extensions.Logging.LogLevel.Error); + Assert.True(loggerErrors.All(t => t.Exception.InnerException.InnerException is FormatException)); } private void UploadTestObject() diff --git a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/WebJobs.Host.EndToEndTests.csproj b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/WebJobs.Host.EndToEndTests.csproj index 77da6f8f..0f49bcf4 100644 --- a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/WebJobs.Host.EndToEndTests.csproj +++ b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/WebJobs.Host.EndToEndTests.csproj @@ -14,6 +14,9 @@ 512 + ..\test.ruleset + true + false @@ -54,10 +57,26 @@ ..\..\packages\Microsoft.Data.Services.Client.5.8.2\lib\net40\Microsoft.Data.Services.Client.dll True + + ..\..\packages\Microsoft.Extensions.DependencyInjection.Abstractions.1.1.0\lib\netstandard1.0\Microsoft.Extensions.DependencyInjection.Abstractions.dll + True + + + ..\..\packages\Microsoft.Extensions.Logging.1.1.1\lib\netstandard1.1\Microsoft.Extensions.Logging.dll + True + + + ..\..\packages\Microsoft.Extensions.Logging.Abstractions.1.1.1\lib\netstandard1.1\Microsoft.Extensions.Logging.Abstractions.dll + True + ..\..\packages\WindowsAzure.ServiceBus.3.4.5\lib\net45-full\Microsoft.ServiceBus.dll True + + ..\..\packages\Microsoft.Win32.Primitives.4.3.0\lib\net46\Microsoft.Win32.Primitives.dll + True + ..\..\packages\Microsoft.WindowsAzure.ConfigurationManager.3.2.3\lib\net40\Microsoft.WindowsAzure.Configuration.dll True @@ -71,9 +90,72 @@ True + + ..\..\packages\System.AppContext.4.3.0\lib\net46\System.AppContext.dll + True + + + + ..\..\packages\System.Console.4.3.0\lib\net46\System.Console.dll + True + + + ..\..\packages\System.Diagnostics.DiagnosticSource.4.3.0\lib\net46\System.Diagnostics.DiagnosticSource.dll + True + + + ..\..\packages\System.Globalization.Calendars.4.3.0\lib\net46\System.Globalization.Calendars.dll + True + + + ..\..\packages\System.IO.Compression.4.3.0\lib\net46\System.IO.Compression.dll + True + + + + ..\..\packages\System.IO.Compression.ZipFile.4.3.0\lib\net46\System.IO.Compression.ZipFile.dll + True + + + ..\..\packages\System.IO.FileSystem.4.3.0\lib\net46\System.IO.FileSystem.dll + True + + + ..\..\packages\System.IO.FileSystem.Primitives.4.3.0\lib\net46\System.IO.FileSystem.Primitives.dll + True + + + ..\..\packages\System.Net.Http.4.3.1\lib\net46\System.Net.Http.dll + True + + + ..\..\packages\System.Net.Sockets.4.3.0\lib\net46\System.Net.Sockets.dll + True + + + + ..\..\packages\System.Runtime.InteropServices.RuntimeInformation.4.3.0\lib\net45\System.Runtime.InteropServices.RuntimeInformation.dll + True + + + ..\..\packages\System.Security.Cryptography.Algorithms.4.3.0\lib\net46\System.Security.Cryptography.Algorithms.dll + True + + + ..\..\packages\System.Security.Cryptography.Encoding.4.3.0\lib\net46\System.Security.Cryptography.Encoding.dll + True + + + ..\..\packages\System.Security.Cryptography.Primitives.4.3.0\lib\net46\System.Security.Cryptography.Primitives.dll + True + + + ..\..\packages\System.Security.Cryptography.X509Certificates.4.3.0\lib\net46\System.Security.Cryptography.X509Certificates.dll + True + ..\..\packages\System.Spatial.5.8.2\lib\net40\System.Spatial.dll @@ -81,6 +163,10 @@ + + ..\..\packages\System.Xml.ReaderWriter.4.3.0\lib\net46\System.Xml.ReaderWriter.dll + True + ..\..\packages\xunit.abstractions.2.0.0\lib\net35\xunit.abstractions.dll True diff --git a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/packages.config b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/packages.config index 1cacafd5..f9eb6e68 100644 --- a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/packages.config +++ b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/packages.config @@ -4,13 +4,63 @@ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + diff --git a/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/ILoggerTests.cs b/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/ILoggerTests.cs new file mode 100644 index 00000000..5ef7d088 --- /dev/null +++ b/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/ILoggerTests.cs @@ -0,0 +1,215 @@ +using System; +using System.Diagnostics; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Azure.WebJobs.Host.Executors; +using Microsoft.Azure.WebJobs.Host.FunctionalTests.TestDoubles; +using Microsoft.Azure.WebJobs.Host.Loggers; +using Microsoft.Azure.WebJobs.Host.TestCommon; +using Microsoft.Extensions.Logging; +using Moq; +using Xunit; + +namespace Microsoft.Azure.WebJobs.Host.FunctionalTests +{ + public class ILoggerTests + { + TestTraceWriter _trace = new TestTraceWriter(TraceLevel.Info); + TestLoggerProvider _loggerProvider = new TestLoggerProvider(); + + [Fact] + public void ILogger_Succeeds() + { + using (JobHost host = new JobHost(CreateConfig())) + { + var method = typeof(ILoggerFunctions).GetMethod(nameof(ILoggerFunctions.ILogger)); + host.Call(method); + } + + // Five loggers are the startup, singleton, executor, results, and function loggers + Assert.Equal(5, _loggerProvider.CreatedLoggers.Count); + + var functionLogger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.Function).Single(); + var resultsLogger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.Results).Single(); + + Assert.Equal(2, functionLogger.LogMessages.Count); + var infoMessage = functionLogger.LogMessages[0]; + var errorMessage = functionLogger.LogMessages[1]; + // These get the {OriginalFormat} property as well as the 3 from TraceWriter + Assert.Equal(3, infoMessage.State.Count()); + Assert.Equal(3, errorMessage.State.Count()); + + Assert.Equal(1, resultsLogger.LogMessages.Count); + //TODO: beef these verifications up + } + + [Fact] + public void TraceWriter_ForwardsTo_ILogger() + { + using (JobHost host = new JobHost(CreateConfig())) + { + var method = typeof(ILoggerFunctions).GetMethod(nameof(ILoggerFunctions.TraceWriterWithILoggerFactory)); + host.Call(method); + } + + Assert.Equal(5, _trace.Traces.Count); + // The third and fourth traces are from our function + var infoLog = _trace.Traces[2]; + var errorLog = _trace.Traces[3]; + + Assert.Equal("This should go to the ILogger", infoLog.Message); + Assert.Null(infoLog.Exception); + Assert.Equal(3, infoLog.Properties.Count); + + Assert.Equal("This should go to the ILogger with an Exception!", errorLog.Message); + Assert.IsType(errorLog.Exception); + Assert.Equal(3, errorLog.Properties.Count); + + // Five loggers are the startup, singleton, executor, results, and function loggers + Assert.Equal(5, _loggerProvider.CreatedLoggers.Count); + var functionLogger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.Function).Single(); + Assert.Equal(2, functionLogger.LogMessages.Count); + var infoMessage = functionLogger.LogMessages[0]; + var errorMessage = functionLogger.LogMessages[1]; + // These get the {OriginalFormat} property as well as the 3 from TraceWriter + Assert.Equal(4, infoMessage.State.Count()); + Assert.Equal(4, errorMessage.State.Count()); + //TODO: beef these verifications up + } + + [Fact] + public void Aggregator_Runs_WhenEnabled_AndFlushes_OnStop() + { + int addCalls = 0; + int flushCalls = 0; + + var config = CreateConfig(); + + var mockAggregator = new Mock>(MockBehavior.Strict); + mockAggregator + .Setup(a => a.AddAsync(It.IsAny(), It.IsAny())) + .Callback((l, t) => addCalls++) + .Returns(Task.CompletedTask); + mockAggregator + .Setup(a => a.FlushAsync(It.IsAny())) + .Callback(t => flushCalls++) + .Returns(Task.CompletedTask); + + var mockFactory = new Mock(MockBehavior.Strict); + mockFactory + .Setup(f => f.Create(5, TimeSpan.FromSeconds(1), It.IsAny())) + .Returns(mockAggregator.Object); + + config.AddService(mockFactory.Object); + + config.Aggregator.IsEnabled = true; + config.Aggregator.BatchSize = 5; + config.Aggregator.FlushTimeout = TimeSpan.FromSeconds(1); + + using (JobHost host = new JobHost(config)) + { + host.Start(); + + var method = typeof(ILoggerFunctions).GetMethod(nameof(ILoggerFunctions.TraceWriterWithILoggerFactory)); + + for (int i = 0; i < 5; i++) + { + host.Call(method); + } + + host.Stop(); + } + + // Add will be called 5 times. The default aggregator will ingore the + // 'Function started' calls. + Assert.Equal(10, addCalls); + + // Flush is called on host stop + Assert.Equal(1, flushCalls); + } + + [Fact] + public void NoILoggerFactory_NoAggregator() + { + var config = CreateConfig(addFactory: false); + + // Ensure the aggregator is never configured by registering an + // AggregatorFactory that with a strict, unconfigured mock. + var mockFactory = new Mock(MockBehavior.Strict); + config.AddService(mockFactory.Object); + + using (JobHost host = new JobHost(config)) + { + var method = typeof(ILoggerFunctions).GetMethod(nameof(ILoggerFunctions.TraceWriterWithILoggerFactory)); + host.Call(method); + } + } + + [Fact] + public void DisabledAggregator_NoAggregator() + { + // Add the loggerfactory but disable the aggregator + var config = CreateConfig(); + config.Aggregator.IsEnabled = false; + + // Ensure the aggregator is never configured by registering an + // AggregatorFactory that with a strict, unconfigured mock. + var mockFactory = new Mock(MockBehavior.Strict); + config.AddService(mockFactory.Object); + + using (JobHost host = new JobHost(config)) + { + // also start and stop the host to ensure nothing throws due to the + // null aggregator + host.Start(); + + var method = typeof(ILoggerFunctions).GetMethod(nameof(ILoggerFunctions.TraceWriterWithILoggerFactory)); + host.Call(method); + + host.Stop(); + } + } + + private JobHostConfiguration CreateConfig(bool addFactory = true) + { + IStorageAccountProvider accountProvider = new FakeStorageAccountProvider() + { + StorageAccount = new FakeStorageAccount() + }; + + ILoggerFactory factory = new LoggerFactory(); + factory.AddProvider(_loggerProvider); + + var config = new JobHostConfiguration(); + config.AddService(accountProvider); + config.TypeLocator = new FakeTypeLocator(new[] { typeof(ILoggerFunctions) }); + config.Tracing.Tracers.Add(_trace); + config.AddService(factory); + config.Aggregator.IsEnabled = false; // disable aggregator + + return config; + } + + private class ILoggerFunctions + { + [NoAutomaticTrigger] + public void ILogger(ILogger log) + { + log.LogInformation("Log {some} keys and {values}", "1", "2"); + + var ex = new InvalidOperationException("Failure."); + log.LogError(0, ex, "Log {other} keys {and} values", "3", "4"); + } + + [NoAutomaticTrigger] + public void TraceWriterWithILoggerFactory(TraceWriter log) + { + log.Info("This should go to the ILogger"); + + var ex = new InvalidOperationException("Failure."); + log.Error("This should go to the ILogger with an Exception!", ex); + } + } + } +} diff --git a/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/Queues/QueueProcessorTests.cs b/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/Queues/QueueProcessorTests.cs index 7b71bf6a..d9bdc56b 100644 --- a/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/Queues/QueueProcessorTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/Queues/QueueProcessorTests.cs @@ -9,6 +9,7 @@ using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Queues; using Microsoft.Azure.WebJobs.Host.Storage.Queue; using Microsoft.Azure.WebJobs.Host.TestCommon; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage.Queue; using Moq; using Xunit; @@ -31,7 +32,7 @@ namespace Microsoft.Azure.WebJobs.Host.FunctionalTests _poisonQueue = fixture.PoisonQueue; _queuesConfig = new JobHostQueuesConfiguration(); - QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(_queue, _trace, _queuesConfig); + QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(_queue, _trace, null, _queuesConfig); _processor = new QueueProcessor(context); } @@ -46,7 +47,7 @@ namespace Microsoft.Azure.WebJobs.Host.FunctionalTests VisibilityTimeout = TimeSpan.FromSeconds(30), MaxPollingInterval = TimeSpan.FromSeconds(15) }; - QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(_queue, _trace, config); + QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(_queue, _trace, null, config); QueueProcessor localProcessor = new QueueProcessor(context); Assert.Equal(config.BatchSize, localProcessor.BatchSize); @@ -94,7 +95,7 @@ namespace Microsoft.Azure.WebJobs.Host.FunctionalTests [Fact] public async Task CompleteProcessingMessageAsync_MaxDequeueCountExceeded_MovesMessageToPoisonQueue() { - QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(_queue, _trace, _queuesConfig, _poisonQueue); + QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(_queue, _trace, null, _queuesConfig, _poisonQueue); QueueProcessor localProcessor = new QueueProcessor(context); bool poisonMessageHandlerCalled = false; @@ -134,7 +135,7 @@ namespace Microsoft.Azure.WebJobs.Host.FunctionalTests // configure a non-zero visibility timeout VisibilityTimeout = TimeSpan.FromMinutes(5) }; - QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(_queue, _trace, queuesConfig, _poisonQueue); + QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(_queue, _trace, null, queuesConfig, _poisonQueue); QueueProcessor localProcessor = new QueueProcessor(context); string messageContent = Guid.NewGuid().ToString(); diff --git a/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/WebJobs.Host.FunctionalTests.csproj b/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/WebJobs.Host.FunctionalTests.csproj index 6a6f5a94..e76c4614 100644 --- a/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/WebJobs.Host.FunctionalTests.csproj +++ b/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/WebJobs.Host.FunctionalTests.csproj @@ -59,6 +59,7 @@ + @@ -145,6 +146,22 @@ ..\..\packages\Microsoft.Data.Services.Client.5.8.2\lib\net40\Microsoft.Data.Services.Client.dll True + + ..\..\packages\Microsoft.Extensions.DependencyInjection.Abstractions.1.1.0\lib\netstandard1.0\Microsoft.Extensions.DependencyInjection.Abstractions.dll + True + + + ..\..\packages\Microsoft.Extensions.Logging.1.1.1\lib\netstandard1.1\Microsoft.Extensions.Logging.dll + True + + + ..\..\packages\Microsoft.Extensions.Logging.Abstractions.1.1.1\lib\netstandard1.1\Microsoft.Extensions.Logging.Abstractions.dll + True + + + ..\..\packages\Microsoft.Win32.Primitives.4.3.0\lib\net46\Microsoft.Win32.Primitives.dll + True + ..\..\packages\Microsoft.WindowsAzure.ConfigurationManager.3.2.3\lib\net40\Microsoft.WindowsAzure.Configuration.dll True @@ -162,14 +179,81 @@ True + + ..\..\packages\System.AppContext.4.3.0\lib\net46\System.AppContext.dll + True + + + + ..\..\packages\System.Console.4.3.0\lib\net46\System.Console.dll + True + + + ..\..\packages\System.Diagnostics.DiagnosticSource.4.3.0\lib\net46\System.Diagnostics.DiagnosticSource.dll + True + + + ..\..\packages\System.Globalization.Calendars.4.3.0\lib\net46\System.Globalization.Calendars.dll + True + + + ..\..\packages\System.IO.Compression.4.3.0\lib\net46\System.IO.Compression.dll + True + + + + ..\..\packages\System.IO.Compression.ZipFile.4.3.0\lib\net46\System.IO.Compression.ZipFile.dll + True + + + ..\..\packages\System.IO.FileSystem.4.3.0\lib\net46\System.IO.FileSystem.dll + True + + + ..\..\packages\System.IO.FileSystem.Primitives.4.3.0\lib\net46\System.IO.FileSystem.Primitives.dll + True + + + ..\..\packages\System.Net.Http.4.3.1\lib\net46\System.Net.Http.dll + True + + + ..\..\packages\System.Net.Sockets.4.3.0\lib\net46\System.Net.Sockets.dll + True + + + + ..\..\packages\System.Runtime.InteropServices.RuntimeInformation.4.3.0\lib\net45\System.Runtime.InteropServices.RuntimeInformation.dll + True + + + ..\..\packages\System.Security.Cryptography.Algorithms.4.3.0\lib\net46\System.Security.Cryptography.Algorithms.dll + True + + + ..\..\packages\System.Security.Cryptography.Encoding.4.3.0\lib\net46\System.Security.Cryptography.Encoding.dll + True + + + ..\..\packages\System.Security.Cryptography.Primitives.4.3.0\lib\net46\System.Security.Cryptography.Primitives.dll + True + + + ..\..\packages\System.Security.Cryptography.X509Certificates.4.3.0\lib\net46\System.Security.Cryptography.X509Certificates.dll + True + ..\..\packages\System.Spatial.5.8.2\lib\net40\System.Spatial.dll True + + ..\..\packages\System.Xml.ReaderWriter.4.3.0\lib\net46\System.Xml.ReaderWriter.dll + True + ..\..\packages\xunit.abstractions.2.0.0\lib\net35\xunit.abstractions.dll True diff --git a/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/app.config b/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/app.config index badb94a2..b6767ed9 100644 --- a/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/app.config +++ b/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/app.config @@ -1,25 +1,29 @@ - + - - + + - - + + - - + + - - + + + + + + - + diff --git a/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/packages.config b/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/packages.config index 3de92605..3507e653 100644 --- a/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/packages.config +++ b/test/Microsoft.Azure.WebJobs.Host.FunctionalTests/packages.config @@ -5,14 +5,64 @@ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + diff --git a/test/Microsoft.Azure.WebJobs.Host.TestCommon/JobHostFactory.cs b/test/Microsoft.Azure.WebJobs.Host.TestCommon/JobHostFactory.cs index 02586456..2483f8ec 100644 --- a/test/Microsoft.Azure.WebJobs.Host.TestCommon/JobHostFactory.cs +++ b/test/Microsoft.Azure.WebJobs.Host.TestCommon/JobHostFactory.cs @@ -1,15 +1,7 @@ // Copyright (c) .NET Foundation. All rights reserved. // Licensed under the MIT License. See License.txt in the project root for license information. -using System.Diagnostics; -using System.Threading; -using Microsoft.Azure.WebJobs.Host.Blobs; using Microsoft.Azure.WebJobs.Host.Executors; -using Microsoft.Azure.WebJobs.Host.Indexers; -using Microsoft.Azure.WebJobs.Host.Listeners; -using Microsoft.Azure.WebJobs.Host.Loggers; -using Microsoft.Azure.WebJobs.Host.Queues; -using Microsoft.Azure.WebJobs.Host.Timers; using Microsoft.WindowsAzure.Storage; namespace Microsoft.Azure.WebJobs.Host.TestCommon diff --git a/test/Microsoft.Azure.WebJobs.Host.TestCommon/LogMessage.cs b/test/Microsoft.Azure.WebJobs.Host.TestCommon/LogMessage.cs new file mode 100644 index 00000000..b4db6742 --- /dev/null +++ b/test/Microsoft.Azure.WebJobs.Host.TestCommon/LogMessage.cs @@ -0,0 +1,20 @@ +// 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 Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host.TestCommon +{ + public class LogMessage + { + public LogLevel Level { get; set; } + public EventId EventId { get; set; } + public IEnumerable> State { get; set; } + public Exception Exception { get; set; } + public string FormattedMessage { get; set; } + + public string Category { get; set; } + } +} diff --git a/test/Microsoft.Azure.WebJobs.Host.TestCommon/NullFunctionOutputLoggerProvider.cs b/test/Microsoft.Azure.WebJobs.Host.TestCommon/NullFunctionOutputLoggerProvider.cs index 342a4aed..7af33956 100644 --- a/test/Microsoft.Azure.WebJobs.Host.TestCommon/NullFunctionOutputLoggerProvider.cs +++ b/test/Microsoft.Azure.WebJobs.Host.TestCommon/NullFunctionOutputLoggerProvider.cs @@ -10,6 +10,7 @@ using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Host.TestCommon { @@ -47,7 +48,7 @@ namespace Microsoft.Azure.WebJobs.Host.TestCommon return new NullFunctionOutput(); } - public IRecurrentCommand CreateParameterLogUpdateCommand(IReadOnlyDictionary watches, TraceWriter trace) + public IRecurrentCommand CreateParameterLogUpdateCommand(IReadOnlyDictionary watches, TraceWriter trace, ILogger logger) { return null; } diff --git a/test/Microsoft.Azure.WebJobs.Host.TestCommon/TestLogger.cs b/test/Microsoft.Azure.WebJobs.Host.TestCommon/TestLogger.cs new file mode 100644 index 00000000..245e3bb1 --- /dev/null +++ b/test/Microsoft.Azure.WebJobs.Host.TestCommon/TestLogger.cs @@ -0,0 +1,52 @@ +// 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 Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host.TestCommon +{ + public class TestLogger : ILogger + { + private readonly Func _filter; + + public string Category { get; private set; } + + public IList LogMessages = new List(); + + public TestLogger(string category, Func filter = null) + { + Category = category; + _filter = filter; + } + + public IDisposable BeginScope(TState state) + { + return null; + } + + public bool IsEnabled(LogLevel logLevel) + { + return _filter?.Invoke(Category, logLevel) ?? true; + } + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + if (!IsEnabled(logLevel)) + { + return; + } + + LogMessages.Add(new LogMessage + { + Level = logLevel, + EventId = eventId, + State = state as IEnumerable>, + Exception = exception, + FormattedMessage = formatter(state, exception), + Category = Category + }); + } + } +} \ No newline at end of file diff --git a/test/Microsoft.Azure.WebJobs.Host.TestCommon/TestLoggerProvider.cs b/test/Microsoft.Azure.WebJobs.Host.TestCommon/TestLoggerProvider.cs new file mode 100644 index 00000000..4a677977 --- /dev/null +++ b/test/Microsoft.Azure.WebJobs.Host.TestCommon/TestLoggerProvider.cs @@ -0,0 +1,39 @@ +// 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 Microsoft.Azure.WebJobs.Host.Loggers; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host.TestCommon +{ + public class TestLoggerProvider : ILoggerProvider + { + private readonly Func _filter; + + public IList CreatedLoggers = new List(); + + public TestLoggerProvider(Func filter = null) + { + _filter = filter ?? new LogCategoryFilter().Filter; + } + + public ILogger CreateLogger(string categoryName) + { + var logger = new TestLogger(categoryName, _filter); + CreatedLoggers.Add(logger); + return logger; + } + + public IEnumerable GetAllLogMessages() + { + return CreatedLoggers.SelectMany(l => l.LogMessages); + } + + public void Dispose() + { + } + } +} diff --git a/test/Microsoft.Azure.WebJobs.Host.TestCommon/WebJobs.Host.TestCommon.csproj b/test/Microsoft.Azure.WebJobs.Host.TestCommon/WebJobs.Host.TestCommon.csproj index 0e60866d..56461a08 100644 --- a/test/Microsoft.Azure.WebJobs.Host.TestCommon/WebJobs.Host.TestCommon.csproj +++ b/test/Microsoft.Azure.WebJobs.Host.TestCommon/WebJobs.Host.TestCommon.csproj @@ -66,6 +66,22 @@ ..\..\packages\Microsoft.Data.Services.Client.5.8.2\lib\net40\Microsoft.Data.Services.Client.dll True + + ..\..\packages\Microsoft.Extensions.DependencyInjection.Abstractions.1.1.0\lib\netstandard1.0\Microsoft.Extensions.DependencyInjection.Abstractions.dll + True + + + ..\..\packages\Microsoft.Extensions.Logging.1.1.1\lib\netstandard1.1\Microsoft.Extensions.Logging.dll + True + + + ..\..\packages\Microsoft.Extensions.Logging.Abstractions.1.1.1\lib\netstandard1.1\Microsoft.Extensions.Logging.Abstractions.dll + True + + + ..\..\packages\Microsoft.Win32.Primitives.4.3.0\lib\net46\Microsoft.Win32.Primitives.dll + True + ..\..\packages\Microsoft.WindowsAzure.ConfigurationManager.3.2.3\lib\net40\Microsoft.WindowsAzure.Configuration.dll True @@ -79,7 +95,70 @@ True + + ..\..\packages\System.AppContext.4.3.0\lib\net46\System.AppContext.dll + True + + + + ..\..\packages\System.Console.4.3.0\lib\net46\System.Console.dll + True + + + ..\..\packages\System.Diagnostics.DiagnosticSource.4.3.0\lib\net46\System.Diagnostics.DiagnosticSource.dll + True + + + ..\..\packages\System.Globalization.Calendars.4.3.0\lib\net46\System.Globalization.Calendars.dll + True + + + ..\..\packages\System.IO.Compression.4.3.0\lib\net46\System.IO.Compression.dll + True + + + + ..\..\packages\System.IO.Compression.ZipFile.4.3.0\lib\net46\System.IO.Compression.ZipFile.dll + True + + + ..\..\packages\System.IO.FileSystem.4.3.0\lib\net46\System.IO.FileSystem.dll + True + + + ..\..\packages\System.IO.FileSystem.Primitives.4.3.0\lib\net46\System.IO.FileSystem.Primitives.dll + True + + + ..\..\packages\System.Net.Http.4.3.1\lib\net46\System.Net.Http.dll + True + + + ..\..\packages\System.Net.Sockets.4.3.0\lib\net46\System.Net.Sockets.dll + True + + + + ..\..\packages\System.Runtime.InteropServices.RuntimeInformation.4.3.0\lib\net45\System.Runtime.InteropServices.RuntimeInformation.dll + True + + + ..\..\packages\System.Security.Cryptography.Algorithms.4.3.0\lib\net46\System.Security.Cryptography.Algorithms.dll + True + + + ..\..\packages\System.Security.Cryptography.Encoding.4.3.0\lib\net46\System.Security.Cryptography.Encoding.dll + True + + + ..\..\packages\System.Security.Cryptography.Primitives.4.3.0\lib\net46\System.Security.Cryptography.Primitives.dll + True + + + ..\..\packages\System.Security.Cryptography.X509Certificates.4.3.0\lib\net46\System.Security.Cryptography.X509Certificates.dll + True + ..\..\packages\System.Spatial.5.8.2\lib\net40\System.Spatial.dll True @@ -89,6 +168,10 @@ + + ..\..\packages\System.Xml.ReaderWriter.4.3.0\lib\net46\System.Xml.ReaderWriter.dll + True + ..\..\packages\xunit.abstractions.2.0.0\lib\net35\xunit.abstractions.dll True @@ -116,6 +199,7 @@ + @@ -123,6 +207,8 @@ + + diff --git a/test/Microsoft.Azure.WebJobs.Host.TestCommon/app.config b/test/Microsoft.Azure.WebJobs.Host.TestCommon/app.config index 1ad795fa..7609ce58 100644 --- a/test/Microsoft.Azure.WebJobs.Host.TestCommon/app.config +++ b/test/Microsoft.Azure.WebJobs.Host.TestCommon/app.config @@ -1,23 +1,27 @@ - + - - + + - - + + - - + + - - + + + + + + - + diff --git a/test/Microsoft.Azure.WebJobs.Host.TestCommon/packages.config b/test/Microsoft.Azure.WebJobs.Host.TestCommon/packages.config index eb90baf1..28e7c1cf 100644 --- a/test/Microsoft.Azure.WebJobs.Host.TestCommon/packages.config +++ b/test/Microsoft.Azure.WebJobs.Host.TestCommon/packages.config @@ -4,13 +4,63 @@ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Executors/FunctionExecutorTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Executors/FunctionExecutorTests.cs index f5d300de..69f8ce28 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Executors/FunctionExecutorTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Executors/FunctionExecutorTests.cs @@ -3,12 +3,14 @@ using System; using System.Diagnostics; +using System.Linq; using System.Reflection; using System.Threading; using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.TestCommon; +using Microsoft.Extensions.Logging; using Moq; using Xunit; @@ -44,7 +46,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Executors TimeoutAttribute attribute = method.GetCustomAttribute(); - System.Timers.Timer timer = FunctionExecutor.StartFunctionTimeout(_mockFunctionInstance.Object, attribute, _cancellationTokenSource, _traceWriter); + System.Timers.Timer timer = FunctionExecutor.StartFunctionTimeout(_mockFunctionInstance.Object, attribute, _cancellationTokenSource, _traceWriter, null); Assert.True(timer.Enabled); Assert.Equal(attribute.Timeout.TotalMilliseconds, timer.Interval); @@ -64,7 +66,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Executors TimeoutAttribute attribute = typeof(Functions).GetCustomAttribute(); - System.Timers.Timer timer = FunctionExecutor.StartFunctionTimeout(_mockFunctionInstance.Object, attribute, _cancellationTokenSource, _traceWriter); + System.Timers.Timer timer = FunctionExecutor.StartFunctionTimeout(_mockFunctionInstance.Object, attribute, _cancellationTokenSource, _traceWriter, null); Assert.True(timer.Enabled); Assert.Equal(attribute.Timeout.TotalMilliseconds, timer.Interval); @@ -76,7 +78,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Executors public void StartFunctionTimeout_NoTimeout_ReturnsNull() { TimeoutAttribute timeoutAttribute = null; - System.Timers.Timer timer = FunctionExecutor.StartFunctionTimeout(null, timeoutAttribute, _cancellationTokenSource, _traceWriter); + System.Timers.Timer timer = FunctionExecutor.StartFunctionTimeout(null, timeoutAttribute, _cancellationTokenSource, _traceWriter, null); Assert.Null(timer); } @@ -90,7 +92,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Executors TimeoutAttribute attribute = typeof(Functions).GetCustomAttribute(); attribute.ThrowOnTimeout = false; - System.Timers.Timer timer = FunctionExecutor.StartFunctionTimeout(_mockFunctionInstance.Object, attribute, _cancellationTokenSource, _traceWriter); + System.Timers.Timer timer = FunctionExecutor.StartFunctionTimeout(_mockFunctionInstance.Object, attribute, _cancellationTokenSource, _traceWriter, null); Assert.Null(timer); @@ -109,7 +111,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Executors TimeoutAttribute attribute = typeof(Functions).GetCustomAttribute(); - System.Timers.Timer timer = FunctionExecutor.StartFunctionTimeout(_mockFunctionInstance.Object, attribute, _cancellationTokenSource, _traceWriter); + System.Timers.Timer timer = FunctionExecutor.StartFunctionTimeout(_mockFunctionInstance.Object, attribute, _cancellationTokenSource, _traceWriter, null); Assert.True(timer.Enabled); Assert.Equal(attribute.Timeout.TotalMilliseconds, timer.Interval); @@ -317,16 +319,26 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Executors TimeoutAttribute attribute = method.GetCustomAttribute(); Guid instanceId = Guid.Parse("B2D1DD72-80E2-412B-A22E-3B4558F378B4"); bool timeoutWhileDebugging = false; - FunctionExecutor.OnFunctionTimeout(timer, method, instanceId, attribute.Timeout, timeoutWhileDebugging, _traceWriter, _cancellationTokenSource, () => isDebugging); + + TestLogger logger = new TestLogger("Tests.FunctionExecutor"); + + FunctionExecutor.OnFunctionTimeout(timer, method, instanceId, attribute.Timeout, timeoutWhileDebugging, _traceWriter, logger, _cancellationTokenSource, () => isDebugging); Assert.False(timer.Enabled); Assert.NotEqual(isDebugging, _cancellationTokenSource.IsCancellationRequested); + string message = string.Format("Timeout value of 00:01:00 exceeded by function 'Functions.MethodLevel' (Id: 'b2d1dd72-80e2-412b-a22e-3b4558f378b4'). {0}", expectedMessage); + + // verify TraceWriter TraceEvent trace = _traceWriter.Traces[0]; Assert.Equal(TraceLevel.Error, trace.Level); Assert.Equal(TraceSource.Execution, trace.Source); - string message = string.Format("Timeout value of 00:01:00 exceeded by function 'Functions.MethodLevel' (Id: 'b2d1dd72-80e2-412b-a22e-3b4558f378b4'). {0}", expectedMessage); Assert.Equal(message, trace.Message); + + // verify ILogger + LogMessage log = logger.LogMessages.Single(); + Assert.Equal(LogLevel.Error, log.Level); + Assert.Equal(message, log.FormattedMessage); } public static void GlobalLevel(CancellationToken cancellationToken) diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/FunctionIndexerFactory.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/FunctionIndexerFactory.cs index 4fafa899..97f0a4a1 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/FunctionIndexerFactory.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/FunctionIndexerFactory.cs @@ -5,16 +5,14 @@ using System; using System.Diagnostics; using System.Threading; using Microsoft.Azure.WebJobs.Host.Bindings; -using Microsoft.Azure.WebJobs.Host.Blobs; using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Indexers; -using Microsoft.Azure.WebJobs.Host.Listeners; using Microsoft.Azure.WebJobs.Host.Loggers; -using Microsoft.Azure.WebJobs.Host.Queues; using Microsoft.Azure.WebJobs.Host.Storage; using Microsoft.Azure.WebJobs.Host.TestCommon; using Microsoft.Azure.WebJobs.Host.Timers; using Microsoft.Azure.WebJobs.Host.Triggers; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage; using Moq; @@ -22,7 +20,8 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests { internal static class FunctionIndexerFactory { - public static FunctionIndexer Create(CloudStorageAccount account = null, INameResolver nameResolver = null, IExtensionRegistry extensionRegistry = null, TraceWriter traceWriter = null) + public static FunctionIndexer Create(CloudStorageAccount account = null, INameResolver nameResolver = null, + IExtensionRegistry extensionRegistry = null, TraceWriter traceWriter = null, ILoggerFactory loggerFactory = null) { IStorageAccountProvider storageAccountProvider = GetStorageAccountProvider(account); @@ -42,7 +41,8 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests IFunctionExecutor executor = new FunctionExecutor(new NullFunctionInstanceLogger(), outputLogger, exceptionHandler, logger); - return new FunctionIndexer(triggerBindingProvider, bindingProvider, DefaultJobActivator.Instance, executor, extensionRegistry, singletonManager, logger); + return new FunctionIndexer(triggerBindingProvider, bindingProvider, DefaultJobActivator.Instance, executor, + extensionRegistry, singletonManager, logger, loggerFactory); } private static IStorageAccountProvider GetStorageAccountProvider(CloudStorageAccount account) diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Indexers/FunctionIndexerIntegrationErrorTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Indexers/FunctionIndexerIntegrationErrorTests.cs index fcc745e5..5e9bef70 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Indexers/FunctionIndexerIntegrationErrorTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Indexers/FunctionIndexerIntegrationErrorTests.cs @@ -11,9 +11,9 @@ using Microsoft.Azure.WebJobs.Host.Bindings; using Microsoft.Azure.WebJobs.Host.Config; using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Indexers; -using Microsoft.Azure.WebJobs.Host.Storage.Blob; using Microsoft.Azure.WebJobs.Host.TestCommon; using Microsoft.Azure.WebJobs.Host.Triggers; +using Microsoft.Extensions.Logging; using Moq; using Xunit; @@ -35,6 +35,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Indexers Mock executorMock = new Mock(MockBehavior.Strict); IFunctionIndexCollector stubIndex = new Mock().Object; + FunctionIndexer indexer = new FunctionIndexer( new Mock(MockBehavior.Strict).Object, new Mock(MockBehavior.Strict).Object, @@ -42,7 +43,8 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Indexers executorMock.Object, extensionsMock.Object, new SingletonManager(), - new TestTraceWriter(TraceLevel.Verbose)); + new TestTraceWriter(TraceLevel.Verbose), + null); Assert.Throws(() => indexer.IndexMethodAsync(method, stubIndex, CancellationToken.None).GetAwaiter().GetResult()); } diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Indexers/FunctionIndexerTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Indexers/FunctionIndexerTests.cs index 757c208c..48c310d2 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Indexers/FunctionIndexerTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Indexers/FunctionIndexerTests.cs @@ -11,9 +11,11 @@ using System.Threading; using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host.Bindings; using Microsoft.Azure.WebJobs.Host.Indexers; +using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.TestCommon; using Microsoft.Azure.WebJobs.Host.Triggers; +using Microsoft.Extensions.Logging; using Moq; using Xunit; @@ -151,16 +153,28 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Indexers public async Task IndexMethod_IfMethodReturnsAsyncVoid_Throws() { var traceWriter = new TestTraceWriter(TraceLevel.Verbose); + var loggerFactory = new LoggerFactory(); + var loggerProvider = new TestLoggerProvider(); + loggerFactory.AddProvider(loggerProvider); // Arrange IFunctionIndexCollector index = CreateStubFunctionIndex(); - FunctionIndexer product = CreateProductUnderTest(traceWriter: traceWriter); + FunctionIndexer product = CreateProductUnderTest(traceWriter: traceWriter, loggerFactory: loggerFactory); // Act & Assert await product.IndexMethodAsync(typeof(FunctionIndexerTests).GetMethod("ReturnAsyncVoid"), index, CancellationToken.None); - var warning = traceWriter.Traces.First(p => p.Level == TraceLevel.Warning); - Assert.Equal("Function 'ReturnAsyncVoid' is async but does not return a Task. Your function may not run correctly.", warning.Message); + string expectedMessage = "Function 'ReturnAsyncVoid' is async but does not return a Task. Your function may not run correctly."; + + // Validate TraceWriter + var traceWarning = traceWriter.Traces.First(p => p.Level == TraceLevel.Warning); + Assert.Equal(expectedMessage, traceWarning.Message); + + // Validate Logger + var logger = loggerProvider.CreatedLoggers.Single(l => l.Category == LogCategories.Startup); + var loggerWarning = logger.LogMessages.Single(); + Assert.Equal(LogLevel.Warning, loggerWarning.Level); + Assert.Equal(expectedMessage, loggerWarning.FormattedMessage); } [Fact] @@ -317,9 +331,9 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Indexers return new Mock(MockBehavior.Strict).Object; } - private static FunctionIndexer CreateProductUnderTest(TraceWriter traceWriter = null) + private static FunctionIndexer CreateProductUnderTest(TraceWriter traceWriter = null, ILoggerFactory loggerFactory = null) { - return FunctionIndexerFactory.Create(traceWriter: traceWriter); + return FunctionIndexerFactory.Create(traceWriter: traceWriter, loggerFactory: loggerFactory); } private static IFunctionIndexCollector CreateStubFunctionIndex() diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Listeners/FunctionListenerTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Listeners/FunctionListenerTests.cs index 34891779..48cb1a68 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Listeners/FunctionListenerTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Listeners/FunctionListenerTests.cs @@ -2,17 +2,17 @@ // Licensed under the MIT License. See License.txt in the project root for license information. using System; +using System.Collections.ObjectModel; using System.Diagnostics; +using System.Linq; using System.Threading; using System.Threading.Tasks; -using Microsoft.Azure.WebJobs.Host.Indexers; using Microsoft.Azure.WebJobs.Host.Listeners; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.TestCommon; -using Microsoft.Azure.WebJobs.Host.Triggers; +using Microsoft.Extensions.Logging; using Moq; using Xunit; -using System.Collections.ObjectModel; namespace Microsoft.Azure.WebJobs.Host.UnitTests.Listeners { @@ -25,6 +25,16 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Listeners ShortName = "testfunc" }; + private readonly ILoggerFactory _loggerFactory; + private readonly TestLoggerProvider _loggerProvider; + + public FunctionListenerTests() + { + _loggerFactory = new LoggerFactory(); + _loggerProvider = new TestLoggerProvider(); + _loggerFactory.AddProvider(_loggerProvider); + } + [Fact] public async Task FunctionListener_Throws_IfUnhandledListenerExceptionOnStartAsync() { @@ -32,12 +42,20 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Listeners Mock badListener = new Mock(MockBehavior.Strict); badListener.Setup(bl => bl.StartAsync(It.IsAny())) .Throws(new Exception("listener")); - var listener = new FunctionListener(badListener.Object, fd, trace); + var listener = new FunctionListener(badListener.Object, fd, trace, _loggerFactory); var e = await Assert.ThrowsAsync(async () => await listener.StartAsync(ct)); - var exc = trace.Traces[0].Exception as FunctionException; - Assert.Equal("testfunc", exc.MethodName); - Assert.False(exc.Handled); + + // Validate TraceWriter + var traceEx = trace.Traces[0].Exception as FunctionException; + Assert.Equal("testfunc", traceEx.MethodName); + Assert.False(traceEx.Handled); + + // Validate Logger + var loggerEx = _loggerProvider.CreatedLoggers.Single().LogMessages.Single().Exception as FunctionException; + Assert.Equal("testfunc", loggerEx.MethodName); + Assert.False(loggerEx.Handled); + badListener.VerifyAll(); } @@ -48,14 +66,25 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Listeners Mock badListener = new Mock(MockBehavior.Strict); badListener.Setup(bl => bl.StartAsync(It.IsAny())) .Throws(new Exception("listener")); - var listener = new FunctionListener(badListener.Object, fd, trace); + var listener = new FunctionListener(badListener.Object, fd, trace, _loggerFactory); await listener.StartAsync(ct); - Assert.Equal("The listener for function 'testfunc' was unable to start.", trace.Traces[0].Message); - var exc = trace.Traces[0].Exception as FunctionException; - Assert.Equal("testfunc", exc.MethodName); - Assert.True(exc.Handled); + string expectedMessage = "The listener for function 'testfunc' was unable to start."; + + // Validate TraceWriter + Assert.Equal(expectedMessage, trace.Traces[0].Message); + var traceEx = trace.Traces[0].Exception as FunctionException; + Assert.Equal("testfunc", traceEx.MethodName); + Assert.True(traceEx.Handled); + + // Validate Logger + var logMessage = _loggerProvider.CreatedLoggers.Single().LogMessages.Single(); + Assert.Equal(expectedMessage, logMessage.FormattedMessage); + var loggerEx = logMessage.Exception as FunctionException; + Assert.Equal("testfunc", loggerEx.MethodName); + Assert.True(loggerEx.Handled); + badListener.VerifyAll(); } @@ -66,7 +95,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Listeners Mock badListener = new Mock(MockBehavior.Strict); badListener.Setup(bl => bl.StartAsync(It.IsAny())) .Throws(new Exception("listener")); - var listener = new FunctionListener(badListener.Object, fd, trace); + var listener = new FunctionListener(badListener.Object, fd, trace, _loggerFactory); await listener.StartAsync(ct); // these should do nothing, as function listener had an exception on start @@ -87,12 +116,13 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Listeners .Returns(Task.FromResult(false)); goodListener.Setup(bl => bl.StopAsync(It.IsAny())) .Returns(Task.FromResult(false)); - var listener = new FunctionListener(goodListener.Object, fd, trace); + var listener = new FunctionListener(goodListener.Object, fd, trace, _loggerFactory); await listener.StartAsync(ct); await listener.StopAsync(ct); Assert.Empty(trace.Traces); + Assert.Empty(_loggerProvider.CreatedLoggers.Single().LogMessages); goodListener.VerifyAll(); } diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Listeners/HostListenerFactoryTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Listeners/HostListenerFactoryTests.cs index e13da200..6f80a921 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Listeners/HostListenerFactoryTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Listeners/HostListenerFactoryTests.cs @@ -4,14 +4,17 @@ using System; using System.Collections.Generic; using System.Diagnostics; +using System.Linq; using System.Reflection; using System.Threading; using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host.Executors; using Microsoft.Azure.WebJobs.Host.Indexers; using Microsoft.Azure.WebJobs.Host.Listeners; +using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Protocols; using Microsoft.Azure.WebJobs.Host.TestCommon; +using Microsoft.Extensions.Logging; using Moq; using Xunit; @@ -43,6 +46,10 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Listeners SingletonManager singletonManager = new SingletonManager(); TestTraceWriter traceWriter = new TestTraceWriter(TraceLevel.Verbose); + ILoggerFactory loggerFactory = new LoggerFactory(); + TestLoggerProvider loggerProvider = new TestLoggerProvider(); + loggerFactory.AddProvider(loggerProvider); + // create a bunch of function definitions that are disabled List functions = new List(); FunctionDescriptor descriptor = new FunctionDescriptor @@ -55,13 +62,22 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Listeners // Create the composite listener - this will fail if any of the // function definitions indicate that they are not disabled - HostListenerFactory factory = new HostListenerFactory(functions, singletonManager, DefaultJobActivator.Instance, null, traceWriter); + HostListenerFactory factory = new HostListenerFactory(functions, singletonManager, DefaultJobActivator.Instance, null, traceWriter, loggerFactory); IListener listener = await factory.CreateAsync(CancellationToken.None); + string expectedMessage = $"Function '{descriptor.ShortName}' is disabled"; + + // Validate TraceWriter Assert.Equal(1, traceWriter.Traces.Count); Assert.Equal(TraceLevel.Info, traceWriter.Traces[0].Level); Assert.Equal(TraceSource.Host, traceWriter.Traces[0].Source); - Assert.Equal(string.Format("Function '{0}' is disabled", descriptor.ShortName), traceWriter.Traces[0].Message); + Assert.Equal(expectedMessage, traceWriter.Traces[0].Message); + + // Validate Logger + var logMessage = loggerProvider.CreatedLoggers.Single().LogMessages.Single(); + Assert.Equal(LogLevel.Information, logMessage.Level); + Assert.Equal(LogCategories.Startup, logMessage.Category); + Assert.Equal(expectedMessage, logMessage.FormattedMessage); Environment.SetEnvironmentVariable("EnvironmentSettingTrue", null); } diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsLoggerTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsLoggerTests.cs new file mode 100644 index 00000000..e17a0a73 --- /dev/null +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsLoggerTests.cs @@ -0,0 +1,481 @@ +// 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.Net.Http; +using System.Reflection; +using System.Threading.Tasks; +using System.Web; +using Microsoft.ApplicationInsights; +using Microsoft.ApplicationInsights.DataContracts; +using Microsoft.ApplicationInsights.Extensibility; +using Microsoft.Azure.WebJobs.Host.Executors; +using Microsoft.Azure.WebJobs.Host.Loggers; +using Microsoft.Azure.WebJobs.Host.Protocols; +using Microsoft.Extensions.Logging; +using Moq; +using Xunit; + +namespace Microsoft.Azure.WebJobs.Host.UnitTests.Loggers +{ + public class ApplicationInsightsLoggerTests + { + private readonly Guid _invocationId = Guid.NewGuid(); + private readonly DateTime _startTime = DateTime.UtcNow; + private readonly DateTime _endTime; + private readonly string _triggerReason = "new queue message"; + private readonly string _functionFullName = "Functions.TestFunction"; + private readonly string _functionShortName = "TestFunction"; + private readonly IDictionary _arguments; + private readonly TestTelemetryChannel _channel = new TestTelemetryChannel(); + private readonly string defaultIp = "0.0.0.0"; + private readonly TelemetryClient _client; + private readonly int durationMs = 450; + + public ApplicationInsightsLoggerTests() + { + _endTime = _startTime.AddMilliseconds(durationMs); + _arguments = new Dictionary + { + ["queueMessage"] = "my message", + ["anotherParam"] = "some value" + }; + + TelemetryConfiguration config = new TelemetryConfiguration + { + TelemetryChannel = _channel, + InstrumentationKey = "some key" + }; + + // Add the same initializers that we use in the product code + DefaultTelemetryClientFactory.AddInitializers(config); + + _client = new TelemetryClient(config); + } + + [Fact] + public void LogFunctionResult_Succeeded_SendsCorrectTelemetry() + { + var result = CreateDefaultInstanceLogEntry(); + ILogger logger = CreateLogger(LogCategories.Results); + + using (logger.BeginFunctionScope(CreateFunctionInstance(_invocationId))) + { + logger.LogFunctionResult(_functionShortName, result, TimeSpan.FromMilliseconds(durationMs)); + } + + RequestTelemetry telemetry = _channel.Telemetries.Single() as RequestTelemetry; + + Assert.Equal(_invocationId.ToString(), telemetry.Id); + Assert.Equal(_invocationId.ToString(), telemetry.Context.Operation.Id); + Assert.Equal(_functionShortName, telemetry.Name); + Assert.Equal(_functionShortName, telemetry.Context.Operation.Name); + Assert.Equal(defaultIp, telemetry.Context.Location.Ip); + // TODO: Beef up validation to include properties + } + + [Fact] + public void LogFunctionResult_Failed_SendsCorrectTelemetry() + { + var result = CreateDefaultInstanceLogEntry(); + FunctionInvocationException fex = new FunctionInvocationException("Failed"); + ILogger logger = CreateLogger(LogCategories.Results); + + using (logger.BeginFunctionScope(CreateFunctionInstance(_invocationId))) + { + logger.LogFunctionResult(_functionShortName, result, TimeSpan.FromMilliseconds(durationMs), fex); + } + + // Errors log an associated Exception + RequestTelemetry requestTelemetry = _channel.Telemetries.OfType().Single(); + ExceptionTelemetry exceptionTelemetry = _channel.Telemetries.OfType().Single(); + + Assert.Equal(2, _channel.Telemetries.Count); + Assert.Equal(_invocationId.ToString(), requestTelemetry.Id); + Assert.Equal(_invocationId.ToString(), requestTelemetry.Context.Operation.Id); + Assert.Equal(_functionShortName, requestTelemetry.Name); + Assert.Equal(_functionShortName, requestTelemetry.Context.Operation.Name); + Assert.Equal(defaultIp, requestTelemetry.Context.Location.Ip); + // TODO: Beef up validation to include properties + + // Exception needs to have associated id + Assert.Equal(_invocationId.ToString(), exceptionTelemetry.Context.Operation.Id); + Assert.Equal(_functionShortName, exceptionTelemetry.Context.Operation.Name); + Assert.Same(fex, exceptionTelemetry.Exception); + // TODO: Beef up validation to include properties + } + + [Fact] + public void LogFunctionAggregate_SendsCorrectTelemetry() + { + DateTime now = DateTime.UtcNow; + var resultAggregate = new FunctionResultAggregate + { + Name = _functionFullName, + Failures = 4, + Successes = 116, + MinDuration = TimeSpan.FromMilliseconds(200), + MaxDuration = TimeSpan.FromMilliseconds(2180), + AverageDuration = TimeSpan.FromMilliseconds(340), + Timestamp = now + }; + + ILogger logger = CreateLogger(LogCategories.Aggregator); + logger.LogFunctionResultAggregate(resultAggregate); + + IEnumerable metrics = _channel.Telemetries.Cast(); + // turn them into a dictionary so we can easily validate + IDictionary metricDict = metrics.ToDictionary(m => m.Name, m => m.Value); + + Assert.Equal(7, metricDict.Count); + Assert.Equal(4, metricDict[$"{_functionFullName} {LoggingKeys.Failures}"]); + Assert.Equal(116, metricDict[$"{_functionFullName} {LoggingKeys.Successes}"]); + Assert.Equal(200, metricDict[$"{_functionFullName} {LoggingKeys.MinDuration}"]); + Assert.Equal(2180, metricDict[$"{_functionFullName} {LoggingKeys.MaxDuration}"]); + Assert.Equal(340, metricDict[$"{_functionFullName} {LoggingKeys.AvgDuration}"]); + Assert.Equal(96.67, metricDict[$"{_functionFullName} {LoggingKeys.SuccessRate}"]); + Assert.Equal(120, metricDict[$"{_functionFullName} {LoggingKeys.Count}"]); + } + + [Fact] + public void LogFunctionResult_HttpRequest_SendsCorrectTelemetry() + { + // If the scope has an HttpRequestMessage, we'll use the proper values + // for the RequestTelemetry + DateTime now = DateTime.UtcNow; + var result = CreateDefaultInstanceLogEntry(); + + var request = new HttpRequestMessage(HttpMethod.Post, "http://someuri/api/path"); + request.Headers.Add("User-Agent", "my custom user agent"); + var response = new HttpResponseMessage(); + request.Properties[ScopeKeys.FunctionsHttpResponse] = response; + + MockIpAddress(request, "1.2.3.4"); + + ILogger logger = CreateLogger(LogCategories.Results); + var scopeProps = CreateScopeDictionary(_invocationId, _functionShortName); + scopeProps[ScopeKeys.HttpRequest] = request; + + using (logger.BeginScope(scopeProps)) + { + logger.LogFunctionResult(_functionShortName, result, TimeSpan.FromMilliseconds(durationMs)); + } + + RequestTelemetry telemetry = _channel.Telemetries.Single() as RequestTelemetry; + + Assert.Equal(_invocationId.ToString(), telemetry.Id); + Assert.Equal(_invocationId.ToString(), telemetry.Context.Operation.Id); + Assert.Equal(_functionShortName, telemetry.Name); + Assert.Equal(_functionShortName, telemetry.Context.Operation.Name); + Assert.Equal("1.2.3.4", telemetry.Context.Location.Ip); + Assert.Equal("POST", telemetry.Properties[LoggingKeys.HttpMethod]); + Assert.Equal(new Uri("http://someuri/api/path"), telemetry.Url); + Assert.Equal("my custom user agent", telemetry.Context.User.UserAgent); + Assert.Equal("200", telemetry.ResponseCode); + // TODO: Beef up validation to include properties + } + + [Fact] + public void LogFunctionResult_HttpRequest_WithException_SendsCorrectTelemetry() + { + // If the scope has an HttpRequestMessage, we'll use the proper values + // for the RequestTelemetry + DateTime now = DateTime.UtcNow; + var result = CreateDefaultInstanceLogEntry(); + + var request = new HttpRequestMessage(HttpMethod.Post, "http://someuri/api/path"); + request.Headers.Add("User-Agent", "my custom user agent"); + + // In the case of an exception being thrown, no response is attached + + MockIpAddress(request, "1.2.3.4"); + + ILogger logger = CreateLogger(LogCategories.Results); + var scopeProps = CreateScopeDictionary(_invocationId, _functionShortName); + scopeProps[ScopeKeys.HttpRequest] = request; + + using (logger.BeginScope(scopeProps)) + { + logger.LogFunctionResult(_functionShortName, result, TimeSpan.FromMilliseconds(durationMs), new Exception("Boom")); + } + + // one Exception, one Request + Assert.Equal(2, _channel.Telemetries.Count); + + RequestTelemetry requestTelemetry = _channel.Telemetries.Where(t => t is RequestTelemetry).Single() as RequestTelemetry; + ExceptionTelemetry exceptionTelemetry = _channel.Telemetries.Where(t => t is ExceptionTelemetry).Single() as ExceptionTelemetry; + + Assert.Equal(_invocationId.ToString(), requestTelemetry.Id); + Assert.Equal(_invocationId.ToString(), requestTelemetry.Context.Operation.Id); + Assert.Equal(_functionShortName, requestTelemetry.Name); + Assert.Equal(_functionShortName, requestTelemetry.Context.Operation.Name); + Assert.Equal("1.2.3.4", requestTelemetry.Context.Location.Ip); + Assert.Equal("POST", requestTelemetry.Properties[LoggingKeys.HttpMethod]); + Assert.Equal(new Uri("http://someuri/api/path"), requestTelemetry.Url); + Assert.Equal("my custom user agent", requestTelemetry.Context.User.UserAgent); + Assert.Equal("500", requestTelemetry.ResponseCode); + // TODO: Beef up validation to include properties + } + + [Fact] + public void Log_NoProperties_CreatesTraceAndCorrelates() + { + Guid scopeGuid = Guid.NewGuid(); + + ILogger logger = CreateLogger(LogCategories.Function); + using (logger.BeginFunctionScope(CreateFunctionInstance(scopeGuid))) + { + logger.LogInformation("Information"); + logger.LogCritical("Critical"); + logger.LogDebug("Debug"); + logger.LogError("Error"); + logger.LogTrace("Trace"); + logger.LogWarning("Warning"); + } + + Assert.Equal(6, _channel.Telemetries.Count); + Assert.Equal(6, _channel.Telemetries.OfType().Count()); + foreach (var telemetry in _channel.Telemetries.Cast()) + { + SeverityLevel expectedLevel; + if (telemetry.Message == "Trace" || telemetry.Message == "Debug") + { + expectedLevel = SeverityLevel.Verbose; + } + else + { + Assert.True(Enum.TryParse(telemetry.Message, out expectedLevel)); + } + Assert.Equal(expectedLevel, telemetry.SeverityLevel); + + Assert.Equal(LogCategories.Function, telemetry.Properties[LoggingKeys.CategoryName]); + Assert.Equal(telemetry.Message, telemetry.Properties[LoggingKeys.CustomPropertyPrefix + LoggingKeys.OriginalFormat]); + Assert.Equal(scopeGuid.ToString(), telemetry.Context.Operation.Id); + Assert.Equal(_functionShortName, telemetry.Context.Operation.Name); + } + } + + [Fact] + public void Log_WithProperties_IncludesProps() + { + ILogger logger = CreateLogger(LogCategories.Function); + logger.LogInformation("Using {some} custom {properties}. {Test}.", "1", 2, "3"); + + var telemetry = _channel.Telemetries.Single() as TraceTelemetry; + + Assert.Equal(SeverityLevel.Information, telemetry.SeverityLevel); + + Assert.Equal(LogCategories.Function, telemetry.Properties[LoggingKeys.CategoryName]); + Assert.Equal("Using {some} custom {properties}. {Test}.", + telemetry.Properties[LoggingKeys.CustomPropertyPrefix + LoggingKeys.OriginalFormat]); + Assert.Equal("Using 1 custom 2. 3.", telemetry.Message); + Assert.Equal("1", telemetry.Properties[LoggingKeys.CustomPropertyPrefix + "some"]); + Assert.Equal("2", telemetry.Properties[LoggingKeys.CustomPropertyPrefix + "properties"]); + Assert.Equal("3", telemetry.Properties[LoggingKeys.CustomPropertyPrefix + "Test"]); + } + + [Fact] + public void Log_WithException_CreatesExceptionAndCorrelates() + { + var ex = new InvalidOperationException("Failure"); + Guid scopeGuid = Guid.NewGuid(); + ILogger logger = CreateLogger(LogCategories.Function); + + using (logger.BeginFunctionScope(CreateFunctionInstance(scopeGuid))) + { + logger.LogError(0, ex, "Error with customer: {customer}.", "John Doe"); + } + + var telemetry = _channel.Telemetries.Single() as ExceptionTelemetry; + + Assert.Equal(SeverityLevel.Error, telemetry.SeverityLevel); + + Assert.Equal(LogCategories.Function, telemetry.Properties[LoggingKeys.CategoryName]); + Assert.Equal("Error with customer: {customer}.", + telemetry.Properties[LoggingKeys.CustomPropertyPrefix + LoggingKeys.OriginalFormat]); + Assert.Equal("Error with customer: John Doe.", telemetry.Message); + Assert.Equal("John Doe", telemetry.Properties[LoggingKeys.CustomPropertyPrefix + "customer"]); + Assert.Same(ex, telemetry.Exception); + Assert.Equal(scopeGuid.ToString(), telemetry.Context.Operation.Id); + Assert.Equal(_functionShortName, telemetry.Context.Operation.Name); + } + + [Theory] + [InlineData("1.2.3.4:5")] + [InlineData("1.2.3.4")] + public void GetIpAddress_ChecksHeaderFirst(string headerIp) + { + HttpRequestMessage request = new HttpRequestMessage(); + request.Headers.Add(ScopeKeys.ForwardedForHeaderName, headerIp); + MockIpAddress(request, "5.6.7.8"); + + string ip = ApplicationInsightsLogger.GetIpAddress(request); + + Assert.Equal("1.2.3.4", ip); + } + + [Fact] + public void GetIpAddress_ChecksContextSecond() + { + HttpRequestMessage request = new HttpRequestMessage(); + MockIpAddress(request, "5.6.7.8"); + + string ip = ApplicationInsightsLogger.GetIpAddress(request); + + Assert.Equal("5.6.7.8", ip); + } + + [Fact] + public async Task BeginScope() + { + List tasks = new List(); + for (int i = 0; i < 20; i++) + { + tasks.Add(Level1(Guid.NewGuid())); + } + + await Task.WhenAll(tasks); + } + + private async Task Level1(Guid asyncLocalSetting) + { + // Push and pop values onto the dictionary at various levels. Make sure they + // maintain their AsyncLocal state + var level1 = new Dictionary + { + ["AsyncLocal"] = asyncLocalSetting, + ["1"] = 1 + }; + + ILogger logger = CreateLogger(LogCategories.Function); + using (logger.BeginScope(level1)) + { + ValidateScope(level1); + + await Level2(asyncLocalSetting); + + ValidateScope(level1); + } + } + + private async Task Level2(Guid asyncLocalSetting) + { + await Task.Delay(1); + + var level2 = new Dictionary + { + ["2"] = 2 + }; + + var expectedLevel2 = new Dictionary + { + ["1"] = 1, + ["2"] = 2, + ["AsyncLocal"] = asyncLocalSetting + }; + + ILogger logger2 = CreateLogger(LogCategories.Function); + using (logger2.BeginScope(level2)) + { + ValidateScope(expectedLevel2); + + await Level3(asyncLocalSetting); + + ValidateScope(expectedLevel2); + } + } + + private async Task Level3(Guid asyncLocalSetting) + { + await Task.Delay(1); + + // also overwrite value 1, we expect this to win here + var level3 = new Dictionary + { + ["1"] = 11, + ["3"] = 3 + }; + + var expectedLevel3 = new Dictionary + { + ["1"] = 11, + ["2"] = 2, + ["3"] = 3, + ["AsyncLocal"] = asyncLocalSetting + }; + + ILogger logger3 = CreateLogger(LogCategories.Function); + using (logger3.BeginScope(level3)) + { + ValidateScope(expectedLevel3); + } + } + + private static void MockIpAddress(HttpRequestMessage request, string ipAddress) + { + Mock mockContext = new Mock(MockBehavior.Strict); + Mock mockRequest = new Mock(MockBehavior.Strict); + mockRequest.Setup(r => r.UserHostAddress).Returns(ipAddress); + mockContext.Setup(c => c.Request).Returns(mockRequest.Object); + request.Properties[ScopeKeys.HttpContext] = mockContext.Object; + } + + private ILogger CreateLogger(string category) + { + return new ApplicationInsightsLogger(_client, category, null); + } + + private static void ValidateScope(IDictionary expected) + { + var scopeDict = DictionaryLoggerScope.GetMergedStateDictionary(); + Assert.Equal(expected.Count, scopeDict.Count); + foreach (var entry in expected) + { + Assert.Equal(entry.Value, scopeDict[entry.Key]); + } + } + + private IFunctionInstance CreateFunctionInstance(Guid id) + { + var descriptor = new FunctionDescriptor + { + Method = GetType().GetMethod(nameof(TestFunction), BindingFlags.NonPublic | BindingFlags.Static) + }; + + return new FunctionInstance(id, null, new ExecutionReason(), null, null, descriptor); + } + + private static IDictionary CreateScopeDictionary(Guid invocationId, string functionName) + { + return new Dictionary + { + [ScopeKeys.FunctionInvocationId] = invocationId, + [ScopeKeys.FunctionName] = functionName + }; + } + + private static void TestFunction() + { + // used for a FunctionDescriptor + } + + private FunctionInstanceLogEntry CreateDefaultInstanceLogEntry() + { + return new FunctionInstanceLogEntry + { + FunctionName = _functionFullName, + FunctionInstanceId = _invocationId, + StartTime = _startTime, + EndTime = _endTime, + LogOutput = "a bunch of output that we will not forward", // not used here -- this is all Traced + TriggerReason = _triggerReason, + ParentId = Guid.NewGuid(), // we do not track this + ErrorDetails = null, // we do not use this -- we pass the exception in separately + Arguments = _arguments + }; + } + + } +} diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/FormattedLogValuesCollectionTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/FormattedLogValuesCollectionTests.cs new file mode 100644 index 00000000..b802f8f3 --- /dev/null +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/FormattedLogValuesCollectionTests.cs @@ -0,0 +1,164 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using System.Collections.Generic; +using System.Collections.ObjectModel; +using Microsoft.Azure.WebJobs.Host.Loggers; +using Xunit; + +namespace Microsoft.Azure.WebJobs.Host.UnitTests.Loggers +{ + public class FormattedLogValuesCollectionTests + { + [Fact] + public void Verify_ToString_AndCollection() + { + var additionalPayload = new Dictionary() + { + ["additional"] = "abc", + ["payload"] = 123 + }; + + var payload = new FormattedLogValuesCollection("This {string} has some {data}", + new object[] { "xyz", 789 }, new ReadOnlyDictionary(additionalPayload)); + + // Verify string behavior + Assert.Equal("This xyz has some 789", payload.ToString()); + + // Verify the collection + var expectedPayload = new Dictionary + { + ["additional"] = "abc", + ["payload"] = 123, + ["string"] = "xyz", + ["data"] = 789, + + // FormattedLogValues adds this automatically to capture the string template + ["{OriginalFormat}"] = "This {string} has some {data}" + }; + + ValidateCollection(expectedPayload, payload); + } + + [Fact] + public void NoAdditionalPayload() + { + var payload = new FormattedLogValuesCollection("This {string} has some {data}", + new object[] { "xyz", 789 }, null); + + // Verify string behavior + Assert.Equal("This xyz has some 789", payload.ToString()); + + // Verify the collection + var expectedPayload = new Dictionary + { + ["string"] = "xyz", + ["data"] = 789, + + // FormattedLogValues adds this automatically to capture the string template + ["{OriginalFormat}"] = "This {string} has some {data}" + }; + + ValidateCollection(expectedPayload, payload); + } + + [Fact] + public void NoStringPayload() + { + var additionalPayload = new Dictionary() + { + ["additional"] = "abc", + ["payload"] = 123 + }; + + var payload = new FormattedLogValuesCollection("This string has no data", + null, new ReadOnlyDictionary(additionalPayload)); + + // Verify string behavior + Assert.Equal("This string has no data", payload.ToString()); + + // Verify the collection + var expectedPayload = new Dictionary + { + ["additional"] = "abc", + ["payload"] = 123, + + // FormattedLogValues adds this automatically to capture the string template + ["{OriginalFormat}"] = "This string has no data" + }; + + ValidateCollection(expectedPayload, payload); + } + + [Theory] + [InlineData(null)] + [InlineData("")] + public void NoString(string message) + { + var additionalPayload = new Dictionary() + { + ["additional"] = "abc", + ["payload"] = 123 + }; + + var payload = new FormattedLogValuesCollection(message, + null, new ReadOnlyDictionary(additionalPayload)); + + // Verify string behavior + // FormattedLogValues changes nulls to [null] + var expectedMessage = message ?? "[null]"; + Assert.Equal(expectedMessage, payload.ToString()); + + // Verify the collection + var expectedPayload = new Dictionary + { + ["additional"] = "abc", + ["payload"] = 123, + + // FormattedLogValues adds this automatically to capture the string template + ["{OriginalFormat}"] = expectedMessage + }; + + ValidateCollection(expectedPayload, payload); + } + + [Fact] + public void NullValues_WithCurlyBraces() + { + var additionalPayload = new Dictionary() + { + ["additional"] = "abc", + ["payload"] = 123 + }; + + var message = "{this} {should} {work} {"; + var payload = new FormattedLogValuesCollection(message, + null, new ReadOnlyDictionary(additionalPayload)); + + // Verify string behavior + Assert.Equal(message, payload.ToString()); + + // Verify the collection + var expectedPayload = new Dictionary + { + ["additional"] = "abc", + ["payload"] = 123, + + // FormattedLogValues adds this automatically to capture the string template + ["{OriginalFormat}"] = message + }; + + ValidateCollection(expectedPayload, payload); + } + + private static void ValidateCollection(IDictionary expectedPayload, + IReadOnlyList> actualPayload) + { + Assert.Equal(expectedPayload.Count, actualPayload.Count); + foreach (var kvp in actualPayload) + { + Assert.Equal(expectedPayload[kvp.Key], kvp.Value); + } + } + } +} diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/FunctionResultAggregatorConfigurationTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/FunctionResultAggregatorConfigurationTests.cs new file mode 100644 index 00000000..b7945cde --- /dev/null +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/FunctionResultAggregatorConfigurationTests.cs @@ -0,0 +1,70 @@ +// 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 Xunit; + +namespace Microsoft.Azure.WebJobs.Host.UnitTests.Loggers +{ + public class FunctionResultAggregatorConfigurationTests + { + [Fact] + public void DefaultValues() + { + var config = new FunctionResultAggregatorConfiguration(); + + Assert.Equal(TimeSpan.FromSeconds(30), config.FlushTimeout); + Assert.Equal(1000, config.BatchSize); + Assert.Equal(true, config.IsEnabled); + } + + [Theory] + [InlineData(0, true)] + [InlineData(10001, true)] + [InlineData(1, false)] + [InlineData(10000, false)] + public void BatchSize_Limits(int batchSize, bool throws) + { + var config = new FunctionResultAggregatorConfiguration(); + ArgumentOutOfRangeException caughtEx = null; + + try + { + config.BatchSize = batchSize; + } + catch (ArgumentOutOfRangeException ex) + { + caughtEx = ex; + } + + Assert.Equal(throws, caughtEx != null); + } + + public static object[][] TimeSpanData = new object[][] { + new object[] { TimeSpan.FromSeconds(300), false }, + new object[] { TimeSpan.FromSeconds(0), true }, + new object[] { TimeSpan.FromSeconds(301), true }, + new object[] { TimeSpan.FromSeconds(1), false }, + }; + + [Theory] + [MemberData(nameof(TimeSpanData))] + public void FlushTimeout_Limits(TimeSpan flushTimeout, bool throws) + { + var config = new FunctionResultAggregatorConfiguration(); + ArgumentOutOfRangeException caughtEx = null; + + try + { + config.FlushTimeout = flushTimeout; + } + catch (ArgumentOutOfRangeException ex) + { + caughtEx = ex; + } + + Assert.Equal(throws, caughtEx != null); + } + } +} diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/FunctionResultAggregatorTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/FunctionResultAggregatorTests.cs new file mode 100644 index 00000000..94c0df2b --- /dev/null +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/FunctionResultAggregatorTests.cs @@ -0,0 +1,209 @@ +// 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.Threading.Tasks; +using Microsoft.Azure.WebJobs.Host.Loggers; +using Microsoft.Extensions.Logging; +using Moq; +using Xunit; + +namespace Microsoft.Azure.WebJobs.Host.UnitTests.Loggers +{ + public class FunctionResultAggregatorTests + { + [Theory] + [InlineData(1)] + [InlineData(1000)] + public async Task Aggregator_Flushes_WhenBatchIsFull(int batchSize) + { + int publishCalls = 0; + + ILoggerFactory factory = CreateMockLoggerFactory((props) => + { + publishCalls++; + Assert.Equal(batchSize, props[LoggingKeys.Successes]); + }); + + var aggregator = new FunctionResultAggregator(batchSize, TimeSpan.FromMinutes(1), factory); + + await AddSuccessResults(aggregator, batchSize * 5); + + // allow a flush + await Task.Delay(100); + + Assert.Equal((batchSize * 5) / batchSize, publishCalls); + } + + [Fact] + public async Task Aggregator_Flushes_WhenTimerFires() + { + int batchSize = 1000; + int numberToInsert = 10; + int publishCalls = 0; + + ILoggerFactory factory = CreateMockLoggerFactory((props) => + { + publishCalls++; + Assert.Equal(numberToInsert, props[LoggingKeys.Successes]); + }); + + var aggregator = new FunctionResultAggregator(batchSize, TimeSpan.FromSeconds(1), factory); + + await AddSuccessResults(aggregator, numberToInsert); + + // allow the timer to fire + await Task.Delay(1100); + + Assert.Equal(1, publishCalls); + } + + [Fact] + public async Task Aggregator_AlternatesTimerAndBatch() + { + int publishCalls = 0; + int totalSuccesses = 0; + int batchSize = 100; + + ILoggerFactory factory = CreateMockLoggerFactory((props) => + { + publishCalls++; + totalSuccesses += Convert.ToInt32(props[LoggingKeys.Successes]); + }); + + var aggregator = new FunctionResultAggregator(batchSize, TimeSpan.FromSeconds(1), factory); + + // do this loop twice to ensure it continues working + for (int i = 0; i < 2; i++) + { + // insert 225. Expect 2 calls to publish, then a flush for 25. + await AddSuccessResults(aggregator, 225); + + await Task.Delay(1100); + Assert.Equal(3 * (i + 1), publishCalls); + } + + Assert.Equal(6, publishCalls); + Assert.Equal(450, totalSuccesses); + } + + [Fact] + public async Task Aggregator_FlushesOnCancelation() + { + int batchSize = 100; + int publishCalls = 0; + + ILoggerFactory factory = CreateMockLoggerFactory((props) => + { + publishCalls++; + Assert.Equal(10, props[LoggingKeys.Successes]); + }); + + var aggregator = new FunctionResultAggregator(batchSize, TimeSpan.FromSeconds(1), factory); + + await AddSuccessResults(aggregator, 10); + } + + [Fact] + public async Task Aggregator_Trims_DefaultClassName() + { + int batchSize = 10; + int publishCalls = 0; + + ILoggerFactory factory = CreateMockLoggerFactory((props) => + { + publishCalls++; + Assert.Equal(10, props[LoggingKeys.Successes]); + Assert.Equal("SomeTest", props[LoggingKeys.Name]); + }); + + var aggregator = new FunctionResultAggregator(batchSize, TimeSpan.FromSeconds(1), factory); + + await AddSuccessResults(aggregator, 10, "Functions.SomeTest"); + } + + [Fact] + public async Task Aggregator_DoesNotTrim_NonDefaultClassName() + { + int batchSize = 10; + int publishCalls = 0; + + ILoggerFactory factory = CreateMockLoggerFactory((props) => + { + publishCalls++; + Assert.Equal(10, props[LoggingKeys.Successes]); + Assert.Equal("AnotherClass.SomeTest", props[LoggingKeys.Name]); + }); + + var aggregator = new FunctionResultAggregator(batchSize, TimeSpan.FromSeconds(1), factory); + + await AddSuccessResults(aggregator, 10, "AnotherClass.SomeTest"); + } + + + private static async Task AddSuccessResults(IAsyncCollector aggregator, int count, string functionName = null) + { + // Simulate the real executor, where a "function start" and "function end" are both added. + // The aggregator will filter out any with EndTime == null + for (int i = 0; i < count; i++) + { + await aggregator.AddAsync(new FunctionInstanceLogEntry + { + FunctionName = functionName, + ErrorDetails = null, + EndTime = null + }); + + await aggregator.AddAsync(new FunctionInstanceLogEntry + { + FunctionName = functionName, + ErrorDetails = null, + EndTime = DateTime.Now + }); + } + } + + private static ILoggerFactory CreateMockLoggerFactory(Action> logAction) + { + ILogger logger = new MockLogger(logAction); + + Mock mockFactory = new Mock(); + mockFactory + .Setup(lf => lf.CreateLogger(It.IsAny())) + .Returns(logger); + + return mockFactory.Object; + } + + private class MockLogger : ILogger + { + private Action> _logAction; + + public MockLogger(Action> logAction) + { + _logAction = logAction; + } + public IDisposable BeginScope(TState state) + { + throw new NotImplementedException(); + } + + public bool IsEnabled(LogLevel logLevel) + { + // in these tests, we will only ever see Information; + Assert.Equal(LogLevel.Information, logLevel); + return true; + } + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + IEnumerable> props = state as IEnumerable>; + Assert.NotNull(props); + + _logAction(props.ToDictionary(k => k.Key, k => k.Value)); + } + } + } +} diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/LogCategoryFilterTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/LogCategoryFilterTests.cs new file mode 100644 index 00000000..d949c182 --- /dev/null +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/LogCategoryFilterTests.cs @@ -0,0 +1,34 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using Microsoft.Azure.WebJobs.Host.Loggers; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace Microsoft.Azure.WebJobs.Host.UnitTests.Loggers +{ + public class LogCategoryFilterTests + { + [Fact] + public void Filter_MatchesLongestCategory() + { + var filter = new LogCategoryFilter(); + filter.DefaultLevel = LogLevel.Error; + filter.CategoryLevels.Add("Microsoft", LogLevel.Critical); + filter.CategoryLevels.Add("Microsoft.Azure", LogLevel.Error); + filter.CategoryLevels.Add("Microsoft.Azure.WebJobs", LogLevel.Information); + filter.CategoryLevels.Add("Microsoft.Azure.WebJobs.Host", LogLevel.Trace); + + Assert.False(filter.Filter("Microsoft", LogLevel.Information)); + Assert.False(filter.Filter("Microsoft.Azure", LogLevel.Information)); + Assert.False(filter.Filter("Microsoft.Azure.WebJob", LogLevel.Information)); + Assert.False(filter.Filter("NoMatch", LogLevel.Information)); + + Assert.True(filter.Filter("Microsoft", LogLevel.Critical)); + Assert.True(filter.Filter("Microsoft.Azure", LogLevel.Critical)); + Assert.True(filter.Filter("Microsoft.Azure.WebJobs.Extensions", LogLevel.Information)); + Assert.True(filter.Filter("Microsoft.Azure.WebJobs.Host", LogLevel.Debug)); + Assert.True(filter.Filter("NoMatch", LogLevel.Error)); + } + } +} diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/LoggerExtensionsTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/LoggerExtensionsTests.cs new file mode 100644 index 00000000..d8e6b35a --- /dev/null +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/LoggerExtensionsTests.cs @@ -0,0 +1,191 @@ +// 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 Microsoft.Azure.WebJobs.Host.Loggers; +using Microsoft.Extensions.Logging; +using Moq; +using Xunit; + +namespace Microsoft.Azure.WebJobs.Host.UnitTests.Loggers +{ + public class LoggerExtensionsTests + { + private Guid _invocationId = Guid.NewGuid(); + private DateTime _startTime = DateTime.Now; + private DateTime _endTime; + private string _triggerReason = "new queue message"; + private string _functionShortName = "TestFunction"; + private string _functionFullName = "Functions.TestFunction"; + private IDictionary _arguments; + + public LoggerExtensionsTests() + { + _endTime = _startTime.AddMilliseconds(450); + _arguments = new Dictionary + { + ["queueMessage"] = "my message", + ["anotherParam"] = "some value" + }; + } + + [Fact] + public void LogFunctionResult_Succeeded_CreatesCorrectState() + { + int logCount = 0; + ILogger logger = CreateMockLogger((l, e, o, ex, f) => + { + logCount++; + Assert.Equal(LogLevel.Information, l); + Assert.Equal(0, e); + Assert.Null(ex); + Assert.Equal($"Executed '{_functionFullName}' (Succeeded, Id={_invocationId})", f(o, ex)); + + var payload = VerifyResultDefaultsAndConvert(o); + Assert.True((bool)payload[LoggingKeys.Succeeded]); + Assert.Equal("Executed '{FullName}' (Succeeded, Id={InvocationId})", payload[LoggingKeys.OriginalFormat]); + }); + + var result = CreateDefaultInstanceLogEntry(); + + logger.LogFunctionResult(_functionShortName, result, TimeSpan.FromMilliseconds(450)); + + Assert.Equal(1, logCount); + } + + [Fact] + public void LogFunctionResult_Failed_CreatesCorrectState() + { + int logCount = 0; + ILogger logger = CreateMockLogger((l, e, o, ex, f) => + { + logCount++; + Assert.Equal(LogLevel.Error, l); + Assert.Equal(0, e); + Assert.NotNull(ex); + Assert.IsType(ex); + Assert.Equal($"Executed '{_functionFullName}' (Failed, Id={_invocationId})", f(o, ex)); + + var payload = VerifyResultDefaultsAndConvert(o); + Assert.False((bool)payload[LoggingKeys.Succeeded]); + Assert.Equal("Executed '{FullName}' (Failed, Id={InvocationId})", payload[LoggingKeys.OriginalFormat]); + }); + + var result = CreateDefaultInstanceLogEntry(); + + var fex = new FunctionInvocationException("Failed"); + + logger.LogFunctionResult(_functionShortName, result, TimeSpan.FromMilliseconds(450), fex); + + Assert.Equal(1, logCount); + } + + [Fact] + public void LogFunctionResultAggregate_CreatesCorrectState() + { + DateTimeOffset now = DateTimeOffset.Now; + int logCount = 0; + ILogger logger = CreateMockLogger((l, e, o, ex, f) => + { + logCount++; + Assert.Equal(LogLevel.Information, l); + Assert.Equal(0, e); + Assert.Null(ex); + + // nothing logged + Assert.Equal(string.Empty, f(o, ex)); + + // convert to dictionary + var payload = o.ToDictionary(k => k.Key, v => v.Value); + + Assert.Equal(10, payload.Count); + Assert.Equal(_functionShortName, payload[LoggingKeys.Name]); + Assert.Equal(4, payload[LoggingKeys.Failures]); + Assert.Equal(116, payload[LoggingKeys.Successes]); + Assert.Equal(TimeSpan.FromMilliseconds(200), (TimeSpan)payload[LoggingKeys.MinDuration]); + Assert.Equal(TimeSpan.FromMilliseconds(2180), (TimeSpan)payload[LoggingKeys.MaxDuration]); + Assert.Equal(TimeSpan.FromMilliseconds(340), (TimeSpan)payload[LoggingKeys.AvgDuration]); + Assert.Equal(now, payload[LoggingKeys.Timestamp]); + Assert.Equal(120, payload[LoggingKeys.Count]); + Assert.Equal(96.67, payload[LoggingKeys.SuccessRate]); + + // {OriginalFormat} is still added, even though it is empty + Assert.Equal(string.Empty, payload[LoggingKeys.OriginalFormat]); + }); + + var resultAggregate = new FunctionResultAggregate + { + Name = _functionShortName, + Failures = 4, + Successes = 116, + MinDuration = TimeSpan.FromMilliseconds(200), + MaxDuration = TimeSpan.FromMilliseconds(2180), + AverageDuration = TimeSpan.FromMilliseconds(340), + Timestamp = now + }; + + logger.LogFunctionResultAggregate(resultAggregate); + + Assert.Equal(1, logCount); + } + + private FunctionInstanceLogEntry CreateDefaultInstanceLogEntry() + { + return new FunctionInstanceLogEntry + { + FunctionName = _functionFullName, + FunctionInstanceId = _invocationId, + StartTime = _startTime, + EndTime = _endTime, + LogOutput = "a bunch of output that we will not forward", // not used here -- this is all Traced + TriggerReason = _triggerReason, + ParentId = Guid.NewGuid(), // we do not track this + ErrorDetails = null, // we do not use this -- we pass the exception in separately + Arguments = _arguments + }; + } + + private IDictionary VerifyResultDefaultsAndConvert(TState state) + { + var enumerable = state as IEnumerable>; + Assert.NotNull(enumerable); + + var payload = enumerable.ToDictionary(k => k.Key, v => v.Value); + + Assert.Equal(11, payload.Count); + Assert.Equal(_functionFullName, payload[LoggingKeys.FullName]); + Assert.Equal(_functionShortName, payload[LoggingKeys.Name]); + Assert.Equal(_invocationId, payload[LoggingKeys.InvocationId]); + Assert.Equal(_startTime, payload[LoggingKeys.StartTime]); + Assert.Equal(_endTime, payload[LoggingKeys.EndTime]); + Assert.Equal(TimeSpan.FromMilliseconds(450), payload[LoggingKeys.Duration]); + Assert.Equal(_triggerReason, payload[LoggingKeys.TriggerReason]); + + // verify default arguments were passed with prefix + var args = payload.Where(kvp => kvp.Value is string && kvp.Key.ToString().StartsWith(LoggingKeys.ParameterPrefix)); + Assert.Equal(_arguments.Count, args.Count()); + foreach (var arg in _arguments) + { + var payloadKey = LoggingKeys.ParameterPrefix + arg.Key; + Assert.Equal(arg.Value, args.Single(kvp => kvp.Key == payloadKey).Value.ToString()); + } + + return payload; + } + + private static ILogger CreateMockLogger(Action> callback) + { + var mockLogger = new Mock(MockBehavior.Strict); + mockLogger + .Setup(l => l.Log(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny>())) + .Callback>((l, e, o, ex, f) => + { + callback(l, e, o, ex, f); + }); + + return mockLogger.Object; + } + } +} diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/TestTelemetryChannel.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/TestTelemetryChannel.cs new file mode 100644 index 00000000..bf34be7d --- /dev/null +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/TestTelemetryChannel.cs @@ -0,0 +1,31 @@ + +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using System.Collections.Concurrent; +using Microsoft.ApplicationInsights.Channel; + +namespace Microsoft.Azure.WebJobs.Host.UnitTests.Loggers +{ + internal class TestTelemetryChannel : ITelemetryChannel + { + public ConcurrentBag Telemetries = new ConcurrentBag(); + + public bool? DeveloperMode { get; set; } + + public string EndpointAddress { get; set; } + + public void Dispose() + { + } + + public void Flush() + { + } + + public void Send(ITelemetry item) + { + Telemetries.Add(item); + } + } +} diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/PublicSurfaceTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/PublicSurfaceTests.cs index eb1c4412..9b41d585 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/PublicSurfaceTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/PublicSurfaceTests.cs @@ -226,7 +226,13 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests "RecoverableException", "FunctionException", "FunctionListenerException", - "ExceptionFormatter" + "ExceptionFormatter", + "FunctionResultAggregatorConfiguration", + "ApplicationInsightsLoggerExtensions", + "LogCategoryFilter", + "LogCategories", + "ITelemetryClientFactory", + "DefaultTelemetryClientFactory" }; AssertPublicTypes(expected, assembly); diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Queues/QueueListenerTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Queues/QueueListenerTests.cs index 8501c4a4..91459019 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Queues/QueueListenerTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Queues/QueueListenerTests.cs @@ -3,7 +3,6 @@ using System; using System.Diagnostics; -using System.IO; using System.Threading; using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host.Executors; @@ -13,6 +12,7 @@ using Microsoft.Azure.WebJobs.Host.Queues.Listeners; using Microsoft.Azure.WebJobs.Host.Storage.Queue; using Microsoft.Azure.WebJobs.Host.TestCommon; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage.Queue; using Moq; using Xunit; @@ -25,6 +25,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Queues private Mock _mockQueueProcessor; private Mock> _mockTriggerExecutor; private StorageQueueMessage _storageMessage; + private ILoggerFactory _loggerFactory; public QueueListenerTests() { @@ -34,10 +35,12 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Queues _mockTriggerExecutor = new Mock>(MockBehavior.Strict); Mock mockExceptionDispatcher = new Mock(MockBehavior.Strict); - TestTraceWriter log = new TestTraceWriter(TraceLevel.Verbose); + TestTraceWriter trace = new TestTraceWriter(TraceLevel.Verbose); + _loggerFactory = new LoggerFactory(); + _loggerFactory.AddProvider(new TestLoggerProvider()); Mock mockQueueProcessorFactory = new Mock(MockBehavior.Strict); JobHostQueuesConfiguration queuesConfig = new JobHostQueuesConfiguration(); - QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(queue, log, queuesConfig); + QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(queue, trace, _loggerFactory, queuesConfig); _mockQueueProcessor = new Mock(MockBehavior.Strict, context); JobHostQueuesConfiguration queueConfig = new JobHostQueuesConfiguration @@ -48,7 +51,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Queues mockQueueProcessorFactory.Setup(p => p.Create(It.IsAny())).Returns(_mockQueueProcessor.Object); - _listener = new QueueListener(mockQueue.Object, null, _mockTriggerExecutor.Object, mockExceptionDispatcher.Object, log, null, queueConfig); + _listener = new QueueListener(mockQueue.Object, null, _mockTriggerExecutor.Object, mockExceptionDispatcher.Object, trace, _loggerFactory, null, queueConfig); CloudQueueMessage cloudMessage = new CloudQueueMessage("TestMessage"); _storageMessage = new StorageQueueMessage(cloudMessage); @@ -58,7 +61,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Queues public void CreateQueueProcessor_CreatesProcessorCorrectly() { CloudQueue poisonQueue = null; - TestTraceWriter log = new TestTraceWriter(TraceLevel.Verbose); + TestTraceWriter trace = new TestTraceWriter(TraceLevel.Verbose); bool poisonMessageHandlerInvoked = false; EventHandler poisonMessageEventHandler = (sender, e) => { poisonMessageHandlerInvoked = true; }; Mock mockQueueProcessorFactory = new Mock(MockBehavior.Strict); @@ -72,7 +75,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Queues // create for a host queue - don't expect custom factory to be invoked CloudQueue queue = new CloudQueue(new Uri(string.Format("https://test.queue.core.windows.net/{0}", HostQueueNames.GetHostQueueName("12345")))); - QueueProcessor queueProcessor = QueueListener.CreateQueueProcessor(queue, poisonQueue, log, queueConfig, poisonMessageEventHandler); + QueueProcessor queueProcessor = QueueListener.CreateQueueProcessor(queue, poisonQueue, trace, _loggerFactory, queueConfig, poisonMessageEventHandler); Assert.False(processorFactoryInvoked); Assert.NotSame(expectedQueueProcessor, queueProcessor); queueProcessor.OnMessageAddedToPoisonQueue(new PoisonMessageEventArgs(null, poisonQueue)); @@ -87,11 +90,12 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Queues Assert.Same(queue, mockProcessorContext.Queue); Assert.Same(poisonQueue, mockProcessorContext.PoisonQueue); Assert.Equal(queueConfig.MaxDequeueCount, mockProcessorContext.MaxDequeueCount); - Assert.Same(log, mockProcessorContext.Trace); + Assert.Same(trace, mockProcessorContext.Trace); + Assert.NotNull(mockProcessorContext.Logger); processorFactoryContext = mockProcessorContext; }) - .Returns(() => + .Returns(() => { expectedQueueProcessor = new QueueProcessor(processorFactoryContext); return expectedQueueProcessor; @@ -101,7 +105,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Queues // host queues (this enables local test mocking) processorFactoryInvoked = false; queue = new CloudQueue(new Uri(string.Format("https://localhost/{0}", HostQueueNames.GetHostQueueName("12345")))); - queueProcessor = QueueListener.CreateQueueProcessor(queue, poisonQueue, log, queueConfig, poisonMessageEventHandler); + queueProcessor = QueueListener.CreateQueueProcessor(queue, poisonQueue, trace, _loggerFactory, queueConfig, poisonMessageEventHandler); Assert.True(processorFactoryInvoked); Assert.Same(expectedQueueProcessor, queueProcessor); @@ -109,7 +113,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Queues poisonMessageHandlerInvoked = false; processorFactoryInvoked = false; queue = new CloudQueue(new Uri("https://test.queue.core.windows.net/testqueue")); - queueProcessor = QueueListener.CreateQueueProcessor(queue, poisonQueue, log, queueConfig, poisonMessageEventHandler); + queueProcessor = QueueListener.CreateQueueProcessor(queue, poisonQueue, trace, _loggerFactory, queueConfig, poisonMessageEventHandler); Assert.True(processorFactoryInvoked); Assert.Same(expectedQueueProcessor, queueProcessor); queueProcessor.OnMessageAddedToPoisonQueue(new PoisonMessageEventArgs(null, poisonQueue)); @@ -118,7 +122,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Queues // if poison message watcher not specified, event not subscribed to poisonMessageHandlerInvoked = false; processorFactoryInvoked = false; - queueProcessor = QueueListener.CreateQueueProcessor(queue, poisonQueue, log, queueConfig, null); + queueProcessor = QueueListener.CreateQueueProcessor(queue, poisonQueue, trace, _loggerFactory, queueConfig, null); Assert.True(processorFactoryInvoked); Assert.Same(expectedQueueProcessor, queueProcessor); queueProcessor.OnMessageAddedToPoisonQueue(new PoisonMessageEventArgs(null, poisonQueue)); diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Queues/QueueProcessorFactoryContextTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Queues/QueueProcessorFactoryContextTests.cs index f80b2bc2..eac59a1f 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Queues/QueueProcessorFactoryContextTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Queues/QueueProcessorFactoryContextTests.cs @@ -3,9 +3,10 @@ using System; using System.Diagnostics; -using System.IO; +using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Queues; using Microsoft.Azure.WebJobs.Host.TestCommon; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage.Queue; using Xunit; @@ -18,14 +19,17 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Queues { CloudQueue queue = new CloudQueue(new Uri("https://test.queue.core.windows.net/testqueue")); CloudQueue poisonQueue = new CloudQueue(new Uri("https://test.queue.core.windows.net/poisonqueue")); - TestTraceWriter log = new TestTraceWriter(TraceLevel.Verbose); + TestTraceWriter trace = new TestTraceWriter(TraceLevel.Verbose); + ILoggerFactory loggerFactory = new LoggerFactory(); + loggerFactory.AddProvider(new TestLoggerProvider()); JobHostQueuesConfiguration queuesConfig = new JobHostQueuesConfiguration(); - QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(queue, log, queuesConfig, poisonQueue); + QueueProcessorFactoryContext context = new QueueProcessorFactoryContext(queue, trace, loggerFactory, queuesConfig, poisonQueue); Assert.Same(queue, context.Queue); - Assert.Same(log, context.Trace); + Assert.Same(trace, context.Trace); Assert.Same(poisonQueue, context.PoisonQueue); + Assert.NotNull(context.Logger); Assert.Equal(queuesConfig.BatchSize, context.BatchSize); Assert.Equal(queuesConfig.NewBatchThreshold, context.NewBatchThreshold); diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Queues/QueueTriggerBindingIntegrationTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Queues/QueueTriggerBindingIntegrationTests.cs index 95bbb548..f3d18dc5 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Queues/QueueTriggerBindingIntegrationTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Queues/QueueTriggerBindingIntegrationTests.cs @@ -34,7 +34,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Queues _binding = new QueueTriggerBinding("parameterName", queue, argumentBinding, new Mock(MockBehavior.Strict).Object, exceptionHandler, new Mock>(MockBehavior.Strict).Object, - new SharedContextProvider(), new TestTraceWriter(TraceLevel.Verbose)); + new SharedContextProvider(), new TestTraceWriter(TraceLevel.Verbose), null); } [Theory] diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonListenerTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonListenerTests.cs index be02dea0..ac7b66d0 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonListenerTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonListenerTests.cs @@ -31,10 +31,12 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Singleton { LockPeriod = TimeSpan.FromSeconds(20) }; - _mockSingletonManager = new Mock(MockBehavior.Strict, null, null, null, null, new FixedHostIdProvider(TestHostId), null); + _mockSingletonManager = new Mock(MockBehavior.Strict, null, null, null, null, null, new FixedHostIdProvider(TestHostId), null); _mockSingletonManager.SetupGet(p => p.Config).Returns(_config); _mockInnerListener = new Mock(MockBehavior.Strict); - _listener = new SingletonListener(methodInfo, _attribute, _mockSingletonManager.Object, _mockInnerListener.Object, new TestTraceWriter(System.Diagnostics.TraceLevel.Verbose)); + + _listener = new SingletonListener(methodInfo, _attribute, _mockSingletonManager.Object, _mockInnerListener.Object, + new TestTraceWriter(System.Diagnostics.TraceLevel.Verbose), null); _lockId = SingletonManager.FormatLockId(methodInfo, SingletonScope.Function, TestHostId, _attribute.ScopeId) + ".Listener"; } @@ -59,7 +61,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Singleton public async Task StartAsync_DoesNotStartListener_WhenLockCannotBeAcquired() { CancellationToken cancellationToken = new CancellationToken(); - _mockSingletonManager.Setup(p => p.TryLockAsync(_lockId, null, _attribute, cancellationToken, false)) + _mockSingletonManager.Setup(p => p.TryLockAsync(_lockId, null, _attribute, cancellationToken, false)) .ReturnsAsync((object)null); await _listener.StartAsync(cancellationToken); diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonManagerTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonManagerTests.cs index 0e11cd2f..f3d8c04a 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonManagerTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonManagerTests.cs @@ -9,10 +9,12 @@ using System.Reflection; using System.Threading; using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host.Executors; +using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Storage; using Microsoft.Azure.WebJobs.Host.Storage.Blob; using Microsoft.Azure.WebJobs.Host.TestCommon; using Microsoft.Azure.WebJobs.Host.Timers; +using Microsoft.Extensions.Logging; using Microsoft.WindowsAzure.Storage; using Microsoft.WindowsAzure.Storage.Blob; using Moq; @@ -39,6 +41,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Singleton private Mock _mockExceptionDispatcher; private Mock _mockStorageBlob; private TestTraceWriter _trace = new TestTraceWriter(TraceLevel.Verbose); + private TestLoggerProvider _loggerProvider; private Dictionary _mockBlobMetadata; private TestNameResolver _nameResolver; @@ -79,7 +82,14 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Singleton _singletonConfig.LockAcquisitionTimeout = TimeSpan.FromMilliseconds(200); _nameResolver = new TestNameResolver(); - _singletonManager = new SingletonManager(_mockAccountProvider.Object, _mockExceptionDispatcher.Object, _singletonConfig, _trace, new FixedHostIdProvider(TestHostId), _nameResolver); + + ILoggerFactory loggerFactory = new LoggerFactory(); + // We want to see all logs, so set the default level to Trace. + LogCategoryFilter filter = new LogCategoryFilter { DefaultLevel = Extensions.Logging.LogLevel.Trace }; + _loggerProvider = new TestLoggerProvider(filter.Filter); + loggerFactory.AddProvider(_loggerProvider); + + _singletonManager = new SingletonManager(_mockAccountProvider.Object, _mockExceptionDispatcher.Object, _singletonConfig, _trace, loggerFactory, new FixedHostIdProvider(TestHostId), _nameResolver); _singletonManager.MinimumLeaseRenewalInterval = TimeSpan.FromMilliseconds(250); } @@ -170,6 +180,13 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Singleton Assert.Equal(1, _trace.Traces.Count(p => p.ToString().Contains("Verbose Singleton lock acquired (testid)"))); Assert.Equal(1, _trace.Traces.Count(p => p.ToString().Contains("Verbose Singleton lock released (testid)"))); + // verify the logger + TestLogger logger = _loggerProvider.CreatedLoggers.Single() as TestLogger; + Assert.Equal(LogCategories.Singleton, logger.Category); + Assert.Equal(2, logger.LogMessages.Count); + Assert.NotNull(logger.LogMessages.Single(m => m.Level == Extensions.Logging.LogLevel.Debug && m.FormattedMessage == "Singleton lock acquired (testid)")); + Assert.NotNull(logger.LogMessages.Single(m => m.Level == Extensions.Logging.LogLevel.Debug && m.FormattedMessage == "Singleton lock released (testid)")); + renewCount = 0; await Task.Delay(1000); @@ -334,7 +351,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Singleton { Mock mockHostIdProvider = new Mock(MockBehavior.Strict); mockHostIdProvider.Setup(p => p.GetHostIdAsync(CancellationToken.None)).ReturnsAsync(TestHostId); - SingletonManager singletonManager = new SingletonManager(null, null, null, null, mockHostIdProvider.Object); + SingletonManager singletonManager = new SingletonManager(null, null, null, null, null, mockHostIdProvider.Object); Assert.Equal(TestHostId, singletonManager.HostId); Assert.Equal(TestHostId, singletonManager.HostId); diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonValueProviderTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonValueProviderTests.cs index 40a02e65..8e1a8e16 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonValueProviderTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonValueProviderTests.cs @@ -24,7 +24,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Singleton public SingletonValueProviderTests() { _attribute = new SingletonAttribute("TestScope"); - SingletonManager singletonManager = new SingletonManager(null, null, null, null, new FixedHostIdProvider(TestHostId)); + SingletonManager singletonManager = new SingletonManager(null, null, null, null, null, new FixedHostIdProvider(TestHostId)); _method = GetType().GetMethod("TestJob", BindingFlags.Static | BindingFlags.Public); _lockId = SingletonManager.FormatLockId(_method, SingletonScope.Function, TestHostId, _attribute.ScopeId); _valueProvider = new SingletonValueProvider(_method, "TestScope", TestInstanceId, _attribute, singletonManager); @@ -54,7 +54,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Singleton [Fact] public async Task ToInvokeString_ReturnsExpectedValue() { - SingletonManager singletonManager = new SingletonManager(null, null, null, null, new FixedHostIdProvider(TestHostId)); + SingletonManager singletonManager = new SingletonManager(null, null, null, null, null, new FixedHostIdProvider(TestHostId)); SingletonAttribute attribute = new SingletonAttribute(); SingletonValueProvider localValueProvider = new SingletonValueProvider(_method, attribute.ScopeId, TestInstanceId, attribute, singletonManager); SingletonLock singletonLock = (SingletonLock)(await localValueProvider.GetValueAsync()); @@ -69,7 +69,7 @@ namespace Microsoft.Azure.WebJobs.Host.UnitTests.Singleton [Fact] public async Task SingletonWatcher_GetStatus_ReturnsExpectedValue() { - Mock mockSingletonManager = new Mock(MockBehavior.Strict, null, null, null, null, new FixedHostIdProvider(TestHostId), null); + Mock mockSingletonManager = new Mock(MockBehavior.Strict, null, null, null, null, null, new FixedHostIdProvider(TestHostId), null); mockSingletonManager.Setup(p => p.GetLockOwnerAsync(_attribute, _lockId, CancellationToken.None)).ReturnsAsync("someotherguy"); SingletonValueProvider localValueProvider = new SingletonValueProvider(_method, _attribute.ScopeId, TestInstanceId, _attribute, mockSingletonManager.Object); SingletonLock localSingletonLock = (SingletonLock)(await localValueProvider.GetValueAsync()); diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/WebJobs.Host.UnitTests.csproj b/test/Microsoft.Azure.WebJobs.Host.UnitTests/WebJobs.Host.UnitTests.csproj index 720b325f..075b3d3a 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/WebJobs.Host.UnitTests.csproj +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/WebJobs.Host.UnitTests.csproj @@ -54,6 +54,10 @@ ..\..\packages\Castle.Core.3.3.3\lib\net45\Castle.Core.dll True + + ..\..\packages\Microsoft.ApplicationInsights.2.3.0\lib\net46\Microsoft.ApplicationInsights.dll + True + ..\..\packages\Microsoft.Azure.KeyVault.Core.1.0.0\lib\net40\Microsoft.Azure.KeyVault.Core.dll True @@ -70,6 +74,22 @@ ..\..\packages\Microsoft.Data.Services.Client.5.8.2\lib\net40\Microsoft.Data.Services.Client.dll True + + ..\..\packages\Microsoft.Extensions.DependencyInjection.Abstractions.1.1.0\lib\netstandard1.0\Microsoft.Extensions.DependencyInjection.Abstractions.dll + True + + + ..\..\packages\Microsoft.Extensions.Logging.1.1.1\lib\netstandard1.1\Microsoft.Extensions.Logging.dll + True + + + ..\..\packages\Microsoft.Extensions.Logging.Abstractions.1.1.1\lib\netstandard1.1\Microsoft.Extensions.Logging.Abstractions.dll + True + + + ..\..\packages\Microsoft.Win32.Primitives.4.3.0\lib\net46\Microsoft.Win32.Primitives.dll + True + ..\..\packages\Microsoft.WindowsAzure.ConfigurationManager.3.2.3\lib\net40\Microsoft.WindowsAzure.Configuration.dll True @@ -87,17 +107,84 @@ True + + ..\..\packages\System.AppContext.4.3.0\lib\net46\System.AppContext.dll + True + + + + ..\..\packages\System.Console.4.3.0\lib\net46\System.Console.dll + True + 3.5 + + ..\..\packages\System.Diagnostics.DiagnosticSource.4.3.0\lib\net46\System.Diagnostics.DiagnosticSource.dll + True + + + ..\..\packages\System.Globalization.Calendars.4.3.0\lib\net46\System.Globalization.Calendars.dll + True + + + ..\..\packages\System.IO.Compression.4.3.0\lib\net46\System.IO.Compression.dll + True + + + + ..\..\packages\System.IO.Compression.ZipFile.4.3.0\lib\net46\System.IO.Compression.ZipFile.dll + True + + + ..\..\packages\System.IO.FileSystem.4.3.0\lib\net46\System.IO.FileSystem.dll + True + + + ..\..\packages\System.IO.FileSystem.Primitives.4.3.0\lib\net46\System.IO.FileSystem.Primitives.dll + True + + + ..\..\packages\System.Net.Http.4.3.1\lib\net46\System.Net.Http.dll + True + + + ..\..\packages\System.Net.Sockets.4.3.0\lib\net46\System.Net.Sockets.dll + True + + + ..\..\packages\System.Runtime.InteropServices.RuntimeInformation.4.3.0\lib\net45\System.Runtime.InteropServices.RuntimeInformation.dll + True + + + ..\..\packages\System.Security.Cryptography.Algorithms.4.3.0\lib\net46\System.Security.Cryptography.Algorithms.dll + True + + + ..\..\packages\System.Security.Cryptography.Encoding.4.3.0\lib\net46\System.Security.Cryptography.Encoding.dll + True + + + ..\..\packages\System.Security.Cryptography.Primitives.4.3.0\lib\net46\System.Security.Cryptography.Primitives.dll + True + + + ..\..\packages\System.Security.Cryptography.X509Certificates.4.3.0\lib\net46\System.Security.Cryptography.X509Certificates.dll + True + ..\..\packages\System.Spatial.5.8.2\lib\net40\System.Spatial.dll True + + + ..\..\packages\System.Xml.ReaderWriter.4.3.0\lib\net46\System.Xml.ReaderWriter.dll + True + ..\..\packages\xunit.abstractions.2.0.0\lib\net35\xunit.abstractions.dll True @@ -155,6 +242,7 @@ + @@ -197,6 +285,12 @@ + + + + + + diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/app.config b/test/Microsoft.Azure.WebJobs.Host.UnitTests/app.config index a7388136..edadf40e 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/app.config +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/app.config @@ -1,37 +1,45 @@ - + - - - - + + + + - - + + - - + + - - + + - - + + - - + + - - + + + + + + + + + + - + diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/packages.config b/test/Microsoft.Azure.WebJobs.Host.UnitTests/packages.config index 3de92605..11198f2e 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/packages.config +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/packages.config @@ -1,18 +1,69 @@  + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + diff --git a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/app.config b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/app.config index 001d0e4e..1c956112 100644 --- a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/app.config +++ b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/app.config @@ -1,37 +1,41 @@ - + - + - - + + - - + + - - + + - - + + - - + + - - + + - - + + + + + + @@ -39,26 +43,26 @@ - - - + + + - - - - - + + + + + - - - - - - - + + + + + + + - +