fix: Properly perform page readiness validation

[mykola-mokhnach]

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]

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]

will test with real devices tonight

[KazuCocoa]

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]

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]

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

[KazuCocoa]

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]

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

[mykola-mokhnach]

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]

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]

Hm, for the no function's case, what maybe we could do is instead of applying https://github.com/appium/appium-remote-debugger/pull/356/commits/f1141a7a460a6a6e0de819a76b7febeeaf8921e9 , 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]

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]

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

[github-actions[bot]]

:tada: This PR is included in version 11.0.0 :tada:

The release is available on:

• npm package (@latest dist-tag)
• GitHub release

Your semantic-release bot :package::rocket: