search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.34k stars 1.97k forks source link

[1.3] When an event is triggered on an end device, no reports get sent out #31348

Closed mkardous-silabs closed 8 months ago

mkardous-silabs commented 8 months ago

Reproduction steps

  1. Build Light-Switch App and flash
  2. Chip-Tool in interactive mode
  3. Subscribe to all events any subscribe-event-by-id 0xFFFFFFFF 0xFFFFFFFF 0 10 <nodeid> 0xFFFF
  4. Trigger event - Nothing gets sent out

Attribute reporting works as expected but not events.

Bug prevalence

Systematically

GitHub hash of the SDK that was being used

6b21935fde

Platform

core

Platform Version(s)

No response

Type

Core SDK Crash

Anything else?

Device Side logs

00> [00:00:40.786][info  ][SC] Received Sigma1 msg
00> [00:00:40.787][detail][SC] Found MRP parameters in the message
00> [00:00:40.787][detail][SC] Peer assigned session key ID 37309
00> [00:00:40.794][info  ][EM] <<< [E:22221r S:0 M:165291602 (Ack:216700616)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd51:b85e:5b91:1:875c:204a:10fb:a185]:54706] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume)
00> [00:00:40.795][detail][SC] Sent Sigma2Resume msg
00> [00:00:41.284][detail][IN] UDP Message Received packet nb : 7 SrcAddr : fd51:b85e:5b91:1:875c:204a:10fb:a185[54706] DestAddr : fd51:b85e:5b91:1:56e7:13b5:430f:ba33[5540] Payload Length 34
00> [00:00:41.284][info  ][EM] >>> [E:22221r S:0 M:216700617 (Ack:165291602)] (U) Msg RX from 0:03047483AF67520A [0000] --- Type 0000:40 (SecureChannel:StatusReport)
00> [00:00:41.284][detail][EM] Found matching exchange: 22221r, Delegate: 0x200253e4
00> [00:00:41.285][detail][EM] Rxd Ack; Removing MessageCounter:165291602 from Retrans Table on exchange 22221r
00> [00:00:41.285][info  ][SC] Success status report received. Session was established
00> [00:00:41.306][detail][IN] UDP Message Received packet nb : 8 SrcAddr : fd51:b85e:5b91:1:875c:204a:10fb:a185[54706] DestAddr : fd51:b85e:5b91:1:56e7:13b5:430f:ba33[5540] Payload Length 50
00> [00:00:41.341][info  ][SC] SecureSession[0x200245c0, LSID:28544]: State change 'kEstablishing' --> 'kActive'
00> [00:00:41.341][detail][IN] SecureSession[0x200245c0]: Activated - Type:2 LSID:28544
00> [00:00:41.341][detail][IN] New secure session activated for device <000000000001B669, 1>, LSID:28544 PSID:37309!
00> [00:00:41.341][info  ][IN] CASE Session established to peer: <000000000001B669, 1>
00> [00:00:41.342][detail][IN] SecureSession[0x20024690]: Allocated Type:2 LSID:28545
00> [00:00:41.342][detail][SC] Allocated SecureSession (0x20024690) - waiting for Sigma1 msg
00> [00:00:41.343][info  ][EM] <<< [E:22221r S:0 M:165291603 (Ack:216700617)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd51:b85e:5b91:1:875c:204a:10fb:a185]:54706] --- Type 0000:10 (SecureChannel:StandaloneAck)
00> [00:00:41.343][detail][EM] Flushed pending ack for MessageCounter:216700617 on exchange 22221r
00> [00:00:41.344][info  ][EM] >>> [E:22222r S:28544 M:158648690] (S) Msg RX from 1:000000000001B669 [8783] --- Type 0001:03 (IM:SubscribeRequest)
00> [00:00:41.345][detail][EM] Handling via exchange: 22222r, Delegate: 0x2001468c
00> [00:00:41.345][detail][IM] Received Subscribe request
00> [00:00:41.345][info  ][DMG] Final negotiated min/max parameters: Min = 0s, Max = 3600s
00> [00:00:41.346][detail][DMG] IM RH moving to [CanStartReporting]
00> [00:00:41.357][detail][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
00> [00:00:41.358][detail][DMG] Fetched 4 events
00> [00:00:41.358][detail][DMG] <RE> Sending report (payload has 176 bytes)...
00> [00:00:41.359][info  ][EM] <<< [E:22222r S:28544 M:179194078 (Ack:158648690)] (S) Msg TX to 1:000000000001B669 [8783] [UDP:[fd51:b85e:5b91:1:875c:204a:10fb:a185]:54706] --- Type 0001:05 (IM:ReportData)
00> [00:00:41.360][detail][DMG] IM RH moving to [AwaitingReportResponse]
00> [00:00:41.360][detail][DMG] <RE> ReportsInFlight = 1 with readHandler 0, RE has no more messages
00> [00:00:41.360][detail][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
00> [00:00:41.804][detail][IN] UDP Message Received packet nb : 9 SrcAddr : fd51:b85e:5b91:1:875c:204a:10fb:a185[54706] DestAddr : fd51:b85e:5b91:1:56e7:13b5:430f:ba33[5540] Payload Length 42
00> [00:00:41.805][info  ][EM] >>> [E:22222r S:28544 M:158648691 (Ack:179194078)] (S) Msg RX from 1:000000000001B669 [8783] --- Type 0001:01 (IM:StatusResponse)
00> [00:00:41.805][detail][EM] Found matching exchange: 22222r, Delegate: 0x200161f4
00> [00:00:41.805][detail][EM] Rxd Ack; Removing MessageCounter:179194078 from Retrans Table on exchange 22222r
00> [00:00:41.806][info  ][IM] Received status response, status is 0x00
00> [00:00:41.807][info  ][EM] <<< [E:22222r S:28544 M:179194079 (Ack:158648691)] (S) Msg TX to 1:000000000001B669 [8783] [UDP:[fd51:b85e:5b91:1:875c:204a:10fb:a185%ot]:54706] --- Type 0001:04 (IM:SubscribeResponse)
00> [00:00:41.807][info  ][DMG] Registered a ReadHandler that will schedule a report between system Timestamp: 0x000000000000A34F and system Timestamp 0x00000000003791CF.
00> [00:00:41.808][detail][DMG] <RE> OnReportConfirm: NumReports = 0
00> [00:00:41.808][detail][DMG] IM RH moving to [CanStartReporting]
00> [00:00:42.304][detail][IN] UDP Message Received packet nb : 10 SrcAddr : fd51:b85e:5b91:1:875c:204a:10fb:a185[54706] DestAddr : fd51:b85e:5b91:1:56e7:13b5:430f:ba33[5540] Payload Length 34
00> [00:00:42.305][info  ][EM] >>> [E:22222r S:28544 M:158648692 (Ack:179194079)] (S) Msg RX from 1:000000000001B669 [8783] --- Type 0000:10 (SecureChannel:StandaloneAck)
00> [00:00:42.305][detail][EM] Found matching exchange: 22222r, Delegate: 0
00> [00:00:42.305][detail][EM] Rxd Ack; Removing MessageCounter:179194079 from Retrans Table on exchange 22222r
00> [00:00:49.164][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff698
00> [00:00:49.164][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:49.164][info  ][ZCL] SwitchServer: OnInitialPress
00> [00:00:49.165][detail][EVL] LogEvent event number: 0x0000000000090004 priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x1 Epoch timestamp: 0x000000DC6AD06C0D
00> [00:00:49.283][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff699
00> [00:00:49.283][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:49.284][info  ][ZCL] SwitchServer: OnShortRelease
00> [00:00:49.284][detail][EVL] LogEvent event number: 0x0000000000090005 priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x3 Epoch timestamp: 0x000000DC6AD06C84
00> [00:00:51.308][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff69a
00> [00:00:51.309][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:51.309][info  ][ZCL] SwitchServer: OnInitialPress
00> [00:00:51.309][detail][EVL] LogEvent event number: 0x0000000000090006 priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x1 Epoch timestamp: 0x000000DC6AD0746D
00> [00:00:51.463][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff69b
00> [00:00:51.463][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:51.464][info  ][ZCL] SwitchServer: OnShortRelease
00> [00:00:51.464][detail][EVL] LogEvent event number: 0x0000000000090007 priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x3 Epoch timestamp: 0x000000DC6AD07508
00> [00:00:51.922][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff69c
00> [00:00:51.922][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:51.923][info  ][ZCL] SwitchServer: OnInitialPress
00> [00:00:51.923][detail][EVL] LogEvent event number: 0x0000000000090008 priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x1 Epoch timestamp: 0x000000DC6AD076D3
00> [00:00:52.065][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff69d
00> [00:00:52.065][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:52.065][info  ][ZCL] SwitchServer: OnShortRelease
00> [00:00:52.066][detail][EVL] LogEvent event number: 0x0000000000090009 priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x3 Epoch timestamp: 0x000000DC6AD07761
00> [00:00:52.430][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff69e
00> [00:00:52.430][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:52.430][info  ][ZCL] SwitchServer: OnInitialPress
00> [00:00:52.430][detail][EVL] LogEvent event number: 0x000000000009000A priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x1 Epoch timestamp: 0x000000DC6AD078CE
00> [00:00:52.592][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff69f
00> [00:00:52.592][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:52.592][info  ][ZCL] SwitchServer: OnShortRelease
00> [00:00:52.593][detail][EVL] LogEvent event number: 0x000000000009000B priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x3 Epoch timestamp: 0x000000DC6AD07971
00> [00:00:52.926][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff6a0
00> [00:00:52.926][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:52.926][info  ][ZCL] SwitchServer: OnInitialPress
00> [00:00:52.926][detail][EVL] Copy Event to next buffer with priority 1
00> [00:00:52.927][detail][EVL] LogEvent event number: 0x000000000009000C priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x1 Epoch timestamp: 0x000000DC6AD07ABE
00> [00:00:53.088][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff6a1
00> [00:00:53.088][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:53.088][info  ][ZCL] SwitchServer: OnShortRelease
00> [00:00:53.089][detail][EVL] Copy Event to next buffer with priority 1
00> [00:00:53.089][detail][EVL] LogEvent event number: 0x000000000009000D priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x3 Epoch timestamp: 0x000000DC6AD07B60
00> [00:00:53.422][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff6a2
00> [00:00:53.422][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:53.422][info  ][ZCL] SwitchServer: OnInitialPress
00> [00:00:53.423][detail][EVL] Copy Event to next buffer with priority 1
00> [00:00:53.423][detail][EVL] LogEvent event number: 0x000000000009000E priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x1 Epoch timestamp: 0x000000DC6AD07CAE
00> [00:00:53.598][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff6a3
00> [00:00:53.598][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:53.598][info  ][ZCL] SwitchServer: OnShortRelease
00> [00:00:53.598][detail][EVL] Copy Event to next buffer with priority 1
00> [00:00:53.599][detail][EVL] LogEvent event number: 0x000000000009000F priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x3 Epoch timestamp: 0x000000DC6AD07D5E
00> [00:00:53.963][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff6a4
00> [00:00:53.963][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:53.963][info  ][ZCL] SwitchServer: OnInitialPress
00> [00:00:53.964][detail][EVL] Copy Event to next buffer with priority 1
00> [00:00:53.964][detail][EVL] LogEvent event number: 0x0000000000090010 priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x1 Epoch timestamp: 0x000000DC6AD07ECB
00> [00:00:53.964][detail][DMG] <RE> Buffer overfilled CHIP_CONFIG_EVENT_LOGGING_BYTE_THRESHOLD 512, schedule engine run
00> [00:00:53.965][detail][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
00> [00:00:54.127][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff6a5
00> [00:00:54.127][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:54.127][info  ][ZCL] SwitchServer: OnShortRelease
00> [00:00:54.127][detail][EVL] Copy Event to next buffer with priority 1
00> [00:00:54.128][detail][EVL] LogEvent event number: 0x0000000000090011 priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x3 Epoch timestamp: 0x000000DC6AD07F6F
00> [00:00:54.128][detail][DMG] <RE> Buffer overfilled CHIP_CONFIG_EVENT_LOGGING_BYTE_THRESHOLD 512, schedule engine run
00> [00:00:54.128][detail][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
00> [00:00:55.323][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff6a6
00> [00:00:55.323][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:55.324][info  ][ZCL] SwitchServer: OnInitialPress
00> [00:00:55.324][detail][EVL] Copy Event to next buffer with priority 1
00> [00:00:55.324][detail][EVL] LogEvent event number: 0x0000000000090012 priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x1 Epoch timestamp: 0x000000DC6AD0841C
00> [00:00:55.325][detail][DMG] <RE> Buffer overfilled CHIP_CONFIG_EVENT_LOGGING_BYTE_THRESHOLD 512, schedule engine run
00> [00:00:55.325][detail][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
00> [00:00:55.434][detail][DMG] Endpoint 2, Cluster 0x0000_003B update version to d33ff6a7
00> [00:00:55.435][info  ][ZCL] Cluster callback: 0x0000_003B
00> [00:00:55.435][info  ][ZCL] SwitchServer: OnShortRelease
00> [00:00:55.435][detail][EVL] Copy Event to next buffer with priority 1
00> [00:00:55.435][detail][EVL] LogEvent event number: 0x0000000000090013 priority: 1, endpoint id:  0x2 cluster id: 0x0000_003B event id: 0x3 Epoch timestamp: 0x000000DC6AD0848B
00> [00:00:55.436][detail][DMG] <RE> Buffer overfilled CHIP_CONFIG_EVENT_LOGGING_BYTE_THRESHOLD 512, schedule engine run
00> [00:00:55.436][detail][DMG] All ReadHandler-s are clean, clear GlobalDirtySet

Chip-Tool logs

>>> any subscribe-event-by-id 0xFFFFFFFF 0xFFFFFFFF 0 10 19464 0xFFFF
[1704919029.684230][4510:4510] CHIP:TOO: Command: any subscribe-event-by-id 0xFFFFFFFF 0xFFFFFFFF 0 10 19464 0xFFFF
[1704919029.685030][4510:4512] CHIP:TOO: Sending command to node 0x4c08
[1704919029.685940][4510:4512] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000004C08]
[1704919029.685999][4510:4512] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1704919029.686067][4510:4512] CHIP:DIS: OperationalSessionSetup[1:0000000000004C08]: State change 1 --> 2
[1704919029.688909][4510:4512] CHIP:DIS: Lookup clearing interface for non LL address
[1704919029.689113][4510:4512] CHIP:DIS: UDP:[fd51:b85e:5b91:1:56e7:13b5:430f:ba33%eth0]:5540: new best score: 5
[1704919029.689167][4510:4512] CHIP:DIS: Checking node lookup status after 3 ms
[1704919029.689212][4510:4512] CHIP:DIS: Keeping DNSSD lookup active
[1704919029.691239][4510:4512] CHIP:DIS: UDP:[fd51:b85e:5b91:1:56e7:13b5:430f:ba33%eth0]:5540: score has not improved: 5
[1704919029.691300][4510:4512] CHIP:DIS: Checking node lookup status after 5 ms
[1704919029.691344][4510:4512] CHIP:DIS: Keeping DNSSD lookup active
[1704919029.693634][4510:4512] CHIP:DIS: UDP:[fd51:b85e:5b91:1:56e7:13b5:430f:ba33%wlan0]:5540: score has not improved: 5
[1704919029.693692][4510:4512] CHIP:DIS: Checking node lookup status after 7 ms
[1704919029.693731][4510:4512] CHIP:DIS: Keeping DNSSD lookup active
[1704919029.695313][4510:4512] CHIP:DIS: UDP:[fd51:b85e:5b91:1:56e7:13b5:430f:ba33%wlan0]:5540: score has not improved: 5
[1704919029.695343][4510:4512] CHIP:DIS: Checking node lookup status after 9 ms
[1704919029.695366][4510:4512] CHIP:DIS: Keeping DNSSD lookup active
[1704919029.695705][4510:4512] CHIP:DIS: SRV record already actively processed.
[1704919029.695793][4510:4512] CHIP:DIS: SRV record already actively processed.
[1704919029.695874][4510:4512] CHIP:DIS: SRV record already actively processed.
[1704919029.695953][4510:4512] CHIP:DIS: SRV record already actively processed.
[1704919029.696054][4510:4512] CHIP:DIS: SRV record already actively processed.
[1704919029.696165][4510:4512] CHIP:DIS: SRV record already actively processed.
[1704919029.698187][4510:4512] CHIP:DIS: UDP:[fd51:b85e:5b91:1:56e7:13b5:430f:ba33%eth0]:5540: score has not improved: 5
[1704919029.698229][4510:4512] CHIP:DIS: Checking node lookup status after 12 ms
[1704919029.698258][4510:4512] CHIP:DIS: Keeping DNSSD lookup active
[1704919029.886458][4510:4512] CHIP:DIS: Checking node lookup status after 200 ms
[1704919029.886570][4510:4512] CHIP:DIS: OperationalSessionSetup[1:0000000000004C08]: Updating device address to UDP:[fd51:b85e:5b91:1:56e7:13b5:430f:ba33]:5540 while in state 2
[1704919029.886629][4510:4512] CHIP:DIS: OperationalSessionSetup[1:0000000000004C08]: State change 2 --> 3
[1704919029.886844][4510:4512] CHIP:IN: SecureSession[0xffff800136b0]: Allocated Type:2 LSID:37309
[1704919029.886974][4510:4512] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000004C08
[1704919029.889280][4510:4512] CHIP:EM: <<< [E:22221i S:0 M:216700616] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd51:b85e:5b91:1:56e7:13b5:430f:ba33]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1704919029.889626][4510:4512] CHIP:SC: Sent Sigma1 msg
[1704919029.889702][4510:4512] CHIP:DIS: OperationalSessionSetup[1:0000000000004C08]: State change 3 --> 4
[1704919030.158684][4510:4512] CHIP:EM: >>> [E:22221i S:0 M:165291601 (Ack:216700616)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1704919030.158769][4510:4512] CHIP:EM: Found matching exchange: 22221i, Delegate: 0xffff8000ec28
[1704919030.158992][4510:4512] CHIP:EM: Rxd Ack; Removing MessageCounter:216700616 from Retrans Table on exchange 22221i
[1704919030.172886][4510:4512] CHIP:EM: >>> [E:22221i S:0 M:165291602 (Ack:216700616)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume)
[1704919030.172961][4510:4512] CHIP:EM: Found matching exchange: 22221i, Delegate: 0xffff8000ec28
[1704919030.173004][4510:4512] CHIP:EM: CHIP MessageCounter:216700616 not in RetransTable on exchange 22221i
[1704919030.173081][4510:4512] CHIP:SC: Received Sigma2Resume msg
[1704919030.173913][4510:4512] CHIP:SC: Found MRP parameters in the message
[1704919030.174001][4510:4512] CHIP:SC: Peer assigned session session ID 28544
[1704919030.179583][4510:4512] CHIP:SC: Sending status report. Protocol code 0, exchange 22221
[1704919030.179864][4510:4512] CHIP:EM: <<< [E:22221i S:0 M:216700617 (Ack:165291602)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd51:b85e:5b91:1:56e7:13b5:430f:ba33%wpan0]:5540] --- Type 0000:40 (SecureChannel:StatusReport)
[1704919030.180596][4510:4512] CHIP:SC: SecureSession[0xffff800136b0, LSID:37309]: State change 'kEstablishing' --> 'kActive'
[1704919030.180680][4510:4512] CHIP:IN: SecureSession[0xffff800136b0]: Activated - Type:2 LSID:37309
[1704919030.180726][4510:4512] CHIP:IN: New secure session activated for device <0000000000004C08, 1>, LSID:37309 PSID:28544!
[1704919030.180781][4510:4512] CHIP:DIS: OperationalSessionSetup[1:0000000000004C08]: State change 4 --> 5
[1704919030.180902][4510:4512] CHIP:TOO: Sending SubscribeEvent to:
[1704919030.180954][4510:4512] CHIP:TOO:    cluster 0xFFFF_FFFF, event: 0xFFFF_FFFF, endpoint 65535
[1704919030.181517][4510:4512] CHIP:EM: <<< [E:22222i S:37309 M:158648690] (S) Msg TX to 1:0000000000004C08 [8783] [UDP:[fd51:b85e:5b91:1:56e7:13b5:430f:ba33%wpan0]:5540] --- Type 0001:03 (IM:SubscribeRequest)
[1704919030.181786][4510:4512] CHIP:DMG: MoveToState ReadClient[0xffff8000a540]: Moving to [AwaitingIn]
[1704919030.714739][4510:4512] CHIP:EM: >>> [E:22221i S:0 M:165291603 (Ack:216700617)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1704919030.714829][4510:4512] CHIP:EM: Found matching exchange: 22221i, Delegate: (nil)
[1704919030.714968][4510:4512] CHIP:EM: Rxd Ack; Removing MessageCounter:216700617 from Retrans Table on exchange 22221i
[1704919030.743727][4510:4512] CHIP:EM: >>> [E:22222i S:37309 M:179194078 (Ack:158648690)] (S) Msg RX from 1:0000000000004C08 [8783] --- Type 0001:05 (IM:ReportData)
[1704919030.743814][4510:4512] CHIP:EM: Found matching exchange: 22222i, Delegate: 0xffff8000a550
[1704919030.743889][4510:4512] CHIP:EM: Rxd Ack; Removing MessageCounter:158648690 from Retrans Table on exchange 22222i
[1704919030.744046][4510:4512] CHIP:DMG: ReportDataMessage =
[1704919030.744196][4510:4512] CHIP:DMG: {
[1704919030.744323][4510:4512] CHIP:DMG:    SubscriptionId = 0xdb88210c,
[1704919030.744380][4510:4512] CHIP:DMG:    EventReportIBs =
[1704919030.744523][4510:4512] CHIP:DMG:    [
[1704919030.744582][4510:4512] CHIP:DMG:        EventReportIB =
[1704919030.744656][4510:4512] CHIP:DMG:        {
[1704919030.744749][4510:4512] CHIP:DMG:            EventDataIB =
[1704919030.745011][4510:4512] CHIP:DMG:            {
[1704919030.745127][4510:4512] CHIP:DMG:                EventPath =
[1704919030.745310][4510:4512] CHIP:DMG:                {
[1704919030.745440][4510:4512] CHIP:DMG:                    Endpoint = 0x0,
[1704919030.745597][4510:4512] CHIP:DMG:                    Cluster = 0x33,
[1704919030.745724][4510:4512] CHIP:DMG:                    Event = 0x3,
[1704919030.745800][4510:4512] CHIP:DMG:                },
[1704919030.745923][4510:4512] CHIP:DMG:
[1704919030.745991][4510:4512] CHIP:DMG:                EventNumber = 0x90000,
[1704919030.746114][4510:4512] CHIP:DMG:                PriorityLevel = 0x2,
[1704919030.746223][4510:4512] CHIP:DMG:                EpochTimestamp = 0xdc6acfac2f,
[1704919030.746326][4510:4512] CHIP:DMG:                EventData =
[1704919030.746395][4510:4512] CHIP:DMG:                {
[1704919030.746504][4510:4512] CHIP:DMG:                    0x0 = 0,
[1704919030.746577][4510:4512] CHIP:DMG:                },
[1704919030.746675][4510:4512] CHIP:DMG:            },
[1704919030.746750][4510:4512] CHIP:DMG:
[1704919030.746836][4510:4512] CHIP:DMG:        },
[1704919030.746997][4510:4512] CHIP:DMG:
[1704919030.747052][4510:4512] CHIP:DMG:        EventReportIB =
[1704919030.747123][4510:4512] CHIP:DMG:        {
[1704919030.747213][4510:4512] CHIP:DMG:            EventDataIB =
[1704919030.747275][4510:4512] CHIP:DMG:            {
[1704919030.747371][4510:4512] CHIP:DMG:                EventPath =
[1704919030.747438][4510:4512] CHIP:DMG:                {
[1704919030.747537][4510:4512] CHIP:DMG:                    Endpoint = 0x0,
[1704919030.747610][4510:4512] CHIP:DMG:                    Cluster = 0x38,
[1704919030.747717][4510:4512] CHIP:DMG:                    Event = 0x0,
[1704919030.747784][4510:4512] CHIP:DMG:                },
[1704919030.747891][4510:4512] CHIP:DMG:
[1704919030.747990][4510:4512] CHIP:DMG:                EventNumber = 0x90001,
[1704919030.748064][4510:4512] CHIP:DMG:                PriorityLevel = 0x1,
[1704919030.748183][4510:4512] CHIP:DMG:                EpochTimestamp = 0xdc6acfac31,
[1704919030.748253][4510:4512] CHIP:DMG:                EventData =
[1704919030.748365][4510:4512] CHIP:DMG:                {
[1704919030.748485][4510:4512] CHIP:DMG:                },
[1704919030.748549][4510:4512] CHIP:DMG:            },
[1704919030.748665][4510:4512] CHIP:DMG:
[1704919030.748769][4510:4512] CHIP:DMG:        },
[1704919030.748904][4510:4512] CHIP:DMG:
[1704919030.748959][4510:4512] CHIP:DMG:        EventReportIB =
[1704919030.749081][4510:4512] CHIP:DMG:        {
[1704919030.749187][4510:4512] CHIP:DMG:            EventDataIB =
[1704919030.749252][4510:4512] CHIP:DMG:            {
[1704919030.749363][4510:4512] CHIP:DMG:                EventPath =
[1704919030.749477][4510:4512] CHIP:DMG:                {
[1704919030.749548][4510:4512] CHIP:DMG:                    Endpoint = 0x0,
[1704919030.749672][4510:4512] CHIP:DMG:                    Cluster = 0x28,
[1704919030.749792][4510:4512] CHIP:DMG:                    Event = 0x0,
[1704919030.749860][4510:4512] CHIP:DMG:                },
[1704919030.749978][4510:4512] CHIP:DMG:
[1704919030.750043][4510:4512] CHIP:DMG:                EventNumber = 0x90002,
[1704919030.750188][4510:4512] CHIP:DMG:                PriorityLevel = 0x2,
[1704919030.750257][4510:4512] CHIP:DMG:                EpochTimestamp = 0xdc6acfac36,
[1704919030.750321][4510:4512] CHIP:DMG:                EventData =
[1704919030.750436][4510:4512] CHIP:DMG:                {
[1704919030.750551][4510:4512] CHIP:DMG:                    0x0 = 1,
[1704919030.750672][4510:4512] CHIP:DMG:                },
[1704919030.750736][4510:4512] CHIP:DMG:            },
[1704919030.750864][4510:4512] CHIP:DMG:
[1704919030.751088][4510:4512] CHIP:DMG:        },
[1704919030.751180][4510:4512] CHIP:DMG:
[1704919030.751231][4510:4512] CHIP:DMG:        EventReportIB =
[1704919030.751303][4510:4512] CHIP:DMG:        {
[1704919030.751409][4510:4512] CHIP:DMG:            EventDataIB =
[1704919030.751518][4510:4512] CHIP:DMG:            {
[1704919030.751579][4510:4512] CHIP:DMG:                EventPath =
[1704919030.751645][4510:4512] CHIP:DMG:                {
[1704919030.751762][4510:4512] CHIP:DMG:                    Endpoint = 0x0,
[1704919030.751883][4510:4512] CHIP:DMG:                    Cluster = 0x38,
[1704919030.751958][4510:4512] CHIP:DMG:                    Event = 0x3,
[1704919030.752072][4510:4512] CHIP:DMG:                },
[1704919030.752198][4510:4512] CHIP:DMG:
[1704919030.752266][4510:4512] CHIP:DMG:                EventNumber = 0x90003,
[1704919030.752379][4510:4512] CHIP:DMG:                PriorityLevel = 0x1,
[1704919030.752412][4510:4512] CHIP:DMG:                EpochTimestamp = 0xdc6acfb1db,
[1704919030.752468][4510:4512] CHIP:DMG:                EventData =
[1704919030.752505][4510:4512] CHIP:DMG:                {
[1704919030.752538][4510:4512] CHIP:DMG:                },
[1704919030.752569][4510:4512] CHIP:DMG:            },
[1704919030.752623][4510:4512] CHIP:DMG:
[1704919030.752676][4510:4512] CHIP:DMG:        },
[1704919030.752710][4510:4512] CHIP:DMG:
[1704919030.752735][4510:4512] CHIP:DMG:    ],
[1704919030.752807][4510:4512] CHIP:DMG:
[1704919030.752834][4510:4512] CHIP:DMG:    InteractionModelRevision = 11
[1704919030.752859][4510:4512] CHIP:DMG: }
[1704919030.753109][4510:4512] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0033 Event 0x0000_0003
[1704919030.753137][4510:4512] CHIP:TOO:   Event number: 589824
[1704919030.753157][4510:4512] CHIP:TOO:   Priority: Critical
[1704919030.753200][4510:4512] CHIP:TOO:   Timestamp: 946684800047
[1704919030.753274][4510:4512] CHIP:TOO:   BootReason: {
[1704919030.753304][4510:4512] CHIP:TOO:     BootReason: 0
[1704919030.753327][4510:4512] CHIP:TOO:    }
[1704919030.753421][4510:4512] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0038 Event 0x0000_0000
[1704919030.753446][4510:4512] CHIP:TOO:   Event number: 589825
[1704919030.753492][4510:4512] CHIP:TOO:   Priority: Info
[1704919030.753514][4510:4512] CHIP:TOO:   Timestamp: 946684800049
[1704919030.753565][4510:4512] CHIP:TOO:   DSTTableEmpty: {
[1704919030.753589][4510:4512] CHIP:TOO:    }
[1704919030.753731][4510:4512] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0028 Event 0x0000_0000
[1704919030.753758][4510:4512] CHIP:TOO:   Event number: 589826
[1704919030.753778][4510:4512] CHIP:TOO:   Priority: Critical
[1704919030.753822][4510:4512] CHIP:TOO:   Timestamp: 946684800054
[1704919030.753878][4510:4512] CHIP:TOO:   StartUp: {
[1704919030.753904][4510:4512] CHIP:TOO:     SoftwareVersion: 1
[1704919030.753955][4510:4512] CHIP:TOO:    }
[1704919030.754046][4510:4512] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0038 Event 0x0000_0003
[1704919030.754070][4510:4512] CHIP:TOO:   Event number: 589827
[1704919030.754090][4510:4512] CHIP:TOO:   Priority: Info
[1704919030.754129][4510:4512] CHIP:TOO:   Timestamp: 946684801499
[1704919030.754156][4510:4512] CHIP:TOO:   TimeFailure: {
[1704919030.754179][4510:4512] CHIP:TOO:    }
[1704919030.754306][4510:4512] CHIP:DMG: MoveToState ReadClient[0xffff8000a540]: Moving to [AwaitingSu]
[1704919030.754638][4510:4512] CHIP:EM: <<< [E:22222i S:37309 M:158648691 (Ack:179194078)] (S) Msg TX to 1:0000000000004C08 [8783] [UDP:[fd51:b85e:5b91:1:56e7:13b5:430f:ba33%wpan0]:5540] --- Type 0001:01 (IM:StatusResponse)
[1704919031.179922][4510:4512] CHIP:EM: >>> [E:22222i S:37309 M:179194079 (Ack:158648691)] (S) Msg RX from 1:0000000000004C08 [8783] --- Type 0001:04 (IM:SubscribeResponse)
[1704919031.180000][4510:4512] CHIP:EM: Found matching exchange: 22222i, Delegate: 0xffff8000a550
[1704919031.180078][4510:4512] CHIP:EM: Rxd Ack; Removing MessageCounter:158648691 from Retrans Table on exchange 22222i
[1704919031.180150][4510:4512] CHIP:DMG: SubscribeResponse is received
[1704919031.180225][4510:4512] CHIP:DMG: SubscribeResponseMessage =
[1704919031.180551][4510:4512] CHIP:DMG: {
[1704919031.180924][4510:4512] CHIP:DMG:    SubscriptionId = 0xdb88210c,
[1704919031.180982][4510:4512] CHIP:DMG:    MaxInterval = 0xe10,
[1704919031.181071][4510:4512] CHIP:DMG:    InteractionModelRevision = 11
[1704919031.181114][4510:4512] CHIP:DMG: }
[1704919031.181164][4510:4512] CHIP:DMG: Subscription established with SubscriptionID = 0xdb88210c MinInterval = 0s MaxInterval = 3600s Peer = 01:0000000000004C08
[1704919031.181248][4510:4512] CHIP:DMG: MoveToState ReadClient[0xffff8000a540]: Moving to [Subscripti]
[1704919031.181328][4510:4512] CHIP:DMG: Refresh LivenessCheckTime for 3604224 milliseconds with SubscriptionId = 0xdb88210c Peer = 01:0000000000004C08
[1704919031.181769][4510:4512] CHIP:EM: <<< [E:22222i S:37309 M:158648692 (Ack:179194079)] (S) Msg TX to 1:0000000000004C08 [8783] [UDP:[fd51:b85e:5b91:1:56e7:13b5:430f:ba33%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1704919031.182014][4510:4512] CHIP:EM: Flushed pending ack for MessageCounter:179194079 on exchange 22222i
yunhanw-google commented 8 months ago

may I know how to trigger event?

mkardous-silabs commented 8 months ago

On the Linux app, i'm not sure how to trigger the event. Test event has a way (TCSWTCH...) On a silabs boards, BTN1 triggers the switch events

bzbarsky-apple commented 8 months ago

So I just tried the following steps to reproduce, after compiling the relevant binaries from SHA 4838490b16f8f36b8d7ae3e62c6e83371f4291d3:

Terminal 1:

% ./out/debug/standalone/chip-all-clusters-app

Terminal 2:

% ./out/debug/standalone/chip-tool pairing code 1 MT:-24J042C00KA0648G00
% ./out/debug/standalone/chip-tool interactive start  
>>>  any subscribe-event-by-id 0xFFFFFFFF 0xFFFFFFFF 0 10 1 0xFFFF

Terminal 3:

% echo '{ "Name": "SoftwareFault" }' > /tmp/chip_all_clusters_fifo_200

In terminal 1 I see:

[1704929918822] [200:7919384] [EVL] LogEvent event number: 0x0000000000000005 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0034 event id: 0x0 Epoch timestamp: 0x0000018CF5BDFF66

After a short delay in terminal 2 I see:

[1704929924908] [218:7918881] [DMG] ReportDataMessage =
[1704929924908] [218:7918881] [DMG] {
[1704929924908] [218:7918881] [DMG]     SubscriptionId = 0xc0936fe8,
[1704929924908] [218:7918881] [DMG]     EventReportIBs =
...
[1704929924909] [218:7918881] [TOO] Endpoint: 0 Cluster: 0x0000_0034 Event 0x0000_0000
[1704929924909] [218:7918881] [TOO]   Event number: 5
[1704929924909] [218:7918881] [TOO]   Priority: Info
[1704929924909] [218:7918881] [TOO]   Timestamp: 1704929918822
[1704929924909] [218:7918881] [TOO]   SoftwareFault: {
[1704929924909] [218:7918881] [TOO]     Id: 200
[1704929924909] [218:7918881] [TOO]     Name: 200
[1704929924909] [218:7918881] [TOO]     FaultRecording: 576564204A616E2031302031383A33383A33382032303234
[1704929924909] [218:7918881] [TOO]    }
yunhanw-google commented 8 months ago

locally when running the below against all-cluster-app ./out/linux-x64-chip-tool/chip-tool interactive start pairing onnetwork-long 1 20202021 3840 unittesting subscribe-event test-event 0 20 1 1 unittesting test-emit-test-event-request 1 2 false 1 1

I am able to receive the test event whenever maximum period is reached if trigger test-emit-test-event-request periodically.

bzbarsky-apple commented 8 months ago

I just tried the following also:

  1. Compile all-clusters-app for esp32 (m5stack).
  2. Commission it with chip-tool and node id 1.
  3. Run the following:
% ./out/debug/standalone/chip-tool interactive start  
>>> any subscribe-event-by-id 0xFFFFFFFF 0xFFFFFFFF 0 10 1 0xFFFF --is-urgent true
>>> accesscontrol write acl '[{"privilege": 5, "authMode": 2, "subjects": null, "targets": null}]' 1 0

I immediately get subscription reports:

[1704990075471] [54161:8230327] [TOO] Endpoint: 0 Cluster: 0x0000_001F Event 0x0000_0000
[1704990075471] [54161:8230327] [TOO]   Event number: 5
[1704990075471] [54161:8230327] [TOO]   Priority: Info
[1704990075471] [54161:8230327] [TOO]   Timestamp: 209453
[1704990075471] [54161:8230327] [TOO]   AccessControlEntryChanged: {

etc.

mkardous-silabs commented 8 months ago

The reason why the event reports were not being sent out was because the subscription request did not have the --is-urgent flag which requests the report to be as soon as possible.