fix: check if the instrumentation process stops by sending a request #655

KazuCocoa · 2023-09-20T04:53:38Z

I observed weird behavior on an Android 13 Samsung device. This was only a specific device so far but potentially could happen on other devices. (I mean I cannot say this does not happen on other devices)

What I saw was in a new session request from uia2 driver to the uia2 server. These are in createSession in driver.js.

/wd/hub/session create session -> ok 200
/wd/hub/session/0e62d0be-bfb4-403e-8b85-6af9ae40fbfd/appium/device/info -> ok
/wd/hub/session/0e62d0be-bfb4-403e-8b85-6af9ae40fbfd/appium/device/pixel_ratio -> invalid session id for 0e62d0be-bfb4-403e-8b85-6af9ae40fbfd

According to the adb log cat, it seems like the uia2 server process stop in cleanupAutomationLeftovers? probably delayed. So activity stop log actually existed before /wd/hub/session in the above, but the process kill itself conducted AFTER /wd/hub/session/0e62d0be-bfb4-403e-8b85-6af9ae40fbfd/appium/device/info. Then the instrumentation process started again, maybe by the instrumentation command.

So probably that happened on the device was something activity handling by the OS had delayed.

So, in this PR, I'd like to check if the cleanupAutomationLeftovers can ensure that the process (the same port is fine to avoid this behavior) actually stops. Then, I expect like the above weird "delay" also can be avoidable.

Error example when this check fails:

[AndroidUiautomator2Driver@8443 (969adba8)] socket hang up
[debug] [AndroidUiautomator2Driver@8443 (969adba8)] Matched '/status' to command name 'getStatus'
[debug] [AndroidUiautomator2Driver@8443 (969adba8)] Proxying [GET /status] to [GET http://127.0.0.1:8200/status] with no body
[AndroidUiautomator2Driver@8443 (969adba8)] socket hang up
[debug] [AndroidUiautomator2Driver@8443 (969adba8)] Matched '/status' to command name 'getStatus'
[debug] [AndroidUiautomator2Driver@8443 (969adba8)] Proxying [GET /status] to [GET http://127.0.0.1:8200/status] with no body
[AndroidUiautomator2Driver@8443 (969adba8)] socket hang up
[AndroidUiautomator2Driver@8443 (969adba8)] The instrumentation process might fail to stop within 1000ms timeout.
[debug] [AndroidUiautomator2Driver@8443 (969adba8)] Deleting UiAutomator2 session
[debug] [AndroidUiautomator2Driver@8443 (969adba8)] Deleting UiAutomator2 server session
[debug] [AndroidUiautomator2Driver@8443 (969adba8)] Matched '/' to command name 'deleteSession'
[AndroidUiautomator2Driver@8443 (969adba8)] Did not get confirmation UiAutomator2 deleteSession worked; Error was: UnknownError: An unknown server-side error occurred while processing the command. Original error: Trying to proxy a session command without session id
[debug] [ADB] Running '/Users/kazu/Library/Android/sdk/platform-tools/adb -P 5037 -s D0AA002182JC0202126 shell dumpsys activity services io.appium.settings/.recorder.RecorderService'
[debug] [Logcat] Stopping logcat capture
[debug] [ADB] Removing forwarded port socket connection: 8200
[debug] [ADB] Running '/Users/kazu/Library/Android/sdk/platform-tools/adb -P 5037 -s D0AA002182JC0202126 forward --remove tcp:8200'
[AndroidUiautomator2Driver@8443 (969adba8)] Restoring hidden api policy to the device default configuration
[debug] [ADB] Running '/Users/kazu/Library/Android/sdk/platform-tools/adb -P 5037 -s D0AA002182JC0202126 shell 'settings delete global hidden_api_policy_pre_p_apps;settings delete global hidden_api_policy_p_apps;settings delete global hidden_api_policy''
[debug] [AppiumDriver@72ca] Event 'newSessionStarted' logged at 1695178273288 (19:51:13 GMT-0700 (Pacific Daylight Time))
[debug] [AppiumDriver@72ca] Encountered internal error running command: Error: The instrumentation process might fail to stop within 1000ms timeout.
[debug] [AppiumDriver@72ca]     at Object.errorAndThrow (/Users/kazu/GitHub/appium-uiautomator2-driver/node_modules/@appium/support/lib/logging.js:115:34)
[debug] [AppiumDriver@72ca]     at waitServiceStop (/Users/kazu/GitHub/appium-uiautomator2-driver/lib/uiautomator2.js:328:18)
[debug] [AppiumDriver@72ca]     at processTicksAndRejections (node:internal/process/task_queues:95:5)
[debug] [AppiumDriver@72ca]     at UiAutomator2Server.cleanupAutomationLeftovers (/Users/kazu/GitHub/appium-uiautomator2-driver/lib/uiautomator2.js:359:7)
[debug] [AppiumDriver@72ca]     at UiAutomator2Server.startSession (/Users/kazu/GitHub/appium-uiautomator2-driver/lib/uiautomator2.js:206:5)
[debug] [AppiumDriver@72ca]     at AndroidUiautomator2Driver.startUiAutomator2Session (/Users/kazu/GitHub/appium-uiautomator2-driver/lib/driver.js:430:5)
[debug] [AppiumDriver@72ca]     at AndroidUiautomator2Driver.createSession (/Users/kazu/GitHub/appium-uiautomator2-driver/lib/driver.js:241:7)
[debug] [AppiumDriver@72ca]     at AppiumDriver.createSession (/Users/kazu/.nvm/versions/node/v18.17.1/lib/node_modules/appium/lib/appium.js:374:35)
[HTTP] <-- POST /session 500 2814 ms - 696

mykola-mokhnach · 2023-09-20T05:50:59Z

lib/uiautomator2.js

+      try {
+        await waitForCondition(async () => {
+          try {
+            await this.jwproxy.command('/status', 'GET');


I assume jwproxy might not exist on this stage
Either perform requests using raw axios like we do it below or simply check the process existence using processExists API.

let me use axios one. thought the process check, but potentially the weird os situation could tell a lie (I don't have the env anymore, so cannot check that though)

Updated.

Latest error case:

[debug] [AndroidUiautomator2Driver@965b (79f6d2c7)] Performing shallow cleanup of automation leftovers [debug] [AndroidUiautomator2Driver@965b (79f6d2c7)] No obsolete sessions have been detected (socket hang up) [debug] [ADB] Running '/Users/kazu/Library/Android/sdk/platform-tools/adb -P 5037 -s D0AA002182JC0202126 shell am force-stop io.appium.uiautomator2.server.test' [AndroidUiautomator2Driver@965b (79f6d2c7)] The instrumentation process might fail to stop within 3000ms timeout. [debug] [AndroidUiautomator2Driver@965b (79f6d2c7)] Deleting UiAutomator2 session [debug] [AndroidUiautomator2Driver@965b (79f6d2c7)] Deleting UiAutomator2 server session [debug] [AndroidUiautomator2Driver@965b (79f6d2c7)] Matched '/' to command name 'deleteSession' [AndroidUiautomator2Driver@965b (79f6d2c7)] Did not get confirmation UiAutomator2 deleteSession worked; Error was: UnknownError: An unknown server-side error occurred while processing the command. Original error: Trying to proxy a session command without session id [debug] [ADB] Running '/Users/kazu/Library/Android/sdk/platform-tools/adb -P 5037 -s D0AA002182JC0202126 shell dumpsys activity services io.appium.settings/.recorder.RecorderService' [debug] [Logcat] Stopping logcat capture [debug] [ADB] Removing forwarded port socket connection: 8800

maybe something else is needed in addition to force-stop io.appium.uiautomator2.server.test to fully stop the automation. I expect to not see [AndroidUiautomator2Driver@965b (79f6d2c7)] The instrumentation process might fail to stop within 3000ms timeout.

Perhaps we should just kill all active instrumentation processes using adb.killProcessesByName ?
It is just necessary to check the actual ps output while it is running

Hm... killing all instrumentation process seems too aggressive...?

What I saw was kind of "delay", but it did not have multiple instrumentation processes. so for now, maybe we can see how this will help...?

after thinking a few, probably "waiting for the process might be stopped (no response for the port)" thing is sufficient for my observation at this time.
The session failure would occur in the createSession, so existing teardown can cover cases. The purpose of this is to make sure the process stop (and if not, let users know possible issue as a warning), thus just printing log is enough

lib/uiautomator2.js

## [2.29.9](v2.29.8...v2.29.9) (2023-09-21) ### Bug Fixes * check if the instrumentation process stops by sending a request ([#655](#655)) ([d42950a](d42950a))

github-actions · 2023-09-21T00:14:08Z

🎉 This PR is included in version 2.29.9 🎉

The release is available on:

Your semantic-release bot 📦🚀

fix: check if the instrumentation process stops by sending a request

aa33ce1

KazuCocoa requested review from jlipps and mykola-mokhnach September 20, 2023 04:54

mykola-mokhnach reviewed Sep 20, 2023

View reviewed changes

KazuCocoa added 2 commits September 19, 2023 23:18

chore: use process existence check instead

00613e6

use vanilla axios

c8f1e8f

mykola-mokhnach reviewed Sep 20, 2023

View reviewed changes

lib/uiautomator2.js Outdated Show resolved Hide resolved

change to warn

d149f8f

mykola-mokhnach reviewed Sep 20, 2023

View reviewed changes

lib/uiautomator2.js Outdated Show resolved Hide resolved

mykola-mokhnach approved these changes Sep 20, 2023

View reviewed changes

simplify a bit

ffa2cfc

mykola-mokhnach reviewed Sep 20, 2023

View reviewed changes

lib/uiautomator2.js Outdated Show resolved Hide resolved

mykola-mokhnach approved these changes Sep 20, 2023

View reviewed changes

Update uiautomator2.js

7a2ebe0

KazuCocoa merged commit d42950a into master Sep 21, 2023

KazuCocoa deleted the fix-service-stop branch September 21, 2023 00:12

github-actions bot pushed a commit that referenced this pull request Sep 21, 2023

chore(release): 2.29.9 [skip ci]

c03f829

## [2.29.9](v2.29.8...v2.29.9) (2023-09-21) ### Bug Fixes * check if the instrumentation process stops by sending a request ([#655](#655)) ([d42950a](d42950a))

github-actions bot added the released label Sep 21, 2023

KazuCocoa mentioned this pull request Jul 22, 2024

fix: stop io.appium.uiautomator2.server process as well (in cleanupAutomationLeftovers) #807

Merged

KazuCocoa mentioned this pull request Jul 31, 2024

Error when Performing Rotate Operation on Android Device using Java Appium Driver Client appium/appium#20422

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: check if the instrumentation process stops by sending a request #655

fix: check if the instrumentation process stops by sending a request #655

KazuCocoa commented Sep 20, 2023 •

edited

Loading

mykola-mokhnach Sep 20, 2023 •

edited

Loading

KazuCocoa Sep 20, 2023

KazuCocoa Sep 20, 2023

mykola-mokhnach Sep 20, 2023

mykola-mokhnach Sep 20, 2023 •

edited

Loading

KazuCocoa Sep 20, 2023

KazuCocoa Sep 20, 2023

github-actions bot commented Sep 21, 2023

fix: check if the instrumentation process stops by sending a request #655

fix: check if the instrumentation process stops by sending a request #655

Conversation

KazuCocoa commented Sep 20, 2023 • edited Loading

mykola-mokhnach Sep 20, 2023 • edited Loading

Choose a reason for hiding this comment

KazuCocoa Sep 20, 2023

Choose a reason for hiding this comment

KazuCocoa Sep 20, 2023

Choose a reason for hiding this comment

mykola-mokhnach Sep 20, 2023

Choose a reason for hiding this comment

mykola-mokhnach Sep 20, 2023 • edited Loading

Choose a reason for hiding this comment

KazuCocoa Sep 20, 2023

Choose a reason for hiding this comment

KazuCocoa Sep 20, 2023

Choose a reason for hiding this comment

github-actions bot commented Sep 21, 2023

KazuCocoa commented Sep 20, 2023 •

edited

Loading

mykola-mokhnach Sep 20, 2023 •

edited

Loading

mykola-mokhnach Sep 20, 2023 •

edited

Loading