//Pairing starts
04-18 14:30:32.100 I NearbyDiscovery: FastPairController: Validator: onValidatorConnectionRequested [CONTEXT service_id=265 ]
04-18 14:30:32.100 I FastPair: FPDC: Starting to pair XX:XX:XX:XX:22:88: key[64], Preferences{gattOperationTimeoutSeconds=10, gattConnectionTimeoutSeconds=15, bluetoothToggleTimeoutSeconds=10, bluetoothToggleSleepSeconds=2,
04-18 14:30:32.107 D FastPairUtils: FastPair: Pairing finished with intent action: com.google.android.gms.nearby.discovery.ACTION_VALIDATOR_PAIR_PROGRESS
04-18 14:30:32.132 I bthal.activity: handle_ble_meta_event: LE Enhanced Connection Complete, conn_handle:041, conn_bda: XX:XX:44:44:22:88
04-18 14:30:32.223 I bt_bta_dm: bta_dm_acl_up: Acl connected peer:xx:xx:xx:xx:22:88 transport:BT_TRANSPORT_LE handle:65
04-18 14:30:32.224 D BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:22:88 is not in cache
04-18 14:30:33.870 D FastPairUtils: FastPair: Pairing finished with intent action: com.google.android.gms.nearby.discovery.ACTION_VALIDATOR_PAIR_PROGRESS
04-18 14:30:34.922 D FastPairUtils: FastPair: Pairing finished with intent action: com.google.android.gms.nearby.discovery.ACTION_VALIDATOR_PAIR_PROGRESS
04-18 14:30:34.944 I BluetoothBondStateMachine: Bond State Change Intent:XX:XX:XX:XX:22:88 BOND_NONE => BOND_BONDING
04-18 14:30:36.075 I bt_bta_dm: bta_dm_acl_up: Acl connected peer:xx:xx:xx:xx:22:88 transport:BT_TRANSPORT_BR_EDR handle:11
04-18 14:30:36.201 D CachedBluetoothDevice: Device name: JBL Tune 530BT
04-18 14:30:36.467 I bt_bta_dm: bta_dm_search_sm_execute: state:BTA_DM_SEARCH_IDLE, event:BTA_DM_API_DISCOVER_EVT[0x202]
//UUIDs discovered and device bonded
04-18 14:30:36.606 D bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1985 - btif_dm_search_services_evt: New GATT over SDP UUIDs for xx:xx:xx:xx:22:88:
04-18 14:30:36.606 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:2002 - btif_dm_search_services_evt: No well known GATT services discovered
04-18 14:30:36.606 I bt_bta_dm: bta_dm_search_sm_execute: state:BTA_DM_DISCOVER_ACTIVE, event:BTA_DM_DISCOVERY_RESULT_EVT[0x207]
04-18 14:30:36.606 V bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1777 - btif_dm_search_services_evt: result=0x0, services 0xc00c0062
04-18 14:30:36.606 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1798 - btif_dm_search_services_evt: SDP finished for xx:xx:xx:xx:22:88:
04-18 14:30:36.606 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1807 - btif_dm_search_services_evt: New UUIDs for xx:xx:xx:xx:22:88:
04-18 14:30:36.606 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1813 - btif_dm_search_services_evt: index:0 uuid:00001101-0000-1000-8000-00805f9b34fb
04-18 14:30:36.606 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1813 - btif_dm_search_services_evt: index:1 uuid:00001108-0000-1000-8000-00805f9b34fb
04-18 14:30:36.607 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1813 - btif_dm_search_services_evt: index:2 uuid:0000111e-0000-1000-8000-00805f9b34fb
04-18 14:30:36.607 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1813 - btif_dm_search_services_evt: index:3 uuid:0000110b-0000-1000-8000-00805f9b34fb
04-18 14:30:36.607 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1813 - btif_dm_search_services_evt: index:4 uuid:0000110e-0000-1000-8000-00805f9b34fb
04-18 14:30:36.607 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1813 - btif_dm_search_services_evt: index:7 uuid:6a24eeab-4b65-4693-986b-3c26c352264f
04-18 14:30:36.607 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1813 - btif_dm_search_services_evt: index:8 uuid:df21fe2c-2515-4fdb-8886-f12c4d67927c
04-18 14:30:36.607 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1863 - btif_dm_search_services_evt: SDP search done for xx:xx:xx:xx:22:88
04-18 14:30:36.607 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1917 - btif_dm_search_services_evt: Bonding LE Audio sink - must wait for le services discovery to pass all services to java xx:xx:xx:xx:22:88
04-18 14:30:36.607 I bt_bta_dm: bta_dm_search_cmpl: No BLE connection, processing classic results
04-18 14:30:39.492 I BluetoothBondStateMachine: Bond State Change Intent:XX:XX:XX:XX:22:88 BOND_BONDING => BOND_BONDED
04-18 14:30:39.993 I FastPair: BluetoothAudioPairer: BondedReceiver: handleBondStateChanged: device=XX:XX:XX:XX:22:88, state=12, reason=-2147483648
Connectionpolicy is -1 for all profiles
04-18 14:30:40.018 D CachedBluetoothDevice: No profiles. Maybe we will connect later for device XX:XX:XX:XX:22:88
04-18 14:30:40.615 I btm_acl : disconnect_acl: Disconnecting peer:xx:xx:xx:xx:22:88 reason:HCI_ERR_PEER_USER comment:stack::l2cap::l2c_link::l2c_link_timeout All channels closed
04-18 14:30:40.768 I bt_shim_hci: packages/modules/Bluetooth/system/main/shim/hci_layer.cc:304 - operator(): ISO disconnection from GD, handle: 0x0b, reason: 0x13
// connectionPolicy=-1 -1是指失败
04-18 14:30:40.777 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:22:88 profile=A2DP, connectionPolicy=-1
04-18 14:30:40.777 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:22:88 profile=HEADSET, connectionPolicy=-1
04-18 14:30:40.777 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:22:88 profile=HID_HOST, connectionPolicy=-1
04-18 14:30:40.777 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:22:88 profile=PAN, connectionPolicy=-1
04-18 14:30:40.777 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:22:88 profile=HEARING_AID, connectionPolicy=-1
04-18 14:30:40.777 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:22:88 profile=HAP_CLIENT, connectionPolicy=-1
04-18 14:30:40.777 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:22:88 profile=VOLUME_CONTROL, connectionPolicy=-1
04-18 14:30:40.777 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:22:88 profile=CSIP_SET_COORDINATOR, connectionPolicy=-1
04-18 14:30:40.777 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:22:88 profile=LE_AUDIO, connectionPolicy=-1
//created bond but never received UUIDs
04-18 14:30:49.941 W FastPair: BluetoothAudioPairer: pair: created bond but never received UUIDs, attempting to continue.
Device disconnected
04-18 14:30:50.083 I bluetooth: disconnect: Device: xx:xx:xx:xx:22:88, cid: 0xffff
04-18 14:30:50.086 I FastPair: Gatt connection with XX:XX:XX:XX:22:88 closed.
04-18 14:30:50.097 D FastPairUtils: FastPair: Pairing finished with intent action: com.google.android.gms.nearby.discovery.ACTION_VALIDATOR_PAIR_PROGRESS
04-18 14:30:51.083 I btm_acl : disconnect_acl: Disconnecting peer:xx:xx:xx:xx:22:88 reason:HCI_ERR_PEER_USER comment:stack::l2cap::l2c_link::l2c_link_timeout All channels closed
04-18 14:30:51.134 I bt_shim_hci: packages/modules/Bluetooth/system/main/shim/hci_layer.cc:304 - operator(): ISO disconnection from GD, handle: 0x41, reason: 0x16
04-18 14:30:51.135 I bluetooth: disconnect: Device: xx:xx:xx:xx:22:88, cid: 0xffff
04-18 14:31:50.101 I BaseModuleTask: event=ModuleEvent{message=Pairing process error. Reason: Is connected: false
04-18 14:31:50.102 D FeatureTestActivity: ModuleEvent{message=Pairing process error. Reason: Is connected: false
04-18 14:31:50.133 I FastPair: BluetoothAudioPairer: unpair: device=XX:XX:XX:XX:22:88, methodName=removeBond
04-18 14:31:50.134 I BluetoothDevice: removeBond() for device XX:XX:XX:XX:22:88 called by pid: 19745 tid: 26174
04-18 14:31:50.146 I BluetoothBondStateMachine: Bond State Change Intent:XX:XX:XX:XX:22:88 BOND_BONDED => BOND_NONE
正常的流程
//Pairing starts
04-18 10:50:49.219 I NearbyDiscovery: FastPairController: Validator: onValidatorConnectionRequested [CONTEXT service_id=265 ]
04-18 10:50:49.221 I FastPair: FPDC: Starting to pair XX:XX:XX:XX:94:09: key[16], Preferences{gattOperationTimeoutSeconds=10, gattConnectionTimeoutSeconds=15, bluetoothToggleTimeoutSeconds=10, bluetoothToggleSleepSeconds=2,
04-18 10:50:49.288 I bthal.activity: handle_ble_meta_event: LE Enhanced Connection Complete, conn_handle:041, conn_bda: XX:XX:55:0b:94:09
04-18 10:50:49.412 I bt_bta_dm: bta_dm_acl_up: Acl connected peer:xx:xx:xx:xx:94:09 transport:BT_TRANSPORT_LE handle:65
04-18 10:50:49.416 D BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:94:09 is not in cache
04-18 10:50:51.779 I BluetoothBondStateMachine: Bond State Change Intent:XX:XX:XX:XX:94:09 BOND_NONE => BOND_BONDING
04-18 10:50:53.322 I bt_bta_dm: bta_dm_search_sm_execute: state:BTA_DM_SEARCH_IDLE, event:BTA_DM_API_DISCOVER_EVT[0x202]
04-18 10:50:53.826 I bt_bta_dm: bta_dm_search_sm_execute: state:BTA_DM_DISCOVER_ACTIVE, event:BTA_DM_API_DISCOVER_EVT[0x202]
//UUIDs discovered
04-18 10:50:54.679 I bt_bta_dm: bta_dm_execute_queued_request: Start pending discovery
04-18 10:50:54.679 I bt_bta_dm: bta_dm_search_sm_execute: state:BTA_DM_SEARCH_IDLE, event:BTA_DM_API_DISCOVER_EVT[0x202]
04-18 10:50:54.680 I bt_bta_dm: bta_dm_discover_device: bta_dm_discovery: starting GATT discovery on xx:xx:xx:xx:94:09
04-18 10:50:54.680 I bt_bta_dm: bta_dm_search_sm_execute: state:BTA_DM_DISCOVER_ACTIVE, event:BTA_DM_DISCOVERY_RESULT_EVT[0x207]
04-18 10:50:54.680 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1952 - btif_dm_search_services_evt: New GATT over LE UUIDs for xx:xx:xx:xx:94:09:
04-18 10:50:54.680 D bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1963 - btif_dm_search_services_evt: clearing pairing_cb
04-18 10:50:54.680 D bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1971 - btif_dm_search_services_evt: Scheduling conn params unlock for xx:xx:xx:xx:94:09
04-18 10:50:54.680 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1996 - btif_dm_search_services_evt: index:0 uuid:0000180f-0000-1000-8000-00805f9b34fb
04-18 10:50:54.680 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1996 - btif_dm_search_services_evt: index:1 uuid:00001844-0000-1000-8000-00805f9b34fb
04-18 10:50:54.680 I bt_btif_dm: packages/modules/Bluetooth/system/btif/src/btif_dm.cc:1996 - btif_dm_search_services_evt: index:2 uuid:0000184e-0000-1000-8000-00805f9b34fb
04-18 10:50:54.681 I BluetoothAdapterService: sendUuidsInternal: Received service discovery UUIDs for device XX:XX:XX:XX:94:09
04-18 10:50:54.681 D BluetoothAdapterService: sendUuidsInternal: index=0 uuid=00001101-0000-1000-8000-00805f9b34fb
04-18 10:50:54.681 D BluetoothAdapterService: sendUuidsInternal: index=1 uuid=00001108-0000-1000-8000-00805f9b34fb
04-18 10:50:54.681 D BluetoothAdapterService: sendUuidsInternal: index=2 uuid=0000110b-0000-1000-8000-00805f9b34fb
04-18 10:50:54.681 D BluetoothAdapterService: sendUuidsInternal: index=3 uuid=0000110e-0000-1000-8000-00805f9b34fb
04-18 10:50:54.681 D BluetoothAdapterService: sendUuidsInternal: index=4 uuid=0000111e-0000-1000-8000-00805f9b34fb
04-18 10:50:54.681 D BluetoothAdapterService: sendUuidsInternal: index=5 uuid=0000180f-0000-1000-8000-00805f9b34fb
04-18 10:50:54.681 D BluetoothAdapterService: sendUuidsInternal: index=6 uuid=00001844-0000-1000-8000-00805f9b34fb
04-18 10:50:54.681 D BluetoothAdapterService: sendUuidsInternal: index=7 uuid=0000184e-0000-1000-8000-00805f9b34fb
04-18 10:50:54.681 D BluetoothAdapterService: sendUuidsInternal: index=8 uuid=6a24eeab-4b65-4693-986b-3c26c352264f
04-18 10:50:54.681 D BluetoothAdapterService: sendUuidsInternal: index=9 uuid=df21fe2c-2515-4fdb-8886-f12c4d67927c
//Bonded
04-18 10:50:54.701 I BluetoothBondStateMachine: Bond State Change Intent:XX:XX:XX:XX:94:09 BOND_BONDING => BOND_BONDED
// profile=A2DP, connectionPolicy=0 0 是指连线成功
04-18 10:50:54.737 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:94:09 profile=A2DP, connectionPolicy=0
04-18 10:50:54.737 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:94:09 profile=A2DP, connectionPolicy=0
04-18 10:50:54.738 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:94:09 profile=HEADSET, connectionPolicy=0
04-18 10:50:54.738 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:94:09 profile=VOLUME_CONTROL, connectionPolicy=100
04-18 10:50:54.738 V BluetoothDatabase: getProfileConnectionPolicy: device XX:XX:XX:XX:94:09 profile=LE_AUDIO, connectionPolicy=100
//action.UUID is received and profiles connected
04-18 10:50:54.751 I FastPair: BluetoothAudioPairer: BondedReceiver: handleUuids: device=XX:XX:XX:XX:94:09, uuids=[00001101-0000-1000-8000-00805f9b34fb, 00001108-0000-1000-8000-00805f9b34fb, 0000110b-0000-1000-8000-00805f9b34fb, 0000110e-0000-1000-8000-00805f9b34fb, 0000111e-0000-1000-8000-00805f9b34fb, 0000180f-0000-1000-8000-00805f9b34fb, 00001844-0000-1000-8000-00805f9b34fb, 0000184e-0000-1000-8000-00805f9b34fb, 6a24eeab-4b65-4693-986b-3c26c352264f, df21fe2c-2515-4fdb-8886-f12c4d67927c]
04-18 10:50:54.785 I FastPair: BluetoothAudioPairer: AdditionalBondedReceiver: onReceive: action=android.bluetooth.device.action.UUID, device=XX:XX:XX:XX:94:09
04-18 10:50:56.829 I BluetoothPhonePolicy: processProfileStateChanged, device=XX:XX:XX:XX:94:09, profile=LE_AUDIO, 1 -> 2
04-18 10:50:56.849 I BluetoothPhonePolicy: processProfileStateChanged, device=XX:XX:XX:XX:94:09, profile=VOLUME_CONTROL, 1 -> 2
//Classic ACL disconnected due no available profiles
04-18 10:50:58.705 I btm_acl : disconnect_acl: Disconnecting peer:xx:xx:xx:xx:19:19 reason:HCI_ERR_PEER_USER comment:stack::l2cap::l2c_link::l2c_link_timeout All channels closed
04-18 10:50:58.847 I bt_shim_hci: packages/modules/Bluetooth/system/main/shim/hci_layer.cc:304 - operator(): ISO disconnection from GD, handle: 0x0b, reason: 0x13
// Bond removed
04-18 10:51:06.883 I FastPair: BluetoothAudioPairer: unpair: device=XX:XX:XX:XX:94:09, methodName=removeBond
04-18 10:51:06.883 I BluetoothDevice: removeBond() for device XX:XX:XX:XX:94:09 called by pid: 5098 tid: 17729
04-18 10:51:06.888 I btm_acl : disconnect_acl: Disconnecting peer:xx:xx:xx:xx:94:09 reason:HCI_ERR_PEER_USER comment:stack::acl::btm_acl::btm_remove_acl
04-18 10:51:06.896 I btm_acl : disconnect_acl: Disconnecting peer:xx:xx:xx:xx:94:09 reason:HCI_ERR_PEER_USER comment:bta::le_audio::client disconnect
04-18 10:51:06.896 I BluetoothPhonePolicy: processProfileStateChanged, device=XX:XX:XX:XX:94:09, profile=VOLUME_CONTROL, 2 -> 3
04-18 10:51:06.897 I BluetoothPhonePolicy: processProfileStateChanged, device=XX:XX:XX:XX:94:09, profile=LE_AUDIO, 2 -> 3
04-18 10:51:06.901 I BluetoothBondStateMachine: Bond State Change Intent:XX:XX:XX:XX:94:09 BOND_BONDED => BOND_NONE
04-18 10:51:06.912 I bt_shim_hci: packages/modules/Bluetooth/system/main/shim/hci_layer.cc:304 - operator(): ISO disconnection from GD, handle: 0x41, reason: 0x16
//Conclusion:
The uuids are not passed to upper layer.
The build seems to be old and there have been changes in this module, please check if it is repro in the latest build.
If reproducible, please provide bug report along with issue timestamp/video.
Steps to enable full bt_snoop logs:
1.Enable Developer options on the device.
2.In the Developer options menu, change the Enable Bluetooth HCI snoop log setting to Enabled.
3.In the "Logger buffer sizes", change the buffer size to "16M"(or highest possible).
4.Enable Verbose Logging from Developer Options (Developer Options -> Enable Bluetooth Stack log -> Select Verbose)
5.In the "Store logger data persistently on device" to "All log buffers"
6.Restart your phone for logging to take effect
7.Try reproducing your issue again and take a new bugreport |