TE8 Mac Chip Tool Darwin: Null values returned seem to cause some sort of crash

[dwgaul]

Tested the following command using chip-tool-darwin:

./chip-tool-darwin identify identify-query 0x000000000001B674 1

The server will send a response to this command, in my case this response returned a null value. But it looks like this handling causes some sort of crash?

Chip-tool-darwin response handling

Commands.h:27571: Success
[1646967711406] [57012:1134082] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:5503044 on exchange 49653i
[1646967711406] [57012:1134082] CHIP: [EM] Found matching exchange: 49653i, Delegate: 0x7feec2711b70
[1646967711406] [57012:1134082] CHIP: [EM] Rxd Ack; Removing MessageCounter:1224616 from Retrans Table on exchange 49653i
[1646967711406] [57012:1134082] CHIP: [EM] Removed CHIP MessageCounter:1224616 from RetransTable on exchange 49653i
[1646967711406] [57012:1134082] CHIP: [DMG] ICR moving to [ResponseRe]
[1646967711406] [57012:1134082] CHIP: [DMG] InvokeResponseMessage =
[1646967711406] [57012:1134082] CHIP: [DMG] {
[1646967711406] [57012:1134082] CHIP: [DMG] 	suppressResponse = false, 
[1646967711406] [57012:1134082] CHIP: [DMG] 	InvokeResponseIBs =
[1646967711406] [57012:1134082] CHIP: [DMG] 	[
[1646967711406] [57012:1134082] CHIP: [DMG] 		InvokeResponseIB =
[1646967711406] [57012:1134082] CHIP: [DMG] 		{
[1646967711406] [57012:1134082] CHIP: [DMG] 			CommandStatusIB =
[1646967711406] [57012:1134082] CHIP: [DMG] 			{
[1646967711406] [57012:1134082] CHIP: [DMG] 				CommandPathIB =
[1646967711406] [57012:1134082] CHIP: [DMG] 				{
[1646967711406] [57012:1134082] CHIP: [DMG] 					EndpointId = 0x1,
[1646967711406] [57012:1134082] CHIP: [DMG] 					ClusterId = 0x3,
[1646967711406] [57012:1134082] CHIP: [DMG] 					CommandId = 0x1,
[1646967711406] [57012:1134082] CHIP: [DMG] 				},
[1646967711406] [57012:1134082] CHIP: [DMG] 				
[1646967711406] [57012:1134082] CHIP: [DMG] 				StatusIB =
[1646967711406] [57012:1134082] CHIP: [DMG] 				{
[1646967711406] [57012:1134082] CHIP: [DMG] 					status = 0x0,
[1646967711406] [57012:1134082] CHIP: [DMG] 				},
[1646967711406] [57012:1134082] CHIP: [DMG] 				
[1646967711406] [57012:1134082] CHIP: [DMG] 			},
[1646967711406] [57012:1134082] CHIP: [DMG] 			
[1646967711406] [57012:1134082] CHIP: [DMG] 		},
[1646967711406] [57012:1134082] CHIP: [DMG] 		
[1646967711406] [57012:1134082] CHIP: [DMG] 	],
[1646967711406] [57012:1134082] CHIP: [DMG] 	
[1646967711406] [57012:1134082] CHIP: [DMG] 	InteractionModelRevision = 1
[1646967711406] [57012:1134082] CHIP: [DMG] },
[1646967711406] [57012:1134082] CHIP: [DMG] Received Command Response Status for Endpoint=1 Cluster=0x0000_0003 Command=0x0000_0001 Status=0x0
[1646967711407] [57012:1134082] CHIP: [DMG] ICR moving to [AwaitingDe]
[1646967711407] [57012:1134083] CHIP: [CTL] Response Time: PFvPvRKN4chip3app8Clusters8Identify8Commands21IdentifyQueryResponse13DecodableTypeEE+1833704769 0.006092 seconds
[1646967711407] [57012:1134082] CHIP: [EM] Sending Standalone Ack for MessageCounter:5503044 on exchange 49653i
[1646967711407] [57012:1134082] CHIP: [IN] Prepared secure message 0x700008257570 to 0x000000000001B674 (1)  of type 0x10 and protocolId (0, 0) on exchange 49653i with MessageCounter:1224617.
[1646967711407] [57012:1134082] CHIP: [IN] Sending encrypted msg 0x700008257570 with MessageCounter:1224617 to 0x000000000001B674 (1) at monotonic time: 531026401 msec
2022-03-10 19:01:51.407 chip-tool-darwin[57012:1134083] Values: (null)
[1646967711407] [57012:1134083] CHIP: [TOO] Error: ../../third_party/connectedhomeip/src/darwin/Framework/CHIP/CHIPError.mm:241: CHIP Error 0x000000AC: Internal error
[1646967711407] [57012:1134083] CHIP: [TOO] Shutting down controller

I do not see this when testing with the regular "chip-tool".

[bzbarsky-apple]

The server is sending an invalid response: a valid response to an IdentifyQuery is either a failure status or an IdentifyQueryResponse command, but the server sends a success status.

Regular chip-tool logs the response and does no validation.

chip-tool-darwin tries to actually parse the response as the intended response type, which fails, and it logs that failure.

What exactly is the problem, apart from the server being buggy and regular chip-tool not doing validation that arguably it should do?

@dwgaul @krypton36 @vivien-apple

[bzbarsky-apple]

Filed #17133 on the server behavior.

[dwgaul]

@bzbarsky-apple Good catch on the server aspect, I agree that should be fixed.

However, from a chip-tool-darwin perspective, are we actually crashing here? If so is there a more graceful way to handle this? Something along the lines of an "accessory out of compliance error" may help in future scenarios. Not sure how simple of an enhancement that would be for scenarios like this.

Ideally we'd never see this behavior with a well-behaved certified accessory, but from my experience even "certified" accessories surprise us from time to time. It might be helpful to have a specific log line for these sort of things.

[bzbarsky-apple]

However, from a chip-tool-darwin perspective, are we actually crashing here?

We are not. We are logging the error and treating it as a failed command invocation.

I agree the logging could be more informative.... I'll take a look into that.

[bzbarsky-apple]

Created #17194 to improve the logging some, by not losing track of the original error. Now it would say:

2022-04-07 22:36:21.090 chip-tool-darwin[79264:22276498] Values: (null)
[1649385381090] [79264:22276498] CHIP: [TOO] Error: ../../../examples/chip-tool-darwin/third_party/connectedhomeip/src/controller/TypedCommandCallback.h:90: CHIP Error 0x0000008E: Schema mismatch
...
[1649385381091] [79264:22276469] CHIP: [-] ../../../examples/chip-tool-darwin/third_party/connectedhomeip/src/controller/TypedCommandCallback.h:90: CHIP Error 0x0000008E: Schema mismatch at ../../../examples/chip-tool-darwin/commands/common/CHIPCommandBri
[1649385381091] [79264:22276469] CHIP: [TOO] Run command failure: ../../../examples/chip-tool-darwin/third_party/connectedhomeip/src/controller/TypedCommandCallback.h:90: CHIP Error 0x0000008E: Schema mismatch

Not sure whether that's enough clearer...

[bzbarsky-apple]

Not a crash issue, and the logging is clearer now.