Skip to content
This repository has been archived by the owner. It is now read-only.

Build failed ERR_STREAM_WRITE_AFTER_END: node v9.7.1 withExEditorHost v3.0.3 archlinux x86_64 #142

Closed
sputnick-dev opened this issue Mar 5, 2018 · 24 comments

Comments

Projects
None yet
8 participants
@sputnick-dev
Copy link

commented Mar 5, 2018

$ git clone ...
$ cd withExEditorHost
$ npm run setup

> withexeditorhost@3.0.3 setup /home/sputnick/sources/withExEditorHost
> npm install && node ./index.js --setup

npm WARN deprecated graceful-fs@3.0.11: please upgrade to graceful-fs 4 for compatibility with current and future versions of Node.js
npm ERR! code ERR_STREAM_WRITE_AFTER_END
npm ERR! write after end

npm ERR! A complete log of this run can be found in:
npm ERR!     /home/sputnick/.npm/_logs/2018-03-04T20_51_42_936Z-debug.log
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! withexeditorhost@3.0.3 setup: `npm install && node ./index.js --setup`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the withexeditorhost@3.0.3 setup script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /home/sputnick/.npm/_logs/2018-03-04T20_51_43_725Z-debug.log

$ cat ~/.npm/_logs/2018-03-04T20_45_46_514Z-debug.log
(...)
4748 silly extract type-check@0.3.2
4749 silly pacote trying type-check@~0.3.2 by hash: sha1-WITKtRLPHTVeP7eE8wgEsrUg23I=
4750 silly pacote data for sha1-WITKtRLPHTVeP7eE8wgEsrUg23I= not present. Using manifest.
4751 verbose stack Error [ERR_STREAM_WRITE_AFTER_END]: write after end
4751 verbose stack     at writeAfterEnd (_stream_writable.js:237:12)
4751 verbose stack     at PassThrough.Writable.write (_stream_writable.js:287:5)
4751 verbose stack     at PassThrough.Writable.end (_stream_writable.js:572:10)
4751 verbose stack     at ReadEntry.entry.on (/usr/lib/node_modules/npm/node_modules/pacote/lib/extract-stream.js:19:41)
4751 verbose stack     at ReadEntry.emit (events.js:132:15)
4751 verbose stack     at ReadEntry.emit (/usr/lib/node_modules/npm/node_modules/tar/node_modules/minipass/index.js:287:25)
4751 verbose stack     at ReadEntry.[maybeEmitEnd] (/usr/lib/node_modules/npm/node_modules/tar/node_modules/minipass/index.js:240:12)
4751 verbose stack     at ReadEntry.end (/usr/lib/node_modules/npm/node_modules/tar/node_modules/minipass/index.js:153:27)
4751 verbose stack     at Unpack.[consumeBody] (/usr/lib/node_modules/npm/node_modules/tar/lib/parse.js:210:13)
4751 verbose stack     at Unpack.[consumeChunkSub] (/usr/lib/node_modules/npm/node_modules/tar/lib/parse.js:391:40)
4751 verbose stack     at Unpack.[consumeChunk] (/usr/lib/node_modules/npm/node_modules/tar/lib/parse.js:360:30)
4751 verbose stack     at Unzip.(anonymous function).on.chunk (/usr/lib/node_modules/npm/node_modules/tar/lib/parse.js:291:59)
4751 verbose stack     at Unzip.emit (events.js:127:13)
4751 verbose stack     at Unzip.emit (/usr/lib/node_modules/npm/node_modules/tar/node_modules/minipass/index.js:287:25)
4751 verbose stack     at Unzip.write (/usr/lib/node_modules/npm/node_modules/tar/node_modules/minipass/index.js:90:17)
4751 verbose stack     at Unzip.write (/usr/lib/node_modules/npm/node_modules/tar/node_modules/minizlib/index.js:284:29)
4752 verbose cwd /home/sputnick/sources/withExEditorHost
4753 verbose Linux 4.15.6-1-ARCH
4754 verbose argv "/usr/bin/node" "/usr/bin/npm" "install"
4755 verbose node v9.7.1
4756 verbose npm  v5.7.1
4757 error code ERR_STREAM_WRITE_AFTER_END
4758 error write after end
4759 verbose exit [ 1, true ]

Initially posted here: asamuzaK/withExEditorHost#32

@deployable

This comment has been minimized.

Copy link

commented Mar 7, 2018

I'm seeing this under node 9.7.1 and npm 5.7.1 as well.

It's happening fairly regularly under the mhart/alpine-node:9.7.1 docker image:

ARG NODE_VERSION=9.7.1
#FROM node:$NODE_VERSION
#FROM node:$NODE_VERSION-alpine
FROM mhart/alpine-node:$NODE_VERSION
WORKDIR /app
RUN echo '{"dependencies":{"react": "^16", "webpack":"^4", "nyc": "^11", "mocha":"^5"}}' > package.json
RUN npm install
@deployable

This comment has been minimized.

Copy link

commented Mar 7, 2018

The other images don't have the latest npm. The error occurs pretty consistently for node 8.9.4 and 9.7.1 across the node:x.x.x, node:x.x.x-alpine and mhart/node-alpine images if npm is upgraded to 5.7.1

ARG NODE_VERSION=9.7.1
FROM node:$NODE_VERSION
#FROM node:$NODE_VERSION-alpine
#FROM mhart/alpine-node:$NODE_VERSION
WORKDIR /app
RUN echo '{"dependencies":{"react": "^16", "webpack":"^4", "nyc": "^11", "mocha":"^5"}}' > package.json
RUN npm -v && npm install -g npm && npm install
@kimown

This comment has been minimized.

Copy link

commented Mar 7, 2018

downgrade to 5.5.1

npm i npm@5.5.1 -g

@deployable

This comment has been minimized.

Copy link

commented Mar 7, 2018

@kimown 5.6.0 seems fine, I think node 9 needs at least that anyway.

deployable added a commit to deployable/node-domain-tree that referenced this issue Mar 7, 2018

work around zkat/pacote#142
`mhart/alpine-node` was using latest npm for 9.7.1
@zkat

This comment has been minimized.

Copy link
Owner

commented Mar 15, 2018

I strongly suspect this has to do with the new pkgJson transform that got added recently interacting in a funny way with tar but I'll have to squint hard at it and read node-tar's code to figure out what the race is here. /cc @isaacs

Thanks for the report! This is handy 👍

@zkat zkat added the bug label Mar 15, 2018

@isaacs

This comment has been minimized.

Copy link
Contributor

commented Mar 16, 2018

If I had to guess, my suspicion would be that tar is expecting the transformed stream to be synchronous rather than artificially deferred. What happens if you replace that stream.PassThrough with a MiniPass stream? (Other than getting a teensy bit faster, of course.)

@sputnick-dev

This comment has been minimized.

Copy link
Author

commented Mar 17, 2018

OK, downgraded npm, but things get still weird :

npm WARN npm npm does not support Node.js v9.8.0
npm WARN npm You should probably upgrade to a newer version of node as we
npm WARN npm can't make any promises that npm will work with this version.
npm WARN npm Supported releases of Node.js are the latest release of 4, 6, 7, 8.
npm WARN npm You can find the latest version at https://nodejs.org/

> withexeditorhost@3.0.3 setup /home/sputnick/sources/withExEditorHost
> npm install && node ./index.js --setup

npm WARN npm npm does not support Node.js v9.8.0
npm WARN npm You should probably upgrade to a newer version of node as we
npm WARN npm can't make any promises that npm will work with this version.
npm WARN npm Supported releases of Node.js are the latest release of 4, 6, 7, 8.
npm WARN npm You can find the latest version at https://nodejs.org/
npm WARN deprecated graceful-fs@3.0.11: please upgrade to graceful-fs 4 for compatibility with current and future versions of Node.js
WARNING: You are likely using a version of node-tar or npm that is incompatible with this version of Node.js.ock for /home/sputnick/sources/w
Please use either the version of npm that is bundled with Node.js, or a version of npm (> 5.5.1 or < 5.4.0) or node-tar (> 4.0.1) that is compatible with Node.js 9 and above.
npm[3822]: ../src/node_zlib.cc:436:static void node::{anonymous}::ZCtx::Init(const v8::FunctionCallbackInfo<v8::Value>&): Assertion `args.Length() == 7 && "init(windowBits, level, memLevel, strategy, writeResult, writeCallback," " dictionary)"' failed.
 1: node::Abort() [npm]
 2: 0x55f8583f961b [npm]
 3: 0x55f858473f18 [npm]
 4: v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) [npm]
 5: 0x55f858605b6f [npm]
 6: 0x55f8586060bf [npm]
 7: 0x2de56e2042fd
sh : ligne 1 :  3822 Abandon                 (core dumped)npm install
npm ERR! code ELIFECYCLE
npm ERR! errno 134
npm ERR! withexeditorhost@3.0.3 setup: `npm install && node ./index.js --setup`
npm ERR! Exit status 134
npm ERR! 
npm ERR! Failed at the withexeditorhost@3.0.3 setup script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /home/sputnick/.npm/_logs/2018-03-17T17_08_04_621Z-debug.log

Relevant log :

15 silly lifecycle withexeditorhost@3.0.3~setup: Args: [ '-c', 'npm install && node ./index.js --setup' ]
16 silly lifecycle withexeditorhost@3.0.3~setup: Returned: code: 134  signal: null
17 info lifecycle withexeditorhost@3.0.3~setup: Failed to exec setup script
18 verbose stack Error: withexeditorhost@3.0.3 setup: `npm install && node ./index.js --setup`
18 verbose stack Exit status 134
18 verbose stack     at EventEmitter.<anonymous> (/usr/lib/node_modules/npm/node_modules/npm-lifecycle/index.js:280:16)
18 verbose stack     at EventEmitter.emit (events.js:180:13)
18 verbose stack     at ChildProcess.<anonymous> (/usr/lib/node_modules/npm/node_modules/npm-lifecycle/lib/spawn.js:55:14)
18 verbose stack     at ChildProcess.emit (events.js:180:13)
18 verbose stack     at maybeClose (internal/child_process.js:936:16)
18 verbose stack     at Process.ChildProcess._handle.onexit (internal/child_process.js:220:5)
19 verbose pkgid withexeditorhost@3.0.3
20 verbose cwd /home/sputnick/sources/withExEditorHost
21 verbose Linux 4.15.7-1-ARCH
22 verbose argv "/usr/bin/node" "/usr/bin/npm" "run" "setup"
23 verbose node v9.8.0
24 verbose npm  v5.5.1
25 error code ELIFECYCLE
26 error errno 134
27 error withexeditorhost@3.0.3 setup: `npm install && node ./index.js --setup`
27 error Exit status 134
28 error Failed at the withexeditorhost@3.0.3 setup script.
28 error This is probably not a problem with npm. There is likely additional logging output above.
29 verbose exit [ 134, true ]
@zkat

This comment has been minimized.

Copy link
Owner

commented Mar 17, 2018

@sputnick-dev you'll need to downgrade node as well in this case

@deployable

This comment has been minimized.

Copy link

commented Mar 17, 2018

@mesteche

This comment has been minimized.

Copy link

commented Mar 18, 2018

I can confirm this issue, I stumbled upon it while installing webpack-dev-server and some other devDependencies in a new project but I noted that running npm install --save-dev webpack-dev-server wasn't failing the second time, so it's probably related to an asynchronous stream.

Also, there is a note in node-tar's documentation:

Note that using an asynchronous stream type with the transform option will cause undefined behavior in sync extractions. MiniPass-based streams are designed for this use case.

This and these logs:

2867 verbose stack     at ReadEntry.entry.on (/usr/lib/node_modules/npm/node_modules/pacote/lib/extract-stream.js:19:41)
2867 verbose stack     at ReadEntry.emit (events.js:185:15)
2867 verbose stack     at ReadEntry.emit (/usr/lib/node_modules/npm/node_modules/tar/node_modules/minipass/index.js:287:25)
2867 verbose stack     at ReadEntry.[maybeEmitEnd] (/usr/lib/node_modules/npm/node_modules/tar/node_modules/minipass/index.js:240:12)
2867 verbose stack     at ReadEntry.end (/usr/lib/node_modules/npm/node_modules/tar/node_modules/minipass/index.js:153:27)

seems to indicate that node-tar already ended the stream when transformed.end is called or that it continues to write data afterward (probably in the callback of ReadEntry.end).
Given the note in node-tar's documentation and the fact that MiniPass is already a dependencie of node-tar anyway, I think @isaacs is right and stream.PassThrough should be replaced with a MiniPass stream but it might not solve the issue.

@zkat

This comment has been minimized.

Copy link
Owner

commented Mar 19, 2018

I'm gonna be mostly on vacation for the next two weeks -- would anyone be interested of putting together a PR and checking that the change actually fixes the problem?

@liqueurdetoile

This comment has been minimized.

Copy link

commented May 11, 2018

Thread about this issue is really active on NPM : npm/npm/issues/19989

@stsvilik

This comment has been minimized.

Copy link
Contributor

commented May 18, 2018

I believe I figured out a problem and fixed it:
stsvilik@74412e6

@isaacs

This comment has been minimized.

Copy link
Contributor

commented May 18, 2018

Oh! It should definitely not be emitting end more than once, so this is a very interesting fix which points at a deeper bug. Thanks!

@stsvilik

This comment has been minimized.

Copy link
Contributor

commented May 18, 2018

@isaacs yep, thats what I figured, but the only place where I can replicate it so far is inside a Docker container which makes it extremely difficult to debug. It seems to be a race condition between pacote and tar since a stream which transforms package.json is shared between them.

@isaacs

This comment has been minimized.

Copy link
Contributor

commented May 18, 2018

It appears that a race condition involving data events triggered by the call to .end() may allow a consumer to call .end() again after the 'end' event is emitted, but before the Minipass internal EMITTED_END flag is set, causing a second end event to be emitted.

That flow control hole is plugged in Minipass v2.3.1.

@stsvilik

This comment has been minimized.

Copy link
Contributor

commented May 18, 2018

Perhaps https://github.com/isaacs/minipass/blob/master/index.js#L162 should be moved to line 154. And return early if this[EMITTED_END] is already true.

@zkat zkat closed this in 50ed408 May 19, 2018

@stsvilik

This comment has been minimized.

Copy link
Contributor

commented May 24, 2018

I still see this happening on node 10 and npm 6.1.0 (inside a Docker), running npm ci. Was cipm updated with latest pacote?

events.js:167
      throw er; // Unhandled 'error' event
      ^

Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:243:12)
    at PassThrough.Writable.write (_stream_writable.js:292:5)
    at PassThrough.Writable.end (_stream_writable.js:592:10)
    at ReadEntry.entry.on (/opt/node-v10.0.0-linux-x64/lib/node_modules/npm/node_modules/libcipm/node_modules/pacote/lib/extract-stream.js:19:41)
    at ReadEntry.emit (events.js:187:15)
    at ReadEntry.emit (/opt/node-v10.0.0-linux-x64/lib/node_modules/npm/node_modules/minipass/index.js:309:30)
    at ReadEntry.[maybeEmitEnd] (/opt/node-v10.0.0-linux-x64/lib/node_modules/npm/node_modules/minipass/index.js:257:12)
    at ReadEntry.end (/opt/node-v10.0.0-linux-x64/lib/node_modules/npm/node_modules/minipass/index.js:167:27)
    at Unpack.[consumeBody] (/opt/node-v10.0.0-linux-x64/lib/node_modules/npm/node_modules/tar/lib/parse.js:210:13)
    at Unpack.[consumeChunkSub] (/opt/node-v10.0.0-linux-x64/lib/node_modules/npm/node_modules/tar/lib/parse.js:391:40)
    at Unpack.[consumeChunk] (/opt/node-v10.0.0-linux-x64/lib/node_modules/npm/node_modules/tar/lib/parse.js:362:30)
    at Unzip.(anonymous function).on.chunk (/opt/node-v10.0.0-linux-x64/lib/node_modules/npm/node_modules/tar/lib/parse.js:291:59)
    at Unzip.emit (events.js:182:13)
    at Unzip.emit (/opt/node-v10.0.0-linux-x64/lib/node_modules/npm/node_modules/minipass/index.js:309:30)
    at Unzip.write (/opt/node-v10.0.0-linux-x64/lib/node_modules/npm/node_modules/minipass/index.js:104:17)
    at Unzip.write (/opt/node-v10.0.0-linux-x64/lib/node_modules/npm/node_modules/minizlib/index.js:284:29)
Emitted 'error' event at:
    at writeAfterEnd (_stream_writable.js:245:10)
    at PassThrough.Writable.write (_stream_writable.js:292:5)
    [... lines matching original stack trace ...]
    at Unzip.write (/opt/node-v10.0.0-linux-x64/lib/node_modules/npm/node_modules/minizlib/index.js:284:29)
@stsvilik

This comment has been minimized.

Copy link
Contributor

commented May 24, 2018

I manually updated pacote inside libcipm to the latest version and it seems to fix the problem. Comon guys!

@isaacs

This comment has been minimized.

Copy link
Contributor

commented May 24, 2018

The root cause is fixed in npm 6.1.1 I believe, not 6.1.0. Should be out soon.

@zkat

This comment has been minimized.

Copy link
Owner

commented May 24, 2018

@stsvilik Are you sure you were running 6.1.0 and not 6.0.1? The version of pacote that shipped with 6.1.0 is the latest (8.1.5) in both cases. Reinstalling pacote in latest does not yield any lock diffs for me, so I don't think any deep deps would be responsible?

@zkat

This comment has been minimized.

Copy link
Owner

commented May 24, 2018

OH DUH.

libcipm.

Thank you, yes. I'll bump that version now. I missed that one :)

@zkat

This comment has been minimized.

Copy link
Owner

commented May 24, 2018

we've done all the updates and next release should fix npm ci. This should work fine with npm install until then.

@stsvilik

This comment has been minimized.

Copy link
Contributor

commented Jun 1, 2018

is there an ETA on 6.1.1?

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
You can’t perform that action at this time.