Bluetooth malfunctioning on m5_tab
Expected Behavior
Bluetooth devices are connected successfully.
Current Behavior
Unable to connect any bluetooth devices.
Steps to Reproduce
Open bluetooth settings, and try to pair a device.
Device information
/device m5_tab /version lineage-21 /date 2023-04-26 /kernel Linux version 4.9.337 #1 SMP PREEMPT Fri Apr 26 14:13:12 UTC 2024 /baseband - /mods -
I have read the directions.
Bluetooth Problem
The problem appeared since lineage-21.0-20240419-nightly-m5_tab and was NOT fixed in the more recent one.
Simply put, Bluetooth is able to discover devices, but unable to pair/connect to them successfully. I tried bugreport and dumpsys to capture some logs.
It is weird that the bluetooth service hasn't crashed, but reporting timeout. But I can successfully connect to the same device with the build 20240315, so I confirmed that the problem is neither at me, nor at the bluetooth mouse and anywhere of my firmware.
Here are logs from Bluetooth manager, I will highlight the critical lines. It seem to be successful at first, but somehow, due to a mysterious timeout error, it failed. I guess the problem may be somewhere of encryption as it says Security state changed.
Tip: the device in the log is xx:xx:xx:xx:e6:01 which is a bluetooth mouse. I also tried my wirless headphone but the problem is the same.
shim::legacy::btm 2024-04-26 01:45:01.078 API Create bond : xx:xx:xx:xx:e6:01 transport:BT_TRANSPORT_AUTO
shim::legacy::btm 2024-04-26 01:45:01.078 CBACK Bond state changed : xx:xx:xx:xx:e6:01 bt_status:success bond_state:1 reason:HCI_SUCCESS
shim::legacy::btm 2024-04-26 01:45:01.079 SEC Bonding initiated : xx:xx:xx:xx:e6:01 BT_TRANSPORT_LE
shim::legacy::btm 2024-04-26 01:45:01.079 ACL Allow connection from : xx:xx:xx:xx:e6:01[random] Le
shim::legacy::btm 2024-04-26 01:45:01.079 SEC Pairing state changed : xx:xx:xx:xx:e6:01 IDLE => WAIT_AUTH_COMPLETE
shim::legacy::btm 2024-04-26 01:45:01.113 ACL Connection successful : xx:xx:xx:xx:e6:01[random] Le
shim::legacy::btm 2024-04-26 01:45:01.346 SMP Security state changed : xx:xx:xx:xx:e6:01[public] SMP_STATE_IDLE => SMP_STATE_WAIT_APP_RSP
shim::legacy::btm 2024-04-26 01:45:01.346 SMP Security state changed : xx:xx:xx:xx:e6:01[public] SMP_STATE_WAIT_APP_RSP => SMP_STATE_PAIR_REQ_RSP
shim::legacy::btm 2024-04-26 01:45:31.346 SMP Security state changed : xx:xx:xx:xx:e6:01[public] SMP_STATE_PAIR_REQ_RSP => SMP_STATE_IDLE
shim::legacy::btm 2024-04-26 01:45:31.346 SMP Pairing failed : xx:xx:xx:xx:e6:01 reason:SMP_RSP_TIMEOUT
shim::legacy::btm 2024-04-26 01:45:31.347 CBACK Bond state changed : xx:xx:xx:xx:e6:01 bt_status:fail bond_state:0 reason:HCI_SUCCESS
shim::legacy::btm 2024-04-26 01:45:31.365 API Device discovery : 00:00:00:00:00:00 is_request_queued:F
shim::legacy::btm 2024-04-26 01:45:31.365 SCAN Classic inquiry started : 00:00:00:00:00:00
shim::legacy::btm 2024-04-26 01:45:31.365 SCAN Le legacy scan started : 00:00:00:00:00:00 Duplicates:disable
shim::legacy::btm 2024-04-26 01:45:31.365 SCAN Le inquiry started : 00:00:00:00:00:00
shim::legacy::btm 2024-04-26 01:45:31.451 ACL Disconnected : xx:xx:xx:xx:e6:01[random] Le reason:REMOTE_USER_TERMINATED_CONNECTION
shim::legacy::btm 2024-04-26 01:45:31.452 BOND Device removed : xx:xx:xx:xx:e6:01 device_type:BLE bond_type:BOND_TYPE_UNKNOWN
shim::legacy::btm 2024-04-26 01:45:31.452 ACL Ignore connection from : xx:xx:xx:xx:e6:01[random] Le
shim::legacy::btm 2024-04-26 01:45:31.456 API Get connection state : xx:xx:xx:xx:e6:01 connected:F classic_encrypted:F le_encrypted:F
Upside is the log from Bluetooth manager, but I also captured a bugreport, there was surely something out there, but I am not familiar with them.
04-26 01:43:38.868 1002 4593 4906 V BluetoothServiceJni: getMetricIdNative
04-26 01:43:38.870 1002 4593 4906 V BluetoothServiceJni: obfuscateAddressNative
04-26 01:43:38.870 1002 4593 4906 V BluetoothServiceJni: getMetricIdNative
04-26 01:43:38.879 1002 4593 4593 D A2dpService: Bond state changed for device: XX:XX:XX:XX:E6:01 state: 11
04-26 01:43:38.879 1002 4593 4593 D HearingAidService: Bond state changed for device: XX:XX:XX:XX:E6:01 state: 11
04-26 01:43:38.879 1002 4593 4900 D BluetoothDatabase: createMetadata: address=XX:XX:XX:XX:E6:01 isActiveHfpDevice=false isActiveA2dpDevice=false
04-26 01:43:38.879 1002 4593 4900 D BluetoothDatabase: updateDatabase XX:XX:XX:XX:E6:01
04-26 01:43:38.881 1002 4593 4906 D BluetoothCompanionManager: register metadata listener: XX:XX:XX:XX:E6:01
04-26 01:43:38.881 1002 4593 4906 D BluetoothAdapter: addOnMetadataChangedListener()
04-26 01:43:38.887 shell 10980 10980 E dumpstate: Failed to start dump thread for service: android.hardware.cas.IMediaCasService/default, status: -2
04-26 01:43:38.890 1002 4593 4906 I BluetoothBondStateMachine: Bond State Change Intent:XX:XX:XX:XX:E6:01 BOND_NONE => BOND_BONDING
04-26 01:43:38.903 root 3961 3961 E libperfmgr: Failed to read node path: /sys/class/mpgpu/mpgpucmd
04-26 01:43:38.925 wifi 3977 3999 I android.hardware.wifi-service: -----------Debug was called----------------
04-26 01:43:38.900 root 3961 3961 W android.hardwar: type=1400 audit(0.0:295): avc: denied { getattr } for path="/sys/class/mpgpu/mpgpucmd" dev="sysfs" ino=29663 scontext=u:r:hal_power_default:s0 tcontext=u:object_r:sysfs_mpgpu_cmd:s0 tclass=file permissive=0
04-26 01:43:38.951 1000 4648 5731 D CachedBluetoothDevice: anonymizedAddress=XX:XX:XX:XX:E6:01 mIsA2dpProfileConnectedFail=false mIsHearingAidProfileConnectedFail=false mIsLeAudioProfileConnectedFail=false mIsHeadsetProfileConnectedFail=false isConnectedSapDevice()=false
04-26 01:43:38.977 1000 4193 4237 E ResilientAtomicFile: Failed to verity-protect shortcut package item
04-26 01:43:38.977 1000 4193 4237 E ResilientAtomicFile: java.io.IOException: Failed to enable fs-verity on FD(402): Inappropriate ioctl for device
04-26 01:43:38.977 1000 4193 4237 E ResilientAtomicFile: at com.android.internal.security.VerityUtils.setUpFsverity(VerityUtils.java:94)
04-26 01:43:38.977 1000 4193 4237 E ResilientAtomicFile: at com.android.server.security.FileIntegrity.setUpFsVerity(FileIntegrity.java:66)
04-26 01:43:38.977 1000 4193 4237 E ResilientAtomicFile: at com.android.server.pm.ResilientAtomicFile.finishWrite(ResilientAtomicFile.java:151)
04-26 01:43:38.977 1000 4193 4237 E ResilientAtomicFile: at com.android.server.pm.ShortcutPackageItem.saveToFileLocked(ShortcutPackageItem.java:182)
04-26 01:43:38.977 1000 4193 4237 E ResilientAtomicFile: at com.android.server.pm.ShortcutPackageItem.saveShortcutPackageItem(ShortcutPackageItem.java:226)
04-26 01:43:38.977 1000 4193 4237 E ResilientAtomicFile: at com.android.server.pm.ShortcutPackageItemExternalSyntheticLambda0.run(R8SyntheticClass:0)
04-26 01:43:38.977 1000 4193 4237 E ResilientAtomicFile: at android.os.Handler.handleCallback(Handler.java:959)
04-26 01:43:38.977 1000 4193 4237 E ResilientAtomicFile: at android.os.Handler.dispatchMessage(Handler.java:100)
04-26 01:43:38.977 1000 4193 4237 E ResilientAtomicFile: at android.os.Looper.loopOnce(Looper.java:232)
04-26 01:43:38.977 1000 4193 4237 E ResilientAtomicFile: at android.os.Looper.loop(Looper.java:317)
04-26 01:43:38.977 1000 4193 4237 E ResilientAtomicFile: at android.os.HandlerThread.run(HandlerThread.java:68)
04-26 01:43:38.984 1002 4593 4752 I bluetooth: packages/modules/Bluetooth/system/gd/hci/le_address_manager.cc:266 - ack_pause: Client already in paused state
04-26 01:43:38.984 1002 4593 4746 I bluetooth: packages/modules/Bluetooth/system/stack/gatt/connection_manager.cc:432 - on_connection_complete: Le connection completed to device:xx:xx:xx:xx:e6:01
04-26 01:43:38.984 1002 4593 4746 I bluetooth: packages/modules/Bluetooth/system/stack/gatt/connection_manager.cc:432 - on_connection_complete: Le connection completed to device:xx:xx:xx:xx:e6:01
04-26 01:43:38.984 1002 4593 4746 I ble_sec : packages/modules/Bluetooth/system/stack/btm/btm_ble_sec.cc:1519 - btm_ble_connected: Update timestamp for ble connection:xx:xx:xx:xx:e6:01
04-26 01:43:38.985 1002 3940 4855 E rtk_parse: rtk_cmd_complete_cback, transmit_command Opcode:fc19
04-26 01:43:38.986 1000 4648 5731 D AdaptiveHomepageIcon: Setting background color -73784
04-26 01:43:38.987 1002 4593 4752 I bluetooth: packages/modules/Bluetooth/system/gd/hci/le_address_manager.cc:602 - OnCommandComplete: Received command complete with op_code LE_REMOVE_DEVICE_FROM_FILTER_ACCEPT_LIST
04-26 01:43:38.987 1002 4593 4752 I bluetooth: packages/modules/Bluetooth/system/gd/hci/le_address_manager.cc:295 - resume_registered_clients: Resuming registered clients
04-26 01:43:38.988 1002 4593 4746 E bt_btu_hcif: packages/modules/Bluetooth/system/stack/btu/btu_hcif.cc:1333 - btu_hcif_hdl_command_status: Command status for opcode:0x2016 should not be handled here status:HCI_SUCCESS.....30 Seconds Later, 4000 lines downside
04-26 01:44:09.234 1002 4593 4746 W smp : packages/modules/Bluetooth/system/stack/smp/smp_utils.cc:1013 - smp_proc_pairing_cmpl: Pairing process has failed to remote:xx:xx:xx:xx:e6:01 smp_reason:SMP_RSP_TIMEOUT sec_level:0x0
04-26 01:44:09.235 1002 4593 4746 I bt_bta_dm_sec: packages/modules/Bluetooth/system/bta/dm/bta_dm_sec.cc:632 - bta_dm_remove_sec_dev_entry: Setting remove_dev_pending for xx:xx:xx:xx:e6:01
04-26 01:44:09.235 1002 4593 4746 E bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:3518 - btif_dm_ble_auth_cmpl_evt: LE authentication for xx:xx:xx:xx:e6:01 failed with reason 99
04-26 01:44:09.235 1002 4593 4746 I bt_btif_storage: packages/modules/Bluetooth/system/btif/src/btif_storage.cc:1259 - btif_storage_remove_ble_bonding_keys: Removing bonding keys for bd addr:xx:xx:xx:xx:e6:01
04-26 01:44:09.235 1002 4593 4746 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:491 - get_cod: remote_cod=0x00000580
04-26 01:44:09.235 1002 4593 4746 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:579 - bond_state_changed: Bond state changed to state=0[0:none, 1:bonding, 2:bonded],prev_state=1, sdp_attempts=0
04-26 01:44:09.235 1002 4593 4746 E BluetoothMetricIdManager: packages/modules/Bluetooth/system/gd/common/metric_id_manager.cc:190 - ForgetDevice: Failed to remove device from paired_device_cache_
04-26 01:44:09.235 1002 4593 4897 I BluetoothBondStateMachine: bondStateChangeCallback: Status: 1 Address: XX:XX:XX:XX:E6:01 newState: 0 hciReason: 0
04-26 01:44:09.236 1002 4593 4906 V BluetoothServiceJni: obfuscateAddressNative
04-26 01:44:09.237 1002 4593 4906 V BluetoothServiceJni: getMetricIdNative
04-26 01:44:09.239 1002 4593 4906 V BluetoothServiceJni: obfuscateAddressNative
04-26 01:44:09.239 1002 4593 4906 V BluetoothServiceJni: getMetricIdNative
04-26 01:44:09.239 1002 4593 4906 D AdapterProperties: Failed to remove device: XX:XX:XX:XX:E6:01
04-26 01:44:09.240 1002 4593 4593 D A2dpService: Bond state changed for device: XX:XX:XX:XX:E6:01 state: 10
04-26 01:44:09.241 1002 4593 4593 D HearingAidService: Bond state changed for device: XX:XX:XX:XX:E6:01 state: 10
04-26 01:44:09.244 1002 4593 4906 D BluetoothCompanionManager: remove metadata listener: XX:XX:XX:XX:E6:01
04-26 01:44:09.244 1002 4593 4906 D BluetoothAdapter: removeOnMetadataChangedListener()
04-26 01:44:09.257 1002 4593 4906 I BluetoothBondStateMachine: Bond State Change Intent:XX:XX:XX:XX:E6:01 BOND_BONDING => BOND_NONE
I don't know what causes the problem, though it is normal in an ealier build. I wonder if there were any method to solve this. Thanks if anyone could provide some resolution or information.
FULL LOG:
bugreport-lineage_m5_tab-AP1A.240405.002.A1-2024-04-26-01-44-56.txt