Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

PASESession timed out while waiting for a response from the peer. Expected message type was 33 #216

Open
law-ko opened this issue Jul 7, 2024 · 2 comments
Open

PASESession timed out while waiting for a response from the peer. Expected message type was 33 #216

law-ko opened this issue Jul 7, 2024 · 2 comments

Comments

@law-ko
Copy link

law-ko commented Jul 7, 2024 •
edited
Loading

We are unable to pair Matter devices due to PASESession timeout. We have also seen this issue on connectedhomeip repo as well. Is the Maven library not updated? As this seems to be fixed by CHIP sometime earlier.

onCreate()
2024-07-08 00:26:49.821 23420-23420 GHSAFM-3p-...ingService com.google.homesampleapp.default     D  onBind(): intent [Intent { pkg=com.google.homesampleapp.default cmp=com.google.homesampleapp.default/com.google.homesampleapp.commissioning.AppCommissioningService }]
2024-07-08 00:26:49.833 23420-23420 ViewRootIm...nActivity] com.google.homesampleapp.default     I  handleWindowFocusChanged: 0 0 call from android.view.ViewRootImpl.-$$Nest$mhandleWindowFocusChanged:0
2024-07-08 00:26:49.834 23420-23420 ImeFocusController      com.google.homesampleapp.default     I  onPreWindowFocus: skipped, hasWindowFocus=false mHasImeFocus=true
2024-07-08 00:26:49.834 23420-23420 ImeFocusController      com.google.homesampleapp.default     I  onPostWindowFocus: skipped, hasWindowFocus=false mHasImeFocus=true
2024-07-08 00:26:49.937 23420-23420 InputTransport          com.google.homesampleapp.default     D  Input channel destroyed: 'ClientS', fd=129
2024-07-08 00:26:50.309 23420-23420 ViewRootIm...nActivity] com.google.homesampleapp.default     I  handleAppVisibility mAppVisible = true visible = false
2024-07-08 00:26:50.317 23420-23420 ViewRootIm...nActivity] com.google.homesampleapp.default     I  destroyHardwareResources: Callers=android.view.ViewRootImpl.performTraversals:3937 android.view.ViewRootImpl.doTraversal:3291 android.view.ViewRootImpl$TraversalRunnable.run:11329 android.view.Choreographer$CallbackRecord.run:1689 android.view.Choreographer$CallbackRecord.run:1698 android.view.Choreographer.doCallbacks:1153 android.view.Choreographer.doFrame:1079 android.view.Choreographer$FrameDisplayEventReceiver.run:1646 android.os.Handler.handleCallback:958 android.os.Handler.dispatchMessage:99 
2024-07-08 00:26:50.318 23420-23471 OpenGLRenderer          com.google.homesampleapp.default     D  CacheManager::trimMemory(20)
2024-07-08 00:26:50.324 23420-23420 ViewRootIm...nActivity] com.google.homesampleapp.default     I  Relayout returned: old=(0,0,1080,2340) new=(0,0,1080,2340) relayoutAsync=false req=(1080,2340)8 dur=4 res=0x402 s={false 0x0} ch=true seqId=0
2024-07-08 00:26:50.325 23420-23420 ViewRootIm...nActivity] com.google.homesampleapp.default     I  stopped(true) old = false
2024-07-08 00:26:50.325 23420-23420 ViewRootIm...nActivity] com.google.homesampleapp.default     D  WindowStopped on com.google.homesampleapp.default/com.google.homesampleapp.MainActivity set to true
2024-07-08 00:26:50.325 23420-23471 OpenGLRenderer          com.google.homesampleapp.default     D  CacheManager::trimMemory(20)
2024-07-08 00:26:55.730 23420-23420 ViewRootIm...nActivity] com.google.homesampleapp.default     I  onDisplayChanged oldDisplayState=2 newDisplayState=2
2024-07-08 00:26:55.837 23420-23420 GHSAFM-3p-...ingService com.google.homesampleapp.default     D  onDestroy()
2024-07-08 00:26:55.847 23420-23420 Choreographer           com.google.homesampleapp.default     D  CoreRune.SYSPERF_ACTIVE_APP_BBA_ENABLE : stop animation in background states
2024-07-08 00:26:55.856 23420-23471 OpenGLRenderer          com.google.homesampleapp.default     D  CacheManager::trimMemory(20)
2024-07-08 00:26:55.927 23420-23420 GHSAFM-3p-...ingService com.google.homesampleapp.default     D  onCreate()
2024-07-08 00:26:55.927 23420-23420 GHSAFM-3p-...ingService com.google.homesampleapp.default     D  onBind(): intent [Intent { pkg=com.google.homesampleapp.default cmp=com.google.homesampleapp.default/com.google.homesampleapp.commissioning.AppCommissioningService }]
2024-07-08 00:26:58.912 23420-23420 ViewRootIm...nActivity] com.google.homesampleapp.default     I  onDisplayChanged oldDisplayState=2 newDisplayState=2
2024-07-08 00:26:58.960 23420-23420 GHSAFM-3p-...ingService com.google.homesampleapp.default     D  onDestroy()
2024-07-08 00:26:59.005 23420-23420 GHSAFM-3p-...ingService com.google.homesampleapp.default     D  onCreate()
2024-07-08 00:26:59.006 23420-23420 GHSAFM-3p-...ingService com.google.homesampleapp.default     D  onBind(): intent [Intent { pkg=com.google.homesampleapp.default cmp=com.google.homesampleapp.default/com.google.homesampleapp.commissioning.AppCommissioningService }]
2024-07-08 00:27:33.526 23420-27697 GHSAFM-3p-...ingService com.google.homesampleapp.default     D  *** onCommissioningRequested ***:
                                                                                                    	deviceDescriptor: deviceType [0] vendorId [xxxx] productId [xxxx]
                                                                                                    	networkLocation: IP address toString() [fe80::4e75:25ff:fee5:b1d8/fe80::4e75:25ff:fee5:b1d8%wlan0] IP address hostAddress [fe80::4e75:25ff:fee5:b1d8%wlan0] port [5540]
                                                                                                    	passCode [16501152]
2024-07-08 00:27:33.531 23420-23420 GHSAFM-3p-...gRequested com.google.homesampleapp.default     D  Commissioning: App fabric -> ChipClient.establishPaseConnection(): deviceId [3030750831052689526]
2024-07-08 00:27:33.533 23420-23420 ChipDeviceController    com.google.homesampleapp.default     D  Establishing PASE connection with ID: 3030750831052689526
2024-07-08 00:27:33.533 23420-23420 IN                      com.google.homesampleapp.default     D  SecureSession[0xb400007c362bb6a8]: Allocated Type:1 LSID:47241
2024-07-08 00:27:33.533 23420-23420 SC                      com.google.homesampleapp.default     D  Assigned local session key ID 47241
2024-07-08 00:27:33.534 23420-23420 EM                      com.google.homesampleapp.default     D  <<< [E:51844i S:0 M:13009032] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
2024-07-08 00:27:33.534 23420-23420 IN                      com.google.homesampleapp.default     D  (U) Sending msg 13009032 to IP address 'UDP:[fe80::4e75:25ff:fee5:b1d8]:5540'
2024-07-08 00:27:33.534 23420-23420 SC                      com.google.homesampleapp.default     D  Sent PBKDF param request
2024-07-08 00:27:33.915 23420-23502 EM                      com.google.homesampleapp.default     D  Retransmitting MessageCounter:13009032 on exchange 51844i Send Cnt 1
2024-07-08 00:27:33.915 23420-23502 IN                      com.google.homesampleapp.default     D  (U) Sending msg 13009032 to IP address 'UDP:[fe80::4e75:25ff:fee5:b1d8]:5540'
2024-07-08 00:27:34.247 23420-23502 EM                      com.google.homesampleapp.default     D  Retransmitting MessageCounter:13009032 on exchange 51844i Send Cnt 2
2024-07-08 00:27:34.247 23420-23502 IN                      com.google.homesampleapp.default     D  (U) Sending msg 13009032 to IP address 'UDP:[fe80::4e75:25ff:fee5:b1d8]:5540'
2024-07-08 00:27:34.781 23420-23502 EM                      com.google.homesampleapp.default     D  Retransmitting MessageCounter:13009032 on exchange 51844i Send Cnt 3
2024-07-08 00:27:34.781 23420-23502 IN                      com.google.homesampleapp.default     D  (U) Sending msg 13009032 to IP address 'UDP:[fe80::4e75:25ff:fee5:b1d8]:5540'
2024-07-08 00:27:35.653 23420-23502 EM                      com.google.homesampleapp.default     D  Retransmitting MessageCounter:13009032 on exchange 51844i Send Cnt 4
2024-07-08 00:27:35.653 23420-23502 IN                      com.google.homesampleapp.default     D  (U) Sending msg 13009032 to IP address 'UDP:[fe80::4e75:25ff:fee5:b1d8]:5540'
2024-07-08 00:27:37.076 23420-23502 EM                      com.google.homesampleapp.default     E  Failed to Send CHIP MessageCounter:13009032 on exchange 51844i sendCount: 4 max retries: 4
2024-07-08 00:27:39.758 23420-23502 SC                      com.google.homesampleapp.default     E  PASESession timed out while waiting for a response from the peer. Expected message type was 33
2024-07-08 00:27:39.759 23420-23502 IN                      com.google.homesampleapp.default     D  SecureSession[0xb400007c362bb6a8]: Released - Type:1 LSID:47241
2024-07-08 00:27:39.762 23420-23502 GHSAFM-3p-...onListener com.google.homesampleapp.default     D  BaseCompletionListener onStatusUpdate(): status [1]
2024-07-08 00:27:39.763 23420-23502 GHSAFM-3p-...onListener com.google.homesampleapp.default     D  BaseCompletionListener onPairingComplete(): code [50]
2024-07-08 00:27:39.771 23420-23420 GHSAFM-3p-...gRequested com.google.homesampleapp.default     E  onCommissioningRequested() failed
                                                                                                    java.lang.IllegalStateException: Pairing failed with error code [50]
                                                                                                    	at com.google.homesampleapp.chip.ChipClient$awaitEstablishPaseConnection$2$1.onPairingComplete(ChipClient.kt:142)
                                                                                                    	at chip.devicecontroller.ChipDeviceController.onPairingComplete(ChipDeviceController.java:329)
2024-07-08 00:27:39.782 23420-23420 GHSAFM-3p-...gRequested com.google.homesampleapp.default     D  Commissioning: commissioningServiceDelegate.sendCommissioningError() succeeded
2024-07-08 00:35:49.529 23420-23471 OpenGLRenderer          com.google.homesampleapp.default     D  CacheManager::trimMemory(15)
@law-ko
Copy link
Author

law-ko commented Jul 7, 2024 •
edited
Loading

It appears that the first commissioning session does not send the commission complete signal to the device, which causes the device's BLE still on and which will affect the Wi-Fi transport due to low RAM. Is there any way to send the commissioning complete signal to the device prior to connecting to 3p fabric?

I (20549) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (20549) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (20559) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (20559) chip[DL]: WiFi station interface connected
I (20579) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 1 **********
I (20579) chip[EM]: <<< [E:64033r S:12541 M:125230816] (S) Msg TX to 1:FFFFFFFB00000000 [71F6] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse)
I (20589) NimBLE: GATT procedure initiated: indicate; 
I (20609) NimBLE: att_handle=18

I (20609) chip[ZCL]: WiFiDiagnosticsDelegate: OnConnectionStatusChanged
I (20609) chip[DL]: Done driving station state, nothing else to do...
I (20619) chip[DIS]: Advertise operational node 4C9D9B08B23E71F6-FA2A8B017C2EE842
I (20619) wifi:<ba-add>idx:0 (ifx:0, 3e:98:b5:96:60:22), tid:0, ssn:0, winSize:64
I (20629) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 4C9D9B08B23E71F6-FA2A8B017C2EE842.
I (20649) chip[DIS]: mDNS service published: _matter._tcp
I (20649) chip[SVR]: Operational advertising enabled
I (20659) chip[DL]: Updating advertising data
I (20689) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (21549) esp_netif_handlers: sta ip: 192.168.2.186, mask: 255.255.255.0, gw: 192.168.2.1
I (21549) chip[DL]: IP_EVENT_STA_GOT_IP
I (21549) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.2.186/255.255.255.0 gateway 192.168.2.1
I (21559) chip[DL]: IPv4 Internet connectivity ESTABLISHED
I (21579) app_main: Interface IP Address changed
I (21579) chip[DIS]: Updating services using commissioning mode 0
I (21589) chip[DIS]: CHIP minimal mDNS started advertising.
I (21599) chip[DIS]: Advertise operational node 4C9D9B08B23E71F6-FA2A8B017C2EE842
I (21599) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 4C9D9B08B23E71F6-FA2A8B017C2EE842.
I (21619) chip[DIS]: mDNS service published: _matter._tcp
I (21739) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0
I (21739) chip[DL]: CHIPoBLE unsubscribe received
I (21739) chip[BLE]: Releasing end point's BLE connection back to application.
I (21759) chip[DL]: BLE GAP connection terminated (con 0 reason 0x213)
I (21769) esp_matter_core: BLE Disconnected
I (21829) chip[DL]: IP_EVENT_GOT_IP6
I (21829) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:4e75:25ff:fee5:b1d8
I (21839) app_main: Interface IP Address changed
I (21849) chip[DIS]: Updating services using commissioning mode 0
I (21849) chip[DIS]: CHIP minimal mDNS started advertising.
I (21849) ROUTE_HOOK: Received RIO
I (21869) ROUTE_HOOK: prefix FDC3:A10B:1B01:: lifetime 1800
I (21879) chip[DIS]: Advertise operational node 4C9D9B08B23E71F6-FA2A8B017C2EE842
I (21879) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 4C9D9B08B23E71F6-FA2A8B017C2EE842.
I (21899) chip[DIS]: mDNS service published: _matter._tcp
I (21899) chip[SVR]: Server initialization complete
I (21899) chip[DIS]: Updating services using commissioning mode 0
I (21919) chip[DIS]: CHIP minimal mDNS started advertising.
I (21929) chip[DIS]: Advertise operational node 4C9D9B08B23E71F6-FA2A8B017C2EE842
I (21929) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 4C9D9B08B23E71F6-FA2A8B017C2EE842.
I (21949) chip[DIS]: mDNS service published: _matter._tcp
I (21959) chip[IM]: No subscriptions to resume
I (23829) chip[DL]: IP_EVENT_GOT_IP6
I (23829) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fdd5:b45e:4ac7:0049:4e75:25ff:fee5:b1d8
I (23839) ROUTE_HOOK: Hook already installed on netif, skip...
I (23839) app_main: Interface IP Address changed
I (23839) chip[DIS]: Updating services using commissioning mode 0
I (23859) chip[DIS]: CHIP minimal mDNS started advertising.
I (23869) chip[DIS]: Advertise operational node 4C9D9B08B23E71F6-FA2A8B017C2EE842
I (23869) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 4C9D9B08B23E71F6-FA2A8B017C2EE842.
I (23889) chip[DIS]: mDNS service published: _matter._tcp
I (30859) wifi:bcn_timeout,ap_probe_send_start
I (30869) ROUTE_HOOK: Received RIO
I (30879) ROUTE_HOOK: prefix FDC3:A10B:1B01:: lifetime 1800
I (30879) chip[EM]: >>> [E:64034r S:0 M:14629439] (U) Msg RX from 0:CA3C37F8549FEA42 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I (30899) chip[IN]: CASE Server received Sigma1 message . Starting handshake. EC 0x3ffc7a28
I (30899) ROUTE_HOOK: Received RIO
I (30899) ROUTE_HOOK: prefix FDC3:A10B:1B01:: lifetime 1800
I (30899) chip[EM]: <<< [E:64034r S:0 M:170399803 (Ack:14629439)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (30929) chip[SC]: Received Sigma1 msg
I (30939) chip[SC]: CASE matched destination ID: fabricIndex 1, NodeID 0xFA2A8B017C2EE842
I (31689) chip[EM]: <<< [E:64034r S:0 M:170399804 (Ack:14629439)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I (31699) chip[SC]: Sent Sigma2 msg
E (31699) chip[DL]: Long dispatch time: 823 ms, for event type 3
I (31709) chip[EM]: >>> [E:64034r S:0 M:14629439] (U) Msg RX from 0:CA3C37F8549FEA42 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I (31719) chip[EM]: <<< [E:64034r S:0 M:170399805 (Ack:14629439)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (31749) chip[EM]: >>> [E:64034r S:0 M:14629439] (U) Msg RX from 0:CA3C37F8549FEA42 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I (31749) chip[EM]: <<< [E:64034r S:0 M:170399806 (Ack:14629439)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0000:10 (SecureChannel:StandaloneAck)
E (31779) chip[EM]: Non-crit err 3000001 sending solitary ack for MessageCounter:14629439 on exchange 64034r
I (31779) chip[EM]: >>> [E:64034r S:0 M:14629439] (U) Msg RX from 0:CA3C37F8549FEA42 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I (31789) chip[EM]: <<< [E:64034r S:0 M:170399807 (Ack:14629439)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0000:10 (SecureChannel:StandaloneAck)
E (31819) chip[EM]: Non-crit err 3000001 sending solitary ack for MessageCounter:14629439 on exchange 64034r
I (31819) chip[EM]: >>> [E:64034r S:0 M:14629439] (U) Msg RX from 0:CA3C37F8549FEA42 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I (31839) chip[EM]: <<< [E:64034r S:0 M:170399808 (Ack:14629439)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0000:10 (SecureChannel:StandaloneAck)
E (31859) chip[EM]: Non-crit err 3000001 sending solitary ack for MessageCounter:14629439 on exchange 64034r
I (32109) chip[EM]: Retransmitting MessageCounter:170399804 on exchange 64034r Send Cnt 1
I (32209) chip[EM]: >>> [E:64034r S:0 M:14629440 (Ack:170399804)] (U) Msg RX from 0:CA3C37F8549FEA42 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I (32229) chip[EM]: <<< [E:64034r S:0 M:170399809 (Ack:14629440)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (32239) chip[SC]: Received Sigma3 msg
E (32249) chip[SC]: The device does not support GetClock_RealTimeMS() API: 6c.  Falling back to Last Known Good UTC Time
E (33369) chip[DL]: Long dispatch time: 1117 ms, for event type 2
I (33389) chip[EM]: <<< [E:64034r S:0 M:170399810 (Ack:14629440)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0000:40 (SecureChannel:StatusReport)
I (33409) chip[SC]: SecureSession[0x3ffc62d0, LSID:12542]: State change 'kEstablishing' --> 'kActive'
I (33409) chip[IN]: CASE Session established to peer: <1EFFFECAF8E35117, 1>
I (33539) chip[EM]: >>> [E:64034r S:0 M:14629441 (Ack:170399810)] (U) Msg RX from 0:CA3C37F8549FEA42 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (33559) chip[EM]: >>> [E:64035r S:12542 M:210317699] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:02 (IM:ReadRequest)
I (33569) chip[EM]: <<< [E:64035r S:12542 M:244292836 (Ack:210317699)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:05 (IM:ReportData)
I (33749) chip[EM]: >>> [E:64035r S:12542 M:210317700 (Ack:244292836)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (33759) chip[EM]: >>> [E:64036r S:12542 M:210317701] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:02 (IM:ReadRequest)
I (33769) chip[EM]: <<< [E:64036r S:12542 M:244292837 (Ack:210317701)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:05 (IM:ReportData)
I (33849) chip[EM]: >>> [E:64036r S:12542 M:210317702 (Ack:244292837)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (33869) chip[EM]: >>> [E:64037r S:12542 M:210317703] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:08 (IM:InvokeCommandRequest)
I (33869) esp_matter_command: Received command 0x00000004 for endpoint 0x0000's cluster 0x00000030
I (33879) chip[FS]: GeneralCommissioning: Received CommissioningComplete
I (33899) chip[FP]: Metadata for Fabric 0x1 persisted to storage.
I (33929) chip[TS]: Committing Last Known Good Time to storage: 2024-06-30T00:00:00
I (33939) chip[ZCL]: OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x4C9D9B08B23E71F6, FabricId 68DF7FB070EE0A13, NodeId FA2A8B017C2EE842, VendorId 0x6006
I (33959) chip[FS]: GeneralCommissioning: Successfully commited pending fabric data
I (33959) chip[FS]: Fail-safe cleanly disarmed
I (33959) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 0 **********
I (33979) chip[EM]: <<< [E:64037r S:12542 M:244292838 (Ack:210317703)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:09 (IM:InvokeCommandResponse)
I (33989) app_main: Fabric is committed
I (33999) chip[SVR]: Commissioning completed successfully
I (34009) chip[DIS]: Updating services using commissioning mode 0
I (34009) chip[DIS]: CHIP minimal mDNS started advertising.
I (34029) chip[DIS]: Advertise operational node 4C9D9B08B23E71F6-FA2A8B017C2EE842
I (34029) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 4C9D9B08B23E71F6-FA2A8B017C2EE842.
I (34049) chip[DIS]: mDNS service published: _matter._tcp
I (34049) chip[SC]: SecureSession[0x3ffc6210, LSID:12541]: State change 'kActive' --> 'kPendingEviction'
I (34069) app_main: Commissioning complete
I (34069) esp_matter_core: Commissioning Complete
I (34069) app_main: Commissioning window closed
I (34079) NimBLE: GAP procedure initiated: stop advertising.

I (34089) chip[DL]: BLE deinit successful and memory reclaimed
I (34089) app_main: BLE deinitialized and memory reclaimed
I (34119) chip[EM]: >>> [E:64037r S:12542 M:210317704 (Ack:244292838)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (34149) chip[EM]: >>> [E:64038r S:12542 M:210317705] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:02 (IM:ReadRequest)
I (34159) chip[EM]: <<< [E:64038r S:12542 M:244292839 (Ack:210317705)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:05 (IM:ReportData)
I (34189) chip[EM]: >>> [E:64038r S:12542 M:210317706 (Ack:244292839)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (34199) chip[EM]: >>> [E:64039r S:12542 M:210317707] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:02 (IM:ReadRequest)
I (34209) chip[EM]: <<< [E:64039r S:12542 M:244292840 (Ack:210317707)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:05 (IM:ReportData)
I (34249) chip[EM]: >>> [E:64039r S:12542 M:210317708 (Ack:244292840)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (34269) chip[EM]: >>> [E:64040r S:12542 M:210317709] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:02 (IM:ReadRequest)
I (34279) chip[EM]: <<< [E:64040r S:12542 M:244292841 (Ack:210317709)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:05 (IM:ReportData)
I (34349) chip[EM]: >>> [E:64040r S:12542 M:210317710 (Ack:244292841)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (34369) chip[EM]: >>> [E:64041r S:12542 M:210317711] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:0a (IM:TimedRequest)
I (34379) chip[EM]: <<< [E:64041r S:12542 M:244292842 (Ack:210317711)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:01 (IM:StatusResponse)
I (34409) chip[EM]: >>> [E:64041r S:12542 M:210317712 (Ack:244292842)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:08 (IM:InvokeCommandRequest)
I (34429) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x0000003C
I (34429) chip[ZCL]: Received command to open commissioning window
I (34439) chip[DIS]: Updating services using commissioning mode 2
I (34449) chip[DIS]: CHIP minimal mDNS started advertising.
I (34459) chip[DIS]: Advertise operational node 4C9D9B08B23E71F6-FA2A8B017C2EE842
I (34459) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 4C9D9B08B23E71F6-FA2A8B017C2EE842.
I (34479) chip[DIS]: mDNS service published: _matter._tcp
I (34489) chip[DIS]: Advertise commission parameter vendorID=xxxx productID=xxxx discriminator=2970/11 cm=2
I (34489) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: F178CABC28C92924.
I (34509) chip[DIS]: mDNS service published: _matterc._udp
I (34509) chip[ZCL]: Commissioning window is now open
I (34519) chip[EM]: <<< [E:64041r S:12542 M:244292843 (Ack:210317712)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:09 (IM:InvokeCommandResponse)
I (34539) app_main: Commissioning window opened
I (34549) chip[EM]: >>> [E:64041r S:12542 M:210317713 (Ack:244292843)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (35219) ROUTE_HOOK: Received RIO
I (35219) ROUTE_HOOK: prefix FDC3:A10B:1B01:: lifetime 1800
I (45479) chip[EM]: >>> [E:64042r S:12542 M:210317714] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:02 (IM:ReadRequest)
I (45489) chip[EM]: <<< [E:64042r S:12542 M:244292844 (Ack:210317714)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:05 (IM:ReportData)
I (45589) chip[EM]: >>> [E:64042r S:12542 M:210317715 (Ack:244292844)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (45609) chip[EM]: >>> [E:64043r S:12542 M:210317716] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:0a (IM:TimedRequest)
I (45609) chip[EM]: <<< [E:64043r S:12542 M:244292845 (Ack:210317716)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:01 (IM:StatusResponse)
I (45639) chip[EM]: >>> [E:64043r S:12542 M:210317717 (Ack:244292845)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:08 (IM:InvokeCommandRequest)
I (45659) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x0000003C
I (45659) chip[ZCL]: Received command to close commissioning window
I (45669) chip[SVR]: Closing pairing window
I (45669) chip[DIS]: Updating services using commissioning mode 0
I (45689) chip[DIS]: CHIP minimal mDNS started advertising.
I (45709) chip[DIS]: Advertise operational node 4C9D9B08B23E71F6-FA2A8B017C2EE842
I (45709) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 4C9D9B08B23E71F6-FA2A8B017C2EE842.
I (45729) chip[DIS]: mDNS service published: _matter._tcp
I (45729) chip[ZCL]: Commissioning window is now closed
I (45739) chip[EM]: <<< [E:64043r S:12542 M:244292846 (Ack:210317717)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:09 (IM:InvokeCommandResponse)
I (45749) app_main: Commissioning window closed
I (45769) chip[EM]: >>> [E:64043r S:12542 M:210317718 (Ack:244292846)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (45789) chip[EM]: >>> [E:64044r S:12542 M:210317719] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:02 (IM:ReadRequest)
I (45799) chip[EM]: <<< [E:64044r S:12542 M:244292847 (Ack:210317719)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:05 (IM:ReportData)
I (46209) chip[EM]: Retransmitting MessageCounter:244292847 on exchange 64044r Send Cnt 1
I (46219) chip[EM]: >>> [E:64044r S:12542 M:210317720 (Ack:244292847)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (46239) chip[EM]: >>> [E:64045r S:12542 M:210317721] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:02 (IM:ReadRequest)
I (46249) chip[EM]: <<< [E:64045r S:12542 M:244292848 (Ack:210317721)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:05 (IM:ReportData)
I (46269) chip[EM]: >>> [E:64045r S:12542 M:210317721] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:02 (IM:ReadRequest)
I (46279) chip[EM]: <<< [E:64045r S:12542 M:244292849 (Ack:210317721)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (46309) chip[EM]: >>> [E:64044r S:12542 M:210317722 (Ack:244292847)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (46319) chip[EM]: >>> [E:64045r S:12542 M:210317723 (Ack:244292848)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (46339) chip[EM]: >>> [E:64046r S:12542 M:210317724] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:0a (IM:TimedRequest)
I (46349) chip[EM]: <<< [E:64046r S:12542 M:244292850 (Ack:210317724)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:01 (IM:StatusResponse)
I (46409) chip[EM]: >>> [E:64046r S:12542 M:210317725 (Ack:244292850)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0001:08 (IM:InvokeCommandRequest)
I (46419) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x0000003C
I (46429) chip[ZCL]: Received command to open commissioning window
I (46439) chip[DIS]: Updating services using commissioning mode 2
I (46439) chip[DIS]: CHIP minimal mDNS started advertising.
I (46459) chip[DIS]: Advertise operational node 4C9D9B08B23E71F6-FA2A8B017C2EE842
I (46459) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 4C9D9B08B23E71F6-FA2A8B017C2EE842.
I (46479) chip[DIS]: mDNS service published: _matter._tcp
I (46479) chip[DIS]: Advertise commission parameter vendorID=xxxx productID=xxxx discriminator=3357/13 cm=2
I (46479) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 781C8FB0662C018A.
I (46509) chip[DIS]: mDNS service published: _matterc._udp
I (46509) chip[ZCL]: Commissioning window is now open
I (46509) chip[EM]: <<< [E:64046r S:12542 M:244292851 (Ack:210317725)] (S) Msg TX to 1:1EFFFECAF8E35117 [71F6] [UDP:[FE80::A1A6:F749:B2B2:6DBF%st1]:42512] --- Type 0001:09 (IM:InvokeCommandResponse)
I (46529) app_main: Commissioning window opened
I (46689) chip[EM]: >>> [E:64046r S:12542 M:210317726 (Ack:244292851)] (S) Msg RX from 1:1EFFFECAF8E35117 [71F6] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (99119) ROUTE_HOOK: Received RIO
I (99119) ROUTE_HOOK: prefix FDC3:A10B:1B01:: lifetime 1800

@law-ko
Copy link
Author

law-ko commented Jul 8, 2024

Apparently the issue wasn't related to ESP32 bcn_timeout issue, I tried pairing to Apple Home first and commission to Google Matter Samples app via Pairing code (open commissioning window by Apple Home) and still the same PASESession timeout issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@law-ko