Page MenuHomePhabricator

"Echo flyout for notices appears when clicked @daily" failed
Open, Needs TriagePublic

Description

https://integration.wikimedia.org/ci/job/wmf-quibble-selenium-php72-docker/74703/console

22:14:25 [0-0] Error in "Echo flyout for notices appears when clicked @daily"
22:14:25 element (".oo-ui-labelElement-label*=Notices") still not displayed after 10000ms
22:14:47 [Chrome 73.0.3683.75 linux #0-0] Spec: /workspace/src/extensions/Echo/tests/selenium/specs/echo.js
22:14:47 [Chrome 73.0.3683.75 linux #0-0] Running: Chrome (v73.0.3683.75) on linux
22:14:47 [Chrome 73.0.3683.75 linux #0-0] Session ID: 5abe34c2-b878-40d0-867a-05cc1893c9ce
22:14:47 [Chrome 73.0.3683.75 linux #0-0]
22:14:47 [Chrome 73.0.3683.75 linux #0-0] Echo
22:14:47 [Chrome 73.0.3683.75 linux #0-0]    ✓ alerts and notices are visible after logging in @daily
22:14:47 [Chrome 73.0.3683.75 linux #0-0]    ✓ flyout for alert appears when clicked @daily
22:14:47 [Chrome 73.0.3683.75 linux #0-0]    ✖ flyout for notices appears when clicked @daily
22:14:47 [Chrome 73.0.3683.75 linux #0-0]    ✓ checks for welcome message after signup
22:14:47 [Chrome 73.0.3683.75 linux #0-0]
22:14:47 [Chrome 73.0.3683.75 linux #0-0] 3 passing (29.8s)
22:14:47 [Chrome 73.0.3683.75 linux #0-0] 1 failing
22:14:47 [Chrome 73.0.3683.75 linux #0-0]
22:14:47 [Chrome 73.0.3683.75 linux #0-0] 1) Echo flyout for notices appears when clicked @daily
22:14:47 [Chrome 73.0.3683.75 linux #0-0] element (".oo-ui-labelElement-label*=Notices") still not displayed after 10000ms
22:14:47 [Chrome 73.0.3683.75 linux #0-0] Error: element (".oo-ui-labelElement-label*=Notices") still not displayed after 10000ms
22:14:47 [Chrome 73.0.3683.75 linux #0-0]     at Context.<anonymous> (/workspace/src/extensions/Echo/tests/selenium/specs/echo.js:39:26)

Investigated in T271281#6884406

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald Transcript

So looking at another failure of this in the past days https://integration.wikimedia.org/ci/job/wmf-quibble-selenium-php72-docker/81921/console trying to see if this lines up with what happens in T273327

The TLDR is in bold at the bottom

The test for convenience:

	it( 'flyout for notices appears when clicked @daily', function () {

		UserLoginPage.login( browser.config.mwUser, browser.config.mwPwd );
		EchoPage.notices.click();
		EchoPage.noticesFlyout.waitForDisplayed();

		assert( EchoPage.noticesFlyout.isExisting() );

	} );

The main test output:

17:29:17 [Chrome 73.0.3683.75 linux #0-0] Echo
17:29:17 [Chrome 73.0.3683.75 linux #0-0]    ✓ alerts and notices are visible after logging in @daily
17:29:17 [Chrome 73.0.3683.75 linux #0-0]    ✓ flyout for alert appears when clicked @daily
17:29:17 [Chrome 73.0.3683.75 linux #0-0]    ✖ flyout for notices appears when clicked @daily
17:29:17 [Chrome 73.0.3683.75 linux #0-0]    ✓ checks for welcome message after signup
17:29:17 [Chrome 73.0.3683.75 linux #0-0]
17:29:17 [Chrome 73.0.3683.75 linux #0-0] 3 passing (30.1s)
17:29:17 [Chrome 73.0.3683.75 linux #0-0] 1 failing
17:29:17 [Chrome 73.0.3683.75 linux #0-0]
17:29:17 [Chrome 73.0.3683.75 linux #0-0] 1) Echo flyout for notices appears when clicked @daily
17:29:17 [Chrome 73.0.3683.75 linux #0-0] element (".oo-ui-labelElement-label*=Notices") still not displayed after 10000ms
17:29:17 [Chrome 73.0.3683.75 linux #0-0] Error: element (".oo-ui-labelElement-label*=Notices") still not displayed after 10000ms
17:29:17 [Chrome 73.0.3683.75 linux #0-0]     at Context.<anonymous> (/workspace/src/extensions/Echo/tests/selenium/specs/echo.js:39:26)

The failure image is https://integration.wikimedia.org/ci/job/wmf-quibble-selenium-php72-docker/81921/artifact/log/flyout-for-notices-appears-when-clicked-%2540daily.png
And example success is https://integration.wikimedia.org/ci/job/wmf-quibble-selenium-php72-docker/81919/artifact/log/flyout-for-notices-appears-when-clicked-%2540daily.png

In the failure example the browser is still on the notifications page, vs success when the browser is on the Main Page??

Success verbose logs:

17:19:43 
17:19:43 INFO:backend.PhpWebserver:[Tue Mar  2 17:19:43 2021] 127.0.0.1:44796 [200]: //index.php?title=Special%3AUserLogin
17:19:44 INFO:backend.PhpWebserver:[Tue Mar  2 17:19:44 2021] 127.0.0.1:44808 [302]: /index.php/Special:UserLogin
17:19:44 INFO:backend.PhpWebserver:[Tue Mar  2 17:19:44 2021] 127.0.0.1:44810 [200]: /index.php/Main_Page
17:19:44 INFO:backend.PhpWebserver:[Tue Mar  2 17:19:44 2021] 127.0.0.1:44830 [200]: /api.php?action=query&format=json&formatversion=2&meta=notifications&notsections=message&notformat=model&notlimit=25&notprop=list%7Ccount%7CseenTime&uselang=en&notcrosswikisummary=1&_=1614705584493
17:19:44 INFO:backend.PhpWebserver:[Tue Mar  2 17:19:44 2021] 127.0.0.1:44834 [200]: /api.php?action=query&format=json&meta=notifications&notsections=message&notgroupbysection=1&notmessageunreadfirst=1&notlimit=25&notprop=count&uselang=en&notcrosswikisummary=1&_=1614705584494
17:19:44 INFO:backend.PhpWebserver:[Tue Mar  2 17:19:44 2021] 127.0.0.1:44836 [200]: /api.php?action=query&format=json&formatversion=2&meta=notifications&notsections=message&notformat=model&notlimit=25&notprop=list%7Ccount%7CseenTime&uselang=en&notcrosswikisummary=1&notunreadfirst=1&notbundle=1&_=1614705584495
17:19:44 INFO:backend.PhpWebserver:[Tue Mar  2 17:19:44 2021] 127.0.0.1:44842 [200]: /api.php?action=echomarkseen&format=json&type=message&timestampFormat=ISO_8601&_=1614705584496
17:19:45 [0-0] 
17:19:45 	Screenshot: /workspace/log/flyout-for-notices-appears-when-clicked-%40daily.png

Failure verbose logs:

17:28:44 
17:28:44 INFO:backend.PhpWebserver:[Tue Mar  2 17:28:44 2021] 127.0.0.1:34946 [200]: //index.php?title=Special%3AUserLogin
17:28:44 INFO:backend.PhpWebserver:[Tue Mar  2 17:28:45 2021] 127.0.0.1:34958 [302]: /index.php/Special:UserLogin
17:28:45 INFO:backend.PhpWebserver:[Tue Mar  2 17:28:45 2021] 127.0.0.1:34960 [200]: /index.php/Main_Page
17:28:45 INFO:backend.PhpWebserver:[Tue Mar  2 17:28:45 2021] 127.0.0.1:34980 [200]: /index.php/Special:Notifications
17:28:45 INFO:backend.PhpWebserver:[Tue Mar  2 17:28:45 2021] 127.0.0.1:34982 [200]: /load.php?lang=en&modules=ext.echo.styles.badge%2Cnotifications%2Cspecial%7Cext.uls.pt%7Cext.visualEditor.desktopArticleTarget.noscript%7Cmediawiki.helplink%7Cmediawiki.htmlform.ooui.styles%7Cmediawiki.htmlform.styles%7Cmediawiki.widgets.styles%7Coojs-ui-core.icons%2Cstyles%7Coojs-ui.styles.icons-alerts%2Cindicators%7Cskins.vector.styles.legacy%7Cwikibase.client.data-bridge.externalModifiers&only=styles&skin=vector
17:28:45 INFO:backend.PhpWebserver:[Tue Mar  2 17:28:46 2021] 127.0.0.1:34990 [200]: /load.php?lang=en&modules=ext.echo.api%2Cdm%2Cinit%2Clogger%2Csecondaryicons%2Cspecial%2Cui%7Cjquery%2Cmoment%2Coojs-ui-core%2Coojs-ui-widgets%2Csite%7Cjquery.ui%7Coojs-ui.styles.icons-content%2Cicons-interactions%2Cicons-moderation%2Cicons-movement%2Cicons-user&skin=vector&version=15s44
17:28:46 INFO:backend.PhpWebserver:[Tue Mar  2 17:28:47 2021] 127.0.0.1:35002 [200]: /api.php?action=query&format=json&meta=unreadnotificationpages&uselang=en&unpgrouppages=true&unpwikis=*&_=1614706126758
17:28:47 INFO:backend.PhpWebserver:[Tue Mar  2 17:28:47 2021] 127.0.0.1:35004 [200]: /api.php?action=query&format=json&formatversion=2&meta=notifications&notsections=message%7Calert&notformat=model&notlimit=50&notprop=list%7Ccount%7CseenTime&uselang=en&notcrosswikisummary=1&notfilter=!read&nottitles=&_=1614706126759
17:28:47 INFO:backend.PhpWebserver:[Tue Mar  2 17:28:48 2021] 127.0.0.1:35006 [200]: /api.php?action=query&format=json&meta=notifications&notgroupbysection=1&notmessageunreadfirst=1&notlimit=50&notprop=count&uselang=en&_=1614706126760
17:28:48 INFO:backend.PhpWebserver:[Tue Mar  2 17:28:48 2021] 127.0.0.1:35008 [200]: /api.php?action=echomarkseen&format=json&type=all&timestampFormat=ISO_8601&_=1614706126761
17:28:48 [0-0] 
17:28:57 	Screenshot: /workspace/log/flyout-for-notices-appears-when-clicked-%40daily.png

Seemingly the requests that are hitting the webserver are totally different between the failure and success cases?
Most noticeably the /index.php/Special:Notifications call?
In Fact the successful log doesn't even have any calls to index.php/Special:Notifications at all!

My initial guess was that EchoPage.notices.click(); ends up clicking on the wrong thing somehow?
But what seems to be happening is the JS has not been loaded onto the button?
The default behaviour of the notification button without JS is to load the notifications page.
So if the button press happens to quickly, the test will fail.

If we had videos for these tests this would be much easier to spot.

Addshore triaged this task as Medium priority.Mar 4 2021, 9:13 PM

Happened again in https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-php72-selenium-docker/40337/console.

[Chrome 73.0.3683.75 linux #0-0] Echo
[Chrome 73.0.3683.75 linux #0-0]    ✓ alerts and notices are visible after logging in @daily
[Chrome 73.0.3683.75 linux #0-0]    ✓ flyout for alert appears when clicked @daily
[Chrome 73.0.3683.75 linux #0-0]    ✖ flyout for notices appears when clicked @daily
[Chrome 73.0.3683.75 linux #0-0]    ✓ checks for welcome message after signup
[Chrome 73.0.3683.75 linux #0-0]
[Chrome 73.0.3683.75 linux #0-0] 3 passing (23.1s)
[Chrome 73.0.3683.75 linux #0-0] 1 failing
[Chrome 73.0.3683.75 linux #0-0]
[Chrome 73.0.3683.75 linux #0-0] 1) Echo flyout for notices appears when clicked @daily
[Chrome 73.0.3683.75 linux #0-0] element (".oo-ui-labelElement-label*=Notices") still not displayed after 10000ms
[Chrome 73.0.3683.75 linux #0-0] Error: element (".oo-ui-labelElement-label*=Notices") still not displayed after 10000ms
[Chrome 73.0.3683.75 linux #0-0]     at Context.<anonymous> (/workspace/src/extensions/Echo/tests/selenium/specs/echo.js:39:26)

By using fresh-node the tests seems to be passed easily...

The problem is that the test fails sometimes, not all the time. Try running the test 10-100 times.

We've done some debugging. The echo.js fails sometimes on lines with click().

Examples:

EchoPage.alerts.click();
EchoPage.notices.click();

Our current understanding is that webdriverio executes click() before javascript has loaded. We'll work on adding code that waits for javascript to load.

Change 678287 had a related patch set uploaded (by Zfilipin; author: Sahilgrewalhere):

[mediawiki/extensions/Echo@master] WIP selenium: Upgrade WebdriverIO to v7

https://gerrit.wikimedia.org/r/678287

TLDR: what we need is a hint on what to wait for on the page before we can click alerts or notices icon, so the alerts and notices popup would display.

Developers/Maintainers says @Krenair and Growth-Team are maintainers of Notifications. Growth page says @kostajh is a member of the team. He's pretty active in Selenium tests, so I'm pinging him too.

In short, we're stuck. We know what the problem is, but we don't know how to solve it.

The problem is that these lines in echo.js sometimes fail because webdriverio calls click() before all relevant javascript on the page has loaded.

EchoPage.alerts.click();
EchoPage.notices.click();

The failures happen frequently, but not always, making it hard to reproduce and debug.

@Soham had a great idea of using puppeteer's waitForNavigation() to wait for events to be fired. We've tried waiting for load, domcontentloaded, networkidle0, networkidle2. It didn't help. See 678287/25.

To prove it's a timing problem, we've used webdriverio's pause() to hard-code a 2 second pause between loading the page and calling click(). See 678287/26.

TLDR: what we need is a hint on what to wait for on the page before we can click alerts or notices icon, so the alerts and notices popup would display.

Developers/Maintainers says @Krenair and Growth-Team are maintainers of Notifications. Growth page says @kostajh is a member of the team. He's pretty active in Selenium tests, so I'm pinging him too.

In short, we're stuck. We know what the problem is, but we don't know how to solve it.

The problem is that these lines in echo.js sometimes fail because webdriverio calls click() before all relevant javascript on the page has loaded.

EchoPage.alerts.click();
EchoPage.notices.click();

The failures happen frequently, but not always, making it hard to reproduce and debug.

@Soham had a great idea of using puppeteer's waitForNavigation() to wait for events to be fired. We've tried waiting for load, domcontentloaded, networkidle0, networkidle2. It didn't help. See 678287/25.

To prove it's a timing problem, we've used webdriverio's pause() to hard-code a 2 second pause between loading the page and calling click(). See 678287/26.

We could modify the JS code in Echo to add an additional CSS class to the button to indicate that JS is finished loading. Then you could use https://webdriver.io/docs/api/element/waitUntil to check for that class before clicking.

zeljkofilipin raised the priority of this task from Medium to Needs Triage.Sep 17 2021, 9:49 AM

I'm just a tourist here, but what about using

Util.waitForModuleState( 'ext.echo.init' );

to make sure JS is loaded? In some other code bases that helped in most cases with similar issues.