Page MenuHomePhabricator

Potential time based race condition with xunit filenames
Open, Needs TriagePublic


When building the job quibble-daily-InterwikiSorting-vendor-mysql-php72-docker I have encountered an UNSTABLE build.

Build kept for comparison:

The failure comes from mediawiki/core tests. Both builds have five tests running.

The bad one only has four xunit reports:

-rw-r--r-- 1 hashar hashar 3556 9 mai 12:19 bad/archive/log/WDIO.xunit-2022-05-09T12-19-28-801Z.xml
-rw-r--r-- 1 hashar hashar 7583 9 mai 12:19 bad/archive/log/WDIO.xunit-2022-05-09T12-19-28-806Z.xml
-rw-r--r-- 1 hashar hashar 2178 9 mai 12:19 bad/archive/log/WDIO.xunit-2022-05-09T12-19-28-840Z.xml
-rw-r--r-- 1 hashar hashar 1023 9 mai 12:19 bad/archive/log/WDIO.xunit-2022-05-09T12-19-31-236Z.xml

The good one has five:

-rw-r--r-- 1 hashar hashar 7585 9 mai 12:40 rebuild/archive/log/WDIO.xunit-2022-05-09T12-40-54-041Z.xml
-rw-r--r-- 1 hashar hashar 1502 9 mai 12:40 rebuild/archive/log/WDIO.xunit-2022-05-09T12-40-54-066Z.xml
-rw-r--r-- 1 hashar hashar 3659 9 mai 12:41 rebuild/archive/log/WDIO.xunit-2022-05-09T12-40-54-116Z.xml
-rw-r--r-- 1 hashar hashar 2174 9 mai 12:40 rebuild/archive/log/WDIO.xunit-2022-05-09T12-40-54-160Z.xml
-rw-r--r-- 1 hashar hashar 1023 9 mai 12:40 rebuild/archive/log/WDIO.xunit-2022-05-09T12-40-56-808Z.xml

I suspect a time based race condition in the wdio xunit reporter which forge two files with the same name and write two set of test result in the same file.

Event Timeline

The bad XML file is WDIO.xunit-2022-05-09T12-19-28-806Z.xml it has <testsuite name="Special RecentChanges"> which is the MediaWiki core test suite tests/selenium/specs/recentchanges.js.

Then the file has at some point the lines:

    <testcase classname="chrome.90_0_4430_212.linux.Page" name="should be creatable" time="0">

Which comes from tests/selenium/specs/page.js.

What I suspect is the reporter generated two identical file names. The result for the Page suite got written then the one from the Recentchange suite. End result is borked :-\

Looks like the issue comes from our wdio-mediawiki NodeJS module, specially:

// See also:
reporters: [
    // See also:
    // See also:
    [ 'junit', {
        outputDir: logPath,
        outputFileFormat: function () {
            return `WDIO.xunit-${makeFilenameDate()}.xml`;
    } ]

Which I guess is subject to time based race condition when the function call to new Date().toISOString() is done in the same millisecond?