Logs returned by ContainerState.getLogs are missing line separators if TTY is set to true

[slovdahl]

Problem

When using testcontainers 1.15.2, a call to ContainerState.getLogs() for a container with TTY set to true returns a string that has no line separators at all between log rows. Reverting to testcontainers 1.15.1 makes it work again.

$ docker -v
Docker version 20.10.6, build 370c289

Analysis

I'm not that familiar with testcontainer internals (yet) and not the Docker API at all (yet), so bear with me :grin: I have been debugging this for the past hours, and just need to start writing down my findings.

First of all, this change of behaviour seems to come from #3752 (which fixed #1763 and #1854). So the immediate cause of this change is quite clear. But I doubt that just reverting #3752 is the right path forward.

So, I have a custom Tomcat container. Stepping through a call to ContainerState.getLogs() on that container, I end up in org.testcontainers.shaded.com.github.dockerjava.core.FramedInputStreamConsumer with StreamType set to RAW (probably because it was started with TTY?).

This in turn means I end up in org.testcontainers.containers.output.FrameConsumerResultCallback.processRawFrame(OutputFrame outputFrame, Consumer<OutputFrame> consumer) and .normalizeLogLines(String utf8String, Consumer<OutputFrame> consumer). The normalizeLogLines method splits the frame on any newline separators, and passes it on to the Consumer<OuputFrame> WITHOUT any newline on the end of a line (even if the raw frame had one).

As long as ToStringConsumer made sure that newlines were added, this worked fine. However, it probably also meant that with testcontainer versions before 1.15.2 and non-TTY containers (with streams of type STDOUT or STDERR), log rows ended up with two \n between them.

Might be worth adding some context on why we're using TTY as well. We previously had some spurious test failures with the Tomcat container. We never really found a way of reliably reproducing it outside CI (maybe even not at all?), but we believe that it was caused by a WaitStrategy that looked for a certain row logged by Tomcat when it had successfully started, and that that log row was sometimes split up on two different lines in the log output. After adding..

withCreateContainerCmdModifier( cmd -> cmd.withTty( true ) );

..we have not seen a single failure of the same kind. On the face of it, it sounds a tiny little bit similar to #455.

Solution

As I said, I don't think reverting #3752 is necessarily the right thing to do, because it solved a real issue. Should FrameConsumerResultCallback.normalizeLogLines be fixed to retain newlines? OTOH, Slf4jLogConsumer already seems to take care of any trailing newlines internally, which may be a hint that the fix in ToStringConsumer should instead have been to check if a trailing newline exists, and just add one if not. Or something completely different?

[slovdahl]

A simple reproducer: https://github.com/slovdahl/testcontainers-issue-4110-reproducer

[SgtSilvio]

but we believe that it was caused by a WaitStrategy that looked for a certain row logged by Tomcat when it had successfully started, and that that log row was sometimes split up on two different lines in the log output

This problem is very likely caused by #5843

[SgtSilvio]

Imho the FrameConsumerResultCallback should guarantee that it passes a single and complete line to the consumer in all cases independent of stream type and fragmentation. Then, there is no need for the lines to contain any newline characters, and every consumer can add them if required.

[aidando73]

I've been able to reproduce this issue. If you set PostgreSQLContainer TTY to true, then it fails to start as it relies on logs for it's startup strategy:

Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
	at app//org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:543)
	at app//org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:345)
	at app//org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
	... 72 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*database system is ready to accept connections.*\s'
	at app//org.testcontainers.containers.wait.strategy.LogMessageWaitStrategy.waitUntilReady(LogMessageWaitStrategy.java:47)
	at app//org.testcontainers.containers.wait.strategy.AbstractWaitStrategy.waitUntilReady(AbstractWaitStrategy.java:52)
	at app//org.testcontainers.containers.PostgreSQLContainer.waitUntilContainerStarted(PostgreSQLContainer.java:139)
	at app//org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:486)
	... 74 more

Though, idk much about TTYs. What's the usecase for them?