Page MenuHomePhabricator
Create Task
Maniphest T216818

MediaWiki webdriver.io dies out with a trace / exit 1 and fail to craft a report
Open, Needs TriagePublic
Actions

Description

There is an issue in MediaWiki webdriver.io system somewhere, the reporter sometime might have an exception thrown which is not handled and it eventually causes NodeJS to exit abruptly. It leaves no indication as to what was the test failure since the reporter has not been crafted.

First got mentioned on T198125, the root cause was mwbot failling to login. At least that part got fixed in wdio-mediawiki with b0102bcc98c35184f5c3d6f1260a4837f2dab7e2 by keeping a Promise chain.

The next one is T216069, EventBus patch https://gerrit.wikimedia.org/r/#/c/490141/7 caused some API request to trigger an error. Apparently that happened in one of the before hook and went unhandled triggering the issue:

node_modules/webdriverio/build/lib/utils/ReporterStats.js:365
				throw Error(`Unrecognised hook [${runner.title}] for suite [${runner.parent}]`);
				^

Error: Unrecognised hook ["after each" hook for "should be deletable"] for suite [Page]
    at ReporterStats.getHookStats (/home/hashar/projects/mediawiki/core/node_modules/webdriverio/build/lib/utils/ReporterStats.js:365:11)
    at ReporterStats.hookEnd (/home/hashar/projects/mediawiki/core/node_modules/webdriverio/build/lib/utils/ReporterStats.js:332:34)
    at BaseReporter.<anonymous> (/home/hashar/projects/mediawiki/core/node_modules/webdriverio/build/lib/utils/BaseReporter.js:147:25)
    at emitOne (events.js:116:13)
    at BaseReporter.emit (events.js:211:7)
    at BaseReporter.handleEvent (/home/hashar/projects/mediawiki/core/node_modules/webdriverio/build/lib/utils/BaseReporter.js:300:27)
    at Launcher.messageHandler (/home/hashar/projects/mediawiki/core/node_modules/webdriverio/build/lib/launcher.js:688:28)
    at emitTwo (events.js:126:13)
    at ChildProcess.emit (events.js:214:7)
    at emit (internal/child_process.js:772:12)
(node:30574) UnhandledPromiseRejectionWarning: Error [ERR_IPC_CHANNEL_CLOSED]: channel closed
    at process.target.send (internal/child_process.js:588:16)
    at /home/hashar/projects/mediawiki/core/node_modules/webdriverio/build/lib/runner.js:746:17
    at <anonymous>
    at process._tickDomainCallback (internal/process/next_tick.js:228:7)
(node:30574) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 4)
(node:30574) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

I reproduce it reliably by not providing an Admin user and running wdio --spec specs/page.js. That way the test suite can not delete page and fails on Page should be deletable.

I went with some basic console.log() statements in webdriverio code.

UID WAS "after each" hook for "should be deletable"33
{ '"before all" hook3': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:13.079Z,
     _duration: 606,
     uid: '"before all" hook3',
     title: '"before all" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: undefined,
     end: 2019-02-22T12:56:13.685Z },
  '"before each" hook5': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:13.685Z,
     _duration: 13,
     uid: '"before each" hook5',
     title: '"before each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be previewable',
     end: 2019-02-22T12:56:13.698Z },
  '"before each" hook6': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:13.700Z,
     _duration: 92,
     uid: '"before each" hook6',
     title: '"before each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be previewable',
     end: 2019-02-22T12:56:13.792Z },
  '"after each" hook7': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:16.146Z,
     _duration: 11,
     uid: '"after each" hook7',
     title: '"after each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be previewable',
     end: 2019-02-22T12:56:16.157Z },
  '"before each" hook9': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:16.159Z,
     _duration: 12,
     uid: '"before each" hook9',
     title: '"before each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be creatable',
     end: 2019-02-22T12:56:16.171Z },
  '"before each" hook10': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:16.171Z,
     _duration: 18,
     uid: '"before each" hook10',
     title: '"before each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be creatable',
     end: 2019-02-22T12:56:16.189Z },
  '"after each" hook11': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:18.579Z,
     _duration: 0,
     uid: '"after each" hook11',
     title: '"after each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be creatable',
     end: 2019-02-22T12:56:18.579Z },
  '"before each" hook13': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:18.579Z,
     _duration: 6,
     uid: '"before each" hook13',
     title: '"before each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be re-creatable',
     end: 2019-02-22T12:56:18.585Z },
  '"before each" hook14': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:18.585Z,
     _duration: 58,
     uid: '"before each" hook14',
     title: '"before each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be re-creatable',
     end: 2019-02-22T12:56:18.643Z },
  '"after each" hook15': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:18.757Z,
     _duration: 0,
     uid: '"after each" hook15',
     title: '"after each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be re-creatable' },
  '"after each" hook16': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:18.760Z,
     _duration: 304,
     uid: '"after each" hook16',
     title: '"after each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be re-creatable',
     end: 2019-02-22T12:56:19.064Z },
  '"before each" hook18': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:18.939Z,
     _duration: 19,
     uid: '"before each" hook18',
     title: '"before each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be editable @daily',
     end: 2019-02-22T12:56:18.958Z },
  '"before each" hook19': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:18.958Z,
     _duration: 0,
     uid: '"before each" hook19',
     title: '"before each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be editable @daily' },
  '"before each" hook21': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:19.064Z,
     _duration: 8,
     uid: '"before each" hook21',
     title: '"before each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should have history @daily',
     end: 2019-02-22T12:56:19.072Z },
  '"before each" hook22': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:19.078Z,
     _duration: 18,
     uid: '"before each" hook22',
     title: '"before each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should have history @daily',
     end: 2019-02-22T12:56:19.096Z },
  '"after each" hook24': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:19.081Z,
     _duration: 0,
     uid: '"after each" hook24',
     title: '"after each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should have history @daily' },
  '"after each" hook25': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:19.081Z,
     _duration: 0,
     uid: '"after each" hook25',
     title: '"after each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should have history @daily' },
  '"after each" hook26': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:19.111Z,
     _duration: 286,
     uid: '"after each" hook26',
     title: '"after each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should have history @daily',
     end: 2019-02-22T12:56:19.397Z },
  '"after all" hook27': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:19.219Z,
     _duration: 0,
     uid: '"after all" hook27',
     title: '"after all" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: undefined,
     end: 2019-02-22T12:56:19.219Z },
  '"before each" hook29': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:19.397Z,
     _duration: 0,
     uid: '"before each" hook29',
     title: '"before each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be deletable' },
  '"after each" hook31': 
   HookStats {
     type: 'hook',
     start: 2019-02-22T12:56:19.397Z,
     _duration: 0,
     uid: '"after each" hook31',
     title: '"after each" hook',
     parent: 'Page',
     parenUid: 'Page2',
     currentTest: 'should be deletable' } }

The "should be deletable" test fail due to lack of permission. It seems to me webdriver.io attempt to craft the report but the after hook has not completed yet? There is no hook33 in the stats.

Also it seems we run after each hook twice! So that might be part of the problem.

Details

SubjectRepoBranchLines +/-
selenium: prevent webdriverio automatic screenshotmediawiki/coremaster+6 -5
Customize query in gerrit

Related Objects

Event Timeline

hashar created this task.Feb 22 2019, 1:07 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptFeb 22 2019, 1:07 PM
hashar mentioned this in T216069: Flaky quibble-vendor-mysql-hhvm-docker test in Jenkins.Feb 22 2019, 1:08 PM
hashar mentioned this in T198125: MediaWiki webdriver afterTest hook should catch mwbot issues/exceptions.
hashar added a comment.Feb 22 2019, 1:32 PM

The reporter works all fine if, in afterTest hook, I early return before saving the screenshot:

--- a/tests/selenium/wdio.conf.js
+++ b/tests/selenium/wdio.conf.js
@@ -201,16 +201,17 @@ exports.config = {
        afterTest: function ( test ) {
                if ( ffmpeg ) {
                        // stop video recording
                        ffmpeg.kill( 'SIGINT' );
                }
 
                // if test passed, ignore, else take and save screenshot
                if ( test.passed ) {
                        return;
                }
+               return;
                // save screenshot
                let screenshotPath = filePath( test, this.screenshotPath, 'png' );
                browser.saveScreenshot( screenshotPath );
                console.log( '\n\tScreenshot location:', screenshotPath, '\n' );
        }
 };

And that fallback to the login error from MWBot being caught as it should ;)

gerritbot subscribed.Feb 22 2019, 2:03 PM

Change 492328 had a related patch set uploaded (by Hashar; owner: Hashar):
[mediawiki/core@master] selenium: prevent webdriverio automatic screenshot

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

gerritbot added a project: Patch-For-Review.Feb 22 2019, 2:03 PM
zeljkofilipin moved this task from Inbox to Selenium on the MediaWiki-Core-Tests board.Feb 22 2019, 2:51 PM
gerritbot added a comment.Feb 22 2019, 3:35 PM

Change 492328 merged by jenkins-bot:
[mediawiki/core@master] selenium: prevent webdriverio automatic screenshot

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

ReleaseTaggerBot added a project: MW-1.33-notes (1.33.0-wmf.19; 2019-02-26).Feb 22 2019, 4:01 PM
Maintenance_bot removed a project: Patch-For-Review.May 22 2019, 1:35 PM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL