diff --git a/src/Worker/Grpc/GrpcDurableTaskWorker.Processor.cs b/src/Worker/Grpc/GrpcDurableTaskWorker.Processor.cs index 6d63f6af..c4cfedcf 100644 --- a/src/Worker/Grpc/GrpcDurableTaskWorker.Processor.cs +++ b/src/Worker/Grpc/GrpcDurableTaskWorker.Processor.cs @@ -894,11 +894,14 @@ await this.ExecuteWithRetryAsync( traceActivity?.Dispose(); } - this.Logger.SendingOrchestratorResponse( - name, - response.InstanceId, - response.Actions.Count, - GetActionsListForLogging(response.Actions)); + if (this.Logger.IsEnabled(LogLevel.Debug)) + { + this.Logger.SendingOrchestratorResponse( + name, + response.InstanceId, + response.Actions.Count, + GetActionsListForLogging(response.Actions)); + } await this.CompleteOrchestratorTaskWithChunkingAsync( response, @@ -911,9 +914,12 @@ async Task OnRunActivityAsync(P.ActivityRequest request, string completionToken, using Activity? traceActivity = TraceHelper.StartTraceActivityForTaskExecution(request); OrchestrationInstance instance = request.OrchestrationInstance.ToCore(); - string rawInput = request.Input; - int inputSize = rawInput != null ? Encoding.UTF8.GetByteCount(rawInput) : 0; - this.Logger.ReceivedActivityRequest(request.Name, request.TaskId, instance.InstanceId, inputSize); + if (this.Logger.IsEnabled(LogLevel.Debug)) + { + string rawInput = request.Input; + int inputSize = rawInput != null ? Encoding.UTF8.GetByteCount(rawInput) : 0; + this.Logger.ReceivedActivityRequest(request.Name, request.TaskId, instance.InstanceId, inputSize); + } P.TaskFailureDetails? failureDetails = null; TaskName name = new(request.Name); @@ -984,21 +990,31 @@ await this.ExecuteWithRetryAsync( return; } - int outputSizeInBytes = 0; if (failureDetails != null) { traceActivity?.SetStatus(ActivityStatusCode.Error, failureDetails.ErrorMessage); - - outputSizeInBytes = failureDetails.GetApproximateByteCount(); } - else if (output != null) + + if (this.Logger.IsEnabled(LogLevel.Debug)) { - outputSizeInBytes = Encoding.UTF8.GetByteCount(output); - } + int outputSizeInBytes; + if (failureDetails != null) + { + outputSizeInBytes = failureDetails.GetApproximateByteCount(); + } + else if (output != null) + { + outputSizeInBytes = Encoding.UTF8.GetByteCount(output); + } + else + { + outputSizeInBytes = 0; + } - string successOrFailure = failureDetails != null ? "failure" : "success"; - this.Logger.SendingActivityResponse( - successOrFailure, name, request.TaskId, instance.InstanceId, outputSizeInBytes); + string successOrFailure = failureDetails != null ? "failure" : "success"; + this.Logger.SendingActivityResponse( + successOrFailure, name, request.TaskId, instance.InstanceId, outputSizeInBytes); + } P.ActivityResponse response = new() { diff --git a/test/Worker/Grpc.Tests/GrpcDurableTaskWorkerDebugLoggingTests.cs b/test/Worker/Grpc.Tests/GrpcDurableTaskWorkerDebugLoggingTests.cs new file mode 100644 index 00000000..2aade729 --- /dev/null +++ b/test/Worker/Grpc.Tests/GrpcDurableTaskWorkerDebugLoggingTests.cs @@ -0,0 +1,368 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System.Reflection; +using System.Text; +using Google.Protobuf.WellKnownTypes; +using Grpc.Core; +using Microsoft.DurableTask.Tests.Logging; +using Microsoft.DurableTask.Worker; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using P = Microsoft.DurableTask.Protobuf; + +namespace Microsoft.DurableTask.Worker.Grpc.Tests; + +/// +/// Tests verifying that debug-only logging work in 's internal Processor +/// (action-list computation for orchestrator responses and UTF-8 byte counting for activity requests/responses) +/// is skipped when Debug logging is disabled, and produces the expected content when Debug logging is enabled. +/// +public class GrpcDurableTaskWorkerDebugLoggingTests +{ + const string Category = "Microsoft.DurableTask.Worker.Grpc"; + const int ReceivedActivityRequestEventId = 13; + const int SendingActivityResponseEventId = 14; + const int SendingOrchestratorResponseEventId = 11; + + static readonly MethodInfo DispatchWorkItemMethod = typeof(GrpcDurableTaskWorker) + .GetNestedType("Processor", BindingFlags.NonPublic)! + .GetMethod("DispatchWorkItem", BindingFlags.Instance | BindingFlags.NonPublic)!; + + [Fact] + public async Task DispatchWorkItem_ActivityRequest_DebugDisabled_DoesNotLogByteCounts() + { + // Arrange + TestLogProvider logProvider = new(new NullOutput()); + DurableTaskWorkerOptions workerOptions = new() { Logging = { UseLegacyCategories = false } }; + GrpcDurableTaskWorker worker = CreateWorker( + new GrpcDurableTaskWorkerOptions(), workerOptions, new MinLevelLoggerFactory(logProvider, LogLevel.Information)); + + P.WorkItem activityWorkItem = CreateActivityWorkItem(input: "42"); + + TaskCompletionSource completed = new(TaskCreationOptions.RunContinuationsAsynchronously); + Mock clientMock = CreateActivityClientMock(completed); + object processor = CreateProcessor(worker, clientMock.Object); + + // Act + InvokeDispatchWorkItem(processor, activityWorkItem, CancellationToken.None); + await completed.Task.WaitAsync(TimeSpan.FromSeconds(5)); + + // Assert - the debug-only byte-count logs must not be emitted when Debug logging is disabled. + logProvider.TryGetLogs(Category, out IReadOnlyCollection? logs); + (logs ?? Array.Empty()).Should().NotContain( + log => log.EventId.Id == ReceivedActivityRequestEventId || log.EventId.Id == SendingActivityResponseEventId); + } + + [Fact] + public async Task DispatchWorkItem_ActivityRequest_DebugEnabled_LogsExactByteCounts() + { + // Arrange + TestLogProvider logProvider = new(new NullOutput()); + DurableTaskWorkerOptions workerOptions = new() { Logging = { UseLegacyCategories = false } }; + GrpcDurableTaskWorker worker = CreateWorker( + new GrpcDurableTaskWorkerOptions(), workerOptions, new MinLevelLoggerFactory(logProvider, LogLevel.Debug)); + + const string input = "42"; + P.WorkItem activityWorkItem = CreateActivityWorkItem(input); + + TaskCompletionSource completed = new(TaskCreationOptions.RunContinuationsAsynchronously); + Mock clientMock = CreateActivityClientMock(completed); + object processor = CreateProcessor(worker, clientMock.Object); + + // Act + InvokeDispatchWorkItem(processor, activityWorkItem, CancellationToken.None); + P.ActivityResponse response = await completed.Task.WaitAsync(TimeSpan.FromSeconds(5)); + + // Assert - when Debug is enabled, the exact byte counts must still be logged. The expected output size is + // derived from the actual completed response so the test doesn't depend on data-converter internals. + int expectedInputSize = Encoding.UTF8.GetByteCount(input); + int expectedOutputSize = Encoding.UTF8.GetByteCount(response.Result ?? string.Empty); + + logProvider.TryGetLogs(Category, out IReadOnlyCollection? logs).Should().BeTrue(); + logs!.Should().Contain(log => + log.EventId.Id == ReceivedActivityRequestEventId && + log.Message.Contains($"with {expectedInputSize} bytes of input data")); + logs.Should().Contain(log => + log.EventId.Id == SendingActivityResponseEventId && + log.Message.Contains($"with {expectedOutputSize} bytes of output data")); + } + + [Fact] + public async Task DispatchWorkItem_OrchestratorRequest_DebugDisabled_DoesNotLogActionsList() + { + // Arrange + TestLogProvider logProvider = new(new NullOutput()); + DurableTaskWorkerOptions workerOptions = new() { Logging = { UseLegacyCategories = false } }; + GrpcDurableTaskWorker worker = CreateWorker( + new GrpcDurableTaskWorkerOptions(), workerOptions, new MinLevelLoggerFactory(logProvider, LogLevel.Information)); + + P.WorkItem orchestratorWorkItem = CreateOrchestratorNotFoundWorkItem(); + + TaskCompletionSource completed = new(TaskCreationOptions.RunContinuationsAsynchronously); + Mock clientMock = CreateOrchestratorClientMock(completed); + object processor = CreateProcessor(worker, clientMock.Object); + + // Act + InvokeDispatchWorkItem(processor, orchestratorWorkItem, CancellationToken.None); + await completed.Task.WaitAsync(TimeSpan.FromSeconds(5)); + + // Assert - the debug-only action-list log must not be emitted when Debug logging is disabled. + logProvider.TryGetLogs(Category, out IReadOnlyCollection? logs); + (logs ?? Array.Empty()).Should().NotContain(log => log.EventId.Id == SendingOrchestratorResponseEventId); + } + + [Fact] + public async Task DispatchWorkItem_OrchestratorRequest_DebugEnabled_LogsActionsList() + { + // Arrange + TestLogProvider logProvider = new(new NullOutput()); + DurableTaskWorkerOptions workerOptions = new() { Logging = { UseLegacyCategories = false } }; + GrpcDurableTaskWorker worker = CreateWorker( + new GrpcDurableTaskWorkerOptions(), workerOptions, new MinLevelLoggerFactory(logProvider, LogLevel.Debug)); + + P.WorkItem orchestratorWorkItem = CreateOrchestratorNotFoundWorkItem(); + + TaskCompletionSource completed = new(TaskCreationOptions.RunContinuationsAsynchronously); + Mock clientMock = CreateOrchestratorClientMock(completed); + object processor = CreateProcessor(worker, clientMock.Object); + + // Act + InvokeDispatchWorkItem(processor, orchestratorWorkItem, CancellationToken.None); + await completed.Task.WaitAsync(TimeSpan.FromSeconds(5)); + + // Assert - when Debug is enabled, the single CompleteOrchestration action must still be logged by name. + logProvider.TryGetLogs(Category, out IReadOnlyCollection? logs).Should().BeTrue(); + logs!.Should().Contain(log => + log.EventId.Id == SendingOrchestratorResponseEventId && + log.Message.Contains("Sending 1 action(s) [CompleteOrchestration]")); + } + + static P.WorkItem CreateActivityWorkItem(string input) + { + return new P.WorkItem + { + ActivityRequest = new P.ActivityRequest + { + Name = "MyActivity", + TaskId = 42, + Input = input, + OrchestrationInstance = new P.OrchestrationInstance + { + InstanceId = "instance1", + ExecutionId = "execution1", + }, + }, + CompletionToken = "completion1", + }; + } + + static P.WorkItem CreateOrchestratorNotFoundWorkItem() + { + P.HistoryEvent executionStarted = new() + { + EventId = -1, + Timestamp = Timestamp.FromDateTime(DateTime.UtcNow), + ExecutionStarted = new P.ExecutionStartedEvent + { + Name = "MissingOrchestrator", + OrchestrationInstance = new P.OrchestrationInstance + { + InstanceId = "instance1", + ExecutionId = "execution1", + }, + }, + }; + + P.OrchestratorRequest orchestratorRequest = new() + { + InstanceId = "instance1", + ExecutionId = "execution1", + NewEvents = { executionStarted }, + EntityParameters = new P.OrchestratorEntityParameters + { + EntityMessageReorderWindow = Duration.FromTimeSpan(TimeSpan.Zero), + }, + }; + + return new P.WorkItem + { + OrchestratorRequest = orchestratorRequest, + CompletionToken = "completion1", + }; + } + + static GrpcDurableTaskWorker CreateWorker( + GrpcDurableTaskWorkerOptions grpcOptions, + DurableTaskWorkerOptions workerOptions, + ILoggerFactory loggerFactory) + { + Mock factoryMock = new(MockBehavior.Strict); + factoryMock + .Setup(factory => factory.TryCreateActivity( + It.Is(name => name.Name == "MyActivity"), + It.IsAny(), + out It.Ref.IsAny)) + .Returns((TaskName name, IServiceProvider serviceProvider, out ITaskActivity? activity) => + { + activity = new TestActivity(); + return true; + }); + + factoryMock + .Setup(factory => factory.TryCreateOrchestrator( + It.IsAny(), + It.IsAny(), + out It.Ref.IsAny)) + .Returns(false); + + return new GrpcDurableTaskWorker( + name: "Test", + factory: factoryMock.Object, + grpcOptions: new OptionsMonitorStub(grpcOptions), + workerOptions: new OptionsMonitorStub(workerOptions), + services: new ServiceCollection().BuildServiceProvider(), + loggerFactory: loggerFactory, + orchestrationFilter: null, + exceptionPropertiesProvider: null, + workItemFiltersMonitor: null); + } + + static Mock CreateActivityClientMock(TaskCompletionSource completed) + { + Mock clientMock = new( + MockBehavior.Strict, new object[] { Mock.Of() }); + clientMock + .Setup(client => client.CompleteActivityTaskAsync( + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny())) + .Callback(() => completed.TrySetResult()) + .Returns(CreateUnaryCall(Task.FromResult(new P.CompleteTaskResponse()))); + return clientMock; + } + + static Mock CreateActivityClientMock( + TaskCompletionSource completed) + { + Mock clientMock = new( + MockBehavior.Strict, new object[] { Mock.Of() }); + clientMock + .Setup(client => client.CompleteActivityTaskAsync( + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny())) + .Callback( + (response, _, _, _) => completed.TrySetResult(response)) + .Returns(CreateUnaryCall(Task.FromResult(new P.CompleteTaskResponse()))); + return clientMock; + } + + static Mock CreateOrchestratorClientMock(TaskCompletionSource completed) + { + Mock clientMock = new( + MockBehavior.Strict, new object[] { Mock.Of() }); + clientMock + .Setup(client => client.CompleteOrchestratorTaskAsync( + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny())) + .Callback(() => completed.TrySetResult()) + .Returns(CreateUnaryCall(Task.FromResult(new P.CompleteTaskResponse()))); + return clientMock; + } + + static object CreateProcessor(GrpcDurableTaskWorker worker, P.TaskHubSidecarService.TaskHubSidecarServiceClient client) + { + System.Type processorType = typeof(GrpcDurableTaskWorker).GetNestedType("Processor", BindingFlags.NonPublic)!; + return Activator.CreateInstance( + processorType, + BindingFlags.Public | BindingFlags.Instance, + binder: null, + args: new object?[] { worker, client, null, null }, + culture: null)!; + } + + static void InvokeDispatchWorkItem(object processor, P.WorkItem workItem, CancellationToken cancellationToken) + { + DispatchWorkItemMethod.Invoke(processor, new object?[] { workItem, cancellationToken }); + } + + static AsyncUnaryCall CreateUnaryCall(Task responseTask) + { + return new AsyncUnaryCall( + responseTask, + Task.FromResult(new Metadata()), + () => new Status(StatusCode.OK, string.Empty), + () => new Metadata(), + () => { }); + } + + sealed class TestActivity : ITaskActivity + { + public System.Type InputType => typeof(object); + + public System.Type OutputType => typeof(object); + + public Task RunAsync(TaskActivityContext context, object? input) + { + return Task.FromResult(input); + } + } + + /// + /// A logger factory that wraps another and enforces a minimum log level, so tests + /// can simulate Debug logging being disabled (unlike 's logger, whose + /// IsEnabled always returns ). + /// + sealed class MinLevelLoggerFactory : ILoggerFactory + { + readonly ILoggerProvider provider; + readonly LogLevel minLevel; + + public MinLevelLoggerFactory(ILoggerProvider provider, LogLevel minLevel) + { + this.provider = provider; + this.minLevel = minLevel; + } + + public void AddProvider(ILoggerProvider loggerProvider) + { + // No-op; single provider. + } + + public ILogger CreateLogger(string categoryName) => new MinLevelLogger(this.provider.CreateLogger(categoryName), this.minLevel); + + public void Dispose() => this.provider.Dispose(); + + sealed class MinLevelLogger : ILogger + { + readonly ILogger inner; + readonly LogLevel minLevel; + + public MinLevelLogger(ILogger inner, LogLevel minLevel) + { + this.inner = inner; + this.minLevel = minLevel; + } + + public IDisposable? BeginScope(TState state) + where TState : notnull + => this.inner.BeginScope(state); + + public bool IsEnabled(LogLevel logLevel) => logLevel >= this.minLevel && this.inner.IsEnabled(logLevel); + + public void Log( + LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) + { + if (this.IsEnabled(logLevel)) + { + this.inner.Log(logLevel, eventId, state, exception, formatter); + } + } + } + } +}