Open Uil2liv opened 2 years ago
2022-04-04 12:09:24:281 [HTTP] --> POST /wd/hub/session/d1c276b8-7601-40a7-bb0e-269e72e1a2b4/element/00000000-0000-0027-ffff-ffff00000156/value
2022-04-04 12:09:24:283 [HTTP] {"text":"Appium","value":["A","p","p","i","u","m"],"id":"00000000-0000-0027-ffff-ffff00000156"}
2022-04-04 12:09:24:284 [W3C (d1c276b8)] Calling AppiumDriver.setValue() with args: [["A","p","p","i","u","m"],"00000000-0000-0027-ffff-ffff00000156","d1c276b8-7601-40a7-bb0e-269e72e1a2b4"]
2022-04-04 12:09:24:285 [WD Proxy] Matched '/element/00000000-0000-0027-ffff-ffff00000156/value' to command name 'setValue'
2022-04-04 12:09:24:286 [Protocol Converter] Added 'value' property ["A","p","p","i","u","m"] to 'setValue' request body
2022-04-04 12:09:24:286 [WD Proxy] Proxying [POST /element/00000000-0000-0027-ffff-ffff00000156/value] to [POST http://127.0.0.1:8200/wd/hub/session/e67596e4-5850-402d-add6-862436f4a5ed/element/00000000-0000-0027-ffff-ffff00000156/value] with body: {"elementId":"00000000-0000-0027-ffff-ffff00000156","text":"Appium","replace":false,"value":["A","p","p","i","u","m"]}
2022-04-04 12:09:25:214 [WD Proxy] Got response with status 200: {"sessionId":"e67596e4-5850-402d-add6-862436f4a5ed","value":null}
2022-04-04 12:09:25:216 [W3C (d1c276b8)] Responding to client with driver.setValue() result: null
2022-04-04 12:09:25:218 [HTTP] <-- POST /wd/hub/session/d1c276b8-7601-40a7-bb0e-269e72e1a2b4/element/00000000-0000-0027-ffff-ffff00000156/value 200 936 ms - 14
2022-04-04 12:09:25:218 [HTTP]
2022-04-04 12:10:25:210 [HTTP] --> POST /wd/hub/session/d1c276b8-7601-40a7-bb0e-269e72e1a2b4/appium/device/press_keycode
2022-04-04 12:10:25:210 [HTTP] {"keycode":66}
2022-04-04 12:10:25:211 [W3C (d1c276b8)] Calling AppiumDriver.pressKeyCode() with args: [66,null,null,null,null,"d1c276b8-7601-40a7-bb0e-269e72e1a2b4"]
2022-04-04 12:10:25:212 [WD Proxy] Matched '/appium/device/press_keycode' to command name 'pressKeyCode'
2022-04-04 12:10:25:212 [WD Proxy] Proxying [POST /appium/device/press_keycode] to [POST http://127.0.0.1:8200/wd/hub/session/e67596e4-5850-402d-add6-862436f4a5ed/appium/device/press_keycode] with body: {"keycode":66,"metastate":null,"flags":null}
2022-04-04 12:10:25:215 [WD Proxy] socket hang up
2022-04-04 12:10:25:237 [W3C (d1c276b8)] Encountered internal error running command: UnknownError: An unknown server-side error occurred while processing the command. Original error: Could not proxy command to the remote server. Original error: socket hang up
2022-04-04 12:10:25:238 [W3C (d1c276b8)] at UIA2Proxy.command (C:\Users\proto\AppData\Roaming\npm\node_modules\appium\node_modules\appium-base-driver\lib\jsonwp-proxy\proxy.js:274:13)
2022-04-04 12:10:25:238 [W3C (d1c276b8)] at runMicrotasks (<anonymous>)
2022-04-04 12:10:25:238 [W3C (d1c276b8)] at processTicksAndRejections (node:internal/process/task_queues:96:5)
2022-04-04 12:10:25:239 [W3C (d1c276b8)] at AndroidUiautomator2Driver.commands.pressKeyCode (C:\Users\proto\AppData\Roaming\npm\node_modules\appium\node_modules\appium-uiautomator2-driver\lib\commands\actions.js:6:10)
2022-04-04 12:10:25:240 [HTTP] <-- POST /wd/hub/session/d1c276b8-7601-40a7-bb0e-269e72e1a2b4/appium/device/press_keycode 500 30 ms - 863
2022-04-04 12:10:25:241 [HTTP]
2022-04-04 12:10:25:484 [HTTP] --> POST /wd/hub/session/d1c276b8-7601-40a7-bb0e-269e72e1a2b4/appium/device/press_keycode
2022-04-04 12:10:25:484 [HTTP] {"keycode":66}
2022-04-04 12:10:25:485 [W3C (d1c276b8)] Calling AppiumDriver.pressKeyCode() with args: [66,null,null,null,null,"d1c276b8-7601-40a7-bb0e-269e72e1a2b4"]
2022-04-04 12:10:25:487 [WD Proxy] Matched '/appium/device/press_keycode' to command name 'pressKeyCode'
2022-04-04 12:10:25:487 [WD Proxy] Proxying [POST /appium/device/press_keycode] to [POST http://127.0.0.1:8200/wd/hub/session/e67596e4-5850-402d-add6-862436f4a5ed/appium/device/press_keycode] with body: {"keycode":66,"metastate":null,"flags":null}
2022-04-04 12:10:25:573 [WD Proxy] Got response with status 200: {"sessionId":"e67596e4-5850-402d-add6-862436f4a5ed","value":null}
2022-04-04 12:10:25:574 [W3C (d1c276b8)] Responding to client with driver.pressKeyCode() result: null
2022-04-04 12:10:25:577 [HTTP] <-- POST /wd/hub/session/d1c276b8-7601-40a7-bb0e-269e72e1a2b4/appium/device/press_keycode 200 90 ms - 14
the press_keycode is probably the below in the logcat. Only one command existed around the similar timeline. It seems like the socket hang's one did not reach the uia2 server by some reasons.
04-04 12:10:22.632 1859 1872 I GnssLocationProvider: WakeLock released by handleMessage(REPORT_SV_STATUS, 0, com.android.server.location.GnssLocationProvider$SvStatusInfo@4b5bfcc)
04-04 12:10:22.659 9318 9562 I appium : READER_IDLE: closing the channel
04-04 12:10:22.951 9318 9649 I appium : channel read: POST /wd/hub/session/e67596e4-5850-402d-add6-862436f4a5ed/appium/device/press_keycode
04-04 12:10:22.952 9318 9649 I appium : PressKeyCode command
04-04 12:10:22.952 9318 9649 I appium : Calling PressKeyCode...
04-04 12:10:22.958 9358 9358 W cr_SpanAutocomplete: Did not notify - no change.
I wonder the adb port forward got an issue temporary at that time, so the 2nd press_keycode reached while the 1st one did not...
+1, I am seeing this exact same issue in some code I am running, where the newCommandTimeout is being set high (e.g. 300 seconds), but commands which wait around 60 seconds will see a "READER_IDLE: closing the channel" logcat line and a "socket hang up" response in Appium.
I am going to work around the issue from the client's side by retrying 500 error code responses, based on the following:
Environment
Driver: UIAutomator2 4.27.0 Device: Android 9 device, real or emulated Server: Appium 1.22.3 Client: Appium-Python-Client 2.1.4
How to reproduce
Wait exactly 60 seconds between 2 driver call. Randomly, the following exception is raised:
Encountered internal error running command: UnknownError: An unknown server-side error occurred while processing the command. Original error: Could not proxy command to the remote server. Original error: socket hang up
Additions
Workaround
Depending on needs, if we wait 59s or 61s, the problem does not occur
Stats & Randomness
I try to reproduce it with random delays around 60s. to identify the worst case scenario. I obtained the following results:
The actual data generated with all test results and timings: 2022_04_04_12_07_56_log.csv
Logs
appium server logs: appium-server-logs.log
all logcats after failure: logcats.zip
Reproducing test
All the data above has been produced with the following script