appium-device-farm: Device busy or blocked trouble (2 emulators/14)

@saikrishna321

Sai, look at this issue please Thats reproduced, but rarely During active use for 2 days, I did not see this error even once; now I caught it on two out of three emulators at once, within the same machine/node

Sorry for giving you logs in archive, but he is so big for gist https://drive.google.com/file/d/1mUXjZoYy-1h0EZTlXEtmcbr1nNRMfpOQ/view?usp=sharing

emulator-5554/10.18.141.125 node from pytest side:

[2024-02-27T23:20:26.875Z] automationName: UIAutomator2
[2024-02-27T23:20:26.875Z] platformName: Android
[2024-02-27T23:20:26.875Z] appium:noReset: True
[2024-02-27T23:20:26.875Z] appium:udid: emulator-5554
[2024-02-27T23:20:26.875Z] appium:deviceName: sdk_gphone64_x86_64
[2024-02-27T23:20:26.875Z] appium:clearDeviceLogsOnStart: True
[2024-02-27T23:20:26.875Z] appium:autoGrantPermissions: True
[2024-02-27T23:20:26.875Z] appium:systemPort: 48751
[2024-02-27T23:20:26.875Z] appium:mjpegServerPort: 48801
[2024-02-27T23:20:26.875Z] appium:disableWindowAnimation: True
[2024-02-27T23:20:26.875Z] appium:uiautomator2ServerInstallTimeout: 30000
[2024-02-27T23:20:26.875Z] appium:uiautomator2ServerLaunchTimeout: 40000
[2024-02-27T23:20:26.875Z] appium:uiautomator2ServerReadTimeout: 45000
[2024-02-27T23:20:26.875Z] appium:newCommandTimeout: 600
[2024-02-27T23:20:26.875Z] appium:shouldTerminateApp: True
[2024-02-27T23:20:26.875Z] appium:enforceXPath1: True
[2024-02-27T23:20:26.875Z] appium:filterByHost: 10.18.141.125
[2024-02-27T23:20:26.876Z] DEBUG    24-02-28 01:09:47.652483 Appium.server.is_running = False
[2024-02-27T23:20:26.876Z] Executed command: ssh user@10.18.141.125 "lsof -t -i tcp:48801"
[2024-02-27T23:20:26.876Z] DEBUG    24-02-28 01:09:47.947887 mjpeg port 48801 is not occupied
[2024-02-27T23:20:26.876Z] DEBUG    24-02-28 01:09:47.948143 Close all appium sessions for device emulator-5554 on node ip 10.18.141.125
[2024-02-27T23:20:26.876Z] No session id found for device emulator-5554 and node ip 10.18.141.125
[2024-02-27T23:20:26.876Z] INFO     24-02-28 01:09:47.951401 Attempt 1 to create driver session
[2024-02-27T23:20:26.876Z] ERROR    24-02-28 01:09:52.962954 Message: An unknown server-side error occurred while processing the command. Original error: Unknown error while creating session
[2024-02-27T23:20:26.876Z] Stacktrace:
[2024-02-27T23:20:26.876Z] UnknownError: An unknown server-side error occurred while processing the command. Original error: Unknown error while creating session
[2024-02-27T23:20:26.876Z]     at getResponseForW3CError (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/errors.js:1118:9)
[2024-02-27T23:20:26.876Z]     at asyncHandler (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/protocol.js:491:57)
[2024-02-27T23:20:26.876Z] INFO     24-02-28 01:09:52.963102 Machine: Linux-tests-6; Device: emulator-5554
[2024-02-27T23:20:26.876Z] Executed command: ssh user@10.18.141.125 "adb -s emulator-5554 get-state"
[2024-02-27T23:20:26.876Z] INFO     24-02-28 01:09:53.267389 Device emulator-5554 is connected = False
[2024-02-27T23:20:26.876Z] Sleep 10 seconds before trying again...
[2024-02-27T23:20:26.876Z] No session id found for device emulator-5554 and node ip 10.18.141.125
[2024-02-27T23:20:26.876Z] INFO     24-02-28 01:10:03.280417 Attempt 2 to create driver session
[2024-02-27T23:20:26.876Z] ERROR    24-02-28 01:15:03.321395 Message: An unknown server-side error occurred while processing the command. Original error: {"value":{"error":"unknown error","message":"An unknown server-side error occurred while processing the command. Original error: Device is busy or blocked.. Device request: {\"platform\":\"android\",\"udid\":\"emulator-5554\",\"filterByHost\":\"10.18.141.125\"}","stacktrace":"UnknownError: An unknown server-side error occurred while processing the command. Original error: Device is busy or blocked.. Device request: {\"platform\":\"android\",\"udid\":\"emulator-5554\",\"filterByHost\":\"10.18.141.125\"}\n    at getResponseForW3CError (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/errors.js:1118:9)\n    at asyncHandler (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/protocol.js:491:57)"}}
[2024-02-27T23:20:26.876Z] Stacktrace:
[2024-02-27T23:20:26.876Z] UnknownError: An unknown server-side error occurred while processing the command. Original error: {"value":{"error":"unknown error","message":"An unknown server-side error occurred while processing the command. Original error: Device is busy or blocked.. Device request: {\"platform\":\"android\",\"udid\":\"emulator-5554\",\"filterByHost\":\"10.18.141.125\"}","stacktrace":"UnknownError: An unknown server-side error occurred while processing the command. Original error: Device is busy or blocked.. Device request: {\"platform\":\"android\",\"udid\":\"emulator-5554\",\"filterByHost\":\"10.18.141.125\"}\n    at getResponseForW3CError (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/errors.js:1118:9)\n    at asyncHandler (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/protocol.js:491:57)"}}
[2024-02-27T23:20:26.876Z]     at getResponseForW3CError (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/errors.js:1118:9)
[2024-02-27T23:20:26.876Z]     at asyncHandler (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/protocol.js:491:57)
[2024-02-27T23:20:26.876Z] INFO     24-02-28 01:15:03.321542 Machine: Linux-tests-6; Device: emulator-5554
[2024-02-27T23:20:26.876Z] Executed command: ssh user@10.18.141.125 "adb -s emulator-5554 get-state"
[2024-02-27T23:20:26.876Z] INFO     24-02-28 01:15:03.523611 Device emulator-5554 is connected = False
[2024-02-27T23:20:26.876Z] Sleep 10 seconds before trying again...
[2024-02-27T23:20:26.876Z] No session id found for device emulator-5554 and node ip 10.18.141.125

emulator-5556/10.18.141.125 node from pytest side:

[2024-02-27T23:30:31.267Z] automationName: UIAutomator2
[2024-02-27T23:30:31.267Z] platformName: Android
[2024-02-27T23:30:31.267Z] appium:noReset: True
[2024-02-27T23:30:31.267Z] appium:udid: emulator-5556
[2024-02-27T23:30:31.267Z] appium:deviceName: sdk_gphone64_x86_64
[2024-02-27T23:30:31.267Z] appium:clearDeviceLogsOnStart: True
[2024-02-27T23:30:31.267Z] appium:autoGrantPermissions: True
[2024-02-27T23:30:31.267Z] appium:systemPort: 48752
[2024-02-27T23:30:31.267Z] appium:mjpegServerPort: 48802
[2024-02-27T23:30:31.267Z] appium:disableWindowAnimation: True
[2024-02-27T23:30:31.267Z] appium:uiautomator2ServerInstallTimeout: 30000
[2024-02-27T23:30:31.267Z] appium:uiautomator2ServerLaunchTimeout: 40000
[2024-02-27T23:30:31.267Z] appium:uiautomator2ServerReadTimeout: 45000
[2024-02-27T23:30:31.267Z] appium:newCommandTimeout: 600
[2024-02-27T23:30:31.267Z] appium:shouldTerminateApp: True
[2024-02-27T23:30:31.267Z] appium:enforceXPath1: True
[2024-02-27T23:30:31.267Z] appium:filterByHost: 10.18.141.125
[2024-02-27T23:30:31.267Z] DEBUG    24-02-28 01:11:58.262733 Appium.server.is_running = False
[2024-02-27T23:30:31.267Z] Executed command: ssh user@10.18.141.125 "lsof -t -i tcp:48802"
[2024-02-27T23:30:31.267Z] DEBUG    24-02-28 01:11:58.510878 mjpeg port 48802 is not occupied
[2024-02-27T23:30:31.267Z] DEBUG    24-02-28 01:11:58.511122 Close all appium sessions for device emulator-5556 on node ip 10.18.141.125
[2024-02-27T23:30:31.267Z] No session id found for device emulator-5556 and node ip 10.18.141.125
[2024-02-27T23:30:31.267Z] INFO     24-02-28 01:11:58.513963 Attempt 1 to create driver session
[2024-02-27T23:30:31.267Z] ERROR    24-02-28 01:12:03.519378 Message: An unknown server-side error occurred while processing the command. Original error: Unknown error while creating session
[2024-02-27T23:30:31.267Z] Stacktrace:
[2024-02-27T23:30:31.267Z] UnknownError: An unknown server-side error occurred while processing the command. Original error: Unknown error while creating session
[2024-02-27T23:30:31.267Z]     at getResponseForW3CError (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/errors.js:1118:9)
[2024-02-27T23:30:31.267Z]     at asyncHandler (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/protocol.js:491:57)
[2024-02-27T23:30:31.267Z] INFO     24-02-28 01:12:03.519534 Machine: Linux-tests-6; Device: emulator-5556
[2024-02-27T23:30:31.267Z] Executed command: ssh user@10.18.141.125 "adb -s emulator-5556 get-state"
[2024-02-27T23:30:31.267Z] INFO     24-02-28 01:12:03.715210 Device emulator-5556 is connected = False
[2024-02-27T23:30:31.267Z] Sleep 10 seconds before trying again...
[2024-02-27T23:30:31.267Z] No session id found for device emulator-5556 and node ip 10.18.141.125
[2024-02-27T23:30:31.267Z] INFO     24-02-28 01:12:13.727684 Attempt 2 to create driver session
[2024-02-27T23:30:31.267Z] ERROR    24-02-28 01:20:03.325374 Message: An unknown server-side error occurred while processing the command. Original error: {"value":{"error":"unknown error","message":"An unknown server-side error occurred while processing the command. Original error: Device is busy or blocked.. Device request: {\"platform\":\"android\",\"udid\":\"emulator-5556\",\"filterByHost\":\"10.18.141.125\"}","stacktrace":"UnknownError: An unknown server-side error occurred while processing the command. Original error: Device is busy or blocked.. Device request: {\"platform\":\"android\",\"udid\":\"emulator-5556\",\"filterByHost\":\"10.18.141.125\"}\n    at getResponseForW3CError (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/errors.js:1118:9)\n    at asyncHandler (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/protocol.js:491:57)"}}
[2024-02-27T23:30:31.267Z] Stacktrace:
[2024-02-27T23:30:31.267Z] UnknownError: An unknown server-side error occurred while processing the command. Original error: {"value":{"error":"unknown error","message":"An unknown server-side error occurred while processing the command. Original error: Device is busy or blocked.. Device request: {\"platform\":\"android\",\"udid\":\"emulator-5556\",\"filterByHost\":\"10.18.141.125\"}","stacktrace":"UnknownError: An unknown server-side error occurred while processing the command. Original error: Device is busy or blocked.. Device request: {\"platform\":\"android\",\"udid\":\"emulator-5556\",\"filterByHost\":\"10.18.141.125\"}\n    at getResponseForW3CError (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/errors.js:1118:9)\n    at asyncHandler (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/protocol.js:491:57)"}}
[2024-02-27T23:30:31.267Z]     at getResponseForW3CError (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/errors.js:1118:9)
[2024-02-27T23:30:31.267Z]     at asyncHandler (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/protocol.js:491:57)
[2024-02-27T23:30:31.267Z] INFO     24-02-28 01:20:03.325536 Machine: Linux-tests-6; Device: emulator-5556
[2024-02-27T23:30:31.267Z] Executed command: ssh user@10.18.141.125 "adb -s emulator-5556 get-state"
[2024-02-27T23:30:31.267Z] INFO     24-02-28 01:20:03.531135 Device emulator-5556 is connected = False
[2024-02-27T23:30:31.267Z] Sleep 10 seconds before trying again...
[2024-02-27T23:30:31.267Z] No session id found for device emulator-5556 and node ip 10.18.141.125
[2024-02-27T23:30:31.267Z] INFO     24-02-28 01:20:13.544544 Attempt 3 to create driver session
[2024-02-27T23:30:31.267Z] ERROR    24-02-28 01:25:13.554050 Message: An unknown server-side error occurred while processing the command. Original error: {"value":{"error":"unknown error","message":"An unknown server-side error occurred while processing the command. Original error: No device matching request.. Device request: {\"platform\":\"android\",\"udid\":\"emulator-5556\",\"filterByHost\":\"10.18.141.125\"}","stacktrace":"UnknownError: An unknown server-side error occurred while processing the command. Original error: No device matching request.. Device request: {\"platform\":\"android\",\"udid\":\"emulator-5556\",\"filterByHost\":\"10.18.141.125\"}\n    at getResponseForW3CError (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/errors.js:1118:9)\n    at asyncHandler (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/protocol.js:491:57)"}}
[2024-02-27T23:30:31.267Z] Stacktrace:
[2024-02-27T23:30:31.267Z] UnknownError: An unknown server-side error occurred while processing the command. Original error: {"value":{"error":"unknown error","message":"An unknown server-side error occurred while processing the command. Original error: No device matching request.. Device request: {\"platform\":\"android\",\"udid\":\"emulator-5556\",\"filterByHost\":\"10.18.141.125\"}","stacktrace":"UnknownError: An unknown server-side error occurred while processing the command. Original error: No device matching request.. Device request: {\"platform\":\"android\",\"udid\":\"emulator-5556\",\"filterByHost\":\"10.18.141.125\"}\n    at getResponseForW3CError (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/errors.js:1118:9)\n    at asyncHandler (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/protocol.js:491:57)"}}
[2024-02-27T23:30:31.267Z]     at getResponseForW3CError (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/errors.js:1118:9)
[2024-02-27T23:30:31.267Z]     at asyncHandler (/home/linuxbrew/.linuxbrew/lib/node_modules/appium/node_modules/@appium/base-driver/lib/protocol/protocol.js:491:57)
[2024-02-27T23:30:31.267Z] INFO     24-02-28 01:25:13.554208 Machine: Linux-tests-6; Device: emulator-5556

For first case - session created with my retries - 6+ min For second - 5+ min

Env: appium v2.4.1 device farm v8.4.7 rc8 uiautomator2 v.3.0.0

About this issue

Original URL
State: closed
Created 4 months ago
Comments: 16 (9 by maintainers)

Commits related to this issue

#1039 keep axios remote session alive — committed to AppiumTestDistribution/appium-device-farm by saikrishna321 4 months ago
Configure axios to keep session alive (#1045) * #1039 keep axios remote session alive * 8.4.7-rc.15 — committed to AppiumTestDistribution/appium-device-farm by saikrishna321 4 months ago

Most upvoted comments

@Comeodore Thanks for the logs. I found the issue.

Hub got a requested to fetch a device matching host "filterByHost":"10.18.141.163","udid":"emulator-5556" but the request went to node host http://10.18.141.66 and blocked the device emulator-5556

Logs from node machine IP 10.18.141.66

{"appium:udid":"emulator-5556","appium:systemPort":37749,"appium:chromeDriverPort":42163,"appium:adbPort":5037,"appium:automationName":"UIAutomator2","platformName":"Android","appium:noReset":true,"appium:deviceName":"sdk_gphone64_x86_64","appium:clearDeviceLogsOnStart":true,"appium:autoGrantPermissions":true,"appium:mjpegServerPort":48811,"appium:disableWindowAnimation":true,"appium:uiautomator2ServerInstallTimeout":30000,"appium:uiautomator2ServerLaunchTimeout":40000,"appium:uiautomator2ServerReadTimeout":45000,"appium:newCommandTimeout":600,"appium:shouldTerminateApp":true,"appium:enforceXPath1":true,"appium:filterByHost":"10.18.141.163"}

In the above request we can see "appium:filterByHost":"10.18.141.163" this is not expected. Now the request has reached IP x.x.x.66 instead of x.x.x.163 and blocks the emulator-5556 in node.

HUB logs

2024-03-01 20:14:20:350 - [38;5;0m[device-farm-main][0m 📱 Blocking device emulator-5556 at host http://10.18.141.66:1111 for new session
2024-03-01 20:14:20:350 - [38;5;0m[device-farm-main][0m Updating allocated device: "{"userBlocked":false,"offline":false,"adbPort":5037,"systemPort":34451,"sdk":"14","realDevice":false,"name":"sdk_gphone64_x86_64","busy":false,"state":"device","udid":"emulator-5556","platform":"android","deviceType":"emulator","host":"http://10.18.141.66:1111","totalUtilizationTimeMilliSec":29053852,"sessionStartTime":0,"nodeId":"39e3d1de-5d86-46c2-baec-ea6aac72722e","meta":{"revision":0,"created":1709320845224,"version":0},"$loki":5}"
2024-03-01 20:14:20:350 - [38;5;0m[device-farm-main][0m Updated allocated device: "{"userBlocked":false,"offline":false,"adbPort":5037,"systemPort":34451,"sdk":"14","realDevice":false,"name":"sdk_gphone64_x86_64","busy":false,"state":"device","udid":"emulator-5556","platform":"android","deviceType":"emulator","host":"http://10.18.141.66:1111","totalUtilizationTimeMilliSec":29053852,"sessionStartTime":0,"nodeId":"39e3d1de-5d86-46c2-baec-ea6aac72722e","meta":{"revision":0,"created":1709320845224,"version":0},"$loki":5}"
2024-03-01 20:14:20:350 - [38;5;0m[device-farm-main][0m device.host: http://10.18.141.66:1111 and pluginArgs.bindHostOrIp: 10.18.141.178
2024-03-01 20:14:20:350 - [38;5;0m[device-farm-main][0m 📱 Forwarding session request to http://10.18.141.66:1111
2024-03-01 20:14:20:351 - [38;5;0m[device-farm-main][0m Creating session with desiredCapabilities: "{"capabilities":{"firstMatch":[{"appium:udid":"emulator-5556","appium:systemPort":37749,"appium:chromeDriverPort":42163,"appium:adbPort":5037}],"alwaysMatch":{"appium:automationName":"UIAutomator2","platformName":"Android","appium:noReset":true,"appium:deviceName":"sdk_gphone64_x86_64","appium:clearDeviceLogsOnStart":true,"appium:autoGrantPermissions":true,"appium:mjpegServerPort":48811,"appium:disableWindowAnimation":true,"appium:uiautomator2ServerInstallTimeout":30000,"appium:uiautomator2ServerLaunchTimeout":40000,"appium:uiautomator2ServerReadTimeout":45000,"appium:newCommandTimeout":600,"appium:shouldTerminateApp":true,"appium:enforceXPath1":true,"appium:filterByHost":"10.18.141.163"}}}"

Let me look at the remaining logs and fix this issue.

saikrishna321 on Mar 1, 2024

Fixed

Comeodore on Mar 6, 2024

@Comeodore Thanks! Will look into it

saikrishna321 on Mar 5, 2024

@Comeodore Please try with latest rc. Make sure you give capabilityy ‘df:filterBHost’:‘http://ip:port’

saikrishna321 on Mar 5, 2024

@Comeodore You mean timestamp in server logs. If yes appium server has way --log-timestamp as the plugin uses appium logger it should use that timestamp.

saikrishna321 on Mar 1, 2024

Will check today

saikrishna321 on Feb 29, 2024