[2025-07-29 13:05:44.530] I: STM system init timer expired, System Init Event not received from STM32
[2025-07-29 13:05:44.530] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 13:05:44.530] I: STM Pending =1, Redpine Pending = 1
[2025-07-29 13:05:44.535] I: STM Post OTA Pending
[2025-07-29 13:05:44.535] I: Redpine Post OTA Pending
[2025-07-29 13:05:44.535] E: Sending UART cmd(9e) st 0
[2025-07-29 13:05:44.535] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 13:05:44.535] I: 30188 [SWU]SMP BLE advertising started
[2025-07-29 13:05:44.535] I: 30192 [DL]DFU over SMP started
[2025-07-29 13:05:44.535] I: IMG Integrity Verified Successfully: 0
[2025-07-29 13:05:46.711] I: IMG Integrity Verified Successfully: 1
[2025-07-29 13:05:46.791] I: IMG Integrity Verified Successfully: 2
[2025-07-29 13:05:47.141] I: IMG Integrity Verified Successfully: 3
[2025-07-29 13:05:47.141] I: OTA Stage Change from (ff)->(32)
[2025-07-29 13:05:47.141] I: OTA device_id = 5 : DISCOVERY_REQ
[2025-07-29 13:05:47.221] I: SECURE_STM : IB_DEVICE_DISCOVERY_REQUEST (80) 
[2025-07-29 13:05:47.271] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 13:05:47.271] I: STM Current Firmware Version: 17 5 4 12
[2025-07-29 13:05:47.271] I: OTA device_id = 5 : FW_UPDATE_START_REQ
[2025-07-29 13:05:47.271] I: SECURE_STM : IB_FW_UPDATE_START_REQUEST (80)
[2025-07-29 13:05:53.621] I: STM OTA Progress = 10
[2025-07-29 13:05:59.921] I: STM OTA Progress = 20
[2025-07-29 13:06:06.241] I: STM OTA Progress = 30
[2025-07-29 13:06:12.631] I: STM OTA Progress = 40
[2025-07-29 13:06:18.951] I: STM OTA Progress = 50
[2025-07-29 13:06:25.291] I: STM OTA Progress = 60
[2025-07-29 13:06:31.608] I: STM OTA Progress = 70
[2025-07-29 13:06:37.921] I: STM OTA Progress = 80
[2025-07-29 13:06:44.261] I: STM OTA Progress = 90
[2025-07-29 13:06:50.571] I: STM OTA Progress = 100
[2025-07-29 13:06:51.271] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 13:06:51.271] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 13:07:08.801] I: Sending Sys Init Resp
[2025-07-29 13:07:08.841] I: Device is provisioned
[2025-07-29 13:07:08.841] I: network state 0
[2025-07-29 13:07:08.841] E: Sending UART cmd(3) st 0
[2025-07-29 13:07:08.841] I: Received DC App Config REQ
[2025-07-29 13:07:08.841] I: DC App Config Resp
[2025-07-29 13:07:08.841] I: Received DC config req
[2025-07-29 13:07:08.841] I: 80 70 03 00 10 10 08 00 |.p......
[2025-07-29 13:07:08.841] I: 50 1e                   |P.      
[2025-07-29 13:07:08.841] I: Matter enabled state 0
[2025-07-29 13:07:08.841] I: Get Matter Commission State
[2025-07-29 13:07:08.841] I: network state 0
[2025-07-29 13:07:08.853] I: network state 0
[2025-07-29 13:07:08.853] E: Sending UART cmd(70) st 0
[2025-07-29 13:07:08.923] I: Lock State Event
[2025-07-29 13:07:08.923] I: Received response of command id 10
[2025-07-29 13:07:08.923] I: Received Lock State event, lock st: 12
[2025-07-29 13:07:08.923] I: Found matching nordic source of operation 0
[2025-07-29 13:07:08.923] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:07:08.923] I: Unlock action completed
[2025-07-29 13:07:08.923] I: Updating LockState attribute
[2025-07-29 13:07:08.923] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:07:08.951] I: Received DC Eco Config REQ
[2025-07-29 13:07:08.951] I: DC Eco Config Resp
[2025-07-29 13:07:08.981] I: Received DC eco config req
[2025-07-29 13:07:08.981] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 13:07:08.981] I: c4 1e                   |..      
[2025-07-29 13:07:08.981] E: Sending UART cmd(72) st 0
[2025-07-29 13:07:09.123] I: General Lock Setting event
[2025-07-29 13:07:09.151] I: Received response of command id 20
[2025-07-29 13:07:09.151] I: Received Lock General Setting event
[2025-07-29 13:07:09.151] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 13:07:09.151] I: Matter Not Enabled do not set
[2025-07-29 13:07:09.261] I: Firmware Attribute event
[2025-07-29 13:07:09.261] I: Received response of command id 30
[2025-07-29 13:07:09.323] I: Hardware Attribute event
[2025-07-29 13:07:09.323] I: Received response of command id 31
[2025-07-29 13:07:09.401] I: Operating mode event
[2025-07-29 13:07:09.401] I: Received response of command id 5
[2025-07-29 13:07:09.401] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:07:09.401] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:07:09.401] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:07:09.401] I: Set Kwikset Lock App State 49
[2025-07-29 13:07:09.401] I: Matter is disabled
[2025-07-29 13:07:09.523] I: Battery Info event
[2025-07-29 13:07:09.523] I: Received response of command id 51
[2025-07-29 13:07:09.523] I: Received Battery info event
[2025-07-29 13:07:09.523] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:07:09.523] Unhandled cluster ID: 0x  2f
[2025-07-29 13:07:09.523] 
[2025-07-29 13:07:09.523] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:07:09.523] Unhandled cluster ID: 0x  2f
[2025-07-29 13:07:09.523] 
[2025-07-29 13:07:09.523] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:07:09.601] I: System info event
[2025-07-29 13:07:09.601] I: Received System Info Event
[2025-07-29 13:07:09.631] W: Time invalid, set time
[2025-07-29 13:07:09.631] I: Get system time
[2025-07-29 13:07:09.631] I: System Real time in seconds 373663017
[2025-07-29 13:07:09.631] I: Time sync status flag 0
[2025-07-29 13:07:09.631] E: Time not sync, keep default value
[2025-07-29 13:07:09.741] I: System init event
[2025-07-29 13:07:09.741] I: Received response of command id 3
[2025-07-29 13:07:09.741] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 13:07:09.741] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:07:09.741] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 13:07:09.741] I: STM Current Firmware Version: 17 5 4 1a
[2025-07-29 13:07:09.741] I: OTA device_id = 5 : FW_UPDATE_COMPLETE_REQ
[2025-07-29 13:07:09.741] I: SECURE_STM : IB_FW_UPDATE_COMPLETE_REQUEST (80) 
[2025-07-29 13:07:09.741] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 13:07:09.741] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 13:07:12.151] I: Sending Sys Init Resp
[2025-07-29 13:07:12.151] I: Device is provisioned
[2025-07-29 13:07:12.151] I: network state 0
[2025-07-29 13:07:12.151] E: Sending UART cmd(3) st 0
[2025-07-29 13:07:12.151] I: Received DC App Config REQ
[2025-07-29 13:07:12.151] I: DC App Config Resp
[2025-07-29 13:07:12.151] I: Received DC config req
[2025-07-29 13:07:12.151] I: 80 70 03 00 10 10 04 1a |.p......
[2025-07-29 13:07:12.151] I: 00 62                   |.b      
[2025-07-29 13:07:12.151] I: Matter enabled state 0
[2025-07-29 13:07:12.151] I: Get Matter Commission State
[2025-07-29 13:07:12.151] I: network state 0
[2025-07-29 13:07:12.151] I: network state 0
[2025-07-29 13:07:12.151] E: Sending UART cmd(70) st 0
[2025-07-29 13:07:12.211] I: Lock State Event
[2025-07-29 13:07:12.211] I: Received response of command id 10
[2025-07-29 13:07:12.211] I: Received Lock State event, lock st: 12
[2025-07-29 13:07:12.211] I: Found matching nordic source of operation 0
[2025-07-29 13:07:12.211] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:07:12.211] I: Unlock action completed
[2025-07-29 13:07:12.211] I: Updating LockState attribute
[2025-07-29 13:07:12.211] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:07:12.241] I: Received DC Eco Config REQ
[2025-07-29 13:07:12.281] I: DC Eco Config Resp
[2025-07-29 13:07:12.281] I: Received DC eco config req
[2025-07-29 13:07:12.281] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 13:07:12.281] I: c4 62                   |.b      
[2025-07-29 13:07:12.281] E: Sending UART cmd(72) st 0
[2025-07-29 13:07:12.424] I: General Lock Setting event
[2025-07-29 13:07:12.451] I: Received response of command id 20
[2025-07-29 13:07:12.451] I: Received Lock General Setting event
[2025-07-29 13:07:12.451] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 13:07:12.451] I: Matter Not Enabled do not set
[2025-07-29 13:07:12.561] I: Firmware Attribute event
[2025-07-29 13:07:12.561] I: Received response of command id 30
[2025-07-29 13:07:12.621] I: Hardware Attribute event
[2025-07-29 13:07:12.621] I: Received response of command id 31
[2025-07-29 13:07:12.691] I: Operating mode event
[2025-07-29 13:07:12.691] I: Received response of command id 5
[2025-07-29 13:07:12.691] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:07:12.691] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:07:12.691] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:07:12.700] I: Set Kwikset Lock App State 49
[2025-07-29 13:07:12.701] I: Matter is disabled
[2025-07-29 13:07:12.821] I: Battery Info event
[2025-07-29 13:07:12.821] I: Received response of command id 51
[2025-07-29 13:07:12.821] I: Received Battery info event
[2025-07-29 13:07:12.821] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:07:12.821] Unhandled cluster ID: 0x  2f
[2025-07-29 13:07:12.821] 
[2025-07-29 13:07:12.821] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:07:12.821] Unhandled cluster ID: 0x  2f
[2025-07-29 13:07:12.821] 
[2025-07-29 13:07:12.821] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:07:12.901] I: System info event
[2025-07-29 13:07:12.901] I: Received System Info Event
[2025-07-29 13:07:12.929] W: Time invalid, set time
[2025-07-29 13:07:12.931] I: Get system time
[2025-07-29 13:07:12.931] I: System Real time in seconds 373663017
[2025-07-29 13:07:12.931] I: Time sync status flag 0
[2025-07-29 13:07:12.931] E: Time not sync, keep default value
[2025-07-29 13:07:13.011] I: System init event
[2025-07-29 13:07:13.011] I: Received response of command id 3
[2025-07-29 13:07:13.018] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 13:07:13.018] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:07:13.018] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 13:07:13.018] I: STM Current Firmware Version: 17 5 4 1a
[2025-07-29 13:07:13.018] I: STM New OTA Firmware Version = 17 5 4 1a
[2025-07-29 13:07:13.018] I: STM Secure OTA Successful
[2025-07-29 13:07:13.121] I: Cleared STM OTA Meta Data
[2025-07-29 13:07:13.121] I: OTA Stage Change from (32)->(33)
[2025-07-29 13:07:13.121] I: Redpine OTA started
[2025-07-29 13:07:13.121] I: OTA Stage Change from (33)->(34)
[2025-07-29 13:07:13.121] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 13:07:20.111] I: STM Reset Count 0
[2025-07-29 13:07:20.141] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 13:07:20.141] I: STM_QSPI : IB_DEVICE_DISCOVERY_REQUEST (80)
[2025-07-29 13:07:20.141] I: OTA device_id = 4 : FW_VERSION_REQ
[2025-07-29 13:07:20.141] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 13:07:20.141] I: Redpine Current Firmware Version: 2.c.0.3
[2025-07-29 13:07:20.161] I: OTA device_id = 4 : FW_UPDATE_START_REQ
[2025-07-29 13:07:20.261] I: STM_QSPI : IB_FW_UPDATE_START_REQUEST (80)
[2025-07-29 13:07:42.991] I: STM Boot Up Properly, Stopped STM Reboot Timer
[2025-07-29 13:07:59.621] I: Redpine Image Stored into STM QSPI, Progress = 10
[2025-07-29 13:08:33.148] I: Redpine Image Stored into STM QSPI, Progress = 20
[2025-07-29 13:08:53.793] I: Redpine Image Stored into STM QSPI, Progress = 30
[2025-07-29 13:09:14.511] I: Redpine Image Stored into STM QSPI, Progress = 40
[2025-07-29 13:09:35.191] I: Redpine Image Stored into STM QSPI, Progress = 50
[2025-07-29 13:09:55.871] I: Redpine Image Stored into STM QSPI, Progress = 60
[2025-07-29 13:10:16.681] I: Redpine Image Stored into STM QSPI, Progress = 70
[2025-07-29 13:10:37.392] I: Redpine Image Stored into STM QSPI, Progress = 80
[2025-07-29 13:10:58.121] I: Redpine Image Stored into STM QSPI, Progress = 90
[2025-07-29 13:11:18.961] I: Redpine Image Stored into STM QSPI, Progress = 100
[2025-07-29 13:11:21.071] I: OTA device_id = 4 : FW_UPDATE_COMPLETE_REQ
[2025-07-29 13:11:21.521] I: STM_QSPI : IB_FW_UPDATE_COMPLETE_REQUEST (80) 
[2025-07-29 13:11:21.651] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (0)
[2025-07-29 13:11:26.462] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (10)
[2025-07-29 13:11:31.338] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (20)
[2025-07-29 13:11:36.281] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (30)
[2025-07-29 13:11:41.261] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (40)
[2025-07-29 13:11:46.211] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (50)
[2025-07-29 13:11:51.121] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (60)
[2025-07-29 13:11:56.096] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (70)
[2025-07-29 13:12:01.071] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (80)
[2025-07-29 13:12:05.966] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (90)
[2025-07-29 13:12:10.761] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (100)
[2025-07-29 13:12:40.191] I: STM_QSPI : IB_FW_UPDATE_REBOOT_REQUEST (80) 
[2025-07-29 13:12:40.291] I: Clear Redpine OTA Meta Data
[2025-07-29 13:12:40.291] I: Redpine OTA Successful
[2025-07-29 13:12:40.322] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 13:12:40.322] I: STM Pending =2, Redpine Pending = 2
[2025-07-29 13:12:40.322] I: PN76 IMG 1 Post OTA Pending
[2025-07-29 13:12:40.322] E: Sending UART cmd(9e) st 0
[2025-07-29 13:12:40.322] I: 447627 [SWU]DFU over SMP was already started
[2025-07-29 13:12:40.401] I: IMG Integrity Verified Successfully: 2
[2025-07-29 13:12:40.771] I: IMG Integrity Verified Successfully: 3
[2025-07-29 13:12:40.771] I: OTA Stage Change from (34)->(3a)
[2025-07-29 13:12:40.771] I: PN76_IMG1_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 13:12:40.771] I: PN76_IMG Update from OTA Task Event
[2025-07-29 13:12:40.771] I: 
[2025-07-29 13:12:40.771] 
[2025-07-29 13:12:40.771] --------------- UPDATING PN7642 NXP FIRMWARE --------------------
[2025-07-29 13:12:40.771] 
[2025-07-29 13:12:40.771] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 13:12:40.814] I: pNXPFWInfo->img_offset = 0x351497
[2025-07-29 13:12:40.814] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 13:12:40.814] I: Reading version of firmware in QSPI flash: MetaData 0x2f60217
[2025-07-29 13:12:40.814] I: PN76 NXP FW VERSION VALIDATION SKIPPED, OTAU TEST BUNDLE
[2025-07-29 13:12:40.921] I: ----> PN7642 OTA Progress = 10 %
[2025-07-29 13:12:40.991] I: ----> PN7642 OTA Progress = 20 %
[2025-07-29 13:12:41.052] I: ----> PN7642 OTA Progress = 30 %
[2025-07-29 13:12:41.115] I: ----> PN7642 OTA Progress = 40 %
[2025-07-29 13:12:41.182] I: ----> PN7642 OTA Progress = 50 %
[2025-07-29 13:12:41.241] I: ----> PN7642 OTA Progress = 60 %
[2025-07-29 13:12:41.311] I: ----> PN7642 OTA Progress = 70 %
[2025-07-29 13:12:41.371] I: ----> PN7642 OTA Progress = 80 %
[2025-07-29 13:12:41.541] I: ----> PN7642 OTA Progress = 100 %
[2025-07-29 13:12:41.541] I: Whole pn7642 FW Image downloaded ....
[2025-07-29 13:12:41.541] I: 
[2025-07-29 13:12:41.541] 
[2025-07-29 13:12:41.541] I: 
[2025-07-29 13:12:41.541] PN7642 Firmware of type 0 Successfully Updated !!!
[2025-07-29 13:12:41.541] I: PN76 Image Update Successful for Device ID(7)
[2025-07-29 13:12:41.672] I: Cleared PN76 Img1 OTA Meta Data
[2025-07-29 13:12:41.672] I: OTA Stage Change from (3a)->(3a)
[2025-07-29 13:12:41.672] I: PN76_IMG2_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 13:12:41.672] I: PN76_IMG Update from OTA Task Event
[2025-07-29 13:12:41.672] I: 
[2025-07-29 13:12:41.672] 
[2025-07-29 13:12:41.672] --------------- UPDATING PN7642 APPLICATION FIRMWARE -------------
[2025-07-29 13:12:41.672] 
[2025-07-29 13:12:41.672] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 13:12:41.715] I: pCustAppFWInfo->img_offset = 0x35c289
[2025-07-29 13:12:41.715] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 13:12:41.715] I: Reading version of firmware in QSPI flash: MetaData 0x2f60217
[2025-07-29 13:12:41.715] I: PN76 APP FW VERSION VALIDATION SKIPPED, OTAU TEST BUNDLE
[2025-07-29 13:12:42.016] I: ----> PN7642 OTA Progress = 10 %
[2025-07-29 13:12:42.291] I: ----> PN7642 OTA Progress = 20 %
[2025-07-29 13:12:42.541] I: ----> PN7642 OTA Progress = 30 %
[2025-07-29 13:12:42.817] I: ----> PN7642 OTA Progress = 40 %
[2025-07-29 13:12:43.071] I: ----> PN7642 OTA Progress = 50 %
[2025-07-29 13:12:43.341] I: ----> PN7642 OTA Progress = 60 %
[2025-07-29 13:12:43.601] I: ----> PN7642 OTA Progress = 70 %
[2025-07-29 13:12:43.871] I: ----> PN7642 OTA Progress = 80 %
[2025-07-29 13:12:44.131] I: ----> PN7642 OTA Progress = 90 %
[2025-07-29 13:12:44.382] I: ----> PN7642 OTA Progress = 100 %
[2025-07-29 13:12:44.422] I: Whole pn7642 FW Image downloaded ....
[2025-07-29 13:12:44.422] I: 
[2025-07-29 13:12:44.422] 
[2025-07-29 13:12:44.422] I: 
[2025-07-29 13:12:44.422] PN7642 Firmware of type 1 Successfully Updated !!!
[2025-07-29 13:12:44.422] I: PN76 Image Update Successful for Device ID(8)
[2025-07-29 13:12:44.502] I: Cleared PN76 Img2 OTA Meta Data
[2025-07-29 13:12:45.031] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 13:12:45.081] I: NFC Boot Event PN7642 FW VERSION 17.01.00.02
[2025-07-29 13:12:45.081] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 13:12:45.081] I: 
[2025-07-29 13:12:45.081] Boot Event Received
[2025-07-29 13:12:45.081] 
[2025-07-29 13:12:45.081] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 13:12:45.081] 
[2025-07-29 13:12:45.081] I: OTA Stage Change from (3a)->(3b)
[2025-07-29 13:12:45.081] I: post_stm_reset_event : init_pending_ota_update
[2025-07-29 13:12:45.081] I: All pending FW Updates are completed.
[2025-07-29 13:12:45.081] I: STM32 Reset Count = 0
[2025-07-29 13:12:45.081] I: REBOOT_STM: Send STM32 Reboot Command, Count (0)
[2025-07-29 13:12:47.451] I: Sending Sys Init Resp
[2025-07-29 13:12:47.451] I: Device is provisioned
[2025-07-29 13:12:47.451] I: network state 0
[2025-07-29 13:12:47.451] E: Sending UART cmd(3) st 0
[2025-07-29 13:12:47.451] I: Received DC App Config REQ
[2025-07-29 13:12:47.451] I: DC App Config Resp
[2025-07-29 13:12:47.451] I: Received DC config req
[2025-07-29 13:12:47.451] I: 80 70 03 00 10 10 19 00 |.p......
[2025-07-29 13:12:47.451] I: 50 62                   |Pb      
[2025-07-29 13:12:47.451] I: Matter enabled state 0
[2025-07-29 13:12:47.451] I: Get Matter Commission State
[2025-07-29 13:12:47.451] I: network state 0
[2025-07-29 13:12:47.451] I: network state 0
[2025-07-29 13:12:47.451] E: Sending UART cmd(70) st 0
[2025-07-29 13:12:47.512] I: Lock State Event
[2025-07-29 13:12:47.512] I: Received response of command id 10
[2025-07-29 13:12:47.512] I: Received Lock State event, lock st: 12
[2025-07-29 13:12:47.512] I: Found matching nordic source of operation 0
[2025-07-29 13:12:47.512] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:12:47.512] I: Unlock action completed
[2025-07-29 13:12:47.512] I: Updating LockState attribute
[2025-07-29 13:12:47.512] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:12:47.542] I: Received DC Eco Config REQ
[2025-07-29 13:12:47.542] I: DC Eco Config Resp
[2025-07-29 13:12:47.574] I: Received DC eco config req
[2025-07-29 13:12:47.574] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 13:12:47.574] I: c4 62                   |.b      
[2025-07-29 13:12:47.574] E: Sending UART cmd(72) st 0
[2025-07-29 13:12:47.741] I: General Lock Setting event
[2025-07-29 13:12:47.741] I: Received response of command id 20
[2025-07-29 13:12:47.741] I: Received Lock General Setting event
[2025-07-29 13:12:47.741] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 13:12:47.741] I: Matter Not Enabled do not set
[2025-07-29 13:12:47.851] I: Firmware Attribute event
[2025-07-29 13:12:47.851] I: Received response of command id 30
[2025-07-29 13:12:47.911] I: Hardware Attribute event
[2025-07-29 13:12:47.911] I: Received response of command id 31
[2025-07-29 13:12:47.981] I: Operating mode event
[2025-07-29 13:12:47.981] I: Received response of command id 5
[2025-07-29 13:12:47.981] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:12:47.981] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:12:47.981] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:12:47.981] I: Set Kwikset Lock App State 49
[2025-07-29 13:12:47.981] I: Matter is disabled
[2025-07-29 13:12:48.111] I: Battery Info event
[2025-07-29 13:12:48.111] I: Received response of command id 51
[2025-07-29 13:12:48.111] I: Received Battery info event
[2025-07-29 13:12:48.111] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:12:48.111] Unhandled cluster ID: 0x  2f
[2025-07-29 13:12:48.111] 
[2025-07-29 13:12:48.111] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:12:48.111] Unhandled cluster ID: 0x  2f
[2025-07-29 13:12:48.111] 
[2025-07-29 13:12:48.111] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:12:48.191] I: System info event
[2025-07-29 13:12:48.191] I: Received System Info Event
[2025-07-29 13:12:48.191] W: Time invalid, set time
[2025-07-29 13:12:48.212] I: Get system time
[2025-07-29 13:12:48.212] I: System Real time in seconds 373663017
[2025-07-29 13:12:48.212] I: Time sync status flag 0
[2025-07-29 13:12:48.212] E: Time not sync, keep default value
[2025-07-29 13:12:48.282] I: System init event
[2025-07-29 13:12:48.282] I: Received response of command id 3
[2025-07-29 13:12:48.282] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 13:12:48.282] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:12:48.282] I: STM Image confirm timer was stopped
[2025-07-29 13:12:55.121] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 13:12:55.121] I: stop_ota_finalization_timer
[2025-07-29 13:12:55.121] I: After OTAU, Redpine Firmware Version: 2.c.0.3
[2025-07-29 13:12:55.121] I: Redpine New OTA Firmware Version = 2 c 0 3
[2025-07-29 13:12:55.121] I: After OTAU, Secure STM Firmware Version: 17 5 4 1a
[2025-07-29 13:12:55.121] I: Send Op Mode command to release Redpine BLE and WiFI
[2025-07-29 13:12:55.121] I: Operating Mode Command: Mode:10, State:f0
[2025-07-29 13:12:55.121] E: Sending UART cmd(5) st 0
[2025-07-29 13:12:55.171] I: Operating mode event
[2025-07-29 13:12:55.171] I: Received response of command id 5
[2025-07-29 13:12:55.171] I: Received Lock Op Mode Event, mode 10, App state 10
[2025-07-29 13:12:55.171] I: Lock Current Mode : 10, Lock Current State = 10
[2025-07-29 13:12:55.171] I: stop_ota_finalization_timer
[2025-07-29 13:12:55.171] I: STM32 HALO APP STATE IS ACTIVATED NORMAL
[2025-07-29 13:12:55.171] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:12:55.171] I: Set Kwikset Lock App State 16
[2025-07-29 13:12:55.171] I: Matter enabled state 0
[2025-07-29 13:12:55.171] I: Matter is disabled
[2025-07-29 13:12:55.171] I: OTA_HOUSEKEEPING
[2025-07-29 13:12:55.171] I: OTA Stage Change from (3b)->(80)
[2025-07-29 13:12:55.171] I: Start Erasing OTA bundle from nRF External Flash
[2025-07-29 13:13:05.911] I: System info event
[2025-07-29 13:13:05.911] I: Received System Info Event
[2025-07-29 13:13:05.911] I: Time is set in STM
[2025-07-29 13:13:56.232] I: Bundle Image Erased from nRF External Flash: 0
[2025-07-29 13:13:56.241] I: OTAU Completed Successfully
[2025-07-29 13:13:56.354] I: Cleared OTA Meta Data
[2025-07-29 13:13:56.354] I: OTA Stage Change from (80)->(90)
[2025-07-29 13:13:58.351] I: All message synced.
[2025-07-29 13:14:11.342] I: STOP BLE Advertisment
[2025-07-29 13:14:11.362] I: 538664 [DL]DFU over SMP stopped
[2025-07-29 13:14:11.362] E: Sending UART cmd(9e) st 0
[2025-07-29 13:18:47.912] I: Updated ota meta data
[2025-07-29 13:18:47.912] I: Operating Mode Command: Mode:10, State:34
[2025-07-29 13:18:47.912] E: Sending UART cmd(5) st 0
[2025-07-29 13:18:47.992] I: Operating mode event
[2025-07-29 13:18:48.052] I: Received response of command id 5
[2025-07-29 13:18:48.052] I: Received Lock Op Mode Event, mode 10, App state 34
[2025-07-29 13:18:48.052] I: Lock Current Mode : 10, Lock Current State = 34
[2025-07-29 13:18:48.052] I: STM32 HALO APP STATE IS BLE OTAU TRANSFER
[2025-07-29 13:18:48.052] E: Sending UART cmd(9e) st 0
[2025-07-29 13:18:48.052] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 13:18:48.052] I: 815343 [SWU]SMP BLE advertising started
[2025-07-29 13:18:48.052] I: 815347 [DL]DFU over SMP started
[2025-07-29 13:18:48.052] I: OTA Stage Change from (90)->(11)
[2025-07-29 13:18:48.052] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:18:48.052] I: Set Kwikset Lock App State 52
[2025-07-29 13:18:48.058] I: Matter is disabled
[2025-07-29 13:19:03.612] I: 830932 [DL]Current number of connections: 1/1
[2025-07-29 13:19:03.612] I: BLE Connected
[2025-07-29 13:19:03.863] I: 831165 [DL]Current number of connections: 0/1
[2025-07-29 13:19:03.863] I: BLE Disconnected: 13
[2025-07-29 13:19:08.712] I: 836019 [DL]Current number of connections: 1/1
[2025-07-29 13:19:08.712] I: BLE Connected
[2025-07-29 13:19:08.922] I: 836241 [DL]DFU Image upload started
[2025-07-29 13:19:09.767] I: Connection parameters updated.
[2025-07-29 13:19:09.772]  interval: 9, latency: 0, timeout: 42
[2025-07-29 13:19:18.742] I: OTA Stage Change from (11)->(12)
[2025-07-29 13:19:18.742] I: 846066 [DL]Image 0 download completed successfully
[2025-07-29 13:19:18.782] I: 846090 [DL]Current number of connections: 0/1
[2025-07-29 13:19:18.782] I: 846094 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:19:18.782] I: BLE Disconnected: 13
[2025-07-29 13:19:31.272] I: 858578 [DL]Current number of connections: 1/1
[2025-07-29 13:19:31.272] I: BLE Connected
[2025-07-29 13:19:31.512] I: 858823 [DL]DFU Image upload started
[2025-07-29 13:19:32.343] I: Connection parameters updated.
[2025-07-29 13:19:32.343]  interval: 9, latency: 0, timeout: 42
[2025-07-29 13:19:32.343] E: No available ACL buffers!
[2025-07-29 13:19:32.343] E: Unexpected first L2CAP frame
[2025-07-29 13:20:24.092] I: OTA Stage Change from (12)->(13)
[2025-07-29 13:20:24.112] I: 911418 [DL]Image 1 download completed successfully
[2025-07-29 13:20:24.112] I: 911437 [DL]Current number of connections: 0/1
[2025-07-29 13:20:24.132] I: 911441 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:20:24.132] I: BLE Disconnected: 13
[2025-07-29 13:20:32.012] I: 919343 [DL]Current number of connections: 1/1
[2025-07-29 13:20:32.032] I: BLE Connected
[2025-07-29 13:20:32.258] I: 919580 [DL]DFU Image upload started
[2025-07-29 13:20:33.072] I: Connection parameters updated.
[2025-07-29 13:20:33.092]  interval: 9, latency: 0, timeout: 42
[2025-07-29 13:20:33.092] E: No available ACL buffers!
[2025-07-29 13:20:33.092] E: Unexpected first L2CAP frame
[2025-07-29 13:23:31.452] I: OTA Stage Change from (13)->(14)
[2025-07-29 13:23:31.452] I: 1098768 [DL]Image 2 download completed successfully
[2025-07-29 13:23:31.482] I: 1098789 [DL]Current number of connections: 0/1
[2025-07-29 13:23:31.482] I: 1098794 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:23:31.482] I: BLE Disconnected: 13
[2025-07-29 13:23:39.152] I: 1106460 [DL]Current number of connections: 1/1
[2025-07-29 13:23:39.152] I: BLE Connected
[2025-07-29 13:23:39.392] I: 1106705 [DL]Current number of connections: 0/1
[2025-07-29 13:23:39.392] I: BLE Disconnected: 13
[2025-07-29 13:23:43.482] I: 1110795 [DL]Current number of connections: 1/1
[2025-07-29 13:23:43.482] I: BLE Connected
[2025-07-29 13:23:43.672] I: 1111006 [DL]DFU_ImgConfirmHandler: Nordic Image Confirmed by MCUMgr
[2025-07-29 13:23:43.722] I: 1111033 [DL]Current number of connections: 0/1
[2025-07-29 13:23:43.722] I: BLE Disconnected: 13
[2025-07-29 13:23:50.633] I: 1117960 [DL]Current number of connections: 1/1
[2025-07-29 13:23:50.652] I: BLE Connected
[2025-07-29 13:23:50.843] I: 1118169 [DL]DFU_ImgConfirmHandler: Nordic Image Confirmed by MCUMgr
[2025-07-29 13:23:50.872] I: 1118203 [DL]Current number of connections: 0/1
[2025-07-29 13:23:50.892] I: BLE Disconnected: 13
[2025-07-29 13:23:58.282] I: 1125609 [DL]Current number of connections: 1/1
[2025-07-29 13:23:58.282] I: BLE Connected
[2025-07-29 13:23:58.492] I: STM Pending =0, Redpine Pending = 0
[2025-07-29 13:23:58.582] I: Count = 4
[2025-07-29 13:23:58.582] I: dfu_header_data.image_count: 4
[2025-07-29 13:23:59.352] I: Connection parameters updated.
[2025-07-29 13:23:59.352]  interval: 9, latency: 0, timeout: 42
[2025-07-29 13:23:59.462] I: IMG Integrity Verified Successfully: 0
[2025-07-29 13:24:02.422] I: IMG Integrity Verified Successfully: 1
[2025-07-29 13:24:02.502] I: IMG Integrity Verified Successfully: 2
[2025-07-29 13:24:02.822] I: IMG Integrity Verified Successfully: 3
[2025-07-29 13:24:02.822] I: OTA Bundle(STM32 + RS9116 + PN76) image integrity Verified
[2025-07-29 13:24:02.822] I: OTA Stage Change from (14)->(30)
[2025-07-29 13:24:02.922] I: Updated ota meta data
[2025-07-29 13:24:02.922] I: Operating Mode Command: Mode:10, State:31
[2025-07-29 13:24:02.922] E: Sending UART cmd(5) st 0
[2025-07-29 13:24:02.922] I: Operating mode event
[2025-07-29 13:24:02.963] I: Received response of command id 5
[2025-07-29 13:24:02.963] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:24:02.963] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:24:02.963] I: STM OTAU Pending: Reset Nordic Triggered
[2025-07-29 13:24:02.963] I: OTA Stage Change from (30)->(30)
[2025-07-29 13:24:02.963] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:24:02.963] I: Set Kwikset Lock App State 49
[2025-07-29 13:24:02.963] I: Matter is disabled
[2025-07-29 13:24:03.022] I: 1130330 [DL]Current number of connections: 0/1
[2025-07-29 13:24:03.022] I: BLE Disconnected: 13
[2025-07-29 13:24:47.993] 
[2025-07-29 13:24:47.993] 
[2025-07-29 13:24:47.993] uart:~$ *** Booting My Application v23.49.0-de86e88ec64e ***
[2025-07-29 13:24:48.032] *** Using nRF Connect SDK v2.7.0-5cb85570ca43 ***
[2025-07-29 13:24:48.032] *** Using Zephyr OS v3.6.99-100befc70c74 ***
[2025-07-29 13:24:48.032] I: KWIKSET HALO 3 PLUS VERSION: 17.31.00.02
[2025-07-29 13:24:48.032] I: 51 [DL]BLE address: D5:6A:B6:E4:AC:9F
[2025-07-29 13:24:48.052] I: No users indexes stored
[2025-07-29 13:24:48.052] I: No stored indexes for credential of type: 1
[2025-07-29 13:24:48.172] I: No stored indexes for credential of type: 2
[2025-07-29 13:24:48.172] I: No stored indexes for credential of type: 3
[2025-07-29 13:24:48.172] I: ========== User Index: 0x01 User ID: 0xffffffff ==========
[2025-07-29 13:24:48.172] I: ========== User Index: 0x02 User ID: 0xffffffff ==========
[2025-07-29 13:24:48.172] I: ========== User Index: 0x03 User ID: 0xffffffff ==========
[2025-07-29 13:24:48.172] I: ========== User Index: 0x04 User ID: 0xffffffff ==========
[2025-07-29 13:24:48.172] I: ========== User Index: 0x05 User ID: 0xffffffff ==========
[2025-07-29 13:24:48.172] I: ========== User Index: 0x06 User ID: 0xffffffff ==========
[2025-07-29 13:24:48.172] I: ========== User Index: 0x07 User ID: 0xffffffff ==========
[2025-07-29 13:24:48.172] I: ========== User Index: 0x08 User ID: 0xffffffff ==========
[2025-07-29 13:24:48.172] I: ========== User Index: 0x09 User ID: 0xffffffff ==========
[2025-07-29 13:24:48.200] I: ========== User Index: 0x0a User ID: 0xffffffff ==========
[2025-07-29 13:24:48.200] I: ========== User Index: 0x0b User ID: 0xffffffff ==========
[2025-07-29 13:24:48.200] I: Board config kwiksetmdb_nrf5340_cpuapp
[2025-07-29 13:24:48.200] I: IMAGE_VERSION 17310002
[2025-07-29 13:24:48.200] I: build time: Jun 18 2025 10:48:56
[2025-07-29 13:24:48.200] I: 162 [DL]CHIP task running
[2025-07-29 13:24:48.200] I: Init CHIP stack
[2025-07-29 13:24:48.200] I: 167 [DL]OpenThread started: OK
[2025-07-29 13:24:48.200] I: 171 [DL]Setting OpenThread device type to SLEEPY END DEVICE
[2025-07-29 13:24:48.200] I: 176 [SWU]New firmware image confirmed
[2025-07-29 13:24:48.200] I: 180 [SWU]DFU_BLEAdvertising_Init
[2025-07-29 13:24:48.213] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 13:24:48.573] I: NFC Boot Event PN7642 FW VERSION 17.01.00.02
[2025-07-29 13:24:48.573] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 13:24:48.573] I: 
[2025-07-29 13:24:48.573] Boot Event Received
[2025-07-29 13:24:48.573] 
[2025-07-29 13:24:48.573] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 13:24:48.573] 
[2025-07-29 13:24:48.573] I: 264 [SVR]Subscription persistence not supported
[2025-07-29 13:24:48.573] I: 268 [SVR]Server initializing...
[2025-07-29 13:24:48.573] I: 272 [TS]Last Known Good Time: 2023-10-14T01:16:48
[2025-07-29 13:24:48.573] I: 277 [DMG]AccessControl: initializing
[2025-07-29 13:24:48.573] I: 280 [DMG]Examples::AccessControlDelegate::Init
[2025-07-29 13:24:48.573] I: 285 [DMG]AccessControl: setting
[2025-07-29 13:24:48.573] I: 288 [DMG]DefaultAclStorage: initializing
[2025-07-29 13:24:48.573] I: 292 [DMG]DefaultAclStorage: 0 entries loaded
[2025-07-29 13:24:48.598] E: 296 [IN]IPV6_PKTINFO failed: 109
[2025-07-29 13:24:48.598] I: 302 [ZCL]Using ZAP configuration...
[2025-07-29 13:24:48.598] I: 307 [DMG]AccessControlCluster: initializing
[2025-07-29 13:24:48.598] ===== Attribute Received are: Cluster=30 Attribute=0 Value=0 =====
[2025-07-29 13:24:48.598] I: 318 [ZCL]Emit DSTTableEmpty event [ep=0]
[2025-07-29 13:24:48.598] I: 322 [ZCL]Initiating Admin Commissioning cluster.
[2025-07-29 13:24:48.598] I: 327 [ZCL]Door Lock server initialized
[2025-07-29 13:24:48.598] E: 330 [ZCL]DeviceInfoProvider is not registered
[2025-07-29 13:24:48.598] E: 335 [ZCL]Failed to read calendar type with error: 0x86
[2025-07-29 13:24:48.598] ===== Attribute Received are: Cluster=3 Attribute=1 Value=3 =====
[2025-07-29 13:24:48.598] I: 346 [ZCL]Door Lock cluster initialized at endpoint #1
[2025-07-29 13:24:48.598] ===== Attribute Received are: Cluster=101 Attribute=0 Value=255 =====
[2025-07-29 13:24:48.598] ===== Attribute Received are: Cluster=101 Attribute=2 Value=1 =====
[2025-07-29 13:24:48.612] ===== Attribute Received are: Cluster=101 Attribute=1 Value=0 =====
[2025-07-29 13:24:48.612] ===== Attribute Received are: Cluster=101 Attribute=11 Value=11 =====
[2025-07-29 13:24:48.612] ===== Attribute Received are: Cluster=101 Attribute=12 Value=35 =====
[2025-07-29 13:24:48.612] ===== Attribute Received are: Cluster=101 Attribute=13 Value=35 =====
[2025-07-29 13:24:48.612] ===== Attribute Received are: Cluster=101 Attribute=1c Value=35 =====
[2025-07-29 13:24:48.612] ===== Attribute Received are: Cluster=101 Attribute=19 Value=80 =====
[2025-07-29 13:24:48.612] I: 399 [DIS]Updating services using commissioning mode 0
[2025-07-29 13:24:48.612] E: 404 [DIS]Failed to remove advertised services: 3
[2025-07-29 13:24:48.612] E: 409 [DIS]Failed to finalize service update: 3
[2025-07-29 13:24:48.612] I: 413 [IN]CASE Server enabling CASE session setups
[2025-07-29 13:24:48.632] I: 418 [SVR]Joining Multicast groups
[2025-07-29 13:24:48.632] I: 422 [SVR]Server Listening...
[2025-07-29 13:24:48.632] I: 425 [DL]Device Configuration:
[2025-07-29 13:24:48.632] I: 427 [DL]  Serial Number: 1789AE57B32427844F
[2025-07-29 13:24:48.632] I: 432 [DL]  Vendor Id: 5153 (0x1421)
[2025-07-29 13:24:48.632] I: 435 [DL]  Product Id: 66 (0x42)
[2025-07-29 13:24:48.632] I: Get product name B, len 0
[2025-07-29 13:24:48.632] I: 441 [DL]  Product Name: B
[2025-07-29 13:24:48.632] I: 443 [DL]  Hardware Version: 1
[2025-07-29 13:24:48.632] I: 446 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 75655451
[2025-07-29 13:24:48.632] I: 452 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 776 (0x308)
[2025-07-29 13:24:48.632] I: 458 [DL]  Manufacturing Date: 2025-07-24
[2025-07-29 13:24:48.632] I: 462 [DL]  Device Type: 10 (0xA)
[2025-07-29 13:24:48.632] I: 465 [SVR]SetupQRCode: [MT:-QWJ08DB00.I2N6SM10]
[2025-07-29 13:24:48.632] I: 469 [SVR]Copy/paste the below URL in a browser to see the QR Code:
[2025-07-29 13:24:48.654] I: 476 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-QWJ08DB00.I2N6SM10
[2025-07-29 13:24:48.654] I: 484 [SVR]Manual pairing code: [05967546175]
[2025-07-29 13:24:48.654] I: STM32 device number: 
[2025-07-29 13:24:48.654] I: 31 37 38 39 41 45 35 37 |1789AE57
[2025-07-29 13:24:48.654] I: 42 33 32 34 32 37 38 34 |B3242784
[2025-07-29 13:24:48.654] I: 34 46                   |4F      
[2025-07-29 13:24:48.654] I: SKU number: 
[2025-07-29 13:24:48.654] I: 4b 31 37 2d 30 31       |K17-01  
[2025-07-29 13:24:48.654] I: WO number: 
[2025-07-29 13:24:48.654] I: 30 30 30 30 30 30 30 30 |00000000
[2025-07-29 13:24:48.654] I: 30                      |0       
[2025-07-29 13:24:48.654] I: Manuf Date: 
[2025-07-29 13:24:48.654] I: 32 30 32 35 2d 30 37 2d |2025-07-
[2025-07-29 13:24:48.654] I: 32 34 00 00 00 00       |24....  
[2025-07-29 13:24:48.654] I: Prod config length 6
[2025-07-29 13:24:48.673] I: Product Config: 
[2025-07-29 13:24:48.673] I: 30 78 30 30 30 31       |0x0001  
[2025-07-29 13:24:48.673] I: Prod Config Read 1
[2025-07-29 13:24:48.673] I: User intend flow enabled, set commissioning flow to kUserActionRequired
[2025-07-29 13:24:48.673] I: Factory Data Version length 2
[2025-07-29 13:24:48.673] I: Factory Data Ver: 
[2025-07-29 13:24:48.673] I: 30 31                   |01      
[2025-07-29 13:24:48.673] I: Payload value in string format: MT:-QWJ04TC00.I2N60Q4P0ILT70VYYR1JFSK14YDB0-0LJ1-0LJ1-0LJ1IHLC0AUZL1XIKJ17AZL1UV700CXYR1K6Y12NNZR1YC-L1-2ZR1OADO1KB40
[2025-07-29 13:24:48.673] I: Pairing Code value in string format: 459675461705153000660
[2025-07-29 13:24:48.673] I: ============== Updating product finish and color to 15, 2, product Name Halo Select Plus ==============
[2025-07-29 13:24:48.673] E: 575 [DL]Long dispatch time: 411 ms, for event type 2
[2025-07-29 13:24:48.673] ===== Attribute Received are: Cluster=101 Attribute=0 Value=1 =====
[2025-07-29 13:24:50.123] I: Syncing up on message 9a
[2025-07-29 13:24:50.163] I: STM32 counter to 1
[2025-07-29 13:24:50.163] I: BLE Device ID: 2784
[2025-07-29 13:24:50.163] I: Device is provisioned
[2025-07-29 13:24:50.163] I: network state 0
[2025-07-29 13:24:50.163] E: Sending UART cmd(3) st 0
[2025-07-29 13:24:50.163] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 13:24:50.163] I: Received response of command id 9a
[2025-07-29 13:24:50.163] I: Command 0x9A Received
[2025-07-29 13:24:50.203] I: Firmware Attribute event
[2025-07-29 13:24:50.203] I: Received response of command id 30
[2025-07-29 13:24:50.203] I: Received DC Eco Config REQ
[2025-07-29 13:24:50.203] I: DC Eco Config Resp
[2025-07-29 13:24:50.203] I: Received DC eco config req
[2025-07-29 13:24:50.203] I: 80 72 03 00 10 00 04 1b |.r......
[2025-07-29 13:24:50.203] I: 17 05                   |..      
[2025-07-29 13:24:50.203] E: Sending UART cmd(72) st 0
[2025-07-29 13:24:52.172] I: Syncing up on message 3
[2025-07-29 13:24:52.172] I: Sys init req
[2025-07-29 13:24:52.172] E: Sending UART cmd(3) st 0
[2025-07-29 13:24:52.172] I: System init Response
[2025-07-29 13:24:52.172] I: Received response of command id 3
[2025-07-29 13:24:52.172] I: Update sync timer
[2025-07-29 13:24:52.172] I: Received Sys Init Resp
[2025-07-29 13:24:52.172] I: battery mode 0
[2025-07-29 13:24:52.172] I: battery percentage 5a
[2025-07-29 13:24:52.172] I: battery type 1
[2025-07-29 13:24:52.172] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:24:52.652] I: Syncing up on message 5
[2025-07-29 13:24:52.652] I: Operating mode req
[2025-07-29 13:24:52.702] E: Sending UART cmd(5) st 0
[2025-07-29 13:24:52.702] I: Operating mode response
[2025-07-29 13:24:52.702] I: Received response of command id 5
[2025-07-29 13:24:52.702] I: Received Lock Op Mode Resp, mode 10, App state 31
[2025-07-29 13:24:52.702] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:24:52.702] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:24:52.702] I: Set Kwikset Lock App State 49
[2025-07-29 13:24:52.702] I: Matter is disabled
[2025-07-29 13:24:53.203] I: Syncing up on message 10
[2025-07-29 13:24:53.203] I: Lock state req
[2025-07-29 13:24:53.203] E: Sending UART cmd(10) st 0
[2025-07-29 13:24:53.203] I: Lock State Response
[2025-07-29 13:24:53.203] I: Received response of command id 10
[2025-07-29 13:24:53.203] I: Received Lock State Response, lock st: 12
[2025-07-29 13:24:53.203] I: Found matching nordic source of operation 0
[2025-07-29 13:24:53.203] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:24:53.203] I: Unlock action completed
[2025-07-29 13:24:53.203] I: Updating LockState attribute
[2025-07-29 13:24:53.203] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:24:53.652] I: Syncing up on message 20
[2025-07-29 13:24:53.692] I: Lock setting req
[2025-07-29 13:24:53.692] E: Sending UART cmd(20) st 0
[2025-07-29 13:24:53.692] I: Lock General Setting Response
[2025-07-29 13:24:53.692] I: Received response of command id 20
[2025-07-29 13:24:53.692] I: Received Lock General Setting resp
[2025-07-29 13:24:53.692] I: Matter Not Enabled do not set
[2025-07-29 13:24:54.153] I: Syncing up on message 51
[2025-07-29 13:24:54.153] I: Battery info req
[2025-07-29 13:24:54.153] E: Sending UART cmd(51) st 0
[2025-07-29 13:24:54.193] I: Received response of command id 51
[2025-07-29 13:24:54.193] I: Received Battery Info resp
[2025-07-29 13:24:54.193] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:24:54.193] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:24:54.193] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:24:54.662] I: All message synced.
[2025-07-29 13:25:18.192] I: STM system init timer expired, System Init Event not received from STM32
[2025-07-29 13:25:18.192] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 13:25:18.192] I: STM Pending =1, Redpine Pending = 1
[2025-07-29 13:25:18.192] I: STM Post OTA Pending
[2025-07-29 13:25:18.192] I: Redpine Post OTA Pending
[2025-07-29 13:25:18.192] E: Sending UART cmd(9e) st 0
[2025-07-29 13:25:18.192] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 13:25:18.192] I: 30191 [SWU]SMP BLE advertising started
[2025-07-29 13:25:18.192] I: 30196 [DL]DFU over SMP started
[2025-07-29 13:25:19.063] I: IMG Integrity Verified Successfully: 0
[2025-07-29 13:25:22.062] I: IMG Integrity Verified Successfully: 1
[2025-07-29 13:25:22.142] I: IMG Integrity Verified Successfully: 2
[2025-07-29 13:25:22.422] I: IMG Integrity Verified Successfully: 3
[2025-07-29 13:25:22.461] I: OTA Stage Change from (ff)->(32)
[2025-07-29 13:25:22.461] I: OTA device_id = 5 : DISCOVERY_REQ
[2025-07-29 13:25:22.573] I: SECURE_STM : IB_DEVICE_DISCOVERY_REQUEST (80) 
[2025-07-29 13:25:22.573] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 13:25:22.573] I: STM Current Firmware Version: 17 5 4 1a
[2025-07-29 13:25:22.573] I: STM New OTA Firmware Version = 17 5 4 1b
[2025-07-29 13:25:22.573] I: OTA device_id = 5 : FW_UPDATE_START_REQ
[2025-07-29 13:25:22.573] I: SECURE_STM : IB_FW_UPDATE_START_REQUEST (80)
[2025-07-29 13:25:28.923] I: STM OTA Progress = 10
[2025-07-29 13:25:35.222] I: STM OTA Progress = 20
[2025-07-29 13:25:41.542] I: STM OTA Progress = 30
[2025-07-29 13:25:47.962] I: STM OTA Progress = 40
[2025-07-29 13:25:54.273] I: STM OTA Progress = 50
[2025-07-29 13:26:00.593] I: STM OTA Progress = 60
[2025-07-29 13:26:06.913] I: STM OTA Progress = 70
[2025-07-29 13:26:13.242] I: STM OTA Progress = 80
[2025-07-29 13:26:19.563] I: STM OTA Progress = 90
[2025-07-29 13:26:25.865] I: STM OTA Progress = 100
[2025-07-29 13:26:26.553] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 13:26:26.572] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 13:26:44.263] I: Sending Sys Init Resp
[2025-07-29 13:26:44.263] I: Device is provisioned
[2025-07-29 13:26:44.263] I: network state 0
[2025-07-29 13:26:44.263] E: Sending UART cmd(3) st 0
[2025-07-29 13:26:44.263] I: Received DC App Config REQ
[2025-07-29 13:26:44.263] I: DC App Config Resp
[2025-07-29 13:26:44.263] I: Received DC config req
[2025-07-29 13:26:44.263] I: 80 70 03 00 10 10 08 00 |.p......
[2025-07-29 13:26:44.263] I: 50 1e                   |P.      
[2025-07-29 13:26:44.263] I: Matter enabled state 0
[2025-07-29 13:26:44.263] I: Get Matter Commission State
[2025-07-29 13:26:44.263] I: network state 0
[2025-07-29 13:26:44.272] I: network state 0
[2025-07-29 13:26:44.272] E: Sending UART cmd(70) st 0
[2025-07-29 13:26:44.335] I: Lock State Event
[2025-07-29 13:26:44.335] I: Received response of command id 10
[2025-07-29 13:26:44.335] I: Received Lock State event, lock st: 12
[2025-07-29 13:26:44.335] I: Found matching nordic source of operation 0
[2025-07-29 13:26:44.335] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:26:44.335] I: Unlock action completed
[2025-07-29 13:26:44.335] I: Updating LockState attribute
[2025-07-29 13:26:44.335] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:26:44.363] I: Received DC Eco Config REQ
[2025-07-29 13:26:44.363] I: DC Eco Config Resp
[2025-07-29 13:26:44.393] I: Received DC eco config req
[2025-07-29 13:26:44.393] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 13:26:44.393] I: c4 1e                   |..      
[2025-07-29 13:26:44.393] E: Sending UART cmd(72) st 0
[2025-07-29 13:26:44.563] I: General Lock Setting event
[2025-07-29 13:26:44.563] I: Received response of command id 20
[2025-07-29 13:26:44.563] I: Received Lock General Setting event
[2025-07-29 13:26:44.563] I: Matter Not Enabled do not set
[2025-07-29 13:26:44.662] I: Firmware Attribute event
[2025-07-29 13:26:44.662] I: Received response of command id 30
[2025-07-29 13:26:44.735] I: Hardware Attribute event
[2025-07-29 13:26:44.735] I: Received response of command id 31
[2025-07-29 13:26:44.812] I: Operating mode event
[2025-07-29 13:26:44.812] I: Received response of command id 5
[2025-07-29 13:26:44.812] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:26:44.812] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:26:44.812] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:26:44.812] I: Set Kwikset Lock App State 49
[2025-07-29 13:26:44.812] I: Matter is disabled
[2025-07-29 13:26:44.932] I: Battery Info event
[2025-07-29 13:26:44.932] I: Received response of command id 51
[2025-07-29 13:26:44.932] I: Received Battery info event
[2025-07-29 13:26:44.932] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:26:44.932] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:26:44.932] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:26:45.015] I: System info event
[2025-07-29 13:26:45.015] I: Received System Info Event
[2025-07-29 13:26:45.040] W: Time invalid, set time
[2025-07-29 13:26:45.040] I: Get system time
[2025-07-29 13:26:45.040] I: System Real time in seconds 373662943
[2025-07-29 13:26:45.040] I: Time sync status flag 0
[2025-07-29 13:26:45.040] E: Time not sync, keep default value
[2025-07-29 13:26:45.152] I: System init event
[2025-07-29 13:26:45.152] I: Received response of command id 3
[2025-07-29 13:26:45.152] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 13:26:45.152] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:26:45.152] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 13:26:45.152] I: STM Current Firmware Version: 17 5 4 1b
[2025-07-29 13:26:45.152] I: OTA device_id = 5 : FW_UPDATE_COMPLETE_REQ
[2025-07-29 13:26:45.152] I: SECURE_STM : IB_FW_UPDATE_COMPLETE_REQUEST (80) 
[2025-07-29 13:26:45.152] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 13:26:45.152] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 13:26:47.613] I: Sending Sys Init Resp
[2025-07-29 13:26:47.613] I: Device is provisioned
[2025-07-29 13:26:47.613] I: network state 0
[2025-07-29 13:26:47.613] E: Sending UART cmd(3) st 0
[2025-07-29 13:26:47.613] I: Received DC App Config REQ
[2025-07-29 13:26:47.613] I: DC App Config Resp
[2025-07-29 13:26:47.613] I: Received DC config req
[2025-07-29 13:26:47.613] I: 80 70 03 00 10 10 04 1b |.p......
[2025-07-29 13:26:47.613] I: 00 62                   |.b      
[2025-07-29 13:26:47.613] I: Matter enabled state 0
[2025-07-29 13:26:47.613] I: Get Matter Commission State
[2025-07-29 13:26:47.613] I: network state 0
[2025-07-29 13:26:47.613] I: network state 0
[2025-07-29 13:26:47.613] E: Sending UART cmd(70) st 0
[2025-07-29 13:26:47.683] I: Lock State Event
[2025-07-29 13:26:47.683] I: Received response of command id 10
[2025-07-29 13:26:47.683] I: Received Lock State event, lock st: 12
[2025-07-29 13:26:47.683] I: Found matching nordic source of operation 0
[2025-07-29 13:26:47.683] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:26:47.683] I: Unlock action completed
[2025-07-29 13:26:47.683] I: Updating LockState attribute
[2025-07-29 13:26:47.683] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:26:47.713] I: Received DC Eco Config REQ
[2025-07-29 13:26:47.713] I: DC Eco Config Resp
[2025-07-29 13:26:47.743] I: Received DC eco config req
[2025-07-29 13:26:47.743] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 13:26:47.743] I: c4 62                   |.b      
[2025-07-29 13:26:47.743] E: Sending UART cmd(72) st 0
[2025-07-29 13:26:47.913] I: General Lock Setting event
[2025-07-29 13:26:47.913] I: Received response of command id 20
[2025-07-29 13:26:47.913] I: Received Lock General Setting event
[2025-07-29 13:26:47.913] I: Matter Not Enabled do not set
[2025-07-29 13:26:48.023] I: Firmware Attribute event
[2025-07-29 13:26:48.023] I: Received response of command id 30
[2025-07-29 13:26:48.083] I: Hardware Attribute event
[2025-07-29 13:26:48.083] I: Received response of command id 31
[2025-07-29 13:26:48.152] I: Operating mode event
[2025-07-29 13:26:48.152] I: Received response of command id 5
[2025-07-29 13:26:48.152] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:26:48.152] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:26:48.152] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:26:48.152] I: Set Kwikset Lock App State 49
[2025-07-29 13:26:48.152] I: Matter is disabled
[2025-07-29 13:26:48.233] I: Battery Info event
[2025-07-29 13:26:48.272] I: Received response of command id 51
[2025-07-29 13:26:48.272] I: Received Battery info event
[2025-07-29 13:26:48.272] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:26:48.272] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:26:48.272] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:26:48.352] I: System info event
[2025-07-29 13:26:48.383] I: Received System Info Event
[2025-07-29 13:26:48.383] W: Time invalid, set time
[2025-07-29 13:26:48.383] I: Get system time
[2025-07-29 13:26:48.383] I: System Real time in seconds 373662943
[2025-07-29 13:26:48.383] I: Time sync status flag 0
[2025-07-29 13:26:48.383] E: Time not sync, keep default value
[2025-07-29 13:26:48.413] I: System init event
[2025-07-29 13:26:48.463] I: Received response of command id 3
[2025-07-29 13:26:48.463] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 13:26:48.463] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:26:48.463] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 13:26:48.463] I: STM Current Firmware Version: 17 5 4 1b
[2025-07-29 13:26:48.463] I: STM New OTA Firmware Version = 17 5 4 1b
[2025-07-29 13:26:48.463] I: STM Secure OTA Successful
[2025-07-29 13:26:48.548] I: Cleared STM OTA Meta Data
[2025-07-29 13:26:48.577] I: OTA Stage Change from (32)->(33)
[2025-07-29 13:26:48.577] I: Redpine OTA started
[2025-07-29 13:26:48.577] I: OTA Stage Change from (33)->(34)
[2025-07-29 13:26:48.577] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 13:26:55.563] I: STM Reset Count 0
[2025-07-29 13:26:55.563] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 13:26:55.593] I: STM_QSPI : IB_DEVICE_DISCOVERY_REQUEST (80)
[2025-07-29 13:26:55.593] I: OTA device_id = 4 : FW_VERSION_REQ
[2025-07-29 13:26:55.593] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 13:26:55.613] I: Redpine Current Firmware Version: 2.c.0.3
[2025-07-29 13:26:55.613] I: Redpine New OTA Firmware Version = 2 c 0 3
[2025-07-29 13:26:55.613] I: Skip Redpine OTA, Older OTA Version Request Received
[2025-07-29 13:26:55.733] I: Clear Redpine OTA Meta Data
[2025-07-29 13:26:55.733] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 13:26:55.733] I: STM Pending =2, Redpine Pending = 2
[2025-07-29 13:26:55.733] I: PN76 IMG 1 Post OTA Pending
[2025-07-29 13:26:55.733] E: Sending UART cmd(9e) st 0
[2025-07-29 13:26:55.733] I: 127743 [SWU]Software update is already enabled
[2025-07-29 13:26:55.813] I: IMG Integrity Verified Successfully: 2
[2025-07-29 13:26:56.143] I: IMG Integrity Verified Successfully: 3
[2025-07-29 13:26:56.143] I: OTA Stage Change from (34)->(3a)
[2025-07-29 13:26:56.143] I: PN76_IMG1_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 13:26:56.143] I: PN76_IMG Update from OTA Task Event
[2025-07-29 13:26:56.143] I: 
[2025-07-29 13:26:56.143] 
[2025-07-29 13:26:56.143] --------------- UPDATING PN7642 NXP FIRMWARE --------------------
[2025-07-29 13:26:56.143] 
[2025-07-29 13:26:56.143] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 13:26:56.183] I: pNXPFWInfo->img_offset = 0x35149a
[2025-07-29 13:26:56.183] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 13:26:56.183] I: Reading version of firmware in QSPI flash: MetaData 0x3f60217
[2025-07-29 13:26:56.183] I: NXP FW Version 2 f6 : 2 f6
[2025-07-29 13:26:56.183] I: PN76 NXP FW VERSION IS EQUAL
[2025-07-29 13:26:56.183] I: 
[2025-07-29 13:26:56.183] PN7642 Firmware of type 0 Successfully Updated !!!
[2025-07-29 13:26:56.313] I: Cleared PN76 Img1 OTA Meta Data
[2025-07-29 13:26:56.313] I: OTA Stage Change from (3a)->(3a)
[2025-07-29 13:26:56.313] I: PN76_IMG2_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 13:26:56.313] I: PN76_IMG Update from OTA Task Event
[2025-07-29 13:26:56.313] I: 
[2025-07-29 13:26:56.313] 
[2025-07-29 13:26:56.313] --------------- UPDATING PN7642 APPLICATION FIRMWARE -------------
[2025-07-29 13:26:56.313] 
[2025-07-29 13:26:56.313] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 13:26:56.352] I: pCustAppFWInfo->img_offset = 0x35c28c
[2025-07-29 13:26:56.352] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 13:26:56.352] I: Reading version of firmware in QSPI flash: MetaData 0x3f60217
[2025-07-29 13:26:56.352] I: PN76 NXP APP FW VERSION IS HIGHER
[2025-07-29 13:26:56.653] I: ----> PN7642 OTA Progress = 10 %
[2025-07-29 13:26:56.923] I: ----> PN7642 OTA Progress = 20 %
[2025-07-29 13:26:57.182] I: ----> PN7642 OTA Progress = 30 %
[2025-07-29 13:26:57.443] I: ----> PN7642 OTA Progress = 40 %
[2025-07-29 13:26:57.713] I: ----> PN7642 OTA Progress = 50 %
[2025-07-29 13:26:57.962] I: ----> PN7642 OTA Progress = 60 %
[2025-07-29 13:26:58.223] I: ----> PN7642 OTA Progress = 70 %
[2025-07-29 13:26:58.493] I: ----> PN7642 OTA Progress = 80 %
[2025-07-29 13:26:58.753] I: ----> PN7642 OTA Progress = 90 %
[2025-07-29 13:26:59.003] I: ----> PN7642 OTA Progress = 100 %
[2025-07-29 13:26:59.032] I: Whole pn7642 FW Image downloaded ....
[2025-07-29 13:26:59.032] I: 
[2025-07-29 13:26:59.032] 
[2025-07-29 13:26:59.032] I: 
[2025-07-29 13:26:59.032] PN7642 Firmware of type 1 Successfully Updated !!!
[2025-07-29 13:26:59.113] I: Cleared PN76 Img2 OTA Meta Data
[2025-07-29 13:26:59.223] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 13:26:59.223] I: NFC Boot Event PN7642 FW VERSION 17.01.00.03
[2025-07-29 13:26:59.223] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 13:26:59.223] I: 
[2025-07-29 13:26:59.223] Boot Event Received
[2025-07-29 13:26:59.223] 
[2025-07-29 13:26:59.223] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 13:26:59.223] 
[2025-07-29 13:26:59.223] I: OTA Stage Change from (3a)->(3b)
[2025-07-29 13:26:59.223] I: post_stm_reset_event : init_pending_ota_update
[2025-07-29 13:26:59.223] I: All pending FW Updates are completed.
[2025-07-29 13:26:59.223] I: STM32 Reset Count = 0
[2025-07-29 13:26:59.228] I: REBOOT_STM: Send STM32 Reboot Command, Count (0)
[2025-07-29 13:27:18.444] I: STM Boot Up Properly, Stopped STM Reboot Timer
[2025-07-29 13:27:48.518] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 13:27:48.553] I: After OTAU, Redpine Version Request timeout (90)
[2025-07-29 13:27:48.553] E: After OTAU, Redpine Firmware Version Request TimedOut
[2025-07-29 13:27:48.553] I: stop_ota_finalization_timer
[2025-07-29 13:27:48.553] I: post_stm_reset_event : IB_FW_VERSION_REQUEST
[2025-07-29 13:27:48.553] I: STM32 Reset Count = 1
[2025-07-29 13:27:48.553] I: REBOOT_STM: Send STM32 Reboot Command, Count (1)
[2025-07-29 13:27:50.533] I: All message synced.
[2025-07-29 13:27:50.823] I: Sending Sys Init Resp
[2025-07-29 13:27:50.873] I: Device is provisioned
[2025-07-29 13:27:50.875] I: network state 0
[2025-07-29 13:27:50.875] E: Sending UART cmd(3) st 0
[2025-07-29 13:27:50.875] I: Received DC App Config REQ
[2025-07-29 13:27:50.875] I: DC App Config Resp
[2025-07-29 13:27:50.875] I: Received DC config req
[2025-07-29 13:27:50.875] I: 80 70 03 00 10 10 00 03 |.p......
[2025-07-29 13:27:50.875] I: 00 62                   |.b      
[2025-07-29 13:27:50.875] I: Matter enabled state 0
[2025-07-29 13:27:50.875] I: Get Matter Commission State
[2025-07-29 13:27:50.875] I: network state 0
[2025-07-29 13:27:50.881] I: network state 0
[2025-07-29 13:27:50.882] E: Sending UART cmd(70) st 0
[2025-07-29 13:27:50.933] I: Lock State Event
[2025-07-29 13:27:50.933] I: Received response of command id 10
[2025-07-29 13:27:50.933] I: Received Lock State event, lock st: 12
[2025-07-29 13:27:50.933] I: Found matching nordic source of operation 0
[2025-07-29 13:27:50.933] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:27:50.933] I: Unlock action completed
[2025-07-29 13:27:50.933] I: Updating LockState attribute
[2025-07-29 13:27:50.933] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:27:50.963] I: Received DC Eco Config REQ
[2025-07-29 13:27:50.963] I: DC Eco Config Resp
[2025-07-29 13:27:50.995] I: Received DC eco config req
[2025-07-29 13:27:50.995] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 13:27:50.995] I: c4 62                   |.b      
[2025-07-29 13:27:50.995] E: Sending UART cmd(72) st 0
[2025-07-29 13:27:51.132] I: General Lock Setting event
[2025-07-29 13:27:51.163] I: Received response of command id 20
[2025-07-29 13:27:51.163] I: Received Lock General Setting event
[2025-07-29 13:27:51.163] I: Matter Not Enabled do not set
[2025-07-29 13:27:51.273] I: Firmware Attribute event
[2025-07-29 13:27:51.273] I: Received response of command id 30
[2025-07-29 13:27:51.332] I: Hardware Attribute event
[2025-07-29 13:27:51.332] I: Received response of command id 31
[2025-07-29 13:27:51.403] I: Operating mode event
[2025-07-29 13:27:51.403] I: Received response of command id 5
[2025-07-29 13:27:51.403] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:27:51.403] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:27:51.403] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:27:51.403] I: Set Kwikset Lock App State 49
[2025-07-29 13:27:51.403] I: Matter is disabled
[2025-07-29 13:27:51.523] I: Battery Info event
[2025-07-29 13:27:51.523] I: Received response of command id 51
[2025-07-29 13:27:51.523] I: Received Battery info event
[2025-07-29 13:27:51.523] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:27:51.523] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:27:51.523] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:27:51.643] I: System info event
[2025-07-29 13:27:51.643] I: Received System Info Event
[2025-07-29 13:27:51.643] W: Time invalid, set time
[2025-07-29 13:27:51.643] I: Get system time
[2025-07-29 13:27:51.643] I: System Real time in seconds 373662943
[2025-07-29 13:27:51.643] I: Time sync status flag 0
[2025-07-29 13:27:51.643] E: Time not sync, keep default value
[2025-07-29 13:27:51.673] I: System init event
[2025-07-29 13:27:51.723] I: Received response of command id 3
[2025-07-29 13:27:51.723] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 13:27:51.723] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:27:51.723] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 13:27:51.723] I: STM Pending =2, Redpine Pending = 2
[2025-07-29 13:27:51.723] I: Lock controller already updated, OTA is in finalization stage
[2025-07-29 13:27:51.723] I: OTA is in finalization stage
[2025-07-29 13:27:51.723] E: Sending UART cmd(9e) st 0
[2025-07-29 13:27:51.723] I: 183735 [SWU]Software update is already enabled
[2025-07-29 13:27:58.572] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 13:27:58.622] I: stop_ota_finalization_timer
[2025-07-29 13:27:58.622] I: After OTAU, Redpine Firmware Version: 2.c.0.3
[2025-07-29 13:27:58.622] I: Redpine New OTA Firmware Version = 2 c 0 3
[2025-07-29 13:27:58.622] I: After OTAU, Secure STM Firmware Version: 17 5 4 1b
[2025-07-29 13:27:58.622] I: Send Op Mode command to release Redpine BLE and WiFI
[2025-07-29 13:27:58.622] I: Operating Mode Command: Mode:10, State:f0
[2025-07-29 13:27:58.622] E: Sending UART cmd(5) st 0
[2025-07-29 13:27:58.673] I: Operating mode event
[2025-07-29 13:27:58.673] I: Received response of command id 5
[2025-07-29 13:27:58.673] I: Received Lock Op Mode Event, mode 10, App state 10
[2025-07-29 13:27:58.673] I: Lock Current Mode : 10, Lock Current State = 10
[2025-07-29 13:27:58.673] I: stop_ota_finalization_timer
[2025-07-29 13:27:58.673] I: STM32 HALO APP STATE IS ACTIVATED NORMAL
[2025-07-29 13:27:58.673] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:27:58.673] I: Set Kwikset Lock App State 16
[2025-07-29 13:27:58.673] I: Matter enabled state 0
[2025-07-29 13:27:58.673] I: Matter is disabled
[2025-07-29 13:27:58.673] I: OTA_HOUSEKEEPING
[2025-07-29 13:27:58.673] I: OTA Stage Change from (3b)->(80)
[2025-07-29 13:27:58.682] I: Start Erasing OTA bundle from nRF External Flash
[2025-07-29 13:28:04.693] I: System info event
[2025-07-29 13:28:04.712] I: Received System Info Event
[2025-07-29 13:28:04.712] I: Time is set in STM
[2025-07-29 13:28:59.143] I: Bundle Image Erased from nRF External Flash: 0
[2025-07-29 13:28:59.223] I: OTAU Completed Successfully
[2025-07-29 13:28:59.313] I: Cleared OTA Meta Data
[2025-07-29 13:28:59.313] I: OTA Stage Change from (80)->(90)
[2025-07-29 13:29:01.333] I: All message synced.
[2025-07-29 13:29:14.343] I: STOP BLE Advertisment
[2025-07-29 13:29:14.343] I: 266353 [DL]DFU over SMP stopped
[2025-07-29 13:29:14.343] E: Sending UART cmd(9e) st 0
[2025-07-29 13:32:39.273] I: Updated ota meta data
[2025-07-29 13:32:39.273] I: Operating Mode Command: Mode:10, State:34
[2025-07-29 13:32:39.293] E: Sending UART cmd(5) st 0
[2025-07-29 13:32:39.293] I: Operating mode event
[2025-07-29 13:32:39.353] I: Received response of command id 5
[2025-07-29 13:32:39.353] I: Received Lock Op Mode Event, mode 10, App state 34
[2025-07-29 13:32:39.353] I: Lock Current Mode : 10, Lock Current State = 34
[2025-07-29 13:32:39.353] I: STM32 HALO APP STATE IS BLE OTAU TRANSFER
[2025-07-29 13:32:39.353] E: Sending UART cmd(9e) st 0
[2025-07-29 13:32:39.353] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 13:32:39.353] I: 471352 [SWU]SMP BLE advertising started
[2025-07-29 13:32:39.353] I: 471357 [DL]DFU over SMP started
[2025-07-29 13:32:39.353] I: OTA Stage Change from (90)->(11)
[2025-07-29 13:32:39.353] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:32:39.353] I: Set Kwikset Lock App State 52
[2025-07-29 13:32:39.353] I: Matter is disabled
[2025-07-29 13:32:54.630] I: 486635 [DL]DFU-BLE-Connected
[2025-07-29 13:32:54.630] I: stop_ble_advertisment_timer
[2025-07-29 13:32:54.630] I: 486641 [DL]Current number of connections: 1/1
[2025-07-29 13:32:54.630] I: BLE Connected
[2025-07-29 13:32:54.868] I: 486875 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:32:54.868] I: 486879 [DL]Current number of connections: 0/1
[2025-07-29 13:32:54.868] I: BLE Disconnected: 13
[2025-07-29 13:33:00.233] I: 492242 [DL]DFU-BLE-Connected
[2025-07-29 13:33:00.233] I: stop_ble_advertisment_timer
[2025-07-29 13:33:00.233] I: 492248 [DL]Current number of connections: 1/1
[2025-07-29 13:33:00.233] I: BLE Connected
[2025-07-29 13:33:00.463] I: 492476 [DL]DFU Image upload started
[2025-07-29 13:33:01.293] I: Connection parameters updated.
[2025-07-29 13:33:01.293]  interval: 9, latency: 0, timeout: 42
[2025-07-29 13:33:08.013] I: OTA Stage Change from (11)->(12)
[2025-07-29 13:33:08.013] I: 500032 [DL]Image 0 download completed successfully
[2025-07-29 13:33:08.123] I: 500132 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:33:08.123] I: 500135 [DL]Current number of connections: 0/1
[2025-07-29 13:33:08.123] I: BLE Disconnected: 13
[2025-07-29 13:33:20.423] I: 512447 [DL]DFU-BLE-Connected
[2025-07-29 13:33:20.423] I: stop_ble_advertisment_timer
[2025-07-29 13:33:20.443] I: 512453 [DL]Current number of connections: 1/1
[2025-07-29 13:33:20.443] I: BLE Connected
[2025-07-29 13:33:20.643] I: 512674 [DL]DFU Image upload started
[2025-07-29 13:33:21.483] I: Connection parameters updated.
[2025-07-29 13:33:21.483]  interval: 9, latency: 0, timeout: 42
[2025-07-29 13:33:58.485] I: OTA Stage Change from (12)->(13)
[2025-07-29 13:33:58.485] I: 550493 [DL]Image 1 download completed successfully
[2025-07-29 13:33:58.583] I: 550595 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:33:58.583] I: 550598 [DL]Current number of connections: 0/1
[2025-07-29 13:33:58.583] I: BLE Disconnected: 13
[2025-07-29 13:34:08.743] I: 560768 [DL]DFU-BLE-Connected
[2025-07-29 13:34:08.743] I: stop_ble_advertisment_timer
[2025-07-29 13:34:08.763] I: 560773 [DL]Current number of connections: 1/1
[2025-07-29 13:34:08.763] I: BLE Connected
[2025-07-29 13:34:08.983] I: 561014 [DL]DFU Image upload started
[2025-07-29 13:34:09.803] I: Connection parameters updated.
[2025-07-29 13:34:09.803]  interval: 9, latency: 0, timeout: 42
[2025-07-29 13:36:01.423] I: OTA Stage Change from (13)->(14)
[2025-07-29 13:36:01.444] I: 673460 [DL]Image 2 download completed successfully
[2025-07-29 13:36:01.553] I: 673564 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:36:01.553] I: 673567 [DL]Current number of connections: 0/1
[2025-07-29 13:36:01.553] I: BLE Disconnected: 13
[2025-07-29 13:36:09.214] I: 681218 [DL]DFU-BLE-Connected
[2025-07-29 13:36:09.214] I: stop_ble_advertisment_timer
[2025-07-29 13:36:09.214] I: 681224 [DL]Current number of connections: 1/1
[2025-07-29 13:36:09.214] I: BLE Connected
[2025-07-29 13:36:09.443] I: 681454 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:36:09.443] I: 681457 [DL]Current number of connections: 0/1
[2025-07-29 13:36:09.443] I: BLE Disconnected: 13
[2025-07-29 13:36:13.273] I: 685313 [DL]DFU-BLE-Connected
[2025-07-29 13:36:13.303] I: stop_ble_advertisment_timer
[2025-07-29 13:36:13.303] I: 685318 [DL]Current number of connections: 1/1
[2025-07-29 13:36:13.303] I: BLE Connected
[2025-07-29 13:36:13.503] I: 685522 [DL]DFU_ImgConfirmHandler: Nordic Image Confirmed by MCUMgr
[2025-07-29 13:36:13.534] I: 685549 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:36:13.534] I: 685552 [DL]Current number of connections: 0/1
[2025-07-29 13:36:13.534] I: BLE Disconnected: 13
[2025-07-29 13:36:20.703] I: 692708 [DL]DFU-BLE-Connected
[2025-07-29 13:36:20.703] I: stop_ble_advertisment_timer
[2025-07-29 13:36:20.703] I: 692714 [DL]Current number of connections: 1/1
[2025-07-29 13:36:20.703] I: BLE Connected
[2025-07-29 13:36:20.903] I: 692940 [DL]DFU_ImgConfirmHandler: Nordic Image Confirmed by MCUMgr
[2025-07-29 13:36:20.934] I: 692974 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:36:20.964] I: 692977 [DL]Current number of connections: 0/1
[2025-07-29 13:36:20.964] I: BLE Disconnected: 13
[2025-07-29 13:36:28.113] I: 700122 [DL]DFU-BLE-Connected
[2025-07-29 13:36:28.113] I: stop_ble_advertisment_timer
[2025-07-29 13:36:28.113] I: 700127 [DL]Current number of connections: 1/1
[2025-07-29 13:36:28.113] I: BLE Connected
[2025-07-29 13:36:28.308] I: STM Pending =0, Redpine Pending = 0
[2025-07-29 13:36:28.403] I: Count = 4
[2025-07-29 13:36:28.403] I: dfu_header_data.image_count: 4
[2025-07-29 13:36:29.138] I: Connection parameters updated.
[2025-07-29 13:36:29.158]  interval: 9, latency: 0, timeout: 42
[2025-07-29 13:36:29.303] I: IMG Integrity Verified Successfully: 0
[2025-07-29 13:36:32.293] I: IMG Integrity Verified Successfully: 1
[2025-07-29 13:36:32.373] I: IMG Integrity Verified Successfully: 2
[2025-07-29 13:36:32.703] I: IMG Integrity Verified Successfully: 3
[2025-07-29 13:36:32.724] I: OTA Bundle(STM32 + RS9116 + PN76) image integrity Verified
[2025-07-29 13:36:32.733] I: OTA Stage Change from (14)->(30)
[2025-07-29 13:36:32.834] I: Updated ota meta data
[2025-07-29 13:36:32.834] I: Operating Mode Command: Mode:10, State:31
[2025-07-29 13:36:32.834] E: Sending UART cmd(5) st 0
[2025-07-29 13:36:32.954] I: 704936 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:36:32.954] I: 704940 [DL]Current number of connections: 0/1
[2025-07-29 13:36:32.954] I: BLE Disconnected: 13
[2025-07-29 13:36:32.954] I: Operating mode event
[2025-07-29 13:36:32.954] I: Received response of command id 5
[2025-07-29 13:36:32.954] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:36:32.954] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:36:32.954] I: STM OTAU Pending: Reset Nordic Triggered
[2025-07-29 13:36:32.954] I: OTA Stage Change from (30)->(30)
[2025-07-29 13:36:32.954] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:36:32.954] I: Set Kwikset Lock App State 49
[2025-07-29 13:36:32.954] I: Matter is disabled
[2025-07-29 13:37:20.509] 
[2025-07-29 13:37:20.509] uart:~$ *** Booting My Application v23.55.1-2f9996e8c87c ***
[2025-07-29 13:37:20.563] *** Using nRF Connect SDK v2.8.0-a2386bfc8401 ***
[2025-07-29 13:37:20.563] *** Using Zephyr OS v3.7.99-0bc3393fb112 ***
[2025-07-29 13:37:20.563] I: KWIKSET HALO 3 PLUS VERSION: 17.37.01.03
[2025-07-29 13:37:20.563] I: 51 [DL]BLE address: E7:36:87:E4:52:FD
[2025-07-29 13:37:20.573] I: No users indexes stored
[2025-07-29 13:37:20.573] I: No stored indexes for credential of type: 1
[2025-07-29 13:37:20.683] I: No stored indexes for credential of type: 2
[2025-07-29 13:37:20.683] I: ========== User Index: 0x01 User ID: 0xffffffff ==========
[2025-07-29 13:37:20.683] I: ========== User Index: 0x02 User ID: 0xffffffff ==========
[2025-07-29 13:37:20.683] I: ========== User Index: 0x03 User ID: 0xffffffff ==========
[2025-07-29 13:37:20.683] I: ========== User Index: 0x04 User ID: 0xffffffff ==========
[2025-07-29 13:37:20.683] I: ========== User Index: 0x05 User ID: 0xffffffff ==========
[2025-07-29 13:37:20.683] I: ========== User Index: 0x06 User ID: 0xffffffff ==========
[2025-07-29 13:37:20.683] I: ========== User Index: 0x07 User ID: 0xffffffff ==========
[2025-07-29 13:37:20.683] I: ========== User Index: 0x08 User ID: 0xffffffff ==========
[2025-07-29 13:37:20.683] I: ========== User Index: 0x09 User ID: 0xffffffff ==========
[2025-07-29 13:37:20.683] I: ========== User Index: 0x0a User ID: 0xffffffff ==========
[2025-07-29 13:37:20.714] I: ========== User Index: 0x0b User ID: 0xffffffff ==========
[2025-07-29 13:37:20.714] I: Board config kwiksetmdb_nrf5340_cpuapp
[2025-07-29 13:37:20.714] I: IMAGE_VERSION 17370103
[2025-07-29 13:37:20.714] I: build time: Jul 29 2025 12:02:01
[2025-07-29 13:37:20.714] I: 158 [DL]CHIP task running
[2025-07-29 13:37:20.714] I: Init CHIP stack
[2025-07-29 13:37:20.714] I: 164 [DL]OpenThread started: OK
[2025-07-29 13:37:20.714] I: 167 [DL]Setting OpenThread device type to SLEEPY END DEVICE
[2025-07-29 13:37:20.714] I: 173 [SWU]New firmware image confirmed
[2025-07-29 13:37:20.714] I: 177 [SWU]DFU_BLEAdvertising_Init
[2025-07-29 13:37:21.096] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 13:37:21.096] I: NFC Boot Event PN7642 FW VERSION 17.01.00.03
[2025-07-29 13:37:21.096] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 13:37:21.103] I: 
[2025-07-29 13:37:21.103] Boot Event Received
[2025-07-29 13:37:21.103] 
[2025-07-29 13:37:21.103] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 13:37:21.103] 
[2025-07-29 13:37:21.103] I: 260 [SVR]Subscription persistence not supported
[2025-07-29 13:37:21.103] I: 265 [SVR]Server initializing...
[2025-07-29 13:37:21.103] I: 268 [TS]Last Known Good Time: 2023-10-14T01:16:48
[2025-07-29 13:37:21.103] I: 274 [DMG]AccessControl: initializing
[2025-07-29 13:37:21.103] I: 277 [DMG]Examples::AccessControlDelegate::Init
[2025-07-29 13:37:21.103] I: 282 [DMG]AccessControl: setting
[2025-07-29 13:37:21.103] I: 285 [DMG]DefaultAclStorage: initializing
[2025-07-29 13:37:21.103] I: 289 [DMG]DefaultAclStorage: 0 entries loaded
[2025-07-29 13:37:21.125] E: 293 [IN]IPV6_PKTINFO failed: 109
[2025-07-29 13:37:21.125] I: 299 [ZCL]Using ZAP configuration...
[2025-07-29 13:37:21.125] I: 304 [DMG]AccessControlCluster: initializing
[2025-07-29 13:37:21.125] Unhandled cluster ID: 0x  30
[2025-07-29 13:37:21.125] 
[2025-07-29 13:37:21.125] ===== Attribute Received are: Cluster=30 Attribute=0 Value=0 =====
[2025-07-29 13:37:21.125] I: 318 [ZCL]Emit DSTTableEmpty event [ep=0]
[2025-07-29 13:37:21.125] I: 322 [ZCL]Initiating Admin Commissioning cluster.
[2025-07-29 13:37:21.125] I: 326 [ZCL]Door Lock server initialized
[2025-07-29 13:37:21.125] E: 330 [ZCL]DeviceInfoProvider is not registered
[2025-07-29 13:37:21.125] E: 334 [ZCL]Failed to read calendar type with error: 0x86
[2025-07-29 13:37:21.125] Unhandled cluster ID: 0x   3
[2025-07-29 13:37:21.125] 
[2025-07-29 13:37:21.125] ===== Attribute Received are: Cluster=3 Attribute=1 Value=3 =====
[2025-07-29 13:37:21.133] I: 348 [ZCL]Door Lock cluster initialized at endpoint #1
[2025-07-29 13:37:21.133] ===== Attribute Received are: Cluster=101 Attribute=0 Value=255 =====
[2025-07-29 13:37:21.133] ===== Attribute Received are: Cluster=101 Attribute=2 Value=1 =====
[2025-07-29 13:37:21.133] ===== Attribute Received are: Cluster=101 Attribute=1 Value=0 =====
[2025-07-29 13:37:21.133] ===== Attribute Received are: Cluster=101 Attribute=11 Value=11 =====
[2025-07-29 13:37:21.133] ===== Attribute Received are: Cluster=101 Attribute=12 Value=35 =====
[2025-07-29 13:37:21.133] ===== Attribute Received are: Cluster=101 Attribute=13 Value=35 =====
[2025-07-29 13:37:21.133] ===== Attribute Received are: Cluster=101 Attribute=1c Value=35 =====
[2025-07-29 13:37:21.133] ===== Attribute Received are: Cluster=101 Attribute=19 Value=80 =====
[2025-07-29 13:37:21.133] I: 402 [DIS]Updating services using commissioning mode 0
[2025-07-29 13:37:21.133] E: 407 [DIS]Failed to remove advertised services: 3
[2025-07-29 13:37:21.153] E: 411 [DIS]Failed to finalize service update: 3
[2025-07-29 13:37:21.153] I: 416 [IN]CASE Server enabling CASE session setups
[2025-07-29 13:37:21.153] I: 421 [SVR]Joining Multicast groups
[2025-07-29 13:37:21.153] I: 424 [SVR]Server Listening...
[2025-07-29 13:37:21.153] I: 427 [DL]Device Configuration:
[2025-07-29 13:37:21.153] I: 430 [DL]  Serial Number: 1789AE57B32427844F
[2025-07-29 13:37:21.153] I: 434 [DL]  Vendor Id: 5153 (0x1421)
[2025-07-29 13:37:21.153] I: 437 [DL]  Product Id: 66 (0x42)
[2025-07-29 13:37:21.153] I: Get product name B, len 0
[2025-07-29 13:37:21.153] I: 443 [DL]  Product Name: B
[2025-07-29 13:37:21.153] I: 446 [DL]  Hardware Version: 1
[2025-07-29 13:37:21.158] I: 449 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 75655451
[2025-07-29 13:37:21.158] I: 454 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 776 (0x308)
[2025-07-29 13:37:21.158] I: 460 [DL]  Manufacturing Date: 2025-07-24
[2025-07-29 13:37:21.174] I: 464 [DL]  Device Type: 10 (0xA)
[2025-07-29 13:37:21.174] I: 467 [SVR]SetupQRCode: [MT:-QWJ08DB00.I2N6SM10]
[2025-07-29 13:37:21.174] I: 472 [SVR]Copy/paste the below URL in a browser to see the QR Code:
[2025-07-29 13:37:21.174] I: 478 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-QWJ08DB00.I2N6SM10
[2025-07-29 13:37:21.174] I: 487 [SVR]Manual pairing code: [05967546175]
[2025-07-29 13:37:21.174] I: STM32 device number: 
[2025-07-29 13:37:21.174] I: 31 37 38 39 41 45 35 37 |1789AE57
[2025-07-29 13:37:21.174] I: 42 33 32 34 32 37 38 34 |B3242784
[2025-07-29 13:37:21.174] I: 34 46                   |4F      
[2025-07-29 13:37:21.174] I: SKU number: 
[2025-07-29 13:37:21.174] I: 4b 31 37 2d 30 31       |K17-01  
[2025-07-29 13:37:21.174] I: WO number: 
[2025-07-29 13:37:21.174] I: 30 30 30 30 30 30 30 30 |00000000
[2025-07-29 13:37:21.174] I: 30                      |0       
[2025-07-29 13:37:21.194] I: Manuf Date: 
[2025-07-29 13:37:21.194] I: 32 30 32 35 2d 30 37 2d |2025-07-
[2025-07-29 13:37:21.194] I: 32 34 00 00 00 00       |24....  
[2025-07-29 13:37:21.194] I: Prod config length 6
[2025-07-29 13:37:21.194] I: Product Config: 
[2025-07-29 13:37:21.194] I: 30 78 30 30 30 31       |0x0001  
[2025-07-29 13:37:21.194] I: Prod Config Read 1
[2025-07-29 13:37:21.194] I: User intend flow enabled, set commissioning flow to kUserActionRequired
[2025-07-29 13:37:21.194] I: Factory Data Version length 2
[2025-07-29 13:37:21.194] I: Factory Data Ver: 
[2025-07-29 13:37:21.194] I: 30 31                   |01      
[2025-07-29 13:37:21.194] I: Payload value in string format: MT:-QWJ04TC00.I2N60Q4P0ILT70VYYR1JFSK14YDB0-0LJ1-0LJ1-0LJ1IHLC0AUZL1XIKJ17AZL1UV700CXYR1K6Y12NNZR1YC-L1-2ZR1OADO1KB40
[2025-07-29 13:37:21.194] I: Pairing Code value in string format: 459675461705153000660
[2025-07-29 13:37:21.194] I: ============== Updating product finish and color to 15, 2, product Name Halo Select Plus ==============
[2025-07-29 13:37:21.220] E: 578 [DL]Long dispatch time: 416 ms, for event type 2
[2025-07-29 13:37:21.220] ===== Attribute Received are: Cluster=101 Attribute=0 Value=1 =====
[2025-07-29 13:37:22.653] I: Syncing up on message 9a
[2025-07-29 13:37:22.653] I: STM32 counter to 1
[2025-07-29 13:37:22.684] I: BLE Device ID: 2784
[2025-07-29 13:37:22.684] I: Device is provisioned
[2025-07-29 13:37:22.684] I: network state 0
[2025-07-29 13:37:22.684] E: Sending UART cmd(3) st 0
[2025-07-29 13:37:22.684] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 13:37:22.684] I: Received response of command id 9a
[2025-07-29 13:37:22.684] I: Command 0x9A Received
[2025-07-29 13:37:22.684] I: Firmware Attribute event
[2025-07-29 13:37:22.720] I: Received response of command id 30
[2025-07-29 13:37:22.720] I: Received DC Eco Config REQ
[2025-07-29 13:37:22.720] I: DC Eco Config Resp
[2025-07-29 13:37:22.720] I: Received DC eco config req
[2025-07-29 13:37:22.720] I: 80 72 03 00 10 00 04 1a |.r......
[2025-07-29 13:37:22.720] I: 17 05                   |..      
[2025-07-29 13:37:22.720] E: Sending UART cmd(72) st 0
[2025-07-29 13:37:24.693] I: Syncing up on message 3
[2025-07-29 13:37:24.693] I: Sys init req
[2025-07-29 13:37:24.693] E: Sending UART cmd(3) st 0
[2025-07-29 13:37:24.693] I: System init Response
[2025-07-29 13:37:24.693] I: Received response of command id 3
[2025-07-29 13:37:24.693] I: Update sync timer
[2025-07-29 13:37:24.693] I: Received Sys Init Resp
[2025-07-29 13:37:24.693] I: battery mode 0
[2025-07-29 13:37:24.693] I: battery percentage 5a
[2025-07-29 13:37:24.693] I: battery type 1
[2025-07-29 13:37:24.693] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:37:25.173] I: Syncing up on message 5
[2025-07-29 13:37:25.173] I: Operating mode req
[2025-07-29 13:37:25.213] E: Sending UART cmd(5) st 0
[2025-07-29 13:37:25.213] I: Operating mode response
[2025-07-29 13:37:25.213] I: Received response of command id 5
[2025-07-29 13:37:25.213] I: Received Lock Op Mode Resp, mode 10, App state 31
[2025-07-29 13:37:25.213] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:37:25.213] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:37:25.213] I: Set Kwikset Lock App State 49
[2025-07-29 13:37:25.213] I: Matter is disabled
[2025-07-29 13:37:25.723] I: Syncing up on message 10
[2025-07-29 13:37:25.723] I: Lock state req
[2025-07-29 13:37:25.723] E: Sending UART cmd(10) st 0
[2025-07-29 13:37:25.723] I: Lock State Response
[2025-07-29 13:37:25.723] I: Received response of command id 10
[2025-07-29 13:37:25.723] I: Received Lock State Response, lock st: 12
[2025-07-29 13:37:25.723] I: Found matching nordic source of operation 0
[2025-07-29 13:37:25.723] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:37:25.723] I: Unlock action completed
[2025-07-29 13:37:25.723] I: Updating LockState attribute
[2025-07-29 13:37:25.723] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:37:26.173] I: Syncing up on message 20
[2025-07-29 13:37:26.173] I: Lock setting req
[2025-07-29 13:37:26.230] E: Sending UART cmd(20) st 0
[2025-07-29 13:37:26.230] I: Lock General Setting Response
[2025-07-29 13:37:26.230] I: Received response of command id 20
[2025-07-29 13:37:26.233] I: Received Lock General Setting resp
[2025-07-29 13:37:26.234] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 13:37:26.234] SoundVolume attribute change
[2025-07-29 13:37:26.234] 
[2025-07-29 13:37:26.234] I: == Sound Volume Attribute Update Callback, sound volume 2 ==
[2025-07-29 13:37:26.234] I: No change in sound volume, return
[2025-07-29 13:37:26.234] ===== Attribute Received are: Cluster=101 Attribute=24 Value=2 =====
[2025-07-29 13:37:26.234] I: Matter Not Enabled do not set
[2025-07-29 13:37:26.723] I: Syncing up on message 51
[2025-07-29 13:37:26.723] I: Battery info req
[2025-07-29 13:37:26.723] E: Sending UART cmd(51) st 0
[2025-07-29 13:37:26.723] I: Received response of command id 51
[2025-07-29 13:37:26.723] I: Received Battery Info resp
[2025-07-29 13:37:26.723] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:37:26.723] Unhandled cluster ID: 0x  2f
[2025-07-29 13:37:26.723] 
[2025-07-29 13:37:26.723] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:37:26.723] Unhandled cluster ID: 0x  2f
[2025-07-29 13:37:26.723] 
[2025-07-29 13:37:26.723] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:37:27.163] I: All message synced.
[2025-07-29 13:37:50.704] I: STM system init timer expired, System Init Event not received from STM32
[2025-07-29 13:37:50.704] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 13:37:50.704] I: STM Pending =1, Redpine Pending = 1
[2025-07-29 13:37:50.704] I: STM Post OTA Pending
[2025-07-29 13:37:50.704] I: Redpine Post OTA Pending
[2025-07-29 13:37:50.704] E: Sending UART cmd(9e) st 0
[2025-07-29 13:37:50.704] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 13:37:50.704] I: 30188 [SWU]SMP BLE advertising started
[2025-07-29 13:37:50.704] I: 30192 [DL]DFU over SMP started
[2025-07-29 13:37:51.570] I: IMG Integrity Verified Successfully: 0
[2025-07-29 13:37:54.524] I: IMG Integrity Verified Successfully: 1
[2025-07-29 13:37:54.603] I: IMG Integrity Verified Successfully: 2
[2025-07-29 13:37:54.944] I: IMG Integrity Verified Successfully: 3
[2025-07-29 13:37:54.944] I: OTA Stage Change from (ff)->(32)
[2025-07-29 13:37:54.974] I: OTA device_id = 5 : DISCOVERY_REQ
[2025-07-29 13:37:55.088] I: SECURE_STM : IB_DEVICE_DISCOVERY_REQUEST (80) 
[2025-07-29 13:37:55.088] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 13:37:55.088] I: STM Current Firmware Version: 17 5 4 1b
[2025-07-29 13:37:55.088] I: OTA device_id = 5 : FW_UPDATE_START_REQ
[2025-07-29 13:37:55.088] I: SECURE_STM : IB_FW_UPDATE_START_REQUEST (80)
[2025-07-29 13:38:01.484] I: STM OTA Progress = 10
[2025-07-29 13:38:07.844] I: STM OTA Progress = 20
[2025-07-29 13:38:14.214] I: STM OTA Progress = 30
[2025-07-29 13:38:20.679] I: STM OTA Progress = 40
[2025-07-29 13:38:27.044] I: STM OTA Progress = 50
[2025-07-29 13:38:33.394] I: STM OTA Progress = 60
[2025-07-29 13:38:39.754] I: STM OTA Progress = 70
[2025-07-29 13:38:46.124] I: STM OTA Progress = 80
[2025-07-29 13:38:52.484] I: STM OTA Progress = 90
[2025-07-29 13:38:58.834] I: STM OTA Progress = 100
[2025-07-29 13:38:59.524] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 13:38:59.554] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 13:39:17.216] I: Sending Sys Init Resp
[2025-07-29 13:39:17.216] I: Device is provisioned
[2025-07-29 13:39:17.216] I: network state 0
[2025-07-29 13:39:17.216] E: Sending UART cmd(3) st 0
[2025-07-29 13:39:17.216] I: Received DC App Config REQ
[2025-07-29 13:39:17.216] I: DC App Config Resp
[2025-07-29 13:39:17.216] I: Received DC config req
[2025-07-29 13:39:17.216] I: 80 70 03 00 10 10 08 00 |.p......
[2025-07-29 13:39:17.216] I: 50 1e                   |P.      
[2025-07-29 13:39:17.216] I: Matter enabled state 0
[2025-07-29 13:39:17.216] I: Get Matter Commission State
[2025-07-29 13:39:17.216] I: network state 0
[2025-07-29 13:39:17.224] I: network state 0
[2025-07-29 13:39:17.224] E: Sending UART cmd(70) st 0
[2025-07-29 13:39:17.284] I: Lock State Event
[2025-07-29 13:39:17.284] I: Received response of command id 10
[2025-07-29 13:39:17.284] I: Received Lock State event, lock st: 12
[2025-07-29 13:39:17.284] I: Found matching nordic source of operation 0
[2025-07-29 13:39:17.284] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:39:17.284] I: Unlock action completed
[2025-07-29 13:39:17.284] I: Updating LockState attribute
[2025-07-29 13:39:17.284] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:39:17.314] I: Received DC Eco Config REQ
[2025-07-29 13:39:17.314] I: DC Eco Config Resp
[2025-07-29 13:39:17.345] I: Received DC eco config req
[2025-07-29 13:39:17.345] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 13:39:17.345] I: c4 1e                   |..      
[2025-07-29 13:39:17.345] E: Sending UART cmd(72) st 0
[2025-07-29 13:39:17.489] I: General Lock Setting event
[2025-07-29 13:39:17.523] I: Received response of command id 20
[2025-07-29 13:39:17.523] I: Received Lock General Setting event
[2025-07-29 13:39:17.523] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 13:39:17.523] I: Matter Not Enabled do not set
[2025-07-29 13:39:17.624] I: Firmware Attribute event
[2025-07-29 13:39:17.624] I: Received response of command id 30
[2025-07-29 13:39:17.684] I: Hardware Attribute event
[2025-07-29 13:39:17.684] I: Received response of command id 31
[2025-07-29 13:39:17.754] I: Operating mode event
[2025-07-29 13:39:17.754] I: Received response of command id 5
[2025-07-29 13:39:17.754] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:39:17.754] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:39:17.754] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:39:17.754] I: Set Kwikset Lock App State 49
[2025-07-29 13:39:17.754] I: Matter is disabled
[2025-07-29 13:39:17.884] I: Battery Info event
[2025-07-29 13:39:17.884] I: Received response of command id 51
[2025-07-29 13:39:17.884] I: Received Battery info event
[2025-07-29 13:39:17.884] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:39:17.884] Unhandled cluster ID: 0x  2f
[2025-07-29 13:39:17.884] 
[2025-07-29 13:39:17.884] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:39:17.884] Unhandled cluster ID: 0x  2f
[2025-07-29 13:39:17.884] 
[2025-07-29 13:39:17.884] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:39:17.984] I: System info event
[2025-07-29 13:39:17.984] I: Received System Info Event
[2025-07-29 13:39:17.984] W: Time invalid, set time
[2025-07-29 13:39:17.984] I: Get system time
[2025-07-29 13:39:17.984] I: System Real time in seconds 373663017
[2025-07-29 13:39:17.984] I: Time sync status flag 0
[2025-07-29 13:39:17.984] E: Time not sync, keep default value
[2025-07-29 13:39:18.014] I: System init event
[2025-07-29 13:39:18.084] I: Received response of command id 3
[2025-07-29 13:39:18.084] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 13:39:18.084] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:39:18.084] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 13:39:18.084] I: STM Current Firmware Version: 17 5 4 1a
[2025-07-29 13:39:18.084] I: OTA device_id = 5 : FW_UPDATE_COMPLETE_REQ
[2025-07-29 13:39:18.084] I: SECURE_STM : IB_FW_UPDATE_COMPLETE_REQUEST (80) 
[2025-07-29 13:39:18.084] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 13:39:18.084] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 13:39:20.564] I: Sending Sys Init Resp
[2025-07-29 13:39:20.564] I: Device is provisioned
[2025-07-29 13:39:20.564] I: network state 0
[2025-07-29 13:39:20.564] E: Sending UART cmd(3) st 0
[2025-07-29 13:39:20.564] I: Received DC App Config REQ
[2025-07-29 13:39:20.564] I: DC App Config Resp
[2025-07-29 13:39:20.564] I: Received DC config req
[2025-07-29 13:39:20.564] I: 80 70 03 00 10 10 04 1a |.p......
[2025-07-29 13:39:20.564] I: 00 62                   |.b      
[2025-07-29 13:39:20.564] I: Matter enabled state 0
[2025-07-29 13:39:20.564] I: Get Matter Commission State
[2025-07-29 13:39:20.564] I: network state 0
[2025-07-29 13:39:20.573] I: network state 0
[2025-07-29 13:39:20.573] E: Sending UART cmd(70) st 0
[2025-07-29 13:39:20.634] I: Lock State Event
[2025-07-29 13:39:20.634] I: Received response of command id 10
[2025-07-29 13:39:20.634] I: Received Lock State event, lock st: 12
[2025-07-29 13:39:20.634] I: Found matching nordic source of operation 0
[2025-07-29 13:39:20.634] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:39:20.634] I: Unlock action completed
[2025-07-29 13:39:20.634] I: Updating LockState attribute
[2025-07-29 13:39:20.634] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:39:20.664] I: Received DC Eco Config REQ
[2025-07-29 13:39:20.664] I: DC Eco Config Resp
[2025-07-29 13:39:20.694] I: Received DC eco config req
[2025-07-29 13:39:20.694] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 13:39:20.694] I: c4 62                   |.b      
[2025-07-29 13:39:20.694] E: Sending UART cmd(72) st 0
[2025-07-29 13:39:20.874] I: General Lock Setting event
[2025-07-29 13:39:20.874] I: Received response of command id 20
[2025-07-29 13:39:20.874] I: Received Lock General Setting event
[2025-07-29 13:39:20.874] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 13:39:20.874] I: Matter Not Enabled do not set
[2025-07-29 13:39:20.983] I: Firmware Attribute event
[2025-07-29 13:39:20.983] I: Received response of command id 30
[2025-07-29 13:39:21.034] I: Hardware Attribute event
[2025-07-29 13:39:21.034] I: Received response of command id 31
[2025-07-29 13:39:21.114] I: Operating mode event
[2025-07-29 13:39:21.114] I: Received response of command id 5
[2025-07-29 13:39:21.114] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:39:21.114] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:39:21.114] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:39:21.114] I: Set Kwikset Lock App State 49
[2025-07-29 13:39:21.114] I: Matter is disabled
[2025-07-29 13:39:21.244] I: Battery Info event
[2025-07-29 13:39:21.244] I: Received response of command id 51
[2025-07-29 13:39:21.244] I: Received Battery info event
[2025-07-29 13:39:21.244] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:39:21.244] Unhandled cluster ID: 0x  2f
[2025-07-29 13:39:21.244] 
[2025-07-29 13:39:21.244] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:39:21.244] Unhandled cluster ID: 0x  2f
[2025-07-29 13:39:21.244] 
[2025-07-29 13:39:21.244] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:39:21.344] I: System info event
[2025-07-29 13:39:21.344] I: Received System Info Event
[2025-07-29 13:39:21.344] W: Time invalid, set time
[2025-07-29 13:39:21.344] I: Get system time
[2025-07-29 13:39:21.344] I: System Real time in seconds 373663017
[2025-07-29 13:39:21.344] I: Time sync status flag 0
[2025-07-29 13:39:21.344] E: Time not sync, keep default value
[2025-07-29 13:39:21.373] I: System init event
[2025-07-29 13:39:21.424] I: Received response of command id 3
[2025-07-29 13:39:21.424] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 13:39:21.424] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:39:21.424] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 13:39:21.424] I: STM Current Firmware Version: 17 5 4 1a
[2025-07-29 13:39:21.424] I: STM New OTA Firmware Version = 17 5 4 1a
[2025-07-29 13:39:21.424] I: STM Secure OTA Successful
[2025-07-29 13:39:21.541] I: Cleared STM OTA Meta Data
[2025-07-29 13:39:21.541] I: OTA Stage Change from (32)->(33)
[2025-07-29 13:39:21.541] I: Redpine OTA started
[2025-07-29 13:39:21.541] I: OTA Stage Change from (33)->(34)
[2025-07-29 13:39:21.541] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 13:39:28.524] I: STM Reset Count 0
[2025-07-29 13:39:28.558] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 13:39:28.558] I: STM_QSPI : IB_DEVICE_DISCOVERY_REQUEST (80)
[2025-07-29 13:39:28.564] I: OTA device_id = 4 : FW_VERSION_REQ
[2025-07-29 13:39:28.564] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 13:39:28.564] I: Redpine Current Firmware Version: 2.c.0.3
[2025-07-29 13:39:28.583] I: OTA device_id = 4 : FW_UPDATE_START_REQ
[2025-07-29 13:39:28.674] I: STM_QSPI : IB_FW_UPDATE_START_REQUEST (80)
[2025-07-29 13:39:51.404] I: STM Boot Up Properly, Stopped STM Reboot Timer
[2025-07-29 13:40:08.214] I: Redpine Image Stored into STM QSPI, Progress = 10
[2025-07-29 13:40:41.804] I: Redpine Image Stored into STM QSPI, Progress = 20
[2025-07-29 13:41:02.486] I: Redpine Image Stored into STM QSPI, Progress = 30
[2025-07-29 13:41:23.274] I: Redpine Image Stored into STM QSPI, Progress = 40
[2025-07-29 13:41:43.954] I: Redpine Image Stored into STM QSPI, Progress = 50
[2025-07-29 13:42:04.684] I: Redpine Image Stored into STM QSPI, Progress = 60
[2025-07-29 13:42:25.494] I: Redpine Image Stored into STM QSPI, Progress = 70
[2025-07-29 13:42:46.241] I: Redpine Image Stored into STM QSPI, Progress = 80
[2025-07-29 13:43:07.024] I: Redpine Image Stored into STM QSPI, Progress = 90
[2025-07-29 13:43:27.884] I: Redpine Image Stored into STM QSPI, Progress = 100
[2025-07-29 13:43:29.994] I: OTA device_id = 4 : FW_UPDATE_COMPLETE_REQ
[2025-07-29 13:43:30.424] I: STM_QSPI : IB_FW_UPDATE_COMPLETE_REQUEST (80) 
[2025-07-29 13:43:30.574] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (0)
[2025-07-29 13:43:35.354] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (10)
[2025-07-29 13:43:40.234] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (20)
[2025-07-29 13:43:45.204] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (30)
[2025-07-29 13:43:50.164] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (40)
[2025-07-29 13:43:55.134] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (50)
[2025-07-29 13:44:00.044] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (60)
[2025-07-29 13:44:05.004] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (70)
[2025-07-29 13:44:09.974] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (80)
[2025-07-29 13:44:14.864] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (90)
[2025-07-29 13:44:19.654] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (100)
[2025-07-29 13:44:49.084] I: STM_QSPI : IB_FW_UPDATE_REBOOT_REQUEST (80) 
[2025-07-29 13:44:49.224] I: Clear Redpine OTA Meta Data
[2025-07-29 13:44:49.224] I: Redpine OTA Successful
[2025-07-29 13:44:49.224] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 13:44:49.224] I: STM Pending =2, Redpine Pending = 2
[2025-07-29 13:44:49.224] I: PN76 IMG 1 Post OTA Pending
[2025-07-29 13:44:49.224] E: Sending UART cmd(9e) st 0
[2025-07-29 13:44:49.224] I: 448716 [SWU]DFU over SMP was already started
[2025-07-29 13:44:49.304] I: IMG Integrity Verified Successfully: 2
[2025-07-29 13:44:49.674] I: IMG Integrity Verified Successfully: 3
[2025-07-29 13:44:49.674] I: OTA Stage Change from (34)->(3a)
[2025-07-29 13:44:49.674] I: PN76_IMG1_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 13:44:49.674] I: PN76_IMG Update from OTA Task Event
[2025-07-29 13:44:49.674] I: 
[2025-07-29 13:44:49.674] 
[2025-07-29 13:44:49.674] --------------- UPDATING PN7642 NXP FIRMWARE --------------------
[2025-07-29 13:44:49.674] 
[2025-07-29 13:44:49.674] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 13:44:49.714] I: pNXPFWInfo->img_offset = 0x351497
[2025-07-29 13:44:49.714] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 13:44:49.714] I: Reading version of firmware in QSPI flash: MetaData 0x2f60217
[2025-07-29 13:44:49.714] I: PN76 NXP FW VERSION VALIDATION SKIPPED, OTAU TEST BUNDLE
[2025-07-29 13:44:49.826] I: ----> PN7642 OTA Progress = 10 %
[2025-07-29 13:44:49.889] I: ----> PN7642 OTA Progress = 20 %
[2025-07-29 13:44:49.954] I: ----> PN7642 OTA Progress = 30 %
[2025-07-29 13:44:50.014] I: ----> PN7642 OTA Progress = 40 %
[2025-07-29 13:44:50.084] I: ----> PN7642 OTA Progress = 50 %
[2025-07-29 13:44:50.147] I: ----> PN7642 OTA Progress = 60 %
[2025-07-29 13:44:50.204] I: ----> PN7642 OTA Progress = 70 %
[2025-07-29 13:44:50.274] I: ----> PN7642 OTA Progress = 80 %
[2025-07-29 13:44:50.444] I: ----> PN7642 OTA Progress = 100 %
[2025-07-29 13:44:50.444] I: Whole pn7642 FW Image downloaded ....
[2025-07-29 13:44:50.444] I: 
[2025-07-29 13:44:50.444] 
[2025-07-29 13:44:50.444] I: 
[2025-07-29 13:44:50.444] PN7642 Firmware of type 0 Successfully Updated !!!
[2025-07-29 13:44:50.444] I: PN76 Image Update Successful for Device ID(7)
[2025-07-29 13:44:50.578] I: Cleared PN76 Img1 OTA Meta Data
[2025-07-29 13:44:50.578] I: OTA Stage Change from (3a)->(3a)
[2025-07-29 13:44:50.578] I: PN76_IMG2_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 13:44:50.578] I: PN76_IMG Update from OTA Task Event
[2025-07-29 13:44:50.578] I: 
[2025-07-29 13:44:50.578] 
[2025-07-29 13:44:50.578] --------------- UPDATING PN7642 APPLICATION FIRMWARE -------------
[2025-07-29 13:44:50.578] 
[2025-07-29 13:44:50.578] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 13:44:50.616] I: pCustAppFWInfo->img_offset = 0x35c289
[2025-07-29 13:44:50.616] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 13:44:50.616] I: Reading version of firmware in QSPI flash: MetaData 0x2f60217
[2025-07-29 13:44:50.616] I: PN76 APP FW VERSION VALIDATION SKIPPED, OTAU TEST BUNDLE
[2025-07-29 13:44:50.914] I: ----> PN7642 OTA Progress = 10 %
[2025-07-29 13:44:51.184] I: ----> PN7642 OTA Progress = 20 %
[2025-07-29 13:44:51.444] I: ----> PN7642 OTA Progress = 30 %
[2025-07-29 13:44:51.714] I: ----> PN7642 OTA Progress = 40 %
[2025-07-29 13:44:51.974] I: ----> PN7642 OTA Progress = 50 %
[2025-07-29 13:44:52.244] I: ----> PN7642 OTA Progress = 60 %
[2025-07-29 13:44:52.504] I: ----> PN7642 OTA Progress = 70 %
[2025-07-29 13:44:52.775] I: ----> PN7642 OTA Progress = 80 %
[2025-07-29 13:44:53.024] I: ----> PN7642 OTA Progress = 90 %
[2025-07-29 13:44:53.327] I: ----> PN7642 OTA Progress = 100 %
[2025-07-29 13:44:53.327] I: Whole pn7642 FW Image downloaded ....
[2025-07-29 13:44:53.327] I: 
[2025-07-29 13:44:53.327] 
[2025-07-29 13:44:53.327] I: 
[2025-07-29 13:44:53.327] PN7642 Firmware of type 1 Successfully Updated !!!
[2025-07-29 13:44:53.327] I: PN76 Image Update Successful for Device ID(8)
[2025-07-29 13:44:53.404] I: Cleared PN76 Img2 OTA Meta Data
[2025-07-29 13:44:53.934] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 13:44:53.982] I: NFC Boot Event PN7642 FW VERSION 17.01.00.02
[2025-07-29 13:44:53.982] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 13:44:53.982] I: 
[2025-07-29 13:44:53.982] Boot Event Received
[2025-07-29 13:44:53.982] 
[2025-07-29 13:44:53.984] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 13:44:53.984] 
[2025-07-29 13:44:53.984] I: OTA Stage Change from (3a)->(3b)
[2025-07-29 13:44:53.984] I: post_stm_reset_event : init_pending_ota_update
[2025-07-29 13:44:53.984] I: All pending FW Updates are completed.
[2025-07-29 13:44:53.984] I: STM32 Reset Count = 0
[2025-07-29 13:44:53.984] I: REBOOT_STM: Send STM32 Reboot Command, Count (0)
[2025-07-29 13:44:56.285] I: Sending Sys Init Resp
[2025-07-29 13:44:56.324] I: Device is provisioned
[2025-07-29 13:44:56.324] I: network state 0
[2025-07-29 13:44:56.324] E: Sending UART cmd(3) st 0
[2025-07-29 13:44:56.324] I: Received DC App Config REQ
[2025-07-29 13:44:56.324] I: DC App Config Resp
[2025-07-29 13:44:56.324] I: Received DC config req
[2025-07-29 13:44:56.324] I: 80 70 03 00 10 10 19 00 |.p......
[2025-07-29 13:44:56.324] I: 50 62                   |Pb      
[2025-07-29 13:44:56.324] I: Matter enabled state 0
[2025-07-29 13:44:56.324] I: Get Matter Commission State
[2025-07-29 13:44:56.324] I: network state 0
[2025-07-29 13:44:56.334] I: network state 0
[2025-07-29 13:44:56.334] E: Sending UART cmd(70) st 0
[2025-07-29 13:44:56.354] I: Lock State Event
[2025-07-29 13:44:56.354] I: Received response of command id 10
[2025-07-29 13:44:56.394] I: Received Lock State event, lock st: 12
[2025-07-29 13:44:56.394] I: Found matching nordic source of operation 0
[2025-07-29 13:44:56.394] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:44:56.394] I: Unlock action completed
[2025-07-29 13:44:56.394] I: Updating LockState attribute
[2025-07-29 13:44:56.394] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:44:56.430] I: Received DC Eco Config REQ
[2025-07-29 13:44:56.430] I: DC Eco Config Resp
[2025-07-29 13:44:56.454] I: Received DC eco config req
[2025-07-29 13:44:56.454] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 13:44:56.454] I: c4 62                   |.b      
[2025-07-29 13:44:56.454] E: Sending UART cmd(72) st 0
[2025-07-29 13:44:56.594] I: General Lock Setting event
[2025-07-29 13:44:56.624] I: Received response of command id 20
[2025-07-29 13:44:56.624] I: Received Lock General Setting event
[2025-07-29 13:44:56.624] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 13:44:56.624] I: Matter Not Enabled do not set
[2025-07-29 13:44:56.734] I: Firmware Attribute event
[2025-07-29 13:44:56.734] I: Received response of command id 30
[2025-07-29 13:44:56.794] I: Hardware Attribute event
[2025-07-29 13:44:56.794] I: Received response of command id 31
[2025-07-29 13:44:56.864] I: Operating mode event
[2025-07-29 13:44:56.864] I: Received response of command id 5
[2025-07-29 13:44:56.864] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:44:56.864] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:44:56.864] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:44:56.864] I: Set Kwikset Lock App State 49
[2025-07-29 13:44:56.864] I: Matter is disabled
[2025-07-29 13:44:56.994] I: Battery Info event
[2025-07-29 13:44:56.994] I: Received response of command id 51
[2025-07-29 13:44:56.994] I: Received Battery info event
[2025-07-29 13:44:56.994] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:44:56.994] Unhandled cluster ID: 0x  2f
[2025-07-29 13:44:56.994] 
[2025-07-29 13:44:56.994] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:44:56.994] Unhandled cluster ID: 0x  2f
[2025-07-29 13:44:56.994] 
[2025-07-29 13:44:56.994] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:44:57.094] I: System info event
[2025-07-29 13:44:57.094] I: Received System Info Event
[2025-07-29 13:44:57.094] W: Time invalid, set time
[2025-07-29 13:44:57.094] I: Get system time
[2025-07-29 13:44:57.094] I: System Real time in seconds 373663017
[2025-07-29 13:44:57.094] I: Time sync status flag 0
[2025-07-29 13:44:57.094] E: Time not sync, keep default value
[2025-07-29 13:44:57.124] I: System init event
[2025-07-29 13:44:57.124] I: Received response of command id 3
[2025-07-29 13:44:57.154] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 13:44:57.154] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:44:57.154] I: STM Image confirm timer was stopped
[2025-07-29 13:45:03.974] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 13:45:04.024] I: stop_ota_finalization_timer
[2025-07-29 13:45:04.024] I: After OTAU, Redpine Firmware Version: 2.c.0.3
[2025-07-29 13:45:04.024] I: Redpine New OTA Firmware Version = 2 c 0 3
[2025-07-29 13:45:04.024] I: After OTAU, Secure STM Firmware Version: 17 5 4 1a
[2025-07-29 13:45:04.024] I: Send Op Mode command to release Redpine BLE and WiFI
[2025-07-29 13:45:04.024] I: Operating Mode Command: Mode:10, State:f0
[2025-07-29 13:45:04.024] E: Sending UART cmd(5) st 0
[2025-07-29 13:45:04.074] I: Operating mode event
[2025-07-29 13:45:04.074] I: Received response of command id 5
[2025-07-29 13:45:04.074] I: Received Lock Op Mode Event, mode 10, App state 10
[2025-07-29 13:45:04.074] I: Lock Current Mode : 10, Lock Current State = 10
[2025-07-29 13:45:04.074] I: stop_ota_finalization_timer
[2025-07-29 13:45:04.074] I: STM32 HALO APP STATE IS ACTIVATED NORMAL
[2025-07-29 13:45:04.074] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:45:04.074] I: Set Kwikset Lock App State 16
[2025-07-29 13:45:04.074] I: Matter enabled state 0
[2025-07-29 13:45:04.074] I: Matter is disabled
[2025-07-29 13:45:04.074] I: OTA_HOUSEKEEPING
[2025-07-29 13:45:04.074] I: OTA Stage Change from (3b)->(80)
[2025-07-29 13:45:04.074] I: Start Erasing OTA bundle from nRF External Flash
[2025-07-29 13:45:09.894] I: System info event
[2025-07-29 13:45:09.894] I: Received System Info Event
[2025-07-29 13:45:09.894] I: Time is set in STM
[2025-07-29 13:46:05.114] I: Bundle Image Erased from nRF External Flash: 0
[2025-07-29 13:46:05.114] I: OTAU Completed Successfully
[2025-07-29 13:46:05.224] I: Cleared OTA Meta Data
[2025-07-29 13:46:05.224] I: OTA Stage Change from (80)->(90)
[2025-07-29 13:46:07.225] I: All message synced.
[2025-07-29 13:46:20.204] I: STOP BLE Advertisment
[2025-07-29 13:46:20.234] I: 539721 [DL]DFU over SMP stopped
[2025-07-29 13:46:20.234] E: Sending UART cmd(9e) st 0
[2025-07-29 13:51:13.425] I: Updated ota meta data
[2025-07-29 13:51:13.425] I: Operating Mode Command: Mode:10, State:34
[2025-07-29 13:51:13.425] E: Sending UART cmd(5) st 0
[2025-07-29 13:51:13.485] I: Operating mode event
[2025-07-29 13:51:13.485] I: Received response of command id 5
[2025-07-29 13:51:13.485] I: Received Lock Op Mode Event, mode 10, App state 34
[2025-07-29 13:51:13.485] I: Lock Current Mode : 10, Lock Current State = 34
[2025-07-29 13:51:13.485] I: STM32 HALO APP STATE IS BLE OTAU TRANSFER
[2025-07-29 13:51:13.485] E: Sending UART cmd(9e) st 0
[2025-07-29 13:51:13.485] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 13:51:13.485] I: 832971 [SWU]SMP BLE advertising started
[2025-07-29 13:51:13.485] I: 832975 [DL]DFU over SMP started
[2025-07-29 13:51:13.485] I: OTA Stage Change from (90)->(11)
[2025-07-29 13:51:13.485] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:51:13.485] I: Set Kwikset Lock App State 52
[2025-07-29 13:51:13.485] I: Matter is disabled
[2025-07-29 13:51:29.545] I: 849053 [DL]Current number of connections: 1/1
[2025-07-29 13:51:29.545] I: BLE Connected
[2025-07-29 13:51:29.795] I: 849292 [DL]Current number of connections: 0/1
[2025-07-29 13:51:29.795] I: BLE Disconnected: 13
[2025-07-29 13:51:33.655] I: 853152 [DL]Current number of connections: 1/1
[2025-07-29 13:51:33.655] I: BLE Connected
[2025-07-29 13:51:33.885] I: 853385 [DL]DFU Image upload started
[2025-07-29 13:51:34.695] I: Connection parameters updated.
[2025-07-29 13:51:34.715]  interval: 9, latency: 0, timeout: 42
[2025-07-29 13:51:34.715] E: No available ACL buffers!
[2025-07-29 13:51:34.735] E: Unexpected first L2CAP frame
[2025-07-29 13:51:53.845] I: OTA Stage Change from (11)->(12)
[2025-07-29 13:51:53.845] I: 873360 [DL]Image 0 download completed successfully
[2025-07-29 13:51:53.885] I: 873382 [DL]Current number of connections: 0/1
[2025-07-29 13:51:53.885] I: 873386 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:51:53.885] I: BLE Disconnected: 13
[2025-07-29 13:52:06.395] I: 885885 [DL]Current number of connections: 1/1
[2025-07-29 13:52:06.395] I: BLE Connected
[2025-07-29 13:52:06.615] I: 886115 [DL]DFU Image upload started
[2025-07-29 13:52:07.445] I: Connection parameters updated.
[2025-07-29 13:52:07.445]  interval: 9, latency: 0, timeout: 42
[2025-07-29 13:52:51.355] I: OTA Stage Change from (12)->(13)
[2025-07-29 13:52:51.355] I: 930853 [DL]Image 1 download completed successfully
[2025-07-29 13:52:51.385] I: 930876 [DL]Current number of connections: 0/1
[2025-07-29 13:52:51.385] I: 930881 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:52:51.385] I: BLE Disconnected: 13
[2025-07-29 13:52:58.275] I: 937766 [DL]Current number of connections: 1/1
[2025-07-29 13:52:58.275] I: BLE Connected
[2025-07-29 13:52:58.495] I: 938000 [DL]DFU Image upload started
[2025-07-29 13:52:59.315] I: Connection parameters updated.
[2025-07-29 13:52:59.335]  interval: 9, latency: 0, timeout: 42
[2025-07-29 13:52:59.335] E: No available ACL buffers!
[2025-07-29 13:52:59.335] E: Unexpected first L2CAP frame
[2025-07-29 13:55:35.925] I: OTA Stage Change from (13)->(14)
[2025-07-29 13:55:35.925] I: 1095425 [DL]Image 2 download completed successfully
[2025-07-29 13:55:35.945] I: 1095448 [DL]Current number of connections: 0/1
[2025-07-29 13:55:35.945] I: 1095452 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 13:55:35.945] I: BLE Disconnected: 13
[2025-07-29 13:55:43.125] I: 1102621 [DL]Current number of connections: 1/1
[2025-07-29 13:55:43.125] I: BLE Connected
[2025-07-29 13:55:43.345] I: 1102842 [DL]Current number of connections: 0/1
[2025-07-29 13:55:43.345] I: BLE Disconnected: 13
[2025-07-29 13:55:47.685] I: 1107185 [DL]Current number of connections: 1/1
[2025-07-29 13:55:47.685] I: BLE Connected
[2025-07-29 13:55:47.905] I: 1107406 [DL]DFU_ImgConfirmHandler: Nordic Image Confirmed by MCUMgr
[2025-07-29 13:55:47.925] I: 1107440 [DL]Current number of connections: 0/1
[2025-07-29 13:55:47.942] I: BLE Disconnected: 13
[2025-07-29 13:55:55.105] I: 1114601 [DL]Current number of connections: 1/1
[2025-07-29 13:55:55.105] I: BLE Connected
[2025-07-29 13:55:55.315] I: 1114808 [DL]DFU_ImgConfirmHandler: Nordic Image Confirmed by MCUMgr
[2025-07-29 13:55:55.335] I: 1114835 [DL]Current number of connections: 0/1
[2025-07-29 13:55:55.335] I: BLE Disconnected: 13
[2025-07-29 13:56:02.985] I: 1122500 [DL]Current number of connections: 1/1
[2025-07-29 13:56:03.005] I: BLE Connected
[2025-07-29 13:56:03.215] I: STM Pending =0, Redpine Pending = 0
[2025-07-29 13:56:03.325] I: Count = 4
[2025-07-29 13:56:03.325] I: dfu_header_data.image_count: 4
[2025-07-29 13:56:04.055] I: Connection parameters updated.
[2025-07-29 13:56:04.055]  interval: 9, latency: 0, timeout: 42
[2025-07-29 13:56:04.195] I: IMG Integrity Verified Successfully: 0
[2025-07-29 13:56:07.155] I: IMG Integrity Verified Successfully: 1
[2025-07-29 13:56:07.235] I: IMG Integrity Verified Successfully: 2
[2025-07-29 13:56:07.555] I: IMG Integrity Verified Successfully: 3
[2025-07-29 13:56:07.555] I: OTA Bundle(STM32 + RS9116 + PN76) image integrity Verified
[2025-07-29 13:56:07.555] I: OTA Stage Change from (14)->(30)
[2025-07-29 13:56:07.655] I: Updated ota meta data
[2025-07-29 13:56:07.655] I: Operating Mode Command: Mode:10, State:31
[2025-07-29 13:56:07.655] E: Sending UART cmd(5) st 0
[2025-07-29 13:56:07.695] I: Operating mode event
[2025-07-29 13:56:07.695] I: Received response of command id 5
[2025-07-29 13:56:07.695] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:56:07.695] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:56:07.695] I: STM OTAU Pending: Reset Nordic Triggered
[2025-07-29 13:56:07.695] I: OTA Stage Change from (30)->(30)
[2025-07-29 13:56:07.695] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:56:07.695] I: Set Kwikset Lock App State 49
[2025-07-29 13:56:07.695] I: Matter is disabled
[2025-07-29 13:56:07.725] I: 1127247 [DL]Current number of connections: 0/1
[2025-07-29 13:56:07.745] I: BLE Disconnected: 13
[2025-07-29 13:56:52.765] 
[2025-07-29 13:56:52.765] 
[2025-07-29 13:56:52.765] uart:~$ *** Booting My Application v23.49.0-de86e88ec64e ***
[2025-07-29 13:56:52.805] *** Using nRF Connect SDK v2.7.0-5cb85570ca43 ***
[2025-07-29 13:56:52.805] *** Using Zephyr OS v3.6.99-100befc70c74 ***
[2025-07-29 13:56:52.805] I: KWIKSET HALO 3 PLUS VERSION: 17.31.00.02
[2025-07-29 13:56:52.805] I: 51 [DL]BLE address: C0:90:B7:D1:1C:01
[2025-07-29 13:56:52.825] I: No users indexes stored
[2025-07-29 13:56:52.825] I: No stored indexes for credential of type: 1
[2025-07-29 13:56:52.945] I: No stored indexes for credential of type: 2
[2025-07-29 13:56:52.945] I: No stored indexes for credential of type: 3
[2025-07-29 13:56:52.945] I: ========== User Index: 0x01 User ID: 0xffffffff ==========
[2025-07-29 13:56:52.945] I: ========== User Index: 0x02 User ID: 0xffffffff ==========
[2025-07-29 13:56:52.945] I: ========== User Index: 0x03 User ID: 0xffffffff ==========
[2025-07-29 13:56:52.945] I: ========== User Index: 0x04 User ID: 0xffffffff ==========
[2025-07-29 13:56:52.945] I: ========== User Index: 0x05 User ID: 0xffffffff ==========
[2025-07-29 13:56:52.945] I: ========== User Index: 0x06 User ID: 0xffffffff ==========
[2025-07-29 13:56:52.945] I: ========== User Index: 0x07 User ID: 0xffffffff ==========
[2025-07-29 13:56:52.945] I: ========== User Index: 0x08 User ID: 0xffffffff ==========
[2025-07-29 13:56:52.945] I: ========== User Index: 0x09 User ID: 0xffffffff ==========
[2025-07-29 13:56:52.967] I: ========== User Index: 0x0a User ID: 0xffffffff ==========
[2025-07-29 13:56:52.967] I: ========== User Index: 0x0b User ID: 0xffffffff ==========
[2025-07-29 13:56:52.967] I: Board config kwiksetmdb_nrf5340_cpuapp
[2025-07-29 13:56:52.967] I: IMAGE_VERSION 17310002
[2025-07-29 13:56:52.967] I: build time: Jun 18 2025 10:48:56
[2025-07-29 13:56:52.967] I: 162 [DL]CHIP task running
[2025-07-29 13:56:52.967] I: Init CHIP stack
[2025-07-29 13:56:52.967] I: 168 [DL]OpenThread started: OK
[2025-07-29 13:56:52.967] I: 171 [DL]Setting OpenThread device type to SLEEPY END DEVICE
[2025-07-29 13:56:52.967] I: 177 [SWU]New firmware image confirmed
[2025-07-29 13:56:52.967] I: 180 [SWU]DFU_BLEAdvertising_Init
[2025-07-29 13:56:52.985] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 13:56:53.345] I: NFC Boot Event PN7642 FW VERSION 17.01.00.02
[2025-07-29 13:56:53.345] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 13:56:53.345] I: 
[2025-07-29 13:56:53.345] Boot Event Received
[2025-07-29 13:56:53.345] 
[2025-07-29 13:56:53.345] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 13:56:53.345] 
[2025-07-29 13:56:53.345] I: 264 [SVR]Subscription persistence not supported
[2025-07-29 13:56:53.345] I: 268 [SVR]Server initializing...
[2025-07-29 13:56:53.345] I: 272 [TS]Last Known Good Time: 2023-10-14T01:16:48
[2025-07-29 13:56:53.345] I: 277 [DMG]AccessControl: initializing
[2025-07-29 13:56:53.355] I: 280 [DMG]Examples::AccessControlDelegate::Init
[2025-07-29 13:56:53.355] I: 285 [DMG]AccessControl: setting
[2025-07-29 13:56:53.355] I: 288 [DMG]DefaultAclStorage: initializing
[2025-07-29 13:56:53.355] I: 292 [DMG]DefaultAclStorage: 0 entries loaded
[2025-07-29 13:56:53.375] E: 296 [IN]IPV6_PKTINFO failed: 109
[2025-07-29 13:56:53.375] I: 302 [ZCL]Using ZAP configuration...
[2025-07-29 13:56:53.375] I: 307 [DMG]AccessControlCluster: initializing
[2025-07-29 13:56:53.375] ===== Attribute Received are: Cluster=30 Attribute=0 Value=0 =====
[2025-07-29 13:56:53.385] I: 318 [ZCL]Emit DSTTableEmpty event [ep=0]
[2025-07-29 13:56:53.385] I: 322 [ZCL]Initiating Admin Commissioning cluster.
[2025-07-29 13:56:53.385] I: 327 [ZCL]Door Lock server initialized
[2025-07-29 13:56:53.385] E: 331 [ZCL]DeviceInfoProvider is not registered
[2025-07-29 13:56:53.385] E: 335 [ZCL]Failed to read calendar type with error: 0x86
[2025-07-29 13:56:53.385] ===== Attribute Received are: Cluster=3 Attribute=1 Value=3 =====
[2025-07-29 13:56:53.385] I: 346 [ZCL]Door Lock cluster initialized at endpoint #1
[2025-07-29 13:56:53.385] ===== Attribute Received are: Cluster=101 Attribute=0 Value=255 =====
[2025-07-29 13:56:53.385] ===== Attribute Received are: Cluster=101 Attribute=2 Value=1 =====
[2025-07-29 13:56:53.395] ===== Attribute Received are: Cluster=101 Attribute=1 Value=0 =====
[2025-07-29 13:56:53.395] ===== Attribute Received are: Cluster=101 Attribute=11 Value=11 =====
[2025-07-29 13:56:53.395] ===== Attribute Received are: Cluster=101 Attribute=12 Value=35 =====
[2025-07-29 13:56:53.395] ===== Attribute Received are: Cluster=101 Attribute=13 Value=35 =====
[2025-07-29 13:56:53.395] ===== Attribute Received are: Cluster=101 Attribute=1c Value=35 =====
[2025-07-29 13:56:53.395] ===== Attribute Received are: Cluster=101 Attribute=19 Value=80 =====
[2025-07-29 13:56:53.395] I: 400 [DIS]Updating services using commissioning mode 0
[2025-07-29 13:56:53.395] E: 405 [DIS]Failed to remove advertised services: 3
[2025-07-29 13:56:53.395] E: 409 [DIS]Failed to finalize service update: 3
[2025-07-29 13:56:53.395] I: 414 [IN]CASE Server enabling CASE session setups
[2025-07-29 13:56:53.415] I: 418 [SVR]Joining Multicast groups
[2025-07-29 13:56:53.415] I: 422 [SVR]Server Listening...
[2025-07-29 13:56:53.415] I: 425 [DL]Device Configuration:
[2025-07-29 13:56:53.415] I: 428 [DL]  Serial Number: 1789AE57B32427844F
[2025-07-29 13:56:53.415] I: 432 [DL]  Vendor Id: 5153 (0x1421)
[2025-07-29 13:56:53.415] I: 435 [DL]  Product Id: 66 (0x42)
[2025-07-29 13:56:53.415] I: Get product name B, len 0
[2025-07-29 13:56:53.415] I: 441 [DL]  Product Name: B
[2025-07-29 13:56:53.415] I: 444 [DL]  Hardware Version: 1
[2025-07-29 13:56:53.415] I: 446 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 75655451
[2025-07-29 13:56:53.415] I: 452 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 776 (0x308)
[2025-07-29 13:56:53.415] I: 458 [DL]  Manufacturing Date: 2025-07-24
[2025-07-29 13:56:53.415] I: 462 [DL]  Device Type: 10 (0xA)
[2025-07-29 13:56:53.415] I: 465 [SVR]SetupQRCode: [MT:-QWJ08DB00.I2N6SM10]
[2025-07-29 13:56:53.415] I: 470 [SVR]Copy/paste the below URL in a browser to see the QR Code:
[2025-07-29 13:56:53.435] I: 476 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-QWJ08DB00.I2N6SM10
[2025-07-29 13:56:53.435] I: 485 [SVR]Manual pairing code: [05967546175]
[2025-07-29 13:56:53.435] I: STM32 device number: 
[2025-07-29 13:56:53.435] I: 31 37 38 39 41 45 35 37 |1789AE57
[2025-07-29 13:56:53.435] I: 42 33 32 34 32 37 38 34 |B3242784
[2025-07-29 13:56:53.435] I: 34 46                   |4F      
[2025-07-29 13:56:53.435] I: SKU number: 
[2025-07-29 13:56:53.435] I: 4b 31 37 2d 30 31       |K17-01  
[2025-07-29 13:56:53.435] I: WO number: 
[2025-07-29 13:56:53.435] I: 30 30 30 30 30 30 30 30 |00000000
[2025-07-29 13:56:53.435] I: 30                      |0       
[2025-07-29 13:56:53.435] I: Manuf Date: 
[2025-07-29 13:56:53.435] I: 32 30 32 35 2d 30 37 2d |2025-07-
[2025-07-29 13:56:53.435] I: 32 34 00 00 00 00       |24....  
[2025-07-29 13:56:53.435] I: Prod config length 6
[2025-07-29 13:56:53.462] I: Product Config: 
[2025-07-29 13:56:53.462] I: 30 78 30 30 30 31       |0x0001  
[2025-07-29 13:56:53.462] I: Prod Config Read 1
[2025-07-29 13:56:53.462] I: User intend flow enabled, set commissioning flow to kUserActionRequired
[2025-07-29 13:56:53.462] I: Factory Data Version length 2
[2025-07-29 13:56:53.462] I: Factory Data Ver: 
[2025-07-29 13:56:53.462] I: 30 31                   |01      
[2025-07-29 13:56:53.462] I: Payload value in string format: MT:-QWJ04TC00.I2N60Q4P0ILT70VYYR1JFSK14YDB0-0LJ1-0LJ1-0LJ1IHLC0AUZL1XIKJ17AZL1UV700CXYR1K6Y12NNZR1YC-L1-2ZR1OADO1KB40
[2025-07-29 13:56:53.462] I: Pairing Code value in string format: 459675461705153000660
[2025-07-29 13:56:53.462] I: ============== Updating product finish and color to 15, 2, product Name Halo Select Plus ==============
[2025-07-29 13:56:53.463] E: 575 [DL]Long dispatch time: 411 ms, for event type 2
[2025-07-29 13:56:53.463] ===== Attribute Received are: Cluster=101 Attribute=0 Value=1 =====
[2025-07-29 13:56:54.895] I: Syncing up on message 9a
[2025-07-29 13:56:54.935] I: STM32 counter to 1
[2025-07-29 13:56:54.935] I: BLE Device ID: 2784
[2025-07-29 13:56:54.935] I: Device is provisioned
[2025-07-29 13:56:54.935] I: network state 0
[2025-07-29 13:56:54.935] E: Sending UART cmd(3) st 0
[2025-07-29 13:56:54.935] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 13:56:54.935] I: Received response of command id 9a
[2025-07-29 13:56:54.935] I: Command 0x9A Received
[2025-07-29 13:56:54.975] I: Firmware Attribute event
[2025-07-29 13:56:54.975] I: Received response of command id 30
[2025-07-29 13:56:54.975] I: Received DC Eco Config REQ
[2025-07-29 13:56:54.975] I: DC Eco Config Resp
[2025-07-29 13:56:54.975] I: Received DC eco config req
[2025-07-29 13:56:54.975] I: 80 72 03 00 10 00 04 1b |.r......
[2025-07-29 13:56:54.975] I: 17 05                   |..      
[2025-07-29 13:56:54.975] E: Sending UART cmd(72) st 0
[2025-07-29 13:56:56.945] I: Syncing up on message 3
[2025-07-29 13:56:56.945] I: Sys init req
[2025-07-29 13:56:56.945] E: Sending UART cmd(3) st 0
[2025-07-29 13:56:56.945] I: System init Response
[2025-07-29 13:56:56.945] I: Received response of command id 3
[2025-07-29 13:56:56.945] I: Update sync timer
[2025-07-29 13:56:56.945] I: Received Sys Init Resp
[2025-07-29 13:56:56.945] I: battery mode 0
[2025-07-29 13:56:56.945] I: battery percentage 5a
[2025-07-29 13:56:56.945] I: battery type 1
[2025-07-29 13:56:56.945] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:56:57.425] I: Syncing up on message 5
[2025-07-29 13:56:57.425] I: Operating mode req
[2025-07-29 13:56:57.475] E: Sending UART cmd(5) st 0
[2025-07-29 13:56:57.475] I: Operating mode response
[2025-07-29 13:56:57.475] I: Received response of command id 5
[2025-07-29 13:56:57.475] I: Received Lock Op Mode Resp, mode 10, App state 31
[2025-07-29 13:56:57.475] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:56:57.475] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:56:57.475] I: Set Kwikset Lock App State 49
[2025-07-29 13:56:57.475] I: Matter is disabled
[2025-07-29 13:56:57.975] I: Syncing up on message 10
[2025-07-29 13:56:57.975] I: Lock state req
[2025-07-29 13:56:57.975] E: Sending UART cmd(10) st 0
[2025-07-29 13:56:57.975] I: Lock State Response
[2025-07-29 13:56:57.975] I: Received response of command id 10
[2025-07-29 13:56:57.975] I: Received Lock State Response, lock st: 12
[2025-07-29 13:56:57.975] I: Found matching nordic source of operation 0
[2025-07-29 13:56:57.975] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:56:57.975] I: Unlock action completed
[2025-07-29 13:56:57.975] I: Updating LockState attribute
[2025-07-29 13:56:57.975] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:56:58.425] I: Syncing up on message 20
[2025-07-29 13:56:58.465] I: Lock setting req
[2025-07-29 13:56:58.465] E: Sending UART cmd(20) st 0
[2025-07-29 13:56:58.465] I: Lock General Setting Response
[2025-07-29 13:56:58.465] I: Received response of command id 20
[2025-07-29 13:56:58.465] I: Received Lock General Setting resp
[2025-07-29 13:56:58.465] I: Matter Not Enabled do not set
[2025-07-29 13:56:58.925] I: Syncing up on message 51
[2025-07-29 13:56:58.925] I: Battery info req
[2025-07-29 13:56:58.925] E: Sending UART cmd(51) st 0
[2025-07-29 13:56:58.969] I: Received response of command id 51
[2025-07-29 13:56:58.969] I: Received Battery Info resp
[2025-07-29 13:56:58.969] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:56:58.969] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:56:58.969] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:56:59.435] I: All message synced.
[2025-07-29 13:57:22.915] I: STM system init timer expired, System Init Event not received from STM32
[2025-07-29 13:57:22.955] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 13:57:22.955] I: STM Pending =1, Redpine Pending = 1
[2025-07-29 13:57:22.955] I: STM Post OTA Pending
[2025-07-29 13:57:22.955] I: Redpine Post OTA Pending
[2025-07-29 13:57:22.955] E: Sending UART cmd(9e) st 0
[2025-07-29 13:57:22.955] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 13:57:22.955] I: 30191 [SWU]SMP BLE advertising started
[2025-07-29 13:57:22.955] I: 30196 [DL]DFU over SMP started
[2025-07-29 13:57:23.835] I: IMG Integrity Verified Successfully: 0
[2025-07-29 13:57:26.825] I: IMG Integrity Verified Successfully: 1
[2025-07-29 13:57:26.909] I: IMG Integrity Verified Successfully: 2
[2025-07-29 13:57:27.195] I: IMG Integrity Verified Successfully: 3
[2025-07-29 13:57:27.220] I: OTA Stage Change from (ff)->(32)
[2025-07-29 13:57:27.220] I: OTA device_id = 5 : DISCOVERY_REQ
[2025-07-29 13:57:27.295] I: SECURE_STM : IB_DEVICE_DISCOVERY_REQUEST (80) 
[2025-07-29 13:57:27.340] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 13:57:27.340] I: STM Current Firmware Version: 17 5 4 1a
[2025-07-29 13:57:27.340] I: STM New OTA Firmware Version = 17 5 4 1b
[2025-07-29 13:57:27.340] I: OTA device_id = 5 : FW_UPDATE_START_REQ
[2025-07-29 13:57:27.340] I: SECURE_STM : IB_FW_UPDATE_START_REQUEST (80)
[2025-07-29 13:57:33.706] I: STM OTA Progress = 10
[2025-07-29 13:57:40.025] I: STM OTA Progress = 20
[2025-07-29 13:57:46.335] I: STM OTA Progress = 30
[2025-07-29 13:57:52.765] I: STM OTA Progress = 40
[2025-07-29 13:57:59.085] I: STM OTA Progress = 50
[2025-07-29 13:58:05.416] I: STM OTA Progress = 60
[2025-07-29 13:58:11.740] I: STM OTA Progress = 70
[2025-07-29 13:58:18.075] I: STM OTA Progress = 80
[2025-07-29 13:58:24.385] I: STM OTA Progress = 90
[2025-07-29 13:58:30.725] I: STM OTA Progress = 100
[2025-07-29 13:58:31.425] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 13:58:31.425] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 13:58:49.035] I: Sending Sys Init Resp
[2025-07-29 13:58:49.035] I: Device is provisioned
[2025-07-29 13:58:49.035] I: network state 0
[2025-07-29 13:58:49.035] E: Sending UART cmd(3) st 0
[2025-07-29 13:58:49.035] I: Received DC App Config REQ
[2025-07-29 13:58:49.035] I: DC App Config Resp
[2025-07-29 13:58:49.035] I: Received DC config req
[2025-07-29 13:58:49.035] I: 80 70 03 00 10 10 08 00 |.p......
[2025-07-29 13:58:49.035] I: 50 1e                   |P.      
[2025-07-29 13:58:49.035] I: Matter enabled state 0
[2025-07-29 13:58:49.035] I: Get Matter Commission State
[2025-07-29 13:58:49.035] I: network state 0
[2025-07-29 13:58:49.035] I: network state 0
[2025-07-29 13:58:49.035] E: Sending UART cmd(70) st 0
[2025-07-29 13:58:49.065] I: Lock State Event
[2025-07-29 13:58:49.105] I: Received response of command id 10
[2025-07-29 13:58:49.105] I: Received Lock State event, lock st: 12
[2025-07-29 13:58:49.105] I: Found matching nordic source of operation 0
[2025-07-29 13:58:49.105] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:58:49.105] I: Unlock action completed
[2025-07-29 13:58:49.105] I: Updating LockState attribute
[2025-07-29 13:58:49.105] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:58:49.145] I: Received DC Eco Config REQ
[2025-07-29 13:58:49.165] I: DC Eco Config Resp
[2025-07-29 13:58:49.165] I: Received DC eco config req
[2025-07-29 13:58:49.165] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 13:58:49.165] I: c4 1e                   |..      
[2025-07-29 13:58:49.165] E: Sending UART cmd(72) st 0
[2025-07-29 13:58:49.347] I: General Lock Setting event
[2025-07-29 13:58:49.347] I: Received response of command id 20
[2025-07-29 13:58:49.347] I: Received Lock General Setting event
[2025-07-29 13:58:49.347] I: Matter Not Enabled do not set
[2025-07-29 13:58:49.442] I: Firmware Attribute event
[2025-07-29 13:58:49.442] I: Received response of command id 30
[2025-07-29 13:58:49.515] I: Hardware Attribute event
[2025-07-29 13:58:49.515] I: Received response of command id 31
[2025-07-29 13:58:49.586] I: Operating mode event
[2025-07-29 13:58:49.586] I: Received response of command id 5
[2025-07-29 13:58:49.586] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:58:49.586] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:58:49.586] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:58:49.586] I: Set Kwikset Lock App State 49
[2025-07-29 13:58:49.586] I: Matter is disabled
[2025-07-29 13:58:49.705] I: Battery Info event
[2025-07-29 13:58:49.705] I: Received response of command id 51
[2025-07-29 13:58:49.705] I: Received Battery info event
[2025-07-29 13:58:49.705] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:58:49.705] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:58:49.705] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:58:49.785] I: System info event
[2025-07-29 13:58:49.785] I: Received System Info Event
[2025-07-29 13:58:49.815] W: Time invalid, set time
[2025-07-29 13:58:49.815] I: Get system time
[2025-07-29 13:58:49.815] I: System Real time in seconds 373662943
[2025-07-29 13:58:49.815] I: Time sync status flag 0
[2025-07-29 13:58:49.815] E: Time not sync, keep default value
[2025-07-29 13:58:49.925] I: System init event
[2025-07-29 13:58:49.925] I: Received response of command id 3
[2025-07-29 13:58:49.925] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 13:58:49.925] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:58:49.925] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 13:58:49.925] I: STM Current Firmware Version: 17 5 4 1b
[2025-07-29 13:58:49.925] I: OTA device_id = 5 : FW_UPDATE_COMPLETE_REQ
[2025-07-29 13:58:49.925] I: SECURE_STM : IB_FW_UPDATE_COMPLETE_REQUEST (80) 
[2025-07-29 13:58:49.925] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 13:58:49.925] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 13:58:52.405] I: Sending Sys Init Resp
[2025-07-29 13:58:52.405] I: Device is provisioned
[2025-07-29 13:58:52.405] I: network state 0
[2025-07-29 13:58:52.405] E: Sending UART cmd(3) st 0
[2025-07-29 13:58:52.405] I: Received DC App Config REQ
[2025-07-29 13:58:52.405] I: DC App Config Resp
[2025-07-29 13:58:52.405] I: Received DC config req
[2025-07-29 13:58:52.405] I: 80 70 03 00 10 10 04 1b |.p......
[2025-07-29 13:58:52.405] I: 00 62                   |.b      
[2025-07-29 13:58:52.405] I: Matter enabled state 0
[2025-07-29 13:58:52.405] I: Get Matter Commission State
[2025-07-29 13:58:52.405] I: network state 0
[2025-07-29 13:58:52.415] I: network state 0
[2025-07-29 13:58:52.415] E: Sending UART cmd(70) st 0
[2025-07-29 13:58:52.475] I: Lock State Event
[2025-07-29 13:58:52.475] I: Received response of command id 10
[2025-07-29 13:58:52.475] I: Received Lock State event, lock st: 12
[2025-07-29 13:58:52.475] I: Found matching nordic source of operation 0
[2025-07-29 13:58:52.475] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:58:52.475] I: Unlock action completed
[2025-07-29 13:58:52.475] I: Updating LockState attribute
[2025-07-29 13:58:52.475] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:58:52.506] I: Received DC Eco Config REQ
[2025-07-29 13:58:52.506] I: DC Eco Config Resp
[2025-07-29 13:58:52.525] I: Received DC eco config req
[2025-07-29 13:58:52.525] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 13:58:52.525] I: c4 62                   |.b      
[2025-07-29 13:58:52.525] E: Sending UART cmd(72) st 0
[2025-07-29 13:58:52.675] I: General Lock Setting event
[2025-07-29 13:58:52.705] I: Received response of command id 20
[2025-07-29 13:58:52.705] I: Received Lock General Setting event
[2025-07-29 13:58:52.705] I: Matter Not Enabled do not set
[2025-07-29 13:58:52.795] I: Firmware Attribute event
[2025-07-29 13:58:52.815] I: Received response of command id 30
[2025-07-29 13:58:52.875] I: Hardware Attribute event
[2025-07-29 13:58:52.875] I: Received response of command id 31
[2025-07-29 13:58:52.952] I: Operating mode event
[2025-07-29 13:58:52.952] I: Received response of command id 5
[2025-07-29 13:58:52.952] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:58:52.952] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:58:52.952] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:58:52.952] I: Set Kwikset Lock App State 49
[2025-07-29 13:58:52.952] I: Matter is disabled
[2025-07-29 13:58:53.066] I: Battery Info event
[2025-07-29 13:58:53.066] I: Received response of command id 51
[2025-07-29 13:58:53.066] I: Received Battery info event
[2025-07-29 13:58:53.066] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:58:53.066] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:58:53.066] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:58:53.146] I: System info event
[2025-07-29 13:58:53.178] I: Received System Info Event
[2025-07-29 13:58:53.178] W: Time invalid, set time
[2025-07-29 13:58:53.178] I: Get system time
[2025-07-29 13:58:53.178] I: System Real time in seconds 373662943
[2025-07-29 13:58:53.178] I: Time sync status flag 0
[2025-07-29 13:58:53.178] E: Time not sync, keep default value
[2025-07-29 13:58:53.205] I: System init event
[2025-07-29 13:58:53.256] I: Received response of command id 3
[2025-07-29 13:58:53.256] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 13:58:53.256] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:58:53.256] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 13:58:53.256] I: STM Current Firmware Version: 17 5 4 1b
[2025-07-29 13:58:53.256] I: STM New OTA Firmware Version = 17 5 4 1b
[2025-07-29 13:58:53.256] I: STM Secure OTA Successful
[2025-07-29 13:58:53.345] I: Cleared STM OTA Meta Data
[2025-07-29 13:58:53.345] I: OTA Stage Change from (32)->(33)
[2025-07-29 13:58:53.365] I: Redpine OTA started
[2025-07-29 13:58:53.365] I: OTA Stage Change from (33)->(34)
[2025-07-29 13:58:53.365] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 13:59:00.355] I: STM Reset Count 0
[2025-07-29 13:59:00.355] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 13:59:00.385] I: STM_QSPI : IB_DEVICE_DISCOVERY_REQUEST (80)
[2025-07-29 13:59:00.385] I: OTA device_id = 4 : FW_VERSION_REQ
[2025-07-29 13:59:00.385] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 13:59:00.405] I: Redpine Current Firmware Version: 2.c.0.3
[2025-07-29 13:59:00.405] I: Redpine New OTA Firmware Version = 2 c 0 3
[2025-07-29 13:59:00.405] I: Skip Redpine OTA, Older OTA Version Request Received
[2025-07-29 13:59:00.525] I: Clear Redpine OTA Meta Data
[2025-07-29 13:59:00.525] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 13:59:00.525] I: STM Pending =2, Redpine Pending = 2
[2025-07-29 13:59:00.525] I: PN76 IMG 1 Post OTA Pending
[2025-07-29 13:59:00.525] E: Sending UART cmd(9e) st 0
[2025-07-29 13:59:00.525] I: 127766 [SWU]Software update is already enabled
[2025-07-29 13:59:00.605] I: IMG Integrity Verified Successfully: 2
[2025-07-29 13:59:00.935] I: IMG Integrity Verified Successfully: 3
[2025-07-29 13:59:00.935] I: OTA Stage Change from (34)->(3a)
[2025-07-29 13:59:00.935] I: PN76_IMG1_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 13:59:00.935] I: PN76_IMG Update from OTA Task Event
[2025-07-29 13:59:00.935] I: 
[2025-07-29 13:59:00.935] 
[2025-07-29 13:59:00.935] --------------- UPDATING PN7642 NXP FIRMWARE --------------------
[2025-07-29 13:59:00.935] 
[2025-07-29 13:59:00.935] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 13:59:00.985] I: pNXPFWInfo->img_offset = 0x35149a
[2025-07-29 13:59:00.985] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 13:59:00.985] I: Reading version of firmware in QSPI flash: MetaData 0x3f60217
[2025-07-29 13:59:00.985] I: NXP FW Version 2 f6 : 2 f6
[2025-07-29 13:59:00.985] I: PN76 NXP FW VERSION IS EQUAL
[2025-07-29 13:59:00.985] I: 
[2025-07-29 13:59:00.985] PN7642 Firmware of type 0 Successfully Updated !!!
[2025-07-29 13:59:01.105] I: Cleared PN76 Img1 OTA Meta Data
[2025-07-29 13:59:01.105] I: OTA Stage Change from (3a)->(3a)
[2025-07-29 13:59:01.105] I: PN76_IMG2_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 13:59:01.105] I: PN76_IMG Update from OTA Task Event
[2025-07-29 13:59:01.105] I: 
[2025-07-29 13:59:01.105] 
[2025-07-29 13:59:01.105] --------------- UPDATING PN7642 APPLICATION FIRMWARE -------------
[2025-07-29 13:59:01.105] 
[2025-07-29 13:59:01.105] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 13:59:01.145] I: pCustAppFWInfo->img_offset = 0x35c28c
[2025-07-29 13:59:01.145] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 13:59:01.145] I: Reading version of firmware in QSPI flash: MetaData 0x3f60217
[2025-07-29 13:59:01.145] I: PN76 NXP APP FW VERSION IS HIGHER
[2025-07-29 13:59:01.445] I: ----> PN7642 OTA Progress = 10 %
[2025-07-29 13:59:01.725] I: ----> PN7642 OTA Progress = 20 %
[2025-07-29 13:59:01.976] I: ----> PN7642 OTA Progress = 30 %
[2025-07-29 13:59:02.238] I: ----> PN7642 OTA Progress = 40 %
[2025-07-29 13:59:02.505] I: ----> PN7642 OTA Progress = 50 %
[2025-07-29 13:59:02.765] I: ----> PN7642 OTA Progress = 60 %
[2025-07-29 13:59:03.015] I: ----> PN7642 OTA Progress = 70 %
[2025-07-29 13:59:03.286] I: ----> PN7642 OTA Progress = 80 %
[2025-07-29 13:59:03.546] I: ----> PN7642 OTA Progress = 90 %
[2025-07-29 13:59:03.805] I: ----> PN7642 OTA Progress = 100 %
[2025-07-29 13:59:03.825] I: Whole pn7642 FW Image downloaded ....
[2025-07-29 13:59:03.825] I: 
[2025-07-29 13:59:03.825] 
[2025-07-29 13:59:03.825] I: 
[2025-07-29 13:59:03.825] PN7642 Firmware of type 1 Successfully Updated !!!
[2025-07-29 13:59:03.905] I: Cleared PN76 Img2 OTA Meta Data
[2025-07-29 13:59:03.976] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 13:59:04.025] I: NFC Boot Event PN7642 FW VERSION 17.01.00.03
[2025-07-29 13:59:04.025] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 13:59:04.025] I: 
[2025-07-29 13:59:04.025] Boot Event Received
[2025-07-29 13:59:04.025] 
[2025-07-29 13:59:04.025] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 13:59:04.025] 
[2025-07-29 13:59:04.025] I: OTA Stage Change from (3a)->(3b)
[2025-07-29 13:59:04.025] I: post_stm_reset_event : init_pending_ota_update
[2025-07-29 13:59:04.025] I: All pending FW Updates are completed.
[2025-07-29 13:59:04.025] I: STM32 Reset Count = 0
[2025-07-29 13:59:04.025] I: REBOOT_STM: Send STM32 Reboot Command, Count (0)
[2025-07-29 13:59:06.345] I: Sending Sys Init Resp
[2025-07-29 13:59:06.345] I: Device is provisioned
[2025-07-29 13:59:06.386] I: network state 0
[2025-07-29 13:59:06.386] E: Sending UART cmd(3) st 0
[2025-07-29 13:59:06.386] I: Received DC App Config REQ
[2025-07-29 13:59:06.386] I: DC App Config Resp
[2025-07-29 13:59:06.386] I: Received DC config req
[2025-07-29 13:59:06.386] I: 80 70 03 00 10 10 00 03 |.p......
[2025-07-29 13:59:06.386] I: 00 62                   |.b      
[2025-07-29 13:59:06.386] I: Matter enabled state 0
[2025-07-29 13:59:06.386] I: Get Matter Commission State
[2025-07-29 13:59:06.386] I: network state 0
[2025-07-29 13:59:06.386] I: network state 0
[2025-07-29 13:59:06.386] E: Sending UART cmd(70) st 0
[2025-07-29 13:59:06.416] I: Lock State Event
[2025-07-29 13:59:06.416] I: Received response of command id 10
[2025-07-29 13:59:06.455] I: Received Lock State event, lock st: 12
[2025-07-29 13:59:06.455] I: Found matching nordic source of operation 0
[2025-07-29 13:59:06.455] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 13:59:06.455] I: Unlock action completed
[2025-07-29 13:59:06.455] I: Updating LockState attribute
[2025-07-29 13:59:06.455] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 13:59:06.485] I: Received DC Eco Config REQ
[2025-07-29 13:59:06.485] I: DC Eco Config Resp
[2025-07-29 13:59:06.506] I: Received DC eco config req
[2025-07-29 13:59:06.506] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 13:59:06.506] I: c4 62                   |.b      
[2025-07-29 13:59:06.506] E: Sending UART cmd(72) st 0
[2025-07-29 13:59:06.685] I: General Lock Setting event
[2025-07-29 13:59:06.685] I: Received response of command id 20
[2025-07-29 13:59:06.685] I: Received Lock General Setting event
[2025-07-29 13:59:06.685] I: Matter Not Enabled do not set
[2025-07-29 13:59:06.775] I: Firmware Attribute event
[2025-07-29 13:59:06.775] I: Received response of command id 30
[2025-07-29 13:59:06.854] I: Hardware Attribute event
[2025-07-29 13:59:06.854] I: Received response of command id 31
[2025-07-29 13:59:06.930] I: Operating mode event
[2025-07-29 13:59:06.930] I: Received response of command id 5
[2025-07-29 13:59:06.930] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 13:59:06.930] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:59:06.930] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:59:06.930] I: Set Kwikset Lock App State 49
[2025-07-29 13:59:06.930] I: Matter is disabled
[2025-07-29 13:59:07.045] I: Battery Info event
[2025-07-29 13:59:07.045] I: Received response of command id 51
[2025-07-29 13:59:07.045] I: Received Battery info event
[2025-07-29 13:59:07.045] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 13:59:07.045] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 13:59:07.045] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 13:59:07.125] I: System info event
[2025-07-29 13:59:07.155] I: Received System Info Event
[2025-07-29 13:59:07.155] W: Time invalid, set time
[2025-07-29 13:59:07.155] I: Get system time
[2025-07-29 13:59:07.155] I: System Real time in seconds 373662943
[2025-07-29 13:59:07.155] I: Time sync status flag 0
[2025-07-29 13:59:07.155] E: Time not sync, keep default value
[2025-07-29 13:59:07.195] I: System init event
[2025-07-29 13:59:07.216] I: Received response of command id 3
[2025-07-29 13:59:07.216] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 13:59:07.216] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 13:59:14.015] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 13:59:14.015] I: stop_ota_finalization_timer
[2025-07-29 13:59:14.055] I: After OTAU, Redpine Firmware Version: 2.c.0.3
[2025-07-29 13:59:14.055] I: Redpine New OTA Firmware Version = 2 c 0 3
[2025-07-29 13:59:14.055] I: After OTAU, Secure STM Firmware Version: 17 5 4 1b
[2025-07-29 13:59:14.055] I: Send Op Mode command to release Redpine BLE and WiFI
[2025-07-29 13:59:14.065] I: Operating Mode Command: Mode:10, State:f0
[2025-07-29 13:59:14.065] E: Sending UART cmd(5) st 0
[2025-07-29 13:59:14.195] I: Operating mode event
[2025-07-29 13:59:14.195] I: Received response of command id 5
[2025-07-29 13:59:14.195] I: Received Lock Op Mode Event, mode 10, App state 10
[2025-07-29 13:59:14.195] I: Lock Current Mode : 10, Lock Current State = 10
[2025-07-29 13:59:14.195] I: stop_ota_finalization_timer
[2025-07-29 13:59:14.195] I: STM32 HALO APP STATE IS ACTIVATED NORMAL
[2025-07-29 13:59:14.195] I: Set Kwikset Lock App Mode 16
[2025-07-29 13:59:14.195] I: Set Kwikset Lock App State 16
[2025-07-29 13:59:14.195] I: Matter enabled state 0
[2025-07-29 13:59:14.195] I: Matter is disabled
[2025-07-29 13:59:14.195] I: OTA_HOUSEKEEPING
[2025-07-29 13:59:14.195] I: OTA Stage Change from (3b)->(80)
[2025-07-29 13:59:14.195] I: Start Erasing OTA bundle from nRF External Flash
[2025-07-29 13:59:19.915] I: System info event
[2025-07-29 13:59:19.915] I: Received System Info Event
[2025-07-29 13:59:19.915] I: Time is set in STM
[2025-07-29 13:59:23.236] I: STM Boot Up Properly, Stopped STM Reboot Timer
[2025-07-29 14:00:14.743] I: Bundle Image Erased from nRF External Flash: 0
[2025-07-29 14:00:14.835] I: OTAU Completed Successfully
[2025-07-29 14:00:14.945] I: Cleared OTA Meta Data
[2025-07-29 14:00:14.945] I: OTA Stage Change from (80)->(90)
[2025-07-29 14:00:16.945] I: All message synced.
[2025-07-29 14:00:29.925] I: STOP BLE Advertisment
[2025-07-29 14:00:29.955] I: 217188 [DL]DFU over SMP stopped
[2025-07-29 14:00:29.955] E: Sending UART cmd(9e) st 0
[2025-07-29 14:03:14.916] I: Updated ota meta data
[2025-07-29 14:03:14.916] I: Operating Mode Command: Mode:10, State:34
[2025-07-29 14:03:14.936] E: Sending UART cmd(5) st 0
[2025-07-29 14:03:14.936] I: Operating mode event
[2025-07-29 14:03:14.986] I: Received response of command id 5
[2025-07-29 14:03:14.986] I: Received Lock Op Mode Event, mode 10, App state 34
[2025-07-29 14:03:14.986] I: Lock Current Mode : 10, Lock Current State = 34
[2025-07-29 14:03:14.986] I: STM32 HALO APP STATE IS BLE OTAU TRANSFER
[2025-07-29 14:03:14.986] E: Sending UART cmd(9e) st 0
[2025-07-29 14:03:14.986] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 14:03:14.986] I: 382220 [SWU]SMP BLE advertising started
[2025-07-29 14:03:14.995] I: 382225 [DL]DFU over SMP started
[2025-07-29 14:03:14.995] I: OTA Stage Change from (90)->(11)
[2025-07-29 14:03:14.995] I: Set Kwikset Lock App Mode 16
[2025-07-29 14:03:14.995] I: Set Kwikset Lock App State 52
[2025-07-29 14:03:15.000] I: Matter is disabled
[2025-07-29 14:03:30.013] I: 397243 [DL]DFU-BLE-Connected
[2025-07-29 14:03:30.013] I: stop_ble_advertisment_timer
[2025-07-29 14:03:30.013] I: 397248 [DL]Current number of connections: 1/1
[2025-07-29 14:03:30.013] I: BLE Connected
[2025-07-29 14:03:30.226] I: 397464 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 14:03:30.226] I: 397467 [DL]Current number of connections: 0/1
[2025-07-29 14:03:30.226] I: BLE Disconnected: 13
[2025-07-29 14:03:34.346] I: 401582 [DL]DFU-BLE-Connected
[2025-07-29 14:03:34.346] I: stop_ble_advertisment_timer
[2025-07-29 14:03:34.346] I: 401587 [DL]Current number of connections: 1/1
[2025-07-29 14:03:34.346] I: BLE Connected
[2025-07-29 14:03:34.556] I: 401805 [DL]DFU Image upload started
[2025-07-29 14:03:35.396] I: Connection parameters updated.
[2025-07-29 14:03:35.396]  interval: 9, latency: 0, timeout: 42
[2025-07-29 14:03:42.017] I: OTA Stage Change from (11)->(12)
[2025-07-29 14:03:42.036] I: 409280 [DL]Image 0 download completed successfully
[2025-07-29 14:03:42.136] I: 409370 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 14:03:42.136] I: 409373 [DL]Current number of connections: 0/1
[2025-07-29 14:03:42.136] I: BLE Disconnected: 13
[2025-07-29 14:03:54.674] I: 421930 [DL]DFU-BLE-Connected
[2025-07-29 14:03:54.696] I: stop_ble_advertisment_timer
[2025-07-29 14:03:54.696] I: 421936 [DL]Current number of connections: 1/1
[2025-07-29 14:03:54.696] I: BLE Connected
[2025-07-29 14:03:54.915] I: 422175 [DL]DFU Image upload started
[2025-07-29 14:03:55.746] I: Connection parameters updated.
[2025-07-29 14:03:55.746]  interval: 9, latency: 0, timeout: 42
[2025-07-29 14:04:32.486] I: OTA Stage Change from (12)->(13)
[2025-07-29 14:04:32.486] I: 459732 [DL]Image 1 download completed successfully
[2025-07-29 14:04:32.596] I: 459833 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 14:04:32.596] I: 459837 [DL]Current number of connections: 0/1
[2025-07-29 14:04:32.596] I: BLE Disconnected: 13
[2025-07-29 14:04:40.496] I: 467753 [DL]DFU-BLE-Connected
[2025-07-29 14:04:40.517] I: stop_ble_advertisment_timer
[2025-07-29 14:04:40.517] I: 467759 [DL]Current number of connections: 1/1
[2025-07-29 14:04:40.517] I: BLE Connected
[2025-07-29 14:04:40.736] I: 467991 [DL]DFU Image upload started
[2025-07-29 14:04:41.576] I: Connection parameters updated.
[2025-07-29 14:04:41.576]  interval: 9, latency: 0, timeout: 42
[2025-07-29 14:06:32.366] I: OTA Stage Change from (13)->(14)
[2025-07-29 14:06:32.366] I: 579611 [DL]Image 2 download completed successfully
[2025-07-29 14:06:32.466] I: 579708 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 14:06:32.466] I: 579712 [DL]Current number of connections: 0/1
[2025-07-29 14:06:32.466] I: BLE Disconnected: 13
[2025-07-29 14:06:39.646] I: 586885 [DL]DFU-BLE-Connected
[2025-07-29 14:06:39.646] I: stop_ble_advertisment_timer
[2025-07-29 14:06:39.646] I: 586891 [DL]Current number of connections: 1/1
[2025-07-29 14:06:39.646] I: BLE Connected
[2025-07-29 14:06:39.876] I: 587122 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 14:06:39.876] I: 587126 [DL]Current number of connections: 0/1
[2025-07-29 14:06:39.876] I: BLE Disconnected: 13
[2025-07-29 14:06:44.226] I: 591466 [DL]DFU-BLE-Connected
[2025-07-29 14:06:44.226] I: stop_ble_advertisment_timer
[2025-07-29 14:06:44.226] I: 591472 [DL]Current number of connections: 1/1
[2025-07-29 14:06:44.226] I: BLE Connected
[2025-07-29 14:06:44.456] I: 591693 [DL]DFU_ImgConfirmHandler: Nordic Image Confirmed by MCUMgr
[2025-07-29 14:06:44.466] I: 591727 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 14:06:44.486] I: 591731 [DL]Current number of connections: 0/1
[2025-07-29 14:06:44.486] I: BLE Disconnected: 13
[2025-07-29 14:06:52.136] I: 599369 [DL]DFU-BLE-Connected
[2025-07-29 14:06:52.136] I: stop_ble_advertisment_timer
[2025-07-29 14:06:52.136] I: 599375 [DL]Current number of connections: 1/1
[2025-07-29 14:06:52.136] I: BLE Connected
[2025-07-29 14:06:52.346] I: 599591 [DL]DFU_ImgConfirmHandler: Nordic Image Confirmed by MCUMgr
[2025-07-29 14:06:52.376] I: 599617 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 14:06:52.376] I: 599621 [DL]Current number of connections: 0/1
[2025-07-29 14:06:52.376] I: BLE Disconnected: 13
[2025-07-29 14:07:00.536] I: 607773 [DL]DFU-BLE-Connected
[2025-07-29 14:07:00.536] I: stop_ble_advertisment_timer
[2025-07-29 14:07:00.536] I: 607778 [DL]Current number of connections: 1/1
[2025-07-29 14:07:00.536] I: BLE Connected
[2025-07-29 14:07:00.746] I: STM Pending =0, Redpine Pending = 0
[2025-07-29 14:07:00.843] I: Count = 4
[2025-07-29 14:07:00.843] I: dfu_header_data.image_count: 4
[2025-07-29 14:07:01.556] I: Connection parameters updated.
[2025-07-29 14:07:01.556]  interval: 9, latency: 0, timeout: 42
[2025-07-29 14:07:01.721] I: IMG Integrity Verified Successfully: 0
[2025-07-29 14:07:04.726] I: IMG Integrity Verified Successfully: 1
[2025-07-29 14:07:04.806] I: IMG Integrity Verified Successfully: 2
[2025-07-29 14:07:05.146] I: IMG Integrity Verified Successfully: 3
[2025-07-29 14:07:05.166] I: OTA Bundle(STM32 + RS9116 + PN76) image integrity Verified
[2025-07-29 14:07:05.166] I: OTA Stage Change from (14)->(30)
[2025-07-29 14:07:05.246] I: Updated ota meta data
[2025-07-29 14:07:05.306] I: Operating Mode Command: Mode:10, State:31
[2025-07-29 14:07:05.306] E: Sending UART cmd(5) st 0
[2025-07-29 14:07:05.306] I: Operating mode event
[2025-07-29 14:07:05.306] I: Received response of command id 5
[2025-07-29 14:07:05.306] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 14:07:05.306] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 14:07:05.306] I: STM OTAU Pending: Reset Nordic Triggered
[2025-07-29 14:07:05.306] I: OTA Stage Change from (30)->(30)
[2025-07-29 14:07:05.306] I: Set Kwikset Lock App Mode 16
[2025-07-29 14:07:05.306] I: Set Kwikset Lock App State 49
[2025-07-29 14:07:05.306] I: Matter is disabled
[2025-07-29 14:07:05.356] I: 612599 [DL]DFU-BLE-Disconnected : 19
[2025-07-29 14:07:05.356] I: 612603 [DL]Current number of connections: 0/1
[2025-07-29 14:07:05.356] I: BLE Disconnected: 13
[2025-07-29 14:07:52.876] 
[2025-07-29 14:07:52.876] uart:~$ *** Booting My Application v23.55.1-2f9996e8c87c ***
[2025-07-29 14:07:52.916] *** Using nRF Connect SDK v2.8.0-a2386bfc8401 ***
[2025-07-29 14:07:52.916] *** Using Zephyr OS v3.7.99-0bc3393fb112 ***
[2025-07-29 14:07:52.916] I: KWIKSET HALO 3 PLUS VERSION: 17.37.01.03
[2025-07-29 14:07:52.916] I: 51 [DL]BLE address: DC:9C:4A:B9:E6:26
[2025-07-29 14:07:52.936] I: No users indexes stored
[2025-07-29 14:07:52.936] I: No stored indexes for credential of type: 1
[2025-07-29 14:07:53.048] I: No stored indexes for credential of type: 2
[2025-07-29 14:07:53.048] I: ========== User Index: 0x01 User ID: 0xffffffff ==========
[2025-07-29 14:07:53.048] I: ========== User Index: 0x02 User ID: 0xffffffff ==========
[2025-07-29 14:07:53.048] I: ========== User Index: 0x03 User ID: 0xffffffff ==========
[2025-07-29 14:07:53.048] I: ========== User Index: 0x04 User ID: 0xffffffff ==========
[2025-07-29 14:07:53.048] I: ========== User Index: 0x05 User ID: 0xffffffff ==========
[2025-07-29 14:07:53.048] I: ========== User Index: 0x06 User ID: 0xffffffff ==========
[2025-07-29 14:07:53.048] I: ========== User Index: 0x07 User ID: 0xffffffff ==========
[2025-07-29 14:07:53.048] I: ========== User Index: 0x08 User ID: 0xffffffff ==========
[2025-07-29 14:07:53.048] I: ========== User Index: 0x09 User ID: 0xffffffff ==========
[2025-07-29 14:07:53.048] I: ========== User Index: 0x0a User ID: 0xffffffff ==========
[2025-07-29 14:07:53.056] I: ========== User Index: 0x0b User ID: 0xffffffff ==========
[2025-07-29 14:07:53.056] I: Board config kwiksetmdb_nrf5340_cpuapp
[2025-07-29 14:07:53.056] I: IMAGE_VERSION 17370103
[2025-07-29 14:07:53.056] I: build time: Jul 29 2025 12:02:01
[2025-07-29 14:07:53.056] I: 158 [DL]CHIP task running
[2025-07-29 14:07:53.056] I: Init CHIP stack
[2025-07-29 14:07:53.056] I: 164 [DL]OpenThread started: OK
[2025-07-29 14:07:53.056] I: 167 [DL]Setting OpenThread device type to SLEEPY END DEVICE
[2025-07-29 14:07:53.056] I: 173 [SWU]New firmware image confirmed
[2025-07-29 14:07:53.056] I: 177 [SWU]DFU_BLEAdvertising_Init
[2025-07-29 14:07:53.456] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 14:07:53.456] I: NFC Boot Event PN7642 FW VERSION 17.01.00.03
[2025-07-29 14:07:53.456] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 14:07:53.456] I: 
[2025-07-29 14:07:53.456] Boot Event Received
[2025-07-29 14:07:53.456] 
[2025-07-29 14:07:53.456] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 14:07:53.456] 
[2025-07-29 14:07:53.456] I: 260 [SVR]Subscription persistence not supported
[2025-07-29 14:07:53.456] I: 265 [SVR]Server initializing...
[2025-07-29 14:07:53.456] I: 268 [TS]Last Known Good Time: 2023-10-14T01:16:48
[2025-07-29 14:07:53.456] I: 274 [DMG]AccessControl: initializing
[2025-07-29 14:07:53.466] I: 277 [DMG]Examples::AccessControlDelegate::Init
[2025-07-29 14:07:53.466] I: 282 [DMG]AccessControl: setting
[2025-07-29 14:07:53.466] I: 285 [DMG]DefaultAclStorage: initializing
[2025-07-29 14:07:53.466] I: 289 [DMG]DefaultAclStorage: 0 entries loaded
[2025-07-29 14:07:53.476] E: 293 [IN]IPV6_PKTINFO failed: 109
[2025-07-29 14:07:53.476] I: 299 [ZCL]Using ZAP configuration...
[2025-07-29 14:07:53.476] I: 304 [DMG]AccessControlCluster: initializing
[2025-07-29 14:07:53.476] Unhandled cluster ID: 0x  30
[2025-07-29 14:07:53.476] 
[2025-07-29 14:07:53.486] ===== Attribute Received are: Cluster=30 Attribute=0 Value=0 =====
[2025-07-29 14:07:53.486] I: 318 [ZCL]Emit DSTTableEmpty event [ep=0]
[2025-07-29 14:07:53.486] I: 322 [ZCL]Initiating Admin Commissioning cluster.
[2025-07-29 14:07:53.486] I: 326 [ZCL]Door Lock server initialized
[2025-07-29 14:07:53.486] E: 330 [ZCL]DeviceInfoProvider is not registered
[2025-07-29 14:07:53.486] E: 334 [ZCL]Failed to read calendar type with error: 0x86
[2025-07-29 14:07:53.486] Unhandled cluster ID: 0x   3
[2025-07-29 14:07:53.486] 
[2025-07-29 14:07:53.486] ===== Attribute Received are: Cluster=3 Attribute=1 Value=3 =====
[2025-07-29 14:07:53.496] I: 348 [ZCL]Door Lock cluster initialized at endpoint #1
[2025-07-29 14:07:53.496] ===== Attribute Received are: Cluster=101 Attribute=0 Value=255 =====
[2025-07-29 14:07:53.496] ===== Attribute Received are: Cluster=101 Attribute=2 Value=1 =====
[2025-07-29 14:07:53.496] ===== Attribute Received are: Cluster=101 Attribute=1 Value=0 =====
[2025-07-29 14:07:53.496] ===== Attribute Received are: Cluster=101 Attribute=11 Value=11 =====
[2025-07-29 14:07:53.496] ===== Attribute Received are: Cluster=101 Attribute=12 Value=35 =====
[2025-07-29 14:07:53.496] ===== Attribute Received are: Cluster=101 Attribute=13 Value=35 =====
[2025-07-29 14:07:53.496] ===== Attribute Received are: Cluster=101 Attribute=1c Value=35 =====
[2025-07-29 14:07:53.496] ===== Attribute Received are: Cluster=101 Attribute=19 Value=80 =====
[2025-07-29 14:07:53.496] I: 402 [DIS]Updating services using commissioning mode 0
[2025-07-29 14:07:53.496] E: 407 [DIS]Failed to remove advertised services: 3
[2025-07-29 14:07:53.516] E: 411 [DIS]Failed to finalize service update: 3
[2025-07-29 14:07:53.516] I: 416 [IN]CASE Server enabling CASE session setups
[2025-07-29 14:07:53.516] I: 421 [SVR]Joining Multicast groups
[2025-07-29 14:07:53.516] I: 424 [SVR]Server Listening...
[2025-07-29 14:07:53.516] I: 427 [DL]Device Configuration:
[2025-07-29 14:07:53.516] I: 430 [DL]  Serial Number: 1789AE57B32427844F
[2025-07-29 14:07:53.516] I: 434 [DL]  Vendor Id: 5153 (0x1421)
[2025-07-29 14:07:53.516] I: 437 [DL]  Product Id: 66 (0x42)
[2025-07-29 14:07:53.516] I: Get product name B, len 0
[2025-07-29 14:07:53.516] I: 443 [DL]  Product Name: B
[2025-07-29 14:07:53.516] I: 446 [DL]  Hardware Version: 1
[2025-07-29 14:07:53.516] I: 449 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 75655451
[2025-07-29 14:07:53.516] I: 454 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 776 (0x308)
[2025-07-29 14:07:53.516] I: 460 [DL]  Manufacturing Date: 2025-07-24
[2025-07-29 14:07:53.544] I: 464 [DL]  Device Type: 10 (0xA)
[2025-07-29 14:07:53.544] I: 467 [SVR]SetupQRCode: [MT:-QWJ08DB00.I2N6SM10]
[2025-07-29 14:07:53.544] I: 472 [SVR]Copy/paste the below URL in a browser to see the QR Code:
[2025-07-29 14:07:53.544] I: 478 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-QWJ08DB00.I2N6SM10
[2025-07-29 14:07:53.544] I: 487 [SVR]Manual pairing code: [05967546175]
[2025-07-29 14:07:53.544] I: STM32 device number: 
[2025-07-29 14:07:53.544] I: 31 37 38 39 41 45 35 37 |1789AE57
[2025-07-29 14:07:53.544] I: 42 33 32 34 32 37 38 34 |B3242784
[2025-07-29 14:07:53.544] I: 34 46                   |4F      
[2025-07-29 14:07:53.544] I: SKU number: 
[2025-07-29 14:07:53.546] I: 4b 31 37 2d 30 31       |K17-01  
[2025-07-29 14:07:53.546] I: WO number: 
[2025-07-29 14:07:53.546] I: 30 30 30 30 30 30 30 30 |00000000
[2025-07-29 14:07:53.546] I: 30                      |0       
[2025-07-29 14:07:53.560] I: Manuf Date: 
[2025-07-29 14:07:53.560] I: 32 30 32 35 2d 30 37 2d |2025-07-
[2025-07-29 14:07:53.560] I: 32 34 00 00 00 00       |24....  
[2025-07-29 14:07:53.560] I: Prod config length 6
[2025-07-29 14:07:53.560] I: Product Config: 
[2025-07-29 14:07:53.560] I: 30 78 30 30 30 31       |0x0001  
[2025-07-29 14:07:53.560] I: Prod Config Read 1
[2025-07-29 14:07:53.560] I: User intend flow enabled, set commissioning flow to kUserActionRequired
[2025-07-29 14:07:53.560] I: Factory Data Version length 2
[2025-07-29 14:07:53.560] I: Factory Data Ver: 
[2025-07-29 14:07:53.560] I: 30 31                   |01      
[2025-07-29 14:07:53.560] I: Payload value in string format: MT:-QWJ04TC00.I2N60Q4P0ILT70VYYR1JFSK14YDB0-0LJ1-0LJ1-0LJ1IHLC0AUZL1XIKJ17AZL1UV700CXYR1K6Y12NNZR1YC-L1-2ZR1OADO1KB40
[2025-07-29 14:07:53.560] I: Pairing Code value in string format: 459675461705153000660
[2025-07-29 14:07:53.560] I: ============== Updating product finish and color to 15, 2, product Name Halo Select Plus ==============
[2025-07-29 14:07:53.576] E: 578 [DL]Long dispatch time: 417 ms, for event type 2
[2025-07-29 14:07:53.576] ===== Attribute Received are: Cluster=101 Attribute=0 Value=1 =====
[2025-07-29 14:07:55.006] I: Syncing up on message 9a
[2025-07-29 14:07:55.006] I: STM32 counter to 1
[2025-07-29 14:07:55.046] I: BLE Device ID: 2784
[2025-07-29 14:07:55.046] I: Device is provisioned
[2025-07-29 14:07:55.046] I: network state 0
[2025-07-29 14:07:55.046] E: Sending UART cmd(3) st 0
[2025-07-29 14:07:55.046] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 14:07:55.046] I: Received response of command id 9a
[2025-07-29 14:07:55.046] I: Command 0x9A Received
[2025-07-29 14:07:55.046] I: Firmware Attribute event
[2025-07-29 14:07:55.077] I: Received response of command id 30
[2025-07-29 14:07:55.077] I: Received DC Eco Config REQ
[2025-07-29 14:07:55.077] I: DC Eco Config Resp
[2025-07-29 14:07:55.077] I: Received DC eco config req
[2025-07-29 14:07:55.077] I: 80 72 03 00 10 00 04 1a |.r......
[2025-07-29 14:07:55.077] I: 17 05                   |..      
[2025-07-29 14:07:55.077] E: Sending UART cmd(72) st 0
[2025-07-29 14:07:57.046] I: Syncing up on message 3
[2025-07-29 14:07:57.046] I: Sys init req
[2025-07-29 14:07:57.046] E: Sending UART cmd(3) st 0
[2025-07-29 14:07:57.046] I: System init Response
[2025-07-29 14:07:57.046] I: Received response of command id 3
[2025-07-29 14:07:57.046] I: Update sync timer
[2025-07-29 14:07:57.046] I: Received Sys Init Resp
[2025-07-29 14:07:57.046] I: battery mode 0
[2025-07-29 14:07:57.046] I: battery percentage 5a
[2025-07-29 14:07:57.046] I: battery type 1
[2025-07-29 14:07:57.046] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 14:07:57.526] I: Syncing up on message 5
[2025-07-29 14:07:57.526] I: Operating mode req
[2025-07-29 14:07:57.576] E: Sending UART cmd(5) st 0
[2025-07-29 14:07:57.576] I: Operating mode response
[2025-07-29 14:07:57.576] I: Received response of command id 5
[2025-07-29 14:07:57.576] I: Received Lock Op Mode Resp, mode 10, App state 31
[2025-07-29 14:07:57.576] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 14:07:57.576] I: Set Kwikset Lock App Mode 16
[2025-07-29 14:07:57.576] I: Set Kwikset Lock App State 49
[2025-07-29 14:07:57.576] I: Matter is disabled
[2025-07-29 14:07:58.076] I: Syncing up on message 10
[2025-07-29 14:07:58.076] I: Lock state req
[2025-07-29 14:07:58.076] E: Sending UART cmd(10) st 0
[2025-07-29 14:07:58.076] I: Lock State Response
[2025-07-29 14:07:58.076] I: Received response of command id 10
[2025-07-29 14:07:58.076] I: Received Lock State Response, lock st: 12
[2025-07-29 14:07:58.076] I: Found matching nordic source of operation 0
[2025-07-29 14:07:58.076] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 14:07:58.076] I: Unlock action completed
[2025-07-29 14:07:58.076] I: Updating LockState attribute
[2025-07-29 14:07:58.076] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 14:07:58.526] I: Syncing up on message 20
[2025-07-29 14:07:58.586] I: Lock setting req
[2025-07-29 14:07:58.586] E: Sending UART cmd(20) st 0
[2025-07-29 14:07:58.586] I: Lock General Setting Response
[2025-07-29 14:07:58.586] I: Received response of command id 20
[2025-07-29 14:07:58.586] I: Received Lock General Setting resp
[2025-07-29 14:07:58.586] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 14:07:58.586] SoundVolume attribute change
[2025-07-29 14:07:58.586] 
[2025-07-29 14:07:58.586] I: == Sound Volume Attribute Update Callback, sound volume 2 ==
[2025-07-29 14:07:58.586] I: No change in sound volume, return
[2025-07-29 14:07:58.586] ===== Attribute Received are: Cluster=101 Attribute=24 Value=2 =====
[2025-07-29 14:07:58.586] I: Matter Not Enabled do not set
[2025-07-29 14:07:59.076] I: Syncing up on message 51
[2025-07-29 14:07:59.076] I: Battery info req
[2025-07-29 14:07:59.076] E: Sending UART cmd(51) st 0
[2025-07-29 14:07:59.076] I: Received response of command id 51
[2025-07-29 14:07:59.076] I: Received Battery Info resp
[2025-07-29 14:07:59.076] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 14:07:59.076] Unhandled cluster ID: 0x  2f
[2025-07-29 14:07:59.076] 
[2025-07-29 14:07:59.076] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 14:07:59.076] Unhandled cluster ID: 0x  2f
[2025-07-29 14:07:59.076] 
[2025-07-29 14:07:59.076] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 14:07:59.530] I: All message synced.
[2025-07-29 14:08:23.066] I: STM system init timer expired, System Init Event not received from STM32
[2025-07-29 14:08:23.066] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 14:08:23.066] I: STM Pending =1, Redpine Pending = 1
[2025-07-29 14:08:23.066] I: STM Post OTA Pending
[2025-07-29 14:08:23.066] I: Redpine Post OTA Pending
[2025-07-29 14:08:23.066] E: Sending UART cmd(9e) st 0
[2025-07-29 14:08:23.066] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 14:08:23.066] I: 30188 [SWU]SMP BLE advertising started
[2025-07-29 14:08:23.066] I: 30192 [DL]DFU over SMP started
[2025-07-29 14:08:23.927] I: IMG Integrity Verified Successfully: 0
[2025-07-29 14:08:26.886] I: IMG Integrity Verified Successfully: 1
[2025-07-29 14:08:26.971] I: IMG Integrity Verified Successfully: 2
[2025-07-29 14:08:27.306] I: IMG Integrity Verified Successfully: 3
[2025-07-29 14:08:27.336] I: OTA Stage Change from (ff)->(32)
[2025-07-29 14:08:27.336] I: OTA device_id = 5 : DISCOVERY_REQ
[2025-07-29 14:08:27.446] I: SECURE_STM : IB_DEVICE_DISCOVERY_REQUEST (80) 
[2025-07-29 14:08:27.446] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 14:08:27.446] I: STM Current Firmware Version: 17 5 4 1b
[2025-07-29 14:08:27.446] I: OTA device_id = 5 : FW_UPDATE_START_REQ
[2025-07-29 14:08:27.446] I: SECURE_STM : IB_FW_UPDATE_START_REQUEST (80)
[2025-07-29 14:08:33.846] I: STM OTA Progress = 10
[2025-07-29 14:08:40.206] I: STM OTA Progress = 20
[2025-07-29 14:08:46.556] I: STM OTA Progress = 30
[2025-07-29 14:08:53.036] I: STM OTA Progress = 40
[2025-07-29 14:08:59.386] I: STM OTA Progress = 50
[2025-07-29 14:09:05.746] I: STM OTA Progress = 60
[2025-07-29 14:09:12.116] I: STM OTA Progress = 70
[2025-07-29 14:09:18.486] I: STM OTA Progress = 80
[2025-07-29 14:09:24.826] I: STM OTA Progress = 90
[2025-07-29 14:09:31.196] I: STM OTA Progress = 100
[2025-07-29 14:09:31.886] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 14:09:31.896] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 14:09:49.076] I: Sending Sys Init Resp
[2025-07-29 14:09:49.076] I: Device is provisioned
[2025-07-29 14:09:49.076] I: network state 0
[2025-07-29 14:09:49.076] E: Sending UART cmd(3) st 0
[2025-07-29 14:09:49.076] I: Received DC App Config REQ
[2025-07-29 14:09:49.076] I: DC App Config Resp
[2025-07-29 14:09:49.076] I: Received DC config req
[2025-07-29 14:09:49.076] I: 80 70 03 00 10 10 08 00 |.p......
[2025-07-29 14:09:49.076] I: 50 1e                   |P.      
[2025-07-29 14:09:49.076] I: Matter enabled state 0
[2025-07-29 14:09:49.076] I: Get Matter Commission State
[2025-07-29 14:09:49.076] I: network state 0
[2025-07-29 14:09:49.086] I: network state 0
[2025-07-29 14:09:49.086] E: Sending UART cmd(70) st 0
[2025-07-29 14:09:49.146] I: Lock State Event
[2025-07-29 14:09:49.146] I: Received response of command id 10
[2025-07-29 14:09:49.146] I: Received Lock State event, lock st: 12
[2025-07-29 14:09:49.146] I: Found matching nordic source of operation 0
[2025-07-29 14:09:49.146] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 14:09:49.146] I: Unlock action completed
[2025-07-29 14:09:49.146] I: Updating LockState attribute
[2025-07-29 14:09:49.146] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 14:09:49.176] I: Received DC Eco Config REQ
[2025-07-29 14:09:49.176] I: DC Eco Config Resp
[2025-07-29 14:09:49.206] I: Received DC eco config req
[2025-07-29 14:09:49.206] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 14:09:49.206] I: c4 1e                   |..      
[2025-07-29 14:09:49.206] E: Sending UART cmd(72) st 0
[2025-07-29 14:09:49.386] I: General Lock Setting event
[2025-07-29 14:09:49.386] I: Received response of command id 20
[2025-07-29 14:09:49.386] I: Received Lock General Setting event
[2025-07-29 14:09:49.386] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 14:09:49.386] I: Matter Not Enabled do not set
[2025-07-29 14:09:49.489] I: Firmware Attribute event
[2025-07-29 14:09:49.489] I: Received response of command id 30
[2025-07-29 14:09:49.546] I: Hardware Attribute event
[2025-07-29 14:09:49.546] I: Received response of command id 31
[2025-07-29 14:09:49.626] I: Operating mode event
[2025-07-29 14:09:49.626] I: Received response of command id 5
[2025-07-29 14:09:49.626] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 14:09:49.626] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 14:09:49.626] I: Set Kwikset Lock App Mode 16
[2025-07-29 14:09:49.626] I: Set Kwikset Lock App State 49
[2025-07-29 14:09:49.626] I: Matter is disabled
[2025-07-29 14:09:49.751] I: Battery Info event
[2025-07-29 14:09:49.751] I: Received response of command id 51
[2025-07-29 14:09:49.751] I: Received Battery info event
[2025-07-29 14:09:49.751] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 14:09:49.751] Unhandled cluster ID: 0x  2f
[2025-07-29 14:09:49.751] 
[2025-07-29 14:09:49.751] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 14:09:49.751] Unhandled cluster ID: 0x  2f
[2025-07-29 14:09:49.751] 
[2025-07-29 14:09:49.751] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 14:09:49.826] I: System info event
[2025-07-29 14:09:49.826] I: Received System Info Event
[2025-07-29 14:09:49.826] W: Time invalid, set time
[2025-07-29 14:09:49.856] I: Get system time
[2025-07-29 14:09:49.856] I: System Real time in seconds 373663017
[2025-07-29 14:09:49.856] I: Time sync status flag 0
[2025-07-29 14:09:49.856] E: Time not sync, keep default value
[2025-07-29 14:09:49.886] I: System init event
[2025-07-29 14:09:49.956] I: Received response of command id 3
[2025-07-29 14:09:49.956] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 14:09:49.956] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 14:09:49.956] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 14:09:49.956] I: STM Current Firmware Version: 17 5 4 1a
[2025-07-29 14:09:49.956] I: OTA device_id = 5 : FW_UPDATE_COMPLETE_REQ
[2025-07-29 14:09:49.956] I: SECURE_STM : IB_FW_UPDATE_COMPLETE_REQUEST (80) 
[2025-07-29 14:09:49.956] I: OTA device_id = 5 : FW_UPDATE_REBOOT_REQ
[2025-07-29 14:09:49.956] I: SECURE_STM : REBOOT_COMMAND (80)
[2025-07-29 14:09:52.386] I: Sending Sys Init Resp
[2025-07-29 14:09:52.386] I: Device is provisioned
[2025-07-29 14:09:52.386] I: network state 0
[2025-07-29 14:09:52.386] E: Sending UART cmd(3) st 0
[2025-07-29 14:09:52.386] I: Received DC App Config REQ
[2025-07-29 14:09:52.386] I: DC App Config Resp
[2025-07-29 14:09:52.386] I: Received DC config req
[2025-07-29 14:09:52.386] I: 80 70 03 00 10 10 04 1a |.p......
[2025-07-29 14:09:52.386] I: 00 62                   |.b      
[2025-07-29 14:09:52.386] I: Matter enabled state 0
[2025-07-29 14:09:52.386] I: Get Matter Commission State
[2025-07-29 14:09:52.386] I: network state 0
[2025-07-29 14:09:52.386] I: network state 0
[2025-07-29 14:09:52.386] E: Sending UART cmd(70) st 0
[2025-07-29 14:09:52.446] I: Lock State Event
[2025-07-29 14:09:52.446] I: Received response of command id 10
[2025-07-29 14:09:52.446] I: Received Lock State event, lock st: 12
[2025-07-29 14:09:52.446] I: Found matching nordic source of operation 0
[2025-07-29 14:09:52.446] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 14:09:52.446] I: Unlock action completed
[2025-07-29 14:09:52.446] I: Updating LockState attribute
[2025-07-29 14:09:52.446] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 14:09:52.476] I: Received DC Eco Config REQ
[2025-07-29 14:09:52.476] I: DC Eco Config Resp
[2025-07-29 14:09:52.506] I: Received DC eco config req
[2025-07-29 14:09:52.506] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 14:09:52.506] I: c4 62                   |.b      
[2025-07-29 14:09:52.506] E: Sending UART cmd(72) st 0
[2025-07-29 14:09:52.686] I: General Lock Setting event
[2025-07-29 14:09:52.686] I: Received response of command id 20
[2025-07-29 14:09:52.686] I: Received Lock General Setting event
[2025-07-29 14:09:52.686] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 14:09:52.686] I: Matter Not Enabled do not set
[2025-07-29 14:09:52.786] I: Firmware Attribute event
[2025-07-29 14:09:52.786] I: Received response of command id 30
[2025-07-29 14:09:52.846] I: Hardware Attribute event
[2025-07-29 14:09:52.846] I: Received response of command id 31
[2025-07-29 14:09:52.926] I: Operating mode event
[2025-07-29 14:09:52.926] I: Received response of command id 5
[2025-07-29 14:09:52.926] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 14:09:52.926] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 14:09:52.926] I: Set Kwikset Lock App Mode 16
[2025-07-29 14:09:52.926] I: Set Kwikset Lock App State 49
[2025-07-29 14:09:52.926] I: Matter is disabled
[2025-07-29 14:09:53.054] I: Battery Info event
[2025-07-29 14:09:53.054] I: Received response of command id 51
[2025-07-29 14:09:53.054] I: Received Battery info event
[2025-07-29 14:09:53.054] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 14:09:53.054] Unhandled cluster ID: 0x  2f
[2025-07-29 14:09:53.054] 
[2025-07-29 14:09:53.054] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 14:09:53.054] Unhandled cluster ID: 0x  2f
[2025-07-29 14:09:53.054] 
[2025-07-29 14:09:53.054] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 14:09:53.127] I: System info event
[2025-07-29 14:09:53.127] I: Received System Info Event
[2025-07-29 14:09:53.156] W: Time invalid, set time
[2025-07-29 14:09:53.156] I: Get system time
[2025-07-29 14:09:53.156] I: System Real time in seconds 373663017
[2025-07-29 14:09:53.156] I: Time sync status flag 0
[2025-07-29 14:09:53.156] E: Time not sync, keep default value
[2025-07-29 14:09:53.243] I: System init event
[2025-07-29 14:09:53.243] I: Received response of command id 3
[2025-07-29 14:09:53.243] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 14:09:53.243] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 14:09:53.243] I: OTA device_id = 5 : FW_VERSION_REQ
[2025-07-29 14:09:53.243] I: STM Current Firmware Version: 17 5 4 1a
[2025-07-29 14:09:53.243] I: STM New OTA Firmware Version = 17 5 4 1a
[2025-07-29 14:09:53.243] I: STM Secure OTA Successful
[2025-07-29 14:09:53.355] I: Cleared STM OTA Meta Data
[2025-07-29 14:09:53.356] I: OTA Stage Change from (32)->(33)
[2025-07-29 14:09:53.356] I: Redpine OTA started
[2025-07-29 14:09:53.356] I: OTA Stage Change from (33)->(34)
[2025-07-29 14:09:53.356] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 14:10:00.341] I: STM Reset Count 0
[2025-07-29 14:10:00.376] I: OTA device_id = 4 : DISCOVERY_REQ
[2025-07-29 14:10:00.376] I: STM_QSPI : IB_DEVICE_DISCOVERY_REQUEST (80)
[2025-07-29 14:10:00.376] I: OTA device_id = 4 : FW_VERSION_REQ
[2025-07-29 14:10:00.376] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 14:10:00.376] I: Redpine Current Firmware Version: 2.c.0.3
[2025-07-29 14:10:00.396] I: OTA device_id = 4 : FW_UPDATE_START_REQ
[2025-07-29 14:10:00.486] I: STM_QSPI : IB_FW_UPDATE_START_REQUEST (80)
[2025-07-29 14:10:23.216] I: STM Boot Up Properly, Stopped STM Reboot Timer
[2025-07-29 14:10:39.916] I: Redpine Image Stored into STM QSPI, Progress = 10
[2025-07-29 14:11:13.436] I: Redpine Image Stored into STM QSPI, Progress = 20
[2025-07-29 14:11:34.036] I: Redpine Image Stored into STM QSPI, Progress = 30
[2025-07-29 14:11:54.816] I: Redpine Image Stored into STM QSPI, Progress = 40
[2025-07-29 14:12:15.516] I: Redpine Image Stored into STM QSPI, Progress = 50
[2025-07-29 14:12:36.226] I: Redpine Image Stored into STM QSPI, Progress = 60
[2025-07-29 14:12:57.037] I: Redpine Image Stored into STM QSPI, Progress = 70
[2025-07-29 14:13:17.766] I: Redpine Image Stored into STM QSPI, Progress = 80
[2025-07-29 14:13:38.487] I: Redpine Image Stored into STM QSPI, Progress = 90
[2025-07-29 14:13:59.247] I: Redpine Image Stored into STM QSPI, Progress = 100
[2025-07-29 14:14:01.366] I: OTA device_id = 4 : FW_UPDATE_COMPLETE_REQ
[2025-07-29 14:14:01.796] I: STM_QSPI : IB_FW_UPDATE_COMPLETE_REQUEST (80) 
[2025-07-29 14:14:01.947] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (0)
[2025-07-29 14:14:06.727] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (10)
[2025-07-29 14:14:11.637] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (20)
[2025-07-29 14:14:16.596] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (30)
[2025-07-29 14:14:21.567] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (40)
[2025-07-29 14:14:26.507] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (50)
[2025-07-29 14:14:31.467] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (60)
[2025-07-29 14:14:36.417] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (70)
[2025-07-29 14:14:41.369] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (80)
[2025-07-29 14:14:46.267] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (90)
[2025-07-29 14:14:51.086] I: STM_QSPI : STM QSPI to Redpine SPI Image Transfer Ongoing (100)
[2025-07-29 14:15:20.487] I: STM_QSPI : IB_FW_UPDATE_REBOOT_REQUEST (80) 
[2025-07-29 14:15:20.587] I: Clear Redpine OTA Meta Data
[2025-07-29 14:15:20.587] I: Redpine OTA Successful
[2025-07-29 14:15:20.616] I: Check Pending Firmware upgrade for STM, Redpine & PN76
[2025-07-29 14:15:20.616] I: STM Pending =2, Redpine Pending = 2
[2025-07-29 14:15:20.616] I: PN76 IMG 1 Post OTA Pending
[2025-07-29 14:15:20.616] E: Sending UART cmd(9e) st 0
[2025-07-29 14:15:20.616] I: 447751 [SWU]DFU over SMP was already started
[2025-07-29 14:15:20.697] I: IMG Integrity Verified Successfully: 2
[2025-07-29 14:15:21.067] I: IMG Integrity Verified Successfully: 3
[2025-07-29 14:15:21.067] I: OTA Stage Change from (34)->(3a)
[2025-07-29 14:15:21.067] I: PN76_IMG1_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 14:15:21.067] I: PN76_IMG Update from OTA Task Event
[2025-07-29 14:15:21.067] I: 
[2025-07-29 14:15:21.067] 
[2025-07-29 14:15:21.067] --------------- UPDATING PN7642 NXP FIRMWARE --------------------
[2025-07-29 14:15:21.067] 
[2025-07-29 14:15:21.067] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 14:15:21.107] I: pNXPFWInfo->img_offset = 0x351497
[2025-07-29 14:15:21.107] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 14:15:21.107] I: Reading version of firmware in QSPI flash: MetaData 0x2f60217
[2025-07-29 14:15:21.107] I: PN76 NXP FW VERSION VALIDATION SKIPPED, OTAU TEST BUNDLE
[2025-07-29 14:15:21.216] I: ----> PN7642 OTA Progress = 10 %
[2025-07-29 14:15:21.286] I: ----> PN7642 OTA Progress = 20 %
[2025-07-29 14:15:21.347] I: ----> PN7642 OTA Progress = 30 %
[2025-07-29 14:15:21.407] I: ----> PN7642 OTA Progress = 40 %
[2025-07-29 14:15:21.477] I: ----> PN7642 OTA Progress = 50 %
[2025-07-29 14:15:21.537] I: ----> PN7642 OTA Progress = 60 %
[2025-07-29 14:15:21.604] I: ----> PN7642 OTA Progress = 70 %
[2025-07-29 14:15:21.667] I: ----> PN7642 OTA Progress = 80 %
[2025-07-29 14:15:21.846] I: ----> PN7642 OTA Progress = 100 %
[2025-07-29 14:15:21.846] I: Whole pn7642 FW Image downloaded ....
[2025-07-29 14:15:21.846] I: 
[2025-07-29 14:15:21.846] 
[2025-07-29 14:15:21.846] I: 
[2025-07-29 14:15:21.846] PN7642 Firmware of type 0 Successfully Updated !!!
[2025-07-29 14:15:21.846] I: PN76 Image Update Successful for Device ID(7)
[2025-07-29 14:15:21.967] I: Cleared PN76 Img1 OTA Meta Data
[2025-07-29 14:15:21.967] I: OTA Stage Change from (3a)->(3a)
[2025-07-29 14:15:21.967] I: PN76_IMG2_DEVICE_DFU_MULTI_IMG_ID
[2025-07-29 14:15:21.967] I: PN76_IMG Update from OTA Task Event
[2025-07-29 14:15:21.967] I: 
[2025-07-29 14:15:21.967] 
[2025-07-29 14:15:21.967] --------------- UPDATING PN7642 APPLICATION FIRMWARE -------------
[2025-07-29 14:15:21.967] 
[2025-07-29 14:15:21.967] I: pn7642_UpdateSecureFirmWareUpdate()::Rebooting pn7642 in HDLL Secure FW Download Mode
[2025-07-29 14:15:22.007] I: pCustAppFWInfo->img_offset = 0x35c289
[2025-07-29 14:15:22.007] I: Getting the current FW versions in pn7642 DL_GET_VERSION
[2025-07-29 14:15:22.007] I: Reading version of firmware in QSPI flash: MetaData 0x2f60217
[2025-07-29 14:15:22.007] I: PN76 APP FW VERSION VALIDATION SKIPPED, OTAU TEST BUNDLE
[2025-07-29 14:15:22.307] I: ----> PN7642 OTA Progress = 10 %
[2025-07-29 14:15:22.577] I: ----> PN7642 OTA Progress = 20 %
[2025-07-29 14:15:22.837] I: ----> PN7642 OTA Progress = 30 %
[2025-07-29 14:15:23.107] I: ----> PN7642 OTA Progress = 40 %
[2025-07-29 14:15:23.367] I: ----> PN7642 OTA Progress = 50 %
[2025-07-29 14:15:23.637] I: ----> PN7642 OTA Progress = 60 %
[2025-07-29 14:15:23.896] I: ----> PN7642 OTA Progress = 70 %
[2025-07-29 14:15:24.167] I: ----> PN7642 OTA Progress = 80 %
[2025-07-29 14:15:24.416] I: ----> PN7642 OTA Progress = 90 %
[2025-07-29 14:15:24.677] I: ----> PN7642 OTA Progress = 100 %
[2025-07-29 14:15:24.707] I: Whole pn7642 FW Image downloaded ....
[2025-07-29 14:15:24.707] I: 
[2025-07-29 14:15:24.707] 
[2025-07-29 14:15:24.707] I: 
[2025-07-29 14:15:24.707] PN7642 Firmware of type 1 Successfully Updated !!!
[2025-07-29 14:15:24.707] I: PN76 Image Update Successful for Device ID(8)
[2025-07-29 14:15:24.787] I: Cleared PN76 Img2 OTA Meta Data
[2025-07-29 14:15:25.367] I: NFC Boot Event Wake Up Reason: 0x00000001
[2025-07-29 14:15:25.367] I: NFC Boot Event PN7642 FW VERSION 17.01.00.02
[2025-07-29 14:15:25.367] I: NFC Boot Event PN7642 Secure FW Version 02.f6
[2025-07-29 14:15:25.367] I: 
[2025-07-29 14:15:25.367] Boot Event Received
[2025-07-29 14:15:25.367] 
[2025-07-29 14:15:25.367] I: Booted NFC IC in Normal Operation Mode.
[2025-07-29 14:15:25.367] 
[2025-07-29 14:15:25.367] I: OTA Stage Change from (3a)->(3b)
[2025-07-29 14:15:25.367] I: post_stm_reset_event : init_pending_ota_update
[2025-07-29 14:15:25.367] I: All pending FW Updates are completed.
[2025-07-29 14:15:25.367] I: STM32 Reset Count = 0
[2025-07-29 14:15:25.376] I: REBOOT_STM: Send STM32 Reboot Command, Count (0)
[2025-07-29 14:15:27.734] I: Sending Sys Init Resp
[2025-07-29 14:15:27.734] I: Device is provisioned
[2025-07-29 14:15:27.734] I: network state 0
[2025-07-29 14:15:27.734] E: Sending UART cmd(3) st 0
[2025-07-29 14:15:27.734] I: Received DC App Config REQ
[2025-07-29 14:15:27.734] I: DC App Config Resp
[2025-07-29 14:15:27.734] I: Received DC config req
[2025-07-29 14:15:27.734] I: 80 70 03 00 10 10 19 00 |.p......
[2025-07-29 14:15:27.734] I: 50 62                   |Pb      
[2025-07-29 14:15:27.734] I: Matter enabled state 0
[2025-07-29 14:15:27.734] I: Get Matter Commission State
[2025-07-29 14:15:27.734] I: network state 0
[2025-07-29 14:15:27.737] I: network state 0
[2025-07-29 14:15:27.737] E: Sending UART cmd(70) st 0
[2025-07-29 14:15:27.797] I: Lock State Event
[2025-07-29 14:15:27.797] I: Received response of command id 10
[2025-07-29 14:15:27.797] I: Received Lock State event, lock st: 12
[2025-07-29 14:15:27.797] I: Found matching nordic source of operation 0
[2025-07-29 14:15:27.797] I: ******** TESTING Real Source 0x0000 ********
[2025-07-29 14:15:27.797] I: Unlock action completed
[2025-07-29 14:15:27.797] I: Updating LockState attribute
[2025-07-29 14:15:27.797] ===== Attribute Received are: Cluster=101 Attribute=0 Value=2 =====
[2025-07-29 14:15:27.831] I: Received DC Eco Config REQ
[2025-07-29 14:15:27.857] I: DC Eco Config Resp
[2025-07-29 14:15:27.857] I: Received DC eco config req
[2025-07-29 14:15:27.857] I: 80 72 03 00 10 00 f5 e0 |.r......
[2025-07-29 14:15:27.857] I: c4 62                   |.b      
[2025-07-29 14:15:27.857] E: Sending UART cmd(72) st 0
[2025-07-29 14:15:28.037] I: General Lock Setting event
[2025-07-29 14:15:28.037] I: Received response of command id 20
[2025-07-29 14:15:28.037] I: Received Lock General Setting event
[2025-07-29 14:15:28.037] I: Sound Volume Attribute Update, sound volume 1
[2025-07-29 14:15:28.037] I: Matter Not Enabled do not set
[2025-07-29 14:15:28.147] I: Firmware Attribute event
[2025-07-29 14:15:28.147] I: Received response of command id 30
[2025-07-29 14:15:28.207] I: Hardware Attribute event
[2025-07-29 14:15:28.207] I: Received response of command id 31
[2025-07-29 14:15:28.277] I: Operating mode event
[2025-07-29 14:15:28.277] I: Received response of command id 5
[2025-07-29 14:15:28.277] I: Received Lock Op Mode Event, mode 10, App state 31
[2025-07-29 14:15:28.277] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 14:15:28.277] I: Set Kwikset Lock App Mode 16
[2025-07-29 14:15:28.277] I: Set Kwikset Lock App State 49
[2025-07-29 14:15:28.277] I: Matter is disabled
[2025-07-29 14:15:28.407] I: Battery Info event
[2025-07-29 14:15:28.407] I: Received response of command id 51
[2025-07-29 14:15:28.407] I: Received Battery info event
[2025-07-29 14:15:28.407] I: Matter App Battery info update: Batt level 5a, Batt st 0, Batt type 1
[2025-07-29 14:15:28.407] Unhandled cluster ID: 0x  2f
[2025-07-29 14:15:28.407] 
[2025-07-29 14:15:28.407] ===== Attribute Received are: Cluster=2f Attribute=e Value=0 =====
[2025-07-29 14:15:28.407] Unhandled cluster ID: 0x  2f
[2025-07-29 14:15:28.407] 
[2025-07-29 14:15:28.407] ===== Attribute Received are: Cluster=2f Attribute=c Value=180 =====
[2025-07-29 14:15:28.487] I: System info event
[2025-07-29 14:15:28.487] I: Received System Info Event
[2025-07-29 14:15:28.507] W: Time invalid, set time
[2025-07-29 14:15:28.507] I: Get system time
[2025-07-29 14:15:28.507] I: System Real time in seconds 373663017
[2025-07-29 14:15:28.507] I: Time sync status flag 0
[2025-07-29 14:15:28.507] E: Time not sync, keep default value
[2025-07-29 14:15:28.577] I: System init event
[2025-07-29 14:15:28.577] I: Received response of command id 3
[2025-07-29 14:15:28.577] I: STM32 Bootup, Received STM32 System Initialization Event
[2025-07-29 14:15:28.577] I: Lock Current Mode : 10, Lock Current State = 31
[2025-07-29 14:15:28.577] I: STM Image confirm timer was stopped
[2025-07-29 14:15:35.407] I: STM_QSPI : IB_FW_VERSION_REQUEST
[2025-07-29 14:15:35.407] I: stop_ota_finalization_timer
[2025-07-29 14:15:35.407] I: After OTAU, Redpine Firmware Version: 2.c.0.3
[2025-07-29 14:15:35.407] I: Redpine New OTA Firmware Version = 2 c 0 3
[2025-07-29 14:15:35.407] I: After OTAU, Secure STM Firmware Version: 17 5 4 1a
[2025-07-29 14:15:35.407] I: Send Op Mode command to release Redpine BLE and WiFI
[2025-07-29 14:15:35.407] I: Operating Mode Command: Mode:10, State:f0
[2025-07-29 14:15:35.407] E: Sending UART cmd(5) st 0
[2025-07-29 14:15:35.467] I: Operating mode event
[2025-07-29 14:15:35.467] I: Received response of command id 5
[2025-07-29 14:15:35.467] I: Received Lock Op Mode Event, mode 10, App state 10
[2025-07-29 14:15:35.467] I: Lock Current Mode : 10, Lock Current State = 10
[2025-07-29 14:15:35.467] I: stop_ota_finalization_timer
[2025-07-29 14:15:35.467] I: STM32 HALO APP STATE IS ACTIVATED NORMAL
[2025-07-29 14:15:35.467] I: Set Kwikset Lock App Mode 16
[2025-07-29 14:15:35.467] I: Set Kwikset Lock App State 16
[2025-07-29 14:15:35.467] I: Matter enabled state 0
[2025-07-29 14:15:35.467] I: Matter is disabled
[2025-07-29 14:15:35.467] I: OTA_HOUSEKEEPING
[2025-07-29 14:15:35.467] I: OTA Stage Change from (3b)->(80)
[2025-07-29 14:15:35.467] I: Start Erasing OTA bundle from nRF External Flash
[2025-07-29 14:15:41.237] I: System info event
[2025-07-29 14:15:41.237] I: Received System Info Event
[2025-07-29 14:15:41.237] I: Time is set in STM
[2025-07-29 14:16:36.577] I: Bundle Image Erased from nRF External Flash: 0
[2025-07-29 14:16:36.577] I: OTAU Completed Successfully
[2025-07-29 14:16:36.687] I: Cleared OTA Meta Data
[2025-07-29 14:16:36.687] I: OTA Stage Change from (80)->(90)
[2025-07-29 14:16:38.687] I: All message synced.
[2025-07-29 14:16:51.677] I: STOP BLE Advertisment
[2025-07-29 14:16:51.697] I: 538827 [DL]DFU over SMP stopped
[2025-07-29 14:16:51.697] E: Sending UART cmd(9e) st 0
[2025-07-29 14:21:24.487] I: Updated ota meta data
[2025-07-29 14:21:24.487] I: Operating Mode Command: Mode:10, State:34
[2025-07-29 14:21:24.487] E: Sending UART cmd(5) st 0
[2025-07-29 14:21:24.627] I: Operating mode event
[2025-07-29 14:21:24.627] I: Received response of command id 5
[2025-07-29 14:21:24.627] I: Received Lock Op Mode Event, mode 10, App state 34
[2025-07-29 14:21:24.627] I: Lock Current Mode : 10, Lock Current State = 34
[2025-07-29 14:21:24.627] I: STM32 HALO APP STATE IS BLE OTAU TRANSFER
[2025-07-29 14:21:24.627] E: Sending UART cmd(9e) st 0
[2025-07-29 14:21:24.627] I: BLE Name set: HU:2784 errCode: 0
[2025-07-29 14:21:24.627] I: 811752 [SWU]SMP BLE advertising started
[2025-07-29 14:21:24.627] I: 811756 [DL]DFU over SMP started
[2025-07-29 14:21:24.627] I: OTA Stage Change from (90)->(11)
[2025-07-29 14:21:24.627] I: Set Kwikset Lock App Mode 16
[2025-07-29 14:21:24.627] I: Set Kwikset Lock App State 52
[2025-07-29 14:21:24.627] I: Matter is disabled
[2025-07-29 14:21:40.907] I: 828041 [DL]Current number of connections: 1/1
[2025-07-29 14:21:40.907] I: BLE Connected
[2025-07-29 14:21:41.147] I: 828280 [DL]Current number of connections: 0/1
[2025-07-29 14:21:41.147] I: BLE Disconnected: 13
[2025-07-29 14:21:45.737] I: 832876 [DL]Current number of connections: 1/1
[2025-07-29 14:21:45.737] I: BLE Connected
[2025-07-29 14:21:45.967] I: 833108 [DL]DFU Image upload started
[2025-07-29 14:21:46.797] I: Connection parameters updated.
[2025-07-29 14:21:46.797]  interval: 9, latency: 0, timeout: 42
[2025-07-29 14:21:46.827] E: No available ACL buffers!
[2025-07-29 14:21:46.827] E: Unexpected first L2CAP frame
[2025-07-29 14:21:59.107] I: OTA Stage Change from (11)->(12)
[2025-07-29 14:21:59.107] I: 846243 [DL]Image 0 download completed successfully
