Java-client will throw exceptions - GridException: Cannot extract a capabilities xxx with webdriver 3.x

[fionazj]

Description

Before the session of the simulator is started, some errors will show up in hub log as follow.

Environment

• WebDriver version build version : webdriver 3.3.1 (Also tried with webdriver 3.3.4)
• java client build version: java-client-5.0.0-BETA7
• Appium : 1.6.5
• Desktop OS/version used to run Appium if necessary: Mac OS 10.12.5
• Node.js version : 4.2.0
• Mobile platform/version under test: IPhone IOS 9.3
• Real device or emulator/simulator: Simulator

Details

Since webdriver3.x is released, so we need to do a trail run on that, so I updated the webdriver in both our project and hub, also java-client in the project, and start the hub to execute cases. But when a session start, exception occurs, and seemed like the Appium is fine, but java-client 5.x with webdriver3.x is not, did i miss something?

And it was totally fine when I change back webdriver to 2.53.0

Code To Reproduce Issue [ Good To Have ]

Hub startup command line:

/usr/bin/java -Xdebug -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=5005 -jar -verbose /root/selenium-grid/selenium-server-standalone-3.3.1.jar -role hub -port 44442 >> bjdev3.log &

Node configuration of Appium

admins-Mac-mini:Desktop uia$ cat appium_node_config_ios.json
{
"capabilities":
[
{
"browserName": "Safari",
"platformVersion":"9.3",
"maxInstances": 1,
"platformName":"iOS",
"deviceName":"iPhone 6s",
"seleniumProtocol":"WebDriver"
}
],

"configuration":
{
"cleanUpCycle":2000,
"timeout":30000,
"proxy": "org.openqa.grid.selenium.proxy.DefaultRemoteProxy",
"url":"http://10.37.2.203:4723/wd/hub",
"maxSession": 1,
"port": 4723,
"host": "10.37.2.203",
"register": true,
"registerCycle": 5000,
"hubPort": 44442,
"hubHost": "10.37.10.37"
}
}

Ecxeption stacktraces

root@ubuntu:~/selenium-grid# 2017-06-12 07:54:04.737:WARN:osjs.HttpChannel:qtp1962826816-19: /wd/hub/session
java.io.IOException: org.openqa.grid.common.exception.GridException: Cannot extract a capabilities from the request: {"capabilities":[{"desiredCapabilities":{"app":"Safari","platformVersion":"9.3","automationName":"XCUITest","browserName":"Safari","javascriptEnabled":"true","autoWebview":"true","platformName":"iOS","deviceName":"iPhone 6"}},{"requiredCapabilities":{}}],"desiredCapabilities":{"app":"Safari","platformVersion":"9.3","automationName":"XCUITest","browserName":"Safari","javascriptEnabled":"true","autoWebview":"true","platformName":"iOS","deviceName":"iPhone 6"},"requiredCapabilities":{}}
at org.openqa.grid.web.servlet.DriverServlet.process(DriverServlet.java:126)
at org.openqa.grid.web.servlet.DriverServlet.doPost(DriverServlet.java:67)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at org.seleniumhq.jetty9.servlet.ServletHolder.handle(ServletHolder.java:841)
at org.seleniumhq.jetty9.servlet.ServletHandler.doHandle(ServletHandler.java:543)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
at org.seleniumhq.jetty9.server.session.SessionHandler.doHandle(SessionHandler.java:1584)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
at org.seleniumhq.jetty9.server.handler.ContextHandler.doHandle(ContextHandler.java:1228)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
at org.seleniumhq.jetty9.servlet.ServletHandler.doScope(ServletHandler.java:481)
at org.seleniumhq.jetty9.server.session.SessionHandler.doScope(SessionHandler.java:1553)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
at org.seleniumhq.jetty9.server.handler.ContextHandler.doScope(ContextHandler.java:1130)
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:564)
at org.seleniumhq.jetty9.server.HttpChannel.handle(HttpChannel.java:320)
at org.seleniumhq.jetty9.server.HttpConnection.onFillable(HttpConnection.java:251)
at org.seleniumhq.jetty9.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
at org.seleniumhq.jetty9.io.FillInterest.fillable(FillInterest.java:112)
at org.seleniumhq.jetty9.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
at org.seleniumhq.jetty9.util.thread.Invocable.invokePreferred(Invocable.java:122)
at org.seleniumhq.jetty9.util.thread.strategy.ExecutingExecutionStrategy.invoke(ExecutingExecutionStrategy.java:58)
at org.seleniumhq.jetty9.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:201)
at org.seleniumhq.jetty9.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:133)
at org.seleniumhq.jetty9.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:672)
at org.seleniumhq.jetty9.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:590)
at java.lang.Thread.run(Thread.java:745)
Caused by:
org.openqa.grid.common.exception.GridException: Cannot extract a capabilities from the request: {"capabilities":[{"desiredCapabilities":{"app":"Safari","platformVersion":"9.3","automationName":"XCUITest","browserName":"Safari","javascriptEnabled":"true","autoWebview":"true","platformName":"iOS","deviceName":"iPhone 6"}},{"requiredCapabilities":{}}],"desiredCapabilities":{"app":"Safari","platformVersion":"9.3","automationName":"XCUITest","browserName":"Safari","javascriptEnabled":"true","autoWebview":"true","platformName":"iOS","deviceName":"iPhone 6"},"requiredCapabilities":{}}
at org.openqa.grid.web.servlet.handler.WebDriverRequest.extractDesiredCapability(WebDriverRequest.java:75)
at org.openqa.grid.web.servlet.handler.SeleniumBasedRequest.(SeleniumBasedRequest.java:102)
at org.openqa.grid.web.servlet.handler.WebDriverRequest.(WebDriverRequest.java:36)
at org.openqa.grid.web.servlet.handler.WebDriverRequestFactory.createFromRequest(WebDriverRequestFactory.java:30)
at org.openqa.grid.web.servlet.handler.SeleniumBasedRequest.createFromRequest(SeleniumBasedRequest.java:73)
at org.openqa.grid.web.servlet.DriverServlet.process(DriverServlet.java:81)
at org.openqa.grid.web.servlet.DriverServlet.doPost(DriverServlet.java:67)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at org.seleniumhq.jetty9.servlet.ServletHolder.handle(ServletHolder.java:841)
at org.seleniumhq.jetty9.servlet.ServletHandler.doHandle(ServletHandler.java:543)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
at org.seleniumhq.jetty9.server.session.SessionHandler.doHandle(SessionHandler.java:1584)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
at org.seleniumhq.jetty9.server.handler.ContextHandler.doHandle(ContextHandler.java:1228)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
at org.seleniumhq.jetty9.servlet.ServletHandler.doScope(ServletHandler.java:481)
at org.seleniumhq.jetty9.server.session.SessionHandler.doScope(SessionHandler.java:1553)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
at org.seleniumhq.jetty9.server.handler.ContextHandler.doScope(ContextHandler.java:1130)
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:564)
at org.seleniumhq.jetty9.server.HttpChannel.handle(HttpChannel.java:320)
at org.seleniumhq.jetty9.server.HttpConnection.onFillable(HttpConnection.java:251)
at org.seleniumhq.jetty9.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
at org.seleniumhq.jetty9.io.FillInterest.fillable(FillInterest.java:112)
at org.seleniumhq.jetty9.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
at org.seleniumhq.jetty9.util.thread.Invocable.invokePreferred(Invocable.java:122)
at org.seleniumhq.jetty9.util.thread.strategy.ExecutingExecutionStrategy.invoke(ExecutingExecutionStrategy.java:58)
at org.seleniumhq.jetty9.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:201)
at org.seleniumhq.jetty9.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:133)
at org.seleniumhq.jetty9.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:672)
at org.seleniumhq.jetty9.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:590)
at java.lang.Thread.run(Thread.java:745)
Caused by:
java.lang.ClassCastException: com.google.gson.JsonArray cannot be cast to com.google.gson.JsonObject
at com.google.gson.JsonObject.getAsJsonObject(JsonObject.java:191)
at org.openqa.grid.web.servlet.handler.WebDriverRequest.extractDesiredCapability(WebDriverRequest.java:69)
at org.openqa.grid.web.servlet.handler.SeleniumBasedRequest.(SeleniumBasedRequest.java:102)
at org.openqa.grid.web.servlet.handler.WebDriverRequest.(WebDriverRequest.java:36)
at org.openqa.grid.web.servlet.handler.WebDriverRequestFactory.createFromRequest(WebDriverRequestFactory.java:30)
at org.openqa.grid.web.servlet.handler.SeleniumBasedRequest.createFromRequest(SeleniumBasedRequest.java:73)
at org.openqa.grid.web.servlet.DriverServlet.process(DriverServlet.java:81)
at org.openqa.grid.web.servlet.DriverServlet.doPost(DriverServlet.java:67)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at org.seleniumhq.jetty9.servlet.ServletHolder.handle(ServletHolder.java:841)
at org.seleniumhq.jetty9.servlet.ServletHandler.doHandle(ServletHandler.java:543)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
at org.seleniumhq.jetty9.server.session.SessionHandler.doHandle(SessionHandler.java:1584)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
at org.seleniumhq.jetty9.server.handler.ContextHandler.doHandle(ContextHandler.java:1228)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
at org.seleniumhq.jetty9.servlet.ServletHandler.doScope(ServletHandler.java:481)
at org.seleniumhq.jetty9.server.session.SessionHandler.doScope(SessionHandler.java:1553)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
at org.seleniumhq.jetty9.server.handler.ContextHandler.doScope(ContextHandler.java:1130)
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:564)
at org.seleniumhq.jetty9.server.HttpChannel.handle(HttpChannel.java:320)
at org.seleniumhq.jetty9.server.HttpConnection.onFillable(HttpConnection.java:251)
at org.seleniumhq.jetty9.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
at org.seleniumhq.jetty9.io.FillInterest.fillable(FillInterest.java:112)
at org.seleniumhq.jetty9.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
at org.seleniumhq.jetty9.util.thread.Invocable.invokePreferred(Invocable.java:122)
at org.seleniumhq.jetty9.util.thread.strategy.ExecutingExecutionStrategy.invoke(ExecutingExecutionStrategy.java:58)
at org.seleniumhq.jetty9.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:201)
at org.seleniumhq.jetty9.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:133)
at org.seleniumhq.jetty9.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:672)
at org.seleniumhq.jetty9.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:590)
at java.lang.Thread.run(Thread.java:745)
07:54:04.778 INFO - Got a request to create a new session: Capabilities [{app=Safari, platformVersion=9.3, automationName=XCUITest, browserName=Safari, javascriptEnabled=true, autoWebview=true, platformName=iOS, deviceName=iPhone 6}]
07:54:04.779 INFO - Trying to create a new session on test slot {seleniumProtocol=WebDriver, platformVersion=9.3, browserName=Safari, maxInstances=1, platformName=iOS, deviceName=iPhone 6s}
07:54:23.100 INFO - Marking the node http://10.37.2.203:4723 as down: cannot reach the node for 2 tries

Link to Appium logs

admins-Mac-mini:tmp uia$ tail -200f appium.log
2017-06-12 05:59:36:206 - info: [Appium] Welcome to Appium v1.6.5
2017-06-12 05:59:36:209 - info: [Appium] Non-default server args:
2017-06-12 05:59:36:210 - info: [Appium] sessionOverride: true
2017-06-12 05:59:36:210 - info: [Appium] log: /tmp/appium.log
2017-06-12 05:59:36:210 - info: [Appium] loglevel: info
2017-06-12 05:59:36:210 - info: [Appium] nodeconfig: /Users/uia/Desktop/appium_node_config_ios.json
2017-06-12 05:59:36:210 - info: [Appium] debugLogSpacing: true
2017-06-12 05:59:36:210 - info: [Appium] platformName: iOS
2017-06-12 05:59:36:211 - info: [Appium] platformVersion: 9.3
2017-06-12 05:59:36:211 - info: [Appium] deviceName: iPhone 7
2017-06-12 05:59:36:211 - info: [Appium] browserName: Safari
2017-06-12 05:59:36:211 - info: [Appium] fullReset: true
2017-06-12 05:59:36:211 - info: [Appium] showIOSLog: true
2017-06-12 05:59:36:212 - warn: [Appium] Deprecated server args:
2017-06-12 05:59:36:212 - warn: [Appium] --platform-name => --default-capabilities '{"platformName":"iOS"}'
2017-06-12 05:59:36:212 - warn: [Appium] --platform-version => --default-capabilities '{"platformVersion":"9.3"}'
2017-06-12 05:59:36:212 - warn: [Appium] --device-name => --default-capabilities '{"deviceName":"iPhone 7"}'
2017-06-12 05:59:36:212 - warn: [Appium] --browser-name => --default-capabilities '{"browserName":"Safari"}'
2017-06-12 05:59:36:213 - warn: [Appium] --full-reset => --default-capabilities '{"fullReset":true}'
2017-06-12 05:59:36:213 - warn: [Appium] --show-ios-log => --default-capabilities '{"showIOSLog":true}'
2017-06-12 05:59:36:213 - info: [Appium] Default capabilities, which will be added to each request unless overridden by desired capabilities:
2017-06-12 05:59:36:215 - info: [Appium] platformName: 'iOS'
2017-06-12 05:59:36:216 - info: [Appium] platformVersion: '9.3'
2017-06-12 05:59:36:216 - info: [Appium] deviceName: 'iPhone 7'
2017-06-12 05:59:36:216 - info: [Appium] browserName: 'Safari'
2017-06-12 05:59:36:216 - info: [Appium] fullReset: true
2017-06-12 05:59:36:216 - info: [Appium] showIOSLog: true
2017-06-12 05:59:36:255 - info: [Appium] Appium REST http interface listener started on 0.0.0.0:4723
2017-06-12 05:59:46:292 - info: [HTTP] --> GET /wd/hub/status {}
2017-06-12 05:59:46:311 - info: [HTTP] <-- GET /wd/hub/status 200 17 ms - 83
2017-06-12 05:59:51:315 - info: [HTTP] --> GET /wd/hub/status {}
2017-06-12 05:59:51:329 - info: [HTTP] <-- GET /wd/hub/status 200 12 ms - 83
2017-06-12 05:59:56:335 - info: [HTTP] --> GET /wd/hub/status {}
2017-06-12 05:59:56:349 - info: [HTTP] <-- GET /wd/hub/status 200 14 ms - 83
2017-06-12 05:59:58:065 - info: [HTTP] --> POST /wd/hub/session {"desiredCapabilities":{"app":"Safari","platformVersion":"9.3","automationName":"XCUITest","browserName":"Safari","javascriptEnabled":"true","autoWebview":"true","platformName":"iOS","deviceName":"iPhone 6"},"requiredCapabilities":{}}
2017-06-12 05:59:58:068 - info: [Appium] Creating new XCUITestDriver (v2.30.0) session
2017-06-12 05:59:58:068 - info: [Appium] Capabilities:
2017-06-12 05:59:58:068 - info: [Appium] app: 'Safari'
2017-06-12 05:59:58:069 - info: [Appium] platformVersion: '9.3'
2017-06-12 05:59:58:069 - info: [Appium] automationName: 'XCUITest'
2017-06-12 05:59:58:069 - info: [Appium] browserName: 'Safari'
2017-06-12 05:59:58:069 - info: [Appium] javascriptEnabled: 'true'
2017-06-12 05:59:58:069 - info: [Appium] autoWebview: 'true'
2017-06-12 05:59:58:070 - info: [Appium] platformName: 'iOS'
2017-06-12 05:59:58:070 - info: [Appium] deviceName: 'iPhone 6'
2017-06-12 05:59:58:070 - info: [Appium] fullReset: true
2017-06-12 05:59:58:071 - info: [Appium] showIOSLog: true
2017-06-12 05:59:58:076 - warn: [BaseDriver] Capability 'autoWebview' changed from string to boolean. This may cause unexpected behavior
2017-06-12 05:59:58:082 - warn: [BaseDriver] The following capabilities were provided, but are not recognized by appium: javascriptEnabled.
2017-06-12 05:59:58:187 - info: [BaseDriver] Session created with session id: 3088b29c-c128-4326-ad65-98521c8b0363
2017-06-12 05:59:58:437 - info: [iOSSim] Constructing iOS simulator for Xcode version 7.3 with udid 'A54CEB4F-C2C3-47E5-8DCF-3A906B568894'
2017-06-12 05:59:58:438 - info: [XCUITest] Determining device to run tests on: udid: 'A54CEB4F-C2C3-47E5-8DCF-3A906B568894', real device: false
2017-06-12 05:59:58:438 - info: [XCUITest] Safari test requested
2017-06-12 06:00:01:357 - info: [HTTP] --> GET /wd/hub/status {}
2017-06-12 06:00:06:359 - info: [HTTP] <-- GET /wd/hub/status - - ms - -
2017-06-12 06:00:09:720 - info: [iOSSim] Cleaning simulator A54CEB4F-C2C3-47E5-8DCF-3A906B568894
2017-06-12 06:00:10:160 - info: [XCUITest] Setting up simulator
2017-06-12 06:00:10:237 - info: [XCUITest] Simulator with udid 'A54CEB4F-C2C3-47E5-8DCF-3A906B568894' not booted. Booting up now
2017-06-12 06:00:10:268 - info: [iOSSim] Starting simulator with command: open -Fn /Applications/Xcode_7.3.app/Contents/Developer/Applications/Simulator.app --args -CurrentDeviceUDID A54CEB4F-C2C3-47E5-8DCF-3A906B568894 -ConnectHardwareKeyboard 0
2017-06-12 06:00:10:374 - info: [iOSSim] Simulator log at '/Users/uia/Library/Logs/CoreSimulator/A54CEB4F-C2C3-47E5-8DCF-3A906B568894/system.log'
2017-06-12 06:00:10:375 - info: [iOSSim] Tailing simulator logs until we encounter the string "System app "com.apple.springboard" finished startup"
2017-06-12 06:00:10:377 - info: [iOSSim] We will time out after 60000ms

[TikhomirovSergey]

@fionazj Could you describe how do run hub/node?

WebDriver version build version : webdriver 3.3.1 (Also tried with webdriver 3.3.4)
And it was totally fine when I change back webdriver to 2.53.0

Do you mean Selenium server? Or do you use another Selenium client dependency?

[fionazj]

@TikhomirovSergey , I mean the selenium server

And here's how I start hub and node:

The hub started by following command:
/usr/bin/java -jar /root/selenium-grid/selenium-server-standalone-3.3.1.jar -role hub -port 44442

For the node, just a config file, and Appium will load the config file
appium --session-override --debug-log-spacing --log "/tmp/appium.log" --log-level "info" --nodeconfig "/Users/uiatouch/Desktop/appium_node_config_ios.json" --platform-version "9.3" --platform-name "iOS" --browser-name "Safari" --full-reset --show-ios-log --device-name "iPhone 7" --launch-timeout "90000"

appium_node_config_ios.json:

{
"capabilities":
[
{
"browserName": "Safari",
"platformVersion":"9.3",
"maxInstances": 1,
"platformName":"iOS",
"deviceName":"iPhone 6s"
}
],

"configuration":
{
"cleanUpCycle":2000,
"timeout":30000,
"proxy": "org.openqa.grid.selenium.proxy.DefaultRemoteProxy",
"url":"http://10.37.2.204:4723/wd/hub",
"maxSession": 1,
"port": 4723,
"host": "10.37.2.204",
"register": true,
"registerCycle": 5000,
"hubPort": 44442,
"hubHost": "10.37.10.37"
}
}

[TikhomirovSergey]

It looks like a bug and it is related to #594 #597

[vikramvi]

@TikhomirovSergey issue is still there with BETA9 as well.

@fionazj any workaround you found ?

[TikhomirovSergey]

appium/appium#8916

[TikhomirovSergey]

The bug was fixed at #682. For now it is recommended to use older selenium server. The fix is going to be available in 5.0.0 soon.

[olyv]

Hi,
can you guys please advise if there is an existing mapping of selenium server to appium java client version?

I am asking because I see "GridException: Cannot extract a capabilities" for a combination of appium java-client 6.1.0 and selenium 3.6.0. I assume the nature of the issue is the same as described in this thread.

[mykola-mokhnach]

One should always use the selenium version, which is set in the gradle config:

java-client/build.gradle

Line 53 in 3c05402

ext.seleniumVersion = '3.13.0'