Espesso "New Command Timeout" during normal test execution

Tests are running normally, passing one after another, then, the session closes with this message

[BaseDriver] Shutting down because we waited 1000 seconds for a command
[Appium] Closing session, cause was ‘New Command Timeout of 1000 seconds expired. Try customizing the timeout using the ‘newCommandTimeout’ desired capability’
[Appium] Removing session ‘25517166-3df9-4bbc-89de-b6a079831fc6’ from our master session list
[debug] [Espresso] Deleting espresso session
debug] [Espresso] Deleting Espresso server session

The problem is that the newCommandTimeout shouldn’t happen as tests execute commands and get responses as usual right before timeout.
The failure says there were “no commands in last 1000s (1.5h)”, but there were too many successful commands during that time.

Before that, many tests are passing as usual, but after that exception, 3 tests are failing with that output, then, tests continuing to run many hours and pass, the issue doesn’t happen again.
That shut-down happens almost after 30m at the beginning of tests execution.

Android version: Appium v1.20.2
driver version: EspressoDriver (v1.41.0)
capabilities:

Creating session with W3C capabilities: {
“alwaysMatch”: {
“appium:espressoBuildConfig”: “./config/espressoBuildConfig.json”,
“appium:locationContextEnabled”: true,
“platformName”: “android”,
“appium:adbExecTimeout”: 1200000,
“appium:app”: “/qa/config/app/prod.apk”,
“appium:appActivity”: “com.prod.android.MainActivity”,
“appium:appPackage”: “com.prod.android.dev”,
“appium:automationName”: “Espresso”,
“appium:deviceName”: “nexus_6p_11.0”,
“appium:newCommandTimeout”: 1000,
“appium:platformVersion”: “11.0”,
“appium:systemPort”: 8201,
“appium:udid”: “emulator-5554”
},
“firstMatch”: [
{}
]
}

The next are output logs before that shutdown, here we see that the execution was working fine before that shutdown.

Logs

06:05:36 [LOG::INFO] click By.xpath: //[@view-tag = ‘item_search’ and @visible = ‘true’]
2021-04-29 06:05:36:423 - [HTTP] → POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/element
2021-04-29 06:05:36:423 - [HTTP] {“using”:“xpath”,“value”:"//
[@view-tag = ‘item_search’ and @visible = ‘true’]“}
2021-04-29 06:05:36:423 - [W3C (431bf992)] Driver proxy active, passing request on via HTTP proxy
2021-04-29 06:05:36:424 - [debug] [WD Proxy] Matched ‘/wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/element’ to command name ‘findElement’
2021-04-29 06:05:36:424 - [debug] [WD Proxy] Proxying [POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/element] to [POST http://localhost:8201/session/53e14db3-def1-4633-b1eb-eca2f5a60042/element] with body: {“using”:“xpath”,“value”:”//[@view-tag = ‘item_search’ and @visible = ‘true’]“}
2021-04-29 06:05:36:545 - [debug] [WD Proxy] Got response with status 200: {“id”:“5513d8cd-1b1b-4230-b940-9d77bfd429b4”,“sessionId”:“53e14db3-def1-4633-b1eb-eca2f5a60042”,“value”:{“ELEMENT”:“223c7ad7-7e0b-48e2-adb0-f6e79cf0b378”}}
2021-04-29 06:05:36:545 - [WD Proxy] Replacing sessionId 53e14db3-def1-4633-b1eb-eca2f5a60042 with 431bf992-015b-49ec-ae59-c955f9ee64f0
2021-04-29 06:05:36:547 - [HTTP] ← POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/element 200 123 ms - 232
2021-04-29 06:05:36:548 - [HTTP]
2021-04-29 06:05:36:549 - [HTTP] → POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/element/223c7ad7-7e0b-48e2-adb0-f6e79cf0b378/click
2021-04-29 06:05:36:550 - [HTTP] {“id”:“223c7ad7-7e0b-48e2-adb0-f6e79cf0b378”}
2021-04-29 06:05:36:550 - [W3C (431bf992)] Driver proxy active, passing request on via HTTP proxy
2021-04-29 06:05:36:551 - [debug] [WD Proxy] Matched ‘/wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/element/223c7ad7-7e0b-48e2-adb0-f6e79cf0b378/click’ to command name ‘click’
2021-04-29 06:05:36:551 - [debug] [WD Proxy] Proxying [POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/element/223c7ad7-7e0b-48e2-adb0-f6e79cf0b378/click] to [POST http://localhost:8201/session/53e14db3-def1-4633-b1eb-eca2f5a60042/element/223c7ad7-7e0b-48e2-adb0-f6e79cf0b378/click] with body: {“id”:“223c7ad7-7e0b-48e2-adb0-f6e79cf0b378”}
2021-04-29 06:05:36:844 - [debug] [WD Proxy] Got response with status 200: {“id”:“17aa27d6-399e-4170-93bd-3aefee4f20fc”,“sessionId”:“53e14db3-def1-4633-b1eb-eca2f5a60042”,“value”:null}
2021-04-29 06:05:36:845 - [WD Proxy] Replacing sessionId 53e14db3-def1-4633-b1eb-eca2f5a60042 with 431bf992-015b-49ec-ae59-c955f9ee64f0
2021-04-29 06:05:36:845 - [HTTP] ← POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/element/223c7ad7-7e0b-48e2-adb0-f6e79cf0b378/click 200 296 ms - 109
2021-04-29 06:05:36:845 - [HTTP]
2021-04-29 06:05:36:955 - [HTTP] → POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/elements
2021-04-29 06:05:36:955 - [HTTP] {“using”:“xpath”,“value”:”//
[@view-tag = ‘search_button’ and @visible = ‘true’]“}
2021-04-29 06:05:36:956 - [W3C (431bf992)] Driver proxy active, passing request on via HTTP proxy
2021-04-29 06:05:36:957 - [debug] [WD Proxy] Matched ‘/wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/elements’ to command name ‘findElements’
2021-04-29 06:05:36:958 - [debug] [WD Proxy] Proxying [POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/elements] to [POST http://localhost:8201/session/53e14db3-def1-4633-b1eb-eca2f5a60042/elements] with body: {“using”:“xpath”,“value”:”//[@view-tag = ‘search_button’ and @visible = ‘true’]“}
2021-04-29 06:05:37:117 - [debug] [WD Proxy] Got response with status 200: {“id”:“65bc83d4-4faf-4a64-aee6-77290cdc9ba1”,“sessionId”:“53e14db3-def1-4633-b1eb-eca2f5a60042”,“value”:[]}
2021-04-29 06:05:37:117 - [WD Proxy] Replacing sessionId 53e14db3-def1-4633-b1eb-eca2f5a60042 with 431bf992-015b-49ec-ae59-c955f9ee64f0
2021-04-29 06:05:37:118 - [HTTP] ← POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/elements 200 162 ms - 107
2021-04-29 06:05:37:118 - [HTTP]
2021-04-29 06:05:37:220 - [HTTP] → POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/elements
2021-04-29 06:05:37:220 - [HTTP] {“using”:“xpath”,“value”:”//
[@view-tag = ‘search_button’ and @visible = ‘true’]“}
2021-04-29 06:05:37:220 - [W3C (431bf992)] Driver proxy active, passing request on via HTTP proxy
2021-04-29 06:05:37:220 - [debug] [WD Proxy] Matched ‘/wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/elements’ to command name ‘findElements’
2021-04-29 06:05:37:220 - [debug] [WD Proxy] Proxying [POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/elements] to [POST http://localhost:8201/session/53e14db3-def1-4633-b1eb-eca2f5a60042/elements] with body: {“using”:“xpath”,“value”:”//[@view-tag = ‘search_button’ and @visible = ‘true’]“}
2021-04-29 06:05:37:449 - [debug] [WD Proxy] Got response with status 200: {“id”:“f40f7479-a9de-482e-bdb8-cbc7b7fdab54”,“sessionId”:“53e14db3-def1-4633-b1eb-eca2f5a60042”,“value”:[]}
2021-04-29 06:05:37:449 - [WD Proxy] Replacing sessionId 53e14db3-def1-4633-b1eb-eca2f5a60042 with 431bf992-015b-49ec-ae59-c955f9ee64f0
2021-04-29 06:05:37:449 - [HTTP] ← POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/elements 200 229 ms - 107
2021-04-29 06:05:37:449 - [HTTP]
2021-04-29 06:05:37:551 - [HTTP] → POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/elements
2021-04-29 06:05:37:552 - [HTTP] {“using”:“xpath”,“value”:”//
[@view-tag = ‘search_button’ and @visible = ‘true’]“}
2021-04-29 06:05:37:552 - [W3C (431bf992)] Driver proxy active, passing request on via HTTP proxy
2021-04-29 06:05:37:553 - [debug] [WD Proxy] Matched ‘/wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/elements’ to command name ‘findElements’
2021-04-29 06:05:37:554 - [debug] [WD Proxy] Proxying [POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/elements] to [POST http://localhost:8201/session/53e14db3-def1-4633-b1eb-eca2f5a60042/elements] with body: {“using”:“xpath”,“value”:”//[@view-tag = ‘search_button’ and @visible = ‘true’]"}
2021-04-29 06:05:38:268 - [BaseDriver] Shutting down because we waited 1000 seconds for a command
2021-04-29 06:05:38:268 - [Appium] Closing session, cause was ‘New Command Timeout of 1000 seconds expired. Try customizing the timeout using the ‘newCommandTimeout’ desired capability’
2021-04-29 06:05:38:268 - [Appium] Removing session ‘25517166-3df9-4bbc-89de-b6a079831fc6’ from our master session list
2021-04-29 06:05:38:268 - [debug] [Espresso] Deleting espresso session
2021-04-29 06:05:38:269 - [debug] [Espresso] Deleting Espresso server session
2021-04-29 06:05:38:269 - [Espresso] Did not get confirmation Espresso deleteSession worked; Error was: UnknownError: An unknown server-side error occurred while processing the command. Original error: ‘DELETE /’ cannot be proxied to Espresso server because the instrumentation process has crashed. Check the Appium server log and the logcat output for more details
2021-04-29 06:05:38:269 - [debug] [ADB] Running ‘/root/platform-tools/adb -P 5037 -s emulator-5554 shell am force-stop com.prod.android.dev’
2021-04-29 06:05:38:747 - [debug] [Espresso] FULL_RESET set to ‘true’, Uninstalling ‘com.prod.android.dev’
2021-04-29 06:05:38:747 - [debug] [ADB] Uninstalling com.prod.android.dev
2021-04-29 06:05:38:747 - [debug] [ADB] Getting install status for com.prod.android.dev
2021-04-29 06:05:38:747 - [debug] [ADB] Running ‘/root/platform-tools/adb -P 5037 -s emulator-5554 shell dumpsys package com.prod.android.dev’
2021-04-29 06:05:38:788 - [debug] [Espresso] [Instrumentation] INSTRUMENTATION_RESULT: shortMsg=Process crashed.
2021-04-29 06:05:38:788 - [debug] [Espresso] INSTRUMENTATION_CODE: 0
2021-04-29 06:05:39:201 - [WD Proxy] socket hang up
2021-04-29 06:05:39:201 - [debug] [W3C (431bf992)] Encountered internal error running command: Error: Could not proxy. Proxy error: Could not proxy command to the remote server. Original error: socket hang up
2021-04-29 06:05:39:202 - [debug] [W3C (431bf992)] at doJwpProxy (/usr/lib/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:481:13)
2021-04-29 06:05:39:202 - [debug] [W3C (431bf992)] at asyncHandler (/usr/lib/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:253:9)
An unknown server-side error occurred while processing the command. Original error: Could not proxy. Proxy error: Could not proxy command to the remote server. Original error: socket hang up
Build info: version: ‘3.141.59’, revision: ‘e82be7d358’, time: ‘2018-11-14T08:17:03’
System info: host: ‘host’, ip: ‘172.17.0.3’, os.name: ‘Linux’, os.arch: ‘amd64’, os.version: ‘4.15.0-142-generic’, java.version: ‘11.0.9.1’
Driver info: io.appium.java_client.android.AndroidDriver
06:05:39 [LOG::ERROR] New Search Page was not opened.
Capabilities {adbExecTimeout: 1200000, app: /store/app/prod…, appActivity: com.prod.android…, appPackage: com.prod.android…, automationName: Espresso, deviceName: nexus_6p_11.0, espressoBuildConfig: /store/espressoBuildCon…, javascriptEnabled: true, locationContextEnabled: true, newCommandTimeout: 1000, platform: ANDROID, platformName: Android, platformVersion: 11.0, systemPort: 8201, udid: emulator-5554}
Session ID: 431bf992-015b-49ec-ae59-c955f9ee64f0
*** Element info: {Using=xpath, value=//
[@view-tag = ‘search_button’ and @visible = ‘true’]}
06:05:39 [LOG::INFO] isElementDisplayed: false
2021-04-29 06:05:39:203 - [HTTP] ← POST /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/elements 500 1651 ms - 697
2021-04-29 06:05:39:203 - [HTTP]
2021-04-29 06:05:39:205 - [HTTP] → GET /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/screenshot
2021-04-29 06:05:39:205 - [HTTP] {}
2021-04-29 06:05:39:206 - [W3C (431bf992)] Driver proxy active, passing request on via HTTP proxy
2021-04-29 06:05:39:206 - [debug] [WD Proxy] Matched ‘/wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/screenshot’ to command name ‘getScreenshot’
2021-04-29 06:05:39:206 - [debug] [WD Proxy] Proxying [GET /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/screenshot] to [GET http://localhost:8201/session/53e14db3-def1-4633-b1eb-eca2f5a60042/screenshot] with no body
2021-04-29 06:05:39:214 - [WD Proxy] socket hang up
2021-04-29 06:05:39:215 - [debug] [W3C (431bf992)] Encountered internal error running command: Error: Could not proxy. Proxy error: Could not proxy command to the remote server. Original error: socket hang up
2021-04-29 06:05:39:215 - [debug] [W3C (431bf992)] at doJwpProxy (/usr/lib/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:481:13)
2021-04-29 06:05:39:216 - [debug] [W3C (431bf992)] at asyncHandler (/usr/lib/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:253:9)
Unable to save screenshot
2021-04-29 06:05:39:217 - [HTTP] ← GET /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/screenshot 500 11 ms - 697
2021-04-29 06:05:39:217 - [HTTP]
2021-04-29 06:05:39:218 - [HTTP] → GET /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/source
2021-04-29 06:05:39:218 - [HTTP] {}
2021-04-29 06:05:39:219 - [W3C (431bf992)] Driver proxy active, passing request on via HTTP proxy
2021-04-29 06:05:39:219 - [debug] [WD Proxy] Matched ‘/wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/source’ to command name ‘getPageSource’
2021-04-29 06:05:39:219 - [debug] [WD Proxy] Proxying [GET /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/source] to [GET http://localhost:8201/session/53e14db3-def1-4633-b1eb-eca2f5a60042/source] with no body
2021-04-29 06:05:39:222 - [WD Proxy] socket hang up
2021-04-29 06:05:39:223 - [debug] [W3C (431bf992)] Encountered internal error running command: Error: Could not proxy. Proxy error: Could not proxy command to the remote server. Original error: socket hang up
2021-04-29 06:05:39:223 - [debug] [W3C (431bf992)] at doJwpProxy (/usr/lib/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:481:13)
2021-04-29 06:05:39:223 - [debug] [W3C (431bf992)] at asyncHandler (/usr/lib/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:253:9)
06:05:39 [LOG::INFO] Failed to fetch Page Source: An unknown server-side error occurred while processing the command. Original error: Could not proxy. Proxy error: Could not proxy command to the remote server. Original error: socket hang up
Build info: version: ‘3.141.59’, revision: ‘e82be7d358’, time: ‘2018-11-14T08:17:03’
System info: host: ‘host’, ip: ‘172.17.0.3’, os.name: ‘Linux’, os.arch: ‘amd64’, os.version: ‘4.15.0-142-generic’, java.version: ‘11.0.9.1’
Driver info: io.appium.java_client.android.AndroidDriver
Capabilities {adbExecTimeout: 1200000, app: /store/app/prod…, appActivity: com.prod.android…, appPackage: com.prod.android…, automationName: Espresso, deviceName: nexus_6p_11.0, espressoBuildConfig: /store/espressoBuildCon…, javascriptEnabled: true, locationContextEnabled: true, newCommandTimeout: 1000, platform: ANDROID, platformName: Android, platformVersion: 11.0, systemPort: 8201, udid: emulator-5554}
Session ID: 431bf992-015b-49ec-ae59-c955f9ee64f0202
1-04-29 [attachment] empty content, can’t attach: New Search Page was not opened.06
:05:39:227 - [HTTP] ← GET /wd/hub/session/431bf992-015b-49ec-ae59-c955f9ee64f0/source 500 8 ms - 697
2021-04-29 06:05:39:227 - [HTTP]

(Please confirm that this is an issue to report in to the appropriate place)

Same problem here, any update?

I have the same problem. U can use session override option and do not close the session improperly like force close appium, for me I use Ctrl + C in terminal when I want to stop the test.

Thank you @mykola-mokhnach

The issue was that you mentioned. The active session id and closed session id were not the same.
The issue is fixed now for my case, anyway, I will not expect the current session to be closed when server closes old remaining session, what I will expect is they should be treated separately.

With best regards.