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.

Sign up for GitHub

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

fix: Properly perform page readiness validation #356

Merged
merged 12 commits into from
Feb 14, 2024
Merged

fix: Properly perform page readiness validation #356

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
12 commits
Select commit Hold shift + click to select a range
30f7a2b
fix: Properly perform page readiness validation
mykola-mokhnach Feb 11, 2024
16b99db
delete extra logs
mykola-mokhnach Feb 11, 2024
23a33bb
less logs
mykola-mokhnach Feb 11, 2024
a2efb36
timeout
mykola-mokhnach Feb 11, 2024
8b38b1f
simplify
mykola-mokhnach Feb 11, 2024
be0651b
moar
mykola-mokhnach Feb 11, 2024
8cc2a89
Address comments
mykola-mokhnach Feb 13, 2024
a235f48
Enable console
mykola-mokhnach Feb 13, 2024
ebd0306
Add broadcast
mykola-mokhnach Feb 14, 2024
a944dde
tune readiness
mykola-mokhnach Feb 14, 2024
f1141a7
Do not wait for response
mykola-mokhnach Feb 14, 2024
3770774
Add timeout
mykola-mokhnach Feb 14, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion lib/mixins/connect.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -285,7 +285,7 @@ async function selectPage (appIdKey, pageIdKey, skipReadyCheck = false) {

// make sure everything is ready to go
if (!skipReadyCheck && !await this.checkPageIsReady()) {
await this.pageUnload();
await this.waitForDom();
}

log.debug(`Selected page after ${timer.getDuration().asMilliSeconds.toFixed(0)}ms`);
Expand Down
296 changes: 139 additions & 157 deletions lib/mixins/navigate.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,107 +5,98 @@ import { timing, util } from '@appium/support';
import _ from 'lodash';
import B from 'bluebird';

const DEFAULT_PAGE_READINESS_TIMEOUT_MS = 20 * 1000;
const PAGE_READINESS_CHECK_INTERVAL_MS = 50;
const CONSOLE_ENABLEMENT_TIMEOUT_MS = 1000;

/**
* @typedef {(() => Promise<any>|void)|undefined} TPageLoadVerifyHook
* @this {import('../remote-debugger').RemoteDebugger}
* @returns {void}
*/
function frameDetached () {
this.emit(events.EVENT_FRAMES_DETACHED);
}

/**
* @this {import('../remote-debugger').RemoteDebugger}
* @returns {void}
*/
function frameDetached () {
this.emit(events.EVENT_FRAMES_DETACHED);
function cancelPageLoad () {
log.debug('Unregistering from page readiness notifications');
this.pageLoading = false;
if (this.pageLoadDelay) {
this.pageLoadDelay.cancel();
}
}

/**
* @this {import('../remote-debugger').RemoteDebugger}
* @param {timing.Timer?} startPageLoadTimer
* @param {TPageLoadVerifyHook} [pageLoadVerifyHook]
* @param {timing.Timer|null|undefined} startPageLoadTimer
* @returns {Promise<void>}
*/
async function pageLoad (startPageLoadTimer, pageLoadVerifyHook = _.noop) {
const timeoutMs = 500;
async function waitForDom (startPageLoadTimer) {
log.debug('Waiting for page readiness');
const readinessTimeoutMs = this.pageLoadMs || DEFAULT_PAGE_READINESS_TIMEOUT_MS;
if (!_.isFunction(startPageLoadTimer?.getDuration)) {
log.debug(`Page load timer not a timer. Creating new timer`);
startPageLoadTimer = new timing.Timer().start();
}

log.debug('Page loaded, verifying whether ready');
let isPageLoading = true;
this.pageLoading = true;

const verify = async () => {
this.pageLoadDelay = util.cancellableDelay(timeoutMs);
try {
await this.pageLoadDelay;
} catch (err) {
if (err instanceof B.CancellationError) {
// if the promise has been cancelled
// we want to skip checking the readiness
this.pageLoadDelay = util.cancellableDelay(readinessTimeoutMs);
/** @type {B<void>} */
const pageReadinessPromise = B.resolve((async () => {
let retry = 0;
while (isPageLoading) {
// if we are ready, or we've spend too much time on this
// @ts-ignore startPageLoadTimer is defined here
const elapsedMs = startPageLoadTimer.getDuration().asMilliSeconds;
// exponential retry
const intervalMs = Math.min(
PAGE_READINESS_CHECK_INTERVAL_MS * Math.pow(2, retry),
readinessTimeoutMs - elapsedMs
);
await B.delay(intervalMs);
// we can get this called in the middle of trying to find a new app
if (!this.appIdKey) {
log.debug('Not connected to an application. Ignoring page readiess check');
return;
}
if (!isPageLoading) {
return;
}
}

// we can get this called in the middle of trying to find a new app
if (!this.appIdKey) {
log.debug('Not connected to an application. Ignoring page load');
return;
}

if (_.isFunction(pageLoadVerifyHook)) {
await pageLoadVerifyHook();
if (await this.checkPageIsReady()) {
if (isPageLoading) {
log.debug(`Page is ready in ${elapsedMs}ms`);
isPageLoading = false;
}
return;
}
if (elapsedMs > readinessTimeoutMs) {
log.info(`Timed out after ${readinessTimeoutMs}ms of waiting for the page readiness. Continuing anyway`);
isPageLoading = false;
return;
}
retry++;
}
})());
/** @type {B<void>} */
const cancellationPromise = B.resolve((async () => {
try {
await this.pageLoadDelay;
} catch (ign) {}
})());

// if we are ready, or we've spend too much time on this
// @ts-ignore startPageLoadTimer is defined here
const elapsedMs = startPageLoadTimer.getDuration().asMilliSeconds;
if (await this.checkPageIsReady() || (this.pageLoadMs > 0 && elapsedMs > this.pageLoadMs)) {
log.debug('Page is ready');
this.pageLoading = false;
} else {
log.debug('Page was not ready, retrying');
await verify();
}
};
try {
await verify();
await B.any([cancellationPromise, pageReadinessPromise]);
} finally {
// @ts-ignore startPageLoadTimer is defined here
log.debug(`Page load completed in ${startPageLoadTimer.getDuration().asMilliSeconds.toFixed(0)}ms`);
isPageLoading = false;
this.pageLoading = false;
this.pageLoadDelay = B.resolve();
}
}
/**
* @this {import('../remote-debugger').RemoteDebugger}
* @returns {void}
*/
function cancelPageLoad () {
log.debug('Unregistering from page readiness notifications');
this.pageLoading = false;
if (this.pageLoadDelay) {
this.pageLoadDelay.cancel();
}
}

/**
* @this {import('../remote-debugger').RemoteDebugger}
* @returns {Promise<void>}
*/
async function pageUnload () {
log.debug('Page unloading');
await this.waitForDom();
}

/**
* @this {import('../remote-debugger').RemoteDebugger}
* @param {timing.Timer|null|undefined} startPageLoadTimer
* @param {TPageLoadVerifyHook} [pageLoadVerifyHook]
* @returns {Promise<void>}
*/
async function waitForDom (startPageLoadTimer, pageLoadVerifyHook) {
log.debug('Waiting for dom...');
await this.pageLoad(startPageLoadTimer, pageLoadVerifyHook);
}

/**
* @this {import('../remote-debugger').RemoteDebugger}
Expand All @@ -114,125 +105,116 @@ async function waitForDom (startPageLoadTimer, pageLoadVerifyHook) {
async function checkPageIsReady () {
checkParams({appIdKey: this.appIdKey});

log.debug('Checking document readyState');
const readyCmd = 'document.readyState;';
let readyState = 'loading';
try {
readyState = await B.resolve(this.execute(readyCmd, true)).timeout(this.pageReadyTimeout);
const readyState = await B.resolve(this.execute(readyCmd, true)).timeout(this.pageReadyTimeout);
log.debug(`Document readyState is '${readyState}'`);
return readyState === 'complete';
} catch (err) {
if (!(err instanceof B.TimeoutError)) {
throw err;
}
log.debug(`Page readiness check timed out after ${this.pageReadyTimeout}ms`);
return false;
}
log.debug(`Document readyState is '${readyState}'`);

return readyState === 'complete';
}

/**
* @this {import('../remote-debugger').RemoteDebugger}
* @param {string} url
* @param {TPageLoadVerifyHook} [pageLoadVerifyHook]
* @returns {Promise<void>}
*/
async function navToUrl (url, pageLoadVerifyHook) {
async function navToUrl (url) {
checkParams({appIdKey: this.appIdKey, pageIdKey: this.pageIdKey});

if (!this.rpcClient) {
throw new Error('rpcClient is undefined. Is the debugger connected?');
}

this._navigatingToPage = true;
log.debug(`Navigating to new URL: '${url}'`);
const readinessTimeoutMs = this.pageLoadMs || DEFAULT_PAGE_READINESS_TIMEOUT_MS;
/** @type {(() => void)|undefined} */
let onPageLoaded;
/** @type {NodeJS.Timeout|undefined|null} */
let onPageLoadedTimeout;
this.pageLoadDelay = util.cancellableDelay(readinessTimeoutMs);
this.pageLoading = true;
let isPageLoading = true;
const start = new timing.Timer().start();

/** @type {B<void>} */
const pageReadinessPromise = new B((resolve) => {
onPageLoadedTimeout = setTimeout(() => {
if (isPageLoading) {
isPageLoading = false;
log.info(
`Timed out after ${start.getDuration().asMilliSeconds.toFixed(0)}ms of waiting ` +
`for the ${url} page readiness. Continuing anyway`
);
}
return resolve();
}, readinessTimeoutMs);

try {
log.debug(`Navigating to new URL: '${url}'`);

// begin listening for frame navigation event, which will be waited for later
const waitForFramePromise = this.waitForFrameNavigated();
onPageLoaded = () => {
if (isPageLoading) {
isPageLoading = false;
log.debug(`The page ${url} is ready in ${start.getDuration().asMilliSeconds.toFixed(0)}ms`);
}
if (onPageLoadedTimeout) {
clearTimeout(onPageLoadedTimeout);
onPageLoadedTimeout = null;
}
return resolve();
};
// https://chromedevtools.github.io/devtools-protocol/tot/Page/#event-loadEventFired
this.rpcClient?.once('Page.loadEventFired', onPageLoaded);

await this.rpcClient.send('Page.navigate', {
this.rpcClient?.send('Page.navigate', {
url,
appIdKey: this.appIdKey,
pageIdKey: this.pageIdKey,
});
});
/** @type {B<void>} */
const cancellationPromise = B.resolve((async () => {
try {
await this.pageLoadDelay;
} catch (ign) {}
})());

if (!this.useNewSafari) {
// a small pause for the browser to catch up
await B.delay(1000);
}

// wait until the page has been navigated
await waitForFramePromise;

await this.waitForDom(new timing.Timer().start(), pageLoadVerifyHook);

// enable console logging, so we get the events (otherwise we only
// get notified when navigating to a local page
await this.rpcClient.send('Console.enable', {
appIdKey: this.appIdKey,
pageIdKey: this.pageIdKey,
});
try {
await B.any([cancellationPromise, pageReadinessPromise]);
} finally {
this.pageLoading = false;
isPageLoading = false;
this._navigatingToPage = false;
}
}

/**
* @this {import('../remote-debugger').RemoteDebugger}
* @returns {Promise<any>}
*/
async function waitForFrameNavigated () {
let navEventListener;
return await new B(async (resolve) => {
log.debug('Waiting for frame navigated message...');
if (!this.rpcClient) {
throw new Error('rpcClient is undefined. Is the debugger connected?');
this.pageLoadDelay = B.resolve();
if (onPageLoadedTimeout && pageReadinessPromise.isFulfilled()) {
clearTimeout(onPageLoadedTimeout);
onPageLoadedTimeout = null;
}
const start = new timing.Timer().start();

// add a handler for the `Page.frameNavigated` message
// from the remote debugger
navEventListener = (err, value) => {
log.debug(`Frame navigated in ${start.getDuration().asMilliSeconds.toFixed(0)}ms from: ${value}`);
if (!this.allowNavigationWithoutReload && !this.pageLoading) {
resolve(value);
} else {
log.debug('Frame navigated but we were warned about it, not ' +
'considering page state unloaded');
this.allowNavigationWithoutReload = false;
}
if (this.navigationDelay) {
this.navigationDelay.cancel();
}
};

this.rpcClient.once('Page.frameNavigated', navEventListener);

// timeout, in case remote debugger doesn't respond,
// or takes a long time
if (!this.useNewSafari || this.pageLoadMs >= 0) {
// use pageLoadMs, or a small amount of time
const timeout = this.useNewSafari ? this.pageLoadMs : 500;
this.navigationDelay = util.cancellableDelay(timeout);
try {
await this.navigationDelay;
navEventListener(null, `${timeout}ms timeout`);
} catch (err) {
// nothing to do: we only get here if the remote debugger
// already notified of frame navigation, and the delay
// was cancelled
}
if (onPageLoaded) {
this.rpcClient.off('Page.loadEventFired', onPageLoaded);
}
}).finally(() => {
if (navEventListener) {
this.rpcClient?.off('Page.frameNavigated', navEventListener);
}

// enable console logging, so we get the events (otherwise we only
// get notified when navigating to a local page
try {
await B.resolve(this.rpcClient.send('Console.enable', {
appIdKey: this.appIdKey,
pageIdKey: this.pageIdKey,
})).timeout(CONSOLE_ENABLEMENT_TIMEOUT_MS);
} catch (err) {
if (err instanceof B.TimeoutError) {
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.`
);
Copy link
Member

Choose a reason for hiding this comment

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

thorw err; to return error to the client?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

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

Copy link
Member

Choose a reason for hiding this comment

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

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...

} else {
throw err;
}
});
}
}


export default {
frameDetached, pageLoad, cancelPageLoad, pageUnload, waitForDom, checkPageIsReady, navToUrl, waitForFrameNavigated
};
export default {frameDetached, cancelPageLoad, waitForDom, checkPageIsReady, navToUrl};
Loading
Loading