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

Issue: The button gets clicked on before the JS has run on the button (that would trigger the fly out thing)
Actionable: Make the test (and others like it) wait for the JS to actually run on the button
Followups : T276503: Make Echo browser tests record and save videos in CI

Details

Related Changes in Gerrit:

	Subject	Repo	Branch	Lines +/-
	selenium: Upgrade WebdriverIO to v7	mediawiki/extensions/Echo	master	+843 -2 K
	WIP selenium: Upgrade WebdriverIO to v7	mediawiki/extensions/Echo	master	+997 -1 K

Customize query in gerrit

Related Objects
Search...

Status	Assigned	Task
Resolved	zeljkofilipin	T210726 Selenium framework maintenance
Resolved	zeljkofilipin	T274579 Upgrade WebdriverIO to v7 in all repositories
Open	None	T291254 Find flaky Selenium tests
Resolved	Osamaahmed17	T271281 "Echo flyout for notices appears when clicked @daily" failed

Event Timeline

Reedy created this task.Jan 5 2021, 10:17 PM

Restricted Application added a project: Growth-Team. · View Herald TranscriptJan 5 2021, 10:17 PM

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

Reedy added a project: Browser-Tests.Jan 5 2021, 10:18 PM

RhinosF1 subscribed.Jan 5 2021, 10:28 PM

Addshore subscribed.Mar 4 2021, 8:33 PM

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 mentioned this in T276503: Make Echo browser tests record and save videos in CI.Mar 4 2021, 8:52 PM

Addshore updated the task description. (Show Details)

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)

MBinder_WMF added a project: Growth-Team-Filtering.Apr 15 2021, 6:48 PM

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.

zeljkofilipin claimed this task.Jul 15 2021, 10:07 AM

zeljkofilipin added a project: User-zeljkofilipin.

zeljkofilipin moved this task from Backlog 🪒 to Deep work 🌊 on the User-zeljkofilipin board.

zeljkofilipin added a project: Quality-and-Test-Engineering-Team.

zeljkofilipin moved this task from Inbox to Test engineering on the Quality-and-Test-Engineering-Team board.

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

gerritbot added a project: Patch-For-Review.Jul 16 2021, 10:47 AM

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 (Echo). 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.

zeljkofilipin removed zeljkofilipin as the assignee of this task.Jul 16 2021, 11:05 AM

zeljkofilipin moved this task from Deep work 🌊 to Waiting 🏹 on the User-zeljkofilipin board.

In T271281#7216974, @zeljkofilipin wrote:
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 (Echo). 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.

Sahilgrewalhere mentioned this in T274579: Upgrade WebdriverIO to v7 in all repositories.Aug 18 2021, 2:26 PM

zeljkofilipin added a parent task: T274579: Upgrade WebdriverIO to v7 in all repositories.Aug 20 2021, 2:24 PM

zeljkofilipin moved this task from Waiting 🏹 to Deep work 🌊 on the User-zeljkofilipin board.Aug 30 2021, 5:57 PM

zeljkofilipin moved this task from Deep work 🌊 to Quarter 👔 on the User-zeljkofilipin board.Aug 31 2021, 3:12 PM

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

zeljkofilipin removed a project: Quality-and-Test-Engineering-Team.

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.

zeljkofilipin moved this task from Quarter 👔 to Backlog 🪒 on the User-zeljkofilipin board.Oct 7 2021, 12:08 PM

zeljkofilipin added a parent task: T291254: Find flaky Selenium tests.Oct 7 2021, 6:06 PM

Change 756166 had a related patch set uploaded (by Osamaahmed17; author: Osamaahmed17):

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

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

I have made a new commit, have resolved the error, and updated the packages. Here is the link to the new commit
Updated commit: https://gerrit.wikimedia.org/r/c/mediawiki/extensions/Echo/+/756166/1

@Sahilgrewalhere, can you abandon your commit as it was having a merge conflict and was getting difficult to resolve?
Your commit: https://gerrit.wikimedia.org/r/c/mediawiki/extensions/Echo/+/678287/

Change 678287 abandoned by Zfilipin:

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

Reason:

Moved to https://gerrit.wikimedia.org/r/c/mediawiki/extensions/Echo/+/756166

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

In T271281#7643188, @Osamaahmed17 wrote:

@Sahilgrewalhere, can you abandon your commit as it was having a merge conflict and was getting difficult to resolve?
Your commit: https://gerrit.wikimedia.org/r/c/mediawiki/extensions/Echo/+/678287/

Done.

zeljkofilipin assigned this task to Osamaahmed17.Jan 24 2022, 12:55 PM

zeljkofilipin moved this task from Backlog 🪒 to Deep work 🌊 on the User-zeljkofilipin board.

Change 756166 merged by jenkins-bot:

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

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

Maintenance_bot removed a project: Patch-For-Review.Jan 26 2022, 5:10 PM

Osamaahmed17 closed this task as Resolved.Jan 26 2022, 5:29 PM