"Stream not Writeable" Error When Running WDIO Tests

[pmoeller91]

Bug Report

Description

Sometimes, when running WDIO tests, under some circumstances, an outdated version of PNGJS (a dependency of node-resemble-js) will encounter a race condition of some kind. This will cause an error when trying to write a screenshot, throwing a "Stream not writeable!" message. It seems very similar to what is described here: https://stackoverflow.com/questions/37776746/node-js-pngjs-error-stream-not-writable-randomly although in my case it seemed highly sensitive to initial conditions. The error would consistently occur in a particular wdio test file, but when any of the starting conditions were changed it would cause the error to not occur.

I wanted to report this early as I'm afraid this may come up randomly as more people start to adopt @cerner/terra-functional-testing in their components.

Steps to Reproduce

1. Run a whole lot of WDIO tests
2. Get unlucky and have a race condition occur which marks the file as unwriteable prior to completing the write
3. Error is thrown, causing a failed test

Additional Context / Screenshots

This is an example of the error occurring. This error would not occur when only running this test, or when running basically any other combination of tests still including this test, but under whatever specific circumstances I am experiencing this would consistently happen.

Expected Behavior

Pngjs should not have nasty race conditions that cause a stream to be marked as not writeable prior to completing output.

Possible Solution

Update or fork node-resemble-js to use a newer version of pngjs may be one possible solution. The whole library seems to be rather old and unmaintained, which is itself perhaps a red flag.

Environment

• Component Name and Version: encounters-js (github.cerner.com, terra-functional-testing-upgrade branch)
• Browser Name and Version: N/A
• Node/npm Version: [e.g. Node 8/npm 5] Node v10.23.1 npm v6.14.10
• Webpack Version: 4.46.0
• Operating System and version (desktop or mobile): MacOS Catalina 10.15.7

@ Mentions

[benbcai]

@pmoeller91 Do you have a link to the specific test(s) in your project showing how your test(s) is written where you encountered this error?

[pmoeller91]

@benbcai This was the specific test where the error would show up, however it was very sensitive to starting conditions: https://gist.github.com/benbcai/e2e214c50fd6415f80842d3712b7dc5b#file-encounters-columns-spec-js-L110 Tests are very simple in this file, just UX validation.

Error also appears to happen in CI, was hoping it was more sensitive than that..

[benbcai]

The following is the conversation with @pmoeller91 that provides more information about this error.

• Q1. What exactly do you mean by "starting conditions" or "initial conditions" that is sensitive in recreating it.

What I meant by that was when I tried to comment out any other tests it seemed like that test would suddenly start passing - it was odd. When narrowed down to JUST that test it passed, too. I can't pin down where the exception is occurring either.

• Q2. When you say "Run a whole lot of WDIO tests", are you referring to running a test file that contains lots of test steps or running a project that contains lots of test files (but each test file doesn't require to have lots of test steps)?

I'm not sure - I was assuming the more tests being run / the more tests within a single spec, the more likely this issue may be to occur. I think this spec file is the spec file in this project that has the most individual tests in it. However, oddly, the error only occurs for tiny viewpoint, which is tested first.

• Q3. When the error does occur, does it always and only occur on this test?

Yes, it only occurs on that one test. There is sometimes an additional error on the subsequent test which seems to be carryover from the previous test failing. Something about file not being defined in a hook, I think the CI build has this error present.

• Q4. When the error occurs either locally or in CI do you just run it again and the error may not occur on the second run?

It actually did seem rather scarily consistent, I assumed I was just unlucky, but I'm a little less confident since it now appears on CI as well.

• Q5. Did this occur before your project(s) upgraded from terra-toolkit to terra-functional-testing?

It did not occur before, but as part of the upgrade I refactored some tests to hang out in a single file since the nesting of directories and etc. in our tests was getting rather excessive, and all these tests fit together nicely.

• Q6. What other projects does you team own where you have seen this error. We may use these projects to help us reproduce and investigate since we haven't seen this error in our projects.

Unfortunately this is the first project where we have tried to do the upgrade. I am doing the upgrade in my float time as essentially a proof of concept to see how it would work for this project and for others that we own.

Error from CI build

[2021-04-24T02:45:45.665Z] [0-23] RUNNING in chrome - /tests/wdio/encounters-visits-table/encounters-columns-spec.js

[2021-04-24T02:46:32.362Z] [0-23] Error in "[tiny] Encounter Columns Personnel Column (1482865, 1482869) Encounter with Attending Physician"

[2021-04-24T02:46:32.362Z] Error: Stream not writable

[2021-04-24T02:46:32.362Z]     at module.exports.ChunkStream.write (/app/node_modules/node-resemble-js/node_modules/pngjs/lib/chunkstream.js:46:24)

[2021-04-24T02:46:32.362Z]     at exports.PNG.PNG.write (/app/node_modules/node-resemble-js/node_modules/pngjs/lib/png.js:92:16)

[2021-04-24T02:46:32.362Z]     at ReadStream.ondata (_stream_readable.js:710:20)

[2021-04-24T02:46:32.362Z]     at ReadStream.emit (events.js:198:13)

[2021-04-24T02:46:32.362Z]     at ReadStream.EventEmitter.emit (domain.js:448:20)

[2021-04-24T02:46:32.362Z]     at addChunk (_stream_readable.js:288:12)

[2021-04-24T02:46:32.362Z]     at readableAddChunk (_stream_readable.js:269:11)

[2021-04-24T02:46:32.362Z]     at ReadStream.Readable.push (_stream_readable.js:224:10)

[2021-04-24T02:46:32.362Z]     at lazyFs.read (internal/fs/streams.js:181:12)

[2021-04-24T02:46:32.362Z]     at FSReqWrap.wrapper [as oncomplete] (fs.js:467:17)

[2021-04-24T02:46:32.362Z] [0-23] Error in "[tiny] Encounter Columns Personnel Column (1482865, 1482869) Encounter with Attending Physician"

[2021-04-24T02:46:32.362Z] Error: done() called multiple times in test <[tiny] Encounter Columns Personnel Column (1482865, 1482869) Encounter with Attending Physician> of file /app/tests/wdio/encounters-visits-table/encounters-columns-spec.js

[2021-04-24T02:46:32.362Z]     at createMultipleDoneError (/app/node_modules/mocha/lib/errors.js:421:13)

[2021-04-24T02:46:32.362Z]     at multiple (/app/node_modules/mocha/lib/runnable.js:290:24)

[2021-04-24T02:46:32.362Z]     at done (/app/node_modules/mocha/lib/runnable.js:301:14)

[2021-04-24T02:46:32.362Z]     at /app/node_modules/mocha/lib/runnable.js:371:11

[2021-04-24T02:46:32.362Z] [0-23] 2021-04-24T02:46:28.622Z ERROR @wdio/sync: TypeError: Cannot read property 'file' of undefined

[2021-04-24T02:46:32.362Z]     at LocalCompare.getScreenshotPaths (/app/node_modules/@cerner/terra-functional-testing/lib/services/wdio-visual-regression-service/methods/BaseCompare.js:109:50)

[2021-04-24T02:46:32.362Z]     at VisualRegressionLauncher.afterTest (/app/node_modules/@cerner/terra-functional-testing/lib/services/wdio-visual-regression-service/VisualRegressionLauncher.js:110:24)

[2021-04-24T02:46:32.363Z]     at execHook (/app/node_modules/@wdio/sync/build/executeHooksWithArgs.js:21:31)

[2021-04-24T02:46:32.363Z] [0-23] Error in "AfterTest Hook"

[2021-04-24T02:46:32.363Z] Cannot read property 'file' of undefined

[2021-04-24T02:46:32.363Z] [0-23] TypeError in "[tiny] Encounter Columns Personnel Column (1482865, 1482869) Encounter with Flex on Type Priority"

[2021-04-24T02:46:32.363Z] TypeError: Cannot read property 'file' of undefined

[2021-04-24T02:46:32.363Z]     at LocalCompare.getScreenshotPaths (/app/node_modules/@cerner/terra-functional-testing/lib/services/wdio-visual-regression-service/methods/BaseCompare.js:109:50)

[2021-04-24T02:46:32.363Z]     at LocalCompare.processScreenshot (/app/node_modules/@cerner/terra-functional-testing/lib/services/wdio-visual-regression-service/methods/LocalCompare.js:48:14)

[2021-04-24T02:46:32.363Z]     at VisualRegressionLauncher.wrappedScreenshotCommand (/app/node_modules/@cerner/terra-functional-testing/lib/services/wdio-visual-regression-service/VisualRegressionLauncher.js:160:42)

[2021-04-24T02:46:32.363Z]     at Browser.next [as checkElement] (/app/node_modules/@wdio/utils/build/monad.js:95:33)

[2021-04-24T02:46:32.363Z]     at Object.screenshot (/app/node_modules/@cerner/terra-functional-testing/lib/commands/validates/screenshot.js:23:43)

[2021-04-24T02:46:32.363Z]     at Context.<anonymous> (/app/tests/wdio/encounters-visits-table/encounters-columns-spec.js:116:23)

[2021-04-24T02:47:04.467Z] [0-23] FAILED in chrome - /tests/wdio/encounters-visits-table/encounters-columns-spec.js

Additional observations and information provided by @pmoeller91

My assumption was some kind of race condition because of the stack overflow mentioning that similar error and since it would explain the strangeness of the error appearing / disappearing depending on which tests were running on a given run, and because even digging into file access I couldn't see something really obvious (although my eye is not that practice as reading the fs_usage command).

I was further leaning towards that being a possible cause because the date on the stack overflow linked (several years old) lines up with the age of the version of the dependency being pulled in fairly closely

My further assumption was that because I felt like I might be a relatively early adopter, this may be an issue that either had not come up yet or was infrequent enough that it was easily overlooked and ignored, so I wanted to throw it out there just in case.

• Also discovered that the error will start happening on a different test if the order of the tests in that describe block are moved around - always happens on the third test.

• Doesn't happen if there's no reference snapshot for the test

• Doesn't happen if any one test before it is commented out

• Still happens even if every subsequent test is commented out

• Does still happen if the name of the snapshot is changed

• Does still happen if a small synchronous delay is added to the failing test case prior to either command, or to the previous test case after either command. (No-op for-loop with 1e5/1e6 iterations)

[benbcai]

Spike Summary

Attempt to recreate with Terra projects

Unable to recreate in terra-core, terra-framework, or terra-clinical, all of which have a very large number of tests capturing several thousand screenshots altogether. One notable difference between these monorepos and encounter-js where the error is reproducible is that it has many tests that load a new url many times within the test. Not certain if this has any impact in triggering the error.

Cause of the error (node-resemble-js and pngjs)

• terra-functional-testing depends on node-resemble-js and pngjs to perform screenshot analysis and comparison.
• terra-functional-testing currently depends on the most current released [email protected]. [email protected] depends on [email protected] which is where the error comes from. See [Error: Stream not writable] on parsing png image pngjs/pngjs#80.
• The latest tagged version [email protected], which is not released depends on [email protected].
• When using the master branch or tagged version of [email protected] with [email protected], the error is no longer reproducible in encounter-js. I do not know which version of pngjs has the fix. Maybe version 3 based on this.

Current situation

• Other open-source projects have also encountered this error.
• The error has been fixed in pngjs. We just need node-resemble-js to publish a release from master that pulls in version 6.0.0 of pngjs.
• Issue #49 is logged to node-resemble-js to request to publish a release but there are some issue publishing the release by the maintainer.

Our options

1. If we could get a new release of node-resemble-js, this would be the easiest and quickest way to resolve the issue by pulling in the new version.
2. If a new version would not be released, should we reference the tagged version 1.2.0 of node-resemble-js?
3. If both options above not acceptable, there are four other replacements for node-resemble-js mentioned in this comment.
   • The first 2 (node-resemble-v2; resemblejs-node) are not well maintained and have limited activities. We should pass on these.
   • The last 2 reference the same Resemble.js. This is better maintained and has better support and weekly download activities. node-resemble-js that terra-functional-testing currently depends on was forked from Resemble.js.
     • Replacing node-resemble-js with Resemble.js appears to work when screenshots are matching. However, errors occur when there are mismatches due to API incompatibilities and difference in the image type. This is still under investigation to determine if it is possible and how much effort is required to switch from using node-resemble-js to Resemble.js.

05/05/2021 edit: @mirzazeyrek/node-resemble-js v1.2.1 just got released. Tested with this version using encounter-js and no longer get the Stream not writable error. The current plan is to go with Option 1.

[mirzazeyrek]

https://www.npmjs.com/package/@mirzazeyrek/node-resemble-js

[yuderekyu]

great investigation @benbcai !! 🎉