PM2 interfering with util.promisify of setTimeout

shanehughes3 commented 5 years ago

What's going wrong?

PM2 is preventing node's util.promisify function from properly handling setTimeout. This is a code pattern recommended by the node documentation that allows setting timeouts that flow within promise chains or async functions. Running this code with node outside of pm2 does not result in an error.

I am not positive when this issue began, but I know that it did not exist a month ago.

The error received is:

1|pm2test  | TypeError [ERR_INVALID_CALLBACK]: Callback must be a function
1|pm2test  |     at setTimeout (timers.js:429:11)
1|pm2test  |     at fallback (/Users/shane/.nvm/versions/node/v11.4.0/lib/node_modules/pm2/node_modules/async-listener/index.js:621:15)
1|pm2test  |     at /Users/shane/.nvm/versions/node/v11.4.0/lib/node_modules/pm2/node_modules/async-listener/index.js:651:53
1|pm2test  |     at Promise (internal/util.js:282:30)
1|pm2test  |     at new WrappedPromise (/Users/shane/.nvm/versions/node/v11.4.0/lib/node_modules/pm2/node_modules/async-listener/es6-wrapped-promise.js:13:18)
1|pm2test  |     at internal/util.js:281:12
1|pm2test  |     at Object.<anonymous> (/Users/shane/dev/test/pm2test.js:3:1)
1|pm2test  |     at Module._compile (internal/modules/cjs/loader.js:723:30)
1|pm2test  |     at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
1|pm2test  |     at Module.load (internal/modules/cjs/loader.js:620:32)

How could we reproduce this issue?

Create a pm2test.js with the following:

const setTimeoutPromise = require('util').promisify(setTimeout);

setTimeoutPromise(1000).then(() => console.log('done'));

First, run this directly with node:

> node pm2test.js
done

Now start with pm2: pm2 start pm2test.js and observe the log output, which produces the above error.

Supporting information

$ pm2 report

--- PM2 report ----------------------------------------------------------------
Date                 : Wed Mar 13 2019 14:50:50 GMT-0500 (Central Daylight Time)
===============================================================================
--- Daemon -------------------------------------------------
pm2d version         : 3.4.0
node version         : 11.4.0
node path            : /Users/shane/.nvm/versions/node/v11.4.0/bin/pm2
argv                 : /Users/shane/.nvm/versions/node/v11.4.0/bin/node,/Users/shane/.nvm/versions/node/v11.4.0/lib/node_modules/pm2/lib/Daemon.js
argv0                : node
user                 : shane
uid                  : 501
gid                  : 20
uptime               : 6min
===============================================================================
--- CLI ----------------------------------------------------
local pm2            : 3.4.0
node version         : 11.4.0
node path            : /Users/shane/.nvm/versions/node/v11.4.0/bin/pm2
argv                 : /Users/shane/.nvm/versions/node/v11.4.0/bin/node,/Users/shane/.nvm/versions/node/v11.4.0/bin/pm2,report
argv0                : node
user                 : shane
uid                  : 501
gid                  : 20
===============================================================================
--- System info --------------------------------------------
arch                 : x64
platform             : darwin
type                 : Darwin
cpus                 : Intel(R) Core(TM) i7-4770HQ CPU @ 2.20GHz
cpus nb              : 8
freemem              : 75673600
totalmem             : 17179869184
home                 : /Users/shane
===============================================================================
--- PM2 list -----------------------------------------------
┌──────────┬────┬─────────┬──────┬───────┬────────┬─────────┬────────┬──────┬───────────┬───────┬──────────┐
│ App name │ id │ version │ mode │ pid   │ status │ restart │ uptime │ cpu  │ mem       │ user  │ watching │
├──────────┼────┼─────────┼──────┼───────┼────────┼─────────┼────────┼──────┼───────────┼───────┼──────────┤
│ pm2test  │ 1  │ 0.0.1   │ fork │ 86497 │ online │ 10      │ 4s     │ 6.5% │ 34.1 MB   │ shane │ disabled │
└──────────┴────┴─────────┴──────┴───────┴────────┴─────────┴────────┴──────┴───────────┴───────┴──────────┘
===============================================================================
--- Daemon logs --------------------------------------------
/Users/shane/.pm2/pm2.log last 20 lines:
PM2        | 2019-03-13T14:50:14: PM2 log: App [pm2test:1] starting in -fork mode-
PM2        | 2019-03-13T14:50:14: PM2 log: App [pm2test:1] online
PM2        | 2019-03-13T14:50:19: PM2 log: App [pm2test:1] exited with code [0] via signal [SIGINT]
PM2        | 2019-03-13T14:50:19: PM2 log: App [pm2test:1] starting in -fork mode-
PM2        | 2019-03-13T14:50:19: PM2 log: App [pm2test:1] online
PM2        | 2019-03-13T14:50:25: PM2 log: App [pm2test:1] exited with code [0] via signal [SIGINT]
PM2        | 2019-03-13T14:50:25: PM2 log: App [pm2test:1] starting in -fork mode-
PM2        | 2019-03-13T14:50:25: PM2 log: App [pm2test:1] online
PM2        | 2019-03-13T14:50:30: PM2 log: App [pm2test:1] exited with code [0] via signal [SIGINT]
PM2        | 2019-03-13T14:50:30: PM2 log: App [pm2test:1] starting in -fork mode-
PM2        | 2019-03-13T14:50:30: PM2 log: App [pm2test:1] online
PM2        | 2019-03-13T14:50:35: PM2 log: App [pm2test:1] exited with code [0] via signal [SIGINT]
PM2        | 2019-03-13T14:50:35: PM2 log: App [pm2test:1] starting in -fork mode-
PM2        | 2019-03-13T14:50:35: PM2 log: App [pm2test:1] online
PM2        | 2019-03-13T14:50:40: PM2 log: App [pm2test:1] exited with code [0] via signal [SIGINT]
PM2        | 2019-03-13T14:50:40: PM2 log: App [pm2test:1] starting in -fork mode-
PM2        | 2019-03-13T14:50:40: PM2 log: App [pm2test:1] online
PM2        | 2019-03-13T14:50:46: PM2 log: App [pm2test:1] exited with code [0] via signal [SIGINT]
PM2        | 2019-03-13T14:50:46: PM2 log: App [pm2test:1] starting in -fork mode-
PM2        | 2019-03-13T14:50:46: PM2 log: App [pm2test:1] online

shanehughes3 commented 5 years ago

It appears it's an upstream issue with async-listener: othiym23/async-listener#136. The maintainer there, however, recommends using native async hooks.

Unitech commented 5 years ago

cc @vmarchaud

vmarchaud commented 5 years ago

Hey,

It should be fixed with a pm2 re-installation:

npm install pm2 -g
pm2 update

gunyakov commented 1 year ago

TypeError [ERR_INVALID_CALLBACK]: Callback must be a function. Received 5000 at setTimeout (node:timers:141:3) at fallback (/usr/lib/node_modules/pm2/node_modules/async-listener/index.js:621:15) at /usr/lib/node_modules/pm2/node_modules/async-listener/index.js:651:53 at node:internal/util:364:7 at new Promise (<anonymous>) at node:internal/util:350:12 at Polling.[Symbol.asyncIterator] (/home/marinecareer/marinecareer-bot/node_modules/telegraf/lib/core/network/polling.js:50:27) at runMicrotasks (<anonymous>) at processTicksAndRejections (node:internal/process/task_queues:96:5) at async Polling.loop (/home/marinecareer/marinecareer-bot/node_modules/telegraf/lib/core/network/polling.js:74:30) { code: 'ERR_INVALID_CALLBACK' }

2022 close to end. Problem still exist. Node 18, Ubuntu 22, Telegraf 4.8 for telegram bots. Every day it`s shut down my bots.

UrsKramer commented 1 year ago

I have the same issue. It only occours using the trace = true option though. Workaround for now is trace = false. Maybe this can hint to a fix?

Unitech / pm2