[darwin-framework-tool] subscribe-by-id times out even when server is responding

[dwgaul]

subscribe-by-id looks to be implemented in Darwin-framework-tool.

Ran the following:

./darwin-framework-tool onoff subscribe-by-id 0 1 2 1 0x00000000000014EA 1 

This appears to be successful as we do get a report from the server and responses:

[1654823473288] [79832:19231325] CHIP: [EM] Received message of type 0x5 with protocolId (0, 1) and MessageCounter:99412664 on exchange 18753i
[1654823473288] [79832:19231325] CHIP: [EM] Found matching exchange: 18753i, Delegate: 0x600000ff40f0
[1654823473288] [79832:19231325] CHIP: [EM] Rxd Ack; Removing MessageCounter:165127678 from Retrans Table on exchange 18753i
[1654823473288] [79832:19231325] CHIP: [EM] Removed CHIP MessageCounter:165127678 from RetransTable on exchange 18753i
[1654823473288] [79832:19231325] CHIP: [DMG] ReportDataMessage =
[1654823473288] [79832:19231325] CHIP: [DMG] {
[1654823473288] [79832:19231325] CHIP: [DMG] 	SubscriptionId = 0xd8bfe177,
[1654823473288] [79832:19231325] CHIP: [DMG] 	AttributeReportIBs =
[1654823473288] [79832:19231325] CHIP: [DMG] 	[
[1654823473288] [79832:19231325] CHIP: [DMG] 		AttributeReportIB =
[1654823473288] [79832:19231325] CHIP: [DMG] 		{
[1654823473288] [79832:19231325] CHIP: [DMG] 			AttributeDataIB =
[1654823473288] [79832:19231325] CHIP: [DMG] 			{
[1654823473288] [79832:19231325] CHIP: [DMG] 				DataVersion = 0x4f6ef2b9,
[1654823473288] [79832:19231325] CHIP: [DMG] 				AttributePathIB =
[1654823473288] [79832:19231325] CHIP: [DMG] 				{
[1654823473288] [79832:19231325] CHIP: [DMG] 					Endpoint = 0x1,
[1654823473288] [79832:19231325] CHIP: [DMG] 					Cluster = 0x6,
[1654823473288] [79832:19231325] CHIP: [DMG] 					Attribute = 0x0000_0000,
[1654823473288] [79832:19231325] CHIP: [DMG] 				}
[1654823473288] [79832:19231325] CHIP: [DMG] 					
[1654823473288] [79832:19231325] CHIP: [DMG] 				Data = false, 
[1654823473288] [79832:19231325] CHIP: [DMG] 			},
[1654823473288] [79832:19231325] CHIP: [DMG] 			
[1654823473288] [79832:19231325] CHIP: [DMG] 		},
[1654823473288] [79832:19231325] CHIP: [DMG] 		
[1654823473288] [79832:19231325] CHIP: [DMG] 	],
[1654823473288] [79832:19231325] CHIP: [DMG] 	
[1654823473288] [79832:19231325] CHIP: [DMG] 	InteractionModelRevision = 1
[1654823473288] [79832:19231325] CHIP: [DMG] }
[1654823473288] [79832:19231325] CHIP: [DMG] MoveToState ReadClient[0x600000ff40f0]: Moving to [AwaitingSu]
[1654823473289] [79832:19231325] CHIP: [EM] Piggybacking Ack for MessageCounter:99412664 on exchange: 18753i
[1654823473289] [79832:19231325] CHIP: [IN] Prepared secure message 0x7f90d101ef18 to 0x00000000000014EA (1)  of type 0x1 and protocolId (0, 1) on exchange 18753i with MessageCounter:165127679.
[1654823473289] [79832:19231325] CHIP: [IN] Sending encrypted msg 0x7f90d101ef18 with MessageCounter:165127679 to 0x00000000000014EA (1) at monotonic time: 00000001F3E489A0 msec
2022-06-09 18:11:13.289 darwin-framework-tool[79832:19231326] Response Item: {
    attributePath = "<CHIPAttributePath: 0x6000030da2c0>";
    data =     {
        type = Boolean;
        value = 0;
    };
}
[1654823473384] [79832:19231325] CHIP: [EM] Received message of type 0x4 with protocolId (0, 1) and MessageCounter:99412665 on exchange 18753i
[1654823473384] [79832:19231325] CHIP: [EM] Found matching exchange: 18753i, Delegate: 0x600000ff40f0
[1654823473384] [79832:19231325] CHIP: [EM] Rxd Ack; Removing MessageCounter:165127679 from Retrans Table on exchange 18753i
[1654823473384] [79832:19231325] CHIP: [EM] Removed CHIP MessageCounter:165127679 from RetransTable on exchange 18753i
[1654823473384] [79832:19231325] CHIP: [DMG] SubscribeResponseMessage =
[1654823473384] [79832:19231325] CHIP: [DMG] {
[1654823473384] [79832:19231325] CHIP: [DMG] 	SubscriptionId = 0xd8bfe177,
[1654823473384] [79832:19231325] CHIP: [DMG] 	MinIntervalFloorSeconds = 0x1,
[1654823473384] [79832:19231325] CHIP: [DMG] 	MaxIntervalCeilingSeconds = 0x2,
[1654823473384] [79832:19231325] CHIP: [DMG] 	InteractionModelRevision = 1
[1654823473384] [79832:19231325] CHIP: [DMG] }
[1654823473384] [79832:19231325] CHIP: [DMG] Subscription established with SubscriptionID = 0xd8bfe177 MinInterval = 1s MaxInterval = 2s Peer = 01:00000000000014EA
[1654823473384] [79832:19231325] CHIP: [DMG] MoveToState ReadClient[0x600000ff40f0]: Moving to [Subscripti]
[1654823473384] [79832:19231325] CHIP: [DMG] Refresh LivenessCheckTime for 27000 milliseconds with SubscriptionId = 0xd8bfe177 Peer = 01:00000000000014EA
[1654823473384] [79832:19231325] CHIP: [EM] Sending Standalone Ack for MessageCounter:99412665 on exchange 18753i
[1654823473384] [79832:19231325] CHIP: [IN] Prepared secure message 0x70000ff004c0 to 0x00000000000014EA (1)  of type 0x10 and protocolId (0, 0) on exchange 18753i with MessageCounter:165127680.
[1654823473384] [79832:19231325] CHIP: [IN] Sending encrypted msg 0x70000ff004c0 with MessageCounter:165127680 to 0x00000000000014EA (1) at monotonic time: 00000001F3E489FF msec
[1654823473384] [79832:19231325] CHIP: [EM] Flushed pending ack for MessageCounter:99412665 on exchange 18753i
[1654823475410] [79832:19231325] CHIP: [EM] Received message of type 0x5 with protocolId (0, 1) and MessageCounter:99412666 on exchange 38188r
[1654823475410] [79832:19231325] CHIP: [EM] Handling via exchange: 38188r, Delegate: 0x10fc77048
[1654823475410] [79832:19231325] CHIP: [DMG] ReportDataMessage =
[1654823475410] [79832:19231325] CHIP: [DMG] {
[1654823475410] [79832:19231325] CHIP: [DMG] 	SubscriptionId = 0xd8bfe177,
[1654823475410] [79832:19231325] CHIP: [DMG] 	InteractionModelRevision = 1
[1654823475410] [79832:19231325] CHIP: [DMG] }

However, despite continuously receiving messages (type 0x5) from the server, darwin-framework-tool eventually times out:

[1654823481655] [79832:19231324] CHIP: [-] ../../commands/common/CHIPCommandBridge.mm:124: CHIP Error 0x00000032: Timeout at ../../commands/common/CHIPCommandBridge.mm:83
[1654823481655] [79832:19231324] CHIP: [TOO] Run command failure: ../../commands/common/CHIPCommandBridge.mm:124: CHIP Error 0x00000032: Timeout
[1654823481658] [79832:19231324] CHIP: [SPT] VerifyOrDie failure at ../../third_party/connectedhomeip/src/lib/support/Pool.h:317: Allocated() == 0
zsh: abort      ./darwin-framework-tool onoff subscribe-by-id 0 1 2 1 0x00000000000014EA 1

This behavior is not seen with darwin-framework-tool when running:

./darwin-framework-tool onoff subscribe on-off 10 20 1 0x00000000000014EA 1 

This command sits and waits indefinitely (as I would expect), assuming the server is sending messages.

Issue seems to be related to subscribe-by-id only

[bzbarsky-apple]

@krypton36

[bzbarsky-apple]

Ah, found it. The generated subscribe commands use mWait, but subscribe-by-id ignores it. Fix coming up.