Issue: Deconz Docker becomes unresponsive with Tuya TS011F Plugs DDF

iisworks · February 12, 2022, 4:01pm

@Smanar, @manup I am pretty sure it has to do with DDF (TS011F) in 2.14.1. When I am adding/updating these plugs, strange things happen. I just saw this when I re-added a plug that previously existed. I see the same thing happening: deconz becomes very unresponsive , DB size increases and updates are delayed a lot (this happens within minutes!). It must be a bug somewhere.

BTW: Notice the many “REPLACE INTO …” sql statements, which keep repeating. Do they maybe create new sensor entries instead of updating them (not only for the plugs)? Please let me know if someone needs such a DB sample PM-ed.
SQLite Replace Statement - Tutlane.

Full L2 log:


15:57:36:116 	payload: 0b05292f00
15:57:36:117 Websocket 172.17.0.1:59794 send message: {"e":"changed","id":"288","r":"sensors","state":{"current":281,"lastupdated":"2022-02-12T15:57:36.115","power":47,"voltage":227},"t":"event","uniqueid":"a4:c1:38:91:cb:9d:7c:e8-01-0b04"} (ret = 186)
15:57:36:146 APS-DATA.indication srcAddr: 0xecd4, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -76
15:57:36:518 ZCL attribute report 0xA4C13891CB9D7CE8 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
15:57:36:519 	payload: 0805212b01
15:57:36:520 Websocket 172.17.0.1:59794 send message: {"e":"changed","id":"288","r":"sensors","state":{"current":299,"lastupdated":"2022-02-12T15:57:36.148","power":47,"voltage":227},"t":"event","uniqueid":"a4:c1:38:91:cb:9d:7c:e8-01-0b04"} (ret = 186)
15:57:36:764 APS-DATA.request id: 117, addrmode: 0x03, addr: 0x00158d000520aba2, profile: 0x0000, cluster: 0x0031, ep: 0x00 -> 0x00 queue: 0 len: 2 tx.options 0x00
15:57:36:777 APS-DATA.confirm id: 117, status: 0x00 SUCCESS
15:57:36:777 APS-DATA.confirm request id: 117 -> confirmed, timeout 2072044165
15:57:37:186 poll node 5c:02:72:ff:fe:74:16:51-01
15:57:37:187 Poll light node Keuken Spot 1
15:57:37:239 Poll APS request to 0x5C0272FFFE741651 cluster: 0x0006 dropped, values are fresh enough
15:57:38:190 poll node 58:8e:81:ff:fe:d3:8e:bc-01
15:57:38:242 read attributes of 0x588E81FFFED38EBC cluster: 0x0006: [ 
15:57:38:242 0x0000 
15:57:38:242 ]
15:57:38:243 add task 1449 type 19 to 0x588E81FFFED38EBC cluster 0x0006 req.id 124
15:57:38:243 Poll APS request 124 to 0x588E81FFFED38EBC cluster: 0x0006
15:57:38:299 APS-DATA.request id: 124, addrmode: 0x03, addr: 0x588e81fffed38ebc, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 1 len: 5 tx.options 0x00
15:57:38:315 Poll APS confirm 124 status: 0x00
15:57:38:316 Erase task req-id: 124, type: 19 zcl seqno: 150 send time 0, profileId: 0x0104, clusterId: 0x0006
15:57:38:316 APS-DATA.confirm id: 124, status: 0x00 SUCCESS
15:57:38:317 APS-DATA.confirm request id: 124 -> erase from queue
15:57:38:324 APS-DATA.indication srcAddr: 0xdb67, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0400, lqi: 255, rssi: -71
15:57:38:325 APS-DATA.request id: 124 erase from queue
15:57:38:325 Node data 0x04cf8cdf3c7d1330 profileId: 0x0104, clusterId: 0x0400
15:57:38:325 0x04CF8CDF3C7D1330: update ZCL value 0x01/0x0400/0x0000 after 0 s
15:57:38:326 [INFO] - No button map for: lumi.sen_ill.mgl01, unicast to: 0x0000, endpoint: 0x01, cluster: 0x0400, command: 0x0A, payload: 0000211354, zclSeq: 76
15:57:38:327 ZCL attribute report 0x04CF8CDF3C7D1330 for cluster: 0x0400, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
15:57:38:327 	payload: 0000211354
15:57:38:335 Websocket 172.17.0.1:59794 send message: {"e":"changed","id":"260","r":"sensors","state":{"dark":false,"daylight":true,"lastupdated":"2022-02-12T15:57:38.326","lightlevel":21523,"lux":142},"t":"event","uniqueid":"04:cf:8c:df:3c:7d:13:30-01-0400"} (ret = 205)
15:57:38:599 DB save zll database items 0x00000081
15:57:38:600 DB sql exec REPLACE INTO nodes (id, state, mac, name, groups, endpoint, modelid, manufacturername, swbuildid, ritems) VALUES ('25', 'normal', '84:fd:27:ff:fe:ce:99:dc-01', 'PC Alena', '65520', '1', 'TS011F', '_TZ3000_mraovvmm', '67', '{"attr/id":"25","attr/lastannounced":null,"attr/lastseen":"2022-02-12T15:57Z","attr/manufacturername":"_TZ3000_mraovvmm","attr/modelid":"TS011F","attr/name":"PC Alena","attr/swversion":"67","attr/type":"On/Off plug-in unit","attr/uniqueid":"84:fd:27:ff:fe:ce:99:dc-01","state/alert":"none","state/on":false,"state/reachable":true}')
15:57:38:601 DB sql exec REPLACE INTO nodes (id, state, mac, name, groups, endpoint, modelid, manufacturername, swbuildid, ritems) VALUES ('18', 'normal', '84:fd:27:ff:fe:ce:7b:ea-01', 'PC Kevin', '65520', '1', 'TS011F', '_TZ3000_mraovvmm', '67', '{"attr/id":"18","attr/lastannounced":null,"attr/lastseen":"2022-02-12T15:57Z","attr/manufacturername":"_TZ3000_mraovvmm","attr/modelid":"TS011F","attr/name":"PC Kevin","attr/swversion":"67","attr/type":"On/Off plug-in unit","attr/uniqueid":"84:fd:27:ff:fe:ce:7b:ea-01","state/alert":"none","state/on":true,"state/reachable":true}')
15:57:38:602 DB sql exec REPLACE INTO nodes (id, state, mac, name, groups, endpoint, modelid, manufacturername, swbuildid, ritems) VALUES ('39', 'normal', 'a4:c1:38:91:cb:9d:7c:e8-01', 'PC JH 1', '65520', '1', 'TS011F', '_TZ3000_gjnozsaz', '', '{"attr/id":"39","attr/lastannounced":null,"attr/lastseen":"2022-02-12T15:57Z","attr/manufacturername":"_TZ3000_gjnozsaz","attr/modelid":"TS011F","attr/name":"PC JH 1","attr/swversion":null,"attr/type":"On/Off plug-in unit","attr/uniqueid":"a4:c1:38:91:cb:9d:7c:e8-01","state/alert":"none","state/on":true,"state/reachable":true}')
15:57:38:603 DB sql exec REPLACE INTO nodes (id, state, mac, name, groups, endpoint, modelid, manufacturername, swbuildid, ritems) VALUES ('38', 'normal', '00:15:8d:00:05:20:e6:9e-01', 'Lamp Muurkast', '65520,11', '1', 'lumi.light.aqcn02', 'LUMI', '1.23', '{"attr/id":"38","attr/lastannounced":null,"attr/lastseen":"2022-02-12T15:57Z","attr/manufacturername":"LUMI","attr/modelid":"lumi.light.aqcn02","attr/name":"Lamp Muurkast","attr/swversion":"1.23","attr/type":"Color temperature light","attr/uniqueid":"00:15:8d:00:05:20:e6:9e-01","state/alert":"none","state/colormode":"hs","state/effect":"none","state/lift":null,"state/on":false,"state/open":null,"state/reachable":true,"state/x":29283,"state/y":26958}')
15:57:38:604 DB sql exec REPLACE INTO sensors (sid, name, type, modelid, manufacturername, uniqueid, swversion, state, config, fingerprint, deletedState, mode, lastseen, lastannounced) VALUES ('27', 'Kevin', 'ZHALightLevel', 'lumi.sensor_motion.aq2', 'LUMI', '00:15:8d:00:04:66:63:8e-01-0400', '20170627', '{"dark":false,"daylight":false,"lastupdated":"2022-02-12T15:57:22.269","lightlevel":13618,"lux":23}', '{"battery":100,"on":true,"reachable":true,"temperature":2100,"tholddark":12000,"tholdoffset":7000}', '{"d":263,"ep":1,"in":[0,1024,1],"p":260}', 'normal', '1', '2022-02-12T15:57Z', '')
15:57:38:605 DB sql exec REPLACE INTO sensors (sid, name, type, modelid, manufacturername, uniqueid, swversion, state, config, fingerprint, deletedState, mode, lastseen, lastannounced) VALUES ('260', 'LightLevel JH', 'ZHALightLevel', 'lumi.sen_ill.mgl01', 'LUMI', '04:cf:8c:df:3c:7d:13:30-01-0400', '20191118', '{"dark":false,"daylight":true,"lastupdated":"2022-02-12T15:57:38.326","lightlevel":21523,"lux":142}', '{"battery":100,"on":true,"reachable":true,"temperature":2500,"tholddark":12000,"tholdoffset":7000}', '{"d":262,"ep":1,"in":[0,1,1024],"p":260}', 'normal', '1', '2022-02-12T15:57Z', '2022-01-15T18:07:52Z')
15:57:38:606 DB sql exec REPLACE INTO sensors (sid, name, type, modelid, manufacturername, uniqueid, swversion, state, config, fingerprint, deletedState, mode, lastseen, lastannounced) VALUES ('26', 'Kevin', 'ZHAPresence', 'lumi.sensor_motion.aq2', 'LUMI', '00:15:8d:00:04:66:63:8e-01-0406', '20170627', '{"lastupdated":"2022-02-12T15:57:22.278","presence":true}', '{"battery":100,"duration":90,"on":true,"reachable":true,"temperature":2100}', '{"d":263,"ep":1,"in":[0,1030,1],"p":260}', 'normal', '1', '2022-02-12T15:57Z', '')
15:57:38:607 DB sql exec REPLACE INTO sensors (sid, name, type, modelid, manufacturername, uniqueid, swversion, state, config, fingerprint, deletedState, mode, lastseen, lastannounced) VALUES ('266', 'Lichtsensor Kevin', 'ZHALightLevel', 'lumi.sen_ill.mgl01', 'LUMI', '04:cf:8c:df:3c:78:c3:9e-01-0400', '20191118', '{"dark":false,"daylight":false,"lastupdated":"2022-02-12T15:57:31.611","lightlevel":13223,"lux":21}', '{"battery":100,"on":true,"reachable":true,"temperature":2500,"tholddark":12000,"tholdoffset":7000}', '{"d":262,"ep":1,"in":[0,1,1024],"p":260}', 'normal', '1', '2022-02-12T15:57Z', '')
15:57:38:608 DB sql exec REPLACE INTO sensors (sid, name, type, modelid, manufacturername, uniqueid, swversion, state, config, fingerprint, deletedState, mode, lastseen, lastannounced) VALUES ('279', 'Consumption 279', 'ZHAConsumption', 'TS011F', '_TZ3000_mraovvmm', '84:fd:27:ff:fe:ce:99:dc-01-0702', '', '{"consumption":3818,"lastupdated":"2022-02-12T15:53:35.084"}', '{"on":true,"reachable":true}', '', 'normal', '2', '2022-02-12T15:57Z', '')
15:57:38:609 DB sql exec REPLACE INTO sensors (sid, name, type, modelid, manufacturername, uniqueid, swversion, state, config, fingerprint, deletedState, mode, lastseen, lastannounced) VALUES ('280', 'Power 280', 'ZHAPower', 'TS011F', '_TZ3000_mraovvmm', '84:fd:27:ff:fe:ce:99:dc-01-0b04', '', '{"current":0,"lastupdated":"2022-02-12T15:57:16.291","power":0,"voltage":226}', '{"on":true,"reachable":true}', '', 'normal', '2', '2022-02-12T15:57Z', '')
15:57:38:610 DB sql exec REPLACE INTO sensors (sid, name, type, modelid, manufacturername, uniqueid, swversion, state, config, fingerprint, deletedState, mode, lastseen, lastannounced) VALUES ('269', 'Consumption 269', 'ZHAConsumption', 'TS011F', '_TZ3000_mraovvmm', '84:fd:27:ff:fe:ce:7b:ea-01-0702', '', '{"consumption":3131,"lastupdated":"2022-02-12T15:53:46.186"}', '{"on":true,"reachable":true}', '', 'normal', '2', '2022-02-12T15:57Z', '')
15:57:38:611 DB sql exec REPLACE INTO sensors (sid, name, type, modelid, manufacturername, uniqueid, swversion, state, config, fingerprint, deletedState, mode, lastseen, lastannounced) VALUES ('270', 'Power 270', 'ZHAPower', 'TS011F', '_TZ3000_mraovvmm', '84:fd:27:ff:fe:ce:7b:ea-01-0b04', '', '{"current":110,"lastupdated":"2022-02-12T15:57:31.621","power":13,"voltage":224}', '{"on":true,"reachable":true}', '', 'normal', '2', '2022-02-12T15:57Z', '')
15:57:38:612 DB sql exec REPLACE INTO sensors (sid, name, type, modelid, manufacturername, uniqueid, swversion, state, config, fingerprint, deletedState, mode, lastseen, lastannounced) VALUES ('287', 'Consumption 287', 'ZHAConsumption', 'TS011F', '_TZ3000_gjnozsaz', 'a4:c1:38:91:cb:9d:7c:e8-01-0702', '', '{"consumption":9,"lastupdated":"2022-02-12T15:55:09.460"}', '{"on":true,"reachable":true}', '', 'normal', '2', '2022-02-12T15:56Z', '')
15:57:38:613 DB sql exec REPLACE INTO sensors (sid, name, type, modelid, manufacturername, uniqueid, swversion, state, config, fingerprint, deletedState, mode, lastseen, lastannounced) VALUES ('288', 'Power 288', 'ZHAPower', 'TS011F', '_TZ3000_gjnozsaz', 'a4:c1:38:91:cb:9d:7c:e8-01-0b04', '', '{"current":299,"lastupdated":"2022-02-12T15:57:36.148","power":47,"voltage":227}', '{"on":true,"reachable":true}', '', 'normal', '2', '2022-02-12T15:57Z', '')

Smanar · February 13, 2022, 9:27am

So long time I haven’t do SQL request

The request done is this one
QString sql = QString(QLatin1String("REPLACE INTO sensors (sid, name, type, modelid, manufacturername, uniqueid, swversion, state, config, fingerprint, deletedState, mode, lastseen, lastannounced) VALUES ('%1', '%2', '%3', '%4', '%5', '%6', '%7', '%8', '%9', '%10', '%11', '%12', '%13', '%14')"))

And on your logs it seem fine because the sid is never the same (one by device, and it s different mac adress)
If I m right it’s the key used by the SQL request.

"CREATE TABLE IF NOT EXISTS sensors (sid TEXT PRIMARY KEY, name TEXT, type TEXT, modelid TEXT,

To have this result, you nned to have a different key (sid) but for the same device, else the request delete the previous one and update it.

Can you check what is the difference between all field for the bugged device ? On your capture all fields look same.

**sid = 161**
name = Consumption 161
type = ZHAConsumption
.....

So if the key is 161 the request need to update the line not create a new one ?

It’s your production or test network ? to check if you can start with a new clean database ?

iisworks · February 13, 2022, 10:32am

It’s my home network. If I look at a normal DB I just see one “sensor” entry for each sensor/sid:

But when the issue is going on, the DB keeps growing and sensors have countless entries per device/sensor, all with the same sid!

For example these 2 entries with identical sid were created instead of updated.
As far as I can see, only 'State" + timestamps changed?

284 Power 284 ZHAPower TS011F _TZ3000_gjnozsaz a4:c1:38:91:cb:9d:7c:e8-01-0b04 {“current”:169,“lastupdated”:“2022-02-13T10:07:08.726”,“power”:22,“voltage”:230} {“on”:true,“reachable”:true} normal 2 2022-02-13T10:08Z

284 Power 284 ZHAPower TS011F _TZ3000_gjnozsaz a4:c1:38:91:cb:9d:7c:e8-01-0b04 {“current”:169,“lastupdated”:“2022-02-13T10:07:08.726”,“power”:22,“voltage”:230} {“on”:true,“reachable”:true} normal 2 2022-02-13T10:07Z

Is there some other DB action performed that is nog logged (or needs additional log categories selected)? Note this is not limited to specific devices or types only, I also see 100s of duplicate sid entries for other devices like motion sensors or light bulbs. So it looks more like the result of an issue than the cause for it?

Steps to reproduce (without adding devices)

Start with a working stable situation (DB restore which runs 100% stable for days/weeks)
Change the “DDF mode” to Include Silver:
Restart Deconz
The built-in DDF was loaded for my 5 existing BW-SHP15 plugs (_TZ3000_mraovvmm):
12:48:07:214 DEV found DDF for 0x84FD27FFFECE979C, path: /usr/share/deCONZ/devices/neo/NAS-WR01B.json

The issue then started, without even adding any new devices!

Smanar · February 13, 2022, 1:21pm

It’s my home network. If I look at a normal DB I just see one “sensor” entry for each sensor/sid:

It’s the good capture ?
I m seing lot of lines with the same device and same sid ?

Edit:
ok, it’s 2 time the ame cpature ^^

iisworks · February 13, 2022, 1:31pm

Sorry, updated with the right screenshot. Accidentally pasted the corrupted DB twice.

But as described I can reproduce it time after time starting from a stable situation by just choosing “Silver” DDF mode and rebooting with the existing functional SHP15 plugs. But how is it even possible to get multiple records with the same primary key???

Swoop · February 13, 2022, 8:08pm

Small progress:
I guess I found out why deconz apparently doesn’t read the manufacturer name for a device which has never been paired to the network before. A tested fix seems to trigger it now.

However, this unfortunately still does not resolve or explain why the wrong json file is chosen in my tests and of course it has nothing to do with the strange DB behavior.

This one is truly a multi in one…

UPDATE:
Looks like I found a solution for the selection of the correct DDF when there’s different manufacturer names. Same prerequisites as previously (3 files with deviating manufacturer names), but this time the correct one is chosen. Need to do some more tests to ensure this wasn’t a coincidence, but it looks promising. Will file a bug report for this.

iisworks · February 14, 2022, 6:20am

Thanks! So that leaves the question why in my case the DB gets corrupted (?) with identical values on the “sid” primary key? This should not be possible becasuse it should not be allowed by the sql driver, correct?

I also did some general searching on sqlite + duplicated primary key values, but that did not turn up much. Is there any way to explain this, and has anyone ever seen this before? I guess I could take the pain and start from scratch with a fresh database for my 60 devices, but only if there is a reasonable chance that it would actually solve the issue.

So I am wondering if someone with some BW-SHP15 plugs who can try DDF Mode “Silver” on 2.14.1 in docker, restart doconz and confirm they have 0 issues after a while?

Smanar · February 14, 2022, 4:09pm

Good question, for the moment I m at same point than you.
If the table is correctly created at start, the key is sId, so you can’t have multiple entry for the same key.
If you can’t try with a clean database, can you check the table property ? (to be sure for the key)

iisworks · February 14, 2022, 4:34pm

I already checked, and it’t a primary key for sure:

Could this be caused by some race condition in the code?

[Update] I removed all my existing SHP15 plugs from the network yesterday to remove possible conflicts. When I start adding a few orange TS011F plugs using the Silver NEO DDF, I noticed the same unresponsiveness again. As if deconz is extremely busy or locked up for a few seconds every minute or so. Also looking on the docker container utilization it’s around 5% on average, while under normal conditions it’s usually 1-2%.

Does anyone see anything wrong in the logs, or could something else be going on that is not logged?

12:10:56:716 Poll APS confirm 21 status: 0x00
12:10:56:716 Erase task req-id: 21, type: 19 zcl seqno: 72 send time 0, profileId: 0x0104, clusterId: 0x0006
12:10:56:717 APS-DATA.confirm id: 21, status: 0x00 SUCCESS
12:10:56:717 APS-DATA.confirm request id: 21 -> erase from queue
12:10:56:732 APS-DATA.indication srcAddr: 0xe8a3, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 255, rssi: -64
12:10:56:732 	asdu: 1848010000001000
12:10:56:733 APS-DATA.request id: 21 erase from queue
12:10:56:733 Node data 0x00158d000520a8a7 profileId: 0x0104, clusterId: 0x0006
12:10:56:734 0x00158D000520A8A7: update ZCL value 0x01/0x0006/0x0000 after 0 s
12:10:56:876 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -82
12:10:56:876 	asdu: 184b0a0805210201
12:10:58:785 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:10:58:786 	payload: 0805210201
12:10:58:792 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":258,"lastupdated":"2022-02-19T12:10:56.879","power":39,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:10:58:800 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -82
12:10:58:801 	asdu: 184c0a0b05292a00
12:10:59:083 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:10:59:084 	payload: 0b05292a00
12:10:59:085 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":258,"lastupdated":"2022-02-19T12:10:58.803","power":42,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:10:59:100 APS-DATA.indication srcAddr: 0x4ffe, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0400, lqi: 255, rssi: -64
12:10:59:102 	asdu: 18b20a000021737f
12:10:59:103 Node data 0x04cf8cdf3c78b5dc profileId: 0x0104, clusterId: 0x0400
12:10:59:104 0x04CF8CDF3C78B5DC: update ZCL value 0x01/0x0400/0x0000 after 0 s
12:10:59:105 [INFO] - No button map for: lumi.sen_ill.mgl01, unicast to: 0x0000, endpoint: 0x01, cluster: 0x0400, command: 0x0A, payload: 000021737F, zclSeq: 178
12:10:59:106 ZCL attribute report 0x04CF8CDF3C78B5DC for cluster: 0x0400, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:10:59:106 	payload: 000021737f
12:10:59:107 Websocket 172.17.0.1:33800 send message: {"attr":{"id":"84","lastannounced":null,"lastseen":"2022-02-19T12:10Z","manufacturername":"LUMI","modelid":"lumi.sen_ill.mgl01","name":"Lichtsensor Voor","swversion":"20191118","type":"ZHALightLevel","uniqueid":"04:cf:8c:df:3c:78:b5:dc-01-0400"},"e":"changed","id":"84","r":"sensors","t":"event","uniqueid":"04:cf:8c:df:3c:78:b5:dc-01-0400"} (ret = 341)
12:10:59:108 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"84","r":"sensors","state":{"dark":false,"daylight":true,"lastupdated":"2022-02-19T12:10:59.105","lightlevel":32627,"lux":1831},"t":"event","uniqueid":"04:cf:8c:df:3c:78:b5:dc-01-0400"} (ret = 205)
12:10:59:120 APS-DATA.indication srcAddr: 0xdb67, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0400, lqi: 255, rssi: -70
12:10:59:121 	asdu: 184c0a0000218556
12:10:59:121 Node data 0x04cf8cdf3c7d1330 profileId: 0x0104, clusterId: 0x0400
12:10:59:125 0x04CF8CDF3C7D1330: update ZCL value 0x01/0x0400/0x0000 after 0 s
12:10:59:130 [INFO] - No button map for: lumi.sen_ill.mgl01, unicast to: 0x0000, endpoint: 0x01, cluster: 0x0400, command: 0x0A, payload: 0000218556, zclSeq: 76
12:10:59:131 ZCL attribute report 0x04CF8CDF3C7D1330 for cluster: 0x0400, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:10:59:131 	payload: 0000218556
12:10:59:132 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"260","r":"sensors","state":{"dark":false,"daylight":true,"lastupdated":"2022-02-19T12:10:59.130","lightlevel":22149,"lux":164},"t":"event","uniqueid":"04:cf:8c:df:3c:7d:13:30-01-0400"} (ret = 205)
12:10:59:742 Skip idle timer callback, too early: elapsed 948 msec
12:10:59:772 poll node 00:15:8d:00:05:20:e6:9e-01
12:10:59:772 Poll light node Lamp Muurkast
12:10:59:819 read attributes of 0x00158D000520E69E cluster: 0x0006: [ 
12:10:59:820 0x0000 
12:10:59:821 ]
12:10:59:821 add task 4423 type 19 to 0x00158D000520E69E cluster 0x0006 req.id 32
12:10:59:821 Poll APS request 32 to 0x00158D000520E69E cluster: 0x0006
12:10:59:877 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -80
12:10:59:877 	asdu: 184d0a080521f000
12:11:00:391 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:00:392 	payload: 080521f000
12:11:00:398 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":240,"lastupdated":"2022-02-19T12:10:59.879","power":42,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:11:00:399 APS-DATA.request id: 32, addrmode: 0x03, addr: 0x00158d000520e69e, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 1 len: 5 tx.options 0x00
12:11:00:399 	asdu (length: 5): 1049000000
12:11:00:409 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -80
12:11:00:410 	asdu: 184e0a0b05292600
12:11:00:721 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:00:722 	payload: 0b05292600
12:11:00:723 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":240,"lastupdated":"2022-02-19T12:11:00.419","power":38,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:11:00:734 Poll APS confirm 32 status: 0x00
12:11:00:734 Erase task req-id: 32, type: 19 zcl seqno: 73 send time 1, profileId: 0x0104, clusterId: 0x0006
12:11:00:735 APS-DATA.confirm id: 32, status: 0x00 SUCCESS
12:11:00:735 APS-DATA.confirm request id: 32 -> erase from queue
12:11:00:743 APS-DATA.indication srcAddr: 0xef57, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 255, rssi: -45
12:11:00:743 	asdu: 1849010000001000
12:11:00:744 APS-DATA.request id: 32 erase from queue
12:11:00:744 Node data 0x00158d000520e69e profileId: 0x0104, clusterId: 0x0006
12:11:00:745 0x00158D000520E69E: update ZCL value 0x01/0x0006/0x0000 after 0 s
12:11:00:760 Websocket 172.17.0.1:33800 send message: {"attr":{"colorcapabilities":16,"ctmax":65279,"ctmin":null,"id":"38","lastannounced":"2022-01-28T19:02:50Z","lastseen":"2022-02-19T12:11Z","manufacturername":"LUMI","modelid":"lumi.light.aqcn02","name":"Lamp Muurkast","swversion":"11-22-2018","type":"Color temperature light","uniqueid":"00:15:8d:00:05:20:e6:9e-01"},"e":"changed","id":"38","r":"lights","t":"event","uniqueid":"00:15:8d:00:05:20:e6:9e-01"} (ret = 406)
12:11:01:642 Skip idle timer callback, too early: elapsed 917 msec
12:11:01:692 poll node 58:8e:81:ff:fe:d3:8e:bc-01-0b04
12:11:01:693 Poll ZHAPower sensor node Power 282
12:11:01:934 read attributes of 0x588E81FFFED38EBC cluster: 0x0B04: [ 
12:11:01:935 0x0505 
12:11:01:935 0x0508 
12:11:01:936 0x050B 
12:11:01:936 ]
12:11:01:936 add task 4432 type 19 to 0x588E81FFFED38EBC cluster 0x0B04 req.id 44
12:11:01:937 Poll APS request 44 to 0x588E81FFFED38EBC cluster: 0x0B04
12:11:01:000 APS-DATA.request id: 44, addrmode: 0x03, addr: 0x588e81fffed38ebc, profile: 0x0104, cluster: 0x0B04, ep: 0x01 -> 0x01 queue: 1 len: 9 tx.options 0x00
12:11:02:000 	asdu (length: 9): 104a00050508050b05
12:11:02:021 Poll APS confirm 44 status: 0x00
12:11:02:022 Erase task req-id: 44, type: 19 zcl seqno: 74 send time 0, profileId: 0x0104, clusterId: 0x0B04
12:11:02:026 APS-DATA.confirm id: 44, status: 0x00 SUCCESS
12:11:02:029 APS-DATA.confirm request id: 44 -> erase from queue
12:11:02:037 APS-DATA.indication srcAddr: 0xc898, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -52
12:11:02:038 	asdu: 184a0105050021e6000805002100000b0500290000
12:11:02:038 APS-DATA.request id: 44 erase from queue
12:11:02:039 Node data 0x588e81fffed38ebc profileId: 0x0104, clusterId: 0x0B04
12:11:02:040 0x588E81FFFED38EBC: update ZCL value 0x01/0x0B04/0x0505 after 0 s
12:11:02:040 0x588E81FFFED38EBC: update ZCL value 0x01/0x0B04/0x0508 after 0 s
12:11:02:041 0x588E81FFFED38EBC: update ZCL value 0x01/0x0B04/0x050B after 0 s
12:11:02:050 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"282","r":"sensors","state":{"current":0,"lastupdated":"2022-02-19T12:11:02.041","power":0,"voltage":230},"t":"event","uniqueid":"58:8e:81:ff:fe:d3:8e:bc-01-0b04"} (ret = 183)
12:11:02:606 poll node 58:8e:81:ff:fe:d3:8e:bc-01-0702
12:11:02:606 Poll ZHAConsumption sensor node Consumption 281
12:11:02:864 read attributes of 0x588E81FFFED38EBC cluster: 0x0702: [ 
12:11:02:864 0x0000 
12:11:02:865 ]
12:11:02:865 add task 4437 type 19 to 0x588E81FFFED38EBC cluster 0x0702 req.id 50
12:11:02:865 Poll APS request 50 to 0x588E81FFFED38EBC cluster: 0x0702
12:11:02:890 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -82
12:11:02:891 	asdu: 184f0a0805211701
12:11:04:745 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:04:746 	payload: 0805211701
12:11:04:752 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":279,"lastupdated":"2022-02-19T12:11:02.893","power":38,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:11:04:753 APS-DATA.request id: 50, addrmode: 0x03, addr: 0x588e81fffed38ebc, profile: 0x0104, cluster: 0x0702, ep: 0x01 -> 0x01 queue: 1 len: 5 tx.options 0x00
12:11:04:754 	asdu (length: 5): 104b000000
12:11:04:756 Daylight now: solarNoon, status: 170, daylight: 1, dark: 0
12:11:04:781 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -81
12:11:04:781 	asdu: 18500a0b05292f00
12:11:05:076 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:05:076 	payload: 0b05292f00
12:11:05:082 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":279,"lastupdated":"2022-02-19T12:11:04.784","power":47,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:11:05:087 APS-DATA.indication srcAddr: 0x2418, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0702, lqi: 255, rssi: -71
12:11:05:088 	asdu: 18750a000025000000000000
12:11:05:091 ZCL attribute report 0xA4C1384FEA5C6370 for cluster: 0x0702, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:05:092 	payload: 000025000000000000
12:11:05:093 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"286","r":"sensors","state":{"consumption":0,"lastupdated":"2022-02-19T12:11:05.090"},"t":"event","uniqueid":"a4:c1:38:4f:ea:5c:63:70-01-0702"} (ret = 163)
12:11:05:121 Poll APS confirm 50 status: 0x00
12:11:05:122 Erase task req-id: 50, type: 19 zcl seqno: 75 send time 1, profileId: 0x0104, clusterId: 0x0702
12:11:05:122 APS-DATA.confirm id: 50, status: 0x00 SUCCESS
12:11:05:123 APS-DATA.confirm request id: 50 -> erase from queue
12:11:05:130 APS-DATA.indication srcAddr: 0xc898, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0702, lqi: 255, rssi: -50
12:11:05:130 	asdu: 184b0100000025020000000000
12:11:05:131 APS-DATA.request id: 50 erase from queue
12:11:05:131 Node data 0x588e81fffed38ebc profileId: 0x0104, clusterId: 0x0702
12:11:05:132 0x588E81FFFED38EBC: update ZCL value 0x01/0x0702/0x0000 after 0 s
12:11:05:154 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"281","r":"sensors","state":{"consumption":20,"lastupdated":"2022-02-19T12:11:05.133"},"t":"event","uniqueid":"58:8e:81:ff:fe:d3:8e:bc-01-0702"} (ret = 164)
12:11:05:698 poll node bc:33:ac:ff:fe:2b:f6:52-01
12:11:05:699 Poll light node Keuken Spot 2
12:11:05:703 Skip idle timer callback, too early: elapsed 945 msec
12:11:05:750 Poll APS request to 0xBC33ACFFFE2BF652 cluster: 0x0006 dropped, values are fresh enough
12:11:05:916 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -79
12:11:05:917 	asdu: 18510a0805212b01
12:11:06:275 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:06:276 	payload: 0805212b01
12:11:06:283 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":299,"lastupdated":"2022-02-19T12:11:05.919","power":47,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:11:06:300 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -79
12:11:06:301 	asdu: 18520a0b05293200
12:11:06:609 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:06:609 	payload: 0b05293200
12:11:06:616 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":299,"lastupdated":"2022-02-19T12:11:06.306","power":50,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:11:06:624 APS-DATA.indication srcAddr: 0x6c2c, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0702, lqi: 255, rssi: -71
12:11:06:625 	asdu: 187f0a000025000000000000
12:11:06:627 ZCL attribute report 0xA4C138B388AA7353 for cluster: 0x0702, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:06:628 	payload: 000025000000000000
12:11:06:654 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"288","r":"sensors","state":{"consumption":0,"lastupdated":"2022-02-19T12:11:06.627"},"t":"event","uniqueid":"a4:c1:38:b3:88:aa:73:53-01-0702"} (ret = 163)
12:11:06:806 sensor 32 (lumi.sensor_motion.aq2): disable presence
12:11:06:809 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"32","r":"sensors","state":{"lastupdated":"2022-02-19T12:11:06.806","presence":false},"t":"event","uniqueid":"00:15:8d:00:05:4d:05:53-01-0406"} (ret = 163)
12:11:07:283 poll node 00:15:8d:00:05:20:f4:43-01
12:11:07:284 Poll light node Lamp JH
12:11:07:336 read attributes of 0x00158D000520F443 cluster: 0x0006: [ 
12:11:07:336 0x0000 
12:11:07:337 ]
12:11:07:337 add task 4447 type 19 to 0x00158D000520F443 cluster 0x0006 req.id 67
12:11:07:338 Poll APS request 67 to 0x00158D000520F443 cluster: 0x0006
12:11:07:400 APS-DATA.request id: 67, addrmode: 0x03, addr: 0x00158d000520f443, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 1 len: 5 tx.options 0x00
12:11:07:400 	asdu (length: 5): 104c000000
12:11:07:423 Poll APS confirm 67 status: 0x00
12:11:07:424 Erase task req-id: 67, type: 19 zcl seqno: 76 send time 0, profileId: 0x0104, clusterId: 0x0006
12:11:07:424 APS-DATA.confirm id: 67, status: 0x00 SUCCESS
12:11:07:425 APS-DATA.confirm request id: 67 -> erase from queue
12:11:07:443 APS-DATA.indication srcAddr: 0xdb67, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0400, lqi: 255, rssi: -71
12:11:07:444 	asdu: 18680a000021f752
12:11:07:444 APS-DATA.request id: 67 erase from queue
12:11:07:444 Node data 0x04cf8cdf3c7d1330 profileId: 0x0104, clusterId: 0x0400
12:11:07:445 0x04CF8CDF3C7D1330: update ZCL value 0x01/0x0400/0x0000 after 0 s
12:11:07:446 [INFO] - No button map for: lumi.sen_ill.mgl01, unicast to: 0x0000, endpoint: 0x01, cluster: 0x0400, command: 0x0A, payload: 000021F752, zclSeq: 104
12:11:07:447 ZCL attribute report 0x04CF8CDF3C7D1330 for cluster: 0x0400, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:07:447 	payload: 000021f752
12:11:07:457 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"260","r":"sensors","state":{"dark":false,"daylight":true,"lastupdated":"2022-02-19T12:11:07.446","lightlevel":21239,"lux":133},"t":"event","uniqueid":"04:cf:8c:df:3c:7d:13:30-01-0400"} (ret = 205)
12:11:07:472 APS-DATA.indication srcAddr: 0xdb67, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0001, lqi: 255, rssi: -71
12:11:07:473 	asdu: 186d0a2000201d
12:11:07:473 Node data 0x04cf8cdf3c7d1330 profileId: 0x0104, clusterId: 0x0001
12:11:07:474 0x04CF8CDF3C7D1330: update ZCL value 0x01/0x0001/0x0020 after 0 s
12:11:07:474 [INFO] - No button map for: lumi.sen_ill.mgl01, unicast to: 0x0000, endpoint: 0x01, cluster: 0x0001, command: 0x0A, payload: 2000201D, zclSeq: 109
12:11:07:475 ZCL attribute report 0x04CF8CDF3C7D1330 for cluster: 0x0001, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:07:475 	payload: 2000201d
12:11:07:487 APS-DATA.indication srcAddr: 0x27b3, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 255, rssi: -71
12:11:07:487 	asdu: 184c010000001000
12:11:07:488 Node data 0x00158d000520f443 profileId: 0x0104, clusterId: 0x0006
12:11:07:488 0x00158D000520F443: update ZCL value 0x01/0x0006/0x0000 after 0 s
12:11:07:602 Skip idle timer callback, too early: elapsed 946 msec
12:11:07:700 sensor 43 (lumi.sensor_motion.aq2): disable presence
12:11:07:703 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"43","r":"sensors","state":{"lastupdated":"2022-02-19T12:11:07.700","presence":false},"t":"event","uniqueid":"00:15:8d:00:04:7e:48:b1-01-0406"} (ret = 163)
12:11:08:442 poll node 00:15:8d:00:05:20:e4:53-01
12:11:08:442 Poll light node Lamp WC
12:11:08:493 read attributes of 0x00158D000520E453 cluster: 0x0006: [ 
12:11:08:494 0x0000 
12:11:08:494 ]
12:11:08:495 add task 4453 type 19 to 0x00158D000520E453 cluster 0x0006 req.id 76
12:11:08:495 Poll APS request 76 to 0x00158D000520E453 cluster: 0x0006
12:11:08:506 APS-DATA.request id: 76, addrmode: 0x03, addr: 0x00158d000520e453, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 1 len: 5 tx.options 0x00
12:11:08:507 	asdu (length: 5): 104d000000
12:11:08:523 Poll APS confirm 76 status: 0x00
12:11:08:524 Erase task req-id: 76, type: 19 zcl seqno: 77 send time 0, profileId: 0x0104, clusterId: 0x0006
12:11:08:524 APS-DATA.confirm id: 76, status: 0x00 SUCCESS
12:11:08:525 APS-DATA.confirm request id: 76 -> erase from queue
12:11:08:543 aps request id: 76 finished, erase from queue
12:11:08:547 APS-DATA.indication srcAddr: 0x3565, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 255, rssi: -49
12:11:08:548 	asdu: 184d010000001000
12:11:08:548 Node data 0x00158d000520e453 profileId: 0x0104, clusterId: 0x0006
12:11:08:549 0x00158D000520E453: update ZCL value 0x01/0x0006/0x0000 after 0 s
12:11:08:557 Websocket 172.17.0.1:33800 send message: {"attr":{"colorcapabilities":16,"ctmax":65279,"ctmin":null,"id":"37","lastannounced":"2022-01-08T13:00:27Z","lastseen":"2022-02-19T12:11Z","manufacturername":"LUMI","modelid":"lumi.light.aqcn02","name":"Lamp WC","swversion":"11-22-2018","type":"Color temperature light","uniqueid":"00:15:8d:00:05:20:e4:53-01"},"e":"changed","id":"37","r":"lights","t":"event","uniqueid":"00:15:8d:00:05:20:e4:53-01"} (ret = 400)
12:11:08:902 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -79
12:11:08:903 	asdu: 18530a0805211901
12:11:09:422 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:09:423 	payload: 0805211901
12:11:09:430 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":281,"lastupdated":"2022-02-19T12:11:08.905","power":50,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:11:09:438 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -79
12:11:09:439 	asdu: 18540a0b05292f00
12:11:09:874 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:09:875 	payload: 0b05292f00
12:11:09:875 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":281,"lastupdated":"2022-02-19T12:11:09.441","power":47,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:11:10:402 poll node 5c:02:72:ff:fe:74:16:51-01
12:11:10:403 Poll light node Keuken Spot 1
12:11:10:450 Poll APS request to 0x5C0272FFFE741651 cluster: 0x0006 dropped, values are fresh enough
12:11:10:599 Skip idle timer callback, too early: elapsed 723 msec
12:11:11:502 poll node 00:15:8d:00:05:20:ab:a2-01
12:11:11:502 Poll light node Lamp Hal Beneden
12:11:11:549 read attributes of 0x00158D000520ABA2 cluster: 0x0006: [ 
12:11:11:550 0x0000 
12:11:11:551 ]
12:11:11:551 add task 4465 type 19 to 0x00158D000520ABA2 cluster 0x0006 req.id 91
12:11:11:551 Poll APS request 91 to 0x00158D000520ABA2 cluster: 0x0006
12:11:11:600 APS-DATA.request id: 91, addrmode: 0x03, addr: 0x00158d000520aba2, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 1 len: 5 tx.options 0x00
12:11:11:601 	asdu (length: 5): 104e000000
12:11:11:614 Poll APS confirm 91 status: 0x00
12:11:11:615 Erase task req-id: 91, type: 19 zcl seqno: 78 send time 0, profileId: 0x0104, clusterId: 0x0006
12:11:11:615 APS-DATA.confirm id: 91, status: 0x00 SUCCESS
12:11:11:616 APS-DATA.confirm request id: 91 -> erase from queue
12:11:11:644 aps request id: 91 finished, erase from queue
12:11:11:650 APS-DATA.indication srcAddr: 0x5c5d, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 255, rssi: -46
12:11:11:651 	asdu: 184e010000001000
12:11:11:651 Node data 0x00158d000520aba2 profileId: 0x0104, clusterId: 0x0006
12:11:11:652 0x00158D000520ABA2: update ZCL value 0x01/0x0006/0x0000 after 0 s
12:11:11:658 Websocket 172.17.0.1:33800 send message: {"attr":{"colorcapabilities":16,"ctmax":65279,"ctmin":null,"id":"36","lastannounced":"2021-07-14T10:40:29Z","lastseen":"2022-02-19T12:11Z","manufacturername":"LUMI","modelid":"lumi.light.aqcn02","name":"Lamp Hal Beneden","swversion":"1.23","type":"Color temperature light","uniqueid":"00:15:8d:00:05:20:ab:a2-01"},"e":"changed","id":"36","r":"lights","t":"event","uniqueid":"00:15:8d:00:05:20:ab:a2-01"} (ret = 403)
12:11:11:878 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -79
12:11:11:879 	asdu: 18550a0805210001
12:11:12:646 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:12:646 	payload: 0805210001
12:11:12:655 Websocket 172.17.0.1:33800 send message: {"attr":{"id":"3","lastannounced":null,"lastseen":"2022-02-19T12:11Z","manufacturername":"_TZ3000_w0qqde0g","modelid":"TS011F","name":"On/Off plug-in unit 3","swversion":null,"type":"On/Off plug-in unit","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01"},"e":"changed","id":"3","r":"lights","t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01"} (ret = 333)
12:11:12:656 Websocket 172.17.0.1:33800 send message: {"attr":{"id":"284","lastannounced":null,"lastseen":"2022-02-19T12:11Z","manufacturername":"_TZ3000_w0qqde0g","modelid":"TS011F","name":"Power 284","swversion":null,"type":"ZHAPower","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"},"e":"changed","id":"284","r":"sensors","t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 325)
12:11:12:658 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":256,"lastupdated":"2022-02-19T12:11:11.881","power":47,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:11:12:684 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -80
12:11:12:685 	asdu: 18560a0b05292900
12:11:13:271 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:13:271 	payload: 0b05292900
12:11:13:272 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":256,"lastupdated":"2022-02-19T12:11:12.690","power":41,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:11:13:281 APS-DATA.indication srcAddr: 0xdb67, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0400, lqi: 255, rssi: -71
12:11:13:282 	asdu: 18730a000021d652
12:11:13:283 Node data 0x04cf8cdf3c7d1330 profileId: 0x0104, clusterId: 0x0400
12:11:13:283 0x04CF8CDF3C7D1330: update ZCL value 0x01/0x0400/0x0000 after 0 s
12:11:13:284 [INFO] - No button map for: lumi.sen_ill.mgl01, unicast to: 0x0000, endpoint: 0x01, cluster: 0x0400, command: 0x0A, payload: 000021D652, zclSeq: 115
12:11:13:285 ZCL attribute report 0x04CF8CDF3C7D1330 for cluster: 0x0400, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:13:285 	payload: 000021d652
12:11:13:286 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"260","r":"sensors","state":{"dark":false,"daylight":true,"lastupdated":"2022-02-19T12:11:13.284","lightlevel":21206,"lux":132},"t":"event","uniqueid":"04:cf:8c:df:3c:7d:13:30-01-0400"} (ret = 205)
12:11:13:600 Daylight now: solarNoon, status: 170, daylight: 1, dark: 0
12:11:13:601 Skip idle timer callback, too early: elapsed 940 msec
12:11:13:904 poll node 00:15:8d:00:05:20:e7:c9-01
12:11:13:904 Poll light node Lamp Dasha
12:11:13:951 read attributes of 0x00158D000520E7C9 cluster: 0x0006: [ 
12:11:13:952 0x0000 
12:11:13:952 ]
12:11:13:953 add task 4472 type 19 to 0x00158D000520E7C9 cluster 0x0006 req.id 102
12:11:13:953 Poll APS request 102 to 0x00158D000520E7C9 cluster: 0x0006
12:11:13:999 APS-DATA.request id: 102, addrmode: 0x03, addr: 0x00158d000520e7c9, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 1 len: 5 tx.options 0x00
12:11:13:000 	asdu (length: 5): 104f000000
12:11:14:014 Poll APS confirm 102 status: 0x00
12:11:14:015 Erase task req-id: 102, type: 19 zcl seqno: 79 send time 0, profileId: 0x0104, clusterId: 0x0006
12:11:14:015 APS-DATA.confirm id: 102, status: 0x00 SUCCESS
12:11:14:016 APS-DATA.confirm request id: 102 -> erase from queue
12:11:14:048 APS-DATA.indication srcAddr: 0x7c3a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 255, rssi: -77
12:11:14:049 	asdu: 184f010000001000
12:11:14:049 APS-DATA.request id: 102 erase from queue
12:11:14:050 Node data 0x00158d000520e7c9 profileId: 0x0104, clusterId: 0x0006
12:11:14:051 0x00158D000520E7C9: update ZCL value 0x01/0x0006/0x0000 after 0 s
12:11:14:058 Websocket 172.17.0.1:33800 send message: {"attr":{"id":"285","lastannounced":null,"lastseen":"2022-02-19T12:11Z","manufacturername":"LUMI","modelid":"lumi.sen_ill.mgl01","name":"LightLevel 285","swversion":"1.23","type":"ZHALightLevel","uniqueid":"00:15:8d:00:05:20:e7:c9-01-0400"},"e":"changed","id":"285","r":"sensors","t":"event","uniqueid":"00:15:8d:00:05:20:e7:c9-01-0400"} (ret = 337)
12:11:14:061 Websocket 172.17.0.1:33800 send message: {"attr":{"id":"22","lastannounced":"2022-02-18T17:45:22Z","lastseen":"2022-02-19T12:11Z","manufacturername":"LUMI","modelid":"lumi.sen_ill.mgl01","name":"Lamp Dasha","swversion":"1.23","type":"Color dimmable light","uniqueid":"00:15:8d:00:05:20:e7:c9-01"},"e":"changed","id":"22","r":"lights","t":"event","uniqueid":"00:15:8d:00:05:20:e7:c9-01"} (ret = 345)
12:11:14:332 read attributes of 0x00158D000520E7C9 cluster: 0x0300: [ 
12:11:14:333 0x0008 
12:11:14:333 0x400B 
12:11:14:333 0x400C 
12:11:14:334 ]
12:11:14:334 add task 4475 type 19 to 0x00158D000520E7C9 cluster 0x0300 req.id 106
12:11:14:334 Poll APS request 106 to 0x00158D000520E7C9 cluster: 0x0300
12:11:14:400 APS-DATA.request id: 106, addrmode: 0x03, addr: 0x00158d000520e7c9, profile: 0x0104, cluster: 0x0300, ep: 0x01 -> 0x01 queue: 1 len: 9 tx.options 0x00
12:11:14:400 	asdu (length: 9): 10500008000b400c40
12:11:14:428 Poll APS confirm 106 status: 0x00
12:11:14:429 Erase task req-id: 106, type: 19 zcl seqno: 80 send time 0, profileId: 0x0104, clusterId: 0x0300
12:11:14:429 APS-DATA.confirm id: 106, status: 0x00 SUCCESS
12:11:14:429 APS-DATA.confirm request id: 106 -> erase from queue
12:11:14:465 APS-DATA.indication srcAddr: 0x7c3a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0300, lqi: 255, rssi: -77
12:11:14:466 	asdu: 18500108000030010b40002100000c400021fffe
12:11:14:466 APS-DATA.request id: 106 erase from queue
12:11:14:466 Node data 0x00158d000520e7c9 profileId: 0x0104, clusterId: 0x0300
12:11:14:467 0x00158D000520E7C9: update ZCL value 0x01/0x0300/0x0008 after 0 s
12:11:14:468 0x00158D000520E7C9: update ZCL value 0x01/0x0300/0x400B after 0 s
12:11:14:468 0x00158D000520E7C9: update ZCL value 0x01/0x0300/0x400C after 0 s
12:11:14:869 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -79
12:11:14:870 	asdu: 18570a0b05292d00
12:11:16:820 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:16:820 	payload: 0b05292d00
12:11:16:829 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":256,"lastupdated":"2022-02-19T12:11:14.872","power":45,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:11:16:832 poll node 00:15:8d:00:05:20:a8:38-01
12:11:16:833 Poll light node Lamp Hal Zolder
12:11:16:884 read attributes of 0x00158D000520A838 cluster: 0x0006: [ 
12:11:16:885 0x0000 
12:11:16:885 ]
12:11:16:885 add task 4479 type 19 to 0x00158D000520A838 cluster 0x0006 req.id 112
12:11:16:886 Poll APS request 112 to 0x00158D000520A838 cluster: 0x0006
12:11:16:924 APS-DATA.request id: 112, addrmode: 0x03, addr: 0x00158d000520a838, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 1 len: 5 tx.options 0x00
12:11:16:925 	asdu (length: 5): 1051000000
12:11:16:940 Poll APS confirm 112 status: 0x00
12:11:16:941 Erase task req-id: 112, type: 19 zcl seqno: 81 send time 0, profileId: 0x0104, clusterId: 0x0006
12:11:16:941 APS-DATA.confirm id: 112, status: 0x00 SUCCESS
12:11:16:942 APS-DATA.confirm request id: 112 -> erase from queue
12:11:16:967 APS-DATA.indication srcAddr: 0x9949, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 255, rssi: -77
12:11:16:968 	asdu: 1851010000001000
12:11:16:968 APS-DATA.request id: 112 erase from queue
12:11:16:969 Node data 0x00158d000520a838 profileId: 0x0104, clusterId: 0x0006
12:11:16:969 0x00158D000520A838: update ZCL value 0x01/0x0006/0x0000 after 0 s
12:11:17:399 APS-DATA.indication srcAddr: 0xdb67, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0400, lqi: 255, rssi: -71
12:11:17:400 	asdu: 18800a000021f752
12:11:17:400 Node data 0x04cf8cdf3c7d1330 profileId: 0x0104, clusterId: 0x0400
12:11:17:401 0x04CF8CDF3C7D1330: update ZCL value 0x01/0x0400/0x0000 after 0 s
12:11:17:402 [INFO] - No button map for: lumi.sen_ill.mgl01, unicast to: 0x0000, endpoint: 0x01, cluster: 0x0400, command: 0x0A, payload: 000021F752, zclSeq: 128
12:11:17:403 ZCL attribute report 0x04CF8CDF3C7D1330 for cluster: 0x0400, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:17:403 	payload: 000021f752
12:11:17:415 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"260","r":"sensors","state":{"dark":false,"daylight":true,"lastupdated":"2022-02-19T12:11:17.401","lightlevel":21239,"lux":133},"t":"event","uniqueid":"04:cf:8c:df:3c:7d:13:30-01-0400"} (ret = 205)
12:11:17:779 Skip idle timer callback, too early: elapsed 945 msec
12:11:17:879 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -79
12:11:17:880 	asdu: 18580a0b05292700
12:11:18:327 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
12:11:18:328 	payload: 0b05292700
12:11:18:334 Websocket 172.17.0.1:33800 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":256,"lastupdated":"2022-02-19T12:11:17.882","power":39,"voltage":233},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
12:11:18:336 poll node 58:8e:81:ff:fe:d3:8e:bc-01
12:11:18:337 Poll light node Lamp Woonkamer
12:11:18:388 read attributes of 0x588E81FFFED38EBC cluster: 0x0006: [ 
12:11:18:388 0x0000 
12:11:18:389 ]
12:11:18:389 add task 4486 type 19 to 0x588E81FFFED38EBC cluster 0x0006 req.id 122
12:11:18:390 Poll APS request 122 to 0x588E81FFFED38EBC cluster: 0x0006
12:11:18:428 APS-DATA.request id: 122, addrmode: 0x03, addr: 0x588e81fffed38ebc, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 1 len: 5 tx.options 0x00
12:11:18:429 	asdu (length: 5): 1052000000
12:11:18:443 Poll APS confirm 122 status: 0x00
12:11:18:444 Erase task req-id: 122, type: 19 zcl seqno: 82 send time 0, profileId: 0x0104, clusterId: 0x0006
12:11:18:445 APS-DATA.confirm id: 122, status: 0x00 SUCCESS
12:11:18:446 APS-DATA.confirm request id: 122 -> erase from queue
12:11:18:467 APS-DATA.indication srcAddr: 0xc898, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 255, rssi: -50
12:11:18:468 	asdu: 1852010000001000
12:11:18:468 APS-DATA.request id: 122 erase from queue
12:11:18:469 Node data 0x588e81fffed38ebc profileId: 0x0104, clusterId: 0x0006
12:11:18:469 0x588E81FFFED38EBC: update ZCL value 0x01/0x0006/0x0000 after 0 s
12:11:18:493 aps request id: 224 prf: 0x0000 cl: 0x0031 timeout (confirmed: 1) to 0x00158D000530371F (0xDD82)
12:11:18:572 aps request id: 224 finished, erase from queue
12:11:19:051 APS-DATA.request id: 126, addrmode: 0x03, addr: 0x00158d000520ab43, profile: 0x0000, cluster: 0x0031, ep: 0x00 -> 0x00 queue: 0 len: 2 tx.options 0x00
12:11:19:052 	asdu (length: 2): 0d00
12:11:19:066 APS-DATA.confirm id: 126, status: 0x00 SUCCESS
12:11:19:067 APS-DATA.confirm request id: 126 -> confirmed, timeout -1631700843
12:11:19:257 poll node 00:15:8d:00:05:30:37:1f-01
12:11:19:257 Poll light node Lamp Badkamer
12:11:19:305 read attributes of 0x00158D000530371F cluster: 0x0006: [ 
12:11:19:306 0x0000

iisworks · February 19, 2022, 7:15pm

Some additional logging of these “microstutters” lasting 6-7s. During that time there is no L2 logging at all, and it coinciding exactly with the deconz ui temporarily hanging and high general memory usage of the container. Also no updates are coming through in the api. Deconz momentarily just freezes completely. Again: without the plugs & DDF I never noticed this behavior!

Anyone got a clue what could cause this? This can’t be caused by devices themselves, can it? It really feels like a deconz bug!

Just check these 2 log sections (6s gap indicated by *******************):

19:01:47:600 Poll APS request to 0xBC33ACFFFE2BF652 cluster: 0x0006 dropped, values are fresh enough
19:01:48:600 poll node 00:15:8d:00:05:20:f4:43-01
19:01:48:601 Poll light node Lamp JH
19:01:48:601 Idle timer triggered
19:01:48:602 Force read attributes for ZHATemperature SensorNode Diepvries T
19:01:48:602 don't create binding for attribute reporting of sensor Diepvries T
19:01:48:603 Force binding of attribute reporting for node Diepvries T
19:01:48:651 read attributes of 0x00158D000520F443 cluster: 0x0006: [ 
19:01:48:651 0x0000 
19:01:48:652 ]
19:01:48:652 add task 40388 type 19 to 0x00158D000520F443 cluster 0x0006 req.id 23
19:01:48:652 Poll APS request 23 to 0x00158D000520F443 cluster: 0x0006
19:01:48:700 APS-DATA.request id: 23, addrmode: 0x03, addr: 0x00158d000520f443, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 0 len: 5 tx.options 0x00
19:01:48:700 	asdu (length: 5): 10bf000000
19:01:48:714 Poll APS confirm 23 status: 0x00
19:01:48:715 Erase task req-id: 23, type: 19 zcl seqno: 191 send time 0, profileId: 0x0104, clusterId: 0x0006
19:01:48:715 APS-DATA.confirm id: 23, status: 0x00 SUCCESS
19:01:48:715 APS-DATA.confirm request id: 23 -> erase from queue
19:01:48:748 aps request id: 23 finished, erase from queue
19:01:48:766 APS-DATA.indication srcAddr: 0x27b3, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 255, rssi: -71
19:01:48:766 	asdu: 18bf010000001001
19:01:48:767 Node data 0x00158d000520f443 profileId: 0x0104, clusterId: 0x0006
19:01:48:767 0x00158D000520F443: update ZCL value 0x01/0x0006/0x0000 after 0 s
19:01:48:769 Websocket 172.17.0.1:59858 send message: {"attr":{"colorcapabilities":16,"ctmax":65279,"ctmin":null,"id":"28","lastannounced":"2022-02-01T06:11:04Z","lastseen":"2022-02-19T19:01Z","manufacturername":"LUMI","modelid":"lumi.light.aqcn02","name":"Lamp JH","swversion":"11-22-2018","type":"Color temperature light","uniqueid":"00:15:8d:00:05:20:f4:43-01"},"e":"changed","id":"28","r":"lights","t":"event","uniqueid":"00:15:8d:00:05:20:f4:43-01"} (ret = 400)
19:01:48:847 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -83
19:01:48:848 	asdu: 18500a080521f000
*******************
19:01:54:779 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
19:01:54:780 	payload: 080521f000
19:01:54:783 Websocket 172.17.0.1:59858 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":240,"lastupdated":"2022-02-19T19:01:48.850","power":39,"voltage":224},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
19:01:54:784 read attributes of 0x00158D000520F443 cluster: 0x0008: [ 
19:01:54:785 0x0000 
19:01:54:785 ]
19:01:54:785 add task 40390 type 19 to 0x00158D000520F443 cluster 0x0008 req.id 27
19:01:54:786 Poll APS request 27 to 0x00158D000520F443 cluster: 0x0008
19:01:54:787 Daylight now: nightStart, status: 230, daylight: 0, dark: 1
19:01:54:796 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 236, rssi: -85
19:01:54:797 	asdu: 18510a0b05292500
19:01:55:166 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
19:01:55:166 	payload: 0b05292500
19:01:55:168 Websocket 172.17.0.1:59858 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":240,"lastupdated":"2022-02-19T19:01:54.799","power":37,"voltage":224},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
19:01:55:170 APS-DATA.request id: 27, addrmode: 0x03, addr: 0x00158d000520f443, profile: 0x0104, cluster: 0x0008, ep: 0x01 -> 0x01 queue: 0 len: 5 tx.options 0x00
19:01:55:170 	asdu (length: 5): 10c0000000
19:01:55:175 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 244, rssi: -85
19:01:55:175 	asdu: 18520a0805210b01
19:01:56:037 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
19:01:56:037 	payload: 0805210b01
19:01:56:038 Websocket 172.17.0.1:59858 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":267,"lastupdated":"2022-02-19T19:01:55.177","power":37,"voltage":224},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
19:01:56:041 Idle timer triggered
19:01:56:042 binding for attribute reporting SensorNode JH of cluster 0x0406 seems to be active
19:01:56:042 Force read attributes for ZHAPresence SensorNode JH

and:

19:02:00:667 add task 40408 type 19 to 0x00158D000520ABA2 cluster 0x0006 req.id 56
19:02:00:667 Poll APS request 56 to 0x00158D000520ABA2 cluster: 0x0006
19:02:00:709 APS-DATA.request id: 56, addrmode: 0x03, addr: 0x00158d000520aba2, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 1 len: 5 tx.options 0x00
19:02:00:710 	asdu (length: 5): 10c3000000
19:02:00:723 Poll APS confirm 56 status: 0x00
19:02:00:724 Erase task req-id: 56, type: 19 zcl seqno: 195 send time 0, profileId: 0x0104, clusterId: 0x0006
19:02:00:724 APS-DATA.confirm id: 56, status: 0x00 SUCCESS
19:02:00:725 APS-DATA.confirm request id: 56 -> erase from queue
19:02:00:733 APS-DATA.indication srcAddr: 0x5c5d, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 255, rssi: -43
19:02:00:734 	asdu: 18c3010000001000
19:02:00:734 APS-DATA.request id: 56 erase from queue
19:02:00:734 Node data 0x00158d000520aba2 profileId: 0x0104, clusterId: 0x0006
19:02:00:735 0x00158D000520ABA2: update ZCL value 0x01/0x0006/0x0000 after 0 s
19:02:00:737 Websocket 172.17.0.1:59858 send message: {"attr":{"colorcapabilities":16,"ctmax":65279,"ctmin":null,"id":"36","lastannounced":"2021-07-14T10:40:29Z","lastseen":"2022-02-19T19:02Z","manufacturername":"LUMI","modelid":"lumi.light.aqcn02","name":"Lamp Hal Beneden","swversion":"1.23","type":"Color temperature light","uniqueid":"00:15:8d:00:05:20:ab:a2-01"},"e":"changed","id":"36","r":"lights","t":"event","uniqueid":"00:15:8d:00:05:20:ab:a2-01"} (ret = 403)
19:02:01:420 APS-DATA.indication srcAddr: 0xdd82, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x000A, lqi: 255, rssi: -64
19:02:01:421 	asdu: 102e000000
19:02:01:423 APS-DATA.request id: 62, addrmode: 0x02, addr: 0xdd82, profile: 0x0104, cluster: 0x000A, ep: 0x01 -> 0x01 queue: 1 len: 11 tx.options 0x00
19:02:01:423 	asdu (length: 11): 182e01000000e229fba329
19:02:01:436 APS-DATA.confirm id: 62, status: 0x00 SUCCESS
19:02:01:437 APS-DATA.confirm request id: 62 -> erase from queue
19:02:01:500 aps request id: 62 finished, erase from queue
19:02:01:600 Daylight now: nightStart, status: 230, daylight: 0, dark: 1
19:02:01:675 poll node 00:15:8d:00:05:20:e7:c9-01
19:02:01:676 Poll light node Lamp Dasha
19:02:01:728 read attributes of 0x00158D000520E7C9 cluster: 0x0006: [ 
19:02:01:729 0x0000 
19:02:01:729 ]
19:02:01:730 add task 40413 type 19 to 0x00158D000520E7C9 cluster 0x0006 req.id 64
19:02:01:730 Poll APS request 64 to 0x00158D000520E7C9 cluster: 0x0006
19:02:01:800 APS-DATA.request id: 64, addrmode: 0x03, addr: 0x00158d000520e7c9, profile: 0x0104, cluster: 0x0006, ep: 0x01 -> 0x01 queue: 1 len: 5 tx.options 0x00
19:02:01:800 	asdu (length: 5): 10c4000000
19:02:01:815 Poll APS confirm 64 status: 0x00
19:02:01:816 Erase task req-id: 64, type: 19 zcl seqno: 196 send time 0, profileId: 0x0104, clusterId: 0x0006
19:02:01:816 APS-DATA.confirm id: 64, status: 0x00 SUCCESS
19:02:01:817 APS-DATA.confirm request id: 64 -> erase from queue
19:02:01:820 aps request id: 64 finished, erase from queue
19:02:01:859 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -81
19:02:01:860 	asdu: 18580a080521fe00
*******************
19:02:08:059 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
19:02:08:060 	payload: 080521fe00
19:02:08:063 Websocket 172.17.0.1:59858 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":254,"lastupdated":"2022-02-19T19:02:01.862","power":40,"voltage":224},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
19:02:08:068 Idle timer triggered
19:02:08:071 Force read attributes for ZHAPower SensorNode Power 289
19:02:08:072 Force binding of attribute reporting for node Power 289
19:02:08:103 GW firmware version: 0x26720700
19:02:08:103 GW firmware version is up to date: 0x26720700
19:02:08:114 APS-DATA.indication srcAddr: 0x7c3a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0006, lqi: 255, rssi: -83
19:02:08:115 	asdu: 18c4010000001001
19:02:08:115 Node data 0x00158d000520e7c9 profileId: 0x0104, clusterId: 0x0006
19:02:08:121 0x00158D000520E7C9: update ZCL value 0x01/0x0006/0x0000 after 0 s
19:02:08:127 Websocket 172.17.0.1:59858 send message: {"attr":{"id":"285","lastannounced":null,"lastseen":"2022-02-19T19:02Z","manufacturername":"LUMI","modelid":"lumi.sen_ill.mgl01","name":"LightLevel 285","swversion":"1.23","type":"ZHALightLevel","uniqueid":"00:15:8d:00:05:20:e7:c9-01-0400"},"e":"changed","id":"285","r":"sensors","t":"event","uniqueid":"00:15:8d:00:05:20:e7:c9-01-0400"} (ret = 337)
19:02:08:129 Websocket 172.17.0.1:59858 send message: {"attr":{"id":"22","lastannounced":"2022-02-18T17:45:22Z","lastseen":"2022-02-19T19:02Z","manufacturername":"LUMI","modelid":"lumi.sen_ill.mgl01","name":"Lamp Dasha","swversion":"1.23","type":"Color dimmable light","uniqueid":"00:15:8d:00:05:20:e7:c9-01"},"e":"changed","id":"22","r":"lights","t":"event","uniqueid":"00:15:8d:00:05:20:e7:c9-01"} (ret = 345)
19:02:08:131 APS-DATA.indication srcAddr: 0xf25a, srcEp: 0x01 dstAddrMode: 2, profile: 0x0104, cluster: 0x0B04, lqi: 255, rssi: -82
19:02:08:132 	asdu: 18590a0b05292500
19:02:08:701 ZCL attribute report 0xA4C138D6A824F918 for cluster: 0x0B04, ep: 0x01, frame control: 0x18, mfcode: 0x0000 
19:02:08:702 	payload: 0b05292500
19:02:08:703 Websocket 172.17.0.1:59858 send message: {"e":"changed","id":"284","r":"sensors","state":{"current":254,"lastupdated":"2022-02-19T19:02:08.134","power":37,"voltage":224},"t":"event","uniqueid":"a4:c1:38:d6:a8:24:f9:18-01-0b04"} (ret = 186)
19:02:08:705 read attributes of 0x00158D000520E7C9 cluster: 0x0008: [ 
19:02:08:706 0x0000 
19:02:08:706 ]
19:02:08:707 add task 40416 type 19 to 0x00158D000520E7C9 cluster 0x0008 req.id 70
19:02:08:707 Poll APS request 70 to 0x00158D000520E7C9 cluster: 0x0008
19:02:08:707 DB save zll database items 0x00000081

iisworks · February 21, 2022, 8:08pm

I decided to start from scratch yesterday with an empty DB so I reset the GW! I eventually added 46 devices: Aqara bulbs, motion/temp/door sensors. Encountered a lot of pairing issues somehow, with devices showing up partially with many separate orphaned devices etc. A lot of repairing attempts and deconz restarts were needed. I created several DB backups during setup phases.

When everything was stabIe I added a few of the new Tuya plugs as a test, and immediately noticed deconz getting slow again, with the hangs/pauses as described above. I also tried using the BW-SHP15 plugs (DDF in Silver mode), and although that went better for a while similar delays occurred the day after. After restoring the DB all was stable again. BTW: I used the 3 plugs for PCs, so the measurements do change a lot.

Does anyone have a clue what could be going on, looking at the logs from the posts above? I am 95% sure it’s some kind of bug or weird coincidence, because it really only happens when I add the new plugs with DDF. Otherwise it’s fast, responsive and runs 100% reliable for weeks. Could this in any way be caused by devices themselves, without any evidence showing up in the logs? Or is that highly unlikely (I did test with different plugs, I have 15 of them).

Maybe @manup or @Smanar have an idea what could be causing this, looking at the L2 logs?
Or maybe @Mimiix knows anyone else I could ask? I am really at my wits end with this…

Smanar · February 22, 2022, 5:58pm

And still the database growing issue ?
The _TZ3000_mraovvmm is the plug with issue.
And you have other SHP15 without issue ?

So we can search someone else using too the _TZ3000_mraovvmm ?

iisworks · February 22, 2022, 6:37pm

I have 3 types of plugs (19 in total).

_TZ3000_mraovvmm (BW-SHP15)
_TZ3000_w0qqde0g (Compact orange plug , Updated 74 FW)
_TZ3000_gjnozsaz (Compact orange plug - New model, Updated 74 FW)

With the last 2 I noticed slowness issues immediately after pairing in DDF Silver mode.
The SHP15 (_TZ3000_mraovvmm) looked fine initially, but I did notice issues after a day. I did see DB growing, but not due to duplicate index issues. I quickly took the plugs out of the network and restored a working DB from before the plugs were added.

Can device hardware cause issues? I also tested with different individual plugs of the same type, with the same issues, so it’s not like one is defective.

Is there anything strange with the logs pasted in post 34 and 35?

Smanar · February 23, 2022, 4:14pm

And you have only DDF file for the _TZ3000_w0qqde0g ? this one https://github.com/dresden-elektronik/deconz-rest-plugin/pull/5577/files

Or you have too edited the file to have 2 more DDF for the 2 others manufacture ?

Probably nothing to see, but it seem there is an issue ATM with device selecting https://github.com/dresden-elektronik/deconz-rest-plugin/pull/5789

If you are using more than 1 DDF, try remove 2 of them.

Can device hardware cause issues? I also tested with different individual plugs of the same type, with the same issues, so it’s not like one is defective.

I realy don’t know what to say, I don’t think it’s hardware, but you are not the only one using plug but the only one with this kind of bugs.
And I realy don’t see how you can have this result on the database.

iisworks · February 23, 2022, 4:33pm

I think the DB issue was the result rather than the cause of the issue.

I was seeing the issues when using just the built-in _TZ3000_w0qqde0g DDF you mentioned. But note that I updated these plugs with a new Tuya FW Appversion 74, which maybe not many others have yet done. That FW enables reporting and fixes On/Off memory. With the previous FW they were polling only.

I guess I will have to wait and see how this plays out for others…

[Update] I may try a restore on a Pi 4 + another Conbee II stick I have laying around. That should at least rule out deconz runnig in Docker on the Synology as a potential cause. Although as mentioned I don’t have any issues on Docker without the plugs…

Smanar · February 24, 2022, 4:56pm

I think the DB issue was the result rather than the cause of the issue.

Yes, but from the code it can’t happen, so there is already something bad here.

So if you use only the DDF for the _TZ3000_w0qqde0g in a “normal world” it need to be skipped for the problematic plugs, so can be better with the swoop correction that prevent bad DDF be seletected.

Ha yes, can be a good idea to test on another hardware, to be sure it’s not from the OS (a library version)

Mimiix · March 2, 2022, 11:00am

A post was split to a new topic: Xiaomi bulbs do not respond after backup and restore of Phoscon Backup

iisworks · March 5, 2022, 2:34pm

I went ahead and copied a backup to a Pi 4 with another Conbee II stick and restored the backup of 2.14.1. And low and behold: even after adding a bunch of Tuya plugs it all seems to keep working fine!

So somehow there is a combination of factors that causes issues only in Deconz running as a Docker container on my Synology NAS. I am wondering what could be that different in the Docker image, and what can explain the problems only after I add Tuya plugs to the equation? Any clues?

[Update] While it’s not a solution for the issue with deconz running in Docker, I’m marking it as a solution since it works on my Pi4.

iisworks · March 18, 2022, 1:01pm

Another update: I also tested with 2.15 beta, hoping that that would solve it but unfortunately, on my NAS in Docker still the same problem. Now I am really starting to think it’s the Docker Base OS. I did a full restore of the fully working Pi4 gateway backup.

I asked the owner of the community docker (GitHub - deconz-community/deconz-docker) repo, but he replied he does not know exactly how to build a version with a new/other base OS? is there anyone here who knows how that works? And I was also wondering if it has been considered to offer an officially endorsed Docker image, much like the pre-built SD Card image for Pi?

iisworks · June 4, 2022, 7:06am

[Update 06/22]
After having used the Pi4 for a few months without any issues I decided to play around with macvlan network a bit. And low and behold: that solved the weird delay issues with deconz in combination with the Tuya plugs.

I added a “macvlan” network to Docker and reconnected the same deconz container to that network instead of the default “bridged” one! The added benefit is that this also allows for a dedicated IP per container, which means less hassle with port conflicts. Something like: How to setup and use a Docker MacVLAN network on a Synology | Sysop's blog

I can’t really explain why this solves this specific issue, but it did and I can turn off the Pi4 for now!

I prefer the DSM docker solution because it means easier setup/upgrade (just download latest and reset the container), automatic backup of the database and less maintenance. in general.