Hi,
We are using the nRF5340 and a Pixel phone for the nRF OTA update. We observed that the Pixel phone application disconnects after updating the connection parameters. However, this disconnection event is not being triggered or received by the application firmware on the nRF5340.
The failure is isolated to the nRF net-core upload phase (mcumgr over SMP/BLE), roughly 1.5 s after that phase starts. At the moment the device transitions into the net-core upload, it requests a Connection Parameter Update down to a 420 ms supervision timeout, Android accepts it, and then the headset itself stops responding on the radio for ~505 ms — longer than the timeout it just requested — so the central declares HCI_ERR_CONNECTION_TOUT (reason 0x08) and the link dies mid-upload.
I have attached the mobile application logs.
09-15 13:16:10.127 I/bthal.activity( 949): bt_power: AclDataStat: 13:16:04:664 - 13:16:10:127, conn_handle: 66, duration: 5463, acl_data_count: 307, acl_tx_data_count: 298, acl_rx_data_count: 9, total_acl_data_count: 22916
09-15 13:16:10.665 I/pixel-thermal( 1850): VIRTUAL-SKIN:37.9087 raw data: VIRTUAL-SKIN:37908.7 VIRTUAL-SKIN-SUB-1:37908.7 VIRTUAL-SKIN-SUB-2:34512.5 VIRTUAL-SKIN-SUB-3:36855.5 charger_therm:41937 gnss_tcxo_therm:38428 modem_therm:39941 quiet_therm:37426 rffe_therm:37092 soc_therm:38072 usb_conn_therm:37003
09-15 13:16:10.666 I/pixel-thermal( 1850): soc_therm:38.072 raw data: soc_therm:38072
09-15 13:16:10.666 I/pixel-thermal( 1850): VIRTUAL-SKIN-HINT:37.9087 raw data: VIRTUAL-SKIN:37908.7 VIRTUAL-SKIN-HINT:37908.7
09-15 13:16:10.666 I/pixel-thermal( 1850): VIRTUAL-SKIN-CPU-MID:37.9087 raw data: VIRTUAL-SKIN:37908.7 VIRTUAL-SKIN-CPU-MID:37908.7
09-15 13:16:10.667 I/pixel-thermal( 1850): VIRTUAL-SKIN-CPU-HIGH:37.9087 raw data: VIRTUAL-SKIN:37908.7 VIRTUAL-SKIN-CPU-HIGH:37908.7
09-15 13:16:10.667 I/pixel-thermal( 1850): VIRTUAL-SKIN-SOC:37.9087 raw data: VIRTUAL-SKIN:37908.7 VIRTUAL-SKIN-SOC:37908.7
09-15 13:16:10.668 I/pixel-thermal( 1850): VIRTUAL-SKIN-SOC power_budget=3752.51 err=7.09129 s_power=800 time_elapsed_ms=7020 p=2127.39 i=825.12 d=-0 dt_per_min=nan compensation=0 budget transient=0 control target=3 excluded power budget=0
09-15 13:16:10.668 I/pixel-thermal( 1850): VIRTUAL-SKIN-SOC binded power rails: (S4M_VDD_CPUCL0: 118.11 mW)(S2M_VDD_CPUCL2: 57.37 mW)(S3M_VDD_CPUCL1: 103.99 mW)(S2S_VDD_G3D: 2.59 mW)(S7M_VDD_TPU: 0.00 mW)
09-15 13:16:10.668 I/pixel-thermal( 1850): cellular-emergency:37.9087 raw data: VIRTUAL-SKIN:37908.7 cellular-emergency:37908.7
09-15 13:16:10.668 I/pixel-thermal( 1850): VIRTUAL-SKIN-CPU-LIGHT-ODPM:37.9087 raw data: VIRTUAL-SKIN:37908.7 VIRTUAL-SKIN-CPU-LIGHT-ODPM:37908.7
09-15 13:16:10.669 I/pixel-thermal( 1850): VIRTUAL-SKIN-CPU-LIGHT-ODPM power_budget=1327.23 err=1.09129 s_power=800 time_elapsed_ms=7020 p=436.517 i=90.7152 d=-0 dt_per_min=nan compensation=0 budget transient=0 control target=2 excluded power budget=0
09-15 13:16:10.669 I/pixel-thermal( 1850): VIRTUAL-SKIN-CPU-LIGHT-ODPM binded power rails: (S4M_VDD_CPUCL0: 118.11 mW)(S2M_VDD_CPUCL2: 57.37 mW)(S3M_VDD_CPUCL1: 103.99 mW)
09-15 13:16:10.669 I/pixel-thermal( 1850): VIRTUAL-SKIN-GPU:37.9087 raw data: VIRTUAL-SKIN:37908.7 VIRTUAL-SKIN-GPU:37908.7
09-15 13:16:11.081 I/WifiHAL ( 1020): Creating message to get link statistics; iface = 47
09-15 13:16:11.158 I/WifiHAL ( 1020): Getting cached scan results, iface handle = 0xb400007bb1428210
09-15 13:16:11.158 E/WifiHAL ( 1020): Creating message to get cached scan results
09-15 13:16:11.167 I/WifiHAL ( 1020): In GetCachedScanResultsCommand::handleResponse
09-15 13:16:11.205 W/BluetoothRemoteDevices(17532): Address type mismatch for XX:XX:XX:XX:DB:74, new type: 1
09-15 13:16:11.216 I/NearbyDiscovery(12966): (REDACTED) BloomFilterAdvManager: Detected bloom filter but too far away, ignoring. %sm, %s
09-15 13:16:11.222 D/WifiHAL ( 1020): Start debug command: mType GET_FEATURE
09-15 13:16:11.222 I/WifiHAL ( 1020): CreateRequest mType = GET_FEATURE
09-15 13:16:11.222 D/WifiHAL ( 1020): In DebugCommand::handleResponse, mType:GET_FEATURE
09-15 13:16:11.222 D/WifiHAL ( 1020): len = 4, expected len = 4
09-15 13:16:11.227 I/HalDevMgr( 1457): bestIfaceCreationProposal is null, requestIface=STA, existingIface=[name=wlan0 type=STA]
09-15 13:16:11.956 D/ActivityManager( 1457): freezing 16832 com.google.android.apps.privacy.wildlife
09-15 13:16:11.977 D/InetDiagMessage( 1457): Destroyed 0 sockets, proto=IPPROTO_TCP, family=AF_INET, states=14
09-15 13:16:11.979 D/InetDiagMessage( 1457): Destroyed 0 sockets, proto=IPPROTO_TCP, family=AF_INET6, states=14
09-15 13:16:11.980 D/InetDiagMessage( 1457): Destroyed live tcp sockets for uids={10175} in 7ms
09-15 13:16:12.203 I/bthal.activity( 949): bt_power: LeAdvStat: 13:16:10:981 - 13:16:12:202, duration: 1221, le_adv_count: 5, total_le_adv_count: 2455, total_event_count: 5
09-15 13:16:12.582 D/TemperatureStateSource( 2371): sequence=217 actualDelay=10003
09-15 13:16:12.586 D/TemperatureStateSource( 2371): Reading temperature: sequence=218
09-15 13:16:12.592 I/pixel-thermal( 1850): VIRTUAL-SKIN:37.9087 raw data: VIRTUAL-SKIN:37908.7
09-15 13:16:12.593 D/TemperatureStateSource( 2371): getDeviceTemperatures: sequence=218 deviceTemperatureType=3 temperatureSource=0 temperatures=[37.908707]
09-15 13:16:12.594 D/TemperatureStateSource( 2371): sequence=218 waitTime=10000
09-15 13:16:12.595 D/ImpulseStateSource( 2371): Notify clients: 228
09-15 13:16:12.740 W/TracingMuxer( 1190): type=1400 audit(0.0:139): avc: denied { write } for name="traced_producer" dev="tmpfs" ino=1335 scontext=u:r:gxp_logging:s0 tcontext=u:object_r:traced_producer_socket:s0 tclass=sock_file permissive=0
09-15 13:16:12.986 I/pixel-thermal( 1850): usb_conn_therm:36.914 raw data: usb_conn_therm:36914
09-15 13:16:12.988 I/pixel-thermal( 1850): VIRTUAL-USB-THROTTLING:0 raw data: USB-MINUS-CHARGER:-5138 VIRTUAL-USB-THROTTLING:0 charger_therm:42052 usb_conn_therm:36914
09-15 13:16:12.988 I/pixel-thermal( 1850): VIRTUAL-USB-UI:0 raw data: USB-MINUS-CHARGER:-5138 VIRTUAL-USB-UI:0 usb_conn_therm:36914
09-15 13:16:13.170 I/pixel-thermal( 1850): charger_therm:42.052 raw data: charger_therm:42052
09-15 13:16:13.173 I/pixel-thermal( 1850): VIRTUAL-SKIN-CHARGE:38.5126 raw data: VIRTUAL-SKIN-CHARGE:38512.6 VIRTUAL-SKIN-CHARGE-SUB-1:38421.8 VIRTUAL-SKIN-CHARGE-SUB-2:38512.6 charger_therm:42052 modem_therm:40209 quiet_therm:37293 rffe_therm:37070 soc_therm:38072
09-15 13:16:13.173 I/pixel-thermal( 1850): VIRTUAL-SKIN-CHARGE power_budget=558.71 err=-0.512589 s_power=2200 time_elapsed_ms=7011 p=-307.553 i=-1291.03 d=0 dt_per_min=nan compensation=0 budget transient=0 control target=2 excluded power budget=42.7095 (PARTIAL_SYSTEM_POWER: 854.19 mW, cdev_weight: 0.050000)
09-15 13:16:13.176 I/pixel-thermal( 1850): VIRTUAL-SKIN-SPEAKER:38.0517 raw data: VIRTUAL-SKIN-SPEAKER:38051.7 VIRTUAL-SKIN-SPEAKER-SUB-1:34712.8 VIRTUAL-SKIN-SPEAKER-SUB-2:38051.7 battery:38100 gnss_tcxo_therm:38383 quiet_therm:37293 soc_therm:38072 usb_conn_therm:36914
09-15 13:16:13.176 I/pixel-thermal( 1850): VIRTUAL-SKIN-CHARGE-WLC:39.0788 raw data: VIRTUAL-SKIN-CHARGE-WLC:39078.8 charger_therm:42052 modem_therm:40209 rffe_therm:37070 soc_therm:38072
09-15 13:16:13.176 I/pixel-thermal( 1850): VIRTUAL-SKIN-CHARGE-WLC power_budget=309.985 err=-1.07884 s_power=1400 time_elapsed_ms=7011 p=-647.305 i=-400 d=-0 dt_per_min=nan compensation=0 budget transient=0 control target=2 excluded power budget=42.7095 (PARTIAL_SYSTEM_POWER: 854.19 mW, cdev_weight: 0.050000)
09-15 13:16:14.236 I/WifiHAL ( 1020): Creating message to get link statistics; iface = 47
09-15 13:16:14.321 I/WifiHAL ( 1020): Getting cached scan results, iface handle = 0xb400007bb1428210
09-15 13:16:14.321 E/WifiHAL ( 1020): Creating message to get cached scan results
09-15 13:16:14.331 I/WifiHAL ( 1020): In GetCachedScanResultsCommand::handleResponse
09-15 13:16:14.370 D/WifiHAL ( 1020): Start debug command: mType GET_FEATURE
09-15 13:16:14.370 I/WifiHAL ( 1020): CreateRequest mType = GET_FEATURE
09-15 13:16:14.370 D/WifiHAL ( 1020): In DebugCommand::handleResponse, mType:GET_FEATURE
09-15 13:16:14.370 D/WifiHAL ( 1020): len = 4, expected len = 4
09-15 13:16:14.373 I/HalDevMgr( 1457): bestIfaceCreationProposal is null, requestIface=STA, existingIface=[name=wlan0 type=STA]
09-15 13:16:15.297 W/BluetoothRemoteDevices(17532): Address type mismatch for XX:XX:XX:XX:DB:74, new type: 1
09-15 13:16:15.305 I/3.g$n (17445): subscribeForNotification: 850bf51a-923d-11ed-a1eb-0242ac120006 011b00000000000000000000000000000000000000000024250e0008ffffffffffffffffffffffff00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
09-15 13:16:15.306 I/NearbyDiscovery(12966): (REDACTED) BloomFilterAdvManager: Detected bloom filter but too far away, ignoring. %sm, %s
09-15 13:16:15.310 E/886.j (17445): TimeOut Canceled
09-15 13:16:15.312 E/5.i (17445): STH7: Response deserializeOtaPacketData opCode - 27 -> data - 011b00000000000000000000000000000000000000000024250e0008ffffffffffffffffffffffff00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
09-15 13:16:15.312 E/2.j$f (17445): TimeOut Started
09-15 13:16:15.314 E/6.i (17445): OTA Value: 0x1B
09-15 13:16:15.314 D/OTA (17445): Value: 0x0D
09-15 13:16:15.315 E/5.i (17445): STH7: Response deserializeOtaPacketData opCode - 27 -> data - 011b00000000000000000000000000000000000000000024250e0008ffffffffffffffffffffffff00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
09-15 13:16:15.316 E/6.i (17445): OTA Value: 0x1B
09-15 13:16:15.317 D/OTA (17445): Value: 0x0D
09-15 13:16:15.320 E/5.i (17445): STH7: Response deserializeOtaPacketData opCode - 27 -> data - 011b00000000000000000000000000000000000000000024250e0008ffffffffffffffffffffffff00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
09-15 13:16:15.322 E/6.i (17445): OTA Value: 0x1B
09-15 13:16:15.322 D/OTA (17445): Value: 0x0D
09-15 13:16:15.323 E/8.j (17445): Nrf5340ClientDevice Voice Notification: [B@6546e10
09-15 13:16:15.324 E/5.i (17445): STH7: Response deserializeOtaPacketData opCode - 27 -> data - 011b00000000000000000000000000000000000000000024250e0008ffffffffffffffffffffffff00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
09-15 13:16:15.325 E/6.i (17445): OTA Value: 0x1B
09-15 13:16:15.325 D/OTA (17445): Value: 0x0D
09-15 13:16:15.326 E/1000.i (17445): STH7: Response (AUDIO_STORED_IN_FLASH, [B@bdbed09)
09-15 13:16:15.327 I/7.g$b (17445): Write: to 850bf51a-923d-11ed-a1eb-0242ac120006 -> (4)00000000
09-15 13:16:15.327 E/655.j (17445): Nrf5340ClientDevice StackState: VoiceCompleted
09-15 13:16:15.328 E/2.a$a0 (17445): sTH7V2OTAUpdateEngine: VoiceCompleted
09-15 13:16:15.329 D/OTA (17445): Serializing DFUAppOtaPacket:
09-15 13:16:15.329 D/OTA (17445): - Packet Type: OTA_INFO
09-15 13:16:15.329 D/OTA (17445): - Control Request: VOICE_PROMPT_FIX
09-15 13:16:15.329 D/OTA (17445): - NRF Mac Address: null
09-15 13:16:15.329 D/OTA (17445): - Application Address: null
09-15 13:16:15.329 D/OTA (17445): - Application Size: null
09-15 13:16:15.329 D/OTA (17445): - OTA Packet: null
09-15 13:16:15.329 D/OTA (17445): - OTA Subset Index: 0
09-15 13:16:15.329 D/OTA (17445): - OTA Packet Size: null
09-15 13:16:15.329 D/OTA (17445): - Last Chunk: null
09-15 13:16:15.329 D/OTA (17445):
09-15 13:16:15.329 E/68.e (17445): startOta false
09-15 13:16:15.329 D/OTA (17445): Calculated length for byte buffer: 5
09-15 13:16:15.329 D/OTA (17445): Packet Type is OTA_INFO, adding prefix 0x0F to buffer
09-15 13:16:15.329 D/OTA (17445): Added OTA Subset Index: 0
09-15 13:16:15.329 D/OTA (17445): Added Packet Type Value: 1
09-15 13:16:15.330 D/OTA (17445): Added Control Request Value: 12
09-15 13:16:15.330 E/OTA (17445): Serialized OTA DATA: 0f00010c00
09-15 13:16:15.330 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:15.335 I/7.g$b (17445): Write: to 850bf51a-923d-11ed-a1eb-0242ac120006 -> (5)0f00010c00
09-15 13:16:15.337 E/1.e$a (17445): onUpgradeStarted
09-15 13:16:15.338 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:15.340 D/BluetoothGatt(17445): BluetoothGatt() UUID=06f362ae-97f9-402d-a1a2-b64de83fd74a
09-15 13:16:15.343 I/stack_app(17532): system/stack/gatt/stack_app.cc:87 appRegister: Allocated name:jp.sygnhouse.bflex.dev uuid:2259f6c4-b1fa-cc3e-7411-ac0be3f71a57 gatt_if:84 eatt_support:false
09-15 13:16:15.343 I/stack_app(17532): system/stack/gatt/stack_app.cc:203 appStartIf: GATT interface 84 already has connected device xx:xx:xx:xx:3b:ea
09-15 13:16:15.343 I/stack_app(17532): system/stack/gatt/stack_app.cc:206 appStartIf: Invoking callback with connection id 84
09-15 13:16:15.343 I/stack_app(17532): system/stack/gatt/stack_app.cc:203 appStartIf: GATT interface 84 already has connected device xx:xx:xx:xx:46:e1
09-15 13:16:15.343 I/stack_app(17532): system/stack/gatt/stack_app.cc:206 appStartIf: Invoking callback with connection id 340
09-15 13:16:15.343 D/BluetoothGatt(17445): onClientRegistered(0)
09-15 13:16:15.346 I/bt_btif_gattc(17532): system/btif/src/btif_gatt_client.cc:339 btif_gattc_open_impl: Transport=BT_TRANSPORT_LE, device type=BLE, address=xx:xx:xx:xx:46:e1, address type=1, auto_mtu_enabled=false
09-15 13:16:15.346 I/bluetooth(17532): system/stack/gatt/gatt_main.cc:256 gatt_update_app_hold_link_status: added gatt_if=84
09-15 13:16:15.347 I/bluetooth(17532): system/stack/gatt/gatt_main.cc:330 gatt_update_app_use_link_flag: check_acl_link is false, no need to check
09-15 13:16:15.350 D/BluetoothGatt(17445): onClientConnectionState() - status=0 connected=true device=XX:XX:XX:XX:46:E1
09-15 13:16:15.351 D/BluetoothGatt(17445): onConfigureMTU(XX:XX:XX:XX:46:E1, 247, 0)
09-15 13:16:15.440 I/NearbyDiscovery(12966): (REDACTED) [trigger-id=ScanD3EC38FC] FastPairCache: Bloom filter changed, %s, newData=%s, oldData=%s, scanMode=%s
09-15 13:16:15.443 I/NearbyDiscovery(12966): (REDACTED) BloomFilterAdvManager: Detected bloom filter but too far away, ignoring. %sm, %s
09-15 13:16:15.653 D/BluetoothGatt(17445): discoverServices() - device: XX:XX:XX:XX:46:E1
09-15 13:16:15.660 I/bt_bta_gattc(17532): system/bta/gatt/bta_gattc_cache.cc:914 bta_gattc_get_gatt_db:
09-15 13:16:15.667 D/BluetoothGatt(17445): onSearchComplete(XX:XX:XX:XX:46:E1, _, 0)
09-15 13:16:15.672 D/BluetoothGatt(17445): configureMTU() - device: XX:XX:XX:XX:46:E1 mtu: 498
09-15 13:16:15.676 I/gatt_api(17532): system/stack/gatt/gatt_api.cc:837 GATTC_TryMtuRequest: xx:xx:xx:xx:46:e1 conn_id=0x0154
09-15 13:16:15.676 I/gatt_api(17532): system/stack/gatt/gatt_api.cc:885 GATTC_UpdateUserAttMtuIfNeeded: xx:xx:xx:xx:46:e1, mtu=498
09-15 13:16:15.676 I/gatt_api(17532): system/stack/gatt/gatt_api.cc:892 GATTC_UpdateUserAttMtuIfNeeded: xx:xx:xx:xx:46:e1, current mtu: 247, max_user_mtu:247, user_mtu: 498
09-15 13:16:15.676 I/gatt_api(17532): system/stack/gatt/gatt_api.cc:896 GATTC_UpdateUserAttMtuIfNeeded: User requested more than what GATT can handle. Trim it.
09-15 13:16:15.677 D/BluetoothGatt(17445): onConfigureMTU(XX:XX:XX:XX:46:E1, 247, 0)
09-15 13:16:15.678 D/BluetoothGatt(17445): setCharacteristicNotification() - uuid: da2e7828-fbce-4e01-ae9e-261174997c48 enable: true
09-15 13:16:15.681 I/gatt_offload(17532): system/stack/gatt/gatt_offload.cc:192 gattc_inform_notification_handle: remote_bda: xx:xx:xx:xx:46:e1, handle: 0x16
09-15 13:16:15.788 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:15.895 D/ActivityManager( 1457): freezing 12979 com.google.android.gms
09-15 13:16:15.908 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.106 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.140 I/eRIDEGRID(17445): exec: Disconnect
09-15 13:16:16.193 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.276 E/gatt_subrate_mgr(17532): system/stack/gatt/gatt_subrate_manager.cc:436 gatt_handle_conn_parameter_cback_status: xx:xx:xx:xx:46:e1 does not exist in gatt_cb.subrate_info
09-15 13:16:16.276 I/bluetooth(17532): system/bta/le_audio/client.cc:7065 le_audio_gattc_callback: event = BTA_GATTC_CONN_UPDATE_EVT
09-15 13:16:16.276 I/bluetooth(17532): system/bta/vcp/vcp_controller.cc:1661 gattc_callback: event = 26
09-15 13:16:16.276 E/bluetooth-asha(17532): system/bta/hearing_aid/hearing_aid.cc:626 OnConnectionUpdateComplete: unknown device: conn_id=0x131
09-15 13:16:16.276 I/bluetooth(17532): system/bta/csis/csis_client.cc:2049 GattcCallback: event = 0x1a
09-15 13:16:16.277 D/BluetoothGatt(17445): onConnectionUpdated() - device=XX:XX:XX:XX:46:E1 interval=9 latency=0 timeout=42 status=0
09-15 13:16:16.278 D/BluetoothGatt(17445): onConnectionUpdated() - device=XX:XX:XX:XX:46:E1 interval=9 latency=0 timeout=42 status=0
09-15 13:16:16.319 E/14.e$a (17445): onStateChanged VALIDATE UPLOAD
09-15 13:16:16.331 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.335 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.338 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.341 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.345 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.348 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.351 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.355 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.358 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.361 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.364 W/bt_osi_alarm(17532): system/osi/src/alarm.cc:244 alarm_cancel: alarm is null
09-15 13:16:16.434 I/bthal.activity( 949): bt_power: LeAdvStat: 13:16:15:288 - 13:16:16:434, duration: 1145, le_adv_count: 5, total_le_adv_count: 2460, total_event_count: 16
09-15 13:16:16.437 D/BoundBrokerSvc(12966): onUnbind: Intent { act=com.google.android.gms.findmydevice.spot.service.locationreport.START dat=chimera-action:/... xflg=0x4 cmp=com.google.android.gms/.chimera.PersistentApiService }
09-15 13:16:16.600 W/bthal.bqr( 949): ParseLinkQualityRelatedEvt: Generic ParametersV7: Appro LSTO , Handle: 0x0042, 1M_PHY, Central, PwLv: 10, RSSI: -47, SNR: 0, UnusedCh: 22, UnidealCh: 0, ReTx: 362, NoRX: 82, NAK: 5182, FlowOff: 0, OverFlow: 0, UndFlow: 0, failedCount: 0, TxTotal: 5621, TxUnAcked: 0, TxFlushed: 0, TxLastSubEvent: 0, CRCError: 0, RxDuplicate: 0, RxUnreceived: 0, coex_info_mask: 8
09-15 13:16:16.600 W/bthal.bqr( 949): ParseLinkQualityRelatedEvt: Vendor Parameters: Appro LSTO , Handle: 0x0042, RSSI_C0: -47, RSSI_C1: -127, TxPw_C0: 10, ReTxPw_C0: 10, TxPw_C1: -128, ReTxPw_C1: -128, BFTx: 0x01, BFReTx: 0x01, DivTx: 0x01, DivReTx: 0x01, Overall_link_quality: 0, Tx_link_quality: 0, Rx_link_quality: 0, TotalTx_pkts: 0, TotalTx_pkts_c0: 0, TotalTx_pkts_c1: 0, TotalTx_pkts_epa: 0, TotalTx_pkts_beamforming: 0, agc_gain_c0: 0, agc_gain_c1: 0, digi_agc_gain_c0: 0, digi_agc_gain_c1: 0
09-15 13:16:16.601 I/bthal.flowcontrol( 949): HciEventPreProcess: HCI Event 0xff Opcode 0 Length 248 unhandled by debug_VendorEvent
09-15 13:16:16.602 I/bthal.bqr( 949): ParseAdvanceRFStatsEvt: Advance RF Stats: Time Period:96652 ms, Extension id: 2, TW_Pw_iPA_BF: 0, TW_Pw_ePA_BF: 0, TW_Pw_iPA_Div: 0, TW_Pw_ePA_Div: 0, RSSI_Chain_>-50: 8069, RSSI_Chain_-50_-55: 770, RSSI_Chain_-55_-60: 1675, RSSI_Chain_-60_-65: 382, RSSI_Chain_-65_-70: 844, RSSI_Chain_-70_-75: 1034, RSSI_Chain_-75_-80: 1015, RSSI_Chain_-80_-85: 1251, RSSI_Chain_-85_-90: 1334, RSSI_Chain_<-90: 1492, RSSI_Delta_<2: 0, RSSI_Delta_2_5: 0, RSSI_Delta_5_8: 0, RSSI_Delta_8_11: 0, RSSI_Delta_>11: 9542, Ant_Switch_Count: 2, Re_Tx_iPA_BF: 0, Re_Tx_ePA_BF: 0, Re_Tx_iPA_Div: 0, Re_Tx_ePA_Div: 0, Ch_Cnt_good: 47, Ch_Cnt_OK: 19, Ch_Cnt_Bad: 13, Ch_Cnt_Verybad: 0, TX_Buf_Que_Cnt: ACL_1:0 ACL_2:0 Le_1:0 Le_2:0 isoc_1:0 isoc_2:0 BIS:0 RSVD:0
09-15 13:16:16.603 I/bthal.flowcontrol( 949): HciEventPreProcess: HCI Event 0xff Opcode 0 Length 113 unhandled by debug_VendorEvent
09-15 13:16:16.604 I/bluetooth(17532): system/btif/src/btif_bqr.cc:1064 bqr_delivery_event: len: 245, addr: xx:xx:xx:xx:46:e1, lmp_ver: 13, manufacturer_id: 89, lmp_subver: 8591
09-15 13:16:16.604 I/BluetoothQualityReportJni(17532): android/app/jni/com_android_bluetooth_BluetoothQualityReport.cpp:52 bqr_delivery_callback:
09-15 13:16:16.605 W/btm_acl (17532): system/stack/acl/btm_acl.cc:1376 BTM_ReadRemoteVersion: Unable to find active acl
09-15 13:16:16.605 I/bluetooth(17532): system/btif/src/btif_bqr.cc:1064 bqr_delivery_event: len: 110, addr: ff:ff:ff:ff:ff:ff, lmp_ver: 0, manufacturer_id: 0, lmp_subver: 0
09-15 13:16:16.612 I/BluetoothQualityReportNativeCallback(17532): BQR: {
09-15 13:16:16.612 I/BluetoothQualityReportNativeCallback(17532): mAddr: CE:D8:C2:A1:46:E1, mLmpVer: 0x0D, mLmpSubVer: 0x218F, mManufacturerId: 0x0059, mName: RIDEGRID_V2, mBluetoothClass: 1f00,
09-15 13:16:16.612 I/BluetoothQualityReportNativeCallback(17532): BqrCommon: {
09-15 13:16:16.612 I/BluetoothQualityReportNativeCallback(17532): mQualityReportId: Approaching LSTO(0x02), mPacketType: INVALID(0x52), mConnectionHandle: 0x0042, mConnectionRole: 0(0), mTxPowerLevel: 10, mRssi: -47, mSnr: 0, mUnusedAfhChannelCount: 22,
09-15 13:16:16.612 I/BluetoothQualityReportNativeCallback(17532): mAfhSelectUnidealChannelCount: 0, mLsto: 672, mPiconetClock: 0x00000727, mRetransmissionCount: 362, mNoRxCount: 82, mNakCount: 5182, mLastTxAckTimestamp: 0x00000713, mFlowOffCount: 0,
09-15 13:16:16.612 I/BluetoothQualityReportNativeCallback(17532): mLastFlowOnTimestamp: 0x00000713, mOverflowCount: 0, mUnderflowCount: 0, mAddr: CE:D8:C2:A1:46:E1, mCalFailedItemCount: 0,
09-15 13:16:16.612 I/BluetoothQualityReportNativeCallback(17532): mTxTotalPackets: 5621, mTxUnackPackets: 0, mTxFlushPackets: 0, mTxLastSubeventPackets: 0, mCrcErrorPackets: 0, mRxDupPackets: 0, mRxUnRecvPackets: 0, mCoexInfoMask: 8
09-15 13:16:16.612 I/BluetoothQualityReportNativeCallback(17532): }
09-15 13:16:16.612 I/BluetoothQualityReportNativeCallback(17532): BqrVsLsto: {
09-15 13:16:16.612 I/BluetoothQualityReportNativeCallback(17532): mConnState: INVALID(0xA0), mBasebandStats: 0x2F00003C, mSlotsUsed: 91, mCxmDenials: 0, mTxSkipped: 18688, mRfLoss: 9049, mNativeClock: 0x00000000, mLastTxAckTimestamp: 0x00000000
09-15 13:16:16.612 I/BluetoothQualityReportNativeCallback(17532): }
09-15 13:16:16.612 I/BluetoothQualityReportNativeCallback(17532): }
09-15 13:16:16.612 I/BluetoothQualityReportJni(17532): android/app/jni/com_android_bluetooth_BluetoothQualityReport.cpp:52 bqr_delivery_callback:
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): BQR: {
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): mAddr: FF:FF:FF:FF:FF:FF, mLmpVer: 0x00, mLmpSubVer: 0x0000, mManufacturerId: 0x0000, mName: , mBluetoothClass: 0,
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): BqrCommon: {
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): mQualityReportId: RF Stats(0x09), mPacketType: INVALID(0x00), mConnectionHandle: 0x0000, mConnectionRole: 0(0), mTxPowerLevel: 0, mRssi: 0, mSnr: 0, mUnusedAfhChannelCount: 0,
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): mAfhSelectUnidealChannelCount: 0, mLsto: 0, mPiconetClock: 0x00000000, mRetransmissionCount: 0, mNoRxCount: 0, mNakCount: 0, mLastTxAckTimestamp: 0x00000000, mFlowOffCount: 0,
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): mLastFlowOnTimestamp: 0x00000000, mOverflowCount: 0, mUnderflowCount: 0, mAddr: null, mCalFailedItemCount: 0,
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): mTxTotalPackets: 0, mTxUnackPackets: 0, mTxFlushPackets: 0, mTxLastSubeventPackets: 0, mCrcErrorPackets: 0, mRxDupPackets: 0, mRxUnRecvPackets: 0, mCoexInfoMask: 0
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): }
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): BqrRfStats: {
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): mExtensionInfo: 2, mReportTimePeriod: 96652, mTxPoweriPaBf: 0, mTxPowerePaBf: 0, mTxPoweriPaDiv: 0, mTxPowerePaDiv: 0,
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): mRssiChainOver50: 8069, mRssiChain50To55: 770, mRssiChain55To60: 1675, mRssiChain60To65: 382, mRssiChain65To70: 844, mRssiChain70To75: 1034, mRssiChain75To80: 1015, mRssiChain80To85: 1251, mRssiChain85To90: 1334, mRssiChainUnder90: 1492,
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): mRssiDeltaUnder2: 0, mRssiDelta2To5: 0, mRssiDelta5To8: 0, mRssiDelta8To11: 0, mRssiDeltaOver11: 9542
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): }
09-15 13:16:16.613 I/BluetoothQualityReportNativeCallback(17532): }
09-15 13:16:16.801 W/bthal.bqr( 949): ParseLinkQualityRelatedEvt: Generic ParametersV7: Appro LSTO , Handle: 0x0042, 1M_PHY, Central, PwLv: 10, RSSI: -47, SNR: 0, UnusedCh: 22, UnidealCh: 0, ReTx: 17, NoRX: 17, NAK: 0, FlowOff: 0, OverFlow: 0, UndFlow: 0, failedCount: 0, TxTotal: 17, TxUnAcked: 0, TxFlushed: 0, TxLastSubEvent: 0, CRCError: 0, RxDuplicate: 0, RxUnreceived: 0, coex_info_mask: 8
09-15 13:16:16.801 W/bthal.bqr( 949): ParseLinkQualityRelatedEvt: Vendor Parameters: Appro LSTO , Handle: 0x0042, RSSI_C0: -47, RSSI_C1: -127, TxPw_C0: 10, ReTxPw_C0: 10, TxPw_C1: -128, ReTxPw_C1: -128, BFTx: 0x01, BFReTx: 0x01, DivTx: 0x01, DivReTx: 0x01, Overall_link_quality: 0, Tx_link_quality: 0, Rx_link_quality: 0, TotalTx_pkts: 0, TotalTx_pkts_c0: 0, TotalTx_pkts_c1: 0, TotalTx_pkts_epa: 0, TotalTx_pkts_beamforming: 0, agc_gain_c0: 0, agc_gain_c1: 0, digi_agc_gain_c0: 0, digi_agc_gain_c1: 0
09-15 13:16:16.801 I/bthal.flowcontrol( 949): HciEventPreProcess: HCI Event 0xff Opcode 0 Length 248 unhandled by debug_VendorEvent
09-15 13:16:16.804 I/bthal.activity( 949): DisConnectCompleteEvent, conn_handle:042, conn_bda: XX:XX:c2:a1:46:e1, conn_cnt: 2
09-15 13:16:16.805 I/bluetooth(17532): system/btif/src/btif_bqr.cc:1064 bqr_delivery_event: len: 245, addr: xx:xx:xx:xx:46:e1, lmp_ver: 13, manufacturer_id: 89, lmp_subver: 8591
09-15 13:16:16.806 I/bthal.bqr( 949): ParseAdvanceRFStatsEvt: Advance RF Stats: Time Period:201 ms, Extension id: 2, TW_Pw_iPA_BF: 0, TW_Pw_ePA_BF: 0, TW_Pw_iPA_Div: 0, TW_Pw_ePA_Div: 0, RSSI_Chain_>-50: 3, RSSI_Chain_-50_-55: 2, RSSI_Chain_-55_-60: 4, RSSI_Chain_-60_-65: 2, RSSI_Chain_-65_-70: 8, RSSI_Chain_-70_-75: 4, RSSI_Chain_-75_-80: 6, RSSI_Chain_-80_-85: 15, RSSI_Chain_-85_-90: 17, RSSI_Chain_<-90: 8, RSSI_Delta_<2: 0, RSSI_Delta_2_5: 0, RSSI_Delta_5_8: 0, RSSI_Delta_8_11: 0, RSSI_Delta_>11: 3, Ant_Switch_Count: 0, Re_Tx_iPA_BF: 0, Re_Tx_ePA_BF: 0, Re_Tx_iPA_Div: 0, Re_Tx_ePA_Div: 0, Ch_Cnt_good: 47, Ch_Cnt_OK: 19, Ch_Cnt_Bad: 13, Ch_Cnt_Verybad: 0, TX_Buf_Que_Cnt: ACL_1:0 ACL_2:0 Le_1:0 Le_2:0 isoc_1:0 isoc_2:0 BIS:0 RSVD:0
09-15 13:16:16.806 I/bthal.flowcontrol( 949): HciEventPreProcess: HCI Event 0xff Opcode 0 Length 113 unhandled by debug_VendorEvent
09-15 13:16:16.806 I/bluetooth(17532): system/gd/hci/acl_manager/round_robin_scheduler.cc:74 Unregister: unregistering acl_queue handle=66, sent_packets=4
09-15 13:16:16.806 I/bt_shim_hci(17532): system/main/shim/hci_layer.cc:323 operator(): ISO disconnection from GD, handle: 0x42, reason: CONNECTION_TIMEOUT(0x08)
09-15 13:16:16.807 I/BluetoothQualityReportJni(17532): android/app/jni/com_android_bluetooth_BluetoothQualityReport.cpp:52 bqr_delivery_callback:
09-15 13:16:16.808 I/bluetooth(17532): system/stack/arbiter/acl_arbiter.cc:51 OnLeDisconnect: Notifying Rust of LE disconnection
09-15 13:16:16.808 I/bluetooth(17532): system/stack/connection_manager/connection_manager.cc:500 on_connection_complete: Le connection completed to device:xx:xx:xx:xx:46:e1
09-15 13:16:16.808 I/gatt_offload(17532): system/stack/gatt/gatt_offload.cc:242 gatt_offload_clear_sessions_by_acl_handle: acl_connection_handle: 0x42
09-15 13:16:16.808 W/gatt_offload(17532): system/stack/gatt/gatt_offload.cc:687 try_sessions_by_acl_handle_to_unoffload: acl_connection_handle: 66 doesn't exist
09-15 13:16:16.808 I/bluetooth(17532): system/stack/eatt/eatt_impl.h:879 disconnect: Device: xx:xx:xx:xx:46:e1, cid: 0xffff
09-15 13:16:16.808 W/bluetooth(17532): system/stack/eatt/eatt_impl.h:883 disconnect: no eatt device found
09-15 13:16:16.808 I/stack_le_connection(17532): system/stack/gatt/stack_le_connection.cc:224 leConnectionUpdateSubrateConfig: gatt_if:84 addr:xx:xx:xx:xx:46:e1, subrate_mode:0
09-15 13:16:16.808 I/gatt_subrate_mgr(17532): system/stack/gatt/gatt_subrate_manager.cc:312 gatt_register_subrate_config: client_if:84 addr:xx:xx:xx:xx:46:e1, subrate_mode:0
09-15 13:16:16.808 E/gatt_subrate_mgr(17532): system/stack/gatt/gatt_subrate_manager.cc:323 gatt_register_subrate_config: xx:xx:xx:xx:46:e1 is disconnected which does not exist in gatt_cb.subrate_info
09-15 13:16:16.808 I/stack_le_connection(17532): system/stack/gatt/stack_le_connection.cc:224 leConnectionUpdateSubrateConfig: gatt_if:83 addr:xx:xx:xx:xx:46:e1, subrate_mode:0
09-15 13:16:16.808 I/gatt_subrate_mgr(17532): system/stack/gatt/gatt_subrate_manager.cc:312 gatt_register_subrate_config: client_if:83 addr:xx:xx:xx:xx:46:e1, subrate_mode:0
09-15 13:16:16.808 E/gatt_subrate_mgr(17532): system/stack/gatt/gatt_subrate_manager.cc:323 gatt_register_subrate_config: xx:xx:xx:xx:46:e1 is disconnected which does not exist in gatt_cb.subrate_info
09-15 13:16:16.808 I/bluetooth(17532): system/bta/ras/ras_server.cc:401 OnGattDisconnect: Address: xx:xx:xx:xx:46:e1, conn_id:301
09-15 13:16:16.808 I/bluetooth(17532): system/stack/gap/gap_ble.cc:323 client_connect_cback: No active GAP service found for peer:xx:xx:xx:xx:46:e1 callback:Disconnected
09-15 13:16:16.808 I/BluetoothQualityReportNativeCallback(17532): BQR: {
09-15 13:16:16.808 I/BluetoothQualityReportNativeCallback(17532): mAddr: CE:D8:C2:A1:46:E1, mLmpVer: 0x0D, mLmpSubVer: 0x218F, mManufacturerId: 0x0059, mName: RIDEGRID_V2, mBluetoothClass: 1f00,
09-15 13:16:16.808 I/BluetoothQualityReportNativeCallback(17532): BqrCommon: {
09-15 13:16:16.808 I/BluetoothQualityReportNativeCallback(17532): mQualityReportId: Approaching LSTO(0x02), mPacketType: INVALID(0x52), mConnectionHandle: 0x0042, mConnectionRole: 0(0), mTxPowerLevel: 10, mRssi: -47, mSnr: 0, mUnusedAfhChannelCount: 22,
09-15 13:16:16.808 I/BluetoothQualityReportNativeCallback(17532): mAfhSelectUnidealChannelCount: 0, mLsto: 672, mPiconetClock: 0x00000738, mRetransmissionCount: 17, mNoRxCount: 17, mNakCount: 0, mLastTxAckTimestamp: 0x00000713, mFlowOffCount: 0,
09-15 13:16:16.808 I/BluetoothQualityReportNativeCallback(17532): mLastFlowOnTimestamp: 0x00000713, mOverflowCount: 0, mUnderflowCount: 0, mAddr: CE:D8:C2:A1:46:E1, mCalFailedItemCount: 0,
09-15 13:16:16.808 I/BluetoothQualityReportNativeCallback(17532): mTxTotalPackets: 17, mTxUnackPackets: 0, mTxFlushPackets: 0, mTxLastSubeventPackets: 0, mCrcErrorPackets: 0, mRxDupPackets: 0, mRxUnRecvPackets: 0, mCoexInfoMask: 8
09-15 13:16:16.808 I/BluetoothQualityReportNativeCallback(17532): }
09-15 13:16:16.808 I/BluetoothQualityReportNativeCallback(17532): BqrVsLsto: {
09-15 13:16:16.808 I/BluetoothQualityReportNativeCallback(17532): mConnState: INVALID(0x56), mBasebandStats: 0x65000000, mSlotsUsed: 0, mCxmDenials: 0, mTxSkipped: 0, mRfLoss: 0, mNativeClock: 0x00000000, mLastTxAckTimestamp: 0x00000000
09-15 13:16:16.808 I/BluetoothQualityReportNativeCallback(17532): }
09-15 13:16:16.808 I/BluetoothQualityReportNativeCallback(17532): }
09-15 13:16:16.808 I/bluetooth(17532): system/stack/gatt/gatt_attr.cc:400 gatt_connect_cback: remove untrusted client status, bda=xx:xx:xx:xx:46:e1
09-15 13:16:16.808 I/gatt_subrate_mgr(17532): system/stack/gatt/gatt_subrate_manager.cc:304 gatt_release_subrate_cb: addr:xx:xx:xx:xx:46:e1
09-15 13:16:16.809 W/bt_btm_sec(17532): system/stack/btm/btm_sec.cc:3867 btm_sec_disconnected: Got uncommon disconnection reason:HCI_ERR_CONNECTION_TOUT handle:0x0042 comment:stack::acl::btm_acl::btm_acl_disconnected
09-15 13:16:16.809 W/bt_bta_dm_sec(17532): system/stack/btm/btm_sec.cc:4011 btm_sec_disconnected: Clearing security flags for unbonded device xx:xx:xx:xx:46:e1
09-15 13:16:16.809 W/btm_acl (17532): system/stack/acl/btm_acl.cc:1376 BTM_ReadRemoteVersion: Unable to find active acl
09-15 13:16:16.809 I/bluetooth(17532): system/btif/src/btif_bqr.cc:1064 bqr_delivery_event: len: 110, addr: ff:ff:ff:ff:ff:ff, lmp_ver: 0, manufacturer_id: 0, lmp_subver: 0
09-15 13:16:16.809 I/bt_bta_dm(17532): system/bta/dm/bta_dm_act.cc:769 bta_dm_acl_down: Device xx:xx:xx:xx:46:e1 disconnected over transport BT_TRANSPORT_LE
09-15 13:16:16.812 D/BluetoothGatt(17445): onClientConnectionState() - status=8 connected=false device=XX:XX:XX:XX:46:E1
09-15 13:16:16.812 D/BluetoothGatt(17445): unregisterApp()
09-15 13:16:16.818 I/BluetoothQualityReportJni(17532): android/app/jni/com_android_bluetooth_BluetoothQualityReport.cpp:52 bqr_delivery_callback:
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): BQR: {
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): mAddr: FF:FF:FF:FF:FF:FF, mLmpVer: 0x00, mLmpSubVer: 0x0000, mManufacturerId: 0x0000, mName: , mBluetoothClass: 0,
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): BqrCommon: {
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): mQualityReportId: RF Stats(0x09), mPacketType: INVALID(0x00), mConnectionHandle: 0x0000, mConnectionRole: 0(0), mTxPowerLevel: 0, mRssi: 0, mSnr: 0, mUnusedAfhChannelCount: 0,
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): mAfhSelectUnidealChannelCount: 0, mLsto: 0, mPiconetClock: 0x00000000, mRetransmissionCount: 0, mNoRxCount: 0, mNakCount: 0, mLastTxAckTimestamp: 0x00000000, mFlowOffCount: 0,
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): mLastFlowOnTimestamp: 0x00000000, mOverflowCount: 0, mUnderflowCount: 0, mAddr: null, mCalFailedItemCount: 0,
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): mTxTotalPackets: 0, mTxUnackPackets: 0, mTxFlushPackets: 0, mTxLastSubeventPackets: 0, mCrcErrorPackets: 0, mRxDupPackets: 0, mRxUnRecvPackets: 0, mCoexInfoMask: 0
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): }
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): BqrRfStats: {
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): mExtensionInfo: 2, mReportTimePeriod: 201, mTxPoweriPaBf: 0, mTxPowerePaBf: 0, mTxPoweriPaDiv: 0, mTxPowerePaDiv: 0,
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): mRssiChainOver50: 3, mRssiChain50To55: 2, mRssiChain55To60: 4, mRssiChain60To65: 2, mRssiChain65To70: 8, mRssiChain70To75: 4, mRssiChain75To80: 6, mRssiChain80To85: 15, mRssiChain85To90: 17, mRssiChainUnder90: 8,
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): mRssiDeltaUnder2: 0, mRssiDelta2To5: 0, mRssiDelta5To8: 0, mRssiDelta8To11: 0, mRssiDeltaOver11: 3
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): }
09-15 13:16:16.820 I/BluetoothQualityReportNativeCallback(17532): }
09-15 13:16:16.820 I/BluetoothRemoteDevices(17532): aclStateChangeCallback: LE Disconnected XX:XX:XX:XX:46:E1(Random ) reason: 8 adapter state: ON
09-15 13:16:16.821 D/BluetoothGatt(17445): close()
09-15 13:16:16.822 I/stack_app(17532): system/stack/gatt/stack_app.cc:121 appDeregister: gatt_if=84
09-15 13:16:16.822 W/bluetooth(17532): system/stack/gatt/gatt_main.cc:271 gatt_update_app_hold_link_status: attempt to remove non-existing gatt_if=84
09-15 13:16:16.823 I/bluetooth(17532): system/stack/gatt/gatt_main.cc:325 gatt_update_app_use_link_flag: App status is not updated for gatt_if=84
09-15 13:16:16.828 D/BluetoothGatt(17445): onClientConnectionState() - status=8 connected=false device=XX:XX:XX:XX:46:E1
09-15 13:16:16.828 D/BluetoothGatt(17445): unregisterApp()
09-15 13:16:16.829 I/BtGatt.GattServerManager(17532): onClientConnected(XX:XX:XX:XX:46:E1, LE, connected=false, connId=310, serverIf=54): Has no more bearers and is disconnected
09-15 13:16:16.830 I/BtGatt.GattServerManager(17532): onClientConnected(XX:XX:XX:XX:46:E1, LE, connected=false, connId=308, serverIf=52): Has no more bearers and is disconnected
09-15 13:16:16.832 E/8.e$a (17445): onUpgradeFailed UPLOAD null
09-15 13:16:16.832 I/BtGatt.GattServerManager(17532): onClientConnected(XX:XX:XX:XX:46:E1, LE, connected=false, connId=307, serverIf=51): Has no more bearers and is disconnected
09-15 13:16:16.834 I/stack_app(17532): system/stack/gatt/stack_app.cc:121 appDeregister: gatt_if=83
09-15 13:16:16.834 W/bluetooth(17532): system/stack/gatt/gatt_main.cc:271 gatt_update_app_hold_link_status: attempt to remove non-existing gatt_if=83
09-15 13:16:16.835 I/bluetooth(17532): system/stack/gatt/gatt_main.cc:325 gatt_update_app_use_link_flag: App status is not updated for gatt_if=83
09-15 13:16:16.835 E/2.a$c0 (17445): NRF5340OTAState: Failed(reason=1, stage=UPLOAD, detail=null)
09-15 13:16:16.835 I/2.g$g$a (17445): GATT: ConnectState: STATE_DISCONNECTED
09-15 13:16:16.836 E/1708.a (17445): TimeOut Canceled
09-15 13:16:16.836 D/BluetoothGatt(17445): close()
09-15 13:16:16.837 E/2.a$s (17445): TimeOut Started
09-15 13:16:16.838 D/OTA_STATE(17445): [6] STATE Failed (reason=1002 (UPLOAD))
09-15 13:16:16.840 D/186.FirmwareUpdateViewModel$observeGlobalState(17445): otaState: Failed(reason=1002 (UPLOAD))
09-15 13:16:16.841 E/203.FirmwareUpdateViewModel$observeGlobalState(17445): FirmwareUpdateViewModel: アップデート失敗 - 1002 (UPLOAD)
09-15 13:16:16.842 E/1025.MainGlobalViewModel(17445): MainGlobalViewModel: DFU失敗 - 1002 (UPLOAD)
09-15 13:16:16.845 D/CachedBluetoothDevice( 2212): onAclStateChanged: device XX:XX:XX:XX:46:E1, state 0, transport 2
09-15 13:16:16.845 D/CachedBluetoothDevice( 2212): onAclStateChanged: device XX:XX:XX:XX:46:E1, connect time is reset
09-15 13:16:16.854 D/ActivityManager( 1457): sync unfroze 6812 com.google.android.crossdeviceaccessservice for 3
09-15 13:16:16.857 D/ActivityManager( 1457): sync unfroze 5541 com.google.android.crossdeviceaccessservice:com.google.android.crossdeviceaccessservice for 10
09-15 13:16:16.860 I/CDAS-App( 6812): On Bluetooth broadcast, action=android.bluetooth.device.action.ACL_DISCONNECTED
09-15 13:16:16.861 D/ActivityManager( 1457): sync unfroze 12979 com.google.android.gms for 10
09-15 13:16:16.862 D/ActivityManager( 1457): sync unfroze 13673 com.google.android.gms.unstable for 10
09-15 13:16:16.863 D/ActivityManager( 1457): sync unfroze 17668 com.google.android.gms.ui for 10
09-15 13:16:16.866 D/ActivityManager( 1457): sync unfroze 20186 com.google.android.googlequicksearchbox:search for 10
09-15 13:16:16.868 D/ActivityManager( 1457): sync unfroze 16369 com.google.android.googlequicksearchbox:googleapp for 10
09-15 13:16:16.868 D/ActivityManager( 1457): sync unfroze 16503 com.google.android.webview:sandboxed_process0:org.chromium.content.app.SandboxedProcessService0:1 for 10
09-15 13:16:16.870 D/ActivityManager( 1457): sync unfroze 5366 com.google.android.projection.gearhead:shared for 3
09-15 13:16:16.871 D/ActivityManager( 1457): sync unfroze 6292 com.google.android.projection.gearhead:car for 10
09-15 13:16:16.871 I/admw ( 3592): onReceive
09-15 13:16:16.871 D/ActivityManager( 1457): sync unfroze 12623 com.google.android.projection.gearhead:projection for 10
09-15 13:16:16.872 D/ActivityManager( 1457): sync unfroze 5380 com.google.android.projection.gearhead:provider for 10
09-15 13:16:16.873 I/ffhm ( 3592): (REDACTED) HDM. appOpsListener %s %s
09-15 13:16:16.873 I/ffhm ( 3592): (REDACTED) HDM. Ignoring irrelevant audio permission changes for package %s
09-15 13:16:16.874 W/hwc-libdisplaycolor( 533): GetRrRegammaForRange: no match found (op_hz, hz, dbv, range_id)=(60,60,647,9)
09-15 13:16:16.887 I/afex ( 3592): (REDACTED) bluetoothConnectionStateChanged. Action: %s
09-15 13:16:16.889 I/CDAS-LockOnDisconnect( 6812): TriggerFeatureUseCaseImpl: intent: Intent { act=android.bluetooth.device.action.ACL_DISCONNECTED flg=0x5000010 xflg=0x4 cmp=com.google.android.crossdeviceaccessservice/.primary.core.intent.bluetooth.BluetoothBroadcastReceiver (has extras) }
09-15 13:16:16.890 I/CDAS-LockOnDisconnect( 6812): CheckPreconditionUseCaseImpl: bluetooth device is not bonded
09-15 13:16:16.890 I/CDAS-LockOnDisconnect( 6812): TriggerFeatureUseCaseImpl: checkPrecondition returned false
09-15 13:16:16.890 E/CDAS-LockOnDisconnect( 6812): ShowPromoNotificationUseCaseImpl: bluetoothDevice is not bonded
09-15 13:16:16.890 E/CDAS-LeftBehind( 6812): ShowPromoNotificationUseCaseImpl: bluetoothDevice is not bonded
09-15 13:16:16.898 W/CDAS-App( 6812): Failed to get local node ID
09-15 13:16:16.898 W/CDAS-App( 6812): com.google.android.gms.common.api.ApiException: 13: ERROR
09-15 13:16:16.898 W/CDAS-App( 6812): at com.google.android.gms.common.internal.ApiExceptionUtil.fromStatus(ApiExceptionUtil.java:3)
09-15 13:16:16.898 W/CDAS-App( 6812): at com.google.android.gms.common.api.internal.TaskUtil.setResultOrApiException(TaskUtil.java:6)
09-15 13:16:16.898 W/CDAS-App( 6812): at com.google.android.gms.wearable.internal.zzoh.zzE(NodeClientImpl.java:2)
09-15 13:16:16.898 W/CDAS-App( 6812): at com.google.android.gms.wearable.internal.zzmc.dispatchTransaction(IWearableCallbacks.java:36)
09-15 13:16:16.898 W/CDAS-App( 6812): at com.google.android.gms.internal.zzbnk.onTransact(BaseStub.java:3)
09-15 13:16:16.898 W/CDAS-App( 6812): at android.os.Binder.execTransactInternal(Binder.java:1369)
09-15 13:16:16.898 W/CDAS-App( 6812): at android.os.Binder.execTransact(Binder.java:1323)
09-15 13:16:16.898 I/CDAS-App( 6812): UpdateConnectionStateUseCase: nodeId is null
09-15 13:16:16.904 I/ActiveUnlock(12966): (REDACTED) BluetoothDevice %s connection state changed: %s, transport: %d, hashcode: %s
09-15 13:16:16.907 W/hwc-libdisplaycolor( 533): GetRrRegammaForRange: no match found (op_hz, hz, dbv, range_id)=(60,60,647,9)
09-15 13:16:16.914 D/OTA_META(17445): [2] DATA_CLEARED firmware update state cleared from storage
09-15 13:16:16.923 I/Nearby (12966): (REDACTED) is blocked device type %s, isAuto=%s, isIot=%s, isLatchsky=%s, isChinaWearable=%s, isTv=%s, isWearable=%s (supportWearOs=%s), isChromeOsDevice=%s (supportChromeOs=%s)
09-15 13:16:16.924 I/NearbyDiscovery(12966): (REDACTED) DiscoveryService onStartCommand action: %s
09-15 13:16:16.924 I/NearbyDiscovery(12966): (REDACTED) onAclChange: state=%s, transport=%s, %s
09-15 13:16:16.926 E/OTA_REGRESSION(17445): cycle 3: the nRF/Realtek engine reported an error of its own; silence 1.5s; 1 unanswered write(s) — battery 48% (113s old) — trace /storage/emulated/0/Android/data/jp.sygnhouse.bflex.dev/files/ota_regression/trace_cycle3_20260915-131616.csv
09-15 13:16:16.927 I/OTA_REGRESSION(17445): cycle 3 [nrf_7_debug.bin no version change]: FAILED at nRF netcore 25% (1002 (UPLOAD)) in 180215ms
09-15 13:16:16.927 D/301.MainGlobalViewModel(17445): MainGlobalViewModel: OTAリグレッション実行中 = true
09-15 13:16:16.927 I/OTA_REGRESSION(17445): waiting for a device in normal mode with metadata
09-15 13:16:17.348 W/ProcessStats( 1457): Tracking association SourceState{11db00c com.google.pixel.camera.services/1000 Persist #26957} whose proc state 0 is better than process ProcessState{b4ad051 com.google.android.apps.camera.services/10164 pkg=com.google.android.apps.camera.services} proc state 14 (16 skipped)
09-15 13:16:17.366 W/GattTransaction( 5697): [[FitbitBluetoothDevice Address: CE:D8:C2:A1:46:E1, Name: RIDEGRID_V2, Rssi: null, Advertising Data: null, Device Origin: CONNECTED]] The transaction conditions are not met
09-15 13:16:17.371 I/bthal.activity( 949): bt_power: AclDataStat: 13:16:15:294 - 13:16:17:365, conn_handle: 66, duration: 2071, acl_data_count: 28, acl_tx_data_count: 19, acl_rx_data_count: 9, total_acl_data_count: 22944
09-15 13:16:17.376 I/WifiHAL ( 1020): Creating message to get link statistics; iface = 47
09-15 13:16:17.440 I/WifiHAL ( 1020): Getting cached scan results, iface handle = 0xb400007bb1428210
09-15 13:16:17.440 E/WifiHAL ( 1020): Creating message to get cached scan results
09-15 13:16:17.448 I/WifiHAL ( 1020): In GetCachedScanResultsCommand::handleResponse
09-15 13:16:17.495 D/WifiHAL ( 1020): Start debug command: mType GET_FEATURE
09-15 13:16:17.496 I/WifiHAL ( 1020): CreateRequest mType = GET_FEATURE
09-15 13:16:17.496 D/WifiHAL ( 1020): In DebugCommand::handleResponse, mType:GET_FEATURE
09-15 13:16:17.496 D/WifiHAL ( 1020): len = 4, expected len = 4
09-15 13:16:17.500 I/HalDevMgr( 1457): bestIfaceCreationProposal is null, requestIface=STA, existingIface=[name=wlan0 type=STA]
09-15 13:16:17.677 I/pixel-thermal( 1850): VIRTUAL-SKIN:37.8095 raw data: VIRTUAL-SKIN:37809.5 VIRTUAL-SKIN-SUB-1:37809.5 VIRTUAL-SKIN-SUB-2:34536.2 VIRTUAL-SKIN-SUB-3:36750.6 charger_therm:41639 gnss_tcxo_therm:38294 modem_therm:40008 quiet_therm:37359 rffe_therm:37025 soc_therm:37983 usb_conn_therm:36914
09-15 13:16:17.677 I/pixel-thermal( 1850): soc_therm:37.983 raw data: soc_therm:37983
09-15 13:16:17.677 I/pixel-thermal( 1850): VIRTUAL-SKIN-HINT:37.8095 raw data: VIRTUAL-SKIN:37809.5 VIRTUAL-SKIN-HINT:37809.5
09-15 13:16:17.677 I/pixel-thermal( 1850): VIRTUAL-SKIN-CPU-MID:37.8095 raw data: VIRTUAL-SKIN:37809.5 VIRTUAL-SKIN-CPU-MID:37809.5
09-15 13:16:17.678 I/pixel-thermal( 1850): VIRTUAL-SKIN-CPU-HIGH:37.8095 raw data: VIRTUAL-SKIN:37809.5 VIRTUAL-SKIN-CPU-HIGH:37809.5
09-15 13:16:17.678 I/pixel-thermal( 1850): VIRTUAL-SKIN-SOC:37.8095 raw data: VIRTUAL-SKIN:37809.5 VIRTUAL-SKIN-SOC:37809.5
09-15 13:16:17.678 I/pixel-thermal( 1850): VIRTUAL-SKIN-SOC power_budget=3782.26 err=7.19045 s_power=800 time_elapsed_ms=7015 p=2157.14 i=825.12 d=0 dt_per_min=nan compensation=0 budget transient=0 control target=3 excluded power budget=0
09-15 13:16:17.678 I/pixel-thermal( 1850): VIRTUAL-SKIN-SOC binded power rails: (S4M_VDD_CPUCL0: 87.15 mW)(S2M_VDD_CPUCL2: 14.79 mW)(S3M_VDD_CPUCL1: 21.56 mW)(S2S_VDD_G3D: 2.02 mW)(S7M_VDD_TPU: 0.00 mW)
09-15 13:16:17.678 I/pixel-thermal( 1850): cellular-emergency:37.8095 raw data: VIRTUAL-SKIN:37809.5 cellular-emergency:37809.5
09-15 13:16:17.678 I/pixel-thermal( 1850): VIRTUAL-SKIN-CPU-LIGHT-ODPM:37.8095 raw data: VIRTUAL-SKIN:37809.5 VIRTUAL-SKIN-CPU-LIGHT-ODPM:37809.5
09-15 13:16:17.679 I/pixel-thermal( 1850): VIRTUAL-SKIN-CPU-LIGHT-ODPM power_budget=1366.9 err=1.19045 s_power=800 time_elapsed_ms=7015 p=476.181 i=90.7152 d=0 dt_per_min=nan compensation=0 budget transient=0 control target=2 excluded power budget=0
09-15 13:16:17.679 I/pixel-thermal( 1850): VIRTUAL-SKIN-CPU-LIGHT-ODPM binded power rails: (S4M_VDD_CPUCL0: 87.15 mW)(S2M_VDD_CPUCL2: 14.79 mW)(S3M_VDD_CPUCL1: 21.56 mW)
09-15 13:16:17.679 I/pixel-thermal( 1850): VIRTUAL-SKIN-GPU:37.8095 raw data: VIRTUAL-SKIN:37809.5 VIRTUAL-SKIN-GPU:37809.5
09-15 13:16:17.739 I/bthal.activity( 949): bt_power: LeAdvStat: 13:16:16:738 - 13:16:17:738, duration: 1000, le_adv_count: 1, total_le_adv_count: 2461, total_event_count: 23
09-15 13:16:17.926 I/ffhm ( 3592): (REDACTED) HDM. appOpsListener %s %s
09-15 13:16:17.927 I/ffhm ( 3592): (REDACTED) HDM. Ignoring irrelevant audio permission changes for package %s
What the app cannot do:
- Android has no API to set a supervision timeout. Only
requestConnectionPriority(), which sets interval/latency. - It cannot reject the headset's request. The stack auto-accepts below the app layer;
BluetoothGattCallbackhas noonConnectionUpdated, so the app cannot even observe the change.
Question for Nordic:
1. Inside mcumgr's Bluetooth SMP transport (smp_bt) or the image-upload path for a net-core update specifically, is there a known operation that can block for ~500 ms per upload chunk — e.g. an IPC round-trip to the network core, a flash-page erase gated on that IPC, or an internal semaphore wait — that would explain the peripheral going completely silent at the LL level (no notifications, no empty-PDU responses counted as "received" by the central) for that long?
2. Why does the transition into the net-core mcumgr phase request a Connection Parameter Update to a 420 ms supervision timeout at all, when the existing link (48.75 ms / 5 s) is already established and working earlier in the same session? Is this multiplier hardcoded somewhere in mcumgr's default connection handling for net-core uploads, or is it something our app-side integration is expected to override?
3. Is there a supported way to either (a) suppress/skip the parameter update at that phase transition so the link keeps its existing 48.75 ms/5 s parameters, or (b) configure mcumgr to request a longer, survivable timeout (e.g. Multiplier 400 / 4 s, matching what this same firmware already uses on its normal operating link) instead of 42?
