Selenium: Grid 3.12.0 with Appium nodes -> Failed to check status of node: unexpected end of stream on Connection

[mcopjan]

OS:
Windows Server 2012 R2
Selenium Version:
3.12.0
Browser:
Appium Safari nodes 1.7.2

Hub config:

_{
"port": 4880,
"servlets": null,
"withoutServlets": null,
"custom": {},
"capabilityMatcher": "org.openqa.grid.internal.utils.DefaultCapabilityMatcher",
"registry": "org.openqa.grid.internal.DefaultGridRegistry",
"throwOnCapabilityNotPresent": true,
"role": "hub",
"cleanUpCycle": 5000,
"debug": true,
"timeout": 120,
"browserTimeout": 90
}_

node/s config

_{
"capabilities": [
{
"platformName": "ios",
"deviceName": "iPhone",
"browserName": "Safari",
"maxInstances": 1
}
],
"configuration": {
"timeout": 300,
"proxy": "org.openqa.grid.selenium.proxy.DefaultRemoteProxy",
"url": "http://uipmspiqat001.ipswich.mgsops.net:4493/wd/hub",
"host": "uipmspiqat001.ipswich.mgsops.net",
"port": 4493,
"maxSession": 1,
"register": true,
"registerCycle": 5000,
"hubPort": 4880,
"hubHost": "UIPWSPITES006"
}
}_

I have a grid spinned up inside Windows server and a few appium nodes registered into this grid from inside Macmini's. I am randomly getting the following error:

From test log:

---

System.InvalidOperationException : cannot forward the request unexpected end of stream on Connection{uipmspiqat001.ipswich.mgsops.net:4492, proxy=DIRECT hostAddress=uipmspiqat001.ipswich.mgsops.net/10.203.48.87:4492 cipherSuite=none protocol=http/1.1}
TearDown : System.InvalidOperationException : Session [7ca83036-de2d-499d-95d1-743b28a4319d] was terminated due to FORWARDING_TO_NODE_FAILED
at OpenQA.Selenium.Remote.RemoteWebDriver.UnpackAndThrowOnError(Response errorResponse)
at OpenQA.Selenium.Remote.RemoteWebDriver.Execute(String driverCommandToExecute, Dictionary2 parameters) at OpenQA.Selenium.Appium.AppiumDriver1.get_Contexts()

This is fired when I am trying to take a screenshot on TearDown but the session had been already killed at that time.
So I switched grid into debug mode and found the following error.

From hub log

---

12:04:29.244 ERROR [RequestHandler.process] - cannot forward the request unexpected end of stream on Connection{uipmspiqat001.ipswich.mgsops.net:4492, proxy=DIRECT hostAddress=uipmspiqat001.ipswich.mgsops.net/10.203.48.87:4492 cipherSuite=none protocol=http/1.1}
java.io.IOException: unexpected end of stream on Connection{uipmspiqat001.ipswich.mgsops.net:4492, proxy=DIRECT hostAddress=uipmspiqat001.ipswich.mgsops.net/10.203.48.87:4492 cipherSuite=none protocol=http/1.1}
at okhttp3.internal.http1.Http1Codec.readResponseHeaders(Http1Codec.java:205)
at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:88)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:125)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:200)
at okhttp3.RealCall.execute(RealCall.java:77)
at org.openqa.selenium.remote.internal.OkHttpClient.execute(OkHttpClient.java:105)
at org.openqa.grid.internal.TestSession.sendRequestToNode(TestSession.java:430)
at org.openqa.grid.internal.TestSession.forward(TestSession.java:237)
at org.openqa.grid.web.servlet.handler.RequestHandler.forwardRequest(RequestHandler.java:99)
at org.openqa.grid.web.servlet.handler.RequestHandler.process(RequestHandler.java:133)
at org.openqa.grid.web.servlet.DriverServlet.process(DriverServlet.java:86)
at org.openqa.grid.web.servlet.DriverServlet.doGet(DriverServlet.java:64)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at org.seleniumhq.jetty9.servlet.ServletHolder.handle(ServletHolder.java:860)
at org.seleniumhq.jetty9.servlet.ServletHandler.doHandle(ServletHandler.java:535)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.seleniumhq.jetty9.security.SecurityHandler.handle(SecurityHandler.java:548)
at org.seleniumhq.jetty9.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)
at org.seleniumhq.jetty9.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
at org.seleniumhq.jetty9.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
at org.seleniumhq.jetty9.servlet.ServletHandler.doScope(ServletHandler.java:473)
at org.seleniumhq.jetty9.server.session.SessionHandler.doScope(SessionHandler.java:1564)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
at org.seleniumhq.jetty9.server.handler.ContextHandler.doScope(ContextHandler.java:1155)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.seleniumhq.jetty9.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
at org.seleniumhq.jetty9.server.Server.handle(Server.java:530)
at org.seleniumhq.jetty9.server.HttpChannel.handle(HttpChannel.java:347)
at org.seleniumhq.jetty9.server.HttpConnection.onFillable(HttpConnection.java:256)
at org.seleniumhq.jetty9.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
at org.seleniumhq.jetty9.io.FillInterest.fillable(FillInterest.java:102)
at org.seleniumhq.jetty9.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
at org.seleniumhq.jetty9.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)
at org.seleniumhq.jetty9.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)
at org.seleniumhq.jetty9.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
at org.seleniumhq.jetty9.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:382)
at org.seleniumhq.jetty9.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708)
at org.seleniumhq.jetty9.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626)
at java.lang.Thread.run(Unknown Source)
Caused by: java.io.EOFException: n not found: limit=0 content=…
at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:227)
at okhttp3.internal.http1.Http1Codec.readHeaderLine(Http1Codec.java:212)
at okhttp3.internal.http1.Http1Codec.readResponseHeaders(Http1Codec.java:189)
... 53 more
12:04:29.258 DEBUG [ActiveTestSessions.getExistingSession] - Session [7ca83036-de2d-499d-95d1-743b28a4319d] was terminated due to FORWARDING_TO_NODE_FAILED
12:04:29.262 DEBUG [ActiveTestSessions.getExistingSession] - Session [7ca83036-de2d-499d-95d1-743b28a4319d] was terminated due to FORWARDING_TO_NODE_FAILED

can anyone guide me how to resolve this issue and what could be the problem please?

[barancev]

And what's the issue? One can't take a screenshot in a killed session, it's expected. Do you mean the error message is not clear enough?

[barancev]

Must be a duplicate of #6025

[bennid]

FYI... I don't believe this is a duplicate. There's some odd issue with the OkHttpClient in selenium server standalone 3.12.0 and 3.13.0 with Appium Grid Nodes (worked fine in 3.11.0). This error was just shown while trying to get the heartbeat of the appium server. The appium server appears to reply correctly with getStatus()

2018-07-10 19:52:37:003 - [HTTP] --> GET /wd/hub/status
2018-07-10 19:52:37:003 - [HTTP] {}
2018-07-10 19:52:37:004 - [debug] [W3C] Calling AppiumDriver.getStatus() with args: []
2018-07-10 19:52:37:019 - [debug] [W3C] Responding to client with driver.getStatus() result: {"build":{"version":"1.8.1","revision":null}}
2018-07-10 19:52:37:020 - [HTTP] <-- GET /wd/hub/status 200 16 ms - 55

But the server just outputs the following:

2018-07-10 15:53:42.196830500  15:53:42.196 INFO [TARemoteProxy.logMessage] - [http://10.96.80.52:4833 -- 28.java.lang.Object@62cebcd9] : Failed to check status of node http://10.96.80.52:4833 :unexpected end of stream on Connection{10.96.80.52:4833, proxy=DIRECT hostAddress=/10.96.80.52:4833 cipherSuite=none protocol=http/1.1}
2018-07-10 15:53:42.196942500  org.openqa.grid.common.exception.GridException: unexpected end of stream on Connection{10.96.80.52:4833, proxy=DIRECT hostAddress=/10.96.80.52:4833 cipherSuite=none protocol=http/1.1}
2018-07-10 15:53:42.196949500   at org.openqa.grid.internal.BaseRemoteProxy.getProxyStatus(BaseRemoteProxy.java:461)
2018-07-10 15:53:42.196951500   at TARemoteProxy.isAlive(TARemoteProxy.java:71)
2018-07-10 15:53:42.196953500   at org.openqa.grid.selenium.proxy.DefaultRemoteProxy$1.run(DefaultRemoteProxy.java:141)
2018-07-10 15:53:42.196954500   at java.lang.Thread.run(Thread.java:748)
2018-07-10 15:53:42.196985500  Caused by: java.io.IOException: unexpected end of stream on Connection{10.96.80.52:4833, proxy=DIRECT hostAddress=/10.96.80.52:4833 cipherSuite=none protocol=http/1.1}
2018-07-10 15:53:42.197016500   at okhttp3.internal.http1.Http1Codec.readResponseHeaders(Http1Codec.java:208)
2018-07-10 15:53:42.197021500   at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:88)
2018-07-10 15:53:42.197022500   at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
2018-07-10 15:53:42.197047500   at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45)
2018-07-10 15:53:42.197051500   at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
2018-07-10 15:53:42.197052500   at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
2018-07-10 15:53:42.197080500   at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93)
2018-07-10 15:53:42.197085500   at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
2018-07-10 15:53:42.197086500   at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
2018-07-10 15:53:42.197087500   at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
2018-07-10 15:53:42.197112500   at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
2018-07-10 15:53:42.197116500   at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:126)
2018-07-10 15:53:42.197117500   at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
2018-07-10 15:53:42.197143500   at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
2018-07-10 15:53:42.197160500   at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:200)
2018-07-10 15:53:42.197161500   at okhttp3.RealCall.execute(RealCall.java:77)
2018-07-10 15:53:42.197188500   at org.openqa.selenium.remote.internal.OkHttpClient.execute(OkHttpClient.java:105)
2018-07-10 15:53:42.197216500   at org.openqa.grid.internal.BaseRemoteProxy.getProxyStatus(BaseRemoteProxy.java:443)
2018-07-10 15:53:42.197220500   ... 3 more
2018-07-10 15:53:42.197310500  Caused by: java.io.EOFException: \n not found: limit=0 content=…
2018-07-10 15:53:42.197322500   at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:237)
2018-07-10 15:53:42.197323500   at okhttp3.internal.http1.Http1Codec.readHeaderLine(Http1Codec.java:215)
2018-07-10 15:53:42.197328500   at okhttp3.internal.http1.Http1Codec.readResponseHeaders(Http1Codec.java:189)
2018-07-10 15:53:42.197380500   ... 20 more

FYI: The TARemoteProxy() isAlive() method is simply:

   @Override
    public boolean isAlive() {
        try {
            getProxyStatus();
            return true;
        } catch (Exception e) {
            logMessage(Level.INFO, "Failed to check status of node " + getRemoteHost().toExternalForm() + " :" + e.getMessage());
            e.printStackTrace();
            return false;
        }
    }

[vinaybalepur]

I am also facing the same issue with no solution. For me the set up is selenium hub and node running on 3.12 and hub config as

{
"capabilities": [
{
"platform":"ANDROID",
"version": "7.0",
"browserName":"Chrome",
"maxInstances": 3,
"seleniumProtocol": "WebDriver",
"udid":"2335452b"
}
],
"configuration": {
"cleanUpCycle": 240,
"timeout": 240,
"proxy": "org.openqa.grid.selenium.proxy.DefaultRemoteProxy",
"host": "localhost",
"port": 4726,
"maxSession": 6,
"register": true,
"url": "http://localhost:4444/wd/hub",
"registerCycle": 5000,
"hubPort": 4444,
"hubHost": "localhost",
"role": "node",
"unregisterIfStillDownAfter": 60000,
"downPollingLimit": 2,
"nodeStatusCheckTimeout": 500,
"nodePolling": 500
}
}

[prakashpqa]

I too faced this problem. Switched back to 3.11.0.

[vinaybalepur]

Any one who might face this issue and coming here for a solution. I downgraded selenium standalone server to 3.9.0. It is after this version that the transition to okhttp was made in selenium and this is culprit which is causing the issue. I have been running on this version for 2 weeks now and I am not facing any issues with the connection loss. I hope this helps people who have moved to the latest version of selenium. Also I have tested with both Android and IOS and it seem to have fixed the issue for both the OS.