Zwavejs2mqtt: [bug] Unhandled error "ZWaveError: Timed out while waiting for a response from the node"

[ODINServ]

Hi,

So,,, you've asked to keep testing,,, apparently i ran into a new issue.
Still running the latest dev container.

Only seen once, when sending a scene while zwave-js is still resuming from cache:

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:
ZWaveError: Timed out while waiting for a response from the node
    at Object.sendDataErrorToZWaveError (/usr/src/app/node_modules/zwave-js/src/lib/driver/StateMachineShared.ts:147:11)
    at /usr/src/app/node_modules/zwave-js/src/lib/driver/SendThreadMachine.ts:432:4
    at /usr/src/app/node_modules/xstate/lib/utils.js:409:33
    at Array.reduce (<anonymous>)
    at Object.updateContext (/usr/src/app/node_modules/xstate/lib/utils.js:399:25)
    at Object.resolveActions (/usr/src/app/node_modules/xstate/lib/actions.js:405:19)
    at StateNode.resolveTransition (/usr/src/app/node_modules/xstate/lib/StateNode.js:787:35)
    at StateNode.transition (/usr/src/app/node_modules/xstate/lib/StateNode.js:733:21)
    at /usr/src/app/node_modules/xstate/lib/interpreter.js:600:34
    at Object.exports.provide (/usr/src/app/node_modules/xstate/lib/serviceScope.js:11:18)
    at Interpreter.nextState (/usr/src/app/node_modules/xstate/lib/interpreter.js:599:38)
    at /usr/src/app/node_modules/xstate/lib/interpreter.js:124:39
    at Scheduler.process (/usr/src/app/node_modules/xstate/lib/scheduler.js:60:13)
    at Scheduler.schedule (/usr/src/app/node_modules/xstate/lib/scheduler.js:44:14)
    at Interpreter.send (/usr/src/app/node_modules/xstate/lib/interpreter.js:121:29)
    at Timeout.<anonymous> (/usr/src/app/node_modules/xstate/lib/interpreter.js:631:23)

I guess when resuming from cache the network is pretty busy and not able to reach this node.
At least it should be handled.

I don't see strange things in the zwave-1 log file
zwave-1.log

Thnx!

[robertsLando]

@AlCalzone I think this is for you

[robertsLando]

@ODINServ Yep keep testing this issues are so useful! :)

[AlCalzone]

Hm - I can't see where this is coming from :(
The driver tries to attach the source (where a transaction was created) to the errors but it is not included here.

[robertsLando]

Only seen once, when sending a scene while zwave-js is still resuming from cache:

@AlCalzone could this be the reason?

[ODINServ]

Not sure if it helps but here is the "podman logs" output.

podman-logs-22.txt

[AlCalzone]

If that is a command that was triggered by the user, zwave-js does not catch promise rejections. The calling application is supposed to catch if a command fails.

[robertsLando]

What is strange here to me:

2020-11-24T09:31:56.116Z z2m:Zwave Node 7: value updated: 38-1-duration Duration { unit: 'unknown', _value: 0 } => Duration { unit: 'unknown', _value: 0 }

Does some valueUpdate events have that format for previous/new values? I mean, ob ject format

[robertsLando]

@ODINServ Is this caused by a specific command or randomly?

[AlCalzone]

Does some valueUpdate events have that format for previous/new values? I mean, ob ject format

The duration class has a pretty JSON representation.

[ODINServ]

@ODINServ Is this caused by a specific command or randomly?

Before the timestamp below the shutters 12 (FGR223) shutters were closed.

2020-11-24T09:30:45.587Z z2m:App Zwave api call: _activateScene [ 2 ]
I'd tried to open them by activating a scene using the website (since that is for now the only way to control them, i did not finalized the openhab integration)

For some reason some did not respond:

2020-11-24T09:30:45.587Z z2m:App Zwave api call: _activateScene [ 2 ]
2020-11-24T09:30:45.589Z z2m:Zwave Success zwave api call _activateScene true
2020-11-24T09:30:52.295Z z2m:Zwave Error while writing 0 on 2-38-1-targetValue: Timed out while waiting for a response from the node
2020-11-24T09:30:52.295Z z2m:Zwave Unable to write 0 on 2-38-1-targetValue
2020-11-24T09:30:58.986Z z2m:Zwave Error while writing 0 on 3-38-1-targetValue: Timed out while waiting for a response from the node
2020-11-24T09:30:58.986Z z2m:Zwave Unable to write 0 on 3-38-1-targetValue
2020-11-24T09:31:05.065Z z2m:Zwave Error while writing 0 on 4-38-1-targetValue: Timed out while waiting for a response from the node
2020-11-24T09:31:05.065Z z2m:Zwave Unable to write 0 on 4-38-1-targetValue
2020-11-24T09:31:11.094Z z2m:Zwave Error while writing 0 on 5-38-1-targetValue: Timed out while waiting for a response from the node
2020-11-24T09:31:11.094Z z2m:Zwave Unable to write 0 on 5-38-1-targetValue
2020-11-24T09:31:17.678Z z2m:Zwave Error while writing 0 on 6-38-1-targetValue: Timed out while waiting for a response from the node
2020-11-24T09:31:17.679Z z2m:Zwave Unable to write 0 on 6-38-1-targetValue
2020-11-24T09:31:25.279Z z2m:Zwave Error while writing 0 on 9-38-1-targetValue: Timed out while waiting for a response from the node
2020-11-24T09:31:25.279Z z2m:Zwave Unable to write 0 on 9-38-1-targetValue

I did a request again to open the other shutters (scene 2)
2020-11-24T09:32:25.008Z z2m:App Zwave api call: _activateScene [ 2 ]
Which then causes a crash just after
2020-11-24T09:33:01.052Z

[robertsLando]

Apart from this do you know that you could also use broadcast apis for such things?

[AlCalzone]

From my perspective it looks like some command error is not handled in zjs2mqtt, but I can't say for sure.

[ODINServ]

No, can you elaborate that or do you have some documentation i have some more questions, like:

It would be nice if i can create a group, i am also using zigbee2mqtt to control zigbee lights, so you can send one command and everything response at the same time, it will broadcast it to that group and all lights will pick them up at the sametime.

Is that the same to groups / associations in zwave?
Since "zwavejs2mqtt/bedroom_left/multi_instance_association/endpoints/2" i see that is associated with the "right" (node3) node.
But how to send a targetValue to that association (if it is the same as in zigbee).

I can do that in openhab by creating a group, but it will then send all commands individually.

[AlCalzone]

In Z-Wave you can either send all commands individually (which has the most flexibility), send one command to all nodes (using the broadcast Node ID 255) or send one command to several nodes via multicast (using an array of Node IDs).
Using broadcast/multicast you cannot target different endpoints per node, but if all commands should go to the same endpoints it should work.

[robertsLando]

I can do that in openhab by creating a group, but it will then send all commands individually.

I think that groups managements is internally managed and it's not something related to zwave protocol. I mean when you create a group X essentially you have an array of ids and you send commands to all them when sending commands to that group

[ODINServ]

@AlCalzone that sounds what i want to do indeed, multicast the close command to a subset of nodes, not all since i don't want my lights to turn on so broadcast sounds not so nice, is that functionality available via mqtt ? (Example close all shutters at the same time)

So the question is then, how to send a multicast via mqtt to for example node 2,3,4,5?

In the zigbee project i have to set this up using the config file, and than a new topic will be created in which i can publish but also to read-back the of the group (which is nice to have) ( it looks like a zigbee feature https://www.zigbee2mqtt.io/information/groups.html)

By using the above add command above, a device will be added to a group. The device itself is responsible for storing to which groups it belongs. Others, e.g. the coordinator, do not have knowledge to which device a groups belongs.

I can also live with a command like topic like:

zwavejs2mqtt/multicast/switch_multilevel/endpoint_1/targetValue
The value will then be { nodes: [2,3,4,5], value: 0 }
Or Node names will be nice.

[robertsLando]

I could easily implement this, let's create a separete issue

[robertsLando]

@ODINServ Try with https://github.com/zwave-js/zwavejs2mqtt/pull/25

The apis are like broadcasts but also require an array of nodes in the mwtt payload, check docs in the pr

[ODINServ]

That's fast!

I Will try tomorrow, is there a docker image available ?
Or do i have to build it from the branch ?

[robertsLando]

No docker image for now, docker builds are only for master branch, could you manually build it or even better use nodejs way?

[ODINServ]

Alright, i moved it into a VM and build it there from the feat#multicast branch.

I ran into a package issue
## There is an issue with `node-fibers` ##
i'd installed in manually
npm install fibers

It is now running that branch.

I will do the actual test this afternoon.

[robertsLando]

There is an issue with node-fibers

No idea about that, will investigate

[ODINServ]

Hey,

I got a new / same crash as the initial ticket.

Running now in a manjaro vm on the mqtt multicast branch and running de node-zwave-js " supervision/refresh" branch.

Now the system was running normally not resuming from cache.
Id cached when i send a command (open/99) to 8 of the fgr223 modules

Console output: console-output.log
"A complete log of this run can be found in:" 2020-11-28T07_41_02_872Z-debug.log
zwave log: zwave-2566.log

Thnx

[robertsLando]

@AlCalzone ?

[AlCalzone]

Not sure where that lib comes from - I don't use it.

$ npm ls node-fibers
@zwave-js/repo@ C:\Repositories\node-zwave-js
└── (empty)

$ npm ls fibers
@zwave-js/repo@ C:\Repositories\node-zwave-js
└── (empty)

Regarding the log: It seems like Node 2 doesn't answer to a Multilevel Switch Get (refresh after set) which causes the transaction to be rejected. These transactions are created outside zwave-js and errors must be handled there. My guess is that @robertsLando forgot a try-catch somewhere.

@ODINServ You seem to have quite some connectivity problems in your network. Lots of missing, very delayed or even duplicate messages from the nodes. That combined with the overhead of Security S0 (2 additional messages per "real" message plus retries) is a terrible combination.
I would advise you to re-include at least the roller shutters non-securely. After all it is not like you can hide what happens with the shutters. Everyone on the streets can see the current state and if they are moving - you don't need to encrypt that.

[robertsLando]

node-fibers is a dev deps of zjs2m but it shouldn't break anything

[robertsLando]

Regarding the log: It seems like Node 2 doesn't answer to a Multilevel Switch Get (refresh after set) which causes the transaction to be rejected. These transactions are created outside zwave-js and errors must be handled there. My guess is that @robertsLando forgot a try-catch somewhere.

It could be but I need to know the event that throws that error in this case, or some more details as I don't understand where it comes from

[AlCalzone]

Is this the only location where you tell zwave-js to write values?

Or could you add an unhandledRejection handler to the zjs2m and log error.transactionSource if that exists? That could give us a lead where the transaction comes from.

[robertsLando]

Is this the only location where you tell zwave-js to write values?

Yes it is

Or could you add an unhandledRejection handler to the zjs2m

I can

[AlCalzone]

Yes it is

Hmm maybe it is a bug in zwave-js then. But the location I'm suspecting has a .catch() call. Lets see if the handler helps us figure it out.

[robertsLando]

I think that almost everything on the code has a try catch block, also it's strange that in the stack there is no reference to my code

[ODINServ]

@AlCalzone alright, i _might_ include them unsecure in the future, but i hope the broadcast / multicast change request can help here.

I do agree with the strange network behavior, for now i do disable again all power reports (i don't care about them), and will update my OpenHAB rule to sleep a bit before sending the next command.

I wont report new issues regarding device timeouts.

I leave it up @robertsLando or @AlCalzone for closing since you might found something regarding the crash it self.

[AlCalzone]

I'll leave this open since I want to find out where this comes from.

[ODINServ]

Regarding the node fibers:

[root@708911b7d203 zwavejs2mqtt]# npm run build

> [email protected] build /git/zwavejs2mqtt
> node build/build.js

## There is an issue with `node-fibers` ##
`/git/zwavejs2mqtt/node_modules/fibers/bin/linux-x64-88-glibc/fibers.node` is missing.

Try running this to fix the issue: /usr/bin/node /git/zwavejs2mqtt/node_modules/fibers/build
Error: Cannot find module '/git/zwavejs2mqtt/node_modules/fibers/bin/linux-x64-88-glibc/fibers'
Require stack:
- /git/zwavejs2mqtt/node_modules/fibers/fibers.js
- /git/zwavejs2mqtt/build/webpack.base.conf.js
- /git/zwavejs2mqtt/build/webpack.prod.conf.js
- /git/zwavejs2mqtt/build/build.js
    at Function.Module._resolveFilename (node:internal/modules/cjs/loader:919:15)
    at Function.Module._load (node:internal/modules/cjs/loader:763:27)
    at Module.require (node:internal/modules/cjs/loader:991:19)
    at require (node:internal/modules/cjs/helpers:92:18)
    at Object.<anonymous> (/git/zwavejs2mqtt/node_modules/fibers/fibers.js:14:39)
    at Module._compile (node:internal/modules/cjs/loader:1102:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1131:10)
    at Module.load (node:internal/modules/cjs/loader:967:32)
    at Function.Module._load (node:internal/modules/cjs/loader:807:14)
    at Module.require (node:internal/modules/cjs/loader:991:19)
/git/zwavejs2mqtt/node_modules/fibers/fibers.js:23
        throw new Error('Missing binary. See message above.');
        ^

Error: Missing binary. See message above.
    at Object.<anonymous> (/git/zwavejs2mqtt/node_modules/fibers/fibers.js:23:9)
    at Module._compile (node:internal/modules/cjs/loader:1102:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1131:10)
    at Module.load (node:internal/modules/cjs/loader:967:32)
    at Function.Module._load (node:internal/modules/cjs/loader:807:14)
    at Module.require (node:internal/modules/cjs/loader:991:19)
    at require (node:internal/modules/cjs/helpers:92:18)
    at Object.<anonymous> (/git/zwavejs2mqtt/build/webpack.base.conf.js:97:24)
    at Module._compile (node:internal/modules/cjs/loader:1102:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1131:10)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! [email protected] build: `node build/build.js`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the [email protected] build script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /root/.npm/_logs/2020-11-30T19_30_08_650Z-debug.log

root@708911b7d203 zwavejs2mqtt]# cat /root/.npm/_logs/2020-11-30T19_30_08_650Z-debug.log
0 info it worked if it ends with ok
1 verbose cli [ '/usr/bin/node', '/usr/sbin/npm', 'run', 'build' ]
2 info using [email protected]
3 info using [email protected]
4 verbose run-script [ 'prebuild', 'build', 'postbuild' ]
5 info lifecycle [email protected]~prebuild: [email protected]
6 info lifecycle [email protected]~build: [email protected]
7 verbose lifecycle [email protected]~build: unsafe-perm in lifecycle true
8 verbose lifecycle [email protected]~build: PATH: /usr/lib/node_modules/npm/node_modules/npm-lifecycle/node-gyp-bin:/git/zwavejs2mqtt/node_modules/.bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
9 verbose lifecycle [email protected]~build: CWD: /git/zwavejs2mqtt
10 silly lifecycle [email protected]~build: Args: [ '-c', 'node build/build.js' ]
11 silly lifecycle [email protected]~build: Returned: code: 1  signal: null
12 info lifecycle [email protected]~build: Failed to exec build script
13 verbose stack Error: [email protected] build: `node build/build.js`
13 verbose stack Exit status 1
13 verbose stack     at EventEmitter.<anonymous> (/usr/lib/node_modules/npm/node_modules/npm-lifecycle/index.js:332:16)
13 verbose stack     at EventEmitter.emit (node:events:376:20)
13 verbose stack     at ChildProcess.<anonymous> (/usr/lib/node_modules/npm/node_modules/npm-lifecycle/lib/spawn.js:55:14)
13 verbose stack     at ChildProcess.emit (node:events:376:20)
13 verbose stack     at maybeClose (node:internal/child_process:1055:16)
13 verbose stack     at Process.ChildProcess._handle.onexit (node:internal/child_process:288:5)
14 verbose pkgid [email protected]
15 verbose cwd /git/zwavejs2mqtt
16 verbose Linux 5.4.80-2-MANJARO
17 verbose argv "/usr/bin/node" "/usr/sbin/npm" "run" "build"
18 verbose node v15.3.0
19 verbose npm  v6.14.8
20 error code ELIFECYCLE
21 error errno 1
22 error [email protected] build: `node build/build.js`
22 error Exit status 1
23 error Failed at the [email protected] build script.
23 error This is probably not a problem with npm. There is likely additional logging output above.
24 verbose exit [ 1, true ]

[robertsLando]

Regarding the node fibers:

Could you give me some more info? What's the arch? arm32 arm64, amd64? Are you running it on docker? What's the OS? alpine, ubuntu, windows, mac? I think that error is not a bug with z2m or zwavejs but something system related as no one is reporting it

[ODINServ]

I'm running manajro linux (gnome version) on my amd64 based laptop and installed zwave-js using the node way.

I do think it indeed needs something for from the OS, because i have to install all development tools (compilers / Linux header) before installing node fibers. Also it does seem to do some compiling after i execute npm install fibers.

I will spin-up a ubuntu vm later to see if i can reproduce it there

But the question is also why do i need to install them manually then?

[robertsLando]

@ODINServ Have you tried to install it manually? What's the output of npm install node-fibers?

[ODINServ]

Well, i did the test with the ubuntu vm.. it seems that is manjaro related issue (Long live all linux distributions)

npm install (Error details in one of the comments above):

npm run build:

So fix for manjaro:

• Install "base-devel" group (pacman -S base-devel)
• Manually install node fibers (npm install fibers)
• Re run install (npm install)
• Run build (npm run build)
• Start (npm start)

I would not hunt this fibers issue indeed, sorry did not know that this was linux distro related, im not a node developer.

[robertsLando]

I would not hunt this fibers issue indeed, sorry did not know that this was linux distro related, im not a node developer.

No worries @ODINServ I thought that because most times such problems are os related. Can we close this?

[ODINServ]

Well i've mixed to much into this issue, the fiber thingy is fine for now.

If i quote @AlCalzone

I'll leave this open since I want to find out where this comes from.

Don't know i'll live it to you two, i think the actual crash (first post) should be handled somehow.
I know you my network is magic (lots of timeouts as you pointed out) but zwavejs should not crash if you ask me.

[AlCalzone]

zwavejs should not crash

I agree but I need some kind of idea where the transaction is created to figure out why rejecting it causes a crash.

[robertsLando]

@ODINServ Can this be closed?