Bugfix: Log consumers are now called with exactly one complete log line

[SgtSilvio]

Fixes #5843: log consumers are now called with exactly one complete log line

Motivation Docker logs provide a stream, the frames provided are not necessarily split by newline characters. So it might happen that a frame contains partial log lines.

Changes

• Line splitting, partial log buffering and line merging independently of the stream type (RAW, STDOUT, STDERR)
• OutputFrame does consistently not contain newline characters (independent of TTY)
• ToStringConsumer now adds newlines
• Slf4jLogConsumer does not need to remove any newlines

Also fixes #4110, #455

[SgtSilvio]

Can someone approve the missing workflows? The code should now be ready.

[SgtSilvio]

Sorry to ask again, but now no more checks/tests should fail (hopefully 😁).

[kiview]

Thanks for the PR @SgtSilvio, I think this is an important topic. We will look into it soon.

[SgtSilvio]

I am happy to explain in more detail and answer any questions to help move this forward. We are heavily affected by this bug because of failing/flaky tests.

[SgtSilvio]

I updated the branch on GitHub and now the workflows need approval again. I don't want to put pressure on you but it would be nice to get a rough estimate of when you plan to incorporate this fix, just that we know if we should add another workaround on our side.

[SgtSilvio]

Any updates?

[SgtSilvio]

If you have any questions or concerns I am happy to explain and discuss.

[eddumelendez]

@SgtSilvio thanks for your contribution! I will be taking a look at it next week. Sorry for the delay.

[perlun]

Ping @eddumelendez, just a friendly reminder that we are eagerly waiting on this fix. :slightly_smiling_face:

[SgtSilvio]

Can we help in any way to get this merged? I will also take care of updating the PR. I always thought you were too busy so I did not ping you unnecessarily, but other PRs like https://github.com/testcontainers/testcontainers-java/pull/6239 got merged so what can I do to move this PR forward? @kiview @eddumelendez

[kiview]

Hi @SgtSilvio, sorry for not yet reviewing and merging. #6239 was a trivial change with minimal effect radius, that's why this got easily merged, while PRs that touch the core of the library sometimes tend to take longer to get reviewed. From the change in CosmosDBEmulatorContainer we can assume this is possibly a breaking change for our users as well, so we will need a bit of time to look into it and prioritize it accordingly.

I will discuss with @eddumelendez when we will find the time to look into this, sorry again and thanks for your patience.

[SgtSilvio]

Thanks @kiview, it is perfectly valid feedback if you have any concerns that the changes might be too breaking. Although I rather see this as a broken behavior that was never reliable, and fixing a broken behavior is imho not a breaking change, I can understand if you see this differently. If you like, I could take another look to restore the old behavior as much as possible and introduce new APIs for the fix instead, for example a method getBytesWithoutNewLine.

My comment was not about putting any stress on you, just about getting any feedback from you how we can help you to get this done.

[SgtSilvio]

Any updates? Should I invest more time into it? Can you give me some feedback?

[eddumelendez]

Sorry for the delay on this one. We are doing our best working on new features, triaging new issues/PRs meanwhile taking a look at the backlog.

@SgtSilvio I just noticed there are some conflicts and if you can solve them, it would be appreciated. Also, regarding to We are heavily affected by this bug because of failing/flaky tests. can you tell us more about when are your having this issue? Just asking to get more context.

[alexandrklimov]

Hi all,

Is there any update on this issue?

Just I suspect it affects integration with Podman significantly. At least, LogMessageWaitStrategy seems isn't working correctly for PostgreSQLContainer on Podman - I've been forced override it to HostPortWaitStrategy as a workaround.

[SgtSilvio]

I just noticed there are some conflicts and if you can solve them, it would be appreciated.

Thanks for your update. I now rebased the branch.

[SgtSilvio]

Also, regarding to We are heavily affected by this bug because of failing/flaky tests. can you tell us more about when are your having this issue? Just asking to get more context.

I described our problems in the linked issue https://github.com/testcontainers/testcontainers-java/issues/5843:

The issue happens especially when using a WaitAllStrategy with more LogMessageWaitStrategy. The second log wait strategy only attaches to the log after the first finished, and then of course gets a lot more data at once, so that log frames may contain multiple and partial log lines.

[SgtSilvio]

If you like, I could take another look to restore the old behavior as much as possible and introduce new APIs for the fix instead, for example a method getBytesWithoutNewLine.

I now restored the old behavior of the methods OutputFrame.getBytes and OutputFrame.getUtf8String, and added a new method OutputFrame.getUtf8StringWithoutLineEnding. @kiview This should now resolve all your concerns about this being a breaking change.

From the change in CosmosDBEmulatorContainer we can assume this is possibly a breaking change for our users as well, so we will need a bit of time to look into it and prioritize it accordingly.

Even the change to CosmosDBEmulatorContainer is now reverted. Tests should pass (though I did not run them yet).

[SgtSilvio]

Now all tests should pass

[SgtSilvio]

Can someone approve the workflows?

[SgtSilvio]

Is anything else required from my side? For example, do you require more comments on the code? Or should I just wait for your review?

[alexandrklimov]

Hi team,

Are there any plans about release this fix?

[SgtSilvio]

Sorry to ping again, but when will this be reviewed?

[eddumelendez]

Thanks for your contribution, @SgtSilvio ! and sorry for the long wait on this one. This is finally merged in main branch and will be part of the next release.

[perlun]

@eddumelendez Thanks a lot for this, appreciated! :pray: Now, if we could just get #3018 merged into the next release as well, I would be completely happy... :joy: :wink:

[alexandrklimov]

@eddumelendez I'm sorry for disturbance but could you please provide some info. about the nearest release date? We are waiting this fix impatiently regarding of the Podman usage.

[perlun]

@alexandrklimov The fix is included in https://github.com/testcontainers/testcontainers-java/releases/tag/1.18.0, released last week. :tada:

However, what I don't understand is why we're now seeing \r\n (CR+LF) line endings when calling org.testcontainers.containers.ContainerState#getLogs() on a Tomcat-based container. :thinking: Both the container and the host are Linux-based in this case. String[] logLines = logsString.split( "\n" ), which is why only the \r is present in the strings in this array.

[SgtSilvio]

@perlun looked again at my changes, and this must be caused by something else (can't find a way how the code would add a \r).

[kiview]

@perlun Is this happening from within a Windows process (JVM running on Windows)?

[perlun]

Is this happening from within a Windows process (JVM running on Windows)?

@kiview Nope, interestingly not. Both the container and the host are Linux-based in this case.

I debugged this a bit and concluded that it comes out as CR+LF all the way here, in org.testcontainers.shaded.com.github.dockerjava.core.DefaultInvocationBuilder#executeAndStream:

And given the fact that HTTP uses CR+LF (not LF only), this is perhaps not so strange after all. :thinking: The data is just propagated from the DockerHttpClient.Response all the way, and this byte buffer contains CR+LF => log lines include CR+LF.

Here's what I think is an approximate description of the history re. this:

• The previous version we were using (1.15.1) used LF only here.
• I fixed a bug in https://github.com/testcontainers/testcontainers-java/pull/3752 (included in 1.15.2).
• 1.15.2 had another bug which prevented us from upgrading: https://github.com/testcontainers/testcontainers-java/issues/4110
• That bug was in turn fixed by @SgtSilvio (thanks!) in this PR (https://github.com/testcontainers/testcontainers-java/pull/5854).

In other words, this change is very likely not "intentional" but a side effect of how the handling of the log output has changed.

---

One (seemingly "nasty") way to deal with it would be to let this method silently discard all CR characters. It would probably be a quite easy and reasonable way to fix this, which would make the log lines be more natural for Linux users. (TODO: should we detect Windows and still return CR+LF log lines in that case? :thinking:)

https://github.com/testcontainers/testcontainers-java/blob/2525748a3aca939387040ae5f2cfedbc8469caee/core/src/main/java/org/testcontainers/containers/output/FrameConsumerResultCallback.java#L98-L126