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.49k stars 2.01k forks source link

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

Closed kean-apple closed 2 years ago

kean-apple commented 2 years ago

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 (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 (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 (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 (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 commented 2 years ago

pairing-pincode-fails-chiptool-logs.txt

kean-apple commented 2 years ago

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 commented 2 years ago

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

kean-apple commented 2 years ago

@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 - https://github.com/project-chip/connectedhomeip/issues/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 commented 2 years ago

@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 commented 2 years ago

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 commented 2 years ago

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.