connectedhomeip: [CERT-BLOCKER] Additional Logging not appearing in TH side logs even when using --trace_decode 1 on 3c8b8c SHA

Reproduction steps

1 -> Build accessory side apps (All Cluster app, TV app, etc) on SHA 3c8b8cf9680e0715d50a9866b125effd7530dbd5 on Raspi platform

Running the below command in terminal from connectedhomeip location will generate all-clusters-app (Replace the <path-to-repo> with the respective path to connectedhomeip location)

scripts/examples/gn_build_example.sh examples/all-clusters-app/linux/ out/all-clusters-app chip_config_network_layer_ble=false chip_code_pre_generated_directory='"/<path-to-repo>/connectedhomeip/zzz_pregenerated/“‘

2 -> After the all-cluster-app gets built in the above step, in the terminal, go to connectedhomeip/out/all-clusters-app location and run the below command,

./chip-all-clusters-app --trace_decode 1

This will start the all-clusters-app with --trace_decode flag set to 1. This flag is expected to help in providing additional logging in the TH logs which is needed for few test cases validation.

3 -> On the Commissioner/Controller side, pair to the accessory,

./darwin-framework-tool pairing code 1 34970112332

4 -> On the Commissioner/Controller side, run a command to read attribute

./darwin-framework-tool operationalcredentials read fabrics 1 0

The output for this step on this SHA is as follows,

[1688785473.647918][13562:13562] CHIP:EM: >>> [E:63707r S:47484 M:40592905] (S) Msg RX from 2:5B645D4389A1F100 [8168] --- Type 0001:02 (IM:ReadRequest)
[1688785473.647983][13562:13562] CHIP:EM: Handling via exchange: 63707r, Delegate: 0xaaaadb4a1778
[1688785473.648034][13562:13562] CHIP:im: Received Read request
[1688785473.648085][13562:13562] CHIP:DMG: ReadRequestMessage =
[1688785473.648114][13562:13562] CHIP:DMG: {
[1688785473.648137][13562:13562] CHIP:DMG: 	AttributePathIBs =
[1688785473.648165][13562:13562] CHIP:DMG: 	[
[1688785473.648191][13562:13562] CHIP:DMG: 		AttributePathIB =
[1688785473.648223][13562:13562] CHIP:DMG: 		{
[1688785473.648255][13562:13562] CHIP:DMG: 			Endpoint = 0x0,
[1688785473.648294][13562:13562] CHIP:DMG: 			Cluster = 0x3e,
[1688785473.648330][13562:13562] CHIP:DMG: 			Attribute = 0x0000_0001,
[1688785473.648363][13562:13562] CHIP:DMG: 		}
[1688785473.648438][13562:13562] CHIP:DMG: 			
[1688785473.648466][13562:13562] CHIP:DMG: 	],
[1688785473.648498][13562:13562] CHIP:DMG: 		
[1688785473.648528][13562:13562] CHIP:DMG: 	isFabricFiltered = false,
[1688785473.648556][13562:13562] CHIP:DMG: 	InteractionModelRevision = 1
[1688785473.648582][13562:13562] CHIP:DMG: },
[1688785473.648703][13562:13562] CHIP:DMG: IM RH moving to [GeneratingReports]
[1688785473.648810][13562:13562] CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[1688785473.648844][13562:13562] CHIP:DMG: <RE:Run> Cluster 3e, Attribute 1 is dirty
[1688785473.648868][13562:13562] CHIP:DMG: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[1688785473.648900][13562:13562] CHIP:DMG: AccessControl: checking f=2 a=c s=0x5B645D4389A1F100 t= c=0x0000_003E e=0 p=v
[1688785473.648936][13562:13562] CHIP:DMG: AccessControl: allowed
[1688785473.649027][13562:13562] CHIP:DMG: <RE> Sending report (payload has 294 bytes)...
[1688785473.649479][13562:13562] CHIP:EM: <<< [E:63707r S:47484 M:94621593 (Ack:40592905)] (S) Msg TX to 2:5B645D4389A1F100 [8168] --- Type 0001:05 (IM:ReportData)
[1688785473.649530][13562:13562] CHIP:in: (S) Sending msg 94621593 on secure session with LSID: 47484

5 -> Observe that the TH side logs doesn’t show additional logging even when we running the app with --trace_decode 1

6 -> Here the log from an old SHA that was giving right output with trace_decode flag

Received message of type 0x2 with protocolId (0, 1) and MessageCounter:163933729 on exchange 21220r
[1663001821.612573][27616:27616] CHIP:EM: Handling via exchange: 21220r, Delegate: 0xaaaacbdde008
[1663001821.612604][27616:27616] CHIP:im: Received Read request
[1663001821.612670][27616:27616] CHIP:DMG: ReadRequestMessage =
[1663001821.612693][27616:27616] CHIP:DMG: {
[1663001821.612711][27616:27616] CHIP:DMG: 	AttributePathIBs =
[1663001821.612730][27616:27616] CHIP:DMG: 	[
[1663001821.612747][27616:27616] CHIP:DMG: 		AttributePathIB =
[1663001821.612767][27616:27616] CHIP:DMG: 		{
[1663001821.612787][27616:27616] CHIP:DMG: 			Endpoint = 0x0,
[1663001821.612807][27616:27616] CHIP:DMG: 			Cluster = 0x3e,
[1663001821.612826][27616:27616] CHIP:DMG: 			Attribute = 0x0000_0001,
[1663001821.612843][27616:27616] CHIP:DMG: 		}
[1663001821.612863][27616:27616] CHIP:DMG: 			
[1663001821.612880][27616:27616] CHIP:DMG: 	],
[1663001821.612901][27616:27616] CHIP:DMG: 		
[1663001821.612921][27616:27616] CHIP:DMG: 	isFabricFiltered = false,
[1663001821.612939][27616:27616] CHIP:DMG: 	InteractionModelRevision = 1
[1663001821.612956][27616:27616] CHIP:DMG: },
[1663001821.613021][27616:27616] CHIP:DMG: IM RH moving to [GeneratingReports]
[1663001821.613093][27616:27616] CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[1663001821.613117][27616:27616] CHIP:DMG: <RE:Run> Cluster 3e, Attribute 1 is dirty
[1663001821.613135][27616:27616] CHIP:DMG: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[1663001821.613157][27616:27616] CHIP:DMG: AccessControl: checking f=1 a=c s=0x344FCA4C025A81CF t= c=0x0000_003E e=0 p=v
[1663001821.613185][27616:27616] CHIP:DMG: AccessControl: allowed
[1663001821.613255][27616:27616] CHIP:DMG: <RE> Sending report (payload has 148 bytes)...
[1663001821.613286][27616:27616] CHIP:EM: Piggybacking Ack for MessageCounter:163933729 on exchange: 21220r
[1663001821.613466][27616:27616] CHIP:in: Prepared secure message 0xaaab08404408 to 0x344FCA4C025A81CF (1)  of type 0x5 and protocolId (0, 1) on exchange 21220r with MessageCounter:9915013.
[1663001821.613499][27616:27616] CHIP:in: Sending encrypted msg 0xaaab08404408 with MessageCounter:9915013 to 0x344FCA4C025A81CF (1) at monotonic time: 00000000027C978A msec
[1663001821.613729][27616:27616] CHIP:DMG: >> to UDP:[fe80::14b7:ddf8:eac8:2edb%eth0]:5541 | 9915013 | [Interaction Model  (1) / Report Data (0x05) / Session = 7505 / Exchange = 21220]
[1663001821.613760][27616:27616] CHIP:DMG: Header Flags =
[1663001821.613779][27616:27616] CHIP:DMG: {
[1663001821.613806][27616:27616] CHIP:DMG:     Exchange (0x06) =
[1663001821.613824][27616:27616] CHIP:DMG:     {
[1663001821.613843][27616:27616] CHIP:DMG:         AckMsg = 163933729
[1663001821.613861][27616:27616] CHIP:DMG:         NeedsAck = true
[1663001821.613878][27616:27616] CHIP:DMG:     }
[1663001821.613902][27616:27616] CHIP:DMG: }
[1663001821.613920][27616:27616] CHIP:DMG:
[1663001821.613942][27616:27616] CHIP:DMG: Encrypted Payload (182 bytes) =
[1663001821.613960][27616:27616] CHIP:DMG: {
[1663001821.613977][27616:27616] CHIP:DMG:     data = 00511d00854a97009a3dac7fb40c70fa12511096d026c98cce70497bc9fff4811b3d85c7eb7452d9069be895a0c7db9f8afa11e0b73dd295197c920c2ec45399d8a3fa06a20ddeff35b478ed0e5e8db7fccb4c2d62b325c417bfdb5a22e49cb1df900a93124a763cc5302e48ec484335650fbe9c27fe3f1cb66091d2005c4439e16a2fb4e8ccd2222bcf79f62515940e4cd0b4d0f1a7de661b745d3c1365fdd4afedc45881f02dd67c222a2b5913d489d3736ea70e04
[1663001821.614021][27616:27616] CHIP:DMG:     buffer_ptr = 187651555499632
[1663001821.614039][27616:27616] CHIP:DMG: }
[1663001821.614055][27616:27616] CHIP:DMG:
[1663001821.614138][27616:27616] CHIP:DMG: ReportDataMessage =
[1663001821.614161][27616:27616] CHIP:DMG: {
[1663001821.614178][27616:27616] CHIP:DMG: 	AttributeReportIBs =
[1663001821.614202][27616:27616] CHIP:DMG: 	[
[1663001821.614219][27616:27616] CHIP:DMG: 		AttributeReportIB =
[1663001821.614243][27616:27616] CHIP:DMG: 		{
[1663001821.614260][27616:27616] CHIP:DMG: 			AttributeDataIB =
[1663001821.614280][27616:27616] CHIP:DMG: 			{
[1663001821.614300][27616:27616] CHIP:DMG: 				DataVersion = 0xe0e78560,
[1663001821.614318][27616:27616] CHIP:DMG: 				AttributePathIB =
[1663001821.614336][27616:27616] CHIP:DMG: 				{
[1663001821.614356][27616:27616] CHIP:DMG: 					Endpoint = 0x0,
[1663001821.614375][27616:27616] CHIP:DMG: 					Cluster = 0x3e,
[1663001821.614395][27616:27616] CHIP:DMG: 					Attribute = 0x0000_0001,
[1663001821.614412][27616:27616] CHIP:DMG: 				}
[1663001821.614432][27616:27616] CHIP:DMG: 					
[1663001821.614451][27616:27616] CHIP:DMG: 				Data = [
[1663001821.614469][27616:27616] CHIP:DMG: 						
[1663001821.614488][27616:27616] CHIP:DMG: 				],
[1663001821.614506][27616:27616] CHIP:DMG: 			},
[1663001821.614527][27616:27616] CHIP:DMG: 			
[1663001821.614544][27616:27616] CHIP:DMG: 		},
[1663001821.614573][27616:27616] CHIP:DMG: 		
[1663001821.614590][27616:27616] CHIP:DMG: 		AttributeReportIB =
[1663001821.614616][27616:27616] CHIP:DMG: 		{
[1663001821.614634][27616:27616] CHIP:DMG: 			AttributeDataIB =
[1663001821.614652][27616:27616] CHIP:DMG: 			{
[1663001821.614672][27616:27616] CHIP:DMG: 				DataVersion = 0xe0e78560,
[1663001821.614689][27616:27616] CHIP:DMG: 				AttributePathIB =
[1663001821.614708][27616:27616] CHIP:DMG: 				{
[1663001821.614727][27616:27616] CHIP:DMG: 					Endpoint = 0x0,
[1663001821.614746][27616:27616] CHIP:DMG: 					Cluster = 0x3e,
[1663001821.614766][27616:27616] CHIP:DMG: 					Attribute = 0x0000_0001,
[1663001821.614785][27616:27616] CHIP:DMG: 					ListIndex = Null,
[1663001821.614802][27616:27616] CHIP:DMG: 				}
[1663001821.614822][27616:27616] CHIP:DMG: 					
[1663001821.614840][27616:27616] CHIP:DMG: 				Data =
[1663001821.614858][27616:27616] CHIP:DMG: 				{
[1663001821.614879][27616:27616] CHIP:DMG: 					0x1 = [
[1663001821.614913][27616:27616] CHIP:DMG: 							0x4, 0xe5, 0x99, 0x88, 0xbd, 0x7b, 0xf4, 0xb4, 0xd1, 0x43, 0xab, 0xd8, 0x7, 0x71, 0x42, 0x91, 0x6b, 0x61, 0x5b, 0x9b, 0x2c, 0xc7, 0x3e, 0x7f, 0xb6, 0x8a, 0x3b, 0xb9, 0xaf, 0x1, 0xac, 0x7d, 0x7e, 0xb4, 0xa7, 0xf8, 0xa4, 0x28, 0xbc, 0x3b, 0x58, 0x19, 0x4c, 0x2e, 0x91, 0x37, 0xa1, 0x5b, 0x6a, 0x9b, 0x9f, 0x8d, 0x9c, 0x48, 0x18, 0x36, 0x21, 0xb8, 0x17, 0xc3, 0x28, 0xc3, 0x6d, 0x1e, 0x17,
[1663001821.614932][27616:27616] CHIP:DMG: 					] (65 bytes)
[1663001821.614952][27616:27616] CHIP:DMG: 					0x2 = 65521,
[1663001821.614972][27616:27616] CHIP:DMG: 					0x3 = 1,
[1663001821.614991][27616:27616] CHIP:DMG: 					0x4 = 1,
[1663001821.615145][27616:27616] CHIP:DMG: 					0x5 = "" (0 chars),
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! Item of interest below !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
[1663001821.615171][27616:27616] CHIP:DMG: 					0xfe = 1,
[1663001821.615189][27616:27616] CHIP:DMG: 				},
[1663001821.615207][27616:27616] CHIP:DMG: 			},
[1663001821.615231][27616:27616] CHIP:DMG: 			
[1663001821.615248][27616:27616] CHIP:DMG: 		},
[1663001821.615272][27616:27616] CHIP:DMG: 		
[1663001821.615290][27616:27616] CHIP:DMG: 	],
[1663001821.615318][27616:27616] CHIP:DMG: 	
[1663001821.615337][27616:27616] CHIP:DMG: 	SuppressResponse = true,
[1663001821.615356][27616:27616] CHIP:DMG: 	InteractionModelRevision = 1
[1663001821.615373][27616:27616] CHIP:DMG: }
[1663001821.615391][27616:27616] CHIP:DMG:
[1663001821.615564][27616:27616] CHIP:DMG: <RE> OnReportConfirm: NumReports = 0
[1663001821.615589][27616:27616] CHIP:DMG: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[1663001821.615635][27616:27616] CHIP:DMG: IM RH moving to [AwaitingDestruction]

7 -> In the above case, we check for “0xfe = 1” (Shown in blue in the step 6 log - used link to highlight it), is also the one ATLs will check to conform the read request showed one fabric. This appears only when --trace_decode flag is set to 1 when we start the all-clusters-app.

Few test cases have usage of --trace_decode 1 as prerequisite and few test steps in the test cases use the additional logging to verify the outcome. So having additional logging while using this flag is essential for evaluating the test cases.

Bug prevalence

All the time

GitHub hash of the SDK that was being used

3c8b8cf9680e0715d50a9866b125effd7530dbd5

Platform

darwin, raspi

Platform Version(s)

No response

Anything else?

No response