java-client icon indicating copy to clipboard operation
java-client copied to clipboard

Published 20 hours ago • verified publisher icon appium

[Appium Client 9.0.0] Connection closed locally

Open darkwilly08 opened this issue 1 year ago • 8 comments

Description

After upgrading appium to version 9.0.0 and selenium to 4.14.1 I am facing some unexpected connection close during test execution.

The same tests using appium 8.6.0 with selenium 4.13.0 works perfectly fine.

Environment

  • Java client build version or git revision if you use some snapshot: openjdk 17.0.2 2022-01-18
  • Appium server version or git revision if you use some snapshot: saucelabs > appium 2.0.0
  • Desktop OS/version used to run Appium if necessary: Windows 10
  • Node.js version (unless using Appium.app|exe) or Appium CLI or Appium.app|exe:
  • Mobile platform/version under test: Web/Chrome 120

Exception Stacktraces

stack trace

 Caused by: org.openqa.selenium.remote.UnreachableBrowserException: Error communicating with the remote browser. It may have died.

Thanks in advance.

darkwilly08 avatar Dec 28 '23 14:12 darkwilly08

We had a similar issue with our e2e tests while switching to the newer selenium client. Enforcing HTTP version to 1.1 on the client side helped to resolve it. So, make sure your client either uses the default connection config or does the same trick if it is customized.

mykola-mokhnach avatar Dec 28 '23 16:12 mykola-mokhnach

btw, I don't observe where Appium java client is used in the stacktrace. Are you sure it is used at all?

mykola-mokhnach avatar Dec 28 '23 16:12 mykola-mokhnach

@mykola-mokhnach my apologies, end of year is too close.

You are absolutely right. For web, we are using selenium directly.

Let me share the stack trace on Android. There you can see java client is used =>

io.appium.java_client.AppiumDriver.execute(AppiumDriver.java:307)

It seems that the issue is not happening in Appium but in selenium 4.14.1. With the downgrade of Appium to 8.x I also downgraded selenium to 4.13.0 and that was the reason the issue disappeared.

darkwilly08 avatar Dec 28 '23 17:12 darkwilly08

Appium server version or git revision if you use some snapshot: saucelabs > appium 2.0.0

Is the issue reproducible locally? If not then it is something that must be reported to saucelabs.

mykola-mokhnach avatar Dec 29 '23 18:12 mykola-mokhnach

Has anyone figured this out yet?

I'm facing the same issue after upgrading to v9. My test gets logcat repeatedly and after a while (e.g. 172 times in a recent run I'm looking at), it fails on a call to driver.manage().logs().get("logcat") with:

org.openqa.selenium.remote.UnreachableBrowserException: Error communicating with the remote browser. It may have died.
    Build info: version: '4.19.0', revision: '5f9cec8963'
    System info: os.name: 'Linux', os.arch: 'amd64', os.version: '6.5.0-1025-azure', java.version: '17.0.12'
    Driver info: io.appium.java_client.android.AndroidDriver
    Command: [3951e115-c812-4c95-bad2-353a0022575c, executeScript [script, args]]
    Capabilities {appium:adbHost: 172.20.0.149, appium:adbPort: 17120, appium:appiumData: {appiumVersion: appium2-20240701, automationName: UiAutomator2}, appium:automationName: UiAutomator2, appium:chromeOptions: {w3c: false}, appium:chromedriverChromeMappingFile: /root/.testobject_devices/w..., appium:chromedriverExecutableDir: /root/.testobject_devices/w..., appium:chromedriverPorts: [[3120, 3130]], appium:databaseEnabled: false, appium:desired: {adbHost: 172.20.0.149, adbPort: 17120, appActivity: com.android.chrome/com.goog..., appPackage: com.android.chrome, automationName: UiAutomator2, browserName: Chrome, chromeOptions: {w3c: false}, chromedriverChromeMappingFile: /root/.testobject_devices/w..., chromedriverExecutableDir: /root/.testobject_devices/w..., chromedriverPorts: [[3120, 3130]], deviceName: Samsung_Galaxy_S22_5G_real, disableWindowAnimation: true, flutterSystemPort: 22620, platformName: Android, remoteAdbHost: 172.20.0.149, remoteAppsCacheLimit: 0, sauce:chromeOptions: {androidDevToolsPort: 22320}, sauce:options: {appiumVersion: appium2-20240701, build: ..., name: Performance tests, tags: [android, ci]}, suppressKillServer: true, systemPort: 21120, uiautomator2ServerInstallTimeout: 60000}, appium:deviceApiLevel: 31, appium:deviceContextId: f06a7a18-56c1-46ce-9518-8b5..., appium:deviceManufacturer: samsung, appium:deviceModel: SM-S901U1, appium:deviceName: R5CT72JR56D, appium:deviceScreenDensity: 480, appium:deviceScreenSize: 1080x2340, appium:deviceUDID: R5CT72JR56D, appium:disableWindowAnimation: true, appium:flutterSystemPort: 22620, appium:javascriptEnabled: true, appium:jobUuid: 3edfa1a2041a4f8bae07a25ff47..., appium:locationContextEnabled: false, appium:networkConnectionEnabled: true, appium:pixelRatio: 3, appium:platformVersion: 12, appium:remoteAdbHost: 172.20.0.149, appium:remoteAppsCacheLimit: 0, appium:statBarHeight: 81, appium:suppressKillServer: true, appium:systemPort: 21120, appium:takesScreenshot: true, appium:testobject_device: Samsung_Galaxy_S22_5G_real, appium:testobject_device_name: Samsung Galaxy S22 5G, appium:testobject_device_session_id: ..., appium:testobject_test_report_api_url: https://api.us-west-1.sauce..., appium:testobject_test_report_url: https://app.saucelabs.com/t..., appium:testobject_user_id: ....., appium:uiautomator2ServerInstallTimeout: 60000, appium:usedCachedDevice: false, appium:viewportRect: {height: 2259, left: 0, top: 81, width: 1080}, appium:warnings: {}, appium:webStorageEnabled: false, browserName: Chrome, platformName: ANDROID, sauce:chromeOptions: {androidDevToolsPort: 22320}, sauce:options: {appiumVersion: appium2-20240701, build: ..., name: Performance tests, tags: [android, ci]}}
    Session ID: .....
        at app//org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:545)
        at app//org.openqa.selenium.remote.RemoteWebDriver.executeScript(RemoteWebDriver.java:463)
        at app//StartupTimeTest.collectAppStartupTimes(StartupTimeTest.kt:176)
        at app//StartupTimeTest.collectStartupTimes$lambda$1(StartupTimeTest.kt:121)
        at app//TestBase.withDriver(TestBase.kt:26)
        at app//StartupTimeTest.collectStartupTimes(StartupTimeTest.kt:98)
        at app//StartupTimeTest.startup time(StartupTimeTest.kt:42)

        Caused by:
        java.io.UncheckedIOException: java.io.IOException: HTTP/1.1 header parser received no bytes
            at org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute0(JdkHttpClient.java:436)
            at io.appium.java_client.internal.filters.AppiumIdempotencyFilter.lambda$apply$0(AppiumIdempotencyFilter.java:35)
            at io.appium.java_client.internal.filters.AppiumUserAgentFilter.lambda$apply$0(AppiumUserAgentFilter.java:87)
            at org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:55)
            at org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute(JdkHttpClient.java:352)
            at org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:187)
            at io.appium.java_client.remote.AppiumCommandExecutor.execute(AppiumCommandExecutor.java:237)
            at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:518)
            ... 6 more

            Caused by:
            java.io.IOException: HTTP/1.1 header parser received no bytes
                at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:348)
                at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:675)
                at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:302)
                at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:268)
                at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
                at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
                at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
                at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
                at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
                at java.base/java.lang.Thread.run(Thread.java:840)

                Caused by:
                java.io.IOException: connection closed locally
                    at java.net.http/jdk.internal.net.http.SocketTube.signalClosed(SocketTube.java:159)
                    at java.net.http/jdk.internal.net.http.PlainHttpConnection.close(PlainHttpConnection.java:372)
                    at java.net.http/jdk.internal.net.http.AsyncSSLConnection.close(AsyncSSLConnection.java:111)
                    at java.net.http/jdk.internal.net.http.Http1Exchange.cancelImpl(Http1Exchange.java:492)
                    at java.net.http/jdk.internal.net.http.Http1Exchange.cancel(Http1Exchange.java:427)
                    at java.net.http/jdk.internal.net.http.Exchange.cancel(Exchange.java:238)
                    at java.net.http/jdk.internal.net.http.MultiExchange.cancel(MultiExchange.java:260)
                    at java.net.http/jdk.internal.net.http.ResponseTimerEvent.handle(ResponseTimerEvent.java:71)
                    at java.net.http/jdk.internal.net.http.HttpClientImpl.purgeTimeoutsAndReturnNextDeadline(HttpClientImpl.java:1270)
                    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:899)

vaind avatar Aug 16 '24 07:08 vaind

I've checked logs on Saucelabs and it looks like the client closes the session on its own accord:

2024-08-16 07:06:06.634 V [3951e115][AndroidUiautomator2Driver@8453] Calling AppiumDriver.execute() with args: ["mobile: startActivity",[{"intent":"com.saucelabs.mydemoapp.rn/.MainActivity","wait":true}],"3951e115-c812-4c95-bad2-353a0022575c"]
2024-08-16 07:06:06.634 V [3951e115][AppiumDriver@b6b0] Clearing new command timeout pre-emptively since plugin(s) will handle this command
2024-08-16 07:06:06.635 V [3951e115][AppiumDriver@b6b0] Plugins which can handle cmd 'execute': images
2024-08-16 07:06:06.635 V [3951e115][AppiumDriver@b6b0] Plugin images is now handling cmd 'execute'
2024-08-16 07:06:06.635 V [3951e115][AppiumDriver@b6b0] Executing default handling behavior for command 'execute'
2024-08-16 07:06:06.635 V [3951e115][AndroidUiautomator2Driver@8453] Executing native command 'mobile: startActivity'
2024-08-16 07:06:06.636 V [3951e115][ADB] Running '/opt/android-sdk/platform-tools/adb -H 172.20.0.149 -P 17120 -s R5CT72JR56D shell am start-activity -W com.saucelabs.mydemoapp.rn/.MainActivity'
2024-08-16 07:06:07.139 V [3951e115][HTTP] --> POST /wd/hub/session/3951e115-c812-4c95-bad2-353a0022575c/se/log {"type":"logcat"}
2024-08-16 07:06:07.139 V [3951e115][AndroidUiautomator2Driver@8453] Calling AppiumDriver.getLog() with args: ["logcat","3951e115-c812-4c95-bad2-353a0022575c"]
2024-08-16 07:06:07.140 V [3951e115][AppiumDriver@b6b0] Clearing new command timeout pre-emptively since plugin(s) will handle this command
2024-08-16 07:06:07.140 V [3951e115][AppiumDriver@b6b0] Plugins which can handle cmd 'getLog': images
2024-08-16 07:06:07.140 V [3951e115][AppiumDriver@b6b0] Plugin images is now handling cmd 'getLog'
2024-08-16 07:06:07.140 V [3951e115][AppiumDriver@b6b0] Executing default handling behavior for command 'getLog'
2024-08-16 07:06:08.951 V [3951e115][AndroidUiautomator2Driver@8453] Retrieving 'logcat' logs
2024-08-16 07:06:08.951 V [3951e115][AndroidUiautomator2Driver@8453] Responding to client with driver.execute() result: "Starting: Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] cmp=com.saucelabs.mydemoapp.rn/.MainActivity }\nStatus: ok\nLaunchState: UNKNOWN (0)\nActivity: com.saucelabs.mydemoapp.rn/.MainActivity\nWaitTime: 2238\nComplete"
2024-08-16 07:06:08.952 V [3951e115][HTTP] <-- POST /wd/hub/session/3951e115-c812-4c95-bad2-353a0022575c/execute/sync 200 2318 ms - 263 
2024-08-16 07:06:08.956 V [3951e115][AndroidUiautomator2Driver@8453] Responding to client with driver.getLog() result: [{"timestamp":1723791965746,"level":"ALL","message":"08-16 04:06:06.639  3972 20773 I NearbySharing: (REDACTED) Failed to convert given advertisement (%s)%s to share target from discovered advertisement. Ignoring."},{"timestamp":1723791965747,"level":"ALL","message":"08-16 04:06:06.639  3972 20773 I NearbySharing: (REDACTED) Report endpoint %s as lost, since we cannot recognize this endpoint anymore"},{"timestamp":1723791965769,"level":"ALL","message":"08-16 04:06:06.661  1477  1477 I DisplayDevice: ActiveConfigToHWC, ID : 5, Display : 4630947232161729154"},{"timestamp":1723791965769,"level":"ALL","message":"08-16 04:06:06.662  1477  1477 I SurfaceFlinger: getBestRefreshRateLocked Idle - choose [1080_24]"},{"timestamp":1723791965769,"level":"ALL","message":"08-16 04:06:06.662  1477  1477 D SurfaceFlinger: GPIS:: requestGPIS"},{"timestamp":1723791965771,"level":"ALL","message":"08-16 04:06:06.663  1379  1681 I SDM     : HWCDisplay::SubmitDisplayConfig: [DispConfigs] config 0 => 9, hs_mode 3 => 3"},{"timesta...
2024-08-16 07:06:08.958 V [3951e115][HTTP] <-- POST /wd/hub/session/3951e115-c812-4c95-bad2-353a0022575c/se/log 200 1819 ms - 241583 
2024-08-16 07:06:09.481 V [3951e115][HTTP] --> DELETE /wd/hub/session/3951e115-c812-4c95-bad2-353a0022575c {}
2024-08-16 07:06:09.481 V [3951e115][AndroidUiautomator2Driver@8453] Calling AppiumDriver.deleteSession() with args: ["3951e115-c812-4c95-bad2-353a0022575c"]
2024-08-16 07:06:09.481 V [3951e115][AppiumDriver@b6b0] Clearing new command timeout pre-emptively since plugin(s) will handle this command
2024-08-16 07:06:09.481 V [3951e115][AppiumDriver@b6b0] Plugins which can handle cmd 'deleteSession': images
2024-08-16 07:06:09.481 V [3951e115][AppiumDriver@b6b0] Plugin images is now handling cmd 'deleteSession'
2024-08-16 07:06:09.482 V [3951e115][AppiumDriver@b6b0] Executing default handling behavior for command 'deleteSession'
2024-08-16 07:06:09.482 V [3951e115][AppiumDriver@b6b0] Event 'quitSessionRequested' logged at 1723791969482 (07:06:09 GMT+0000 (Coordinated Universal Time))
2024-08-16 07:06:09.483 V [3951e115][AppiumDriver@b6b0] Removing session 3951e115-c812-4c95-bad2-353a0022575c from our master session list
2024-08-16 07:06:09.484 V [3951e115][AndroidUiautomator2Driver@8453] Deleting UiAutomator2 session
2024-08-16 07:06:09.484 V [3951e115][AndroidUiautomator2Driver@8453] Stopping chromedriver for context CHROMIUM
2024-08-16 07:06:09.484 V [3951e115][Chromedriver@eecf] Changed state to 'stopping'
2024-08-16 07:06:09.492 V [3951e115][Chromedriver@eecf] Proxying [DELETE /] to [DELETE http://127.0.0.1:3120/session/c86cde95a56a0fe10100139ca453e0d9] with no body
2024-08-16 07:06:09.651 V [3951e115][Chromedriver@eecf] Got response with status 200: {"sessionId":"c86cde95a56a0fe10100139ca453e0d9","status":0,"value":null}
2024-08-16 07:06:09.653 V [3951e115][Chromedriver@eecf] Changed state to 'stopped'
2024-08-16 07:06:09.653 V [3951e115][AndroidUiautomator2Driver@8453] Deleting UiAutomator2 server session
2024-08-16 07:06:09.653 V [3951e115][AndroidUiautomator2Driver@8453] Matched '/' to command name 'deleteSession'
2024-08-16 07:06:09.654 V [3951e115][AndroidUiautomator2Driver@8453] Proxying [DELETE /] to [DELETE http://172.20.0.149:21120/session/4a35b1c0-f998-46ad-8eb9-98e1e215b27e] with no body
2024-08-16 07:06:09.730 V [3951e115][AndroidUiautomator2Driver@8453] Got response with status 200: {"sessionId":"4a35b1c0-f998-46ad-8eb9-98e1e215b27e","value":null}
2024-08-16 07:06:09.731 V [3951e115][ADB] Running '/opt/android-sdk/platform-tools/adb -H 172.20.0.149 -P 17120 -s R5CT72JR56D shell dumpsys activity services io.appium.settings/.recorder.RecorderService'

vaind avatar Aug 16 '24 07:08 vaind

Hi @vaind, my appologies for not replying here with the solution. I went from:

return new AndroidDriver(new URL(appiumServerUrl), capabilities);

to

return new AndroidDriver(AppiumClientConfig.defaultConfig().baseUrl(new URL(appiumServerUrl)), capabilities);

This way selenium is using http 1.1 protocol and I do not have any issues.

darkwilly08 avatar Aug 16 '24 13:08 darkwilly08