Await: Log-Strategy fails with ConnectionClosedException

[Aviss]

Issue Overview

Trying to use the log-strategy succedes in finding the right log entries but runs into an exception regardless

Expected Behaviour

The container is considered started when the correct log entires are found

Current Behaviour

As soon as the log entries are found, an exception is thrown (stacktrace below)

Steps To Reproduce

1. Configure a valid await-log-strategy.
2. Run a Container test.

Additional Information

Debugging this issue I found that LogScanningAwaitStrategy#await is about to return when the exception is thrown. The exception is coming from closing the LogContainerResultCallback opened as a try-with-resource.

I'm using:

• Arquillian Cube Docker 1.18.2
• Apache Maven 3.3.9 (bb52d8502b132ec0a5a3f4c09453c07478323dc5; 2015-11-10T17:41:47+01:00)
• Java version: 1.8.0_192, vendor: Oracle Corporation
• OS name: "windows 10", version: "10.0", arch: "amd64", family: "dos"

Stacktrace:

java.lang.RuntimeException: Could not auto start container application

	at org.arquillian.cube.docker.impl.client.CubeSuiteLifecycleController.waitForCompletion(CubeSuiteLifecycleController.java:107)
	at org.arquillian.cube.docker.impl.client.CubeSuiteLifecycleController.startAllSteps(CubeSuiteLifecycleController.java:80)
	at org.arquillian.cube.docker.impl.client.CubeSuiteLifecycleController.startAutoContainers(CubeSuiteLifecycleController.java:57)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:86)
	at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:103)
	at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:90)
	at org.jboss.arquillian.test.impl.TestContextHandler.createSuiteContext(TestContextHandler.java:69)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:86)
	at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:95)
	at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:133)
	at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:105)
	at org.jboss.arquillian.test.impl.EventTestRunnerAdaptor.beforeSuite(EventTestRunnerAdaptor.java:71)
	at org.jboss.arquillian.junit.AdaptorManager.initializeAdaptor(AdaptorManager.java:23)
	at org.jboss.arquillian.junit.AdaptorManagerWithNotifier.initializeAdaptor(AdaptorManagerWithNotifier.java:19)
	at org.jboss.arquillian.junit.Arquillian.run(Arquillian.java:109)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
	at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47)
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242)
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)
Caused by: org.arquillian.cube.spi.CubeControlException: Could not start application
	at org.arquillian.cube.spi.CubeControlException.failedStart(CubeControlException.java:19)
	at org.arquillian.cube.docker.impl.model.DockerCube.start(DockerCube.java:141)
	at org.arquillian.cube.impl.client.CubeLifecycleController.start(CubeLifecycleController.java:19)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:86)
	at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:103)
	at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:90)
	at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:133)
	at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:105)
	at org.jboss.arquillian.core.impl.EventImpl.fire(EventImpl.java:62)
	at org.arquillian.cube.docker.impl.client.CubeSuiteLifecycleController$StartCubes.call(CubeSuiteLifecycleController.java:147)
	at org.arquillian.cube.docker.impl.client.CubeSuiteLifecycleController$StartCubes.call(CubeSuiteLifecycleController.java:130)
	at org.jboss.arquillian.core.impl.threading.ThreadedExecutorService$ContextualCallable.call(ThreadedExecutorService.java:88)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: javax.ws.rs.ProcessingException: Error closing message content input stream.
	at org.glassfish.jersey.message.internal.EntityInputStream.close(EntityInputStream.java:161)
	at com.github.dockerjava.jaxrs.util.WrappedResponseInputStream.close(WrappedResponseInputStream.java:60)
	at com.github.dockerjava.core.async.ResultCallbackTemplate.close(ResultCallbackTemplate.java:81)
	at org.arquillian.cube.docker.impl.await.LogScanningAwaitStrategy.await(LogScanningAwaitStrategy.java:82)
	at org.arquillian.cube.docker.impl.model.DockerCube.start(DockerCube.java:135)
	... 18 more
Caused by: org.apache.http.ConnectionClosedException: Premature end of chunk coded message body: closing chunk expected
	at org.apache.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:266)
	at org.apache.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:225)
	at org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:184)
	at org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:213)
	at org.apache.http.impl.io.ChunkedInputStream.close(ChunkedInputStream.java:315)
	at org.apache.http.impl.execchain.ResponseEntityProxy.streamClosed(ResponseEntityProxy.java:143)
	at org.apache.http.conn.EofSensorInputStream.checkClose(EofSensorInputStream.java:228)
	at org.apache.http.conn.EofSensorInputStream.close(EofSensorInputStream.java:172)
	at java.io.BufferedInputStream.close(BufferedInputStream.java:483)
	at java.io.FilterInputStream.close(FilterInputStream.java:181)
	at org.glassfish.jersey.apache.connector.ApacheConnector$3.close(ApacheConnector.java:644)
	at java.io.FilterInputStream.close(FilterInputStream.java:181)
	at org.glassfish.jersey.apache.connector.ApacheConnector$HttpClientResponseInputStream.close(ApacheConnector.java:621)
	at org.glassfish.jersey.message.internal.EntityInputStream.close(EntityInputStream.java:158)
	... 22 more

docker-compose.yml

application:
  buildImage:
    dockerfileLocation: .
    noCache: true
    remove: true
  await:
    strategy: log
    timeout: 60
    match: 'badassmicrofish'
    occurrences: 2
  portBindings:
    - 8080

Dockerfile

FROM payara/micro
COPY ./target/test-stack.war ${DEPLOY_DIR}

[marcos-scholtz]

I'm having the same problem. Did you find a workaround?

[Aviss]

Unfortunately not. We eventually switched back to regular Arquillian and running integration tests with a managed Wildfly container

[marcos-scholtz]

Damn. Ok, thanks for the info.