diff --git a/samples/FunctionApp/Function4/Function4.cs b/samples/FunctionApp/Function4/Function4.cs index 0f9fdbc69..4a0893212 100644 --- a/samples/FunctionApp/Function4/Function4.cs +++ b/samples/FunctionApp/Function4/Function4.cs @@ -17,7 +17,8 @@ public static class Function4 [FunctionName("Function4")] public static HttpResponseData Run([HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequestData req, FunctionContext executionContext) { - var logger = executionContext.Logger; + var logger = executionContext.GetLogger("FunctionApp.Function4"); + logger.LogInformation("message logged"); var response = new HttpResponseData(HttpStatusCode.OK); var headers = new Dictionary(); diff --git a/samples/FunctionApp/Function5/Function5.cs b/samples/FunctionApp/Function5/Function5.cs index 5bcf752c8..a0f0924a8 100644 --- a/samples/FunctionApp/Function5/Function5.cs +++ b/samples/FunctionApp/Function5/Function5.cs @@ -14,17 +14,18 @@ namespace FunctionApp public class Function5 { private readonly IHttpResponderService _responderService; + private readonly ILogger _logger; - public Function5(IHttpResponderService responderService) + public Function5(IHttpResponderService responderService, ILogger logger) { _responderService = responderService; + _logger = logger; } [FunctionName(nameof(Function5))] - public HttpResponseData Run([HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequestData req, FunctionContext executionContext) + public HttpResponseData Run([HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequestData req) { - var logger = executionContext.Logger; - logger.LogInformation("message logged"); + _logger.LogInformation("message logged"); return _responderService.ProcessRequest(req); } diff --git a/samples/SampleApp/Blob/BlobFunction.cs b/samples/SampleApp/Blob/BlobFunction.cs index 9ab8ba118..09f5eeab8 100644 --- a/samples/SampleApp/Blob/BlobFunction.cs +++ b/samples/SampleApp/Blob/BlobFunction.cs @@ -17,7 +17,7 @@ public static void Run( [BlobInput("test-samples-input/sample1.txt", Connection = "AzureWebJobsStorage")] string myBlob, FunctionContext context) { - var logger = context.Logger; + var logger = context.GetLogger("BlobFunction"); logger.LogInformation($"Triggered Item = {myTriggerItem}"); logger.LogInformation($"Input Item = {myBlob}"); diff --git a/samples/SampleApp/CosmosDB/CosmosDBFunction.cs b/samples/SampleApp/CosmosDB/CosmosDBFunction.cs index 114ba8157..34fb1584a 100644 --- a/samples/SampleApp/CosmosDB/CosmosDBFunction.cs +++ b/samples/SampleApp/CosmosDB/CosmosDBFunction.cs @@ -1,7 +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.Collections.Generic; +using System.Collections.Generic; using System.Linq; using Microsoft.Azure.Functions.Worker; using Microsoft.Azure.Functions.Worker.Extensions.Abstractions; @@ -19,7 +19,7 @@ public static void Run( LeaseCollectionName = "leases", CreateLeaseCollectionIfNotExists = true)] IReadOnlyList input, FunctionContext context) { - var logger = context.Logger; + var logger = context.GetLogger("CosmosDBFunction"); if (input != null && input.Any()) { diff --git a/samples/SampleApp/DependencyInjection/DependencyInjectionFunction.cs b/samples/SampleApp/DependencyInjection/DependencyInjectionFunction.cs index 84dc99b6f..6e725bcba 100644 --- a/samples/SampleApp/DependencyInjection/DependencyInjectionFunction.cs +++ b/samples/SampleApp/DependencyInjection/DependencyInjectionFunction.cs @@ -6,7 +6,6 @@ using Microsoft.Azure.Functions.Worker; using Microsoft.Azure.Functions.Worker.Extensions.Abstractions; using Microsoft.Azure.Functions.Worker.Extensions.Http; -using Microsoft.Azure.Functions.Worker.Pipeline; using Microsoft.Extensions.Logging; namespace SampleApp @@ -14,18 +13,19 @@ namespace SampleApp public class DependencyInjectionFunction { private readonly IHttpResponderService _responderService; + private readonly ILogger _logger; - public DependencyInjectionFunction(IHttpResponderService responderService) + public DependencyInjectionFunction(IHttpResponderService responderService, ILogger logger) { _responderService = responderService; + _logger = logger; } [FunctionName(nameof(DependencyInjectionFunction))] public HttpResponseData Run([HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequestData req, - FunctionContext executionContext) + FunctionContext context) { - var logger = executionContext.Logger; - logger.LogInformation("message logged"); + _logger.LogInformation("message logged"); return _responderService.ProcessRequest(req); } diff --git a/samples/SampleApp/EventGrid/EventGridFunction.cs b/samples/SampleApp/EventGrid/EventGridFunction.cs index 04d7031f3..678a28c7f 100644 --- a/samples/SampleApp/EventGrid/EventGridFunction.cs +++ b/samples/SampleApp/EventGrid/EventGridFunction.cs @@ -1,7 +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.Collections.Generic; +using System.Collections.Generic; using Microsoft.Azure.Functions.Worker; using Microsoft.Azure.Functions.Worker.Extensions.Abstractions; using Microsoft.Azure.Functions.Worker.Extensions.EventGrid; @@ -15,7 +15,7 @@ public static class EventGridFunction [EventGridOutput("output", TopicEndpointUri = "MyEventGridTopicUriSetting", TopicKeySetting = "MyEventGridTopicKeySetting")] public static void Run([EventGridTrigger] MyEventType input, FunctionContext context) { - var logger = context.Logger; + var logger = context.GetLogger("EventGridFunction"); logger.LogInformation(input.Data.ToString()); diff --git a/samples/SampleApp/EventHubs/EventHubsFunction.cs b/samples/SampleApp/EventHubs/EventHubsFunction.cs index b69d610d2..1668ec0a1 100644 --- a/samples/SampleApp/EventHubs/EventHubsFunction.cs +++ b/samples/SampleApp/EventHubs/EventHubsFunction.cs @@ -1,7 +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; +using System; using Microsoft.Azure.Functions.Worker; using Microsoft.Azure.Functions.Worker.Extensions.Abstractions; using Microsoft.Azure.Functions.Worker.Extensions.EventHubs; @@ -16,7 +16,7 @@ public static class EventHubsFunction public static void Run([EventHubTrigger("src", Connection = "EventHubConnectionAppSetting")] string input, FunctionContext context) { - var logger = context.Logger; + var logger = context.GetLogger("EventHubsFunction"); logger.LogInformation(input); diff --git a/samples/SampleApp/Http/HttpFunction.cs b/samples/SampleApp/Http/HttpFunction.cs index caee858eb..cc9d551a1 100644 --- a/samples/SampleApp/Http/HttpFunction.cs +++ b/samples/SampleApp/Http/HttpFunction.cs @@ -6,7 +6,6 @@ using Microsoft.Azure.Functions.Worker; using Microsoft.Azure.Functions.Worker.Extensions.Abstractions; using Microsoft.Azure.Functions.Worker.Extensions.Http; -using Microsoft.Azure.Functions.Worker.Pipeline; using Microsoft.Extensions.Logging; namespace SampleApp @@ -17,7 +16,7 @@ public static class HttpFunction public static HttpResponseData Run([HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequestData req, FunctionContext executionContext) { - var logger = executionContext.Logger; + var logger = executionContext.GetLogger("HttpFunction"); logger.LogInformation("message logged"); var response = new HttpResponseData(HttpStatusCode.OK); var headers = new Dictionary(); diff --git a/samples/SampleApp/Kafka/KafkaFunction.cs b/samples/SampleApp/Kafka/KafkaFunction.cs index ffc88216b..c4c6a99ba 100644 --- a/samples/SampleApp/Kafka/KafkaFunction.cs +++ b/samples/SampleApp/Kafka/KafkaFunction.cs @@ -1,7 +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; +using System; using Microsoft.Azure.Functions.Worker; using Microsoft.Azure.Functions.Worker.Extensions.Abstractions; using Microsoft.Azure.Functions.Worker.Extensions.Kafka; @@ -17,7 +17,7 @@ public static void Run([KafkaTrigger("LocalBroker", "stringTopicTenPartitions", ConsumerGroup = "$Default", AuthenticationMode = BrokerAuthenticationMode.Plain)] string input, FunctionContext context) { - var logger = context.Logger; + var logger = context.GetLogger("KafkaFunction"); logger.LogInformation(input); diff --git a/samples/SampleApp/Queue/QueueFunction.cs b/samples/SampleApp/Queue/QueueFunction.cs index fa654d15c..81a889114 100644 --- a/samples/SampleApp/Queue/QueueFunction.cs +++ b/samples/SampleApp/Queue/QueueFunction.cs @@ -15,7 +15,7 @@ public static class QueueFunction public static void Run([QueueTrigger("functionstesting2", Connection = "AzureWebJobsStorage")] Book myQueueItem, FunctionContext context) { - var logger = context.Logger; + var logger = context.GetLogger("QueueFunction"); logger.LogInformation($"Book name = {myQueueItem.Name}"); // Queue Output diff --git a/samples/SampleApp/RabbitMQ/RabbitMQFunction.cs b/samples/SampleApp/RabbitMQ/RabbitMQFunction.cs index 7833315d2..439d85eaf 100644 --- a/samples/SampleApp/RabbitMQ/RabbitMQFunction.cs +++ b/samples/SampleApp/RabbitMQ/RabbitMQFunction.cs @@ -1,7 +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; +using System; using Microsoft.Azure.Functions.Worker; using Microsoft.Azure.Functions.Worker.Extensions.Abstractions; using Microsoft.Azure.Functions.Worker.Extensions.RabbitMQ; @@ -16,7 +16,7 @@ public static class RabbitMQFunction public static void Run([RabbitMQTrigger("queue", ConnectionStringSetting = "rabbitMQConnectionAppSetting")] string item, FunctionContext context) { - var logger = context.Logger; + var logger = context.GetLogger("RabbitMQFunction"); logger.LogInformation(item); diff --git a/samples/SampleApp/ServiceBus/ServiceBusFunction.cs b/samples/SampleApp/ServiceBus/ServiceBusFunction.cs index 9dcc81b2f..1ec5d8b71 100644 --- a/samples/SampleApp/ServiceBus/ServiceBusFunction.cs +++ b/samples/SampleApp/ServiceBus/ServiceBusFunction.cs @@ -1,7 +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; +using System; using Microsoft.Azure.Functions.Worker; using Microsoft.Azure.Functions.Worker.Extensions.Abstractions; using Microsoft.Azure.Functions.Worker.Extensions.ServiceBus; @@ -16,7 +16,7 @@ public static class ServiceBusFunction public static void Run([ServiceBusTrigger("queue", Connection = "ServiceBusConnection")] string item, FunctionContext context) { - var logger = context.Logger; + var logger = context.GetLogger("ServiceBusFunction"); logger.LogInformation(item); diff --git a/samples/SampleApp/SignalR/SignalRFunction.cs b/samples/SampleApp/SignalR/SignalRFunction.cs index d171ffb47..ee861628b 100644 --- a/samples/SampleApp/SignalR/SignalRFunction.cs +++ b/samples/SampleApp/SignalR/SignalRFunction.cs @@ -1,7 +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; +using System; using Microsoft.Azure.Functions.Worker; using Microsoft.Azure.Functions.Worker.Extensions.Abstractions; using Microsoft.Azure.Functions.Worker.Extensions.SignalRService; @@ -18,7 +18,7 @@ public static class SignalRFunction [SignalRConnectionInfoInput(HubName = "chat")] MyConnectionInfo connectionInfo, FunctionContext context) { - var logger = context.Logger; + var logger = context.GetLogger("SignalRFunction"); logger.LogInformation(item); logger.LogInformation($"Connection URL = {connectionInfo.Url}"); diff --git a/samples/SampleApp/Table/TableFunction.cs b/samples/SampleApp/Table/TableFunction.cs index 762010aa1..8c95f540a 100644 --- a/samples/SampleApp/Table/TableFunction.cs +++ b/samples/SampleApp/Table/TableFunction.cs @@ -1,7 +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; +using System; using Microsoft.Azure.Functions.Worker; using Microsoft.Azure.Functions.Worker.Extensions.Abstractions; using Microsoft.Azure.Functions.Worker.Extensions.Storage; @@ -18,7 +18,7 @@ public static void Run([QueueTrigger("table-items")] string input, [TableInput("MyTable", "MyPartition", "{queueTrigger}")] JObject tableItem, FunctionContext context) { - var logger = context.Logger; + var logger = context.GetLogger("TableFunction"); logger.LogInformation(tableItem.ToString()); diff --git a/samples/SampleApp/Timer/TimerFunction.cs b/samples/SampleApp/Timer/TimerFunction.cs index 6ad96799b..57c99ab0c 100644 --- a/samples/SampleApp/Timer/TimerFunction.cs +++ b/samples/SampleApp/Timer/TimerFunction.cs @@ -15,7 +15,7 @@ public static class TimerFunction public static void Run([TimerTrigger("0 */5 * * * *")] MyInfo timerInfo, FunctionContext context) { - var logger = context.Logger; + var logger = context.GetLogger("TimerFunction"); logger.LogInformation($"Function Ran. Next timer schedule = {timerInfo.ScheduleStatus.Next}"); } } diff --git a/samples/SampleApp/Warmup/Warmup.cs b/samples/SampleApp/Warmup/Warmup.cs index ca319a3aa..5a4ce7079 100644 --- a/samples/SampleApp/Warmup/Warmup.cs +++ b/samples/SampleApp/Warmup/Warmup.cs @@ -13,7 +13,7 @@ public static class Warmup [FunctionName("Warmup")] public static void Run([WarmupTrigger] object _, FunctionContext context) { - var logger = context.Logger; + var logger = context.GetLogger("Warmup"); logger.LogInformation("Function App instance is now warm!"); } diff --git a/src/DotNetWorker/Broker/FunctionBroker.Log.cs b/src/DotNetWorker/Broker/FunctionBroker.Log.cs new file mode 100644 index 000000000..5e74062f2 --- /dev/null +++ b/src/DotNetWorker/Broker/FunctionBroker.Log.cs @@ -0,0 +1,23 @@ +// 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.Functions.Worker +{ + internal partial class FunctionBroker + { + private static class Log + { + private static readonly Action _functionDefinitionCreated = + WorkerMessage.Define(LogLevel.Trace, new EventId(1, nameof(FunctionDefinitionCreated)), + "Function definition for '{functionName}' created with id '{functionid}'."); + + public static void FunctionDefinitionCreated(ILogger logger, FunctionDefinition functionDefinition) + { + _functionDefinitionCreated(logger, functionDefinition.Metadata.Name, functionDefinition.Metadata.FunctionId, null); + } + } + } +} diff --git a/src/DotNetWorker/Broker/FunctionBroker.cs b/src/DotNetWorker/Broker/FunctionBroker.cs index 8d8d63e08..cbda202ba 100644 --- a/src/DotNetWorker/Broker/FunctionBroker.cs +++ b/src/DotNetWorker/Broker/FunctionBroker.cs @@ -5,35 +5,41 @@ using System.Collections.Concurrent; using System.Threading.Tasks; using Microsoft.Azure.Functions.Worker.Context; +using Microsoft.Azure.Functions.Worker.Diagnostics; using Microsoft.Azure.Functions.Worker.Pipeline; using Microsoft.Azure.WebJobs.Script.Grpc.Messages; +using Microsoft.Extensions.Logging; using Status = Microsoft.Azure.WebJobs.Script.Grpc.Messages.StatusResult.Types.Status; namespace Microsoft.Azure.Functions.Worker { - internal class FunctionBroker : IFunctionBroker + internal partial class FunctionBroker : IFunctionBroker { private readonly ConcurrentDictionary _functionMap = new ConcurrentDictionary(); private readonly FunctionExecutionDelegate _functionExecutionDelegate; private readonly IFunctionContextFactory _functionContextFactory; - private readonly IFunctionDefinitionFactory _functionDescriptorFactory; + private readonly IFunctionDefinitionFactory _functionDefinitionFactory; + private readonly ILogger _logger; - public FunctionBroker(FunctionExecutionDelegate functionExecutionDelegate, IFunctionContextFactory functionContextFactory, IFunctionDefinitionFactory functionDescriptorFactory) + public FunctionBroker(FunctionExecutionDelegate functionExecutionDelegate, IFunctionContextFactory functionContextFactory, + IFunctionDefinitionFactory functionDescriptorFactory, ILogger logger) { _functionExecutionDelegate = functionExecutionDelegate ?? throw new ArgumentNullException(nameof(functionExecutionDelegate)); _functionContextFactory = functionContextFactory ?? throw new ArgumentNullException(nameof(functionContextFactory)); - _functionDescriptorFactory = functionDescriptorFactory ?? throw new ArgumentNullException(nameof(functionDescriptorFactory)); + _functionDefinitionFactory = functionDescriptorFactory ?? throw new ArgumentNullException(nameof(functionDescriptorFactory)); + _logger = logger ?? throw new ArgumentNullException(nameof(logger)); } public void AddFunction(FunctionLoadRequest functionLoadRequest) { - FunctionDefinition functionDefinition = _functionDescriptorFactory.Create(functionLoadRequest); + FunctionDefinition functionDefinition = _functionDefinitionFactory.Create(functionLoadRequest); if (functionDefinition.Metadata.FunctionId is null) { throw new InvalidOperationException("The function ID for the current load request is invalid"); } + Log.FunctionDefinitionCreated(_logger, functionDefinition); _functionMap.TryAdd(functionDefinition.Metadata.FunctionId, functionDefinition); } @@ -47,54 +53,58 @@ public async Task InvokeAsync(FunctionInvocation invocation) }; FunctionContext? executionContext = null; + var functionDefinition = _functionMap[invocation.FunctionId]; - try + var scope = new FunctionInvocationScope(functionDefinition.Metadata.Name, invocation.InvocationId); + using (_logger.BeginScope(scope)) { - executionContext = _functionContextFactory.Create(invocation, _functionMap[invocation.FunctionId]); - - await _functionExecutionDelegate(executionContext); + try + { + executionContext = _functionContextFactory.Create(invocation, functionDefinition); - var parameterBindings = executionContext.OutputBindings; - var result = executionContext.InvocationResult; + await _functionExecutionDelegate(executionContext); - foreach (var paramBinding in parameterBindings) - { - // TODO: ParameterBinding shouldn't happen here + var parameterBindings = executionContext.OutputBindings; + var result = executionContext.InvocationResult; - foreach (var binding in executionContext.OutputBindings) + foreach (var paramBinding in parameterBindings) { - var parameterBinding = new ParameterBinding + // TODO: ParameterBinding shouldn't happen here + + foreach (var binding in executionContext.OutputBindings) { - Name = binding.Key, - Data = binding.Value.ToRpc() - }; - response.OutputData.Add(parameterBinding); + var parameterBinding = new ParameterBinding + { + Name = binding.Key, + Data = binding.Value.ToRpc() + }; + response.OutputData.Add(parameterBinding); + } } + if (result != null) + { + var returnVal = result.ToRpc(); + + response.ReturnValue = returnVal; + } + + response.Result = new StatusResult { Status = Status.Success }; } - if (result != null) + catch (Exception ex) { - var returnVal = result.ToRpc(); - - response.ReturnValue = returnVal; + response.Result = new StatusResult + { + Exception = ex.ToRpcException(), + Status = Status.Failure + }; } - - response.Result = new StatusResult { Status = Status.Success }; - } - catch (Exception ex) - { - response.Result = new StatusResult + finally { - Exception = ex.ToRpcException(), - Status = Status.Failure - }; - } - finally - { - (executionContext as IDisposable)?.Dispose(); + (executionContext as IDisposable)?.Dispose(); + } } return response; } } - } diff --git a/src/DotNetWorker/Configuration/ServiceCollectionExtensions.cs b/src/DotNetWorker/Configuration/ServiceCollectionExtensions.cs index 9f1ddc498..33713f377 100644 --- a/src/DotNetWorker/Configuration/ServiceCollectionExtensions.cs +++ b/src/DotNetWorker/Configuration/ServiceCollectionExtensions.cs @@ -8,12 +8,14 @@ using Microsoft.Azure.Functions.Worker; using Microsoft.Azure.Functions.Worker.Configuration; using Microsoft.Azure.Functions.Worker.Converters; +using Microsoft.Azure.Functions.Worker.Diagnostics; using Microsoft.Azure.Functions.Worker.Invocation; using Microsoft.Azure.Functions.Worker.Pipeline; using Microsoft.Azure.WebJobs.Script.Grpc.Messages; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; using static Microsoft.Azure.WebJobs.Script.Grpc.Messages.FunctionRpc; @@ -29,6 +31,12 @@ public static IFunctionsWorkerApplicationBuilder AddFunctionsWorker(this IServic // Channels services.RegisterOutputChannel(); + // Internal logging + services.AddLogging(logging => + { + logging.Services.AddSingleton(); + }); + // Request handling services.AddSingleton(); services.AddSingleton(); @@ -73,7 +81,8 @@ public static IFunctionsWorkerApplicationBuilder AddFunctionsWorker(this IServic internal static IServiceCollection RegisterDefaultConverters(this IServiceCollection services) { - return services.AddSingleton() + return services.AddSingleton() + .AddSingleton() .AddSingleton() .AddSingleton(); } diff --git a/src/DotNetWorker/Context/DefaultFunctionContext.cs b/src/DotNetWorker/Context/DefaultFunctionContext.cs index 7c08cba1a..ba2b3a387 100644 --- a/src/DotNetWorker/Context/DefaultFunctionContext.cs +++ b/src/DotNetWorker/Context/DefaultFunctionContext.cs @@ -4,7 +4,6 @@ using System; using System.Collections.Generic; using Microsoft.Azure.Functions.Worker.Context; -using Microsoft.Azure.Functions.Worker.Logging; using Microsoft.Azure.Functions.Worker.Pipeline; using Microsoft.Extensions.DependencyInjection; @@ -32,8 +31,6 @@ public DefaultFunctionContext(IServiceScopeFactory serviceScopeFactory, Function public override object? InvocationResult { get; set; } - public override InvocationLogger? Logger { get; set; } - public override IDictionary OutputBindings { get; } public override IDictionary Items { get; set; } = new Dictionary(); diff --git a/src/DotNetWorker/Context/FunctionContext.cs b/src/DotNetWorker/Context/FunctionContext.cs index 54e3fa0ed..54ed029f4 100644 --- a/src/DotNetWorker/Context/FunctionContext.cs +++ b/src/DotNetWorker/Context/FunctionContext.cs @@ -4,7 +4,6 @@ using System; using System.Collections.Generic; using Microsoft.Azure.Functions.Worker.Context; -using Microsoft.Azure.Functions.Worker.Logging; namespace Microsoft.Azure.Functions.Worker { @@ -33,11 +32,6 @@ public abstract class FunctionContext /// public abstract object? InvocationResult { get; set; } - /// - /// GEts or sets an scoped to the current invocation. - /// - public abstract InvocationLogger? Logger { get; set; } - // TODO: Double-check previous projects for layout of FunctionInvocation, Bindings, /// /// Gets or sets a key/value collection with results for defined output bindings. diff --git a/src/DotNetWorker/Context/FunctionExecutionContextExtensions.cs b/src/DotNetWorker/Context/FunctionExecutionContextExtensions.cs new file mode 100644 index 000000000..ae3ccb48f --- /dev/null +++ b/src/DotNetWorker/Context/FunctionExecutionContextExtensions.cs @@ -0,0 +1,23 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.Functions.Worker +{ + public static class FunctionExecutionContextExtensions + { + public static ILogger GetLogger(this FunctionContext context) + { + return context.InstanceServices.GetService>(); + } + + public static ILogger GetLogger(this FunctionContext context, string categoryName) + { + return context.InstanceServices + .GetService() + .CreateLogger(categoryName); + } + } +} diff --git a/src/DotNetWorker/Converters/ConverterMiddleware.cs b/src/DotNetWorker/Converters/ConverterMiddleware.cs index 2a647d28b..a98148167 100644 --- a/src/DotNetWorker/Converters/ConverterMiddleware.cs +++ b/src/DotNetWorker/Converters/ConverterMiddleware.cs @@ -1,9 +1,9 @@ -// Copyright (c) .NET Foundation. All rights reserved. +// 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.Tasks; -using Microsoft.Azure.Functions.Worker.Logging; using Microsoft.Azure.Functions.Worker.Pipeline; namespace Microsoft.Azure.Functions.Worker.Converters @@ -11,32 +11,22 @@ namespace Microsoft.Azure.Functions.Worker.Converters internal sealed class ConverterMiddleware { private readonly IEnumerable _converters; - private readonly FunctionsHostOutputChannel _channel; - public ConverterMiddleware(IEnumerable converters, FunctionsHostOutputChannel channel) + public ConverterMiddleware(IEnumerable converters) { - _converters = converters; - _channel = channel; + _converters = converters ?? throw new ArgumentNullException(nameof(converters)); } public Task Invoke(FunctionContext context, FunctionExecutionDelegate next) { foreach (var param in context.FunctionDefinition.Parameters) { - if (param.Type == typeof(FunctionContext)) + object? source = context.Invocation.ValueProvider.GetValue(param.Name); + var converterContext = new DefaultConverterContext(param, source, context); + if (TryConvert(converterContext, out object? target)) { - context.Logger = new InvocationLogger(context.Invocation.InvocationId, _channel.Channel.Writer); - param.Value = context; - } - else - { - object? source = context.Invocation.ValueProvider.GetValue(param.Name); - var converterContext = new DefaultConverterContext(param, source, context); - if (TryConvert(converterContext, out object? target)) - { - param.Value = target; - continue; - } + param.Value = target; + continue; } } @@ -49,10 +39,9 @@ internal bool TryConvert(ConverterContext context, out object? target) // The first converter to successfully convert wins. // For example, this allows a converter that parses JSON strings to return false if the - // string is not valid JSON. This manager will then continue with the next matching provider. + // string is not valid JSON. This manager will then continue with the next matching provider. foreach (var converter in _converters) { - if (converter.TryConvert(context, out object? targetObj)) { target = targetObj; diff --git a/src/DotNetWorker/Converters/FunctionContextConverter.cs b/src/DotNetWorker/Converters/FunctionContextConverter.cs new file mode 100644 index 000000000..a2826f619 --- /dev/null +++ b/src/DotNetWorker/Converters/FunctionContextConverter.cs @@ -0,0 +1,19 @@ +namespace Microsoft.Azure.Functions.Worker.Converters +{ + internal class FunctionContextConverter : IConverter + { + public bool TryConvert(ConverterContext context, out object? target) + { + target = null; + + // Special handling for the context. + if (context.Parameter.Type == typeof(FunctionContext)) + { + target = context.FunctionContext; + return true; + } + + return false; + } + } +} diff --git a/src/DotNetWorker/Diagnostics/FunctionInvocationScope.cs b/src/DotNetWorker/Diagnostics/FunctionInvocationScope.cs new file mode 100644 index 000000000..49e5d7e17 --- /dev/null +++ b/src/DotNetWorker/Diagnostics/FunctionInvocationScope.cs @@ -0,0 +1,61 @@ +// 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; + +namespace Microsoft.Azure.Functions.Worker.Diagnostics +{ + internal class FunctionInvocationScope : IReadOnlyList> + { + internal const string FunctionInvocationIdKey = "AzureFunctions_InvocationId"; + internal const string FunctionNameKey = "AzureFunctions_FunctionName"; + + private readonly string _invocationId; + private readonly string _functionName; + + private string? _cachedToString; + + public FunctionInvocationScope(string functionName, string invocationid) + { + _functionName = functionName; + _invocationId = invocationid; + } + + public KeyValuePair this[int index] + { + get + { + return index switch + { + 0 => new KeyValuePair(FunctionInvocationIdKey, _invocationId), + 1 => new KeyValuePair(FunctionNameKey, _functionName), + _ => throw new ArgumentOutOfRangeException(nameof(index)), + }; + } + } + + public int Count => 2; + + public IEnumerator> GetEnumerator() + { + for (var i = 0; i < Count; ++i) + { + yield return this[i]; + } + } + + IEnumerator IEnumerable.GetEnumerator() => GetEnumerator(); + + public override string ToString() + { + if (_cachedToString == null) + { + _cachedToString = FormattableString.Invariant($"{FunctionNameKey}:{_functionName} {FunctionInvocationIdKey}:{_invocationId}"); + } + + return _cachedToString; + } + } +} diff --git a/src/DotNetWorker/Diagnostics/WorkerMessage.cs b/src/DotNetWorker/Diagnostics/WorkerMessage.cs new file mode 100644 index 000000000..5ed907550 --- /dev/null +++ b/src/DotNetWorker/Diagnostics/WorkerMessage.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 System.Threading; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.Functions.Worker +{ + internal static class WorkerMessage + { + private static readonly AsyncLocal _isSystemLog = new AsyncLocal(); + + internal static bool IsSystemLog => _isSystemLog.Value; + + public static Action Define(LogLevel logLevel, EventId eventId, string formatString) + { + var log = LoggerMessage.Define(logLevel, eventId, formatString); + + return (logger, exception) => + { + try + { + _isSystemLog.Value = true; + log(logger, exception); + } + finally + { + _isSystemLog.Value = false; + } + }; + } + + public static Action Define(LogLevel logLevel, EventId eventId, string formatString) + { + var log = LoggerMessage.Define(logLevel, eventId, formatString); + + return (logger, arg1, exception) => + { + try + { + _isSystemLog.Value = true; + log(logger, arg1, exception); + } + finally + { + _isSystemLog.Value = false; + } + }; + } + + public static Action Define(LogLevel logLevel, EventId eventId, string formatString) + { + var log = LoggerMessage.Define(logLevel, eventId, formatString); + + return (logger, arg1, arg2, exception) => + { + try + { + _isSystemLog.Value = true; + log(logger, arg1, arg2, exception); + } + finally + { + _isSystemLog.Value = false; + } + }; + } + } +} diff --git a/src/DotNetWorker/Logging/InvocationLogger.cs b/src/DotNetWorker/Grpc/GrpcFunctionsHostLogger.cs similarity index 52% rename from src/DotNetWorker/Logging/InvocationLogger.cs rename to src/DotNetWorker/Grpc/GrpcFunctionsHostLogger.cs index 88b08efcd..b737c3b26 100644 --- a/src/DotNetWorker/Logging/InvocationLogger.cs +++ b/src/DotNetWorker/Grpc/GrpcFunctionsHostLogger.cs @@ -2,47 +2,75 @@ // Licensed under the MIT License. See License.txt in the project root for license information. using System; +using System.Collections.Generic; using System.Threading.Channels; +using Microsoft.Azure.Functions.Worker.Diagnostics; using Microsoft.Azure.WebJobs.Script.Grpc.Messages; using Microsoft.Extensions.Logging; using static Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types; namespace Microsoft.Azure.Functions.Worker.Logging { - public class InvocationLogger : ILogger + /// + /// A logger that sends logs back to the Functions host. + /// + internal class GrpcFunctionsHostLogger : ILogger { - private string _invocationId; - private ChannelWriter _channelWriter; + private readonly string _category; + private readonly ChannelWriter _channelWriter; + private IExternalScopeProvider _scopeProvider; - public InvocationLogger(string invocationId, ChannelWriter channelWriter) + public GrpcFunctionsHostLogger(string category, ChannelWriter channelWriter, IExternalScopeProvider scopeProvider) { - _invocationId = invocationId; - _channelWriter = channelWriter; + _category = category ?? throw new ArgumentNullException(nameof(category)); + _channelWriter = channelWriter ?? throw new ArgumentNullException(nameof(channelWriter)); + _scopeProvider = scopeProvider ?? throw new ArgumentNullException(nameof(scopeProvider)); } public IDisposable BeginScope(TState state) { - return EmptyDisposable.Instance; + // The built-in DI wire-up guarantees that scope provider will be set. + return _scopeProvider!.Push(state); } public bool IsEnabled(LogLevel logLevel) { - return true; + return logLevel != LogLevel.None; } public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { var response = new StreamingMessage(); string message = formatter(state, exception); - response.RpcLog = new RpcLog + var rpcLog = new RpcLog { EventId = eventId.ToString(), Exception = exception.ToRpcException(), - LogCategory = RpcLogCategory.User, + Category = _category, + LogCategory = WorkerMessage.IsSystemLog ? RpcLogCategory.System : RpcLogCategory.User, Level = ToRpcLogLevel(logLevel), - InvocationId = _invocationId, Message = message }; + + // Grab the invocation id from the current scope, if present. + _scopeProvider.ForEachScope((scope, log) => + { + if (scope is IEnumerable> properties) + { + foreach (KeyValuePair pair in properties) + { + if (pair.Key == FunctionInvocationScope.FunctionInvocationIdKey) + { + log.InvocationId = pair.Value?.ToString(); + break; + } + } + } + }, + rpcLog); + + response.RpcLog = rpcLog; + _channelWriter.TryWrite(response); } diff --git a/src/DotNetWorker/Grpc/GrpcFunctionsHostLoggerProvider.cs b/src/DotNetWorker/Grpc/GrpcFunctionsHostLoggerProvider.cs new file mode 100644 index 000000000..43bc716fe --- /dev/null +++ b/src/DotNetWorker/Grpc/GrpcFunctionsHostLoggerProvider.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. + +using System.Threading.Channels; +using Microsoft.Azure.Functions.Worker.Logging; +using Microsoft.Azure.WebJobs.Script.Grpc.Messages; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.Functions.Worker.Diagnostics +{ + internal class GrpcFunctionsHostLoggerProvider : ILoggerProvider, ISupportExternalScope + { + private readonly ChannelWriter _channelWriter; + private IExternalScopeProvider? _scopeProvider; + + public GrpcFunctionsHostLoggerProvider(FunctionsHostOutputChannel outputChannel) + { + _channelWriter = outputChannel.Channel.Writer; + } + + public ILogger CreateLogger(string categoryName) => new GrpcFunctionsHostLogger(categoryName, _channelWriter, _scopeProvider!); + + public void Dispose() + { + } + + public void SetScopeProvider(IExternalScopeProvider scopeProvider) + { + _scopeProvider = scopeProvider; + } + } +} diff --git a/src/DotNetWorker/Grpc/GrpcHttpRequestData.cs b/src/DotNetWorker/Grpc/GrpcHttpRequestData.cs index cd4db778e..94066924a 100644 --- a/src/DotNetWorker/Grpc/GrpcHttpRequestData.cs +++ b/src/DotNetWorker/Grpc/GrpcHttpRequestData.cs @@ -14,8 +14,8 @@ internal class GrpcHttpRequestData : HttpRequestData { private readonly RpcHttp _httpData; private Uri? _url; - private IEnumerable _identities; - private HttpHeadersCollection _headers; + private IEnumerable? _identities; + private HttpHeadersCollection? _headers; public GrpcHttpRequestData(RpcHttp httpData) { diff --git a/src/DotNetWorker/RpcExtensions.cs b/src/DotNetWorker/RpcExtensions.cs index b1b6174d3..bd7a23560 100644 --- a/src/DotNetWorker/RpcExtensions.cs +++ b/src/DotNetWorker/RpcExtensions.cs @@ -187,9 +187,9 @@ internal static TypedData ToRpcLongArray(this long[] arrLong) return new RpcException { - Message = exception.Message, - Source = exception.Source, - StackTrace = exception.StackTrace + Message = exception.ToString(), + Source = exception.Source ?? string.Empty, + StackTrace = exception.StackTrace ?? string.Empty }; } } diff --git a/test/DotNetWorkerTests/Diagnostics/GrpcHostLoggerTests.cs b/test/DotNetWorkerTests/Diagnostics/GrpcHostLoggerTests.cs new file mode 100644 index 000000000..2e6e719c9 --- /dev/null +++ b/test/DotNetWorkerTests/Diagnostics/GrpcHostLoggerTests.cs @@ -0,0 +1,104 @@ +using System; +using System.Collections.Generic; +using System.Threading.Channels; +using System.Threading.Tasks; +using Microsoft.Azure.Functions.Worker.Diagnostics; +using Microsoft.Azure.WebJobs.Script.Grpc.Messages; +using Microsoft.Extensions.Logging; +using Xunit; +using static Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types; + +namespace Microsoft.Azure.Functions.Worker.Tests.Diagnostics +{ + public class GrpcHostLoggerTests + { + private readonly GrpcFunctionsHostLoggerProvider _provider; + private readonly Channel _channel; + + public GrpcHostLoggerTests() + { + _channel = Channel.CreateUnbounded(); + var outputChannel = new FunctionsHostOutputChannel(_channel); + _provider = new GrpcFunctionsHostLoggerProvider(outputChannel); + _provider.SetScopeProvider(new LoggerExternalScopeProvider()); + } + + [Fact] + public async Task UserLog() + { + var logger = _provider.CreateLogger("TestLogger"); + + logger.LogInformation("user"); + + _channel.Writer.Complete(); + + int count = 0; + await foreach (var msg in _channel.Reader.ReadAllAsync()) + { + count++; + Assert.Equal("TestLogger", msg.RpcLog.Category); + Assert.Equal(RpcLog.Types.RpcLogCategory.User, msg.RpcLog.LogCategory); + Assert.Equal("user", msg.RpcLog.Message); + Assert.Equal("0", msg.RpcLog.EventId); + } + + Assert.Equal(1, count); + } + + [Fact] + public async Task SystemLog_WithException_AndScope() + { + var logger = _provider.CreateLogger("TestLogger"); + Exception thrownException = null; + + using (logger.BeginScope(new FunctionInvocationScope("MyFunction", "MyInvocationId"))) + { + try + { + throw new InvalidOperationException("boom"); + } + catch (Exception ex) + { + // The only way to log a system log. + var log = WorkerMessage.Define(LogLevel.Trace, new EventId(1, "One"), "system log with {param}"); + log(logger, "this", ex); + thrownException = ex; + } + + // make sure this is now user + logger.LogInformation("user"); + } + + _channel.Writer.Complete(); + + IList msgs = new List(); + + await foreach (var msg in _channel.Reader.ReadAllAsync()) + { + msgs.Add(msg); + } + + Assert.Collection(msgs, + p => + { + Assert.Equal("TestLogger", p.RpcLog.Category); + Assert.Equal(RpcLogCategory.System, p.RpcLog.LogCategory); + Assert.Equal("system log with this", p.RpcLog.Message); + Assert.Equal("One", p.RpcLog.EventId); + Assert.Equal("MyInvocationId", p.RpcLog.InvocationId); + Assert.Equal(thrownException.ToString(), p.RpcLog.Exception.Message); + Assert.Equal("Microsoft.Azure.Functions.Worker.Tests", p.RpcLog.Exception.Source); + Assert.Contains(nameof(SystemLog_WithException_AndScope), p.RpcLog.Exception.StackTrace); + }, + p => + { + Assert.Equal("TestLogger", p.RpcLog.Category); + Assert.Equal(RpcLogCategory.User, p.RpcLog.LogCategory); + Assert.Equal("user", p.RpcLog.Message); + Assert.Equal("0", p.RpcLog.EventId); + Assert.Equal("MyInvocationId", p.RpcLog.InvocationId); + Assert.Null(p.RpcLog.Exception); + }); + } + } +} diff --git a/test/DotNetWorkerTests/Diagnostics/WorkerLoggerTests.cs b/test/DotNetWorkerTests/Diagnostics/WorkerLoggerTests.cs new file mode 100644 index 000000000..69df4bc3c --- /dev/null +++ b/test/DotNetWorkerTests/Diagnostics/WorkerLoggerTests.cs @@ -0,0 +1,59 @@ +// 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.Linq; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace Microsoft.Azure.Functions.Worker.Tests.Diagnostics +{ + public class WorkerMessageTests + { + private readonly TestLoggerProvider _loggerProvider = new(); + + [Fact] + public void WorkerMessage1() + { + Action msg1 = WorkerMessage.Define(LogLevel.Information, new EventId(1, "One"), "No params"); + var logger = _loggerProvider.CreateLogger("1"); + + msg1(logger, null); + logger.LogInformation("info"); + + var logMsg1 = _loggerProvider.GetAllLogMessages().First(); + var logMsg2 = _loggerProvider.GetAllLogMessages().Last(); + + Assert.Equal("No params", logMsg1.FormattedMessage); + Assert.True(logMsg1.IsSystemLog); + Assert.Equal(LogLevel.Information, logMsg1.Level); + Assert.Equal(1, logMsg1.EventId.Id); + Assert.Equal("One", logMsg1.EventId.Name); + Assert.Collection(logMsg1.State, + p => Assert.True(p.Key == "{OriginalFormat}" && (string)p.Value == "No params")); + + Assert.False(logMsg2.IsSystemLog); + } + + [Fact] + public void WorkerMessage2() + { + Action msg2 = WorkerMessage.Define(LogLevel.Information, new EventId(2, "Two"), "One param: {p1}"); + var logger = _loggerProvider.CreateLogger("2"); + + msg2(logger, "a", null); + + var logMsg = _loggerProvider.GetAllLogMessages().Single(); + + Assert.Equal("One param: a", logMsg.FormattedMessage); + Assert.True(logMsg.IsSystemLog); + Assert.Equal(LogLevel.Information, logMsg.Level); + Assert.Equal(2, logMsg.EventId.Id); + Assert.Equal("Two", logMsg.EventId.Name); + Assert.Collection(logMsg.State, + p => Assert.True(p.Key == "p1" && (string)p.Value == "a"), + p => Assert.True(p.Key == "{OriginalFormat}" && (string)p.Value == "One param: {p1}")); + + } + } +} diff --git a/test/DotNetWorkerTests/FunctionBrokerTests.cs b/test/DotNetWorkerTests/FunctionBrokerTests.cs index 31e473236..de1eab811 100644 --- a/test/DotNetWorkerTests/FunctionBrokerTests.cs +++ b/test/DotNetWorkerTests/FunctionBrokerTests.cs @@ -5,6 +5,7 @@ using Microsoft.Azure.Functions.Worker.Context; using Microsoft.Azure.Functions.Worker.Pipeline; using Microsoft.Azure.WebJobs.Script.Grpc.Messages; +using Microsoft.Extensions.Logging.Abstractions; using Moq; using Xunit; @@ -19,7 +20,8 @@ public class FunctionBrokerTests public FunctionBrokerTests() { - _functionBroker = new FunctionBroker(_mockFunctionExecutionDelegate.Object, _mockFunctionContextFactory.Object, _mockFunctionDefinitionFactory.Object); + _functionBroker = new FunctionBroker(_mockFunctionExecutionDelegate.Object, _mockFunctionContextFactory.Object, + _mockFunctionDefinitionFactory.Object, NullLogger.Instance); } [Fact] diff --git a/test/DotNetWorkerTests/Helpers/LogMessage.cs b/test/DotNetWorkerTests/Helpers/LogMessage.cs new file mode 100644 index 000000000..2ed755d29 --- /dev/null +++ b/test/DotNetWorkerTests/Helpers/LogMessage.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; +using System.Collections.Generic; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.Functions.Worker.Tests +{ + public class LogMessage + { + public LogLevel Level { get; set; } + + public EventId EventId { get; set; } + + public IEnumerable> State { get; set; } + + public IDictionary Scope { get; set; } + + public bool IsSystemLog { get; set; } + + public Exception Exception { get; set; } + + public string FormattedMessage { get; set; } + + public string Category { get; set; } + + public DateTime Timestamp { get; set; } + + public override string ToString() + { + return $"[{Timestamp:HH:mm:ss.fff}] [{Category}] {FormattedMessage}"; + } + } + +} diff --git a/test/DotNetWorkerTests/Helpers/TestLogger.cs b/test/DotNetWorkerTests/Helpers/TestLogger.cs new file mode 100644 index 000000000..164222dbe --- /dev/null +++ b/test/DotNetWorkerTests/Helpers/TestLogger.cs @@ -0,0 +1,98 @@ +// 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.Diagnostics; +using System.Linq; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.Functions.Worker.Tests +{ + [DebuggerDisplay("{DebuggerDisplay,nq}")] + public class TestLogger : ILogger + { + private readonly object _syncLock = new object(); + private readonly IExternalScopeProvider _scopeProvider; + private IList _logMessages = new List(); + + public TestLogger(string category) + : this(category, new LoggerExternalScopeProvider()) + { + } + + public TestLogger(string category, IExternalScopeProvider scopeProvider) + { + Category = category; + _scopeProvider = scopeProvider; + } + + public string Category { get; private set; } + + private string DebuggerDisplay => $"Category: {Category}, Count: {_logMessages.Count}"; + + public IDisposable BeginScope(TState state) => _scopeProvider.Push(state); + + public bool IsEnabled(LogLevel logLevel) + { + return true; + } + + public IList GetLogMessages() + { + lock (_syncLock) + { + return _logMessages.ToList(); + } + } + + public void ClearLogMessages() + { + lock (_syncLock) + { + _logMessages.Clear(); + } + } + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + LogMessage logMessage = new LogMessage + { + Level = logLevel, + EventId = eventId, + State = state as IEnumerable>, + Scope = GetScopeDictionaryOrNull(_scopeProvider), + IsSystemLog = WorkerMessage.IsSystemLog, + Exception = exception, + FormattedMessage = formatter(state, exception), + Category = Category, + Timestamp = DateTime.UtcNow + }; + + lock (_syncLock) + { + _logMessages.Add(logMessage); + } + } + + private static IDictionary GetScopeDictionaryOrNull(IExternalScopeProvider scopeProvider) + { + IDictionary result = null; + + scopeProvider?.ForEachScope((scope, _) => + { + if (scope is IEnumerable> kvps) + { + result = result ?? new Dictionary(StringComparer.OrdinalIgnoreCase); + + foreach (var kvp in kvps) + { + result[kvp.Key] = kvp.Value; + } + } + }, (object)null); + + return result; + } + } +} diff --git a/test/DotNetWorkerTests/Helpers/TestLoggerProvider.cs b/test/DotNetWorkerTests/Helpers/TestLoggerProvider.cs new file mode 100644 index 000000000..fcb8ac64c --- /dev/null +++ b/test/DotNetWorkerTests/Helpers/TestLoggerProvider.cs @@ -0,0 +1,74 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Linq; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.Functions.Worker.Tests +{ + public class TestLoggerProvider : ILoggerProvider, ISupportExternalScope + { + private IExternalScopeProvider _scopeProvider; + private Lazy _lazyFactory; + + public TestLoggerProvider() + { + _lazyFactory = new Lazy(() => + { + return new ServiceCollection() + .AddLogging(b => + { + b.AddProvider(this); + }) + .BuildServiceProvider() + .GetService(); + }); + } + + private ConcurrentDictionary LoggerCache { get; } = new ConcurrentDictionary(); + + public ILoggerFactory Factory => _lazyFactory.Value; + + public IEnumerable CreatedLoggers => LoggerCache.Values; + + public ILogger CreateLogger(string categoryName) + { + return LoggerCache.GetOrAdd(categoryName, (key) => new TestLogger(key, _scopeProvider)); + } + + public IList GetAllLogMessages() + { + return CreatedLoggers.SelectMany(l => l.GetLogMessages()).OrderBy(p => p.Timestamp).ToList(); + } + + /// + /// Returns a single string that contains all log message strings on a separate line. + /// + /// The log message. + public string GetLog() + { + return string.Join(Environment.NewLine, GetAllLogMessages()); + } + + public void ClearAllLogMessages() + { + foreach (TestLogger logger in CreatedLoggers) + { + logger.ClearLogMessages(); + } + } + + public void SetScopeProvider(IExternalScopeProvider scopeProvider) + { + _scopeProvider = scopeProvider; + } + + public void Dispose() + { + } + } +} diff --git a/test/DotNetWorkerTests/TestFunctionContext.cs b/test/DotNetWorkerTests/TestFunctionContext.cs index 36a3f2005..60d5f6f69 100644 --- a/test/DotNetWorkerTests/TestFunctionContext.cs +++ b/test/DotNetWorkerTests/TestFunctionContext.cs @@ -4,7 +4,6 @@ using System; using System.Collections.Generic; using Microsoft.Azure.Functions.Worker.Context; -using Microsoft.Azure.Functions.Worker.Logging; using Microsoft.Azure.Functions.Worker.Pipeline; namespace Microsoft.Azure.Functions.Worker.Tests @@ -19,8 +18,6 @@ internal class TestFunctionContext : FunctionContext, IDisposable public override object InvocationResult { get; set; } - public override InvocationLogger Logger { get; set; } - public override IDictionary Items { get; set; } public override FunctionInvocation Invocation { get; set; } diff --git a/test/E2ETests/E2EApps/E2EApp/Cosmos/CosmosFunction.cs b/test/E2ETests/E2EApps/E2EApp/Cosmos/CosmosFunction.cs index ae3287949..0530c33ec 100644 --- a/test/E2ETests/E2EApps/E2EApp/Cosmos/CosmosFunction.cs +++ b/test/E2ETests/E2EApps/E2EApp/Cosmos/CosmosFunction.cs @@ -31,7 +31,7 @@ public static void Run([CosmosDBTrigger( { foreach (var doc in input) { - context.Logger.LogInformation($"id: {doc.Id}"); + context.GetLogger("Function.CosmosTrigger").LogInformation($"id: {doc.Id}"); } context.OutputBindings["output"] = input.Select(p => new { id = p.Id }); diff --git a/test/E2ETests/E2EApps/E2EApp/Cosmos/MyDocument.cs b/test/E2ETests/E2EApps/E2EApp/Cosmos/MyDocument.cs index c61a4c856..46a70759b 100644 --- a/test/E2ETests/E2EApps/E2EApp/Cosmos/MyDocument.cs +++ b/test/E2ETests/E2EApps/E2EApp/Cosmos/MyDocument.cs @@ -1,16 +1,22 @@ -// Copyright (c) .NET Foundation. All rights reserved. +// 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.Functions.Worker.E2EApp.Cosmos +using System.Text.Json.Serialization; + +namespace Microsoft.Azure.Functions.Worker.E2EApp.Cosmos { public class MyDocument { + [JsonPropertyName("id")] public string Id { get; set; } + [JsonPropertyName("text")] public string Text { get; set; } + [JsonPropertyName("number")] public int Number { get; set; } + [JsonPropertyName("boolean")] public bool Boolean { get; set; } } } diff --git a/test/E2ETests/E2EApps/E2EApp/Http/BasicHttpFunctions.cs b/test/E2ETests/E2EApps/E2EApp/Http/BasicHttpFunctions.cs index 5880a8e3c..268694cad 100644 --- a/test/E2ETests/E2EApps/E2EApp/Http/BasicHttpFunctions.cs +++ b/test/E2ETests/E2EApps/E2EApp/Http/BasicHttpFunctions.cs @@ -1,12 +1,9 @@ -using System; -using System.Collections.Generic; -using System.Net; +using System.Net; using System.Text; using System.Text.Json; using System.Web; using Microsoft.Azure.Functions.Worker.Extensions.Abstractions; using Microsoft.Azure.Functions.Worker.Extensions.Http; -using Microsoft.Azure.Functions.Worker.Pipeline; using Microsoft.Extensions.Logging; namespace Microsoft.Azure.Functions.Worker.E2EApp @@ -18,9 +15,10 @@ public static HttpResponseData HelloFromQuery( [HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequestData req, FunctionContext context) { - context.Logger.LogInformation(".NET Worker HTTP trigger function processed a request"); + var logger = context.GetLogger(nameof(HelloFromQuery)); + logger.LogInformation(".NET Worker HTTP trigger function processed a request"); var queryName = HttpUtility.ParseQueryString(req.Url.Query)["name"]; - + if (!string.IsNullOrEmpty(queryName)) { var response = new HttpResponseData(HttpStatusCode.OK); @@ -38,7 +36,8 @@ public static HttpResponseData HelloFromJsonBody( [HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequestData req, FunctionContext context) { - context.Logger.LogInformation(".NET Worker HTTP trigger function processed a request"); + var logger = context.GetLogger(nameof(HelloFromJsonBody)); + logger.LogInformation(".NET Worker HTTP trigger function processed a request"); var body = Encoding.UTF8.GetString(req.Body.Value.Span); if (!string.IsNullOrEmpty(body)) @@ -53,7 +52,7 @@ public static HttpResponseData HelloFromJsonBody( return new HttpResponseData(HttpStatusCode.BadRequest); } } - + public class CallerName { public string Name { get; set; } diff --git a/test/E2ETests/E2EApps/E2EApp/Http/FailingHttpFunctions.cs b/test/E2ETests/E2EApps/E2EApp/Http/FailingHttpFunctions.cs index 20e766a2b..ea310e1dd 100644 --- a/test/E2ETests/E2EApps/E2EApp/Http/FailingHttpFunctions.cs +++ b/test/E2ETests/E2EApps/E2EApp/Http/FailingHttpFunctions.cs @@ -1,7 +1,6 @@ using System; using Microsoft.Azure.Functions.Worker.Extensions.Abstractions; using Microsoft.Azure.Functions.Worker.Extensions.Http; -using Microsoft.Azure.Functions.Worker.Pipeline; using Microsoft.Extensions.Logging; namespace Microsoft.Azure.Functions.Worker.E2EApp @@ -13,7 +12,8 @@ public static HttpResponseData ExceptionFunction( [HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequestData req, FunctionContext context) { - context.Logger.LogInformation(".NET Worker HTTP trigger function processed a request"); + var logger = context.GetLogger(nameof(ExceptionFunction)); + logger.LogInformation(".NET Worker HTTP trigger function processed a request"); throw new Exception("This should never succeed!"); } } diff --git a/test/E2ETests/E2ETests/E2ETests.sln b/test/E2ETests/E2ETests/E2ETests.sln index 7da009ec4..1b799bd3c 100644 --- a/test/E2ETests/E2ETests/E2ETests.sln +++ b/test/E2ETests/E2ETests/E2ETests.sln @@ -13,6 +13,14 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "DotNetWorker", "..\..\..\sr EndProject Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "E2EApp", "..\E2EApps\E2EApp\E2EApp.csproj", "{D37818A3-3821-4F7F-B92B-41E4038C63CC}" EndProject +Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Worker.Extensions.Abstractions", "..\..\..\extensions\Worker.Extensions.Abstractions\Worker.Extensions.Abstractions.csproj", "{BD751B7E-148B-4E37-83F8-95F87B146147}" +EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "Extensions", "Extensions", "{ACDC4021-5308-4F63-AC93-C4B368FEF400}" +EndProject +Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Worker.Extensions.Http", "..\..\..\extensions\Worker.Extensions.Http\Worker.Extensions.Http.csproj", "{D9B395CB-70CE-49B0-8E49-20022A06059D}" +EndProject +Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Worker.Extensions.CosmosDB", "..\..\..\extensions\Worker.Extensions.CosmosDB\Worker.Extensions.CosmosDB.csproj", "{48D901E0-015C-4516-93A6-64A922ED78C8}" +EndProject Global GlobalSection(SolutionConfigurationPlatforms) = preSolution Debug|Any CPU = Debug|Any CPU @@ -35,12 +43,27 @@ Global {D37818A3-3821-4F7F-B92B-41E4038C63CC}.Debug|Any CPU.Build.0 = Debug|Any CPU {D37818A3-3821-4F7F-B92B-41E4038C63CC}.Release|Any CPU.ActiveCfg = Release|Any CPU {D37818A3-3821-4F7F-B92B-41E4038C63CC}.Release|Any CPU.Build.0 = Release|Any CPU + {BD751B7E-148B-4E37-83F8-95F87B146147}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {BD751B7E-148B-4E37-83F8-95F87B146147}.Debug|Any CPU.Build.0 = Debug|Any CPU + {BD751B7E-148B-4E37-83F8-95F87B146147}.Release|Any CPU.ActiveCfg = Release|Any CPU + {BD751B7E-148B-4E37-83F8-95F87B146147}.Release|Any CPU.Build.0 = Release|Any CPU + {D9B395CB-70CE-49B0-8E49-20022A06059D}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {D9B395CB-70CE-49B0-8E49-20022A06059D}.Debug|Any CPU.Build.0 = Debug|Any CPU + {D9B395CB-70CE-49B0-8E49-20022A06059D}.Release|Any CPU.ActiveCfg = Release|Any CPU + {D9B395CB-70CE-49B0-8E49-20022A06059D}.Release|Any CPU.Build.0 = Release|Any CPU + {48D901E0-015C-4516-93A6-64A922ED78C8}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {48D901E0-015C-4516-93A6-64A922ED78C8}.Debug|Any CPU.Build.0 = Debug|Any CPU + {48D901E0-015C-4516-93A6-64A922ED78C8}.Release|Any CPU.ActiveCfg = Release|Any CPU + {48D901E0-015C-4516-93A6-64A922ED78C8}.Release|Any CPU.Build.0 = Release|Any CPU EndGlobalSection GlobalSection(SolutionProperties) = preSolution HideSolutionNode = FALSE EndGlobalSection GlobalSection(NestedProjects) = preSolution {D37818A3-3821-4F7F-B92B-41E4038C63CC} = {A5270BA7-7A26-41E0-B48E-26EBEF1A6AF2} + {BD751B7E-148B-4E37-83F8-95F87B146147} = {ACDC4021-5308-4F63-AC93-C4B368FEF400} + {D9B395CB-70CE-49B0-8E49-20022A06059D} = {ACDC4021-5308-4F63-AC93-C4B368FEF400} + {48D901E0-015C-4516-93A6-64A922ED78C8} = {ACDC4021-5308-4F63-AC93-C4B368FEF400} EndGlobalSection GlobalSection(ExtensibilityGlobals) = postSolution SolutionGuid = {89DAAC07-473A-4DEC-957E-62A8D7F2494B} diff --git a/test/E2ETests/E2ETests/Helpers/CosmosDBHelpers.cs b/test/E2ETests/E2ETests/Helpers/CosmosDBHelpers.cs index 75c039ab0..bd58bd05d 100644 --- a/test/E2ETests/E2ETests/Helpers/CosmosDBHelpers.cs +++ b/test/E2ETests/E2ETests/Helpers/CosmosDBHelpers.cs @@ -10,15 +10,17 @@ namespace Microsoft.Azure.Functions.Tests.E2ETests { public static class CosmosDBHelpers { - private static DocumentClient _docDbClient; - private static Uri inputCollectionsUri = UriFactory.CreateDocumentCollectionUri(Constants.CosmosDB.DbName, Constants.CosmosDB.InputCollectionName); - private static Uri outputCollectionsUri = UriFactory.CreateDocumentCollectionUri(Constants.CosmosDB.DbName, Constants.CosmosDB.OutputCollectionName); - private static Uri leasesCollectionsUri = UriFactory.CreateDocumentCollectionUri(Constants.CosmosDB.DbName, Constants.CosmosDB.LeaseCollectionName); + private static readonly DocumentClient _docDbClient; + private static readonly Uri inputCollectionsUri = UriFactory.CreateDocumentCollectionUri(Constants.CosmosDB.DbName, Constants.CosmosDB.InputCollectionName); + private static readonly Uri outputCollectionsUri = UriFactory.CreateDocumentCollectionUri(Constants.CosmosDB.DbName, Constants.CosmosDB.OutputCollectionName); + private static readonly Uri leasesCollectionsUri = UriFactory.CreateDocumentCollectionUri(Constants.CosmosDB.DbName, Constants.CosmosDB.LeaseCollectionName); static CosmosDBHelpers() { - var builder = new System.Data.Common.DbConnectionStringBuilder(); - builder.ConnectionString = Constants.CosmosDB.CosmosDBConnectionStringSetting; + var builder = new System.Data.Common.DbConnectionStringBuilder + { + ConnectionString = Constants.CosmosDB.CosmosDBConnectionStringSetting + }; var serviceUri = new Uri(builder["AccountEndpoint"].ToString()); _docDbClient = new DocumentClient(serviceUri, builder["AccountKey"].ToString()); } diff --git a/test/TestUtility/TestUtility.csproj b/test/TestUtility/TestUtility.csproj index 72fd865b3..5fcc76226 100644 --- a/test/TestUtility/TestUtility.csproj +++ b/test/TestUtility/TestUtility.csproj @@ -1,4 +1,4 @@ - + netcoreapp3.1 @@ -11,6 +11,7 @@ +