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

handle "Paste from other apps" alert become extremely slow( cost 3 min) with wait.until(ExpectedConditions.alertIsPresent()) and base.getIosDriver().switchTo().alert().accept() after upgrading the xcuitest driver to version 6.0.0 (also tried version 7.1.0, same issue exists)) #19814

Closed
3 tasks done
Rosepotato opened this issue Feb 21, 2024 · 21 comments
Labels
ThirdParty upstream problems XCUITest regarding xcuitest driver

Comments

@Rosepotato
Copy link

Rosepotato commented Feb 21, 2024

Do I have the most recent component updates?

  • I use the most recent available driver/plugin and server versions

Is the component officially supported by the Appium team?

  • I have verified the component repository is present under the Appium organization in GitHub

Is there an existing issue for this?

  • I have searched the existing issues

Current Behavior

2024-02-20 03:33:16:234 - [HTTP] --> GET /session/2324dd1a-87cf-472d-97ec-8cbf70c6c40f/alert/text
2024-02-20 03:33:16:234 - [HTTP] {}
2024-02-20 03:34:16:644 - [HTTP] <-- GET /session/2324dd1a-87cf-472d-97ec-8cbf70c6c40f/alert/text 200 60411 ms - 110
2024-02-20 03:34:16:644 - [HTTP]
2024-02-20 03:34:22:450 - [HTTP] --> GET /session/2324dd1a-87cf-472d-97ec-8cbf70c6c40f/alert/text
2024-02-20 03:34:22:450 - [HTTP] {}
2024-02-20 03:35:22:748 - [HTTP] <-- GET /session/2324dd1a-87cf-472d-97ec-8cbf70c6c40f/alert/text 200 60298 ms - 110
2024-02-20 03:35:22:748 - [HTTP]

2024-02-20 03:35:22:751 - [HTTP] --> POST /session/2324dd1a-87cf-472d-97ec-8cbf70c6c40f/alert/accept
2024-02-20 03:35:22:752 - [HTTP] {}
2024-02-20 03:36:23:861 - [HTTP] <-- POST /session/2324dd1a-87cf-472d-97ec-8cbf70c6c40f/alert/accept 200 61110 ms - 14

Expected Behavior

Can get quick response when handle the alert as before.

e.g. on xcuitest driver version 5.16.1.

2024-02-21 01:59:11:114 - [HTTP] --> GET /session/a3b9be09-c7b6-4517-abfe-ca43a660ea3a/alert/text
2024-02-21 01:59:11:114 - [HTTP] {}
2024-02-21 01:59:11:244 - [HTTP] <-- GET /session/a3b9be09-c7b6-4517-abfe-ca43a660ea3a/alert/text 200 130 ms - 110
2024-02-21 01:59:11:244 - [HTTP] 
2024-02-21 01:59:11:245 - [HTTP] --> GET /session/a3b9be09-c7b6-4517-abfe-ca43a660ea3a/alert/text
2024-02-21 01:59:11:245 - [HTTP] {}
2024-02-21 01:59:11:324 - [HTTP] <-- GET /session/a3b9be09-c7b6-4517-abfe-ca43a660ea3a/alert/text 200 78 ms - 110
2024-02-21 01:59:11:324 - [HTTP] 
2024-02-21 01:59:11:325 - [HTTP] --> POST /session/a3b9be09-c7b6-4517-abfe-ca43a660ea3a/alert/accept
2024-02-21 01:59:11:325 - [HTTP] {}
2024-02-21 01:59:12:277 - [HTTP] <-- POST /session/a3b9be09-c7b6-4517-abfe-ca43a660ea3a/alert/accept 200 951 ms - 14

Minimal Reproducible Example

  1. call base.getIosDriver().setClipboardText(text)
  2. "Paste from other apps" permission dialog is triggered
Screenshot 2024-02-21 at 14 28 18
  1. use the following acceptAlert method to accept the alert.
public static boolean acceptAlert(TestBase base, long waitTimeInSec) {
        if(base.isIOS()) {
            WebDriverWait wait = new WebDriverWait(base.getIosDriver(), Duration.ofSeconds(waitTimeInSec));
            try {
                wait.until(ExpectedConditions.alertIsPresent());
                base.getIosDriver().switchTo().alert().accept();
                return true;
            } catch (Exception e) {
                System.err.println("   no alert visible after " + waitTimeInSec + " sec.");
                return false;
            }
        }
        return true;
    }
  1. got really slow response for alert get/post command with xcuitest version 6.0.0

Environment

  • Operating system: macOS Sonoma Version 14.2.1 (23C71)
  • Appium server version (output of appium --version): 2.5.1
  • Appium driver(s) and their version(s): xcuitest 6.0.0
  • Appium plugin(s) and their version(s): execute-driver 3.0.25
  • Node.js version (output of node --version):v18.10.0
  • npm version (output of npm --version):8.19.2
  • Last component(s) version which did not exhibit the problem: xcuitest 5.16.1 works fine, all the other envs are the same
  • Platform and version under test: xcode 15.0.1, ios 17.0.1
  • Real device or emulator/simulator: iOS simulator
  • Selenium-java version 4.17.0
  • Appium java-client version 9.1.0.

Link to Appium Logs

No response

Further Information

No response

@Rosepotato Rosepotato added Bug a problem that needs fixing Needs Triage bugs which are not yet confirmed labels Feb 21, 2024
@Rosepotato Rosepotato changed the title handle "Paste from other apps" alert become extremely slow( cost 3 min) with wait.until(ExpectedConditions.alertIsPresent()) and base.getIosDriver().switchTo().alert().accept() after upgrading the xcuitest driver to version 6.0.0 handle "Paste from other apps" alert become extremely slow( cost 3 min) with wait.until(ExpectedConditions.alertIsPresent()) and base.getIosDriver().switchTo().alert().accept() after upgrading the xcuitest driver to version 6.0.0 (also tried version 7.1.0, same issue exists)) Feb 21, 2024
@mykola-mokhnach mykola-mokhnach added XCUITest regarding xcuitest driver and removed Needs Triage bugs which are not yet confirmed labels Feb 21, 2024
@mykola-mokhnach
Copy link
Collaborator

Try to activate the springboard app before interacting with the alert as described in https://github.com/appium/appium-xcuitest-driver/blob/master/docs/guides/troubleshooting.md#interact-with-dialogs-managed-by-comapplespringboard

@mykola-mokhnach mykola-mokhnach added the Needs Info typically non-actionable; needs author to respond label Feb 21, 2024
@mykola-mokhnach
Copy link
Collaborator

@Dan-Maor Do you have an idea what exactly may cause the delay? I've prepared appium/WebDriverAgent#851, but I'm also not 100% sure it is going to address it if I don't know the cause

@Dan-Maor
Copy link
Contributor

I sometimes observed a "round" 1 minute duration when testmanagerd fails to open a direct connection to the application under test with the action succeeding in the way of a fallback. I'm not testing with simulators often, this is a behavior I've seen with real devices (haven't encountered it for a long time though), however it might be a similar case here.

@Rosepotato will you be able to attach the simulator syslog captured while the scenario is performed?

Regardless, this looks like something specific in this app's scenario since I'm unable to reproduce the issue with various Springboard alerts (allow notification, pasteboard, location) with a simulator or a real device. Keep in mind, I am using Xcode 15.2 and don't have Xcode 15.0 available at the moment, so perhaps it is worth checking whether updating to Xcode 15.2 would help.

@Rosepotato
Copy link
Author

Rosepotato commented Feb 22, 2024

@Dan-Maor I have attached the full log including the IOSSimulatorLog. You can search the logs by "alert/text" and "alert/accept". And I use selenium-java version 4.17.0 and java-client version 9.1.0.

    <dependency>
        <groupId>org.seleniumhq.selenium</groupId>
        <artifactId>selenium-java</artifactId>
        <version>4.17.0</version>
    </dependency>

    <dependency>
        <groupId>io.appium</groupId>
        <artifactId>java-client</artifactId>
        <version>9.1.0</version>
    </dependency>

alertLog.txt

@Rosepotato
Copy link
Author

Rosepotato commented Feb 22, 2024

@mykola-mokhnach I have tried this way mentioned in (https://github.com/appium/appium-xcuitest-driver/blob/master/docs/guides/troubleshooting.md#interact-with-dialogs-managed-by-comapplespringboard), still need 1 min to accept the alert.

fun IOSDriver.acceptAlert(){
    val args: MutableMap<String, Any> = HashMap()
    args["action"] = "accept"
    this.executeScript("mobile: alert", args)
}

@mykola-mokhnach
Copy link
Collaborator

I've actually asked to try a different workaround:

Try to activate the springboard app before interacting with the alert

@Rosepotato
Copy link
Author

Rosepotato commented Feb 22, 2024

@mykola-mokhnach Switching between test app and springboard app is not a good way for my whole test logic. I'd prefer to keep my own test app in active status. Are there anything significant changes since xcuitest driver version 6.0.0? I see that wda 6.0 is bound to xcuitest driver since version 6.0.0. Not sure if issue comes out of new wda. The strange thing is that pasteboard alert is handled quickly just before the xcuitest driver version 6.0.0.

@mykola-mokhnach
Copy link
Collaborator

@Dan-Maor

I assume this is the main cause:

2024-02-22 03:16:36:399 - [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2024-02-22 11:16:36.398 E  testmanagerd[97169:15855d] [com.apple.dt.xctest:Default] XCTAS Error: XCTAutomationSupportErrorUnknownElement: Error getting main window kAXErrorIPCTimeout
2024-02-22 03:16:36:400 - [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2024-02-22 11:16:36.398 E  testmanagerd[97169:2c9c9a] [com.apple.dt.xctest:Default] XCTAS Error: Error Domain=com.apple.dt.xctest.automation-support.error Code=7 "XCTPerformOnMainRunLoop work timed out after 60.0s" UserInfo={NSLocalizedDescription=XCTPerformOnMainRunLoop work timed out after 60.0s}
2024-02-22 03:16:36:400 - [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2024-02-22 11:16:36.399 E  testmanagerd[97169:15855d] [com.apple.dt.xctest:Default] XCTAS Error: Error Domain=com.apple.dt.xctest.automation-support.error Code=8 "Error getting main window kAXErrorIPCTimeout" UserInfo={NSLocalizedDescription=Error getting main window kAXErrorIPCTimeout}

@Dan-Maor
Copy link
Contributor

Thanks for providing the logs @Rosepotato
It looks like the issue is testmanagerd hanging for 60 seconds trying to retrieve the main window in order to get accessibility information:

2024-02-22 03:16:36:399 - [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2024-02-22 11:16:36.398 E  testmanagerd[97169:15855d] [com.apple.dt.xctest:Default] XCTAS Error: XCTAutomationSupportErrorUnknownElement: Error getting main window kAXErrorIPCTimeout
2024-02-22 03:16:36:400 - [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2024-02-22 11:16:36.398 E  testmanagerd[97169:2c9c9a] [com.apple.dt.xctest:Default] XCTAS Error: Error Domain=com.apple.dt.xctest.automation-support.error Code=7 "XCTPerformOnMainRunLoop work timed out after 60.0s" UserInfo={NSLocalizedDescription=XCTPerformOnMainRunLoop work timed out after 60.0s}
2024-02-22 03:16:36:400 - [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2024-02-22 11:16:36.399 E  testmanagerd[97169:15855d] [com.apple.dt.xctest:Default] XCTAS Error: Error Domain=com.apple.dt.xctest.automation-support.error Code=8 "Error getting main window kAXErrorIPCTimeout" UserInfo={NSLocalizedDescription=Error getting main window kAXErrorIPCTimeout}

I also noticed that you're capturing a video during your test, and during the paste attempt screenshots are failing as well:

2024-02-22 03:15:37:503 - [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2024-02-22 11:15:37.503 Df WebDriverAgentRunner-Runner[13772:2c9d22] (WebDriverAgentLib) Error Domain=com.facebook.WebDriverAgent Code=1 "Cannot take a screenshot within 20000 ms timeout" UserInfo={NSLocalizedDescription=Cannot take a screenshot within 20000 ms timeout}

I wrote a simple app which access the UIPasteboard in a loop on the main thread and managed to reproduce the issue - testamangerd hanged. Accessing it from a block using detachNewThreadWithBlock did not cause the hang.

Accessing the pasteboard on the main thread of an app - given that UI operations and interactions (elements retrieval and screenshots) rely on the target application main queue to be idle - could be the reason for testmanagerd hanging.

@Rosepotato Are you are you accessing UIPasteboard on the main thread of your application?

@Rosepotato
Copy link
Author

@Dan-Maor Good to know that you can reproduce it. I have confirmed with our iOS developer that we access UIPasteboard on the main thread of our application. I attached a video. You can have a check.

SPND2698_sendMemberRequestByPasteFromClipboard.sendMemberRequestByPasteFromClipboard.mp4

@Dan-Maor
Copy link
Contributor

Thanks for confirming.

I find it quite strange that this scenario hangs only on WDA above 6 since I am able to reproduce the flow using older WDA releases as well. If the application's main run loop is held by repeated calls to pasteboard then it stands to reason that testmanagerd won't be able to use it since it's not idle.

Will you be able to repeat the flow with an older XCUITest driver version while capturing the syslog and attach it here? Perhaps I could spot a difference in the behavior that way. Please use the same Xcode and OS versions.

@mykola-mokhnach
Copy link
Collaborator

mykola-mokhnach commented Feb 22, 2024

@Dan-Maor The main difference between v5 and v6 version of the driver is that the logic for active app detection has been optimised. Now we assume the active app is always the app under test as soon as it is in Running foreground state instead of checking to which app a random on-screen pixel belongs.
As far as I can understand in this particular situation with springboard alert shown xcuitest still marks the app under test as running in foreground (and thus it is selected as active) even though it is covered by the springboard alert (the springboard always has "running in foreground" state).
This is also the reason why there was no delay in v5 - it did not even try to ask the app under test if it has an alert, but was requesting the springboard first.
As a conclusion I would say it is not a bug, but a feature, because it also helps to figure out bugs in the app that cause blockage on the main run loop.

@mykola-mokhnach mykola-mokhnach added ThirdParty upstream problems and removed Bug a problem that needs fixing Needs Info typically non-actionable; needs author to respond labels Feb 22, 2024
@Rosepotato
Copy link
Author

@Dan-Maor What's the conclusion for this issue? not a bug, just a intended changes in xcuitest v6? Do I need to provide the syslog with older version again?

@Dan-Maor
Copy link
Contributor

@Rosepotato I tend to agree with @mykola-mokhnach that the new behavior is intended, so syslog from v5 is not needed at this point.

@Rosepotato
Copy link
Author

@Dan-Maor @mykola-mokhnach still cost 3 mins after activate sprintboard app whether by mobile: activateApp or getIosDriver().activateApp("com.apple.springboard") before interact with the pasteboard alert on xcuitest version v7.1.0.

public static boolean acceptAlert(TestBase base, long waitTimeInSec) {
        if(base.isIOS()) {
//            base.getIosDriver().activateApp("com.apple.springboard");
            IosUtils.activateApp(base, "com.apple.springboard");
            WebDriverWait wait = new WebDriverWait(base.getIosDriver(), Duration.ofSeconds(waitTimeInSec));
            try {
                wait.until(ExpectedConditions.alertIsPresent());
                base.getIosDriver().switchTo().alert().accept();
                return true;
            } catch (Exception e) {
                System.err.println("   no alert visible after " + waitTimeInSec + " sec.");
                return false;
            }
            finally {
                base.getIosDriver().activateApp(TestBase.getBundleId());
            }
        }
        return true;
    }

    public static boolean activateApp(TestBase base, String bundleId) {
        if(base.isIOS()) {
            try {
                HashMap<String, String> args = new HashMap();
                args.put("bundleId", bundleId);
                base.getIosDriver().executeScript("mobile: activateApp", args);
                return true;
            } catch (Exception e) {
                System.err.println("Error happened when activateSpringboardApp!!!");
                return false;
            }
        }
        return true;
    }
2024-02-23 06:52:00:886 - [HTTP] --> POST /session/2030e78b-b604-487f-abb2-59ac612b0d77/execute/sync
2024-02-23 06:52:00:886 - [HTTP] {"args":[{"bundleId":"com.apple.springboard"}],"script":"mobile: activateApp"}
2024-02-23 06:52:00:971 - [HTTP] <-- POST /session/2030e78b-b604-487f-abb2-59ac612b0d77/execute/sync 200 85 ms - 14
2024-02-23 06:52:00:971 - [HTTP] 
2024-02-23 06:52:00:977 - [HTTP] --> GET /session/2030e78b-b604-487f-abb2-59ac612b0d77/alert/text
2024-02-23 06:52:00:977 - [HTTP] {}
2024-02-23 06:53:01:270 - [HTTP] <-- GET /session/2030e78b-b604-487f-abb2-59ac612b0d77/alert/text 200 60291 ms - 110
2024-02-23 06:53:01:270 - [HTTP] 
2024-02-23 06:53:01:276 - [HTTP] --> GET /session/2030e78b-b604-487f-abb2-59ac612b0d77/alert/text
2024-02-23 06:53:01:276 - [HTTP] {}
2024-02-23 06:54:01:526 - [HTTP] <-- GET /session/2030e78b-b604-487f-abb2-59ac612b0d77/alert/text 200 60248 ms - 110
2024-02-23 06:54:01:526 - [HTTP] 
2024-02-23 06:54:01:530 - [HTTP] --> POST /session/2030e78b-b604-487f-abb2-59ac612b0d77/alert/accept
2024-02-23 06:54:01:530 - [HTTP] {}
2024-02-23 06:55:02:564 - [HTTP] <-- POST /session/2030e78b-b604-487f-abb2-59ac612b0d77/alert/accept 200 61032 ms - 14
2024-02-23 06:55:02:564 - [HTTP] 

@Rosepotato
Copy link
Author

@Dan-Maor @mykola-mokhnach Use mobile: activateApp to activate the springboard app, then call mobile: alert to accept the alert, still cost around 1 mins per alert request, I think it's not acceptable for so slow response.
I attached the full log with syslog. You can search by "/execute/sync".

Uploading alertLogActivateApp.txt…

2024-02-23 07:19:47:353 - [HTTP] --> POST /session/1f09c993-d82a-4858-a363-8b883a8f6924/execute/sync
2024-02-23 07:19:47:353 - [HTTP] {"args":[{"bundleId":"com.apple.springboard"}],"script":"mobile: activateApp"}
2024-02-23 07:19:47:452 - [HTTP] <-- POST /session/1f09c993-d82a-4858-a363-8b883a8f6924/execute/sync 200 98 ms - 14
2024-02-23 07:19:47:452 - [HTTP] 
2024-02-23 07:19:47:454 - [HTTP] --> POST /session/1f09c993-d82a-4858-a363-8b883a8f6924/execute/sync
2024-02-23 07:19:47:454 - [HTTP] {"args":[{"action":"accept"}],"script":"mobile: alert"}
2024-02-23 07:20:48:612 - [HTTP] <-- POST /session/1f09c993-d82a-4858-a363-8b883a8f6924/execute/sync 200 61156 ms - 14

@Rosepotato
Copy link
Author

@Dan-Maor @mykola-mokhnach I tried another suggested way as the following steps (didn't call "mobile: activateApp" here), still cost more than 1 min to accept the alert.
Steps:

  1. base.getIosDriver().setSetting("acceptAlertButtonSelector", "//XCUIElementTypeButton[@Label='Allow Paste']");
  2. call acceptAlert2
    public static boolean acceptAlert2(TestBase base) {
    if(base.isIOS()) {
    try {
    HashMap<String, String> args = new HashMap();
    args.put("action", "accept");
    base.getIosDriver().executeScript("mobile: alert", args);
    return true;
    } catch (Exception e) {
    System.err.println("Error happened when accept the alert!!!");
    return false;
    }
    }
    return true;
    }
2024-02-23 08:13:59:932 - [HTTP] --> POST /session/1995decb-2ef2-423f-b553-5ba554add3fd/appium/settings
2024-02-23 08:13:59:932 - [HTTP] {"settings":{"acceptAlertButtonSelector":"//XCUIElementTypeButton[@label='Allow Paste']"}}
2024-02-23 08:13:59:946 - [HTTP] <-- POST /session/1995decb-2ef2-423f-b553-5ba554add3fd/appium/settings 200 14 ms - 14
2024-02-23 08:13:59:946 - [HTTP] 
2024-02-23 08:13:59:950 - [HTTP] --> POST /session/1995decb-2ef2-423f-b553-5ba554add3fd/execute/sync
2024-02-23 08:13:59:950 - [HTTP] {"script":"mobile: alert","args":[{"action":"accept"}]}
2024-02-23 08:15:01:030 - [HTTP] <-- POST /session/1995decb-2ef2-423f-b553-5ba554add3fd/execute/sync 200 61079 ms - 14
2024-02-23 08:15:01:030 - [HTTP] 

@Rosepotato
Copy link
Author

@Dan-Maor I attached a log file with older xcuitest version 5.16.1 which has quick response for alert handling. Hope it's helpful.

alertXcuitest5.16.1.txt

@Dan-Maor
Copy link
Contributor

@Rosepotato can you please try again using xcuitest version 7.1.1? (released a few hours ago) which contains @mykola-mokhnach 's fix, in the reproduction scenario I created it seems to have fixed the issue. If the issue still occurs, please let us know and if possible attach the syslog of the execution.

@fleytman
Copy link

I am reproducing this problem as well. When the application starts, the notification alert appears on the authorization screen and in the inspector the structure of the authorization screen, not the dialog with the alert. Version 7.1.2 did not fix the problem. On version 5.16.1 it works with no problem.

This causes all tests to stop working. Judging by Rosepotato's posts, the old mechanism was more efficient. I guess not so many people have upgraded and encountered the problem (usually you upgrade when the new Xcode/sumulator stops working on the old driver version).

@Rosepotato
Copy link
Author

Rosepotato commented Feb 26, 2024

@Dan-Maor Great work! I tested the xcuitest v7.1.2. The alert handling response is much quicker(almost the same as that in xcuitest v5.16.1)

2024-02-26 02:13:30:454 - [HTTP] --> GET /session/a4180aac-f140-4780-a379-ead7b8007220/alert/text
2024-02-26 02:13:30:454 - [HTTP] {}
2024-02-26 02:13:30:685 - [HTTP] <-- GET /session/a4180aac-f140-4780-a379-ead7b8007220/alert/text 200 231 ms - 110
2024-02-26 02:13:30:685 - [HTTP]
2024-02-26 02:13:30:687 - [HTTP] --> POST /session/a4180aac-f140-4780-a379-ead7b8007220/alert/accept
2024-02-26 02:13:31:614 - [HTTP] <-- POST /session/a4180aac-f140-4780-a379-ead7b8007220/alert/accept 200 927 ms - 14

alert7.1.2.txt.zip

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
ThirdParty upstream problems XCUITest regarding xcuitest driver
Projects
None yet
Development

No branches or pull requests

4 participants