Page MenuHomePhabricator

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

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.

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

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 ;)

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

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

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