mfucci
commented
2 years ago Pull request https://github.com/mfucci/node-matter/pull/13 should fix this issue since this is related to read attribute wildcards not handled.
Closed jdesai61 closed 1 year ago
mfucci
commented
2 years ago Pull request https://github.com/mfucci/node-matter/pull/13 should fix this issue since this is related to read attribute wildcards not handled.
jdesai61
commented
2 years ago Pull request #13 does not completely fix this issue. I see more messages in HA now after the 'Cleanup' line (compared to before)...
2022-08-03 22:42:56 77f1785d-matter-server chip.CTL[121] INFO Received CommissioningComplete response, errorCode=0
2022-08-03 22:42:56 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'SendComplete'
2022-08-03 22:42:56 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'SendComplete' -> 'Cleanup'
2022-08-03 22:42:56 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'Cleanup'
2022-08-03 22:42:56 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'Cleanup'
2022-08-03 22:42:56 77f1785d-matter-server chip.IN[121] INFO Prepared secure message 0x7f5be77fcda8 to 0x00000000000010EF (1) of type 0x10 and protocolId (0, 0) on exchange 29568i with MessageCounter:27426691.
2022-08-03 22:42:56 77f1785d-matter-server chip.IN[121] INFO Sending encrypted msg 0x7f5be77fcda8 with MessageCounter:27426691 to 0x00000000000010EF (1) at monotonic time: 00000000125A37B0 msec
2022-08-03 22:42:56 77f1785d-matter-server matter_server.server.server[121] INFO [140032684332464] Deserialized message: CommandMessage(messageId='f4dc6d1d210e4dcd8c9540367f602086', command='device_controller.ResolveNode', args={'nodeid': 4335})
2022-08-03 22:42:56 77f1785d-matter-server matter_server.server.server[121] INFO [140032684332464] Deserialized message: CommandMessage(messageId='c79c0d655f7d439f99738b9c0fe5b590', command='device_controller.Read', args={'nodeid': 4335, 'attributes': '*', 'dataVersionFilters': None, 'events': '*', 'returnClusterObject': True, 'reportInterval': None, 'fabricFiltered': True, 'keepSubscriptions': False})
2022-08-03 22:42:56 77f1785d-matter-server chip.IN[121] INFO Prepared secure message 0x7f5bd402f3d8 to 0x00000000000010EF (1) of type 0x2 and protocolId (0, 1) on exchange 29569i with MessageCounter:27426692.
2022-08-03 22:42:56 77f1785d-matter-server chip.IN[121] INFO Sending encrypted msg 0x7f5bd402f3d8 with MessageCounter:27426692 to 0x00000000000010EF (1) at monotonic time: 00000000125A37BD msec
2022-08-03 22:42:56 77f1785d-matter-server chip.EM[121] INFO Received message of type 0x5 with protocolId (0, 1) and MessageCounter:2746782166 on exchange 29569i
2022-08-03 22:42:56 77f1785d-matter-server chip.IN[121] INFO Prepared secure message 0x7f5be77fcda8 to 0x00000000000010EF (1) of type 0x10 and protocolId (0, 0) on exchange 29569i with MessageCounter:27426693.
2022-08-03 22:42:56 77f1785d-matter-server chip.IN[121] INFO Sending encrypted msg 0x7f5be77fcda8 with MessageCounter:27426693 to 0x00000000000010EF (1) at monotonic time: 00000000125A37CA msecBut I don't see the device in HA... here is what I see from node-matter (don't see any further read requests than before)
my s0Qname=_S0._sub._matterc._udp.local
Matter server listening
Pase: Received pairing request from udp://192.168.1.57:57969
Pase: Paired succesfully with udp://192.168.1.57:57969
Received read request from udp://192.168.1.57:57969 on session secure/12390: */49/65532, 0/48/0, 0/48/1, 0/48/2, 0/48/3, 0/40/2, 0/40/4, */49/3
Received invoke request from udp://192.168.1.57:57969 on session secure/12390: 0/48/0
Received invoke request from udp://192.168.1.57:57969 on session secure/12390: 0/48/2
Received invoke request from udp://192.168.1.57:57969 on session secure/12390: 0/62/2
Received invoke request from udp://192.168.1.57:57969 on session secure/12390: 0/62/2
Received invoke request from udp://192.168.1.57:57969 on session secure/12390: 0/62/0
Received invoke request from udp://192.168.1.57:57969 on session secure/12390: 0/62/4
Received invoke request from udp://192.168.1.57:57969 on session secure/12390: 0/62/11
Received invoke request from udp://192.168.1.57:57969 on session secure/12390: 0/62/6
Case: Received pairing request from udp://192.168.1.57:57969
Case: Paired succesfully with udp://192.168.1.57:57969
Received invoke request from udp://192.168.1.57:57969 on session secure/12391: 0/48/4
Received read request from udp://192.168.1.57:57969 on session secure/12391: */*/*After enabling debug logs on HA, here is what I am seeing. Not sure what ResolveNode does...
2022-08-04 11:36:49 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'SendComplete' -> 'Cleanup'
2022-08-04 11:36:49 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'Cleanup'
2022-08-04 11:36:49 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'Cleanup'
2022-08-04 11:36:49 77f1785d-matter-server chip.IN[121] INFO Prepared secure message 0x7f64caffbda8 to 0x00000000000010F2 (1) of type 0x10 and protocolId (0, 0) on exchange 51172i with MessageCounter:246117618.
2022-08-04 11:36:49 77f1785d-matter-server chip.IN[121] INFO Sending encrypted msg 0x7f64caffbda8 with MessageCounter:246117618 to 0x00000000000010F2 (1) at monotonic time: 00000000151EBB33 msec
2022-08-04 11:36:49 77f1785d-matter-server matter_server.server.server[121] DEBUG [140070856632400] Sending {"messageId": "30431277a2164fd4bc44ecff4430b96d", "result": {"raw": true}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-08-04 11:36:49 77f1785d-matter-server matter_server.server.server[121] DEBUG [140070856632400] Received: {"messageId": "4777a91cef454e7aae41d094df987359", "command": "device_controller.ResolveNode", "args": {"nodeid": 4338}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-08-04 11:36:49 77f1785d-matter-server matter_server.server.server[121] INFO [140070856632400] Deserialized message: CommandMessage(messageId='4777a91cef454e7aae41d094df987359', command='device_controller.ResolveNode', args={'nodeid': 4338})
2022-08-04 11:36:49 77f1785d-matter-server matter_server.server.server[121] DEBUG [140070856632400] Received CommandMessage(messageId='4777a91cef454e7aae41d094df987359', command='device_controller.ResolveNode', args={'nodeid': 4338})
2022-08-04 11:36:49 77f1785d-matter-server matter_server.server.server[121] DEBUG [140070856632400] Sending {"messageId": "4777a91cef454e7aae41d094df987359", "result": {"raw": null}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-08-04 11:36:49 77f1785d-matter-server matter_server.server.server[121] DEBUG [140070856632400] Received: {"messageId": "54429f8a79f84a3c93016617df87c67c", "command": "device_controller.Read", "args": {"nodeid": 4338, "attributes": "*", "dataVersionFilters": null, "events": "*", "returnClusterObject": true, "reportInterval": null, "fabricFiltered": true, "keepSubscriptions": false}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-08-04 11:36:49 77f1785d-matter-server matter_server.server.server[121] INFO [140070856632400] Deserialized message: CommandMessage(messageId='54429f8a79f84a3c93016617df87c67c', command='device_controller.Read', args={'nodeid': 4338, 'attributes': '*', 'dataVersionFilters': None, 'events': '*', 'returnClusterObject': True, 'reportInterval': None, 'fabricFiltered': True, 'keepSubscriptions': False})
2022-08-04 11:36:49 77f1785d-matter-server matter_server.server.server[121] DEBUG [140070856632400] Received CommandMessage(messageId='54429f8a79f84a3c93016617df87c67c', command='device_controller.Read', args={'nodeid': 4338, 'attributes': '*', 'dataVersionFilters': None, 'events': '*', 'returnClusterObject': True, 'reportInterval': None, 'fabricFiltered': True, 'keepSubscriptions': False})
2022-08-04 11:36:49 77f1785d-matter-server chip.IN[121] INFO Prepared secure message 0x7f64b802f858 to 0x00000000000010F2 (1) of type 0x2 and protocolId (0, 1) on exchange 51173i with MessageCounter:246117619.
2022-08-04 11:36:49 77f1785d-matter-server chip.IN[121] INFO Sending encrypted msg 0x7f64b802f858 with MessageCounter:246117619 to 0x00000000000010F2 (1) at monotonic time: 00000000151EBB3E msec
2022-08-04 11:36:49 77f1785d-matter-server chip.EM[121] INFO Received message of type 0x5 with protocolId (0, 1) and MessageCounter:947212581 on exchange 51173i
2022-08-04 11:36:49 77f1785d-matter-server matter_server.server.server[121] DEBUG [140070856632400] Sending {"messageId": "54429f8a79f84a3c93016617df87c67c", "result": {"attributes": {"0": {"Basic": {"dataModelRevision": null, "vendorName": "node-matter", "vendorID": 65521, "productName": "Matter test device", "productID": 32769, "nodeLabel": null, "location": null, "hardwareVersion": null, "hardwareVersionString": null, "softwareVersion": null, "softwareVersionString": null, "manufacturingDate": null, "partNumber": null, "productURL": null, "productLabel": null, "serialNumber": null, "localConfigDisabled": null, "reachable": null, "uniqueID": null, "capabilityMinima": null, "generatedCommandList": null, "acceptedCommandList": null, "attributeList": null, "featureMap": null, "clusterRevision": null, "_type": "chip.clusters.Objects.Basic"}, "GeneralCommissioning": {"breadcrumb": 4, "basicCommissioningInfo": {"failSafeExpiryLengthSeconds": 60, "maxCumulativeFailsafeSeconds": 0, "_type": "chip.clusters.Objects.GeneralCommissioning.Structs.BasicCommissioningInfo"}, "regulatoryConfig": 0, "locationCapability": 2, "supportsConcurrentConnection": null, "generatedCommandList": null, "acceptedCommandList": null, "attributeList": null, "featureMap": null, "clusterRevision": null, "_type": "chip.clusters.Objects.GeneralCommissioning"}}, "1": {"OnOff": {"onOff": false, "globalSceneControl": null, "onTime": null, "offWaitTime": null, "startUpOnOff": null, "generatedCommandList": null, "acceptedCommandList": null, "attributeList": null, "featureMap": null, "clusterRevision": null, "_type": "chip.clusters.Objects.OnOff"}}}, "events": [], "_type": "chip.clusters.Attribute.AsyncReadTransaction.ReadResponse"}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-08-04 11:36:49 77f1785d-matter-server chip.IN[121] INFO Prepared secure message 0x7f64caffbda8 to 0x00000000000010F2 (1) of type 0x10 and protocolId (0, 0) on exchange 51173i with MessageCounter:246117620.
2022-08-04 11:36:49 77f1785d-matter-server chip.IN[121] INFO Sending encrypted msg 0x7f64caffbda8 with MessageCounter:246117620 to 0x00000000000010F2 (1) at monotonic time: 00000000151EBB4B msec
2022-08-04 11:37:03 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 15007 ms
2022-08-04 11:37:03 77f1785d-matter-server chip.DIS[121] ERROR Operational discovery failed for 0x00000000000010F0: ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
2022-08-04 11:37:03 77f1785d-matter-server matter_server.server.server[121] DEBUG [140070856632400] Sending {"messageId": "5ce224fc30964b3abb60014e9db97a63", "errorCode": "CHIP Error 0x00000032: Timeout", "_type": "matter_server.common.model.message.ErrorResultMessage"}
2022-08-04 11:37:03 77f1785d-matter-server matter_server.server.server[121] DEBUG [140070856632400] Received: {"messageId": "ed88b1b0a2ee4137b9142f3aa6ed6c4c", "command": "device_controller.ResolveNode", "args": {"nodeid": 4337}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-08-04 11:37:03 77f1785d-matter-server matter_server.server.server[121] INFO [140070856632400] Deserialized message: CommandMessage(messageId='ed88b1b0a2ee4137b9142f3aa6ed6c4c', command='device_controller.ResolveNode', args={'nodeid': 4337})
2022-08-04 11:37:03 77f1785d-matter-server matter_server.server.server[121] DEBUG [140070856632400] Received CommandMessage(messageId='ed88b1b0a2ee4137b9142f3aa6ed6c4c', command='device_controller.ResolveNode', args={'nodeid': 4337})
2022-08-04 11:37:03 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 201 ms0/48/4 has been invoked (CommissioningComplete) so the commissioning should have succeeded. This might be a MDNS issue now: Operational discovery failed for 0x00000000000010F0
Can you capture the network packets to check what is going on?
mfucci
commented
2 years ago Any chance to get a network capture to investigate this issue? Or you can give me some pointers on how to install HA Matter plugin so I can reproduce the issue? (I don't have a HA instance, so I need to install everything from scratch...)
jdesai61
commented
2 years ago I can get network capture tomorrow.
Sent from my T-Mobile 5G Device Get Outlook for Androidhttps://aka.ms/AAb9ysg
From: mfucci @.> Sent: Monday, August 8, 2022 8:16:18 PM To: mfucci/node-matter @.> Cc: Jatin Desai @.>; Mention @.> Subject: Re: [mfucci/node-matter] Unable to complete commission process with Home Assistant (Issue #11)
Any chance to get a network capture to investigate this issue? Or you can give me some pointers on how to install HA Matter plugin so I can reproduce the issue? (I don't have a HA instance, so I need to install everything from scratch...)
— Reply to this email directly, view it on GitHubhttps://nam12.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fmfucci%2Fnode-matter%2Fissues%2F11%23issuecomment-1208749882&data=05%7C01%7C%7Ca7b06b22fd1d4b9b7d7b08da799c622c%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C637956009830868286%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=WYYZPNL9UAM7oV%2FMQ8A0jKSx%2Bn4T7BXkgZbXjK%2FPe1o%3D&reserved=0, or unsubscribehttps://nam12.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FADBZQWACSHZVUUMSOUE44ZLVYGPNFANCNFSM53TPMB6A&data=05%7C01%7C%7Ca7b06b22fd1d4b9b7d7b08da799c622c%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C637956009831024522%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=PAtAxPdu4hrQ0%2B3OBHOqoHmSBq1rT4fhcPrM8H2o8hM%3D&reserved=0. You are receiving this because you were mentioned.Message ID: @.***>
jdesai61
commented
2 years ago Here are two pcap files - both captured on home-assistant side. One is with succesful commissioning of ESPDev device that HA tutorial used. The other is almost successful (but not quite) capture with node-matter. node-matter-esp-ha.zip The HA logs with node-matter are already posted above. But I am attaching HA logs showing succesfull commissioning with esp-ha.log ESP DevKit device
Hope Assistant IP: 192.168.1.57 (IPV6: fe80::a199:dcb4:dc7) ESP DevKit IP: 192.168.1.165 (IPV6 fe80::86f7:3ff:fe60:ff8) Node Matter VM IP: 192.168.1.28
tcpdump command used to capture (on HA machine):
tcpdump -ni enp0s18 -w MYFILE.pcap port 5540 or port 5353Hope this helps.
mfucci
commented
2 years ago Thanks! Per the logs, it doesn't seem to be a MDNS issue. It more looks like HA Matter plugin doesn't like something that is returned by: read //* request. The ESPDev device returns many more attributes.
I know that many mandatory clusters / attributes are not implemented in node-matter.
Many if we pinpoint the attributes that HA plugin expects, I can add just those one.
In matter_server/client/matter.py#L86 can you add a few logs to check if self.client.driver.device_controller.commission_with_code is returning? I think the problem happens in "await self._interview_node(node_id)" but I am not sure.
Does "ERROR Operational discovery failed for" happens each time? Previous log says that it waited for 15s but that doesn't match with the other timestamps in the logs, since logs start less than a second ago.
jdesai61
commented
2 years ago Agree the MDNS was only related to discovering commissionable device. The logs and tcpdump capture don't agree on timing, because I failed to capture logs when I was using tcpdump, so they are from a different run.
I tried to edit the matter_server files to add log statements, but within HA this is not easily done because the matter server is a docker image that I can't easily manipulate. I am out of town for next two weeks so when I return, perhaps I will try to build my own docker container for matter server and insert the debug statements.
javierbarellano4v
commented
2 years ago Does the zipped version of node-matter includes all fixes up until to this point?
Thanks.
mfucci
commented
2 years ago Hi Javier,
If you download the sip of the main branch, it will contain all the latest fixes. Alternatively, I just uploaded a new version to npm, so you install the latest version with: npm i node-matter Let me know if you run into any issue!
Thanks,
javierbarellano4v
commented
2 years ago Hey Marco,
It worked (via npm)
Is there another Cluster (command) I can try to hit the Matter Server so to speak?
Thanks so much! Greatly appreciate it!!
mfucci
commented
2 years ago The last log means that the commissioning was successful. The only cluster implemented right now is the On/Off cluster which can be used to turn on / off a light, an appliances, etc. You can send command via the Android Matter test app or using Matter test command line tool.
To turn on/off one LED on a Raspberry Pi, here is the command:
matter -on "echo 255 > /sys/class/leds/led1/brightness" -off "echo 0 > /sys/class/leds/led1/brightness"
You can run your own scripts on "on" / "off" to do something more advanced.
Thanks!
javierbarellano4v
commented
2 years ago As a matter of fact, I have Matter deployed on a Raspberry Pi 4. So I ran the chip-tool on it to pair with your Matter server.
Thanks again.
jdesai61
commented
2 years ago As a matter of fact, I have Matter deployed on a Raspberry Pi 4. So I ran the chip-tool on it to pair with your Matter server.
Thanks again.
I have previously mentioned that chip-tool can successfully pair with node-matter after the following issue was fixed: https://github.com/mfucci/node-matter/issues/3#issue-1279118941. T
his particular issue is inability to complete pairing process with Home Assistant Matter Add-on.
javierbarellano4v
commented
2 years ago Inadvertently, the HA aspect of the issue didn't register, just the issue of the commission process
I will start a separate issue, for any further non-HA questions/problems.
jdesai61
commented
2 years ago Upon further debugging interview_node is failing because of missing "Descriptor" field in some attribute returned by node-matter.
The affected code is in matter_server/client/model/node.py (line 129)
for endpoint_id, endpoint_info in node_info["attributes"].items():
descriptor: all_clusters.Descriptor = endpoint_info["Descriptor"]
for device_info in descriptor.deviceList:Here is the stack dump
^[[31m2022-08-25 11:00:04.535 ERROR (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Error executing
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 447, in _async_step
await getattr(self, handler)()
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 680, in _async_call_service_step
await service_task
File "/usr/src/homeassistant/homeassistant/core.py", line 1713, in async_call
task.result()
File "/usr/src/homeassistant/homeassistant/core.py", line 1750, in _execute_service
await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 746, in admin_handler
await result
File "/config/custom_components/matter_experimental/__init__.py", line 116, in commission
await matter.commission(call.data["code"])
File "/usr/local/lib/python3.10/site-packages/matter_server/client/matter.py", line 101, in commission
await self._interview_node(node_id)
File "/usr/local/lib/python3.10/site-packages/matter_server/client/matter.py", line 129, in _interview_node
self._nodes[node_id] = MatterNode(self, node_info)
File "/usr/local/lib/python3.10/site-packages/matter_server/client/model/node.py", line 37, in __init__
descriptor: all_clusters.Descriptor = endpoint_info["Descriptor"]
KeyError: 'Descriptor'The working ESP device seems to send following attributes and other fields (as printed by HA add-on)
2022 - 08 - 09 15: 25: 40 77f1785d - matter - server matter_server.server.server[121]DEBUG[140637758294048]Sending {
"messageId": "874bcbecb8e54c328d66d629f52209f7",
"result": {
"attributes": {
"0": {
"Groups": {
"nameSupport": 128,
"generatedCommandList": [0, 1, 2, 3],
"acceptedCommandList": [0, 1, 2, 3, 4, 5],
"attributeList": [0, 65528, 65529, 65531, 65532, 65533],
"featureMap": 1,
"clusterRevision": 4,
"_type": "chip.clusters.Objects.Groups"
},
"Descriptor": {
"deviceList": [{
"type": 22,
"revision": 1,
"_type": "chip.clusters.Objects.Descriptor.Structs.DeviceType"
}
],
"serverList": [4, 29, 31, 40, 42, 43, 44, 48, 49, 50, 51, 52, 53, 54, 55, 59, 60, 62, 63, 64, 65],
"clientList": [41],
"partsList": [1],
"generatedCommandList": [],
"acceptedCommandList": [],
"attributeList": [0, 1, 2, 3, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.Descriptor"
},
"AccessControl": {
"acl": [{
"privilege": 5,
"authMode": 2,
"subjects": [1],
"targets": null,
"fabricIndex": 1,
"_type": "chip.clusters.Objects.AccessControl.Structs.AccessControlEntry"
}
],
"extension": [],
"subjectsPerAccessControlEntry": 4,
"targetsPerAccessControlEntry": 3,
"accessControlEntriesPerFabric": 3,
"generatedCommandList": [],
"acceptedCommandList": [],
"attributeList": [0, 1, 2, 3, 4, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.AccessControl"
},
"Basic": {
"dataModelRevision": 1,
"vendorName": "Nabu Casa",
"vendorID": 65521,
"productName": "ESP32-C3-DevKitM-1 Lighting App",
"productID": 32768,
"nodeLabel": "",
"location": "XX",
"hardwareVersion": 0,
"hardwareVersionString": "v1.0",
"softwareVersion": 1,
"softwareVersionString": "0c8cbf5",
"manufacturingDate": "20200101",
"partNumber": "",
"productURL": "",
"productLabel": "",
"serialNumber": "TEST_SN",
"localConfigDisabled": false,
"reachable": true,
"uniqueID": "056CEBAA23521480",
"capabilityMinima": {
"caseSessionsPerFabric": 3,
"subscriptionsPerFabric": 3,
"_type": "chip.clusters.Objects.Basic.Structs.CapabilityMinimaStruct"
},
"generatedCommandList": [],
"acceptedCommandList": [],
"attributeList": [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.Basic"
},
"OtaSoftwareUpdateRequestor": {
"defaultOtaProviders": [],
"updatePossible": true,
"updateState": 0,
"updateStateProgress": 0,
"generatedCommandList": [],
"acceptedCommandList": [0],
"attributeList": [0, 1, 2, 3, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.OtaSoftwareUpdateRequestor"
},
"LocalizationConfiguration": {
"activeLocale": "en-US",
"supportedLocales": ["en-US", "de-DE", "fr-FR", "en-GB", "es-ES", "zh-CN", "it-IT", "ja-JP"],
"generatedCommandList": [],
"acceptedCommandList": [],
"attributeList": [0, 1, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.LocalizationConfiguration"
},
"TimeFormatLocalization": {
"hourFormat": 0,
"activeCalendarType": 0,
"supportedCalendarTypes": [0, 1, 2, 3, 4, 5, 6, 8, 9, 10, 11, 7],
"generatedCommandList": [],
"acceptedCommandList": [],
"attributeList": [0, 1, 2, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.TimeFormatLocalization"
},
"GeneralCommissioning": {
"breadcrumb": 0,
"basicCommissioningInfo": {
"failSafeExpiryLengthSeconds": 60,
"maxCumulativeFailsafeSeconds": 900,
"_type": "chip.clusters.Objects.GeneralCommissioning.Structs.BasicCommissioningInfo"
},
"regulatoryConfig": 0,
"locationCapability": 0,
"supportsConcurrentConnection": true,
"generatedCommandList": [1, 3, 5],
"acceptedCommandList": [0, 2, 4],
"attributeList": [0, 1, 2, 3, 4, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.GeneralCommissioning"
},
"NetworkCommissioning": {
"maxNetworks": 1,
"networks": [],
"scanMaxTimeSeconds": 10,
"connectMaxTimeSeconds": 30,
"interfaceEnabled": true,
"lastNetworkingStatus": 0,
"lastNetworkID": {
"_type": "bytes",
"value": "ZGpoY3Jz"
},
"lastConnectErrorValue": null,
"generatedCommandList": [1, 5, 7],
"acceptedCommandList": [0, 2, 4, 6, 8],
"attributeList": [0, 1, 2, 3, 4, 5, 6, 7, 65528, 65529, 65531, 65532, 65533],
"featureMap": 1,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.NetworkCommissioning"
},
"DiagnosticLogs": {
"generatedCommandList": [1],
"acceptedCommandList": [0],
"attributeList": [65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.DiagnosticLogs"
},
"GeneralDiagnostics": {
"networkInterfaces": [{
"name": "WIFI_AP_DEF",
"isOperational": true,
"offPremiseServicesReachableIPv4": null,
"offPremiseServicesReachableIPv6": null,
"hardwareAddress": {
"_type": "bytes",
"value": "6JSan9qT"
},
"IPv4Addresses": [],
"IPv6Addresses": [],
"type": 1,
"_type": "chip.clusters.Objects.GeneralDiagnostics.Structs.NetworkInterfaceType"
}, {
"name": "WIFI_STA_DEF",
"isOperational": true,
"offPremiseServicesReachableIPv4": null,
"offPremiseServicesReachableIPv6": null,
"hardwareAddress": {
"_type": "bytes",
"value": "hPcDYA/4"
},
"IPv4Addresses": [],
"IPv6Addresses": [],
"type": 1,
"_type": "chip.clusters.Objects.GeneralDiagnostics.Structs.NetworkInterfaceType"
}
],
"rebootCount": 3,
"upTime": 561,
"totalOperationalHours": 0,
"bootReasons": 6,
"activeHardwareFaults": [],
"activeRadioFaults": [],
"activeNetworkFaults": [],
"testEventTriggersEnabled": false,
"generatedCommandList": [],
"acceptedCommandList": [0],
"attributeList": [0, 1, 2, 3, 4, 5, 6, 7, 8, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.GeneralDiagnostics"
},
"SoftwareDiagnostics": {
"threadMetrics": [],
"currentHeapFree": 115604,
"currentHeapUsed": 139564,
"currentHeapHighWatermark": 154920,
"generatedCommandList": [],
"acceptedCommandList": [],
"attributeList": [0, 1, 2, 3, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.SoftwareDiagnostics"
},
"ThreadNetworkDiagnostics": {
"TLVValue": {
"0": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"1": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"2": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"3": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"4": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"5": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"6": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"7": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"8": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"9": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"10": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"11": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"12": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"13": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"14": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"15": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"16": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"17": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"18": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"19": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"20": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"21": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"22": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"23": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"24": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"25": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"26": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"27": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"28": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"29": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"30": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"31": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"32": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"33": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"34": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"35": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"36": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"37": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"38": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"39": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"40": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"41": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"42": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"43": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"44": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"45": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"46": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"47": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"48": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"49": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"50": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"51": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"52": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"53": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"54": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"55": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"56": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"57": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"58": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"59": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"60": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"61": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"62": {
"TLVValue": null,
"Reason": "InteractionModelError: Failure (0x1)",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"65532": 15,
"65533": 1,
"65528": [],
"65529": [0],
"65531": [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 65528, 65529, 65531, 65532, 65533]
},
"Reason": "Failed to decode field [].channel, expected type <class 'chip.tlv.uint'>, got <class 'chip.clusters.Attribute.ValueDecodeFailure'>",
"_type": "chip.clusters.Attribute.ValueDecodeFailure"
},
"WiFiNetworkDiagnostics": {
"bssid": {
"_type": "bytes",
"value": "GOgpFEER"
},
"securityType": 4,
"wiFiVersion": 3,
"channelNumber": 6,
"rssi": -66,
"beaconLostCount": 0,
"beaconRxCount": 0,
"packetMulticastRxCount": 0,
"packetMulticastTxCount": 0,
"packetUnicastRxCount": 0,
"packetUnicastTxCount": 0,
"currentMaxRate": 0,
"overrunCount": 0,
"generatedCommandList": [],
"acceptedCommandList": [0],
"attributeList": [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 65528, 65529, 65531, 65532, 65533],
"featureMap": 3,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.WiFiNetworkDiagnostics"
},
"EthernetNetworkDiagnostics": {
"PHYRate": null,
"fullDuplex": null,
"packetRxCount": 0,
"packetTxCount": 0,
"txErrCount": 0,
"collisionCount": 0,
"overrunCount": 0,
"carrierDetect": null,
"timeSinceReset": 0,
"generatedCommandList": [],
"acceptedCommandList": [0],
"attributeList": [0, 1, 2, 3, 4, 5, 6, 7, 8, 65528, 65529, 65531, 65532, 65533],
"featureMap": 3,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.EthernetNetworkDiagnostics"
},
"Switch": {
"numberOfPositions": null,
"currentPosition": null,
"multiPressMax": null,
"generatedCommandList": [],
"acceptedCommandList": [],
"attributeList": [65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.Switch"
},
"AdministratorCommissioning": {
"windowStatus": 0,
"adminFabricIndex": 0,
"adminVendorId": 0,
"generatedCommandList": [],
"acceptedCommandList": [0, 1, 2],
"attributeList": [0, 1, 2, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.AdministratorCommissioning"
},
"OperationalCredentials": {
"NOCs": [{
"noc": {
"_type": "bytes",
"value": "FTABAQEkAgE3AyQTARgmBIAigScmBYAlTTo3BiQVASUR7xAYJAcBJAgBMAlBBBsyOSBsvpJD9MVrfy1t1hbYLlf7VX2lUHs7QKcpIti6NEs5nrF3zeTWryFX9Ky3uOGD13LtBTBdAueJrgsGQsg3CjUBKAEYJAIBNgMEAgQBGDAEFGK+Rp8+0BVdp4RqrLTGlgPwdlHIMAUU+HATk8fb5lVNCXBTFjsN5gzVp3gYMAtA4cfOvqDct//cVZjgm5I4deugkAEn16KLqCozfac0niBiZAmLVDcczQJh3F7YVhRqM5i3qtkzU/kW8tGi0ckQRxg="
},
"icac": {
"_type": "bytes",
"value": "FTABAQAkAgE3AyQUABgmBIAigScmBYAlTTo3BiQTARgkBwEkCAEwCUEEAuOopp5gSR1ksvGRtTRym8vpNeFM5mM0DpGYAac4zt3hd3eVhWmkHZmhlfl13K6ejNOnpQP3uYvg2oUz/PpxlzcKNQEpARgkAmAwBBT4cBOTx9vmVU0JcFMWOw3mDNWneDAFFFKfFiBRGsyg+9mRHi4OeDcV8vlVGDALQOq36cF0FkRy7iwzY1KjPqzKmQqw/s8dUU6fAINjFNh0fK8ZRejrH1OzBeon12AWng/hh/EHzouGjWAcTD8C2TEY"
},
"fabricIndex": 1,
"_type": "chip.clusters.Objects.OperationalCredentials.Structs.NOCStruct"
}
],
"fabrics": [{
"rootPublicKey": {
"_type": "bytes",
"value": "BFv8vYiVLpJOZWvyQOeeI36az1dmWpcIyGuPs7YD57yKIqfqHvdT88odch6Mi4stx3wNsgYllXCa6zFi+CBl3nM="
},
"vendorId": 21467,
"fabricId": 1,
"nodeId": 4335,
"label": "",
"fabricIndex": 1,
"_type": "chip.clusters.Objects.OperationalCredentials.Structs.FabricDescriptor"
}
],
"supportedFabrics": 5,
"commissionedFabrics": 1,
"trustedRootCertificates": [{
"_type": "bytes",
"value": "FTABAQAkAgE3AyQUABgmBIAigScmBYAlTTo3BiQUABgkBwEkCAEwCUEEW/y9iJUukk5la/JA554jfprPV2ZalwjIa4+ztgPnvIoip+oe91Pzyh1yHoyLiy3HfA2yBiWVcJrrMWL4IGXeczcKNQEpARgkAmAwBBRSnxYgURrMoPvZkR4uDng3FfL5VTAFFFKfFiBRGsyg+9mRHi4OeDcV8vlVGDALQIcrzff/7ztYMnUNthe1Pop7GVAD/p2hPW1bs4G5wkB0bk6lvYB0gZaecG6dfq8zkvlOdLPESQZMcKhSjyi4mhsY"
}
],
"currentFabricIndex": 1,
"generatedCommandList": [1, 3, 5, 8],
"acceptedCommandList": [0, 2, 4, 6, 7, 9, 10, 11],
"attributeList": [0, 1, 2, 3, 4, 5, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.OperationalCredentials"
},
"GroupKeyManagement": {
"groupKeyMap": [],
"groupTable": [],
"maxGroupsPerFabric": 3,
"maxGroupKeysPerFabric": 2,
"generatedCommandList": [2, 5],
"acceptedCommandList": [0, 1, 3, 4],
"attributeList": [0, 1, 2, 3, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.GroupKeyManagement"
},
"FixedLabel": {
"labelList": [{
"label": "room",
"value": "bedroom 2",
"_type": "chip.clusters.Objects.FixedLabel.Structs.LabelStruct"
}, {
"label": "orientation",
"value": "North",
"_type": "chip.clusters.Objects.FixedLabel.Structs.LabelStruct"
}, {
"label": "floor",
"value": "2",
"_type": "chip.clusters.Objects.FixedLabel.Structs.LabelStruct"
}, {
"label": "direction",
"value": "up",
"_type": "chip.clusters.Objects.FixedLabel.Structs.LabelStruct"
}
],
"generatedCommandList": [],
"acceptedCommandList": [],
"attributeList": [0, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.FixedLabel"
},
"UserLabel": {
"labelList": [],
"generatedCommandList": [],
"acceptedCommandList": [],
"attributeList": [0, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.UserLabel"
}
},
"1": {
"Identify": {
"identifyTime": 0,
"identifyType": 0,
"generatedCommandList": [],
"acceptedCommandList": [0, 64],
"attributeList": [0, 1, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 4,
"_type": "chip.clusters.Objects.Identify"
},
"Groups": {
"nameSupport": 128,
"generatedCommandList": [0, 1, 2, 3],
"acceptedCommandList": [0, 1, 2, 3, 4, 5],
"attributeList": [0, 65528, 65529, 65531, 65532, 65533],
"featureMap": 1,
"clusterRevision": 4,
"_type": "chip.clusters.Objects.Groups"
},
"OnOff": {
"onOff": false,
"globalSceneControl": true,
"onTime": 0,
"offWaitTime": 0,
"startUpOnOff": null,
"generatedCommandList": [],
"acceptedCommandList": [0, 1, 2, 64, 65, 66],
"attributeList": [0, 16384, 16385, 16386, 16387, 65528, 65529, 65531, 65532, 65533],
"featureMap": 1,
"clusterRevision": 4,
"_type": "chip.clusters.Objects.OnOff"
},
"LevelControl": {
"currentLevel": 254,
"remainingTime": 0,
"minLevel": 1,
"maxLevel": 254,
"currentFrequency": 0,
"minFrequency": 0,
"maxFrequency": 0,
"options": 0,
"onOffTransitionTime": 0,
"onLevel": null,
"onTransitionTime": 0,
"offTransitionTime": 0,
"defaultMoveRate": 50,
"startUpCurrentLevel": null,
"generatedCommandList": [],
"acceptedCommandList": [0, 1, 2, 3, 4, 5, 6, 7],
"attributeList": [0, 1, 2, 3, 4, 5, 6, 15, 16, 17, 18, 19, 20, 16384, 65528, 65529, 65531, 65532, 65533],
"featureMap": 3,
"clusterRevision": 5,
"_type": "chip.clusters.Objects.LevelControl"
},
"Descriptor": {
"deviceList": [{
"type": 257,
"revision": 1,
"_type": "chip.clusters.Objects.Descriptor.Structs.DeviceType"
}
],
"serverList": [3, 4, 6, 8, 29, 768, 1030],
"clientList": [],
"partsList": [],
"generatedCommandList": [],
"acceptedCommandList": [],
"attributeList": [0, 1, 2, 3, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 1,
"_type": "chip.clusters.Objects.Descriptor"
},
"ColorControl": {
"currentHue": 0,
"currentSaturation": 0,
"remainingTime": 0,
"currentX": 24939,
"currentY": 24701,
"driftCompensation": null,
"compensationText": null,
"colorTemperature": 0,
"colorMode": 2,
"options": 0,
"numberOfPrimaries": 0,
"primary1X": null,
"primary1Y": null,
"primary1Intensity": null,
"primary2X": null,
"primary2Y": null,
"primary2Intensity": null,
"primary3X": null,
"primary3Y": null,
"primary3Intensity": null,
"primary4X": null,
"primary4Y": null,
"primary4Intensity": null,
"primary5X": null,
"primary5Y": null,
"primary5Intensity": null,
"primary6X": null,
"primary6Y": null,
"primary6Intensity": null,
"whitePointX": null,
"whitePointY": null,
"colorPointRX": null,
"colorPointRY": null,
"colorPointRIntensity": null,
"colorPointGX": null,
"colorPointGY": null,
"colorPointGIntensity": null,
"colorPointBX": null,
"colorPointBY": null,
"colorPointBIntensity": null,
"enhancedCurrentHue": 0,
"enhancedColorMode": 2,
"colorLoopActive": 0,
"colorLoopDirection": 0,
"colorLoopTime": 25,
"colorLoopStartEnhancedHue": 8960,
"colorLoopStoredEnhancedHue": 0,
"colorCapabilities": 31,
"colorTempPhysicalMinMireds": 0,
"colorTempPhysicalMaxMireds": 65279,
"coupleColorTempToLevelMinMireds": 0,
"startUpColorTemperatureMireds": 0,
"generatedCommandList": [],
"acceptedCommandList": [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 64, 65, 66, 67, 68, 71, 75, 76],
"attributeList": [0, 1, 2, 3, 4, 7, 8, 15, 16, 16384, 16385, 16386, 16387, 16388, 16389, 16390, 16394, 16395, 16396, 16397, 16400, 65528, 65529, 65531, 65532, 65533],
"featureMap": 31,
"clusterRevision": 5,
"_type": "chip.clusters.Objects.ColorControl"
},
"OccupancySensing": {
"occupancy": 0,
"occupancySensorType": 0,
"occupancySensorTypeBitmap": 1,
"pirOccupiedToUnoccupiedDelay": null,
"pirUnoccupiedToOccupiedDelay": null,
"pirUnoccupiedToOccupiedThreshold": null,
"ultrasonicOccupiedToUnoccupiedDelay": null,
"ultrasonicUnoccupiedToOccupiedDelay": null,
"ultrasonicUnoccupiedToOccupiedThreshold": null,
"physicalContactOccupiedToUnoccupiedDelay": null,
"physicalContactUnoccupiedToOccupiedDelay": null,
"physicalContactUnoccupiedToOccupiedThreshold": null,
"generatedCommandList": [],
"acceptedCommandList": [],
"attributeList": [0, 1, 2, 65528, 65529, 65531, 65532, 65533],
"featureMap": 0,
"clusterRevision": 3,
"_type": "chip.clusters.Objects.OccupancySensing"
}
}
},
"events": [{
"Header": {
"EndpointId": 0,
"ClusterId": 51,
"EventId": 3,
"EventNumber": 0,
"Priority": 2,
"Timestamp": 1754,
"TimestampType": 0,
"_type": "chip.clusters.Attribute.EventHeader"
},
"Status": 0,
"Data": {
"bootReason": 6,
"_type": "chip.clusters.Objects.GeneralDiagnostics.Events.BootReason"
},
"_type": "chip.clusters.Attribute.EventReadResult"
}, {
"Header": {
"EndpointId": 0,
"ClusterId": 40,
"EventId": 0,
"EventNumber": 1,
"Priority": 2,
"Timestamp": 2169,
"TimestampType": 0,
"_type": "chip.clusters.Attribute.EventHeader"
},
"Status": 0,
"Data": {
"softwareVersion": 1,
"_type": "chip.clusters.Objects.Basic.Events.StartUp"
},
"_type": "chip.clusters.Attribute.EventReadResult"
}, {
"Header": {
"EndpointId": 0,
"ClusterId": 54,
"EventId": 2,
"EventNumber": 2,
"Priority": 1,
"Timestamp": 24219,
"TimestampType": 0,
"_type": "chip.clusters.Attribute.EventHeader"
},
"Status": 0,
"Data": {
"connectionStatus": 0,
"_type": "chip.clusters.Objects.WiFiNetworkDiagnostics.Events.ConnectionStatus"
},
"_type": "chip.clusters.Attribute.EventReadResult"
}, {
"Header": {
"EndpointId": 0,
"ClusterId": 54,
"EventId": 0,
"EventNumber": 3,
"Priority": 1,
"Timestamp": 37734,
"TimestampType": 0,
"_type": "chip.clusters.Attribute.EventHeader"
},
"Status": 0,
"Data": {
"reasonCode": 200,
"_type": "chip.clusters.Objects.WiFiNetworkDiagnostics.Events.Disconnection"
},
"_type": "chip.clusters.Attribute.EventReadResult"
}, {
"Header": {
"EndpointId": 0,
"ClusterId": 54,
"EventId": 2,
"EventNumber": 4,
"Priority": 1,
"Timestamp": 37736,
"TimestampType": 0,
"_type": "chip.clusters.Attribute.EventHeader"
},
"Status": 0,
"Data": {
"connectionStatus": 1,
"_type": "chip.clusters.Objects.WiFiNetworkDiagnostics.Events.ConnectionStatus"
},
"_type": "chip.clusters.Attribute.EventReadResult"
}, {
"Header": {
"EndpointId": 0,
"ClusterId": 54,
"EventId": 2,
"EventNumber": 5,
"Priority": 1,
"Timestamp": 191368,
"TimestampType": 0,
"_type": "chip.clusters.Attribute.EventHeader"
},
"Status": 0,
"Data": {
"connectionStatus": 0,
"_type": "chip.clusters.Objects.WiFiNetworkDiagnostics.Events.ConnectionStatus"
},
"_type": "chip.clusters.Attribute.EventReadResult"
}, {
"Header": {
"EndpointId": 0,
"ClusterId": 31,
"EventId": 0,
"EventNumber": 6,
"Priority": 1,
"Timestamp": 559489,
"TimestampType": 0,
"_type": "chip.clusters.Attribute.EventHeader"
},
"Status": 0,
"Data": {
"adminNodeID": null,
"adminPasscodeID": 0,
"changeType": 1,
"latestValue": {
"privilege": 5,
"authMode": 2,
"subjects": [1],
"targets": null,
"fabricIndex": 1,
"_type": "chip.clusters.Objects.AccessControl.Structs.AccessControlEntry"
},
"adminFabricIndex": 1,
"_type": "chip.clusters.Objects.AccessControl.Events.AccessControlEntryChanged"
},
"_type": "chip.clusters.Attribute.EventReadResult"
}
],
"_type": "chip.clusters.Attribute.AsyncReadTransaction.ReadResponse"
},
"_type": "matter_server.common.model.message.SuccessResultMessage"
}Thanks you very much for this debugging! I will add more attributes to check if this will solve the problem (in a few days).
mfucci
commented
2 years ago Here is a PR that adds the Descriptor cluster: https://github.com/mfucci/node-matter/pull/17
Let me know if this allows to pass one extra steps with HA! It will probably crash at the next one :-)
jdesai61
commented
2 years ago With this change, interaction with HA goes much further (the device shows up in UI - but broken). It is likely because following error in node-matter
Received read request from udp://192.168.1.57:53322 on session secure/27525: */*/*
/home/DadAdmin/tmp/node-matter/build/interaction/InteractionMessenger.js:36
throw new Error(`Unsupported message type ${message.payloadHeader.messageType}`);
^
Error: Unsupported message type 3
at InteractionMessenger.<anonymous> (/home/DadAdmin/tmp/node-matter/build/interaction/InteractionMessenger.js:36:27)
at Generator.next (<anonymous>)
at fulfilled (/home/DadAdmin/tmp/node-matter/build/interaction/InteractionMessenger.js:5:58)
I am seeing the descriptor in HA logs
2022-08-29 15:48:39 local-matter-server matter_server.server.server[121] DEBUG [140057956195632] Sending
{
"messageId": "805043f5de7c41ccb6e2364551135231",
"result": {
"attributes": {
"0": {
"Basic": {
"dataModelRevision": null,
"vendorName": "node-matter",
"vendorID": 65521,
"productName": "Matter test device",
"productID": 32769,
"nodeLabel": null,
"location": null,
"hardwareVersion": null,
"hardwareVersionString": null,
"softwareVersion": null,
"softwareVersionString": null,
"manufacturingDate": null,
"partNumber": null,
"productURL": null,
"productLabel": null,
"serialNumber": null,
"localConfigDisabled": null,
"reachable": null,
"uniqueID": null,
"capabilityMinima": null,
"generatedCommandList": null,
"acceptedCommandList": null,
"attributeList": null,
"featureMap": null,
"clusterRevision": null,
"_type": "chip.clusters.Objects.Basic"
},
"GeneralCommissioning": {
"breadcrumb": 4,
"basicCommissioningInfo": {
"failSafeExpiryLengthSeconds": 60,
"maxCumulativeFailsafeSeconds": 0,
"_type": "chip.clusters.Objects.GeneralCommissioning.Structs.BasicCommissioningInfo"
},
"regulatoryConfig": 0,
"locationCapability": 2,
"supportsConcurrentConnection": null,
"generatedCommandList": null,
"acceptedCommandList": null,
"attributeList": null,
"featureMap": null,
"clusterRevision": null,
"_type": "chip.clusters.Objects.GeneralCommissioning"
},
"Descriptor": {
"deviceList": [{
"type": 22,
"revision": 1,
"_type": "chip.clusters.Objects.Descriptor.Structs.DeviceType"
}
],
"serverList": [29, 40, 48, 62],
"clientList": null,
"partsList": [],
"generatedCommandList": null,
"acceptedCommandList": null,
"attributeList": null,
"featureMap": null,
"clusterRevision": null,
"_type": "chip.clusters.Objects.Descriptor"
}
},
"1": {
"OnOff": {
"onOff": false,
"globalSceneControl": null,
"onTime": null,
"offWaitTime": null,
"startUpOnOff": null,
"generatedCommandList": null,
"acceptedCommandList": null,
"attributeList": null,
"featureMap": null,
"clusterRevision": null,
"_type": "chip.clusters.Objects.OnOff"
},
"Descriptor": {
"deviceList": [{
"type": 256,
"revision": 1,
"_type": "chip.clusters.Objects.Descriptor.Structs.DeviceType"
}
],
"serverList": [29, 6],
"clientList": null,
"partsList": [],
"generatedCommandList": null,
"acceptedCommandList": null,
"attributeList": null,
"featureMap": null,
"clusterRevision": null,
"_type": "chip.clusters.Objects.Descriptor"
}
}
},
"events": [],
"_type": "chip.clusters.Attribute.AsyncReadTransaction.ReadResponse"
},
"_type": "matter_server.common.model.message.SuccessResultMessage"
}Here is one more log snippet from HA that may help
2022-08-29 15:48:54 local-matter-server chip.DIS[121] ERROR Operational discovery failed for 0x00000000000010F3: ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
2022-08-29 15:49:06 local-matter-server chip.DMG[121] ERROR Time out! failed to receive report data from Exchange: 39580i
2022-08-29 15:49:06 local-matter-server chip.DMG[121] INFO Will try to resubscribe to 01:00000000000010F3 at retry index 0 after 0ms due to error ../../src/app/ReadClient.cpp:610: CHIP Error 0x00000032: Timeout
Exception ignored on calling ctypes callback function: <function _OnResubscriptionAttemptedCallback at 0x7f61ce291430>
Traceback (most recent call last):
File "/usr/local/lib/python3.9/dist-packages/chip/clusters/Attribute.py", line 829, in _OnResubscriptionAttemptedCallback
closure.handleResubscriptionAttempted(terminationCause, nextResubscribeIntervalMsec)
File "/usr/local/lib/python3.9/dist-packages/chip/clusters/Attribute.py", line 701, in handleResubscriptionAttempted
self._subscription_handler._onResubscriptionAttemptedCb, self._subscription_handler, terminationCause, nextResubscribeIntervalMsec)
AttributeError: 'NoneType' object has no attribute '_onResubscriptionAttemptedCb'
Message type 3 on the interaction protocol is SubscribeRequest per this file: https://github.com/project-chip/connectedhomeip/blob/master/src/protocols/interaction_model/Constants.h
And yes, this is not implemented yet. Both ReadRequest (implemented) and SubscribeRequest returns a SubscribeResponse so half of it is already implemented but subscribe mean the server should inform the client when the value changes so that would be the first message initiated by the server rather than the client, which will probably require some large refactoring.
I can do a quick hack and just have SubscribeRequest acting as ReadRequest, this should probably make it works for now. I might find some time to do that tomorrow.
mfucci
commented
2 years ago Thanks for your help testing this!
jdesai61
commented
2 years ago Even if the message is not supported, the code should not throw an exception and exit. It should log an error/info message and continue. This is true when handling MDNS requests too. Currently, I am getting exception with MDNS requests from 127.0.0.1 that results in code throwing an exception and exiting. I will open up another issue for MDNS.
mfucci
commented
2 years ago Here is a fake implementation of subscribe that should allow to pass that step: https://github.com/mfucci/node-matter/pull/20 Let me know if this works now!
A correct handling of unsupported operations is more complex then just ignoring it since it can lead to incorrect states. For instance, if the subscribe request doesn't return a response, the client might hang forever wait for it... For now, crashing on unsupported operations will ensure that the system cannot go in an incorrect state, a better handling of exception will require much more work
jdesai61
commented
2 years ago I tried the above PR and things seem to progress much further, but now HA is repeatedly issuing following logs (the key error seems to be ../../src/app/MessageDef/ReportDataMessage.cpp:90: CHIP Error 0x00000026: Wrong TLV type:
2022-09-01 09:52:05 local-matter-server chip.IN[121] INFO Prepared secure message 0x7f13caffbda8 to 0x00000000000010EF (1) of type 0x10 and protocolId (0, 0) on exchange 64596i with MessageCounter:229464784.
2022-09-01 09:52:05 local-matter-server chip.IN[121] INFO Sending encrypted msg 0x7f13caffbda8 with MessageCounter:229464784 to 0x00000000000010EF (1) at monotonic time: 000000001E821C0E msec
2022-09-01 09:52:05 local-matter-server chip.IN[121] INFO Prepared secure message 0x7f13b802f2c8 to 0x00000000000010EF (1) of type 0x3 and protocolId (0, 1) on exchange 64597i with MessageCounter:229464785.
2022-09-01 09:52:05 local-matter-server chip.IN[121] INFO Sending encrypted msg 0x7f13b802f2c8 with MessageCounter:229464785 to 0x00000000000010EF (1) at monotonic time: 000000001E821C0F msec
2022-09-01 09:52:05 local-matter-server chip.EM[121] INFO Received message of type 0x5 with protocolId (0, 1) and MessageCounter:6624795 on exchange 64597i
2022-09-01 09:52:05 local-matter-server chip.DMG[121] INFO Will try to resubscribe to 01:00000000000010EF at retry index 7955 after 0ms
due to error ../../src/app/MessageDef/ReportDataMessage.cpp:90: CHIP Error 0x00000026: Wrong TLV type
Exception ignored on calling ctypes callback function: <function _OnResubscriptionAttemptedCallback at 0x7f13d34d5430>
Traceback (most recent call last):
File "/usr/local/lib/python3.9/dist-packages/chip/clusters/Attribute.py", line 829, in _OnResubscriptionAttemptedCallback
closure.handleResubscriptionAttempted(terminationCause, nextResubscribeIntervalMsec)
File "/usr/local/lib/python3.9/dist-packages/chip/clusters/Attribute.py", line 701, in handleResubscriptionAttempted
self._subscription_handler._onResubscriptionAttemptedCb, self._subscription_handler, terminationCause, nextResubscribeIntervalMsec)
AttributeError: 'NoneType' object has no attribute '_onResubscriptionAttemptedCb'And node-matter keeps printing the following message repeatedly
Received subscribe request from udp://192.168.1.57:41978 on session secure/58969Looking at the code base, it seems like one of the attribute node-matter is returning needs to be an array:
CHIP_ERROR ReportDataMessage::Parser::CheckSchemaValidity
...
case to_underlying(Tag::kAttributeReportIBs):
// check if this tag has appeared before
VerifyOrReturnError(!(tagPresenceMask & (1 << to_underlying(Tag::kAttributeReportIBs))), CHIP_ERROR_INVALID_TLV_TAG);
tagPresenceMask |= (1 << to_underlying(Tag::kAttributeReportIBs));
VerifyOrReturnError(TLV::kTLVType_Array == reader.GetType(), CHIP_ERROR_WRONG_TLV_TYPE);Thanks as usual for your detailed debugging! Found the issue, just a stupid copy / paste issue from my side. Should be fixed now in #20
Somehow, this bug did crash the Andoid test app, I did test the subscribe request with it...
jdesai61
commented
2 years ago With this change, I am able to successfully add device to HA and have it appear in the UI. When I try turning the light ON using the UI, the node-matter prints proper echo message (e.g. matter -on "echo itson")
However, I suspect that since the subscription message is a dummy implementation, the state of the light within HA reverts back to Off and then HA tries to re-subscribe periodically. Here is the log from HA
2022-09-01 17:06:48 local-matter-server matter_server.server.server[122] DEBUG [139646939671520] Received: {"messageId": "2e29a9b5b1db4bb79d320fbe2f232d0a", "command": "device_controller.SendCommand", "args": {"nodeid": 4335, "endpoint": 1, "payload": {"_type": "chip.clusters.Objects.OnOff.Commands.On"}}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-09-01 17:06:48 local-matter-server matter_server.server.server[122] INFO [139646939671520] Deserialized message: CommandMessage(messageId='2e29a9b5b1db4bb79d320fbe2f232d0a', command='device_controller.SendCommand', args={'nodeid': 4335, 'endpoint': 1, 'payload': OnOff.Commands.On()})
2022-09-01 17:06:48 local-matter-server matter_server.server.server[122] DEBUG [139646939671520] Received CommandMessage(messageId='2e29a9b5b1db4bb79d320fbe2f232d0a', command='device_controller.SendCommand', args={'nodeid': 4335, 'endpoint': 1, 'payload': OnOff.Commands.On()})
2022-09-01 17:06:48 local-matter-server chip.IN[122] INFO Prepared secure message 0x7f020401ba38 to 0x00000000000010EF (1) of type 0x8 and protocolId (0, 1) on exchange 35972i with MessageCounter:129042438.
2022-09-01 17:06:48 local-matter-server chip.IN[122] INFO Sending encrypted msg 0x7f020401ba38 with MessageCounter:129042438 to 0x00000000000010EF (1) at monotonic time: 0000000020101A40 msec
2022-09-01 17:06:48 local-matter-server chip.EM[122] INFO Received message of type 0x9 with protocolId (0, 1) and MessageCounter:2289690974 on exchange 35972i
2022-09-01 17:06:48 local-matter-server chip.DMG[122] INFO Received Command Response Status for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0001 Status=0x0
2022-09-01 17:06:48 local-matter-server matter_server.server.server[122] DEBUG [139646939671520] Sending {"messageId": "2e29a9b5b1db4bb79d320fbe2f232d0a", "result": {"raw": null}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-09-01 17:06:48 local-matter-server chip.IN[122] INFO Prepared secure message 0x7f02177fcda8 to 0x00000000000010EF (1) of type 0x10 and protocolId (0, 0) on exchange 35972i with MessageCounter:129042439.
2022-09-01 17:06:48 local-matter-server chip.IN[122] INFO Sending encrypted msg 0x7f02177fcda8 with MessageCounter:129042439 to 0x00000000000010EF (1) at monotonic time: 0000000020101A56 msec
2022-09-01 17:07:05 local-matter-server chip.DMG[122] ERROR Subscription Liveness timeout with SubscriptionID = 0x00000000, Peer = 01:00000000000010EF
2022-09-01 17:07:05 local-matter-server chip.DMG[122] INFO Will try to resubscribe to 01:00000000000010EF at retry index 0 after 0ms due to error ../../src/app/ReadClient.cpp:809: CHIP Error 0x00000032: Timeout
2022-09-01 17:07:05 local-matter-server chip.IN[122] INFO Prepared secure message 0x7f0204031a48 to 0x00000000000010EF (1) of type 0x3 and protocolId (0, 1) on exchange 35973i with MessageCounter:129042440.
2022-09-01 17:07:05 local-matter-server chip.IN[122] INFO Sending encrypted msg 0x7f0204031a48 with MessageCounter:129042440 to 0x00000000000010EF (1) at monotonic time: 0000000020105DFD msec
2022-09-01 17:07:05 local-matter-server chip.EM[122] INFO Received message of type 0x4 with protocolId (0, 1) and MessageCounter:2289690975 on exchange 35973i
2022-09-01 17:07:05 local-matter-server chip.DMG[122] INFO Subscription established with SubscriptionID = 0x00000000 MinInterval = 0s MaxInterval = 10s Peer = 01:00000000000010EF
2022-09-01 17:07:05 local-matter-server chip.DMG[122] INFO Refresh LivenessCheckTime for 35000 milliseconds with SubscriptionId = 0x00000000 Peer = 01:00000000000010EF
2022-09-01 17:07:05 local-matter-server chip.IN[122] INFO Prepared secure message 0x7f02177fcda8 to 0x00000000000010EF (1) of type 0x10 and protocolId (0, 0) on exchange 35973i with MessageCounter:129042441.
2022-09-01 17:07:05 local-matter-server chip.IN[122] INFO Sending encrypted msg 0x7f02177fcda8 with MessageCounter:129042441 to 0x00000000000010EF (1) at monotonic time: 0000000020105E02 msec
...
2022-09-01 17:08:50 local-matter-server chip.DMG[122] ERROR Subscription Liveness timeout with SubscriptionID = 0x00000000, Peer = 01:00000000000010EF
2022-09-01 17:08:50 local-matter-server chip.DMG[122] INFO Will try to resubscribe to 01:00000000000010EF at retry index 0 after 0ms due to error ../../src/app/ReadClient.cpp:809: CHIP Error 0x00000032: Timeout
2022-09-01 17:08:50 local-matter-server chip.IN[122] INFO Prepared secure message 0x7f020402ec28 to 0x00000000000010EF (1) of type 0x3 and protocolId (0, 1) on exchange 35976i with MessageCounter:129042446.
2022-09-01 17:08:50 local-matter-server chip.IN[122] INFO Sending encrypted msg 0x7f020402ec28 with MessageCounter:129042446 to 0x00000000000010EF (1) at monotonic time: 000000002011F83E msec
2022-09-01 17:08:50 local-matter-server chip.EM[122] INFO Received message of type 0x4 with protocolId (0, 1) and MessageCounter:2289690978 on exchange 35976i
2022-09-01 17:08:50 local-matter-server chip.DMG[122] INFO Subscription established with SubscriptionID = 0x00000000 MinInterval = 0s MaxInterval = 10s Peer = 01:00000000000010EF
2022-09-01 17:08:50 local-matter-server chip.DMG[122] INFO Refresh LivenessCheckTime for 35000 milliseconds with SubscriptionId = 0x00000000 Peer = 01:00000000000010EF
2022-09-01 17:08:50 local-matter-server chip.IN[122] INFO Prepared secure message 0x7f02177fcda8 to 0x00000000000010EF (1) of type 0x10 and protocolId (0, 0) on exchange 35976i with MessageCounter:129042447.
2022-09-01 17:08:50 local-matter-server chip.IN[122] INFO Sending encrypted msg 0x7f02177fcda8 with MessageCounter:129042447 to 0x00000000000010EF (1) at monotonic time: 000000002011F846 msecHere is log from node-matter
node build/Main.js -on "echo itson" -off "echo otsoff"
Matter server listening
Pase: Received pairing request from udp://192.168.1.57:41755
Pase: Paired succesfully with udp://192.168.1.57:41755
Received read request from udp://192.168.1.57:41755 on session secure/55302: */49/65532, 0/48/0, 0/48/1, 0/48/2, 0/48/3, 0/40/2, 0/40/4, */49/3
Received invoke request from udp://192.168.1.57:41755 on session secure/55302: 0/48/0
Received invoke request from udp://192.168.1.57:41755 on session secure/55302: 0/48/2
Received invoke request from udp://192.168.1.57:41755 on session secure/55302: 0/62/2
Received invoke request from udp://192.168.1.57:41755 on session secure/55302: 0/62/2
Received invoke request from udp://192.168.1.57:41755 on session secure/55302: 0/62/0
Received invoke request from udp://192.168.1.57:41755 on session secure/55302: 0/62/4
Received invoke request from udp://192.168.1.57:41755 on session secure/55302: 0/62/11
Received invoke request from udp://192.168.1.57:41755 on session secure/55302: 0/62/6
Case: Received pairing request from udp://192.168.1.57:41755
Case: Paired succesfully with udp://192.168.1.57:41755
Received invoke request from udp://192.168.1.57:41755 on session secure/55303: 0/48/4
Received read request from udp://192.168.1.57:41755 on session secure/55303: */*/*
Received subscribe request from udp://192.168.1.57:41755 on session secure/55303
Received read request from udp://192.168.1.57:41755 on session secure/55303: 1/6/0
Received subscribe request from udp://192.168.1.57:41755 on session secure/55303
Received invoke request from udp://192.168.1.57:41755 on session secure/55303: 1/6/1
on: itson
Received subscribe request from udp://192.168.1.57:41755 on session secure/55303
Received subscribe request from udp://192.168.1.57:41755 on session secure/55303
Received subscribe request from udp://192.168.1.57:41755 on session secure/55303Fantastic, we are close now!
The Android app has a subscribe button, so I should be able to do the real implementation of "subscribe". It will require some refactoring though since I now need to keep a state per attribute telling who has subscribe to it, so it will take a couple of days.
mfucci
commented
2 years ago Still working on supporting attribute subscription. I have finished 1/3 of the required code refactoring. So maybe sometime next week it should work.
mfucci
commented
2 years ago Here is a PR implementing attribute subscription: https://github.com/mfucci/node-matter/pull/25
Can you give a try against HA? The subscription seems to stop working after 10s so more debugging might be required, but this should be close!
jdesai61
commented
2 years ago I tried this and we are so close... HA now recognizes the device and shows up in the UI. When I toggle light using On/Off UI, I see log messages in node-matter. However, within a few minutes after comissioning, HA keeps printing following messag
Previous subscription failed with Error: 47 - re-subscribing in 0ms...
Previous subscription failed with Error: 47 - re-subscribing in 0ms...
Previous subscription failed with Error: 47 - re-subscribing in 0ms...
Previous subscription failed with Error: 47 - re-subscribing in 0ms...
2022-09-12 22:13:56 local-matter-server chip.IN[121] INFO Sending encrypted msg 0x7fe4f40316a8 with MessageCounter:207316082 to 0x00000000000010F0 (1) at monotonic time: 0000000059CF40D1 msec
2022-09-12 22:13:58 local-matter-server chip.EM[121] ERROR Failed to Send CHIP MessageCounter:207316082 on exchange 17141i sendCount: 4 max retries: 4
2022-09-12 22:14:09 local-matter-server chip.DIS[121] INFO Checking node lookup status after 15000 ms
2022-09-12 22:14:09 local-matter-server chip.DIS[121] ERROR Operational discovery failed for 0x00000000000010F0: ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: TimeoutAnd node-matter keeps printing
Received subscribe request from udp://192.168.1.57:48369 on session secure/17616
Received subscribe request from udp://192.168.1.57:48369 on session secure/17616
Received subscribe request from udp://192.168.1.57:48369 on session secure/17616
Received subscribe request from udp://192.168.1.57:48369 on session secure/17616I have added full HA matter log here hamatter.log
mfucci
commented
1 year ago Thanks! Sorry, I am slow on this: I am spending my effort on the Matter client right now, I should be able to fix this sometime next week.
The good news is that I can now write an integration test to validate the subscription behavior so this would make it easier to fix this...
jdesai61
commented
1 year ago I have been away for a week and saw lots of activity. Just pulled the latest code (main branch) and still see that the subscription liveness messages are not being sent and hence HA sends another pairing message. See the node-matter errors and HA logs below...
node build/Main.js -on "echo IamOn" -off "echo IamOff"
Pase server: Received pairing request from udp://192.168.1.57:55323
Pase server: Paired succesfully with udp://192.168.1.57:55323
Received read request from udp://192.168.1.57:55323 on session secure/50771: */49/65532, 0/48/0, 0/48/1, 0/48/2, 0/48/3, 0/40/2, 0/40/4, */49/3
Received invoke request from udp://192.168.1.57:55323 on session secure/50771: 0/48/0
Received invoke request from udp://192.168.1.57:55323 on session secure/50771: 0/48/2
Received invoke request from udp://192.168.1.57:55323 on session secure/50771: 0/62/2
Received invoke request from udp://192.168.1.57:55323 on session secure/50771: 0/62/2
Received invoke request from udp://192.168.1.57:55323 on session secure/50771: 0/62/0
Received invoke request from udp://192.168.1.57:55323 on session secure/50771: 0/62/4
Received invoke request from udp://192.168.1.57:55323 on session secure/50771: 0/62/11
Received invoke request from udp://192.168.1.57:55323 on session secure/50771: 0/62/6
Case server: Received pairing request from udp://192.168.1.57:55323
Case server: Paired succesfully with udp://192.168.1.57:55323
Received invoke request from udp://192.168.1.57:55323 on session secure/50772: 0/48/4
Commissioning completed on fabric #1 as node #4336.
Received read request from udp://192.168.1.57:55323 on session secure/50772: */*/*
Received subscribe request from udp://192.168.1.57:55323 on session secure/50772
Received read request from udp://192.168.1.57:55323 on session secure/50772: 1/6/0
Received invoke request from udp://192.168.1.57:55323 on session secure/50772: 1/6/1
on: IamOn
Received invoke request from udp://192.168.1.57:55323 on session secure/50772: 1/6/0
off: IamOff
Case server: Received pairing request from udp://192.168.1.57:55323
An error occured during the commissioning Error: Unsupported state or unable to authenticate data
at Decipheriv.final (node:internal/crypto/cipher:193:29)
at Function.decrypt (/home/DadAdmin/node-matter/build/crypto/Crypto.js:37:16)
at CaseServer.<anonymous> (/home/DadAdmin/node-matter/build/session/secure/CaseServer.js:47:33)
at Generator.next (<anonymous>)
at fulfilled (/home/DadAdmin/node-matter/build/session/secure/CaseServer.js:5:58)
HA Log
2022-10-03 17:01:26 77f1785d-matter-server chip.DMG[122] ERROR Subscription Liveness timeout with SubscriptionID = 0x00000000, Peer = 01:00000000000010F0
2022-10-03 17:01:26 77f1785d-matter-server chip.SC[122] INFO SecureSession[0x7f354801e280]: Moving from state 'kActive' --> 'kDefunct'
2022-10-03 17:01:26 77f1785d-matter-server chip.DMG[122] INFO Will try to resubscribe to 01:00000000000010F0 at retry index 0 after 0ms due to error ../../src/app/ReadClient.cpp:867: CHIP Error 0x00000032: Timeout
2022-10-03 17:01:26 77f1785d-matter-server chip.DMG[122] INFO OnResubscribeTimerCallback: DoCASE = 1
/usr/lib/python3.9/asyncio/events.py:80: RuntimeWarning: coroutine 'DefaultResubscriptionAttemptedCallback' was never awaited
self._context.run(self._callback, *self._args)
RuntimeWarning: Enable tracemalloc to get the object allocation traceback
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%enp0s18:5540: new best score: 2
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 6 ms
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 7 ms
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 8 ms
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 9 ms
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 9 ms
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 10 ms
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-10-03 17:01:26 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 200 ms
2022-10-03 17:01:26 77f1785d-matter-server chip.SC[122] INFO Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x00000000000010F0
2022-10-03 17:01:26 77f1785d-matter-server chip.EM[122] INFO <<< [E:48029i M:130201559] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
2022-10-03 17:01:26 77f1785d-matter-server chip.IN[122] INFO (U) Sending msg 130201559 to IP address 'UDP:192.168.1.28:5540'
2022-10-03 17:01:26 77f1785d-matter-server chip.SC[122] INFO Sent Sigma1 msg
2022-10-03 17:01:26 77f1785d-matter-server chip.EM[122] INFO >>> [E:48029i M:2236577181 (Ack:130201559)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
2022-10-03 17:01:26 77f1785d-matter-server chip.SC[122] ERROR Received error (protocol code 2) during pairing process: ../../src/protocols/secure_channel/CASESession.cpp:1605: CHIP Error 0x00000054: Invalid CASE parameter
2022-10-03 17:01:26 77f1785d-matter-server chip.DMG[122] ERROR Failed to establish CASE for re-subscription with error '../../src/protocols/secure_channel/CASESession.cpp:1605: CHIP Error 0x00000054: Invalid CASE parameter'
2022-10-03 17:01:26 77f1785d-matter-server chip.DMG[122] INFO Will try to resubscribe to 01:00000000000010F0 at retry index 1 after 3639ms due to error ../../src/protocols/secure_channel/CASESession.cpp:1605: CHIP Error 0x00000054: Invalid CASE parameter
2022-10-03 17:01:26 77f1785d-matter-server chip.EM[122] INFO <<< [E:48029i M:130201560 (Ack:2236577181)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-03 17:01:26 77f1785d-matter-server chip.IN[122] INFO (U) Sending msg 130201560 to IP address 'UDP:192.168.1.28%enp0s18:5540'
2022-10-03 17:01:30 77f1785d-matter-server chip.DMG[122] INFO OnResubscribeTimerCallback: DoCASE = 0
2022-10-03 17:01:30 77f1785d-matter-server chip.EM[122] ERROR NewContext failed: session inactive
2022-10-03 17:01:30 77f1785d-matter-server chip.DMG[122] INFO Will try to resubscribe to 01:00000000000010F0 at retry index 2 after 7349ms due to error ../../src/app/ReadClient.cpp:1007: CHIP Error 0x0000000B: No memoryI literally just saw this too while following up.
Unfortunately, I had tested without a cluster command in the invocation, e.g., "..-on "echo 1" -off "echo 0".
My bad.
So, there's a remaining problem as it stands.
mfucci
commented
1 year ago @jdesai61 Can you try with the code from this PR: https://github.com/mfucci/node-matter/pull/50 ? I did find a bug in the subscription reply: protocolVersion field was missing.
Establishing a new session should have worked though... so there are more bugs there. I will add a "debug mode" in the library to help debugging: it will log all message bytes and crypto material so I can reproduce everything on my side.
mfucci
commented
1 year ago I still have more work to do on #50 : the logic to handle min / max update times is still not done.
jdesai61
commented
1 year ago I tried "gh pr checkout 50". But running "npm run build" gives me following errors:
src/matter/interaction/InteractionProtocol.ts:233:60 - error TS2339: Property 'session' does not exist on type 'SubscriptionHandler'.
233 const exchange = this.server.initiateExchange(this.session, this.channel, INTERACTION_PROTOCOL_ID);
~~~~~~~
src/matter/interaction/InteractionProtocol.ts:233:74 - error TS2339: Property 'channel' does not exist on type 'SubscriptionHandler'.
233 const exchange = this.server.initiateExchange(this.session, this.channel, INTERACTION_PROTOCOL_ID);
~~~~~~~
src/matter/interaction/InteractionProtocol.ts:251:60 - error TS2339: Property 'session' does not exist on type 'SubscriptionHandler'.
251 const exchange = this.server.initiateExchange(this.session, this.channel, INTERACTION_PROTOCOL_ID);
~~~~~~~
src/matter/interaction/InteractionProtocol.ts:251:74 - error TS2339: Property 'channel' does not exist on type 'SubscriptionHandler'.
251 const exchange = this.server.initiateExchange(this.session, this.channel, INTERACTION_PROTOCOL_ID);
~~~~~~~
Oups... bleeding-edge branches are sometime still bleeding...
I was in the middle of implementing the MDNS scanner to find the subscriber on the network when I submitted. Give me 10mn and I will fix this.
mfucci
commented
1 year ago Took longer than expected. Can you update the branch and try now? Subscription seems to work from the mobile app.
jdesai61
commented
1 year ago Still getting following error:
node build/Device.js -on "echo IamOn" -off "echo IamOff"
Pase server: Received pairing request from udp://192.168.1.57:51267
Pase server: Paired succesfully with udp://192.168.1.57:51267
Received read request from udp://192.168.1.57:51267 on session secure/56876: */49/65532, 0/48/0, 0/48/1, 0/48/2, 0/48/3, 0/40/2, 0/40/4, */49/3
Received invoke request from udp://192.168.1.57:51267 on session secure/56876: 0/48/0
Received invoke request from udp://192.168.1.57:51267 on session secure/56876: 0/48/2
Received invoke request from udp://192.168.1.57:51267 on session secure/56876: 0/62/2
Received invoke request from udp://192.168.1.57:51267 on session secure/56876: 0/62/2
Received invoke request from udp://192.168.1.57:51267 on session secure/56876: 0/62/0
Received invoke request from udp://192.168.1.57:51267 on session secure/56876: 0/62/4
Received invoke request from udp://192.168.1.57:51267 on session secure/56876: 0/62/11
Received invoke request from udp://192.168.1.57:51267 on session secure/56876: 0/62/6
Case server: Received pairing request from udp://192.168.1.57:51267
Case server: Paired succesfully with udp://192.168.1.57:51267
Received invoke request from udp://192.168.1.57:51267 on session secure/56877: 0/48/4
Commissioning completed on fabric #1 as node #4335.
Received read request from udp://192.168.1.57:51267 on session secure/56877: */*/*
Received subscribe request from udp://192.168.1.57:51267 on session secure/56877
Received read request from udp://192.168.1.57:51267 on session secure/56877: 1/6/0
Case server: Received pairing request from udp://192.168.1.57:51267
An error occured during the commissioning Error: Unsupported state or unable to authenticate data
at Decipheriv.final (node:internal/crypto/cipher:193:29)
at Function.decrypt (/home/DadAdmin/foo/node-matter/build/crypto/Crypto.js:37:16)
at CaseServer.<anonymous> (/home/DadAdmin/foo/node-matter/build/matter/session/secure/CaseServer.js:47:33)
at Generator.next (<anonymous>)
at fulfilled (/home/DadAdmin/foo/node-matter/build/matter/session/secure/CaseServer.js:5:58)HA Log
2022-10-05 16:59:44 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 200 ms
2022-10-05 16:59:44 77f1785d-matter-server chip.SC[121] INFO Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x00000000000010EF
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:30913i M:64792441] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
2022-10-05 16:59:44 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 64792441 to IP address 'UDP:192.168.1.28:5540'
2022-10-05 16:59:44 77f1785d-matter-server chip.SC[121] INFO Sent Sigma1 msg
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO >>> [E:30913i M:2611930197 (Ack:64792441)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
2022-10-05 16:59:44 77f1785d-matter-server chip.SC[121] INFO Received Sigma2 msg
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:30913i M:64792442 (Ack:2611930197)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
2022-10-05 16:59:44 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 64792442 to IP address 'UDP:192.168.1.28%enp0s18:5540'
2022-10-05 16:59:44 77f1785d-matter-server chip.SC[121] INFO Sent Sigma3 msg
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO >>> [E:30913i M:2611930198 (Ack:64792442)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
2022-10-05 16:59:44 77f1785d-matter-server chip.SC[121] INFO Success status report received. Session was established
2022-10-05 16:59:44 77f1785d-matter-server PersistentStorage[121] INFO SetSdkKey: f/1/s/00000000000010EF = b"\x150\x03\x10V\x96\x90I\x997\xc5S\xad\x7f>R?'\xc3_0\x04 \xff\xc7m\xa9idm\x12\x7fC\\\xc1\x19\xa0\x04\xcd\x85\xf3\x89\xab\xdd\x8f\xcb\xf4\xf3\x9b\x9el\xbb\xbf\xcc\xdb0\x05\x0c\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x18"
2022-10-05 16:59:44 77f1785d-matter-server PersistentStorage[121] INFO Committing...
2022-10-05 16:59:44 77f1785d-matter-server PersistentStorage[121] INFO SetSdkKey: g/s/VpaQSZk3xVOtfz5SPyfDXw== = b'\x15$\x01\x01%\x02\xef\x10\x18'
2022-10-05 16:59:44 77f1785d-matter-server PersistentStorage[121] INFO Committing...
2022-10-05 16:59:44 77f1785d-matter-server PersistentStorage[121] INFO SetSdkKey: g/sri = b'\x16\x15$\x01\x01%\x02\xef\x10\x18\x18'
2022-10-05 16:59:44 77f1785d-matter-server PersistentStorage[121] INFO Committing...
2022-10-05 16:59:44 77f1785d-matter-server chip.SC[121] INFO SecureSession[0x7f795001faa0]: Moving from state 'kEstablishing' --> 'kActive'
2022-10-05 16:59:44 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'FindOperational'
2022-10-05 16:59:44 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'FindOperational' -> 'SendComplete'
2022-10-05 16:59:44 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'SendComplete'
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:30914i M:48603990] (S) Msg TX to 1:00000000000010EF [3D44] --- Type 0001:08 (IM:InvokeCommandRequest)
2022-10-05 16:59:44 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 48603990 on secure session with LSID: 51233
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:30913i M:64792443 (Ack:2611930198)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-05 16:59:44 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 64792443 to IP address 'UDP:192.168.1.28%enp0s18:5540'
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO >>> [E:30914i M:2611930199 (Ack:48603990)] (S) Msg RX from 1:00000000000010EF [3D44] --- Type 0001:09 (IM:InvokeCommandResponse)
2022-10-05 16:59:44 77f1785d-matter-server chip.DMG[121] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005
2022-10-05 16:59:44 77f1785d-matter-server chip.CTL[121] INFO Received CommissioningComplete response, errorCode=0
2022-10-05 16:59:44 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'SendComplete'
2022-10-05 16:59:44 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'SendComplete' -> 'Cleanup'
2022-10-05 16:59:44 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'Cleanup'
2022-10-05 16:59:44 77f1785d-matter-server chip.SC[121] INFO SecureSession[0x7f795001f9b0]: Moving from state 'kActive' --> 'kPendingEviction'
2022-10-05 16:59:44 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'Cleanup'
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:30914i M:48603991 (Ack:2611930199)] (S) Msg TX to 1:00000000000010EF [3D44] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-05 16:59:44 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 48603991 on secure session with LSID: 51233
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [140159358257856] Sending {"messageId": "39ce3a0b38f04fd7be8a1806af40ab71", "result": {"raw": true}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [140159358257856] Received: {"messageId": "ac79fbd2f76d474e8d76aa35a0035112", "command": "device_controller.ResolveNode", "args": {"nodeid": 4335}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] INFO [140159358257856] Deserialized message: CommandMessage(messageId='ac79fbd2f76d474e8d76aa35a0035112', command='device_controller.ResolveNode', args={'nodeid': 4335})
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [140159358257856] Received CommandMessage(messageId='ac79fbd2f76d474e8d76aa35a0035112', command='device_controller.ResolveNode', args={'nodeid': 4335})
2022-10-05 16:59:44 77f1785d-matter-server chip.CTL[121] INFO Found an existing secure session to [1:00000000000010EF]!
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [140159358257856] Sending {"messageId": "ac79fbd2f76d474e8d76aa35a0035112", "result": {"raw": null}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [140159358257856] Received: {"messageId": "c9bd35f9624f449281280e9e1eed21d4", "command": "device_controller.Read", "args": {"nodeid": 4335, "attributes": "*", "dataVersionFilters": null, "events": "*", "returnClusterObject": true, "reportInterval": null, "fabricFiltered": true, "keepSubscriptions": false}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] INFO [140159358257856] Deserialized message: CommandMessage(messageId='c9bd35f9624f449281280e9e1eed21d4', command='device_controller.Read', args={'nodeid': 4335, 'attributes': '*', 'dataVersionFilters': None, 'events': '*', 'returnClusterObject': True, 'reportInterval': None, 'fabricFiltered': True, 'keepSubscriptions': False})
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [140159358257856] Received CommandMessage(messageId='c9bd35f9624f449281280e9e1eed21d4', command='device_controller.Read', args={'nodeid': 4335, 'attributes': '*', 'dataVersionFilters': None, 'events': '*', 'returnClusterObject': True, 'reportInterval': None, 'fabricFiltered': True, 'keepSubscriptions': False})
2022-10-05 16:59:44 77f1785d-matter-server chip.CTL[121] INFO Found an existing secure session to [1:00000000000010EF]!
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:30915i M:48603992] (S) Msg TX to 1:00000000000010EF [3D44] --- Type 0001:02 (IM:ReadRequest)
2022-10-05 16:59:44 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 48603992 on secure session with LSID: 51233
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO >>> [E:30915i M:2611930200 (Ack:48603992)] (S) Msg RX from 1:00000000000010EF [3D44] --- Type 0001:05 (IM:ReportData)
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [140159358257856] Sending {"messageId": "c9bd35f9624f449281280e9e1eed21d4", "result": {"attributes": {"0": {"Basic": {"dataModelRevision": null, "vendorName": "node-matter", "vendorID": 65521, "productName": "Matter test device", "productID": 32769, "nodeLabel": null, "location": null, "hardwareVersion": null, "hardwareVersionString": null, "softwareVersion": null, "softwareVersionString": null, "manufacturingDate": null, "partNumber": null, "productURL": null, "productLabel": null, "serialNumber": null, "localConfigDisabled": null, "reachable": null, "uniqueID": null, "capabilityMinima": null, "generatedCommandList": null, "acceptedCommandList": null, "attributeList": null, "featureMap": null, "clusterRevision": null, "_type": "chip.clusters.Objects.Basic"}, "GeneralCommissioning": {"breadcrumb": 4, "basicCommissioningInfo": {"failSafeExpiryLengthSeconds": 60, "maxCumulativeFailsafeSeconds": 0, "_type": "chip.clusters.Objects.GeneralCommissioning.Structs.BasicCommissioningInfo"}, "regulatoryConfig": 0, "locationCapability": 2, "supportsConcurrentConnection": null, "generatedCommandList": null, "acceptedCommandList": null, "attributeList": null, "featureMap": null, "clusterRevision": null, "_type": "chip.clusters.Objects.GeneralCommissioning"}, "Descriptor": {"deviceTypeList": [{"type": 22, "revision": 1, "_type": "chip.clusters.Objects.Descriptor.Structs.DeviceTypeStruct"}], "serverList": [40, 48, 62, 29], "clientList": null, "partsList": [], "generatedCommandList": null, "acceptedCommandList": null, "attributeList": null, "featureMap": null, "clusterRevision": null, "_type": "chip.clusters.Objects.Descriptor"}}, "1": {"OnOff": {"onOff": false, "globalSceneControl": null, "onTime": null, "offWaitTime": null, "startUpOnOff": null, "generatedCommandList": null, "acceptedCommandList": null, "attributeList": null, "featureMap": null, "clusterRevision": null, "_type": "chip.clusters.Objects.OnOff"}, "Descriptor": {"deviceTypeList": [{"type": 256, "revision": 1, "_type": "chip.clusters.Objects.Descriptor.Structs.DeviceTypeStruct"}], "serverList": [6, 29], "clientList": null, "partsList": [], "generatedCommandList": null, "acceptedCommandList": null, "attributeList": null, "featureMap": null, "clusterRevision": null, "_type": "chip.clusters.Objects.Descriptor"}}}, "events": [], "_type": "chip.clusters.Attribute.AsyncReadTransaction.ReadResponse"}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:30915i M:48603993 (Ack:2611930200)] (S) Msg TX to 1:00000000000010EF [3D44] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-05 16:59:44 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 48603993 on secure session with LSID: 51233
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [140159358257856] Received: {"messageId": "82bf75ac13ad4679bbf71b4ba55026d2", "command": "device_controller.Read", "args": {"nodeid": 4335, "attributes": [[1, {"_class": "chip.clusters.Objects.OnOff.Attributes.OnOff"}]], "dataVersionFilters": null, "events": null, "returnClusterObject": false, "reportInterval": [0, 10], "fabricFiltered": true, "keepSubscriptions": true}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] INFO [140159358257856] Deserialized message: CommandMessage(messageId='82bf75ac13ad4679bbf71b4ba55026d2', command='device_controller.Read', args={'nodeid': 4335, 'attributes': [[1, <class 'chip.clusters.Objects.OnOff.Attributes.OnOff'>]], 'dataVersionFilters': None, 'events': None, 'returnClusterObject': False, 'reportInterval': [0, 10], 'fabricFiltered': True, 'keepSubscriptions': True})
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [140159358257856] Received CommandMessage(messageId='82bf75ac13ad4679bbf71b4ba55026d2', command='device_controller.Read', args={'nodeid': 4335, 'attributes': [[1, <class 'chip.clusters.Objects.OnOff.Attributes.OnOff'>]], 'dataVersionFilters': None, 'events': None, 'returnClusterObject': False, 'reportInterval': [0, 10], 'fabricFiltered': True, 'keepSubscriptions': True})
2022-10-05 16:59:44 77f1785d-matter-server chip.CTL[121] INFO Found an existing secure session to [1:00000000000010EF]!
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:30916i M:48603994] (S) Msg TX to 1:00000000000010EF [3D44] --- Type 0001:03 (IM:SubscribeRequest)
2022-10-05 16:59:44 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 48603994 on secure session with LSID: 51233
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO >>> [E:41336r M:2611930201] (S) Msg RX from 1:00000000000010EF [3D44] --- Type 0001:05 (IM:ReportData)
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:41336r M:48603995 (Ack:2611930201)] (S) Msg TX to 1:00000000000010EF [3D44] --- Type 0001:01 (IM:StatusResponse)
2022-10-05 16:59:44 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 48603995 on secure session with LSID: 51233
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO >>> [E:30916i M:2611930202 (Ack:48603994)] (S) Msg RX from 1:00000000000010EF [3D44] --- Type 0001:04 (IM:SubscribeResponse)
2022-10-05 16:59:44 77f1785d-matter-server chip.DMG[121] INFO SubscribeResponse is received
2022-10-05 16:59:44 77f1785d-matter-server chip.DMG[121] INFO Subscription established with SubscriptionID = 0x00000000 MinInterval = 0s MaxInterval = 10s Peer = 01:00000000000010EF
2022-10-05 16:59:44 77f1785d-matter-server chip.DMG[121] INFO Refresh LivenessCheckTime for 35000 milliseconds with SubscriptionId = 0x00000000 Peer = 01:00000000000010EF
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:30916i M:48603996 (Ack:2611930202)] (S) Msg TX to 1:00000000000010EF [3D44] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-05 16:59:44 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 48603996 on secure session with LSID: 51233
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] INFO [140159358257856] Setting up Subscription for [(1, <class 'chip.clusters.Objects.OnOff.Attributes.OnOff'>)]
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] INFO [140159358257856] SubscriptionId 0
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [140159358257856] Sending {"messageId": "82bf75ac13ad4679bbf71b4ba55026d2", "result": {"subscription_id": 0}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [140159358257856] Received: {"messageId": "96b3d556824140f897271559a3f72d6c", "command": "device_controller.Read", "args": {"nodeid": 4335, "attributes": [[1, {"_class": "chip.clusters.Objects.OnOff.Attributes.OnOff"}]], "dataVersionFilters": null, "events": null, "returnClusterObject": false, "reportInterval": null, "fabricFiltered": true, "keepSubscriptions": false}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] INFO [140159358257856] Deserialized message: CommandMessage(messageId='96b3d556824140f897271559a3f72d6c', command='device_controller.Read', args={'nodeid': 4335, 'attributes': [[1, <class 'chip.clusters.Objects.OnOff.Attributes.OnOff'>]], 'dataVersionFilters': None, 'events': None, 'returnClusterObject': False, 'reportInterval': None, 'fabricFiltered': True, 'keepSubscriptions': False})
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [140159358257856] Received CommandMessage(messageId='96b3d556824140f897271559a3f72d6c', command='device_controller.Read', args={'nodeid': 4335, 'attributes': [[1, <class 'chip.clusters.Objects.OnOff.Attributes.OnOff'>]], 'dataVersionFilters': None, 'events': None, 'returnClusterObject': False, 'reportInterval': None, 'fabricFiltered': True, 'keepSubscriptions': False})
2022-10-05 16:59:44 77f1785d-matter-server chip.CTL[121] INFO Found an existing secure session to [1:00000000000010EF]!
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:30917i M:48603997] (S) Msg TX to 1:00000000000010EF [3D44] --- Type 0001:02 (IM:ReadRequest)
2022-10-05 16:59:44 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 48603997 on secure session with LSID: 51233
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO >>> [E:30917i M:2611930203 (Ack:48603997)] (S) Msg RX from 1:00000000000010EF [3D44] --- Type 0001:05 (IM:ReportData)
2022-10-05 16:59:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [140159358257856] Sending {"messageId": "96b3d556824140f897271559a3f72d6c", "result": {"attributes": {"1": {"OnOff": {"DataVersion": 0, "OnOff": false}}}, "events": [], "_type": "chip.clusters.Attribute.AsyncReadTransaction.ReadResponse"}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-10-05 16:59:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:30917i M:48603998 (Ack:2611930203)] (S) Msg TX to 1:00000000000010EF [3D44] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-05 16:59:44 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 48603998 on secure session with LSID: 51233
2022-10-05 16:59:45 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 48603995 on secure session with LSID: 51233
2022-10-05 16:59:45 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 48603995 on secure session with LSID: 51233
2022-10-05 16:59:45 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 48603995 on secure session with LSID: 51233
2022-10-05 16:59:46 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 48603995 on secure session with LSID: 51233
2022-10-05 16:59:48 77f1785d-matter-server chip.EM[121] ERROR Failed to Send CHIP MessageCounter:48603995 on exchange 41336r sendCount: 4 max retries: 4
2022-10-05 16:59:48 77f1785d-matter-server chip.SC[121] INFO SecureSession[0x7f795001faa0]: Moving from state 'kActive' --> 'kDefunct'There is some progress, I now see "Subscription established with SubscriptionID = 0x00000000"
I see what is the problem now: the code doesn't expect a StatusResponse reply after it sends the attribute value so it doesn't ack it, which in turn makes HA believes that the session is down.
Let me fix that, thanks for your patience and again thanks a lot for testing / debugging with me!
mfucci
commented
1 year ago Hmmm... the Android app I compiled some time ago is not sending those StatusResponse on Subscription messages... Maybe something has changed in the protocol, however I am not able to recompile a new Android app on the lastest Matter codebase. This will take some time to fix since I need to figure out what is supposed to be the correct message flow.
mfucci
commented
1 year ago The Matter protocol seems to have modified since I compiled the Android app since a newly built chip-tool is also sending a StatusResponse, like HA.
I updated the code now to wait for a StatusResponse and added additional logs for debugging.
Can you give a try now?
jdesai61
commented
1 year ago I just tried it again, HA adds the device and I can try to toggle on/off. But when I do that, I get error on node-matter side.
node build/Device.js -on "IamOn" -off "IamOff"
onMessageReceived id:0/921/39106174 t:0/32 reqAck:true payload: 153001203b94300497f2a6f937db14c595046ad7f5c474166e89d67275f633ad7086c6682502fb6e240300280435052501881325022c011818
Pase server: Received pairing request from udp://192.168.1.57:58823
sending id:0/921/1954469591 t:0/33 acked:39106174 reqAck:true payload: 153001203b94300497f2a6f937db14c595046ad7f5c474166e89d67275f633ad7086c66830022034f1cefc23fba0cd7f91c1b3f3aa76720ddaa18fc674cb1e807daedff44c2ae02503bc3a35042501e8033002201054a7210975c47e3144c77f6d96b370283f7d0ac800fa336439be047ad69cb51835052501881325022c011818
onMessageReceived id:0/921/39106175 t:0/34 acked:1954469591 reqAck:true payload: 15300141048c1c45024e660ff612f8c2c9f3d5c526360434f0615d4171b6b1df6a169ab3a0ecda249062cee45196d32f5bd3132964dd5c985fc5aaf2988d350a6a712fc29618
sending id:0/921/1954469592 t:0/35 acked:39106175 reqAck:true payload: 1530014104db2b172e043426c182b4410cd01246a4bdfeb342409f7aed1a23fd569c4be5001e5a6e04a4a4dbd352f77a14a4f75f140311d90309d29845684111cb413abee53002206a8f595f20e306a7aef897983914853b71757e4d96950082588d6288d7449e0918
onMessageReceived id:0/921/39106176 t:0/36 acked:1954469592 reqAck:true payload: 1530012031c0dce7d7c22ff3d835a98fda42e531fc1c60a16fb00ab45d1a0913e79d553218
sending id:0/921/1954469593 t:0/64 acked:39106176 reqAck:true payload: 0000000000000000
Pase server: Paired succesfully with udp://192.168.1.57:58823
onMessageReceived id:15036/922/24924086 t:1/2 reqAck:true payload: 153600172403312504fcff18172402002403302404001817240200240330240401181724020024033024040218172402002403302404031817240200240328240402181724020024032824040418172403312404031818280324ff0118
Received read request from udp://192.168.1.57:58823 on session secure/15036: */49/65532, 0/48/0, 0/48/1, 0/48/2, 0/48/3, 0/40/2, 0/40/4, */49/3
sending id:15036/922/1954469594 t:1/5 acked:24924086 reqAck:true payload: 1536011535012400003701240200240330240400182402001818153501240000370124020024033024040118350224003c181818153501240000370124020024033024040218240200181815350124000037012402002403302404031824020218181535012400003701240200240328240402182502f1ff181815350124000037012402002403282404041825020180181818290424ff0118
onMessageReceived id:0/921/39106177 t:0/16 acked:1954469593 reqAck:false payload:
onMessageReceived id:15036/923/24924087 t:1/8 reqAck:true payload: 1528002801360215370024000024013024020018350124003c24010318181824ff0118
Received invoke request from udp://192.168.1.57:58823 on session secure/15036: 0/48/0
sending id:15036/923/1954469595 t:1/9 acked:24924087 reqAck:true payload: 152800360115350037002400002401302402011835012400002c01001818181824ff0118
onMessageReceived id:15036/922/24924088 t:0/16 acked:1954469594 reqAck:false payload:
onMessageReceived id:15036/924/24924089 t:1/8 reqAck:true payload: 152800280136021537002400002401302402021835012400002c0102585824020418181824ff0118
Received invoke request from udp://192.168.1.57:58823 on session secure/15036: 0/48/2
sending id:15036/924/1954469596 t:1/9 acked:24924089 reqAck:true payload: 152800360115350037002400002401302402031835012400002c01001818181824ff0118
onMessageReceived id:15036/923/24924090 t:0/16 acked:1954469595 reqAck:false payload:
onMessageReceived id:15036/925/24924091 t:1/8 reqAck:true payload: 1528002801360215370024000024013e24020218350124000218181824ff0118
Received invoke request from udp://192.168.1.57:58823 on session secure/15036: 0/62/2
sending id:15036/925/1954469597 t:1/9 acked:24924091 reqAck:true payload: 1528003601153500370024000024013e2402031835013100d801308201d43082017aa00302010202083e6ce6509ad840cd300a06082a8648ce3d04030230303118301606035504030c0f4d617474657220546573742050414131143012060a2b0601040182a27c02010c04464646313020170d3231303632383134323334335a180f39393939313233313233353935395a30463118301606035504030c0f4d617474657220546573742050414931143012060a2b0601040182a27c02010c044646463131143012060a2b0601040182a27c02020c04383030303059301306072a8648ce3d020106082a8648ce3d0301070342000480ddf11b228f3e31f63bcf5798da14623aebbde82ef378eeadbfb18fe1abce31d08ed4b20604b6ccc6d9b5fab64e7de10cb74be017c9ec1516056d70f2cd0b22a366306430120603551d130101ff040830060101ff020100300e0603551d0f0101ff040403020106301d0603551d0e04160414af42b7094debd515ec6ecf33b81115225f325288301f0603551d230418301680146afd22771f511fecbf1641976710dcdc31a1717e300a06082a8648ce3d040302034800304502210096c9c8cf2e01886005d8f5bc72c07b75fd9a57695ac4911131138bea033ce50302202554943be57d53d6c475f7d23ebfcfc2036cd29ba6393ec7efad8714ab7182191818181824ff0118
onMessageReceived id:15036/924/24924092 t:0/16 acked:1954469596 reqAck:false payload:
onMessageReceived id:15036/926/24924093 t:1/8 reqAck:true payload: 1528002801360215370024000024013e24020218350124000118181824ff0118
Received invoke request from udp://192.168.1.57:58823 on session secure/15036: 0/62/2
sending id:15036/926/1954469598 t:1/9 acked:24924093 reqAck:true payload: 1528003601153500370024000024013e2402031835013100ec01308201e83082018fa0030201020208143c9d1689f498f0300a06082a8648ce3d04030230463118301606035504030c0f4d617474657220546573742050414931143012060a2b0601040182a27c02010c044646463131143012060a2b0601040182a27c02020c04383030303020170d3231303632383134323334335a180f39393939313233313233353935395a304b311d301b06035504030c144d6174746572205465737420444143203030303731143012060a2b0601040182a27c02010c044646463131143012060a2b0601040182a27c02020c04383030303059301306072a8648ce3d020106082a8648ce3d0301070342000462e2b6e1baff8d74a6fd8216c4cb67a3363a31e691492792e61aee610261481396725ef95e142686ba98f339b0ff65bc338bec7b9e8be0bdf3b2774982476220a360305e300c0603551d130101ff04023000300e0603551d0f0101ff040403020780301d0603551d0e04160414ee95ad96983a9ea95bcd2b00dc5e671727690383301f0603551d23041830168014af42b7094debd515ec6ecf33b81115225f325288300a06082a8648ce3d040302034700304402202f51cf53bf7777df7318094b9db595eebf2fa881c8c572847b1e689ece654264022029782708ee6b32c7f08ff63dbe618e9a580bb14c183bc288777adf9e2dcff5e61818181824ff0118
onMessageReceived id:15036/925/24924094 t:0/16 acked:1954469597 reqAck:false payload:
onMessageReceived id:15036/927/24924095 t:1/8 reqAck:true payload: 1528002801360215370024000024013e240200183501300020c055a81f85e343fb74707b97d1e7ace5ebdcc11e7ba13c6bdebd54cd1c85636c18181824ff0118
Received invoke request from udp://192.168.1.57:58823 on session secure/15036: 0/62/0
sending id:15036/927/1954469599 t:1/9 acked:24924095 reqAck:true payload: 1528003601153500370024000024013e240201183501310049021531011d023082021906092a864886f70d010702a082020a30820206020103310d300b06096086480165030402013082017106092a864886f70d010701a08201620482015e152400012501f1ff3602050080050180050280050380050480050580050680050780050880050980050a80050b80050c80050d80050e80050f80051080051180051280051380051480051580051680051780051880051980051a80051b80051c80051d80051e80051f80052080052180052280052380052480052580052680052780052880052980052a80052b80052c80052d80052e80052f80053080053180053280053380053480053580053680053780053880053980053a80053b80053c80053d80053e80053f80054080054180054280054380054480054580054680054780054880054980054a80054b80054c80054d80054e80054f80055080055180055280055380055480055580055680055780055880055980055a80055b80055c80055d80055e80055f80056080056180056280056380182403162c04135a494732303134325a423333303030332d32342405002406002507942624080018317d307b020103801462fa823359acfaa9963e1cfa140addf504f37160300b0609608648016503040201300a06082a8648ce3d04030204473045022024e5d1f47a7d7b0d206a26ef699b7c9757b72d469089de3192e678c745e7f60c022100f8aa2fa711fcb79b97e397ceda667bae464e2bd3ffdfc3cced7aa8ca5f4c1a7c300220c055a81f85e343fb74707b97d1e7ace5ebdcc11e7ba13c6bdebd54cd1c85636c24030018300140de32dc2b53182a0d20b99ecc97596849e80f82db93acc8446a7dc1231c660ca9a3959e19d651274be6219657a7b359b7cf6d33c9ac19441463e9ff197a8d06251818181824ff0118
onMessageReceived id:15036/926/24924096 t:0/16 acked:1954469598 reqAck:false payload:
onMessageReceived id:15036/928/24924097 t:1/8 reqAck:true payload: 1528002801360215370024000024013e240204183501300020ccfbcaa52c21154f3276ed2b59a45eda9d7c513a0abb11a31e88b21550f6d02a18181824ff0118
Received invoke request from udp://192.168.1.57:58823 on session secure/15036: 0/62/4
sending id:15036/928/1954469600 t:1/9 acked:24924097 reqAck:true payload: 1528003601153500370024000024013e2402051835013000f3153001cb3081c83070020100300e310c300a060355040a0c034353523059301306072a8648ce3d020106082a8648ce3d03010703420004b153bffa4ddf0d3772ce050ae601012e146aaa67908c89ae4a973723381be88327ed73c4206c7f6a9d2baa38a7b692ab7a262d6716b1489634508d9329a4578aa000300a06082a8648ce3d04030203480030450220458f1e142d679bb3a4372fd515b7a102ad7483265e77dfa83515f0a5543b4fde022100eadc5550598d551834adce52e1dec827e12e480e3c76185689bc93ecbf827df6300220ccfbcaa52c21154f3276ed2b59a45eda9d7c513a0abb11a31e88b21550f6d02a183001406cf8ab6c137189ce20c79fca629cf704c23b4c491d04ce29209b09cdf55abe6b2a93cc18ee38cce1c6f03d3713113fa0480516da7b4eaa39fa400db0680e67521818181824ff0118
onMessageReceived id:15036/927/24924098 t:0/16 acked:1954469599 reqAck:false payload:
onMessageReceived id:15036/929/24924099 t:1/8 reqAck:true payload: 1528002801360215370024000024013e24020b1835013000e71530010101240201370324140118260480228127260580254d3a3706241401182407012408013009410480eb6673b37e2d07153d0900adf458dc8b60b9fe00936ec936d17998b70d7ed93fa341c38e020aba3964949362b4baa75d11263fccefaa6d5b2387a0fe8aed58370a35012901182402603004147a8349743147a82d1b223bd803a1ce08e7fef8913005147a8349743147a82d1b223bd803a1ce08e7fef89118300b40f0ca9d41b5fc5b74a8fdba26f933fd39a095e9776352000c03e2e7202dd13797cb8fb56784a0b633e3180a7488918ef3822e18b93839d4b65fa344934d3f1e371818181824ff0118
Received invoke request from udp://192.168.1.57:58823 on session secure/15036: 0/62/11
sending id:15036/929/1954469601 t:1/9 acked:24924099 reqAck:true payload: 1528003601153501370024000024013e24020b1835012400001818181824ff0118
onMessageReceived id:15036/928/24924100 t:0/16 acked:1954469600 reqAck:false payload:
onMessageReceived id:15036/930/24924101 t:1/8 reqAck:true payload: 1528002801360215370024000024013e2402061835013000f21530010101240201370324130218260480228127260580254d3a37062415012511f2101824070124080130094104b153bffa4ddf0d3772ce050ae601012e146aaa67908c89ae4a973723381be88327ed73c4206c7f6a9d2baa38a7b692ab7a262d6716b1489634508d9329a4578a370a3501280118240201360304020401183004147931e0fad6db14984c63b92e5c89ac3e5f2ef38430051408f1aea9203fc4ee2e091c942a6e8a2518f54b4b18300b40208661ad8dd687cd782951798f7c7740455ce1f22c31daccd069ef00dc4005c0d65a083abcc392f91ae3ef4e1f4d9749de72fc39bb1a09c9704c892c399e064d183001e71530010101240201370324140118260480228127260580254d3a37062413021824070124080130094104fe57c93eefec4883fb4eef15f0c5867efaeb2698213cec56108eca6764f23a473fc36448e9df440b0cb5937b6d901d3c81a1a0b6061ad2de08f747c48567d40f370a350129011824026030041408f1aea9203fc4ee2e091c942a6e8a2518f54b4b3005147a8349743147a82d1b223bd803a1ce08e7fef89118300b40218f53ed59c5591cd165d5bbc3f29bd55fd05b84426c771aee28b423b97025936ba8db00bfe9463c172cdec34630f0facd0b06ac2eecb8e3eaabf37e883066121830021074656d706f726172792069706b203031260369b601002504f1ff18181824ff0118
Received invoke request from udp://192.168.1.57:58823 on session secure/15036: 0/62/6
onMessageReceived id:15036/929/24924102 t:0/16 acked:1954469601 reqAck:false payload:
sending id:15036/930/1954469602 t:1/9 acked:24924101 reqAck:true payload: 1528003601153500370024000024013e2402081835012400001818181824ff0118
onMessageReceived id:15036/930/24924103 t:0/16 acked:1954469602 reqAck:false payload:
onMessageReceived id:0/931/39106178 t:0/48 reqAck:true payload: 1530012036dc7bb5e7d8949b8d05ec4f417eb4d52cce0e27c6316bd5091e49f1b16caa432502fc6e300320c0e5bb6ee8fb02f661663fd5d562d945b1d3ca9882412035bd57cf7fed511f5b300441045eb90f57fc8703a2643512e7b312a1cc8b90d6dabd30a9e34d6b8918f4239fb5dc1545db0fbf23e225271df494ad72e931b80c6603dd71870b6fcb2ed21a834535052501881325022c011818
Case server: Received pairing request from udp://192.168.1.57:58823
sending id:0/931/1954469603 t:0/49 acked:39106178 reqAck:true payload: 15300120f64b7f2188f275aed4690b8308512e0f57c8f66de65e086322c95f0182e819a02502bd3a300341046e9f45d1ce1c4f287719b6b1e53a99fdbba710c3565399cf4f0a9218c38be8f82630472ee38cd901492ecb6861f44a0a6ad12842be0de8953d7c1e2a11ebbbd0310447027aa4736511d4ecaad6937fd6dafe66762e99c17c6637c07450b65560a2b78cb7aba82ecaf18daf67ee5d681d53f4e9b306d23666c10bcc1fd11432cd630e8f2b088687f0443b007804d5ee157f6952947dc79793a57b3c3c5716e1d1f423ba84153e5cd6fb8cda3210551ef2a7c728b8bb985cd147d8a4cd068ec8ccf9e76bef8e997f7d0b838d6dc9d078f4854f9aeb8249baa79668e05ffbb58aa3cc015b850e2368fbf94378f078ff423f7d71b05f9521379775dfb20c7411b937e3df695201cee23f7fcf30edc088bf0431babdc15a21c036ce2608f9ae7b8a111cd18e855c89fe1e6d3cdcde7d6246740ed9517e8979b70a361aa931605012c19a1340602a083afb44e7374757b1d0c584cdc21c9cf2e0db6ee0208d92ab96cbb77bca8708a527c400d04b6a318d86d042d42d348bc18ff2b20d60b96784e5ef0878c513e85c497110589fdd9a21b8e81009b1fe7d359e808970e92a0a08e6e4f26275413fde35a40aae55af8b026ecbac00a2c590047ac176bb90a9da1a1b9a16214f17b22454b6dd9dc7669836a08e1fa00c64654e95a4e429bf8470be03092152e3505e9197fd1ddd49c00e86a073874d4f1ea9fc332846905a2f560758c15934d201b713f6f23a0b7ae714d5cd9a84e539b244a056e63a1317a347d2010c589a23da93dcebcb9e15919c3e92339798e1bfd306c312720be182c3875ecde0211588bc37eb47d36f669b2bd2a556b7525ff32ab1431b6cf2141b9f6fd60b0b1076dc96782e0a294d3947d6b89cd55e0bad8a33f73226649100e7ed1df10de5b79ab608971af21d7f4e5d35052501881325022c011818
onMessageReceived id:0/931/39106179 t:0/50 acked:1954469603 reqAck:true payload: 1531013602947c87db39965f3d3d2f23815bf4ea4f133512e81dc35756fed155f6cc1881cb529ec71ff6debd13b22a96e77ee2476ccbde67554d966a8877a1c24e9cceaed19310b3ef639add3fc8343213632447efc0852dee27bb7544455abce8be110d7c56a9fdd46b6a14056989c4a1982582da5cbc9a392fb985faa7bf7c9ff3ed4843756b036292d01c92154fcdad8b974e4f35669ab4b523a4fd4dabcc701eacf590f68ee195cfae23538dbcd9dbe3da52994d244833bcb95ee7efe3c04b29537ef2a0639cfd91774f8d69db346749c032ebfe5161dbfce8ea6e2e18a3438af3fbae5e0d0cca81e4578250f0c744ebe5d1747642a59fe7b6b013c24081434f0c4a40b0b76537fa73deb0bf68b04ffdf25909310f3847ae705b83be9a17581bf5a82f02790a21a19ccca040716a40008d4f04edb93d1c96e55790b10ba42c8b8c32a868858f47435cfd1f1c57e2f5737299bbe51b9cc5edc2c0ea3d05f78f66e380c7c7d3d50b9a3c741ba3dd6dc7c8e5c0e18615e9391f8500fa8cf2d81091cd1d56bbb6bdd20dd3a4c8585b97dc027e668af1e6bd9b5e588d055cf499b24c0d0e87ac0fedbeceeaa03d12bd4d3261342d956e8bf2098301ba5fedccace5bb3e00b753e93098b663c0e6a0d97a0ab6663ff144ff8599305456431eed9d29ef996c4902d83944ed560c266ed7562c3ce6c9e78e5603bfa8fce41f662d93bc55d2dd47360575a9a8fbb5abcc9f4fa4f639312802555abd00308f6d3731fdbd93f30f76a8e18b9662d867c614bf41b6e5d140cef4a1f499652518
Case server: Paired succesfully with udp://192.168.1.57:58823
sending id:0/931/1954469604 t:0/64 acked:39106179 reqAck:true payload: 0000000000000000
onMessageReceived id:15037/932/65784833 t:1/8 reqAck:true payload: 1528002801360215370024000024013024020418350118181824ff0118
Received invoke request from udp://192.168.1.57:58823 on session secure/15037: 0/48/4
Commissioning completed on fabric #1 as node #4338.
sending id:15037/932/1954469605 t:1/9 acked:65784833 reqAck:true payload: 152800360115350037002400002401302402051835012400002c01001818181824ff0118
onMessageReceived id:0/931/39106180 t:0/16 acked:1954469604 reqAck:false payload:
onMessageReceived id:15037/932/65784834 t:0/16 acked:1954469605 reqAck:false payload:
onMessageReceived id:15037/933/65784835 t:1/2 reqAck:true payload: 1536001718183601171818290324ff0118
Received read request from udp://192.168.1.57:58823 on session secure/15037: */*/*
sending id:15037/933/1954469606 t:1/5 acked:65784835 reqAck:true payload: 1536011535012400003701240200240328240401182c020b6e6f64652d6d617474657218181535012400003701240200240328240402182502f1ff18181535012400003701240200240328240403182c02124d617474657220746573742064657669636518181535012400003701240200240328240404182502018018181535012400023701240200240330240400182402041818153501240000370124020024033024040118350224003c18181815350124000037012402002403302404021824020018181535012400003701240200240330240403182402021818153501240000370124020024031d2404001836021524001624010118181818153501240001370124020024031d24040118360204280430043e041d181818153501240000370124020024031d240403183602181818153501240001370124020024031d240404183602040118181815350124000037012402012403062404001828021818153501240000370124020124031d240400183602152500000124010118181818153501240001370124020124031d2404011836020406041d181818153501240000370124020124031d240403183602181818153501240000370124020124031d24040418360218181818290424ff0118
onMessageReceived id:15037/933/65784836 t:0/16 acked:1954469606 reqAck:false payload:
onMessageReceived id:15037/934/65784837 t:1/3 reqAck:true payload: 15290024010024020a3603172402012403062404001818290724ff0118
Received subscribe request from udp://192.168.1.57:58823 on session secure/15037
Sending updates
sending id:28412/40283/1954469607 t:1/5 reqAck:true payload: 152400003601153501240000370124020124030624040018280218181824ff0118
sending id:15037/934/1954469608 t:1/4 acked:65784837 reqAck:true payload: 1524000024020a24ff0118
Waiting for success
onMessageReceived id:15037/40283/65784838 t:1/1 acked:1954469607 reqAck:true payload: 1524007d24ff0118
Success received
sending id:28412/40283/1954469609 t:1/16 acked:65784838 reqAck:false payload:
onMessageReceived id:15037/934/65784839 t:0/16 acked:1954469608 reqAck:false payload:
onMessageReceived id:15037/935/65784840 t:1/2 reqAck:true payload: 153600172402012403062404001818290324ff0118
Received read request from udp://192.168.1.57:58823 on session secure/15037: 1/6/0
sending id:15037/935/1954469610 t:1/5 acked:65784840 reqAck:true payload: 1536011535012400003701240201240306240400182802181818290424ff0118
onMessageReceived id:15037/935/65784841 t:0/16 acked:1954469610 reqAck:false payload:
onMessageReceived id:0/936/39106181 t:0/48 reqAck:true payload: 15300120d16e97ffe6ac9cf9b241690a52a28d03ab8b0ea0c3475c4d6e77f099e4ace5332502fd6e300320ffa96e8a836afd7faeddd35c6432bb597161028c8668ce3c48651c5014d5eb3a300441044e74fb33eb8ceca529ab00b6462ef47cee4f9acebdede74be4efe92af266e447d850a69e491251c262dfab02910853f135b592a84b702c27db2b24b8fa18330b35052501881325022c0118300610b75b0cc5ccd127413bf70cf92f00ec20300710c58d7c0126352c7fc4cf13a62afc97a418
Case server: Received pairing request from udp://192.168.1.57:58823
An error occured during the commissioning Error: Unsupported state or unable to authenticate data
at Decipheriv.final (node:internal/crypto/cipher:193:29)
at Function.decrypt (/home/DadAdmin/foo/node-matter/build/crypto/Crypto.js:37:16)
at CaseServer.<anonymous> (/home/DadAdmin/foo/node-matter/build/matter/session/secure/CaseServer.js:47:33)
at Generator.next (<anonymous>)
at fulfilled (/home/DadAdmin/foo/node-matter/build/matter/session/secure/CaseServer.js:5:58)
sending id:0/936/1954469611 t:0/64 acked:39106181 reqAck:true payload: 0100000000000200
onMessageReceived id:0/936/39106182 t:0/16 acked:1954469611 reqAck:false payload:
onMessageReceived id:0/937/39106183 t:0/48 reqAck:true payload: 15300120b9a9e2796866396dcd2269896e8840fef23490f2e35832a3f326739dacf0c2312502fe6e300320b11b0e0b2cc6bd2b03e8f4183f70fa2c51ab30d37aac9c4156b5327bfc32d947300441042571554d862e86a592949b57769dd63c8c3b740c2c5aa55609357f3cbc7f16a582a6dfdc865216d4f24b31a1e8f64acf7bf1cbd2c7347d0b9b0d214fe4970ed035052501881325022c0118300610b75b0cc5ccd127413bf70cf92f00ec2030071005b7e528f0f4e814a62d788f249a4df718
Case server: Received pairing request from udp://192.168.1.57:58823
An error occured during the commissioning Error: Unsupported state or unable to authenticate data
at Decipheriv.final (node:internal/crypto/cipher:193:29)
at Function.decrypt (/home/DadAdmin/foo/node-matter/build/crypto/Crypto.js:37:16)
at CaseServer.<anonymous> (/home/DadAdmin/foo/node-matter/build/matter/session/secure/CaseServer.js:47:33)
at Generator.next (<anonymous>)
at fulfilled (/home/DadAdmin/foo/node-matter/build/matter/session/secure/CaseServer.js:5:58)
sending id:0/937/1954469612 t:0/64 acked:39106183 reqAck:true payload: 0100000000000200
onMessageReceived id:0/937/39106184 t:0/16 acked:1954469612 reqAck:false payload:
onMessageReceived id:0/938/39106185 t:0/48 reqAck:true payload: 15300120c35b336002600e9d2142d8bdd5bc62867a1fb1bf3200f869dabc6a82c8e49aec2502ff6e3003206e31b926d3f9202b4f52764bb4c1595a2dde81e999a86a9f88ffd28732b9b6c5300441047bc013c263519b2af48179d2c689e95e77905d0dac2ef56883ec7baf761ce15c0d9d867d6a75489e0fd4c86cb5ef97ca59d9e044de3c7c5d5614d5ee9905568835052501881325022c0118300610b75b0cc5ccd127413bf70cf92f00ec203007108e148b692392b434ea68d654219ce38518
Case server: Received pairing request from udp://192.168.1.57:58823
An error occured during the commissioning Error: Unsupported state or unable to authenticate data
at Decipheriv.final (node:internal/crypto/cipher:193:29)
at Function.decrypt (/home/DadAdmin/foo/node-matter/build/crypto/Crypto.js:37:16)
at CaseServer.<anonymous> (/home/DadAdmin/foo/node-matter/build/matter/session/secure/CaseServer.js:47:33)
at Generator.next (<anonymous>)
at fulfilled (/home/DadAdmin/foo/node-matter/build/matter/session/secure/CaseServer.js:5:58)
sending id:0/938/1954469613 t:0/64 acked:39106185 reqAck:true payload: 0100000000000200
onMessageReceived id:0/938/39106186 t:0/16 acked:1954469613 reqAck:false payload:
onMessageReceived id:0/939/39106187 t:0/48 reqAck:true payload: 15300120da69092e7b8e474874ab38ef67fcd1b76950e3920d2ccc49f5fdc30953e80fc12502006f300320862d3e5d51a8f833b1bc8a6cf14f8fa5342eb8b99ef927a706a0f4cb46a91cec30044104fb761e8260e77ec9c27575f2f8a313bdb7776c59e72d052af5d35c0399a36adf2ac42ab32e5f527936c5711eee8b003309caf28d43d0c39aa5b38ca3b59a91ff35052501881325022c0118300610b75b0cc5ccd127413bf70cf92f00ec20300710111238140be4010e4edc829afd7734da18
Case server: Received pairing request from udp://192.168.1.57:58823
An error occured during the commissioning Error: Unsupported state or unable to authenticate data
at Decipheriv.final (node:internal/crypto/cipher:193:29)
at Function.decrypt (/home/DadAdmin/foo/node-matter/build/crypto/Crypto.js:37:16)
at CaseServer.<anonymous> (/home/DadAdmin/foo/node-matter/build/matter/session/secure/CaseServer.js:47:33)
at Generator.next (<anonymous>)
at fulfilled (/home/DadAdmin/foo/node-matter/build/matter/session/secure/CaseServer.js:5:58)
sending id:0/939/1954469614 t:0/64 acked:39106187 reqAck:true payload: 0100000000000200
onMessageReceived id:0/939/39106188 t:0/16 acked:1954469614 reqAck:false payload:
HA logs
2022-10-06 17:32:52 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Connected from 192.168.1.57
2022-10-06 17:32:52 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Sending {"driver_version": 0, "server_version": 0, "min_schema_version": 1, "max_schema_version": 1, "_type": "matter_server.common.model.version.VersionInfo"}
2022-10-06 17:32:52 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received: {"messageId": "server-get-info", "command": "server.GetInfo", "args": {}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-06 17:32:52 77f1785d-matter-server matter_server.server.server[121] INFO [139977026126944] Deserialized message: CommandMessage(messageId='server-get-info', command='server.GetInfo', args={})
2022-10-06 17:32:52 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received CommandMessage(messageId='server-get-info', command='server.GetInfo', args={})
2022-10-06 17:32:52 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Sending {"messageId": "server-get-info", "result": {"fabricId": 1, "compressedFabricId": 11403566809045482820, "_type": "matter_server.common.model.message.ServerInformation"}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-10-06 17:32:52 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received: {"messageId": "aaa13414c937434e9a49dfbe381d69b0", "command": "device_controller.Read", "args": {"nodeid": 4335, "attributes": [[1, {"_class": "chip.clusters.Objects.OnOff.Attributes.OnOff"}]], "dataVersionFilters": null, "events": null, "returnClusterObject": false, "reportInterval": [0, 10], "fabricFiltered": true, "keepSubscriptions": true}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-06 17:32:52 77f1785d-matter-server matter_server.server.server[121] INFO [139977026126944] Deserialized message: CommandMessage(messageId='aaa13414c937434e9a49dfbe381d69b0', command='device_controller.Read', args={'nodeid': 4335, 'attributes': [[1, <class 'chip.clusters.Objects.OnOff.Attributes.OnOff'>]], 'dataVersionFilters': None, 'events': None, 'returnClusterObject': False, 'reportInterval': [0, 10], 'fabricFiltered': True, 'keepSubscriptions': True})
2022-10-06 17:32:52 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received CommandMessage(messageId='aaa13414c937434e9a49dfbe381d69b0', command='device_controller.Read', args={'nodeid': 4335, 'attributes': [[1, <class 'chip.clusters.Objects.OnOff.Attributes.OnOff'>]], 'dataVersionFilters': None, 'events': None, 'returnClusterObject': False, 'reportInterval': [0, 10], 'fabricFiltered': True, 'keepSubscriptions': True})
2022-10-06 17:32:52 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 201 ms
2022-10-06 17:33:07 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 15008 ms
2022-10-06 17:33:07 77f1785d-matter-server chip.DIS[121] ERROR OperationalSessionSetup[1:00000000000010EF]: operational discovery failed: ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
2022-10-06 17:33:07 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Sending {"messageId": "aaa13414c937434e9a49dfbe381d69b0", "errorCode": "CHIP Error 0x00000032: Timeout", "_type": "matter_server.common.model.message.ErrorResultMessage"}
2022-10-06 17:33:23 77f1785d-matter-server chip.DIS[121] ERROR Timeout waiting for mDNS resolution.
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received: {"messageId": "f46de219581b4bd8a79f6b3fc12fd1df", "command": "device_controller.CommissionWithCode", "args": {"setupPayload": "34970112332", "nodeid": 4338}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] INFO [139977026126944] Deserialized message: CommandMessage(messageId='f46de219581b4bd8a79f6b3fc12fd1df', command='device_controller.CommissionWithCode', args={'setupPayload': '34970112332', 'nodeid': 4338})
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received CommandMessage(messageId='f46de219581b4bd8a79f6b3fc12fd1df', command='device_controller.CommissionWithCode', args={'setupPayload': '34970112332', 'nodeid': 4338})
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] WARNING [139977026126944] Received commissioning without Wi-Fi set
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Setting attestation nonce to random value
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Setting CSR nonce to random value
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Starting commissioning discovery over BLE
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Starting commissioning discovery over DNS-SD
2022-10-06 17:33:27 77f1785d-matter-server chip.DL[121] ERROR FAIL: NULL apEndpoint->mpAdapter in bluezObjectsSetup
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] ERROR Commissioning discovery over BLE failed: ../../src/platform/Linux/BLEManagerImpl.cpp:655: CHIP Error 0x00000003: Incorrect state
2022-10-06 17:33:27 77f1785d-matter-server chip.-[121] ERROR ../../src/platform/Linux/BLEManagerImpl.cpp:655: CHIP Error 0x00000003: Incorrect state at ../../src/controller/SetUpCodePairer.cpp:283
2022-10-06 17:33:27 77f1785d-matter-server chip.BLE[121] ERROR No adapter available for new connection establishment
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Discovered device to be commissioned over DNS-SD
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Attempting PASE connection to UDP:192.168.1.28:5540
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:921i M:39106174] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106174 to IP address 'UDP:192.168.1.28:5540'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commission called for node ID 0x00000000000010F2
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Discovered device to be commissioned over DNS-SD
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Discovered device to be commissioned over DNS-SD
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Discovered device to be commissioned over DNS-SD
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Discovered device to be commissioned over DNS-SD
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Discovered device to be commissioned over DNS-SD
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:921i M:1954469591 (Ack:39106174)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:921i M:39106175 (Ack:1954469591)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106175 to IP address 'UDP:192.168.1.28%enp0s18:5540'
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:921i M:1954469592 (Ack:39106175)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:921i M:39106176 (Ack:1954469592)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106176 to IP address 'UDP:192.168.1.28%enp0s18:5540'
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:921i M:1954469593 (Ack:39106176)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
2022-10-06 17:33:27 77f1785d-matter-server chip.SC[121] INFO SecureSession[0x7f4edc01e280]: Moving from state 'kEstablishing' --> 'kActive'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'ReadCommissioningInfo'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Sending request for commissioning information
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:922i M:24924086] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924086 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:921i M:39106177 (Ack:1954469593)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106177 to IP address 'UDP:192.168.1.28%enp0s18:5540'
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:922i M:1954469594 (Ack:24924086)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'ReadCommissioningInfo'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'ArmFailSafe'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Arming failsafe (60 seconds)
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:923i M:24924087] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924087 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:922i M:24924088 (Ack:1954469594)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924088 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:923i M:1954469595 (Ack:24924087)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2022-10-06 17:33:27 77f1785d-matter-server chip.DMG[121] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Received ArmFailSafe response errorCode=0
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'ArmFailSafe'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Not a BLE connection, skipping ScanNetworks
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'ConfigRegulatory'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Setting Regulatory Config
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO No regulatory config supplied by controller, leaving as device default (0)
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:924i M:24924089] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924089 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:923i M:24924090 (Ack:1954469595)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924090 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:924i M:1954469596 (Ack:24924089)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2022-10-06 17:33:27 77f1785d-matter-server chip.DMG[121] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Received SetRegulatoryConfig response errorCode=0
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'ConfigRegulatory'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'SendPAICertificateRequest'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Sending request for PAI certificate
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:925i M:24924091] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924091 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:924i M:24924092 (Ack:1954469596)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924092 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:925i M:1954469597 (Ack:24924091)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2022-10-06 17:33:27 77f1785d-matter-server chip.DMG[121] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Received certificate chain from the device
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'SendPAICertificateRequest'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'SendDACCertificateRequest'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Sending request for DAC certificate
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:926i M:24924093] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924093 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:925i M:24924094 (Ack:1954469597)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924094 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:926i M:1954469598 (Ack:24924093)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2022-10-06 17:33:27 77f1785d-matter-server chip.DMG[121] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Received certificate chain from the device
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'SendDACCertificateRequest'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'SendAttestationRequest'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Sending Attestation Request to the device.
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:927i M:24924095] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924095 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:926i M:24924096 (Ack:1954469598)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924096 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:927i M:1954469599 (Ack:24924095)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2022-10-06 17:33:27 77f1785d-matter-server chip.DMG[121] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Received Attestation Information from the device
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'SendAttestationRequest'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'AttestationVerification'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Verifying attestation
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully validated 'Attestation Information' command received from the device.
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'AttestationVerification'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'SendOpCertSigningRequest'
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:928i M:24924097] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924097 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:927i M:24924098 (Ack:1954469599)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924098 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:928i M:1954469600 (Ack:24924097)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2022-10-06 17:33:27 77f1785d-matter-server chip.DMG[121] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Received certificate signing request from the device
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'SendOpCertSigningRequest'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'ValidateCSR'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'ValidateCSR'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'GenerateNOCChain'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Getting certificate chain for the device from the issuer
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Verifying Certificate Signing Request
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Generating NOC
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Providing certificate chain to the commissioner
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Received callback from the CA for NOC Chain generation. Status ../../src/controller/ExampleOperationalCredentialsIssuer.cpp:396: Success
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'GenerateNOCChain'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'SendTrustedRootCert'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Sending root certificate to the device
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:929i M:24924099] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924099 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Sent root certificate to the device
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:928i M:24924100 (Ack:1954469600)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924100 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:929i M:1954469601 (Ack:24924099)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2022-10-06 17:33:27 77f1785d-matter-server chip.DMG[121] INFO Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Device confirmed that it has received the root certificate
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'SendTrustedRootCert'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'SendNOC'
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:930i M:24924101] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924101 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Sent operational certificate to the device
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:929i M:24924102 (Ack:1954469601)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924102 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:930i M:1954469602 (Ack:24924101)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2022-10-06 17:33:27 77f1785d-matter-server chip.DMG[121] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Device returned status 0 on receiving the NOC
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Operational credentials provisioned on device 0x7f4edc02cec0
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'SendNOC'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'SendNOC' -> 'FindOperational'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'FindOperational'
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:930i M:24924103 (Ack:1954469602)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 24924103 on secure session with LSID: 28411
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: new best score: 2
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 3 ms
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 3 ms
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 4 ms
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 4 ms
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 5 ms
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 5 ms
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 8 ms
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 9 ms
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 9 ms
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 10 ms
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 11 ms
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 12 ms
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:33:27 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 200 ms
2022-10-06 17:33:27 77f1785d-matter-server chip.SC[121] INFO Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x00000000000010F2
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:931i M:39106178] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106178 to IP address 'UDP:192.168.1.28:5540'
2022-10-06 17:33:27 77f1785d-matter-server chip.SC[121] INFO Sent Sigma1 msg
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:931i M:1954469603 (Ack:39106178)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
2022-10-06 17:33:27 77f1785d-matter-server chip.SC[121] INFO Received Sigma2 msg
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:931i M:39106179 (Ack:1954469603)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106179 to IP address 'UDP:192.168.1.28%enp0s18:5540'
2022-10-06 17:33:27 77f1785d-matter-server chip.SC[121] INFO Sent Sigma3 msg
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:931i M:1954469604 (Ack:39106179)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
2022-10-06 17:33:27 77f1785d-matter-server chip.SC[121] INFO Success status report received. Session was established
2022-10-06 17:33:27 77f1785d-matter-server PersistentStorage[121] INFO SetSdkKey: f/1/s/00000000000010F2 = b"\x150\x03\x10\xb7[\x0c\xc5\xcc\xd1'A;\xf7\x0c\xf9/\x00\xec 0\x04 \xe2\xa9\xd8\x18\xef\xc4\x94\x08\xf0\x93J\xfb\xd3\xec@+\xd2\xbb\xbd\xf0\x01\xa5\xce\xe6\x16\xad\xe2\x9f<\x0f8l0\x05\x0c\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x18"
2022-10-06 17:33:27 77f1785d-matter-server PersistentStorage[121] INFO Committing...
2022-10-06 17:33:27 77f1785d-matter-server PersistentStorage[121] INFO SetSdkKey: g/s/t1sMxczRJ0E79wz5LwDsIA== = b'\x15$\x01\x01%\x02\xf2\x10\x18'
2022-10-06 17:33:27 77f1785d-matter-server PersistentStorage[121] INFO Committing...
2022-10-06 17:33:27 77f1785d-matter-server PersistentStorage[121] INFO SetSdkKey: g/sri = b'\x16\x15$\x01\x01%\x02\xf2\x10\x18\x18'
2022-10-06 17:33:27 77f1785d-matter-server PersistentStorage[121] INFO Committing...
2022-10-06 17:33:27 77f1785d-matter-server chip.SC[121] INFO SecureSession[0x7f4edc02eda0]: Moving from state 'kEstablishing' --> 'kActive'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'FindOperational'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'FindOperational' -> 'SendComplete'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'SendComplete'
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:932i M:65784833] (S) Msg TX to 1:00000000000010F2 [3D44] --- Type 0001:08 (IM:InvokeCommandRequest)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 65784833 on secure session with LSID: 28412
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:931i M:39106180 (Ack:1954469604)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106180 to IP address 'UDP:192.168.1.28%enp0s18:5540'
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:932i M:1954469605 (Ack:65784833)] (S) Msg RX from 1:00000000000010F2 [3D44] --- Type 0001:09 (IM:InvokeCommandResponse)
2022-10-06 17:33:27 77f1785d-matter-server chip.DMG[121] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Received CommissioningComplete response, errorCode=0
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'SendComplete'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Commissioning stage next step: 'SendComplete' -> 'Cleanup'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Performing next commissioning step 'Cleanup'
2022-10-06 17:33:27 77f1785d-matter-server chip.SC[121] INFO SecureSession[0x7f4edc01e280]: Moving from state 'kActive' --> 'kPendingEviction'
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Successfully finished commissioning step 'Cleanup'
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:932i M:65784834 (Ack:1954469605)] (S) Msg TX to 1:00000000000010F2 [3D44] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 65784834 on secure session with LSID: 28412
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Sending {"messageId": "f46de219581b4bd8a79f6b3fc12fd1df", "result": {"raw": true}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received: {"messageId": "fea0d9ef1f0c4568b91642e2892eaaf5", "command": "device_controller.ResolveNode", "args": {"nodeid": 4338}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] INFO [139977026126944] Deserialized message: CommandMessage(messageId='fea0d9ef1f0c4568b91642e2892eaaf5', command='device_controller.ResolveNode', args={'nodeid': 4338})
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received CommandMessage(messageId='fea0d9ef1f0c4568b91642e2892eaaf5', command='device_controller.ResolveNode', args={'nodeid': 4338})
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Found an existing secure session to [1:00000000000010F2]!
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Sending {"messageId": "fea0d9ef1f0c4568b91642e2892eaaf5", "result": {"raw": null}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received: {"messageId": "0418efd1c45f40a6ae841159381c3094", "command": "device_controller.Read", "args": {"nodeid": 4338, "attributes": "*", "dataVersionFilters": null, "events": "*", "returnClusterObject": true, "reportInterval": null, "fabricFiltered": true, "keepSubscriptions": false}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] INFO [139977026126944] Deserialized message: CommandMessage(messageId='0418efd1c45f40a6ae841159381c3094', command='device_controller.Read', args={'nodeid': 4338, 'attributes': '*', 'dataVersionFilters': None, 'events': '*', 'returnClusterObject': True, 'reportInterval': None, 'fabricFiltered': True, 'keepSubscriptions': False})
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received CommandMessage(messageId='0418efd1c45f40a6ae841159381c3094', command='device_controller.Read', args={'nodeid': 4338, 'attributes': '*', 'dataVersionFilters': None, 'events': '*', 'returnClusterObject': True, 'reportInterval': None, 'fabricFiltered': True, 'keepSubscriptions': False})
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Found an existing secure session to [1:00000000000010F2]!
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:933i M:65784835] (S) Msg TX to 1:00000000000010F2 [3D44] --- Type 0001:02 (IM:ReadRequest)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 65784835 on secure session with LSID: 28412
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:933i M:1954469606 (Ack:65784835)] (S) Msg RX from 1:00000000000010F2 [3D44] --- Type 0001:05 (IM:ReportData)
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Sending {"messageId": "0418efd1c45f40a6ae841159381c3094", "result": {"attributes": {"0": {"Basic": {"dataModelRevision": null, "vendorName": "node-matter", "vendorID": 65521, "productName": "Matter test device", "productID": 32769, "nodeLabel": null, "location": null, "hardwareVersion": null, "hardwareVersionString": null, "softwareVersion": null, "softwareVersionString": null, "manufacturingDate": null, "partNumber": null, "productURL": null, "productLabel": null, "serialNumber": null, "localConfigDisabled": null, "reachable": null, "uniqueID": null, "capabilityMinima": null, "generatedCommandList": null, "acceptedCommandList": null, "attributeList": null, "featureMap": null, "clusterRevision": null, "_type": "chip.clusters.Objects.Basic"}, "GeneralCommissioning": {"breadcrumb": 4, "basicCommissioningInfo": {"failSafeExpiryLengthSeconds": 60, "maxCumulativeFailsafeSeconds": 0, "_type": "chip.clusters.Objects.GeneralCommissioning.Structs.BasicCommissioningInfo"}, "regulatoryConfig": 0, "locationCapability": 2, "supportsConcurrentConnection": null, "generatedCommandList": null, "acceptedCommandList": null, "attributeList": null, "featureMap": null, "clusterRevision": null, "_type": "chip.clusters.Objects.GeneralCommissioning"}, "Descriptor": {"deviceTypeList": [{"type": 22, "revision": 1, "_type": "chip.clusters.Objects.Descriptor.Structs.DeviceTypeStruct"}], "serverList": [40, 48, 62, 29], "clientList": null, "partsList": [], "generatedCommandList": null, "acceptedCommandList": null, "attributeList": null, "featureMap": null, "clusterRevision": null, "_type": "chip.clusters.Objects.Descriptor"}}, "1": {"OnOff": {"onOff": false, "globalSceneControl": null, "onTime": null, "offWaitTime": null, "startUpOnOff": null, "generatedCommandList": null, "acceptedCommandList": null, "attributeList": null, "featureMap": null, "clusterRevision": null, "_type": "chip.clusters.Objects.OnOff"}, "Descriptor": {"deviceTypeList": [{"type": 256, "revision": 1, "_type": "chip.clusters.Objects.Descriptor.Structs.DeviceTypeStruct"}], "serverList": [6, 29], "clientList": null, "partsList": [], "generatedCommandList": null, "acceptedCommandList": null, "attributeList": null, "featureMap": null, "clusterRevision": null, "_type": "chip.clusters.Objects.Descriptor"}}}, "events": [], "_type": "chip.clusters.Attribute.AsyncReadTransaction.ReadResponse"}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:933i M:65784836 (Ack:1954469606)] (S) Msg TX to 1:00000000000010F2 [3D44] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 65784836 on secure session with LSID: 28412
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received: {"messageId": "8f665957522f4b978f0586b4e8bea352", "command": "device_controller.Read", "args": {"nodeid": 4338, "attributes": [[1, {"_class": "chip.clusters.Objects.OnOff.Attributes.OnOff"}]], "dataVersionFilters": null, "events": null, "returnClusterObject": false, "reportInterval": [0, 10], "fabricFiltered": true, "keepSubscriptions": true}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] INFO [139977026126944] Deserialized message: CommandMessage(messageId='8f665957522f4b978f0586b4e8bea352', command='device_controller.Read', args={'nodeid': 4338, 'attributes': [[1, <class 'chip.clusters.Objects.OnOff.Attributes.OnOff'>]], 'dataVersionFilters': None, 'events': None, 'returnClusterObject': False, 'reportInterval': [0, 10], 'fabricFiltered': True, 'keepSubscriptions': True})
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received CommandMessage(messageId='8f665957522f4b978f0586b4e8bea352', command='device_controller.Read', args={'nodeid': 4338, 'attributes': [[1, <class 'chip.clusters.Objects.OnOff.Attributes.OnOff'>]], 'dataVersionFilters': None, 'events': None, 'returnClusterObject': False, 'reportInterval': [0, 10], 'fabricFiltered': True, 'keepSubscriptions': True})
2022-10-06 17:33:27 77f1785d-matter-server chip.CTL[121] INFO Found an existing secure session to [1:00000000000010F2]!
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:934i M:65784837] (S) Msg TX to 1:00000000000010F2 [3D44] --- Type 0001:03 (IM:SubscribeRequest)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 65784837 on secure session with LSID: 28412
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:40283r M:1954469607] (S) Msg RX from 1:00000000000010F2 [3D44] --- Type 0001:05 (IM:ReportData)
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:40283r M:65784838 (Ack:1954469607)] (S) Msg TX to 1:00000000000010F2 [3D44] --- Type 0001:01 (IM:StatusResponse)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 65784838 on secure session with LSID: 28412
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:934i M:1954469608 (Ack:65784837)] (S) Msg RX from 1:00000000000010F2 [3D44] --- Type 0001:04 (IM:SubscribeResponse)
2022-10-06 17:33:27 77f1785d-matter-server chip.DMG[121] INFO SubscribeResponse is received
2022-10-06 17:33:27 77f1785d-matter-server chip.DMG[121] INFO Subscription established with SubscriptionID = 0x00000000 MinInterval = 0s MaxInterval = 10s Peer = 01:00000000000010F2
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] INFO [139977026126944] Setting up Subscription for [(1, <class 'chip.clusters.Objects.OnOff.Attributes.OnOff'>)]
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] INFO [139977026126944] SubscriptionId 0
2022-10-06 17:33:27 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Sending {"messageId": "8f665957522f4b978f0586b4e8bea352", "result": {"subscription_id": 0}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-10-06 17:33:27 77f1785d-matter-server chip.DMG[121] INFO Refresh LivenessCheckTime for 35000 milliseconds with SubscriptionId = 0x00000000 Peer = 01:00000000000010F2
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO <<< [E:934i M:65784839 (Ack:1954469608)] (S) Msg TX to 1:00000000000010F2 [3D44] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:27 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 65784839 on secure session with LSID: 28412
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] INFO >>> [E:40283r M:1954469609 (Ack:65784838)] (S) Msg RX from 1:00000000000010F2 [3D44] --- Type 0001:10 (IM:----)
2022-10-06 17:33:27 77f1785d-matter-server chip.EM[121] ERROR Dropping unexpected message of type 0x10 with protocolId (0, 1) and MessageCounter:1954469609 on exchange 40283r
2022-10-06 17:33:28 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received: {"messageId": "64630cbf5b1f4174a1f829ab344079e9", "command": "device_controller.Read", "args": {"nodeid": 4338, "attributes": [[1, {"_class": "chip.clusters.Objects.OnOff.Attributes.OnOff"}]], "dataVersionFilters": null, "events": null, "returnClusterObject": false, "reportInterval": null, "fabricFiltered": true, "keepSubscriptions": false}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-06 17:33:28 77f1785d-matter-server matter_server.server.server[121] INFO [139977026126944] Deserialized message: CommandMessage(messageId='64630cbf5b1f4174a1f829ab344079e9', command='device_controller.Read', args={'nodeid': 4338, 'attributes': [[1, <class 'chip.clusters.Objects.OnOff.Attributes.OnOff'>]], 'dataVersionFilters': None, 'events': None, 'returnClusterObject': False, 'reportInterval': None, 'fabricFiltered': True, 'keepSubscriptions': False})
2022-10-06 17:33:28 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received CommandMessage(messageId='64630cbf5b1f4174a1f829ab344079e9', command='device_controller.Read', args={'nodeid': 4338, 'attributes': [[1, <class 'chip.clusters.Objects.OnOff.Attributes.OnOff'>]], 'dataVersionFilters': None, 'events': None, 'returnClusterObject': False, 'reportInterval': None, 'fabricFiltered': True, 'keepSubscriptions': False})
2022-10-06 17:33:28 77f1785d-matter-server chip.CTL[121] INFO Found an existing secure session to [1:00000000000010F2]!
2022-10-06 17:33:28 77f1785d-matter-server chip.EM[121] INFO <<< [E:935i M:65784840] (S) Msg TX to 1:00000000000010F2 [3D44] --- Type 0001:02 (IM:ReadRequest)
2022-10-06 17:33:28 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 65784840 on secure session with LSID: 28412
2022-10-06 17:33:28 77f1785d-matter-server chip.EM[121] INFO >>> [E:935i M:1954469610 (Ack:65784840)] (S) Msg RX from 1:00000000000010F2 [3D44] --- Type 0001:05 (IM:ReportData)
2022-10-06 17:33:28 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Sending {"messageId": "64630cbf5b1f4174a1f829ab344079e9", "result": {"attributes": {"1": {"OnOff": {"DataVersion": 0, "OnOff": false}}}, "events": [], "_type": "chip.clusters.Attribute.AsyncReadTransaction.ReadResponse"}, "_type": "matter_server.common.model.message.SuccessResultMessage"}
2022-10-06 17:33:28 77f1785d-matter-server chip.EM[121] INFO <<< [E:935i M:65784841 (Ack:1954469610)] (S) Msg TX to 1:00000000000010F2 [3D44] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:33:28 77f1785d-matter-server chip.IN[121] INFO (S) Sending msg 65784841 on secure session with LSID: 28412
2022-10-06 17:34:02 77f1785d-matter-server chip.DMG[121] ERROR Subscription Liveness timeout with SubscriptionID = 0x00000000, Peer = 01:00000000000010F2
2022-10-06 17:34:02 77f1785d-matter-server chip.SC[121] INFO SecureSession[0x7f4edc02eda0]: Moving from state 'kActive' --> 'kDefunct'
2022-10-06 17:34:02 77f1785d-matter-server chip.DMG[121] INFO Will try to resubscribe to 01:00000000000010F2 at retry index 0 after 0ms due to error ../../src/app/ReadClient.cpp:867: CHIP Error 0x00000032: Timeout
2022-10-06 17:34:02 77f1785d-matter-server chip.DMG[121] INFO OnResubscribeTimerCallback: DoCASE = 1
2022-10-06 17:34:02 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: new best score: 2
2022-10-06 17:34:02 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 5 ms
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 6 ms
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
/usr/lib/python3.9/asyncio/events.py:80: RuntimeWarning: coroutine 'DefaultResubscriptionAttemptedCallback' was never awaited
self._context.run(self._callback, *self._args)
RuntimeWarning: Enable tracemalloc to get the object allocation traceback
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 8 ms
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 9 ms
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 10 ms
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 11 ms
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:03 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 200 ms
2022-10-06 17:34:03 77f1785d-matter-server chip.SC[121] INFO Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x00000000000010F2
2022-10-06 17:34:03 77f1785d-matter-server chip.EM[121] INFO <<< [E:936i M:39106181] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
2022-10-06 17:34:03 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106181 to IP address 'UDP:192.168.1.28:5540'
2022-10-06 17:34:03 77f1785d-matter-server chip.SC[121] INFO Sent Sigma1 msg
2022-10-06 17:34:03 77f1785d-matter-server chip.EM[121] INFO >>> [E:936i M:1954469611 (Ack:39106181)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
2022-10-06 17:34:03 77f1785d-matter-server chip.SC[121] ERROR Received error (protocol code 2) during pairing process: ../../src/protocols/secure_channel/CASESession.cpp:1605: CHIP Error 0x00000054: Invalid CASE parameter
2022-10-06 17:34:03 77f1785d-matter-server chip.DMG[121] ERROR Failed to establish CASE for re-subscription with error '../../src/protocols/secure_channel/CASESession.cpp:1605: CHIP Error 0x00000054: Invalid CASE parameter'
2022-10-06 17:34:03 77f1785d-matter-server chip.DMG[121] INFO Will try to resubscribe to 01:00000000000010F2 at retry index 1 after 9272ms due to error ../../src/protocols/secure_channel/CASESession.cpp:1605: CHIP Error 0x00000054: Invalid CASE parameter
2022-10-06 17:34:03 77f1785d-matter-server chip.EM[121] INFO <<< [E:936i M:39106182 (Ack:1954469611)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:34:03 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106182 to IP address 'UDP:192.168.1.28%enp0s18:5540'
2022-10-06 17:34:12 77f1785d-matter-server chip.DMG[121] INFO OnResubscribeTimerCallback: DoCASE = 0
2022-10-06 17:34:12 77f1785d-matter-server chip.EM[121] ERROR NewContext failed: session inactive
2022-10-06 17:34:12 77f1785d-matter-server chip.DMG[121] INFO Will try to resubscribe to 01:00000000000010F2 at retry index 2 after 5369ms due to error ../../src/app/ReadClient.cpp:1007: CHIP Error 0x0000000B: No memory
2022-10-06 17:34:17 77f1785d-matter-server chip.DMG[121] INFO OnResubscribeTimerCallback: DoCASE = 0
2022-10-06 17:34:17 77f1785d-matter-server chip.EM[121] ERROR NewContext failed: session inactive
2022-10-06 17:34:17 77f1785d-matter-server chip.DMG[121] INFO Will try to resubscribe to 01:00000000000010F2 at retry index 3 after 19231ms due to error ../../src/app/ReadClient.cpp:1007: CHIP Error 0x0000000B: No memory
2022-10-06 17:34:31 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received: {"messageId": "7717b9a56e5042eaaf2de1a11f17140b", "command": "device_controller.SendCommand", "args": {"nodeid": 4338, "endpoint": 1, "payload": {"_type": "chip.clusters.Objects.OnOff.Commands.On"}}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-06 17:34:31 77f1785d-matter-server matter_server.server.server[121] INFO [139977026126944] Deserialized message: CommandMessage(messageId='7717b9a56e5042eaaf2de1a11f17140b', command='device_controller.SendCommand', args={'nodeid': 4338, 'endpoint': 1, 'payload': OnOff.Commands.On()})
2022-10-06 17:34:31 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received CommandMessage(messageId='7717b9a56e5042eaaf2de1a11f17140b', command='device_controller.SendCommand', args={'nodeid': 4338, 'endpoint': 1, 'payload': OnOff.Commands.On()})
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: new best score: 2
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 4 ms
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 5 ms
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 7 ms
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 8 ms
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 9 ms
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 9 ms
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:31 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 201 ms
2022-10-06 17:34:31 77f1785d-matter-server chip.SC[121] INFO Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x00000000000010F2
2022-10-06 17:34:31 77f1785d-matter-server chip.EM[121] INFO <<< [E:937i M:39106183] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
2022-10-06 17:34:31 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106183 to IP address 'UDP:192.168.1.28:5540'
2022-10-06 17:34:31 77f1785d-matter-server chip.SC[121] INFO Sent Sigma1 msg
2022-10-06 17:34:31 77f1785d-matter-server chip.EM[121] INFO >>> [E:937i M:1954469612 (Ack:39106183)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
2022-10-06 17:34:31 77f1785d-matter-server chip.SC[121] ERROR Received error (protocol code 2) during pairing process: ../../src/protocols/secure_channel/CASESession.cpp:1605: CHIP Error 0x00000054: Invalid CASE parameter
2022-10-06 17:34:31 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Sending {"messageId": "7717b9a56e5042eaaf2de1a11f17140b", "errorCode": "CHIP Error 0x00000054: Invalid CASE parameter", "_type": "matter_server.common.model.message.ErrorResultMessage"}
2022-10-06 17:34:31 77f1785d-matter-server chip.EM[121] INFO <<< [E:937i M:39106184 (Ack:1954469612)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:34:31 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106184 to IP address 'UDP:192.168.1.28%enp0s18:5540'
2022-10-06 17:34:37 77f1785d-matter-server chip.DMG[121] INFO OnResubscribeTimerCallback: DoCASE = 0
2022-10-06 17:34:37 77f1785d-matter-server chip.EM[121] ERROR NewContext failed: session inactive
2022-10-06 17:34:37 77f1785d-matter-server chip.DMG[121] INFO Will try to resubscribe to 01:00000000000010F2 at retry index 4 after 16690ms due to error ../../src/app/ReadClient.cpp:1007: CHIP Error 0x0000000B: No memory
2022-10-06 17:34:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received: {"messageId": "7f41c39e086e479ab0184c6f84d9c750", "command": "device_controller.SendCommand", "args": {"nodeid": 4338, "endpoint": 1, "payload": {"_type": "chip.clusters.Objects.OnOff.Commands.Off"}}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-06 17:34:44 77f1785d-matter-server matter_server.server.server[121] INFO [139977026126944] Deserialized message: CommandMessage(messageId='7f41c39e086e479ab0184c6f84d9c750', command='device_controller.SendCommand', args={'nodeid': 4338, 'endpoint': 1, 'payload': OnOff.Commands.Off()})
2022-10-06 17:34:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received CommandMessage(messageId='7f41c39e086e479ab0184c6f84d9c750', command='device_controller.SendCommand', args={'nodeid': 4338, 'endpoint': 1, 'payload': OnOff.Commands.Off()})
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: new best score: 2
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 5 ms
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 6 ms
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 7 ms
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 8 ms
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 9 ms
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 11 ms
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:34:44 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 200 ms
2022-10-06 17:34:44 77f1785d-matter-server chip.SC[121] INFO Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x00000000000010F2
2022-10-06 17:34:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:938i M:39106185] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
2022-10-06 17:34:44 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106185 to IP address 'UDP:192.168.1.28:5540'
2022-10-06 17:34:44 77f1785d-matter-server chip.SC[121] INFO Sent Sigma1 msg
2022-10-06 17:34:44 77f1785d-matter-server chip.EM[121] INFO >>> [E:938i M:1954469613 (Ack:39106185)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
2022-10-06 17:34:44 77f1785d-matter-server chip.SC[121] ERROR Received error (protocol code 2) during pairing process: ../../src/protocols/secure_channel/CASESession.cpp:1605: CHIP Error 0x00000054: Invalid CASE parameter
2022-10-06 17:34:44 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Sending {"messageId": "7f41c39e086e479ab0184c6f84d9c750", "errorCode": "CHIP Error 0x00000054: Invalid CASE parameter", "_type": "matter_server.common.model.message.ErrorResultMessage"}
2022-10-06 17:34:44 77f1785d-matter-server chip.EM[121] INFO <<< [E:938i M:39106186 (Ack:1954469613)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:34:44 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106186 to IP address 'UDP:192.168.1.28%enp0s18:5540'
2022-10-06 17:34:53 77f1785d-matter-server chip.DMG[121] INFO OnResubscribeTimerCallback: DoCASE = 0
2022-10-06 17:34:53 77f1785d-matter-server chip.EM[121] ERROR NewContext failed: session inactive
2022-10-06 17:34:53 77f1785d-matter-server chip.DMG[121] INFO Will try to resubscribe to 01:00000000000010F2 at retry index 5 after 28809ms due to error ../../src/app/ReadClient.cpp:1007: CHIP Error 0x0000000B: No memory
2022-10-06 17:35:04 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received: {"messageId": "b5765d82e2a74e6eb67576f0aceeed0b", "command": "device_controller.SendCommand", "args": {"nodeid": 4338, "endpoint": 1, "payload": {"_type": "chip.clusters.Objects.OnOff.Commands.On"}}, "_type": "matter_server.common.model.message.CommandMessage"}
2022-10-06 17:35:04 77f1785d-matter-server matter_server.server.server[121] INFO [139977026126944] Deserialized message: CommandMessage(messageId='b5765d82e2a74e6eb67576f0aceeed0b', command='device_controller.SendCommand', args={'nodeid': 4338, 'endpoint': 1, 'payload': OnOff.Commands.On()})
2022-10-06 17:35:04 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Received CommandMessage(messageId='b5765d82e2a74e6eb67576f0aceeed0b', command='device_controller.SendCommand', args={'nodeid': 4338, 'endpoint': 1, 'payload': OnOff.Commands.On()})
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: new best score: 2
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 5 ms
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 7 ms
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 9 ms
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 11 ms
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 12 ms
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 13 ms
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO Keeping DNSSD lookup active
2022-10-06 17:35:05 77f1785d-matter-server chip.DIS[121] INFO Checking node lookup status after 201 ms
2022-10-06 17:35:05 77f1785d-matter-server chip.SC[121] INFO Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x00000000000010F2
2022-10-06 17:35:05 77f1785d-matter-server chip.EM[121] INFO <<< [E:939i M:39106187] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
2022-10-06 17:35:05 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106187 to IP address 'UDP:192.168.1.28:5540'
2022-10-06 17:35:05 77f1785d-matter-server chip.SC[121] INFO Sent Sigma1 msg
2022-10-06 17:35:05 77f1785d-matter-server chip.EM[121] INFO >>> [E:939i M:1954469614 (Ack:39106187)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
2022-10-06 17:35:05 77f1785d-matter-server chip.SC[121] ERROR Received error (protocol code 2) during pairing process: ../../src/protocols/secure_channel/CASESession.cpp:1605: CHIP Error 0x00000054: Invalid CASE parameter
2022-10-06 17:35:05 77f1785d-matter-server chip.EM[121] INFO <<< [E:939i M:39106188 (Ack:1954469614)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2022-10-06 17:35:05 77f1785d-matter-server matter_server.server.server[121] DEBUG [139977026126944] Sending {"messageId": "b5765d82e2a74e6eb67576f0aceeed0b", "errorCode": "CHIP Error 0x00000054: Invalid CASE parameter", "_type": "matter_server.common.model.message.ErrorResultMessage"}
2022-10-06 17:35:05 77f1785d-matter-server chip.IN[121] INFO (U) Sending msg 39106188 to IP address 'UDP:192.168.1.28%enp0s18:5540'
2022-10-06 17:35:22 77f1785d-matter-server chip.DMG[121] INFO OnResubscribeTimerCallback: DoCASE = 0
2022-10-06 17:35:22 77f1785d-matter-server chip.EM[121] ERROR NewContext failed: session inactive
2022-10-06 17:35:22 77f1785d-matter-server chip.DMG[121] INFO Will try to resubscribe to 01:00000000000010F2 at retry index 6 after 75144ms due to error ../../src/app/ReadClient.cpp:1007: CHIP Error 0x0000000B: No memory
2022-10-06 17:36:37 77f1785d-matter-server chip.DMG[121] INFO OnResubscribeTimerCallback: DoCASE = 0
2022-10-06 17:36:37 77f1785d-matter-server chip.EM[121] ERROR NewContext failed: session inactive
2022-10-06 17:36:37 77f1785d-matter-server chip.DMG[121] INFO Will try to resubscribe to 01:00000000000010F2 at retry index 7 after 83488ms due to error ../../src/app/ReadClient.cpp:1007: CHIP Error 0x0000000B: No memory
2022-10-06 17:38:01 77f1785d-matter-server chip.DMG[121] INFO OnResubscribeTimerCallback: DoCASE = 0
2022-10-06 17:38:01 77f1785d-matter-server chip.EM[121] ERROR NewContext failed: session inactive
2022-10-06 17:38:01 77f1785d-matter-server chip.DMG[121] INFO Will try to resubscribe to 01:00000000000010F2 at retry index 8 after 166458ms due to error ../../src/app/ReadClient.cpp:1007: CHIP Error 0x0000000B: No memoryGreat, so there is some progress!
I see 3 issues remaining from the logs:
As next steps, I will:
mfucci
commented
1 year ago Update:
mfucci
commented
1 year ago Update:
The subscription should now work in degraded mode: the session keep being reconnected every 30s
Next step: finish implementing the subscription logic
After modifying the code to make clusterId and attribute Id optional by returning zero when either of the fields are not present), commissioning with Home Assistant progresses further and from node-matter it seems like the device paired - but somehow HA add-on gives up after receiving response from last read... Here is how it looks from the node-matter side:
No further communication from HA to node-matter after this read request. However, HA doesn't complete the full commissioning process. Not sure what is going on, but here are some HA logs...
Without specs, it is hard for me to tell what is going on. But HA add-on is also WIP, so will wait till it stabilizes
Originally posted by @jdesai61 in https://github.com/mfucci/node-matter/issues/8#issuecomment-1183735907