java.io.IOException: Failed to upgrade connection when running test against OCP 3.9

[goldmann]

Issue Overview

I would like to get some help on investigating why this is failing on newest OCP release. This can be reproduced every time. I'm using the 1.15.4-SNAPSHOT version which is current master + #1046. It looks like the test is executed successfully, environment teared down correctly. I do remember tests passing fine on this environment, but now these are failing. I'm not entirely sure why it is this case.

Any ideas?

Additional Information

I do see also this in testrunner log:

{"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"Get https://172.16.212.13:10250/containerLogs/test-sso-7f61f278/testrunner/testrunner?follow=true: dial tcp 172.16.212.13:10250: getsockopt: connection timed out","code":500}

And in the output log:

INFO: Deleting environment for org.jboss.test.arquillian.ce.sso.Sso72ServerBasicTest
Exception in thread "OkHttp Dispatcher" java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@1282bda0 rejected from java.util.concurrent.ThreadPoolExecutor@637dd22a[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
	at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063)
	at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830)
	at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379)
	at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112)
	at java.util.concurrent.Executors$DelegatedExecutorService.submit(Executors.java:678)
	at io.fabric8.kubernetes.clnt.v3_1.dsl.internal.LogWatchCallback.onResponse(LogWatchCallback.java:162)
	at okhttp3.RealCall$AsyncCall.execute(RealCall.java:141)
	at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
	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)
[2018-04-19T08:26:30Z] [Normal] [Pod:testrunner]: (Killing) Killing container with id docker://testrunner:Need to kill Pod

[2018-04-19T08:26:30Z] [Normal] [Pod:testrunner]: (Killing) Killing container with id docker://testrunner:Need to kill Pod

This is running the test on:

OpenShift Master: v3.9.14
Kubernetes Master: v1.9.1+a0ce1bc657
OpenShift Web Console: v3.9.14

Stacktrace can be found below.

Stacktrace

Running org.jboss.test.arquillian.ce.sso.Sso72ServerLogTest
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 159.383 sec <<< FAILURE! - in org.jboss.test.arquillian.ce.sso.Sso72ServerLogTest
org.jboss.test.arquillian.ce.sso.Sso72ServerLogTest  Time elapsed: 159.383 sec  <<< ERROR!
org.arquillian.cube.spi.CubeControlException: Could not start testrunner
	at org.arquillian.cube.spi.CubeControlException.failedStart(CubeControlException.java:19)
	at org.arquillian.cube.openshift.impl.model.BuildablePodCube.start(BuildablePodCube.java:128)
	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.impl.client.container.CubeContainerLifecycleController.startCubeMappedContainer(CubeContainerLifecycleController.java:47)
	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.jboss.arquillian.container.impl.ContainerImpl.start(ContainerImpl.java:177)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController$8.perform(ContainerLifecycleController.java:137)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController$8.perform(ContainerLifecycleController.java:133)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController.forContainer(ContainerLifecycleController.java:208)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController.startContainer(ContainerLifecycleController.java:133)
	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.container.impl.client.ContainerDeploymentContextHandler.createContainerContext(ContainerDeploymentContextHandler.java:54)
	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.core.impl.EventImpl.fire(EventImpl.java:62)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController$3.perform(ContainerLifecycleController.java:82)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController$3.perform(ContainerLifecycleController.java:76)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController.forEachClassContainer(ContainerLifecycleController.java:191)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController.startClassContainers(ContainerLifecycleController.java:76)
	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.jboss.arquillian.container.test.impl.client.ContainerEventController.execute(ContainerEventController.java:94)
	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.createClassContext(TestContextHandler.java:83)
	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.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.beforeClass(EventTestRunnerAdaptor.java:89)
	at org.jboss.arquillian.junit.Arquillian$2.evaluate(Arquillian.java:163)
	at org.jboss.arquillian.junit.Arquillian.multiExecute(Arquillian.java:350)
	at org.jboss.arquillian.junit.Arquillian.access$200(Arquillian.java:54)
	at org.jboss.arquillian.junit.Arquillian$3.evaluate(Arquillian.java:177)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.jboss.arquillian.junit.Arquillian.run(Arquillian.java:115)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:367)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:274)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:161)
	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121)
Caused by: java.io.IOException: Failed to establish portforward client connection
	at org.arquillian.cube.kubernetes.impl.portforward.PortForwarder.(PortForwarder.java:145)
	at org.arquillian.cube.openshift.impl.model.BuildablePodCube$PortBindings.createProxies(BuildablePodCube.java:357)
	at org.arquillian.cube.openshift.impl.model.BuildablePodCube$PortBindings.podStarted(BuildablePodCube.java:349)
	at org.arquillian.cube.openshift.impl.model.BuildablePodCube$PortBindings.access$000(BuildablePodCube.java:214)
	at org.arquillian.cube.openshift.impl.model.BuildablePodCube.start(BuildablePodCube.java:114)
	... 96 more
Caused by: java.io.IOException: Unexpected error
	at org.arquillian.cube.kubernetes.impl.portforward.PortForwarder$2$1.completed(PortForwarder.java:123)
	at org.arquillian.cube.kubernetes.impl.portforward.PortForwarder$2$1.completed(PortForwarder.java:117)
	at io.undertow.client.http.HttpClientExchange.setResponse(HttpClientExchange.java:115)
	at io.undertow.client.http.HttpClientConnection$ClientReadListener.handleEvent(HttpClientConnection.java:584)
	at io.undertow.client.http.HttpClientConnection$ClientReadListener.handleEvent(HttpClientConnection.java:473)
	at org.xnio.ChannelListeners.invokeChannelListener(ChannelListeners.java:92)
	at org.xnio.conduits.ReadReadyHandler$ChannelListenerHandler.readReady(ReadReadyHandler.java:66)
	at org.xnio.nio.NioSocketConduit.handleReady(NioSocketConduit.java:88)
	at org.xnio.nio.WorkerThread.run(WorkerThread.java:539)
Caused by: java.io.IOException: Failed to upgrade connection
	at org.arquillian.cube.kubernetes.impl.portforward.PortForwarder.upgradeConnection(PortForwarder.java:262)
	at org.arquillian.cube.kubernetes.impl.portforward.PortForwarder.access$000(PortForwarder.java:48)
	at org.arquillian.cube.kubernetes.impl.portforward.PortForwarder$2$1.completed(PortForwarder.java:121)
	... 8 more

[goldmann]

Issue may be related to some OCP hiccup, I cannot get even logs using web console or oc utility. Investigating.

[goldmann]

Closing this issue. The problem was that in my environment, I accidentally disabled required ports for logs fetching and this caused the mentioned issue.