Add test output logging to functional tests (#661)

Author: JamesNK

examples/README.md

@@ -117,7 +117,7 @@ dotnet run --EnableOpenTelemetry=true
 
 ## [Tester](./Tester)
 
-The tester shows how to test gRPC services. The unit tests create and test a gRPC service directly. The functional tests show how to use [Microsoft.AspNetCore.TestHost](https://www.nuget.org/packages/Microsoft.AspNetCore.TestHost/) to host a gRPC service with an in-memory test server and call it using a gRPC client.
+The tester shows how to test gRPC services. The unit tests create and test a gRPC service directly. The functional tests show how to use [Microsoft.AspNetCore.TestHost](https://www.nuget.org/packages/Microsoft.AspNetCore.TestHost/) to host a gRPC service with an in-memory test server and call it using a gRPC client. The functional tests write client and server logs to the test output.
 
 > **NOTE:** There is a known issue in ASP.NET Core 3.0 that prevents functional testing of bidirectional gRPC methods. Bidirectional gRPC methods can still be unit tested.
 

examples/Tester/Tests/FunctionalTests/FunctionalTestBase.cs

@@ -16,16 +16,19 @@
 
 #endregion
 
+using System;
 using Grpc.Net.Client;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Logging;
 using NUnit.Framework;
+using Tests.FunctionalTests.Helpers;
 
 namespace Tests.FunctionalTests
 {
     public class FunctionalTestBase
     {
         private GrpcChannel? _channel;
+        private IDisposable? _testContext;
 
         protected GrpcTestFixture<Server.Startup> Fixture { get; private set; } = default!;
 
@@ -57,5 +60,18 @@ public void OneTimeTearDown()
         {
             Fixture.Dispose();
         }
+
+        [SetUp]
+        public void SetUp()
+        {
+            _testContext = Fixture.GetTestContext();
+        }
+
+        [TearDown]
+        public void TearDown()
+        {
+            _testContext?.Dispose();
+            _channel = null;
+        }
     }
 }

examples/Tester/Tests/FunctionalTests/Helpers/ForwardingLoggerProvider.cs

@@ -0,0 +1,69 @@
+#region Copyright notice and license
+
+// Copyright 2019 The gRPC Authors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#endregion
+
+using System;
+using Microsoft.Extensions.Logging;
+
+namespace Tests.FunctionalTests.Helpers
+{
+    internal class ForwardingLoggerProvider : ILoggerProvider
+    {
+        private readonly LogMessage _logAction;
+
+        public ForwardingLoggerProvider(LogMessage logAction)
+        {
+            _logAction = logAction;
+        }
+
+        public ILogger CreateLogger(string categoryName)
+        {
+            return new ForwardingLogger(categoryName, _logAction);
+        }
+
+        public void Dispose()
+        {
+        }
+
+        internal class ForwardingLogger : ILogger
+        {
+            private readonly string _categoryName;
+            private readonly LogMessage _logAction;
+
+            public ForwardingLogger(string categoryName, LogMessage logAction)
+            {
+                _categoryName = categoryName;
+                _logAction = logAction;
+            }
+
+            public IDisposable? BeginScope<TState>(TState state)
+            {
+                return null;
+            }
+
+            public bool IsEnabled(LogLevel logLevel)
+            {
+                return true;
+            }
+
+            public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
+            {
+                _logAction(logLevel, _categoryName, eventId, formatter(state, exception), exception);
+            }
+        }
+    }
+}

examples/Tester/Tests/FunctionalTests/Helpers/GrpcTestContext.cs

@@ -0,0 +1,57 @@
+#region Copyright notice and license
+
+// Copyright 2019 The gRPC Authors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#endregion
+
+using System;
+using System.Diagnostics;
+using System.Threading;
+using Microsoft.Extensions.Logging;
+
+namespace Tests.FunctionalTests.Helpers
+{
+    internal class GrpcTestContext<TStartup> : IDisposable where TStartup : class
+    {
+        private readonly ExecutionContext _executionContext;
+        private readonly Stopwatch _stopwatch;
+        private readonly GrpcTestFixture<TStartup> _fixture;
+
+        public GrpcTestContext(GrpcTestFixture<TStartup> fixture)
+        {
+            _executionContext = ExecutionContext.Capture()!;
+            _stopwatch = Stopwatch.StartNew();
+            _fixture = fixture;
+            _fixture.LoggedMessage += WriteMessage;
+        }
+
+        private void WriteMessage(LogLevel logLevel, string category, EventId eventId, string message, Exception exception)
+        {
+            // Log using the passed in execution context.
+            // In the case of NUnit, console output is only captured by the test
+            // if it is written in the test's execution context.
+            ExecutionContext.Run(_executionContext, s =>
+            {
+                Console.WriteLine($"{_stopwatch.Elapsed.TotalSeconds:N3}s {category} - {logLevel}: {message}");
+            }, null);
+        }
+
+        public void Dispose()
+        {
+            _fixture.LoggedMessage -= WriteMessage;
+            _executionContext?.Dispose();
+        }
+    }
+}

examples/Tester/Tests/FunctionalTests/GrpcTestFixture.cs renamed to examples/Tester/Tests/FunctionalTests/Helpers/GrpcTestFixture.cs

@@ -23,28 +23,35 @@
 using Microsoft.AspNetCore.Hosting;
 using Microsoft.AspNetCore.TestHost;
 using Microsoft.Extensions.DependencyInjection;
-using Microsoft.Extensions.DependencyInjection.Extensions;
 using Microsoft.Extensions.Hosting;
 using Microsoft.Extensions.Logging;
 
-namespace Tests.FunctionalTests
+namespace Tests.FunctionalTests.Helpers
 {
+    public delegate void LogMessage(LogLevel logLevel, string categoryName, EventId eventId, string message, Exception exception);
+
     public class GrpcTestFixture<TStartup> : IDisposable where TStartup : class
     {
         private readonly TestServer _server;
         private readonly IHost _host;
 
+        public event LogMessage? LoggedMessage;
+
         public GrpcTestFixture() : this(null) { }
 
         public GrpcTestFixture(Action<IServiceCollection>? initialConfigureServices)
         {
             LoggerFactory = new LoggerFactory();
+            LoggerFactory.AddProvider(new ForwardingLoggerProvider((logLevel, category, eventId, message, exception) =>
+            {
+                LoggedMessage?.Invoke(logLevel, category, eventId, message, exception);
+            }));
 
             var builder = new HostBuilder()
                 .ConfigureServices(services =>
                 {
                     initialConfigureServices?.Invoke(services);
-                    services.TryAddSingleton<ILoggerFactory>(LoggerFactory);
+                    services.AddSingleton<ILoggerFactory>(LoggerFactory);
                 })
                 .ConfigureWebHostDefaults(webHost =>
                 {
@@ -87,5 +94,10 @@ protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage
                 return response;
             }
         }
+
+        public IDisposable GetTestContext()
+        {
+            return new GrpcTestContext<TStartup>(this);
+        }
     }
 }