[Regression in 14.1.0 - Windows] `stdout` is sometimes empty #33166

nicolo-ribaudo · 2020-04-30T14:25:51Z

Version: 14.1.0
Platform: Windows 64-bit on VirtualBox and on Travis CI
Subsystem: N/A

Bug description

After the Node.js 14.1.0 release, Babel's CI tests on Windows started failing. The failures are all related to @babel/cli and @babel/node: we run those CLI programs, capture their output (from stdout) and compare it with the expected output.

Sometimes, the generated stdout is empty: you can see an example here or here. In this CI log you can also see some error messages coming from V8 internals in @babel/node tests, but I don't know if it's the same problem.

How often does it reproduce? Is there a required condition?

My guess is that every test has about 1% chance of failing. However, we have ~100 tests for those 2 packages so something is failing more often than not.

What steps will reproduce the bug?

I couldn't find a small and isolated reproduction example. I'll keep trying to create one, but here is what I have for now.
Also, building Babel on Windows is painful and I couldn't run the full test suite. However, I managed to reproduce the bug.

I'm running these commands using Powershell, Nodej.s 14.1.0 and Yarn 1.22

# Clone the babel repository
git clone https://github.com/babel/babel.git .

# Install deps
yarn
yarn lerna bootstrap # This takes a while

# Build Babel (this won't build everything, but enough packages to show the bug)
yarn gulp build-no-bundle

# Run the @babel/cli and @babel/node tests
yarn jest --runInBand babel-node babel-cli

If you don't see the last command failing, try running it 2 or three times. The --runInBand option isn't necessary to reproduce the problem, but it disables Jest's workers so it removes one possible cause.

What is the expected behavior?

Tests should pass

What do you see instead?

An example of output failing locally is this:

PS C:\Users\Nicolò\Downloads\babel-master\babel-master> yarn jest --runInBand babel-node babel-cli
yarn run v1.22.4
$ C:\Users\Nicolò\Downloads\babel-master\babel-master\node_modules\.bin\jest --runInBand babel-node babel-cli
 FAIL  packages/babel-cli/test/index.js (33.099s)
  ● bin/babel › --only glob

    "C:\Users\Nicolò\Downloads\babel-master\babel-master\packages\babel-cli\lib\babel" "--presets" "C:\Users\Nicolò\Downloads\babel-master\babel-master\packages\babel-preset-react" "--plugins" "C:\Users\Nicolò\Downloads\babel-master\babel-master\packages\babel-plugin-transform-arrow-functions,C:\Users\Nicolò\Downloads\babel-master\babel-master\packages\babel-plugin-transform-strict-mode,C:\Users\Nicolò\Downloads\babel-master\babel-master\packages\babel-plugin-transform-modules-commonjs" "src" "--out-dir" "lib" "--only" "**/*.foo.js" "--verbose": expect(received).toBe(expected) // Object.is equality

    Expected: "src/a.foo.js -> lib/a.foo.js
    src/baz/b.foo.js -> lib/baz/b.foo.js
    Successfully compiled 2 files with Babel."
    Received: ""

      85 |       expect(stdout).toContain(expectStdout);
      86 |     } else {
    > 87 |       expect(stdout).toBe(expectStdout);
         |                      ^
      88 |     }
      89 |   } else if (stdout) {
      90 |     throw new Error("stdout:\n" + stdout);

      at assertTest (packages/babel-cli/test/index.js:87:22)
      at ChildProcess.<anonymous> (packages/babel-cli/test/index.js:152:9)

 PASS  packages/babel-node/test/index.js (22.924s)

Test Suites: 1 failed, 1 passed, 2 total
Tests:       1 failed, 89 passed, 90 total
Snapshots:   0 total
Time:        56.088s, estimated 62s
Ran all test suites matching /babel-node|babel-cli/i.
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.

Additional information

You can see here how we capture stdout for @babel/cli tests, . For @babel/node it's the same.
@JLHwung suggested that this might be related to stream: don't wait for close on legacy streams #33058 or stream: don't emit end after close #33076
The bug is not present when using Node.js 14.0

The text was updated successfully, but these errors were encountered:

lpinca · 2020-04-30T17:14:45Z

cc: @nodejs/streams @ronag

mcollina · 2020-04-30T18:17:24Z

Can you confirm this happening only on Windows? This is widely unexpected.

ronag · 2020-04-30T19:02:22Z

I can't reproduce on OSX. @nicolo-ribaudo any chance you could bisect? I don't have a Windows machine at the moment.

ronag · 2020-04-30T19:04:31Z

I'm unsure where to go with the V8 errors. @addaleax maybe?

nicolo-ribaudo · 2020-04-30T19:05:12Z

Yes, I can only reproduce this on windows (not the V8 errors), only the empty stdouts. I'll try to bisect.

addaleax · 2020-04-30T19:21:20Z

@ronag I’m not sure… Stack traces on Windows are basically garbage unless you take some extra steps (that I don’t know how to take), and given that the error message isn’t particularly helpful here either – there are over 2000 instances of UNREACHABLE(); in V8 – I’m not quite sure where to start here.

/cc @nodejs/v8 @nodejs/platform-windows

nicolo-ribaudo · 2020-04-30T21:47:04Z

Update: this might not be a Node.js bug.

Today I made two local clones of the Babel repository: one ~6 hours ago and I can consistently reproduce the errors there, and one ~2 hours ago where I cannot reproduce the errors. This makes me think that maybe it's a bug in a dependency that didn't support Node.js 14.1.0 on windows, and it was recently updated to fix the bug.

Even if there was a bug in a dependency I don't think that it should trigger the V8 internal error, but I cannot reproduce that one anyway 🤷

I'll try to re-run the build on Travis CI a bunch of times, and see if I can reproduce it there.

ronag · 2020-04-30T21:49:54Z

This makes me think that maybe it's a bug in a dependency that didn't support Node.js 14.1.0 on windows, and it was recently updated to fix the bug.

Can you diff the dependencies?

nicolo-ribaudo · 2020-04-30T21:53:46Z

Yeah I'm trying. I'm on a Windows VM and I haven't used Windows for a while, so it might take some time 😛

Also, another thing I noticed: in the folder where I can (consistently!) reproduce the problem, I can only reproduce it when using Node.js 14.1.0. If I use a build form master (4b2d958) it doesn't fail.

ronag · 2020-04-30T21:55:09Z

If I use a build form master (4b2d958) it doesn't fail.

Yea, a bisect would be very useful.

nicolo-ribaudo · 2020-04-30T23:16:35Z

I gave up for today, I will continue tomorrow.
Also, I noticed that Jest's own tests have the same problem: https://github.com/facebook/jest/pull/9934/checks?check_run_id=633574558 (cc @SimenB)

dr-js · 2020-05-01T01:46:02Z

Not sure if it's related, I got win10 + nodejs@14 + babel on CI with flaky ELIFECYCLE/3221225477 exit code in one of my repo: nodejs/help#2660

Update:

I've reduced CI exit test case to some of my source files and babel + 2 babel plugins
The code is at: https://github.com/dr-js/dr-dev/tree/8e111ec5194adc3e159db2d3bc3594f8587dc230
The latest CI fail: https://github.com/dr-js/dr-dev/actions/runs/92784081

Update 2:

With more debug log found the exit happen before the @babel/env plugin gets load, after minify-replace and module-resolver loaded.
Related CI run: https://github.com/dr-js/dr-dev/actions/runs/92845322

SimenB · 2020-05-01T08:51:16Z

Yeah, Jest is failing often on Node 14.1.0 on Windows with empty stdout in one test or the other almost every test run. The V8 thing is actually in the latest build on master: https://github.com/facebook/jest/runs/634830924

nicolo-ribaudo · 2020-05-01T08:54:02Z

Ok, have no idea where to start bisecting. I can still consistently reproduce the failures with the Node.js 14.1.0 installed with the installer, but not if I build 9ffd8e7.

mcollina · 2020-05-02T07:13:33Z

Ok, have no idea where to start bisecting. I can still consistently reproduce the failures with the Node.js 14.1.0 installed with the installer, but not if I build 9ffd8e7.

@nodejs/releasers can you check if there could be any differences between what is available via the installer and what was tagged?

targos · 2020-05-02T08:26:34Z

I think there's no way to be sure it's the promoted one, but I can confirm that the latest release build was done with commit 9ffd8e7
Refs: https://ci-release.nodejs.org/job/iojs+release/5995/
The times of the file on the server and in the build logs also match.

mcollina · 2020-05-02T08:38:03Z

@jasnell I know you have a beefy windows machine, could you check this out and run a bisect?

Yeah, Jest is failing often on Node 14.1.0 on Windows with empty stdout in one test or the other almost every test run. The V8 thing is actually in the latest build on master: https://github.com/facebook/jest/runs/634830924

@SimenB This is worrysome. Are you using any wasm inside Jest?

targos · 2020-05-02T08:51:12Z

I'm building the release commit on my machine (Win10, VS2019)

SimenB · 2020-05-02T09:43:56Z

@mcollina nope, only experimental stuff we ship is the VM ESM APIs, but that code is guarded behind a check that vm.SyntheticModule is defined, which is flagged.

EDIT: That said, some dependency might? Seems unlikely, though - node 14.0 behaved fine, and both mac and linux on 14.1 behaves fine

targos · 2020-05-02T09:48:58Z

Well, we'd need some more simple and reliable way to reproduce this.
I cloned Jest and tried to run e2e\__tests__\toThrowErrorMatchingInlineSnapshot.test.ts multiple times with my local build and the release but it never errors.

mcollina · 2020-05-02T09:51:37Z

That said, some dependency might? Seems unlikely, though - node 14.0 behaved fine, and both mac and linux on 14.1 behaves fine

The V8 stacktrace you posted shows a failure within some code in the wasm namespace in V8.

Hopefully @targos can shed some light on this.

targos · 2020-05-02T10:01:01Z

Commits between 14.0.0 and 14.1.0: v14.0.0...v14.1.0
3 of them to deps/v8:

bbed1e5 only changed a test, cannot affect releases.
b50333e refactored the native code for Intl.NumberFormat
56f50ae fixed a bug related to inline caches. The linked issue (https://bugs.chromium.org/p/chromium/issues/detail?id=1053939) is under embargo so I guess that's related to security in Chromium. I do not know if those code paths are hit by WASM modules.

nicolo-ribaudo · 2020-05-02T17:49:23Z

I'm now trying to remove as much code as possible from my local failing clone of Babel to reduce the number of possible error causes.

mcollina · 2020-05-04T08:15:06Z

This seems to be not babel specific: https://github.com/pinojs/pino/runs/642073186. Again, this is consistently flaky :(.

@targos did you run the tests in Linux WSL or using the normal bin? I have a hunch that Github CI is using WSL.

targos · 2020-05-04T08:24:05Z

I used the normal bin in PowerShell

mcollina · 2020-05-04T08:35:18Z

Would you mind to try out if it works in WSL?

targos · 2020-05-04T08:38:40Z

@mcollina what exactly do you want me to try?
BTW I cloned pino, npm i, npm t with Node.js 14.1.0 on Windows and all tests pass 😕

SimenB · 2020-05-15T13:12:27Z

The revert will not be backported to v13, right? Only applicable to v14? The only code I've got that uses it is on an unpushed branch on my own machine, so I ask more to manage my own expectations rather than for fear of breakage

devsnek · 2020-05-15T15:52:38Z

did this only ever reproduce with builds directly from our windows release build servers?

nicolo-ribaudo · 2020-05-15T19:12:13Z

Also locally: #33166 (comment)

This reverts commit 74c393d. Fixes: #33166 PR-URL: #33364 Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com> Reviewed-By: Beth Griggs <Bethany.Griggs@uk.ibm.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Michael Dawson <michael_dawson@ca.ibm.com>

Flarna · 2020-05-19T22:49:30Z

Would be nice if someone who was able to reproduce this test with 14.3.0.

mcollina · 2020-05-20T08:11:28Z

I cannot reproduce the problem with Node v14.3.0. It's fully solved for me.

nicolo-ribaudo · 2020-05-20T10:24:06Z

I broke my laptop so I cannot test it locally, but as soon as Travis supports Node.js 14.3.0 I can test it on our CI.

SimenB · 2020-05-20T10:27:01Z

Could #31860 be reopened? Or is the un-reverting tracked somewhere else?

bzoz · 2020-05-20T12:18:53Z

Would be nice if someone who was able to reproduce this test with 14.3.0.

Can confirm, built 14.3.0 locally, the issue no longer reproduces.

SimenB · 2020-06-24T11:49:10Z

This still happens using node 14.4.0, fwiw. See https://github.com/facebook/jest/pull/10188/checks?check_run_id=802977045

mcollina · 2020-06-29T12:34:01Z

Maybe @orangemocha can help here.

orangemocha · 2020-06-29T13:07:46Z

Looping in @bzoz @joaocgreis @jaimecbernardo

bzoz · 2020-06-29T17:21:49Z

Sorry, I cannot reproduce with 14.4.0.

notable change: - break: move `getPackageTgzName` to `@dr-js/node` as `toPackageTgzName` in `module/Software/npm` - break: promote `common/terminalColor`, `node/npm/path`, and `parsePackageNameAndVersion` from `node/npm/npxLazy` to `@dr-js/node` - break: use `getGitBranch|getGitCommitHash` from `@dr-js/node` - break: use `createTest` to init test in `common/test` - break: longer default test timeout - break: use `nodejs@14` instead of `nodejs@13` for CI test - break: use `dr-dev -E` instead of `cross-env` - break: update to `eslint-config-almost-standard-v14` - break: update to `eslint-config-almost-standard-jsx-v8` - break: use `getSourceJsFileListFromPathList` instead of `getScriptFileListFromPathList` from `node/filePreset` - break: use `collectSourceJsRouteMap` instead of `collectSourceRouteMap` from `node/export/parsePreset` - break: pass `pathAutoLicenseFile` instead of `pathLicenseFile` to `initOutput()` from `output` - add: `@dr-js/node` as dependency - add: `@dr-js/dev-eslint` config - add: `clearOutput` to `output` - add: `wrapTestScriptStringToHTML` to `puppeteer` - add: cleaner `isTest` script - add: verify rule - add: `source/node/preset` for keep preset path naming rule in one place - add: support `testUrl` for `testWithPuppeteer` - fix: default `pathInfoFilter` in `collectSourceJsRouteMap` - fix: code lint - fix: build script clean `README.md` file - bin: add: `exec` and `exec-load` mode - ci: mark `windows-latest + 14.x` as unstable. check: nodejs/help#2660 and nodejs/node#33166 - ci: test on all 3 platform - ci: update GitHub CI: https://github.blog/changelog/2020-04-15-github-actions-sets-the-ci-environment-variable-to-true/ - ci: update `INIT#.github#workflows#ci-test.yml` - script sort - package update

…tion"" This reverts commit 2d5d773. See: nodejs#32985 See: nodejs#33364 See: nodejs#33166 Fixes: nodejs#31860

notable change: - break: use `webpack@5` - break: use `@dr-js/*@0.4.0-dev.*` - ci: unmark `windows-latest + 14.x` as unstable. issue may be fixed, check: nodejs/help#2660 and nodejs/node#33166 - script sort - package update

…tion"" This reverts commit 2d5d773. See: nodejs#32985 See: nodejs#33364 See: nodejs#33166 Fixes: nodejs#31860

This reverts commit 2d5d773. See: #32985 See: #33364 See: #33166 Fixes: #31860 PR-URL: #35431 Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Antoine du Hamel <duhamelantoine1995@gmail.com> Reviewed-By: Ujjwal Sharma <ryzokuken@disroot.org>

targos · 2021-11-20T15:51:12Z

It seems like this is fixed now. Please reopen if I'm mistaken.

lpinca added the stream Issues and PRs related to the stream subsystem. label Apr 30, 2020

ronag added v8 engine Issues and PRs related to the V8 dependency. windows Issues and PRs related to the Windows platform. labels May 1, 2020

mhdawson mentioned this issue May 18, 2020

Node.js Technical Steering Committee (TSC) Meeting 2020-05-21 nodejs/TSC#868

Closed

mcollina mentioned this issue May 20, 2020

vm.compileFunction is missing importModuleDynamically #31860

Closed

mhdawson removed the tsc-agenda Issues and PRs to discuss during the meetings of the TSC. label May 21, 2020

JLHwung mentioned this issue Jun 19, 2020

Revert "chore: pin windows node.js version (#11522)" babel/babel#11730

Merged

devsnek added a commit to devsnek/node that referenced this issue Sep 29, 2020

Revert "Revert "vm: add importModuleDynamically option to compileFunc…

12aff38

…tion"" This reverts commit 2d5d773. See: nodejs#32985 See: nodejs#33364 See: nodejs#33166 Fixes: nodejs#31860

devsnek mentioned this issue Sep 30, 2020

Revert "Revert "vm: add importModuleDynamically option to compileFunction"" #35431

Merged

4 tasks

devsnek added a commit to devsnek/node that referenced this issue Feb 5, 2021

Revert "Revert "vm: add importModuleDynamically option to compileFunc…

056a671

…tion"" This reverts commit 2d5d773. See: nodejs#32985 See: nodejs#33364 See: nodejs#33166 Fixes: nodejs#31860

devsnek added a commit to devsnek/node that referenced this issue Feb 5, 2021

Revert "Revert "vm: add importModuleDynamically option to compileFunc…

28f5ec8

…tion"" This reverts commit 2d5d773. See: nodejs#32985 See: nodejs#33364 See: nodejs#33166 Fixes: nodejs#31860

targos closed this as completed Nov 20, 2021

[Regression in 14.1.0 - Windows] stdout is sometimes empty #33166

[Regression in 14.1.0 - Windows] stdout is sometimes empty #33166

Comments

nicolo-ribaudo commented Apr 30, 2020 • edited Loading

Bug description

How often does it reproduce? Is there a required condition?

What steps will reproduce the bug?

What is the expected behavior?

What do you see instead?

Additional information

lpinca commented Apr 30, 2020 • edited Loading

mcollina commented Apr 30, 2020

ronag commented Apr 30, 2020 • edited Loading

ronag commented Apr 30, 2020 • edited Loading

nicolo-ribaudo commented Apr 30, 2020

addaleax commented Apr 30, 2020

nicolo-ribaudo commented Apr 30, 2020

ronag commented Apr 30, 2020

nicolo-ribaudo commented Apr 30, 2020

ronag commented Apr 30, 2020

nicolo-ribaudo commented Apr 30, 2020

dr-js commented May 1, 2020 • edited Loading

Update:

Update 2:

SimenB commented May 1, 2020

nicolo-ribaudo commented May 1, 2020

mcollina commented May 2, 2020

targos commented May 2, 2020

mcollina commented May 2, 2020

targos commented May 2, 2020

SimenB commented May 2, 2020 • edited Loading

targos commented May 2, 2020

mcollina commented May 2, 2020

targos commented May 2, 2020 • edited Loading

nicolo-ribaudo commented May 2, 2020

mcollina commented May 4, 2020

targos commented May 4, 2020

mcollina commented May 4, 2020

targos commented May 4, 2020

SimenB commented May 15, 2020 • edited Loading

devsnek commented May 15, 2020

nicolo-ribaudo commented May 15, 2020

Flarna commented May 19, 2020

mcollina commented May 20, 2020

nicolo-ribaudo commented May 20, 2020

SimenB commented May 20, 2020 • edited Loading

bzoz commented May 20, 2020

SimenB commented Jun 24, 2020

mcollina commented Jun 29, 2020

orangemocha commented Jun 29, 2020

bzoz commented Jun 29, 2020

targos commented Nov 20, 2021

[Regression in 14.1.0 - Windows] `stdout` is sometimes empty #33166

[Regression in 14.1.0 - Windows] `stdout` is sometimes empty #33166

nicolo-ribaudo commented Apr 30, 2020 •

edited

Loading

lpinca commented Apr 30, 2020 •

edited

Loading

ronag commented Apr 30, 2020 •

edited

Loading

ronag commented Apr 30, 2020 •

edited

Loading

dr-js commented May 1, 2020 •

edited

Loading

SimenB commented May 2, 2020 •

edited

Loading

targos commented May 2, 2020 •

edited

Loading

SimenB commented May 15, 2020 •

edited

Loading

SimenB commented May 20, 2020 •

edited

Loading