container.getLogs() returns double line endings for each newline

[perlun]

Hi,

Using testcontainers 1.11.3, I am seeing a weird behavior when getting the logs from a container. For whatever reason, newlines are duplicated (i.e. \n\n instead of \n) for each new line, making the logs a bit more awkward to work with.

Here is a simple test case that illustrates the problem:

import static org.testng.Assert.assertFalse;

import java.util.concurrent.Future;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.TimeoutException;

import org.testcontainers.containers.GenericContainer;
import org.testcontainers.containers.output.WaitingConsumer;
import org.testcontainers.images.builder.ImageFromDockerfile;
import org.testng.annotations.Test;

public class MinimalTest {

    @Test
    void test_getLogs_duplicates_line_endings() throws TimeoutException {
        TomcatContainer container = startContainer();

        String logs = container.getLogs();

        // logs will contain \n\n-delimited output at this stage
        assertFalse( logs.contains( "\n\n" ) );
    }

    private TomcatContainer startContainer() throws TimeoutException {
        TomcatContainer container = new TomcatContainer(
                new ImageFromDockerfile()
                        .withDockerfileFromBuilder( builder -> builder
                                .from( TomcatContainer.IMAGE_NAME )
                        )
        );

        container.start();

        WaitingConsumer consumer = new WaitingConsumer();

        container.followOutput( consumer );

        consumer.waitUntil( frame ->
                frame.getUtf8String().contains( "org.apache.catalina.startup.Catalina.start Server startup in" ), 10, TimeUnit.SECONDS );

        return container;
    }

    private static class TomcatContainer extends GenericContainer<TomcatContainer> {
        static final String IMAGE_NAME = "tomcat:9";

        TomcatContainer( Future<String> image ) {
            super( image );
        }
    }
}

Running the same container on the command line works fine:

$ docker run tomcat:9
NOTE: Picked up JDK_JAVA_OPTIONS:  --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
21-Aug-2019 06:17:22.103 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name:   Apache Tomcat/9.0.24
21-Aug-2019 06:17:22.106 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Aug 14 2019 21:16:42 UTC
21-Aug-2019 06:17:22.106 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 9.0.24.0
21-Aug-2019 06:17:22.106 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
21-Aug-2019 06:17:22.106 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            4.19.0-5-amd64
21-Aug-2019 06:17:22.107 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
21-Aug-2019 06:17:22.107 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/local/openjdk-11
21-Aug-2019 06:17:22.107 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           11.0.4+11
21-Aug-2019 06:17:22.107 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
21-Aug-2019 06:17:22.107 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /usr/local/tomcat
21-Aug-2019 06:17:22.107 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /usr/local/tomcat
21-Aug-2019 06:17:22.116 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
21-Aug-2019 06:17:22.117 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
21-Aug-2019 06:17:22.117 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
21-Aug-2019 06:17:22.117 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties
21-Aug-2019 06:17:22.117 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
21-Aug-2019 06:17:22.117 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
21-Aug-2019 06:17:22.117 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
21-Aug-2019 06:17:22.117 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
21-Aug-2019 06:17:22.117 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
21-Aug-2019 06:17:22.118 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/usr/local/tomcat
21-Aug-2019 06:17:22.118 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/local/tomcat
21-Aug-2019 06:17:22.118 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/usr/local/tomcat/temp
21-Aug-2019 06:17:22.118 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded APR based Apache Tomcat Native library [1.2.23] using APR version [1.5.2].
21-Aug-2019 06:17:22.118 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
21-Aug-2019 06:17:22.118 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true]
21-Aug-2019 06:17:22.121 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized [OpenSSL 1.1.0k  28 May 2019]
21-Aug-2019 06:17:22.333 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
21-Aug-2019 06:17:22.354 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-nio-8009"]
21-Aug-2019 06:17:22.356 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [421] milliseconds
21-Aug-2019 06:17:22.401 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
21-Aug-2019 06:17:22.401 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.24]
21-Aug-2019 06:17:22.409 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/ROOT]
21-Aug-2019 06:17:22.587 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/ROOT] has finished in [178] ms
21-Aug-2019 06:17:22.587 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/host-manager]
21-Aug-2019 06:17:22.626 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/host-manager] has finished in [39] ms
21-Aug-2019 06:17:22.627 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/docs]
21-Aug-2019 06:17:22.643 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/docs] has finished in [16] ms
21-Aug-2019 06:17:22.643 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/examples]
21-Aug-2019 06:17:22.826 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/examples] has finished in [183] ms
21-Aug-2019 06:17:22.826 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/manager]
21-Aug-2019 06:17:22.842 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/manager] has finished in [16] ms
21-Aug-2019 06:17:22.847 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
21-Aug-2019 06:17:22.854 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-8009"]
21-Aug-2019 06:17:22.860 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [504] milliseconds
^C21-Aug-2019 06:17:26.282 INFO [Thread-4] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-8080"]
21-Aug-2019 06:17:26.290 INFO [Thread-4] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["ajp-nio-8009"]
21-Aug-2019 06:17:26.296 INFO [Thread-4] org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina]
21-Aug-2019 06:17:26.338 INFO [Thread-4] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-8080"]
21-Aug-2019 06:17:26.341 INFO [Thread-4] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["ajp-nio-8009"]
21-Aug-2019 06:17:26.344 INFO [Thread-4] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["http-nio-8080"]
21-Aug-2019 06:17:26.345 INFO [Thread-4] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["ajp-nio-8009"]

$ docker --version
Docker version 19.03.1, build 74b1e89

Any ideas what could be causing this? I am running on Debian GNU/Linux, so the potential for line ending inconsistencies should be low, but...

[weiminyu]

Just saw this one after filing my own issue.

I believe this is related to #1854, since getLog() also uses ToStringConsumer to collect data.

[kiview]

Hey @perlun, thanks for raising this issues and sorry for not getting in touch for long. With regards to #1854 I'd hope we can solve both issues together.

[tomqwpl]

I also see this. The OutputFrames passed to ToStringConsumer already have newlines on the end.

[jkroepke]

Any workarounds?

[tomqwpl]

I just wrote my own log consumer to do it how I wanted to.

[perlun]

I just wrote my own log consumer to do it how I wanted to.

@tomqwpl Would you mind sharing some sample code from your workaround?

[tomqwpl]

It's not complex, I just took the original and removed the explicit addition of newlines:

public class ToStringConsumer extends BaseConsumer<ToStringConsumer> {
    private ByteArrayOutputStream stringBuffer = new ByteArrayOutputStream();

    @Override
    public void accept(OutputFrame outputFrame) {
        try {
            if (outputFrame.getBytes() != null) {
                stringBuffer.write(outputFrame.getBytes());
                stringBuffer.flush();
            }
        } catch (IOException e) {
            throw new RuntimeException(e);
        }
    }

    public String toUtf8String() {
        byte[] bytes = stringBuffer.toByteArray();
        return new String(bytes, StandardCharsets.UTF_8);
    }
}

[perlun]

@tomqwpl Interesting, thanks. 👍 For reference, this (the extra newline) seems to have been added in this MR a couple of years ago: https://github.com/testcontainers/testcontainers-java/pull/643/files#diff-321431024ed34199142ebf2d70a46ba89f8a09e66582d40527885123e429b4d9R22-R24