[2025-07-29 15:28:14.083] 
[2025-07-29 15:28:14.083] uart:~$ *** Booting My Application v23.55.2-2f9996e8c87c ***
[2025-07-29 15:28:14.123] *** Using nRF Connect SDK v2.8.0-a2386bfc8401 ***
[2025-07-29 15:28:14.123] *** Using Zephyr OS v3.7.99-0bc3393fb112 ***
[2025-07-29 15:28:14.123] I: KWIKSET HALO 3 PLUS VERSION: 17.37.02.03
[2025-07-29 15:28:14.123] I: 51 [DL]BLE address: F7:B0:19:DA:67:29
[2025-07-29 15:28:14.135] I: No users indexes stored
[2025-07-29 15:28:14.135] I: No stored indexes for credential of type: 1
[2025-07-29 15:28:14.253] I: No stored indexes for credential of type: 2
[2025-07-29 15:28:14.253] I: ========== User Index: 0x01 User ID: 0xffffffff ==========
[2025-07-29 15:28:14.253] I: ========== User Index: 0x02 User ID: 0xffffffff ==========
[2025-07-29 15:28:14.253] I: ========== User Index: 0x03 User ID: 0xffffffff ==========
[2025-07-29 15:28:14.253] I: ========== User Index: 0x04 User ID: 0xffffffff ==========
[2025-07-29 15:28:14.253] I: ========== User Index: 0x05 User ID: 0xffffffff ==========
[2025-07-29 15:28:14.253] I: ========== User Index: 0x06 User ID: 0xffffffff ==========
[2025-07-29 15:28:14.253] I: ========== User Index: 0x07 User ID: 0xffffffff ==========
[2025-07-29 15:28:14.253] I: ========== User Index: 0x08 User ID: 0xffffffff ==========
[2025-07-29 15:28:14.253] I: ========== User Index: 0x09 User ID: 0xffffffff ==========
[2025-07-29 15:28:14.253] I: ========== User Index: 0x0a User ID: 0xffffffff ==========
[2025-07-29 15:28:14.276] I: ========== User Index: 0x0b User ID: 0xffffffff ==========
[2025-07-29 15:28:14.276] I: Board config kwiksetmdb_nrf5340_cpuapp
[2025-07-29 15:28:14.276] I: IMAGE_VERSION 17370203
[2025-07-29 15:28:14.278] I: build time: Jul 29 2025 12:22:21
[2025-07-29 15:28:14.278] I: 158 [DL]CHIP task running
[2025-07-29 15:28:14.278] I: Init CHIP stack
[2025-07-29 15:28:14.278] I: 164 [DL]OpenThread started: OK
[2025-07-29 15:28:14.278] I: 167 [DL]Setting OpenThread device type to SLEEPY END DEVICE
[2025-07-29 15:28:14.278] I: 173 [SWU]DFU_BLEAdvertising_Init
[2025-07-29 15:28:14.292] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 15:28:14.653] I: NFC Boot Event PN7642 FW VERSION 17.01.00.02
[2025-07-29 15:28:14.653] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 15:28:14.653] I: 
[2025-07-29 15:28:14.653] Boot Event Received
[2025-07-29 15:28:14.653] 
[2025-07-29 15:28:14.653] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 15:28:14.653] 
[2025-07-29 15:28:14.653] I: 256 [SVR]Subscription persistence not supported
[2025-07-29 15:28:14.653] I: 261 [SVR]Server initializing...
[2025-07-29 15:28:14.653] I: 264 [TS]Last Known Good Time: 2023-10-14T01:16:48
[2025-07-29 15:28:14.653] I: 270 [DMG]AccessControl: initializing
[2025-07-29 15:28:14.663] I: 273 [DMG]Examples::AccessControlDelegate::Init
[2025-07-29 15:28:14.663] I: 278 [DMG]AccessControl: setting
[2025-07-29 15:28:14.663] I: 281 [DMG]DefaultAclStorage: initializing
[2025-07-29 15:28:14.663] I: 285 [DMG]DefaultAclStorage: 0 entries loaded
[2025-07-29 15:28:14.663] E: 289 [IN]IPV6_PKTINFO failed: 109
[2025-07-29 15:28:14.673] I: 295 [ZCL]Using ZAP configuration...
[2025-07-29 15:28:14.673] I: 299 [DMG]AccessControlCluster: initializing
[2025-07-29 15:28:14.673] Unhandled cluster ID: 0x  30
[2025-07-29 15:28:14.673] 
[2025-07-29 15:28:14.673] ===== Attribute Received are: Cluster=30 Attribute=0 Value=0 =====
[2025-07-29 15:28:14.673] I: 314 [ZCL]Emit DSTTableEmpty event [ep=0]
[2025-07-29 15:28:14.673] I: 318 [ZCL]Initiating Admin Commissioning cluster.
[2025-07-29 15:28:14.673] I: 322 [ZCL]Door Lock server initialized
[2025-07-29 15:28:14.673] E: 326 [ZCL]DeviceInfoProvider is not registered
[2025-07-29 15:28:14.673] E: 330 [ZCL]Failed to read calendar type with error: 0x86
[2025-07-29 15:28:14.673] Unhandled cluster ID: 0x   3
[2025-07-29 15:28:14.673] 
[2025-07-29 15:28:14.673] ===== Attribute Received are: Cluster=3 Attribute=1 Value=3 =====
[2025-07-29 15:28:14.673] I: 344 [ZCL]Door Lock cluster initialized at endpoint #1
[2025-07-29 15:28:14.693] ===== Attribute Received are: Cluster=101 Attribute=0 Value=255 =====
[2025-07-29 15:28:14.693] ===== Attribute Received are: Cluster=101 Attribute=2 Value=1 =====
[2025-07-29 15:28:14.693] ===== Attribute Received are: Cluster=101 Attribute=1 Value=0 =====
[2025-07-29 15:28:14.693] ===== Attribute Received are: Cluster=101 Attribute=11 Value=11 =====
[2025-07-29 15:28:14.693] ===== Attribute Received are: Cluster=101 Attribute=12 Value=35 =====
[2025-07-29 15:28:14.693] ===== Attribute Received are: Cluster=101 Attribute=13 Value=35 =====
[2025-07-29 15:28:14.693] ===== Attribute Received are: Cluster=101 Attribute=1c Value=35 =====
[2025-07-29 15:28:14.693] ===== Attribute Received are: Cluster=101 Attribute=19 Value=80 =====
[2025-07-29 15:28:14.693] I: 398 [DIS]Updating services using commissioning mode 0
[2025-07-29 15:28:14.693] E: 403 [DIS]Failed to remove advertised services: 3
[2025-07-29 15:28:14.693] E: 407 [DIS]Failed to finalize service update: 3
[2025-07-29 15:28:14.713] I: 411 [IN]CASE Server enabling CASE session setups
[2025-07-29 15:28:14.713] I: 416 [SVR]Joining Multicast groups
[2025-07-29 15:28:14.713] I: 420 [SVR]Server Listening...
[2025-07-29 15:28:14.713] I: 423 [DL]Device Configuration:
[2025-07-29 15:28:14.713] I: 426 [DL]  Serial Number: 1789AE57B32427844F
[2025-07-29 15:28:14.713] I: 430 [DL]  Vendor Id: 5153 (0x1421)
[2025-07-29 15:28:14.713] I: 433 [DL]  Product Id: 66 (0x42)
[2025-07-29 15:28:14.713] I: Get product name B, len 0
[2025-07-29 15:28:14.713] I: 439 [DL]  Product Name: B
[2025-07-29 15:28:14.713] I: 441 [DL]  Hardware Version: 1
[2025-07-29 15:28:14.713] I: 444 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 75655451
[2025-07-29 15:28:14.713] I: 450 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 776 (0x308)
[2025-07-29 15:28:14.713] I: 456 [DL]  Manufacturing Date: 2025-07-24
[2025-07-29 15:28:14.713] I: 460 [DL]  Device Type: 10 (0xA)
[2025-07-29 15:28:14.733] I: 463 [SVR]SetupQRCode: [MT:-QWJ08DB00.I2N6SM10]
[2025-07-29 15:28:14.733] I: 467 [SVR]Copy/paste the below URL in a browser to see the QR Code:
[2025-07-29 15:28:14.733] I: 474 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-QWJ08DB00.I2N6SM10
[2025-07-29 15:28:14.733] I: 483 [SVR]Manual pairing code: [05967546175]
[2025-07-29 15:28:14.733] I: STM32 device number: 
[2025-07-29 15:28:14.733] I: 31 37 38 39 41 45 35 37 |1789AE57
[2025-07-29 15:28:14.733] I: 42 33 32 34 32 37 38 34 |B3242784
[2025-07-29 15:28:14.733] I: 34 46                   |4F      
[2025-07-29 15:28:14.733] I: SKU number: 
[2025-07-29 15:28:14.733] I: 4b 31 37 2d 30 31       |K17-01  
[2025-07-29 15:28:14.738] I: WO number: 
[2025-07-29 15:28:14.738] I: 30 30 30 30 30 30 30 30 |00000000
[2025-07-29 15:28:14.738] I: 30                      |0       
[2025-07-29 15:28:14.738] I: Manuf Date: 
[2025-07-29 15:28:14.755] I: 32 30 32 35 2d 30 37 2d |2025-07-
[2025-07-29 15:28:14.755] I: 32 34 00 00 00 00       |24....  
[2025-07-29 15:28:14.755] I: Prod config length 6
[2025-07-29 15:28:14.755] I: Product Config: 
[2025-07-29 15:28:14.755] I: 30 78 30 30 30 31       |0x0001  
[2025-07-29 15:28:14.755] I: Prod Config Read 1
[2025-07-29 15:28:14.755] I: User intend flow enabled, set commissioning flow to kUserActionRequired
[2025-07-29 15:28:14.755] I: Factory Data Version length 2
[2025-07-29 15:28:14.755] I: Factory Data Ver: 
[2025-07-29 15:28:14.755] I: 30 31                   |01      
[2025-07-29 15:28:14.755] I: Payload value in string format: MT:-QWJ04TC00.I2N60Q4P0ILT70VYYR1JFSK14YDB0-0LJ1-0LJ1-0LJ1IHLC0AUZL1XIKJ17AZL1UV700CXYR1K6Y12NNZR1YC-L1-2ZR1OADO1KB40
[2025-07-29 15:28:14.755] I: Pairing Code value in string format: 459675461705153000660
[2025-07-29 15:28:14.755] I: ============== Updating product finish and color to 15, 2, product Name Halo Select Plus ==============
[2025-07-29 15:28:14.773] E: 573 [DL]Long dispatch time: 412 ms, for event type 2
[2025-07-29 15:28:14.773] ===== Attribute Received are: Cluster=101 Attribute=0 Value=1 =====
[2025-07-29 15:28:14.813] I: Lock State Event
[2025-07-29 15:28:14.853] I: Received response of command id 10
[2025-07-29 15:28:14.853] I: Received Lock State event, lock st: 12
[2025-07-29 15:28:14.853] I: Found matching nordic source of operation 0
[2025-07-29 15:28:14.853] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 15:28:14.853] I: Unlock action completed
[2025-07-29 15:28:14.853] I: Updating LockState attribute
[2025-07-29 15:28:14.853] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 15:28:16.213] I: Syncing up on message 9a
[2025-07-29 15:28:16.213] I: STM32 counter to 1
[2025-07-29 15:28:16.273] I: BLE Device ID: 2784
[2025-07-29 15:28:16.273] I: Device is provisioned
[2025-07-29 15:28:16.273] I: network state 0
[2025-07-29 15:28:16.273] E: Sending UART cmd(3) st 0
[2025-07-29 15:28:16.273] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 15:28:16.273] I: Received response of command id 9a
[2025-07-29 15:28:16.273] I: Command 0x9A Received
[2025-07-29 15:28:16.273] I: Received DC Eco Config REQ
[2025-07-29 15:28:16.273] I: DC Eco Config Resp
[2025-07-29 15:28:16.273] I: Received DC eco config req
[2025-07-29 15:28:16.273] I: 80 72 03 00 10 00 50 e0 |.r....P.
[2025-07-29 15:28:16.273] I: c5 ba                   |..      
[2025-07-29 15:28:16.273] E: Sending UART cmd(72) st 0
[2025-07-29 15:28:16.473] I: General Lock Setting event
[2025-07-29 15:28:16.473] I: Received response of command id 20
[2025-07-29 15:28:16.473] I: Received Lock General Setting event
[2025-07-29 15:28:16.473] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 15:28:16.473] SoundVolume attribute change
[2025-07-29 15:28:16.473] 
[2025-07-29 15:28:16.473] I: == Sound Volume Attribute Update Callback, sound volume 2 ==
[2025-07-29 15:28:16.473] I: No change in sound volume, return
[2025-07-29 15:28:16.473] ===== Attribute Received are: Cluster=101 Attribute=24 Value=2 =====
[2025-07-29 15:28:16.473] I: Matter Not Enabled do not set
[2025-07-29 15:28:16.567] I: Firmware Attribute event
[2025-07-29 15:28:16.567] I: Received response of command id 30
[2025-07-29 15:28:16.623] I: Hardware Attribute event
[2025-07-29 15:28:16.623] I: Received response of command id 31
[2025-07-29 15:28:16.703] I: Operating mode event
[2025-07-29 15:28:16.703] I: Received response of command id 5
[2025-07-29 15:28:16.703] I: Received Lock Op Mode Event, mode 10, App state 10
[2025-07-29 15:28:16.703] I: Lock Current Mode : 10, Lock Current State = 10
[2025-07-29 15:28:16.703] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:28:16.703] I: Set Kwikset Lock App State 16
[2025-07-29 15:28:16.703] I: Matter enabled state 0
[2025-07-29 15:28:16.703] I: Matter is disabled
[2025-07-29 15:28:16.823] I: Battery Info event
[2025-07-29 15:28:16.823] I: Received response of command id 51
[2025-07-29 15:28:16.823] I: Received Battery info event
[2025-07-29 15:28:16.823] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 15:28:16.823] Unhandled cluster ID: 0x  2f
[2025-07-29 15:28:16.823] 
[2025-07-29 15:28:16.823] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 15:28:16.823] Unhandled cluster ID: 0x  2f
[2025-07-29 15:28:16.823] 
[2025-07-29 15:28:16.823] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 15:28:16.933] I: System info event
[2025-07-29 15:28:16.933] I: Received System Info Event
[2025-07-29 15:28:16.933] W: Time invalid, set time
[2025-07-29 15:28:16.933] I: Get system time
[2025-07-29 15:28:16.933] I: System Real time in seconds 373663017
[2025-07-29 15:28:16.933] I: Time sync status flag 0
[2025-07-29 15:28:16.933] E: Time not sync, keep default value
[2025-07-29 15:28:16.967] I: System init event
[2025-07-29 15:28:16.967] I: Received response of command id 3
[2025-07-29 15:28:17.003] I: Update sync timer
[2025-07-29 15:28:17.003] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 15:28:17.003] I: Lock Current Mode : 10, Lock Current State = 10
[2025-07-29 15:28:17.003] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 15:28:17.003] I: STM Pending =0, Redpine Pending = 0
[2025-07-29 15:28:17.107] I: Count = 0
[2025-07-29 15:28:17.107] I: BLE-OTA: No pending image transfers
[2025-07-29 15:28:17.107] I: OTA STAGE = ff
[2025-07-29 15:28:17.107] I: OTA Stage Change from (ff)->(10)
[2025-07-29 15:28:17.473] I: All message synced.
[2025-07-29 15:28:22.733] I: System info event
[2025-07-29 15:28:22.733] I: Received System Info Event
[2025-07-29 15:28:22.733] I: Time is set in STM
[2025-07-29 15:28:48.999] I: Updated ota meta data
[2025-07-29 15:28:48.999] I: Operating Mode Command: Mode:10, State:34
[2025-07-29 15:28:49.013] E: Sending UART cmd(5) st 0
[2025-07-29 15:28:49.013] I: Operating mode event
[2025-07-29 15:28:49.073] I: Received response of command id 5
[2025-07-29 15:28:49.073] I: Received Lock Op Mode Event, mode 10, App state 34
[2025-07-29 15:28:49.073] I: Lock Current Mode : 10, Lock Current State = 34
[2025-07-29 15:28:49.073] I: STM32 HALO APP STATE IS BLE OTAU TRANSFER
[2025-07-29 15:28:49.073] E: Sending UART cmd(9e) st 0
[2025-07-29 15:28:49.073] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 15:28:49.073] I: 34985 [SWU]SMP BLE advertising started
[2025-07-29 15:28:49.073] I: 34989 [DL]DFU over SMP started
[2025-07-29 15:28:49.073] I: OTA Stage Change from (10)->(11)
[2025-07-29 15:28:49.073] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:28:49.073] I: Set Kwikset Lock App State 52
[2025-07-29 15:28:49.073] I: Matter is disabled
[2025-07-29 15:29:04.103] I: 50047 [DL]Current number of connections: 1/1
[2025-07-29 15:29:04.125] I: BLE Connected
[2025-07-29 15:29:04.373] I: 50291 [DL]Current number of connections: 0/1
[2025-07-29 15:29:04.373] I: BLE Disconnected: 13
[2025-07-29 15:29:08.713] I: 54634 [DL]Current number of connections: 1/1
[2025-07-29 15:29:08.713] I: BLE Connected
[2025-07-29 15:29:08.935] I: 54871 [DL]DFU Image upload started
[2025-07-29 15:29:09.753] I: Connection parameters updated.
[2025-07-29 15:29:09.753]  interval: 9, latency: 0, timeout: 42
[2025-07-29 15:29:18.593] I: OTA Stage Change from (11)->(12)
[2025-07-29 15:29:18.593] I: 64518 [DL]Image 0 download completed successfully
[2025-07-29 15:29:18.613] I: 64541 [DL]Current number of connections: 0/1
[2025-07-29 15:29:18.613] I: 64545 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 15:29:18.613] I: BLE Disconnected: 13
[2025-07-29 15:29:31.123] I: 77068 [DL]Current number of connections: 1/1
[2025-07-29 15:29:31.143] I: BLE Connected
[2025-07-29 15:29:31.363] I: 77296 [DL]DFU Image upload started
[2025-07-29 15:29:32.183] I: Connection parameters updated.
[2025-07-29 15:29:32.183]  interval: 9, latency: 0, timeout: 42
[2025-07-29 15:30:15.093] I: OTA Stage Change from (12)->(13)
[2025-07-29 15:30:15.093] I: 121015 [DL]Image 1 download completed successfully
[2025-07-29 15:30:15.113] I: 121034 [DL]Current number of connections: 0/1
[2025-07-29 15:30:15.113] I: 121038 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 15:30:15.113] I: BLE Disconnected: 13
[2025-07-29 15:30:22.013] I: 127935 [DL]Current number of connections: 1/1
[2025-07-29 15:30:22.013] I: BLE Connected
[2025-07-29 15:30:22.223] I: 128161 [DL]DFU Image upload started
[2025-07-29 15:30:23.053] I: Connection parameters updated.
[2025-07-29 15:30:23.083]  interval: 9, latency: 0, timeout: 42
[2025-07-29 15:30:23.083] E: No available ACL buffers!
[2025-07-29 15:30:23.083] E: Unexpected first L2CAP frame
[2025-07-29 15:33:15.723] I: OTA Stage Change from (13)->(14)
[2025-07-29 15:33:15.723] I: 301647 [DL]Image 2 download completed successfully
[2025-07-29 15:33:15.743] I: 301670 [DL]Current number of connections: 0/1
[2025-07-29 15:33:15.743] I: 301674 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 15:33:15.743] I: BLE Disconnected: 13
[2025-07-29 15:33:22.893] I: 308838 [DL]Current number of connections: 1/1
[2025-07-29 15:33:22.913] I: BLE Connected
[2025-07-29 15:33:23.134] I: 309076 [DL]Current number of connections: 0/1
[2025-07-29 15:33:23.134] I: BLE Disconnected: 13
[2025-07-29 15:33:27.763] I: 313690 [DL]Current number of connections: 1/1
[2025-07-29 15:33:27.763] I: BLE Connected
[2025-07-29 15:33:27.953] I: 313902 [DL]DFU_ImgConfirmHandler: Nordic Image Confirmed by MCUMgr
[2025-07-29 15:33:28.014] I: 313936 [DL]Current number of connections: 0/1
[2025-07-29 15:33:28.014] I: BLE Disconnected: 13
[2025-07-29 15:33:34.894] I: 320821 [DL]Current number of connections: 1/1
[2025-07-29 15:33:34.894] I: BLE Connected
[2025-07-29 15:33:35.103] I: 321050 [DL]DFU_ImgConfirmHandler: Nordic Image Confirmed by MCUMgr
[2025-07-29 15:33:35.153] I: 321076 [DL]Current number of connections: 0/1
[2025-07-29 15:33:35.153] I: BLE Disconnected: 13
[2025-07-29 15:33:42.314] I: 328261 [DL]Current number of connections: 1/1
[2025-07-29 15:33:42.334] I: BLE Connected
[2025-07-29 15:33:42.543] I: STM Pending =0, Redpine Pending = 0
[2025-07-29 15:33:42.633] I: Count = 4
[2025-07-29 15:33:42.633] I: dfu_header_data.image_count: 4
[2025-07-29 15:33:43.389] I: Connection parameters updated.
[2025-07-29 15:33:43.389]  interval: 9, latency: 0, timeout: 42
[2025-07-29 15:33:43.513] I: IMG Integrity Verified Successfully: 0
[2025-07-29 15:33:46.473] I: IMG Integrity Verified Successfully: 1
[2025-07-29 15:33:46.553] I: IMG Integrity Verified Successfully: 2
[2025-07-29 15:33:46.843] I: IMG Integrity Verified Successfully: 3
[2025-07-29 15:33:46.864] I: OTA Bundle(STM32 + RS9116 + PN76) image integrity Verified
[2025-07-29 15:33:46.864] I: OTA Stage Change from (14)->(30)
[2025-07-29 15:33:46.964] I: Updated ota meta data
[2025-07-29 15:33:46.964] I: Operating Mode Command: Mode:10, State:31
[2025-07-29 15:33:46.964] E: Sending UART cmd(5) st 0
[2025-07-29 15:33:47.014] I: Operating mode event
[2025-07-29 15:33:47.014] I: Received response of command id 5
[2025-07-29 15:33:47.014] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 15:33:47.014] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:33:47.014] I: STM OTAU Pending: Reset Nordic Triggered
[2025-07-29 15:33:47.014] I: OTA Stage Change from (30)->(30)
[2025-07-29 15:33:47.014] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:33:47.014] I: Set Kwikset Lock App State 49
[2025-07-29 15:33:47.014] I: Matter is disabled
[2025-07-29 15:33:47.043] I: 332986 [DL]Current number of connections: 0/1
[2025-07-29 15:33:47.053] I: BLE Disconnected: 13
[2025-07-29 15:34:32.063] 
[2025-07-29 15:34:32.063] 
[2025-07-29 15:34:32.063] uart:~$ *** Booting My Application v23.49.0-de86e88ec64e ***
[2025-07-29 15:34:32.113] *** Using nRF Connect SDK v2.7.0-5cb85570ca43 ***
[2025-07-29 15:34:32.113] *** Using Zephyr OS v3.6.99-100befc70c74 ***
[2025-07-29 15:34:32.113] I: KWIKSET HALO 3 PLUS VERSION: 17.31.00.02
[2025-07-29 15:34:32.113] I: 51 [DL]BLE address: CC:C4:36:D0:E5:1C
[2025-07-29 15:34:32.123] I: No users indexes stored
[2025-07-29 15:34:32.123] I: No stored indexes for credential of type: 1
[2025-07-29 15:34:32.243] I: No stored indexes for credential of type: 2
[2025-07-29 15:34:32.243] I: No stored indexes for credential of type: 3
[2025-07-29 15:34:32.243] I: ========== User Index: 0x01 User ID: 0xffffffff ==========
[2025-07-29 15:34:32.243] I: ========== User Index: 0x02 User ID: 0xffffffff ==========
[2025-07-29 15:34:32.243] I: ========== User Index: 0x03 User ID: 0xffffffff ==========
[2025-07-29 15:34:32.243] I: ========== User Index: 0x04 User ID: 0xffffffff ==========
[2025-07-29 15:34:32.243] I: ========== User Index: 0x05 User ID: 0xffffffff ==========
[2025-07-29 15:34:32.243] I: ========== User Index: 0x06 User ID: 0xffffffff ==========
[2025-07-29 15:34:32.243] I: ========== User Index: 0x07 User ID: 0xffffffff ==========
[2025-07-29 15:34:32.243] I: ========== User Index: 0x08 User ID: 0xffffffff ==========
[2025-07-29 15:34:32.243] I: ========== User Index: 0x09 User ID: 0xffffffff ==========
[2025-07-29 15:34:32.273] I: ========== User Index: 0x0a User ID: 0xffffffff ==========
[2025-07-29 15:34:32.273] I: ========== User Index: 0x0b User ID: 0xffffffff ==========
[2025-07-29 15:34:32.273] I: Board config kwiksetmdb_nrf5340_cpuapp
[2025-07-29 15:34:32.273] I: IMAGE_VERSION 17310002
[2025-07-29 15:34:32.273] I: build time: Jun 18 2025 10:48:56
[2025-07-29 15:34:32.273] I: 161 [DL]CHIP task running
[2025-07-29 15:34:32.273] I: Init CHIP stack
[2025-07-29 15:34:32.273] I: 167 [DL]OpenThread started: OK
[2025-07-29 15:34:32.273] I: 170 [DL]Setting OpenThread device type to SLEEPY END DEVICE
[2025-07-29 15:34:32.273] I: 176 [SWU]New firmware image confirmed
[2025-07-29 15:34:32.273] I: 180 [SWU]DFU_BLEAdvertising_Init
[2025-07-29 15:34:32.293] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 15:34:32.643] I: NFC Boot Event PN7642 FW VERSION 17.01.00.02
[2025-07-29 15:34:32.643] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 15:34:32.643] I: 
[2025-07-29 15:34:32.643] Boot Event Received
[2025-07-29 15:34:32.643] 
[2025-07-29 15:34:32.643] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 15:34:32.643] 
[2025-07-29 15:34:32.643] I: 263 [SVR]Subscription persistence not supported
[2025-07-29 15:34:32.643] I: 268 [SVR]Server initializing...
[2025-07-29 15:34:32.643] I: 271 [TS]Last Known Good Time: 2023-10-14T01:16:48
[2025-07-29 15:34:32.643] I: 277 [DMG]AccessControl: initializing
[2025-07-29 15:34:32.643] I: 280 [DMG]Examples::AccessControlDelegate::Init
[2025-07-29 15:34:32.643] I: 285 [DMG]AccessControl: setting
[2025-07-29 15:34:32.643] I: 288 [DMG]DefaultAclStorage: initializing
[2025-07-29 15:34:32.643] I: 291 [DMG]DefaultAclStorage: 0 entries loaded
[2025-07-29 15:34:32.663] E: 296 [IN]IPV6_PKTINFO failed: 109
[2025-07-29 15:34:32.663] I: 301 [ZCL]Using ZAP configuration...
[2025-07-29 15:34:32.663] I: 306 [DMG]AccessControlCluster: initializing
[2025-07-29 15:34:32.663] ===== Attribute Received are: Cluster=30 Attribute=0 Value=0 =====
[2025-07-29 15:34:32.663] I: 318 [ZCL]Emit DSTTableEmpty event [ep=0]
[2025-07-29 15:34:32.663] I: 322 [ZCL]Initiating Admin Commissioning cluster.
[2025-07-29 15:34:32.663] I: 326 [ZCL]Door Lock server initialized
[2025-07-29 15:34:32.663] E: 330 [ZCL]DeviceInfoProvider is not registered
[2025-07-29 15:34:32.663] E: 334 [ZCL]Failed to read calendar type with error: 0x86
[2025-07-29 15:34:32.663] ===== Attribute Received are: Cluster=3 Attribute=1 Value=3 =====
[2025-07-29 15:34:32.663] I: 345 [ZCL]Door Lock cluster initialized at endpoint #1
[2025-07-29 15:34:32.663] ===== Attribute Received are: Cluster=101 Attribute=0 Value=255 =====
[2025-07-29 15:34:32.668] ===== Attribute Received are: Cluster=101 Attribute=2 Value=1 =====
[2025-07-29 15:34:32.687] ===== Attribute Received are: Cluster=101 Attribute=1 Value=0 =====
[2025-07-29 15:34:32.687] ===== Attribute Received are: Cluster=101 Attribute=11 Value=11 =====
[2025-07-29 15:34:32.687] ===== Attribute Received are: Cluster=101 Attribute=12 Value=35 =====
[2025-07-29 15:34:32.687] ===== Attribute Received are: Cluster=101 Attribute=13 Value=35 =====
[2025-07-29 15:34:32.687] ===== Attribute Received are: Cluster=101 Attribute=1c Value=35 =====
[2025-07-29 15:34:32.687] ===== Attribute Received are: Cluster=101 Attribute=19 Value=80 =====
[2025-07-29 15:34:32.687] I: 399 [DIS]Updating services using commissioning mode 0
[2025-07-29 15:34:32.687] E: 404 [DIS]Failed to remove advertised services: 3
[2025-07-29 15:34:32.687] E: 409 [DIS]Failed to finalize service update: 3
[2025-07-29 15:34:32.687] I: 413 [IN]CASE Server enabling CASE session setups
[2025-07-29 15:34:32.703] I: 418 [SVR]Joining Multicast groups
[2025-07-29 15:34:32.703] I: 421 [SVR]Server Listening...
[2025-07-29 15:34:32.703] I: 424 [DL]Device Configuration:
[2025-07-29 15:34:32.703] I: 427 [DL]  Serial Number: 1789AE57B32427844F
[2025-07-29 15:34:32.703] I: 431 [DL]  Vendor Id: 5153 (0x1421)
[2025-07-29 15:34:32.703] I: 435 [DL]  Product Id: 66 (0x42)
[2025-07-29 15:34:32.703] I: Get product name B, len 0
[2025-07-29 15:34:32.703] I: 440 [DL]  Product Name: B
[2025-07-29 15:34:32.703] I: 443 [DL]  Hardware Version: 1
[2025-07-29 15:34:32.703] I: 446 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 75655451
[2025-07-29 15:34:32.703] I: 451 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 776 (0x308)
[2025-07-29 15:34:32.703] I: 458 [DL]  Manufacturing Date: 2025-07-24
[2025-07-29 15:34:32.708] I: 461 [DL]  Device Type: 10 (0xA)
[2025-07-29 15:34:32.708] I: 465 [SVR]SetupQRCode: [MT:-QWJ08DB00.I2N6SM10]
[2025-07-29 15:34:32.708] I: 469 [SVR]Copy/paste the below URL in a browser to see the QR Code:
[2025-07-29 15:34:32.724] I: 475 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-QWJ08DB00.I2N6SM10
[2025-07-29 15:34:32.724] I: 484 [SVR]Manual pairing code: [05967546175]
[2025-07-29 15:34:32.724] I: STM32 device number: 
[2025-07-29 15:34:32.724] I: 31 37 38 39 41 45 35 37 |1789AE57
[2025-07-29 15:34:32.724] I: 42 33 32 34 32 37 38 34 |B3242784
[2025-07-29 15:34:32.724] I: 34 46                   |4F      
[2025-07-29 15:34:32.724] I: SKU number: 
[2025-07-29 15:34:32.724] I: 4b 31 37 2d 30 31       |K17-01  
[2025-07-29 15:34:32.724] I: WO number: 
[2025-07-29 15:34:32.724] I: 30 30 30 30 30 30 30 30 |00000000
[2025-07-29 15:34:32.728] I: 30                      |0       
[2025-07-29 15:34:32.728] I: Manuf Date: 
[2025-07-29 15:34:32.728] I: 32 30 32 35 2d 30 37 2d |2025-07-
[2025-07-29 15:34:32.728] I: 32 34 00 00 00 00       |24....  
[2025-07-29 15:34:32.728] I: Prod config length 6
[2025-07-29 15:34:32.748] I: Product Config: 
[2025-07-29 15:34:32.748] I: 30 78 30 30 30 31       |0x0001  
[2025-07-29 15:34:32.748] I: Prod Config Read 1
[2025-07-29 15:34:32.748] I: User intend flow enabled, set commissioning flow to kUserActionRequired
[2025-07-29 15:34:32.748] I: Factory Data Version length 2
[2025-07-29 15:34:32.748] I: Factory Data Ver: 
[2025-07-29 15:34:32.748] I: 30 31                   |01      
[2025-07-29 15:34:32.748] I: Payload value in string format: MT:-QWJ04TC00.I2N60Q4P0ILT70VYYR1JFSK14YDB0-0LJ1-0LJ1-0LJ1IHLC0AUZL1XIKJ17AZL1UV700CXYR1K6Y12NNZR1YC-L1-2ZR1OADO1KB40
[2025-07-29 15:34:32.748] I: Pairing Code value in string format: 459675461705153000660
[2025-07-29 15:34:32.748] I: ============== Updating product finish and color to 15, 2, product Name Halo Select Plus ==============
[2025-07-29 15:34:32.748] E: 575 [DL]Long dispatch time: 411 ms, for event type 2
[2025-07-29 15:34:32.748] ===== Attribute Received are: Cluster=101 Attribute=0 Value=1 =====
[2025-07-29 15:34:34.243] I: Syncing up on message 9a
[2025-07-29 15:34:34.243] I: STM32 counter to 1
[2025-07-29 15:34:34.243] I: BLE Device ID: 2784
[2025-07-29 15:34:34.243] I: Device is provisioned
[2025-07-29 15:34:34.243] I: network state 0
[2025-07-29 15:34:34.243] E: Sending UART cmd(3) st 0
[2025-07-29 15:34:34.243] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 15:34:34.243] I: Received response of command id 9a
[2025-07-29 15:34:34.243] I: Command 0x9A Received
[2025-07-29 15:34:34.243] I: Firmware Attribute event
[2025-07-29 15:34:34.243] I: Received response of command id 30
[2025-07-29 15:34:34.273] I: Received DC Eco Config REQ
[2025-07-29 15:34:34.273] I: DC Eco Config Resp
[2025-07-29 15:34:34.273] I: Received DC eco config req
[2025-07-29 15:34:34.273] I: 80 72 03 00 10 00 04 1b |.r......
[2025-07-29 15:34:34.273] I: 17 05                   |..      
[2025-07-29 15:34:34.273] E: Sending UART cmd(72) st 0
[2025-07-29 15:34:36.243] I: Syncing up on message 3
[2025-07-29 15:34:36.243] I: Sys init req
[2025-07-29 15:34:36.243] E: Sending UART cmd(3) st 0
[2025-07-29 15:34:36.243] I: System init Response
[2025-07-29 15:34:36.243] I: Received response of command id 3
[2025-07-29 15:34:36.243] I: Update sync timer
[2025-07-29 15:34:36.243] I: Received Sys Init Resp
[2025-07-29 15:34:36.243] I: battery mode 0
[2025-07-29 15:34:36.243] I: battery percentage 5a
[2025-07-29 15:34:36.243] I: battery type 1
[2025-07-29 15:34:36.243] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:34:36.724] I: Syncing up on message 5
[2025-07-29 15:34:36.724] I: Operating mode req
[2025-07-29 15:34:36.763] E: Sending UART cmd(5) st 0
[2025-07-29 15:34:36.763] I: Operating mode response
[2025-07-29 15:34:36.763] I: Received response of command id 5
[2025-07-29 15:34:36.763] I: Received Lock Op Mode Resp, mode 10, App state 31
[2025-07-29 15:34:36.763] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:34:36.763] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:34:36.763] I: Set Kwikset Lock App State 49
[2025-07-29 15:34:36.763] I: Matter is disabled
[2025-07-29 15:34:37.274] I: Syncing up on message 10
[2025-07-29 15:34:37.274] I: Lock state req
[2025-07-29 15:34:37.274] E: Sending UART cmd(10) st 0
[2025-07-29 15:34:37.274] I: Lock State Response
[2025-07-29 15:34:37.274] I: Received response of command id 10
[2025-07-29 15:34:37.274] I: Received Lock State Response, lock st: 12
[2025-07-29 15:34:37.274] I: Found matching nordic source of operation 0
[2025-07-29 15:34:37.274] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 15:34:37.274] I: Unlock action completed
[2025-07-29 15:34:37.274] I: Updating LockState attribute
[2025-07-29 15:34:37.274] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 15:34:37.723] I: Syncing up on message 20
[2025-07-29 15:34:37.723] I: Lock setting req
[2025-07-29 15:34:37.763] E: Sending UART cmd(20) st 0
[2025-07-29 15:34:37.763] I: Lock General Setting Response
[2025-07-29 15:34:37.763] I: Received response of command id 20
[2025-07-29 15:34:37.763] I: Received Lock General Setting resp
[2025-07-29 15:34:37.763] I: Matter Not Enabled do not set
[2025-07-29 15:34:38.273] I: Syncing up on message 51
[2025-07-29 15:34:38.273] I: Battery info req
[2025-07-29 15:34:38.273] E: Sending UART cmd(51) st 0
[2025-07-29 15:34:38.273] I: Received response of command id 51
[2025-07-29 15:34:38.273] I: Received Battery Info resp
[2025-07-29 15:34:38.273] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 15:34:38.273] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 15:34:38.273] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 15:34:38.733] I: All message synced.
[2025-07-29 15:35:02.213] I: STM system init timer expired, System Init Event not received from STM32
[2025-07-29 15:35:02.263] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 15:35:02.263] I: STM Pending =1, Redpine Pending = 1
[2025-07-29 15:35:02.263] I: STM Post OTA Pending
[2025-07-29 15:35:02.263] I: Redpine Post OTA Pending
[2025-07-29 15:35:02.263] E: Sending UART cmd(9e) st 0
[2025-07-29 15:35:02.263] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 15:35:02.263] I: 30191 [SWU]SMP BLE advertising started
[2025-07-29 15:35:02.263] I: 30196 [DL]DFU over SMP started
[2025-07-29 15:35:03.146] I: IMG Integrity Verified Successfully: 0
[2025-07-29 15:35:06.134] I: IMG Integrity Verified Successfully: 1
[2025-07-29 15:35:06.214] I: IMG Integrity Verified Successfully: 2
[2025-07-29 15:35:06.503] I: IMG Integrity Verified Successfully: 3
[2025-07-29 15:35:06.533] I: OTA Stage Change from (ff)->(32)
[2025-07-29 15:35:06.533] I: OTA device_id = 5 : DISCOVERY_REQ
[2025-07-29 15:35:06.643] I: SECURE_STM : IB_DEVICE_DISCOVERY_REQUEST (80) 
[2025-07-29 15:35:06.643] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 15:35:06.653] I: STM Current Firmware Version: 17 5 4 1a
[2025-07-29 15:35:06.653] I: STM New OTA Firmware Version = 17 5 4 1b
[2025-07-29 15:35:06.653] I: OTA device_id = 5 : FW_UPDATE_START_REQ
[2025-07-29 15:35:06.653] I: SECURE_STM : IB_FW_UPDATE_START_REQUEST (80)
[2025-07-29 15:35:13.000] I: STM OTA Progress = 10
[2025-07-29 15:35:19.303] I: STM OTA Progress = 20
[2025-07-29 15:35:25.614] I: STM OTA Progress = 30
[2025-07-29 15:35:32.034] I: STM OTA Progress = 40
[2025-07-29 15:35:38.334] I: STM OTA Progress = 50
[2025-07-29 15:35:44.654] I: STM OTA Progress = 60
[2025-07-29 15:35:50.971] I: STM OTA Progress = 70
[2025-07-29 15:35:57.284] I: STM OTA Progress = 80
[2025-07-29 15:36:03.604] I: STM OTA Progress = 90
[2025-07-29 15:36:09.924] I: STM OTA Progress = 100
[2025-07-29 15:36:10.614] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 15:36:10.614] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 15:36:28.254] I: Sending Sys Init Resp
[2025-07-29 15:36:28.254] I: Device is provisioned
[2025-07-29 15:36:28.254] I: network state 0
[2025-07-29 15:36:28.254] E: Sending UART cmd(3) st 0
[2025-07-29 15:36:28.254] I: Received DC App Config REQ
[2025-07-29 15:36:28.254] I: DC App Config Resp
[2025-07-29 15:36:28.254] I: Received DC config req
[2025-07-29 15:36:28.254] I: 80 70 03 00 10 10 08 00 |.p......
[2025-07-29 15:36:28.254] I: 50 1e                   |P.      
[2025-07-29 15:36:28.254] I: Matter enabled state 0
[2025-07-29 15:36:28.254] I: Get Matter Commission State
[2025-07-29 15:36:28.254] I: network state 0
[2025-07-29 15:36:28.264] I: network state 0
[2025-07-29 15:36:28.264] E: Sending UART cmd(70) st 0
[2025-07-29 15:36:28.284] I: Lock State Event
[2025-07-29 15:36:28.284] I: Received response of command id 10
[2025-07-29 15:36:28.324] I: Received Lock State event, lock st: 12
[2025-07-29 15:36:28.324] I: Found matching nordic source of operation 0
[2025-07-29 15:36:28.324] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 15:36:28.324] I: Unlock action completed
[2025-07-29 15:36:28.324] I: Updating LockState attribute
[2025-07-29 15:36:28.324] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 15:36:28.384] I: Received DC Eco Config REQ
[2025-07-29 15:36:28.384] I: DC Eco Config Resp
[2025-07-29 15:36:28.384] I: Received DC eco config req
[2025-07-29 15:36:28.384] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 15:36:28.384] I: c4 1e                   |..      
[2025-07-29 15:36:28.384] E: Sending UART cmd(72) st 0
[2025-07-29 15:36:28.564] I: General Lock Setting event
[2025-07-29 15:36:28.564] I: Received response of command id 20
[2025-07-29 15:36:28.564] I: Received Lock General Setting event
[2025-07-29 15:36:28.564] I: Matter Not Enabled do not set
[2025-07-29 15:36:28.661] I: Firmware Attribute event
[2025-07-29 15:36:28.661] I: Received response of command id 30
[2025-07-29 15:36:28.741] I: Hardware Attribute event
[2025-07-29 15:36:28.741] I: Received response of command id 31
[2025-07-29 15:36:28.803] I: Operating mode event
[2025-07-29 15:36:28.813] I: Received response of command id 5
[2025-07-29 15:36:28.813] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 15:36:28.813] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:36:28.813] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:36:28.813] I: Set Kwikset Lock App State 49
[2025-07-29 15:36:28.813] I: Matter is disabled
[2025-07-29 15:36:28.933] I: Battery Info event
[2025-07-29 15:36:28.933] I: Received response of command id 51
[2025-07-29 15:36:28.933] I: Received Battery info event
[2025-07-29 15:36:28.933] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 15:36:28.933] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 15:36:28.933] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 15:36:29.014] I: System info event
[2025-07-29 15:36:29.043] I: Received System Info Event
[2025-07-29 15:36:29.043] W: Time invalid, set time
[2025-07-29 15:36:29.043] I: Get system time
[2025-07-29 15:36:29.043] I: System Real time in seconds 373662943
[2025-07-29 15:36:29.043] I: Time sync status flag 0
[2025-07-29 15:36:29.043] E: Time not sync, keep default value
[2025-07-29 15:36:29.154] I: System init event
[2025-07-29 15:36:29.154] I: Received response of command id 3
[2025-07-29 15:36:29.154] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 15:36:29.154] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:36:29.154] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 15:36:29.154] I: STM Current Firmware Version: 17 5 4 1b
[2025-07-29 15:36:29.154] I: OTA device_id = 5 : FW_UPDATE_COMPLETE_REQ
[2025-07-29 15:36:29.154] I: SECURE_STM : IB_FW_UPDATE_COMPLETE_REQUEST (80) 
[2025-07-29 15:36:29.154] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 15:36:29.154] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 15:36:31.504] I: Sending Sys Init Resp
[2025-07-29 15:36:31.556] I: Device is provisioned
[2025-07-29 15:36:31.556] I: network state 0
[2025-07-29 15:36:31.556] E: Sending UART cmd(3) st 0
[2025-07-29 15:36:31.556] I: Received DC App Config REQ
[2025-07-29 15:36:31.556] I: DC App Config Resp
[2025-07-29 15:36:31.556] I: Received DC config req
[2025-07-29 15:36:31.556] I: 80 70 03 00 10 10 04 1b |.p......
[2025-07-29 15:36:31.556] I: 00 62                   |.b      
[2025-07-29 15:36:31.556] I: Matter enabled state 0
[2025-07-29 15:36:31.556] I: Get Matter Commission State
[2025-07-29 15:36:31.556] I: network state 0
[2025-07-29 15:36:31.559] I: network state 0
[2025-07-29 15:36:31.559] E: Sending UART cmd(70) st 0
[2025-07-29 15:36:31.614] I: Lock State Event
[2025-07-29 15:36:31.614] I: Received response of command id 10
[2025-07-29 15:36:31.614] I: Received Lock State event, lock st: 12
[2025-07-29 15:36:31.614] I: Found matching nordic source of operation 0
[2025-07-29 15:36:31.614] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 15:36:31.614] I: Unlock action completed
[2025-07-29 15:36:31.614] I: Updating LockState attribute
[2025-07-29 15:36:31.614] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 15:36:31.644] I: Received DC Eco Config REQ
[2025-07-29 15:36:31.644] I: DC Eco Config Resp
[2025-07-29 15:36:31.679] I: Received DC eco config req
[2025-07-29 15:36:31.679] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 15:36:31.679] I: c4 62                   |.b      
[2025-07-29 15:36:31.679] E: Sending UART cmd(72) st 0
[2025-07-29 15:36:31.813] I: General Lock Setting event
[2025-07-29 15:36:31.843] I: Received response of command id 20
[2025-07-29 15:36:31.843] I: Received Lock General Setting event
[2025-07-29 15:36:31.843] I: Matter Not Enabled do not set
[2025-07-29 15:36:31.934] I: Firmware Attribute event
[2025-07-29 15:36:31.934] I: Received response of command id 30
[2025-07-29 15:36:32.013] I: Hardware Attribute event
[2025-07-29 15:36:32.013] I: Received response of command id 31
[2025-07-29 15:36:32.084] I: Operating mode event
[2025-07-29 15:36:32.084] I: Received response of command id 5
[2025-07-29 15:36:32.084] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 15:36:32.084] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:36:32.084] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:36:32.084] I: Set Kwikset Lock App State 49
[2025-07-29 15:36:32.084] I: Matter is disabled
[2025-07-29 15:36:32.204] I: Battery Info event
[2025-07-29 15:36:32.204] I: Received response of command id 51
[2025-07-29 15:36:32.204] I: Received Battery info event
[2025-07-29 15:36:32.204] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 15:36:32.204] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 15:36:32.204] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 15:36:32.284] I: System info event
[2025-07-29 15:36:32.284] I: Received System Info Event
[2025-07-29 15:36:32.313] W: Time invalid, set time
[2025-07-29 15:36:32.313] I: Get system time
[2025-07-29 15:36:32.313] I: System Real time in seconds 373662943
[2025-07-29 15:36:32.313] I: Time sync status flag 0
[2025-07-29 15:36:32.313] E: Time not sync, keep default value
[2025-07-29 15:36:32.393] I: System init event
[2025-07-29 15:36:32.393] I: Received response of command id 3
[2025-07-29 15:36:32.393] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 15:36:32.393] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:36:32.393] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 15:36:32.393] I: STM Current Firmware Version: 17 5 4 1b
[2025-07-29 15:36:32.393] I: STM New OTA Firmware Version = 17 5 4 1b
[2025-07-29 15:36:32.393] I: STM Secure OTA Successful
[2025-07-29 15:36:32.504] I: Cleared STM OTA Meta Data
[2025-07-29 15:36:32.504] I: OTA Stage Change from (32)->(33)
[2025-07-29 15:36:32.504] I: Redpine OTA started
[2025-07-29 15:36:32.504] I: OTA Stage Change from (33)->(34)
[2025-07-29 15:36:32.504] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 15:36:39.494] I: STM Reset Count 0
[2025-07-29 15:36:39.524] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 15:36:39.524] I: STM_QSPI : IB_DEVICE_DISCOVERY_REQUEST (80)
[2025-07-29 15:36:39.524] I: OTA device_id = 4 : FW_VERSION_REQ
[2025-07-29 15:36:39.524] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 15:36:39.524] I: Redpine Current Firmware Version: 2.c.0.3
[2025-07-29 15:36:39.553] I: Redpine New OTA Firmware Version = 2 c 0 3
[2025-07-29 15:36:39.553] I: Skip Redpine OTA, Older OTA Version Request Received
[2025-07-29 15:36:39.663] I: Clear Redpine OTA Meta Data
[2025-07-29 15:36:39.663] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 15:36:39.663] I: STM Pending =2, Redpine Pending = 2
[2025-07-29 15:36:39.663] I: PN76 IMG 1 Post OTA Pending
[2025-07-29 15:36:39.663] E: Sending UART cmd(9e) st 0
[2025-07-29 15:36:39.663] I: 127606 [SWU]Software update is already enabled
[2025-07-29 15:36:39.744] I: IMG Integrity Verified Successfully: 2
[2025-07-29 15:36:40.080] I: IMG Integrity Verified Successfully: 3
[2025-07-29 15:36:40.080] I: OTA Stage Change from (34)->(3a)
[2025-07-29 15:36:40.080] I: PN76_IMG1_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 15:36:40.080] I: PN76_IMG Update from OTA Task Event
[2025-07-29 15:36:40.080] I: 
[2025-07-29 15:36:40.080] 
[2025-07-29 15:36:40.080] --------------- UPDATING PN7642 NXP FIRMWARE --------------------
[2025-07-29 15:36:40.080] 
[2025-07-29 15:36:40.080] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 15:36:40.124] I: pNXPFWInfo->img_offset = 0x35149a
[2025-07-29 15:36:40.124] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 15:36:40.124] I: Reading version of firmware in QSPI flash: MetaData 0x3f60217
[2025-07-29 15:36:40.124] I: NXP FW Version 2 f6 : 2 f6
[2025-07-29 15:36:40.124] I: PN76 NXP FW VERSION IS EQUAL
[2025-07-29 15:36:40.124] I: 
[2025-07-29 15:36:40.124] PN7642 Firmware of type 0 Successfully Updated !!!
[2025-07-29 15:36:40.244] I: Cleared PN76 Img1 OTA Meta Data
[2025-07-29 15:36:40.244] I: OTA Stage Change from (3a)->(3a)
[2025-07-29 15:36:40.253] I: PN76_IMG2_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 15:36:40.254] I: PN76_IMG Update from OTA Task Event
[2025-07-29 15:36:40.254] I: 
[2025-07-29 15:36:40.254] 
[2025-07-29 15:36:40.254] --------------- UPDATING PN7642 APPLICATION FIRMWARE -------------
[2025-07-29 15:36:40.254] 
[2025-07-29 15:36:40.254] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 15:36:40.284] I: pCustAppFWInfo->img_offset = 0x35c28c
[2025-07-29 15:36:40.284] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 15:36:40.284] I: Reading version of firmware in QSPI flash: MetaData 0x3f60217
[2025-07-29 15:36:40.284] I: PN76 NXP APP FW VERSION IS HIGHER
[2025-07-29 15:36:40.594] I: ----> PN7642 OTA Progress = 10 %
[2025-07-29 15:36:40.864] I: ----> PN7642 OTA Progress = 20 %
[2025-07-29 15:36:41.124] I: ----> PN7642 OTA Progress = 30 %
[2025-07-29 15:36:41.374] I: ----> PN7642 OTA Progress = 40 %
[2025-07-29 15:36:41.644] I: ----> PN7642 OTA Progress = 50 %
[2025-07-29 15:36:41.903] I: ----> PN7642 OTA Progress = 60 %
[2025-07-29 15:36:42.156] I: ----> PN7642 OTA Progress = 70 %
[2025-07-29 15:36:42.433] I: ----> PN7642 OTA Progress = 80 %
[2025-07-29 15:36:42.684] I: ----> PN7642 OTA Progress = 90 %
[2025-07-29 15:36:42.944] I: ----> PN7642 OTA Progress = 100 %
[2025-07-29 15:36:42.974] I: Whole pn7642 FW Image downloaded ....
[2025-07-29 15:36:42.974] I: 
[2025-07-29 15:36:42.974] 
[2025-07-29 15:36:42.974] I: 
[2025-07-29 15:36:42.974] PN7642 Firmware of type 1 Successfully Updated !!!
[2025-07-29 15:36:43.054] I: Cleared PN76 Img2 OTA Meta Data
[2025-07-29 15:36:43.154] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 15:36:43.154] I: NFC Boot Event PN7642 FW VERSION 17.01.00.03
[2025-07-29 15:36:43.154] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 15:36:43.154] I: 
[2025-07-29 15:36:43.154] Boot Event Received
[2025-07-29 15:36:43.154] 
[2025-07-29 15:36:43.154] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 15:36:43.154] 
[2025-07-29 15:36:43.154] I: OTA Stage Change from (3a)->(3b)
[2025-07-29 15:36:43.154] I: post_stm_reset_event : init_pending_ota_update
[2025-07-29 15:36:43.154] I: All pending FW Updates are completed.
[2025-07-29 15:36:43.154] I: STM32 Reset Count = 0
[2025-07-29 15:36:43.163] I: REBOOT_STM: Send STM32 Reboot Command, Count (0)
[2025-07-29 15:36:45.534] I: Sending Sys Init Resp
[2025-07-29 15:36:45.534] I: Device is provisioned
[2025-07-29 15:36:45.534] I: network state 0
[2025-07-29 15:36:45.534] E: Sending UART cmd(3) st 0
[2025-07-29 15:36:45.534] I: Received DC App Config REQ
[2025-07-29 15:36:45.534] I: DC App Config Resp
[2025-07-29 15:36:45.534] I: Received DC config req
[2025-07-29 15:36:45.534] I: 80 70 03 00 10 10 00 03 |.p......
[2025-07-29 15:36:45.534] I: 00 62                   |.b      
[2025-07-29 15:36:45.534] I: Matter enabled state 0
[2025-07-29 15:36:45.534] I: Get Matter Commission State
[2025-07-29 15:36:45.534] I: network state 0
[2025-07-29 15:36:45.534] I: network state 0
[2025-07-29 15:36:45.534] E: Sending UART cmd(70) st 0
[2025-07-29 15:36:45.594] I: Lock State Event
[2025-07-29 15:36:45.594] I: Received response of command id 10
[2025-07-29 15:36:45.594] I: Received Lock State event, lock st: 12
[2025-07-29 15:36:45.594] I: Found matching nordic source of operation 0
[2025-07-29 15:36:45.594] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 15:36:45.594] I: Unlock action completed
[2025-07-29 15:36:45.594] I: Updating LockState attribute
[2025-07-29 15:36:45.594] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 15:36:45.624] I: Received DC Eco Config REQ
[2025-07-29 15:36:45.654] I: DC Eco Config Resp
[2025-07-29 15:36:45.654] I: Received DC eco config req
[2025-07-29 15:36:45.654] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 15:36:45.654] I: c4 62                   |.b      
[2025-07-29 15:36:45.654] E: Sending UART cmd(72) st 0
[2025-07-29 15:36:45.824] I: General Lock Setting event
[2025-07-29 15:36:45.824] I: Received response of command id 20
[2025-07-29 15:36:45.824] I: Received Lock General Setting event
[2025-07-29 15:36:45.824] I: Matter Not Enabled do not set
[2025-07-29 15:36:45.926] I: Firmware Attribute event
[2025-07-29 15:36:45.943] I: Received response of command id 30
[2025-07-29 15:36:46.007] I: Hardware Attribute event
[2025-07-29 15:36:46.007] I: Received response of command id 31
[2025-07-29 15:36:46.074] I: Operating mode event
[2025-07-29 15:36:46.074] I: Received response of command id 5
[2025-07-29 15:36:46.074] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 15:36:46.074] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:36:46.074] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:36:46.074] I: Set Kwikset Lock App State 49
[2025-07-29 15:36:46.074] I: Matter is disabled
[2025-07-29 15:36:46.194] I: Battery Info event
[2025-07-29 15:36:46.194] I: Received response of command id 51
[2025-07-29 15:36:46.194] I: Received Battery info event
[2025-07-29 15:36:46.194] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 15:36:46.194] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 15:36:46.194] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 15:36:46.274] I: System info event
[2025-07-29 15:36:46.308] I: Received System Info Event
[2025-07-29 15:36:46.308] W: Time invalid, set time
[2025-07-29 15:36:46.308] I: Get system time
[2025-07-29 15:36:46.308] I: System Real time in seconds 373662943
[2025-07-29 15:36:46.308] I: Time sync status flag 0
[2025-07-29 15:36:46.314] E: Time not sync, keep default value
[2025-07-29 15:36:46.364] I: System init event
[2025-07-29 15:36:46.364] I: Received response of command id 3
[2025-07-29 15:36:46.364] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 15:36:46.364] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:36:53.143] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 15:36:53.194] I: stop_ota_finalization_timer
[2025-07-29 15:36:53.204] I: After OTAU, Redpine Firmware Version: 2.c.0.3
[2025-07-29 15:36:53.204] I: Redpine New OTA Firmware Version = 2 c 0 3
[2025-07-29 15:36:53.204] I: After OTAU, Secure STM Firmware Version: 17 5 4 1b
[2025-07-29 15:36:53.204] I: Send Op Mode command to release Redpine BLE and WiFI
[2025-07-29 15:36:53.204] I: Operating Mode Command: Mode:10, State:f0
[2025-07-29 15:36:53.204] E: Sending UART cmd(5) st 0
[2025-07-29 15:36:53.334] I: Operating mode event
[2025-07-29 15:36:53.334] I: Received response of command id 5
[2025-07-29 15:36:53.334] I: Received Lock Op Mode Event, mode 10, App state 10
[2025-07-29 15:36:53.334] I: Lock Current Mode : 10, Lock Current State = 10
[2025-07-29 15:36:53.334] I: stop_ota_finalization_timer
[2025-07-29 15:36:53.334] I: STM32 HALO APP STATE IS ACTIVATED NORMAL
[2025-07-29 15:36:53.334] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:36:53.334] I: Set Kwikset Lock App State 16
[2025-07-29 15:36:53.334] I: Matter enabled state 0
[2025-07-29 15:36:53.334] I: Matter is disabled
[2025-07-29 15:36:53.334] I: OTA_HOUSEKEEPING
[2025-07-29 15:36:53.334] I: OTA Stage Change from (3b)->(80)
[2025-07-29 15:36:53.346] I: Start Erasing OTA bundle from nRF External Flash
[2025-07-29 15:36:59.074] I: System info event
[2025-07-29 15:36:59.074] I: Received System Info Event
[2025-07-29 15:36:59.074] I: Time is set in STM
[2025-07-29 15:37:02.374] I: STM Boot Up Properly, Stopped STM Reboot Timer
[2025-07-29 15:37:53.934] I: Bundle Image Erased from nRF External Flash: 0
[2025-07-29 15:37:54.014] I: OTAU Completed Successfully
[2025-07-29 15:37:54.134] I: Cleared OTA Meta Data
[2025-07-29 15:37:54.134] I: OTA Stage Change from (80)->(90)
[2025-07-29 15:37:56.136] I: All message synced.
[2025-07-29 15:38:09.124] I: STOP BLE Advertisment
[2025-07-29 15:38:09.144] I: 217078 [DL]DFU over SMP stopped
[2025-07-29 15:38:09.144] E: Sending UART cmd(9e) st 0
[2025-07-29 15:40:54.154] I: Updated ota meta data
[2025-07-29 15:40:54.174] I: Operating Mode Command: Mode:10, State:34
[2025-07-29 15:40:54.174] E: Sending UART cmd(5) st 0
[2025-07-29 15:40:54.234] I: Operating mode event
[2025-07-29 15:40:54.234] I: Received response of command id 5
[2025-07-29 15:40:54.234] I: Received Lock Op Mode Event, mode 10, App state 34
[2025-07-29 15:40:54.234] I: Lock Current Mode : 10, Lock Current State = 34
[2025-07-29 15:40:54.234] I: STM32 HALO APP STATE IS BLE OTAU TRANSFER
[2025-07-29 15:40:54.234] E: Sending UART cmd(9e) st 0
[2025-07-29 15:40:54.234] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 15:40:54.234] I: 382164 [SWU]SMP BLE advertising started
[2025-07-29 15:40:54.234] I: 382169 [DL]DFU over SMP started
[2025-07-29 15:40:54.234] I: OTA Stage Change from (90)->(11)
[2025-07-29 15:40:54.234] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:40:54.234] I: Set Kwikset Lock App State 52
[2025-07-29 15:40:54.244] I: Matter is disabled
[2025-07-29 15:41:09.564] I: 397492 [DL]DFU-BLE-Connected
[2025-07-29 15:41:09.564] I: stop_ble_advertisment_timer
[2025-07-29 15:41:09.564] I: 397497 [DL]Current number of connections: 1/1
[2025-07-29 15:41:09.564] I: BLE Connected
[2025-07-29 15:41:09.774] I: 397713 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 15:41:09.774] I: 397717 [DL]Current number of connections: 0/1
[2025-07-29 15:41:09.774] I: BLE Disconnected: 13
[2025-07-29 15:41:13.634] I: 401562 [DL]DFU-BLE-Connected
[2025-07-29 15:41:13.634] I: stop_ble_advertisment_timer
[2025-07-29 15:41:13.634] I: 401567 [DL]Current number of connections: 1/1
[2025-07-29 15:41:13.634] I: BLE Connected
[2025-07-29 15:41:13.834] I: 401785 [DL]DFU Image upload started
[2025-07-29 15:41:14.656] I: Connection parameters updated.
[2025-07-29 15:41:14.676]  interval: 9, latency: 0, timeout: 42
[2025-07-29 15:41:21.344] I: OTA Stage Change from (11)->(12)
[2025-07-29 15:41:21.344] I: 409282 [DL]Image 0 download completed successfully
[2025-07-29 15:41:21.424] I: 409380 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 15:41:21.447] I: 409383 [DL]Current number of connections: 0/1
[2025-07-29 15:41:21.447] I: BLE Disconnected: 13
[2025-07-29 15:41:33.484] I: 421414 [DL]DFU-BLE-Connected
[2025-07-29 15:41:33.484] I: stop_ble_advertisment_timer
[2025-07-29 15:41:33.484] I: 421420 [DL]Current number of connections: 1/1
[2025-07-29 15:41:33.484] I: BLE Connected
[2025-07-29 15:41:33.704] I: 421651 [DL]DFU Image upload started
[2025-07-29 15:41:34.504] I: Connection parameters updated.
[2025-07-29 15:41:34.524]  interval: 9, latency: 0, timeout: 42
[2025-07-29 15:42:10.634] I: OTA Stage Change from (12)->(13)
[2025-07-29 15:42:10.634] I: 458571 [DL]Image 1 download completed successfully
[2025-07-29 15:42:10.734] I: 458673 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 15:42:10.734] I: 458677 [DL]Current number of connections: 0/1
[2025-07-29 15:42:10.734] I: BLE Disconnected: 13
[2025-07-29 15:42:17.914] I: 465851 [DL]DFU-BLE-Connected
[2025-07-29 15:42:17.914] I: stop_ble_advertisment_timer
[2025-07-29 15:42:17.914] I: 465856 [DL]Current number of connections: 1/1
[2025-07-29 15:42:17.914] I: BLE Connected
[2025-07-29 15:42:18.144] I: 466096 [DL]DFU Image upload started
[2025-07-29 15:42:18.974] I: Connection parameters updated.
[2025-07-29 15:42:18.974]  interval: 9, latency: 0, timeout: 42
[2025-07-29 15:44:09.704] I: OTA Stage Change from (13)->(14)
[2025-07-29 15:44:09.704] I: 577662 [DL]Image 2 download completed successfully
[2025-07-29 15:44:09.824] I: 577764 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 15:44:09.824] I: 577768 [DL]Current number of connections: 0/1
[2025-07-29 15:44:09.824] I: BLE Disconnected: 13
[2025-07-29 15:44:17.254] I: 585186 [DL]DFU-BLE-Connected
[2025-07-29 15:44:17.254] I: stop_ble_advertisment_timer
[2025-07-29 15:44:17.254] I: 585191 [DL]Current number of connections: 1/1
[2025-07-29 15:44:17.254] I: BLE Connected
[2025-07-29 15:44:17.484] I: 585422 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 15:44:17.484] I: 585425 [DL]Current number of connections: 0/1
[2025-07-29 15:44:17.484] I: BLE Disconnected: 13
[2025-07-29 15:44:21.324] I: 589281 [DL]DFU-BLE-Connected
[2025-07-29 15:44:21.350] I: stop_ble_advertisment_timer
[2025-07-29 15:44:21.350] I: 589286 [DL]Current number of connections: 1/1
[2025-07-29 15:44:21.350] I: BLE Connected
[2025-07-29 15:44:21.554] I: 589490 [DL]DFU_ImgConfirmHandler: Nordic Image Confirmed by MCUMgr
[2025-07-29 15:44:21.574] I: 589517 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 15:44:21.574] I: 589520 [DL]Current number of connections: 0/1
[2025-07-29 15:44:21.574] I: BLE Disconnected: 13
[2025-07-29 15:44:28.984] I: 596938 [DL]DFU-BLE-Connected
[2025-07-29 15:44:28.984] I: stop_ble_advertisment_timer
[2025-07-29 15:44:29.004] I: 596944 [DL]Current number of connections: 1/1
[2025-07-29 15:44:29.004] I: BLE Connected
[2025-07-29 15:44:29.197] I: 597156 [DL]DFU_ImgConfirmHandler: Nordic Image Confirmed by MCUMgr
[2025-07-29 15:44:29.234] I: 597189 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 15:44:29.234] I: 597193 [DL]Current number of connections: 0/1
[2025-07-29 15:44:29.254] I: BLE Disconnected: 13
[2025-07-29 15:44:38.974] I: 606910 [DL]DFU-BLE-Connected
[2025-07-29 15:44:38.974] I: stop_ble_advertisment_timer
[2025-07-29 15:44:38.974] I: 606915 [DL]Current number of connections: 1/1
[2025-07-29 15:44:38.974] I: BLE Connected
[2025-07-29 15:44:39.164] I: STM Pending =0, Redpine Pending = 0
[2025-07-29 15:44:39.274] I: Count = 4
[2025-07-29 15:44:39.274] I: dfu_header_data.image_count: 4
[2025-07-29 15:44:40.024] I: Connection parameters updated.
[2025-07-29 15:44:40.024]  interval: 9, latency: 0, timeout: 42
[2025-07-29 15:44:40.174] I: IMG Integrity Verified Successfully: 0
[2025-07-29 15:44:43.164] I: IMG Integrity Verified Successfully: 1
[2025-07-29 15:44:43.247] I: IMG Integrity Verified Successfully: 2
[2025-07-29 15:44:43.575] I: IMG Integrity Verified Successfully: 3
[2025-07-29 15:44:43.595] I: OTA Bundle(STM32 + RS9116 + PN76) image integrity Verified
[2025-07-29 15:44:43.595] I: OTA Stage Change from (14)->(30)
[2025-07-29 15:44:43.674] I: Updated ota meta data
[2025-07-29 15:44:43.735] I: Operating Mode Command: Mode:10, State:31
[2025-07-29 15:44:43.735] E: Sending UART cmd(5) st 0
[2025-07-29 15:44:43.735] I: Operating mode event
[2025-07-29 15:44:43.735] I: Received response of command id 5
[2025-07-29 15:44:43.735] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 15:44:43.735] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:44:43.735] I: STM OTAU Pending: Reset Nordic Triggered
[2025-07-29 15:44:43.735] I: OTA Stage Change from (30)->(30)
[2025-07-29 15:44:43.735] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:44:43.735] I: Set Kwikset Lock App State 49
[2025-07-29 15:44:43.735] I: Matter is disabled
[2025-07-29 15:44:43.794] I: 611732 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 15:44:43.794] I: 611735 [DL]Current number of connections: 0/1
[2025-07-29 15:44:43.794] I: BLE Disconnected: 13
[2025-07-29 15:45:31.234] 
[2025-07-29 15:45:31.234] uart:~$ *** Booting My Application v23.55.3-2f9996e8c87c ***
[2025-07-29 15:45:31.275] *** Using nRF Connect SDK v2.8.0-a2386bfc8401 ***
[2025-07-29 15:45:31.275] *** Using Zephyr OS v3.7.99-0bc3393fb112 ***
[2025-07-29 15:45:31.275] I: KWIKSET HALO 3 PLUS VERSION: 17.37.03.03
[2025-07-29 15:45:31.275] I: 51 [DL]BLE address: CC:8B:D2:9D:1D:00
[2025-07-29 15:45:31.284] I: No users indexes stored
[2025-07-29 15:45:31.284] I: No stored indexes for credential of type: 1
[2025-07-29 15:45:31.404] I: No stored indexes for credential of type: 2
[2025-07-29 15:45:31.404] I: ========== User Index: 0x01 User ID: 0xffffffff ==========
[2025-07-29 15:45:31.404] I: ========== User Index: 0x02 User ID: 0xffffffff ==========
[2025-07-29 15:45:31.404] I: ========== User Index: 0x03 User ID: 0xffffffff ==========
[2025-07-29 15:45:31.405] I: ========== User Index: 0x04 User ID: 0xffffffff ==========
[2025-07-29 15:45:31.405] I: ========== User Index: 0x05 User ID: 0xffffffff ==========
[2025-07-29 15:45:31.405] I: ========== User Index: 0x06 User ID: 0xffffffff ==========
[2025-07-29 15:45:31.405] I: ========== User Index: 0x07 User ID: 0xffffffff ==========
[2025-07-29 15:45:31.405] I: ========== User Index: 0x08 User ID: 0xffffffff ==========
[2025-07-29 15:45:31.405] I: ========== User Index: 0x09 User ID: 0xffffffff ==========
[2025-07-29 15:45:31.405] I: ========== User Index: 0x0a User ID: 0xffffffff ==========
[2025-07-29 15:45:31.414] I: ========== User Index: 0x0b User ID: 0xffffffff ==========
[2025-07-29 15:45:31.414] I: Board config kwiksetmdb_nrf5340_cpuapp
[2025-07-29 15:45:31.414] I: IMAGE_VERSION 17370303
[2025-07-29 15:45:31.414] I: build time: Jul 29 2025 12:54:31
[2025-07-29 15:45:31.414] I: 158 [DL]CHIP task running
[2025-07-29 15:45:31.414] I: Init CHIP stack
[2025-07-29 15:45:31.414] I: 164 [DL]OpenThread started: OK
[2025-07-29 15:45:31.414] I: 167 [DL]Setting OpenThread device type to SLEEPY END DEVICE
[2025-07-29 15:45:31.414] I: 173 [SWU]New firmware image confirmed
[2025-07-29 15:45:31.414] I: 177 [SWU]DFU_BLEAdvertising_Init
[2025-07-29 15:45:31.815] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 15:45:31.815] I: NFC Boot Event PN7642 FW VERSION 17.01.00.03
[2025-07-29 15:45:31.815] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 15:45:31.815] I: 
[2025-07-29 15:45:31.815] Boot Event Received
[2025-07-29 15:45:31.815] 
[2025-07-29 15:45:31.815] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 15:45:31.815] 
[2025-07-29 15:45:31.815] I: 260 [SVR]Subscription persistence not supported
[2025-07-29 15:45:31.815] I: 265 [SVR]Server initializing...
[2025-07-29 15:45:31.815] I: 268 [TS]Last Known Good Time: 2023-10-14T01:16:48
[2025-07-29 15:45:31.815] I: 273 [DMG]AccessControl: initializing
[2025-07-29 15:45:31.819] I: 277 [DMG]Examples::AccessControlDelegate::Init
[2025-07-29 15:45:31.819] I: 281 [DMG]AccessControl: setting
[2025-07-29 15:45:31.819] I: 284 [DMG]DefaultAclStorage: initializing
[2025-07-29 15:45:31.819] I: 288 [DMG]DefaultAclStorage: 0 entries loaded
[2025-07-29 15:45:31.834] E: 293 [IN]IPV6_PKTINFO failed: 109
[2025-07-29 15:45:31.834] I: 298 [ZCL]Using ZAP configuration...
[2025-07-29 15:45:31.834] I: 303 [DMG]AccessControlCluster: initializing
[2025-07-29 15:45:31.834] Unhandled cluster ID: 0x  30
[2025-07-29 15:45:31.834] 
[2025-07-29 15:45:31.834] ===== Attribute Received are: Cluster=30 Attribute=0 Value=0 =====
[2025-07-29 15:45:31.834] I: 318 [ZCL]Emit DSTTableEmpty event [ep=0]
[2025-07-29 15:45:31.834] I: 321 [ZCL]Initiating Admin Commissioning cluster.
[2025-07-29 15:45:31.834] I: 326 [ZCL]Door Lock server initialized
[2025-07-29 15:45:31.834] E: 330 [ZCL]DeviceInfoProvider is not registered
[2025-07-29 15:45:31.834] E: 334 [ZCL]Failed to read calendar type with error: 0x86
[2025-07-29 15:45:31.844] Unhandled cluster ID: 0x   3
[2025-07-29 15:45:31.844] 
[2025-07-29 15:45:31.845] ===== Attribute Received are: Cluster=3 Attribute=1 Value=3 =====
[2025-07-29 15:45:31.854] I: 348 [ZCL]Door Lock cluster initialized at endpoint #1
[2025-07-29 15:45:31.854] ===== Attribute Received are: Cluster=101 Attribute=0 Value=255 =====
[2025-07-29 15:45:31.854] ===== Attribute Received are: Cluster=101 Attribute=2 Value=1 =====
[2025-07-29 15:45:31.854] ===== Attribute Received are: Cluster=101 Attribute=1 Value=0 =====
[2025-07-29 15:45:31.854] ===== Attribute Received are: Cluster=101 Attribute=11 Value=11 =====
[2025-07-29 15:45:31.854] ===== Attribute Received are: Cluster=101 Attribute=12 Value=35 =====
[2025-07-29 15:45:31.854] ===== Attribute Received are: Cluster=101 Attribute=13 Value=35 =====
[2025-07-29 15:45:31.854] ===== Attribute Received are: Cluster=101 Attribute=1c Value=35 =====
[2025-07-29 15:45:31.854] ===== Attribute Received are: Cluster=101 Attribute=19 Value=80 =====
[2025-07-29 15:45:31.854] I: 401 [DIS]Updating services using commissioning mode 0
[2025-07-29 15:45:31.854] E: 406 [DIS]Failed to remove advertised services: 3
[2025-07-29 15:45:31.874] E: 411 [DIS]Failed to finalize service update: 3
[2025-07-29 15:45:31.874] I: 415 [IN]CASE Server enabling CASE session setups
[2025-07-29 15:45:31.874] I: 420 [SVR]Joining Multicast groups
[2025-07-29 15:45:31.874] I: 424 [SVR]Server Listening...
[2025-07-29 15:45:31.874] I: 426 [DL]Device Configuration:
[2025-07-29 15:45:31.874] I: 429 [DL]  Serial Number: 1789AE57B32427844F
[2025-07-29 15:45:31.874] I: 434 [DL]  Vendor Id: 5153 (0x1421)
[2025-07-29 15:45:31.874] I: 437 [DL]  Product Id: 66 (0x42)
[2025-07-29 15:45:31.874] I: Get product name B, len 0
[2025-07-29 15:45:31.874] I: 443 [DL]  Product Name: B
[2025-07-29 15:45:31.874] I: 445 [DL]  Hardware Version: 1
[2025-07-29 15:45:31.879] I: 448 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 75655451
[2025-07-29 15:45:31.879] I: 453 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 776 (0x308)
[2025-07-29 15:45:31.879] I: 460 [DL]  Manufacturing Date: 2025-07-24
[2025-07-29 15:45:31.901] I: 464 [DL]  Device Type: 10 (0xA)
[2025-07-29 15:45:31.901] I: 467 [SVR]SetupQRCode: [MT:-QWJ08DB00.I2N6SM10]
[2025-07-29 15:45:31.901] I: 471 [SVR]Copy/paste the below URL in a browser to see the QR Code:
[2025-07-29 15:45:31.901] I: 477 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-QWJ08DB00.I2N6SM10
[2025-07-29 15:45:31.901] I: 486 [SVR]Manual pairing code: [05967546175]
[2025-07-29 15:45:31.901] I: STM32 device number: 
[2025-07-29 15:45:31.901] I: 31 37 38 39 41 45 35 37 |1789AE57
[2025-07-29 15:45:31.901] I: 42 33 32 34 32 37 38 34 |B3242784
[2025-07-29 15:45:31.901] I: 34 46                   |4F      
[2025-07-29 15:45:31.901] I: SKU number: 
[2025-07-29 15:45:31.901] I: 4b 31 37 2d 30 31       |K17-01  
[2025-07-29 15:45:31.901] I: WO number: 
[2025-07-29 15:45:31.901] I: 30 30 30 30 30 30 30 30 |00000000
[2025-07-29 15:45:31.901] I: 30                      |0       
[2025-07-29 15:45:31.914] I: Manuf Date: 
[2025-07-29 15:45:31.914] I: 32 30 32 35 2d 30 37 2d |2025-07-
[2025-07-29 15:45:31.914] I: 32 34 00 00 00 00       |24....  
[2025-07-29 15:45:31.914] I: Prod config length 6
[2025-07-29 15:45:31.914] I: Product Config: 
[2025-07-29 15:45:31.914] I: 30 78 30 30 30 31       |0x0001  
[2025-07-29 15:45:31.914] I: Prod Config Read 1
[2025-07-29 15:45:31.914] I: User intend flow enabled, set commissioning flow to kUserActionRequired
[2025-07-29 15:45:31.914] I: Factory Data Version length 2
[2025-07-29 15:45:31.914] I: Factory Data Ver: 
[2025-07-29 15:45:31.914] I: 30 31                   |01      
[2025-07-29 15:45:31.914] I: Payload value in string format: MT:-QWJ04TC00.I2N60Q4P0ILT70VYYR1JFSK14YDB0-0LJ1-0LJ1-0LJ1IHLC0AUZL1XIKJ17AZL1UV700CXYR1K6Y12NNZR1YC-L1-2ZR1OADO1KB40
[2025-07-29 15:45:31.914] I: Pairing Code value in string format: 459675461705153000660
[2025-07-29 15:45:31.914] I: ============== Updating product finish and color to 15, 2, product Name Halo Select Plus ==============
[2025-07-29 15:45:31.934] E: 577 [DL]Long dispatch time: 416 ms, for event type 2
[2025-07-29 15:45:31.934] ===== Attribute Received are: Cluster=101 Attribute=0 Value=1 =====
[2025-07-29 15:45:33.364] I: Syncing up on message 9a
[2025-07-29 15:45:33.364] I: STM32 counter to 1
[2025-07-29 15:45:33.404] I: BLE Device ID: 2784
[2025-07-29 15:45:33.404] I: Device is provisioned
[2025-07-29 15:45:33.404] I: network state 0
[2025-07-29 15:45:33.404] E: Sending UART cmd(3) st 0
[2025-07-29 15:45:33.404] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 15:45:33.404] I: Received response of command id 9a
[2025-07-29 15:45:33.404] I: Command 0x9A Received
[2025-07-29 15:45:33.404] I: Firmware Attribute event
[2025-07-29 15:45:33.435] I: Received response of command id 30
[2025-07-29 15:45:33.435] I: Received DC Eco Config REQ
[2025-07-29 15:45:33.435] I: DC Eco Config Resp
[2025-07-29 15:45:33.435] I: Received DC eco config req
[2025-07-29 15:45:33.435] I: 80 72 03 00 10 00 04 1a |.r......
[2025-07-29 15:45:33.435] I: 17 05                   |..      
[2025-07-29 15:45:33.435] E: Sending UART cmd(72) st 0
[2025-07-29 15:45:35.405] I: Syncing up on message 3
[2025-07-29 15:45:35.405] I: Sys init req
[2025-07-29 15:45:35.405] E: Sending UART cmd(3) st 0
[2025-07-29 15:45:35.405] I: System init Response
[2025-07-29 15:45:35.405] I: Received response of command id 3
[2025-07-29 15:45:35.405] I: Update sync timer
[2025-07-29 15:45:35.405] I: Received Sys Init Resp
[2025-07-29 15:45:35.405] I: battery mode 0
[2025-07-29 15:45:35.405] I: battery percentage 5a
[2025-07-29 15:45:35.405] I: battery type 1
[2025-07-29 15:45:35.405] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:45:35.884] I: Syncing up on message 5
[2025-07-29 15:45:35.884] I: Operating mode req
[2025-07-29 15:45:35.924] E: Sending UART cmd(5) st 0
[2025-07-29 15:45:35.924] I: Operating mode response
[2025-07-29 15:45:35.924] I: Received response of command id 5
[2025-07-29 15:45:35.924] I: Received Lock Op Mode Resp, mode 10, App state 31
[2025-07-29 15:45:35.924] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:45:35.924] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:45:35.924] I: Set Kwikset Lock App State 49
[2025-07-29 15:45:35.924] I: Matter is disabled
[2025-07-29 15:45:36.434] I: Syncing up on message 10
[2025-07-29 15:45:36.434] I: Lock state req
[2025-07-29 15:45:36.434] E: Sending UART cmd(10) st 0
[2025-07-29 15:45:36.434] I: Lock State Response
[2025-07-29 15:45:36.434] I: Received response of command id 10
[2025-07-29 15:45:36.434] I: Received Lock State Response, lock st: 12
[2025-07-29 15:45:36.434] I: Found matching nordic source of operation 0
[2025-07-29 15:45:36.434] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 15:45:36.434] I: Unlock action completed
[2025-07-29 15:45:36.434] I: Updating LockState attribute
[2025-07-29 15:45:36.434] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 15:45:36.884] I: Syncing up on message 20
[2025-07-29 15:45:36.945] I: Lock setting req
[2025-07-29 15:45:36.945] E: Sending UART cmd(20) st 0
[2025-07-29 15:45:36.945] I: Lock General Setting Response
[2025-07-29 15:45:36.945] I: Received response of command id 20
[2025-07-29 15:45:36.945] I: Received Lock General Setting resp
[2025-07-29 15:45:36.945] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 15:45:36.945] SoundVolume attribute change
[2025-07-29 15:45:36.945] 
[2025-07-29 15:45:36.945] I: == Sound Volume Attribute Update Callback, sound volume 2 ==
[2025-07-29 15:45:36.945] I: No change in sound volume, return
[2025-07-29 15:45:36.945] ===== Attribute Received are: Cluster=101 Attribute=24 Value=2 =====
[2025-07-29 15:45:36.945] I: Matter Not Enabled do not set
[2025-07-29 15:45:37.434] I: Syncing up on message 51
[2025-07-29 15:45:37.434] I: Battery info req
[2025-07-29 15:45:37.434] E: Sending UART cmd(51) st 0
[2025-07-29 15:45:37.434] I: Received response of command id 51
[2025-07-29 15:45:37.434] I: Received Battery Info resp
[2025-07-29 15:45:37.434] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 15:45:37.434] Unhandled cluster ID: 0x  2f
[2025-07-29 15:45:37.434] 
[2025-07-29 15:45:37.434] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 15:45:37.434] Unhandled cluster ID: 0x  2f
[2025-07-29 15:45:37.434] 
[2025-07-29 15:45:37.434] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 15:45:37.884] I: All message synced.
[2025-07-29 15:46:01.414] I: STM system init timer expired, System Init Event not received from STM32
[2025-07-29 15:46:01.414] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 15:46:01.414] I: STM Pending =1, Redpine Pending = 1
[2025-07-29 15:46:01.414] I: STM Post OTA Pending
[2025-07-29 15:46:01.414] I: Redpine Post OTA Pending
[2025-07-29 15:46:01.414] E: Sending UART cmd(9e) st 0
[2025-07-29 15:46:01.414] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 15:46:01.414] I: 30188 [SWU]SMP BLE advertising started
[2025-07-29 15:46:01.414] I: 30192 [DL]DFU over SMP started
[2025-07-29 15:46:02.284] I: IMG Integrity Verified Successfully: 0
[2025-07-29 15:46:05.244] I: IMG Integrity Verified Successfully: 1
[2025-07-29 15:46:05.324] I: IMG Integrity Verified Successfully: 2
[2025-07-29 15:46:05.670] I: IMG Integrity Verified Successfully: 3
[2025-07-29 15:46:05.670] I: OTA Stage Change from (ff)->(32)
[2025-07-29 15:46:05.670] I: OTA device_id = 5 : DISCOVERY_REQ
[2025-07-29 15:46:05.754] I: SECURE_STM : IB_DEVICE_DISCOVERY_REQUEST (80) 
[2025-07-29 15:46:05.794] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 15:46:05.794] I: STM Current Firmware Version: 17 5 4 1b
[2025-07-29 15:46:05.794] I: OTA device_id = 5 : FW_UPDATE_START_REQ
[2025-07-29 15:46:05.794] I: SECURE_STM : IB_FW_UPDATE_START_REQUEST (80)
[2025-07-29 15:46:12.174] I: STM OTA Progress = 10
[2025-07-29 15:46:18.524] I: STM OTA Progress = 20
[2025-07-29 15:46:24.875] I: STM OTA Progress = 30
[2025-07-29 15:46:31.334] I: STM OTA Progress = 40
[2025-07-29 15:46:37.684] I: STM OTA Progress = 50
[2025-07-29 15:46:44.035] I: STM OTA Progress = 60
[2025-07-29 15:46:50.404] I: STM OTA Progress = 70
[2025-07-29 15:46:56.754] I: STM OTA Progress = 80
[2025-07-29 15:47:03.104] I: STM OTA Progress = 90
[2025-07-29 15:47:09.454] I: STM OTA Progress = 100
[2025-07-29 15:47:10.135] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 15:47:10.156] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 15:47:27.851] I: Sending Sys Init Resp
[2025-07-29 15:47:27.851] I: Device is provisioned
[2025-07-29 15:47:27.851] I: network state 0
[2025-07-29 15:47:27.851] E: Sending UART cmd(3) st 0
[2025-07-29 15:47:27.851] I: Received DC App Config REQ
[2025-07-29 15:47:27.851] I: DC App Config Resp
[2025-07-29 15:47:27.851] I: Received DC config req
[2025-07-29 15:47:27.851] I: 80 70 03 00 10 10 08 00 |.p......
[2025-07-29 15:47:27.851] I: 50 1e                   |P.      
[2025-07-29 15:47:27.851] I: Matter enabled state 0
[2025-07-29 15:47:27.851] I: Get Matter Commission State
[2025-07-29 15:47:27.851] I: network state 0
[2025-07-29 15:47:27.854] I: network state 0
[2025-07-29 15:47:27.854] E: Sending UART cmd(70) st 0
[2025-07-29 15:47:27.915] I: Lock State Event
[2025-07-29 15:47:27.915] I: Received response of command id 10
[2025-07-29 15:47:27.915] I: Received Lock State event, lock st: 12
[2025-07-29 15:47:27.915] I: Found matching nordic source of operation 0
[2025-07-29 15:47:27.915] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 15:47:27.915] I: Unlock action completed
[2025-07-29 15:47:27.915] I: Updating LockState attribute
[2025-07-29 15:47:27.915] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 15:47:27.947] I: Received DC Eco Config REQ
[2025-07-29 15:47:27.974] I: DC Eco Config Resp
[2025-07-29 15:47:27.974] I: Received DC eco config req
[2025-07-29 15:47:27.974] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 15:47:27.974] I: c4 1e                   |..      
[2025-07-29 15:47:27.974] E: Sending UART cmd(72) st 0
[2025-07-29 15:47:28.155] I: General Lock Setting event
[2025-07-29 15:47:28.155] I: Received response of command id 20
[2025-07-29 15:47:28.155] I: Received Lock General Setting event
[2025-07-29 15:47:28.155] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 15:47:28.155] I: Matter Not Enabled do not set
[2025-07-29 15:47:28.255] I: Firmware Attribute event
[2025-07-29 15:47:28.255] I: Received response of command id 30
[2025-07-29 15:47:28.315] I: Hardware Attribute event
[2025-07-29 15:47:28.324] I: Received response of command id 31
[2025-07-29 15:47:28.395] I: Operating mode event
[2025-07-29 15:47:28.395] I: Received response of command id 5
[2025-07-29 15:47:28.395] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 15:47:28.395] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:47:28.395] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:47:28.395] I: Set Kwikset Lock App State 49
[2025-07-29 15:47:28.395] I: Matter is disabled
[2025-07-29 15:47:28.525] I: Battery Info event
[2025-07-29 15:47:28.527] I: Received response of command id 51
[2025-07-29 15:47:28.527] I: Received Battery info event
[2025-07-29 15:47:28.527] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 15:47:28.527] Unhandled cluster ID: 0x  2f
[2025-07-29 15:47:28.527] 
[2025-07-29 15:47:28.527] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 15:47:28.527] Unhandled cluster ID: 0x  2f
[2025-07-29 15:47:28.527] 
[2025-07-29 15:47:28.527] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 15:47:28.624] I: System info event
[2025-07-29 15:47:28.624] I: Received System Info Event
[2025-07-29 15:47:28.624] W: Time invalid, set time
[2025-07-29 15:47:28.624] I: Get system time
[2025-07-29 15:47:28.624] I: System Real time in seconds 373663017
[2025-07-29 15:47:28.624] I: Time sync status flag 0
[2025-07-29 15:47:28.624] E: Time not sync, keep default value
[2025-07-29 15:47:28.734] I: System init event
[2025-07-29 15:47:28.734] I: Received response of command id 3
[2025-07-29 15:47:28.734] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 15:47:28.734] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:47:28.734] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 15:47:28.734] I: STM Current Firmware Version: 17 5 4 1a
[2025-07-29 15:47:28.734] I: OTA device_id = 5 : FW_UPDATE_COMPLETE_REQ
[2025-07-29 15:47:28.734] I: SECURE_STM : IB_FW_UPDATE_COMPLETE_REQUEST (80) 
[2025-07-29 15:47:28.734] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 15:47:28.734] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 15:47:31.124] I: Sending Sys Init Resp
[2025-07-29 15:47:31.171] I: Device is provisioned
[2025-07-29 15:47:31.171] I: network state 0
[2025-07-29 15:47:31.171] E: Sending UART cmd(3) st 0
[2025-07-29 15:47:31.171] I: Received DC App Config REQ
[2025-07-29 15:47:31.171] I: DC App Config Resp
[2025-07-29 15:47:31.171] I: Received DC config req
[2025-07-29 15:47:31.171] I: 80 70 03 00 10 10 04 1a |.p......
[2025-07-29 15:47:31.171] I: 00 62                   |.b      
[2025-07-29 15:47:31.171] I: Matter enabled state 0
[2025-07-29 15:47:31.171] I: Get Matter Commission State
[2025-07-29 15:47:31.171] I: network state 0
[2025-07-29 15:47:31.174] I: network state 0
[2025-07-29 15:47:31.174] E: Sending UART cmd(70) st 0
[2025-07-29 15:47:31.195] I: Lock State Event
[2025-07-29 15:47:31.195] I: Received response of command id 10
[2025-07-29 15:47:31.234] I: Received Lock State event, lock st: 12
[2025-07-29 15:47:31.234] I: Found matching nordic source of operation 0
[2025-07-29 15:47:31.234] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 15:47:31.234] I: Unlock action completed
[2025-07-29 15:47:31.234] I: Updating LockState attribute
[2025-07-29 15:47:31.234] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 15:47:31.265] I: Received DC Eco Config REQ
[2025-07-29 15:47:31.304] I: DC Eco Config Resp
[2025-07-29 15:47:31.304] I: Received DC eco config req
[2025-07-29 15:47:31.304] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 15:47:31.304] I: c4 62                   |.b      
[2025-07-29 15:47:31.304] E: Sending UART cmd(72) st 0
[2025-07-29 15:47:31.445] I: General Lock Setting event
[2025-07-29 15:47:31.474] I: Received response of command id 20
[2025-07-29 15:47:31.474] I: Received Lock General Setting event
[2025-07-29 15:47:31.474] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 15:47:31.474] I: Matter Not Enabled do not set
[2025-07-29 15:47:31.564] I: Firmware Attribute event
[2025-07-29 15:47:31.564] I: Received response of command id 30
[2025-07-29 15:47:31.634] I: Hardware Attribute event
[2025-07-29 15:47:31.634] I: Received response of command id 31
[2025-07-29 15:47:31.716] I: Operating mode event
[2025-07-29 15:47:31.716] I: Received response of command id 5
[2025-07-29 15:47:31.716] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 15:47:31.716] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:47:31.716] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:47:31.716] I: Set Kwikset Lock App State 49
[2025-07-29 15:47:31.716] I: Matter is disabled
[2025-07-29 15:47:31.845] I: Battery Info event
[2025-07-29 15:47:31.845] I: Received response of command id 51
[2025-07-29 15:47:31.845] I: Received Battery info event
[2025-07-29 15:47:31.845] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 15:47:31.845] Unhandled cluster ID: 0x  2f
[2025-07-29 15:47:31.845] 
[2025-07-29 15:47:31.845] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 15:47:31.845] Unhandled cluster ID: 0x  2f
[2025-07-29 15:47:31.845] 
[2025-07-29 15:47:31.845] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 15:47:31.955] I: System info event
[2025-07-29 15:47:31.955] I: Received System Info Event
[2025-07-29 15:47:31.955] W: Time invalid, set time
[2025-07-29 15:47:31.955] I: Get system time
[2025-07-29 15:47:31.955] I: System Real time in seconds 373663017
[2025-07-29 15:47:31.955] I: Time sync status flag 0
[2025-07-29 15:47:31.955] E: Time not sync, keep default value
[2025-07-29 15:47:32.034] I: System init event
[2025-07-29 15:47:32.034] I: Received response of command id 3
[2025-07-29 15:47:32.034] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 15:47:32.034] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:47:32.044] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 15:47:32.044] I: STM Current Firmware Version: 17 5 4 1a
[2025-07-29 15:47:32.044] I: STM New OTA Firmware Version = 17 5 4 1a
[2025-07-29 15:47:32.044] I: STM Secure OTA Successful
[2025-07-29 15:47:32.151] I: Cleared STM OTA Meta Data
[2025-07-29 15:47:32.151] I: OTA Stage Change from (32)->(33)
[2025-07-29 15:47:32.151] I: Redpine OTA started
[2025-07-29 15:47:32.151] I: OTA Stage Change from (33)->(34)
[2025-07-29 15:47:32.151] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 15:47:39.134] I: STM Reset Count 0
[2025-07-29 15:47:39.174] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 15:47:39.174] I: STM_QSPI : IB_DEVICE_DISCOVERY_REQUEST (80)
[2025-07-29 15:47:39.174] I: OTA device_id = 4 : FW_VERSION_REQ
[2025-07-29 15:47:39.174] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 15:47:39.174] I: Redpine Current Firmware Version: 2.c.0.3
[2025-07-29 15:47:39.194] I: OTA device_id = 4 : FW_UPDATE_START_REQ
[2025-07-29 15:47:39.284] I: STM_QSPI : IB_FW_UPDATE_START_REQUEST (80)
[2025-07-29 15:48:02.015] I: STM Boot Up Properly, Stopped STM Reboot Timer
[2025-07-29 15:48:18.765] I: Redpine Image Stored into STM QSPI, Progress = 10
[2025-07-29 15:48:52.315] I: Redpine Image Stored into STM QSPI, Progress = 20
[2025-07-29 15:49:12.965] I: Redpine Image Stored into STM QSPI, Progress = 30
[2025-07-29 15:49:33.745] I: Redpine Image Stored into STM QSPI, Progress = 40
[2025-07-29 15:49:54.405] I: Redpine Image Stored into STM QSPI, Progress = 50
[2025-07-29 15:50:15.125] I: Redpine Image Stored into STM QSPI, Progress = 60
[2025-07-29 15:50:35.915] I: Redpine Image Stored into STM QSPI, Progress = 70
[2025-07-29 15:50:56.625] I: Redpine Image Stored into STM QSPI, Progress = 80
[2025-07-29 15:51:17.341] I: Redpine Image Stored into STM QSPI, Progress = 90
[2025-07-29 15:51:38.135] I: Redpine Image Stored into STM QSPI, Progress = 100
[2025-07-29 15:51:40.245] I: OTA device_id = 4 : FW_UPDATE_COMPLETE_REQ
[2025-07-29 15:51:40.685] I: STM_QSPI : IB_FW_UPDATE_COMPLETE_REQUEST (80) 
[2025-07-29 15:51:40.805] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (0)
[2025-07-29 15:51:45.655] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (10)
[2025-07-29 15:51:50.505] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (20)
[2025-07-29 15:51:55.445] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (30)
[2025-07-29 15:52:00.445] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (40)
[2025-07-29 15:52:05.405] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (50)
[2025-07-29 15:52:10.371] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (60)
[2025-07-29 15:52:15.325] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (70)
[2025-07-29 15:52:20.265] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (80)
[2025-07-29 15:52:25.185] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (90)
[2025-07-29 15:52:29.995] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (100)
[2025-07-29 15:52:59.457] I: STM_QSPI : IB_FW_UPDATE_REBOOT_REQUEST (80) 
[2025-07-29 15:52:59.555] I: Clear Redpine OTA Meta Data
[2025-07-29 15:52:59.555] I: Redpine OTA Successful
[2025-07-29 15:52:59.585] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 15:52:59.585] I: STM Pending =2, Redpine Pending = 2
[2025-07-29 15:52:59.585] I: PN76 IMG 1 Post OTA Pending
[2025-07-29 15:52:59.585] E: Sending UART cmd(9e) st 0
[2025-07-29 15:52:59.585] I: 448364 [SWU]DFU over SMP was already started
[2025-07-29 15:52:59.665] I: IMG Integrity Verified Successfully: 2
[2025-07-29 15:53:00.035] I: IMG Integrity Verified Successfully: 3
[2025-07-29 15:53:00.035] I: OTA Stage Change from (34)->(3a)
[2025-07-29 15:53:00.035] I: PN76_IMG1_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 15:53:00.035] I: PN76_IMG Update from OTA Task Event
[2025-07-29 15:53:00.035] I: 
[2025-07-29 15:53:00.035] 
[2025-07-29 15:53:00.035] --------------- UPDATING PN7642 NXP FIRMWARE --------------------
[2025-07-29 15:53:00.035] 
[2025-07-29 15:53:00.035] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 15:53:00.075] I: pNXPFWInfo->img_offset = 0x351497
[2025-07-29 15:53:00.075] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 15:53:00.075] I: Reading version of firmware in QSPI flash: MetaData 0x2f60217
[2025-07-29 15:53:00.075] I: PN76 NXP FW VERSION VALIDATION SKIPPED, OTAU TEST BUNDLE
[2025-07-29 15:53:00.185] I: ----> PN7642 OTA Progress = 10 %
[2025-07-29 15:53:00.245] I: ----> PN7642 OTA Progress = 20 %
[2025-07-29 15:53:00.315] I: ----> PN7642 OTA Progress = 30 %
[2025-07-29 15:53:00.375] I: ----> PN7642 OTA Progress = 40 %
[2025-07-29 15:53:00.445] I: ----> PN7642 OTA Progress = 50 %
[2025-07-29 15:53:00.505] I: ----> PN7642 OTA Progress = 60 %
[2025-07-29 15:53:00.565] I: ----> PN7642 OTA Progress = 70 %
[2025-07-29 15:53:00.637] I: ----> PN7642 OTA Progress = 80 %
[2025-07-29 15:53:00.805] I: ----> PN7642 OTA Progress = 100 %
[2025-07-29 15:53:00.805] I: Whole pn7642 FW Image downloaded ....
[2025-07-29 15:53:00.805] I: 
[2025-07-29 15:53:00.805] 
[2025-07-29 15:53:00.815] I: 
[2025-07-29 15:53:00.815] PN7642 Firmware of type 0 Successfully Updated !!!
[2025-07-29 15:53:00.815] I: PN76 Image Update Successful for Device ID(7)
[2025-07-29 15:53:00.935] I: Cleared PN76 Img1 OTA Meta Data
[2025-07-29 15:53:00.935] I: OTA Stage Change from (3a)->(3a)
[2025-07-29 15:53:00.935] I: PN76_IMG2_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 15:53:00.935] I: PN76_IMG Update from OTA Task Event
[2025-07-29 15:53:00.935] I: 
[2025-07-29 15:53:00.935] 
[2025-07-29 15:53:00.935] --------------- UPDATING PN7642 APPLICATION FIRMWARE -------------
[2025-07-29 15:53:00.935] 
[2025-07-29 15:53:00.935] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 15:53:00.975] I: pCustAppFWInfo->img_offset = 0x35c289
[2025-07-29 15:53:00.975] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 15:53:00.975] I: Reading version of firmware in QSPI flash: MetaData 0x2f60217
[2025-07-29 15:53:00.975] I: PN76 APP FW VERSION VALIDATION SKIPPED, OTAU TEST BUNDLE
[2025-07-29 15:53:01.275] I: ----> PN7642 OTA Progress = 10 %
[2025-07-29 15:53:01.545] I: ----> PN7642 OTA Progress = 20 %
[2025-07-29 15:53:01.807] I: ----> PN7642 OTA Progress = 30 %
[2025-07-29 15:53:02.075] I: ----> PN7642 OTA Progress = 40 %
[2025-07-29 15:53:02.335] I: ----> PN7642 OTA Progress = 50 %
[2025-07-29 15:53:02.609] I: ----> PN7642 OTA Progress = 60 %
[2025-07-29 15:53:02.865] I: ----> PN7642 OTA Progress = 70 %
[2025-07-29 15:53:03.135] I: ----> PN7642 OTA Progress = 80 %
[2025-07-29 15:53:03.385] I: ----> PN7642 OTA Progress = 90 %
[2025-07-29 15:53:03.645] I: ----> PN7642 OTA Progress = 100 %
[2025-07-29 15:53:03.682] I: Whole pn7642 FW Image downloaded ....
[2025-07-29 15:53:03.682] I: 
[2025-07-29 15:53:03.682] 
[2025-07-29 15:53:03.682] I: 
[2025-07-29 15:53:03.682] PN7642 Firmware of type 1 Successfully Updated !!!
[2025-07-29 15:53:03.682] I: PN76 Image Update Successful for Device ID(8)
[2025-07-29 15:53:03.755] I: Cleared PN76 Img2 OTA Meta Data
[2025-07-29 15:53:04.335] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 15:53:04.335] I: NFC Boot Event PN7642 FW VERSION 17.01.00.02
[2025-07-29 15:53:04.335] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 15:53:04.335] I: 
[2025-07-29 15:53:04.335] Boot Event Received
[2025-07-29 15:53:04.335] 
[2025-07-29 15:53:04.335] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 15:53:04.335] 
[2025-07-29 15:53:04.335] I: OTA Stage Change from (3a)->(3b)
[2025-07-29 15:53:04.335] I: post_stm_reset_event : init_pending_ota_update
[2025-07-29 15:53:04.335] I: All pending FW Updates are completed.
[2025-07-29 15:53:04.335] I: STM32 Reset Count = 0
[2025-07-29 15:53:04.335] I: REBOOT_STM: Send STM32 Reboot Command, Count (0)
[2025-07-29 15:53:06.635] I: Sending Sys Init Resp
[2025-07-29 15:53:06.635] I: Device is provisioned
[2025-07-29 15:53:06.635] I: network state 0
[2025-07-29 15:53:06.635] E: Sending UART cmd(3) st 0
[2025-07-29 15:53:06.635] I: Received DC App Config REQ
[2025-07-29 15:53:06.635] I: DC App Config Resp
[2025-07-29 15:53:06.635] I: Received DC config req
[2025-07-29 15:53:06.635] I: 80 70 03 00 10 10 19 00 |.p......
[2025-07-29 15:53:06.635] I: 50 62                   |Pb      
[2025-07-29 15:53:06.635] I: Matter enabled state 0
[2025-07-29 15:53:06.635] I: Get Matter Commission State
[2025-07-29 15:53:06.635] I: network state 0
[2025-07-29 15:53:06.645] I: network state 0
[2025-07-29 15:53:06.645] E: Sending UART cmd(70) st 0
[2025-07-29 15:53:06.705] I: Lock State Event
[2025-07-29 15:53:06.705] I: Received response of command id 10
[2025-07-29 15:53:06.705] I: Received Lock State event, lock st: 12
[2025-07-29 15:53:06.705] I: Found matching nordic source of operation 0
[2025-07-29 15:53:06.705] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 15:53:06.705] I: Unlock action completed
[2025-07-29 15:53:06.705] I: Updating LockState attribute
[2025-07-29 15:53:06.705] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 15:53:06.735] I: Received DC Eco Config REQ
[2025-07-29 15:53:06.735] I: DC Eco Config Resp
[2025-07-29 15:53:06.765] I: Received DC eco config req
[2025-07-29 15:53:06.765] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 15:53:06.765] I: c4 62                   |.b      
[2025-07-29 15:53:06.765] E: Sending UART cmd(72) st 0
[2025-07-29 15:53:06.945] I: General Lock Setting event
[2025-07-29 15:53:06.945] I: Received response of command id 20
[2025-07-29 15:53:06.945] I: Received Lock General Setting event
[2025-07-29 15:53:06.945] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 15:53:06.945] I: Matter Not Enabled do not set
[2025-07-29 15:53:07.045] I: Firmware Attribute event
[2025-07-29 15:53:07.045] I: Received response of command id 30
[2025-07-29 15:53:07.106] I: Hardware Attribute event
[2025-07-29 15:53:07.106] I: Received response of command id 31
[2025-07-29 15:53:07.185] I: Operating mode event
[2025-07-29 15:53:07.185] I: Received response of command id 5
[2025-07-29 15:53:07.185] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 15:53:07.185] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:53:07.185] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:53:07.185] I: Set Kwikset Lock App State 49
[2025-07-29 15:53:07.185] I: Matter is disabled
[2025-07-29 15:53:07.315] I: Battery Info event
[2025-07-29 15:53:07.315] I: Received response of command id 51
[2025-07-29 15:53:07.315] I: Received Battery info event
[2025-07-29 15:53:07.315] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 15:53:07.315] Unhandled cluster ID: 0x  2f
[2025-07-29 15:53:07.315] 
[2025-07-29 15:53:07.315] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 15:53:07.315] Unhandled cluster ID: 0x  2f
[2025-07-29 15:53:07.315] 
[2025-07-29 15:53:07.315] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 15:53:07.395] I: System info event
[2025-07-29 15:53:07.395] I: Received System Info Event
[2025-07-29 15:53:07.415] W: Time invalid, set time
[2025-07-29 15:53:07.415] I: Get system time
[2025-07-29 15:53:07.415] I: System Real time in seconds 373663017
[2025-07-29 15:53:07.415] I: Time sync status flag 0
[2025-07-29 15:53:07.415] E: Time not sync, keep default value
[2025-07-29 15:53:07.485] I: System init event
[2025-07-29 15:53:07.485] I: Received response of command id 3
[2025-07-29 15:53:07.485] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 15:53:07.485] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 15:53:07.485] I: STM Image confirm timer was stopped
[2025-07-29 15:53:14.375] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 15:53:14.375] I: stop_ota_finalization_timer
[2025-07-29 15:53:14.375] I: After OTAU, Redpine Firmware Version: 2.c.0.3
[2025-07-29 15:53:14.375] I: Redpine New OTA Firmware Version = 2 c 0 3
[2025-07-29 15:53:14.375] I: After OTAU, Secure STM Firmware Version: 17 5 4 1a
[2025-07-29 15:53:14.375] I: Send Op Mode command to release Redpine BLE and WiFI
[2025-07-29 15:53:14.375] I: Operating Mode Command: Mode:10, State:f0
[2025-07-29 15:53:14.375] E: Sending UART cmd(5) st 0
[2025-07-29 15:53:14.435] I: Operating mode event
[2025-07-29 15:53:14.435] I: Received response of command id 5
[2025-07-29 15:53:14.435] I: Received Lock Op Mode Event, mode 10, App state 10
[2025-07-29 15:53:14.435] I: Lock Current Mode : 10, Lock Current State = 10
[2025-07-29 15:53:14.435] I: stop_ota_finalization_timer
[2025-07-29 15:53:14.435] I: STM32 HALO APP STATE IS ACTIVATED NORMAL
[2025-07-29 15:53:14.435] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:53:14.435] I: Set Kwikset Lock App State 16
[2025-07-29 15:53:14.435] I: Matter enabled state 0
[2025-07-29 15:53:14.435] I: Matter is disabled
[2025-07-29 15:53:14.435] I: OTA_HOUSEKEEPING
[2025-07-29 15:53:14.435] I: OTA Stage Change from (3b)->(80)
[2025-07-29 15:53:14.441] I: Start Erasing OTA bundle from nRF External Flash
[2025-07-29 15:53:20.795] I: System info event
[2025-07-29 15:53:20.795] I: Received System Info Event
[2025-07-29 15:53:20.795] I: Time is set in STM
[2025-07-29 15:54:15.595] I: Bundle Image Erased from nRF External Flash: 0
[2025-07-29 15:54:15.595] I: OTAU Completed Successfully
[2025-07-29 15:54:15.705] I: Cleared OTA Meta Data
[2025-07-29 15:54:15.705] I: OTA Stage Change from (80)->(90)
[2025-07-29 15:54:17.705] I: All message synced.
[2025-07-29 15:54:30.695] I: STOP BLE Advertisment
[2025-07-29 15:54:30.715] I: 539489 [DL]DFU over SMP stopped
[2025-07-29 15:54:30.715] E: Sending UART cmd(9e) st 0
[2025-07-29 15:57:18.656] I: Updated ota meta data
[2025-07-29 15:57:18.656] I: Operating Mode Command: Mode:10, State:34
[2025-07-29 15:57:18.656] E: Sending UART cmd(5) st 0
[2025-07-29 15:57:18.736] I: Operating mode event
[2025-07-29 15:57:18.795] I: Received response of command id 5
[2025-07-29 15:57:18.795] I: Received Lock Op Mode Event, mode 10, App state 34
[2025-07-29 15:57:18.795] I: Lock Current Mode : 10, Lock Current State = 34
[2025-07-29 15:57:18.795] I: STM32 HALO APP STATE IS BLE OTAU TRANSFER
[2025-07-29 15:57:18.797] E: Sending UART cmd(9e) st 0
[2025-07-29 15:57:18.797] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 15:57:18.797] I: 707562 [SWU]SMP BLE advertising started
[2025-07-29 15:57:18.797] I: 707566 [DL]DFU over SMP started
[2025-07-29 15:57:18.797] I: OTA Stage Change from (90)->(11)
[2025-07-29 15:57:18.797] I: Set Kwikset Lock App Mode 16
[2025-07-29 15:57:18.797] I: Set Kwikset Lock App State 52
[2025-07-29 15:57:18.797] I: Matter is disabled
[2025-07-29 15:57:35.885] I: 724689 [DL]Current number of connections: 1/1
[2025-07-29 15:57:35.905] I: BLE Connected
[2025-07-29 15:57:36.155] I: 724935 [DL]Current number of connections: 0/1
[2025-07-29 15:57:36.155] I: BLE Disconnected: 13
[2025-07-29 15:57:40.765] I: 729541 [DL]Current number of connections: 1/1
[2025-07-29 15:57:40.765] I: BLE Connected
[2025-07-29 15:57:40.986] I: 729771 [DL]DFU Image upload started
[2025-07-29 15:57:41.795] I: Connection parameters updated.
[2025-07-29 15:57:41.795]  interval: 9, latency: 0, timeout: 42
[2025-07-29 15:57:41.833] E: No available ACL buffers!
[2025-07-29 15:57:41.833] E: Unexpected first L2CAP frame
[2025-07-29 15:57:55.581] I: OTA Stage Change from (11)->(12)
[2025-07-29 15:57:55.581] I: 744364 [DL]Image 0 download completed successfully
[2025-07-29 16:01:51.126] I: OTA Stage Change from (12)->(11)
[2025-07-29 16:01:51.156] I: Lock Already in OTAU Transport/Update mode
[2025-07-29 16:01:51.156] E: Sending UART cmd(9e) st 0
[2025-07-29 16:01:51.156] I: 979943 [SWU]DFU over SMP was already started
