appium: [1.6.3] A session is either terminated or not started

The problem

Hey guys, I’ve been getting this issue quite frequently when running tests on appium via webdriverIO on my Note 4. Its been getting quite frequent which is causing my tests to time out, hang or fail: ERROR: A session is either terminated or not started.

I’m not sure how to resolve this issue.

I think this might be a chromedriver issue, as i have this in the following logs.

[Chromedriver] ProxyRequestError: Could not proxy command to remote server. Original error: Error: connect ECONNREFUSED 127.0.0.1:8000
    at JWProxy.proxy$ (../../../lib/jsonwp-proxy/proxy.js:126:13)
    at tryCatch (C:\Users\Rambo\AppData\Roaming\npm\node_modules\appium\node_modules\babel-runtime\regenerator\runtime.js:67:40)
    at GeneratorFunctionPrototype.invoke [as _invoke] (C:\Users\Rambo\AppData\Roaming\npm\node_modules\appium\node_modules\babel-runtime\regenerator\runtime.js:315:22)
    at GeneratorFunctionPrototype.prototype.(anonymous function) [as throw] (C:\Users\Rambo\AppData\Roaming\npm\node_modules\appium\node_modules\babel-runtime\regenerator\runtime.js:100:21)
    at GeneratorFunctionPrototype.invoke (C:\Users\Rambo\AppData\Roaming\npm\node_modules\appium\node_modules\babel-runtime\regenerator\runtime.js:136:37)
 { ProxyRequestError: Could not proxy command to remote server. Original error: Error: connect ECONNREFUSED 127.0.0.1:8000
    at JWProxy.proxy$ (../../../lib/jsonwp-proxy/proxy.js:126:13)
    at tryCatch (C:\Users\Rambo\AppData\Roaming\npm\node_modules\appium\node_modules\babel-runtime\regenerator\runtime.js:67:40)
    at GeneratorFunctionPrototype.invoke [as _invoke] (C:\Users\Rambo\AppData\Roaming\npm\node_modules\appium\node_modules\babel-runtime\regenerator\runtime.js:315:22)
    at GeneratorFunctionPrototype.prototype.(anonymous function) [as throw] (C:\Users\Rambo\AppData\Roaming\npm\node_modules\appium\node_modules\babel-runtime\regenerator\runtime.js:100:21)
    at GeneratorFunctionPrototype.invoke (C:\Users\Rambo\AppData\Roaming\npm\node_modules\appium\node_modules\babel-runtime\regenerator\runtime.js:136:37)
  jsonwp: 
   { Error: connect ECONNREFUSED 127.0.0.1:8000
       at Object.exports._errnoException (util.js:1026:11)
       at exports._exceptionWithHostPort (util.js:1049:20)
       at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1090:14)
     code: 'ECONNREFUSED',
     errno: 'ECONNREFUSED',
     syscall: 'connect',
     address: '127.0.0.1',
     port: 8000 } }

Environment

  • Appium version: 1.6.3
  • Desktop OS/version used to run Appium: Windows 10 - 64 bit
  • Node.js version: 7.0.0
  • Npm version: 4.3.0
  • Mobile platform/version under test: Android 6.0.1
  • Real device or emulator/simulator: Samsung Note 4.
  • Appium CLI

Link to Appium logs

The full log:

https://gist.github.com/johnRambo2k14/5d47195974fbeca380f1eb83d2e41071

About this issue

  • Original URL
  • State: closed
  • Created 7 years ago
  • Reactions: 1
  • Comments: 24 (1 by maintainers)

Most upvoted comments

I encounter this kind of question,finally i solve it.First time i set newCommandTimeout: “4000” to “newCommandTimeout”: “400000”,after i return to 4000 the Exception had solved.

I wouldn’t exactly call this a fix lol

The “newCommandTimeout” here is set to 0.

In doc, the value stands for “How long (in seconds) Appium will wait for a new command from the client before assuming the client quit and ending the session”. So you can set a bigger one, e.g. 60.

This capability when set to 0 means it has no timeout so that can’t be the issue.

I have the same issue as above, same error

when Appium takes a screenshot, it crashes.

Here’s an example from my instance of the bug, I have filtered out only the session related lines and this is the logs from the beginning of the session to the end.

[HTTP] --> GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/orientation
[debug] [JSONWP Proxy] Matched '/wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/orientation' to command name 'getOrientation'
[debug] [JSONWP Proxy] Proxying [GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/orientation] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/orientation] with body: {}
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : \"PORTRAIT\",\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 0\n}"
[JSONWP Proxy] Replacing sessionId 08D4562B-090B-447D-9E06-2B1A2B0A51CF with 3e51b914-4a13-44d5-86ac-507c00ad3435
[HTTP] <-- GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/orientation 200 14 ms - 82
[HTTP] --> POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/url
[HTTP] --> POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync
[debug] [JSONWP Proxy] Proxying [GET /alert/text] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/alert/text] with no body
[HTTP] <-- POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/url 200 3417 ms - 14
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 27\n}"
[debug] [JSONWP Proxy] Proxying [POST /elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/elements] with body: {"using":"class name","value":"XCUIElementTypeScrollView","countOnly":false}
[debug] [JSONWP Proxy] Got response with status 200: {"value":[{"ELEMENT":"1A000000-0000-0000-2656-010000000000"}],"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[debug] [JSONWP Proxy] Proxying [POST /element/1A000000-0000-0000-2656-010000000000/elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/element/1A000000-0000-0000-2656-010000000000/elements] with body: {"using":"class name","value":"XCUIElementTypeTextView","countOnly":true}
[debug] [JSONWP Proxy] Got response with status 200: {"value":{"count":0},"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[HTTP] <-- POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync 200 6008 ms - 20
[HTTP] --> POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync
[debug] [JSONWP Proxy] Proxying [GET /alert/text] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/alert/text] with no body
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 27\n}"
[debug] [JSONWP Proxy] Proxying [POST /elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/elements] with body: {"using":"class name","value":"XCUIElementTypeScrollView","countOnly":false}
[debug] [JSONWP Proxy] Got response with status 200: {"value":[{"ELEMENT":"1A000000-0000-0000-2656-010000000000"}],"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[debug] [JSONWP Proxy] Proxying [POST /element/1A000000-0000-0000-2656-010000000000/elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/element/1A000000-0000-0000-2656-010000000000/elements] with body: {"using":"class name","value":"XCUIElementTypeTextView","countOnly":true}
[debug] [JSONWP Proxy] Got response with status 200: {"value":{"count":0},"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[HTTP] <-- POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync 200 2527 ms - 20
[HTTP] --> POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync
[debug] [JSONWP Proxy] Proxying [GET /alert/text] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/alert/text] with no body
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 27\n}"
[debug] [JSONWP Proxy] Proxying [POST /elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/elements] with body: {"using":"class name","value":"XCUIElementTypeScrollView","countOnly":false}
[debug] [JSONWP Proxy] Got response with status 200: {"value":[{"ELEMENT":"1A000000-0000-0000-2656-010000000000"}],"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[debug] [JSONWP Proxy] Proxying [POST /element/1A000000-0000-0000-2656-010000000000/elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/element/1A000000-0000-0000-2656-010000000000/elements] with body: {"using":"class name","value":"XCUIElementTypeTextView","countOnly":true}
[debug] [JSONWP Proxy] Got response with status 200: {"value":{"count":0},"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[HTTP] <-- POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync 200 2489 ms - 20
[HTTP] --> POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync
[debug] [JSONWP Proxy] Proxying [GET /alert/text] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/alert/text] with no body
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 27\n}"
[debug] [JSONWP Proxy] Proxying [POST /elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/elements] with body: {"using":"class name","value":"XCUIElementTypeScrollView","countOnly":false}
[debug] [JSONWP Proxy] Got response with status 200: {"value":[{"ELEMENT":"1A000000-0000-0000-2656-010000000000"}],"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[debug] [JSONWP Proxy] Proxying [POST /element/1A000000-0000-0000-2656-010000000000/elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/element/1A000000-0000-0000-2656-010000000000/elements] with body: {"using":"class name","value":"XCUIElementTypeTextView","countOnly":true}
[debug] [JSONWP Proxy] Got response with status 200: {"value":{"count":0},"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[HTTP] <-- POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync 200 2511 ms - 20
[HTTP] --> POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync
[debug] [JSONWP Proxy] Proxying [GET /alert/text] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/alert/text] with no body
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 27\n}"
[debug] [JSONWP Proxy] Proxying [POST /elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/elements] with body: {"using":"class name","value":"XCUIElementTypeScrollView","countOnly":false}
[debug] [JSONWP Proxy] Got response with status 200: {"value":[{"ELEMENT":"1A000000-0000-0000-2656-010000000000"}],"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[debug] [JSONWP Proxy] Proxying [POST /element/1A000000-0000-0000-2656-010000000000/elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/element/1A000000-0000-0000-2656-010000000000/elements] with body: {"using":"class name","value":"XCUIElementTypeTextView","countOnly":true}
[debug] [JSONWP Proxy] Got response with status 200: {"value":{"count":0},"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[HTTP] <-- POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync 200 2460 ms - 621
[HTTP] --> GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/source
[debug] [JSONWP Proxy] Proxying [GET /alert/text] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/alert/text] with no body
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 27\n}"
[debug] [JSONWP Proxy] Proxying [POST /elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/elements] with body: {"using":"class name","value":"XCUIElementTypeScrollView","countOnly":false}
[debug] [JSONWP Proxy] Got response with status 200: {"value":[{"ELEMENT":"1A000000-0000-0000-2656-010000000000"}],"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[debug] [JSONWP Proxy] Proxying [POST /element/1A000000-0000-0000-2656-010000000000/elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/element/1A000000-0000-0000-2656-010000000000/elements] with body: {"using":"class name","value":"XCUIElementTypeTextView","countOnly":true}
[debug] [JSONWP Proxy] Got response with status 200: {"value":{"count":0},"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[HTTP] <-- GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/source 200 2535 ms - 450838
[HTTP] --> GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/url
[HTTP] <-- GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/url 200 15 ms - 37
[HTTP] --> POST /wd/hub/session/08e92283-00a8-40e6-8826-d824c54c9376/elements
[debug] [GENERIC] Encountered internal error running command: NoSuchDriverError: A session is either terminated or not started
[HTTP] <-- POST /wd/hub/session/08e92283-00a8-40e6-8826-d824c54c9376/elements 404 27 ms - 6489

[HTTP] --> DELETE /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435
[Appium] Removing session 3e51b914-4a13-44d5-86ac-507c00ad3435 from our master session list
[debug] [JSONWP Proxy] Matched '/session/3e51b914-4a13-44d5-86ac-507c00ad3435' to command name 'deleteSession'
[debug] [JSONWP Proxy] Proxying [DELETE /session/3e51b914-4a13-44d5-86ac-507c00ad3435] to [DELETE http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF] with no body
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"CB73E933-E58B-49EB-A29A-A35B370B7887\",\n  \"status\" : 0\n}"
[debug] [XCUITest] In a web session. Removing remote debugger
[debug] [W3C] But deleting session, so not returning
[HTTP] <-- DELETE /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435 200 1448 ms - 14

As you can see the line which errors is: [HTTP] --> POST /wd/hub/session/08e92283-00a8-40e6-8826-d824c54c9376/elements where the driver tries to POST to an incorrect session. The session it tries to POST to is not mentioned anywhere else in the log.

Also this happens about 15% of the time. This bug has occurred for me on the drivers: XCUITest, UiAutomator and UiAutomator2.

Here are the capabilities from the session above

{  
   "capabilities":{  
      "webStorageEnabled":false,
      "locationContextEnabled":false,
      "browserName":"Safari",
      "platform":"MAC",
      "javascriptEnabled":true,
      "databaseEnabled":false,
      "takesScreenshot":true,
      "networkConnectionEnabled":false,
      "platformName":"iOS",
      "nativeWebTap":true,
      "deviceName":"iPad Air",
      "udid":"3F3E502B-F1F9-4D49-8B3D-9776CB4D9F94",
      "automationName":"XCUITest",
      "showSafariConsoleLog":true,
      "clearSystemFiles":true,
      "wdaLaunchTimeout":300000,
      "newCommandTimeout":0,
      "platformVersion":"11.3"
   }
}

Additional Information: This only happens when trying to use find elements soon after the driver has initialised in this example approximately 23 seconds had elapsed between the session being created to the invalid POST request.

Is it possible to get this issue reopened as I think this is a genuine issue. –

The “newCommandTimeout” here is set to 0.

In doc, the value stands for “How long (in seconds) Appium will wait for a new command from the client before assuming the client quit and ending the session”. So you can set a bigger one, e.g. 60.

Here’s an example from my instance of the bug, I have filtered out only the session related lines and this is the logs from the beginning of the session to the end.

[HTTP] --> GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/orientation
[debug] [JSONWP Proxy] Matched '/wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/orientation' to command name 'getOrientation'
[debug] [JSONWP Proxy] Proxying [GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/orientation] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/orientation] with body: {}
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : \"PORTRAIT\",\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 0\n}"
[JSONWP Proxy] Replacing sessionId 08D4562B-090B-447D-9E06-2B1A2B0A51CF with 3e51b914-4a13-44d5-86ac-507c00ad3435
[HTTP] <-- GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/orientation 200 14 ms - 82
[HTTP] --> POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/url
[HTTP] --> POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync
[debug] [JSONWP Proxy] Proxying [GET /alert/text] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/alert/text] with no body
[HTTP] <-- POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/url 200 3417 ms - 14
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 27\n}"
[debug] [JSONWP Proxy] Proxying [POST /elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/elements] with body: {"using":"class name","value":"XCUIElementTypeScrollView","countOnly":false}
[debug] [JSONWP Proxy] Got response with status 200: {"value":[{"ELEMENT":"1A000000-0000-0000-2656-010000000000"}],"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[debug] [JSONWP Proxy] Proxying [POST /element/1A000000-0000-0000-2656-010000000000/elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/element/1A000000-0000-0000-2656-010000000000/elements] with body: {"using":"class name","value":"XCUIElementTypeTextView","countOnly":true}
[debug] [JSONWP Proxy] Got response with status 200: {"value":{"count":0},"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[HTTP] <-- POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync 200 6008 ms - 20
[HTTP] --> POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync
[debug] [JSONWP Proxy] Proxying [GET /alert/text] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/alert/text] with no body
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 27\n}"
[debug] [JSONWP Proxy] Proxying [POST /elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/elements] with body: {"using":"class name","value":"XCUIElementTypeScrollView","countOnly":false}
[debug] [JSONWP Proxy] Got response with status 200: {"value":[{"ELEMENT":"1A000000-0000-0000-2656-010000000000"}],"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[debug] [JSONWP Proxy] Proxying [POST /element/1A000000-0000-0000-2656-010000000000/elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/element/1A000000-0000-0000-2656-010000000000/elements] with body: {"using":"class name","value":"XCUIElementTypeTextView","countOnly":true}
[debug] [JSONWP Proxy] Got response with status 200: {"value":{"count":0},"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[HTTP] <-- POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync 200 2527 ms - 20
[HTTP] --> POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync
[debug] [JSONWP Proxy] Proxying [GET /alert/text] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/alert/text] with no body
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 27\n}"
[debug] [JSONWP Proxy] Proxying [POST /elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/elements] with body: {"using":"class name","value":"XCUIElementTypeScrollView","countOnly":false}
[debug] [JSONWP Proxy] Got response with status 200: {"value":[{"ELEMENT":"1A000000-0000-0000-2656-010000000000"}],"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[debug] [JSONWP Proxy] Proxying [POST /element/1A000000-0000-0000-2656-010000000000/elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/element/1A000000-0000-0000-2656-010000000000/elements] with body: {"using":"class name","value":"XCUIElementTypeTextView","countOnly":true}
[debug] [JSONWP Proxy] Got response with status 200: {"value":{"count":0},"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[HTTP] <-- POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync 200 2489 ms - 20
[HTTP] --> POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync
[debug] [JSONWP Proxy] Proxying [GET /alert/text] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/alert/text] with no body
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 27\n}"
[debug] [JSONWP Proxy] Proxying [POST /elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/elements] with body: {"using":"class name","value":"XCUIElementTypeScrollView","countOnly":false}
[debug] [JSONWP Proxy] Got response with status 200: {"value":[{"ELEMENT":"1A000000-0000-0000-2656-010000000000"}],"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[debug] [JSONWP Proxy] Proxying [POST /element/1A000000-0000-0000-2656-010000000000/elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/element/1A000000-0000-0000-2656-010000000000/elements] with body: {"using":"class name","value":"XCUIElementTypeTextView","countOnly":true}
[debug] [JSONWP Proxy] Got response with status 200: {"value":{"count":0},"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[HTTP] <-- POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync 200 2511 ms - 20
[HTTP] --> POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync
[debug] [JSONWP Proxy] Proxying [GET /alert/text] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/alert/text] with no body
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 27\n}"
[debug] [JSONWP Proxy] Proxying [POST /elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/elements] with body: {"using":"class name","value":"XCUIElementTypeScrollView","countOnly":false}
[debug] [JSONWP Proxy] Got response with status 200: {"value":[{"ELEMENT":"1A000000-0000-0000-2656-010000000000"}],"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[debug] [JSONWP Proxy] Proxying [POST /element/1A000000-0000-0000-2656-010000000000/elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/element/1A000000-0000-0000-2656-010000000000/elements] with body: {"using":"class name","value":"XCUIElementTypeTextView","countOnly":true}
[debug] [JSONWP Proxy] Got response with status 200: {"value":{"count":0},"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[HTTP] <-- POST /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/execute/sync 200 2460 ms - 621
[HTTP] --> GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/source
[debug] [JSONWP Proxy] Proxying [GET /alert/text] to [GET http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/alert/text] with no body
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"08D4562B-090B-447D-9E06-2B1A2B0A51CF\",\n  \"status\" : 27\n}"
[debug] [JSONWP Proxy] Proxying [POST /elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/elements] with body: {"using":"class name","value":"XCUIElementTypeScrollView","countOnly":false}
[debug] [JSONWP Proxy] Got response with status 200: {"value":[{"ELEMENT":"1A000000-0000-0000-2656-010000000000"}],"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[debug] [JSONWP Proxy] Proxying [POST /element/1A000000-0000-0000-2656-010000000000/elements] to [POST http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF/element/1A000000-0000-0000-2656-010000000000/elements] with body: {"using":"class name","value":"XCUIElementTypeTextView","countOnly":true}
[debug] [JSONWP Proxy] Got response with status 200: {"value":{"count":0},"sessionId":"08D4562B-090B-447D-9E06-2B1A2B0A51CF","status":0}
[HTTP] <-- GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/source 200 2535 ms - 450838
[HTTP] --> GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/url
[HTTP] <-- GET /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435/url 200 15 ms - 37
[HTTP] --> POST /wd/hub/session/08e92283-00a8-40e6-8826-d824c54c9376/elements
[debug] [GENERIC] Encountered internal error running command: NoSuchDriverError: A session is either terminated or not started
[HTTP] <-- POST /wd/hub/session/08e92283-00a8-40e6-8826-d824c54c9376/elements 404 27 ms - 6489

[HTTP] --> DELETE /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435
[Appium] Removing session 3e51b914-4a13-44d5-86ac-507c00ad3435 from our master session list
[debug] [JSONWP Proxy] Matched '/session/3e51b914-4a13-44d5-86ac-507c00ad3435' to command name 'deleteSession'
[debug] [JSONWP Proxy] Proxying [DELETE /session/3e51b914-4a13-44d5-86ac-507c00ad3435] to [DELETE http://localhost:4829/session/08D4562B-090B-447D-9E06-2B1A2B0A51CF] with no body
[debug] [JSONWP Proxy] Got response with status 200: "{\n  \"value\" : {\n\n  },\n  \"sessionId\" : \"CB73E933-E58B-49EB-A29A-A35B370B7887\",\n  \"status\" : 0\n}"
[debug] [XCUITest] In a web session. Removing remote debugger
[debug] [W3C] But deleting session, so not returning
[HTTP] <-- DELETE /wd/hub/session/3e51b914-4a13-44d5-86ac-507c00ad3435 200 1448 ms - 14

As you can see the line which errors is: [HTTP] --> POST /wd/hub/session/08e92283-00a8-40e6-8826-d824c54c9376/elements where the driver tries to POST to an incorrect session. The session it tries to POST to is not mentioned anywhere else in the log.

Also this happens about 15% of the time. This bug has occurred for me on the drivers: XCUITest, UiAutomator and UiAutomator2.

Here are the capabilities from the session above

{  
   "capabilities":{  
      "webStorageEnabled":false,
      "locationContextEnabled":false,
      "browserName":"Safari",
      "platform":"MAC",
      "javascriptEnabled":true,
      "databaseEnabled":false,
      "takesScreenshot":true,
      "networkConnectionEnabled":false,
      "platformName":"iOS",
      "nativeWebTap":true,
      "deviceName":"iPad Air",
      "udid":"3F3E502B-F1F9-4D49-8B3D-9776CB4D9F94",
      "automationName":"XCUITest",
      "showSafariConsoleLog":true,
      "clearSystemFiles":true,
      "wdaLaunchTimeout":300000,
      "newCommandTimeout":0,
      "platformVersion":"11.3"
   }
}

Additional Information: This only happens when trying to use find elements soon after the driver has initialised in this example approximately 23 seconds had elapsed between the session being created to the invalid POST request.

Is it possible to get this issue reopened as I think this is a genuine issue.

closing since no response. also the screenshot error is a red herring; that’s saying it couldn’t take a screenshot after ending the session. but of course you can’t!

@mykola-mokhnach , hmm, i have this in the console though,

{ sessionId: 'ceb8dcce-7c0d-4591-8fb2-fa52c404c4af',
  value: { ELEMENT: '0.39025192720192314-1' },
  selector: '//*[@id=\'username\']/input',
  _status: 0 }
[14:05:38]  COMMAND     POST     "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af/elements"
[14:05:38]  DATA                {"using":"xpath","value":"//*[@id='username']/input"}
[14:05:38]  RESULT              [{"ELEMENT":"0.39025192720192314-1"}]
[14:05:38]  COMMAND     POST     "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af/element/0.39025192720192314-1/clear"
[14:05:38]  DATA                {}
[14:05:38]  RESULT              null
[14:05:38]  COMMAND     POST     "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af/element/0.39025192720192314-1/value"
[14:05:38]  DATA                {"value":["A","l","i"]}
[14:05:39]  RESULT              null
[14:05:39]  COMMAND     POST     "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af/elements"
[14:05:39]  DATA                {"using":"xpath","value":"//*[@id='login']"}
[14:05:39]  RESULT              [{"ELEMENT":"0.39025192720192314-3"}]
[14:05:39]  COMMAND     POST     "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af/element"
[14:05:39]  DATA                {"using":"xpath","value":"//*[@id='login']"}
[14:05:39]  RESULT              {"ELEMENT":"0.39025192720192314-3"}
[14:05:39]  COMMAND     POST     "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af/element/0.39025192720192314-3/click"
[14:05:39]  DATA                {}
[14:05:39]  RESULT              null
[14:05:39]  COMMAND     POST     "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af/elements"
[14:05:39]  DATA                {"using":"xpath","value":"//*[@class='toast-message']"}
[14:05:39]  RESULT              []
[14:05:39]  COMMAND     POST     "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af/elements"
[14:05:39]  DATA                {"using":"xpath","value":"//*[@class='toast-message']"}
[14:05:41]  RESULT              []
[14:05:41]  COMMAND     POST     "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af/elements"
[14:05:41]  DATA                {"using":"xpath","value":"//*[@class='toast-message']"}
[14:05:43]  RESULT              []
[14:05:43]  COMMAND     POST     "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af/elements"
[14:05:43]  DATA                {"using":"xpath","value":"//*[@class='toast-message']"}
[14:05:46]  RESULT              []
[14:05:46]  COMMAND     POST     "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af/elements"
[14:05:46]  DATA                {"using":"xpath","value":"//*[@class='toast-message']"}
[14:05:47]  RESULT              []
[14:05:47]  COMMAND     POST     "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af/elements"
[14:05:47]  DATA                {"using":"xpath","value":"//*[@class='toast-message']"}
[14:05:49]  COMMAND     GET      "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af/screenshot"
[14:05:49]  DATA                {}
[14:05:50]  RESULT              []
[14:05:59]  COMMAND     DELETE   "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af"
[14:05:59]  DATA                {}
[14:07:19]      Failed to take screenshot on reject:     {"message":"A session is either terminated or not started","type":"RuntimeError","seleniumStack":{"status":6,"type":"NoSuchDriver","message":"A session is either terminated or not started","orgStatusMessage":"A session is either terminated or not started"}}
ERROR: A session is either terminated or not started
[14:07:29] fbipartyvan.android.6_0.android-debug_apk
COMMAND DELETE   "/wd/hub/session/ceb8dcce-7c0d-4591-8fb2-fa52c404c4af"
Error[14:07:29]
DATA            {}
ERROR: A session is either terminated or not started

Error

npm ERR! Windows_NT 10.0.14393
npm ERR! argv "C:\\Program Files\\nodejs\\node.exe" "C:\\Program Files\\nodejs\\node_modules\\npm\\bin\\npm-cli.js" "run" "e2e" "--" "--suite" "login"
npm ERR! node v7.0.0
npm ERR! npm  v3.10.8
npm ERR! code ELIFECYCLE
npm ERR! ionic-hello-world@ e2e: `npm run build-e2e && wdio ./e2e/dist/wdio.conf.js "--suite" "login"`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the ionic-hello-world@ e2e script 'npm run build-e2e && wdio ./e2e/dist/wdio.conf.js "--suite" "login"'.
npm ERR! Make sure you have the latest version of node.js and npm installed.
npm ERR! If you do, this is most likely a problem with the ionic-hello-world package,
npm ERR! not with npm itself.
npm ERR! Tell the author that this fails on your system:
npm ERR!     npm run build-e2e && wdio ./e2e/dist/wdio.conf.js "--suite" "login"
npm ERR! You can get information on how to open an issue for this project with:
npm ERR!     npm bugs ionic-hello-world
npm ERR! Or if that isnt available, you can get their info via:
npm ERR!     npm owner ls ionic-hello-world
npm ERR! There is likely additional logging output above.

npm ERR! Please include the following file with any support request:
npm ERR!     c:\Users\Rambo\Documents\mercury\npm-debug.log

The above shows entering the string “Ali” into the input field and clicking on the login button with the id “login”, then Its looking for the element with the class “'toast-message” which it cant find, so that’s why it keeps repeating itself, which is expected behavior as its waiting for the element to appear, so it throws a fail but it tries to take the screenshot which is where it fails.

The npm debug log: https://gist.github.com/johnRambo2k14/d1b9a0af9caa8247e59e7b5422e7c642