playwright [BUG] Route creation appears to be committed before it succeeds in some cases

System info

Playwright Version: [v1.33]
Operating System: Ubuntu 22.04 (GitHub Actions)
Browser: Electron

Source code

https://github.com/webbuilders-group/playwright-23162/

Steps

Test with multiple custom routes (in my testing 45) applied to Electron's context by calling electronApp.context().route() wrapped in a Promise.all call.

Expected

All routes would be applied consistently every time.

Actual

In some cases routes appear to be created, but the Playwright API debug shows a commit between the last created and first succeeded log. When this happens the routes do not get properly applied and the calls are made to their original destination. Note in the examples below the steps are different for the tests but they both start the same. In 1.32 this works as expected, oddly in 1.33 it seems to work fine in Windows 10 and Ubuntu Server 22.04 with Xvfb running (just like in GitHub Actions) however for some reason in GitHub actions it fails pretty consistently.

Successful Test

pw:api => electron.launch started +6ms
pw:api <= selectors.setTestIdAttribute succeeded +3ms
pw:api <= electron.launch succeeded +1s
pw:api => tracing.start started +7ms
pw:api => browserContext.route started +40ms
pw:api => browserContext.route started +3ms
pw:api => browserContext.route started +14ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +6ms
pw:api => browserContext.route started +13ms
pw:api => browserContext.route started +3ms
pw:api => browserContext.route started +11ms
pw:api => browserContext.route started +4ms
pw:api => browserContext.route started +3ms
pw:api => browserContext.route started +25ms
pw:api => browserContext.route started +3ms
pw:api => browserContext.route started +9ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +3ms
pw:api => browserContext.route started +4ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +4ms
pw:api => browserContext.route started +18ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +3ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +1ms
pw:api <= browserContext.route succeeded +17ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +2ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api => electronApplication.evaluate started +2ms
pw:api <= tracing.start succeeded +11ms
pw:api =>  started +1ms
pw:api <=  succeeded +5ms
pw:api   "commit" event fired +4ms
pw:api   "commit" event fired +136ms
pw:api   navigated to "file:///home/runner/work/app-name/app-name/index.html" +1ms
pw:api   "load" event fired +151ms
pw:api   "domcontentloaded" event fired +1ms
pw:api <= electronApplication.evaluate succeeded +49ms
pw:api => page.fill started +23ms
pw:api waiting for locator('#login-view [id^=login-email-]') +19ms
pw:api   locator resolved to <input type="text" required="" spellcheck="false" id="l…/> +22ms
pw:api elementHandle.fill("[email protected]") +2ms
pw:api   waiting for element to be visible, enabled and editable +3ms
pw:api   element is visible, enabled and editable +6ms
pw:api <= page.fill succeeded +9ms
pw:api => page.fill started +2ms
pw:api waiting for locator('#login-view [id^=login-password-]') +2ms
pw:api   locator resolved to <input required="" type="password" id="login-password-6…/> +3ms
pw:api elementHandle.fill("123456") +2ms
pw:api   waiting for element to be visible, enabled and editable +1ms
pw:api   element is visible, enabled and editable +11ms
pw:api <= page.fill succeeded +4ms
pw:api => page.click started +2ms
pw:api waiting for locator('#login-view .form-actions button[type=submit]') +2ms
pw:api   locator resolved to <button type="submit">Login</button> +5ms
pw:api attempting click action +2ms
pw:api   waiting for element to be visible, enabled and stable +1ms
pw:api   element is visible, enabled and stable +28ms
pw:api   scrolling into view if needed +1ms
pw:api   done scrolling +1ms
pw:api   performing click action +5ms
pw:api => route.fulfill started +24ms
pw:api   click action done +2ms
pw:api   waiting for scheduled navigations to finish +0ms
pw:api <= route.fulfill succeeded +2ms
pw:api   navigations have finished +11ms
pw:api <= page.click succeeded +25ms
pw:api => page.waitForSelector started +2ms
pw:api waiting for locator('#timing-view .timer-face') to be visible +30ms
pw:api   locator resolved to visible <div class="timer-face">…</div> +5ms
pw:api <= page.waitForSelector succeeded +13ms
pw:api => page.content started +1ms
pw:api <= page.content succeeded +4ms
pw:api => electronApplication.evaluate started +5ms
pw:api => electronApplication.waitForEvent started +2ms
pw:api <= electronApplication.evaluate succeeded +25ms
pw:api   "commit" event fired +22ms
pw:api   "commit" event fired +39ms
pw:api   navigated to "devtools://devtools/bundled/devtools_app.html?remoteBase=https://chrome-devtools-frontend.appspot.com/serve_file/@58e740cfc1ed1964a2d1edd9bd3d78a394a7f3a6/&can_dock=&toolbarColor=rgba(223,223,223,1)&textColor=rgba(0,0,0,1)&experiments=true" +0ms
pw:api => page.title started +2ms
pw:api   "commit" event fired +20ms
pw:api <= page.title succeeded +6ms
pw:api   "commit" event fired +165ms
pw:api   navigated to "file:///home/runner/work/app-name/app-name/ui-styles-debug.html" +0ms
pw:api => page.title started +1ms
pw:api <= page.title succeeded +85ms
pw:api <= electronApplication.waitForEvent succeeded +2ms
pw:api => electronApplication.evaluate started +1ms
pw:api <= electronApplication.evaluate succeeded +11ms
pw:api => page.exposeBinding started +2ms
pw:api   "networkidle" event fired +42ms
pw:api   "load" event fired +39ms
pw:api   "domcontentloaded" event fired +2ms
pw:api   "domcontentloaded" event fired +105ms
pw:api   "load" event fired +11ms
pw:api <= page.exposeBinding succeeded +4ms
pw:api => electronApplication.evaluate started +1ms
pw:api   "networkidle" event fired +1ms
pw:api <= electronApplication.evaluate succeeded +11ms
pw:api => page.waitForEvent started +1ms
pw:api => page.click started +5ms
pw:api waiting for event "minimize" +2ms
pw:api waiting for locator('.window-title-bar button.minimize') +12ms
pw:api   locator resolved to <button type="button" class="minimize" title="Minimize" …></button> +25ms
pw:api attempting click action +2ms
pw:api   waiting for element to be visible, enabled and stable +0ms
pw:api   element is visible, enabled and stable +44ms
pw:api   scrolling into view if needed +0ms
pw:api   done scrolling +1ms
pw:api   performing click action +12ms
pw:api   click action done +28ms
pw:api   waiting for scheduled navigations to finish +0ms
pw:api   navigations have finished +2ms
pw:api <= page.click succeeded +3ms
pw:api =>  started +28ms
pw:api <= page.waitForEvent succeeded +2ms
pw:api => electronApplication.evaluate started +1ms
pw:api <=  succeeded +3ms
pw:api <= electronApplication.evaluate succeeded +3ms
pw:api => page.waitForEvent started +2ms
pw:api => electronApplication.evaluate started +4ms
pw:api waiting for event "restore" +6ms
pw:api <= electronApplication.evaluate succeeded +1ms
pw:api =>  started +2ms
pw:api <= page.waitForEvent succeeded +2ms
pw:api => page.waitForEvent started +0ms
pw:api => page.click started +4ms
pw:api waiting for event "maximize" +1ms
pw:api <=  succeeded +1ms
pw:api waiting for locator('.window-title-bar button.maximize') +3ms
pw:api   locator resolved to <button type="button" class="maximize" title="Maximize" …></button> +3ms
pw:api attempting click action +1ms
pw:api   waiting for element to be visible, enabled and stable +1ms
pw:api   element is visible, enabled and stable +15ms
pw:api   scrolling into view if needed +0ms
pw:api   done scrolling +1ms
pw:api   performing click action +4ms
pw:api   click action done +6ms
pw:api   waiting for scheduled navigations to finish +1ms
pw:api =>  started +12ms
pw:api <= page.waitForEvent succeeded +3ms
pw:api   navigations have finished +1ms
pw:api <=  succeeded +4ms
pw:api <= page.click succeeded +2ms
pw:api => electronApplication.evaluate started +2ms
pw:api <= electronApplication.evaluate succeeded +2ms
pw:api => page.waitForEvent started +4ms
pw:api => page.click started +4ms
pw:api waiting for event "unmaximize" +2ms
pw:api waiting for locator('.window-title-bar button.maximize') +4ms
pw:api   locator resolved to <button type="button" title="Maximize" aria-label="Maxim…></button> +8ms
pw:api attempting click action +2ms
pw:api   waiting for element to be visible, enabled and stable +1ms
pw:api   element is visible, enabled and stable +20ms
pw:api   scrolling into view if needed +0ms
pw:api   done scrolling +1ms
pw:api   performing click action +5ms
pw:api   click action done +6ms
pw:api   waiting for scheduled navigations to finish +0ms
pw:api =>  started +1ms
pw:api <= page.waitForEvent succeeded +5ms
pw:api <=  succeeded +3ms
pw:api   navigations have finished +1ms
pw:api <= page.click succeeded +5ms
pw:api => electronApplication.evaluate started +1ms
pw:api <= electronApplication.evaluate succeeded +2ms
pw:api => page.waitForEvent started +2ms
pw:api => page.click started +4ms
pw:api waiting for event "close" +6ms
pw:api waiting for locator('.window-title-bar button.close') +5ms
pw:api   locator resolved to <button type="button" class="close" title="Close" aria-l…></button> +3ms
pw:api attempting click action +1ms
pw:api   waiting for element to be visible, enabled and stable +0ms
pw:api   element is visible, enabled and stable +14ms
pw:api   scrolling into view if needed +1ms
pw:api   done scrolling +1ms
pw:api   performing click action +4ms
pw:api <= page.waitForEvent succeeded +14ms
pw:api <= page.click failed +0ms
pw:api => electronApplication.evaluate started +3ms
pw:api <= electronApplication.evaluate succeeded +2ms
pw:api => electronApplication.close started +1ms
pw:api <= electronApplication.close succeeded +52ms`

Failing Test

pw:api => selectors.setTestIdAttribute started +5ms
pw:api => electron.launch started +3ms
pw:api <= selectors.setTestIdAttribute succeeded +2ms
pw:api <= electron.launch succeeded +374ms
pw:api => tracing.start started +1ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +5ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +23ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +10ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +8ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +9ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +11ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +4ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +1ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +4ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +3ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +3ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +5ms
pw:api => browserContext.route started +4ms
pw:api => browserContext.route started +8ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +7ms
pw:api => browserContext.route started +2ms
pw:api => browserContext.route started +6ms
pw:api => browserContext.route started +7ms
pw:api   "commit" event fired +12ms
pw:api <= browserContext.route succeeded +3ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api <= browserContext.route succeeded +1ms
pw:api <= browserContext.route succeeded +0ms
pw:api => electronApplication.evaluate started +2ms
pw:api <= tracing.start succeeded +2ms
pw:api =>  started +1ms
pw:api <=  succeeded +1ms
pw:api   "commit" event fired +70ms
pw:api   navigated to "file:///home/runner/work/app-name/app-name/index.html" +1ms
pw:api   "load" event fired +140ms
pw:api   "domcontentloaded" event fired +1ms
pw:api <= electronApplication.evaluate succeeded +47ms
pw:api => page.fill started +2ms
pw:api waiting for locator('#login-view [id^=login-email-]') +5ms
pw:api   locator resolved to <input type="text" required="" spellcheck="false" id="l…/> +34ms
pw:api elementHandle.fill("[email protected]") +1ms
pw:api   waiting for element to be visible, enabled and editable +2ms
pw:api   element is visible, enabled and editable +6ms
pw:api <= page.fill succeeded +10ms
pw:api => page.fill started +1ms
pw:api waiting for locator('#login-view [id^=login-password-]') +3ms
pw:api   locator resolved to <input required="" type="password" id="login-password-4…/> +2ms
pw:api elementHandle.fill("123456") +3ms
pw:api   waiting for element to be visible, enabled and editable +2ms
pw:api   element is visible, enabled and editable +10ms
pw:api <= page.fill succeeded +8ms
pw:api => page.click started +2ms
pw:api waiting for locator('#login-view .form-actions button[type=submit]') +2ms
pw:api   locator resolved to <button type="submit">Login</button> +3ms
pw:api attempting click action +1ms
pw:api   waiting for element to be visible, enabled and stable +1ms
pw:api   element is visible, enabled and stable +17ms
pw:api   scrolling into view if needed +1ms
pw:api   done scrolling +1ms
pw:api   performing click action +3ms
pw:api   click action done +39ms
pw:api   waiting for scheduled navigations to finish +0ms
pw:api   navigations have finished +4ms
pw:api <= page.click succeeded +2ms
pw:api => page.waitForSelector started +1ms
pw:api waiting for locator('#timing-view .timer-face') to be visible +2ms
pw:api   "networkidle" event fired +653ms
pw:api => tracing.stop started +28s
pw:api <= tracing.stop succeeded +170ms

May 19 '23 15:05 UndefinedOffset

@UndefinedOffset We have to reproduce this issue locally to be able to debug it. Please fill in all the details of the "Bug Report" template.

May 19 '23 18:05 dgozman

@dgozman have a look at the repo linked in the issue description now, you can see both tests are functionally identical but they produce different results see https://github.com/webbuilders-group/playwright-23162/actions/runs/5027594204.

The app is super basic, click a button and it makes a request that playwright should intercept which would result in a 200 ok but instead in some cases playwright doesn't intercept it so it gets a 404 which I'm bubbling up to playwright with an error thrown in the window and listening to the pageerror event to fail the test.

Note sometimes the first test fails sometimes the second, in my experience in our actual app it appears "random" and it only seems to regularly happen on GitHub Actions.

May 19 '23 19:05 UndefinedOffset

@UndefinedOffset Thank you for the repro! Unfortunately, I had no luck reproducing the issue. I ran all tests ~200 times, with and without CI=1 flag, and every single time both tests passed.

Looking at the source, I can see a pattern that probably does not work as you expect it to work. Calling test.afterEach() in the _helpers/launcher.js only registers the afterEach hook in the first test file in the case you have many. I'd recommend moving code from that hook into closer.js instead. Note that you can always access TestInfo by calling test.info() from any place, so that should not be a problem.

Other than the issue above, everything seems clear.

May 22 '23 15:05 dgozman

We have to reproduce this issue locally to be able to debug it. If you can provide a full repro, please file a new issue by filling the "Bug Report" template, and link to this one.

May 23 '23 15:05 dgozman

@dgozman the only place I was able to reliably reproduce this was using github actions, I tried locally on windows 10 and in a headless ubuntu server vm both were passing reliably.

Thanks for the heads up on the afterEach I'll made adjustments in our main repo.

May 23 '23 15:05 UndefinedOffset

playwright playwright copied to clipboard

[BUG] Route creation appears to be committed before it succeeds in some cases

System info

Source code

playwright
playwright copied to clipboard