Error "Wait for message .... in logs for container" happens sometimes but not always #247
Description
I'm currently writing integration tests for my project. But what I'm running into is that these sometimes fail.
The error that pops up is that it can't find the configured log line in the containers messages.
My configuration:
_dockerContainerPosgres = new Builder()
.UseContainer()
.UseImage("postgres:14.2-alpine")
.ExposePort(0, 5432)
.WithEnvironment("POSTGRES_PASSWORD=password")
.WaitForPort("5432/tcp", TimeSpan.FromSeconds(30), "127.0.0.1")
.WaitForMessageInLog("database system is ready to accept connections", TimeSpan.FromSeconds(30))
.WaitForProcess("postgres")
.Build()
.Start();
I've been debugging this problem for the last few hours now and have basically copied the "WaitForMessageInLogs" method in my own source code so that I could debug what's going on.
The problem seems to be that this line seems to return an empty list of strings sometimes:
var logs = service.Logs().ReadToEnd((int)millisTimeout);
I added some additional logging information so that I could figure out what's going on: (Logging in Xunit is stupidly hard so I simply expanded the exception message):
var logs = service.Logs().ReadToEnd((int)millisTimeout);
var match = logs.FirstOrDefault(stringToCheck => stringToCheck.Contains(message));
if (match != null)
{
mre.Set();
}
if (stopwatch.ElapsedMilliseconds > millisTimeout)
{
var config = service.GetConfiguration(true);
var configData = $"{Environment.NewLine}Name:{config.Name}{Environment.NewLine}";
configData += $"State:{config.State.Status}{Environment.NewLine}";
configData += $"Restartcount:{config.RestartCount}{Environment.NewLine}";
var exceptionString = $"Wait for message '{message}' in logs for container {service.Id}{Environment.NewLine}{Environment.NewLine}Actual logs:{Environment.NewLine}{string.Join(Environment.NewLine, logs)}{Environment.NewLine}Config:{Environment.NewLine}{configData}";
Console.WriteLine(exceptionString);
Beepje();
Thread.Sleep(100000);
exception = new FluentDockerException(exceptionString);
mre.Set();
}
This showed the following output:
[xUnit.net 00:02:36.11] Api.Tests.ResourceActionEventsAggregation.ResourceActionAggregationUpsertTest.TestMultiThreadedUpsertPostgres [FAIL]
[xUnit.net 00:02:36.11] Ductus.FluentDocker.Common.FluentDockerException : Wait for message 'database system is ready to accept connections' in logs for container a205a48efea151bf616a5e39e3a9a73345e1ae73534639e4f7223158328faac4
[xUnit.net 00:02:36.11]
[xUnit.net 00:02:36.11] Actual logs:
[xUnit.net 00:02:36.11]
[xUnit.net 00:02:36.11] Config:
[xUnit.net 00:02:36.11]
[xUnit.net 00:02:36.11] Name:intelligent_shannon
[xUnit.net 00:02:36.11] State:running
[xUnit.net 00:02:36.11] Restartcount:0
[xUnit.net 00:02:36.11]
[xUnit.net 00:02:36.11] Stack Trace:
[xUnit.net 00:02:36.11] C:\api\src\Api.Tests\TestHelpers\PostgresDockerDbProvider.cs(142,0): at Api.Tests.TestHelpers.PostgresDockerDbProvider`1.WaitForMessageInLogsWithExtraLogging(IContainerService service, String message, Int64 millisTimeout)
As you can see the Actual logs field seems to be empty.
Again because I simply couldn't get Xunit to print Console messages I added the Beepje(); method to start beeping when the exception occurred (😄) so that I knew when something was going wrong.
After that I immediately did a docker log .... on all running containers and by some quick typing was able to grab the docker container logs before the container exited. Here's the logs:
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
3871fb77109c postgres:14.2-alpine "docker-entrypoint.s…" 48 seconds ago Up 25 seconds 0.0.0.0:49443->5432/tcp objective_davinci
a205a48efea1 postgres:14.2-alpine "docker-entrypoint.s…" 59 seconds ago Up 52 seconds 0.0.0.0:49442->5432/tcp intelligent_shannon
79f3138f6bf3 postgres:14.2-alpine "docker-entrypoint.s…" 59 seconds ago Up 53 seconds 0.0.0.0:49441->5432/tcp frosty_lehmann
a0e22f2050e2 postgres:14.2-alpine "docker-entrypoint.s…" About a minute ago Up 59 seconds 0.0.0.0:49438->5432/tcp charming_hermann
bdbc2b073439 rabbitmq:3-alpine "docker-entrypoint.s…" About a minute ago Up 59 seconds 4369/tcp, 5671/tcp, 15691-15692/tcp, 25672/tcp, 0.0.0.0:49439->5672/tcp adoring_mendeleev
PS C:\Users\*******> docker logs a205
The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.
The database cluster will be initialized with locale "en_US.utf8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".
Data page checksums are disabled.
fixing permissions on existing directory /var/lib/postgresql/data ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... UTC
creating configuration files ... ok
running bootstrap script ... ok
sh: locale: not found
2022-03-15 15:46:48.831 UTC [31] WARNING: no usable system locales were found
performing post-bootstrap initialization ... ok
initdb: warning: enabling "trust" authentication for local connections
You can change this by editing pg_hba.conf or using the option -A, or
--auth-local and --auth-host, the next time you run initdb.
syncing data to disk ... ok
Success. You can now start the database server using:
pg_ctl -D /var/lib/postgresql/data -l logfile start
waiting for server to start....2022-03-15 15:46:56.905 UTC [37] LOG: starting PostgreSQL 14.2 on x86_64-pc-linux-musl, compiled by gcc (Alpine 10.3.1_git20211027) 10.3.1 20211027, 64-bit
2022-03-15 15:46:56.921 UTC [37] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-03-15 15:46:57.004 UTC [38] LOG: database system was shut down at 2022-03-15 15:46:50 UTC
2022-03-15 15:46:57.038 UTC [37] LOG: database system is ready to accept connections
done
server started
/usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
waiting for server to shut down...2022-03-15 15:46:57.166 UTC [37] LOG: received fast shutdown request
.2022-03-15 15:46:57.199 UTC [37] LOG: aborting any active transactions
2022-03-15 15:46:57.202 UTC [37] LOG: background worker "logical replication launcher" (PID 44) exited with exit code 1
2022-03-15 15:46:57.206 UTC [39] LOG: shutting down
2022-03-15 15:46:57.492 UTC [37] LOG: database system is shut down
done
server stopped
PostgreSQL init process complete; ready for start up.
2022-03-15 15:46:57.760 UTC [1] LOG: starting PostgreSQL 14.2 on x86_64-pc-linux-musl, compiled by gcc (Alpine 10.3.1_git20211027) 10.3.1 20211027, 64-bit
2022-03-15 15:46:57.760 UTC [1] LOG: listening on IPv4 address "0.0.0.0", port 5432
2022-03-15 15:46:57.760 UTC [1] LOG: listening on IPv6 address "::", port 5432
2022-03-15 15:46:57.836 UTC [1] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-03-15 15:46:57.935 UTC [49] LOG: database system was shut down at 2022-03-15 15:46:57 UTC
2022-03-15 15:46:58.047 UTC [1] LOG: database system is ready to accept connections
As you can see we do in fact have logs including the message that the database system is ready to accept connections.
I don't understand why but it seems that sometimes the logs aren't being streamed correctly into FluentDocker. It could possibly have something to do with running multiple containers in parallel but I'm honestly lost.