Page MenuHomePhabricator

✖ can retry saving bridge from ErrorSaving
Closed, ResolvedPublic3 Estimated Story Points

Description

Seen on https://gerrit.wikimedia.org/r/c/mediawiki/core/+/660007 at https://integration.wikimedia.org/ci/job/wmf-quibble-selenium-php72-docker/77746/console

21:11:52 [chrome 73.0.3683.75 Linux #0-4] Spec: /workspace/src/extensions/Wikibase/client/data-bridge/tests/selenium/specs/errorHandling.js
21:11:52 [chrome 73.0.3683.75 Linux #0-4] Running: chrome (v73.0.3683.75) on Linux
21:11:52 [chrome 73.0.3683.75 Linux #0-4] Session ID: 1b92ecc4a46a23f161326a627f8bfc43
21:11:52 [chrome 73.0.3683.75 Linux #0-4]
21:11:52 [chrome 73.0.3683.75 Linux #0-4] App
21:11:52 [chrome 73.0.3683.75 Linux #0-4]    ✓ shows ErrorUnknown when launching bridge for a non-existent entity
21:11:52 [chrome 73.0.3683.75 Linux #0-4]    ✓ can be relaunched from ErrorUnknown
21:11:52 [chrome 73.0.3683.75 Linux #0-4]    ✖ can retry saving bridge from ErrorSaving
21:11:52 [chrome 73.0.3683.75 Linux #0-4]    ✓ can go back from a save error both on desktop and mobile
21:11:52 [chrome 73.0.3683.75 Linux #0-4]
21:11:52 [chrome 73.0.3683.75 Linux #0-4]     when assertuser fails
21:11:52 [chrome 73.0.3683.75 Linux #0-4]        ✓ can retry saving without assertuser
21:11:52 [chrome 73.0.3683.75 Linux #0-4]        ✓ can login and retry saving
21:11:52 [chrome 73.0.3683.75 Linux #0-4]        ✓ still asserts user after logging in
21:11:52 [chrome 73.0.3683.75 Linux #0-4]        ✓ shows custom Bridge warning on login page
21:11:52 [chrome 73.0.3683.75 Linux #0-4]
21:11:52 [chrome 73.0.3683.75 Linux #0-4]     when there is an edit conflict
21:11:52 [chrome 73.0.3683.75 Linux #0-4]        ✓ reloads on reload button click
21:11:52 [chrome 73.0.3683.75 Linux #0-4]        ✓ reloads on close button click
21:11:52 [chrome 73.0.3683.75 Linux #0-4]
21:11:52 [chrome 73.0.3683.75 Linux #0-4] 9 passing (1m 10.6s)
21:11:52 [chrome 73.0.3683.75 Linux #0-4] 1 failing
21:11:52 [chrome 73.0.3683.75 Linux #0-4]
21:11:52 [chrome 73.0.3683.75 Linux #0-4] 1) App can retry saving bridge from ErrorSaving
21:11:52 [chrome 73.0.3683.75 Linux #0-4] element (".oo-ui-dialog #data-bridge-app .wb-db-bridge") still not displayed after 5000ms
21:11:52 [chrome 73.0.3683.75 Linux #0-4] Error: element (".oo-ui-dialog #data-bridge-app .wb-db-bridge") still not displayed after 5000ms
21:11:52 [chrome 73.0.3683.75 Linux #0-4]     at Context.it (/workspace/src/extensions/Wikibase/client/data-bridge/tests/selenium/specs/errorHandling.js:100:25)

Investigated in T273327#6884379.
There doesn't appear to be anything wrong with the test.
@Addshore would proposed doubling the timeout for this test... (and similar waits / timeouts)

Acceptance Criteria:

  • Set the timeout for this wait to be higher (inline with what the timings in the investigation suggest might be okay)
  • Increase timeouts in other places where waitForDisplayed, which is related to an API call, is being used.

Event Timeline

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

Preserving the log here.

23:17:17 [chrome 73.0.3683.75 Linux #0-5] Spec: /workspace/src/extensions/Wikibase/client/data-bridge/tests/selenium/specs/init.js
23:17:17 [chrome 73.0.3683.75 Linux #0-5] Running: chrome (v73.0.3683.75) on Linux
23:17:17 [chrome 73.0.3683.75 Linux #0-5] Session ID: 2ffecfec7427d922a3e97a2e57dc39d0
23:17:17 [chrome 73.0.3683.75 Linux #0-5]
23:17:17 [chrome 73.0.3683.75 Linux #0-5] init
23:17:17 [chrome 73.0.3683.75 Linux #0-5]    ✓ opens app in OOUI dialog
23:17:17 [chrome 73.0.3683.75 Linux #0-5]    ✓ indicates loading while app gathers its data
23:17:17 [chrome 73.0.3683.75 Linux #0-5]
23:17:17 [chrome 73.0.3683.75 Linux #0-5]     once app is launched
23:17:17 [chrome 73.0.3683.75 Linux #0-5]        ✖ shows the current targetValue
23:17:17 [chrome 73.0.3683.75 Linux #0-5]        ✓ shows the current targetReference
23:17:17 [chrome 73.0.3683.75 Linux #0-5]
23:17:17 [chrome 73.0.3683.75 Linux #0-5]         target property label
23:17:17 [chrome 73.0.3683.75 Linux #0-5]            ✓ uses the label from the page content language
23:17:17 [chrome 73.0.3683.75 Linux #0-5]            ✓ uses the label from a non-English fallback language
23:17:17 [chrome 73.0.3683.75 Linux #0-5]            ✓ uses the label from the English fallback language
23:17:17 [chrome 73.0.3683.75 Linux #0-5]            ✓ uses the property ID if no label in fallback chain found
23:17:17 [chrome 73.0.3683.75 Linux #0-5]
23:17:17 [chrome 73.0.3683.75 Linux #0-5]     warning for anonymous edits
23:17:17 [chrome 73.0.3683.75 Linux #0-5]        ✓ is not shown when logged in
23:17:17 [chrome 73.0.3683.75 Linux #0-5]
23:17:17 [chrome 73.0.3683.75 Linux #0-5]         when anonymous
23:17:17 [chrome 73.0.3683.75 Linux #0-5]            ✓ is shown and can be dismissed
23:17:17 [chrome 73.0.3683.75 Linux #0-5]            ✓ is shown and leads to login page
23:17:17 [chrome 73.0.3683.75 Linux #0-5]
23:17:17 [chrome 73.0.3683.75 Linux #0-5] 10 passing (1m 21.7s)
23:17:17 [chrome 73.0.3683.75 Linux #0-5] 1 failing
23:17:17 [chrome 73.0.3683.75 Linux #0-5]
23:17:17 [chrome 73.0.3683.75 Linux #0-5] 1) once app is launched shows the current targetValue
23:17:17 [chrome 73.0.3683.75 Linux #0-5] element (".oo-ui-dialog #data-bridge-app .wb-db-bridge") still not displayed after 5000ms
23:17:17 [chrome 73.0.3683.75 Linux #0-5] Error: element (".oo-ui-dialog #data-bridge-app .wb-db-bridge") still not displayed after 5000ms
23:17:17 [chrome 73.0.3683.75 Linux #0-5]     at Context.it (/workspace/src/extensions/Wikibase/client/data-bridge/tests/selenium/specs/init.js:107:26)

I smell a fish, though i'm not sure if it is a herring.

element (".oo-ui-dialog #data-bridge-app .wb-db-bridge") still not displayed after 5000ms``

However the video artifact of the test is only 3 seconds long?
https://integration.wikimedia.org/ci/job/wmf-quibble-selenium-php72-docker/81176/artifact/log/once-app-is-launched_shows-the-current-targetValue.mp4
And the timeout that is failing is 5 seconds long?
Not only that but the test makes at least 3 api calls that should be taking some amount of time, after which the 5second time out should start...
This could just be an issue with the video recording though?

			const title = DataBridgePage.getDummyTitle();
			const propertyId = browser.call( () => WikibaseApi.getProperty( 'string' ) );
			const stringPropertyExampleValue = 'ExampleString';
			const entityId = browser.call( () => WikibaseApi.createItem( 'data bridge browser test item', {
				'claims': [ {
					'mainsnak': {
						'snaktype': 'value',
						'property': propertyId,
						'datavalue': { 'value': stringPropertyExampleValue, 'type': 'string' },
					},
					'type': 'statement',
					'rank': 'normal',
				} ],
			} ) );
			const content = DataBridgePage.createInfoboxWikitext( [ {
				label: 'official website',
				entityId,
				propertyId,
				editFlow: 'single-best-value',
			} ] );
			browser.call( () => Api.bot().then( ( bot ) => bot.edit( title, content ) ) );

			DataBridgePage.openAppOnPage( title );

			DataBridgePage.bridge.waitForDisplayed( 5000 );

The full output can be seen below for the individual test.

Simplified a bit:

  • 23:15:38 - Last API call happens
  • 23:15:39 - Web call to server to load page for test index.php?title=Talk%3AData-bridge-test-page-0.873948559966494-I%C3%B1t%C3%ABrn%C3%A2ti%C3%B4n%C3%A0liz%C3%A6ti%C3%B8n happens
  • 23:15:44 - Video saves, test has failed due to element (".oo-ui-dialog #data-bridge-app .wb-db-bridge") still not displayed after 5000ms
  • 2 seconds after failing the API calls that happen on bridge init happen?
  • 23:15:46 /api.php?action=query&format=json&titles=Talk%3AData-bridge-test-page-0.873948559966494-I%C3%B1t%C3%ABrn%C3%A2ti%C3%B4n%C3%A0liz%C3%A6ti%C3%B8n&prop=info&meta=siteinfo&intestactions=edit&intestactionsdetail=full&siprop=restrictions&errorformat=raw&formatversion=2
  • 23:15:47 /api.php?action=wbgetentities&format=json&props=labels%7Cdatatype%7Cinfo%7Cclaims&ids=P8%7CQ26&languages=en&languagefallback=true&formatversion=2
  • 23:15:47 /api.php?action=query&format=json&meta=wbdatabridgeconfig%7Csiteinfo&formatversion=2&errorformat=raw&titles=Item%3AQ26&prop=info&intestactions=edit&intestactionsdetail=full&siprop=restrictions

So really all this timeout is doing is stopping a test that is actually working from finishing (just for the few seconds when the test is running the shared CPU is going a bit slower for whatever reason)

23:15:23 [0-5] RUNNING in chrome - /tests/selenium/specs/init.js
23:15:25 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:25 2021] 127.0.0.1:39280 [200]: //api.php?format=json
23:15:25 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:25 2021] 127.0.0.1:39282 [200]: //api.php?format=json
23:15:25 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:25 2021] 127.0.0.1:39284 [200]: //api.php?format=json
23:15:26 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:26 2021] 127.0.0.1:39286 [200]: //api.php?format=json
23:15:26 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:26 2021] 127.0.0.1:39288 [200]: //api.php?format=json
23:15:26 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:26 2021] 127.0.0.1:39290 [200]: //api.php?format=json
23:15:26 [0-5] [23:15:26] [S] [MWBOT] Login successful: WikiAdmin@http://127.0.0.1:9412/
23:15:26 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:26 2021] 127.0.0.1:39296 [200]: //api.php?format=json
23:15:26 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:26 2021] 127.0.0.1:39298 [200]: //api.php?format=json
23:15:27 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:27 2021] 127.0.0.1:39304 [200]: //index.php?title=Talk%3AData-bridge-test-page-0.8359347529096492-I%C3%B1t%C3%ABrn%C3%A2ti%C3%B4n%C3%A0liz%C3%A6ti%C3%B8n
23:15:27 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:27 2021] 127.0.0.1:39306 [200]: /load.php?lang=en&modules=ext.uls.pt%7Cext.visualEditor.desktopArticleTarget.noscript%7Cskins.vector.styles.legacy%7Cwikibase.client.data-bridge.externalModifiers%7Cwikibase.client.init&only=styles&skin=vector
23:15:27 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:27 2021] 127.0.0.1:39308 [200]: /load.php?lang=en&modules=startup&only=scripts&raw=1&skin=vector
23:15:28 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:27 2021] 127.0.0.1:39334 [200]: /load.php?lang=en&modules=ext.visualEditor.core.utils.parsing%7Cext.visualEditor.desktopArticleTarget.init%7Cext.visualEditor.progressBarWidget%2CsupportCheck%2CtargetLoader%2CtempWikitextEditorWidget%2Ctrack%2Cve&skin=vector&version=1i7sy
23:15:28 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:28 2021] 127.0.0.1:39336 [200]: /load.php?lang=en&modules=dataValues%2Cjquery%2Coojs%2Coojs-ui-core%2Coojs-ui-widgets%2Coojs-ui-windows%2Csite%7CdataValues.DataValue%7Cext.cx.eventlogging.campaigns%7Cext.eventLogging%2CnavigationTiming%7Cext.uls.interface%2Cpreferences%2Cwebfonts%7Cjquery.client%2Ccookie%2Cspinner%2CtextSelection%2Cui%7Cjquery.event.special.eachchange%7Cjquery.spinner.styles%7Cjquery.ui.suggester%7Cjquery.wikibase.entityselector%7Cmediawiki.ForeignApi%2CString%2CTitle%2CUri%2Capi%2Cbase%2Ccldr%2Ccookie%2CjqueryMsg%2Clanguage%2Cstorage%2Ctemplate%2Cuser%2Cutil%7Cmediawiki.ForeignApi.core%7Cmediawiki.editfont.styles%7Cmediawiki.libs.pluralruleparser%7Cmediawiki.page.ready%7Cmediawiki.template.mustache%2Cmustache%2Bdom%7Cmw.config.values.wbDataBridgeConfig%7Coojs-ui-core.icons%2Cstyles%7Coojs-ui-widgets.icons%7Coojs-ui-windows.icons%7Coojs-ui.styles.indicators%7Cskins.vector.legacy.js%7Cuser.defaults%7Cutil.inherit%7Cwikibase.api.RepoApi%7Cwikibase.client.data-bridge.init%7Cwikibase.datamodel%7Cwikibase.mediainfo.base%2Csearch%7Cwikibase.ui.entitysearch&skin=vector&version=1nay7
23:15:28 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:28 2021] 127.0.0.1:39338 [404]: /favicon.ico - No such file or directory
23:15:28 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:28 2021] 127.0.0.1:39340 [200]: /load.php?lang=en&modules=jquery.uls.data%7Cmw.config.values.wbRepo%7Cvue%2Cvuex%7Cwikibase.client.data-bridge.app&skin=vector&version=hdpnl
23:15:28 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:28 2021] 127.0.0.1:39342 [200]: /load.php?lang=en&modules=ext.uls.webfonts.fonts%2Crepository%7Cjquery.webfonts&skin=vector&version=11vcv
23:15:28 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:28 2021] 127.0.0.1:39348 [200]: /load.php?lang=en&modules=wikibase.client.data-bridge.app.modern&skin=vector&version=tyb9e
23:15:29 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:29 2021] 127.0.0.1:39350 [200]: /api.php?action=query&format=json&titles=Talk%3AData-bridge-test-page-0.8359347529096492-I%C3%B1t%C3%ABrn%C3%A2ti%C3%B4n%C3%A0liz%C3%A6ti%C3%B8n&prop=info&meta=siteinfo&intestactions=edit&intestactionsdetail=full&siprop=restrictions&errorformat=raw&formatversion=2
23:15:29 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:29 2021] 127.0.0.1:39352 [200]: /api.php?action=wbgetentities&format=json&props=labels%7Cdatatype%7Cinfo%7Cclaims&ids=P8%7CQ24&languages=en&languagefallback=true&formatversion=2
23:15:29 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:29 2021] 127.0.0.1:39354 [200]: /api.php?action=query&format=json&meta=wbdatabridgeconfig%7Csiteinfo&formatversion=2&errorformat=raw&titles=Item%3AQ24&prop=info&intestactions=edit&intestactionsdetail=full&siprop=restrictions
23:15:30 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:30 2021] 127.0.0.1:39388 [200]: //api.php?format=json
23:15:31 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:30 2021] 127.0.0.1:39392 [200]: //api.php?format=json
23:15:31 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:31 2021] 127.0.0.1:39394 [200]: //api.php?format=json
23:15:31 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:31 2021] 127.0.0.1:39400 [200]: //api.php?format=json
23:15:31 [0-5] [23:15:31] [S] [MWBOT] Login successful: WikiAdmin@http://127.0.0.1:9412/
23:15:31 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:31 2021] 127.0.0.1:39410 [200]: //api.php?format=json
23:15:31 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:31 2021] 127.0.0.1:39412 [200]: //api.php?format=json
23:15:31 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:31 2021] 127.0.0.1:39414 [200]: //index.php?title=Talk%3AData-bridge-test-page-0.5750508401188479-I%C3%B1t%C3%ABrn%C3%A2ti%C3%B4n%C3%A0liz%C3%A6ti%C3%B8n
23:15:32 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:32 2021] 127.0.0.1:39428 [200]: /load.php?lang=en&modules=jquery%2Coojs-ui-core%2Coojs-ui-widgets%7Cjquery.ui&skin=vector&version=1e40s
23:15:33 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:33 2021] 127.0.0.1:39438 [200]: /api.php?action=query&format=json&titles=Talk%3AData-bridge-test-page-0.5750508401188479-I%C3%B1t%C3%ABrn%C3%A2ti%C3%B4n%C3%A0liz%C3%A6ti%C3%B8n&prop=info&meta=siteinfo&intestactions=edit&intestactionsdetail=full&siprop=restrictions&errorformat=raw&formatversion=2
23:15:33 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:33 2021] 127.0.0.1:39440 [200]: /api.php?action=wbgetentities&format=json&props=labels%7Cdatatype%7Cinfo%7Cclaims&ids=P8%7CQ25&languages=en&languagefallback=true&formatversion=2
23:15:33 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:33 2021] 127.0.0.1:39442 [200]: /api.php?action=query&format=json&meta=wbdatabridgeconfig%7Csiteinfo&formatversion=2&errorformat=raw&titles=Item%3AQ25&prop=info&intestactions=edit&intestactionsdetail=full&siprop=restrictions
23:15:37 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:37 2021] 127.0.0.1:39490 [200]: //api.php?format=json
23:15:38 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:38 2021] 127.0.0.1:39492 [200]: //api.php?format=json
23:15:38 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:38 2021] 127.0.0.1:39504 [200]: //api.php?format=json
23:15:38 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:38 2021] 127.0.0.1:39506 [200]: //api.php?format=json
23:15:38 [0-5] [23:15:38] [S] [MWBOT] Login successful: WikiAdmin@http://127.0.0.1:9412/
23:15:38 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:38 2021] 127.0.0.1:39512 [200]: //api.php?format=json
23:15:38 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:38 2021] 127.0.0.1:39514 [200]: //api.php?format=json
23:15:39 INFO:backend.PhpWebserver:[Thu Feb 25 23:15:38 2021] 127.0.0.1:39526 [200]: //index.php?title=Talk%3AData-bridge-test-page-0.873948559966494-I%C3%B1t%C3%ABrn%C3%A2ti%C3%B4n%C3%A0liz%C3%A6ti%C3%B8n
23:15:44 [0-5] Video location: /workspace/log/once-app-is-launched_shows-the-current-targetValue.mp4
23:15:46 [0-5] 
23:15:46 	Screenshot: /workspace/log/shows-the-current-targetValue.png
23:15:46 
23:15:46 [0-5] Error in "init once app is launched shows the current targetValue"
23:15:46 element (".oo-ui-dialog #data-bridge-app .wb-db-bridge") still not displayed after 5000ms
noarave set the point value for this task to 3.

Change 673545 had a related patch set uploaded (by Silvan Heintze; owner: Silvan Heintze):
[mediawiki/extensions/Wikibase@master] Increase timeouts for selenium tests

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

Change 673545 merged by jenkins-bot:
[mediawiki/extensions/Wikibase@master] data-bridge: Increase timeouts for selenium tests

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