Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Node keeps running, resp. exits slowly with empty process._getActiveRequests() or process._getActiveHandles() #2823

Closed
ekpyron opened this issue Jul 7, 2020 · 5 comments
Labels

Comments

@ekpyron
Copy link

ekpyron commented Jul 7, 2020

  • Node.js Version: 12+
  • OS: linux (ubuntu, debian, archlinux)
  • Scope: runtime

I'm part of the team developing the solidity compiler. We release emscripten compiled binaries that can be used via node-js.
Recently we got reports of surprising behavior of node-js, which I can reproduce, but could use help in fixing.
An example of an affected compiler binary can be found here:
https://raw.githubusercontent.com/ethereum/solc-bin/gh-pages/bin/soljson-v0.6.10%2Bcommit.00c0fcaf.js

The issue can be observed with a simple script like

#!/usr/bin/node
require('./soljson.js');
console.log('Require returned.')

With node 10 the actual require takes a long time, but once it returns, node exits quickly.
Starting from node 12 (actually some versions of node 11 appear to behave the same already), the require is fast, but node takes several seconds to exit.

After the require, process._getActiveRequests() is empty.
process._getActiveHandles() contains the following, but IIUC this is just stdio and shouldn't prevent the exit, right?

[
  <ref *1> WriteStream {
    connecting: false,
    _hadError: false,
    _parent: null,
    _host: null,
    _readableState: ReadableState {
      objectMode: false,
      highWaterMark: 16384,
      buffer: BufferList { head: null, tail: null, length: 0 },
      length: 0,
      pipes: [],
      flowing: null,
      ended: false,
      endEmitted: false,
      reading: false,
      sync: true,
      needReadable: false,
      emittedReadable: false,
      readableListening: false,
      resumeScheduled: false,
      errorEmitted: false,
      emitClose: false,
      autoDestroy: false,
      destroyed: false,
      errored: false,
      closed: false,
      closeEmitted: false,
      defaultEncoding: 'utf8',
      awaitDrainWriters: null,
      multiAwaitDrain: false,
      readingMore: false,
      decoder: null,
      encoding: null,
      readable: false,
      [Symbol(kPaused)]: null
    },
    _events: [Object: null prototype] { end: [Function: onReadableStreamEnd] },
    _eventsCount: 1,
    _maxListeners: undefined,
    _writableState: WritableState {
      objectMode: false,
      highWaterMark: 16384,
      finalCalled: false,
      needDrain: false,
      ending: false,
      ended: false,
      finished: false,
      destroyed: false,
      decodeStrings: false,
      defaultEncoding: 'utf8',
      length: 0,
      writing: false,
      corked: 0,
      sync: false,
      bufferProcessing: false,
      onwrite: [Function: bound onwrite],
      writecb: null,
      writelen: 0,
      afterWriteTickInfo: [Object],
      buffered: [],
      bufferedIndex: 0,
      allBuffers: true,
      allNoop: true,
      pendingcb: 1,
      prefinished: false,
      errorEmitted: false,
      emitClose: false,
      autoDestroy: false,
      errored: false,
      closed: false
    },
    allowHalfOpen: false,
    _sockname: null,
    _pendingData: null,
    _pendingEncoding: '',
    server: null,
    _server: null,
    columns: 162,
    rows: 43,
    _type: 'tty',
    fd: 1,
    _isStdio: true,
    destroySoon: [Function: destroy],
    _destroy: [Function: dummyDestroy],
    [Symbol(async_id_symbol)]: 2,
    [Symbol(kHandle)]: TTY { [Symbol(owner_symbol)]: [Circular *1] },
    [Symbol(kSetNoDelay)]: false,
    [Symbol(lastWriteQueueSize)]: 0,
    [Symbol(timeout)]: null,
    [Symbol(kBuffer)]: null,
    [Symbol(kBufferCb)]: null,
    [Symbol(kBufferGen)]: null,
    [Symbol(kCapture)]: false,
    [Symbol(kBytesRead)]: 0,
    [Symbol(kBytesWritten)]: 0
  }
]

soljson.js itself contains an emscripten build with embedded wasm that is loaded synchronously. No I/O from or to stdin/stdout should be performed in it. Immediately after the require all entry points seem to be available and working - we have no notion of what we might cause that would prevent node from exiting.

Calling either process.exit() or abort() after the require causes node to exit immediately, which hints me at
https://nodejs.org/api/process.html#process_process_exit_code
"Calling process.exit() will force the process to exit as quickly as possible even if there are still asynchronous operations pending that have not yet completed fully, including I/O operations to process.stdout and process.stderr."

Is there any other way than examining process._getActiveRequests() and process._getActiveHandles() to check for pending asynchronous operations or I/O operations? I'm not aware of any such operations soljson.js could cause, though. Is there any other reason why node could behave like this or can you provide any further help to debug this?

Thank you very much for your help!

@bnoordhuis
Copy link
Member

If the wasm file is big, it's possible V8 is still busy compiling it in the background. That would square with the v10-vs-v12 behavior you're seeing, asynchronous compilation of WASM is relatively new.

An easy way to verify that hypothesis is to start node with --predictable (implies --single_threaded), that should revert to the v10 behavior of slow require(), fast exit.

@ekpyron
Copy link
Author

ekpyron commented Jul 7, 2020

--predictable indeed makes the require() slower, but doesn't lead to a fast exit (i.e. it still takes a long while to exit after the require returns, unless using process.exit()). So it wouldn't appear to be that (or at least that alone)... Also it's already possible to execute the wasm directly after the require, still leading to a delay before the exit, which would indicate to me that wasm compilation has to be complete already.

@cspotcode
Copy link

I am seeing the same issue when doing this:

node -e 'require("@swc/wasm"); console.log("done");'

Seems to be about a 5 or 6 second delay between seeing "done" and process termination.

Copy link

It seems there has been no activity on this issue for a while, and it is being closed in 30 days. If you believe this issue should remain open, please leave a comment.
If you need further assistance or have questions, you can also search for similar issues on Stack Overflow.
Make sure to look at the README file for the most updated links.

@github-actions github-actions bot added the stale label May 12, 2024
Copy link

It seems there has been no activity on this issue for a while, and it is being closed. If you believe this issue should remain open, please leave a comment.
If you need further assistance or have questions, you can also search for similar issues on Stack Overflow.
Make sure to look at the README file for the most updated links.

@github-actions github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale Jun 12, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

3 participants