[Enhancement]: ILogger should be injected into all AbstractBuilder subclasses

[0xced]

Problem

Shipping a default console logger that works with any .NET test framework has been dismissed as impossible to do by VSTest engineers in microsoft/vstest#4125. Yet we'd still want to collect logs in xUnit.net.

Solution

Injecting an ILogger into all AbstractBuilder subclasses would allow to pass a logger implementation that writes logs to xUnit's ITestOutputHelper. I have started prototyping this in my ILoggerInjection branch but it's far from complete.

I'm not familiar enough with other testing frameworks but I hope they have a similar solution to xUnit's ITestOutputHelper. I think that NUnit captures the console output so it might already work with the current ConsoleLogger implementation.

Benefit

The Testcontainers logs can be captured when running unit tests in xUnit.net.

Here's the output when running dotnet test --logger "console;verbosity=detailed" for Testcontainers.PostgreSql.Tests (still in my ILoggerInjection branch)

[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.4.5+1caef2f33e (64-bit .NET 6.0.21)
[xUnit.net 00:00:00.54]   Discovering: Testcontainers.PostgreSql.Tests
[xUnit.net 00:00:00.58]   Discovered:  Testcontainers.PostgreSql.Tests
[xUnit.net 00:00:00.58]   Starting:    Testcontainers.PostgreSql.Tests
  Passed Testcontainers.PostgreSql.PostgreSqlContainerTest.ConnectionStateReturnsOpen [278 ms]
  Standard Output Messages:
 [testcontainers.org 00:00:00.120] Connected to Docker:
   Host: npipe://./pipe/docker_engine
   Server Version: 24.0.5
   Kernel Version: 5.15.90.1-microsoft-standard-WSL2
   API Version: 1.43
   Operating System: Docker Desktop
   Total Memory: 5.79 GB
 [testcontainers.org 00:00:01.843] Docker container 4f8851616709 created
 [testcontainers.org 00:00:01.856] Start Docker container 4f8851616709
 [testcontainers.org 00:00:03.322] Wait for Docker container 4f8851616709 to complete readiness checks
 [testcontainers.org 00:00:04.356] Docker container 4f8851616709 ready
 [testcontainers.org 00:00:04.502] Delete Docker container 4f8851616709


[xUnit.net 00:00:07.53]   Finished:    Testcontainers.PostgreSql.Tests
  Passed Testcontainers.PostgreSql.PostgreSqlContainerTest.ExecScriptReturnsSuccessful [188 ms]
  Standard Output Messages:
 [testcontainers.org 00:00:00.057] Docker container 495bfd1b3892 created
 [testcontainers.org 00:00:00.065] Start Docker container 495bfd1b3892
 [testcontainers.org 00:00:01.451] Wait for Docker container 495bfd1b3892 to complete readiness checks
 [testcontainers.org 00:00:01.462] Docker container 495bfd1b3892 ready
 [testcontainers.org 00:00:01.478] Copy tar archive to "/" to Docker container 495bfd1b3892
 [testcontainers.org 00:00:01.491] Execute "psql --username postgres --dbname postgres --file /tmp/e91386fd-e7c4-44b2-b7d3-dcb8be088409/oso2tyro.p1a" at Docker container 495bfd1b3892
 [testcontainers.org 00:00:01.656] Delete Docker container 495bfd1b3892

Alternatives

No other alternatives were considered to solve this issue.

Would you like to help contributing this enhancement?

Yes

[HofmeisterAn]

I agree that the current logging approach is far from perfect, and I am not very happy with it either, especially given the situation with VSTest. I haven't had a chance to review your implementation yet; however, I will take a look at it in the next days. I just wanted to share my initial thoughts, as I hadn't digged into the details yet. I've been thinking of developing an xUnit.net module that integrates Testcontainers into the xUnit.net test framework upon assembly load or through a similar mechanism. A dedicated xUnit.net module could also be useful for incorporating additional features, such as leveraging Testcontainers with annotations, into tests.

[HofmeisterAn]

What about extending the abstract builder and adding a member for setting the ILogger implementation, like WithLogger(ILogger)? This way, we wouldn't need to make changes to the constructors. The only changes required would be in the Build() method, which creates the actual Docker resource instance.

So far, so good. However, I'm still uncertain about when we should log the information regarding the container runtime. Currently, my idea is to log it each time the logger changes (this would support xUnit.net's grouped output).

Unfortunately, this approach doesn't work seamlessly with xUnit.net's shared context, such as class fixtures, etc. These contexts do not have access to ITestOutputHelper, and developers need to enable the diagnostic output and utilize the IMessageSink interface.

I still think that a module that leverages the test framework API and integrates with its logging mechanism is something worth to dig into. Perhaps we come up with a solution that works right out of the box (without additional configuration).

[0xced]

What about extending the abstract builder and adding a member for setting the ILogger implementation, like WithLogger(ILogger)?

Just after filing this issue I realized that this may be a better approach. And indeed it is! My ILoggerBuilder branch looks better than the ILogger injection approach in my opinion. Note that I still had to touch all containers to remove the ILogger constructor parameter since it's now part of the resource configuration.

For the PostgreSQL container, this change looks like this:

diff --git a/src/Testcontainers.PostgreSql/PostgreSqlBuilder.cs b/src/Testcontainers.PostgreSql/PostgreSqlBuilder.cs
index fc7e5be..a3650de 100644
--- a/src/Testcontainers.PostgreSql/PostgreSqlBuilder.cs
+++ b/src/Testcontainers.PostgreSql/PostgreSqlBuilder.cs
@@ -73,7 +73,7 @@ public sealed class PostgreSqlBuilder : ContainerBuilder<PostgreSqlBuilder, Post
     public override PostgreSqlContainer Build()
     {
         Validate();
-        return new PostgreSqlContainer(DockerResourceConfiguration, TestcontainersSettings.Logger);
+        return new PostgreSqlContainer(DockerResourceConfiguration);
     }
 
     /// <inheritdoc />
diff --git a/src/Testcontainers.PostgreSql/PostgreSqlContainer.cs b/src/Testcontainers.PostgreSql/PostgreSqlContainer.cs
index 3ac4844..2535fba 100644
--- a/src/Testcontainers.PostgreSql/PostgreSqlContainer.cs
+++ b/src/Testcontainers.PostgreSql/PostgreSqlContainer.cs
@@ -10,9 +10,8 @@ public sealed class PostgreSqlContainer : DockerContainer
     /// Initializes a new instance of the <see cref="PostgreSqlContainer" /> class.
     /// </summary>
     /// <param name="configuration">The container configuration.</param>
-    /// <param name="logger">The logger.</param>
-    public PostgreSqlContainer(PostgreSqlConfiguration configuration, ILogger logger)
-        : base(configuration, logger)
+    public PostgreSqlContainer(PostgreSqlConfiguration configuration)
+        : base(configuration)
     {
         _configuration = configuration;
     }

So far, so good. However, I'm still uncertain about when we should log the information regarding the container runtime. Currently, my idea is to log it each time the logger changes (this would support xUnit.net's grouped output).

That was the hardest part. I tried several places and was not satisfied (or it just plain did not work). In the end I chose to log the runtime information at the very beginning of TestcontainersClient.RunAsync. Unlike previously, this will be logged each time a container is started. I'm open to put it in a more appropriate place we can identify one.

Unfortunately, this approach doesn't work seamlessly with xUnit.net's shared context, such as class fixtures, etc. These contexts do not have access to ITestOutputHelper, and developers need to enable the diagnostic output and utilize the IMessageSink interface.
I still think that a module that leverages the test framework API and integrates with its logging mechanism is something worth to dig into. Perhaps we come up with a solution that works right out of the box (without additional configuration).

I'm well aware of this but there's no other way around for xUnit. For this purpose I prototyped a new Testcontainers.Xunit project that provides a ContainerTest base class and a ContainerFixture that automatically start and stop containers. ILogger adapters for both ITestOutputHelper and IMessageSink are also provided. You can have a look at it in my Testcontainers.Xunit branch. I tried to use the DbContainerFixture in the MariaDB test (commit 87f9d8a) and the ContainerTest in the MongoDB test (commit a28599e). Of course this new package could also be distributed in NuGet and be useful for everyone. Happy to have your feedback about it too.

[HofmeisterAn]

If we cannot find a better solution, we can continue in this direction. However, it requires a more effective approach to log container runtime information. Generally, the current approach works well for all other testing frameworks; it's mostly xUnit.net that's causing issues. I also attempted using events like this:

ConsoleLogger.Instance.MessageLogged += (_, message) => testOutputHelper.WriteLine(message);

But that approach didn't work well either. In general, I've been considering using xUnit.net's XunitTestAssemblyRunner to set up the logger before the test cases are created. I just haven't had the time to explore this thoroughly yet.

I've noticed that xUnit 3 has introduced some significant changes. The TestContext looks promising. Perhaps we should get in touch with Brad and seek his guidance. He likely has more knowledge about it and can point us in the right direction. It's a bit of an unusual case because Testcontainer sits between the test framework and the test itself.

[0xced]

However, it requires a more effective approach to log container runtime information.

Do you mean that you don't like logging at the very beginning of TestcontainersClient.RunAsync because it could log the container runtime information multiple times? Or do you mean something else that I failed to grasp?

Generally, the current approach works well for all other testing frameworks; it's mostly xUnit.net that's causing issues.

I think I nailed the Testcontainers/xUnit integration in my Testcontainers.Xunit branch (which sits on top of my ILoggerBuilder branch).

Excerpt of the ContainerFixture and ContainerTest classes.

public class ContainerFixture<TBuilderEntity, TContainerEntity> : IAsyncLifetime
  where TBuilderEntity : IContainerBuilder<TBuilderEntity, TContainerEntity>, new()
  where TContainerEntity : IContainer
{
  private readonly TBuilderEntity _builder;

  public ContainerFixture(IMessageSink messageSink)
  {
    _builder = new TBuilderEntity().WithLogger(new MessageSinkLogger(messageSink));
  }
// ...
}

public abstract class ContainerTest<TBuilderEntity, TContainerEntity> : IAsyncLifetime
  where TBuilderEntity : IContainerBuilder<TBuilderEntity, TContainerEntity>, new()
  where TContainerEntity : IContainer
{
  protected ContainerTest(ITestOutputHelper testOutputHelper, Func<TBuilderEntity, TBuilderEntity> configure = null)
  {
    var builder = new TBuilderEntity().WithLogger(new TestOutputLogger(testOutputHelper));
    Container = configure == null ? builder.Build() : configure(builder).Build();
  }
// ...
}

By having the logger configurable through the new WithLogger method it becomes very easy to configure it for xUnit with either an IMessageSink or an ITestOutputHelper without any additional hassle.

Does that make sense?

[HofmeisterAn]

Do you mean that you don't like logging at the very beginning of TestcontainersClient.RunAsync because it could log the container runtime information multiple times? Or do you mean something else that I failed to grasp?

Yeah, kind of. That one is difficult... For the ITestOutputHelper, it would make sense somehow. Here, we can include the Docker host information in the unit test output. Just logging the information once feels wrong. Otherwise, developers need to figure out the first test that logged the Docker host information. For all the other cases, that is not what we want, I guess. As soon as we have a single (the same) log output target, we want to log the information just once at the very beginning.

We also need to keep the other builders and resources in mind. TestcontainersClient.RunAsync does not consider all resources and might already be too late. I think UnsafeCreateAsync(CancellationToken) might be more suitable. This has another advantage (also covered by your suggestion). We were able to log the Docker host information, even for configurations where the developer chooses to override the default Docker host (chosen by the auto-discovery mechanism). However, it is still unclear to me how exactly we find out the resources or cases in which we need to log the information. I am thinking about three cases:

1. Individual for each unit test (ITestOutputHelper).
2. Once at the very beginning.
3. Once for every individual Docker host at the very beginning.

I do not want to make it more complex (it is already complex enough). I just want to collect all valid cases to think about the best implementation and to evaluate pros and cons (or cases we do not support at all).

I think I nailed the Testcontainers/xUnit integration in my Testcontainers.Xunit branch (which sits on top of my ILoggerBuilder branch).

Thanks again for your efforts. Much appreciated. I will look at the changes and the proposal by the weekend at the latest.

Edit:

Sorry, I haven't had the time yet. I hope I'll be able to look at it by the end of this week. I haven't forgotten it.

[HofmeisterAn]

I was playing around with xUnit.net's diagnostic messages in another project and felt very unsatisfied. Getting the output properly in Rider requires even more individual configurations (BTW, I stumbled across your JB ticket too).

As mentioned earlier, I think it makes total sense to extend the builders and allow configuring the used logger instances through the builder. That is definitely something we should offer. I need to test a few different configurations, but as also mentioned, UnsafeCreateAsync(CancellationToken) is probably most suitable to log the information once per logger instance.

[HofmeisterAn]

I will add the ILogger to the abstract builder and configuration (private builder method) in the next few days. Once it is prepared, we just need to think about synchronizing and writing the container runtime information properly.

[0xced]

I just rebased my ILoggerBuilder branch on develop with all the builders and containers to not use TestcontainersSettings.Logger anymore.