setStateAsync with unknown id and no try/catch crashes javascript adatper

[Garfonso]

Describe the bug
setStateAsync with unknown id and no try/catch crashes javascript adatper

To Reproduce
Steps to reproduce the behavior:

1. Write Javascript-Script with following code: aync function xy() { await setStateAsync('alias.0.somethingnotexisting', true); }; xy(); (maybe the await is not necessary, but I had it in my code)
2. Save the script.
3. Check log files and see that javascript adapter crashes with unhandle promise rejection

Expected behavior
Javascript Adapter should try to catch this error and write an error to logfile and not crash with stopping all scripts. :-)

Screenshots & Logfiles

2021-02-14 11:25:02.775  - info: javascript.0 (614739) Start javascript script.js.otherSmarthome.fusswaermerAutoAn
2021-02-14 11:25:02.782  - info: javascript.0 (614739) script.js.otherSmarthome.fusswaermerAutoAn: registered 1 subscription and 0 schedules
2021-02-14 11:25:02.783  - info: javascript.0 (614739) script.js.otherSmarthome.fusswaermerAutoAn: Schalte Fusswärmer an wegen Stromverbrauch von 81.442W.
2021-02-14 11:25:02.783  - warn: javascript.0 (614739) State "alias.0.plugs.Fusswarmer.state" not found
2021-02-14 11:25:02.784  - warn: javascript.0 (614739)     at setState (/opt/iobroker/node_modules/iobroker.javascript/lib/sandbox.js:1417:20)
2021-02-14 11:25:02.784  - warn: javascript.0 (614739)     at /opt/iobroker/node_modules/iobroker.javascript/lib/tools.js:80:16
2021-02-14 11:25:02.784  - warn: javascript.0 (614739)     at new Promise (<anonymous>)
2021-02-14 11:25:02.784  - warn: javascript.0 (614739)     at /opt/iobroker/node_modules/iobroker.javascript/lib/tools.js:79:16
2021-02-14 11:25:02.784  - warn: javascript.0 (614739)     at switchOnOff (script.js.otherSmarthome.fusswaermerAutoAn:15:11)
2021-02-14 11:25:02.784  - warn: javascript.0 (614739)     at runMicrotasks (<anonymous>)
2021-02-14 11:25:02.784  - warn: javascript.0 (614739)     at runNextTicks (internal/process/task_queues.js:62:5)
2021-02-14 11:25:02.784  - warn: javascript.0 (614739)     at processImmediate (internal/timers.js:434:9)
2021-02-14 11:25:02.785  - error: javascript.0 (614739) 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(
2021-02-14 11:25:02.785  - error: javascript.0 (614739) unhandled promise rejection: undefined
2021-02-14 11:25:02.785  - error: javascript.0 (614739) undefined
2021-02-14 11:25:02.821  - info: javascript.0 (614739) Stop script script.js.multimedia.toonieBoxClon
2021-02-14 11:25:02.821  - info: javascript.0 (614739) Stop script script.js.Licht.bueroMehrLicht
2021-02-14 11:25:02.821  - info: javascript.0 (614739) Stop script script.js.otherSmarthome.GasCounter
2021-02-14 11:25:02.822  - info: javascript.0 (614739) Stop script script.js.multimedia.repairAudio
2021-02-14 11:25:02.822  - info: javascript.0 (614739) Stop script script.js.Telegram.sendToUser
....
2021-02-14 11:25:02.832  - info: javascript.0 (614739) Stop script script.js.KNX.reactToButtons
2021-02-14 11:25:02.832  - info: javascript.0 (614739) Stop script script.js.Schlafen.kinderSchlafen
2021-02-14 11:25:02.832  - info: javascript.0 (614739) Stop script script.js.otherSmarthome.fusswaermerAutoAn
2021-02-14 11:25:02.835  - info: javascript.0 (614739) terminating
2021-02-14 11:25:02.835  - warn: javascript.0 (614739) Terminated (UNCAUGHT_EXCEPTION): Without reason
2021-02-14 11:25:03.628  - error: host.Server 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
2021-02-14 11:25:03.630  - error: host.Server Caught by controller[1]: State "alias.0.plugs.Fusswarmer.state" not found
2021-02-14 11:25:03.630  - error: host.Server instance system.adapter.javascript.0 terminated with code 6 (UNCAUGHT_EXCEPTION)

It seems to stop all scripts before exit. But still it exits.

Versions:

• Adapter version: 4.10.15
• JS-Controller version: 3.2.16
• Node version: v12.20.1
• Operating system: Ubuntu 20.04 (or so) on x86_64 hardware.

[Apollon77]

@AlCalzone any idea how to best protect the sandbox for unhandled promise rejections?

[AlCalzone]

@Apollon77 it looks like our error code in js-controller is at least executed:

unhandled promise rejection: undefined

It probably has a bug though, since https://github.com/ioBroker/ioBroker.javascript/blob/4c6f93ab1520e2ffb82b126be5e628e12da42902/main.js#L644-L672 does not seem to do anything.

[Apollon77]

@AlCalzone Do an unhandled promise rejection has a stack?

Logging wise when checking controller this "Log behaviour" can only happen when:

• err exists
• err-message is logged as "undefined"
• err.stack is "truthy" but when logging it gives "undefined"

https://github.com/ioBroker/ioBroker.js-controller/blob/3.1.x/lib/adapter.js#L8320-L8326

And becasue of that the whole handling in javascript adapter only reacts on "err.stack"

[AlCalzone]

Yes, it essentially passes an Error around (or whatever was used as the rejection reason). You see its stack in the above log as a warning. Not sure why that no longer exists in the error handler. @Garfonso do you have a chance to set a breakpoint inside the error method I posted above and run javascript with a debugger attached?

[Apollon77]

I'm not that sure ...

the "State "id" not found" warning log comes from sandbox.js L368 also with the stack because "context.logWithLineInfo.warn" is used!!

after that the

                    callback.call(sandbox, 'State "' + id + '" not found');

happens and is promisified by tools.js promisify method to a rejected promise

[AlCalzone]

Okay then we need a custom-made promisified version of setState that does not throw.

[Apollon77]

Or we find a way to really detect a unhandled promise rejection ... maybe the error object is "just different" data wise?

[Apollon77]

or the javascript adapter error handler assumes an unhandled rejection when err..stack is undefined and also consider it "handled" automatically?

[AlCalzone]

My bet is on err is a string, since we didn't convert that to pass an error:

callback.call(sandbox, 'State "' + id + '" not found');

[Apollon77]

hhuuuuu ... so maybe add that to the javascript rpomisify function and test?

[Garfonso]

Yes, it essentially passes an Error around (or whatever was used as the rejection reason). You see its stack in the above log as a warning. Not sure why that no longer exists in the error handler. @Garfonso do you have a chance to set a breakpoint inside the error method I posted above and run javascript with a debugger attached?

I can do that, maybe today or tomorrow in the afternoon. Is this still relevant or did you figure it out by yourselves? (I did not fully get all of your conversation 😄 )

[AlCalzone]

It would help to verify if err is indeed a string there.

[Apollon77]

Alternatively we propose the lib/tools.js change in javascript adapter to make sure it is an error and retest that script again and see if error message is different

[Garfonso]

Jup, err is just a string not an Error-Object.

[Garfonso]

I tried to understand your proposed solution and implemented it here: https://github.com/Garfonso/ioBroker.javascript/commit/83ff6407f2bc8a30efdef93a47066767b50dab59

With that change the rejection is handled and an error message printed and the adapter keeps running. If the change is what you meant, I'll open a PR.

[Apollon77]

awesome!

[Apollon77]

The only question is if we consider this as "breakign "or not? I would say not because not that many users use async stuff in javasscript scripts. I would do a minor increase with this. Option opinions?

[Garfonso]

One test (macos, node 14) failed... did not yet understand, why..? Is this known to happen?

The only question is if we consider this as "breakign "or not? I would say not because not that many users use async stuff in javasscript scripts. I would do a minor increase with this. Option opinions?

I don't think it is breaking. Only in the case that somebody catches an error from one of the promisified functions and expects a string. I don't think anybody really does that and the toString() function of Error does a pretty good job, too. I'd do a minor increase, too.

[Apollon77]

restart tests. there is still a "timing issue" somewhere ... somewhen wee need to find it" :-))