Skip to content

node {16,17,18} doesn't respect spawn timeout and hangs #43704

New issue
New issue
Closed as not planned
Closed as not planned
node {16,17,18} doesn't respect spawn timeout and hangs#43704
Labels
child_processIssues and PRs related to the child_process subsystem.

Description

@aviadhahami
aviadhahami
opened on Jul 6, 2022

Version

16.*

Platform

linux
Linux f092196b2008 5.10.104-linuxkit #1 SMP Thu Mar 17 17:08:06 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

What steps will reproduce the bug?

I've created a demo using docker so you can easily swap node versions and see the bug.
That being said, I'm sharing the tarball as bas64 because I wasn't sure if you'd like to download tarballs...that being said you may also not want to decode b64 🤷‍♂️

download here if you'd like: poc

or run the following:

base64 -d <<< H4sIACurxWIAA+1YbWvbMBDOZ/+KqzfqZCSyZcsxBLoLjpJp+fRKchuVA7HcQLfB912y9ZxSdkuAJi4Xey5PvE9cDAmJGiAX/3UGo2ZKMJcTiW8YGH8gJ90G40e6F+sY9W+ECB7OGNJ3Ek7+SxFYlJFjHX5x06wyr/nuzL/BHvdBjhVTOY+Xnn+32zZQ5baw1BMjCIc75gpjynudiZhOqa5acQ8Oqc56EMCnQLeSidAS7M8M9piPPcyavwlkP1Bp3LEElpVDMmHLiEP8B/7S/4T38eS/x7xSM3/TeDToP8NFOd7kvQiYVPD+N4ffP2wNwCbZ4Vh7PYPjgFJyhsf948Gxwf9vf0jOAGtE2YbTJbG9Bf6IUw4rVXg5QHZKpFnUx7PEiqqKQYfUf8RQhx9/+O6/tsIkL0kcHUx1um/G9zKv9dV+o+xV+v/JhDxVBRwLbLwMj28SqM57EBOf85YTptWNJFV31mW84gKYbUMQ3nzhKKEj5vWofoNS8cIIdm3GqFppdnUap9YTI4cJonVtpCdnY9l2+lc0HzIBbVO2zJmETPek24TmrPCakPBppTPih6WG/jOm7fuhtMBVCl6RWW45963/wU6NRX/B/AY/cdBIPnvup5b6/8mUOY/C6PzcEzlLcDTp4+xTv89n9zov0PU/e/X+r8ZXBsga/lwSs0emPIomG1lkDItGE+VDSMHOaU1piLKWVYsekrjNGT62+odoK2lo5AdKoA0ZDld3AfKmUYTDtYXmiQcRjmfgkgozaS437htWbC9rV8mgGzdrQaXg811gHN6dcnzWEU4OdWWcFZMeH4zsYRFNBV6XXuHu6Yxr++MP6Dk/3J/q4mx9v3vBff03wscXPN/E7hbYqljICs6SbtLVdLR4qgsyZrN1s77O66fOY9hynNVAFqtti7ZuurTAtuGEBJeyLqwpty/jnvvfykGTx/j8e9/3/fk/e8iVM2EbuOV879GjRqvF78BY21wXQAgAAA= > out.tar.gz

then tar -zxf out.tar.gz and you'll see the following files:

Dockerfile  build-n-run.sh  index.js  node_modules  pkg

you can run the build-n-run.sh that I've created (which is a silly 2liner), or build and run it yourself

Steps to Reproduce

  1. Run something like:
const {spawnSync} = require('child_process')

console.log('Spawning...')
spawnSync('npm',['install','./pkg','--verbose'], {stdio:'inherit', timeout:1000*3})
console.log('spawner bye')

and make the package preinstall script for pkg to hang (via long setTimeout that will make it busy)
3. Expect ETIMEOUT, but get nothing

Activity

  1. mscdex commented on Jul 6, 2022

    @mscdex
    mscdex
    on Jul 6, 2022
    Contributor

    Using 'sleep 10' as the command works for me.

    Are you expecting a thrown exception? You need to be checking the return value of spawnSync() (specifically .error), as that is where you'll find the ETIMEDOUT error.

  2. aviadhahami commented on Jul 6, 2022

    @aviadhahami
    aviadhahami
    on Jul 6, 2022
    Author

    I'd expect it to terminate at first, then check the status code;

    wdym by sleep 10? did u try my poc?

  3. mscdex commented on Jul 6, 2022

    @mscdex
    mscdex
    on Jul 6, 2022
    Contributor

    I'd expect it to terminate at first, then check the status code

    When I tested, spawnSync() returned after 3 seconds (due to ETIMEDOUT). From there, you just check the various properties from the returned object.

    wdym by sleep 10?

    spawnSync('sleep',['10'], {stdio:'inherit', timeout:1000*3})

    did u try my poc?

    No, 'sleep 10' should be equivalent.

  4. aviadhahami commented on Jul 6, 2022

    @aviadhahami
    aviadhahami
    on Jul 6, 2022
    Author

    interesting; I'm checking this in the above env

  5. aviadhahami commented on Jul 6, 2022

    @aviadhahami
    aviadhahami
    on Jul 6, 2022
    Author

    you are not wrong - I can reproduce it as well;
    That being said - my POC still works. I'll try to reduce it to the bare minimum, I have a feeling it has to do with multiple children or so.

    This is ps aux from the hanging container (with poc):

    USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.1  0.7 319640 31760 ?        Ssl  20:26   0:00 node index.js
root        13  1.1  1.4 907304 59800 ?        Sl   20:26   0:00 npm install ./pkg
root        24  0.0  0.0   2388   744 ?        S    20:26   0:00 sh -c echo 'Hello from sleeper preinstall!' && node ./sleep.
root        25  0.0  0.7 319640 31076 ?        Sl   20:26   0:00 node ./sleep.js
root        32  0.0  0.0   3868  3184 pts/0    Ss   20:26   0:00 /bin/bash
root      1209  0.0  0.0   7640  2760 pts/0    R+   20:27   0:00 ps aux

    Minus the last 2 procs - the rest are the hanged

    ====

    Update:
    I'm unable to repro this using simple spawns, but yes every time using the npm install :\

  6. wa-Nadoo commented on Jul 6, 2022

    @wa-Nadoo
    wa-Nadoo
    on Jul 6, 2022

    Please try to add killSignal: 'SIGKILL' option to spawn. By default spawn sends SIGTERM signal to child process that not enough for some programs.

  7. daeyeon
    added
    child_processIssues and PRs related to the child_process subsystem.
    on Jul 7, 2022

  8. aviadhahami commented on Jul 7, 2022

    @aviadhahami
    aviadhahami
    on Jul 7, 2022
    Author

    @wa-Nadoo this doesn't work either;
    tho regardless of the signal itself -- I would expect it to terminate;
    This works on node 14, but doesn't on 16;

  9. aviadhahami commented on Jul 7, 2022

    @aviadhahami
    aviadhahami
    on Jul 7, 2022
    Author

    Checked, it reproduces on these node versions: 16,17,18

  10. aviadhahami
    changed the title [-]node16 doesn't respect spawn timeout and hangs[/-] [+]node {16|17|18} doesn't respect spawn timeout and hangs[/+] on Jul 7, 2022
  11. aviadhahami
    changed the title [-]node {16|17|18} doesn't respect spawn timeout and hangs[/-] [+]node {16,17,18} doesn't respect spawn timeout and hangs[/+] on Jul 7, 2022

  12. lirantal commented on Jul 7, 2022

    @lirantal
    lirantal
    on Jul 7, 2022
    Member

    @aviadhahami can you check if you're also using different npm versions along with those 16,17,18 runtime versions? I suspect that it's the npm executable specifically that is indeed not respecting/forwarding signals correctly to child processes that it spawns.

  13. aviadhahami commented on Jul 7, 2022

    @aviadhahami
    aviadhahami
    on Jul 7, 2022
    Author

    For the supplied PoC, these are the versions:
    node:16-slim - [email protected]
    node:17-slim - [email protected]
    node:18-slim - [email protected]

  14. lirantal commented on Jul 7, 2022

    @lirantal
    lirantal
    on Jul 7, 2022
    Member

    Ok, so pretty close version ranges so I assume no big changes there, although worth looking into the changelog and see if anything obvious comes up in the diff.

  15. benjamingr commented on Jul 8, 2022

    @benjamingr
    benjamingr
    on Jul 8, 2022
    Member

    Does the issue reproduce when you manually when you spawn npm in these versions in a terminal and kill it from another terminal? (find it with ps and send it the same signal).

    If it does this can/should be an NPM issue, I am also not able to reproduce this with a simple program and agree with Liran that it's probably a function of NPM versions

  16. aviadhahami commented on Jul 8, 2022

    @aviadhahami
    aviadhahami
    on Jul 8, 2022
    Author

    @benjamingr to make sure I understand - you like me to test in these setups whether npm respect SIGTERM?

  17. benjamingr commented on Jul 8, 2022

    @benjamingr
    benjamingr
    on Jul 8, 2022
    Member

    @aviadhahami basically I want to isolate whether or not this is a Node.js issue or an npm issue - I suspect it's an NPM issue so the next step would be to prove it and simulate what Node.js is doing (in your code) without Node.js

  18. aviadhahami commented on Jul 8, 2022

    @aviadhahami
    aviadhahami
    on Jul 8, 2022
    Author

    @benjamingr -- I've tried the following:

    1. Ran the poc and let the procs hang
    2. Execed into the machine and ran kill <PID>

    The node processes (the sleeping one) died and the whole processes tree collapsed
    Attaching a screenshot, the spawned npm log and the ps aux from the machine:

    1. hanging process:
    Spawning...
npm verb cli /usr/local/bin/node /usr/local/bin/npm
npm info using [email protected]
npm info using [email protected]
npm timing npm:load:whichnode Completed in 0ms
npm timing config:load:defaults Completed in 3ms
npm timing config:load:file:/usr/local/lib/node_modules/npm/npmrc Completed in 1ms
npm timing config:load:builtin Completed in 2ms
npm timing config:load:cli Completed in 4ms
npm timing config:load:env Completed in 0ms
npm timing config:load:file:/opt/.npmrc Completed in 0ms
npm timing config:load:project Completed in 6ms
npm timing config:load:file:/root/.npmrc Completed in 0ms
npm timing config:load:user Completed in 0ms
npm timing config:load:file:/usr/local/etc/npmrc Completed in 1ms
npm timing config:load:global Completed in 1ms
npm timing config:load:validate Completed in 0ms
npm timing config:load:credentials Completed in 1ms
npm timing config:load:setEnvs Completed in 1ms
npm timing config:load Completed in 18ms
npm timing npm:load:configload Completed in 19ms
npm timing npm:load:mkdirpcache Completed in 1ms
npm timing npm:load:mkdirplogs Completed in 1ms
npm verb title npm install ./pkg
npm verb argv "install" "./pkg" "--loglevel" "verbose"
npm timing npm:load:setTitle Completed in 1ms
npm timing config:load:flatten Completed in 3ms
npm timing npm:load:display Completed in 12ms
npm verb logfile logs-max:10 dir:/root/.npm/_logs
npm verb logfile /root/.npm/_logs/2022-07-08T22_14_35_782Z-debug-0.log
npm timing npm:load:logFile Completed in 6ms
npm timing npm:load:timers Completed in 1ms
npm timing npm:load:configScope Completed in 0ms
npm timing npm:load Completed in 41ms
npm timing arborist:ctor Completed in 1ms
npm timing arborist:ctor Completed in 0ms
npm timing idealTree:init Completed in 44ms
npm timing idealTree:userRequests Completed in 4ms
npm timing idealTree:#root Completed in 31ms
npm timing idealTree:node_modules/pkg Completed in 0ms
npm timing idealTree:pkg Completed in 0ms
npm timing idealTree:buildDeps Completed in 33ms
npm timing idealTree:fixDepFlags Completed in 0ms
npm timing idealTree Completed in 85ms
npm timing reify:loadTrees Completed in 85ms
npm timing reify:diffTrees Completed in 1ms
npm timing reify:retireShallow Completed in 1ms
npm timing reify:createSparse Completed in 0ms
npm timing reify:loadBundles Completed in 0ms
npm timing reify:unpack Completed in 1ms
npm timing reify:unretire Completed in 0ms
npm timing build:queue Completed in 0ms
npm timing build:deps Completed in 1ms
npm timing build:queue Completed in 1ms
npm info run [email protected] preinstall pkg echo 'Hello from sleeper preinstall!' && node ./sleep.js
npm http fetch GET 200 https://registry.npmjs.org/npm 326ms (cache miss)
npm http fetch POST 200 https://registry.npmjs.org/-/npm/v1/security/advisories/bulk 336ms
npm timing auditReport:getReport Completed in 338ms
npm timing auditReport:init Completed in 0ms
npm timing reify:audit Completed in 340ms
npm info run [email protected] preinstall { code: 143, signal: null }
npm timing reify:rollback:createSparse Completed in 0ms
npm timing reify:rollback:retireShallow Completed in 0ms
npm timing command:install Completed in 44803ms
npm notice
npm notice New minor version of npm available! 8.11.0 -> 8.13.2
npm notice Changelog: <https://github.com/npm/cli/releases/tag/v8.13.2>
npm notice Run `npm install -g [email protected]` to update!
npm notice
npm verb stack Error: command failed
npm verb stack     at ChildProcess.<anonymous> (/usr/local/lib/node_modules/npm/node_modules/@npmcli/promise-spawn/lib/index.js:63:27)
npm verb stack     at ChildProcess.emit (node:events:527:28)
npm verb stack     at maybeClose (node:internal/child_process:1092:16)
npm verb stack     at Socket.<anonymous> (node:internal/child_process:451:11)
npm verb stack     at Socket.emit (node:events:527:28)
npm verb stack     at Pipe.<anonymous> (node:net:709:12)
npm verb pkgid [email protected]
npm verb cwd /opt
npm verb Linux 5.10.104-linuxkit
npm verb node v16.15.1
npm verb npm  v8.11.0
npm ERR! code 143
npm ERR! path /opt/pkg
npm ERR! command failed
npm ERR! command sh -c echo 'Hello from sleeper preinstall!' && node ./sleep.js
npm ERR! Hello from sleeper preinstall!
npm ERR! sleeping now
npm ERR! Terminated
npm verb exit 143
npm timing npm Completed in 44999ms
npm verb unfinished npm timer reify 1657318475972
npm verb unfinished npm timer reify:build 1657318476160
npm verb unfinished npm timer build 1657318476160
npm verb unfinished npm timer build:links 1657318476161
npm verb unfinished npm timer build:run:preinstall 1657318476162
npm verb unfinished npm timer build:run:preinstall:pkg 1657318476162
npm verb code 143

npm ERR! A complete log of this run can be found in:
npm ERR!     /root/.npm/_logs/2022-07-08T22_14_35_782Z-debug-0.log
spawner bye
    1. The shell we killed the hanging process with:
    root@0082c586c971:/opt# ps aux
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.1  0.7 319640 31812 ?        Ssl  22:14   0:00 node index.js
root        13  2.7  1.4 907536 60044 ?        Sl   22:14   0:01 npm install ./pkg
root        24  0.0  0.0   2388   688 ?        S    22:14   0:00 sh -c echo 'Hello from sleeper preinstall!' && node ./sleep
root        25  0.0  0.7 319640 31184 ?        Sl   22:14   0:00 node ./sleep.js
root        38  0.1  0.0   3868  3148 pts/0    Ss   22:14   0:00 /bin/bash
root       354  0.0  0.0   7640  2696 pts/0    R+   22:15   0:00 ps aux
root@0082c586c971:/opt# kill 25
root@0082c586c971:/opt# %

    image

    wdyt?

  19. bnoordhuis commented on Mar 27, 2023

    @bnoordhuis
    bnoordhuis
    on Mar 27, 2023
    Member

    I suspect this is explained by a change in how npm starts child processes. The SIGTERM or SIGKILL is delivered to the first child process, not all (grand)child processes. That's not something node can fix, it's just the unfortunate reality of Unix process trees.

    What can work with well-behaved programs is to start them in a new process group and signal the entire process group:

    const proc = child_process.spawn("npm", [/*args*/], {detached: true})
const timer = setTimeout(() => process.kill(-proc.pid), 10e3)

    Node can't do that automatically without breaking backwards compatibility (and blocking off some valid use cases) but now you know the option exists. I'll go ahead and close this.

  20. bnoordhuis
    closed this as not plannedon Mar 27, 2023

  21. aviadhahami commented on Apr 10, 2023

    @aviadhahami
    aviadhahami
    on Apr 10, 2023
    Author

    @bnoordhuis thx for replying!
    can you refer me to the relevant code/change please?

  22. yaanfpv
    added a commit that references this issue on Aug 4, 2026

    Correct nodejs/node#43704's status - it is closed, not open

    bf22dc4
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    child_processIssues and PRs related to the child_process subsystem.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions