fix: Properly perform page readiness validation #356

mykola-mokhnach · 2024-02-11T17:06:36Z

The previous implementation was always waiting for 500ms before checking the page readiness. This one applies a proper race condition, so the validation starts immediately and thus could finish faster if the page loads fast enough.

mykola-mokhnach · 2024-02-11T17:07:33Z

I've also removed the pageLoadVerifyHook argument. Seems like it was some legacy stuff that was never actually used anywhere (I've verified this separately). Thus safe to remove

KazuCocoa · 2024-02-12T18:47:12Z

will test with real devices tonight

KazuCocoa · 2024-02-13T06:50:27Z

Can we relax the interval of document.readyState check a bit more?

On a real device, I observed high frequent document.readyState could make page load slow, or slow response by safari.

When I repeated opening https://yahoo.co.jp / https://rakuten.co.j from the US to Japan, so it was basically not so fast to load. Then, in current master generally complete the page load in 1500ms - 3000ms (so almost a couple of times's document.readyState check). This PR was 1100ms - 3000ms+. (This time is based on the response time for the client like <-- POST /session/819a6638-1d7e-462b-9b31-89e620d74fb8/url 200 1385 ms - 14's 1385 ms.)

Actually this PR improved fast case, but this pr slightly increased slow response or no response case than current master in my test. I'm not sure what exactly caused this slow behavior (my current guess is something JS handles in the Safari/WebInspector side, but I'm not sure of the root issue), but for now, relaxing the interval could improve the stability in this perspective.

Below is one example of no response case with this PR.

2024-02-13 06:39:55:209 - [HTTP] --> POST /session/b0bfcdfa-64ef-484b-9fea-c8b205ca03be/url
2024-02-13 06:39:55:209 - [HTTP] {"url":"https://rakuten.co.jp"}
2024-02-13 06:39:55:209 - [debug] [XCUITestDriver@4ee8 (b0bfcdfa)] Calling AppiumDriver.setUrl() with args: ["https://rakuten.co.jp","b0bfcdfa-64ef-484b-9fea-c8b205ca03be"]
2024-02-13 06:39:55:210 - [debug] [XCUITestDriver@4ee8 (b0bfcdfa)] Executing command 'setUrl'
2024-02-13 06:39:55:212 - [debug] [XCUITestDriver@4ee8 (b0bfcdfa)] Attempting to set url 'https://rakuten.co.jp'
2024-02-13 06:39:55:212 - [debug] [RemoteDebugger] Navigating to new URL: 'https://rakuten.co.jp'
2024-02-13 06:39:55:213 - [debug] [RemoteDebugger] Waiting for frame navigated message...
2024-02-13 06:39:55:214 - [debug] [RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:6545', page '1', target 'page-83' (id: 278): 'Page.navigate'
2024-02-13 06:39:55:389 - [debug] [RemoteDebugger] Received data response from send (id: 278): '{}'
2024-02-13 06:39:55:389 - [debug] [RemoteDebugger] Sending to Web Inspector took 176ms
2024-02-13 06:39:55:715 - [debug] [RemoteDebugger] Frame navigated in 501ms from: 500ms timeout
2024-02-13 06:39:56:391 - [debug] [RemoteDebugger] Waiting for dom...
2024-02-13 06:39:56:392 - [debug] [RemoteDebugger] Page loaded, waiting up to 6000ms until it is ready
2024-02-13 06:39:56:423 - [debug] [RemoteDebugger] Sending javascript command: 'document.readyState;'
2024-02-13 06:39:56:425 - [debug] [RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:6545', page '1', target 'page-83' (id: 280): 'Runtime.evaluate'
2024-02-13 06:39:56:645 - [debug] [RemoteDebugger] Received data response from send (id: 280): '"loading"'
2024-02-13 06:39:56:646 - [debug] [RemoteDebugger] Sending to Web Inspector took 222ms
2024-02-13 06:39:56:678 - [debug] [RemoteDebugger] Sending javascript command: 'document.readyState;'
2024-02-13 06:39:56:678 - [debug] [RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:6545', page '1', target 'page-83' (id: 282): 'Runtime.evaluate'
2024-02-13 06:39:56:703 - [debug] [RemoteDebugger] Received data response from send (id: 282): '"loading"'
2024-02-13 06:39:56:704 - [debug] [RemoteDebugger] Sending to Web Inspector took 26ms
2024-02-13 06:39:56:735 - [debug] [RemoteDebugger] Sending javascript command: 'document.readyState;'
2024-02-13 06:39:56:736 - [debug] [RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:6545', page '1', target 'page-83' (id: 284): 'Runtime.evaluate'
2024-02-13 06:39:56:762 - [debug] [RemoteDebugger] Received data response from send (id: 284): '"loading"'
2024-02-13 06:39:56:762 - [debug] [RemoteDebugger] Sending to Web Inspector took 27ms
2024-02-13 06:39:56:794 - [debug] [RemoteDebugger] Sending javascript command: 'document.readyState;'
2024-02-13 06:39:56:794 - [debug] [RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:6545', page '1', target 'page-83' (id: 286): 'Runtime.evaluate'
2024-02-13 06:39:56:807 - [debug] [RemoteDebugger] Received data response from send (id: 286): '"loading"'
2024-02-13 06:39:56:807 - [debug] [RemoteDebugger] Sending to Web Inspector took 14ms
2024-02-13 06:39:56:812 - [debug] [RemoteDebugger] Received page change notice for app 'PID:6545' but the listing has not changed. Ignoring.
2024-02-13 06:39:56:838 - [debug] [RemoteDebugger] Sending javascript command: 'document.readyState;'
2024-02-13 06:39:56:838 - [debug] [RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:6545', page '1', target 'page-83' (id: 288): 'Runtime.evaluate'
2024-02-13 06:40:01:842 - [debug] [RemoteDebugger] Page readiness check timed out after 5000ms
2024-02-13 06:40:01:874 - [debug] [RemoteDebugger] Sending javascript command: 'document.readyState;'
2024-02-13 06:40:01:874 - [debug] [RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:6545', page '1', target 'page-83' (id: 290): 'Runtime.evaluate'
2024-02-13 06:40:06:879 - [debug] [RemoteDebugger] Page readiness check timed out after 5000ms
2024-02-13 06:40:06:909 - [RemoteDebugger] Timed out after 6000ms of waiting for the page readiness. Continuing anyway
2024-02-13 06:40:06:912 - [debug] [RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:6545', page '1', target 'page-83' (id: 292): 'Console.enable'
2024-02-13 06:40:10:507 - [debug] [RemoteDebugger] Received page change notice for app 'PID:6545' but the listing has not changed. Ignoring.

# no response by Safari over a couple of minutes after this log. So this caused no response to the client. I killed the appium process to end the session eventually.

(no customization. Just started a session with browserName safari.)

mykola-mokhnach · 2024-02-13T07:33:35Z

I assume I need to take another approach for successful navigation detection, which is based on async listeners rther than the active polling. Maybe something similar to https://github.com/microsoft/playwright/blob/f605a5009b3c75746120a6ec6d940f62624af5ec/packages/playwright-core/src/client/frame.ts#L116

mykola-mokhnach · 2024-02-14T07:43:15Z

@KazuCocoa It looks like I've found a way to properly enable lifecycle events broadcast on all pages.

KazuCocoa · 2024-02-14T08:30:42Z

Checking with a944dde.
I met no return behavior as client as https://gist.github.com/KazuCocoa/63f221e31ee53b649cb296330eaf8b2f
The log had Page is ready in 3850ms but no response to the client. Maybe we could do something to return response to the client in this case?

I'm reading code as well

update: oh, maybe Console.enable did not get any response in this case

KazuCocoa · 2024-02-14T08:40:23Z

hm, once my previous comment case occurs, it looks like no longer web inspector responds responses while appium sends new commands

mykola-mokhnach · 2024-02-14T08:42:15Z

update: oh, maybe Console.enable did not get any response in this case

looks like that. I have disabled the wait for response there

KazuCocoa · 2024-02-14T09:02:08Z

It looks like this is not this PR itself, but let me leave note here.

When I kept opening a page repeatedly, suddenly the Safari no longer loaded page properly. I leave the log with my comment in https://gist.github.com/KazuCocoa/63f221e31ee53b649cb296330eaf8b2f?permalink_comment_id=4898811#gistcomment-4898811 After this behavior, it looks like Web Inspector no longer respond.

The same behavior occurs via WebInspecor (not via Appium) as well. So when I attached a page with Web Inspector and kept reloading the URL via the inspector, then the reload button no longer functioned. I mean the device's Safari no longer reloaded the page while the inspector tried to show some information. Once this circumstance occurred, the inspector no longer got the page source, etc, from Safari.

Bad thing as us is that Safari still worked via UI directly, I mean by my hand's direct interaction works. So this is Web Inspector/Safari internal issue by Apple I guess

To recover this situation, I needed to kill the safari process once and re-open the Safari. This is the same in appium session, so terminating the safari and activating it again, then I corrected the context, the same operation worked again.

KazuCocoa

This change itself looks good in my testing.
iOS 17 x Safari? has issue but it is maybe WebInspector/Safari related, not this change itself.

KazuCocoa · 2024-02-14T09:19:34Z

Hm, for the no function's case, what maybe we could do is instead of applying f1141a7 , if no response by browse against Console.enable, can we response an error message to the client...?

So the Concole.enable keeps waiting the response, and sendToDevice? will raise error if no response by Web Inspector in XXX seconds. (just an idea, not sure if we can add this in current implementation though, but just a note)

mykola-mokhnach · 2024-02-14T09:55:20Z

Hm, for the no function's case, what maybe we could do is instead of applying f1141a7 , if no response by browse against Console.enable, can we response an error message to the client...?

So the Concole.enable keeps waiting the response, and sendToDevice? will raise error if no response by Web Inspector in XXX seconds. (just an idea, not sure if we can add this in current implementation though, but just a note)

I've added a timeout there and a warning message. Does it make more sense to you?

KazuCocoa · 2024-02-14T10:12:38Z

lib/mixins/navigate.js

+      log.warn(
+        `Could not enable console events on the page '${this.pageIdKey}' (app '${this.appIdKey}') ` +
+        `within ${CONSOLE_ENABLEMENT_TIMEOUT_MS}ms. This might be an Inspector bug.`
+      );


thorw err; to return error to the client?

lets try this one first. Maybe it would still respond later...

I did more testing. There was no response for over 10 minutes on my env... and the only way to recover the situation was to restart the Safari process. So probably #359 might help.

Once this occurs, other commands such as driver.title also go to the same no response condition. Potentially we may need to add timeout error for other places in the future...

KazuCocoa · 2024-02-14T10:13:44Z

Yes, thank you. It is more clear than failing to load page silently (and return no-error)

## [11.0.0](v10.2.2...v11.0.0) (2024-02-14) ### ⚠ BREAKING CHANGES * Removed the pageUnload API * Removed the waitForFrameNavigated API * Removed the pageLoadVerifyHook argument from waitForDom and from navToUrl APIs ### Features * Properly perform page readiness validation ([#356](#356)) ([a2fbd5a](a2fbd5a))

github-actions · 2024-02-14T12:45:29Z

🎉 This PR is included in version 11.0.0 🎉

The release is available on:

Your semantic-release bot 📦🚀

fix: Properly perform page readiness validation

30f7a2b

mykola-mokhnach requested review from jlipps and KazuCocoa February 11, 2024 17:06

mykola-mokhnach added 5 commits February 11, 2024 18:09

delete extra logs

16b99db

less logs

23a33bb

timeout

a2efb36

simplify

8b38b1f

moar

be0651b

jlipps approved these changes Feb 12, 2024

View reviewed changes

mykola-mokhnach added 2 commits February 13, 2024 22:10

Address comments

8cc2a89

Enable console

a235f48

mykola-mokhnach marked this pull request as draft February 13, 2024 23:04

Add broadcast

ebd0306

mykola-mokhnach marked this pull request as ready for review February 14, 2024 07:42

tune readiness

a944dde

Do not wait for response

f1141a7

KazuCocoa approved these changes Feb 14, 2024

View reviewed changes

Add timeout

3770774

KazuCocoa reviewed Feb 14, 2024

View reviewed changes

mykola-mokhnach merged commit a2fbd5a into appium:master Feb 14, 2024
7 checks passed

mykola-mokhnach deleted the load_wait branch February 14, 2024 12:44

github-actions bot added the released label Feb 14, 2024

mykola-mokhnach mentioned this pull request Feb 14, 2024

chore: Bump remote debugger version appium/appium-xcuitest-driver#2328

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: Properly perform page readiness validation #356

fix: Properly perform page readiness validation #356

mykola-mokhnach commented Feb 11, 2024 •

edited

Loading

mykola-mokhnach commented Feb 11, 2024

KazuCocoa commented Feb 12, 2024

KazuCocoa commented Feb 13, 2024 •

edited

Loading

mykola-mokhnach commented Feb 13, 2024

mykola-mokhnach commented Feb 14, 2024

KazuCocoa commented Feb 14, 2024 •

edited

Loading

KazuCocoa commented Feb 14, 2024

mykola-mokhnach commented Feb 14, 2024

KazuCocoa commented Feb 14, 2024 •

edited

Loading

KazuCocoa left a comment

KazuCocoa commented Feb 14, 2024

mykola-mokhnach commented Feb 14, 2024

KazuCocoa Feb 14, 2024

mykola-mokhnach Feb 14, 2024

KazuCocoa Feb 14, 2024

KazuCocoa commented Feb 14, 2024

github-actions bot commented Feb 14, 2024

fix: Properly perform page readiness validation #356

fix: Properly perform page readiness validation #356

Conversation

mykola-mokhnach commented Feb 11, 2024 • edited Loading

mykola-mokhnach commented Feb 11, 2024

KazuCocoa commented Feb 12, 2024

KazuCocoa commented Feb 13, 2024 • edited Loading

mykola-mokhnach commented Feb 13, 2024

mykola-mokhnach commented Feb 14, 2024

KazuCocoa commented Feb 14, 2024 • edited Loading

KazuCocoa commented Feb 14, 2024

mykola-mokhnach commented Feb 14, 2024

KazuCocoa commented Feb 14, 2024 • edited Loading

KazuCocoa left a comment

Choose a reason for hiding this comment

KazuCocoa commented Feb 14, 2024

mykola-mokhnach commented Feb 14, 2024

KazuCocoa Feb 14, 2024

Choose a reason for hiding this comment

mykola-mokhnach Feb 14, 2024

Choose a reason for hiding this comment

KazuCocoa Feb 14, 2024

Choose a reason for hiding this comment

KazuCocoa commented Feb 14, 2024

github-actions bot commented Feb 14, 2024

mykola-mokhnach commented Feb 11, 2024 •

edited

Loading

KazuCocoa commented Feb 13, 2024 •

edited

Loading

KazuCocoa commented Feb 14, 2024 •

edited

Loading

KazuCocoa commented Feb 14, 2024 •

edited

Loading