Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: do not get active process information in a new session request #774

Merged
merged 2 commits into from
Sep 22, 2023

Conversation

KazuCocoa
Copy link
Member

@KazuCocoa KazuCocoa commented Sep 22, 2023

After some investigation, I found FBApplication *application = [FBSession activeSession].activeApplication; (called in the last of new session request

return FBResponseWithObject(FBSessionCommands.sessionInformation);
) could take 1 minute over when the view was com.apple.springboard in iOS. (e.g. no app/bundle id) It resulted in over 1 minute new session request time duration. It is pretty high.

Usually XCUITest driver's new session request completes in a few seconds, but in this situation, it could be 1 minute or so. The root cause was probably #772 . Resolving the springboard's application info, or the application's accessibility stuff is basically expensive.

Afaik, the response of WDA here is not important since https://github.com/appium/appium-xcuitest-driver/blob/master/lib/driver.js#L1352C9-L1352C24 does not have any references for the response. So we simply can remove them.

Instead, the new session request process speed will be able to keep fast by this. Only when bundle id is specified, launching it could take time by this.

Btw, because of the com.apple.springboard, like http://127.0.0.1:8100/wda/activeAppInfo endpoint also has the same issue. I observed resolving active application (and it is the springboard) could also take much longer time like this. But we do not have such endpoint call except for user's explicit call

@Dan-Maor
Copy link
Collaborator

This issue seems familiar, I may have seen it happen before.

Please check the testmanagerd logs in syslog when the issue occurs, if I remember correctly the last message that should appear before the 60 seconds hang would be something related to requesting an automation session endpoint. Is that the case here as well?

@KazuCocoa
Copy link
Member Author

KazuCocoa commented Sep 22, 2023

It seems yes. After around Getting the most recent active application log (this is WDA's one), 50 - 60 seconds had no response. I don't recall testmanagerd etc log well, but they also had no helpful messages usually printed without such hang.
This behavior itself could happen in http://127.0.0.1:8100/wda/activeAppInfo call as well. So far, maybe

[FBLogger logFmt:@"Getting the most recent active application (out of %@ total items)", @(activeApplicationElements.count)];
for (id<FBXCAccessibilityElement> appElement in activeApplicationElements) {
FBApplication *application = [FBApplication fb_applicationWithPID:appElement.processIdentifier];
if (nil != application) {
return application;
}
around here is relevant call, especially current active application was springboard. Other app's case did not in what i saw

After getting the response after 60 sec or around, the same call no longer takes such long wait. Probably this happens once? after starting WDA process. (this is my guess)

@Dan-Maor
Copy link
Collaborator

It could be the same issue I saw, but I can’t know for sure without the testmanagerd syslog output.

In my case, testmanagerd was trying to create an automation session against the target application in order to offload the automation heavy-lifting (objects hierarchy processing) to be done by the application under test using a communication endpoint. There’s a 60 seconds timeout for attempting to open the endpoint, and in cases it fails the process is marked as one in which processing needs to be done in testmanagerd side in the context of WDA (meaning the issue will occur again for the same process if WDA is restarted).

This usually happens if testmanagerd crashes during an objects automation operation, and in that case once testmanagerd restarts it tries to create new automation endpoints against target processes, however if a target process was previously automated, for the rest of its lifetime it can no longer accepts new requests for creating new automation endpoints since it thinks one is already open against the previously killed testmanagerd instance, hence the timeout.

This is usually resolved by restarting the target process, however since Springboard is not ever restarted during the device’s uptime the issue will be most noticeable with it (resolved by either killing Springboard forcefully or restarting the device).

@KazuCocoa
Copy link
Member Author

KazuCocoa commented Sep 22, 2023

Thanks for the details. Sounds like correct. Checked testmanagerd log a few, then I saw spring board operation by testmanagerd had 60 sec around wait, looks like.

With this PR, start a session -> killApp the spring board directly, then the springboard process gets restarted and the behavior backs to normal without the device reboot.

So, it looks like this pr itself makes sense to not block testmanagerd operation to the target app (e,g. spring board), then a user can kill the springboard process etc if needed before proceeding their automation in an appium session.

@KazuCocoa KazuCocoa changed the title fix: improve new session creation performance fix: do not get active process information in a new session request Sep 22, 2023
@KazuCocoa
Copy link
Member Author

ok, so this pr is removing testmanagerd communication (FBApplication *application = [FBSession activeSession].activeApplication) from the new session request handler. Users can terminate the test target after new session request to avoid this finding (possible 60 sec hang) in the appium session as test env setup. It will avoid this root cause.
For spring board, users can kill that with mobile:killApp (than, need to unlock the device screen etc) to proceed their test scenario instead of waiting 60 sec every session creation by this issue.

I'll write up this in xcuitest's troubleshooting after merging this

Copy link

@mykola-mokhnach mykola-mokhnach left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Theoretically this is a breaking change, but since we don't use this output anywhere it is probably fine...

@KazuCocoa
Copy link
Member Author

yea. let me change to "feat" to update as minor... probably better than patch. Maybe not necessary as a major version bump as no-usage

@KazuCocoa KazuCocoa changed the title fix: do not get active process information in a new session request feat: do not get active process information in a new session request Sep 22, 2023
@KazuCocoa KazuCocoa merged commit 2784ce4 into master Sep 22, 2023
43 of 45 checks passed
@KazuCocoa KazuCocoa deleted the remove-applicationinfo branch September 22, 2023 18:18
github-actions bot pushed a commit that referenced this pull request Sep 22, 2023
## [5.9.0](v5.8.7...v5.9.0) (2023-09-22)

### Features

* do not get active process information in a new session request ([#774](#774)) ([2784ce4](2784ce4))
@github-actions
Copy link

🎉 This PR is included in version 5.9.0 🎉

The release is available on:

Your semantic-release bot 📦🚀

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants