Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unable to complete commission process with Home Assistant #11

Closed
jdesai61 opened this issue Jul 14, 2022 · 165 comments
Closed

Unable to complete commission process with Home Assistant #11

jdesai61 opened this issue Jul 14, 2022 · 165 comments

Comments

@jdesai61
Copy link
Collaborator

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:

node build/Main.js
Matter server listening
Pase: Received pairing request from udp://192.168.1.57:60161
Pase: Paired succesfully with udp://192.168.1.57:60161
Received read request from udp://192.168.1.57:60161 on session secure/20610: */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:60161 on session secure/20610: 0/48/0
Received invoke request from udp://192.168.1.57:60161 on session secure/20610: 0/48/2
Received invoke request from udp://192.168.1.57:60161 on session secure/20610: 0/62/2
Received invoke request from udp://192.168.1.57:60161 on session secure/20610: 0/62/2
Received invoke request from udp://192.168.1.57:60161 on session secure/20610: 0/62/0
Received invoke request from udp://192.168.1.57:60161 on session secure/20610: 0/62/4
Received invoke request from udp://192.168.1.57:60161 on session secure/20610: 0/62/11
Received invoke request from udp://192.168.1.57:60161 on session secure/20610: 0/62/6
Case: Received pairing request from udp://192.168.1.57:60161
Case: Paired succesfully with udp://192.168.1.57:60161
Received invoke request from udp://192.168.1.57:60161 on session secure/20611: 0/48/4
Received read request from udp://192.168.1.57:60161 on session secure/20611: */undefined/undefined

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...

2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Sending encrypted msg 0x7fc7dc0197a8 with MessageCounter:167328143 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000209E1A50 msec
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Sent operational certificate to the device
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Prepared secure message 0x7fc7f0c23da8 to 0xFFFFFFFB00000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 15703i with MessageCounter:167328144.
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Sending encrypted msg 0x7fc7f0c23da8 with MessageCounter:167328144 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000209E1A51 msec
2022-07-13 17:44:01 77f1785d-matter-server chip.EM[122] INFO Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4064267261 on exchange 15704i
2022-07-13 17:44:01 77f1785d-matter-server chip.DMG[122] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Device returned status 0 on receiving the NOC
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Operational credentials provisioned on device 0x7fc7dc02c520
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Successfully finished commissioning step 'SendNOC'
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Commissioning stage next step: 'SendNOC' -> 'FindOperational'
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Performing next commissioning step 'FindOperational'
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Operational node lookup already in progress. Will NOT start a new one.
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Prepared secure message 0x7fc7f0c23da8 to 0xFFFFFFFB00000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 15704i with MessageCounter:167328145.
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Sending encrypted msg 0x7fc7f0c23da8 with MessageCounter:167328145 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000209E1A6B msec
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%enp0s18:5540: new best score: 2
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 8 ms
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 9 ms
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 10 ms
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 11 ms
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 11 ms
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 12 ms
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 18 ms
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 19 ms
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%enp0s18:5540: score has not improved: 2
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 21 ms
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 22 ms
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 23 ms
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO UDP:192.168.1.28%hassio:5540: score has not improved: 2
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 24 ms
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Keeping DNSSD lookup active
2022-07-13 17:44:01 77f1785d-matter-server chip.DIS[122] INFO Checking node lookup status after 200 ms
2022-07-13 17:44:01 77f1785d-matter-server chip.SC[122] INFO Initiating session on local FabricIndex 1 from 0x0000000000000001 -> 0x00000000000010EF
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Prepared unauthenticated message 0x7fc7dc027818 to 0x0000000000000000 (0)  of type 0x30 and protocolId (0, 0) on exchange 15705i with MessageCounter:12213759.
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Sending unauthenticated msg 0x7fc7dc027818 with MessageCounter:12213759 to 0x0000000000000000 at monotonic time: 00000000209E1B2E msec
2022-07-13 17:44:01 77f1785d-matter-server chip.SC[122] INFO Sent Sigma1 msg
2022-07-13 17:44:01 77f1785d-matter-server chip.EM[122] INFO Received message of type 0x31 with protocolId (0, 0) and MessageCounter:4064267262 on exchange 15705i
2022-07-13 17:44:01 77f1785d-matter-server chip.SC[122] INFO Received Sigma2 msg
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Prepared unauthenticated message 0x7fc7dc02f6b8 to 0x0000000000000000 (0)  of type 0x32 and protocolId (0, 0) on exchange 15705i with MessageCounter:12213760.
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Sending unauthenticated msg 0x7fc7dc02f6b8 with MessageCounter:12213760 to 0x0000000000000000 at monotonic time: 00000000209E1B3F msec
2022-07-13 17:44:01 77f1785d-matter-server chip.SC[122] INFO Sent Sigma3 msg
2022-07-13 17:44:01 77f1785d-matter-server chip.EM[122] INFO Received message of type 0x40 with protocolId (0, 0) and MessageCounter:4064267263 on exchange 15705i
2022-07-13 17:44:01 77f1785d-matter-server chip.SC[122] INFO Success status report received. Session was established
2022-07-13 17:44:01 77f1785d-matter-server root[122] INFO SetSdkKey: f/1/s/00000000000010EF = b'\x150\x03\x10\xbf\x05\x9d\x12W\x97N\xd1}m\xfd\x97\x08\x9c\x87/0\x04 "/\xe0F\xfc\xf8\x9b\xfbEW\xe4\x87\xad)X\xce\x91\xda\x81\x8b\x81<}\xc3\xe2\x13\xe5\xa3\xc7DX\xb90\x05\x0c\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x18'
2022-07-13 17:44:01 77f1785d-matter-server root[122] INFO SetSdkKey: g/s/vwWdEleXTtF9bf2XCJyHLw== = b'\x15$\x01\x01%\x02\xef\x10\x18'
2022-07-13 17:44:01 77f1785d-matter-server root[122] INFO SetSdkKey: g/sri = b'\x16\x15$\x01\x01%\x02\xef\x10\x18\x18'
2022-07-13 17:44:01 77f1785d-matter-server chip.SC[122] INFO SecureSession[0x7fc7dc0279a0]: Moving from state 'kEstablishing' --> 'kActive'
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Successfully finished commissioning step 'FindOperational'
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Commissioning stage next step: 'FindOperational' -> 'SendComplete'
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Performing next commissioning step 'SendComplete'
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Prepared secure message 0x7fc7dc02f6b8 to 0x00000000000010EF (1)  of type 0x8 and protocolId (0, 1) on exchange 15706i with MessageCounter:157404875.
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Sending encrypted msg 0x7fc7dc02f6b8 with MessageCounter:157404875 to 0x00000000000010EF (1) at monotonic time: 00000000209E1B4B msec
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Prepared unauthenticated message 0x7fc7f0c23de8 to 0x0000000000000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 15705i with MessageCounter:12213761.
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Sending unauthenticated msg 0x7fc7f0c23de8 with MessageCounter:12213761 to 0x0000000000000000 at monotonic time: 00000000209E1B4C msec
2022-07-13 17:44:01 77f1785d-matter-server chip.EM[122] INFO Received message of type 0x9 with protocolId (0, 1) and MessageCounter:4064267264 on exchange 15706i
2022-07-13 17:44:01 77f1785d-matter-server chip.DMG[122] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Received CommissioningComplete response, errorCode=0
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Successfully finished commissioning step 'SendComplete'
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Commissioning stage next step: 'SendComplete' -> 'Cleanup'
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Performing next commissioning step 'Cleanup'
2022-07-13 17:44:01 77f1785d-matter-server chip.CTL[122] INFO Successfully finished commissioning step 'Cleanup'
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Prepared secure message 0x7fc7f0c23da8 to 0x00000000000010EF (1)  of type 0x10 and protocolId (0, 0) on exchange 15706i with MessageCounter:157404876.
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Sending encrypted msg 0x7fc7f0c23da8 with MessageCounter:157404876 to 0x00000000000010EF (1) at monotonic time: 00000000209E1B52 msec
2022-07-13 17:44:01 77f1785d-matter-server matter_server.server.server[122] INFO [140496488854960] Deserialized message: CommandMessage(messageId='355dd24ba3044913b6318af120e34980', command='device_controller.ResolveNode', args={'nodeid': 4335})
2022-07-13 17:44:01 77f1785d-matter-server matter_server.server.server[122] INFO [140496488854960] Deserialized message: CommandMessage(messageId='8296edfecec6419499c9ae4db7ced4c7', command='device_controller.Read', args={'nodeid': 4335, 'attributes': '*', 'dataVersionFilters': None, 'events': '*', 'returnClusterObject': True, 'reportInterval': None, 'fabricFiltered': True, 'keepSubscriptions': False})
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Prepared secure message 0x7fc7dc02f6b8 to 0x00000000000010EF (1)  of type 0x2 and protocolId (0, 1) on exchange 15707i with MessageCounter:157404877.
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Sending encrypted msg 0x7fc7dc02f6b8 with MessageCounter:157404877 to 0x00000000000010EF (1) at monotonic time: 00000000209E1B63 msec
2022-07-13 17:44:01 77f1785d-matter-server chip.EM[122] INFO Received message of type 0x5 with protocolId (0, 1) and MessageCounter:4064267265 on exchange 15707i
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Prepared secure message 0x7fc7f0c23da8 to 0x00000000000010EF (1)  of type 0x10 and protocolId (0, 0) on exchange 15707i with MessageCounter:157404878.
2022-07-13 17:44:01 77f1785d-matter-server chip.IN[122] INFO Sending encrypted msg 0x7fc7f0c23da8 with MessageCounter:157404878 to 0x00000000000010EF (1) at monotonic time: 00000000209E1B67 msec

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 #8 (comment)

@mfucci
Copy link
Owner

mfucci commented Aug 4, 2022

Pull request #13 should fix this issue since this is related to read attribute wildcards not handled.

@jdesai61
Copy link
Collaborator Author

jdesai61 commented Aug 4, 2022

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 msec

But 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: */*/*

@jdesai61
Copy link
Collaborator Author

jdesai61 commented Aug 4, 2022

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 ms

@mfucci
Copy link
Owner

mfucci commented Aug 4, 2022

0/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
Copy link
Owner

mfucci commented Aug 9, 2022

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
Copy link
Collaborator Author

jdesai61 commented Aug 9, 2022 via email

@jdesai61
Copy link
Collaborator Author

jdesai61 commented Aug 9, 2022

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 5353

Hope this helps.

@mfucci
Copy link
Owner

mfucci commented Aug 10, 2022

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
Copy link
Collaborator Author

jdesai61 commented Aug 11, 2022

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
Copy link
Collaborator

Does the zipped version of node-matter includes all fixes up until to this point?

Thanks.

@mfucci
Copy link
Owner

mfucci commented Aug 17, 2022

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,

  • Marco

@javierbarellano4v
Copy link
Collaborator

Hey Marco,

It worked (via npm)

8d2bca48-4f94-42f2-b995-2cf49cdabe4a

Is there another Cluster (command) I can try to hit the Matter Server so to speak?

Thanks so much! Greatly appreciate it!!

@mfucci
Copy link
Owner

mfucci commented Aug 18, 2022

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!

  • Marco

@javierbarellano4v
Copy link
Collaborator

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
Copy link
Collaborator Author

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: #3 (comment). T

his particular issue is inability to complete pairing process with Home Assistant Matter Add-on.

@javierbarellano4v
Copy link
Collaborator

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
Copy link
Collaborator Author

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'

@jdesai61
Copy link
Collaborator Author

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"
}

@mfucci
Copy link
Owner

mfucci commented Aug 26, 2022

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
Copy link
Owner

mfucci commented Aug 27, 2022

Here is a PR that adds the Descriptor cluster: #17

Let me know if this allows to pass one extra steps with HA!
It will probably crash at the next one :-)

@jdesai61
Copy link
Collaborator Author

jdesai61 commented Aug 29, 2022

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'

@mfucci
Copy link
Owner

mfucci commented Aug 30, 2022

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
Copy link
Owner

mfucci commented Aug 30, 2022

Thanks for your help testing this!

@jdesai61
Copy link
Collaborator Author

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
Copy link
Owner

mfucci commented Aug 30, 2022

Here is a fake implementation of subscribe that should allow to pass that step: #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
Copy link
Collaborator Author

jdesai61 commented Sep 1, 2022

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/58969

@jdesai61
Copy link
Collaborator Author

jdesai61 commented Sep 1, 2022

Looking 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);

@mfucci
Copy link
Owner

mfucci commented Sep 1, 2022

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
Copy link
Collaborator Author

jdesai61 commented Sep 1, 2022

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 msec

Here 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/55303

@mfucci
Copy link
Owner

mfucci commented Sep 1, 2022

Fantastic, 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.

@jdesai61
Copy link
Collaborator Author

If a network interface has multiple IPv6 addresses, you may want to choose the one that has the longest prefix length or the highest address scope

This is the right answer.

For a simple test, I just hardcoded my ipv6 address into node-matter and Commissioning with Google Home App worked and devices showed up in my "Home". But it immediately went offline. This is a repeatable behaviour so we should be able to debug it.

When I tried the same hardcoded ipv6 address hack with Android HA Companion App, the commissioning went much further but somehow the HA app just got stuck (waiting for some response or such).

@Apollon77
Copy link
Collaborator

I will experiment around with it tomorrow and potrovide an experimental PR. Idea wopuld be to sort the adresses and start with the "most global one" found ...

For Google home "went offline after commissioning": Do you have just the App or also a Google/Nest Hub? If not then this behaviour is to be expected, see our Readme! Google, Apple and ALexa all need a "hub" to operate the devices. Pairing works via app on Google and Apple, but after that only the hubs are communicating. For Alex even the commissioning process is done by their Hubs (aka Echo devices)

@jdesai61
Copy link
Collaborator Author

Aha - I don't have a hub - that explains it.

@Apollon77
Copy link
Collaborator

exactly.No idea how it work with HA, but I assume that HA server would be the "hub" then afterwards ... ?!

@jdesai61
Copy link
Collaborator Author

That is the idea - matter-server add-on is supposed to be the hub

@jdesai61
Copy link
Collaborator Author

jdesai61 commented Feb 15, 2023

Attached are captured logs from node-matter and android phone (adb logcat | grep matter) when trying to Commission with HA Android Companion app (with hardcoded ipv6 address in node-matter). It seems like things progress up-to a certain point and then stall.
matterandroodadblog.txt
nodematter11.txt
The HA add-on did not produce any logs.

@jdesai61
Copy link
Collaborator Author

jdesai61 commented Feb 15, 2023

For comparison, attached are node-matter and adb logs with Commissioning actually does complete when using Google Home app.
matterandroodadblog2.txt
nodematter12.txt

@Apollon77
Copy link
Collaborator

In fact according to the ligs in my eyes nothing is "stalled" ... it just has been commissioned correctly...

see also

Commissioning completed on fabric #18156227419154863424 as node #00000000FB1AA4D5.

Also the adb log shows

02-15 18:03:25.479 25634 25634 I MatterCommissioner: Commissioning completed successfully. [CONTEXT service_id=336 ]

So the initial step is done.

For Apple/Google this is konf og the part the app does. AFter that you get a new connection to the device coming from "the hub" to initiate the operational connection that then subscrie to values and such

So here the question would go to HA about what is supposed to come next

@jdesai61
Copy link
Collaborator Author

jdesai61 commented Feb 16, 2023

In fact according to the ligs in my eyes nothing is "stalled" ... it just has been commissioned correctly...

The lines you are seeing is in successful commissioning with Google HA app. The logs for commissioning with HA Companion app (one reply above that) don't have the 'completed' lines.

@Apollon77
Copy link
Collaborator

This is the right answer.

I'm not sure after investigating. especially for MDNS traffic which is supposed to be "local discovery" it makes more sense to use local interfaces over global ones

@Apollon77
Copy link
Collaborator

The lines you are seeing is in successful commissioning with Google HA app. The logs for commissioning with HA Companion app (one reply above that) don't have the 'completed' lines.

then please show the logs when pairing with Companion app?? :-)

@jdesai61
Copy link
Collaborator Author

jdesai61 commented Feb 17, 2023

then please show the logs when pairing with Companion app?? :-)

They are already posted here. I posted logs with HA App first and then with Google Home app.

#11 (comment)

@vves vves mentioned this issue Feb 17, 2023
@jdesai61
Copy link
Collaborator Author

Good news (at least for me). It seems like my router was somehow not enabled for IPv6 routing on the LAN. After enabling IPV6 routing on my local LAN, the node-matter code now works without any modifications (for hardcoding IP) - the Google Home App can now consistently find and commission. The HA app now consistently finds the device and starts commissioning but fails to complete it (as seen in logs I posted earlier #11 (comment)).

Attached is the screenshot of my working IPV6 router settings (I am using Unify USG router). This shows the LAN ipv6 properties.
image

@Apollon77
Copy link
Collaborator

Ok, then the reason is that we do not yet respon correctly to read requests for unknown attributes.

2023-02-15 17:56:40.570 DEBUG InteractionProtocol Received read request from udp://fd04:8e92:e99f:1:cb2b:b7a6:ccb2:1613:39893 on session secure/23602: MA-rootdevice(0x0)/Basic Information(0x28)/unknown(0x12), isFabricFiltered=true

I already solved this locally and PR will come soon

@Apollon77
Copy link
Collaborator

Ok the PR that fixes the read response of unknown attributes is in. Please try again and provide a new log. Thank you

@jdesai61
Copy link
Collaborator Author

Yes!!!! With this change I am able to commission the node-matter device and control it with HA. We can close the issue now.

@Apollon77
Copy link
Collaborator

Apollon77 commented Feb 28, 2023

Can you please (for completeness) post a node-mater log from such a pairing process? Then I close

@jdesai61
Copy link
Collaborator Author

For future reference, attached is log from node-matter and corresponding logs from HA Matter server of a successful commissioning and turning the switch on/off from HA a couple of times
ha-matter-server.log
nodematter-success-home-assistant.txt

Hopefully closing this issue for good now.

@Apollon77
Copy link
Collaborator

Let's see ... I have one PR that I will merge soon that could get interesting so I would poke again here after merging for a last test if ok for you.

But interesting ... Hass even registers 3 Fabrics on the devcie which is 1 more then Apple/Google ... no idea why they do that. Seems like the "Google way" plus then one of their own.

@jdesai61
Copy link
Collaborator Author

sure

@jdesai61
Copy link
Collaborator Author

jdesai61 commented Mar 7, 2023

With latest release of Home Assistant and Matter Add-on, I can no longer commission with node-matter. However, this is not an issue with node-matter. It is an issue with HA because it is now refusing to commit devices with test vendor id (0xfff1). I am still looking for a workaround similar to how you have to add test vendor/product Id to the Google backend for pairing with Google Home.

@Apollon77
Copy link
Collaborator

With the infos from above and the "HA companion App" which uses Google in the background please check the readme about the instructions on how to use the Google Developer Console to whitelist this vendor/product id ... I would expect that this helps then?!

@jdesai61
Copy link
Collaborator Author

jdesai61 commented Mar 8, 2023 via email

@Apollon77
Copy link
Collaborator

DId you opened an issue on Homeassistent to get details?

@Apollon77
Copy link
Collaborator

Can you please post logs from both parties (node-matter and also HA).
Are you sure that only HA was updated or did you also updated node-matter? because we now generate correct certificates and not use the "full testing default chain". But chiptool and all othersd are ok with it, so would be interesting to see the logs

@jdesai61
Copy link
Collaborator Author

jdesai61 commented Mar 8, 2023 via email

@Apollon77
Copy link
Collaborator

But sorry when e have not a singel connection request then it CAN NOT be certificates or such ... then it is more network or UDP data flow

@jdesai61
Copy link
Collaborator Author

jdesai61 commented Mar 8, 2023

Not sure what happened, but after another upgrade of HA, it started working again... Sorry for the noise.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants