Zwavejs2mqtt: [bug] Unknown manufacturer/product even though zwave-js eventually detects it

[ahochsteger]

Version

Build/Run method: Docker

zwavejs2mqtt version: 1.0.0-rc.1 (master branch)
zwavejs version: 6.0.2

Describe the bug

(For updated logs and similar problems with nodes 25+36 see: [https://github.com/zwave-js/zwavejs2mqtt/issues/347#issuecomment-767346459])

I still have the problem with "Unknown manufacturer / product" for some battery-powered devices that take a longer time to be interviewed successfully, esp. if they are a bit further from the Z-Wave controller away.
Most of the time it is possible to trigger a re-interview in zwavejs2mqtt and waking up the device which causes the device to fully show up in the nodes table.
Unfortunately some devices show then up as "Unknown manufacturer/product" which cannot be changed to the correct names by re-interviewing again, even though zwave-js is able to successfully detect the name - although it may take a longer time (e.g. 20-30h).
Here are screenshots for the 2 problematic nodes (25, 150):

The attached logs for both zwavejs2mqtt and zwave-js show about 30 hours from a fresh start (empty store directory) up until after the problem occurred again and include all the relevant config files: files.zip
The problematic nodes are: 25 and 150 - both Shenzhen Neo NAS-DS01Z Door/Window sensors.

These are some interesting log lines from zwavejs2mqtt:

2021-01-24 18:08:31.896 INFO ZWAVE: Node 150 ready: Shenzhen Neo Electronics Co., Ltd. - NAS-DS01Z (Door/Window Sensor)
2021-01-25 07:31:16.974 INFO ZWAVE: Node 150 ready: Shenzhen Neo Electronics Co., Ltd. - NAS-DS01Z (Door/Window Sensor)
2021-01-25 18:18:01.868 INFO ZWAVE: Node 150 ready: Unknown manufacturer undefined - Unknown product undefined (Unknown)
2021-01-25 19:09:13.604 INFO ZWAVE: Node 25: value added 25-134-0-protocolVersion => undefined
2021-01-25 19:09:13.607 INFO ZWAVE: Node 25: value added 25-134-0-firmwareVersions => undefined
2021-01-25 19:09:13.609 INFO ZWAVE: Node 25: value added 25-114-0-manufacturerId => undefined
2021-01-25 19:09:13.612 INFO ZWAVE: Node 25: value added 25-114-0-productType => undefined
2021-01-25 19:09:13.615 INFO ZWAVE: Node 25: value added 25-114-0-productId => undefined
2021-01-25 19:09:13.617 INFO ZWAVE: Node 25: value added 25-128-0-level => undefined
2021-01-25 19:09:13.620 INFO ZWAVE: Node 25: value added 25-128-0-isLow => undefined
2021-01-25 19:09:13.623 INFO ZWAVE: Node 25: value added 25-132-0-wakeUpInterval => 43200
2021-01-25 19:09:13.626 INFO ZWAVE: Node 25: value added 25-132-0-controllerNodeId => undefined
2021-01-25 19:09:13.652 INFO ZWAVE: Node 25 ready: Unknown manufacturer undefined - Unknown product undefined (Unknown)
2021-01-25 19:09:13.653 INFO ZWAVE: Node 25: interview completed, all values are updated
2021-01-25 20:32:50.297 INFO ZWAVE: Node 150 ready: Unknown manufacturer undefined - Unknown product undefined (Unknown)
2021-01-25 20:33:43.034 INFO ZWAVE: Node 150 ready: Unknown manufacturer undefined - Unknown product undefined (Unknown)
2021-01-25 20:34:47.740 ERROR ZWAVE: Interview of node 150 has failed: Attempt 1/5 failed
2021-01-25 21:20:29.828 INFO ZWAVE: Node 150 ready: Unknown manufacturer undefined - Unknown product undefined (Unknown)
2021-01-25 21:48:26.261 INFO ZWAVE: Node 25 ready: Unknown manufacturer undefined - Unknown product undefined (Unknown)

Interesting is, that it seems that zwavejs2mqtt already got the correct manufacturer and product names but I don't remember to have seen them in the UI - otherwise I wouldn't have triggert a re-interview that often. One day later the device is not shown empty in the UI anymore but shows up as "Unknown manufacturer/device".

These are interesting log lines from zwave-js (from date 2021-01-25 - btw. can we output the date in the zwave-js logs too?) where a re-interview of node 150 has been triggered:

18:08:27.863 CNTRLR « [Node 150] received response for manufacturer information:
                        manufacturer: Shenzhen Neo Electronics Co., Ltd. (0x0258)
                        product type: 0x03
                        product id:   0x1082
18:08:27.863 CNTRLR   [Node 150] [+] [Manufacturer Specific] interviewComple [Endpoint 0] [internal]
                      te: true
...
19:07:37.194 CNTRLR « [Node 025] received response for manufacturer information:
                        manufacturer: Shenzhen Neo Electronics Co., Ltd. (0x0258)
                        product type: 0x03
                        product id:   0x1082
19:07:37.195 CNTRLR   [Node 025] [+] [Manufacturer Specific] interviewComple [Endpoint 0] [internal]
                      te: true
...
19:07:38.796 CNTRLR « [Node 025] received response for manufacturer information:
...
20:32:35.216 CNTRLR « [Node 150] received response for manufacturer information:
...
20:32:35.480 CNTRLR « [Node 150] received response for manufacturer information:
...
20:33:34.234 CNTRLR « [Node 150] received response for manufacturer information:
...
21:20:25.652 CNTRLR « [Node 150] received response for manufacturer information:

A related question:
What happens, if a device reports data (e.g. door opened/closed) while it has not yet been successfully interviewed?
I have the suspicion that this may trigger a race condition, but I have not been able to track this down.
Hopefully the logs and config files give enough information to find out what's going on.

To Reproduce

Steps to reproduce the behavior:

1. Make sure there are no files in the store directory
2. Start zwavejs2mqtt
3. Wait hours until there are empty devices left, that could not yet interviewed
4. Trigger a re-interview of the remaining ones and waking them up (e.g. press button 3x on Door/Window sensor)
5. Wait a few minutes
6. Repeat for devices that could not be interviewed correctly
7. Eventually some devices end up as being detected as "Unknown manufacturer/product" which are stuck in the ProtocolInfo stage

Expected behavior

zwavejs2mqtt should be able to recover from an "Unknown" device state as soon as zwave-js is able to correctly detect the device.

Additional context

This issue has already been reported as part of #233 where fixes have been committed which did not reproduce the problem until now why I'm opening a new issue with new information.

[ahochsteger]

@robertsLando I guess the event recorder + fake driver we talked about would be an easy way to analyze this issue :-).

[robertsLando]

@AlCalzone any clue? Could it be that the ready eventi is still triggered without the deviceConfig loaded ?

[robertsLando]

@ahochsteger do you have a full log? Of both

[ahochsteger]

@robertsLando both logs are in files.zip (see also link in the description).

[ahochsteger]

FYI: @robertsLando, @AlCalzone
I restarted zwavejs2mqtt yesterday at '22:44' since I had some troubles that re-inclusion did not work either which caused the unknown devices to show up as "empty" and trying to re-interview some of them again which worked for most.
The problematic node 150 from the logs in the description has then been re-included as node 165 which worked then.

I still had two more nodes (25 and 36) this morning that have not yet been successfully discovered which I just re-interviewed again a few times resulting in both showing up as "unknown".
The new logfiles can be found here: files-25-36.zip

Again I can see the pattern, that zwave-js is eventually able to discover the node with the correct manufacturer name:

# Re-inclusion of problematic node 150 as node 165 worked:
23:07:59.319 CNTRLR « [Node 165] received response for manufacturer information:
...
# Re-interview of not yet successfully discovered node 149 worked:
07:13:19.628 CNTRLR « [Node 149] received response for manufacturer information:
...
# Re-interview of not yet successfully discovered node 25 worked in zwave-js but shows as "unknown" in zwavejs2mqtt:
07:39:33.208 CNTRLR « [Node 025] received response for manufacturer information:
...
# 2x Re-interview of not yet successfully discovered node 36 worked in zwave-js but shows as "unknown" in zwavejs2mqtt:
07:40:15.413 CNTRLR « [Node 036] received response for manufacturer information:
07:40:54.130 CNTRLR « [Node 036] received response for manufacturer information:

[AlCalzone]

Could it be that the ready eventi is still triggered without the deviceConfig loaded ?

Should be easy to find in the log.

[AlCalzone]

Okay it is not that easy. There are like 10 interviews of Node 25 going on, some in parallel, some are started after the node was successfully interviewed and marked ready.

@ahochsteger you're likely to have some better luck not restarting the interviews all the time. Wake up the battery powered nodes manually, even multiple times in a row if necessary. My guess is that part of the chaos you're seeing is caused by multiple concurrent interviews - which should not happen, but https://github.com/zwave-js/node-zwave-js/issues/903 and https://github.com/zwave-js/node-zwave-js/issues/900 exist for a reason.

[robertsLando]

07:39:30.973 CNTRLR   [Node 025] Interview completed
07:39:31.882 CNTRLR   [Node 025] The node is ready to be used
07:39:31.909 SERIAL » 0x010900131902720425eb46                                            (11 bytes)
07:39:31.912 DRIVER » [Node 025] [REQ] [SendData]
                      │ transmit options: 0x25
                      │ callback id:      235
                      └─[ManufacturerSpecificCCGet]

.....

07:39:33.039 DRIVER » [Node 025] [REQ] [SendData]
                      │ transmit options: 0x25
                      │ callback id:      235
                      └─[ManufacturerSpecificCCGet]
07:39:33.042 SERIAL « [ACK]                                                                   (0x06)
07:39:33.048 SERIAL « 0x0104011301e8                                                       (6 bytes)
07:39:33.048 SERIAL » [ACK]                                                                   (0x06)
07:39:33.050 DRIVER « [RES] [SendData]
                        was sent: true
07:39:33.098 SERIAL « 0x01050013eb0002                                                     (7 bytes)
07:39:33.099 SERIAL » [ACK]                                                                   (0x06)
07:39:33.100 DRIVER « [REQ] [SendData]
                        callback id:     235
                        transmit status: OK
07:39:33.174 SERIAL « 0x011000040019087205025800031082cf0089                              (18 bytes)
07:39:33.177 CNTRLR   [Node 025] [+] [Manufacturer Specific] manufacturerId: 600        [Endpoint 0]
07:39:33.184 CNTRLR   [Node 025] [+] [Manufacturer Specific] productType: 3             [Endpoint 0]
07:39:33.190 CNTRLR   [Node 025] [+] [Manufacturer Specific] productId: 4226            [Endpoint 0]
07:39:33.196 SERIAL » [ACK]                                                                   (0x06)
07:39:33.204 DRIVER « [Node 025] [REQ] [ApplicationCommand]
                      └─[ManufacturerSpecificCCReport]
                          manufacturer id: 0x0258
                          product type:    0x03
                          product id:      0x1082
07:39:33.208 CNTRLR « [Node 025] received response for manufacturer information:
                        manufacturer: Shenzhen Neo Electronics Co., Ltd. (0x0258)
                        product type: 0x03
                        product id:   0x1082
07:39:33.209 CNTRLR   [Node 025] [+] [Manufacturer Specific] interviewComple [Endpoint 0] [internal]
                      te: true
07:39:33.210 CNTRLR   [Node 025] trying to load device config
07:39:33.212 CNTRLR   [Node 025] no device config loaded
07:39:33.291 CNTRLR   [Node 025] VersionCC: doing a complete interview...
07:39:33.292 CNTRLR » [Node 025] querying node versions...
07:39:33.306 SERIAL » 0x010900131902861125eca0                                            (11 bytes)
07:39:33.307 DRIVER » [Node 025] [REQ] [SendData]
                      │ transmit options: 0x25
                      │ callback id:      236
                      └─[VersionCCGet]

And then

2021-01-26 07:39:31.840 INFO ZWAVE: Node 25: value added 25-132-0-controllerNodeId => 1
2021-01-26 07:39:31.843 INFO ZWAVE: Node 25: value added 25-134-0-libraryType => undefined
2021-01-26 07:39:31.846 INFO ZWAVE: Node 25: value added 25-134-0-protocolVersion => undefined
2021-01-26 07:39:31.848 INFO ZWAVE: Node 25: value added 25-134-0-firmwareVersions => undefined
2021-01-26 07:39:31.851 INFO ZWAVE: Node 25: value added 25-114-0-manufacturerId => undefined
2021-01-26 07:39:31.853 INFO ZWAVE: Node 25: value added 25-114-0-productType => undefined
2021-01-26 07:39:31.856 INFO ZWAVE: Node 25: value added 25-114-0-productId => undefined
2021-01-26 07:39:31.859 INFO ZWAVE: Node 25: value added 25-128-0-level => 95
2021-01-26 07:39:31.861 INFO ZWAVE: Node 25: value added 25-128-0-isLow => false
2021-01-26 07:39:31.881 INFO ZWAVE: Node 25 ready: Unknown manufacturer undefined - Unknown product undefined (Unknown)
2021-01-26 07:39:31.886 INFO ZWAVE: Node 25: interview completed, all values are updated

So to answer my own question yes seems that the manufacturer producttype and id are retrived after the node is ready

[ahochsteger]

@AlCalzone thanks for your feedback!
The problem I'm facing is that I have to do something if the devices still have not yet discovered after a full day and triggering a wakeup and/or re-interview does not provide any feedback (at least in the UI) if there is happening something or not. Not seeing any results and not knowing, when I can start the next re-interview may add more chaos to the problems - even though I see myself as a very patient person ;-).

@robertsLando maybe this is something we can improve in the UI to give the user more feedback about what's going on to take informed decisions about what to do in case of problems ...

[robertsLando]

There are like 10 interviews of Node 25 going on, some in parallel, some are started after the node was successfully interviewed and marked ready.

@AlCalzone How can this be possible? I mean shouldn't a new interview abort the running one?

@ahochsteger Do you have something in mind about how to help users? I mean there is the interview stage shown that should be enought

[ahochsteger]

@robertsLando concerning the undefined manufacturerId:
Even if zwavejs2mqtt gets undefined data, shouldn't it update it afterwards, when zwavejs reports the correct data at a later time?
See these logs:

2021-01-26 07:39:31.851 INFO ZWAVE: Node 25: value added 25-114-0-manufacturerId => undefined
2021-01-26 07:39:33.181 INFO ZWAVE: Node 25: value added 25-114-0-manufacturerId => 600
2021-01-26 07:40:53.898 INFO ZWAVE: Node 36: value added 36-114-0-manufacturerId => undefined
2021-01-26 07:40:54.103 INFO ZWAVE: Node 36: value added 36-114-0-manufacturerId => 600

[AlCalzone]

I mean shouldn't a new interview abort the running one?

Short answer: It should, but doesn't. I have several things I want/need to change here - so for the meantime the solution is: "don't" ;)

[ahochsteger]

@ahochsteger Do you have something in mind about how to help users? I mean there is the interview stage shown that should be enought

@robertsLando no, I don't have any specific in mind yet. To be honest I did not trust the interview stage very much since I've seen nodes with no information at all that were already in the stage "Complete" and nodes that have been in the ProtocolInfo or NodeInfo stage for hours or even days. :-/

[AlCalzone]

in the ProtocolInfo

That means no communication with the node yet

NodeInfo stage for hours

That takes up the heap of the interview - so that is not suprising for battery-powered devices. IMO the main UX problem is that you don't see any progress here.

[robertsLando]

IMO the main UX problem is that you don't see any progress here.

What should I show so?

[AlCalzone]

You can't. There's no information exposed you could use.

[ivdimitro]

IMO the main UX problem is that you don't see any progress here.

What should I show so?

Hi, I have a TriSensor which is battery powered sleeping device suffering from exactly the same issues.
The strange thing for me is that even if the interview is not complete if the correct sensors has been interviewed the status is being updated in HA. So the device is "semi" functional but not visible in the GUI.

A proposal - reuse the cache values before the interview is finished. I mean if the node has already been discovered and the supported classes have not changed and most likely the configuration either. So why not initialize the GUI and HA with the same values from the last successful interview? The status can be changed accordingly "interview in progress" or something. There is "end of interview" message so it is possible to know when the cache needs to be updated or the status to changed.

I understand that this is more of a workaround/hack but it can be made optional behaviour if you know your network and don't play with the setting often.

[AlCalzone]

reuse the cache values before the interview is finished

zwave-js does. Can't speak for zwavejs2mqtt, but AFAIK it listens for the node ready event. That happens pretty quick on subsequent startups.

Your problem likely is that the interview didn't ever complete, so the node isn't considered ready yet. This causes z2m not to display the manufacturer info.

[ivdimitro]

reuse the cache values before the interview is finished

zwave-js does. Can't speak for zwavejs2mqtt, but AFAIK it listens for the node ready event. That happens pretty quick on subsequent startups.

Your problem likely is that the interview didn't ever complete, so the node isn't considered ready yet. This causes z2m not to display the manufacturer info.

I was talking for zwaveJS2mqtt GUI. The observed behaviour is not only for the sleeping devices. After restart the devices go from "Complete" to "RestartFromCache" mode but parameters are being removed if the values are in state "undefined" as shown in the original ticket.
My idea was "if node value ==> undefined then read from cache when available" .

[AlCalzone]

@robertsLando why are they undefined anyways? They should be in the zwave-js cache unless they have never been read before.

[robertsLando]

They should be in the zwave-js cache unless they have never been read before.

That's a question I would ask to you, I sincerly dunno why this happens but the informations says that's undefined :man_shrugging:

[AlCalzone]

Again, can't tell without an interview that is not restarted all the time through user intervention.

[robertsLando]

@ahochsteger Could you give a try to https://github.com/zwave-js/zwavejs2mqtt/pull/376

[ahochsteger]

@robertsLando I can definitely confirm that this helps to fix the problem since I found a way to fully reproduce the problem on my test device using the following procedure:

• Remove all cache files
• Start server + gui
• Wait until all devices before the battery-powered devices have been initialized and show up
• Wait a bit longer (5-10s) to make sure that zwave-js is trying to interview the battery-powered device
• Select and trigger "Re-interview" and directly wakeup the device (3x button press)

This always leads to "Unknown manufacturer" without this PR.
This PR seems to show "Unknown manufacturer" as well for a very short time (1s) but replaces it later with the correct manufacturer and product name.

Well done! :-)

[AlCalzone]

This PR seems to show "Unknown manufacturer" as well for a very short time (1s)

Is that before or after the re-interview?

[ahochsteger]

As I see it the "unknonw manufacturer" is shown just after pressing the button on the door sensor 3x - so I would say it is after triggering the re-interview in the UI but before the re-interview is finished, but I have not analyzed the logs to confirm the exact times of the events.
A short time (seconds) later "unknown manufacturer" is then replaced by the real manufacturer name in the UI.

But I just found out an important difference which may have to do with the way I'm waking up the device:
If I wake up the device the correct way as I just read in the manual (just press the button once) the "unknown manufacturer" problem does not show up at all (even without this PR). Only if I press the button 3x (causing it to gon into inclusion mode - which seems to be an old habit, since I had more success by pressing it 3x in the past) does cause the "unknown" problem.

Waking it up just by 1x pressing the button is now working reliably (maybe due to other fixes in the past) so I won't have to do the 3x press anymore.
I guess this is important for you, @AlCalzone, since it may make a big difference for zwave-js if it goes into inclusion mode vs. just waking it up.

Here are the logs where this can be further analyzed, if it is of any help:

• zwavejs2mqtt.log
• zwavejs_1280703.log

[robertsLando]

@ahochsteger what a mess :laughing: BTW glad that this problem seems fixed now, I have added many different checks that should fix this in all cases, even with messy devices

[bachya]

@robertsLando FYI, I'm still experiencing this, specifically with two Schlage locks ("Allegion - BE469").

One of them, Node 16, shows correctly in the dashboard:

The other, Node 5, shows as unknown in the dashboard:

zwave-js version: 6.1.1
z2m version: 1.0.4

zwave-js log (silly-level): https://gist.github.com/bachya/a1db9b1caa45319e30dc124ae654c6c9#file-zwavejs_1-log
z2m log (silly-level): https://gist.github.com/bachya/a1db9b1caa45319e30dc124ae654c6c9#file-zwavejs2mqtt-log

Perhaps my z2m version doesn't contain this fix?

[AlCalzone]

@bachya

1. you have several interview of node 5 going on at once. I'm not sure why that happens since it shouldn't, but I've usually seen it when users are not patient enough and press the refreshInfo button too often.
2. Node 5 does simply not respond to the manufacturer info request, so we're not getting that information.

[bachya]

Thanks, @AlCalzone. I was probably impatient. 😂 I'm still able to interact with the node and its entities, so the fact that it doesn't return info isn't the end of the world.

[benquan]

I have something similar:

Zwave JS integration reads the device just fine. But the addon dashboard shows as Unknown Manufacturer:

Actually everything was working fine until all of a sudden I lost all devices. So I Zwave had to find all devices again, and the battery operated devices got left behind. When I managed to add them back again one of the got its full information (Aeon Minimote) but a door sensor got stouck with Unknown Modifier. Apart from the name, the device is working just fine as the integration sees it correctly.

[robertsLando]

Try yo manually wakeup your devices

[markrennie71]

Mine have started doing this again today.. They have been up and running for weeks with no issues

[AlCalzone]

Please post a driver log (level debug) of the startup.

[markrennie71]

Please post a driver log (level debug) of the startup.

zwavejs2mqtt.log

Here you go, thanks. I also have an issue with node 3, I don't have that node and I cannot delete it, it is always stuck on ProtocolInfo

[AlCalzone]

That's not a driver log. ==> https://zwave-js.github.io/zwavejs2mqtt/#/troubleshooting/bug_report?id=driver-logs

[markrennie71]

That's not a driver log. ==> https://zwave-js.github.io/zwavejs2mqtt/#/troubleshooting/bug_report?id=driver-logs

oops sorry
zwavejs_2021-06-07.log

[AlCalzone]

@markrennie71 The log claims the nodes are ready. Can you share your cache files fadb18a0.json and fadb18a0.values.jsonl?

As for node 3: you're looking for the "remove failed node" function in zwavejs2mqtt.

[markrennie71]

The nodes all work in home assistant but in zwavejs2mqtt they look like the attached. also here are the files you requested. PS the remove failed node doesn't work in this case. I guess I could reset the stick and start again, but that is a pain in the arse :)
store.zip

[AlCalzone]

here are the files you requested

The .values.jsonl got corrupted. You'll have to re-interview all devices.

PS the remove failed node doesn't work in this case

Why not? What's in the driver log then?

[markrennie71]

PS the remove failed node doesn't work in this case

Why not? What's in the driver log then?

when I try I get the following, even thought this is 100% not on my mesh

`Error while calling api removeFailedNode: The node removal process could not be started because the node responded to a ping.

[AlCalzone]

Please share a driver log where you try that.

[markrennie71]

edit, I tried about 10 times and nothing, then out of the blue it worked.. odd. Thanks for your help

[Walt750]

I lost power last night. My pi4 went down and after the power came back on .. the unknown devices appeared. This is not the first time. The last time I decided to do a zwave-js upgrade and perhaps this problem would remedy itself. That was totally wrong and I ended up loading 45 devices from scratch. I was not a happy camper. It took a lot of my time. This time I will leave it alone and see if it remedies itself. Shouldn't reloading the node-js file from backup fix this? This is very un-acceptable.