search

dresden-elektronik / deconz-rest-plugin

deCONZ REST-API plugin to control ZigBee devices
BSD 3-Clause "New" or "Revised" License
1.89k stars 496 forks source link

Model Id reported as hexadecimal and not string #6665

Closed BabaIsYou closed 1 year ago

BabaIsYou commented 1 year ago

Describe the bug

Fed up to have a thermostat with "sticky" 0xFF endpoints that always reappears I decided, (after upgrade to version 2.19.3 beta) to delete the device once again and rejoining it to have it cleared.

Surprisingly it identified itself not with a string as usual for "Model Identifier" in Basic cluster, but with haxadeciaml value ?!

i.e. instaed of model identifier SMT402AD i got litteraly 0x534d5434303241440000000000301800203944000803000000dd590008ffff and in Location description (in the same cluster), I got also a strange value image

Of course the dedicated DDF (SMT402ad.json) is not recognzied until I add 0x534d5434303241440000000000301800203944000803000000dd590008ffff as modelid. Then, once reloaded, the thermsotat is recognized and all seems to work ... and I didn't have 0xFF endpoints anymore ! ;-)

Steps to reproduce the behavior

I deleted the device several times and rejoined it with the same behavior. Even after doing a factory reset on the thermostat the behavior is the same.

Just to add that in the same time I added another thermostat from another brand and it has a "normal" behavior. Then I don't really know if it's a Deconz trouble or a device trouble (I only have one of this brand).

Expected behavior

To be recognized as a SMT402AD and not as 0x534d5434303241440000000000301800203944000803000000dd590008ffff

Screenshots

Environment

deCONZ Logs

Which kind of log could be useful to trace that ?

Additional context

As we can notice 0x534d543430324144 is the hexadecimal value for SMT402AD but don't know what the rest of the value stands for.

Smanar commented 1 year ago

So you mean the model id in deconz (on cluster 0x0000) was "SMT402AD" but on recent version "0x534d5434303241440000000000301800203944000803000000dd590008ffff" ?

BabaIsYou commented 1 year ago

Exactly, just for this device. I deleted it and repairing a couple of time with same behavior !

manup commented 1 year ago

Interesting, I'd propose we check the APS_L2 / ZCL logs when reading the modelid to see what the raw data contains. A while ago I've added some code to the ZclAttribute parser to let invalid strings be represented as hex string (was needed for another device) to have access to all the data in the string.

When you enter the hex representation 534d5434303241440000000000301800203944000803000000dd590008ffff in below site you see that the first part indeed contains "SMT402AD" and then comes some binary encoded stuff which can't be represented as string, the old code would just cut this part off at first 00 like a zero terminated C-string.

https://www.rapidtables.com/convert/number/hex-to-ascii.html

Not sure what's the best approach to tackle this, both ways have their pros and contras.

BabaIsYou commented 1 year ago

the first part indeed contains "SMT402AD"

Yes I already noticed it in the additional context while opening this issue ;-) We can notice too in the screenshot that the "location description" is also in hexadecimal (0x4d61657374726f537461740000881c, whose begining "means" MaestroSta that was the string value displayed before as I remember)

Update : here is the log. Device is f8:f0:05:ff:ff:70:7e:95

06:54:29:669 b0:ce:18:14:03:6b:d3:71-01-0b04/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.8
06:54:29:672 b0:ce:18:14:03:6b:d3:71-01-0702/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.8
06:54:29:782 50:0b:91:40:00:02:58:c7-01-0b04/state/current expression: if (Attr.val != 65535) { Item.val = Attr.val / 1000; } --> 1.879
06:54:29:783 50:0b:91:40:00:02:58:c7-01-0b04/state/power expression: if (Attr.val != -32768 && Attr.val != 32768) { Item.val = Attr.val; } --> 458
06:54:29:785 50:0b:91:40:00:02:58:c7-01-0702/state/power expression: if (Attr.val != -32768 && Attr.val != 32768) { Item.val = Attr.val; } --> 458
06:54:31:145 b0:ce:18:14:03:6b:d1:0e-01/state/on expression: Item.val = Attr.val --> false
06:54:31:210 b0:ce:18:14:03:6b:d3:71-01-0b04/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.2
06:54:31:214 b0:ce:18:14:03:6b:d3:71-01-0702/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.2
06:54:31:232 50:0b:91:40:00:02:c4:36-01-0702/state/consumption expression: Item.val = Attr.val --> 648642
06:54:31:240 00:15:8d:00:02:58:42:c4-01/state/ct expression: Item.val = Attr.val --> 65535
06:54:31:242 00:15:8d:00:02:58:42:c4-01/state/sat expression: Item.val = Attr.val --> 224
06:54:31:440 50:0b:91:40:00:02:c4:36-01-0201/config/heatsetpoint expression: Item.val = Attr.val; --> 2200
06:54:31:628 f8:f0:05:ff:ff:70:7e:95-19-0201/attr/modelid expression: Item.val = Attr.val --> 0x534d54343032414400000000000000000000000000cc1e00205f210008ffff
06:54:31:629 f8:f0:05:ff:ff:70:7e:95-19-0405/attr/modelid expression: Item.val = Attr.val --> 0x534d54343032414400000000000000000000000000cc1e00205f210008ffff
06:54:31:631 f8:f0:05:ff:ff:70:7e:95/attr/modelid expression: Item.val = Attr.val --> 0x534d54343032414400000000000000000000000000cc1e00205f210008ffff
06:54:31:665 f8:f0:05:ff:ff:70:7e:95-19-0201/attr/swversion expression: Item.val = Attr.val --> 20000000 00000
06:54:31:666 f8:f0:05:ff:ff:70:7e:95-19-0405/attr/swversion expression: Item.val = Attr.val --> 20000000 00000
06:54:32:737 b0:ce:18:14:03:6b:d3:71-01-0b04/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.8
06:54:32:740 b0:ce:18:14:03:6b:d3:71-01-0702/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.8
06:54:32:897 00:0d:6f:00:15:65:fd:b0-01-0b04/state/current expression: if (Attr.val != 65535) { Item.val = Attr.val / 100; } --> 0.44
06:54:33:512 00:22:a3:00:00:25:33:39-01/state/on expression: Item.val = Attr.val --> false
06:54:33:517 f8:f0:05:ff:ff:70:7e:95-19-0201/attr/manufacturername expression: Item.val = Attr.val --> Stelpro
06:54:33:518 f8:f0:05:ff:ff:70:7e:95-19-0405/attr/manufacturername expression: Item.val = Attr.val --> Stelpro
06:54:33:519 f8:f0:05:ff:ff:70:7e:95/attr/manufacturername expression: Item.val = Attr.val --> Stelpro
06:54:33:628 f8:f0:05:ff:ff:70:7e:95-19-0201/attr/modelid expression: Item.val = Attr.val --> 0x534d54343032414400000000000000000000000000cc1e00205f210008ffff
06:54:33:629 f8:f0:05:ff:ff:70:7e:95-19-0405/attr/modelid expression: Item.val = Attr.val --> 0x534d54343032414400000000000000000000000000cc1e00205f210008ffff
06:54:33:631 f8:f0:05:ff:ff:70:7e:95/attr/modelid expression: Item.val = Attr.val --> 0x534d54343032414400000000000000000000000000cc1e00205f210008ffff
06:54:33:649 f8:f0:05:ff:ff:70:7e:95-19-0201/attr/swversion expression: Item.val = Attr.val --> 20000000 00000
06:54:33:652 f8:f0:05:ff:ff:70:7e:95-19-0405/attr/swversion expression: Item.val = Attr.val --> 20000000 00000
06:54:33:828 50:0b:91:40:00:02:58:c7-01-0201/config/heatsetpoint expression: Item.val = Attr.val; --> 1800
06:54:34:042 50:0b:91:40:00:02:c4:36-01-0702/state/consumption expression: Item.val = Attr.val --> 648643
06:54:34:056 00:15:8d:00:02:5c:9b:ff-01/state/ct expression: Item.val = Attr.val --> 370
06:54:34:057 00:15:8d:00:02:5c:9b:ff-01/state/sat expression: Item.val = Attr.val --> 254
06:54:34:084 b0:ce:18:14:03:6b:d3:71-01-0b04/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.2
06:54:34:086 b0:ce:18:14:03:6b:d3:71-01-0702/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.2
06:54:34:134 50:0b:91:40:00:02:ca:1c-01-0201/config/heatsetpoint expression: Item.val = Attr.val; --> 2200
06:54:34:438 00:0d:6f:00:15:65:fd:b0-01-0b04/state/current expression: if (Attr.val != 65535) { Item.val = Attr.val / 100; } --> 0.44
06:54:34:901 f8:f0:05:ff:ff:70:7e:95-19-0201/config/heatsetpoint expression: Item.val = Attr.val; --> 2150
06:54:35:103 00:22:a3:00:00:25:33:39-01-0702/state/power expression: if (Attr.val != -32768 && Attr.val != 32768) { Item.val = Attr.val / 10; } --> 0
06:54:35:107 50:0b:91:40:00:02:ca:1c-01-0702/state/consumption expression: Item.val = Attr.val --> 1808719
06:54:35:167 b0:ce:18:14:03:6b:d3:71-01-0b04/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.8
06:54:35:171 b0:ce:18:14:03:6b:d3:71-01-0702/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.8
06:54:35:508 70:ac:08:ff:fe:69:80:b9-01-ef00/attr/swversion expression: var v = Attr.val;
Item.val = String((v & 192) >> 6) + '.' + String((v & 48) >> 4) + '.' + String(v & 15);
 --> 1.0.6
06:54:35:510 70:ac:08:ff:fe:69:80:b9-01-0400/attr/swversion expression: var v = Attr.val;
Item.val = String((v & 192) >> 6) + '.' + String((v & 48) >> 4) + '.' + String(v & 15);
 --> 1.0.6
06:54:37:026 50:0b:91:40:00:02:c4:36-01-0702/state/consumption expression: Item.val = Attr.val --> 648644
06:54:37:080 50:0b:91:40:00:02:ca:1c-01-0702/state/consumption expression: Item.val = Attr.val --> 1808720
06:54:37:358 b0:ce:18:14:03:6b:d3:71-01-0b04/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.2
06:54:37:360 b0:ce:18:14:03:6b:d3:71-01-0702/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.2
06:54:38:471 b0:ce:18:14:03:6b:d3:71-01-0b04/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.8
06:54:38:473 b0:ce:18:14:03:6b:d3:71-01-0702/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.8
06:54:39:082 50:0b:91:40:00:02:ca:1c-01-0702/state/consumption expression: Item.val = Attr.val --> 1808721
06:54:39:569 b0:ce:18:14:03:6b:d3:71-01-0b04/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.2
06:54:39:572 b0:ce:18:14:03:6b:d3:71-01-0702/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.2
06:54:40:025 50:0b:91:40:00:02:c4:36-01-0702/state/consumption expression: Item.val = Attr.val --> 648645
06:54:40:090 50:0b:91:40:00:02:ca:1c-01-0702/state/consumption expression: Item.val = Attr.val --> 1808722
06:54:40:175 f8:f0:05:ff:ff:70:7e:95-19-0201/attr/modelid expression: Item.val = Attr.val --> 0x534d54343032414400000000000000000000000000cc1e00205f210008ffff
06:54:40:176 f8:f0:05:ff:ff:70:7e:95-19-0405/attr/modelid expression: Item.val = Attr.val --> 0x534d54343032414400000000000000000000000000cc1e00205f210008ffff
06:54:40:178 f8:f0:05:ff:ff:70:7e:95/attr/modelid expression: Item.val = Attr.val --> 0x534d54343032414400000000000000000000000000cc1e00205f210008ffff
06:54:40:671 b0:ce:18:14:03:6b:d3:71-01-0b04/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.8
06:54:40:672 b0:ce:18:14:03:6b:d3:71-01-0702/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.8
06:54:41:162 00:15:8d:00:02:5c:9b:ff-01/state/hue expression: Item.val = Attr.val --> 44490
06:54:41:169 Delay APS request id: 244 to 0x6870, profile: 0x0104 cluster: 0x0300 node already has busy 2
06:54:41:171 Delay APS request id: 244 to 0x6870, profile: 0x0104 cluster: 0x0300 node already has busy 2
06:54:41:190 Delay APS request id: 244 to 0x6870, profile: 0x0104 cluster: 0x0300 node already has busy 2
06:54:41:197 Delay APS request id: 244 to 0x6870, profile: 0x0104 cluster: 0x0300 node already has busy 2
06:54:41:285 00:15:8d:00:02:5c:9b:ff-01/state/on expression: Item.val = Attr.val --> false
06:54:41:937 08:6b:d7:ff:fe:5b:86:88-01/state/on expression: Item.val = Attr.val --> true
06:54:42:099 50:0b:91:40:00:02:ca:1c-01-0702/state/consumption expression: Item.val = Attr.val --> 1808723
06:54:42:117 f8:f0:05:ff:ff:70:7e:95-19-0201/attr/modelid expression: Item.val = Attr.val --> 0x534d54343032414400000000000000000000000000cc1e00205f210008ffff
06:54:42:119 f8:f0:05:ff:ff:70:7e:95-19-0405/attr/modelid expression: Item.val = Attr.val --> 0x534d54343032414400000000000000000000000000cc1e00205f210008ffff
06:54:42:121 f8:f0:05:ff:ff:70:7e:95/attr/modelid expression: Item.val = Attr.val --> 0x534d54343032414400000000000000000000000000cc1e00205f210008ffff
06:54:42:905 b0:ce:18:14:03:6b:d3:71-01-0b04/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.2
06:54:42:906 b0:ce:18:14:03:6b:d3:71-01-0702/state/power expression: if (Attr.val != -32768) { Item.val = Attr.val / 10; } --> 5.2
06:54:43:139 50:0b:91:40:00:01:cb:9b-01-0201/config/heatsetpoint expression: Item.val = Attr.val; --> 2150

Second update : I didn't select the right choice in log. Here is another one. Device is 0x5ef2

07:06:37:099 ZCL read attr 0x086BD7FFFE5B8688, ep: 0x01, cl: 0x0006, attr: 0x0000, mfcode: 0x0000, aps.id: 17, zcl.seq: 180 07:06:37:200 ZCL got data for node=0x749F, cl=0x0006, at=0x0000, status=0x00, type=0x10 07:06:37:856 ZCL read attr 0x500B91400001CB9B, ep: 0x01, cl: 0x0201, attr: 0x0012, mfcode: 0x0000, aps.id: 28, zcl.seq: 181 07:06:37:938 ZCL got data for node=0x964D, cl=0x0201, at=0x0012, status=0x00, type=0x29 07:06:37:941 ZCL read attr 0x500B91400001CB9B, ep: 0x01, cl: 0x0201, attr: 0x0025, mfcode: 0x0000, aps.id: 32, zcl.seq: 182 07:06:37:963 ZCL read report config, ep: 0x01, cl: 0x0204, mfcode: 0x0000, aps.id: 34, zcl.seq: 183 07:06:38:028 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:38:029 ZCL got data for node=0x964D, cl=0x0201, at=0x0025, status=0x86, type=0x00 07:06:38:030 ZCL read attr 0x500B91400001CB9B, ep: 0x01, cl: 0x0006, attr: 0x0000, mfcode: 0x0000, aps.id: 36, zcl.seq: 184 07:06:38:044 ZCL configure reporting ep: 0x01, cl: 0x0204, mfcode: 0x0000, aps.id: 38, zcl.seq: 185 07:06:38:116 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:38:117 ZCL got data for node=0x964D, cl=0x0006, at=0x0000, status=0x86, type=0x00 07:06:38:856 ZCL read attr 0x500B91400002CA1C, ep: 0x01, cl: 0x0201, attr: 0x0012, mfcode: 0x0000, aps.id: 46, zcl.seq: 186 07:06:38:928 ZCL got data for node=0x9BE9, cl=0x0201, at=0x0012, status=0x00, type=0x29 07:06:38:930 ZCL read attr 0x500B91400002CA1C, ep: 0x01, cl: 0x0201, attr: 0x0025, mfcode: 0x0000, aps.id: 49, zcl.seq: 187 07:06:39:014 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:39:015 ZCL got data for node=0x9BE9, cl=0x0201, at=0x0025, status=0x86, type=0x00 07:06:39:017 ZCL read attr 0x500B91400002CA1C, ep: 0x01, cl: 0x0006, attr: 0x0000, mfcode: 0x0000, aps.id: 53, zcl.seq: 188 07:06:39:072 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:39:073 ZCL got data for node=0x9BE9, cl=0x0006, at=0x0000, status=0x86, type=0x00 07:06:39:105 ZCL read report config, ep: 0x01, cl: 0x0B04, mfcode: 0x0000, aps.id: 58, zcl.seq: 189 07:06:39:174 ZCL configure reporting ep: 0x01, cl: 0x0B04, mfcode: 0x0000, aps.id: 62, zcl.seq: 190 07:06:40:855 ZCL read attr 0xB0CE1814036BCF99, ep: 0x01, cl: 0x0000, attr: 0x4000, mfcode: 0x0000, aps.id: 75, zcl.seq: 191 07:06:40:934 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:40:935 ZCL got data for node=0x9FD3, cl=0x0000, at=0x4000, status=0x86, type=0x00 07:06:40:937 ZCL read attr 0xB0CE1814036BCF99, ep: 0x01, cl: 0x0006, attr: 0x0000, mfcode: 0x0000, aps.id: 77, zcl.seq: 192 07:06:40:981 ZCL got data for node=0x9FD3, cl=0x0006, at=0x0000, status=0x00, type=0x10 07:06:40:983 ZCL read attr 0xB0CE1814036BCF99, ep: 0x01, cl: 0x0000, attr: 0x4000, mfcode: 0x0000, aps.id: 80, zcl.seq: 193 07:06:41:042 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:41:043 ZCL got data for node=0x9FD3, cl=0x0000, at=0x4000, status=0x86, type=0x00 07:06:41:046 ZCL read attr 0xB0CE1814036BCF99, ep: 0x01, cl: 0x0000, attr: 0x4000, mfcode: 0x0000, aps.id: 83, zcl.seq: 194 07:06:41:097 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:41:098 ZCL got data for node=0x9FD3, cl=0x0000, at=0x4000, status=0x86, type=0x00 07:06:41:335 ZCL read cluster: 0x0000, attribute: 0x0000 07:06:41:336 ZCL read cluster: 0x0000, attribute: 0x0001 07:06:41:337 ZCL read cluster: 0x0000, attribute: 0x0002 07:06:41:338 ZCL read cluster: 0x0000, attribute: 0x0003 07:06:41:338 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:41:370 ZCL read cluster: 0x0000, attribute: 0x0004 07:06:41:372 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:41:395 ZCL read cluster: 0x0000, attribute: 0x0005 07:06:41:397 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:41:427 ZCL read cluster: 0x0000, attribute: 0x0006 07:06:41:428 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:41:441 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0000, status=0x00, type=0x20 07:06:41:443 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0001, status=0x00, type=0x20 07:06:41:445 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0002, status=0x00, type=0x20 07:06:41:446 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0003, status=0x00, type=0x20 07:06:41:487 ZCL read cluster: 0x0000, attribute: 0x0007 07:06:41:488 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:42:955 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0004, status=0x00, type=0x42 07:06:43:001 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0005, status=0x00, type=0x42 07:06:43:043 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0006, status=0x00, type=0x42 07:06:43:079 ZCL read cluster: 0x0000, attribute: 0xFFFD 07:06:43:080 ZCL read cluster: 0x0000, attribute: 0x0010 07:06:43:081 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:43:097 ZCL read cluster: 0x0000, attribute: 0x0011 07:06:43:100 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:43:116 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0007, status=0x00, type=0x30 07:06:43:164 ZCL got data for node=0x5EF2, cl=0x0000, at=0xFFFD, status=0x00, type=0x21 07:06:43:165 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0010, status=0x00, type=0x42 07:06:43:205 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0011, status=0x00, type=0x30 07:06:43:289 ZCL read cluster: 0x0000, attribute: 0x0000 07:06:43:290 ZCL read cluster: 0x0000, attribute: 0x0001 07:06:43:291 ZCL read cluster: 0x0000, attribute: 0x0002 07:06:43:291 ZCL read cluster: 0x0000, attribute: 0x0003 07:06:43:292 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:43:309 ZCL read cluster: 0x0000, attribute: 0x0004 07:06:43:310 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:43:332 ZCL read cluster: 0x0000, attribute: 0x0005 07:06:43:335 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:43:374 ZCL read cluster: 0x0000, attribute: 0x0006 07:06:43:375 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:43:385 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0000, status=0x00, type=0x20 07:06:43:387 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0001, status=0x00, type=0x20 07:06:43:388 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0002, status=0x00, type=0x20 07:06:43:389 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0003, status=0x00, type=0x20 07:06:43:424 ZCL read cluster: 0x0000, attribute: 0x0007 07:06:43:425 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:43:435 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0004, status=0x00, type=0x42 07:06:43:479 ZCL read cluster: 0x0000, attribute: 0xFFFD 07:06:43:480 ZCL read cluster: 0x0000, attribute: 0x0010 07:06:43:480 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:43:532 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0005, status=0x00, type=0x42 07:06:43:560 ZCL read cluster: 0x0000, attribute: 0x0011 07:06:43:562 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:43:572 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0006, status=0x00, type=0x42 07:06:43:601 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0007, status=0x00, type=0x30 07:06:43:727 ZCL got data for node=0x5EF2, cl=0x0000, at=0xFFFD, status=0x00, type=0x21 07:06:43:728 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0010, status=0x00, type=0x42 07:06:43:771 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0011, status=0x00, type=0x30 07:06:43:872 ZCL read attr 0xB0CE1814036BD371, ep: 0x01, cl: 0x0000, attr: 0x4000, mfcode: 0x0000, aps.id: 127, zcl.seq: 195 07:06:43:932 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:43:933 ZCL got data for node=0xBE7B, cl=0x0000, at=0x4000, status=0x86, type=0x00 07:06:43:934 ZCL read attr 0xB0CE1814036BD371, ep: 0x01, cl: 0x0006, attr: 0x0000, mfcode: 0x0000, aps.id: 130, zcl.seq: 196 07:06:43:982 ZCL got data for node=0xBE7B, cl=0x0006, at=0x0000, status=0x00, type=0x10 07:06:43:984 ZCL read attr 0xB0CE1814036BD371, ep: 0x01, cl: 0x0000, attr: 0x4000, mfcode: 0x0000, aps.id: 133, zcl.seq: 197 07:06:44:054 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:44:055 ZCL got data for node=0xBE7B, cl=0x0000, at=0x4000, status=0x86, type=0x00 07:06:44:056 ZCL read attr 0xB0CE1814036BD371, ep: 0x01, cl: 0x0000, attr: 0x4000, mfcode: 0x0000, aps.id: 136, zcl.seq: 198 07:06:45:127 ZCL read cluster: 0x0000, attribute: 0x0000 07:06:45:129 ZCL read cluster: 0x0000, attribute: 0x0001 07:06:45:131 ZCL read cluster: 0x0000, attribute: 0x0002 07:06:45:133 ZCL read cluster: 0x0000, attribute: 0x0003 07:06:45:135 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:45:186 ZCL read attr 0x000D6F001565FDB0, ep: 0x01, cl: 0x0006, attr: 0x0000, mfcode: 0x0000, aps.id: 140, zcl.seq: 199 07:06:45:191 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:45:193 ZCL got data for node=0xBE7B, cl=0x0000, at=0x4000, status=0x86, type=0x00 07:06:45:268 ZCL read cluster: 0x0000, attribute: 0x0004 07:06:45:269 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:45:319 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0000, status=0x00, type=0x20 07:06:45:320 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0001, status=0x00, type=0x20 07:06:45:321 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0002, status=0x00, type=0x20 07:06:45:321 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0003, status=0x00, type=0x20 07:06:45:353 ZCL read cluster: 0x0000, attribute: 0x0005 07:06:45:355 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:45:381 ZCL read cluster: 0x0000, attribute: 0x0006 07:06:45:382 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:45:424 ZCL read cluster: 0x0000, attribute: 0x0007 07:06:45:425 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:45:436 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0004, status=0x00, type=0x42 07:06:45:466 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0005, status=0x00, type=0x42 07:06:45:503 ZCL read cluster: 0x0000, attribute: 0xFFFD 07:06:45:505 ZCL read cluster: 0x0000, attribute: 0x0010 07:06:45:506 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:45:523 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0006, status=0x00, type=0x42 07:06:45:556 ZCL read cluster: 0x0000, attribute: 0x0011 07:06:45:558 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:45:613 ZCL got data for node=0x5EF2, cl=0x0000, at=0xFFFD, status=0x00, type=0x21 07:06:45:614 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0010, status=0x00, type=0x42 07:06:45:656 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0007, status=0x00, type=0x30 07:06:45:692 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0011, status=0x00, type=0x30 07:06:46:171 ZCL read attr 0x00158D00025842C4, ep: 0x01, cl: 0x0300, attr: 0x0008, mfcode: 0x0000, aps.id: 165, zcl.seq: 200 07:06:46:476 ZCL got data for node=0xD0CF, cl=0x0300, at=0x0008, status=0x00, type=0x30 07:06:46:479 ZCL read attr 0x00158D00025842C4, ep: 0x01, cl: 0x0300, attr: 0x4000, mfcode: 0x0000, aps.id: 171, zcl.seq: 201 07:06:46:593 ZCL read report config, ep: 0x01, cl: 0x0008, mfcode: 0x0000, aps.id: 174, zcl.seq: 202 07:06:46:595 Delay APS request id: 174 to 0xD0CF, profile: 0x0104 cluster: 0x0008 node already has busy 2 07:06:48:091 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:48:127 ZCL read attr 0x000D6F001565FDB0, ep: 0x01, cl: 0x0006, attr: 0x0000, mfcode: 0x0000, aps.id: 177, zcl.seq: 203 07:06:48:130 ZCL got data for node=0xD0CF, cl=0x0300, at=0x4000, status=0x00, type=0x21 07:06:48:132 ZCL read attr 0x00158D00025842C4, ep: 0x01, cl: 0x0006, attr: 0x0000, mfcode: 0x0000, aps.id: 179, zcl.seq: 204 07:06:48:156 ZCL read report config, ep: 0x01, cl: 0x0300, mfcode: 0x0000, aps.id: 182, zcl.seq: 205 07:06:48:161 Delay APS request id: 182 to 0xD0CF, profile: 0x0104 cluster: 0x0300 node already has busy 2 07:06:48:163 Delay APS request id: 182 to 0xD0CF, profile: 0x0104 cluster: 0x0300 node already has busy 2 07:06:48:181 ZCL got data for node=0xC6F3, cl=0x0006, at=0x0000, status=0x00, type=0x10 07:06:48:206 Delay APS request id: 182 to 0xD0CF, profile: 0x0104 cluster: 0x0300 node already has busy 3 07:06:48:218 Delay APS request id: 182 to 0xD0CF, profile: 0x0104 cluster: 0x0300 node already has busy 3 07:06:48:236 Delay APS request id: 182 to 0xD0CF, profile: 0x0104 cluster: 0x0300 node already has busy 3 07:06:48:259 Delay APS request id: 182 to 0xD0CF, profile: 0x0104 cluster: 0x0300 node already has busy 3 07:06:48:265 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0005, status=0x00, type=0x42 07:06:48:310 Delay APS request id: 182 to 0xD0CF, profile: 0x0104 cluster: 0x0300 node already has busy 3 07:06:48:321 Delay APS request id: 182 to 0xD0CF, profile: 0x0104 cluster: 0x0300 node already has busy 2 07:06:48:333 ZCL got data for node=0xD0CF, cl=0x0006, at=0x0000, status=0x00, type=0x10 07:06:48:434 ZCL configure reporting ep: 0x01, cl: 0x0300, mfcode: 0x0000, aps.id: 189, zcl.seq: 206 07:06:49:035 ZCL read attr 0xB0CE1814036BD7D0, ep: 0x01, cl: 0x0000, attr: 0x4000, mfcode: 0x0000, aps.id: 197, zcl.seq: 207 07:06:49:089 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:49:090 ZCL got data for node=0xDBC9, cl=0x0000, at=0x4000, status=0x86, type=0x00 07:06:49:091 ZCL read attr 0xB0CE1814036BD7D0, ep: 0x01, cl: 0x0006, attr: 0x0000, mfcode: 0x0000, aps.id: 199, zcl.seq: 208 07:06:49:153 ZCL got data for node=0xDBC9, cl=0x0006, at=0x0000, status=0x00, type=0x10 07:06:49:155 ZCL read attr 0xB0CE1814036BD7D0, ep: 0x01, cl: 0x0000, attr: 0x4000, mfcode: 0x0000, aps.id: 203, zcl.seq: 209 07:06:50:646 ZCL cmd-req nwk: 0x5EF2, profile: 0x0104, cluster: 0x0000 cmd: 0x00 07:06:50:669 ZCL read attr 0x000D6F001565FDB0, ep: 0x01, cl: 0x0006, attr: 0x0000, mfcode: 0x0000, aps.id: 208, zcl.seq: 210 07:06:50:672 ZCL read attr 0xB0CE1814036BD10E, ep: 0x01, cl: 0x0000, attr: 0x4000, mfcode: 0x0000, aps.id: 209, zcl.seq: 211 07:06:50:698 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:50:702 ZCL got data for node=0xDBC9, cl=0x0000, at=0x4000, status=0x86, type=0x00 07:06:50:705 ZCL read attr 0xB0CE1814036BD7D0, ep: 0x01, cl: 0x0000, attr: 0x4000, mfcode: 0x0000, aps.id: 212, zcl.seq: 212 07:06:50:845 ZCL got data for node=0x5EF2, cl=0x0000, at=0x0005, status=0x00, type=0x42 07:06:50:889 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:50:892 ZCL got data for node=0xDBC9, cl=0x0000, at=0x4000, status=0x86, type=0x00 07:06:50:904 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:50:908 ZCL got data for node=0xE4F9, cl=0x0000, at=0x4000, status=0x86, type=0x00 07:06:50:910 ZCL read attr 0xB0CE1814036BD10E, ep: 0x01, cl: 0x0006, attr: 0x0000, mfcode: 0x0000, aps.id: 220, zcl.seq: 213 07:06:50:977 ZCL got data for node=0xE4F9, cl=0x0006, at=0x0000, status=0x00, type=0x10 07:06:50:979 ZCL read attr 0xB0CE1814036BD10E, ep: 0x01, cl: 0x0000, attr: 0x4000, mfcode: 0x0000, aps.id: 223, zcl.seq: 214 07:06:51:062 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:51:063 ZCL got data for node=0xE4F9, cl=0x0000, at=0x4000, status=0x86, type=0x00 07:06:51:064 ZCL read attr 0xB0CE1814036BD10E, ep: 0x01, cl: 0x0000, attr: 0x4000, mfcode: 0x0000, aps.id: 226, zcl.seq: 215 07:06:51:335 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:51:336 ZCL got data for node=0xE4F9, cl=0x0000, at=0x4000, status=0x86, type=0x00 07:06:51:690 ZCL read attr 0x500B91400002C436, ep: 0x01, cl: 0x0201, attr: 0x0012, mfcode: 0x0000, aps.id: 238, zcl.seq: 217 07:06:51:764 ZCL got data for node=0x9239, cl=0x0201, at=0x0012, status=0x00, type=0x29 07:06:51:767 ZCL read attr 0x500B91400002C436, ep: 0x01, cl: 0x0201, attr: 0x0025, mfcode: 0x0000, aps.id: 241, zcl.seq: 218 07:06:51:897 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:51:898 ZCL got data for node=0x9239, cl=0x0201, at=0x0025, status=0x86, type=0x00 07:06:51:899 ZCL read attr 0x500B91400002C436, ep: 0x01, cl: 0x0006, attr: 0x0000, mfcode: 0x0000, aps.id: 246, zcl.seq: 219 07:06:51:967 ZCL got unsupported status: 0x86 for mandatory attribute 07:06:51:968 ZCL got data for node=0x9239, cl=0x0006, at=0x0000, status=0x86, type=0x00 07:06:51:978 ZCL read report config, ep: 0x01, cl: 0x0B04, mfcode: 0x0000, aps.id: 251, zcl.seq: 220 07:06:52:030 ZCL configure reporting ep: 0x01, cl: 0x0B04, mfcode: 0x0000, aps.id: 253, zcl.seq: 221 07:06:52:330 ZCL got data for node=0xC6F3, cl=0x0006, at=0x0000, status=0x00, type=0x10 07:06:52:332 ZCL read attr 0x000D6F001565FDB0, ep: 0x01, cl: 0x0B04, attr: 0x050B, mfcode: 0x0000, aps.id: 4, zcl.seq: 222

BabaIsYou commented 1 year ago

Grrr !!! After some Deconz restarts to test new DDFs, then 0XFF endpoints are back again ... with the hexadecimal Model ID but the deleted old device names and cluster (0x0402) that did not exist anymore in the actual DDF ... Completely crazy.

Think that sometimes DeConz relaod some configuration from kind of "cache" or "backup" database and mix it with current i"nfrastructure" image

Smanar commented 1 year ago

Strange, long time I haven't see this issue on recent version.

After some Deconz restarts

Just restart ? If I m right deconz don't create new entries if the permit join is not enabled ? And with old deleted devices .... But the date/time on the right is the last seen, and it's the today date.

BTW capture is from domoticz, same on the API ?

BabaIsYou commented 1 year ago

To be honest, yesterday I tried a lot of things, adding a new aquara light sensor (then permit join) that didn't work on first try, trying some DDF modifications on another presence sensor device already joinded (then some retsart of DeConz too). At which time these old EP where coming back, I don't really trace that, I discovered them this morning via Domoticz plugin interface. ANd they exist also in API of course.

{
    "config": {
        "offset": 0,
        "on": true,
        "reachable": true
    },
    "etag": "b5568cb4c2f4d6d25fd7f5d51968c0a4",
    "lastannounced": null,
    "lastseen": "2023-01-17T19:37Z",
    "manufacturername": "Stelpro",
    "modelid": "0x534d54343032414400dd590008fffffffff39e0008fffffffff9ffffffffff",
    "name": "Humidité CdM",
    "state": {
        "humidity": 5000,
        "lastupdated": "2022-10-12T09:15:31.898"
    },
    "type": "ZHAHumidity",
    "uniqueid": "f8:f0:05:ff:ff:70:7e:95-ff-0405"
}

Each modification on these FF EP (renaming, deleting, etc ...) acts on the "regular" EP up to the GUI.

BabaIsYou commented 1 year ago

It's quite clear for me that these old 0XFF EPs are coming from a sort of cache or backup because the Cluster 0x0402 doesn't exist on this device nor the associated DDF (and it doesn,t appear in the "regular" EP). I think that DecOnz crashes last afternoon during my several tests ... may be it's the root of this re-appearing ...

SwoopX commented 1 year ago

@BabaIsYou I'm afraid the partial logs you shared above is not quite what holds the gems. The APS_L2 logs would give us the actual APS payload (missing above) and maybe some insights what the device sends (in addition). Would be great to give it another go with ZCL and APS_L2.

With regard to the endpoint(s), you might want to take a look at the database. Data of interest is stored in sensors table (legacy), but also in table resource_items. Eventually, data there is kinda out of sync and loaded/processed un an unfortunate way. That might also cause the changing modelIDs btw.

BabaIsYou commented 1 year ago

Would be great to give it another go with ZCL and APS_L2.

Checked ZCL, APS and APS_L2 and did a read on Basic Cluster and specific Model ID attributes. Here it is,. Device NWK is 0xA2C7, MAC is 0xf8f005ffff707e95

https://pastebin.com/bhvXvzdm

BabaIsYou commented 1 year ago

Well, seems that database is a mess ;-( Insensors table I have some sensors with wrong EP (0x01) that was created when I tested the DDF but with the right modelid (SMT402AD), I also have some sensors with right EP (0x19) and right Modelid, and I also have sensors with right EP (0x19) but wrong Modelid (hxadecimal) image

In ressource_tems is looks like that I don't have resources with EP -ff i have two with EP -19 image

How can I clean this ? Can I just delete de device one more time and just delete the lines insensors table that could still be present after deleteing the device ?

Smanar commented 1 year ago

How can I clean this ? Can I just delete de device one more time and just delete the lines in sensors table that could still be present after deleteing the device ?

For me, yes.

First, I will try to delete the device using phoscon and deconz. Then check again the database to see what is still here. But yes it seem you can just remove the "line".

I think the "ressource" table will be clean, but you still have crappy stuff in the "sensors" one.

And BTW don't forget to make a backup before the try ^^.

BabaIsYou commented 1 year ago

Well, after cleaning database and repairing the device I only have deux sensors for this thermostat with valid EP (0x19). That part seems ok ;-) Thx

But I still have the Modelid in hexadecimal ;-(

BabaIsYou commented 1 year ago

The value seems not to be constant, sometimes it's 0x534d54343032414400dd590008fffffffff39e0008fffffffff9ffffffffff and sometimes 0x534d543430324144000000000000000000dd590008fffffffff39e0008ffff

Smanar commented 1 year ago

Lol, it's look like a buffer limit result. The usefull part is up to the null character. Only the first part is usefull, but we have random garbage character after, it depend of what happen in the memory if the buffer is not "cleared"

github-actions[bot] commented 1 year ago

As there has not been any response in 21 days, this issue has been automatically marked as stale. At OP: Please either close this issue or keep it active It will be closed in 7 days if no further activity occurs.

SwoopX commented 1 year ago

Bump

BabaIsYou commented 1 year ago

Lol, it's look like a buffer limit result. The usefull part is up to the null character. Only the first part is usefull, but we have random garbage character after, it depend of what happen in the memory if the buffer is not "cleared"

Interesting … may be one can change the reading of this attribute to keep only value before first null … don’t know the incidence.

github-actions[bot] commented 1 year ago

As there has not been any response in 21 days, this issue has been automatically marked as stale. At OP: Please either close this issue or keep it active It will be closed in 7 days if no further activity occurs.

BabaIsYou commented 1 year ago

I think that we can close this issue. I had opportunity to test this device with Z2M and another dongle and even if it is recognized as Stelpro SMT402AD by Z2M, the model displayed stays weird image Then I guess that it's my thermostat that has a trouble even if it seems functionnal.

BabaIsYou commented 1 year ago

See above

opechunka commented 4 months ago

I have a similar issue with Salus PS600 pipe temperature sensor. The Model Id is reported as a hex number:

"0x5053363030000020f60120b199000090000000a7750000b7c500009000000090"

Actually the first part "0x505336303000" is null a terminated representation of "PS600". A worse thing is that the part after the "0x505336303000" is not stable, some of the numbers randomly change. So I cannot just replace the model id in DDF file ss909zb_temp_sensor.json I have 4 of those sensors. The behavior are the same for all of them. Of cause the second part differs for every of 4 devices.