diff --git a/system/stack/btm/btm_iso_impl.h b/system/stack/btm/btm_iso_impl.h index 358296e81e6d8b61c22e9c041980dd6214d5883d..a9562043aec1308671ac00675cabdfaf5f20eddf 100644 --- a/system/stack/btm/btm_iso_impl.h +++ b/system/stack/btm/btm_iso_impl.h @@ -25,6 +25,7 @@ #include "base/callback.h" #include "base/logging.h" #include "bind_helpers.h" +#include "btm_dev.h" #include "btm_iso_api.h" #include "common/time_util.h" #include "device/include/controller.h" @@ -33,6 +34,7 @@ #include "osi/include/allocator.h" #include "osi/include/log.h" #include "stack/include/bt_hdr.h" +#include "stack/include/btm_log_history.h" #include "stack/include/hci_error_code.h" #include "stack/include/hcidefs.h" @@ -49,6 +51,8 @@ static constexpr uint8_t kStateFlagIsConnected = 0x02; static constexpr uint8_t kStateFlagHasDataPathSet = 0x04; static constexpr uint8_t kStateFlagIsBroadcast = 0x10; +constexpr char kBtmLogTag[] = "ISO"; + struct iso_sync_info { uint32_t first_sync_ts; uint16_t seq_nb; @@ -118,6 +122,12 @@ struct iso_impl { uint8_t evt_code = IsCigKnown(cig_id) ? kIsoEventCigOnReconfigureCmpl : kIsoEventCigOnCreateCmpl; + BTM_LogHistory( + kBtmLogTag, RawAddress::kEmpty, "CIG Create complete", + base::StringPrintf( + "cig_id:0x%02x, status: %s", evt.cig_id, + hci_status_code_text((tHCI_STATUS)(evt.status)).c_str())); + if (evt.status == HCI_SUCCESS) { LOG_ASSERT(len >= (3) + (cis_cnt * sizeof(uint16_t))) << "Invalid CIS count: " << +cis_cnt; @@ -164,6 +174,11 @@ struct iso_impl { cig_params.cis_cfgs.size(), cig_params.cis_cfgs.data(), base::BindOnce(&iso_impl::on_set_cig_params, base::Unretained(this), cig_id, cig_params.sdu_itv_mtos)); + + BTM_LogHistory( + kBtmLogTag, RawAddress::kEmpty, "CIG Create", + base::StringPrintf("cig_id:0x%02x, size: %d", cig_id, + static_cast<int>(cig_params.cis_cfgs.size()))); } void reconfigure_cig(uint8_t cig_id, @@ -188,6 +203,12 @@ struct iso_impl { STREAM_TO_UINT8(evt.status, stream); STREAM_TO_UINT8(evt.cig_id, stream); + BTM_LogHistory( + kBtmLogTag, RawAddress::kEmpty, "CIG Remove complete", + base::StringPrintf( + "cig_id:0x%02x, status: %s", evt.cig_id, + hci_status_code_text((tHCI_STATUS)(evt.status)).c_str())); + if (evt.status == HCI_SUCCESS) { auto cis_it = conn_hdl_to_cis_map_.cbegin(); while (cis_it != conn_hdl_to_cis_map_.cend()) { @@ -210,6 +231,8 @@ struct iso_impl { btsnd_hcic_remove_cig(cig_id, base::BindOnce(&iso_impl::on_remove_cig, base::Unretained(this))); + BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "CIG Remove", + base::StringPrintf("cig_id:0x%02x (f:%d)", cig_id, force)); } void on_status_establish_cis( @@ -234,6 +257,14 @@ struct iso_impl { evt.cig_id = 0xFF; cis->state_flags &= ~kStateFlagIsConnecting; cig_callbacks_->OnCisEvent(kIsoEventCisEstablishCmpl, &evt); + + BTM_LogHistory( + kBtmLogTag, cis_hdl_to_addr[evt.cis_conn_hdl], + "Establish CIS failed ", + base::StringPrintf( + "handle:0x%04x, status: %s", evt.cis_conn_hdl, + hci_status_code_text((tHCI_STATUS)(status)).c_str())); + cis_hdl_to_addr.erase(evt.cis_conn_hdl); } } } @@ -246,6 +277,13 @@ struct iso_impl { (kStateFlagIsConnected | kStateFlagIsConnecting))) << "Already connected or connecting"; cis->state_flags |= kStateFlagIsConnecting; + + tBTM_SEC_DEV_REC* p_rec = btm_find_dev_by_handle(el.acl_conn_handle); + if (p_rec) { + cis_hdl_to_addr[el.cis_conn_handle] = p_rec->ble.pseudo_addr; + BTM_LogHistory(kBtmLogTag, p_rec->ble.pseudo_addr, "Establish CIS", + base::StringPrintf("handle:0x%04x", el.acl_conn_handle)); + } } btsnd_hcic_create_cis(conn_params.conn_pairs.size(), conn_params.conn_pairs.data(), @@ -261,6 +299,11 @@ struct iso_impl { << "Not connected"; bluetooth::legacy::hci::GetInterface().Disconnect( cis_handle, static_cast<tHCI_STATUS>(reason)); + + BTM_LogHistory(kBtmLogTag, cis_hdl_to_addr[cis_handle], "Disconnect CIS ", + base::StringPrintf( + "handle:0x%04x, reason:%s", cis_handle, + hci_reason_code_text((tHCI_REASON)(reason)).c_str())); } void on_setup_iso_data_path(uint8_t* stream, uint16_t len) { @@ -278,6 +321,12 @@ struct iso_impl { return; } + BTM_LogHistory(kBtmLogTag, cis_hdl_to_addr[conn_handle], + "Setup data path complete", + base::StringPrintf( + "handle:0x%04x, status:%s", conn_handle, + hci_status_code_text((tHCI_STATUS)(status)).c_str())); + if (status == HCI_SUCCESS) iso->state_flags |= kStateFlagHasDataPathSet; if (iso->state_flags & kStateFlagIsBroadcast) { LOG_ASSERT(big_callbacks_ != nullptr) << "Invalid BIG callbacks"; @@ -306,6 +355,12 @@ struct iso_impl { std::move(path_params.codec_conf), base::BindOnce(&iso_impl::on_setup_iso_data_path, base::Unretained(this))); + BTM_LogHistory( + kBtmLogTag, cis_hdl_to_addr[conn_handle], "Setup data path", + base::StringPrintf( + "handle:0x%04x, dir:0x%02x, path_id:0x%02x, codec_id:0x%02x", + conn_handle, path_params.data_path_dir, path_params.data_path_id, + path_params.codec_id_format)); } void on_remove_iso_data_path(uint8_t* stream, uint16_t len) { @@ -323,6 +378,12 @@ struct iso_impl { return; } + BTM_LogHistory(kBtmLogTag, cis_hdl_to_addr[conn_handle], + "Remove data path complete", + base::StringPrintf( + "handle:0x%04x, status:%s", conn_handle, + hci_status_code_text((tHCI_STATUS)(status)).c_str())); + if (status == HCI_SUCCESS) iso->state_flags &= ~kStateFlagHasDataPathSet; if (iso->state_flags & kStateFlagIsBroadcast) { @@ -345,6 +406,9 @@ struct iso_impl { iso_handle, data_path_dir, base::BindOnce(&iso_impl::on_remove_iso_data_path, base::Unretained(this))); + BTM_LogHistory(kBtmLogTag, cis_hdl_to_addr[iso_handle], "Remove data path", + base::StringPrintf("handle:0x%04x, dir:0x%02x", iso_handle, + data_path_dir)); } void on_iso_link_quality_read(uint8_t* stream, uint16_t len) { @@ -491,6 +555,12 @@ struct iso_impl { auto cis = GetCisIfKnown(evt.cis_conn_hdl); LOG_ASSERT(cis != nullptr) << "No such cis: " << +evt.cis_conn_hdl; + BTM_LogHistory(kBtmLogTag, cis_hdl_to_addr[evt.cis_conn_hdl], + "CIS established event", + base::StringPrintf( + "cis_handle:0x%04x status:%s", evt.cis_conn_hdl, + hci_error_code_text((tHCI_STATUS)(evt.status)).c_str())); + cis->sync_info.first_sync_ts = bluetooth::common::time_get_os_boottime_us(); STREAM_TO_UINT24(evt.cig_sync_delay, data); @@ -508,7 +578,11 @@ struct iso_impl { STREAM_TO_UINT16(evt.max_pdu_stom, data); STREAM_TO_UINT16(evt.iso_itv, data); - if (evt.status == HCI_SUCCESS) cis->state_flags |= kStateFlagIsConnected; + if (evt.status == HCI_SUCCESS) { + cis->state_flags |= kStateFlagIsConnected; + } else { + cis_hdl_to_addr.erase(evt.cis_conn_hdl); + } cis->state_flags &= ~kStateFlagIsConnecting; @@ -524,6 +598,13 @@ struct iso_impl { LOG_ASSERT(cig_callbacks_ != nullptr) << "Invalid CIG callbacks"; LOG_INFO("%s flags: %d", __func__, +cis->state_flags); + + BTM_LogHistory( + kBtmLogTag, cis_hdl_to_addr[handle], "CIS disconnected", + base::StringPrintf("cis_handle:0x%04x, reason:%s", handle, + hci_error_code_text((tHCI_REASON)(reason)).c_str())); + cis_hdl_to_addr.erase(handle); + if (cis->state_flags & kStateFlagIsConnected) { cis_disconnected_evt evt = { .reason = reason, @@ -870,6 +951,7 @@ struct iso_impl { std::map<uint16_t, std::unique_ptr<iso_cis>> conn_hdl_to_cis_map_; std::map<uint16_t, std::unique_ptr<iso_bis>> conn_hdl_to_bis_map_; + std::map<uint16_t, RawAddress> cis_hdl_to_addr; std::atomic_uint16_t iso_credits_; uint16_t iso_buffer_size_; diff --git a/system/stack/gatt/connection_manager.cc b/system/stack/gatt/connection_manager.cc index 4e3592f1c467aced4339eaea75984684d96776fa..82f50bd1a8046c01ac1e028e6300763826c7b387 100644 --- a/system/stack/gatt/connection_manager.cc +++ b/system/stack/gatt/connection_manager.cc @@ -175,8 +175,6 @@ static void target_announcement_observe_results_cb(tBTM_INQ_RESULTS* p_inq, LOG_INFO("Found targeted announcement for device %s", ADDRESS_TO_LOGGABLE_CSTR(addr)); - BTM_LogHistory(kBtmLogTag, addr, "Found TA from"); - if (it->second.is_in_accept_list) { LOG_INFO("Device %s is already connecting", ADDRESS_TO_LOGGABLE_CSTR(addr)); return; @@ -187,6 +185,8 @@ static void target_announcement_observe_results_cb(tBTM_INQ_RESULTS* p_inq, return; } + BTM_LogHistory(kBtmLogTag, addr, "Found TA from"); + /* Take fist app_id and use it for direct_connect */ auto app_id = *(it->second.doing_targeted_announcements_conn.begin()); diff --git a/system/stack/test/btm_iso_test.cc b/system/stack/test/btm_iso_test.cc index a5554a06a7073eb6684e6db6f1a5e04f8d054169..50859186e2326906000de0adbc738d35adc1556d 100644 --- a/system/stack/test/btm_iso_test.cc +++ b/system/stack/test/btm_iso_test.cc @@ -24,6 +24,7 @@ #include "mock_controller.h" #include "mock_hcic_layer.h" #include "osi/include/allocator.h" +#include "stack/btm/btm_dev.h" #include "stack/include/bt_hdr.h" #include "stack/include/hci_error_code.h" #include "stack/include/hcidefs.h" @@ -42,6 +43,10 @@ using testing::Test; // Iso Manager currently works on top of the legacy HCI layer bool bluetooth::shim::is_gd_shim_enabled() { return false; } +tBTM_SEC_DEV_REC* btm_find_dev_by_handle(uint16_t handle) { return nullptr; } +void BTM_LogHistory(const std::string& tag, const RawAddress& bd_addr, + const std::string& msg, const std::string& extra) {} + namespace bte { class BteInterface { public: