Unable to pair via manual pin code on iOS chip tool - Error Domain=CHIPErrorDomain Code=9 "Transaction timed out." UserInfo={NSLocalizedDescription=Transaction timed out

[kean-apple]

Unable to pair M5 all clusters app via pin code with iOS chip tool

1. Launch iOS chiptool
2. Enter manual pin code to pair via iOS chip tool

In step 2: Seeing timeout failures with pin code: Error Domain=CHIPErrorDomain Code=9 "Transaction timed out." UserInfo={NSLocalizedDescription=Transaction timed out

Only activity seen on the M5 board logs when entering manual pin code - 3 retries:
I (650936) ROUTE_HOOK: Received RIO
I (650936) ROUTE_HOOK: prefix FDE4:B950:2EE9:: lifetime 1800

With the M5 in the same state, I was able to scan in the QR code and pair the M5 board successfully

Seen: 5 out of 5

Logs on chiptool:

CFPrefsSearchListSource<0x283f76200> (Domain: com.apple.keyboard.preferences, Container: (null))
2022-03-28 09:28:36.967776-0700  localhost CHIPTool[608]: (CHIP) [com.zigbee.chip:all] � [1648484916967] [608:19924] CHIP: [EM] Retransmitting MessageCounter:3977131908 on exchange 22553i Send Cnt 1
2022-03-28 09:28:36.968002-0700  localhost CHIPTool[608]: (CHIP) [com.zigbee.chip:all] � [1648484916967] [608:19924] CHIP: [IN] Sending unauthenticated msg 0x11a04e068 with MessageCounter:3977131908 to 0x0000000000000000 at monotonic time: 0000017FD15B9EE7 msec
2022-03-28 09:28:38.969502-0700  localhost CHIPTool[608]: (CHIP) [com.zigbee.chip:all] � [1648484918969] [608:19824] CHIP: [EM] Retransmitting MessageCounter:3977131908 on exchange 22553i Send Cnt 2
2022-03-28 09:28:38.969774-0700  localhost CHIPTool[608]: (CHIP) [com.zigbee.chip:all] � [1648484918969] [608:19824] CHIP: [IN] Sending unauthenticated msg 0x11a04e068 with MessageCounter:3977131908 to 0x0000000000000000 at monotonic time: 0000017FD15BA6B9 msec
2022-03-28 09:28:40.971276-0700  localhost CHIPTool[608]: (CHIP) [com.zigbee.chip:all] � [1648484920971] [608:19924] CHIP: [EM] Failed to Send CHIP MessageCounter:3977131908 on exchange 22553i sendCount: 3 max retries: 3
2022-03-28 09:29:14.603417-0700  localhost CHIPTool[608]: (UIKitCore) [com.apple.UIKit:MultitouchAnalytics] Analytics: Reporting foreground time: 60.001 sec
2022-03-28 09:29:14.603731-0700  localhost CHIPTool[608]: (CoreAnalytics) [com.apple.CoreAnalytics.event:send] com.apple.app-profile {"appForegroundActiveDuration":60.001276041666664,"bundleID":"com.chip.CHIPTool-Kean"}
2022-03-28 09:29:16.818913-0700  localhost CHIPTool[608]: (AssistantServices) [com.apple.siri:Client] _AFInternalPreferencesDidChangeCallback Internal Preferences Changed!
2022-03-28 09:29:16.819145-0700  localhost CHIPTool[608]: (AssistantServices) [com.apple.siri:Client] -[AFPreferences _internalPreferencesDidChangeExternally] 0x281f06af0 <AFInstanceContextHost: 0x281348980> (default)
2022-03-28 09:29:19.964836-0700  localhost CHIPTool[608]: (CHIP) [com.zigbee.chip:all] � [1648484959964] [608:19924] CHIP: [SC] PASESession timed out while waiting for a response from the peer. Expected message type was 33
2022-03-28 09:29:19.965100-0700  localhost CHIPTool[608]: (CHIP) DevicePairingDelegate status updated: 1
2022-03-28 09:29:19.965594-0700  localhost CHIPTool[608]: (CHIP) DevicePairingDelegate Pairing complete. Status ../../../../../../../../../../../connectedhomeip/src/protocols/secure_channel/PASESession.cpp:324: CHIP Error 0x00000032: Timeout
2022-03-28 09:29:19.965966-0700  localhost CHIPTool[608]: (CoreFoundation) [com.apple.CFBundle:resources] Resource lookup at CFBundle 0x119e05070 </private/var/containers/Bundle/Application/E0C9D276-266F-430A-BEB2-939ACC8A91CD/CHIPTool.app> (executable, loaded)
	Request       : Localizable type: strings
	Result        : None
2022-03-28 09:29:19.966124-0700  localhost CHIPTool[608]: (CoreFoundation) [com.apple.CFBundle:resources] Resource lookup at CFBundle 0x119e05070 </private/var/containers/Bundle/Application/E0C9D276-266F-430A-BEB2-939ACC8A91CD/CHIPTool.app> (executable, loaded)
	Request       : Localizable type: stringsdict
	Result        : None
2022-03-28 09:29:19.966215-0700  localhost CHIPTool[608]: (CoreFoundation) [com.apple.CFBundle:strings] Hit last resort and creating empty strings table
2022-03-28 09:29:19.966340-0700  localhost CHIPTool[608]: (CoreFoundation) [com.apple.defaults:User Defaults] found no value for key NSShowNonLocalizedStrings in CFPrefsSearchListSource<0x283f50c00> (Domain: com.chip.CHIPTool-Kean, Container: (null))
2022-03-28 09:29:19.966460-0700  localhost CHIPTool[608]: (CoreFoundation) [com.apple.CFBundle:strings] Bundle: CFBundle 0x119e05070 </private/var/containers/Bundle/Application/E0C9D276-266F-430A-BEB2-939ACC8A91CD/CHIPTool.app> (executable, loaded), key: Transaction timed out., value: , table: Localizable, localizationName: (null), result: Transaction timed out.
2022-03-28 09:29:19.966690-0700  localhost CHIPTool[608]: Got pairing error back Error Domain=CHIPErrorDomain Code=9 "Transaction timed out." UserInfo={NSLocalizedDescription=Transaction timed out.}

[kean-apple]

pairing-pincode-fails-chiptool-logs.txt

[kean-apple]

I was able to pair via manual code finally..I noticed the above behavior seems to happen after removing M5 board (which causes the M5 to reset) and then trying to pair via pin code with iOS chiptool

[bzbarsky-apple]

@kean-apple I'm not quite sure what "removing m5 board" means... What are the specific steps to reproduce this?

[kean-apple]

@bzbarsky-apple - by remove I meant unpair via iOS chiptool

steps:

1. Pair M5 (all clusters app) via QR and chip-tool - verify control works
2. Unpair M5 board via iOS chiptool unpair option -> note M5 board crashes/panic - M5 board crashes when adding 2nd fabric using iOS chiptool - assert failed: spinlock_acquire spinlock.h:123 ((result == SPINLOCK_FREE) == (lock->count == 0)) #16632
3. Manual reset M5 board again using the Setup->Reset to factory
4. Try to pair M5 board using iOS manual pin code -> it often fails

Note: seen this with QR code as well so its not specific to pin/QR code, the above are just the usual steps in the smoke test

[bzbarsky-apple]

@kean-apple Ah, OK. I am guessing what happens here is:

1. We commision the m5stack.
2. We remove the fabric, m5stack crashes. That causes it to reboot, and when it reboots it is no longer commissioned but is on the IP network, so it advertises itself as commissionable on the IP network via mDNS.
3. The m5 is factory reset. It stops being on the IP network, but the stale mDNS advertisement remains for the TTL (2 minutes).
4. We try to commission again, discover the mDNS advertisement before the BLE one, try to connect to the IP being advertised, that fails, and commissioning fails.

We really need to have our SetupCodePairer/AutoCommissioner combo fall back to other transports if the first one it tries can't be used to establish a PASE session....

@cecille @sagar-apple @msandstedt

[bzbarsky-apple]

As a workaround, we could have the factory reset on the m5stack advertise as not commissionable before it actually does the reset, I guess... But I'm not sure it's worth doing that.

[sagar-apple]

Yeah that would just be band-aid. Plus the spec doesn't really say what should happen here and so we should bake in something in our example apps.