Socket hang up after 60 seconds of inactivity

[Uil2liv]

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

import os
import subprocess
from datetime import datetime
from random import uniform
from time import sleep

import pytest
from _pytest.fixtures import fixture
from appium import webdriver
from appium.webdriver.common.appiumby import AppiumBy
from appium.webdriver.extensions.android.nativekey import AndroidKey
from selenium.common.exceptions import WebDriverException

sdk_platform_tools = "C:\\Users\\proto\\AppData\\Local\\Android\\Sdk\\platform-tools"


@fixture(scope="module")
def log_file():
    filename = datetime.now().strftime("%Y_%m_%d_%H_%M_%S") + "_log.csv"
    with open(filename, "w") as log:
        print("Delay;Status;Time", file=log)
    return filename


@fixture(scope="module")
def driver():
    desired_capabilities = {
        "platformName": "Android",
        "automationName": "UiAutomator2",
        "newCommandTimeout": 600
    }

    _driver = webdriver.Remote("http://localhost:4723/wd/hub", desired_capabilities)
    _driver.implicitly_wait(10)

    yield _driver

    _driver.quit()


@fixture(scope="module")
def browser_opened(driver):
    driver.activate_app("com.android.chrome")
    driver.wait_activity("com.google.android.apps.chrome.Main", 60)
    driver.find_element(AppiumBy.ID, "com.android.chrome:id/search_box_text")

    yield

    driver.terminate_app("com.android.chrome")


@fixture()
def new_tab(driver):
    tab_switcher = driver.find_element(AppiumBy.ID, "com.android.chrome:id/tab_switcher_button")
    tab_switcher.click()

    menu_button = driver.find_element(AppiumBy.ID, "com.android.chrome:id/menu_button")
    menu_button.click()

    close_all_tabs = driver.find_element(AppiumBy.ACCESSIBILITY_ID, "Close all tabs")
    close_all_tabs.click()

    new_tab = driver.find_element(AppiumBy.ID, "com.android.chrome:id/new_tab_button")
    new_tab.click()

    return


delays = [uniform(59.98, 60.01) for _ in range(100)]


@pytest.mark.parametrize("delay", delays)
def test_socket_timeout(log_file, driver, browser_opened, new_tab, delay):
    status = "Not Executed"

    search_box = driver.find_element(AppiumBy.ID, "com.android.chrome:id/search_box_text")
    search_box.send_keys("Appium")

    sleep(delay)

    try:
        driver.press_keycode(AndroidKey.ENTER)
    except WebDriverException as exc:
        if "Original error: socket hang up" in exc.msg:
            status = "Failed - socket hang up"
            logcat_filename = datetime.now().strftime("%Y_%m_%d_%H_%M_%S") + "_logcat.log"
            subprocess.run([os.path.join(sdk_platform_tools, "adb"), "logcat", "-d", ">", logcat_filename], shell=True)
            subprocess.run([os.path.join(sdk_platform_tools, "adb"), "logcat", "-c"])
        else:
            status = "Failed - other exception"

        driver.press_keycode(AndroidKey.ENTER)

        raise exc
    except Exception as exc:
        status = "Failed - other exception"

        driver.press_keycode(AndroidKey.ENTER)

        raise exc
    else:
        status = "Passed"
    finally:
        time = datetime.now().strftime("%Y-%m-%d %H:%M:%S.%f")
        with open(log_file, "a") as log:
            print(";".join([str(delay), status, time]), file=log)

[KazuCocoa]

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...

[aristeia]

+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:

• https://github.com/appium/python-client#set-custom-appiumconnection
• https://stackoverflow.com/a/35504626