Test script for issue #104 (with fix/workaround) #157

danielweck · 2019-10-17T06:16:32Z

Stacktrace / debug info:

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

Error: EBADF: bad file descriptor, read
Emitted 'error' event at:
    at lazyFs.read (internal/fs/streams.js:165:12)
    at FSReqWrap.wrapper [as oncomplete] (fs.js:467:17)

node --version
=>
v10.16.3

https://github.com/nodejs/node/blob/v10.16.3/lib/fs.js#L467

  function wrapper(err, bytesRead) {
    // Retain a reference to buffer so that it can't be GC'ed too soon.
    callback && callback(err, bytesRead || 0, buffer);
  }

https://github.com/nodejs/node/blob/v10.16.3/lib/internal/fs/streams.js#L165

  // the actual read.
  lazyFs().read(this.fd, pool, pool.used, toRead, this.pos, (er, bytesRead) => {
    if (er) {
      if (this.autoClose) {
        this.destroy();
      }
      this.emit('error', er);
    }

danielweck · 2019-10-17T06:16:44Z

The bug occurs randomly, so it can take a few tries to observe it. Sometimes it triggers immediately.

I use the following CLI to repeat the process:

node "issue-104.js" "./testData/" "100" "1"

CLI arguments:

100 is the number of iterations for each ZIP file inside the testData folder. Each iteration consists in reading the entire ZIP directory, i.e. to stream each ZIP entry into /dev/null (so to speak, as the actual technique consists in reading incoming data buffers, and to ignore them)
1 means that only the unzipper lib is used to perform the test. If this argument is removed, then the libs node-zip-stream and yauzl are used as well (this is useful to compare performance metrics, as printed to stdout).
note that "./testData/" can be replaced with an absolute or relative path to a single ZIP file (it does not have to be a folder)

danielweck · 2019-10-17T06:19:11Z

Here is an example output (MacOS):

Note that each dot . is a single ZIP entry from the directory.

node "issue-104.js" "./testData" "100" "1"
=>

process.cwd():
/xx/node-unzipper
__dirname:
/xx/node-unzipper
args:
[ './testData', '100', '1' ]
./testData
=====================================
testData/accessible_epub_3.epub
=====================================
1/100 ......................................
2/100 ......................................
3/100 ......................................
4/100 ......................................
5/100 ......................................
6/100 ......................................
7/100 ......................................
8/100 ......................................
9/100 ......................................
10/100 ......................................
11/100 ......................................
12/100 ......................................
13/100 ......................................
14/100 ......................................
15/100 ......................................
16/100 ......................................
17/100 ......................................
18/100 ......................................
19/100 ......................................
20/100 ......................................
21/100 ......................................
22/100 ......................................
23/100 ......................................
24/100 ......................................
25/100 ...................events.js:174
      throw er; // Unhandled 'error' event
      ^

Error: EBADF: bad file descriptor, read
Emitted 'error' event at:
    at lazyFs.read (internal/fs/streams.js:165:12)
    at FSReqWrap.wrapper [as oncomplete] (fs.js:467:17)

danielweck · 2019-10-17T06:23:42Z

Another hit:

Note that this is with a single iteration instead of 100, and all 3 zip libs are used (only unzipper randomly crashes, I have never managed to make node-zip-stream or yauzl crash).

node "issue-104.js" "./testData" "1"
=>

process.cwd():
/xx/node-unzipper
__dirname:
/xx/node-unzipper
args:
[ './testData', '1' ]
./testData
=====================================
testData/accessible_epub_3.epub
=====================================
1/1 ......................................
1/1 ......................................
1/1 ..events.js:174
      throw er; // Unhandled 'error' event
      ^

Error: EBADF: bad file descriptor, read
Emitted 'error' event at:
    at lazyFs.read (internal/fs/streams.js:165:12)
    at FSReqWrap.wrapper [as oncomplete] (fs.js:467:17)

danielweck · 2019-10-17T06:33:55Z

I managed to reproduce the issue for a single ZIP file (which eliminates the possibility of folder scanning being a factor). See output below.

Note that this PR includes accessible_epub_3.epub (public domain ebook publication) because it is representative of the type of ZIP files I deal with. I am otherwise able to reproduce the unzipper crash on other files, albeit randomly. Feel free to try with other ZIPs (just make sure the ZIP entries directory contains many small/medium files, rather than few large ones, as we need to stress-test the opening/closing of streams).

node "issue-104.js" "./testData/accessible_epub_3.epub" "500" "1"
=>

process.cwd():
/xx/node-unzipper
__dirname:
/xx/node-unzipper
args:
[ './testData/accessible_epub_3.epub', '500', '1' ]
./testData/accessible_epub_3.epub
=====================================
./testData/accessible_epub_3.epub
=====================================
1/500 ......................................
2/500 ......................................
...
...
464/500 ......................................
465/500 .......events.js:174
      throw er; // Unhandled 'error' event
      ^

Error: EBADF: bad file descriptor, read
Emitted 'error' event at:
    at lazyFs.read (internal/fs/streams.js:165:12)
    at FSReqWrap.wrapper [as oncomplete] (fs.js:467:17)

danielweck · 2019-10-17T09:52:59Z

I implemented a fix by replacing fs.createReadStream() (graceful-fs or regular fs) with fs.open() (which provides a raw file descriptor) and a simple "subclass" of Stream.Readable called DataReaderStream (code shamelessly copied from the yauzl source code) which pulls data from the raw file descriptor (fs.read(fd, ...)).

The PR commit which introduces this change:

c7f6243

Note that the USE_ALTERNATIVE_STREAM_METHOD constant controls whether or not to activate this bugfix. I am not able to reproduce the bug when I use this alternative method.

Caveat: the raw file descriptor must be manually closed, thus the introduction of a new closeFileDescriptor() "method" on the ZIP directory API (note that yauzl and node-zip-stream expose a similar close() function).

ZJONSSON · 2019-10-17T13:55:49Z

Awesome @danielweck thank you so much for doing this!! I'm still keeping backward compatibility on the basis that unzipper is a drop-in replacement for unzip. Would you mind fixing the PR for the old node versions (mostly renaming const and let to var)

danielweck · 2019-10-18T09:53:58Z

I see:
https://travis-ci.org/ZJONSSON/node-unzipper/builds/599077802
I can certainly fix that, but please note that this PR is really just a test-bed to investigate the cause of the issue / to attempt to reproduce the random crash more consistently.

This wasn't intended to provide a robust, properly thought-out solution. By process of elimination, I came up with the conclusion that fs.createReadStream() is the root of the problem, so I tested an alternative strategy to open streams ... the problem now seems gone, but there are concerning side-effects when using this new method.

Most notably, this PR introduces a "breaking change" in that the unzipper API now requires explicitly invoking a new zip.close() function in order to tear-down the zip instance and to gracefully release resources (before that change, it was assumed that all created streams would be automatically handled by garbage collection).

This lifecycle pattern is actually aligned with the two other well-known performant implementations yauzl and node-zip-stream, but this is a departure from the original unzipper design.

Plus, my implementation is kinda dirty, as you can see I attach the .close() function to the source object with the expectation that the _fd file descriptor was previously allocated, so I rely on the implicit call chain .size() (promise) -> followed by .stream() (not a promise). It all smells a bit like "spaghetti code", if you know what I mean :)
(in fact, this breaks one of the unit tests, probably because .stream() is called directly ... I'm not sure, see 75894cc )

…-unzipper/builds/599077802 )

…58261

…N/node-unzipper/builds/599567608

ZJONSSON · 2019-10-19T14:07:56Z

Thanks @danielweck this is very helpful. Of course we could close fd automatically if it hasn't been used for a small amount of time (and reopen if it has been closed if/when we need it again, i.e. caching the fd temporarily based on last-touch). That should make the behavior backwards compatible, i.e. explicit close would not be required, but slightly more hacky. Will take a closer look this weekend

dreamerblue · 2019-11-05T02:04:50Z

Is there any progress? @ZJONSSON

danielweck added 2 commits October 17, 2019 07:04

Test script for issue #104

cc90300

exclude malicious zip

7e7600c

danielweck mentioned this pull request Oct 17, 2019

Error: EBADF: bad file descriptor, read when parsing over Open.file() #104

Closed

alternative method to fs.createReadStream() seems to fix the bug

c7f6243

fix unit test edge case

75894cc

danielweck changed the title ~~Test script for issue #104~~ Test script for issue #104 (with fix/workaround) Oct 17, 2019

danielweck added 5 commits October 18, 2019 11:01

let replaced with var (should fix https://travis-ci.org/ZJONSSON/node…

af6133e

…-unzipper/builds/599077802 )

TravisCI fix https://travis-ci.org/ZJONSSON/node-unzipper/builds/5995…

5040da2

…58261

another attempt to solve TravisCI fails https://travis-ci.org/ZJONSSO…

43e9f59

…N/node-unzipper/builds/599567608

TravisCI after_success

778774f

TravisCI typo (Node version check)

9833c19

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Test script for issue #104 (with fix/workaround) #157

Test script for issue #104 (with fix/workaround) #157

danielweck commented Oct 17, 2019

danielweck commented Oct 17, 2019 •

edited

Loading

danielweck commented Oct 17, 2019 •

edited

Loading

danielweck commented Oct 17, 2019 •

edited

Loading

danielweck commented Oct 17, 2019 •

edited

Loading

danielweck commented Oct 17, 2019

ZJONSSON commented Oct 17, 2019

danielweck commented Oct 18, 2019

ZJONSSON commented Oct 19, 2019

dreamerblue commented Nov 5, 2019

Test script for issue #104 (with fix/workaround) #157

Are you sure you want to change the base?

Test script for issue #104 (with fix/workaround) #157

Conversation

danielweck commented Oct 17, 2019

danielweck commented Oct 17, 2019 • edited Loading

danielweck commented Oct 17, 2019 • edited Loading

danielweck commented Oct 17, 2019 • edited Loading

danielweck commented Oct 17, 2019 • edited Loading

danielweck commented Oct 17, 2019

ZJONSSON commented Oct 17, 2019

danielweck commented Oct 18, 2019

ZJONSSON commented Oct 19, 2019

dreamerblue commented Nov 5, 2019

danielweck commented Oct 17, 2019 •

edited

Loading

danielweck commented Oct 17, 2019 •

edited

Loading

danielweck commented Oct 17, 2019 •

edited

Loading

danielweck commented Oct 17, 2019 •

edited

Loading