search

martincostello / xunit-logging

Logging extensions for xunit
https://blog.martincostello.com/writing-logs-to-xunit-test-output/
Apache License 2.0
266 stars 11 forks source link

Does integration testing still work with this library? #553

Closed kakins closed 10 months ago

kakins commented 10 months ago

Describe the bug

I have tried implementing this at least 3 times in different projects and can never get it to work to log aspnet logs to the test output.

Steps To reproduce

I followed the code examples exactly in the repo. I'm using .NET 6.

Expected behaviour

I would expect the aspnet logs to be written to the test output in the runner window as well as the console.

Actual behaviour

No logs are written.

System information

Additional context

Here's a very simple repro:

    public class BusinessControllerTests
    {
        private readonly TestContextFixture _fixture;
        private readonly ITestOutputHelper _outputHelper;

        public BusinessControllerTests(ITestOutputHelper outputHelper)
        {
            _fixture = new TestContextFixture(outputHelper);
            _fixture.InitializeAsync().Wait();
            _outputHelper = outputHelper;
        }

        [Fact]
        public async Task Test1()
        {
            // Arrange
            //var client = _fixture.Factory.CreateClient();
            var factory = new RecipesPlusApiFactory();
            factory.OutputHelper = _outputHelper;
            var client = factory.CreateClient();

            // Act
            var result = await client.GetAsync("/api/mystuff");

            Assert.Equal(result.StatusCode, System.Net.HttpStatusCode.OK);
        }
    }
    public class RecipesPlusApiFactory : WebApplicationFactory<Program>, ITestOutputHelperAccessor
    {
        public ITestOutputHelper? OutputHelper { get; set; }

        protected override void ConfigureWebHost(IWebHostBuilder builder)
        {
            builder.ConfigureLogging((p) =>
            {
                p.ClearProviders();
                p.AddXUnit(this);
            });

            builder.ConfigureTestServices(services =>
            {
                services
                    .AddAuthentication(defaultScheme: "Basic")
                    .AddScheme<AuthenticationSchemeOptions, TestAuthHandler>("Basic", options => { });

                // It is important to add this again here, otherwise test authorization will not work
                services.AddAuthorization(options =>
                {
                       // other stuff here
                });
            });
        }
    }
martincostello commented 10 months ago

Does integration testing still work with this library?

So the short answer is...yes it does 😄

If I clone this repo, and run the tests, I can see the output in the places I'd expect to see it in Visual Studio:

image

Note that by default, the output to the console is intercepted by xunit itself and isn't shown unless the test fails. The verbosity has to turned up to see it all the time (which will in turn slow down your tests, which is why you don't see it by default on the console when you do dotnet test).

If I run the dotnet test in the root of this repo, I get this output:

❯ dotnet test
  Determining projects to restore...
  All projects are up-to-date for restore.
  TodoApp -> C:\Coding\martincostello\dotnet-minimal-api-integration-testing\src\TodoApp\bin\Debug\net8.0\TodoApp.dll
  TodoApp.Tests -> C:\Coding\martincostello\dotnet-minimal-api-integration-testing\tests\TodoApp.Tests\bin\Debug\net8.0
  \TodoApp.Tests.dll
Test run for C:\Coding\martincostello\dotnet-minimal-api-integration-testing\tests\TodoApp.Tests\bin\Debug\net8.0\TodoApp.Tests.dll (.NETCoreApp,Version=v8.0)
Microsoft (R) Test Execution Command Line Tool Version 17.8.0 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.

Passed!  - Failed:     0, Passed:     9, Skipped:     0, Total:     9, Duration: 18 s - TodoApp.Tests.dll (net8.0)

Calculating coverage result...
  Generating report 'C:\Coding\martincostello\dotnet-minimal-api-integration-testing\tests\TodoApp.Tests\coverage.cobertura.xml'
  Generating report 'C:\Coding\martincostello\dotnet-minimal-api-integration-testing\tests\TodoApp.Tests\coverage.json'

+---------+--------+--------+--------+
| Module  | Line   | Branch | Method |
+---------+--------+--------+--------+
| TodoApp | 91.88% | 79.72% | 92.59% |
+---------+--------+--------+--------+

+---------+--------+--------+--------+
|         | Line   | Branch | Method |
+---------+--------+--------+--------+
| Total   | 91.88% | 79.72% | 92.59% |
+---------+--------+--------+--------+
| Average | 91.88% | 79.72% | 92.59% |
+---------+--------+--------+--------+

If I run dotnet test --logger:"console;verbosity=detailed", then I get the below. Note that it is much more detailed.

❯ dotnet test --logger:"console;verbosity=detailed"
  Determining projects to restore...
  Restored C:\Coding\martincostello\xunit-logging\tests\SampleApp\SampleApp.csproj (in 267 ms).
  Restored C:\Coding\martincostello\xunit-logging\src\Logging.XUnit\MartinCostello.Logging.XUnit.csproj (in 267 ms).
  Restored C:\Coding\martincostello\xunit-logging\tests\Logging.XUnit.Tests\MartinCostello.Logging.XUnit.Tests.csproj (
  in 302 ms).
  MartinCostello.Logging.XUnit -> C:\Coding\martincostello\xunit-logging\artifacts\bin\MartinCostello.Logging.XUnit\deb
  ug_netstandard2.0\MartinCostello.Logging.XUnit.dll
  SampleApp -> C:\Coding\martincostello\xunit-logging\artifacts\bin\SampleApp\debug\SampleApp.dll
  MartinCostello.Logging.XUnit.Tests -> C:\Coding\martincostello\xunit-logging\artifacts\bin\MartinCostello.Logging.XUn
  it.Tests\debug_net8.0\MartinCostello.Logging.XUnit.Tests.dll
Test run for C:\Coding\martincostello\xunit-logging\artifacts\bin\MartinCostello.Logging.XUnit.Tests\debug_net8.0\MartinCostello.Logging.XUnit.Tests.dll (.NETCoreApp,Version=v8.0)
Microsoft (R) Test Execution Command Line Tool Version 17.8.0 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
C:\Coding\martincostello\xunit-logging\artifacts\bin\MartinCostello.Logging.XUnit.Tests\debug_net8.0\MartinCostello.Logging.XUnit.Tests.dll
[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.5.6+bf9b858c26 (64-bit .NET 8.0.1)
[xUnit.net 00:00:00.14]   Discovering: MartinCostello.Logging.XUnit.Tests (method display = Method, method display options = ReplaceUnderscoreWithSpace)
[xUnit.net 00:00:00.21]   Discovered:  MartinCostello.Logging.XUnit.Tests (found 70 test cases)
[xUnit.net 00:00:00.21]   Starting:    MartinCostello.Logging.XUnit.Tests (parallel test collections = on [16 threads], stop on fail = off)
[xUnit.net 00:00:00.27] MartinCostello.Logging.XUnit.Tests: [2024-01-22 20:17:27Z] info: MartinCostello.Logging.XUnit.Integration.DatabaseFixture[0]
      Initializing database
[xUnit.net 00:00:00.29] MartinCostello.Logging.XUnit.Tests: [2024-01-22 20:17:27Z] info: MartinCostello.Logging.XUnit.Integration.DatabaseFixture[0]
      Disposing database
  Passed Run Database Test [15 ms]
  Passed Calculator Sums Two Different Integers [42 ms]
  Standard Output Messages:
 [2024-01-22 20:17:27Z] info: MartinCostello.Logging.XUnit.Examples.Calculator[0]
       The sum of 1 and 2 is 3.

  Passed Calculator Sums Two Equal Integers [2 ms]
  Standard Output Messages:
 [2024-01-22 20:17:27Z] info: MartinCostello.Logging.XUnit.Examples.Calculator[0]
       The sum of 2 and 2 is 4.

  Passed AddXUnit IMessageSink With Options Works [94 ms]
  Passed XUnitLogger BeginScope Returns Value [98 ms]
  Passed AddXUnit ITestOutputHelperAccessor Registers Services [9 ms]
  Passed XUnitLogger BeginScope Throws If State Is Null [6 ms]
  Passed AddXUnit IMessageSink Registers Services [< 1 ms]
  Passed AddXUnit IMessageSink With Filter Works [< 1 ms]
  Passed AddXUnit TestOutputHelper For ILoggerFactory Validates Parameters [3 ms]
  Passed ToLoggerFactory Validates Parameters [< 1 ms]
  Passed AddXUnit IMessageSink With LogLevel Works [< 1 ms]
  Passed AddXUnit Registers Services [< 1 ms]
  Passed XUnitLogger Constructor Initializes Instance(constructor: IMessageSink) [10 ms]
  Passed XUnitLoggerProvider Creates Logger(constructor: ITestOutputHelper) [115 ms]
  Passed XUnitLogger Constructor Initializes Instance(constructor: ITestOutputHelper) [< 1 ms]
  Passed XUnitLoggerProvider Creates Logger(constructor: IMessageSink) [< 1 ms]
  Passed XUnitLoggerProvider TestOutputHelper Constructor Validates Parameters [1 ms]
  Passed AddXUnit MessageSink For ILoggerBuilder Validates Parameters [6 ms]
  Passed XUnitLoggerProvider MessageSink Constructor Validates Parameters [1 ms]
  Passed AddXUnit IMessageSinkAccessor Registers Services [< 1 ms]
  Passed AddXUnit ITestOutputHelper Registers Services [< 1 ms]
  Passed XUnitLogger Log Does Nothing If Not Enabled [5 ms]
  Passed Can Configure xunit For ILoggerBuilder [121 ms]
  Passed XUnitLogger Log Throws If LogLevel Is Invalid [10 ms]
  Passed AddXUnit TestOutputHelper For ILoggerBuilder Validates Parameters [11 ms]
  Passed Can Configure xunit For ILoggerBuilder TestOutputHelper [10 ms]
  Passed Can Configure xunit For ILoggerFactory With Configure Options [1 ms]
  Passed XUnitLogger Log Logs Message If Scopes Included And There Are Scopes Of KeyValuePairs [2 ms]
  Passed XUnitLogger Log Logs Message If Scopes Included And There Is Scope Of KeyValuePairs [< 1 ms]
  Passed Can Configure xunit For ILoggerBuilder TestOutputHelper With Configuration [1 ms]
  Passed AddXUnit MessageSink For ILoggerFactory Validates Parameters [3 ms]
  Passed Can Configure xunit For ILoggerFactory [< 1 ms]
  Passed XUnitLogger Log Logs Message If Scopes Included And There Are Scopes [< 1 ms]
  Passed XUnitLogger Log Logs Messages(logLevel: Critical, shortLevel: "crit") [< 1 ms]
  Passed XUnitLogger Log Logs Messages(logLevel: Trace, shortLevel: "trce") [< 1 ms]
  Passed XUnitLogger Log Logs Messages(logLevel: Warning, shortLevel: "warn") [< 1 ms]
  Passed XUnitLogger Log Logs Messages(logLevel: Error, shortLevel: "fail") [< 1 ms]
  Passed XUnitLogger Log Logs Messages(logLevel: Debug, shortLevel: "dbug") [< 1 ms]
  Passed Can Configure xunit For ILoggerFactory With Minimum Level [< 1 ms]
  Passed XUnitLogger Log Logs Messages(logLevel: Information, shortLevel: "info") [< 1 ms]
  Passed XUnitLogger Log Logs Message If Scopes Included And There Is Scope Of KeyValuePair [< 1 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: Trace, expected: False) [4 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: Debug, expected: False) [< 1 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: Warning, expected: True) [< 1 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: Error, expected: True) [< 1 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: Information, expected: False) [< 1 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: Critical, expected: True) [< 1 ms]
  Passed Can Configure xunit For ILoggerBuilderAccessor TestOutputHelper [6 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: None, expected: False) [< 1 ms]
  Passed XUnitLogger Log Throws If Formatter Is Null [< 1 ms]
  Passed XUnitLogger Log Logs Very Long Messages [< 1 ms]
  Passed XUnitLogger Log Does Nothing If No OutputHelper [< 1 ms]
  Passed Can Configure xunit For ILoggerFactory With Options Factory [2 ms]
  Passed XUnitLogger Validates Parameters [1 ms]
  Passed XUnitLogger Log Does Nothing If Null Message And No Exception [< 1 ms]
  Passed XUnitLogger Log Logs Message If Message And No Exception [< 1 ms]
  Passed Can Configure xunit For ILoggerFactory With Options [1 ms]
  Passed XUnitLogger Log Logs Message If Message And Exception [< 1 ms]
  Passed XUnitLogger Log Logs Message If Scopes Included But There Are No Scopes [< 1 ms]
  Passed XUnitLogger Log Logs Message If Only Exception [< 1 ms]
  Passed XUnitLogger Log Does Nothing If Empty Message And No Exception [< 1 ms]
  Passed Can Configure xunit For ILoggerFactory With Filter [1 ms]
  Passed XUnitLogger Log Logs Message If Scopes Included And There Is Scope Of IEnumerable [< 1 ms]
  Passed Can Configure xunit For ILoggerBuilder TestOutputHelperAccessor With Configuration [2 ms]
  Passed Http Get Single [450 ms]
  Standard Output Messages:
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
       Request starting HTTP/1.1 GET http://localhost/api/values/a - - -
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
       Executing endpoint 'HTTP: GET /api/values/{id}'
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
       Executed endpoint 'HTTP: GET /api/values/{id}'
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
       Request finished HTTP/1.1 GET http://localhost/api/values/a - 200 - text/plain;+charset=utf-8 51.1344ms

  Passed Http Post [25 ms]
  Standard Output Messages:
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
       Request starting HTTP/1.1 POST http://localhost/api/values - application/json;+charset=utf-8 2
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
       Executing endpoint 'HTTP: POST /api/values'
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Http.Result.NoContentResult[1]
       Setting HTTP status code 204.
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
       Executed endpoint 'HTTP: POST /api/values'
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
       Request finished HTTP/1.1 POST http://localhost/api/values - 204 - - 15.1705ms

  Passed Http Put [2 ms]
  Standard Output Messages:
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
       Request starting HTTP/1.1 PUT http://localhost/api/values/d - application/json;+charset=utf-8 3
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
       Executing endpoint 'HTTP: PUT /api/values/{id}'
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Http.Result.NoContentResult[1]
       Setting HTTP status code 204.
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
       Executed endpoint 'HTTP: PUT /api/values/{id}'
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
       Request finished HTTP/1.1 PUT http://localhost/api/values/d - 204 - - 0.6166ms

  Passed Http Delete [1 ms]
  Standard Output Messages:
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
       Request starting HTTP/1.1 DELETE http://localhost/api/values/d - - -
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
       Executing endpoint 'HTTP: DELETE /api/values/{id}'
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Http.Result.NoContentResult[1]
       Setting HTTP status code 204.
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
       Executed endpoint 'HTTP: DELETE /api/values/{id}'
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
       Request finished HTTP/1.1 DELETE http://localhost/api/values/d - 204 - - 0.3256ms

[xUnit.net 00:00:00.76]   Finished:    MartinCostello.Logging.XUnit.Tests
  Passed Http Get Many [4 ms]
  Standard Output Messages:
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
       Request starting HTTP/1.1 GET http://localhost/api/values - - -
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
       Executing endpoint 'HTTP: GET /api/values'
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Http.Result.JsonResult[3]
       Writing value of type 'String[]' as Json.
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
       Executed endpoint 'HTTP: GET /api/values'
 [2024-01-22 20:17:28Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
       Request finished HTTP/1.1 GET http://localhost/api/values - 200 - application/json;+charset=utf-8 3.1378ms

Test Run Successful.
Total tests: 70
     Passed: 70
 Total time: 1.5056 Seconds

Calculating coverage result...
  Generating report 'C:\Coding\martincostello\xunit-logging\artifacts\coverage\coverage.net8.0.cobertura.xml'
  Generating report 'C:\Coding\martincostello\xunit-logging\artifacts\coverage\coverage.net8.0.json'

+------------------------------+------+--------+--------+
| Module                       | Line | Branch | Method |
+------------------------------+------+--------+--------+
| MartinCostello.Logging.XUnit | 99%  | 98.55% | 100%   |
+------------------------------+------+--------+--------+

+---------+------+--------+--------+
|         | Line | Branch | Method |
+---------+------+--------+--------+
| Total   | 99%  | 98.55% | 100%   |
+---------+------+--------+--------+
| Average | 99%  | 98.55% | 100%   |
+---------+------+--------+--------+

I don't see anything obviously wrong with the code you included above, so if with the above explanation you still think there's a bug, I'd need a repro that I can fully compile and run to step through it to see what's wrong.

kakins commented 10 months ago

Ok... user error of course ;) Thanks for taking the time to respond.

I should have paid more attention to the comment on the main readme that mentions if you're using Serilog this may not work as expected. I guess I just assumed that if I used ConfigureTestServices in my integration test that it would override any Serilog specific configuration added during DI.

Looks like that's not the case. When I commented out this line, the Xunit logging started to work:

image

That led me to look at Serilog.Sinks.Xunit, which you referenced. A little hassle to get that working, but I got it. Thank you!