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

dotnet test IntegrationTest\ -l "console;verbosity=detailed" won't log messages from endpoint #328

Closed msschl closed 2 years ago

msschl commented 2 years ago

When running the integration sample. The logs of the test server won't be logged. Let's say you'd have a ILogger on a razor page logging a message, this message is not displayed when running the test like dotnet test IntegrationTest\ -l "console;verbosity=detailed" this in a console.

martincostello commented 2 years ago

I cannot replicate what you describe with the sample application here.

If I change one of the endpoints in Program.cs to this:

app.MapGet("/api/values", () =>
{
    app.Logger.LogInformation("Hello");
    return Results.Json(new string[] { "a", "b", "c" });
});

Then I get the following output, where you can see the Hello log message amongst other messages logged by ASP.NET Core itself.

xunit-logging\tests\Logging.XUnit.Tests on  main [!] via .NET v6.0.301 🎯 net6.0
❯ dotnet test -l "console;verbosity=detailed"
  Determining projects to restore...
  The project C:\Coding\martincostello\xunit-logging\tests\SampleApp\SampleApp.csproj is using CentralPackageVersionManagemen
  t, a NuGet preview feature.
  The project C:\Coding\martincostello\xunit-logging\tests\Logging.XUnit.Tests\MartinCostello.Logging.XUnit.Tests.csproj is u
  sing CentralPackageVersionManagement, a NuGet preview feature.
  The project C:\Coding\martincostello\xunit-logging\src\Logging.XUnit\MartinCostello.Logging.XUnit.csproj is using CentralPa
  ckageVersionManagement, a NuGet preview feature.
  Restored C:\Coding\martincostello\xunit-logging\tests\SampleApp\SampleApp.csproj (in 190 ms).
  Restored C:\Coding\martincostello\xunit-logging\src\Logging.XUnit\MartinCostello.Logging.XUnit.csproj (in 190 ms).
  Restored C:\Coding\martincostello\xunit-logging\tests\Logging.XUnit.Tests\MartinCostello.Logging.XUnit.Tests.csproj (in 391
   ms).
  MartinCostello.Logging.XUnit -> C:\Coding\martincostello\xunit-logging\src\Logging.XUnit\bin\Debug\netstandard2.0\MartinCos
  tello.Logging.XUnit.dll
  SampleApp -> C:\Coding\martincostello\xunit-logging\tests\SampleApp\bin\Debug\net6.0\SampleApp.dll
  MartinCostello.Logging.XUnit.Tests -> C:\Coding\martincostello\xunit-logging\tests\Logging.XUnit.Tests\bin\Debug\net6.0\Mar
  tinCostello.Logging.XUnit.Tests.dll
Test run for C:\Coding\martincostello\xunit-logging\tests\Logging.XUnit.Tests\bin\Debug\net6.0\MartinCostello.Logging.XUnit.Tests.dll (.NETCoreApp,Version=v6.0)
Microsoft (R) Test Execution Command Line Tool Version 17.2.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\tests\Logging.XUnit.Tests\bin\Debug\net6.0\MartinCostello.Logging.XUnit.Tests.dll
[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.4.5+1caef2f33e (64-bit .NET 6.0.6)
[xUnit.net 00:00:00.69]   Discovering: MartinCostello.Logging.XUnit.Tests (method display = Method, method display options = ReplaceUnderscoreWithSpace)
[xUnit.net 00:00:00.73]   Discovered:  MartinCostello.Logging.XUnit.Tests (found 70 test cases)
[xUnit.net 00:00:00.74]   Starting:    MartinCostello.Logging.XUnit.Tests (parallel test collections = on, max threads = 16)
[xUnit.net 00:00:00.78] MartinCostello.Logging.XUnit.Tests: [2022-06-16 15:41:04Z] info: MartinCostello.Logging.XUnit.Integration.DatabaseFixture[0]
      Initializing database
[xUnit.net 00:00:00.80] MartinCostello.Logging.XUnit.Tests: [2022-06-16 15:41:04Z] info: MartinCostello.Logging.XUnit.Integration.DatabaseFixture[0]
      Disposing database
  Passed Run Database Test [2 ms]
  Passed Calculator Sums Two Different Integers [29 ms]
  Standard Output Messages:
 [2022-06-16 15:41:04Z] info: MartinCostello.Logging.XUnit.Examples.Calculator[0]
       The sum of 1 and 2 is 3.

  Passed Calculator Sums Two Equal Integers [1 ms]
  Standard Output Messages:
 [2022-06-16 15:41:04Z] info: MartinCostello.Logging.XUnit.Examples.Calculator[0]
       The sum of 2 and 2 is 4.

  Passed AddXUnit IMessageSink With Options Works [60 ms]
  Passed AddXUnit ITestOutputHelperAccessor Registers Services [2 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 XUnitLoggerProvider Creates Logger(constructor: ITestOutputHelper) [68 ms]
  Passed AddXUnit Registers Services [< 1 ms]
  Passed XUnitLoggerProvider Creates Logger(constructor: IMessageSink) [< 1 ms]
  Passed XUnitLoggerProvider TestOutputHelper Constructor Validates Parameters [< 1 ms]
  Passed XUnitLoggerProvider MessageSink Constructor Validates Parameters [2 ms]
  Passed AddXUnit MessageSink For ILoggerBuilder Validates Parameters [3 ms]
  Passed AddXUnit IMessageSinkAccessor Registers Services [< 1 ms]
  Passed AddXUnit ITestOutputHelper Registers Services [< 1 ms]
  Passed AddXUnit TestOutputHelper For ILoggerBuilder Validates Parameters [1 ms]
  Passed AddXUnit MessageSink For ILoggerFactory Validates Parameters [1 ms]
  Passed XUnitLogger Log Logs Messages(logLevel: Trace, shortLevel: "trce") [80 ms]
  Passed Can Configure xunit For ILoggerBuilder [80 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 ILoggerBuilder TestOutputHelper [< 1 ms]
  Passed XUnitLogger Log Logs Messages(logLevel: Warning, shortLevel: "warn") [< 1 ms]
  Passed XUnitLogger Log Logs Messages(logLevel: Information, shortLevel: "info") [< 1 ms]
  Passed Can Configure xunit For ILoggerFactory With Configure Options [1 ms]
  Passed XUnitLogger Log Logs Messages(logLevel: Critical, shortLevel: "crit") [< 1 ms]
  Passed Can Configure xunit For ILoggerBuilder TestOutputHelper With Configuration [1 ms]
  Passed XUnitLogger Constructor Initializes Instance(constructor: IMessageSink) [1 ms]
  Passed XUnitLogger Constructor Initializes Instance(constructor: ITestOutputHelper) [< 1 ms]
  Passed Can Configure xunit For ILoggerFactory [< 1 ms]
  Passed XUnitLogger BeginScope Returns Value [1 ms]
  Passed Can Configure xunit For ILoggerFactory With Minimum Level [< 1 ms]
  Passed XUnitLogger BeginScope Throws If State Is Null [< 1 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: Trace, expected: False) [4 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: None, expected: False) [< 1 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: Information, expected: False) [< 1 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: Warning, expected: True) [< 1 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: Critical, expected: True) [< 1 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: Error, expected: True) [< 1 ms]
  Passed XUnitLogger IsEnabled Returns Correct Result(logLevel: Debug, expected: False) [< 1 ms]
  Passed XUnitLogger Log Does Nothing If Not Enabled [1 ms]
  Passed XUnitLogger Log Throws If LogLevel Is Invalid [< 1 ms]
  Passed Can Configure xunit For ILoggerBuilderAccessor TestOutputHelper [7 ms]
  Passed Can Configure xunit For ILoggerFactory With Options Factory [< 1 ms]
  Passed Can Configure xunit For ILoggerFactory With Options [< 1 ms]
  Passed XUnitLogger Log Logs Message If Scopes Included And There Are Scopes Of KeyValuePairs [2 ms]
  Passed Can Configure xunit For ILoggerFactory With Filter [< 1 ms]
  Passed XUnitLogger Log Logs Message If Scopes Included And There Is Scope Of KeyValuePairs [< 1 ms]
  Passed Can Configure xunit For ILoggerBuilder TestOutputHelperAccessor With Configuration [< 1 ms]
  Passed XUnitLogger Log Logs Message If Scopes Included And There Are Scopes [1 ms]
  Passed XUnitLogger Log Logs Message If Scopes Included And There Is Scope Of KeyValuePair [7 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 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 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]
[xUnit.net 00:00:00.99]   Finished:    MartinCostello.Logging.XUnit.Tests
  Passed XUnitLogger Log Logs Message If Scopes Included And There Is Scope Of IEnumerable [< 1 ms]
  Passed Http Get Single [162 ms]
  Standard Output Messages:
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
       Request starting HTTP/1.1 GET http://localhost/api/values/a - -
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
       Executing endpoint 'HTTP: GET /api/values/{id}'
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
       Executed endpoint 'HTTP: GET /api/values/{id}'
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
       Request finished HTTP/1.1 GET http://localhost/api/values/a - - - 200 - text/plain;+charset=utf-8 32.1124ms

  Passed Http Post [13 ms]
  Standard Output Messages:
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
       Request starting HTTP/1.1 POST http://localhost/api/values application/json;+charset=utf-8 2
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
       Executing endpoint 'HTTP: POST /api/values'
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Http.Result.NoContentResult[1]
       Executing StatusCodeResult, setting HTTP status code 204.
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
       Executed endpoint 'HTTP: POST /api/values'
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
       Request finished HTTP/1.1 POST http://localhost/api/values application/json;+charset=utf-8 2 - 204 - - 6.7401ms

  Passed Http Put [1 ms]
  Standard Output Messages:
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
       Request starting HTTP/1.1 PUT http://localhost/api/values/d application/json;+charset=utf-8 3
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
       Executing endpoint 'HTTP: PUT /api/values/{id}'
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Http.Result.NoContentResult[1]
       Executing StatusCodeResult, setting HTTP status code 204.
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
       Executed endpoint 'HTTP: PUT /api/values/{id}'
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
       Request finished HTTP/1.1 PUT http://localhost/api/values/d application/json;+charset=utf-8 3 - 204 - - 0.2946ms

  Passed Http Delete [< 1 ms]
  Standard Output Messages:
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
       Request starting HTTP/1.1 DELETE http://localhost/api/values/d - -
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
       Executing endpoint 'HTTP: DELETE /api/values/{id}'
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Http.Result.NoContentResult[1]
       Executing StatusCodeResult, setting HTTP status code 204.
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
       Executed endpoint 'HTTP: DELETE /api/values/{id}'
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
       Request finished HTTP/1.1 DELETE http://localhost/api/values/d - - - 204 - - 0.1643ms

  Passed Http Get Many [5 ms]
  Standard Output Messages:
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
       Request starting HTTP/1.1 GET http://localhost/api/values - -
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
       Executing endpoint 'HTTP: GET /api/values'
 [2022-06-16 15:41:04Z] info: SampleApp[0]
       Hello
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Http.Result.JsonResult[1]
       Executing JsonResult, writing value of type 'System.String[]'.
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
       Executed endpoint 'HTTP: GET /api/values'
 [2022-06-16 15:41:04Z] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
       Request finished HTTP/1.1 GET http://localhost/api/values - - - 200 - application/json;+charset=utf-8 4.2101ms

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

Please provide a minimal reproduceable example showing your issue.

msschl commented 2 years ago

Here is a repository to reproduce the bug.

martincostello commented 2 years ago

This isn't a bug - you're using Serilog rather than Microsoft's built-in LoggerFactory implementation.

UseSerilog() overrides the ILoggerFactory, meaning that log messages never reach the logging implementation provided by this library (which plugs into the Microsoft implementation).

If I delete the Serilog code from your Program.cs then it works as expected:

❯ dotnet test IntegrationTest\ -l "console;verbosity=detailed"
  Determining projects to restore...
  All projects are up-to-date for restore.
C:\Program Files\dotnet\sdk\7.0.100-preview.5.22307.18\Sdks\Microsoft.NET.Sdk\targets\Microsoft.NET.RuntimeIdentifierInferenc
e.targets(219,5): message NETSDK1057: You are using a preview version of .NET. See: https://aka.ms/dotnet-support-policy [C:\
Coding\_temp\-xunit-logging-bug-repo\IntegrationTest\IntegrationTest.csproj]
  TestPages -> C:\Coding\_temp\-xunit-logging-bug-repo\TestPages\bin\Debug\net6.0\TestPages.dll
  IntegrationTest -> C:\Coding\_temp\-xunit-logging-bug-repo\IntegrationTest\bin\Debug\net6.0\IntegrationTest.dll
Test run for C:\Coding\_temp\-xunit-logging-bug-repo\IntegrationTest\bin\Debug\net6.0\IntegrationTest.dll (.NETCoreApp,Version=v6.0)
Microsoft (R) Test Execution Command Line Tool Version 17.3.0-preview-20220523-03 (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\_temp\-xunit-logging-bug-repo\IntegrationTest\bin\Debug\net6.0\IntegrationTest.dll
[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.4.5+1caef2f33e (64-bit .NET 6.0.6)
[xUnit.net 00:00:00.54]   Discovering: IntegrationTest
[xUnit.net 00:00:00.57]   Discovered:  IntegrationTest
[xUnit.net 00:00:00.57]   Starting:    IntegrationTest
[xUnit.net 00:00:00.88]   Finished:    IntegrationTest
  Passed IntegrationTest.Test.Get_EndpointsReturnSuccessAndCorrectContentType [248 ms]
  Standard Output Messages:
 [2022-06-17 08:22:19Z] warn: Microsoft.AspNetCore.HttpsPolicy.HttpsRedirectionMiddleware[3]
       Failed to determine the https port for redirect.
 [2022-06-17 08:22:19Z] info: TestPages.Pages.IndexModel[0]
       OnGet log

Test Run Successful.
Total tests: 1
     Passed: 1
 Total time: 1.3996 Seconds

If you're using Serilog, you should use the Serilog.Sinks.XUnit package from trbenning/serilog-sinks-xunit instead.

msschl commented 2 years ago

Thanks @martincostello

I didn't notice that 👍🏽

Tyrrrz commented 10 months ago

I got bitten by this too when adding logging to an existing testing solution. As an alternative, you can also pass writeToProviders: true to UseSerilog(...), that way other logging providers (such as the default logger) will get to handle log events.

https://github.com/serilog/serilog-extensions-hosting/blob/d50fa97ca1ea0e58461f28079c28d7d7257057fb/src/Serilog.Extensions.Hosting/SerilogHostBuilderExtensions.cs#L105