Restart of JS-Adapter when error in Promise function

[GreatSUN]

When there is an error in a function in a promise (see code below) then the adapter cannot identify where the error comes from and restarts the adapter. I hope that I have created a reasonable example code, because I have changed my implementation meanwhile to node-fetch and fixed all potential errors. It at least did what I described when I tried it here.

function callFunction(testVar) { console.log(testMeVar); } var request = require('then-request'); request('GET', 'http://example.com').done(function (res) { callFunction('test'); })

Expected behavior
The code should raise an error, but the instance should not be restarted.

Screenshots & Logfiles
20:53:18.081 | error | javascript.0 (527) script.js.Test.TestScript: ReferenceError: testMeVar is not defined 20:53:18.081 | error | javascript.0 (527) at callFunction (script.js.Test.TestScript:2:17) 20:53:18.082 | error | javascript.0 (527) at script.js.Test.TestScript:6:5 20:53:18.205 | error | host.iobroker Caught by controller[0]: at callFunction (script.js.Test.TestScript:364:17) 20:53:18.205 | error | host.iobroker Caught by controller[0]: at script.js.Test.TestScript:368:5

Versions:

• Adapter version: v5.6.0
• JS-Controller version: 4.0.23
• Node version: v16.15.0
• Operating system: Slackware Host + Debian 11.3 in container managed by podman

[Apollon77]

Is the instance really restarted? Please post more log

[GreatSUN]

Here the output of the main log (sorry for the crazy icons):

2022-05-04 20:53:18.081  - [31merror[39m: javascript.0 (527) script.js.Test.TestScript: ReferenceError: testMeVar is not defined
2022-05-04 20:53:18.081  - [31merror[39m: javascript.0 (527)     at callFunction (script.js.Test.TestScript:2:17)
2022-05-04 20:53:18.082  - [31merror[39m: javascript.0 (527)     at script.js.Test.TestScript:6:5
2022-05-04 20:53:18.082  - [31merror[39m: javascript.0 (527)     at tryCallOne (/opt/iobroker/node_modules/promise/lib/core.js:37:12)
2022-05-04 20:53:18.082  - [31merror[39m: javascript.0 (527)     at /opt/iobroker/node_modules/promise/lib/core.js:123:15
2022-05-04 20:53:18.082  - [31merror[39m: javascript.0 (527)     at flush (/opt/iobroker/node_modules/asap/raw.js:50:29)
2022-05-04 20:53:18.083  - [31merror[39m: javascript.0 (527)     at processTicksAndRejections (node:internal/process/task_queues:78:11)
2022-05-04 20:53:18.205  - [31merror[39m: host.iobroker Caught by controller[0]: ReferenceError: testMeVar is not defined
2022-05-04 20:53:18.205  - [31merror[39m: host.iobroker Caught by controller[0]:     at callFunction (script.js.Test.TestScript:364:17)
2022-05-04 20:53:18.205  - [31merror[39m: host.iobroker Caught by controller[0]:     at script.js.Test.TestScript:368:5
2022-05-04 20:53:18.205  - [31merror[39m: host.iobroker Caught by controller[0]:     at tryCallOne (/opt/iobroker/node_modules/promise/lib/core.js:37:12)
2022-05-04 20:53:18.205  - [31merror[39m: host.iobroker Caught by controller[0]:     at /opt/iobroker/node_modules/promise/lib/core.js:123:15
2022-05-04 20:53:18.206  - [31merror[39m: host.iobroker Caught by controller[0]:     at flush (/opt/iobroker/node_modules/asap/raw.js:50:29)
2022-05-04 20:53:18.206  - [31merror[39m: host.iobroker Caught by controller[0]:     at processTicksAndRejections (node:internal/process/task_queues:78:11)
2022-05-04 20:53:18.206  - [31merror[39m: host.iobroker instance system.adapter.javascript.0 terminated with code 1 (JS_CONTROLLER_STOPPED)
2022-05-04 20:53:18.206  - [32minfo[39m: host.iobroker Restart adapter system.adapter.javascript.0 because enabled
2022-05-04 20:53:48.280  - [32minfo[39m: host.iobroker instance system.adapter.javascript.0 started with pid 591

[Apollon77]

I checked it and yes it seems that since node.js 16 "Unhandled rejections" like in your case can be grabbed with a listener (and we do this), but the node process will exit in any case once this happens :-(

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs within the next 7 days. Please check if the issue is still relevant in the most current version of the adapter and tell us. Also check that all relevant details, logs and reproduction steps are included and update them if needed. Thank you for your contributions. Dieses Problem wurde automatisch als veraltet markiert, da es in letzter Zeit keine Aktivitäten gab. Es wird geschlossen, wenn nicht innerhalb der nächsten 7 Tage weitere Aktivitäten stattfinden. Bitte überprüft, ob das Problem auch in der aktuellsten Version des Adapters noch relevant ist, und teilt uns dies mit. Überprüft auch, ob alle relevanten Details, Logs und Reproduktionsschritte enthalten sind bzw. aktualisiert diese. Vielen Dank für Eure Unterstützung.

[ticaki]

nodejs: v18.18.2

io-package.json: "compact": false, "nodeProcessParams": ["--unhandled-rejections=warn"],

Testscript:

async function test() {
    return await messageToAsync('test','test', {timeout: 1000})
}
async function test2 () {
    return await test()
}
test2()

Log:

2023-11-10 16:46:10.565 - info: javascript.0 (50870) Start javascript script.js.Test.Skript_1
2023-11-10 16:46:10.576 - info: javascript.0 (50870) script.js.Test.Skript_1: registered 0 subscriptions, 0 schedules, 0 messages, 0 logs and 0 file subscriptions
2023-11-10 16:46:11.577 - error: javascript.0 (50870) Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch().
2023-11-10 16:46:11.578 - error: javascript.0 (50870) unhandled promise rejection: undefined
2023-11-10 16:46:11.578 - error: javascript.0 (50870) undefined

...


2023-11-10 16:46:11.634 - info: javascript.0 (50870) terminating
2023-11-10 16:46:11.635 - warn: javascript.0 (50870) Terminated (UNCAUGHT_EXCEPTION): Without reason
2023-11-10 16:46:12.112 - info: javascript.0 (50870) terminating
2023-11-10 16:46:12.215 - error: host.iobroker Caught by controller[0]: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason:
2023-11-10 16:46:12.216 - error: host.iobroker Caught by controller[1]: timeout
2023-11-10 16:46:12.216 - error: host.iobroker Caught by controller[2]: (node:50870) UnhandledPromiseRejectionWarning: timeout
2023-11-10 16:46:12.216 - error: host.iobroker Caught by controller[2]: (Use `node --trace-warnings ...` to show where the warning was created)
2023-11-10 16:46:12.216 - error: host.iobroker Caught by controller[3]: (node:50870) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 4)
2023-11-10 16:46:12.216 - error: host.iobroker instance system.adapter.javascript.0 terminated with code 6 (UNCAUGHT_EXCEPTION)
2023-11-10 16:46:12.216 - info: host.iobroker Restart adapter system.adapter.javascript.0 because enabled
2023-11-10 16:46:20.573 - info: admin.0 (576) <== Disconnect system.user.admin from ::ffff:192.168.178.133 javascript
2023-11-10 16:46:42.260 - info: host.iobroker instance system.adapter.javascript.0 started with pid 57320

[klein0r]

@ticaki Yes, because it is also an unhandled exception. You can shorten your test script like

throw new Error('test');

[ticaki]

Test and report requested by Apollon77. :)

to test this: https://github.com/ioBroker/ioBroker.js-controller/issues/844#issuecomment-1151106315

[klein0r]

Looks like the "new" common.nodeProcessParams: ["--unhandled-rejections=warn"] is available since js-controller 5

https://github.com/ioBroker/ioBroker.js-controller/pull/2123

Using this feature will disable the possibility to start the adapter in compact mode

Mhhh - if specified, the adapter won't start in compact mode anymore? Are there any statistics, how many users are running their system in compact mode and have the JavaScript adapter installed @Apollon77 ?

[Apollon77]

Start not anymore? this was never reported and yes there should be a log when using compact but there should be no error or such.

[ticaki]

If compact is allowed, "common.nodeProcessParams" is not activated, regardless of whether it is used.

2023-11-10 15:01:38.436 - warn: host.iobroker Adapter javascript has "compact=true" as well as "nodeProcessParams" specified, this is not supported, please report to developer

[klein0r]

Of course - but the warning will be raised when common.compact is set to true - which means: on every adapter start.

https://github.com/ioBroker/ioBroker.js-controller/blob/bb422a02d9a94a000eae16cf0c342485b028e224/packages/controller/src/main.ts#L4117-L4122

So compact mode support must be disabled completely:

https://github.com/ioBroker/ioBroker.javascript/blob/939b0b0a70dd857684afc10be6732467fb3a5208/io-package.json#L142

Otherwise the warning will be raised on every start. Even if the instance is not running in compact mode. That will lead to many issues (because it should be reported to the developers).

[Apollon77]

I would more fevor then a js-controller issue to only log this message if compact is szpported and also active foir this instance ... to then log on start :-)

In fact till now - to be honest additionally - this setting do not seem to have a noticeable solving effect for issues with uhancled rejections :-)