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.47k stars 2k forks source link

[CERT-TEST-FAILURE] Test_TC_CADMIN_1_16/Test_TC_CADMIN_1_4/TestFabricRemovalWhileSubscribed/TestSelfFabricRemoval #29284

Open Apollon77 opened 1 year ago

Apollon77 commented 1 year ago

Feature Area

Other

Test Case

Reproduction steps

The tests are deleting it's own fabric, but then also expects to receive the Removal response which is especially described in the specs (11.17.6.12.) like:

  1. If the FabricIndex equals the accessing fabric index, then the device SHALL begin the process of irrevocably deleting all associated Fabric-Scoped data, including Access Control Entries, bind­ ings, group keys, operational certificates, etc. Any remaining Trusted Roots no longer refer­ enced by any operational certificate SHALL also be removed. All secure sessions, exchanges and interaction model constructs related to the Operational Identity under the given Fabric SHALL also be removed. Since this operation involves the removal of the secure session data that may underpin the current set of exchanges, the Node invoking the command SHOULD NOT expect a response before terminating its secure session with the target.

Bug prevalence

reproducable anytime

GitHub hash of the SDK that was being used

can not reproduce anymore, was mid august as I build the chip-tool I used for the tests - but because I see this more a topic also in the test result expectation it should be independent - unless I read the specs wrong or the specs are written wrong

Platform

other

Anything else?

Here a log from the TestFabricRemovalWhileSubscribed test.

The specs needs to be adjusted or the test needs to be adjusted to also allow a "failure" and verify the deleting by e.g. a not fabric-scoped read on the "beta" identify after "alpha" deletion.

[1694762175469] [14219:6944507] [TOO]  ***** Test Step 7 : Remove single own fabric

[1694762175469] [14219:6944507] [DMG] ICR moving to [AddingComm]
[1694762175469] [14219:6944507] [DMG] ICR moving to [AddedComma]
[1694762175469] [14219:6944507] [EM] <<< [E:64703i S:31700 M:163041026] (S) Msg TX to 2:0000000012344321 [7A5E] --- Type 0001:08 (IM:InvokeCommandRequest)
[1694762175469] [14219:6944507] [IN] (S) Sending msg 163041026 on secure session with LSID: 31700
[1694762175469] [14219:6944507] [DMG] ICR moving to [CommandSen]
[1694762175469] [14219:6944507] [DL] _OnPlatformEvent
[1694762175474] [14219:6944507] [EM] >>> [E:51463r S:31700 M:3984090030] (S) Msg RX from 2:0000000012344321 [7A5E] --- Type 0000:40 (SecureChannel:StatusReport)
[1694762175474] [14219:6944507] [EM] Handling via exchange: 51463r, Delegate: 0x6000039ccda0
[1694762175474] [14219:6944507] [EM] Received CloseSession status message, closing session
[1694762175474] [14219:6944507] [IN] SecureSession[0x6000007e0200]: MarkForEviction Type:2 LSID:31700
[1694762175474] [14219:6944507] [SC] SecureSession[0x6000007e0200, LSID:31700]: State change 'kActive' --> 'kPendingEviction'
[1694762175474] [14219:6944507] [DMG] Time out! failed to receive invoke command response from Exchange: 64703i
[1694762175474] [14219:6944507] [TOO]  ***** Test Failure: status value mismatch: expected 0 but got 1

[1694762175474] [14219:6944507] [DMG] ICR moving to [AwaitingDe]
[1694762175474] [14219:6944507] [IN] SecureSession[0x6000007e0200]: Released - Type:2 LSID:31700
[1694762175474] [14219:6944507] [DL] _OnPlatformEvent
[1694762175474] [14219:6944506] [CTL] Shutting down the commissioner
[1694762175474] [14219:6944506] [CTL] Stopping commissioning discovery over DNS-SD
[1694762175474] [14219:6944506] [CTL] Shutting down the controller
[1694762175474] [14219:6944506] [IN] Expiring all sessions for fabric 0x2!!
[1694762175474] [14219:6944506] [FP] Forgetting fabric 0x2
[1694762175474] [14219:6944506] [TS] Pending Last Known Good Time: 2023-08-14T23:38:54
[1694762175474] [14219:6944506] [TS] Previous Last Known Good Time: 2023-08-14T23:38:54
[1694762175474] [14219:6944506] [TS] Reverted Last Known Good Time to previous value

As you can see the device is sending a sesion close becuse the secure session data are removed as defined. But the test step fails because it did not received the response of the removeFabric call.

The matter.js log:

2023-09-15 09:16:15.471 DEBUG MessageExchange New exchange protocol: 1 id: 64703 active retransmit ms: 300 idle retransmit ms: 5000 retries: 5
2023-09-15 09:16:15.471 DEBUG MessageExchange Message « id: 63875/64703/163041026 type: 1/8 reqAck: true payload: 1528002801360215370024000024013e24020a18350124000118181824ff0a18
2023-09-15 09:16:15.471 DEBUG InteractionServer Received invoke request from udp://fe80::419:56de:f7c4:1373%en7:54532 on session secure/63875: MA-rootdevice(0x0)/OperationalCredentials(0x3e)/removeFabric(0xa), suppressResponse=false
2023-09-15 09:16:15.471 DEBUG CommandServer Invoke removeFabric with data {"fabricIndex":1}
2023-09-15 09:16:15.471 DEBUG EventHandler Received event: {"eventNumber":3,"eventId":2,"clusterId":40,"endpointId":0,"epochTimestamp":1694762175471,"priority":1,"data":{"fabricIndex":1}}
2023-09-15 09:16:15.472 DEBUG MatterDevice Remove CASE session secure/63875
2023-09-15 09:16:15.472 DEBUG MessageExchange New exchange protocol: 0 id: 51463 active retransmit ms: 300 idle retransmit ms: 5000 retries: 5
2023-09-15 09:16:15.472 DEBUG ExchangeManager Message » id: 31700/51463/3984090030 type: 0/64 reqAck: false payload: 0000000000000300
2023-09-15 09:16:15.498 DEBUG CommandServer Invoke removeFabric response : {"statusCode":0,"fabricIndex":1}
2023-09-15 09:16:15.499 DEBUG ExchangeManager Message » id: 63875/64703/3984090031 type: 1/9 acked: 163041026 reqAck: true payload: 1528003601153500370024000024013e2402081835012400002401011818181824ff0a18

/Because the sesion got destroyed before the actual send, the send is listed in the log but not really happened because session removed).

So is this wrong in the 1.1 Matter specs, or does the test have invalid expectations here?

And BTW: I would have expected that the "TestFabricRemovalWhileSubscribed" also verifies anything with the subscription done there, but it is not :-)

Apollon77 commented 1 year ago

@bzbarsky-apple sorry to tag you here directly but with your spec knowledge it would be great to know if we have a spec issue here too or if the test assumptions should be adjusted. In fact i could also have opened a chip bug because the removeFabric fails on Chip level which it should not because it „shall“ Be expected to get no response ;-)

bzbarsky-apple commented 1 year ago

@Apollon77 The basic spec situation is:

  1. The server MAY send a response before tearing things down.
  2. The client SHOULD NOT expect this response.

There is no SHALL involved here, nor „shall“, whatever that is.

The SDK situation is that the SDK goes to some pains to in fact send the response. TestFabricRemovalWhileSubscribed and TestSelfFabricRemoval are fine, since they are SDK self-tests. TestFabricRemovalWhileSubscribed in particular is a test that verifies the server does not crash in this situation; it's a regression test for https://github.com/project-chip/connectedhomeip/issues/20678

The cert tests, on the other hand, need to get fixed. @cjandhyala @manjunath-grl I filed https://github.com/CHIP-Specifications/chip-test-scripts/issues/663 on that.

bzbarsky-apple commented 1 year ago

Looks like Test_TC_CADMIN_1_6 has the same issue.

Apollon77 commented 1 year ago

Yes I stopped some time to add more cases. Can check later if I have more on my list I stumbled over. And thank you again for the clarification.

I might consider now for matter.js to change our implementation to match with Chip (destroy Session a bit later to send response out in any case) because else we can not be sure that clients/controller really respect the "should not" and because of missing formal controller certification and validation this is else completely unsure how they react to devices doing it differently then Chip.

Apollon77 commented 1 year ago

Looks like Test_TC_CADMIN_1_6 has the same issue.

I updated the list in first post. these are the test cases I'm aware of.

Apollon77 commented 1 year ago

@bzbarsky-apple Discussed all this I have one (a bit) off-topic question ... How can I address that Apple in most iOS 16.x and also now 17.x do not remove all fabrics when a device gets deleted? I think to remember it was correct in iOS 16.1 or such, but then broke somewhen. Furthermore it seems to try to contact the device after having removed that fabric with a destination id of the removed fabric ... In fact this controller behaviour is turning the device "Unusable" because it is not "uncommissioned" afterwards (sorry to say, but at least Google does all right). I thought/hoped that it is because of the fact that we (matter.js) were killing the sessions immediatly on removal (like discussed above), but also now that I changed the session eviction to be a bit "delayed" as chip too does, the behaviour did not really changed.

Here a log from device side (chip tool):

[1695481944020] [86228:12286929] [EM] Handling via exchange: 30797r, Delegate: 0x10b03f7b8
[1695481944021] [86228:12286929] [IM] Received Read request
[1695481944021] [86228:12286929] [DMG] ReadRequestMessage =
[1695481944021] [86228:12286929] [DMG] {
[1695481944021] [86228:12286929] [DMG]  AttributePathIBs =
[1695481944021] [86228:12286929] [DMG]  [
[1695481944021] [86228:12286929] [DMG]      AttributePathIB =
[1695481944021] [86228:12286929] [DMG]      {
[1695481944021] [86228:12286929] [DMG]          Endpoint = 0x0,
[1695481944021] [86228:12286929] [DMG]          Cluster = 0x1d,
[1695481944021] [86228:12286929] [DMG]          Attribute = 0x0000_0003,
[1695481944021] [86228:12286929] [DMG]      }
[1695481944021] [86228:12286929] [DMG]          
[1695481944021] [86228:12286929] [DMG]  ],
[1695481944021] [86228:12286929] [DMG]      
[1695481944021] [86228:12286929] [DMG]  isFabricFiltered = true, 
[1695481944021] [86228:12286929] [DMG]  InteractionModelRevision = 1
[1695481944021] [86228:12286929] [DMG] },
[1695481944021] [86228:12286929] [DMG] IM RH moving to [CanStartReporting]
[1695481944021] [86228:12286929] [DMG] Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[1695481944021] [86228:12286929] [DMG] <RE:Run> Cluster 1d, Attribute 3 is dirty
[1695481944021] [86228:12286929] [DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
[1695481944021] [86228:12286929] [DMG] AccessControl: checking f=1 a=c s=0x27951A9BAF2C0627 t= c=0x0000_001D e=0 p=v
[1695481944021] [86228:12286929] [DMG] AccessControl: allowed
[1695481944021] [86228:12286929] [DMG] <RE> Sending report (payload has 38 bytes)...
[1695481944021] [86228:12286929] [EM] <<< [E:30797r S:9402 M:80392219 (Ack:182351192)] (S) Msg TX to 1:27951A9BAF2C0627 [62D9] --- Type 0001:05 (IM:ReportData)
[1695481944021] [86228:12286929] [IN] (S) Sending msg 80392219 on secure session with LSID: 9402
[1695481944022] [86228:12286929] [DMG] <RE> OnReportConfirm: NumReports = 0
[1695481944022] [86228:12286929] [DMG] <RE> ReportsInFlight = 0 with readHandler 1, RE has no more messages
[1695481944022] [86228:12286929] [DMG] IM RH moving to [AwaitingDestruction]
[1695481944028] [86228:12286929] [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[1695481944029] [86228:12286929] [DL] _OnPlatformEvent
[1695481944031] [86228:12286929] [EM] >>> [E:30797r S:9402 M:182351193 (Ack:80392219)] (S) Msg RX from 1:27951A9BAF2C0627 [62D9] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1695481944031] [86228:12286929] [EM] Found matching exchange: 30797r, Delegate: 0x0
[1695481944031] [86228:12286929] [EM] Rxd Ack; Removing MessageCounter:80392219 from Retrans Table on exchange 30797r
[1695481944031] [86228:12286929] [DL] _OnPlatformEvent
[1695481944038] [86228:12287607] [EM] >>> [E:30798r S:9402 M:182351194] (S) Msg RX from 1:27951A9BAF2C0627 [62D9] --- Type 0001:02 (IM:ReadRequest)
[1695481944038] [86228:12287607] [EM] Handling via exchange: 30798r, Delegate: 0x10b03f7b8
[1695481944038] [86228:12287607] [IM] Received Read request
[1695481944038] [86228:12287607] [DMG] ReadRequestMessage =
[1695481944038] [86228:12287607] [DMG] {
[1695481944039] [86228:12287607] [DMG]  AttributePathIBs =
[1695481944039] [86228:12287607] [DMG]  [
[1695481944039] [86228:12287607] [DMG]      AttributePathIB =
[1695481944039] [86228:12287607] [DMG]      {
[1695481944039] [86228:12287607] [DMG]          Endpoint = 0x0,
[1695481944039] [86228:12287607] [DMG]          Cluster = 0x1d,
[1695481944039] [86228:12287607] [DMG]          Attribute = 0x0000_0001,
[1695481944039] [86228:12287607] [DMG]      }
[1695481944039] [86228:12287607] [DMG]          
[1695481944039] [86228:12287607] [DMG]  ],
[1695481944039] [86228:12287607] [DMG]      
[1695481944039] [86228:12287607] [DMG]  isFabricFiltered = true, 
[1695481944039] [86228:12287607] [DMG]  InteractionModelRevision = 1
[1695481944039] [86228:12287607] [DMG] },
[1695481944039] [86228:12287607] [DMG] IM RH moving to [CanStartReporting]
[1695481944039] [86228:12287607] [DMG] Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[1695481944039] [86228:12287607] [DMG] <RE:Run> Cluster 1d, Attribute 1 is dirty
[1695481944039] [86228:12287607] [DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[1695481944039] [86228:12287607] [DMG] AccessControl: checking f=1 a=c s=0x27951A9BAF2C0627 t= c=0x0000_001D e=0 p=v
[1695481944039] [86228:12287607] [DMG] AccessControl: allowed
[1695481944039] [86228:12287607] [DMG] <RE> Sending report (payload has 76 bytes)...
[1695481944039] [86228:12287607] [EM] <<< [E:30798r S:9402 M:80392220 (Ack:182351194)] (S) Msg TX to 1:27951A9BAF2C0627 [62D9] --- Type 0001:05 (IM:ReportData)
[1695481944039] [86228:12287607] [IN] (S) Sending msg 80392220 on secure session with LSID: 9402
[1695481944039] [86228:12287607] [DMG] <RE> OnReportConfirm: NumReports = 0
[1695481944039] [86228:12287607] [DMG] <RE> ReportsInFlight = 0 with readHandler 1, RE has no more messages
[1695481944039] [86228:12287607] [DMG] IM RH moving to [AwaitingDestruction]
[1695481944045] [86228:12287607] [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[1695481944045] [86228:12287607] [EM] >>> [E:30799r S:9402 M:182351195] (S) Msg RX from 1:27951A9BAF2C0627 [62D9] --- Type 0001:02 (IM:ReadRequest)
[1695481944045] [86228:12287607] [EM] Handling via exchange: 30799r, Delegate: 0x10b03f7b8
[1695481944045] [86228:12287607] [IM] Received Read request
[1695481944045] [86228:12287607] [DMG] ReadRequestMessage =
[1695481944045] [86228:12287607] [DMG] {
[1695481944045] [86228:12287607] [DMG]  AttributePathIBs =
[1695481944045] [86228:12287607] [DMG]  [
[1695481944045] [86228:12287607] [DMG]      AttributePathIB =
[1695481944046] [86228:12287607] [DMG]      {
[1695481944046] [86228:12287607] [DMG]          Endpoint = 0x1,
[1695481944046] [86228:12287607] [DMG]          Cluster = 0x1d,
[1695481944046] [86228:12287607] [DMG]          Attribute = 0x0000_0001,
[1695481944046] [86228:12287607] [DMG]      }
[1695481944046] [86228:12287607] [DMG]          
[1695481944046] [86228:12287607] [DMG]  ],
[1695481944046] [86228:12287607] [DMG]      
[1695481944046] [86228:12287607] [DMG]  isFabricFiltered = true, 
[1695481944046] [86228:12287607] [DMG]  InteractionModelRevision = 1
[1695481944046] [86228:12287607] [DMG] },
[1695481944046] [86228:12287607] [DMG] IM RH moving to [CanStartReporting]
[1695481944046] [86228:12287607] [DL] _OnPlatformEvent
[1695481944046] [86228:12287607] [DMG] Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[1695481944046] [86228:12287607] [DMG] <RE:Run> Cluster 1d, Attribute 1 is dirty
[1695481944046] [86228:12287607] [DMG] Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0001 (expanded=0)
[1695481944046] [86228:12287607] [DMG] AccessControl: checking f=1 a=c s=0x27951A9BAF2C0627 t= c=0x0000_001D e=1 p=v
[1695481944046] [86228:12287607] [DMG] AccessControl: allowed
[1695481944046] [86228:12287607] [DMG] <RE> Sending report (payload has 54 bytes)...
[1695481944046] [86228:12287607] [EM] <<< [E:30799r S:9402 M:80392221 (Ack:182351195)] (S) Msg TX to 1:27951A9BAF2C0627 [62D9] --- Type 0001:05 (IM:ReportData)
[1695481944046] [86228:12287607] [IN] (S) Sending msg 80392221 on secure session with LSID: 9402
[1695481944046] [86228:12287607] [DMG] <RE> OnReportConfirm: NumReports = 0
[1695481944046] [86228:12287607] [DMG] <RE> ReportsInFlight = 0 with readHandler 1, RE has no more messages
[1695481944046] [86228:12287607] [DMG] IM RH moving to [AwaitingDestruction]
[1695481944051] [86228:12287607] [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[1695481944051] [86228:12287607] [DL] _OnPlatformEvent
[1695481944051] [86228:12287607] [EM] >>> [E:30798r S:9402 M:182351196 (Ack:80392220)] (S) Msg RX from 1:27951A9BAF2C0627 [62D9] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1695481944051] [86228:12287607] [EM] Found matching exchange: 30798r, Delegate: 0x0
[1695481944051] [86228:12287607] [EM] Rxd Ack; Removing MessageCounter:80392220 from Retrans Table on exchange 30798r
[1695481944051] [86228:12287607] [DL] _OnPlatformEvent
[1695481944052] [86228:12286929] [EM] >>> [E:30799r S:9402 M:182351197 (Ack:80392221)] (S) Msg RX from 1:27951A9BAF2C0627 [62D9] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1695481944052] [86228:12286929] [EM] Found matching exchange: 30799r, Delegate: 0x0
[1695481944052] [86228:12286929] [EM] Rxd Ack; Removing MessageCounter:80392221 from Retrans Table on exchange 30799r
[1695481944052] [86228:12286929] [DL] _OnPlatformEvent
[1695481944055] [86228:12286929] [EM] >>> [E:30800r S:9402 M:182351198] (S) Msg RX from 1:27951A9BAF2C0627 [62D9] --- Type 0001:02 (IM:ReadRequest)
[1695481944055] [86228:12286929] [EM] Handling via exchange: 30800r, Delegate: 0x10b03f7b8
[1695481944055] [86228:12286929] [IM] Received Read request
[1695481944055] [86228:12286929] [DMG] ReadRequestMessage =
[1695481944055] [86228:12286929] [DMG] {
[1695481944055] [86228:12286929] [DMG]  AttributePathIBs =
[1695481944055] [86228:12286929] [DMG]  [
[1695481944055] [86228:12286929] [DMG]      AttributePathIB =
[1695481944055] [86228:12286929] [DMG]      {
[1695481944055] [86228:12286929] [DMG]          Endpoint = 0x0,
[1695481944055] [86228:12286929] [DMG]          Cluster = 0x3e,
[1695481944055] [86228:12286929] [DMG]          Attribute = 0x0000_0005,
[1695481944055] [86228:12286929] [DMG]      }
[1695481944055] [86228:12286929] [DMG]          
[1695481944055] [86228:12286929] [DMG]  ],
[1695481944055] [86228:12286929] [DMG]      
[1695481944055] [86228:12286929] [DMG]  isFabricFiltered = true, 
[1695481944055] [86228:12286929] [DMG]  InteractionModelRevision = 1
[1695481944055] [86228:12286929] [DMG] },
[1695481944055] [86228:12286929] [DMG] IM RH moving to [CanStartReporting]
[1695481944055] [86228:12286929] [DMG] Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[1695481944055] [86228:12286929] [DMG] <RE:Run> Cluster 3e, Attribute 5 is dirty
[1695481944055] [86228:12286929] [DMG] Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0005 (expanded=0)
[1695481944055] [86228:12286929] [DMG] AccessControl: checking f=1 a=c s=0x27951A9BAF2C0627 t= c=0x0000_003E e=0 p=v
[1695481944055] [86228:12286929] [DMG] AccessControl: allowed
[1695481944055] [86228:12286929] [DMG] <RE> Sending report (payload has 36 bytes)...
[1695481944055] [86228:12286929] [EM] <<< [E:30800r S:9402 M:80392222 (Ack:182351198)] (S) Msg TX to 1:27951A9BAF2C0627 [62D9] --- Type 0001:05 (IM:ReportData)
[1695481944055] [86228:12286929] [IN] (S) Sending msg 80392222 on secure session with LSID: 9402
[1695481944056] [86228:12286929] [DMG] <RE> OnReportConfirm: NumReports = 0
[1695481944056] [86228:12286929] [DMG] <RE> ReportsInFlight = 0 with readHandler 1, RE has no more messages
[1695481944056] [86228:12286929] [DMG] IM RH moving to [AwaitingDestruction]
[1695481944061] [86228:12286929] [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[1695481944061] [86228:12286929] [DL] _OnPlatformEvent
[1695481944064] [86228:12286929] [EM] >>> [E:30800r S:9402 M:182351199 (Ack:80392222)] (S) Msg RX from 1:27951A9BAF2C0627 [62D9] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1695481944064] [86228:12286929] [EM] Found matching exchange: 30800r, Delegate: 0x0
[1695481944064] [86228:12286929] [EM] Rxd Ack; Removing MessageCounter:80392222 from Retrans Table on exchange 30800r
[1695481944064] [86228:12286929] [DL] _OnPlatformEvent
[1695481944065] [86228:12286929] [EM] >>> [E:30801r S:9402 M:182351200] (S) Msg RX from 1:27951A9BAF2C0627 [62D9] --- Type 0001:08 (IM:InvokeCommandRequest)
[1695481944065] [86228:12286929] [EM] Handling via exchange: 30801r, Delegate: 0x10b03f7b8
[1695481944065] [86228:12286929] [DMG] InvokeRequestMessage =
[1695481944065] [86228:12286929] [DMG] {
[1695481944065] [86228:12286929] [DMG]  suppressResponse = false, 
[1695481944065] [86228:12286929] [DMG]  timedRequest = false, 
[1695481944065] [86228:12286929] [DMG]  InvokeRequests =
[1695481944065] [86228:12286929] [DMG]  [
[1695481944065] [86228:12286929] [DMG]      CommandDataIB =
[1695481944065] [86228:12286929] [DMG]      {
[1695481944065] [86228:12286929] [DMG]          CommandPathIB =
[1695481944065] [86228:12286929] [DMG]          {
[1695481944065] [86228:12286929] [DMG]              EndpointId = 0x0,
[1695481944065] [86228:12286929] [DMG]              ClusterId = 0x3e,
[1695481944065] [86228:12286929] [DMG]              CommandId = 0xa,
[1695481944065] [86228:12286929] [DMG]          },
[1695481944065] [86228:12286929] [DMG]          
[1695481944065] [86228:12286929] [DMG]          CommandFields = 
[1695481944065] [86228:12286929] [DMG]          {
[1695481944065] [86228:12286929] [DMG]              0x0 = 1, 
[1695481944065] [86228:12286929] [DMG]          },
[1695481944065] [86228:12286929] [DMG]      },
[1695481944065] [86228:12286929] [DMG]      
[1695481944065] [86228:12286929] [DMG]  ],
[1695481944065] [86228:12286929] [DMG]  
[1695481944065] [86228:12286929] [DMG]  InteractionModelRevision = 1
[1695481944065] [86228:12286929] [DMG] },
[1695481944065] [86228:12286929] [DMG] AccessControl: checking f=1 a=c s=0x27951A9BAF2C0627 t= c=0x0000_003E e=0 p=a
[1695481944065] [86228:12286929] [DMG] AccessControl: allowed
[1695481944065] [86228:12286929] [DMG] Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000A
[1695481944065] [86228:12286929] [ZCL] OpCreds: Received a RemoveFabric Command for FabricIndex 0x1
[1695481944065] [86228:12286929] [EM] <<< [E:30801r S:9402 M:80392223 (Ack:182351200)] (S) Msg TX to 1:27951A9BAF2C0627 [62D9] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1695481944065] [86228:12286929] [IN] (S) Sending msg 80392223 on secure session with LSID: 9402
[1695481944065] [86228:12286929] [EM] Flushed pending ack for MessageCounter:182351200 on exchange 30801r
[1695481944065] [86228:12286929] [EVL] LogEvent event number: 0x0000000000000004 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Epoch timestamp: 0x0000018AC2995801
[1695481944065] [86228:12286929] [DMG] Urgent event will be sent once reporting is not blocked by the min interval
[1695481944065] [86228:12286929] [DMG] Building Reports for ReadHandler with LastReportGeneration = 40 DirtyGeneration = 40
[1695481944065] [86228:12286929] [DMG] AccessControl: checking f=1 a=c s=0x27951A9BAF2C0627 t= c=0x0000_0028 e=0 p=v
[1695481944065] [86228:12286929] [DMG] AccessControl: allowed
[1695481944065] [86228:12286929] [DMG] Fetched 1 events
[1695481944065] [86228:12286929] [DMG] <RE> Sending report (payload has 53 bytes)...
[1695481944066] [86228:12286929] [EM] <<< [E:13929i S:9402 M:80392224] (S) Msg TX to 1:27951A9BAF2C0627 [62D9] --- Type 0001:05 (IM:ReportData)
[1695481944066] [86228:12286929] [IN] (S) Sending msg 80392224 on secure session with LSID: 9402
[1695481944066] [86228:12286929] [DMG] IM RH moving to [AwaitingReportResponse]
[1695481944066] [86228:12286929] [DMG] <RE> ReportsInFlight = 1 with readHandler 0, RE has no more messages
[1695481944066] [86228:12286929] [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[1695481944069] [86228:12286929] [FP] Fabric (0x1) deleted.
[1695481944069] [86228:12286929] [IM] Deleting expired ReadHandler for NodeId: 27951A9BAF2C0627, FabricIndex: 1
[1695481944075] [86228:12286929] [DMG] <RE> OnReportConfirm: NumReports = 0
[1695481944075] [86228:12286929] [DMG] IM RH moving to [AwaitingDestruction]
[1695481944080] [86228:12286929] [ZCL] OpCreds: Fabric index 0x1 was removed
[1695481944080] [86228:12286929] [DIS] Updating services using commissioning mode 0
[1695481944080] [86228:12286929] [DL] Using wifi MAC for hostname
[1695481944080] [86228:12286929] [DIS] Advertise operational node 415CBA0DFE49D4EA-00000000F70C413A
[1695481944080] [86228:12286929] [DIS] Registering service 415CBA0DFE49D4EA-00000000F70C413A on host 000000000000.local. with port 5540 and type: _matter._tcp,_I415CBA0DFE49D4EA on interface id: 0
[1695481944080] [86228:12286929] [DL] Using wifi MAC for hostname
[1695481944081] [86228:12286929] [DIS] Advertise commission parameter vendorID=65521 productID=32769 discriminator=2345/09 cm=0
[1695481944081] [86228:12286929] [DIS] Registering service D0FFCA98768FF6F5 on host 000000000000.local. with port 5540 and type: _matterc._udp,_V65521,_T257,_S9,_L2345 on interface id: 0
[1695481944081] [86228:12286929] [DMG] Endpoint 0, Cluster 0x0000_003E update version to 72b893e2
[1695481944081] [86228:12286929] [DMG] Endpoint 0, Cluster 0x0000_003E update version to 72b893e3
[1695481944092] [86228:12286929] [ZCL] OpCreds: RemoveFabric successful
[1695481944092] [86228:12286929] [DMG] Command handler moving to [ Preparing]
[1695481944092] [86228:12286929] [DMG] Command handler moving to [AddingComm]
[1695481944092] [86228:12286929] [DMG] Command handler moving to [AddedComma]
[1695481944092] [86228:12286929] [IN] Expiring all sessions for fabric 0x1!!
[1695481944092] [86228:12286929] [IN] SecureSession[0x60000260ca00]: MarkForEviction Type:2 LSID:9400
[1695481944092] [86228:12286929] [SC] SecureSession[0x60000260ca00, LSID:9400]: State change 'kActive' --> 'kPendingEviction'
[1695481944092] [86228:12286929] [IN] SecureSession[0x60000260ca00]: Released - Type:2 LSID:9400
[1695481944092] [86228:12286929] [IN] SecureSession[0x600002605100]: MarkForEviction Type:2 LSID:9402
[1695481944092] [86228:12286929] [SC] SecureSession[0x600002605100, LSID:9402]: State change 'kActive' --> 'kPendingEviction'
[1695481944092] [86228:12286929] [DMG] Decreasing reference count for CommandHandler, remaining 0
[1695481944092] [86228:12286929] [EM] <<< [E:30801r S:9402 M:80392225 (Ack:182351200)] (S) Msg TX to 1:27951A9BAF2C0627 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1695481944092] [86228:12286929] [IN] (S) Sending msg 80392225 on secure session with LSID: 9402
[1695481944092] [86228:12286929] [DMG] Command handler moving to [CommandSen]
[1695481944092] [86228:12286929] [DMG] Command handler moving to [AwaitingDe]
[1695481944093] [86228:12286929] [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[1695481944093] [86228:12286929] [DL] _OnPlatformEvent
[1695481944093] [86228:12286929] [DL] _OnPlatformEvent
[1695481944093] [86228:12286929] [DL] _OnPlatformEvent
[1695481944093] [86228:12286929] [EM] >>> [E:13929i S:9402 M:182351201 (Ack:80392224)] (S) Msg RX from 1:27951A9BAF2C0627 [0000] --- Type 0001:01 (IM:StatusResponse)
[1695481944093] [86228:12286929] [EM] Dropping message on inactive session that does not match an existing exchange
[1695481944101] [86228:12286929] [EM] >>> [E:30801r S:9402 M:182351202 (Ack:80392225)] (S) Msg RX from 1:27951A9BAF2C0627 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1695481944101] [86228:12286929] [EM] Found matching exchange: 30801r, Delegate: 0x0
[1695481944101] [86228:12286929] [EM] Rxd Ack; Removing MessageCounter:80392225 from Retrans Table on exchange 30801r
[1695481944101] [86228:12286929] [IN] SecureSession[0x600002605100]: Released - Type:2 LSID:9402
[1695481944101] [86228:12286929] [DL] _OnPlatformEvent
[1695481944471] [86228:12286929] [IN] Data received on an unknown session (LSID=9402). Dropping it!
[1695481944805] [86228:12286929] [DIS] Mdns: OnRegister name: 415CBA0DFE49D4EA-00000000F70C413A, type: _matter._tcp., domain: local., flags: 2
[1695481944805] [86228:12286929] [DIS] mDNS service published: _matter._tcp; instance name: 415CBA0DFE49D4EA-00000000F70C413A
[1695481944805] [86228:12286929] [DIS] Mdns: OnRegister name: D0FFCA98768FF6F5, type: _matterc._udp., domain: local., flags: 2
[1695481944805] [86228:12286929] [DIS] mDNS service published: _matterc._udp; instance name: D0FFCA98768FF6F5
[1695481944805] [86228:12286929] [DIS] Status: Satisfied
[1695481944806] [86228:12286929] [DIS]  lo0 (1)
[1695481944806] [86228:12286929] [DIS]      * ipv4: 127.0.0.1
[1695481944806] [86228:12286929] [DIS]      * ipv6: ::1
[1695481944806] [86228:12286929] [DIS]      * ipv6: fe80::1
[1695481944808] [86228:12286929] [DIS]  en7 (14 / Wired)
[1695481944808] [86228:12286929] [DIS]      * ipv4: 192.168.178.65
[1695481944808] [86228:12286929] [DIS]      * ipv6: fe80::1c3e:5f63:6021:c8f5
[1695481944808] [86228:12286929] [DIS]      * ipv6: 2a02:8071:2c87:399c:18c5:b75f:602d:597d
[1695481944808] [86228:12286929] [DIS]      * ipv6: 2a02:8071:2c87:399c:f964:13d0:5e28:7cff
[1695481944808] [86228:12286929] [DIS]      * ipv6: fd00::14fa:6b7d:35f9:48b
[1695481944810] [86228:12286929] [DIS]  en0 (7 / WiFi)
[1695481944810] [86228:12286929] [DIS]      * ipv4: 192.168.178.159
[1695481944810] [86228:12286929] [DIS]      * ipv6: fe80::419:56de:f7c4:1373
[1695481944810] [86228:12286929] [DIS]      * ipv6: 2a02:8071:2c87:399c:8a0:8914:4763:faad
[1695481944810] [86228:12286929] [DIS]      * ipv6: 2a02:8071:2c87:399c:94e1:77d3:ee9c:7578
[1695481944810] [86228:12286929] [DIS]      * ipv6: fd00::10a4:fa22:87a6:330c
[1695481944810] [86228:12286929] [DIS]      * ipv6: 2a02:8071:2c87:399c:b0b2:fbf0:40ca:4369
[1695481944812] [86228:12286929] [DIS] Status: Satisfied
[1695481944812] [86228:12286929] [DIS]  lo0 (1)
[1695481944812] [86228:12286929] [DIS]      * ipv4: 127.0.0.1
[1695481944812] [86228:12286929] [DIS]      * ipv6: ::1
[1695481944812] [86228:12286929] [DIS]      * ipv6: fe80::1
[1695481944815] [86228:12286929] [DIS]  en7 (14 / Wired)
[1695481944815] [86228:12286929] [DIS]      * ipv4: 192.168.178.65
[1695481944815] [86228:12286929] [DIS]      * ipv6: fe80::1c3e:5f63:6021:c8f5
[1695481944815] [86228:12286929] [DIS]      * ipv6: 2a02:8071:2c87:399c:18c5:b75f:602d:597d
[1695481944815] [86228:12286929] [DIS]      * ipv6: 2a02:8071:2c87:399c:f964:13d0:5e28:7cff
[1695481944815] [86228:12286929] [DIS]      * ipv6: fd00::14fa:6b7d:35f9:48b
[1695481944817] [86228:12286929] [DIS]  en0 (7 / WiFi)
[1695481944817] [86228:12286929] [DIS]      * ipv4: 192.168.178.159
[1695481944817] [86228:12286929] [DIS]      * ipv6: fe80::419:56de:f7c4:1373
[1695481944817] [86228:12286929] [DIS]      * ipv6: 2a02:8071:2c87:399c:8a0:8914:4763:faad
[1695481944817] [86228:12286929] [DIS]      * ipv6: 2a02:8071:2c87:399c:94e1:77d3:ee9c:7578
[1695481944817] [86228:12286929] [DIS]      * ipv6: fd00::10a4:fa22:87a6:330c
[1695481944817] [86228:12286929] [DIS]      * ipv6: 2a02:8071:2c87:399c:b0b2:fbf0:40ca:4369
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 0
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 1
[1695481944818] [86228:12286929] [DIS] Mdns: OnRegisterRecord flags: 0
[1695481944829] [86228:12286929] [IN] Data received on an unknown session (LSID=9402). Dropping it!
[1695481945365] [86228:12286929] [IN] Data received on an unknown session (LSID=9402). Dropping it!
[1695481946308] [86228:12286929] [IN] Data received on an unknown session (LSID=9402). Dropping it!

After a restart it states the same:

[1695482181390] [86250:12289988] [FP] Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x415CBA0DFE49D4EA, FabricId 0x0000000000000002, NodeId 0x00000000F70C413A, VendorId 0x1384

And log from matter. js ... kind of the same:

2023-09-23 15:37:04.094 INFO  CaseServer           session 5225 resumed with udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350 for Fabric 000000000D625E26(index 1) and PeerNode 27951A9BAF2C0627

2023-09-23 15:38:05.108 DEBUG MessageExchange      New exchange protocol: 1 id: 30648 active retransmit ms: 300 idle retransmit ms: 5000 retries: 5
2023-09-23 15:38:05.108 DEBUG MessageExchange      Message « id: 5225/30648/38128139 type: 1/2 reqAck: true payload: 1536001724020024031d2404031818290324ff0118
2023-09-23 15:38:05.109 DEBUG InteractionServer    Received read request from udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350 on session secure/5225: attributes:MA-rootdevice(0x0)/Descriptor(0x1d)/partsList(0x3), events:none isFabricFiltered=true
2023-09-23 15:38:05.109 DEBUG InteractionServer    Read attribute from udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350 on session secure/5225: MA-rootdevice(0x0)/Descriptor(0x1d)/partsList(0x3)=[1] (version=1965097353)
2023-09-23 15:38:05.110 DEBUG InteractionMessenger Sending DataReport chunk with 1 attributes and 0 events: 38 bytes
2023-09-23 15:38:05.110 DEBUG InteractionMessenger checkDecode {"attributeReports":[{"attributeData":{"dataVersion":1965097353,"path":{"endpointId":0,"clusterId":29,"attributeId":3},"data":[{"typeLength":{"type":22}},{"typeLength":{"type":4,"length":0},"value":1},{"typeLength":{"type":24}}]}}],"suppressResponse":false,"interactionModelRevision":10}
2023-09-23 15:38:05.110 DEBUG ExchangeManager      Message » id: 5225/30648/185973258 type: 1/5 acked: 38128139 reqAck: true payload: 153601153501260089012175370124020024031d240403183602040118181818280424ff0a18
2023-09-23 15:38:05.119 DEBUG MessageExchange      Message « id: 5225/30648/38128140 type: 1/1 acked: 185973258 reqAck: true payload: 1524000024ff0118
2023-09-23 15:38:05.119 DEBUG ExchangeManager      Message » id: 5225/30648/185973259 type: 0/16 acked: 38128140 reqAck: false payload: 
2023-09-23 15:38:05.123 DEBUG MessageExchange      New exchange protocol: 1 id: 30649 active retransmit ms: 300 idle retransmit ms: 5000 retries: 5
2023-09-23 15:38:05.123 DEBUG MessageExchange      Message « id: 5225/30649/38128141 type: 1/2 reqAck: true payload: 1536001724020024031d2404011818290324ff0118
2023-09-23 15:38:05.123 DEBUG InteractionServer    Received read request from udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350 on session secure/5225: attributes:MA-rootdevice(0x0)/Descriptor(0x1d)/serverList(0x1), events:none isFabricFiltered=true
2023-09-23 15:38:05.123 DEBUG InteractionServer    Read attribute from udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350 on session secure/5225: MA-rootdevice(0x0)/Descriptor(0x1d)/serverList(0x1)=[29,31,40,48,49,51,60,62,63] (version=1965097353)
2023-09-23 15:38:05.124 DEBUG InteractionMessenger Sending DataReport chunk with 1 attributes and 0 events: 54 bytes
2023-09-23 15:38:05.124 DEBUG InteractionMessenger checkDecode {"attributeReports":[{"attributeData":{"dataVersion":1965097353,"path":{"endpointId":0,"clusterId":29,"attributeId":1},"data":[{"typeLength":{"type":22}},{"typeLength":{"type":4,"length":0},"value":29},{"typeLength":{"type":4,"length":0},"value":31},{"typeLength":{"type":4,"length":0},"value":40},{"typeLength":{"type":4,"length":0},"value":48},{"typeLength":{"type":4,"length":0},"value":49},{"typeLength":{"type":4,"length":0},"value":51},{"typeLength":{"type":4,"length":0},"value":60},{"typeLength":{"type":4,"length":0},"value":62},{"typeLength":{"type":4,"length":0},"value":63},{"typeLength":{"type":24}}]}}],"suppressResponse":false,"interactionModelRevision":10}
2023-09-23 15:38:05.124 DEBUG ExchangeManager      Message » id: 5225/30649/185973260 type: 1/5 acked: 38128141 reqAck: true payload: 153601153501260089012175370124020024031d240401183602041d041f0428043004310433043c043e043f18181818280424ff0a18
2023-09-23 15:38:05.125 DEBUG MessageExchange      New exchange protocol: 1 id: 30650 active retransmit ms: 300 idle retransmit ms: 5000 retries: 5
2023-09-23 15:38:05.125 DEBUG MessageExchange      Message « id: 5225/30650/38128142 type: 1/2 reqAck: true payload: 1536001724020124031d2404011818290324ff0118
2023-09-23 15:38:05.125 DEBUG InteractionServer    Received read request from udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350 on session secure/5225: attributes:MA-onoffpluginunit(0x1)/Descriptor(0x1d)/serverList(0x1), events:none isFabricFiltered=true
2023-09-23 15:38:05.125 DEBUG InteractionServer    Read attribute from udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350 on session secure/5225: MA-onoffpluginunit(0x1)/Descriptor(0x1d)/serverList(0x1)=[3,4,5,6,29,30] (version=3353541251)
2023-09-23 15:38:05.126 DEBUG InteractionMessenger Sending DataReport chunk with 1 attributes and 0 events: 48 bytes
2023-09-23 15:38:05.126 DEBUG InteractionMessenger checkDecode {"attributeReports":[{"attributeData":{"dataVersion":3353541251,"path":{"endpointId":1,"clusterId":29,"attributeId":1},"data":[{"typeLength":{"type":22}},{"typeLength":{"type":4,"length":0},"value":3},{"typeLength":{"type":4,"length":0},"value":4},{"typeLength":{"type":4,"length":0},"value":5},{"typeLength":{"type":4,"length":0},"value":6},{"typeLength":{"type":4,"length":0},"value":29},{"typeLength":{"type":4,"length":0},"value":30},{"typeLength":{"type":24}}]}}],"suppressResponse":false,"interactionModelRevision":10}
2023-09-23 15:38:05.126 DEBUG ExchangeManager      Message » id: 5225/30650/185973261 type: 1/5 acked: 38128142 reqAck: true payload: 153601153501260083fae2c7370124020124031d2404011836020403040404050406041d041e18181818280424ff0a18
2023-09-23 15:38:05.137 DEBUG MessageExchange      Message « id: 5225/30649/38128143 type: 1/1 acked: 185973260 reqAck: true payload: 1524000024ff0118
2023-09-23 15:38:05.137 DEBUG ExchangeManager      Message » id: 5225/30649/185973262 type: 0/16 acked: 38128143 reqAck: false payload: 
2023-09-23 15:38:05.142 DEBUG MessageExchange      Message « id: 5225/30650/38128144 type: 1/1 acked: 185973261 reqAck: true payload: 1524000024ff0118
2023-09-23 15:38:05.142 DEBUG ExchangeManager      Message » id: 5225/30650/185973263 type: 0/16 acked: 38128144 reqAck: false payload: 
2023-09-23 15:38:05.143 DEBUG MessageExchange      New exchange protocol: 1 id: 30651 active retransmit ms: 300 idle retransmit ms: 5000 retries: 5
2023-09-23 15:38:05.143 DEBUG MessageExchange      Message « id: 5225/30651/38128145 type: 1/2 reqAck: true payload: 1536001724020024033e2404051818290324ff0118
2023-09-23 15:38:05.143 DEBUG InteractionServer    Received read request from udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350 on session secure/5225: attributes:MA-rootdevice(0x0)/OperationalCredentials(0x3e)/currentFabricIndex(0x5), events:none isFabricFiltered=true
2023-09-23 15:38:05.143 DEBUG InteractionServer    Read attribute from udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350 on session secure/5225: MA-rootdevice(0x0)/OperationalCredentials(0x3e)/currentFabricIndex(0x5)=1 (version=2526305142)
2023-09-23 15:38:05.143 DEBUG InteractionMessenger Sending DataReport chunk with 1 attributes and 0 events: 36 bytes
2023-09-23 15:38:05.144 DEBUG InteractionMessenger checkDecode {"attributeReports":[{"attributeData":{"dataVersion":2526305142,"path":{"endpointId":0,"clusterId":62,"attributeId":5},"data":[{"typeLength":{"type":4,"length":0},"value":1}]}}],"suppressResponse":false,"interactionModelRevision":10}
2023-09-23 15:38:05.144 DEBUG ExchangeManager      Message » id: 5225/30651/185973264 type: 1/5 acked: 38128145 reqAck: true payload: 1536011535012600765b9496370124020024033e24040518240201181818280424ff0a18
2023-09-23 15:38:05.150 DEBUG MessageExchange      Message « id: 5225/30651/38128146 type: 1/1 acked: 185973264 reqAck: true payload: 1524000024ff0118
2023-09-23 15:38:05.151 DEBUG ExchangeManager      Message » id: 5225/30651/185973265 type: 0/16 acked: 38128146 reqAck: false payload: 
2023-09-23 15:38:05.154 DEBUG MessageExchange      New exchange protocol: 1 id: 30652 active retransmit ms: 300 idle retransmit ms: 5000 retries: 5
2023-09-23 15:38:05.154 DEBUG MessageExchange      Message « id: 5225/30652/38128147 type: 1/8 reqAck: true payload: 1528002801360215370024000024013e24020a18350124000118181824ff0118
2023-09-23 15:38:05.155 DEBUG InteractionServer    Received invoke request from udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350 on session secure/5225: MA-rootdevice(0x0)/OperationalCredentials(0x3e)/removeFabric(0xa), suppressResponse=false
2023-09-23 15:38:05.155 DEBUG CommandServer        Invoke removeFabric with data {"fabricIndex":1}
2023-09-23 15:38:05.155 DEBUG EventHandler         Received event: {"eventNumber":6,"eventId":2,"clusterId":40,"endpointId":0,"epochTimestamp":1695476285155,"priority":1,"data":{"fabricIndex":1}}
2023-09-23 15:38:05.177 DEBUG SubscriptionHandler  Flushing subscription 1748430053 with 0 attributes and 1 events
2023-09-23 15:38:05.177 DEBUG SubscriptionHandler  Sending subscription update message for ID 1748430053 with 0 attributes and 1 events
2023-09-23 15:38:05.177 DEBUG MessageExchange      New exchange protocol: 1 id: 19204 active retransmit ms: 300 idle retransmit ms: 5000 retries: 5
2023-09-23 15:38:05.177 DEBUG SubscriptionHandler  Sending subscription changes for ID 1748430053: 
2023-09-23 15:38:05.177 DEBUG InteractionMessenger Sending DataReport chunk with 0 attributes and 1 events: 57 bytes
2023-09-23 15:38:05.178 DEBUG InteractionMessenger checkDecode {"subscriptionId":1748430053,"eventReports":[{"eventData":{"path":{"endpointId":0,"clusterId":40,"eventId":2,"isUrgent":true},"eventNumber":6,"priority":1,"epochTimestamp":"1695476285155","data":[{"typeLength":{"type":21}},{"tag":{"id":0},"typeLength":{"type":4,"length":0},"value":1},{"typeLength":{"type":24}}]}}],"suppressResponse":false,"interactionModelRevision":10}
2023-09-23 15:38:05.178 DEBUG ExchangeManager      Message » id: 16347/19204/185973266 type: 1/5 reqAck: true payload: 152600e5ec3668360215350137002401002402282403022904182401062402012703e3fe42c28a010000350724000118181818280424ff0a18
2023-09-23 15:38:05.178 DEBUG SecureSession        Removed subscription 1748430053 from secure/5225/5225
2023-09-23 15:38:05.178 INFO  SessionManager       Register Session secure/5225 to send a close when interaction is finished.
2023-09-23 15:38:05.305 DEBUG CommandServer        Invoke removeFabric response : {"statusCode":0,"fabricIndex":1}
2023-09-23 15:38:05.306 DEBUG ExchangeManager      Message » id: 5225/30652/185973267 type: 1/9 acked: 38128147 reqAck: true payload: 1528003601153500370024000024013e2402081835012400002401011818181824ff0a18
2023-09-23 15:38:05.317 DEBUG MessageExchange      Message « id: 5225/19204/38128148 type: 1/1 acked: 185973266 reqAck: true payload: 1524000024ff0118
2023-09-23 15:38:05.317 DEBUG ExchangeManager      Message » id: 16347/19204/185973268 type: 0/16 acked: 38128148 reqAck: false payload: 
2023-09-23 15:38:05.326 DEBUG MessageExchange      Message « id: 5225/30652/38128149 type: 0/16 acked: 185973267 reqAck: false payload: 
2023-09-23 15:38:05.327 DEBUG MatterDevice         Remove CASE session secure/5225
2023-09-23 15:38:05.327 DEBUG MessageExchange      New exchange protocol: 0 id: 19205 active retransmit ms: 300 idle retransmit ms: 5000 retries: 5
2023-09-23 15:38:05.327 DEBUG ExchangeManager      Message » id: 16347/19205/185973269 type: 0/64 reqAck: false payload: 0000000000000300
2023-09-23 15:38:05.327 INFO  SessionManager       Remove Session secure/5225 from session manager.
2023-09-23 15:38:05.327 DEBUG MatterDevice         Announcing fabric: 2
2023-09-23 15:38:05.328 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: en5
2023-09-23 15:38:05.328 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: en0
2023-09-23 15:38:05.329 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: awdl0
2023-09-23 15:38:05.330 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: llw0
2023-09-23 15:38:05.331 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: utun0
2023-09-23 15:38:05.331 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: utun1
2023-09-23 15:38:05.332 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: utun2
2023-09-23 15:38:05.332 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: utun3
2023-09-23 15:38:05.333 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: en7
2023-09-23 15:38:05.355 INFO  UdpMulticastServer   en5: send EHOSTUNREACH ff02::fb:5353
2023-09-23 15:38:13.639 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: lo0
2023-09-23 15:38:20.781 DEBUG MessageExchange      New exchange protocol: 0 id: 30653 active retransmit ms: 300 idle retransmit ms: 5000 retries: 5
2023-09-23 15:38:20.781 DEBUG MessageExchange      Message « id: 0/30653/118949585 type: 0/48 reqAck: true payload: 153001209cc112cd53e2a4e0e760a0d87f006c6cfc6279942c22e9fb081f82a1161bc9042502dc3f300320ceb4911adcda9c766fd1f54d17b220aefab3edb94021d142d7478e92e777890e300441049ecc75f92a8abffe371d4828d09640500f48a76085a110f818aac1ee36af2c5bd699263a93ff680f0d8c5c300704a9e9e515f8bad62fcbcb4ed5b548d7fffa7f300610ced657ba100e62a0c679fdd3caf65ed4300710ba2568c608e797feb7b48d7a063e86e518
2023-09-23 15:38:20.781 INFO  CaseServer           Received pairing request from udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350
2023-09-23 15:38:20.782 ERROR CaseServer           An error occurred during the commissioning Fabric cannot be found from destinationId
    at FabricManager.findFabricFromDestinationId (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/fabric/FabricManager.js:95:11)
    at MatterDevice.findFabricFromDestinationId (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/MatterDevice.js:187:31)
    at CaseServer.handleSigma1 (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/session/case/CaseServer.js:108:29)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async CaseServer.onNewExchange (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/session/case/CaseServer.js:43:7)
    at async SecureChannelProtocol.onNewExchange (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/protocol/securechannel/SecureChannelProtocol.js:74:9)
    at async ExchangeManager.onMessage (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/protocol/ExchangeManager.js:130:7)
2023-09-23 15:38:20.783 DEBUG ExchangeManager      Message » id: 0/30653/185973270 type: 0/64 acked: 118949585 reqAck: true payload: 0100000000000200
2023-09-23 15:38:20.792 DEBUG MessageExchange      Message « id: 0/30653/118949586 type: 0/16 acked: 185973270 reqAck: false payload: 
2023-09-23 15:38:28.261 DEBUG MessageExchange      New exchange protocol: 0 id: 30654 active retransmit ms: 300 idle retransmit ms: 5000 retries: 5
2023-09-23 15:38:28.261 DEBUG MessageExchange      Message « id: 0/30654/118949587 type: 0/48 reqAck: true payload: 15300120a2e1a2f1ed244851e0c93144a52283194f45d3f854c1e9cdc0cd4b609267136e2502dd3f3003208ff1d824ea178c8afef1076daee599b2b1bc20a1bab10af281d9fb59c25118a7300441047cd03ecb20804783afd41ca795c17be39d5c93540e54d42c8775fdf3f94da40e5946ed5e5ee32ff653d92d0baa9a07b2ae7e6ed03ae5fcda6511e959d11723d4300610ced657ba100e62a0c679fdd3caf65ed430071004d0c578af84a103b63cb6ccc0995d3918
2023-09-23 15:38:28.262 INFO  CaseServer           Received pairing request from udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350
2023-09-23 15:38:28.262 ERROR CaseServer           An error occurred during the commissioning Fabric cannot be found from destinationId
    at FabricManager.findFabricFromDestinationId (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/fabric/FabricManager.js:95:11)
    at MatterDevice.findFabricFromDestinationId (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/MatterDevice.js:187:31)
    at CaseServer.handleSigma1 (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/session/case/CaseServer.js:108:29)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async CaseServer.onNewExchange (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/session/case/CaseServer.js:43:7)
    at async SecureChannelProtocol.onNewExchange (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/protocol/securechannel/SecureChannelProtocol.js:74:9)
    at async ExchangeManager.onMessage (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/protocol/ExchangeManager.js:130:7)
2023-09-23 15:38:28.262 DEBUG ExchangeManager      Message » id: 0/30654/185973271 type: 0/64 acked: 118949587 reqAck: true payload: 0100000000000200
2023-09-23 15:38:28.272 DEBUG MessageExchange      Message « id: 0/30654/118949588 type: 0/16 acked: 185973271 reqAck: false payload: 
2023-09-23 15:38:33.682 DEBUG MessageExchange      New exchange protocol: 0 id: 30655 active retransmit ms: 300 idle retransmit ms: 5000 retries: 5
2023-09-23 15:38:33.682 DEBUG MessageExchange      Message « id: 0/30655/118949589 type: 0/48 reqAck: true payload: 15300120ff4bd9221d79b92635c327fe1eb2c874406f043d64782bef2a28b2c2c3ef50fc2502de3f3003203a66a888ff4d0f2ca4b94cb554f402e975c4dcdb2291609d5ee4cb761846243530044104368e8f100f4ae272c2a986169219762009053f91084dd425e38b242a6b1e3ccb68f40534f043caa2a0e25146f0318dc1bb8ab6f13135d0d5c24041a6d8bdcf1b300610ced657ba100e62a0c679fdd3caf65ed430071004b2b461b7422a1985faebd67ec496d818
2023-09-23 15:38:33.683 INFO  CaseServer           Received pairing request from udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350
2023-09-23 15:38:33.683 ERROR CaseServer           An error occurred during the commissioning Fabric cannot be found from destinationId
    at FabricManager.findFabricFromDestinationId (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/fabric/FabricManager.js:95:11)
    at MatterDevice.findFabricFromDestinationId (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/MatterDevice.js:187:31)
    at CaseServer.handleSigma1 (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/session/case/CaseServer.js:108:29)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async CaseServer.onNewExchange (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/session/case/CaseServer.js:43:7)
    at async SecureChannelProtocol.onNewExchange (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/protocol/securechannel/SecureChannelProtocol.js:74:9)
    at async ExchangeManager.onMessage (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/protocol/ExchangeManager.js:130:7)
2023-09-23 15:38:33.683 DEBUG ExchangeManager      Message » id: 0/30655/185973272 type: 0/64 acked: 118949589 reqAck: true payload: 0100000000000200
2023-09-23 15:38:33.697 DEBUG MessageExchange      Message « id: 0/30655/118949590 type: 0/16 acked: 185973272 reqAck: false payload: 
2023-09-23 15:38:45.266 DEBUG MessageExchange      New exchange protocol: 0 id: 30656 active retransmit ms: 300 idle retransmit ms: 5000 retries: 5
2023-09-23 15:38:45.266 DEBUG MessageExchange      Message « id: 0/30656/118949591 type: 0/48 reqAck: true payload: 15300120183ed27e674fd8b3c3b526967dd55329bef923966c5d19d713b065cc1cb331672502df3f30032002948d3e33183d1f92e5d977d1d02235b2c0db26355238effe2009b930b6ba22300441045cedb71f7af73f02f42da91bedf94aae1ed009b572262c72f43559427268d699b7a9e62ae6a790acf60f9ed6d72d1227d4aa5217a8654ccd2ef1725763e2fc2e300610ced657ba100e62a0c679fdd3caf65ed4300710301ae30800945c050ecbef05371ecdde18
2023-09-23 15:38:45.266 INFO  CaseServer           Received pairing request from udp://fe80::1c1c:4eaf:c9ff:472a%en0:60350
2023-09-23 15:38:45.267 ERROR CaseServer           An error occurred during the commissioning Fabric cannot be found from destinationId
    at FabricManager.findFabricFromDestinationId (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/fabric/FabricManager.js:95:11)
    at MatterDevice.findFabricFromDestinationId (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/MatterDevice.js:187:31)
    at CaseServer.handleSigma1 (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/session/case/CaseServer.js:108:29)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async CaseServer.onNewExchange (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/session/case/CaseServer.js:43:7)
    at async SecureChannelProtocol.onNewExchange (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/protocol/securechannel/SecureChannelProtocol.js:74:9)
    at async ExchangeManager.onMessage (/Users/ingof/Dev/GitHub/matter.js/packages/matter.js/dist/cjs/protocol/ExchangeManager.js:130:7)
2023-09-23 15:38:45.267 DEBUG ExchangeManager      Message » id: 0/30656/185973273 type: 0/64 acked: 118949591 reqAck: true payload: 0100000000000200
2023-09-23 15:38:45.275 DEBUG MessageExchange      Message « id: 0/30656/118949592 type: 0/16 acked: 185973273 reqAck: false payload: 
2023-09-23 15:39:05.329 DEBUG MatterDevice         Announcing fabric: 2
2023-09-23 15:39:05.330 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: en5
2023-09-23 15:39:05.331 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: en0
2023-09-23 15:39:05.332 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: awdl0
2023-09-23 15:39:05.332 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: llw0
2023-09-23 15:39:05.333 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: utun0
2023-09-23 15:39:05.333 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: utun1
2023-09-23 15:39:05.334 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: utun2
2023-09-23 15:39:05.334 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: utun3
2023-09-23 15:39:05.335 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: en7
2023-09-23 15:39:05.336 INFO  UdpMulticastServer   en5: send EHOSTUNREACH ff02::fb:5353
2023-09-23 15:39:18.619 DEBUG MdnsBroadcaster      Announcement: Fabric id: 415cba0dfe49d4ea/324348170 qname: 415CBA0DFE49D4EA-000000001355290A._matter._tcp.local port: 5541 interface: lo0
^C2023-09-23 15:39:19.110 DEBUG EventHandler         Received event: {"eventNumber":7,"eventId":1,"clusterId":40,"endpointId":0,"epochTimestamp":1695476359110,"priority":2}
bzbarsky-apple commented 1 year ago

when a device gets deleted

Deleted from where? When you commission a device into Apple Home, it gets added to the Apple Home fabric and the System Commisioner fabric. The latter is used to open commissioning windows for any other fabrics that want to commission the device, including if the device is removed from the Apple Home fabric.

Similarly, if you commission a device on iOS into some non-Apple fabric to start with, it will be added to the System Commissioner fabric first (because that avoids having to communicate the network credentials to the application doing hte commissioning), then on-network commissioning happens for the actual target fabric.

There is separate UI, as I understand, for removing devices entirely from the System Commissioner fabric. It's not part of the Home UI, since it's not attached to Home, I believe. But I can check for sure next week.

Furthermore it seems to try to contact the device after having removed that fabric with a destination id of the removed fabric

I don't know why Home is doing that. Please file a feedback assistant ticket and let me know the id and I will pass it along to the right people. See https://github.com/project-chip/connectedhomeip/issues/28256#issuecomment-1703123417 for an example set of instructions for filing the feedback assistant ticket.

Apollon77 commented 1 year ago

In fact I just used Apple Home to add a device (chip tool or also matter.js as seen above) and 1 minute later removed this device again via Apple home. So i was not doing anything else or any other secondary commissioning or such. Do the "pure basics".

Insane that there is a separate section in settings where you can also handle matter devices. I will check if removing there solves it. But even if this would be - from a user perspective - completely unexpected. A user expects to use one ui and when removing a device in the place it got added - and it is the last "operative fabric" then I would expect that this is cleared too.

I will try to open such a feedback ticket.

Apollon77 commented 1 year ago

@bzbarsky-apple Ok ... with the knowledge that the second faric is the system commisioner fabric which can be seen and managed via iOS Settings - General - Matter devices then yes this is correct and with "remove from keyring" (no idea how it is called in english, my ios is german, so I translated) you can remove the second fabric and then the devcie gets back to the right state.

If this makes sense if a device was onlycommissioned via Apple Home and so the user added the devcie in Apple Home and expects also a deletion to only handled there is another story ;-) So that might be a user feedback ...

As I tried delete today also the hub did not tried to contact the devcie after removal ... so that what was clearly reproducable yesterday did not happen :-)

bzbarsky-apple commented 1 year ago

If this makes sense if a device was onlycommissioned via Apple Home and so the user added the devcie in Apple Home

Fwiw, it's true no matter what application commissions the device. It's commissioned into the System Commissioner fabric and into the fabric of the application doing the commissioning. After that the "Matter devices" UI can be used to open new commissioning windows to commission into new fabrics, etc, as I understand it.

Apollon77 commented 1 year ago

I agree from a tech perspective, my main comments were from a pure users perspective: When I add the devcie via Apple Home and then remove it in Apple Home too (so I never got any contact with any "System commissioner UI" or even know it exists) then I would expect that I can commission the device to e.g Amazon or Google or such again directly ... but thats not possible. So you need to do a factory reset to remove the system commissioner fabric on the device (but the Apple System comissionier still has that entry then and it might not go away ever).