diff --git a/config/scripts/mobile-web-app-html-preview-render.test.mjs b/config/scripts/mobile-web-app-html-preview-render.test.mjs index 9ce903b3f3d..fc794241d71 100644 --- a/config/scripts/mobile-web-app-html-preview-render.test.mjs +++ b/config/scripts/mobile-web-app-html-preview-render.test.mjs @@ -34,6 +34,7 @@ import { } from './mobile-web-app-render-harness.mjs' import { createCspReportSink, reportedDirectives } from './mobile-web-app-preview-csp-reports.mjs' import { recordRequestsTo } from './mobile-web-app-preview-request-log.mjs' +import { watchImageEvidence } from './mobile-web-app-preview-image-evidence.mjs' import { ARTIFACT_RGB, ENTRY_SOURCE, @@ -246,7 +247,10 @@ async function open( const page = await context.newPage() // Subscribed before the first navigation, so a request made during load is in the log. Cheap // while an arm passes: it fills arrays, and only an abort asks them to speak. - const describeRequests = await recordRequestsTo(page, SECURE_ORIGIN) + const requestLog = await recordRequestsTo(page, SECURE_ORIGIN) + // Asked only when an arm has aborted, so the fresh-image probe and its wait cost a failing run + // and never a passing one. + const describeRequests = watchImageEvidence(page, SECURE_ORIGIN, requestLog) try { const navigations = [] const popups = [] @@ -371,7 +375,8 @@ async function open( await settleAfterMount(page, navigations, expectNavigation, signal, { frame: artifactFrame, browserVersion, - arm + arm, + describeRequests }) const result = { page, diff --git a/config/scripts/mobile-web-app-preview-frame-readiness.mjs b/config/scripts/mobile-web-app-preview-frame-readiness.mjs index dd95bb8e2f2..c994afa1fc6 100644 --- a/config/scripts/mobile-web-app-preview-frame-readiness.mjs +++ b/config/scripts/mobile-web-app-preview-frame-readiness.mjs @@ -206,7 +206,7 @@ async function describeAdmittedImages(page, readImageHits, describeRequests) { const reading = image === false ? 'the reading never answered' : image // What the browser said about the requests themselves, which is where a request that never // reached the rig's route handler is distinguishable from one the page never made. - const requests = describeRequests?.() ?? 'no request log for this arm' + const requests = (await describeRequests?.(frame)) ?? 'no request log for this arm' return `the arm recorded ${JSON.stringify(readImageHits())} of ${JSON.stringify(ADMITTED_IMAGE_PATHS)}; #remote ${JSON.stringify(reading)}; ${requests}` } @@ -288,9 +288,14 @@ export async function waitForRecordedNavigation( } if (Date.now() - since > sampleEveryMs) { since = Date.now() - latest = await describePreviewFrame(page, reading?.frame, reading?.browserVersion).catch( - (error) => `the reading itself failed: ${String(error).split('\n')[0]}` - ) + latest = await describePreviewFrame(page, reading?.frame, reading?.browserVersion) + .then(async (frameReading) => { + // The same evidence the images arm prints. A navigation arm that produced nothing is + // asking the same question of the same frame, and on CI this one fails on its own. + const evidence = await reading?.describeRequests?.(reading?.frame) + return evidence ? `${frameReading} | ${evidence}` : frameReading + }) + .catch((error) => `the reading itself failed: ${String(error).split('\n')[0]}`) } await page.waitForTimeout(10) } diff --git a/config/scripts/mobile-web-app-preview-image-evidence.mjs b/config/scripts/mobile-web-app-preview-image-evidence.mjs new file mode 100644 index 00000000000..223101e0b31 --- /dev/null +++ b/config/scripts/mobile-web-app-preview-image-evidence.mjs @@ -0,0 +1,117 @@ +/** + * Why an image the policy admits was never fetched, asked of the frame that should have fetched it. + * + * The network log says whether a request happened. This says what the document thinks happened, + * which is the other half: on CI's Chrome 152 the `` reported `complete` with a zero + * `naturalWidth` and a resolved `currentSrc` while no request was ever made, and those two readings + * cannot both be true of a request that went out and failed. + * + * Every reading here is taken only when an arm has already aborted, so none of it costs a passing + * run. The frame is reached through Playwright's CDP evaluate, which answers in a sandboxed frame + * whose own scripts are blocked. + */ + +/** Two seconds: long enough for a request to reach the rig's own in-process route handler. */ +const FRESH_IMAGE_MS = 2000 + +/** + * Every document commit in a subframe, counted from now. + * + * Subscribed at mount rather than read at the abort, because a parse leaves nothing behind to count: + * a second document is a new window, so the init script's own timestamp is overwritten rather than + * appended. Two commits would mean the artifact parsed twice and the second parse could be meeting a + * failure the first one cached. + */ +function recordFrameParses(page) { + const parses = [] + page.on('framenavigated', (frame) => { + if (frame === page.mainFrame()) { + return + } + parses.push({ url: frame.url(), at: Math.round(performance.now()) }) + }) + return () => [...parses] +} + +/** + * What the frame says about its images, and whether a request made right now is seen. + * + * The fresh image is the part that splits the two live explanations. Its URL has never existed, so + * nothing can have cached a failure for it; if the rig sees that request and not the artifact's, + * the frame can fetch and something about the parser-inserted element is the cause, and if the rig + * sees neither, requests from this frame are not reaching the rig at all. + */ +async function describeImageEvidence(page, frame, { originPrefix, requestLog, parses }) { + if (!frame) { + return `no frame to ask; ${requestLog.describe()}` + } + const inFrame = await frame + .evaluate(async () => { + const remote = document.getElementById('remote') + const decode = remote + ? await remote.decode().then( + () => 'resolved', + (error) => `rejected ${error.name}` + ) + : 'no element' + return { + readyState: document.readyState, + initAt: window.__initAt ?? null, + images: document.images.length, + // Every subresource this document actually fetched, from the document's own side. An entry + // here for a URL the rig never saw would mean the request left the frame and died before it. + resources: performance.getEntriesByType('resource').map((one) => one.name), + navigations: performance.getEntriesByType('navigation').map((one) => one.type), + remote: remote + ? { + src: remote.getAttribute('src'), + isConnected: remote.isConnected, + complete: remote.complete, + naturalWidth: remote.naturalWidth, + currentSrc: remote.currentSrc, + decode + } + : null + } + }) + .catch((error) => `the reading itself failed: ${String(error).split('\n')[0]}`) + + const freshUrl = `${originPrefix}/fresh-${String(Date.now())}.png` + const issued = await frame + .evaluate((url) => { + const image = new Image() + image.src = url + globalThis.__freshImage = image + return true + }, freshUrl) + .catch((error) => `the request itself failed: ${String(error).split('\n')[0]}`) + await new Promise((resolve) => { + const timer = setTimeout(resolve, FRESH_IMAGE_MS) + timer.unref?.() + }) + const fresh = await frame + .evaluate(() => { + const image = globalThis.__freshImage + return image ? { complete: image.complete, naturalWidth: image.naturalWidth } : null + }) + .catch(() => null) + + return [ + `frame ${JSON.stringify(inFrame)}`, + `subframe parses ${JSON.stringify(parses())}`, + `fresh ${JSON.stringify(freshUrl)} issued ${JSON.stringify(issued)} seen ${String(requestLog.asked().includes(freshUrl))} element ${JSON.stringify(fresh)}`, + requestLog.describe() + ].join('; ') +} + +/** + * Subscribes now and hands back the reading, so a caller wires one thing rather than three. + * + * The subscription is the only part that has to happen at mount; everything it reports is asked for + * later, and only by an arm that aborted. + */ +export function watchImageEvidence(page, originPrefix, requestLog) { + const parses = recordFrameParses(page) + return async (frame) => + await describeImageEvidence(page, frame, { originPrefix, requestLog, parses }) +} diff --git a/config/scripts/mobile-web-app-preview-request-log.mjs b/config/scripts/mobile-web-app-preview-request-log.mjs index ba21126a91c..5ee208d7774 100644 --- a/config/scripts/mobile-web-app-preview-request-log.mjs +++ b/config/scripts/mobile-web-app-preview-request-log.mjs @@ -22,6 +22,8 @@ export async function recordRequestsTo(page, originPrefix) { // Only this origin's ids, because `Network.loadingFailed` carries a request id and no URL, and an // unfiltered list would report every other request on the page as this arm's evidence. const ours = new Set() + /** Every child target this session attached to, which says whether the frame is out of process. */ + const attached = [] page.on('request', (request) => { if (request.url().startsWith(originPrefix)) { @@ -40,6 +42,21 @@ export async function recordRequestsTo(page, originPrefix) { .catch(() => null) if (cdp) { await cdp.send('Network.enable').catch(() => {}) + // Chromium isolates sandboxed iframes into their own process, srcdoc included, so the page's own + // session sees none of the frame's requests: `cdp sent` came back empty on CI even for a request + // Playwright did record. Flattened auto-attach puts each child target on this same connection, + // and `Network.enable` on the child is what makes its requests visible here. + cdp.on('Target.attachedToTarget', (event) => { + attached.push({ type: event.targetInfo?.type ?? null, url: event.targetInfo?.url ?? null }) + cdp.send('Network.enable', {}, event.sessionId).catch(() => {}) + }) + await cdp + .send('Target.setAutoAttach', { + autoAttach: true, + waitForDebuggerOnStart: false, + flatten: true + }) + .catch(() => {}) cdp.on('Network.requestWillBeSent', (event) => { if (!event.request?.url?.startsWith(originPrefix)) { return @@ -65,6 +82,9 @@ export async function recordRequestsTo(page, originPrefix) { }) } - return () => - `asked ${JSON.stringify(asked)}; failed ${JSON.stringify(failed)}; cdp ${cdp ? 'on' : 'off'} sent ${JSON.stringify(sent)}; cdp loadingFailed ${JSON.stringify(loadingFailed)}` + return { + asked: () => [...asked], + describe: () => + `asked ${JSON.stringify(asked)}; failed ${JSON.stringify(failed)}; cdp ${cdp ? 'on' : 'off'} attached ${JSON.stringify(attached)} sent ${JSON.stringify(sent)}; cdp loadingFailed ${JSON.stringify(loadingFailed)}` + } }