MATTER/Log chip-device-ctrl - fail 될때 분석

(controller 는 test_event_7 으로 빌드되었고, esp32 는 v1.0.0 으로 빌드된 상태)

패턴#1 - BLE scan 은 됐지만 subscribe(연결?)은 안됐다는 의미인 듯.

chip-device-ctrl > connect -ble 3840 20202021 135246
Device is assigned with nodeid = 135246
[1665287009.145994][73052:73059] CHIP:IN: Prepared plaintext message 0x7f9981c9f8e0 to 0x0000000000000000 of type 0x20 and protocolId (0, 0) on exchange 24750i with MessageCounter:4166880492.
[1665287009.146014][73052:73059] CHIP:IN: Sending plaintext msg 0x7f9981c9f8e0 with MessageCounter:4166880492 to 0x0000000000000000 at monotonic time: 4235973 msec
[1665287009.149161][73052:73057] CHIP:BLE: BLE removing known devices.
[1665287009.150164][73052:73057] CHIP:BLE: BLE initiating scan.
[1665287010.286397][73052:73057] CHIP:BLE: New device scanned: DF:31:40:71:89:F8
[1665287010.286414][73052:73057] CHIP:BLE: Device discriminator match. Attempting to connect.
[1665287010.312706][73052:73057] CHIP:BLE: Scan complete notification without an active scan.
Failed to establish secure session to device: 50
[1665287039.147948][73052:73059] CHIP:SC: PASESession timed out while waiting for a response from the peer. Expected message type was 33
Failed to establish secure session to device: 50
CHIP Error 0x00000032: Timeout

패턴#2

chip-device-ctrl > connect -ble 3840 20202021 135246
Device is assigned with nodeid = 135246
[1665287161.466307][73052:73059] CHIP:IN: Prepared plaintext message 0x7f9981c9f8e0 to 0x0000000000000000 of type 0x20 and protocolId (0, 0) on exchange 24751i with MessageCounter:4166880493.
[1665287161.466327][73052:73059] CHIP:IN: Sending plaintext msg 0x7f9981c9f8e0 with MessageCounter:4166880493 to 0x0000000000000000 at monotonic time: 4388293 msec
[1665287161.467564][73052:73057] CHIP:BLE: BLE removing known devices.
[1665287161.468498][73052:73057] CHIP:BLE: BLE initiating scan.
[1665287162.298958][73052:73057] CHIP:BLE: New device scanned: E7:BF:DF:8A:25:AB
[1665287162.298976][73052:73057] CHIP:BLE: Device discriminator match. Attempting to connect.
[1665287162.302243][73052:73057] CHIP:BLE: Scan complete notification without an active scan.
[1665287163.689337][73052:73059] CHIP:BLE: subscribe complete, ep = 0x7f9984d111c0
[1665287163.689823][73052:73059] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1665287163.689831][73052:73059] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1665287163.689834][73052:73059] CHIP:BLE: local and remote recv window size = 5
Failed to establish secure session to device: 50
[1665287191.466770][73052:73059] CHIP:SC: PASESession timed out while waiting for a response from the peer. Expected message type was 33
Failed to establish secure session to device: 50
CHIP Error 0x00000032: Timeout

<ESP 리셋 시 보이는 로그> BLE 커넥션이 끊겼다는 의미인 것 가음
chip-device-ctrl > [1665288783.196372][73052:73057] CHIP:DL: Bluez notify CHIPoBluez connection disconnected

#3 - controller 재실행 이나 보드 재부팅 없이 계속 반복하다보면 이런 형태도 보임

chip-device-ctrl > connect -ble 3840 20202021 135246
Device is assigned with nodeid = 135246
[1665287817.373930][73052:73059] CHIP:IN: Prepared plaintext message 0x7f9981c9f8e0 to 0x0000000000000000 of type 0x20 and protocolId (0, 0) on exchange 24756i with MessageCounter:4166880498.
[1665287817.373952][73052:73059] CHIP:IN: Sending plaintext msg 0x7f9981c9f8e0 with MessageCounter:4166880498 to 0x0000000000000000 at monotonic time: 5044201 msec
[1665287817.375372][73052:73057] CHIP:BLE: BLE removing known devices.
[1665287817.433849][73052:73057] CHIP:BLE: BLE initiating scan.
[1665287818.307388][73052:73057] CHIP:BLE: New device scanned: E7:BF:DF:8A:25:AB
[1665287818.307402][73052:73057] CHIP:BLE: Device discriminator match. Attempting to connect.
[1665287818.334765][73052:73057] CHIP:BLE: Scan complete notification without an active scan.
[1665287820.749813][73052:73059] CHIP:BLE: subscribe complete, ep = 0x7f9984d111c0
[1665287820.750145][73052:73059] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1665287820.750157][73052:73059] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1665287820.750163][73052:73059] CHIP:BLE: local and remote recv window size = 5
[1665287824.666176][73052:73057] CHIP:DL: Bluez notify CHIPoBluez connection disconnected
[1665287827.719273][73052:73059] CHIP:DL: MAC is not known, using a default.
[1665287827.719329][73052:73059] CHIP:DIS: Advertise commission parameter vendorID=9050 productID=65279 discriminator=3840/00
[1665287827.719344][73052:73059] CHIP:DL: Cannot get device role with Thread api client: 
[1665287827.719485][73052:73059] CHIP:DL: Cannot set hostname on this system, continue anyway...
[1665287827.719508][73052:73059] CHIP:DL: PublishService AE39004D0E211053._matterd._udp5550.-1
[1665287828.568863][73052:73059] CHIP:DL: Avahi group established

Failed to establish secure session to device: 50
[1665287847.375175][73052:73059] CHIP:SC: PASESession timed out while waiting for a response from the peer. Expected message type was 33
Failed to establish secure session to device: 50
CHIP Error 0x00000032: Timeout

#1 출력형태를 보일 때 ESP32 의 출력

I (572040) chip[DL]: BLE GAP connection established (con 0)
I (572040) chip[DL]: CHIPoBLE advertising stopped
I (572040) app-devicecallbacks: Current free heap: 77692

lld_pdu_get_tx_flush_nb HCI packet count mismatch (0, 1)
I (573220) chip[DL]: BLE GAP connection terminated (con 0 reason 0x208)
I (573220) app-devicecallbacks: CHIPoBLE disconnected
I (573240) app-devicecallbacks: Current free heap: 77692

I (573240) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (573250) NimBLE: GAP procedure initiated: advertise; 
I (573250) NimBLE: disc_mode=2
I (573250) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (573270) NimBLE: 

I (573280) chip[DL]: CHIPoBLE advertising started
I (573280) app-devicecallbacks: Current free heap: 77692

 

#2 형태를 보일 때 ESP32의 출력

 (16860) chip[DL]: BLE GAP connection established (con 0)
I (16860) chip[DL]: CHIPoBLE advertising stopped
I (16860) app-devicecallbacks: Current free heap: 77696

I (18110) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (18110) chip[BLE]: local and remote recv window sizes = 5
I (18110) chip[BLE]: selected BTP version 4
I (18120) chip[BLE]: using BTP fragment sizes rx 244 / tx 244.
I (18200) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 1
I (18200) chip[DL]: CHIPoBLE subscribe received
I (18200) NimBLE: GATT procedure initiated: indicate; 
I (18210) NimBLE: att_handle=14

I (18210) app-devicecallbacks: CHIPoBLE connection established
I (18220) app-devicecallbacks: Current free heap: 76176

I (18290) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (18290) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (18300) chip[IN]: Received malformed unsecure packet with source 0x0000000000000000 destination 0x0000000000000000
I (20800) NimBLE: GATT procedure initiated: indicate; 
I (20800) NimBLE: att_handle=14

I (20940) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (23600) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (26100) NimBLE: GATT procedure initiated: indicate; 
I (26100) NimBLE: att_handle=14

I (26210) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
마지막 Write -- Confirm 이 반복됨