diff --git a/system/stack/include/l2c_api.h b/system/stack/include/l2c_api.h index 3f257ba19203769afd5813c249c86200bc7f7030..bc1ad238362fb86f0ff14095f2902cb745406606 100644 --- a/system/stack/include/l2c_api.h +++ b/system/stack/include/l2c_api.h @@ -24,6 +24,7 @@ #ifndef L2C_API_H #define L2C_API_H +#include <bluetooth/log.h> #include <stdbool.h> #include <cstdint> @@ -925,4 +926,11 @@ void L2CA_SetMediaStreamChannel(uint16_t local_media_cid, bool status); bool L2CA_isMediaChannel(uint16_t handle, uint16_t channel_id, bool is_local_cid); +namespace fmt { +template <> +struct formatter<tL2CAP_LATENCY> : enum_formatter<tL2CAP_LATENCY> {}; +template <> +struct formatter<tL2CAP_PRIORITY> : enum_formatter<tL2CAP_PRIORITY> {}; +} // namespace fmt + #endif /* L2C_API_H */ diff --git a/system/stack/include/l2cdefs.h b/system/stack/include/l2cdefs.h index 2d8be2b985b15e94482cffbcb474d3b9e5d0a95c..c1c26f7de09800e1a86a39c62b8f9c9df67d0fc7 100644 --- a/system/stack/include/l2cdefs.h +++ b/system/stack/include/l2cdefs.h @@ -481,4 +481,9 @@ constexpr uint16_t L2CAP_SDU_LENGTH_LE_MAX = 0xffff; /* Mask for sequence numbers (range 0 - 63) */ #define L2CAP_FCR_SEQ_MODULO 0x3F +namespace fmt { +template <> +struct formatter<tL2CAP_CONN> : enum_formatter<tL2CAP_CONN> {}; +} // namespace fmt + #endif diff --git a/system/stack/l2cap/l2c_api.cc b/system/stack/l2cap/l2c_api.cc index dceb8257056a1cabd14e5dcefd0ab742621068dd..d12df9b1107623f5c896aeb28109bec0efa156ca 100644 --- a/system/stack/l2cap/l2c_api.cc +++ b/system/stack/l2cap/l2c_api.cc @@ -29,6 +29,7 @@ #include <base/location.h> #include <base/logging.h> #include <base/strings/stringprintf.h> +#include <bluetooth/log.h> #include <cstdint> #include <string> @@ -53,6 +54,8 @@ #include "stack/l2cap/l2c_int.h" #include "types/raw_address.h" +using namespace bluetooth; + void btsnd_hcic_enhanced_flush(uint16_t handle, uint8_t packet_type); // TODO Remove @@ -133,16 +136,16 @@ uint16_t L2CA_Register(uint16_t psm, const tL2CAP_APPL_INFO& p_cb_info, ** or only a server. */ if (!config_cfm_cb || !data_ind_cb || !disconnect_ind_cb) { - LOG_ERROR( - "L2CAP - no cb registering PSM: 0x%04x cfg_cfm:%u cfg_ind:%u" - " data_ind:%u discon_int:%u", + log::error( + "L2CAP - no cb registering PSM: 0x{:04x} cfg_cfm:{} cfg_ind:{} " + "data_ind:{} discon_int:{}", psm, config_cfm_cb, config_ind_cb, data_ind_cb, disconnect_ind_cb); return (0); } /* Verify PSM is valid */ if (L2C_INVALID_PSM(psm)) { - LOG_ERROR("L2CAP - invalid PSM value, PSM: 0x%04x", psm); + log::error("L2CAP - invalid PSM value, PSM: 0x{:04x}", psm); return (0); } @@ -154,7 +157,7 @@ uint16_t L2CA_Register(uint16_t psm, const tL2CAP_APPL_INFO& p_cb_info, if (p_rcb == NULL) break; } - LOG_DEBUG("L2CAP - Real PSM: 0x%04x Virtual PSM: 0x%04x", psm, vpsm); + log::debug("L2CAP - Real PSM: 0x{:04x} Virtual PSM: 0x{:04x}", psm, vpsm); } /* If registration block already there, just overwrite it */ @@ -162,13 +165,13 @@ uint16_t L2CA_Register(uint16_t psm, const tL2CAP_APPL_INFO& p_cb_info, if (p_rcb == NULL) { p_rcb = l2cu_allocate_rcb(vpsm); if (p_rcb == NULL) { - LOG_WARN("L2CAP - no RCB available, PSM: 0x%04x vPSM: 0x%04x", psm, - vpsm); + log::warn("L2CAP - no RCB available, PSM: 0x{:04x} vPSM: 0x{:04x}", psm, + vpsm); return (0); } } - LOG_INFO("L2CAP Registered service classic PSM: 0x%04x", psm); + log::info("L2CAP Registered service classic PSM: 0x{:04x}", psm); p_rcb->log_packets = enable_snoop; p_rcb->api = p_cb_info; p_rcb->real_psm = psm; @@ -198,7 +201,7 @@ void L2CA_Deregister(uint16_t psm) { tL2C_LCB* p_lcb; int ii; - LOG_VERBOSE("L2CAP - L2CA_Deregister() called for PSM: 0x%04x", psm); + log::verbose("L2CAP - L2CA_Deregister() called for PSM: 0x{:04x}", psm); p_rcb = l2cu_find_rcb_by_psm(psm); if (p_rcb != NULL) { @@ -223,7 +226,7 @@ void L2CA_Deregister(uint16_t psm) { } l2cu_release_rcb(p_rcb); } else { - LOG_WARN("L2CAP - PSM: 0x%04x not found for deregistration", psm); + log::warn("L2CAP - PSM: 0x{:04x} not found for deregistration", psm); } } @@ -241,11 +244,11 @@ uint16_t L2CA_AllocateLePSM(void) { uint16_t psm = l2cb.le_dyn_psm; uint16_t count = 0; - LOG_VERBOSE("%s: last psm=%d", __func__, psm); + log::verbose("last psm={}", psm); while (!done) { count++; if (count > LE_DYNAMIC_PSM_RANGE) { - LOG_ERROR("%s: Out of free BLE PSM", __func__); + log::error("Out of free BLE PSM"); return 0; } @@ -257,13 +260,12 @@ uint16_t L2CA_AllocateLePSM(void) { if (!l2cb.le_dyn_psm_assigned[psm - LE_DYNAMIC_PSM_START]) { /* make sure the newly allocated psm is not used right now */ if (l2cu_find_ble_rcb_by_psm(psm)) { - LOG_WARN("%s: supposedly-free PSM=%d have allocated rcb!", __func__, - psm); + log::warn("supposedly-free PSM={} have allocated rcb!", psm); continue; } l2cb.le_dyn_psm_assigned[psm - LE_DYNAMIC_PSM_START] = true; - LOG_VERBOSE("%s: assigned PSM=%d", __func__, psm); + log::verbose("assigned PSM={}", psm); done = true; break; } @@ -283,15 +285,15 @@ uint16_t L2CA_AllocateLePSM(void) { * ******************************************************************************/ void L2CA_FreeLePSM(uint16_t psm) { - LOG_VERBOSE("%s: to free psm=%d", __func__, psm); + log::verbose("to free psm={}", psm); if ((psm < LE_DYNAMIC_PSM_START) || (psm > LE_DYNAMIC_PSM_END)) { - LOG_ERROR("%s: Invalid PSM=%d value!", __func__, psm); + log::error("Invalid PSM={} value!", psm); return; } if (!l2cb.le_dyn_psm_assigned[psm - LE_DYNAMIC_PSM_START]) { - LOG_WARN("%s: PSM=%d was not allocated!", __func__, psm); + log::warn("PSM={} was not allocated!", psm); } l2cb.le_dyn_psm_assigned[psm - LE_DYNAMIC_PSM_START] = false; } @@ -317,18 +319,17 @@ uint16_t L2CA_ConnectReq2(uint16_t psm, const RawAddress& p_bd_addr, * ******************************************************************************/ uint16_t L2CA_ConnectReq(uint16_t psm, const RawAddress& p_bd_addr) { - VLOG(1) << __func__ << "BDA " << ADDRESS_TO_LOGGABLE_STR(p_bd_addr) - << StringPrintf(" PSM: 0x%04x", psm); + log::verbose("BDA {} PSM: 0x{:04x}", ADDRESS_TO_LOGGABLE_STR(p_bd_addr), psm); /* Fail if we have not established communications with the controller */ if (!BTM_IsDeviceUp()) { - LOG(WARNING) << __func__ << ": BTU not ready"; + log::warn("BTU not ready"); return 0; } /* Fail if the PSM is not registered */ tL2C_RCB* p_rcb = l2cu_find_rcb_by_psm(psm); if (p_rcb == nullptr) { - LOG(WARNING) << __func__ << ": no RCB, PSM=" << loghex(psm); + log::warn("no RCB, PSM={}", loghex(psm)); return 0; } @@ -340,9 +341,8 @@ uint16_t L2CA_ConnectReq(uint16_t psm, const RawAddress& p_bd_addr) { p_lcb = l2cu_allocate_lcb(p_bd_addr, false, BT_TRANSPORT_BR_EDR); /* currently use BR/EDR for ERTM mode l2cap connection */ if (p_lcb == nullptr) { - LOG(WARNING) << __func__ - << ": connection not started for PSM=" << loghex(psm) - << ", p_lcb=" << p_lcb; + log::warn("connection not started for PSM={}, p_lcb={}", loghex(psm), + fmt::ptr(p_lcb)); return 0; } l2cu_create_conn_br_edr(p_lcb); @@ -351,7 +351,7 @@ uint16_t L2CA_ConnectReq(uint16_t psm, const RawAddress& p_bd_addr) { /* Allocate a channel control block */ tL2C_CCB* p_ccb = l2cu_allocate_ccb(p_lcb, 0); if (p_ccb == nullptr) { - LOG(WARNING) << __func__ << ": no CCB, PSM=" << loghex(psm); + log::warn("no CCB, PSM={}", loghex(psm)); return 0; } @@ -370,14 +370,14 @@ uint16_t L2CA_ConnectReq(uint16_t psm, const RawAddress& p_bd_addr) { * ccb will be automatically retried after link disconnect * arrives */ - LOG_VERBOSE("L2CAP API - link disconnecting: RETRY LATER"); + log::verbose("L2CAP API - link disconnecting: RETRY LATER"); /* Save ccb so it can be started after disconnect is finished */ p_lcb->p_pending_ccb = p_ccb; } - LOG_VERBOSE("L2CAP - L2CA_conn_req(psm: 0x%04x) returned CID: 0x%04x", psm, - p_ccb->local_cid); + log::verbose("L2CAP - L2CA_conn_req(psm: 0x{:04x}) returned CID: 0x{:04x}", + psm, p_ccb->local_cid); /* Return the local CID as our handle */ return p_ccb->local_cid; @@ -412,13 +412,13 @@ uint16_t L2CA_RegisterLECoc(uint16_t psm, const tL2CAP_APPL_INFO& p_cb_info, ** or only a server. */ if ((!p_cb_info.pL2CA_DataInd_Cb) || (!p_cb_info.pL2CA_DisconnectInd_Cb)) { - LOG_ERROR("No cb registering BLE PSM: 0x%04x", psm); + log::error("No cb registering BLE PSM: 0x{:04x}", psm); return 0; } /* Verify PSM is valid */ if (!L2C_IS_VALID_LE_PSM(psm)) { - LOG_ERROR("Invalid BLE PSM value, PSM: 0x%04x", psm); + log::error("Invalid BLE PSM value, PSM: 0x{:04x}", psm); return 0; } @@ -431,25 +431,26 @@ uint16_t L2CA_RegisterLECoc(uint16_t psm, const tL2CAP_APPL_INFO& p_cb_info, (p_cb_info.pL2CA_ConnectInd_Cb == NULL)) { vpsm = L2CA_AllocateLePSM(); if (vpsm == 0) { - LOG_ERROR("Out of free BLE PSM"); + log::error("Out of free BLE PSM"); return 0; } - LOG_DEBUG("Real PSM: 0x%04x Virtual PSM: 0x%04x", psm, vpsm); + log::debug("Real PSM: 0x{:04x} Virtual PSM: 0x{:04x}", psm, vpsm); } /* If registration block already there, just overwrite it */ p_rcb = l2cu_find_ble_rcb_by_psm(vpsm); if (p_rcb == NULL) { - LOG_DEBUG("Allocate rcp for Virtual PSM: 0x%04x", vpsm); + log::debug("Allocate rcp for Virtual PSM: 0x{:04x}", vpsm); p_rcb = l2cu_allocate_ble_rcb(vpsm); if (p_rcb == NULL) { - LOG_WARN("No BLE RCB available, PSM: 0x%04x vPSM: 0x%04x", psm, vpsm); + log::warn("No BLE RCB available, PSM: 0x{:04x} vPSM: 0x{:04x}", psm, + vpsm); return 0; } } - LOG_INFO("Registered service LE COC PSM: 0x%04x", psm); + log::info("Registered service LE COC PSM: 0x{:04x}", psm); p_rcb->api = p_cb_info; p_rcb->real_psm = psm; p_rcb->coc_cfg = cfg; @@ -468,11 +469,11 @@ uint16_t L2CA_RegisterLECoc(uint16_t psm, const tL2CAP_APPL_INFO& p_cb_info, * ******************************************************************************/ void L2CA_DeregisterLECoc(uint16_t psm) { - LOG_VERBOSE("%s called for PSM: 0x%04x", __func__, psm); + log::verbose("called for PSM: 0x{:04x}", psm); tL2C_RCB* p_rcb = l2cu_find_ble_rcb_by_psm(psm); if (p_rcb == NULL) { - LOG_WARN("%s PSM: 0x%04x not found for deregistration", __func__, psm); + log::warn("PSM: 0x{:04x} not found for deregistration", psm); return; } @@ -516,19 +517,19 @@ uint16_t L2CA_ConnectLECocReq(uint16_t psm, const RawAddress& p_bd_addr, get_btm_client_interface().security.BTM_SetSecurityLevel( true, "", 0, sec_level, psm, 0, 0); - VLOG(1) << __func__ << " BDA: " << ADDRESS_TO_LOGGABLE_STR(p_bd_addr) - << StringPrintf(" PSM: 0x%04x", psm); + log::verbose("BDA: {} PSM: 0x{:04x}", ADDRESS_TO_LOGGABLE_STR(p_bd_addr), + psm); /* Fail if we have not established communications with the controller */ if (!BTM_IsDeviceUp()) { - LOG_WARN("%s BTU not ready", __func__); + log::warn("BTU not ready"); return 0; } /* Fail if the PSM is not registered */ tL2C_RCB* p_rcb = l2cu_find_ble_rcb_by_psm(psm); if (p_rcb == NULL) { - LOG_WARN("%s No BLE RCB, PSM: 0x%04x", __func__, psm); + log::warn("No BLE RCB, PSM: 0x{:04x}", psm); return 0; } @@ -540,8 +541,8 @@ uint16_t L2CA_ConnectLECocReq(uint16_t psm, const RawAddress& p_bd_addr, if ((p_lcb == NULL) /* currently use BR/EDR for ERTM mode l2cap connection */ || (!l2cu_create_conn_le(p_lcb))) { - LOG_WARN("%s conn not started for PSM: 0x%04x p_lcb: 0x%p", __func__, - psm, p_lcb); + log::warn("conn not started for PSM: 0x{:04x} p_lcb: 0x{}", psm, + fmt::ptr(p_lcb)); return 0; } } @@ -549,7 +550,7 @@ uint16_t L2CA_ConnectLECocReq(uint16_t psm, const RawAddress& p_bd_addr, /* Allocate a channel control block */ tL2C_CCB* p_ccb = l2cu_allocate_ccb(p_lcb, 0); if (p_ccb == NULL) { - LOG_WARN("%s no CCB, PSM: 0x%04x", __func__, psm); + log::warn("no CCB, PSM: 0x{:04x}", psm); return 0; } @@ -567,7 +568,7 @@ uint16_t L2CA_ConnectLECocReq(uint16_t psm, const RawAddress& p_bd_addr, /* If link is up, start the L2CAP connection */ if (p_lcb->link_state == LST_CONNECTED) { if (p_ccb->p_lcb->transport == BT_TRANSPORT_LE) { - LOG_VERBOSE("%s LE Link is up", __func__); + log::verbose("LE Link is up"); // post this asynchronously to avoid out-of-order callback invocation // should this operation fail do_in_main_thread( @@ -583,14 +584,13 @@ uint16_t L2CA_ConnectLECocReq(uint16_t psm, const RawAddress& p_bd_addr, * arrives */ else if (p_lcb->link_state == LST_DISCONNECTING) { - LOG_VERBOSE("%s link disconnecting: RETRY LATER", __func__); + log::verbose("link disconnecting: RETRY LATER"); /* Save ccb so it can be started after disconnect is finished */ p_lcb->p_pending_ccb = p_ccb; } - LOG_VERBOSE("%s(psm: 0x%04x) returned CID: 0x%04x", __func__, psm, - p_ccb->local_cid); + log::verbose("(psm: 0x{:04x}) returned CID: 0x{:04x}", psm, p_ccb->local_cid); /* Return the local CID as our handle */ return p_ccb->local_cid; @@ -610,11 +610,11 @@ uint16_t L2CA_ConnectLECocReq(uint16_t psm, const RawAddress& p_bd_addr, * ******************************************************************************/ bool L2CA_GetPeerLECocConfig(uint16_t lcid, tL2CAP_LE_CFG_INFO* peer_cfg) { - LOG_VERBOSE("%s CID: 0x%04x", __func__, lcid); + log::verbose("CID: 0x{:04x}", lcid); tL2C_CCB* p_ccb = l2cu_find_ccb_by_cid(NULL, lcid); if (p_ccb == NULL) { - LOG_ERROR("%s No CCB for CID:0x%04x", __func__, lcid); + log::error("No CCB for CID:0x{:04x}", lcid); return false; } @@ -639,13 +639,13 @@ uint16_t L2CA_GetPeerLECocCredit(const RawAddress& bd_addr, uint16_t lcid) { tL2C_LCB* p_lcb = l2cu_find_lcb_by_bd_addr(bd_addr, BT_TRANSPORT_LE); if (p_lcb == NULL) { /* No link. Get an LCB and start link establishment */ - LOG_WARN("%s no LCB", __func__); + log::warn("no LCB"); return L2CAP_LE_CREDIT_MAX; } tL2C_CCB* p_ccb = l2cu_find_ccb_by_cid(p_lcb, lcid); if (p_ccb == NULL) { - LOG_ERROR("%s No CCB for CID:0x%04x", __func__, lcid); + log::error("No CCB for CID:0x{:04x}", lcid); return L2CAP_LE_CREDIT_MAX; } @@ -671,15 +671,15 @@ uint16_t L2CA_GetPeerLECocCredit(const RawAddress& bd_addr, uint16_t lcid) { bool L2CA_ConnectCreditBasedRsp(const RawAddress& p_bd_addr, uint8_t id, std::vector<uint16_t>& accepted_lcids, uint16_t result, tL2CAP_LE_CFG_INFO* p_cfg) { - VLOG(1) << __func__ << " BDA: " << ADDRESS_TO_LOGGABLE_STR(p_bd_addr) - << StringPrintf(" num of cids: %d Result: %d", - int(accepted_lcids.size()), +result); + log::verbose("BDA: {} num of cids: {} Result: {}", + ADDRESS_TO_LOGGABLE_STR(p_bd_addr), int(accepted_lcids.size()), + result); /* First, find the link control block */ tL2C_LCB* p_lcb = l2cu_find_lcb_by_bd_addr(p_bd_addr, BT_TRANSPORT_LE); if (p_lcb == NULL) { /* No link. Get an LCB and start link establishment */ - LOG_WARN("%s no LCB", __func__); + log::warn("no LCB"); return false; } @@ -688,14 +688,14 @@ bool L2CA_ConnectCreditBasedRsp(const RawAddress& p_bd_addr, uint8_t id, tL2C_CCB* p_ccb = l2cu_find_ccb_by_cid(p_lcb, p_lcb->pending_lead_cid); if (!p_ccb) { - LOG_ERROR("%s No CCB for CID:0x%04x", __func__, p_lcb->pending_lead_cid); + log::error("No CCB for CID:0x{:04x}", p_lcb->pending_lead_cid); return false; } for (uint16_t cid : accepted_lcids) { tL2C_CCB* temp_p_ccb = l2cu_find_ccb_by_cid(p_lcb, cid); if (temp_p_ccb == NULL) { - LOG_WARN("%s no CCB", __func__); + log::warn("no CCB"); return false; } @@ -707,8 +707,7 @@ bool L2CA_ConnectCreditBasedRsp(const RawAddress& p_bd_addr, uint8_t id, /* The IDs must match */ if (p_ccb->remote_id != id) { - LOG_WARN("%s bad id. Expected: %d Got: %d", __func__, p_ccb->remote_id, - id); + log::warn("bad id. Expected: {} Got: {}", p_ccb->remote_id, id); return false; } @@ -743,46 +742,46 @@ bool L2CA_ConnectCreditBasedRsp(const RawAddress& p_bd_addr, uint8_t id, std::vector<uint16_t> L2CA_ConnectCreditBasedReq(uint16_t psm, const RawAddress& p_bd_addr, tL2CAP_LE_CFG_INFO* p_cfg) { - VLOG(1) << __func__ << " BDA: " << ADDRESS_TO_LOGGABLE_STR(p_bd_addr) - << StringPrintf(" PSM: 0x%04x", psm); + log::verbose("BDA: {} PSM: 0x{:04x}", ADDRESS_TO_LOGGABLE_STR(p_bd_addr), + psm); std::vector<uint16_t> allocated_cids; /* Fail if we have not established communications with the controller */ if (!BTM_IsDeviceUp()) { - LOG_WARN("%s BTU not ready", __func__); + log::warn("BTU not ready"); return allocated_cids; } if (!p_cfg) { - LOG_WARN("%s p_cfg is NULL", __func__); + log::warn("p_cfg is NULL"); return allocated_cids; } /* Fail if the PSM is not registered */ tL2C_RCB* p_rcb = l2cu_find_ble_rcb_by_psm(psm); if (p_rcb == NULL) { - LOG_WARN("%s No BLE RCB, PSM: 0x%04x", __func__, psm); + log::warn("No BLE RCB, PSM: 0x{:04x}", psm); return allocated_cids; } /* First, see if we already have a le link to the remote */ tL2C_LCB* p_lcb = l2cu_find_lcb_by_bd_addr(p_bd_addr, BT_TRANSPORT_LE); if (p_lcb == NULL) { - LOG_WARN("%s No link available", __func__); + log::warn("No link available"); return allocated_cids; } if (p_lcb->link_state != LST_CONNECTED) { - LOG_WARN("%s incorrect link state: %d", __func__, p_lcb->link_state); + log::warn("incorrect link state: {}", p_lcb->link_state); return allocated_cids; } - LOG_VERBOSE("%s LE Link is up", __func__); + log::verbose("LE Link is up"); /* Check if there is no ongoing connection request */ if (p_lcb->pending_ecoc_conn_cnt > 0) { - LOG_WARN("There is ongoing connection request, PSM: 0x%04x", psm); + log::warn("There is ongoing connection request, PSM: 0x{:04x}", psm); return allocated_cids; } @@ -800,7 +799,7 @@ std::vector<uint16_t> L2CA_ConnectCreditBasedReq(uint16_t psm, l2cu_allocate_ccb(p_lcb, 0, psm == BT_PSM_EATT /* is_eatt */); if (p_ccb == NULL) { if (i == 0) { - LOG_WARN("%s no CCB, PSM: 0x%04x", __func__, psm); + log::warn("no CCB, PSM: 0x{:04x}", psm); return allocated_cids; } else { break; @@ -832,8 +831,8 @@ std::vector<uint16_t> L2CA_ConnectCreditBasedReq(uint16_t psm, p_lcb->pending_ecoc_conn_cnt = (uint16_t)(allocated_cids.size()); l2c_csm_execute(p_ccb_primary, L2CEVT_L2CA_CREDIT_BASED_CONNECT_REQ, NULL); - LOG_VERBOSE("%s(psm: 0x%04x) returned CID: 0x%04x", __func__, psm, - p_ccb_primary->local_cid); + log::verbose("(psm: 0x{:04x}) returned CID: 0x{:04x}", psm, + p_ccb_primary->local_cid); return allocated_cids; } @@ -856,10 +855,10 @@ bool L2CA_ReconfigCreditBasedConnsReq(const RawAddress& bda, tL2CAP_LE_CFG_INFO* p_cfg) { tL2C_CCB* p_ccb; - LOG_VERBOSE("L2CA_ReconfigCreditBasedConnsReq() "); + log::verbose("L2CA_ReconfigCreditBasedConnsReq() "); if (lcids.empty()) { - LOG_WARN("L2CAP - no lcids given to %s", __func__); + log::warn("L2CAP - empty lcids"); return (false); } @@ -867,28 +866,28 @@ bool L2CA_ReconfigCreditBasedConnsReq(const RawAddress& bda, p_ccb = l2cu_find_ccb_by_cid(NULL, cid); if (!p_ccb) { - LOG_WARN("L2CAP - no CCB for L2CA_cfg_req, CID: %d", cid); + log::warn("L2CAP - no CCB for L2CA_cfg_req, CID: {}", cid); return (false); } if ((p_ccb->local_conn_cfg.mtu > p_cfg->mtu) || (p_ccb->local_conn_cfg.mps > p_cfg->mps)) { - LOG_WARN("L2CAP - MPS or MTU reduction, CID: %d", cid); + log::warn("L2CAP - MPS or MTU reduction, CID: {}", cid); return (false); } } if (p_cfg->mtu > L2CAP_MTU_SIZE) { - LOG_WARN("L2CAP - adjust MTU: %u too large", p_cfg->mtu); + log::warn("L2CAP - adjust MTU: {} too large", p_cfg->mtu); p_cfg->mtu = L2CAP_MTU_SIZE; } /* Mark all the p_ccbs which going to be reconfigured */ for (uint16_t cid : lcids) { - LOG_VERBOSE(" cid: %d", cid); + log::verbose("cid: {}", cid); p_ccb = l2cu_find_ccb_by_cid(NULL, cid); if (!p_ccb) { - LOG(ERROR) << __func__ << "Missing cid? " << int(cid); + log::error("Missing cid? {}", int(cid)); return (false); } p_ccb->reconfig_started = true; @@ -927,11 +926,11 @@ bool L2CA_DisconnectReq(uint16_t cid) { /* Find the channel control block. We don't know the link it is on. */ p_ccb = l2cu_find_ccb_by_cid(NULL, cid); if (p_ccb == NULL) { - LOG_WARN("L2CAP - no CCB for L2CA_disc_req, CID: %d", cid); + log::warn("L2CAP - no CCB for L2CA_disc_req, CID: {}", cid); return (false); } - LOG_DEBUG("L2CAP Local disconnect request CID: 0x%04x", cid); + log::debug("L2CAP Local disconnect request CID: 0x{:04x}", cid); l2c_csm_execute(p_ccb, L2CEVT_L2CA_DISCONNECT_REQ, NULL); @@ -1009,12 +1008,12 @@ bool L2CA_UseLatencyMode(const RawAddress& bd_addr, bool use_latency_mode) { /* Find the link control block for the acl channel */ tL2C_LCB* p_lcb = l2cu_find_lcb_by_bd_addr(bd_addr, BT_TRANSPORT_BR_EDR); if (p_lcb == nullptr) { - LOG_WARN("L2CAP - no LCB for L2CA_SetUseLatencyMode, BDA: %s", - ADDRESS_TO_LOGGABLE_CSTR(bd_addr)); + log::warn("L2CAP - no LCB for L2CA_SetUseLatencyMode, BDA: {}", + ADDRESS_TO_LOGGABLE_CSTR(bd_addr)); return false; } - LOG_INFO("BDA: %s, use_latency_mode: %s", ADDRESS_TO_LOGGABLE_CSTR(bd_addr), - use_latency_mode ? "true" : "false"); + log::info("BDA: {}, use_latency_mode: {}", ADDRESS_TO_LOGGABLE_CSTR(bd_addr), + use_latency_mode ? "true" : "false"); p_lcb->use_latency_mode = use_latency_mode; return true; } @@ -1031,8 +1030,8 @@ bool L2CA_UseLatencyMode(const RawAddress& bd_addr, bool use_latency_mode) { * ******************************************************************************/ bool L2CA_SetAclPriority(const RawAddress& bd_addr, tL2CAP_PRIORITY priority) { - VLOG(1) << __func__ << " BDA: " << ADDRESS_TO_LOGGABLE_STR(bd_addr) - << ", priority: " << std::to_string(priority); + log::verbose("BDA: {}, priority: {}", ADDRESS_TO_LOGGABLE_STR(bd_addr), + priority); return (l2cu_set_acl_priority(bd_addr, priority, false)); } @@ -1046,8 +1045,8 @@ bool L2CA_SetAclPriority(const RawAddress& bd_addr, tL2CAP_PRIORITY priority) { * ******************************************************************************/ bool L2CA_SetAclLatency(const RawAddress& bd_addr, tL2CAP_LATENCY latency) { - LOG_INFO("BDA: %s, latency: %s", ADDRESS_TO_LOGGABLE_CSTR(bd_addr), - std::to_string(latency).c_str()); + log::info("BDA: {}, latency: {}", ADDRESS_TO_LOGGABLE_CSTR(bd_addr), + std::to_string(latency)); return l2cu_set_acl_latency(bd_addr, latency); } @@ -1063,12 +1062,13 @@ bool L2CA_SetAclLatency(const RawAddress& bd_addr, tL2CAP_LATENCY latency) { bool L2CA_SetTxPriority(uint16_t cid, tL2CAP_CHNL_PRIORITY priority) { tL2C_CCB* p_ccb; - LOG_VERBOSE("L2CA_SetTxPriority() CID: 0x%04x, priority:%d", cid, priority); + log::verbose("L2CA_SetTxPriority() CID: 0x{:04x}, priority:{}", cid, + priority); /* Find the channel control block. We don't know the link it is on. */ p_ccb = l2cu_find_ccb_by_cid(NULL, cid); if (p_ccb == NULL) { - LOG_WARN("L2CAP - no CCB for L2CA_SetTxPriority, CID: %d", cid); + log::warn("L2CAP - no CCB for L2CA_SetTxPriority, CID: {}", cid); return (false); } @@ -1098,13 +1098,13 @@ bool L2CA_GetPeerFeatures(const RawAddress& bd_addr, uint32_t* p_ext_feat, /* We must already have a link to the remote */ p_lcb = l2cu_find_lcb_by_bd_addr(bd_addr, BT_TRANSPORT_BR_EDR); if (p_lcb == NULL) { - LOG(WARNING) << __func__ << " No BDA: " << ADDRESS_TO_LOGGABLE_STR(bd_addr); + log::warn("No BDA: {}", ADDRESS_TO_LOGGABLE_STR(bd_addr)); return false; } - VLOG(1) << __func__ << " BDA: " << ADDRESS_TO_LOGGABLE_STR(bd_addr) - << StringPrintf(" ExtFea: 0x%08x Chnl_Mask[0]: 0x%02x", - p_lcb->peer_ext_fea, p_lcb->peer_chnl_mask[0]); + log::verbose("BDA: {} ExtFea: 0x{:08x} Chnl_Mask[0]: 0x{:02x}", + ADDRESS_TO_LOGGABLE_STR(bd_addr), p_lcb->peer_ext_fea, + p_lcb->peer_chnl_mask[0]); *p_ext_feat = p_lcb->peer_ext_fea; @@ -1150,13 +1150,12 @@ bool L2CA_RegisterFixedChannel(uint16_t fixed_cid, tL2CAP_FIXED_CHNL_REG* p_freg) { if ((fixed_cid < L2CAP_FIRST_FIXED_CHNL) || (fixed_cid > L2CAP_LAST_FIXED_CHNL)) { - LOG_ERROR("Invalid fixed CID: 0x%04x", fixed_cid); + log::error("Invalid fixed CID: 0x{:04x}", fixed_cid); return false; } l2cb.fixed_reg[fixed_cid - L2CAP_FIRST_FIXED_CHNL] = *p_freg; - LOG_DEBUG("Registered fixed channel:%s", - fixed_channel_text(fixed_cid).c_str()); + log::debug("Registered fixed channel:{}", fixed_channel_text(fixed_cid)); return true; } @@ -1176,20 +1175,20 @@ bool L2CA_ConnectFixedChnl(uint16_t fixed_cid, const RawAddress& rem_bda) { tL2C_LCB* p_lcb; tBT_TRANSPORT transport = BT_TRANSPORT_BR_EDR; - LOG_DEBUG(" fixed_cid:0x%04x", fixed_cid); + log::debug("fixed_cid:0x{:04x}", fixed_cid); // Check CID is valid and registered if ((fixed_cid < L2CAP_FIRST_FIXED_CHNL) || (fixed_cid > L2CAP_LAST_FIXED_CHNL) || (l2cb.fixed_reg[fixed_cid - L2CAP_FIRST_FIXED_CHNL].pL2CA_FixedData_Cb == NULL)) { - LOG_ERROR("Invalid fixed_cid:0x%04x", fixed_cid); + log::error("Invalid fixed_cid:0x{:04x}", fixed_cid); return (false); } // Fail if BT is not yet up if (!BTM_IsDeviceUp()) { - LOG_WARN("Bt controller is not ready fixed_cid:0x%04x", fixed_cid); + log::warn("Bt controller is not ready fixed_cid:0x{:04x}", fixed_cid); return (false); } @@ -1211,21 +1210,21 @@ bool L2CA_ConnectFixedChnl(uint16_t fixed_cid, const RawAddress& rem_bda) { // Check for supported channel if (!(peer_channel_mask & (1 << fixed_cid))) { - LOG_INFO("Peer device does not support fixed_cid:0x%04x", fixed_cid); + log::info("Peer device does not support fixed_cid:0x{:04x}", fixed_cid); return false; } // Get a CCB and link the lcb to it if (!l2cu_initialize_fixed_ccb(p_lcb, fixed_cid)) { - LOG_WARN("Unable to allocate fixed channel resource fixed_cid:0x%04x", - fixed_cid); + log::warn("Unable to allocate fixed channel resource fixed_cid:0x{:04x}", + fixed_cid); return false; } // racing with disconnecting, queue the connection request if (p_lcb->link_state == LST_DISCONNECTING) { - LOG_DEBUG( - "Link is disconnecting so deferring connection fixed_cid:0x%04x", + log::debug( + "Link is disconnecting so deferring connection fixed_cid:0x{:04x}", fixed_cid); /* Save ccb so it can be started after disconnect is finished */ p_lcb->p_pending_ccb = @@ -1241,15 +1240,16 @@ bool L2CA_ConnectFixedChnl(uint16_t fixed_cid, const RawAddress& rem_bda) { // No link. Get an LCB and start link establishment p_lcb = l2cu_allocate_lcb(rem_bda, false, transport); if (p_lcb == NULL) { - LOG_WARN("Unable to allocate link resource for connection fixed_cid:0x%04x", - fixed_cid); + log::warn( + "Unable to allocate link resource for connection fixed_cid:0x{:04x}", + fixed_cid); return false; } // Get a CCB and link the lcb to it if (!l2cu_initialize_fixed_ccb(p_lcb, fixed_cid)) { - LOG_WARN("Unable to allocate fixed channel resource fixed_cid:0x%04x", - fixed_cid); + log::warn("Unable to allocate fixed channel resource fixed_cid:0x{:04x}", + fixed_cid); l2cu_release_lcb(p_lcb); return false; } @@ -1257,8 +1257,9 @@ bool L2CA_ConnectFixedChnl(uint16_t fixed_cid, const RawAddress& rem_bda) { if (transport == BT_TRANSPORT_LE) { bool ret = l2cu_create_conn_le(p_lcb); if (!ret) { - LOG_WARN("Unable to create fixed channel le connection fixed_cid:0x%04x", - fixed_cid); + log::warn( + "Unable to create fixed channel le connection fixed_cid:0x{:04x}", + fixed_cid); l2cu_release_lcb(p_lcb); return false; } @@ -1294,13 +1295,13 @@ uint16_t L2CA_SendFixedChnlData(uint16_t fixed_cid, const RawAddress& rem_bda, (fixed_cid > L2CAP_LAST_FIXED_CHNL) || (l2cb.fixed_reg[fixed_cid - L2CAP_FIRST_FIXED_CHNL].pL2CA_FixedData_Cb == NULL)) { - LOG_WARN("No service registered or invalid CID: 0x%04x", fixed_cid); + log::warn("No service registered or invalid CID: 0x{:04x}", fixed_cid); osi_free(p_buf); return (L2CAP_DW_FAILED); } if (!BTM_IsDeviceUp()) { - LOG_WARN("Controller is not ready CID: 0x%04x", fixed_cid); + log::warn("Controller is not ready CID: 0x{:04x}", fixed_cid); osi_free(p_buf); return (L2CAP_DW_FAILED); } @@ -1308,7 +1309,8 @@ uint16_t L2CA_SendFixedChnlData(uint16_t fixed_cid, const RawAddress& rem_bda, p_lcb = l2cu_find_lcb_by_bd_addr(rem_bda, transport); if (p_lcb == NULL || p_lcb->link_state == LST_DISCONNECTING) { /* if link is disconnecting, also report data sending failure */ - LOG_WARN("Link is disconnecting or does not exist CID: 0x%04x", fixed_cid); + log::warn("Link is disconnecting or does not exist CID: 0x{:04x}", + fixed_cid); osi_free(p_buf); return (L2CAP_DW_FAILED); } @@ -1322,7 +1324,7 @@ uint16_t L2CA_SendFixedChnlData(uint16_t fixed_cid, const RawAddress& rem_bda, peer_channel_mask = p_lcb->peer_chnl_mask[0]; if ((peer_channel_mask & (1 << fixed_cid)) == 0) { - LOG_WARN("Peer does not support fixed channel CID: 0x%04x", fixed_cid); + log::warn("Peer does not support fixed channel CID: 0x{:04x}", fixed_cid); osi_free(p_buf); return (L2CAP_DW_FAILED); } @@ -1332,16 +1334,16 @@ uint16_t L2CA_SendFixedChnlData(uint16_t fixed_cid, const RawAddress& rem_bda, if (!p_lcb->p_fixed_ccbs[fixed_cid - L2CAP_FIRST_FIXED_CHNL]) { if (!l2cu_initialize_fixed_ccb(p_lcb, fixed_cid)) { - LOG_WARN("No channel control block found for CID: 0x%4x", fixed_cid); + log::warn("No channel control block found for CID: 0x{:4x}", fixed_cid); osi_free(p_buf); return (L2CAP_DW_FAILED); } } if (p_lcb->p_fixed_ccbs[fixed_cid - L2CAP_FIRST_FIXED_CHNL]->cong_sent) { - LOG_WARN( - "Unable to send data due to congestion CID: 0x%04x xmit_hold_q.count: " - "%zu buff_quota: %u", + log::warn( + "Unable to send data due to congestion CID: 0x{:04x} " + "xmit_hold_q.count: {} buff_quota: {}", fixed_cid, fixed_queue_length( p_lcb->p_fixed_ccbs[fixed_cid - L2CAP_FIRST_FIXED_CHNL] @@ -1351,7 +1353,7 @@ uint16_t L2CA_SendFixedChnlData(uint16_t fixed_cid, const RawAddress& rem_bda, return (L2CAP_DW_FAILED); } - LOG_DEBUG("Enqueued data for CID: 0x%04x len:%hu", fixed_cid, p_buf->len); + log::debug("Enqueued data for CID: 0x{:04x} len:{}", fixed_cid, p_buf->len); l2c_enqueue_peer_data(p_lcb->p_fixed_ccbs[fixed_cid - L2CAP_FIRST_FIXED_CHNL], p_buf); @@ -1365,7 +1367,7 @@ uint16_t L2CA_SendFixedChnlData(uint16_t fixed_cid, const RawAddress& rem_bda, } if (p_lcb->p_fixed_ccbs[fixed_cid - L2CAP_FIRST_FIXED_CHNL]->cong_sent) { - LOG_DEBUG("Link congested for CID: 0x%04x", fixed_cid); + log::debug("Link congested for CID: 0x{:04x}", fixed_cid); return (L2CAP_DW_CONGESTED); } @@ -1395,7 +1397,7 @@ bool L2CA_RemoveFixedChnl(uint16_t fixed_cid, const RawAddress& rem_bda) { (fixed_cid > L2CAP_LAST_FIXED_CHNL) || (l2cb.fixed_reg[fixed_cid - L2CAP_FIRST_FIXED_CHNL].pL2CA_FixedData_Cb == NULL)) { - LOG_ERROR("L2CA_RemoveFixedChnl() Invalid CID: 0x%04x", fixed_cid); + log::error("L2CA_RemoveFixedChnl() Invalid CID: 0x{:04x}", fixed_cid); return (false); } @@ -1407,13 +1409,13 @@ bool L2CA_RemoveFixedChnl(uint16_t fixed_cid, const RawAddress& rem_bda) { if (((p_lcb) == NULL) || (!p_lcb->p_fixed_ccbs[fixed_cid - L2CAP_FIRST_FIXED_CHNL])) { - LOG(WARNING) << __func__ << " BDA: " << ADDRESS_TO_LOGGABLE_STR(rem_bda) - << StringPrintf(" CID: 0x%04x not connected", fixed_cid); + log::warn("BDA: {} CID: 0x{:04x} not connected", + ADDRESS_TO_LOGGABLE_STR(rem_bda), fixed_cid); return (false); } - VLOG(2) << __func__ << " BDA: " << ADDRESS_TO_LOGGABLE_STR(rem_bda) - << StringPrintf(" CID: 0x%04x", fixed_cid); + log::verbose("BDA: {} CID: 0x{:04x}", ADDRESS_TO_LOGGABLE_STR(rem_bda), + fixed_cid); /* Release the CCB, starting an inactivity timeout on the LCB if no other CCBs * exist */ @@ -1458,8 +1460,8 @@ bool L2CA_SetLeGattTimeout(const RawAddress& rem_bda, uint16_t idle_tout) { tL2C_LCB* p_lcb = l2cu_find_lcb_by_bd_addr(rem_bda, BT_TRANSPORT_LE); if (((p_lcb) == NULL) || (!p_lcb->p_fixed_ccbs[kAttCid - L2CAP_FIRST_FIXED_CHNL])) { - LOG(WARNING) << __func__ << " BDA: " << ADDRESS_TO_LOGGABLE_STR(rem_bda) - << StringPrintf(" CID: 0x%04x not connected", kAttCid); + log::warn("BDA: {} CID: 0x{:04x} not connected", + ADDRESS_TO_LOGGABLE_STR(rem_bda), kAttCid); return (false); } @@ -1481,8 +1483,7 @@ bool L2CA_MarkLeLinkAsActive(const RawAddress& rem_bda) { if (p_lcb == NULL) { return false; } - LOG(INFO) << __func__ << "setting link to " - << ADDRESS_TO_LOGGABLE_STR(rem_bda) << " as active"; + log::info("setting link to {} as active", ADDRESS_TO_LOGGABLE_STR(rem_bda)); p_lcb->with_active_local_clients = true; return true; } @@ -1500,7 +1501,7 @@ bool L2CA_MarkLeLinkAsActive(const RawAddress& rem_bda) { * ******************************************************************************/ uint8_t L2CA_DataWrite(uint16_t cid, BT_HDR* p_data) { - LOG_VERBOSE("L2CA_DataWrite() CID: 0x%04x Len: %d", cid, p_data->len); + log::verbose("L2CA_DataWrite() CID: 0x{:04x} Len: {}", cid, p_data->len); return l2c_data_write(cid, p_data, L2CAP_FLUSHABLE_CH_BASED); } @@ -1524,14 +1525,14 @@ bool L2CA_SetChnlFlushability(uint16_t cid, bool is_flushable) { /* Find the channel control block. We don't know the link it is on. */ p_ccb = l2cu_find_ccb_by_cid(NULL, cid); if (p_ccb == NULL) { - LOG_WARN("L2CAP - no CCB for L2CA_SetChnlFlushability, CID: %d", cid); + log::warn("L2CAP - no CCB for L2CA_SetChnlFlushability, CID: {}", cid); return (false); } p_ccb->is_flushable = is_flushable; - LOG_VERBOSE("L2CA_SetChnlFlushability() CID: 0x%04x is_flushable: %d", cid, - is_flushable); + log::verbose("L2CA_SetChnlFlushability() CID: 0x{:04x} is_flushable: {}", + cid, is_flushable); return (true); } @@ -1558,19 +1559,20 @@ uint16_t L2CA_FlushChannel(uint16_t lcid, uint16_t num_to_flush) { p_ccb = l2cu_find_ccb_by_cid(NULL, lcid); if (!p_ccb || (p_ccb->p_lcb == NULL)) { - LOG_WARN("L2CA_FlushChannel() abnormally returning 0 CID: 0x%04x", lcid); + log::warn("L2CA_FlushChannel() abnormally returning 0 CID: 0x{:04x}", + lcid); return (0); } p_lcb = p_ccb->p_lcb; if (num_to_flush != L2CAP_FLUSH_CHANS_GET) { - LOG_VERBOSE( - "L2CA_FlushChannel (FLUSH) CID: 0x%04x NumToFlush: %d QC: %zu " - "pFirst: 0x%p", + log::verbose( + "L2CA_FlushChannel (FLUSH) CID: 0x{:04x} NumToFlush: {} QC: {} " + "pFirst: 0x{}", lcid, num_to_flush, fixed_queue_length(p_ccb->xmit_hold_q), - fixed_queue_try_peek_first(p_ccb->xmit_hold_q)); + fmt::ptr(fixed_queue_try_peek_first(p_ccb->xmit_hold_q))); } else { - LOG_VERBOSE("L2CA_FlushChannel (QUERY) CID: 0x%04x", lcid); + log::verbose("L2CA_FlushChannel (QUERY) CID: 0x{:04x}", lcid); } /* Cannot flush eRTM buffers once they have a sequence number */ @@ -1627,8 +1629,8 @@ uint16_t L2CA_FlushChannel(uint16_t lcid, uint16_t num_to_flush) { num_left += fixed_queue_length(p_ccb->xmit_hold_q); /* Return the local number of buffers left for the CID */ - LOG_VERBOSE("L2CA_FlushChannel() flushed: %u + %u, num_left: %u", - num_flushed1, num_flushed2, num_left); + log::verbose("L2CA_FlushChannel() flushed: {} + {}, num_left: {}", + num_flushed1, num_flushed2, num_left); /* If we were congested, and now we are not, tell the app */ l2cu_check_channel_congestion(p_ccb); @@ -1661,7 +1663,7 @@ void L2CA_SetMediaStreamChannel(uint16_t local_media_cid, bool status) { bluetooth::hal::SnoopLogger* snoop_logger = bluetooth::shim::GetSnoopLogger(); if (snoop_logger == nullptr) { - LOG_ERROR("bluetooth::shim::GetSnoopLogger() is nullptr"); + log::error("bluetooth::shim::GetSnoopLogger() is nullptr"); return; } @@ -1669,8 +1671,8 @@ void L2CA_SetMediaStreamChannel(uint16_t local_media_cid, bool status) { return; } - LOG_DEBUG("local_media_cid=%d, status=%s", local_media_cid, - (status ? "add" : "remove")); + log::debug("local_media_cid={}, status={}", local_media_cid, + (status ? "add" : "remove")); if (status) { for (i = 0; i < MAX_ACTIVE_AVDT_CONN; i++) { @@ -1681,7 +1683,7 @@ void L2CA_SetMediaStreamChannel(uint16_t local_media_cid, bool status) { } if (set_channel < 0) { - LOG_ERROR("%s: No empty slot found to set media channel", __func__); + log::error("No empty slot found to set media channel"); return; } @@ -1699,10 +1701,9 @@ void L2CA_SetMediaStreamChannel(uint16_t local_media_cid, bool status) { av_media_channels[set_channel].local_cid, av_media_channels[set_channel].p_ccb->remote_cid); - LOG_VERBOSE( - "%s: Set A2DP media snoop filtering for local_cid: %d, remote_cid: %d", - __func__, local_media_cid, - av_media_channels[set_channel].p_ccb->remote_cid); + log::verbose( + "Set A2DP media snoop filtering for local_cid: {}, remote_cid: {}", + local_media_cid, av_media_channels[set_channel].p_ccb->remote_cid); } else { for (i = 0; i < MAX_ACTIVE_AVDT_CONN; i++) { if (av_media_channels[i].is_active && @@ -1713,8 +1714,8 @@ void L2CA_SetMediaStreamChannel(uint16_t local_media_cid, bool status) { } if (set_channel < 0) { - LOG_ERROR("%s: The channel %d not found in active media channels", - __func__, local_media_cid); + log::error("The channel {} not found in active media channels", + local_media_cid); return; } @@ -1727,8 +1728,8 @@ void L2CA_SetMediaStreamChannel(uint16_t local_media_cid, bool status) { av_media_channels[set_channel].p_ccb->p_lcb->Handle(), av_media_channels[set_channel].local_cid); - LOG_VERBOSE("%s: Reset A2DP media snoop filtering for local_cid: %d", - __func__, local_media_cid); + log::verbose("Reset A2DP media snoop filtering for local_cid: {}", + local_media_cid); } av_media_channels[set_channel].is_active = status; diff --git a/system/stack/l2cap/l2c_ble.cc b/system/stack/l2cap/l2c_ble.cc index e1d73940c2568e538148a2a43862ac3c6a0de709..d83d253824ae88e1f31564fac5a75b3eb3fb901e 100644 --- a/system/stack/l2cap/l2c_ble.cc +++ b/system/stack/l2cap/l2c_ble.cc @@ -26,6 +26,7 @@ #include <base/logging.h> #include <base/strings/stringprintf.h> +#include <bluetooth/log.h> #include <log/log.h> #ifdef __ANDROID__ @@ -57,6 +58,8 @@ #include "stack/l2cap/l2c_int.h" #include "types/raw_address.h" +using namespace bluetooth; + namespace { constexpr char kBtmLogTag[] = "L2CAP"; @@ -75,9 +78,9 @@ void L2CA_Consolidate(const RawAddress& identity_addr, const RawAddress& rpa) { return; } - LOG_INFO("consolidating l2c_lcb record %s -> %s", - ADDRESS_TO_LOGGABLE_CSTR(rpa), - ADDRESS_TO_LOGGABLE_CSTR(identity_addr)); + log::info("consolidating l2c_lcb record {} -> {}", + ADDRESS_TO_LOGGABLE_CSTR(rpa), + ADDRESS_TO_LOGGABLE_CSTR(identity_addr)); p_lcb->remote_bd_addr = identity_addr; } @@ -101,7 +104,7 @@ hci_role_t L2CA_GetBleConnRole(const RawAddress& bd_addr) { void l2cble_notify_le_connection(const RawAddress& bda) { tL2C_LCB* p_lcb = l2cu_find_lcb_by_bd_addr(bda, BT_TRANSPORT_LE); if (p_lcb == nullptr) { - LOG_WARN("Received notification for le connection but no lcb found"); + log::warn("Received notification for le connection but no lcb found"); return; } @@ -138,17 +141,17 @@ bool l2cble_conn_comp(uint16_t handle, uint8_t role, const RawAddress& bda, if (!p_lcb) { p_lcb = l2cu_allocate_lcb(bda, false, BT_TRANSPORT_LE); if (!p_lcb) { - LOG_ERROR("Unable to allocate link resource for le acl connection"); + log::error("Unable to allocate link resource for le acl connection"); return false; } else { if (!l2cu_initialize_fixed_ccb(p_lcb, L2CAP_ATT_CID)) { - LOG_ERROR("Unable to allocate channel resource for le acl connection"); + log::error("Unable to allocate channel resource for le acl connection"); return false; } } p_lcb->link_state = LST_CONNECTING; } else if (role == HCI_ROLE_CENTRAL && p_lcb->link_state != LST_CONNECTING) { - LOG_ERROR( + log::error( "Received le acl connection as role central but not in connecting " "state"); return false; @@ -248,7 +251,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { p_pkt_end = p + pkt_len; if (p + 4 > p_pkt_end) { - LOG(ERROR) << "invalid read"; + log::error("invalid read"); return; } @@ -258,8 +261,8 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { /* Check command length does not exceed packet length */ if ((p + cmd_len) > p_pkt_end) { - LOG_WARN("L2CAP - LE - format error, pkt_len: %d cmd_len: %d code: %d", - pkt_len, cmd_len, cmd_code); + log::warn("L2CAP - LE - format error, pkt_len: {} cmd_len: {} code: {}", + pkt_len, cmd_len, cmd_code); return; } @@ -268,8 +271,9 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { uint16_t reason; if (p + 2 > p_pkt_end) { - LOG(ERROR) << "invalid L2CAP_CMD_REJECT packet," - << " not containing enough data for `reason` field"; + log::error( + "invalid L2CAP_CMD_REJECT packet, not containing enough data for " + "`reason` field"); return; } @@ -291,7 +295,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CMD_BLE_UPDATE_REQ: if (p + 8 > p_pkt_end) { - LOG(ERROR) << "invalid read"; + log::error("invalid read"); return; } @@ -339,7 +343,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CMD_CREDIT_BASED_CONN_REQ: { if (p + 10 > p_pkt_end) { - LOG(ERROR) << "invalid L2CAP_CMD_CREDIT_BASED_CONN_REQ len"; + log::error("invalid L2CAP_CMD_CREDIT_BASED_CONN_REQ len"); return; } @@ -351,33 +355,31 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { /* Check how many channels remote side wants. */ num_of_channels = (p_pkt_end - p) / sizeof(uint16_t); if (num_of_channels > L2CAP_CREDIT_BASED_MAX_CIDS) { - LOG_WARN("L2CAP - invalid number of channels requested: %d", - num_of_channels); + log::warn("L2CAP - invalid number of channels requested: {}", + num_of_channels); l2cu_reject_credit_based_conn_req(p_lcb, id, L2CAP_CREDIT_BASED_MAX_CIDS, L2CAP_LE_RESULT_INVALID_PARAMETERS); return; } - LOG_DEBUG( - "Recv L2CAP_CMD_CREDIT_BASED_CONN_REQ with " - "mtu = %d, " - "mps = %d, " - "initial credit = %d" - "num_of_channels = %d", + log::debug( + "Recv L2CAP_CMD_CREDIT_BASED_CONN_REQ with mtu = {}, mps = {}, " + "initial credit = {}num_of_channels = {}", mtu, mps, initial_credit, num_of_channels); /* Check PSM Support */ p_rcb = l2cu_find_ble_rcb_by_psm(con_info.psm); if (p_rcb == NULL) { - LOG_WARN("L2CAP - rcvd conn req for unknown PSM: 0x%04x", con_info.psm); + log::warn("L2CAP - rcvd conn req for unknown PSM: 0x{:04x}", + con_info.psm); l2cu_reject_credit_based_conn_req(p_lcb, id, num_of_channels, L2CAP_LE_RESULT_NO_PSM); return; } if (p_lcb->pending_ecoc_conn_cnt > 0) { - LOG_WARN("L2CAP - L2CAP_CMD_CREDIT_BASED_CONN_REQ collision:"); + log::warn("L2CAP - L2CAP_CMD_CREDIT_BASED_CONN_REQ collision:"); if (p_rcb->api.pL2CA_CreditBasedCollisionInd_Cb && con_info.psm == BT_PSM_EATT) { (*p_rcb->api.pL2CA_CreditBasedCollisionInd_Cb)(p_lcb->remote_bd_addr); @@ -390,8 +392,8 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { p_lcb->pending_ecoc_conn_cnt = num_of_channels; if (!p_rcb->api.pL2CA_CreditBasedConnectInd_Cb) { - LOG_WARN("L2CAP - rcvd conn req for outgoing-only connection PSM: %d", - con_info.psm); + log::warn("L2CAP - rcvd conn req for outgoing-only connection PSM: {}", + con_info.psm); l2cu_reject_credit_based_conn_req(p_lcb, id, num_of_channels, L2CAP_CONN_NO_PSM); return; @@ -400,7 +402,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { /* validate the parameters */ if (mtu < L2CAP_CREDIT_BASED_MIN_MTU || mps < L2CAP_CREDIT_BASED_MIN_MPS || mps > L2CAP_LE_MAX_MPS) { - LOG_ERROR("L2CAP don't like the params"); + log::error("L2CAP don't like the params"); l2cu_reject_credit_based_conn_req(p_lcb, id, num_of_channels, L2CAP_LE_RESULT_INVALID_PARAMETERS); return; @@ -412,7 +414,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { STREAM_TO_UINT16(rcid, p); temp_p_ccb = l2cu_find_ccb_by_remote_cid(p_lcb, rcid); if (temp_p_ccb) { - LOG_WARN("L2CAP - rcvd conn req for duplicated cid: 0x%04x", rcid); + log::warn("L2CAP - rcvd conn req for duplicated cid: 0x{:04x}", rcid); p_lcb->pending_ecoc_connection_cids[i] = 0; p_lcb->pending_l2cap_result = L2CAP_LE_RESULT_SOURCE_CID_ALREADY_ALLOCATED; @@ -421,7 +423,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { temp_p_ccb = l2cu_allocate_ccb( p_lcb, 0, con_info.psm == BT_PSM_EATT /* is_eatt */); if (temp_p_ccb == NULL) { - LOG_ERROR("L2CAP - unable to allocate CCB"); + log::error("L2CAP - unable to allocate CCB"); p_lcb->pending_ecoc_connection_cids[i] = 0; p_lcb->pending_l2cap_result = L2CAP_LE_RESULT_NO_RESOURCES; continue; @@ -458,23 +460,23 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { } if (!lead_cid_set) { - LOG_ERROR("L2CAP - unable to allocate CCB"); + log::error("L2CAP - unable to allocate CCB"); l2cu_reject_credit_based_conn_req(p_lcb, id, num_of_channels, p_lcb->pending_l2cap_result); return; } - LOG_DEBUG("L2CAP - processing peer credit based connect request"); + log::debug("L2CAP - processing peer credit based connect request"); l2c_csm_execute(p_ccb, L2CEVT_L2CAP_CREDIT_BASED_CONNECT_REQ, NULL); break; } case L2CAP_CMD_CREDIT_BASED_CONN_RES: if (p + 8 > p_pkt_end) { - LOG(ERROR) << "invalid L2CAP_CMD_CREDIT_BASED_CONN_RES len"; + log::error("invalid L2CAP_CMD_CREDIT_BASED_CONN_RES len"); return; } - LOG_VERBOSE("Recv L2CAP_CMD_CREDIT_BASED_CONN_RES"); + log::verbose("Recv L2CAP_CMD_CREDIT_BASED_CONN_RES"); /* For all channels, see whose identifier matches this id */ for (temp_p_ccb = p_lcb->ccb_queue.p_first_ccb; temp_p_ccb; temp_p_ccb = temp_p_ccb->p_next_ccb) { @@ -485,7 +487,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { } if (!p_ccb) { - LOG_VERBOSE(" Cannot find matching connection req"); + log::verbose("Cannot find matching connection req"); con_info.l2cap_result = L2CAP_LE_RESULT_INVALID_SOURCE_CID; l2c_csm_execute(p_ccb, L2CEVT_L2CAP_CONNECT_RSP_NEG, &con_info); return; @@ -506,7 +508,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { con_info.l2cap_result == L2CAP_LE_RESULT_INSUFFICIENT_AUTHORIZATION || con_info.l2cap_result == L2CAP_LE_RESULT_UNACCEPTABLE_PARAMETERS || con_info.l2cap_result == L2CAP_LE_RESULT_INVALID_PARAMETERS) { - LOG_ERROR("L2CAP - not accepted. Status %d", con_info.l2cap_result); + log::error("L2CAP - not accepted. Status {}", con_info.l2cap_result); l2cble_handle_connect_rsp_neg(p_lcb, &con_info); return; } @@ -514,7 +516,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { /* validate the parameters */ if (mtu < L2CAP_CREDIT_BASED_MIN_MTU || mps < L2CAP_CREDIT_BASED_MIN_MPS || mps > L2CAP_LE_MAX_MPS) { - LOG_ERROR("L2CAP - invalid params"); + log::error("L2CAP - invalid params"); con_info.l2cap_result = L2CAP_LE_RESULT_INVALID_PARAMETERS; l2cble_handle_connect_rsp_neg(p_lcb, &con_info); return; @@ -524,20 +526,16 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { * good*/ num_of_channels = (p_pkt_end - p) / sizeof(uint16_t); if (num_of_channels != p_lcb->pending_ecoc_conn_cnt) { - LOG_ERROR( - "Incorrect response." - "expected num of channels = %d" - "received num of channels = %d", + log::error( + "Incorrect response.expected num of channels = {} received num of " + "channels = {}", num_of_channels, p_lcb->pending_ecoc_conn_cnt); return; } - LOG_VERBOSE( - "mtu = %d, " - "mps = %d, " - "initial_credit = %d, " - "con_info.l2cap_result = %d" - "num_of_channels = %d", + log::verbose( + "mtu = {}, mps = {}, initial_credit = {}, con_info.l2cap_result = " + "{} num_of_channels = {}", mtu, mps, initial_credit, con_info.l2cap_result, num_of_channels); con_info.peer_mtu = mtu; @@ -561,10 +559,9 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { */ temp_p_ccb = l2cu_find_ccb_by_remote_cid(p_lcb, rcid); if (temp_p_ccb != nullptr) { - LOG_ERROR( - "Already Allocated Destination cid. " - "rcid = %d " - "send peer_disc_req", + log::error( + "Already Allocated Destination cid. rcid = {} send " + "peer_disc_req", rcid); l2cu_send_peer_disc_req(temp_p_ccb); @@ -581,10 +578,8 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { temp_p_ccb = l2cu_find_ccb_by_cid(p_lcb, cid); temp_p_ccb->remote_cid = rcid; - LOG_VERBOSE( - "local cid = %d " - "remote cid = %d", - cid, temp_p_ccb->remote_cid); + log::verbose("local cid = {} remote cid = {}", cid, + temp_p_ccb->remote_cid); /* Check if peer accepted channel, if not release the one not * created @@ -620,7 +615,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { /* validate the parameters */ if (mtu < L2CAP_CREDIT_BASED_MIN_MTU || mps < L2CAP_CREDIT_BASED_MIN_MPS || mps > L2CAP_LE_MAX_MPS) { - LOG_ERROR("L2CAP - invalid params"); + log::error("L2CAP - invalid params"); l2cu_send_ble_reconfig_rsp(p_lcb, id, L2CAP_RECONFIG_UNACCAPTED_PARAM); return; } @@ -628,11 +623,9 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { /* Check how many channels remote side wants to reconfigure */ num_of_channels = (p_pkt_end - p) / sizeof(uint16_t); - LOG_VERBOSE( - "Recv L2CAP_CMD_CREDIT_BASED_RECONFIG_REQ with " - "mtu = %d, " - "mps = %d, " - "num_of_channels = %d", + log::verbose( + "Recv L2CAP_CMD_CREDIT_BASED_RECONFIG_REQ with mtu = {}, mps = {}, " + "num_of_channels = {}", mtu, mps, num_of_channels); uint8_t* p_tmp = p; @@ -640,15 +633,15 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { STREAM_TO_UINT16(rcid, p_tmp); p_ccb = l2cu_find_ccb_by_remote_cid(p_lcb, rcid); if (!p_ccb) { - LOG_WARN("L2CAP - rcvd config req for non existing cid: 0x%04x", - rcid); + log::warn("L2CAP - rcvd config req for non existing cid: 0x{:04x}", + rcid); l2cu_send_ble_reconfig_rsp(p_lcb, id, L2CAP_RECONFIG_INVALID_DCID); return; } if (p_ccb->peer_conn_cfg.mtu > mtu) { - LOG_WARN( - "L2CAP - rcvd config req mtu reduction new mtu < mtu (%d < %d)", + log::warn( + "L2CAP - rcvd config req mtu reduction new mtu < mtu ({} < {})", mtu, p_ccb->peer_conn_cfg.mtu); l2cu_send_ble_reconfig_rsp(p_lcb, id, L2CAP_RECONFIG_REDUCTION_MTU_NO_ALLOWED); @@ -656,8 +649,8 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { } if (p_ccb->peer_conn_cfg.mps > mps && num_of_channels > 1) { - LOG_WARN( - "L2CAP - rcvd config req mps reduction new mps < mps (%d < %d)", + log::warn( + "L2CAP - rcvd config req mps reduction new mps < mps ({} < {})", mtu, p_ccb->peer_conn_cfg.mtu); l2cu_send_ble_reconfig_rsp(p_lcb, id, L2CAP_RECONFIG_REDUCTION_MPS_NO_ALLOWED); @@ -689,14 +682,13 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CMD_CREDIT_BASED_RECONFIG_RES: { uint16_t result; if (p + sizeof(uint16_t) > p_pkt_end) { - LOG(ERROR) << "invalid read"; + log::error("invalid read"); return; } STREAM_TO_UINT16(result, p); - LOG_VERBOSE( - "Recv L2CAP_CMD_CREDIT_BASED_RECONFIG_RES for " - "result = 0x%04x", + log::verbose( + "Recv L2CAP_CMD_CREDIT_BASED_RECONFIG_RES for result = 0x{:04x}", result); p_lcb->pending_ecoc_reconfig_cfg.result = result; @@ -722,7 +714,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CMD_BLE_CREDIT_BASED_CONN_REQ: if (p + 10 > p_pkt_end) { - LOG(ERROR) << "invalid read"; + log::error("invalid read"); return; } @@ -732,16 +724,14 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { STREAM_TO_UINT16(mps, p); STREAM_TO_UINT16(initial_credit, p); - LOG_VERBOSE( - "Recv L2CAP_CMD_BLE_CREDIT_BASED_CONN_REQ with " - "mtu = %d, " - "mps = %d, " - "initial credit = %d", + log::verbose( + "Recv L2CAP_CMD_BLE_CREDIT_BASED_CONN_REQ with mtu = {}, mps = {}, " + "initial credit = {}", mtu, mps, initial_credit); p_ccb = l2cu_find_ccb_by_remote_cid(p_lcb, rcid); if (p_ccb) { - LOG_WARN("L2CAP - rcvd conn req for duplicated cid: 0x%04x", rcid); + log::warn("L2CAP - rcvd conn req for duplicated cid: 0x{:04x}", rcid); l2cu_reject_ble_coc_connection( p_lcb, id, L2CAP_LE_RESULT_SOURCE_CID_ALREADY_ALLOCATED); break; @@ -749,13 +739,15 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { p_rcb = l2cu_find_ble_rcb_by_psm(con_info.psm); if (p_rcb == NULL) { - LOG_WARN("L2CAP - rcvd conn req for unknown PSM: 0x%04x", con_info.psm); + log::warn("L2CAP - rcvd conn req for unknown PSM: 0x{:04x}", + con_info.psm); l2cu_reject_ble_coc_connection(p_lcb, id, L2CAP_LE_RESULT_NO_PSM); break; } else { if (!p_rcb->api.pL2CA_ConnectInd_Cb) { - LOG_WARN("L2CAP - rcvd conn req for outgoing-only connection PSM: %d", - con_info.psm); + log::warn( + "L2CAP - rcvd conn req for outgoing-only connection PSM: {}", + con_info.psm); l2cu_reject_ble_coc_connection(p_lcb, id, L2CAP_CONN_NO_PSM); break; } @@ -765,7 +757,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { p_ccb = l2cu_allocate_ccb(p_lcb, 0, con_info.psm == BT_PSM_EATT /* is_eatt */); if (p_ccb == NULL) { - LOG_ERROR("L2CAP - unable to allocate CCB"); + log::error("L2CAP - unable to allocate CCB"); l2cu_reject_ble_connection(p_ccb, id, L2CAP_CONN_NO_RESOURCES); break; } @@ -773,7 +765,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { /* validate the parameters */ if (mtu < L2CAP_LE_MIN_MTU || mps < L2CAP_LE_MIN_MPS || mps > L2CAP_LE_MAX_MPS) { - LOG_ERROR("L2CAP do not like the params"); + log::error("L2CAP do not like the params"); l2cu_reject_ble_connection(p_ccb, id, L2CAP_CONN_NO_RESOURCES); break; } @@ -804,7 +796,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { break; case L2CAP_CMD_BLE_CREDIT_BASED_CONN_RES: - LOG_VERBOSE("Recv L2CAP_CMD_BLE_CREDIT_BASED_CONN_RES"); + log::verbose("Recv L2CAP_CMD_BLE_CREDIT_BASED_CONN_RES"); /* For all channels, see whose identifier matches this id */ for (temp_p_ccb = p_lcb->ccb_queue.p_first_ccb; temp_p_ccb; temp_p_ccb = temp_p_ccb->p_next_ccb) { @@ -814,9 +806,9 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { } } if (p_ccb) { - LOG_VERBOSE("I remember the connection req"); + log::verbose("I remember the connection req"); if (p + 10 > p_pkt_end) { - LOG(ERROR) << "invalid read"; + log::error("invalid read"); return; } @@ -827,12 +819,9 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { STREAM_TO_UINT16(con_info.l2cap_result, p); con_info.remote_cid = p_ccb->remote_cid; - LOG_VERBOSE( - "remote_cid = %d, " - "mtu = %d, " - "mps = %d, " - "initial_credit = %d, " - "con_info.l2cap_result = %d", + log::verbose( + "remote_cid = {}, mtu = {}, mps = {}, initial_credit = {}, " + "con_info.l2cap_result = {}", p_ccb->remote_cid, p_ccb->peer_conn_cfg.mtu, p_ccb->peer_conn_cfg.mps, p_ccb->peer_conn_cfg.credits, con_info.l2cap_result); @@ -841,7 +830,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { if (p_ccb->peer_conn_cfg.mtu < L2CAP_LE_MIN_MTU || p_ccb->peer_conn_cfg.mps < L2CAP_LE_MIN_MPS || p_ccb->peer_conn_cfg.mps > L2CAP_LE_MAX_MPS) { - LOG_ERROR("L2CAP do not like the params"); + log::error("L2CAP do not like the params"); con_info.l2cap_result = L2CAP_LE_RESULT_NO_RESOURCES; l2c_csm_execute(p_ccb, L2CEVT_L2CAP_CONNECT_RSP_NEG, &con_info); break; @@ -858,7 +847,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { else l2c_csm_execute(p_ccb, L2CEVT_L2CAP_CONNECT_RSP_NEG, &con_info); } else { - LOG_VERBOSE("I DO NOT remember the connection req"); + log::verbose("I DO NOT remember the connection req"); con_info.l2cap_result = L2CAP_LE_RESULT_INVALID_SOURCE_CID; l2c_csm_execute(p_ccb, L2CEVT_L2CAP_CONNECT_RSP_NEG, &con_info); } @@ -866,21 +855,20 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CMD_BLE_FLOW_CTRL_CREDIT: if (p + 4 > p_pkt_end) { - LOG(ERROR) << "invalid read"; + log::error("invalid read"); return; } STREAM_TO_UINT16(lcid, p); p_ccb = l2cu_find_ccb_by_remote_cid(p_lcb, lcid); if (p_ccb == NULL) { - LOG_VERBOSE("%s Credit received for unknown channel id %d", __func__, - lcid); + log::verbose("Credit received for unknown channel id {}", lcid); break; } STREAM_TO_UINT16(credit, p); l2c_csm_execute(p_ccb, L2CEVT_L2CAP_RECV_FLOW_CONTROL_CREDIT, &credit); - LOG_VERBOSE("%s Credit received", __func__); + log::verbose("Credit received"); break; case L2CAP_CMD_DISC_REQ: @@ -903,7 +891,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CMD_DISC_RSP: if (p + 4 > p_pkt_end) { - LOG(ERROR) << "invalid read"; + log::error("invalid read"); return; } STREAM_TO_UINT16(rcid, p); @@ -917,7 +905,7 @@ void l2cble_process_sig_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { break; default: - LOG_WARN("L2CAP - LE - unknown cmd code: %d", cmd_code); + log::warn("L2CAP - LE - unknown cmd code: {}", cmd_code); l2cu_send_peer_cmd_reject(p_lcb, L2CAP_CMD_REJ_NOT_UNDERSTOOD, id, 0, 0); break; } @@ -1032,9 +1020,9 @@ void l2c_ble_link_adjust_allocation(void) { l2cb.ble_round_robin_unacked = 0; qq = qq_remainder = 0; } - LOG_VERBOSE( - "l2c_ble_link_adjust_allocation num_hipri: %u num_lowpri: %u " - "low_quota: %u round_robin_quota: %u qq: %u", + log::verbose( + "l2c_ble_link_adjust_allocation num_hipri: {} num_lowpri: {} " + "low_quota: {} round_robin_quota: {} qq: {}", num_hipri_links, num_lowpri_links, low_quota, l2cb.ble_round_robin_quota, qq); @@ -1059,12 +1047,12 @@ void l2c_ble_link_adjust_allocation(void) { } } - LOG_VERBOSE( - "l2c_ble_link_adjust_allocation LCB %d Priority: %d XmitQuota: %d", + log::verbose( + "l2c_ble_link_adjust_allocation LCB {} Priority: {} XmitQuota: {}", yy, p_lcb->acl_priority, p_lcb->link_xmit_quota); - LOG_VERBOSE(" SentNotAcked: %d RRUnacked: %d", - p_lcb->sent_not_acked, l2cb.round_robin_unacked); + log::verbose("SentNotAcked: {} RRUnacked: {}", p_lcb->sent_not_acked, + l2cb.round_robin_unacked); /* There is a special case where we have readjusted the link quotas and */ /* this link may have sent anything but some other link sent packets so */ @@ -1093,7 +1081,7 @@ void l2cble_update_data_length(tL2C_LCB* p_lcb) { uint16_t tx_mtu = 0; uint16_t i = 0; - LOG_VERBOSE("%s", __func__); + log::verbose(""); /* See if we have a link control block for the connection */ if (p_lcb == NULL) return; @@ -1131,16 +1119,17 @@ void l2cble_process_data_length_change_event(uint16_t handle, uint16_t rx_data_len) { tL2C_LCB* p_lcb = l2cu_find_lcb_by_handle(handle); if (p_lcb == nullptr) { - LOG_WARN("Received data length change event for unknown ACL handle:0x%04x", - handle); + log::warn( + "Received data length change event for unknown ACL handle:0x{:04x}", + handle); return; } if (is_legal_tx_data_len(tx_data_len)) { if (p_lcb->tx_data_len != tx_data_len) { - LOG_DEBUG( - "Received data length change event for device:%s tx_data_len:%hu => " - "%hu", + log::debug( + "Received data length change event for device:{} tx_data_len:{} => " + "{}", ADDRESS_TO_LOGGABLE_CSTR(p_lcb->remote_bd_addr), p_lcb->tx_data_len, tx_data_len); BTM_LogHistory(kBtmLogTag, p_lcb->remote_bd_addr, "LE Data length change", @@ -1148,15 +1137,15 @@ void l2cble_process_data_length_change_event(uint16_t handle, p_lcb->tx_data_len, tx_data_len)); p_lcb->tx_data_len = tx_data_len; } else { - LOG_DEBUG( - "Received duplicated data length change event for device:%s " - "tx_data_len:%hu", + log::debug( + "Received duplicated data length change event for device:{} " + "tx_data_len:{}", ADDRESS_TO_LOGGABLE_CSTR(p_lcb->remote_bd_addr), tx_data_len); } } else { - LOG_WARN( - "Received illegal data length change event for device:%s " - "tx_data_len:%hu", + log::warn( + "Received illegal data length change event for device:{} " + "tx_data_len:{}", ADDRESS_TO_LOGGABLE_CSTR(p_lcb->remote_bd_addr), tx_data_len); } /* ignore rx_data len for now */ @@ -1176,7 +1165,7 @@ void l2cble_credit_based_conn_req(tL2C_CCB* p_ccb) { if (!p_ccb) return; if (p_ccb->p_lcb && p_ccb->p_lcb->transport != BT_TRANSPORT_LE) { - LOG_WARN("LE link doesn't exist"); + log::warn("LE link doesn't exist"); return; } @@ -1202,7 +1191,7 @@ void l2cble_credit_based_conn_res(tL2C_CCB* p_ccb, uint16_t result) { if (!p_ccb) return; if (p_ccb->p_lcb && p_ccb->p_lcb->transport != BT_TRANSPORT_LE) { - LOG_WARN("LE link doesn't exist"); + log::warn("LE link doesn't exist"); return; } @@ -1224,7 +1213,7 @@ void l2cble_send_flow_control_credit(tL2C_CCB* p_ccb, uint16_t credit_value) { if (!p_ccb) return; if (p_ccb->p_lcb && p_ccb->p_lcb->transport != BT_TRANSPORT_LE) { - LOG_WARN("LE link doesn't exist"); + log::warn("LE link doesn't exist"); return; } @@ -1243,11 +1232,11 @@ void l2cble_send_flow_control_credit(tL2C_CCB* p_ccb, uint16_t credit_value) { * ******************************************************************************/ void l2cble_send_peer_disc_req(tL2C_CCB* p_ccb) { - LOG_VERBOSE("%s", __func__); + log::verbose(""); if (!p_ccb) return; if (p_ccb->p_lcb && p_ccb->p_lcb->transport != BT_TRANSPORT_LE) { - LOG_WARN("LE link doesn't exist"); + log::warn("LE link doesn't exist"); return; } @@ -1273,8 +1262,8 @@ void l2cble_sec_comp(const RawAddress* bda, tBT_TRANSPORT transport, uint8_t sec_act; if (!p_lcb) { - LOG_WARN("%s: security complete for unknown device. bda=%s", __func__, - ADDRESS_TO_LOGGABLE_CSTR(*bda)); + log::warn("security complete for unknown device. bda={}", + ADDRESS_TO_LOGGABLE_CSTR(*bda)); return; } @@ -1284,8 +1273,7 @@ void l2cble_sec_comp(const RawAddress* bda, tBT_TRANSPORT transport, if (!fixed_queue_is_empty(p_lcb->le_sec_pending_q)) { p_buf = (tL2CAP_SEC_DATA*)fixed_queue_dequeue(p_lcb->le_sec_pending_q); if (!p_buf) { - LOG_WARN("%s Security complete for request not initiated from L2CAP", - __func__); + log::warn("Security complete for request not initiated from L2CAP"); return; } @@ -1298,21 +1286,20 @@ void l2cble_sec_comp(const RawAddress* bda, tBT_TRANSPORT transport, (*(p_buf->p_callback))(bda, BT_TRANSPORT_LE, p_buf->p_ref_data, status); else { - LOG_VERBOSE("%s MITM Protection Not present", __func__); + log::verbose("MITM Protection Not present"); (*(p_buf->p_callback))(bda, BT_TRANSPORT_LE, p_buf->p_ref_data, BTM_FAILED_ON_SECURITY); } } else { - LOG_VERBOSE("%s MITM Protection not required sec_act = %d", __func__, - p_lcb->sec_act); + log::verbose("MITM Protection not required sec_act = {}", + p_lcb->sec_act); (*(p_buf->p_callback))(bda, BT_TRANSPORT_LE, p_buf->p_ref_data, status); } osi_free(p_buf); } } else { - LOG_WARN("%s Security complete for request not initiated from L2CAP", - __func__); + log::warn("Security complete for request not initiated from L2CAP"); return; } @@ -1350,14 +1337,14 @@ tL2CAP_LE_RESULT_CODE l2ble_sec_access_req(const RawAddress& bd_addr, tL2C_LCB* p_lcb = NULL; if (!p_callback) { - LOG_ERROR("No callback function"); + log::error("No callback function"); return L2CAP_LE_RESULT_NO_RESOURCES; } p_lcb = l2cu_find_lcb_by_bd_addr(bd_addr, BT_TRANSPORT_LE); if (!p_lcb) { - LOG_ERROR("Security check for unknown device"); + log::error("Security check for unknown device"); p_callback(&bd_addr, BT_TRANSPORT_LE, p_ref_data, BTM_UNKNOWN_ADDR); return L2CAP_LE_RESULT_NO_RESOURCES; } @@ -1365,7 +1352,7 @@ tL2CAP_LE_RESULT_CODE l2ble_sec_access_req(const RawAddress& bd_addr, tL2CAP_SEC_DATA* p_buf = (tL2CAP_SEC_DATA*)osi_malloc((uint16_t)sizeof(tL2CAP_SEC_DATA)); if (!p_buf) { - LOG_ERROR("No resources for connection"); + log::error("No resources for connection"); p_callback(&bd_addr, BT_TRANSPORT_LE, p_ref_data, BTM_NO_RESOURCES); return L2CAP_LE_RESULT_NO_RESOURCES; } @@ -1392,7 +1379,7 @@ tL2CAP_LE_RESULT_CODE l2ble_sec_access_req(const RawAddress& bd_addr, case BTM_INSUFFICIENT_ENCRYPT_KEY_SIZE: return L2CAP_LE_RESULT_INSUFFICIENT_ENCRYP_KEY_SIZE; default: - LOG_ERROR("unexpected return value: %s", btm_status_text(result).c_str()); + log::error("unexpected return value: {}", btm_status_text(result)); return L2CAP_LE_RESULT_INVALID_PARAMETERS; } } @@ -1420,13 +1407,13 @@ void L2CA_AdjustConnectionIntervals(uint16_t* min_interval, // When there are bonded Hearing Aid devices, we will constrained this // minimum interval. phone_min_interval = BTM_BLE_CONN_INT_MIN_HEARINGAID; - LOG_VERBOSE("%s: Have Hearing Aids. Min. interval is set to %d", __func__, - phone_min_interval); + log::verbose("Have Hearing Aids. Min. interval is set to {}", + phone_min_interval); } if (*min_interval < phone_min_interval) { - LOG_VERBOSE("%s: requested min_interval=%d too small. Set to %d", __func__, - *min_interval, phone_min_interval); + log::verbose("requested min_interval={} too small. Set to {}", + *min_interval, phone_min_interval); *min_interval = phone_min_interval; } @@ -1435,8 +1422,8 @@ void L2CA_AdjustConnectionIntervals(uint16_t* min_interval, // to remain established. // In other words, this is a workaround for certain peripherals. if (*max_interval < phone_min_interval) { - LOG_VERBOSE("%s: requested max_interval=%d too small. Set to %d", __func__, - *max_interval, phone_min_interval); + log::verbose("requested max_interval={} too small. Set to {}", + *max_interval, phone_min_interval); *max_interval = phone_min_interval; } } diff --git a/system/stack/l2cap/l2c_ble_conn_params.cc b/system/stack/l2cap/l2c_ble_conn_params.cc index 47f983231c787826b6611c8b45d6b95d9b07aaff..2db0debba1314c06e9b2e1b0d847c7d64100fa0c 100644 --- a/system/stack/l2cap/l2c_ble_conn_params.cc +++ b/system/stack/l2cap/l2c_ble_conn_params.cc @@ -26,6 +26,7 @@ #define LOG_TAG "l2c_ble_conn_params" #include <base/logging.h> +#include <bluetooth/log.h> #include <log/log.h> #include "internal_include/stack_config.h" @@ -38,6 +39,8 @@ #include "stack/l2cap/l2c_int.h" #include "types/raw_address.h" +using namespace bluetooth; + void l2cble_start_conn_update(tL2C_LCB* p_lcb); static void l2cble_start_subrate_change(tL2C_LCB* p_lcb); @@ -63,18 +66,19 @@ bool L2CA_UpdateBleConnParams(const RawAddress& rem_bda, uint16_t min_int, /* If we do not have one, create one and accept the connection. */ if (!p_lcb || !BTM_IsAclConnectionUp(rem_bda, BT_TRANSPORT_LE)) { - LOG(WARNING) << __func__ << " - unknown BD_ADDR " << rem_bda; + log::warn("- unknown BD_ADDR {}", ADDRESS_TO_LOGGABLE_STR(rem_bda)); return (false); } if (p_lcb->transport != BT_TRANSPORT_LE) { - LOG(WARNING) << __func__ << " - BD_ADDR " << rem_bda << " not LE"; + log::warn("- BD_ADDR {} not LE", ADDRESS_TO_LOGGABLE_STR(rem_bda)); return (false); } - VLOG(2) << __func__ << ": BD_ADDR=" << ADDRESS_TO_LOGGABLE_STR(rem_bda) - << ", min_int=" << min_int << ", max_int=" << max_int - << ", min_ce_len=" << min_ce_len << ", max_ce_len=" << max_ce_len; + log::verbose( + "BD_ADDR={}, min_int={}, max_int={}, min_ce_len={}, max_ce_len={}", + ADDRESS_TO_LOGGABLE_STR(rem_bda), min_int, max_int, min_ce_len, + max_ce_len); p_lcb->min_interval = min_int; p_lcb->max_interval = max_int; @@ -101,32 +105,32 @@ void L2CA_LockBleConnParamsForServiceDiscovery(const RawAddress& rem_bda, tL2C_LCB* p_lcb = l2cu_find_lcb_by_bd_addr(rem_bda, BT_TRANSPORT_LE); if (!p_lcb) { - LOG_WARN("unknown address %s", ADDRESS_TO_LOGGABLE_CSTR(rem_bda)); + log::warn("unknown address {}", ADDRESS_TO_LOGGABLE_CSTR(rem_bda)); return; } if (p_lcb->transport != BT_TRANSPORT_LE) { - LOG_WARN("%s not LE, link role %d", ADDRESS_TO_LOGGABLE_CSTR(rem_bda), - p_lcb->LinkRole()); + log::warn("{} not LE, link role {}", ADDRESS_TO_LOGGABLE_CSTR(rem_bda), + p_lcb->LinkRole()); return; } if (lock == p_lcb->conn_update_blocked_by_service_discovery) { - LOG_WARN("%s service discovery already locked/unlocked conn params: %d", - ADDRESS_TO_LOGGABLE_CSTR(rem_bda), +lock); + log::warn("{} service discovery already locked/unlocked conn params: {}", + ADDRESS_TO_LOGGABLE_CSTR(rem_bda), lock); return; } p_lcb->conn_update_blocked_by_service_discovery = lock; if (p_lcb->conn_update_blocked_by_profile_connection) { - LOG_INFO("%s conn params stay locked because of audio setup", - ADDRESS_TO_LOGGABLE_CSTR(rem_bda)); + log::info("{} conn params stay locked because of audio setup", + ADDRESS_TO_LOGGABLE_CSTR(rem_bda)); return; } - LOG_INFO("%s Locking/unlocking conn params for service discovery: %d", - ADDRESS_TO_LOGGABLE_CSTR(rem_bda), +lock); + log::info("{} Locking/unlocking conn params for service discovery: {}", + ADDRESS_TO_LOGGABLE_CSTR(rem_bda), lock); l2c_enable_update_ble_conn_params(p_lcb, !lock); } @@ -140,39 +144,39 @@ void L2CA_LockBleConnParamsForProfileConnection(const RawAddress& rem_bda, tL2C_LCB* p_lcb = l2cu_find_lcb_by_bd_addr(rem_bda, BT_TRANSPORT_LE); if (!p_lcb) { - LOG_WARN("unknown address %s", ADDRESS_TO_LOGGABLE_CSTR(rem_bda)); + log::warn("unknown address {}", ADDRESS_TO_LOGGABLE_CSTR(rem_bda)); return; } if (p_lcb->transport != BT_TRANSPORT_LE) { - LOG_WARN("%s not LE, link role %d", ADDRESS_TO_LOGGABLE_CSTR(rem_bda), - p_lcb->LinkRole()); + log::warn("{} not LE, link role {}", ADDRESS_TO_LOGGABLE_CSTR(rem_bda), + p_lcb->LinkRole()); return; } if (lock == p_lcb->conn_update_blocked_by_profile_connection) { - LOG_INFO("%s audio setup already locked/unlocked conn params: %d", - ADDRESS_TO_LOGGABLE_CSTR(rem_bda), +lock); + log::info("{} audio setup already locked/unlocked conn params: {}", + ADDRESS_TO_LOGGABLE_CSTR(rem_bda), lock); return; } p_lcb->conn_update_blocked_by_profile_connection = lock; if (p_lcb->conn_update_blocked_by_service_discovery) { - LOG_INFO("%s conn params stay locked because of service discovery", - ADDRESS_TO_LOGGABLE_CSTR(rem_bda)); + log::info("{} conn params stay locked because of service discovery", + ADDRESS_TO_LOGGABLE_CSTR(rem_bda)); return; } - LOG_INFO("%s Locking/unlocking conn params for audio setup: %d", - ADDRESS_TO_LOGGABLE_CSTR(rem_bda), +lock); + log::info("{} Locking/unlocking conn params for audio setup: {}", + ADDRESS_TO_LOGGABLE_CSTR(rem_bda), lock); l2c_enable_update_ble_conn_params(p_lcb, !lock); } static bool l2c_enable_update_ble_conn_params(tL2C_LCB* p_lcb, bool enable) { - LOG_DEBUG("%s enable %d current upd state 0x%02x", - ADDRESS_TO_LOGGABLE_CSTR(p_lcb->remote_bd_addr), enable, - p_lcb->conn_update_mask); + log::debug("{} enable {} current upd state 0x{:02x}", + ADDRESS_TO_LOGGABLE_CSTR(p_lcb->remote_bd_addr), enable, + p_lcb->conn_update_mask); if (enable) { p_lcb->conn_update_mask &= ~L2C_BLE_CONN_UPDATE_DISABLE; @@ -202,7 +206,8 @@ static bool l2c_enable_update_ble_conn_params(tL2C_LCB* p_lcb, bool enable) { void l2cble_start_conn_update(tL2C_LCB* p_lcb) { uint16_t min_conn_int, max_conn_int, peripheral_latency, supervision_tout; if (!BTM_IsAclConnectionUp(p_lcb->remote_bd_addr, BT_TRANSPORT_LE)) { - LOG(ERROR) << "No known connection ACL for " << p_lcb->remote_bd_addr; + log::error("No known connection ACL for {}", + ADDRESS_TO_LOGGABLE_STR(p_lcb->remote_bd_addr)); return; } @@ -288,27 +293,27 @@ void l2cble_start_conn_update(tL2C_LCB* p_lcb) { void l2cble_process_conn_update_evt(uint16_t handle, uint8_t status, uint16_t interval, uint16_t latency, uint16_t timeout) { - LOG_VERBOSE("%s", __func__); + log::verbose(""); /* See if we have a link control block for the remote device */ tL2C_LCB* p_lcb = l2cu_find_lcb_by_handle(handle); if (!p_lcb) { - LOG_WARN("%s: Invalid handle: %d", __func__, handle); + log::warn("Invalid handle: {}", handle); return; } p_lcb->conn_update_mask &= ~L2C_BLE_UPDATE_PENDING; if (status != HCI_SUCCESS) { - LOG_WARN("%s: Error status: %d", __func__, status); + log::warn("Error status: {}", status); } l2cble_start_conn_update(p_lcb); l2cble_start_subrate_change(p_lcb); - LOG_VERBOSE("%s: conn_update_mask=%d , subrate_req_mask=%d", __func__, - p_lcb->conn_update_mask, p_lcb->subrate_req_mask); + log::verbose("conn_update_mask={} , subrate_req_mask={}", + p_lcb->conn_update_mask, p_lcb->subrate_req_mask); } /******************************************************************************* @@ -336,14 +341,14 @@ void l2cble_process_rc_param_request_evt(uint16_t handle, uint16_t int_min, btsnd_hcic_ble_rc_param_req_reply(handle, int_min, int_max, latency, timeout, 0, 0); } else { - LOG_VERBOSE("L2CAP - LE - update currently disabled"); + log::verbose("L2CAP - LE - update currently disabled"); p_lcb->conn_update_mask |= L2C_BLE_NEW_CONN_PARAM; btsnd_hcic_ble_rc_param_req_neg_reply(handle, HCI_ERR_UNACCEPT_CONN_INTERVAL); } } else { - LOG_WARN("No link to update connection parameter"); + log::warn("No link to update connection parameter"); } } @@ -365,10 +370,10 @@ void l2cble_use_preferred_conn_params(const RawAddress& bda) { (p_lcb->min_interval > p_dev_rec->conn_params.max_conn_int) || (p_lcb->latency > p_dev_rec->conn_params.peripheral_latency) || (p_lcb->timeout > p_dev_rec->conn_params.supervision_tout))) { - LOG_VERBOSE( - "%s: HANDLE=%d min_conn_int=%d max_conn_int=%d peripheral_latency=%d " - "supervision_tout=%d", - __func__, p_lcb->Handle(), p_dev_rec->conn_params.min_conn_int, + log::verbose( + "HANDLE={} min_conn_int={} max_conn_int={} peripheral_latency={} " + "supervision_tout={}", + p_lcb->Handle(), p_dev_rec->conn_params.min_conn_int, p_dev_rec->conn_params.max_conn_int, p_dev_rec->conn_params.peripheral_latency, p_dev_rec->conn_params.supervision_tout); @@ -400,23 +405,23 @@ void l2cble_use_preferred_conn_params(const RawAddress& bda) { ******************************************************************************/ static void l2cble_start_subrate_change(tL2C_LCB* p_lcb) { if (!BTM_IsAclConnectionUp(p_lcb->remote_bd_addr, BT_TRANSPORT_LE)) { - LOG(ERROR) << "No known connection ACL for " - << ADDRESS_TO_LOGGABLE_STR(p_lcb->remote_bd_addr); + log::error("No known connection ACL for {}", + ADDRESS_TO_LOGGABLE_STR(p_lcb->remote_bd_addr)); return; } btm_find_or_alloc_dev(p_lcb->remote_bd_addr); - LOG_VERBOSE("%s: subrate_req_mask=%d conn_update_mask=%d", __func__, - p_lcb->subrate_req_mask, p_lcb->conn_update_mask); + log::verbose("subrate_req_mask={} conn_update_mask={}", + p_lcb->subrate_req_mask, p_lcb->conn_update_mask); if (p_lcb->subrate_req_mask & L2C_BLE_SUBRATE_REQ_PENDING) { - LOG_VERBOSE("%s: returning L2C_BLE_SUBRATE_REQ_PENDING ", __func__); + log::verbose("returning L2C_BLE_SUBRATE_REQ_PENDING "); return; } if (p_lcb->subrate_req_mask & L2C_BLE_SUBRATE_REQ_DISABLE) { - LOG_VERBOSE("%s: returning L2C_BLE_SUBRATE_REQ_DISABLE ", __func__); + log::verbose("returning L2C_BLE_SUBRATE_REQ_DISABLE "); return; } @@ -424,17 +429,16 @@ static void l2cble_start_subrate_change(tL2C_LCB* p_lcb) { if (!(p_lcb->subrate_req_mask & L2C_BLE_NEW_SUBRATE_PARAM) || (p_lcb->conn_update_mask & L2C_BLE_UPDATE_PENDING) || (p_lcb->conn_update_mask & L2C_BLE_NEW_CONN_PARAM)) { - LOG_VERBOSE("%s: returning L2C_BLE_NEW_SUBRATE_PARAM", __func__); + log::verbose("returning L2C_BLE_NEW_SUBRATE_PARAM"); return; } if (!controller_get_interface()->SupportsBleConnectionSubrating() || !acl_peer_supports_ble_connection_subrating(p_lcb->remote_bd_addr) || !acl_peer_supports_ble_connection_subrating_host(p_lcb->remote_bd_addr)) { - LOG_VERBOSE( - "%s: returning L2C_BLE_NEW_SUBRATE_PARAM local_host_sup=%d, " - "local_conn_subrarte_sup=%d, peer_subrate_sup=%d, peer_host_sup=%d", - __func__, + log::verbose( + "returning L2C_BLE_NEW_SUBRATE_PARAM local_host_sup={}, " + "local_conn_subrarte_sup={}, peer_subrate_sup={}, peer_host_sup={}", controller_get_interface()->SupportsBleConnectionSubratingHost(), controller_get_interface()->SupportsBleConnectionSubrating(), acl_peer_supports_ble_connection_subrating(p_lcb->remote_bd_addr), @@ -442,7 +446,7 @@ static void l2cble_start_subrate_change(tL2C_LCB* p_lcb) { return; } - LOG_VERBOSE("%s: Sending HCI cmd for subrate req", __func__); + log::verbose("Sending HCI cmd for subrate req"); bluetooth::shim::ACL_LeSubrateRequest( p_lcb->Handle(), p_lcb->subrate_min, p_lcb->subrate_max, p_lcb->max_latency, p_lcb->cont_num, p_lcb->supervision_tout); @@ -466,9 +470,9 @@ static void l2cble_start_subrate_change(tL2C_LCB* p_lcb) { void L2CA_SetDefaultSubrate(uint16_t subrate_min, uint16_t subrate_max, uint16_t max_latency, uint16_t cont_num, uint16_t timeout) { - VLOG(1) << __func__ << " subrate_min=" << subrate_min - << ", subrate_max=" << subrate_max << ", max_latency=" << max_latency - << ", cont_num=" << cont_num << ", timeout=" << timeout; + log::verbose( + "subrate_min={}, subrate_max={}, max_latency={}, cont_num={}, timeout={}", + subrate_min, subrate_max, max_latency, cont_num, timeout); bluetooth::shim::ACL_LeSetDefaultSubrate(subrate_min, subrate_max, max_latency, cont_num, timeout); @@ -495,21 +499,20 @@ bool L2CA_SubrateRequest(const RawAddress& rem_bda, uint16_t subrate_min, /* If we don't have one, create one and accept the connection. */ if (!p_lcb || !BTM_IsAclConnectionUp(rem_bda, BT_TRANSPORT_LE)) { - LOG(WARNING) << __func__ << " - unknown BD_ADDR " - << ADDRESS_TO_LOGGABLE_STR(rem_bda); + log::warn("unknown BD_ADDR {}", ADDRESS_TO_LOGGABLE_STR(rem_bda)); return (false); } if (p_lcb->transport != BT_TRANSPORT_LE) { - LOG(WARNING) << __func__ << " - BD_ADDR " - << ADDRESS_TO_LOGGABLE_STR(rem_bda) << " not LE"; + log::warn("BD_ADDR {} not LE", ADDRESS_TO_LOGGABLE_STR(rem_bda)); return (false); } - VLOG(1) << __func__ << ": BD_ADDR=" << ADDRESS_TO_LOGGABLE_STR(rem_bda) - << ", subrate_min=" << subrate_min << ", subrate_max=" << subrate_max - << ", max_latency=" << max_latency << ", cont_num=" << cont_num - << ", timeout=" << timeout; + log::verbose( + "BD_ADDR={}, subrate_min={}, subrate_max={}, max_latency={}, " + "cont_num={}, timeout={}", + ADDRESS_TO_LOGGABLE_STR(rem_bda), subrate_min, subrate_max, max_latency, + cont_num, timeout); p_lcb->subrate_min = subrate_min; p_lcb->subrate_max = subrate_max; @@ -545,25 +548,25 @@ void l2cble_process_subrate_change_evt(uint16_t handle, uint8_t status, uint16_t subrate_factor, uint16_t peripheral_latency, uint16_t cont_num, uint16_t timeout) { - LOG_VERBOSE("%s", __func__); + log::verbose(""); /* See if we have a link control block for the remote device */ tL2C_LCB* p_lcb = l2cu_find_lcb_by_handle(handle); if (!p_lcb) { - LOG_WARN("%s: Invalid handle: %d", __func__, handle); + log::warn("Invalid handle: {}", handle); return; } p_lcb->subrate_req_mask &= ~L2C_BLE_SUBRATE_REQ_PENDING; if (status != HCI_SUCCESS) { - LOG_WARN("%s: Error status: %d", __func__, status); + log::warn("Error status: {}", status); } l2cble_start_conn_update(p_lcb); l2cble_start_subrate_change(p_lcb); - LOG_VERBOSE("%s: conn_update_mask=%d , subrate_req_mask=%d", __func__, - p_lcb->conn_update_mask, p_lcb->subrate_req_mask); + log::verbose("conn_update_mask={} , subrate_req_mask={}", + p_lcb->conn_update_mask, p_lcb->subrate_req_mask); } diff --git a/system/stack/l2cap/l2c_csm.cc b/system/stack/l2cap/l2c_csm.cc index b64571d3bcf740656e786e4922253004ed1b9a8f..fbab24bcea3acd89c763852206c978ba01843e0e 100644 --- a/system/stack/l2cap/l2c_csm.cc +++ b/system/stack/l2cap/l2c_csm.cc @@ -25,6 +25,7 @@ #include <base/functional/callback.h> #include <base/logging.h> +#include <bluetooth/log.h> #include <frameworks/proto_logging/stats/enums/bluetooth/enums.pb.h> #include <string> @@ -43,6 +44,8 @@ #include "stack/include/l2cdefs.h" #include "stack/l2cap/l2c_int.h" +using namespace bluetooth; + /******************************************************************************/ /* L O C A L F U N C T I O N P R O T O T Y P E S */ /******************************************************************************/ @@ -106,7 +109,7 @@ static void l2c_csm_indicate_connection_open(tL2C_CCB* p_ccb) { p_ccb->p_lcb->remote_bd_addr, p_ccb->local_cid, p_ccb->p_rcb->psm, p_ccb->remote_id); } else { - LOG_WARN("pL2CA_ConnectInd_Cb is null"); + log::warn("pL2CA_ConnectInd_Cb is null"); } } if (p_ccb->chnl_state == CST_OPEN && !p_ccb->p_lcb->is_transport_ble()) { @@ -129,18 +132,18 @@ static void l2c_csm_indicate_connection_open(tL2C_CCB* p_ccb) { ******************************************************************************/ void l2c_csm_execute(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { if (p_ccb == nullptr) { - LOG_WARN("CCB is null for event (%d)", event); + log::warn("CCB is null for event ({})", event); return; } if (!l2cu_is_ccb_active(p_ccb)) { - LOG_WARN("CCB not in use, event (%d) cannot be processed", event); + log::warn("CCB not in use, event ({}) cannot be processed", event); return; } - LOG_VERBOSE("Entry chnl_state=%s [%d], event=%s [%d]", - channel_state_text(p_ccb->chnl_state).c_str(), p_ccb->chnl_state, - l2c_csm_get_event_name(event), event); + log::verbose("Entry chnl_state={} [{}], event={} [{}]", + channel_state_text(p_ccb->chnl_state), p_ccb->chnl_state, + l2c_csm_get_event_name(event), event); switch (p_ccb->chnl_state) { case CST_CLOSED: @@ -180,7 +183,7 @@ void l2c_csm_execute(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { break; default: - LOG_ERROR("Unhandled state %d, event %d", p_ccb->chnl_state, event); + log::error("Unhandled state {}, event {}", p_ccb->chnl_state, event); break; } } @@ -202,20 +205,20 @@ static void l2c_csm_closed(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { tL2CA_DISCONNECT_IND_CB* disconnect_ind; if (p_ccb->p_rcb == NULL) { - LOG_ERROR("LCID: 0x%04x st: CLOSED evt: %s p_rcb == NULL", - p_ccb->local_cid, l2c_csm_get_event_name(event)); + log::error("LCID: 0x{:04x} st: CLOSED evt: {} p_rcb == NULL", + p_ccb->local_cid, l2c_csm_get_event_name(event)); return; } disconnect_ind = p_ccb->p_rcb->api.pL2CA_DisconnectInd_Cb; - LOG_DEBUG("LCID: 0x%04x st: CLOSED evt: %s", p_ccb->local_cid, - l2c_csm_get_event_name(event)); + log::debug("LCID: 0x{:04x} st: CLOSED evt: {}", p_ccb->local_cid, + l2c_csm_get_event_name(event)); switch (event) { case L2CEVT_LP_DISCONNECT_IND: /* Link was disconnected */ - LOG_DEBUG("Calling Disconnect_Ind_Cb(), CID: 0x%04x No Conf Needed", - p_ccb->local_cid); + log::debug("Calling Disconnect_Ind_Cb(), CID: 0x{:04x} No Conf Needed", + p_ccb->local_cid); l2cu_release_ccb(p_ccb); (*disconnect_ind)(local_cid, false); break; @@ -255,7 +258,7 @@ static void l2c_csm_closed(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { true, &l2c_link_sec_comp, p_ccb); } else { if (!BTM_SetLinkPolicyActiveMode(p_ccb->p_lcb->remote_bd_addr)) { - LOG_WARN("Unable to set link policy active"); + log::warn("Unable to set link policy active"); } /* If sec access does not result in started SEC_COM or COMP_NEG are * already processed */ @@ -332,7 +335,7 @@ static void l2c_csm_closed(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { } } else { if (!BTM_SetLinkPolicyActiveMode(p_ccb->p_lcb->remote_bd_addr)) { - LOG_WARN("Unable to set link policy active"); + log::warn("Unable to set link policy active"); } p_ccb->chnl_state = CST_TERM_W4_SEC_COMP; auto status = btm_sec_l2cap_access_req(p_ccb->p_lcb->remote_bd_addr, @@ -342,8 +345,8 @@ static void l2c_csm_closed(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { // started the security process, tell the peer to set a longer timer l2cu_send_peer_connect_rsp(p_ccb, L2CAP_CONN_PENDING, 0); } else { - LOG_INFO("Check security for psm 0x%04x, status %d", - p_ccb->p_rcb->psm, status); + log::info("Check security for psm 0x{:04x}, status {}", + p_ccb->p_rcb->psm, status); } } break; @@ -367,11 +370,11 @@ static void l2c_csm_closed(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { break; default: - LOG_ERROR("Handling unexpected event:%s", l2c_csm_get_event_name(event)); + log::error("Handling unexpected event:{}", l2c_csm_get_event_name(event)); } - LOG_VERBOSE("Exit chnl_state=%s [%d], event=%s [%d]", - channel_state_text(p_ccb->chnl_state).c_str(), p_ccb->chnl_state, - l2c_csm_get_event_name(event), event); + log::verbose("Exit chnl_state={} [{}], event={} [{}]", + channel_state_text(p_ccb->chnl_state), p_ccb->chnl_state, + l2c_csm_get_event_name(event), event); } /******************************************************************************* @@ -390,16 +393,16 @@ static void l2c_csm_orig_w4_sec_comp(tL2C_CCB* p_ccb, tL2CEVT event, p_ccb->p_rcb->api.pL2CA_DisconnectInd_Cb; uint16_t local_cid = p_ccb->local_cid; - LOG_DEBUG("%s - LCID: 0x%04x st: ORIG_W4_SEC_COMP evt: %s", - ((p_ccb->p_lcb) && (p_ccb->p_lcb->transport == BT_TRANSPORT_LE)) - ? "LE " - : "", - p_ccb->local_cid, l2c_csm_get_event_name(event)); + log::debug("{} - LCID: 0x{:04x} st: ORIG_W4_SEC_COMP evt: {}", + ((p_ccb->p_lcb) && (p_ccb->p_lcb->transport == BT_TRANSPORT_LE)) + ? "LE " + : "", + p_ccb->local_cid, l2c_csm_get_event_name(event)); switch (event) { case L2CEVT_LP_DISCONNECT_IND: /* Link was disconnected */ - LOG_DEBUG("Calling Disconnect_Ind_Cb(), CID: 0x%04x No Conf Needed", - p_ccb->local_cid); + log::debug("Calling Disconnect_Ind_Cb(), CID: 0x{:04x} No Conf Needed", + p_ccb->local_cid); l2cu_release_ccb(p_ccb); (*disconnect_ind)(local_cid, false); break; @@ -475,11 +478,11 @@ static void l2c_csm_orig_w4_sec_comp(tL2C_CCB* p_ccb, tL2CEVT event, break; default: - LOG_ERROR("Handling unexpected event:%s", l2c_csm_get_event_name(event)); + log::error("Handling unexpected event:{}", l2c_csm_get_event_name(event)); } - LOG_VERBOSE("Exit chnl_state=%s [%d], event=%s [%d]", - channel_state_text(p_ccb->chnl_state).c_str(), p_ccb->chnl_state, - l2c_csm_get_event_name(event), event); + log::verbose("Exit chnl_state={} [{}], event={} [{}]", + channel_state_text(p_ccb->chnl_state), p_ccb->chnl_state, + l2c_csm_get_event_name(event), event); } /******************************************************************************* @@ -494,8 +497,8 @@ static void l2c_csm_orig_w4_sec_comp(tL2C_CCB* p_ccb, tL2CEVT event, ******************************************************************************/ static void l2c_csm_term_w4_sec_comp(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { - LOG_DEBUG("LCID: 0x%04x st: TERM_W4_SEC_COMP evt: %s", p_ccb->local_cid, - l2c_csm_get_event_name(event)); + log::debug("LCID: 0x{:04x} st: TERM_W4_SEC_COMP evt: {}", p_ccb->local_cid, + l2c_csm_get_event_name(event)); switch (event) { case L2CEVT_LP_DISCONNECT_IND: /* Link was disconnected */ @@ -511,20 +514,20 @@ static void l2c_csm_term_w4_sec_comp(tL2C_CCB* p_ccb, tL2CEVT event, /* Wait for the info resp in next state before sending connect ind (if * needed) */ if (!p_ccb->p_lcb->w4_info_rsp) { - LOG_DEBUG("Not waiting for info response, sending connect response"); + log::debug("Not waiting for info response, sending connect response"); /* Don't need to get info from peer or already retrieved so continue */ alarm_set_on_mloop(p_ccb->l2c_ccb_timer, L2CAP_CHNL_CONNECT_TIMEOUT_MS, l2c_ccb_timer_timeout, p_ccb); if (p_ccb->p_lcb->transport != BT_TRANSPORT_LE) { - LOG_DEBUG("Not LE connection, sending configure request"); + log::debug("Not LE connection, sending configure request"); l2c_csm_send_connect_rsp(p_ccb); l2c_csm_send_config_req(p_ccb); } else { if (p_ccb->ecoc) { /* Handle Credit Based Connection */ - LOG_DEBUG("Calling CreditBasedConnect_Ind_Cb(), num of cids: %d", - p_ccb->p_lcb->pending_ecoc_conn_cnt); + log::debug("Calling CreditBasedConnect_Ind_Cb(), num of cids: {}", + p_ccb->p_lcb->pending_ecoc_conn_cnt); std::vector<uint16_t> pending_cids; for (int i = 0; i < p_ccb->p_lcb->pending_ecoc_conn_cnt; i++) { @@ -537,8 +540,8 @@ static void l2c_csm_term_w4_sec_comp(tL2C_CCB* p_ccb, tL2CEVT event, p_ccb->peer_conn_cfg.mtu, p_ccb->remote_id); } else { /* Handle BLE CoC */ - LOG_DEBUG("Calling Connect_Ind_Cb(), CID: 0x%04x", - p_ccb->local_cid); + log::debug("Calling Connect_Ind_Cb(), CID: 0x{:04x}", + p_ccb->local_cid); l2c_csm_send_connect_rsp(p_ccb); l2c_csm_indicate_connection_open(p_ccb); } @@ -560,7 +563,7 @@ static void l2c_csm_term_w4_sec_comp(tL2C_CCB* p_ccb, tL2CEVT event, alarm_cancel(p_ccb->l2c_ccb_timer); /* Waiting for the info resp, tell the peer to set a longer timer */ - LOG_DEBUG("Waiting for info response, sending connect pending"); + log::debug("Waiting for info response, sending connect pending"); l2cu_send_peer_connect_rsp(p_ccb, L2CAP_CONN_PENDING, 0); } break; @@ -615,11 +618,11 @@ static void l2c_csm_term_w4_sec_comp(tL2C_CCB* p_ccb, tL2CEVT event, break; default: - LOG_ERROR("Handling unexpected event:%s", l2c_csm_get_event_name(event)); + log::error("Handling unexpected event:{}", l2c_csm_get_event_name(event)); } - LOG_VERBOSE("Exit chnl_state=%s [%d], event=%s [%d]", - channel_state_text(p_ccb->chnl_state).c_str(), p_ccb->chnl_state, - l2c_csm_get_event_name(event), event); + log::verbose("Exit chnl_state={} [{}], event={} [{}]", + channel_state_text(p_ccb->chnl_state), p_ccb->chnl_state, + l2c_csm_get_event_name(event), event); } /******************************************************************************* @@ -642,8 +645,8 @@ static void l2c_csm_w4_l2cap_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, uint16_t local_cid = p_ccb->local_cid; tL2C_LCB* p_lcb = p_ccb->p_lcb; - LOG_DEBUG("LCID: 0x%04x st: W4_L2CAP_CON_RSP evt: %s", p_ccb->local_cid, - l2c_csm_get_event_name(event)); + log::debug("LCID: 0x{:04x} st: W4_L2CAP_CON_RSP evt: {}", p_ccb->local_cid, + l2c_csm_get_event_name(event)); switch (event) { case L2CEVT_LP_DISCONNECT_IND: /* Link was disconnected */ @@ -654,8 +657,8 @@ static void l2c_csm_w4_l2cap_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, p_ccb->chnl_state = CST_CLOSED; if ((p_ccb->flags & CCB_FLAG_NO_RETRY) || !p_data || (*((uint8_t*)p_data) != HCI_ERR_PEER_USER)) { - LOG_DEBUG("Calling Disconnect_Ind_Cb(), CID: 0x%04x No Conf Needed", - p_ccb->local_cid); + log::debug("Calling Disconnect_Ind_Cb(), CID: 0x{:04x} No Conf Needed", + p_ccb->local_cid); l2cu_release_ccb(p_ccb); (*disconnect_ind)(local_cid, false); } @@ -677,8 +680,8 @@ static void l2c_csm_w4_l2cap_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, alarm_set_on_mloop(p_ccb->l2c_ccb_timer, L2CAP_CHNL_CFG_TIMEOUT_MS, l2c_ccb_timer_timeout, p_ccb); } - LOG_DEBUG("Calling Connect_Cfm_Cb(), CID: 0x%04x, Success", - p_ccb->local_cid); + log::debug("Calling Connect_Cfm_Cb(), CID: 0x{:04x}, Success", + p_ccb->local_cid); l2c_csm_send_config_req(p_ccb); break; @@ -693,20 +696,16 @@ static void l2c_csm_w4_l2cap_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, case L2CEVT_L2CAP_CREDIT_BASED_CONNECT_RSP: alarm_cancel(p_ccb->l2c_ccb_timer); p_ccb->chnl_state = CST_OPEN; - LOG_DEBUG( - "Calling credit_based_connect_cfm()," - "cid %d, result 0x%04x", - p_ccb->local_cid, L2CAP_CONN_OK); + log::debug("Calling credit_based_connect_cfm(),cid {}, result 0x{:04x}", + p_ccb->local_cid, L2CAP_CONN_OK); (*credit_based_connect_cfm)(p_lcb->remote_bd_addr, p_ccb->local_cid, p_ci->peer_mtu, L2CAP_CONN_OK); break; case L2CEVT_L2CAP_CREDIT_BASED_CONNECT_RSP_NEG: - LOG_DEBUG( - "Calling pL2CA_Error_Cb()," - "cid %d, result 0x%04x", - local_cid, p_ci->l2cap_result); + log::debug("Calling pL2CA_Error_Cb(),cid {}, result 0x{:04x}", local_cid, + p_ci->l2cap_result); (*p_ccb->p_rcb->api.pL2CA_Error_Cb)(local_cid, p_ci->l2cap_result); bluetooth::shim::CountCounterMetrics( android::bluetooth::CodePathCounterKeyEnum:: @@ -717,9 +716,8 @@ static void l2c_csm_w4_l2cap_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, break; case L2CEVT_L2CAP_CONNECT_RSP_NEG: /* Peer rejected connection */ - LOG(WARNING) << __func__ << ": L2CAP connection rejected, lcid=" - << loghex(p_ccb->local_cid) - << ", reason=" << loghex(p_ci->l2cap_result); + log::warn("L2CAP connection rejected, lcid={}, reason={}", + loghex(p_ccb->local_cid), loghex(p_ci->l2cap_result)); l2cu_release_ccb(p_ccb); if (p_lcb->transport == BT_TRANSPORT_LE) { (*p_ccb->p_rcb->api.pL2CA_Error_Cb)( @@ -732,13 +730,13 @@ static void l2c_csm_w4_l2cap_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, break; case L2CEVT_TIMEOUT: - LOG(WARNING) << __func__ << ": L2CAP connection timeout"; + log::warn("L2CAP connection timeout"); if (p_ccb->ecoc) { for (int i = 0; i < p_lcb->pending_ecoc_conn_cnt; i++) { uint16_t cid = p_lcb->pending_ecoc_connection_cids[i]; tL2C_CCB* temp_p_ccb = l2cu_find_ccb_by_cid(p_lcb, cid); - LOG(WARNING) << __func__ << ": lcid= " << loghex(cid); + log::warn("lcid= {}", loghex(cid)); (*p_ccb->p_rcb->api.pL2CA_Error_Cb)(p_ccb->local_cid, L2CAP_CONN_TIMEOUT); bluetooth::shim::CountCounterMetrics( @@ -752,7 +750,7 @@ static void l2c_csm_w4_l2cap_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, L2CAP_CREDIT_BASED_MAX_CIDS); } else { - LOG(WARNING) << __func__ << ": lcid= " << loghex(p_ccb->local_cid); + log::warn("lcid= {}", loghex(p_ccb->local_cid)); l2cu_release_ccb(p_ccb); (*p_ccb->p_rcb->api.pL2CA_Error_Cb)(local_cid, L2CAP_CONN_OTHER_ERROR); bluetooth::shim::CountCounterMetrics( @@ -803,11 +801,11 @@ static void l2c_csm_w4_l2cap_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, break; default: - LOG_ERROR("Handling unexpected event:%s", l2c_csm_get_event_name(event)); + log::error("Handling unexpected event:{}", l2c_csm_get_event_name(event)); } - LOG_VERBOSE("Exit chnl_state=%s [%d], event=%s [%d]", - channel_state_text(p_ccb->chnl_state).c_str(), p_ccb->chnl_state, - l2c_csm_get_event_name(event), event); + log::verbose("Exit chnl_state={} [{}], event={} [{}]", + channel_state_text(p_ccb->chnl_state), p_ccb->chnl_state, + l2c_csm_get_event_name(event), event); } /******************************************************************************* @@ -828,13 +826,13 @@ static void l2c_csm_w4_l2ca_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, p_ccb->p_rcb->api.pL2CA_DisconnectInd_Cb; uint16_t local_cid = p_ccb->local_cid; - LOG_DEBUG("LCID: 0x%04x st: W4_L2CA_CON_RSP evt: %s", p_ccb->local_cid, - l2c_csm_get_event_name(event)); + log::debug("LCID: 0x{:04x} st: W4_L2CA_CON_RSP evt: {}", p_ccb->local_cid, + l2c_csm_get_event_name(event)); switch (event) { case L2CEVT_LP_DISCONNECT_IND: /* Link was disconnected */ - LOG_DEBUG("Calling Disconnect_Ind_Cb(), CID: 0x%04x No Conf Needed", - p_ccb->local_cid); + log::debug("Calling Disconnect_Ind_Cb(), CID: 0x{:04x} No Conf Needed", + p_ccb->local_cid); l2cu_release_ccb(p_ccb); (*disconnect_ind)(local_cid, false); break; @@ -842,7 +840,7 @@ static void l2c_csm_w4_l2ca_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, case L2CEVT_L2CA_CREDIT_BASED_CONNECT_RSP: p_ci = (tL2C_CONN_INFO*)p_data; if ((p_lcb == nullptr) || (p_lcb && p_lcb->transport != BT_TRANSPORT_LE)) { - LOG_WARN("LE link doesn't exist"); + log::warn("LE link doesn't exist"); return; } l2cu_send_peer_credit_based_conn_res(p_ccb, p_ci->lcids, @@ -852,8 +850,8 @@ static void l2c_csm_w4_l2ca_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, for (int i = 0; i < p_lcb->pending_ecoc_conn_cnt; i++) { uint16_t cid = p_lcb->pending_ecoc_connection_cids[i]; if (cid == 0) { - LOG_WARN("pending_ecoc_connection_cids[%d] is %d", i, cid); - continue; + log::warn("pending_ecoc_connection_cids[{}] is {}", i, cid); + continue; } tL2C_CCB* temp_p_ccb = l2cu_find_ccb_by_cid(p_lcb, cid); @@ -866,7 +864,9 @@ static void l2c_csm_w4_l2ca_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, } } else { - LOG_WARN("temp_p_ccb is NULL, pending_ecoc_connection_cids[%d] is %d", i, cid); + log::warn( + "temp_p_ccb is NULL, pending_ecoc_connection_cids[{}] is {}", i, + cid); } } p_lcb->pending_ecoc_conn_cnt = 0; @@ -889,15 +889,15 @@ static void l2c_csm_w4_l2ca_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, } else { /* Result should be OK or PENDING */ if ((!p_ci) || (p_ci->l2cap_result == L2CAP_CONN_OK)) { - LOG_DEBUG("Sending connection ok for BR_EDR"); + log::debug("Sending connection ok for BR_EDR"); l2cu_send_peer_connect_rsp(p_ccb, L2CAP_CONN_OK, 0); p_ccb->chnl_state = CST_CONFIG; alarm_set_on_mloop(p_ccb->l2c_ccb_timer, L2CAP_CHNL_CFG_TIMEOUT_MS, l2c_ccb_timer_timeout, p_ccb); } else { /* If pending, stay in same state and start extended timer */ - LOG_DEBUG("Sending connection result %d and status %d", - p_ci->l2cap_result, p_ci->l2cap_status); + log::debug("Sending connection result {} and status {}", + p_ci->l2cap_result, p_ci->l2cap_status); l2cu_send_peer_connect_rsp(p_ccb, p_ci->l2cap_result, p_ci->l2cap_status); alarm_set_on_mloop(p_ccb->l2c_ccb_timer, @@ -938,8 +938,8 @@ static void l2c_csm_w4_l2ca_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, case L2CEVT_TIMEOUT: l2cu_send_peer_connect_rsp(p_ccb, L2CAP_CONN_NO_PSM, 0); - LOG_DEBUG("Calling Disconnect_Ind_Cb(), CID: 0x%04x No Conf Needed", - p_ccb->local_cid); + log::debug("Calling Disconnect_Ind_Cb(), CID: 0x{:04x} No Conf Needed", + p_ccb->local_cid); l2cu_release_ccb(p_ccb); (*disconnect_ind)(local_cid, false); break; @@ -960,17 +960,17 @@ static void l2c_csm_w4_l2ca_connect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, /* We have feature info, so now give the upper layer connect IND */ alarm_set_on_mloop(p_ccb->l2c_ccb_timer, L2CAP_CHNL_CONNECT_TIMEOUT_MS, l2c_ccb_timer_timeout, p_ccb); - LOG_DEBUG("Calling Connect_Ind_Cb(), CID: 0x%04x", p_ccb->local_cid); + log::debug("Calling Connect_Ind_Cb(), CID: 0x{:04x}", p_ccb->local_cid); l2c_csm_send_connect_rsp(p_ccb); l2c_csm_send_config_req(p_ccb); break; default: - LOG_ERROR("Handling unexpected event:%s", l2c_csm_get_event_name(event)); + log::error("Handling unexpected event:{}", l2c_csm_get_event_name(event)); } - LOG_VERBOSE("Exit chnl_state=%s [%d], event=%s [%d]", - channel_state_text(p_ccb->chnl_state).c_str(), p_ccb->chnl_state, - l2c_csm_get_event_name(event), event); + log::verbose("Exit chnl_state={} [{}], event={} [{}]", + channel_state_text(p_ccb->chnl_state), p_ccb->chnl_state, + l2c_csm_get_event_name(event), event); } /******************************************************************************* @@ -993,13 +993,13 @@ static void l2c_csm_config(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { tL2C_CCB* temp_p_ccb; tL2CAP_LE_CFG_INFO* p_le_cfg = (tL2CAP_LE_CFG_INFO*)p_data; - LOG_DEBUG("LCID: 0x%04x st: CONFIG evt: %s", p_ccb->local_cid, - l2c_csm_get_event_name(event)); + log::debug("LCID: 0x{:04x} st: CONFIG evt: {}", p_ccb->local_cid, + l2c_csm_get_event_name(event)); switch (event) { case L2CEVT_LP_DISCONNECT_IND: /* Link was disconnected */ - LOG_DEBUG("Calling Disconnect_Ind_Cb(), CID: 0x%04x No Conf Needed", - p_ccb->local_cid); + log::debug("Calling Disconnect_Ind_Cb(), CID: 0x{:04x} No Conf Needed", + p_ccb->local_cid); l2cu_release_ccb(p_ccb); (*disconnect_ind)(local_cid, false); break; @@ -1008,8 +1008,8 @@ static void l2c_csm_config(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { /* For ecoc reconfig is handled below in l2c_ble. In case of success * let us notify upper layer about the reconfig */ - LOG_DEBUG("Calling LeReconfigCompleted_Cb(), CID: 0x%04x", - p_ccb->local_cid); + log::debug("Calling LeReconfigCompleted_Cb(), CID: 0x{:04x}", + p_ccb->local_cid); (*p_ccb->p_rcb->api.pL2CA_CreditBasedReconfigCompleted_Cb)( p_lcb->remote_bd_addr, p_ccb->local_cid, false, p_le_cfg); @@ -1017,8 +1017,9 @@ static void l2c_csm_config(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { case L2CEVT_L2CAP_CONFIG_REQ: /* Peer config request */ cfg_result = l2cu_process_peer_cfg_req(p_ccb, p_cfg); if (cfg_result == L2CAP_PEER_CFG_OK) { - LOG_DEBUG("Calling Config_Req_Cb(), CID: 0x%04x, C-bit %d", - p_ccb->local_cid, (p_cfg->flags & L2CAP_CFG_FLAGS_MASK_CONT)); + log::debug("Calling Config_Req_Cb(), CID: 0x{:04x}, C-bit {}", + p_ccb->local_cid, + (p_cfg->flags & L2CAP_CFG_FLAGS_MASK_CONT)); l2c_csm_send_config_rsp_ok(p_ccb, p_cfg->flags & L2CAP_CFG_FLAGS_MASK_CONT); if (p_ccb->config_done & OB_CFG_DONE) { @@ -1037,11 +1038,11 @@ static void l2c_csm_config(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { } } else if (cfg_result == L2CAP_PEER_CFG_DISCONNECT) { /* Disconnect if channels are incompatible */ - LOG_DEBUG("incompatible configurations disconnect"); + log::debug("incompatible configurations disconnect"); l2cu_disconnect_chnl(p_ccb); } else /* Return error to peer so it can renegotiate if possible */ { - LOG_DEBUG("incompatible configurations trying reconfig"); + log::debug("incompatible configurations trying reconfig"); l2cu_send_peer_config_rsp(p_ccb, p_cfg); } break; @@ -1052,7 +1053,7 @@ static void l2c_csm_config(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { p_ccb->chnl_state = CST_OPEN; alarm_cancel(p_ccb->l2c_ccb_timer); - LOG_DEBUG("Calling Config_Rsp_Cb(), CID: 0x%04x", p_ccb->local_cid); + log::debug("Calling Config_Rsp_Cb(), CID: 0x{:04x}", p_ccb->local_cid); p_ccb->p_rcb->api.pL2CA_CreditBasedReconfigCompleted_Cb( p_lcb->remote_bd_addr, p_ccb->local_cid, true, p_le_cfg); @@ -1073,9 +1074,9 @@ static void l2c_csm_config(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { /* Verify two sides are in compatible modes before continuing */ if (p_ccb->our_cfg.fcr.mode != p_ccb->peer_cfg.fcr.mode) { l2cu_send_peer_disc_req(p_ccb); - LOG_WARN( - "Calling Disconnect_Ind_Cb(Incompatible CFG), CID: " - "0x%04x No Conf Needed", + log::warn( + "Calling Disconnect_Ind_Cb(Incompatible CFG), CID: 0x{:04x} No " + "Conf Needed", p_ccb->local_cid); l2cu_release_ccb(p_ccb); (*disconnect_ind)(local_cid, false); @@ -1116,7 +1117,7 @@ static void l2c_csm_config(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { p_ccb->peer_cfg.fcr.mode != L2CAP_FCR_BASIC_MODE); } - LOG_DEBUG("Calling Config_Rsp_Cb(), CID: 0x%04x", p_ccb->local_cid); + log::debug("Calling Config_Rsp_Cb(), CID: 0x{:04x}", p_ccb->local_cid); p_ccb->remote_config_rsp_result = p_cfg->result; if (p_ccb->config_done & IB_CFG_DONE) { l2c_csm_indicate_connection_open(p_ccb); @@ -1129,8 +1130,8 @@ static void l2c_csm_config(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { /* If failure was channel mode try to renegotiate */ if (!l2c_fcr_renegotiate_chan(p_ccb, p_cfg)) { - LOG_DEBUG("Calling Config_Rsp_Cb(), CID: 0x%04x, Failure: %d", - p_ccb->local_cid, p_cfg->result); + log::debug("Calling Config_Rsp_Cb(), CID: 0x{:04x}, Failure: {}", + p_ccb->local_cid, p_cfg->result); if (p_ccb->connection_initiator == L2CAP_INITIATOR_LOCAL) { (*p_ccb->p_rcb->api.pL2CA_Error_Cb)(p_ccb->local_cid, L2CAP_CFG_FAILED_NO_REASON); @@ -1145,8 +1146,8 @@ static void l2c_csm_config(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { alarm_set_on_mloop(p_ccb->l2c_ccb_timer, L2CAP_CHNL_DISCONNECT_TIMEOUT_MS, l2c_ccb_timer_timeout, p_ccb); p_ccb->chnl_state = CST_W4_L2CA_DISCONNECT_RSP; - LOG_DEBUG("Calling Disconnect_Ind_Cb(), CID: 0x%04x Conf Needed", - p_ccb->local_cid); + log::debug("Calling Disconnect_Ind_Cb(), CID: 0x{:04x} Conf Needed", + p_ccb->local_cid); (*p_ccb->p_rcb->api.pL2CA_DisconnectInd_Cb)(p_ccb->local_cid, true); l2c_csm_send_disconnect_rsp(p_ccb); break; @@ -1172,9 +1173,9 @@ static void l2c_csm_config(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { /* Verify two sides are in compatible modes before continuing */ if (p_ccb->our_cfg.fcr.mode != p_ccb->peer_cfg.fcr.mode) { l2cu_send_peer_disc_req(p_ccb); - LOG_WARN( - "Calling Disconnect_Ind_Cb(Incompatible CFG), CID: " - "0x%04x No Conf Needed", + log::warn( + "Calling Disconnect_Ind_Cb(Incompatible CFG), CID: 0x{:04x} No " + "Conf Needed", p_ccb->local_cid); l2cu_release_ccb(p_ccb); (*disconnect_ind)(local_cid, false); @@ -1215,7 +1216,7 @@ static void l2c_csm_config(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { break; case L2CEVT_L2CAP_DATA: /* Peer data packet rcvd */ - LOG_DEBUG("Calling DataInd_Cb(), CID: 0x%04x", p_ccb->local_cid); + log::debug("Calling DataInd_Cb(), CID: 0x{:04x}", p_ccb->local_cid); if (p_ccb->local_cid >= L2CAP_FIRST_FIXED_CHNL && p_ccb->local_cid <= L2CAP_LAST_FIXED_CHNL) { if (p_ccb->local_cid < L2CAP_BASE_APPL_CID) { @@ -1261,17 +1262,17 @@ static void l2c_csm_config(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { } l2cu_send_peer_disc_req(p_ccb); - LOG_DEBUG("Calling Disconnect_Ind_Cb(), CID: 0x%04x No Conf Needed", - p_ccb->local_cid); + log::debug("Calling Disconnect_Ind_Cb(), CID: 0x{:04x} No Conf Needed", + p_ccb->local_cid); l2cu_release_ccb(p_ccb); (*disconnect_ind)(local_cid, false); break; default: - LOG_ERROR("Handling unexpected event:%s", l2c_csm_get_event_name(event)); + log::error("Handling unexpected event:{}", l2c_csm_get_event_name(event)); } - LOG_VERBOSE("Exit chnl_state=%s [%d], event=%s [%d]", - channel_state_text(p_ccb->chnl_state).c_str(), p_ccb->chnl_state, - l2c_csm_get_event_name(event), event); + log::verbose("Exit chnl_state={} [{}], event={} [{}]", + channel_state_text(p_ccb->chnl_state), p_ccb->chnl_state, + l2c_csm_get_event_name(event), event); } /******************************************************************************* @@ -1293,13 +1294,13 @@ static void l2c_csm_open(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { uint16_t credit = 0; tL2CAP_LE_CFG_INFO* p_le_cfg = (tL2CAP_LE_CFG_INFO*)p_data; - LOG_VERBOSE("LCID: 0x%04x st: OPEN evt: %s", p_ccb->local_cid, - l2c_csm_get_event_name(event)); + log::verbose("LCID: 0x{:04x} st: OPEN evt: {}", p_ccb->local_cid, + l2c_csm_get_event_name(event)); switch (event) { case L2CEVT_LP_DISCONNECT_IND: /* Link was disconnected */ - LOG_DEBUG("Calling Disconnect_Ind_Cb(), CID: 0x%04x No Conf Needed", - p_ccb->local_cid); + log::debug("Calling Disconnect_Ind_Cb(), CID: 0x{:04x} No Conf Needed", + p_ccb->local_cid); power_telemetry::GetInstance().LogChannelDisconnected( p_ccb->p_rcb->psm, p_ccb->local_cid, p_ccb->remote_id, p_ccb->p_lcb->remote_bd_addr); @@ -1313,8 +1314,8 @@ static void l2c_csm_open(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { * let us notify upper layer about the reconfig */ if (p_le_cfg) { - LOG_DEBUG("Calling LeReconfigCompleted_Cb(), CID: 0x%04x", - p_ccb->local_cid); + log::debug("Calling LeReconfigCompleted_Cb(), CID: 0x{:04x}", + p_ccb->local_cid); (*p_ccb->p_rcb->api.pL2CA_CreditBasedReconfigCompleted_Cb)( p_ccb->p_lcb->remote_bd_addr, p_ccb->local_cid, false, p_le_cfg); } @@ -1362,15 +1363,15 @@ static void l2c_csm_open(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { case L2CEVT_L2CAP_DISCONNECT_REQ: /* Peer disconnected request */ if (p_ccb->p_lcb->transport != BT_TRANSPORT_LE) { if (!BTM_SetLinkPolicyActiveMode(p_ccb->p_lcb->remote_bd_addr)) { - LOG_WARN("Unable to set link policy active"); + log::warn("Unable to set link policy active"); } } p_ccb->chnl_state = CST_W4_L2CA_DISCONNECT_RSP; alarm_set_on_mloop(p_ccb->l2c_ccb_timer, L2CAP_CHNL_DISCONNECT_TIMEOUT_MS, l2c_ccb_timer_timeout, p_ccb); - LOG_DEBUG("Calling Disconnect_Ind_Cb(), CID: 0x%04x Conf Needed", - p_ccb->local_cid); + log::debug("Calling Disconnect_Ind_Cb(), CID: 0x{:04x} Conf Needed", + p_ccb->local_cid); power_telemetry::GetInstance().LogChannelDisconnected( p_ccb->p_rcb->psm, p_ccb->local_cid, p_ccb->remote_id, p_ccb->p_lcb->remote_bd_addr); @@ -1397,7 +1398,7 @@ static void l2c_csm_open(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { if (p_ccb->p_lcb->transport != BT_TRANSPORT_LE) { /* Make sure we are not in sniff mode */ if (!BTM_SetLinkPolicyActiveMode(p_ccb->p_lcb->remote_bd_addr)) { - LOG_WARN("Unable to set link policy active"); + log::warn("Unable to set link policy active"); } } power_telemetry::GetInstance().LogChannelDisconnected( @@ -1437,7 +1438,7 @@ static void l2c_csm_open(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { break; case L2CEVT_L2CA_CONFIG_REQ: /* Upper layer config req */ - LOG_ERROR( + log::error( "Dropping L2CAP re-config request because there is no usage and " "should not be invoked"); break; @@ -1455,7 +1456,7 @@ static void l2c_csm_open(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { case L2CEVT_L2CA_SEND_FLOW_CONTROL_CREDIT: if (p_data) { - LOG_DEBUG("Sending credit"); + log::debug("Sending credit"); credit = *(uint16_t*)p_data; l2cble_send_flow_control_credit(p_ccb, credit); } @@ -1464,7 +1465,7 @@ static void l2c_csm_open(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { case L2CEVT_L2CAP_RECV_FLOW_CONTROL_CREDIT: if (p_data) { credit = *(uint16_t*)p_data; - LOG_DEBUG("Credits received %d", credit); + log::debug("Credits received {}", credit); if ((p_ccb->peer_conn_cfg.credits + credit) > L2CAP_LE_CREDIT_MAX) { /* we have received credits more than max coc credits, * so disconnecting the Le Coc Channel @@ -1477,11 +1478,11 @@ static void l2c_csm_open(tL2C_CCB* p_ccb, tL2CEVT event, void* p_data) { } break; default: - LOG_ERROR("Handling unexpected event:%s", l2c_csm_get_event_name(event)); + log::error("Handling unexpected event:{}", l2c_csm_get_event_name(event)); } - LOG_VERBOSE("Exit chnl_state=%s [%d], event=%s [%d]", - channel_state_text(p_ccb->chnl_state).c_str(), p_ccb->chnl_state, - l2c_csm_get_event_name(event), event); + log::verbose("Exit chnl_state={} [{}], event={} [{}]", + channel_state_text(p_ccb->chnl_state), p_ccb->chnl_state, + l2c_csm_get_event_name(event), event); } /******************************************************************************* @@ -1500,8 +1501,8 @@ static void l2c_csm_w4_l2cap_disconnect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, p_ccb->p_rcb->api.pL2CA_DisconnectCfm_Cb; uint16_t local_cid = p_ccb->local_cid; - LOG_DEBUG("LCID: 0x%04x st: W4_L2CAP_DISC_RSP evt: %s", p_ccb->local_cid, - l2c_csm_get_event_name(event)); + log::debug("LCID: 0x{:04x} st: W4_L2CAP_DISC_RSP evt: {}", p_ccb->local_cid, + l2c_csm_get_event_name(event)); switch (event) { case L2CEVT_L2CAP_DISCONNECT_RSP: /* Peer disconnect response */ @@ -1534,11 +1535,11 @@ static void l2c_csm_w4_l2cap_disconnect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, osi_free(p_data); break; default: - LOG_ERROR("Handling unexpected event:%s", l2c_csm_get_event_name(event)); + log::error("Handling unexpected event:{}", l2c_csm_get_event_name(event)); } - LOG_VERBOSE("Exit chnl_state=%s [%d], event=%s [%d]", - channel_state_text(p_ccb->chnl_state).c_str(), p_ccb->chnl_state, - l2c_csm_get_event_name(event), event); + log::verbose("Exit chnl_state={} [{}], event={} [{}]", + channel_state_text(p_ccb->chnl_state), p_ccb->chnl_state, + l2c_csm_get_event_name(event), event); } /******************************************************************************* @@ -1557,13 +1558,13 @@ static void l2c_csm_w4_l2ca_disconnect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, p_ccb->p_rcb->api.pL2CA_DisconnectInd_Cb; uint16_t local_cid = p_ccb->local_cid; - LOG_DEBUG("LCID: 0x%04x st: W4_L2CA_DISC_RSP evt: %s", p_ccb->local_cid, - l2c_csm_get_event_name(event)); + log::debug("LCID: 0x{:04x} st: W4_L2CA_DISC_RSP evt: {}", p_ccb->local_cid, + l2c_csm_get_event_name(event)); switch (event) { case L2CEVT_LP_DISCONNECT_IND: /* Link was disconnected */ - LOG_DEBUG("Calling Disconnect_Ind_Cb(), CID: 0x%04x No Conf Needed", - p_ccb->local_cid); + log::debug("Calling Disconnect_Ind_Cb(), CID: 0x{:04x} No Conf Needed", + p_ccb->local_cid); l2cu_release_ccb(p_ccb); (*disconnect_ind)(local_cid, false); break; @@ -1571,8 +1572,8 @@ static void l2c_csm_w4_l2ca_disconnect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, case L2CEVT_TIMEOUT: l2cu_send_peer_disc_rsp(p_ccb->p_lcb, p_ccb->remote_id, p_ccb->local_cid, p_ccb->remote_cid); - LOG_DEBUG("Calling Disconnect_Ind_Cb(), CID: 0x%04x No Conf Needed", - p_ccb->local_cid); + log::debug("Calling Disconnect_Ind_Cb(), CID: 0x{:04x} No Conf Needed", + p_ccb->local_cid); l2cu_release_ccb(p_ccb); (*disconnect_ind)(local_cid, false); break; @@ -1589,11 +1590,11 @@ static void l2c_csm_w4_l2ca_disconnect_rsp(tL2C_CCB* p_ccb, tL2CEVT event, osi_free(p_data); break; default: - LOG_ERROR("Handling unexpected event:%s", l2c_csm_get_event_name(event)); + log::error("Handling unexpected event:{}", l2c_csm_get_event_name(event)); } - LOG_VERBOSE("Exit chnl_state=%s [%d], event=%s [%d]", - channel_state_text(p_ccb->chnl_state).c_str(), p_ccb->chnl_state, - l2c_csm_get_event_name(event), event); + log::verbose("Exit chnl_state={} [{}], event={} [{}]", + channel_state_text(p_ccb->chnl_state), p_ccb->chnl_state, + l2c_csm_get_event_name(event), event); } /******************************************************************************* @@ -1744,10 +1745,10 @@ void l2c_enqueue_peer_data(tL2C_CCB* p_ccb, BT_HDR* p_buf) { } if (p_ccb->xmit_hold_q == NULL) { - LOG_ERROR( - "empty queue: p_ccb = %p p_ccb->in_use = %d p_ccb->chnl_state = %d " - "p_ccb->local_cid = %u p_ccb->remote_cid = %u", - p_ccb, p_ccb->in_use, p_ccb->chnl_state, p_ccb->local_cid, + log::error( + "empty queue: p_ccb = {} p_ccb->in_use = {} p_ccb->chnl_state = {} " + "p_ccb->local_cid = {} p_ccb->remote_cid = {}", + fmt::ptr(p_ccb), p_ccb->in_use, p_ccb->chnl_state, p_ccb->local_cid, p_ccb->remote_cid); } else { fixed_queue_enqueue(p_ccb->xmit_hold_q, p_buf); diff --git a/system/stack/l2cap/l2c_fcr.cc b/system/stack/l2cap/l2c_fcr.cc index 6d8e95d477acc71310ce0e03d5b4815083562e8d..be6678561ab97d0f4b36b218d7debcdf5de05ec0 100644 --- a/system/stack/l2cap/l2c_fcr.cc +++ b/system/stack/l2cap/l2c_fcr.cc @@ -24,6 +24,7 @@ ******************************************************************************/ #include <base/logging.h> +#include <bluetooth/log.h> #include <stdio.h> #include <stdlib.h> #include <string.h> @@ -42,6 +43,8 @@ */ #define L2C_FCR_RETX_ALL_PKTS 0xFF +using namespace bluetooth; + /* this is the minimal offset required by OBX to process incoming packets */ static const uint16_t OBX_BUF_MIN_OFFSET = 4; @@ -349,18 +352,18 @@ static void prepare_I_frame(tL2C_CCB* p_ccb, BT_HDR* p_buf, p_buf->len += L2CAP_FCS_LEN; if (is_retransmission) { - LOG_VERBOSE( - "L2CAP eRTM ReTx I-frame CID: 0x%04x Len: %u SAR: %s TxSeq: %u " - "ReqSeq: %u F: %u", + log::verbose( + "L2CAP eRTM ReTx I-frame CID: 0x{:04x} Len: {} SAR: {} TxSeq: {} " + "ReqSeq: {} F: {}", p_ccb->local_cid, p_buf->len, SAR_types[(ctrl_word & L2CAP_FCR_SAR_BITS) >> L2CAP_FCR_SAR_BITS_SHIFT], (ctrl_word & L2CAP_FCR_TX_SEQ_BITS) >> L2CAP_FCR_TX_SEQ_BITS_SHIFT, (ctrl_word & L2CAP_FCR_REQ_SEQ_BITS) >> L2CAP_FCR_REQ_SEQ_BITS_SHIFT, (ctrl_word & L2CAP_FCR_F_BIT) >> L2CAP_FCR_F_BIT_SHIFT); } else { - LOG_VERBOSE( - "L2CAP eRTM Tx I-frame CID: 0x%04x Len: %u SAR: %-12s TxSeq: %u " - "ReqSeq: %u F: %u", + log::verbose( + "L2CAP eRTM Tx I-frame CID: 0x{:04x} Len: {} SAR: {:<12s} TxSeq: {} " + " ReqSeq: {} F: {}", p_ccb->local_cid, p_buf->len, SAR_types[(ctrl_word & L2CAP_FCR_SAR_BITS) >> L2CAP_FCR_SAR_BITS_SHIFT], (ctrl_word & L2CAP_FCR_TX_SEQ_BITS) >> L2CAP_FCR_TX_SEQ_BITS_SHIFT, @@ -427,25 +430,25 @@ void l2c_fcr_send_S_frame(tL2C_CCB* p_ccb, uint16_t function_code, if ((((ctrl_word & L2CAP_FCR_SUP_BITS) >> L2CAP_FCR_SUP_SHIFT) == 1) || (((ctrl_word & L2CAP_FCR_SUP_BITS) >> L2CAP_FCR_SUP_SHIFT) == 3)) { - LOG_WARN( - "L2CAP eRTM Tx S-frame CID: 0x%04x ctrlword: 0x%04x Type: %s " - "ReqSeq: %u P: %u F: %u", + log::warn( + "L2CAP eRTM Tx S-frame CID: 0x{:04x} ctrlword: 0x{:04x} Type: {} " + "ReqSeq: {} P: {} F: {}", p_ccb->local_cid, ctrl_word, SUP_types[(ctrl_word & L2CAP_FCR_SUP_BITS) >> L2CAP_FCR_SUP_SHIFT], (ctrl_word & L2CAP_FCR_REQ_SEQ_BITS) >> L2CAP_FCR_REQ_SEQ_BITS_SHIFT, (ctrl_word & L2CAP_FCR_P_BIT) >> L2CAP_FCR_P_BIT_SHIFT, (ctrl_word & L2CAP_FCR_F_BIT) >> L2CAP_FCR_F_BIT_SHIFT); - LOG_WARN(" Buf Len: %u", p_buf->len); + log::warn("Buf Len: {}", p_buf->len); } else { - LOG_VERBOSE( - "L2CAP eRTM Tx S-frame CID: 0x%04x ctrlword: 0x%04x Type: %s " - "ReqSeq: %u P: %u F: %u", + log::verbose( + "L2CAP eRTM Tx S-frame CID: 0x{:04x} ctrlword: 0x{:04x} Type: {} " + "ReqSeq: {} P: {} F: {}", p_ccb->local_cid, ctrl_word, SUP_types[(ctrl_word & L2CAP_FCR_SUP_BITS) >> L2CAP_FCR_SUP_SHIFT], (ctrl_word & L2CAP_FCR_REQ_SEQ_BITS) >> L2CAP_FCR_REQ_SEQ_BITS_SHIFT, (ctrl_word & L2CAP_FCR_P_BIT) >> L2CAP_FCR_P_BIT_SHIFT, (ctrl_word & L2CAP_FCR_F_BIT) >> L2CAP_FCR_F_BIT_SHIFT); - LOG_VERBOSE(" Buf Len: %u", p_buf->len); + log::verbose("Buf Len: {}", p_buf->len); } l2c_link_check_send_pkts(p_ccb->p_lcb, 0, p_buf); @@ -478,8 +481,8 @@ void l2c_fcr_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { min_pdu_len = (uint16_t)(L2CAP_FCS_LEN + L2CAP_FCR_OVERHEAD); if (p_buf->len < min_pdu_len) { - LOG_WARN("Rx L2CAP PDU: CID: 0x%04x Len too short: %u", p_ccb->local_cid, - p_buf->len); + log::warn("Rx L2CAP PDU: CID: 0x{:04x} Len too short: {}", + p_ccb->local_cid, p_buf->len); osi_free(p_buf); return; } @@ -492,18 +495,18 @@ void l2c_fcr_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { if ((((ctrl_word & L2CAP_FCR_SUP_BITS) >> L2CAP_FCR_SUP_SHIFT) == 1) || (((ctrl_word & L2CAP_FCR_SUP_BITS) >> L2CAP_FCR_SUP_SHIFT) == 3)) { /* REJ or SREJ */ - LOG_WARN( - "L2CAP eRTM Rx S-frame: cid: 0x%04x Len: %u Type: %s ReqSeq: %u " - "P: %u F: %u", + log::warn( + "L2CAP eRTM Rx S-frame: cid: 0x{:04x} Len: {} Type: {} ReqSeq: {} " + " P: {} F: {}", p_ccb->local_cid, p_buf->len, SUP_types[(ctrl_word & L2CAP_FCR_SUP_BITS) >> L2CAP_FCR_SUP_SHIFT], (ctrl_word & L2CAP_FCR_REQ_SEQ_BITS) >> L2CAP_FCR_REQ_SEQ_BITS_SHIFT, (ctrl_word & L2CAP_FCR_P_BIT) >> L2CAP_FCR_P_BIT_SHIFT, (ctrl_word & L2CAP_FCR_F_BIT) >> L2CAP_FCR_F_BIT_SHIFT); } else { - LOG_VERBOSE( - "L2CAP eRTM Rx S-frame: cid: 0x%04x Len: %u Type: %s ReqSeq: %u " - "P: %u F: %u", + log::verbose( + "L2CAP eRTM Rx S-frame: cid: 0x{:04x} Len: {} Type: {} ReqSeq: {} " + " P: {} F: {}", p_ccb->local_cid, p_buf->len, SUP_types[(ctrl_word & L2CAP_FCR_SUP_BITS) >> L2CAP_FCR_SUP_SHIFT], (ctrl_word & L2CAP_FCR_REQ_SEQ_BITS) >> L2CAP_FCR_REQ_SEQ_BITS_SHIFT, @@ -511,9 +514,9 @@ void l2c_fcr_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { (ctrl_word & L2CAP_FCR_F_BIT) >> L2CAP_FCR_F_BIT_SHIFT); } } else { - LOG_VERBOSE( - "L2CAP eRTM Rx I-frame: cid: 0x%04x Len: %u SAR: %-12s TxSeq: %u " - "ReqSeq: %u F: %u", + log::verbose( + "L2CAP eRTM Rx I-frame: cid: 0x{:04x} Len: {} SAR: {:<12s} TxSeq: " + "{} ReqSeq: {} F: {}", p_ccb->local_cid, p_buf->len, SAR_types[(ctrl_word & L2CAP_FCR_SAR_BITS) >> L2CAP_FCR_SAR_BITS_SHIFT], (ctrl_word & L2CAP_FCR_TX_SEQ_BITS) >> L2CAP_FCR_TX_SEQ_BITS_SHIFT, @@ -521,9 +524,9 @@ void l2c_fcr_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { (ctrl_word & L2CAP_FCR_F_BIT) >> L2CAP_FCR_F_BIT_SHIFT); } - LOG_VERBOSE( - " eRTM Rx Nxt_tx_seq %u, Lst_rx_ack %u, Nxt_seq_exp %u, Lst_ack_snt " - "%u, wt_q.cnt %zu, tries %u", + log::verbose( + "eRTM Rx Nxt_tx_seq {}, Lst_rx_ack {}, Nxt_seq_exp {}, Lst_ack_snt {}, " + "wt_q.cnt {}, tries {}", p_ccb->fcrb.next_tx_seq, p_ccb->fcrb.last_rx_ack, p_ccb->fcrb.next_seq_expected, p_ccb->fcrb.last_ack_sent, fixed_queue_length(p_ccb->fcrb.waiting_for_ack_q), p_ccb->fcrb.num_tries); @@ -536,7 +539,7 @@ void l2c_fcr_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { p_buf->len -= L2CAP_FCS_LEN; if (l2c_fcr_rx_get_fcs(p_buf) != fcs) { - LOG_WARN("Rx L2CAP PDU: CID: 0x%04x BAD FCS", p_ccb->local_cid); + log::warn("Rx L2CAP PDU: CID: 0x{:04x} BAD FCS", p_ccb->local_cid); osi_free(p_buf); return; } @@ -619,9 +622,9 @@ void l2c_fcr_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { STREAM_TO_UINT16(ctrl_word, p); - LOG_VERBOSE( - "l2c_fcr_proc_pdu() CID: 0x%04x Process Buffer from SREJ_Hold_Q " - "TxSeq: %u Expected_Seq: %u", + log::verbose( + "l2c_fcr_proc_pdu() CID: 0x{:04x} Process Buffer from SREJ_Hold_Q " + " TxSeq: {} Expected_Seq: {}", p_ccb->local_cid, (ctrl_word & L2CAP_FCR_TX_SEQ_BITS) >> L2CAP_FCR_TX_SEQ_BITS_SHIFT, p_ccb->fcrb.next_seq_expected); @@ -647,9 +650,9 @@ void l2c_fcr_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { (p_ccb->fcrb.next_seq_expected != p_ccb->fcrb.last_ack_sent)) l2c_fcr_send_S_frame(p_ccb, L2CAP_FCR_SUP_RR, 0); else { - LOG_VERBOSE( - "l2c_fcr_proc_pdu() not sending RR CID: 0x%04x local_busy:%d " - "rej_sent:%d srej_sent:%d Expected_Seq:%u Last_Ack:%u", + log::verbose( + "l2c_fcr_proc_pdu() not sending RR CID: 0x{:04x} local_busy:{} " + "rej_sent:{} srej_sent:{} Expected_Seq:{} Last_Ack:{}", p_ccb->local_cid, 0, p_ccb->fcrb.rej_sent, p_ccb->fcrb.srej_sent, p_ccb->fcrb.next_seq_expected, p_ccb->fcrb.last_ack_sent); } @@ -682,8 +685,8 @@ void l2c_lcc_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { /* Buffer length should not exceed local mps */ if (p_buf->len > p_ccb->local_conn_cfg.mps) { - LOG_ERROR("buffer length=%d exceeds local mps=%d. Drop and disconnect.", - p_buf->len, p_ccb->local_conn_cfg.mps); + log::error("buffer length={} exceeds local mps={}. Drop and disconnect.", + p_buf->len, p_ccb->local_conn_cfg.mps); /* Discard the buffer and disconnect*/ osi_free(p_buf); @@ -693,8 +696,7 @@ void l2c_lcc_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { if (p_ccb->is_first_seg) { if (p_buf->len < sizeof(sdu_length)) { - LOG_ERROR("%s: buffer length=%d too small. Need at least 2.", __func__, - p_buf->len); + log::error("buffer length={} too small. Need at least 2.", p_buf->len); /* Discard the buffer */ osi_free(p_buf); return; @@ -703,8 +705,8 @@ void l2c_lcc_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { /* Check the SDU Length with local MTU size */ if (sdu_length > p_ccb->local_conn_cfg.mtu) { - LOG_ERROR("sdu length=%d exceeds local mtu=%d. Drop and disconnect.", - sdu_length, p_ccb->local_conn_cfg.mtu); + log::error("sdu length={} exceeds local mtu={}. Drop and disconnect.", + sdu_length, p_ccb->local_conn_cfg.mtu); /* Discard the buffer and disconnect*/ osi_free(p_buf); l2cu_disconnect_chnl(p_ccb); @@ -715,7 +717,7 @@ void l2c_lcc_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { p_buf->offset += sizeof(sdu_length); if (sdu_length < p_buf->len) { - LOG_ERROR("%s: Invalid sdu_length: %d", __func__, sdu_length); + log::error("Invalid sdu_length: {}", sdu_length); /* Discard the buffer */ osi_free(p_buf); return; @@ -730,7 +732,7 @@ void l2c_lcc_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { p_ccb->ble_sdu = p_data; p_data->len = 0; p_ccb->ble_sdu_length = sdu_length; - LOG_VERBOSE("%s SDU Length = %d", __func__, sdu_length); + log::verbose("SDU Length = {}", sdu_length); p_data->offset = 0; } else { @@ -740,8 +742,8 @@ void l2c_lcc_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { return; } if (p_buf->len > (p_ccb->ble_sdu_length - p_data->len)) { - LOG_ERROR("%s: buffer length=%d too big. max=%d. Dropped", __func__, - p_data->len, (p_ccb->ble_sdu_length - p_data->len)); + log::error("buffer length={} too big. max={}. Dropped", p_data->len, + (p_ccb->ble_sdu_length - p_data->len)); osi_free(p_buf); /* Throw away all pending fragments and disconnects */ @@ -782,9 +784,9 @@ void l2c_lcc_proc_pdu(tL2C_CCB* p_ccb, BT_HDR* p_buf) { ******************************************************************************/ void l2c_fcr_proc_tout(tL2C_CCB* p_ccb) { CHECK(p_ccb != NULL); - LOG_VERBOSE( - "l2c_fcr_proc_tout: CID: 0x%04x num_tries: %u (max: %u) wait_ack: %u " - "ack_q_count: %zu", + log::verbose( + "l2c_fcr_proc_tout: CID: 0x{:04x} num_tries: {} (max: {}) wait_ack: " + "{} ack_q_count: {}", p_ccb->local_cid, p_ccb->fcrb.num_tries, p_ccb->peer_cfg.fcr.max_transmit, p_ccb->fcrb.wait_ack, fixed_queue_length(p_ccb->fcrb.waiting_for_ack_q)); @@ -809,8 +811,9 @@ void l2c_fcr_proc_tout(tL2C_CCB* p_ccb) { ******************************************************************************/ void l2c_fcr_proc_ack_tout(tL2C_CCB* p_ccb) { CHECK(p_ccb != NULL); - LOG_VERBOSE( - "l2c_fcr_proc_ack_tout: CID: 0x%04x State: %u Wack:%u Rq:%d Acked:%d", + log::verbose( + "l2c_fcr_proc_ack_tout: CID: 0x{:04x} State: {} Wack:{} Rq:{} " + "Acked:{}", p_ccb->local_cid, p_ccb->chnl_state, p_ccb->fcrb.wait_ack, p_ccb->fcrb.next_seq_expected, p_ccb->fcrb.last_ack_sent); @@ -858,9 +861,9 @@ static bool process_reqseq(tL2C_CCB* p_ccb, uint16_t ctrl_word) { /* Verify the request sequence is in range before proceeding */ if (num_bufs_acked > fixed_queue_length(p_fcrb->waiting_for_ack_q)) { /* The channel is closed if ReqSeq is not in range */ - LOG_WARN( - "L2CAP eRTM Frame BAD Req_Seq - ctrl_word: 0x%04x req_seq 0x%02x " - "last_rx_ack: 0x%02x QCount: %zu", + log::warn( + "L2CAP eRTM Frame BAD Req_Seq - ctrl_word: 0x{:04x} req_seq 0x{:02x} " + "last_rx_ack: 0x{:02x} QCount: {}", ctrl_word, req_seq, p_fcrb->last_rx_ack, fixed_queue_length(p_fcrb->waiting_for_ack_q)); @@ -931,11 +934,11 @@ static void process_s_frame(tL2C_CCB* p_ccb, BT_HDR* p_buf, bool all_ok = true; if (p_buf->len != 0) { - LOG_WARN("Incorrect S-frame Length (%d)", p_buf->len); + log::warn("Incorrect S-frame Length ({})", p_buf->len); } - LOG_VERBOSE("process_s_frame ctrl_word 0x%04x fcrb_remote_busy:%d", ctrl_word, - p_fcrb->remote_busy); + log::verbose("process_s_frame ctrl_word 0x{:04x} fcrb_remote_busy:{}", + ctrl_word, p_fcrb->remote_busy); if (ctrl_word & L2CAP_FCR_P_BIT) { p_fcrb->rej_sent = false; /* After checkpoint, we can send anoher REJ */ @@ -981,7 +984,7 @@ static void process_s_frame(tL2C_CCB* p_ccb, BT_HDR* p_buf, p_fcrb->send_f_rsp = false; } } else { - LOG_VERBOSE("process_s_frame hit_max_retries"); + log::verbose("process_s_frame hit_max_retries"); } osi_free(p_buf); @@ -1023,15 +1026,15 @@ static void process_i_frame(tL2C_CCB* p_ccb, BT_HDR* p_buf, uint16_t ctrl_word, /* Is the frame a duplicate ? If so, just drop it */ if (num_lost >= p_ccb->our_cfg.fcr.tx_win_sz) { /* Duplicate - simply drop it */ - LOG_WARN( - "process_i_frame() Dropping Duplicate Frame tx_seq:%u ExpectedTxSeq " - "%u", + log::warn( + "process_i_frame() Dropping Duplicate Frame tx_seq:{} ExpectedTxSeq " + "{}", tx_seq, p_fcrb->next_seq_expected); osi_free(p_buf); } else { - LOG_WARN( - "process_i_frame() CID: 0x%04x Lost: %u tx_seq:%u ExpTxSeq %u " - "Rej: %u SRej: %u", + log::warn( + "process_i_frame() CID: 0x{:04x} Lost: {} tx_seq:{} ExpTxSeq {} " + "Rej: {} SRej: {}", p_ccb->local_cid, num_lost, tx_seq, p_fcrb->next_seq_expected, p_fcrb->rej_sent, p_fcrb->srej_sent); @@ -1047,17 +1050,17 @@ static void process_i_frame(tL2C_CCB* p_ccb, BT_HDR* p_buf, uint16_t ctrl_word, if ((tx_seq == next_srej) && (fixed_queue_length(p_fcrb->srej_rcv_hold_q) < p_ccb->our_cfg.fcr.tx_win_sz)) { - LOG_VERBOSE( - "process_i_frame() Lost: %u tx_seq:%u ExpTxSeq %u Rej: %u " + log::verbose( + "process_i_frame() Lost: {} tx_seq:{} ExpTxSeq {} Rej: {} " "SRej1", num_lost, tx_seq, p_fcrb->next_seq_expected, p_fcrb->rej_sent); p_buf->layer_specific = tx_seq; fixed_queue_enqueue(p_fcrb->srej_rcv_hold_q, p_buf); } else { - LOG_WARN( - "process_i_frame() CID: 0x%04x frame dropped in Srej Sent " - "next_srej:%u hold_q.count:%zu win_sz:%u", + log::warn( + "process_i_frame() CID: 0x{:04x} frame dropped in Srej Sent " + "next_srej:{} hold_q.count:{} win_sz:{}", p_ccb->local_cid, next_srej, fixed_queue_length(p_fcrb->srej_rcv_hold_q), p_ccb->our_cfg.fcr.tx_win_sz); @@ -1066,17 +1069,17 @@ static void process_i_frame(tL2C_CCB* p_ccb, BT_HDR* p_buf, uint16_t ctrl_word, osi_free(p_buf); } } else if (p_fcrb->rej_sent) { - LOG_WARN( - "process_i_frame() CID: 0x%04x Lost: %u tx_seq:%u ExpTxSeq %u " - "Rej: 1 SRej: %u", + log::warn( + "process_i_frame() CID: 0x{:04x} Lost: {} tx_seq:{} ExpTxSeq {} " + " Rej: 1 SRej: {}", p_ccb->local_cid, num_lost, tx_seq, p_fcrb->next_seq_expected, p_fcrb->srej_sent); /* If REJ sent, just drop the frame */ osi_free(p_buf); } else { - LOG_VERBOSE( - "process_i_frame() CID: 0x%04x tx_seq:%u ExpTxSeq %u Rej: %u", + log::verbose( + "process_i_frame() CID: 0x{:04x} tx_seq:{} ExpTxSeq {} Rej: {}", p_ccb->local_cid, tx_seq, p_fcrb->next_seq_expected, p_fcrb->rej_sent); @@ -1087,9 +1090,9 @@ static void process_i_frame(tL2C_CCB* p_ccb, BT_HDR* p_buf, uint16_t ctrl_word, l2c_fcr_send_S_frame(p_ccb, L2CAP_FCR_SUP_REJ, 0); } else { if (!fixed_queue_is_empty(p_fcrb->srej_rcv_hold_q)) { - LOG_ERROR( - "process_i_frame() CID: 0x%04x sending SREJ tx_seq:%d " - "hold_q.count:%zu", + log::error( + "process_i_frame() CID: 0x{:04x} sending SREJ tx_seq:{} " + "hold_q.count:{}", p_ccb->local_cid, tx_seq, fixed_queue_length(p_fcrb->srej_rcv_hold_q)); } @@ -1115,8 +1118,8 @@ static void process_i_frame(tL2C_CCB* p_ccb, BT_HDR* p_buf, uint16_t ctrl_word, /* If any SAR problem in eRTM mode, spec says disconnect. */ if (!do_sar_reassembly(p_ccb, p_buf, ctrl_word)) { - LOG_WARN("process_i_frame() CID: 0x%04x reassembly failed", - p_ccb->local_cid); + log::warn("process_i_frame() CID: 0x{:04x} reassembly failed", + p_ccb->local_cid); l2cu_disconnect_chnl(p_ccb); return; } @@ -1168,9 +1171,9 @@ static bool do_sar_reassembly(tL2C_CCB* p_ccb, BT_HDR* p_buf, /* Check if the SAR state is correct */ if ((sar_type == L2CAP_FCR_UNSEG_SDU) || (sar_type == L2CAP_FCR_START_SDU)) { if (p_fcrb->p_rx_sdu != NULL) { - LOG_WARN( - "SAR - got unexpected unsegmented or start SDU Expected len: %u " - "Got so far: %u", + log::warn( + "SAR - got unexpected unsegmented or start SDU Expected len: {} " + "Got so far: {}", p_fcrb->rx_sdu_len, p_fcrb->p_rx_sdu->len); packet_ok = false; @@ -1178,12 +1181,12 @@ static bool do_sar_reassembly(tL2C_CCB* p_ccb, BT_HDR* p_buf, /* Check the length of the packet */ if ((sar_type == L2CAP_FCR_START_SDU) && (p_buf->len < L2CAP_SDU_LEN_OVERHEAD)) { - LOG_WARN("SAR start packet too short: %u", p_buf->len); + log::warn("SAR start packet too short: {}", p_buf->len); packet_ok = false; } } else { if (p_fcrb->p_rx_sdu == NULL) { - LOG_WARN("SAR - got unexpected cont or end SDU"); + log::warn("SAR - got unexpected cont or end SDU"); packet_ok = false; } } @@ -1199,8 +1202,8 @@ static bool do_sar_reassembly(tL2C_CCB* p_ccb, BT_HDR* p_buf, p_buf->len -= 2; if (p_fcrb->rx_sdu_len > p_ccb->max_rx_mtu) { - LOG_WARN("SAR - SDU len: %u larger than MTU: %u", p_fcrb->rx_sdu_len, - p_ccb->max_rx_mtu); + log::warn("SAR - SDU len: {} larger than MTU: {}", p_fcrb->rx_sdu_len, + p_ccb->max_rx_mtu); packet_ok = false; } else { p_fcrb->p_rx_sdu = (BT_HDR*)osi_malloc( @@ -1212,14 +1215,14 @@ static bool do_sar_reassembly(tL2C_CCB* p_ccb, BT_HDR* p_buf, if (packet_ok) { if ((p_fcrb->p_rx_sdu->len + p_buf->len) > p_fcrb->rx_sdu_len) { - LOG_ERROR("SAR - SDU len exceeded Type: %u Lengths: %u %u %u", - sar_type, p_fcrb->p_rx_sdu->len, p_buf->len, - p_fcrb->rx_sdu_len); + log::error("SAR - SDU len exceeded Type: {} Lengths: {} {} {}", + sar_type, p_fcrb->p_rx_sdu->len, p_buf->len, + p_fcrb->rx_sdu_len); packet_ok = false; } else if ((sar_type == L2CAP_FCR_END_SDU) && ((p_fcrb->p_rx_sdu->len + p_buf->len) != p_fcrb->rx_sdu_len)) { - LOG_WARN("SAR - SDU end rcvd but SDU incomplete: %u %u %u", - p_fcrb->p_rx_sdu->len, p_buf->len, p_fcrb->rx_sdu_len); + log::warn("SAR - SDU end rcvd but SDU incomplete: {} {} {}", + p_fcrb->p_rx_sdu->len, p_buf->len, p_fcrb->rx_sdu_len); packet_ok = false; } else { memcpy(((uint8_t*)(p_fcrb->p_rx_sdu + 1)) + p_fcrb->p_rx_sdu->offset + @@ -1277,9 +1280,9 @@ static bool retransmit_i_frames(tL2C_CCB* p_ccb, uint8_t tx_seq) { if ((!fixed_queue_is_empty(p_ccb->fcrb.waiting_for_ack_q)) && (p_ccb->peer_cfg.fcr.max_transmit != 0) && (p_ccb->fcrb.num_tries >= p_ccb->peer_cfg.fcr.max_transmit)) { - LOG_VERBOSE( - "Max Tries Exceeded: (last_acq: %d CID: 0x%04x num_tries: %u (max: " - "%u) ack_q_count: %zu", + log::verbose( + "Max Tries Exceeded: (last_acq: {} CID: 0x{:04x} num_tries: {} " + "(max: {}) ack_q_count: {}", p_ccb->fcrb.last_rx_ack, p_ccb->local_cid, p_ccb->fcrb.num_tries, p_ccb->peer_cfg.fcr.max_transmit, fixed_queue_length(p_ccb->fcrb.waiting_for_ack_q)); @@ -1310,16 +1313,16 @@ static bool retransmit_i_frames(tL2C_CCB* p_ccb, uint8_t tx_seq) { buf_seq = (ctrl_word & L2CAP_FCR_TX_SEQ_BITS) >> L2CAP_FCR_TX_SEQ_BITS_SHIFT; - LOG_VERBOSE("retransmit_i_frames() cur seq: %u looking for: %u", - buf_seq, tx_seq); + log::verbose("retransmit_i_frames() cur seq: {} looking for: {}", + buf_seq, tx_seq); if (tx_seq == buf_seq) break; } } if (!p_buf) { - LOG_ERROR("retransmit_i_frames() UNKNOWN seq: %u q_count: %zu", tx_seq, - fixed_queue_length(p_ccb->fcrb.waiting_for_ack_q)); + log::error("retransmit_i_frames() UNKNOWN seq: {} q_count: {}", tx_seq, + fixed_queue_length(p_ccb->fcrb.waiting_for_ack_q)); return (true); } } else { @@ -1439,8 +1442,8 @@ BT_HDR* l2c_fcr_get_next_xmit_sdu_seg(tL2C_CCB* p_ccb, } else /* Should never happen if the application has configured buffers correctly */ { - LOG_ERROR("L2CAP - cannot get buffer for segmentation, max_pdu: %u", - max_pdu); + log::error("L2CAP - cannot get buffer for segmentation, max_pdu: {}", + max_pdu); return (NULL); } } else /* Use the original buffer if no segmentation, or the last segment */ @@ -1495,8 +1498,9 @@ BT_HDR* l2c_fcr_get_next_xmit_sdu_seg(tL2C_CCB* p_ccb, l2c_fcr_clone_buf(p_xmit, HCI_DATA_PREAMBLE_SIZE, p_xmit->len); if (!p_wack) { - LOG_ERROR("L2CAP - no buffer for xmit cloning, CID: 0x%04x Length: %u", - p_ccb->local_cid, p_xmit->len); + log::error( + "L2CAP - no buffer for xmit cloning, CID: 0x{:04x} Length: {}", + p_ccb->local_cid, p_xmit->len); /* We will not save the FCS in case we reconfigure and change options */ p_xmit->len -= L2CAP_FCS_LEN; @@ -1600,7 +1604,7 @@ uint8_t l2c_fcr_chk_chan_modes(tL2C_CCB* p_ccb) { /* Remove nonbasic options that the peer does not support */ if (!(p_ccb->p_lcb->peer_ext_fea & L2CAP_EXTFEA_ENH_RETRANS) && p_ccb->p_rcb->ertm_info.preferred_mode == L2CAP_FCR_ERTM_MODE) { - LOG_WARN("L2CAP - Peer does not support our desired channel types"); + log::warn("L2CAP - Peer does not support our desired channel types"); p_ccb->p_rcb->ertm_info.preferred_mode = 0; return false; } @@ -1636,8 +1640,8 @@ void l2c_fcr_adj_monitor_retran_timeout(tL2C_CCB* p_ccb) { p_ccb->our_cfg.fcr.rtrans_tout = 0; } - LOG_VERBOSE( - "l2c_fcr_adj_monitor_retran_timeout: mon_tout:%d, rtrans_tout:%d", + log::verbose( + "l2c_fcr_adj_monitor_retran_timeout: mon_tout:{}, rtrans_tout:{}", p_ccb->our_cfg.fcr.mon_tout, p_ccb->our_cfg.fcr.rtrans_tout); } } @@ -1667,8 +1671,8 @@ void l2c_fcr_adj_our_rsp_options(tL2C_CCB* p_ccb, tL2CAP_CFG_INFO* p_cfg) { * adjust it. For now, respond with our own tx_wnd_sz. */ /* Note: peer is not guaranteed to obey our adjustment */ if (p_ccb->peer_cfg.fcr.tx_win_sz > p_ccb->our_cfg.fcr.tx_win_sz) { - LOG_VERBOSE("%s: adjusting requested tx_win_sz from %i to %i", __func__, - p_ccb->peer_cfg.fcr.tx_win_sz, p_ccb->our_cfg.fcr.tx_win_sz); + log::verbose("adjusting requested tx_win_sz from {} to {}", + p_ccb->peer_cfg.fcr.tx_win_sz, p_ccb->our_cfg.fcr.tx_win_sz); p_ccb->peer_cfg.fcr.tx_win_sz = p_ccb->our_cfg.fcr.tx_win_sz; } @@ -1712,7 +1716,7 @@ bool l2c_fcr_renegotiate_chan(tL2C_CCB* p_ccb, tL2CAP_CFG_INFO* p_cfg) { if (p_ccb->our_cfg.fcr.mode != peer_mode) { if ((--p_ccb->fcr_cfg_tries) == 0) { p_cfg->result = L2CAP_CFG_FAILED_NO_REASON; - LOG_WARN("l2c_fcr_renegotiate_chan (Max retries exceeded)"); + log::warn("l2c_fcr_renegotiate_chan (Max retries exceeded)"); } can_renegotiate = false; @@ -1723,7 +1727,7 @@ bool l2c_fcr_renegotiate_chan(tL2C_CCB* p_ccb, tL2CAP_CFG_INFO* p_cfg) { case L2CAP_FCR_ERTM_MODE: /* We can try basic for any other peer mode because it's always * supported */ - LOG_VERBOSE("%s(Trying Basic)", __func__); + log::verbose("(Trying Basic)"); can_renegotiate = true; p_ccb->our_cfg.fcr.mode = L2CAP_FCR_BASIC_MODE; break; @@ -1742,7 +1746,7 @@ bool l2c_fcr_renegotiate_chan(tL2C_CCB* p_ccb, tL2CAP_CFG_INFO* p_cfg) { /* Basic Mode uses ACL Data Pool, make sure the MTU fits */ if ((p_cfg->mtu_present) && (p_cfg->mtu > L2CAP_MTU_SIZE)) { - LOG_WARN("L2CAP - adjust MTU: %u too large", p_cfg->mtu); + log::warn("L2CAP - adjust MTU: {} too large", p_cfg->mtu); p_cfg->mtu = L2CAP_MTU_SIZE; } } @@ -1758,8 +1762,8 @@ bool l2c_fcr_renegotiate_chan(tL2C_CCB* p_ccb, tL2CAP_CFG_INFO* p_cfg) { /* Disconnect if the channels do not match */ if (p_ccb->our_cfg.fcr.mode != peer_mode) { - LOG_WARN("L2C CFG: Channels incompatible (local %d, peer %d)", - p_ccb->our_cfg.fcr.mode, peer_mode); + log::warn("L2C CFG: Channels incompatible (local {}, peer {})", + p_ccb->our_cfg.fcr.mode, peer_mode); l2cu_disconnect_chnl(p_ccb); } @@ -1787,9 +1791,9 @@ uint8_t l2c_fcr_process_peer_cfg_req(tL2C_CCB* p_ccb, tL2CAP_CFG_INFO* p_cfg) { p_ccb->p_lcb->w4_info_rsp = false; /* Handles T61x SonyEricsson Bug in Info Request */ - LOG_VERBOSE( - "l2c_fcr_process_peer_cfg_req() CFG fcr_present:%d fcr.mode:%d CCB FCR " - "mode:%d preferred: %u", + log::verbose( + "l2c_fcr_process_peer_cfg_req() CFG fcr_present:{} fcr.mode:{} CCB FCR " + "mode:{} preferred: {}", p_cfg->fcr_present, p_cfg->fcr.mode, p_ccb->our_cfg.fcr.mode, p_ccb->p_rcb->ertm_info.preferred_mode); @@ -1846,8 +1850,8 @@ uint8_t l2c_fcr_process_peer_cfg_req(tL2C_CCB* p_ccb, tL2CAP_CFG_INFO* p_cfg) { /* Ensure the MPS is not bigger than our retransmission buffer */ if (p_cfg->fcr.mps > max_retrans_size) { - LOG_VERBOSE("CFG: Overriding MPS to %d (orig %d)", max_retrans_size, - p_cfg->fcr.mps); + log::verbose("CFG: Overriding MPS to {} (orig {})", max_retrans_size, + p_cfg->fcr.mps); p_cfg->fcr.mps = max_retrans_size; p_ccb->out_cfg_fcr_present = true; diff --git a/system/stack/l2cap/l2c_int.h b/system/stack/l2cap/l2c_int.h index be9b715f07d09b3b730a3988ec9198c7b89233e6..6221ff16461eff44b9dec00483fb86dc582eab5d 100644 --- a/system/stack/l2cap/l2c_int.h +++ b/system/stack/l2cap/l2c_int.h @@ -25,6 +25,7 @@ #define L2C_INT_H #include <base/strings/stringprintf.h> +#include <bluetooth/log.h> #include <stdbool.h> #include <string> @@ -884,4 +885,13 @@ void l2cble_process_subrate_change_evt(uint16_t handle, uint8_t status, uint16_t peripheral_latency, uint16_t cont_num, uint16_t timeout); +namespace fmt { +template <> +struct formatter<tL2C_LINK_STATE> : enum_formatter<tL2C_LINK_STATE> {}; +template <> +struct formatter<tL2CEVT> : enum_formatter<tL2CEVT> {}; +template <> +struct formatter<tL2C_CHNL_STATE> : enum_formatter<tL2C_CHNL_STATE> {}; +} // namespace fmt + #endif diff --git a/system/stack/l2cap/l2c_link.cc b/system/stack/l2cap/l2c_link.cc index 33bc1305615ccc58e724f8dfed45341849afd049..a3f17bad682a4eef1ac33fca8185df135f3bb7af 100644 --- a/system/stack/l2cap/l2c_link.cc +++ b/system/stack/l2cap/l2c_link.cc @@ -25,6 +25,8 @@ ******************************************************************************/ #define LOG_TAG "l2c_link" +#include <bluetooth/log.h> + #include <cstdint> #include "device/include/device_iot_config.h" @@ -44,6 +46,8 @@ #include "types/bt_transport.h" #include "types/raw_address.h" +using namespace bluetooth; + extern tBTM_CB btm_cb; bool BTM_ReadPowerMode(const RawAddress& remote_bda, tBTM_PM_MODE* p_mode); @@ -78,26 +82,26 @@ void l2c_link_hci_conn_comp(tHCI_STATUS status, uint16_t handle, if (p_lcb == nullptr) { p_lcb = l2cu_allocate_lcb(ci.bd_addr, false, BT_TRANSPORT_BR_EDR); if (p_lcb == nullptr) { - LOG_WARN("Failed to allocate an LCB"); + log::warn("Failed to allocate an LCB"); return; } - LOG_DEBUG("Allocated l2cap control block for new connection state:%s", - link_state_text(p_lcb->link_state).c_str()); + log::debug("Allocated l2cap control block for new connection state:{}", + link_state_text(p_lcb->link_state)); p_lcb->link_state = LST_CONNECTING; } if ((p_lcb->link_state == LST_CONNECTED) && (status == HCI_ERR_CONNECTION_EXISTS)) { - LOG_WARN("Connection already exists handle:0x%04x", handle); + log::warn("Connection already exists handle:0x{:04x}", handle); return; } else if (p_lcb->link_state != LST_CONNECTING) { - LOG_ERROR( - "Link received unexpected connection complete state:%s status:%s " - "handle:0x%04x", - link_state_text(p_lcb->link_state).c_str(), - hci_error_code_text(status).c_str(), p_lcb->Handle()); + log::error( + "Link received unexpected connection complete state:{} status:{} " + "handle:0x{:04x}", + link_state_text(p_lcb->link_state), hci_error_code_text(status), + p_lcb->Handle()); if (status != HCI_SUCCESS) { - LOG_ERROR("Disconnecting..."); + log::error("Disconnecting..."); l2c_link_hci_disc_comp(p_lcb->Handle(), status); } return; @@ -114,7 +118,7 @@ void l2c_link_hci_conn_comp(tHCI_STATUS status, uint16_t handle, l2cu_send_peer_info_req(p_lcb, L2CAP_EXTENDED_FEATURES_INFO_TYPE); if (p_lcb->IsBonding()) { - LOG_DEBUG("Link is dedicated bonding handle:0x%04x", p_lcb->Handle()); + log::debug("Link is dedicated bonding handle:0x{:04x}", p_lcb->Handle()); if (l2cu_start_post_bond_timer(handle)) return; } @@ -136,8 +140,8 @@ void l2c_link_hci_conn_comp(tHCI_STATUS status, uint16_t handle, /* If there's an lcb disconnecting set this one to holding */ else if ((ci.status == HCI_ERR_MAX_NUM_OF_CONNECTIONS) && l2cu_lcb_disconnecting()) { - LOG_WARN("Delaying connection as reached max number of links:%u", - HCI_ERR_MAX_NUM_OF_CONNECTIONS); + log::warn("Delaying connection as reached max number of links:{}", + HCI_ERR_MAX_NUM_OF_CONNECTIONS); p_lcb->link_state = LST_CONNECT_HOLDING; p_lcb->InvalidateHandle(); } else { @@ -154,8 +158,8 @@ void l2c_link_hci_conn_comp(tHCI_STATUS status, uint16_t handle, p_ccb = pn; } - LOG_INFO("Disconnecting link handle:0x%04x status:%s", p_lcb->Handle(), - hci_error_code_text(status).c_str()); + log::info("Disconnecting link handle:0x{:04x} status:{}", p_lcb->Handle(), + hci_error_code_text(status)); p_lcb->SetDisconnectReason(status); /* Release the LCB */ if (p_lcb->ccb_queue.p_first_ccb == NULL) @@ -191,9 +195,8 @@ void l2c_link_sec_comp(const RawAddress* p_bda, tL2C_CCB* p_ccb; tL2C_CCB* p_next_ccb; - LOG_DEBUG("btm_status=%s, BD_ADDR=%s, transport=%s", - btm_status_text(status).c_str(), ADDRESS_TO_LOGGABLE_CSTR(*p_bda), - bt_transport_text(transport).c_str()); + log::debug("btm_status={}, BD_ADDR={}, transport={}", btm_status_text(status), + ADDRESS_TO_LOGGABLE_CSTR(*p_bda), bt_transport_text(transport)); if (status == BTM_SUCCESS_NO_SECURITY) { status = BTM_SUCCESS; @@ -207,7 +210,7 @@ void l2c_link_sec_comp(const RawAddress* p_bda, /* If we don't have one, this is an error */ if (!p_lcb) { - LOG_WARN("L2CAP got sec_comp for unknown BD_ADDR"); + log::warn("L2CAP got sec_comp for unknown BD_ADDR"); return; } @@ -324,7 +327,7 @@ bool l2c_link_hci_disc_comp(uint16_t handle, tHCI_REASON reason) { disconnecting */ if (p_lcb->ccb_queue.p_first_ccb != NULL || p_lcb->p_pending_ccb) { - LOG_DEBUG("l2c_link_hci_disc_comp: Restarting pending ACL request"); + log::debug("l2c_link_hci_disc_comp: Restarting pending ACL request"); /* Release any held buffers */ while (!list_is_empty(p_lcb->link_xmit_data_q)) { BT_HDR* p_buf = @@ -395,9 +398,8 @@ void l2c_link_timeout(tL2C_LCB* p_lcb) { tL2C_CCB* p_ccb; tBTM_STATUS rc; - LOG_DEBUG("L2CAP - l2c_link_timeout() link state:%s is_bonding:%s", - link_state_text(p_lcb->link_state).c_str(), - logbool(p_lcb->IsBonding()).c_str()); + log::debug("L2CAP - l2c_link_timeout() link state:{} is_bonding:{}", + link_state_text(p_lcb->link_state), logbool(p_lcb->IsBonding())); /* If link was connecting or disconnecting, clear all channels and drop the * LCB */ @@ -428,7 +430,7 @@ void l2c_link_timeout(tL2C_LCB* p_lcb) { uint64_t timeout_ms; bool start_timeout = true; - LOG_WARN("TODO: Remove this callback into bcm_sec_disconnect"); + log::warn("TODO: Remove this callback into bcm_sec_disconnect"); rc = btm_sec_disconnect( p_lcb->Handle(), HCI_ERR_PEER_USER, "stack::l2cap::l2c_link::l2c_link_timeout All channels closed"); @@ -596,9 +598,9 @@ void l2c_link_adjust_allocation(void) { qq = qq_remainder = 1; } - LOG_DEBUG( - "l2c_link_adjust_allocation num_hipri: %u num_lowpri: %u low_quota: " - "%u round_robin_quota: %u qq: %u", + log::debug( + "l2c_link_adjust_allocation num_hipri: {} num_lowpri: {} low_quota: " + "{} round_robin_quota: {} qq: {}", num_hipri_links, num_lowpri_links, low_quota, l2cb.round_robin_quota, qq); /* Now, assign the quotas to each link */ @@ -623,12 +625,12 @@ void l2c_link_adjust_allocation(void) { } } - LOG_DEBUG( - "l2c_link_adjust_allocation LCB %d Priority: %d XmitQuota: %d", yy, + log::debug( + "l2c_link_adjust_allocation LCB {} Priority: {} XmitQuota: {}", yy, p_lcb->acl_priority, p_lcb->link_xmit_quota); - LOG_DEBUG(" SentNotAcked: %d RRUnacked: %d", - p_lcb->sent_not_acked, l2cb.round_robin_unacked); + log::debug("SentNotAcked: {} RRUnacked: {}", p_lcb->sent_not_acked, + l2cb.round_robin_unacked); /* There is a special case where we have readjusted the link quotas and */ /* this link may have sent anything but some other link sent packets so */ @@ -667,9 +669,9 @@ void l2c_link_adjust_chnl_allocation(void) { tL2CAP_CHNL_DATA_RATE data_rate = p_ccb->tx_data_rate + p_ccb->rx_data_rate; p_ccb->buff_quota = L2CAP_CBB_DEFAULT_DATA_RATE_BUFF_QUOTA * data_rate; - LOG_DEBUG( - "CID:0x%04x FCR Mode:%u Priority:%u TxDataRate:%u RxDataRate:%u " - "Quota:%u", + log::debug( + "CID:0x{:04x} FCR Mode:{} Priority:{} TxDataRate:{} RxDataRate:{} " + "Quota:{}", p_ccb->local_cid, p_ccb->peer_cfg.fcr.mode, p_ccb->ccb_priority, p_ccb->tx_data_rate, p_ccb->rx_data_rate, p_ccb->buff_quota); @@ -780,7 +782,7 @@ static bool l2c_link_check_power_mode(tL2C_LCB* p_lcb) { tBTM_PM_MODE mode; if (BTM_ReadPowerMode(p_lcb->remote_bd_addr, &mode)) { if (mode == BTM_PM_STS_PENDING) { - LOG_DEBUG("LCB(0x%x) is in PM pending state", p_lcb->Handle()); + log::debug("LCB(0x{:x}) is in PM pending state", p_lcb->Handle()); return true; } } @@ -826,7 +828,7 @@ void l2c_link_check_send_pkts(tL2C_LCB* p_lcb, uint16_t local_cid, ** This LCB will be served when receiving number of completed packet event. */ if (l2cb.is_cong_cback_context) { - LOG_INFO("skipping, is_cong_cback_context=true"); + log::info("skipping, is_cong_cback_context=true"); return; } @@ -834,7 +836,7 @@ void l2c_link_check_send_pkts(tL2C_LCB* p_lcb, uint16_t local_cid, ** have at least 1, then do a round-robin for all the LCBs */ if ((p_lcb == NULL) || (p_lcb->link_xmit_quota == 0)) { - LOG_DEBUG("Round robin"); + log::debug("Round robin"); if (p_lcb == NULL) { p_lcb = l2cb.lcb_pool; } else if (!single_write) { @@ -853,34 +855,34 @@ void l2c_link_check_send_pkts(tL2C_LCB* p_lcb, uint16_t local_cid, (p_lcb->transport == BT_TRANSPORT_LE && (l2cb.ble_round_robin_unacked >= l2cb.ble_round_robin_quota || l2cb.controller_le_xmit_window == 0))) { - LOG_DEBUG("Skipping lcb %d due to controller window full", xx); + log::debug("Skipping lcb {} due to controller window full", xx); continue; } if ((!p_lcb->in_use) || (p_lcb->link_state != LST_CONNECTED) || (p_lcb->link_xmit_quota != 0) || (l2c_link_check_power_mode(p_lcb))) { - LOG_DEBUG("Skipping lcb %d due to quota", xx); + log::debug("Skipping lcb {} due to quota", xx); continue; } /* See if we can send anything from the Link Queue */ if (!list_is_empty(p_lcb->link_xmit_data_q)) { - LOG_VERBOSE("Sending to lower layer"); + log::verbose("Sending to lower layer"); p_buf = (BT_HDR*)list_front(p_lcb->link_xmit_data_q); list_remove(p_lcb->link_xmit_data_q, p_buf); l2c_link_send_to_lower(p_lcb, p_buf, NULL); } else if (single_write) { /* If only doing one write, break out */ - LOG_DEBUG("single_write is true, skipping"); + log::debug("single_write is true, skipping"); break; } /* If nothing on the link queue, check the channel queue */ else { tL2C_TX_COMPLETE_CB_INFO cbi = {}; - LOG_DEBUG("Check next buffer"); + log::debug("Check next buffer"); p_buf = l2cu_get_next_buffer_to_send(p_lcb, &cbi); if (p_buf != NULL) { - LOG_DEBUG("Sending next buffer"); + log::debug("Sending next buffer"); l2c_link_send_to_lower(p_lcb, p_buf, &cbi); } } @@ -901,12 +903,12 @@ void l2c_link_check_send_pkts(tL2C_LCB* p_lcb, uint16_t local_cid, /* If a partial segment is being sent, can't send anything else */ if ((p_lcb->link_state != LST_CONNECTED) || (l2c_link_check_power_mode(p_lcb))) { - LOG_INFO("A partial segment is being sent, cannot send anything else"); + log::info("A partial segment is being sent, cannot send anything else"); return; } - LOG_VERBOSE( - "Direct send, transport=%d, xmit_window=%d, le_xmit_window=%d, " - "sent_not_acked=%d, link_xmit_quota=%d", + log::verbose( + "Direct send, transport={}, xmit_window={}, le_xmit_window={}, " + "sent_not_acked={}, link_xmit_quota={}", p_lcb->transport, l2cb.controller_xmit_window, l2cb.controller_le_xmit_window, p_lcb->sent_not_acked, p_lcb->link_xmit_quota); @@ -918,10 +920,10 @@ void l2c_link_check_send_pkts(tL2C_LCB* p_lcb, uint16_t local_cid, (p_lcb->transport == BT_TRANSPORT_LE))) && (p_lcb->sent_not_acked < p_lcb->link_xmit_quota)) { if (list_is_empty(p_lcb->link_xmit_data_q)) { - LOG_VERBOSE("No transmit data, skipping"); + log::verbose("No transmit data, skipping"); break; } - LOG_VERBOSE("Sending to lower layer"); + log::verbose("Sending to lower layer"); p_buf = (BT_HDR*)list_front(p_lcb->link_xmit_data_q); list_remove(p_lcb->link_xmit_data_q, p_buf); l2c_link_send_to_lower(p_lcb, p_buf, NULL); @@ -929,7 +931,7 @@ void l2c_link_check_send_pkts(tL2C_LCB* p_lcb, uint16_t local_cid, if (!single_write) { /* See if we can send anything for any channel */ - LOG_VERBOSE("Trying to send other data when single_write is false"); + log::verbose("Trying to send other data when single_write is false"); while (((l2cb.controller_xmit_window != 0 && (p_lcb->transport == BT_TRANSPORT_BR_EDR)) || (l2cb.controller_le_xmit_window != 0 && @@ -938,10 +940,10 @@ void l2c_link_check_send_pkts(tL2C_LCB* p_lcb, uint16_t local_cid, tL2C_TX_COMPLETE_CB_INFO cbi = {}; p_buf = l2cu_get_next_buffer_to_send(p_lcb, &cbi); if (p_buf == NULL) { - LOG_VERBOSE("No next buffer, skipping"); + log::verbose("No next buffer, skipping"); break; } - LOG_VERBOSE("Sending to lower layer"); + log::verbose("Sending to lower layer"); l2c_link_send_to_lower(p_lcb, p_buf, &cbi); } } @@ -963,7 +965,7 @@ void l2c_OnHciModeChangeSendPendingPackets(RawAddress remote) { if (p_lcb != NULL) { /* There might be any pending packets due to SNIFF or PENDING state */ /* Trigger L2C to start transmission of the pending packets. */ - LOG_VERBOSE( + log::verbose( "btm mode change to active; check l2c_link for outgoing packets"); l2c_link_check_send_pkts(p_lcb, 0, NULL); } @@ -987,10 +989,10 @@ static void l2c_link_send_to_lower_br_edr(tL2C_LCB* p_lcb, BT_HDR* p_buf) { l2cb.controller_xmit_window--; acl_send_data_packet_br_edr(p_lcb->remote_bd_addr, p_buf); - LOG_VERBOSE("TotalWin=%d,Hndl=0x%x,Quota=%d,Unack=%d,RRQuota=%d,RRUnack=%d", - l2cb.controller_xmit_window, p_lcb->Handle(), - p_lcb->link_xmit_quota, p_lcb->sent_not_acked, - l2cb.round_robin_quota, l2cb.round_robin_unacked); + log::verbose( + "TotalWin={},Hndl=0x{:x},Quota={},Unack={},RRQuota={},RRUnack={}", + l2cb.controller_xmit_window, p_lcb->Handle(), p_lcb->link_xmit_quota, + p_lcb->sent_not_acked, l2cb.round_robin_quota, l2cb.round_robin_unacked); } static void l2c_link_send_to_lower_ble(tL2C_LCB* p_lcb, BT_HDR* p_buf) { @@ -1004,10 +1006,10 @@ static void l2c_link_send_to_lower_ble(tL2C_LCB* p_lcb, BT_HDR* p_buf) { l2cb.controller_le_xmit_window--; acl_send_data_packet_ble(p_lcb->remote_bd_addr, p_buf); - LOG_DEBUG("TotalWin=%d,Hndl=0x%x,Quota=%d,Unack=%d,RRQuota=%d,RRUnack=%d", - l2cb.controller_le_xmit_window, p_lcb->Handle(), - p_lcb->link_xmit_quota, p_lcb->sent_not_acked, - l2cb.ble_round_robin_quota, l2cb.ble_round_robin_unacked); + log::debug("TotalWin={},Hndl=0x{:x},Quota={},Unack={},RRQuota={},RRUnack={}", + l2cb.controller_le_xmit_window, p_lcb->Handle(), + p_lcb->link_xmit_quota, p_lcb->sent_not_acked, + l2cb.ble_round_robin_quota, l2cb.ble_round_robin_unacked); } static void l2c_link_send_to_lower(tL2C_LCB* p_lcb, BT_HDR* p_buf, @@ -1039,7 +1041,7 @@ void l2c_packets_completed(uint16_t handle, uint16_t num_sent) { l2cb.update_outstanding_le_packets(num_sent); break; default: - LOG_ERROR("Unknown transport received:%u", p_lcb->transport); + log::error("Unknown transport received:{}", p_lcb->transport); return; } @@ -1085,15 +1087,15 @@ void l2c_link_segments_xmitted(BT_HDR* p_msg) { /* Find the LCB based on the handle */ tL2C_LCB* p_lcb = l2cu_find_lcb_by_handle(handle); if (p_lcb == nullptr) { - LOG_WARN("Received segment complete for unknown connection handle:%d", - handle); + log::warn("Received segment complete for unknown connection handle:{}", + handle); osi_free(p_msg); return; } if (p_lcb->link_state != LST_CONNECTED) { - LOG_INFO("Received segment complete for unconnected connection handle:%d:", - handle); + log::info("Received segment complete for unconnected connection handle:{}:", + handle); osi_free(p_msg); return; } @@ -1109,14 +1111,14 @@ tBTM_STATUS l2cu_ConnectAclForSecurity(const RawAddress& bd_addr) { tL2C_LCB* p_lcb = l2cu_find_lcb_by_bd_addr(bd_addr, BT_TRANSPORT_BR_EDR); if (p_lcb && (p_lcb->link_state == LST_CONNECTED || p_lcb->link_state == LST_CONNECTING)) { - LOG_WARN("Connection already exists"); + log::warn("Connection already exists"); return BTM_CMD_STARTED; } /* Make sure an L2cap link control block is available */ if (!p_lcb && (p_lcb = l2cu_allocate_lcb(bd_addr, true, BT_TRANSPORT_BR_EDR)) == NULL) { - LOG_WARN("failed allocate LCB for %s", ADDRESS_TO_LOGGABLE_CSTR(bd_addr)); + log::warn("failed allocate LCB for {}", ADDRESS_TO_LOGGABLE_CSTR(bd_addr)); return BTM_NO_RESOURCES; } @@ -1155,13 +1157,13 @@ tL2C_CCB* l2cu_get_next_channel_in_rr(tL2C_LCB* p_lcb) { p_ccb = p_lcb->rr_serv[p_lcb->rr_pri].p_serve_ccb; if (!p_ccb) { - LOG_ERROR("p_serve_ccb is NULL, rr_pri=%d", p_lcb->rr_pri); + log::error("p_serve_ccb is NULL, rr_pri={}", p_lcb->rr_pri); return NULL; } - LOG_VERBOSE("RR scan pri=%d, lcid=0x%04x, q_cout=%zu", - p_ccb->ccb_priority, p_ccb->local_cid, - fixed_queue_length(p_ccb->xmit_hold_q)); + log::verbose("RR scan pri={}, lcid=0x{:04x}, q_cout={}", + p_ccb->ccb_priority, p_ccb->local_cid, + fixed_queue_length(p_ccb->xmit_hold_q)); /* store the next serving channel */ /* this channel is the last channel of its priority group */ @@ -1178,7 +1180,7 @@ tL2C_CCB* l2cu_get_next_channel_in_rr(tL2C_LCB* p_lcb) { if (p_ccb->chnl_state != CST_OPEN) continue; if (p_ccb->p_lcb->transport == BT_TRANSPORT_LE) { - LOG_DEBUG("Connection oriented channel"); + log::debug("Connection oriented channel"); if (fixed_queue_is_empty(p_ccb->xmit_hold_q)) continue; } else { @@ -1217,10 +1219,10 @@ tL2C_CCB* l2cu_get_next_channel_in_rr(tL2C_LCB* p_lcb) { } if (p_serve_ccb) { - LOG_VERBOSE("RR service pri=%d, quota=%d, lcid=0x%04x", - p_serve_ccb->ccb_priority, - p_lcb->rr_serv[p_serve_ccb->ccb_priority].quota, - p_serve_ccb->local_cid); + log::verbose("RR service pri={}, quota={}, lcid=0x{:04x}", + p_serve_ccb->ccb_priority, + p_lcb->rr_serv[p_serve_ccb->ccb_priority].quota, + p_serve_ccb->local_cid); } return p_serve_ccb; @@ -1274,7 +1276,7 @@ BT_HDR* l2cu_get_next_buffer_to_send(tL2C_LCB* p_lcb, if (!fixed_queue_is_empty(p_ccb->xmit_hold_q)) { p_buf = (BT_HDR*)fixed_queue_try_dequeue(p_ccb->xmit_hold_q); if (NULL == p_buf) { - LOG_ERROR("No data to be sent"); + log::error("No data to be sent"); return (NULL); } @@ -1299,7 +1301,7 @@ BT_HDR* l2cu_get_next_buffer_to_send(tL2C_LCB* p_lcb, if (p_ccb->p_lcb->transport == BT_TRANSPORT_LE) { /* Check credits */ if (p_ccb->peer_conn_cfg.credits == 0) { - LOG_DEBUG("No credits to send packets"); + log::debug("No credits to send packets"); return NULL; } @@ -1319,7 +1321,7 @@ BT_HDR* l2cu_get_next_buffer_to_send(tL2C_LCB* p_lcb, } else { p_buf = (BT_HDR*)fixed_queue_try_dequeue(p_ccb->xmit_hold_q); if (NULL == p_buf) { - LOG_ERROR("#2: No data to be sent"); + log::error("#2: No data to be sent"); return (NULL); } } diff --git a/system/stack/l2cap/l2c_main.cc b/system/stack/l2cap/l2c_main.cc index c1fcd6c45ace98df7f1b45d3407e9faff89a11a3..6634b7bab799f2965b6d54efa47d2caa11051040 100644 --- a/system/stack/l2cap/l2c_main.cc +++ b/system/stack/l2cap/l2c_main.cc @@ -24,6 +24,7 @@ #define LOG_TAG "bt_l2c_main" +#include <bluetooth/log.h> #include <string.h> #include "common/init_flags.h" @@ -41,6 +42,8 @@ #include "stack/include/l2cdefs.h" #include "stack/l2cap/l2c_int.h" +using namespace bluetooth; + /******************************************************************************/ /* L O C A L F U N C T I O N P R O T O T Y P E S */ /******************************************************************************/ @@ -73,7 +76,7 @@ void l2c_rcv_acl_data(BT_HDR* p_msg) { /* Since the HCI Transport is putting segmented packets back together, we */ /* should never get a valid packet with the type set to "continuation" */ if (pkt_type == L2CAP_PKT_CONTINUE) { - LOG_WARN("L2CAP - received packet continuation"); + log::warn("L2CAP - received packet continuation"); osi_free(p_msg); return; } @@ -82,7 +85,7 @@ void l2c_rcv_acl_data(BT_HDR* p_msg) { STREAM_TO_UINT16(hci_len, p); if (hci_len < L2CAP_PKT_OVERHEAD || hci_len != p_msg->len - 4) { /* Remote-declared packet size must match HCI_ACL size - ACL header (4) */ - LOG_WARN("L2CAP - got incorrect hci header"); + log::warn("L2CAP - got incorrect hci header"); osi_free(p_msg); return; } @@ -94,8 +97,8 @@ void l2c_rcv_acl_data(BT_HDR* p_msg) { /* Find the LCB based on the handle */ tL2C_LCB* p_lcb = l2cu_find_lcb_by_handle(handle); if (!p_lcb) { - LOG_ERROR("L2CAP - rcvd ACL for unknown handle:%d ls:%d cid:%d", handle, - p_msg->layer_specific, rcv_cid); + log::error("L2CAP - rcvd ACL for unknown handle:{} ls:{} cid:{}", handle, + p_msg->layer_specific, rcv_cid); osi_free(p_msg); return; } @@ -117,7 +120,7 @@ void l2c_rcv_acl_data(BT_HDR* p_msg) { if (rcv_cid >= L2CAP_BASE_APPL_CID) { p_ccb = l2cu_find_ccb_by_cid(p_lcb, rcv_cid); if (!p_ccb) { - LOG_WARN("L2CAP - unknown CID: 0x%04x", rcv_cid); + log::warn("L2CAP - unknown CID: 0x{:04x}", rcv_cid); osi_free(p_msg); return; } @@ -127,8 +130,8 @@ void l2c_rcv_acl_data(BT_HDR* p_msg) { p_msg->offset += L2CAP_PKT_OVERHEAD; if (l2cap_len != p_msg->len) { - LOG_WARN("L2CAP - bad length in pkt. Exp: %d Act: %d", l2cap_len, - p_msg->len); + log::warn("L2CAP - bad length in pkt. Exp: {} Act: {}", l2cap_len, + p_msg->len); osi_free(p_msg); return; } @@ -226,7 +229,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { /* if l2cap command received in CID 1 on top of an LE link, ignore this * command */ if (p_lcb->transport == BT_TRANSPORT_LE) { - LOG_INFO("Dropping data on CID 1 for LE link"); + log::info("Dropping data on CID 1 for LE link"); return; } @@ -238,8 +241,8 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { * will be ignored. Here we simply mark the bad packet and decide which cmd * ID to reject later */ pkt_size_rej = true; - LOG_WARN("Signaling pkt_len=%d exceeds MTU size %d", pkt_len, - L2CAP_DEFAULT_MTU); + log::warn("Signaling pkt_len={} exceeds MTU size {}", pkt_len, + L2CAP_DEFAULT_MTU); } uint8_t* p_next_cmd = p; @@ -276,8 +279,8 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { first_cmd = false; if (cmd_len > BT_SMALL_BUFFER_SIZE) { - LOG_WARN("Command size %u exceeds limit %d", cmd_len, - BT_SMALL_BUFFER_SIZE); + log::warn("Command size {} exceeds limit {}", cmd_len, + BT_SMALL_BUFFER_SIZE); l2cu_send_peer_cmd_reject(p_lcb, L2CAP_CMD_REJ_MTU_EXCEEDED, id, 0, 0); return; } @@ -285,22 +288,22 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { /* Check command length does not exceed packet length */ p_next_cmd = p + cmd_len; if (p_next_cmd > p_pkt_end) { - LOG_WARN("cmd_len > pkt_len, pkt_len=%d, cmd_len=%d, code=%d", pkt_len, - cmd_len, cmd_code); + log::warn("cmd_len > pkt_len, pkt_len={}, cmd_len={}, code={}", pkt_len, + cmd_len, cmd_code); break; } - LOG_DEBUG("cmd: %s, id:%d, cmd_len:%d", - l2cap_command_code_text(cmd_code).c_str(), id, cmd_len); + log::debug("cmd: {}, id:{}, cmd_len:{}", l2cap_command_code_text(cmd_code), + id, cmd_len); /* Bad L2CAP packet length, look for cmd to reject */ if (pkt_size_rej) { /* If command found rejected it and we're done, otherwise keep looking */ if (l2c_is_cmd_rejected(cmd_code, id, p_lcb)) { - LOG_WARN("Rejected command %d due to bad packet length", cmd_code); + log::warn("Rejected command {} due to bad packet length", cmd_code); return; } else { - LOG_WARN("No need to reject command %d for bad packet len", cmd_code); + log::warn("No need to reject command {} for bad packet len", cmd_code); continue; /* Look for next cmd/response in current packet */ } } @@ -309,39 +312,40 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CMD_REJECT: uint16_t rej_reason; if (p + 2 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_REJECT"); + log::warn("Not enough data for L2CAP_CMD_REJECT"); return; } STREAM_TO_UINT16(rej_reason, p); if (rej_reason == L2CAP_CMD_REJ_MTU_EXCEEDED) { uint16_t rej_mtu; if (p + 2 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_REJ_MTU_EXCEEDED"); + log::warn("Not enough data for L2CAP_CMD_REJ_MTU_EXCEEDED"); return; } STREAM_TO_UINT16(rej_mtu, p); /* What to do with the MTU reject ? We have negotiated an MTU. For now * we will ignore it and let a higher protocol timeout take care of it */ - LOG_WARN("MTU rej Handle: %d MTU: %d", p_lcb->Handle(), rej_mtu); + log::warn("MTU rej Handle: {} MTU: {}", p_lcb->Handle(), rej_mtu); } if (rej_reason == L2CAP_CMD_REJ_INVALID_CID) { uint16_t lcid, rcid; if (p + 4 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_REJ_INVALID_CID"); + log::warn("Not enough data for L2CAP_CMD_REJ_INVALID_CID"); return; } STREAM_TO_UINT16(rcid, p); STREAM_TO_UINT16(lcid, p); - LOG_WARN("Rejected due to invalid CID, LCID: 0x%04x RCID: 0x%04x", - lcid, rcid); + log::warn( + "Rejected due to invalid CID, LCID: 0x{:04x} RCID: 0x{:04x}", + lcid, rcid); /* Remote CID invalid. Treat as a disconnect */ tL2C_CCB* p_ccb = l2cu_find_ccb_by_cid(p_lcb, lcid); if ((p_ccb != NULL) && (p_ccb->remote_cid == rcid)) { /* Fake link disconnect - no reply is generated */ - LOG_WARN("Remote CID is invalid, treat as disconnected"); + log::warn("Remote CID is invalid, treat as disconnected"); l2c_csm_execute(p_ccb, L2CEVT_LP_DISCONNECT_IND, NULL); } } @@ -367,27 +371,27 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CMD_CONN_REQ: { uint16_t rcid; if (p + 4 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_CONN_REQ"); + log::warn("Not enough data for L2CAP_CMD_CONN_REQ"); return; } STREAM_TO_UINT16(con_info.psm, p); STREAM_TO_UINT16(rcid, p); p_rcb = l2cu_find_rcb_by_psm(con_info.psm); if (!p_rcb) { - LOG_WARN("Rcvd conn req for unknown PSM: %d", con_info.psm); + log::warn("Rcvd conn req for unknown PSM: {}", con_info.psm); l2cu_reject_connection(p_lcb, rcid, id, L2CAP_CONN_NO_PSM); break; } else { if (!p_rcb->api.pL2CA_ConnectInd_Cb) { - LOG_WARN("Rcvd conn req for outgoing-only connection PSM: %d", - con_info.psm); + log::warn("Rcvd conn req for outgoing-only connection PSM: {}", + con_info.psm); l2cu_reject_connection(p_lcb, rcid, id, L2CAP_CONN_NO_PSM); break; } } tL2C_CCB* p_ccb = l2cu_allocate_ccb(p_lcb, 0); if (p_ccb == nullptr) { - LOG_ERROR("Unable to allocate CCB"); + log::error("Unable to allocate CCB"); l2cu_reject_connection(p_lcb, rcid, id, L2CAP_CONN_NO_RESOURCES); break; } @@ -411,7 +415,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CMD_CONN_RSP: { uint16_t lcid; if (p + 8 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_CONN_REQ"); + log::warn("Not enough data for L2CAP_CMD_CONN_REQ"); return; } STREAM_TO_UINT16(con_info.remote_cid, p); @@ -421,12 +425,12 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { tL2C_CCB* p_ccb = l2cu_find_ccb_by_cid(p_lcb, lcid); if (!p_ccb) { - LOG_WARN("no CCB for conn rsp, LCID: %d RCID: %d", lcid, - con_info.remote_cid); + log::warn("no CCB for conn rsp, LCID: {} RCID: {}", lcid, + con_info.remote_cid); break; } if (p_ccb->local_id != id) { - LOG_WARN("con rsp - bad ID. Exp: %d Got: %d", p_ccb->local_id, id); + log::warn("con rsp - bad ID. Exp: {} Got: {}", p_ccb->local_id, id); break; } @@ -457,7 +461,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { uint16_t lcid; if (p + 4 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_CONFIG_REQ"); + log::warn("Not enough data for L2CAP_CMD_CONFIG_REQ"); return; } STREAM_TO_UINT16(lcid, p); @@ -472,7 +476,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { while (p < p_cfg_end) { uint8_t cfg_code, cfg_len; if (p + 2 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_CONFIG_REQ sub_event"); + log::warn("Not enough data for L2CAP_CMD_CONFIG_REQ sub_event"); return; } STREAM_TO_UINT8(cfg_code, p); @@ -601,7 +605,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { uint8_t* p_cfg_end = p + cmd_len; uint16_t lcid; if (p + 6 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_CONFIG_RSP"); + log::warn("Not enough data for L2CAP_CMD_CONFIG_RSP"); return; } STREAM_TO_UINT16(lcid, p); @@ -615,7 +619,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { while (p < p_cfg_end) { uint8_t cfg_code, cfg_len; if (p + 2 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_CONFIG_RSP sub_event"); + log::warn("Not enough data for L2CAP_CMD_CONFIG_RSP sub_event"); return; } STREAM_TO_UINT8(cfg_code, p); @@ -625,7 +629,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CFG_TYPE_MTU: cfg_info.mtu_present = true; if (p + 2 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CFG_TYPE_MTU"); + log::warn("Not enough data for L2CAP_CFG_TYPE_MTU"); return; } STREAM_TO_UINT16(cfg_info.mtu, p); @@ -634,7 +638,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CFG_TYPE_FLUSH_TOUT: cfg_info.flush_to_present = true; if (p + 2 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CFG_TYPE_FLUSH_TOUT"); + log::warn("Not enough data for L2CAP_CFG_TYPE_FLUSH_TOUT"); return; } STREAM_TO_UINT16(cfg_info.flush_to, p); @@ -643,7 +647,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CFG_TYPE_QOS: cfg_info.qos_present = true; if (p + 2 + 5 * 4 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CFG_TYPE_QOS"); + log::warn("Not enough data for L2CAP_CFG_TYPE_QOS"); return; } STREAM_TO_UINT8(cfg_info.qos.qos_flags, p); @@ -658,7 +662,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CFG_TYPE_FCR: cfg_info.fcr_present = true; if (p + 3 + 3 * 2 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CFG_TYPE_FCR"); + log::warn("Not enough data for L2CAP_CFG_TYPE_FCR"); return; } STREAM_TO_UINT8(cfg_info.fcr.mode, p); @@ -672,7 +676,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CFG_TYPE_FCS: cfg_info.fcs_present = true; if (p + 1 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CFG_TYPE_FCS"); + log::warn("Not enough data for L2CAP_CFG_TYPE_FCS"); return; } STREAM_TO_UINT8(cfg_info.fcs, p); @@ -681,7 +685,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CFG_TYPE_EXT_FLOW: cfg_info.ext_flow_spec_present = true; if (p + 2 + 2 + 3 * 4 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CFG_TYPE_EXT_FLOW"); + log::warn("Not enough data for L2CAP_CFG_TYPE_EXT_FLOW"); return; } STREAM_TO_UINT8(cfg_info.ext_flow_spec.id, p); @@ -697,7 +701,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { tL2C_CCB* p_ccb = l2cu_find_ccb_by_cid(p_lcb, lcid); if (p_ccb) { if (p_ccb->local_id != id) { - LOG_WARN("cfg rsp - bad ID. Exp: %d Got: %d", p_ccb->local_id, id); + log::warn("cfg rsp - bad ID. Exp: {} Got: {}", p_ccb->local_id, id); break; } if (cfg_info.result == L2CAP_CFG_OK) { @@ -706,7 +710,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { l2c_csm_execute(p_ccb, L2CEVT_L2CAP_CONFIG_RSP_NEG, &cfg_info); } } else { - LOG_WARN("Rcvd cfg rsp for unknown CID: 0x%04x", lcid); + log::warn("Rcvd cfg rsp for unknown CID: 0x{:04x}", lcid); } break; } @@ -714,7 +718,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CMD_DISC_REQ: { uint16_t lcid, rcid; if (p + 4 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_DISC_REQ"); + log::warn("Not enough data for L2CAP_CMD_DISC_REQ"); return; } STREAM_TO_UINT16(lcid, p); @@ -735,7 +739,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CMD_DISC_RSP: { uint16_t lcid, rcid; if (p + 4 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_DISC_RSP"); + log::warn("Not enough data for L2CAP_CMD_DISC_RSP"); return; } STREAM_TO_UINT16(rcid, p); @@ -757,7 +761,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { case L2CAP_CMD_INFO_REQ: { uint16_t info_type; if (p + 2 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_INFO_REQ"); + log::warn("Not enough data for L2CAP_CMD_INFO_REQ"); return; } STREAM_TO_UINT16(info_type, p); @@ -774,7 +778,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { uint16_t info_type, result; if (p + 4 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_INFO_RSP"); + log::warn("Not enough data for L2CAP_CMD_INFO_RSP"); return; } STREAM_TO_UINT16(info_type, p); @@ -783,7 +787,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { if ((info_type == L2CAP_EXTENDED_FEATURES_INFO_TYPE) && (result == L2CAP_INFO_RESP_RESULT_SUCCESS)) { if (p + 4 > p_next_cmd) { - LOG_WARN("Not enough data for L2CAP_CMD_INFO_RSP sub_event"); + log::warn("Not enough data for L2CAP_CMD_INFO_RSP sub_event"); return; } STREAM_TO_UINT32(p_lcb->peer_ext_fea, p); @@ -818,7 +822,7 @@ static void process_l2cap_cmd(tL2C_LCB* p_lcb, uint8_t* p, uint16_t pkt_len) { break; default: - LOG_WARN("Bad cmd code: %d", cmd_code); + log::warn("Bad cmd code: {}", cmd_code); l2cu_send_peer_cmd_reject(p_lcb, L2CAP_CMD_REJ_NOT_UNDERSTOOD, id, 0, 0); return; @@ -906,7 +910,7 @@ uint8_t l2c_data_write(uint16_t cid, BT_HDR* p_data, uint16_t flags) { /* Find the channel control block. We don't know the link it is on. */ tL2C_CCB* p_ccb = l2cu_find_ccb_by_cid(NULL, cid); if (!p_ccb) { - LOG_WARN("L2CAP - no CCB for L2CA_DataWrite, CID: %d", cid); + log::warn("L2CAP - no CCB for L2CA_DataWrite, CID: {}", cid); osi_free(p_data); return (L2CAP_DW_FAILED); } @@ -920,9 +924,9 @@ uint8_t l2c_data_write(uint16_t cid, BT_HDR* p_data, uint16_t flags) { mtu = p_ccb->peer_cfg.mtu; if (p_data->len > mtu) { - LOG_WARN( - "L2CAP - CID: 0x%04x cannot send message bigger than peer's mtu size: " - "len=%u mtu=%u", + log::warn( + "L2CAP - CID: 0x{:04x} cannot send message bigger than peer's mtu " + "size: len={} mtu={}", cid, p_data->len, mtu); osi_free(p_data); return (L2CAP_DW_FAILED); @@ -933,9 +937,9 @@ uint8_t l2c_data_write(uint16_t cid, BT_HDR* p_data, uint16_t flags) { /* If already congested, do not accept any more packets */ if (p_ccb->cong_sent) { - LOG_ERROR( - "L2CAP - CID: 0x%04x cannot send, already congested " - "xmit_hold_q.count: %zu buff_quota: %u", + log::error( + "L2CAP - CID: 0x{:04x} cannot send, already congested " + "xmit_hold_q.count: {} buff_quota: {}", p_ccb->local_cid, fixed_queue_length(p_ccb->xmit_hold_q), p_ccb->buff_quota); diff --git a/system/stack/l2cap/l2c_utils.cc b/system/stack/l2cap/l2c_utils.cc index bdf4e66c73cdf4d1443f40edeec399f5ecad5135..f1e845e62d8397e51b26657a7b85a3f5433746f8 100644 --- a/system/stack/l2cap/l2c_utils.cc +++ b/system/stack/l2cap/l2c_utils.cc @@ -24,6 +24,7 @@ #define LOG_TAG "l2c_utils" #include <base/logging.h> +#include <bluetooth/log.h> #include <stdio.h> #include <string.h> @@ -47,6 +48,8 @@ #include "stack/l2cap/l2c_int.h" #include "types/raw_address.h" +using namespace bluetooth; + tL2C_CCB* l2cu_get_next_channel_in_rr(tL2C_LCB* p_lcb); // TODO Move /******************************************************************************* @@ -107,8 +110,8 @@ tL2C_LCB* l2cu_allocate_lcb(const RawAddress& p_bd_addr, bool is_bonding, void l2cu_set_lcb_handle(struct t_l2c_linkcb& p_lcb, uint16_t handle) { if (p_lcb.Handle() != HCI_INVALID_HANDLE) { - LOG_WARN("Should not replace active handle:%hu with new handle:%hu", - p_lcb.Handle(), handle); + log::warn("Should not replace active handle:{} with new handle:{}", + p_lcb.Handle(), handle); } p_lcb.SetHandle(handle); } @@ -127,8 +130,8 @@ void l2cu_update_lcb_4_bonding(const RawAddress& p_bd_addr, bool is_bonding) { tL2C_LCB* p_lcb = l2cu_find_lcb_by_bd_addr(p_bd_addr, BT_TRANSPORT_BR_EDR); if (p_lcb) { - VLOG(1) << __func__ << " BDA: " << ADDRESS_TO_LOGGABLE_STR(p_bd_addr) - << " is_bonding: " << is_bonding; + log::verbose("BDA: {} is_bonding: {}", ADDRESS_TO_LOGGABLE_STR(p_bd_addr), + is_bonding); if (is_bonding) { p_lcb->SetBonding(); } else { @@ -277,7 +280,7 @@ bool l2c_is_cmd_rejected(uint8_t cmd_code, uint8_t signal_id, tL2C_LCB* p_lcb) { case L2CAP_CMD_BLE_UPDATE_REQ: l2cu_send_peer_cmd_reject(p_lcb, L2CAP_CMD_REJ_MTU_EXCEEDED, signal_id, L2CAP_DEFAULT_MTU, 0); - LOG_WARN("Dumping first Command (%d)", cmd_code); + log::warn("Dumping first Command ({})", cmd_code); return true; default: /* Otherwise a response */ @@ -372,7 +375,7 @@ void l2cu_send_peer_cmd_reject(tL2C_LCB* p_lcb, uint16_t reason, uint8_t rem_id, p_buf = l2cu_build_header(p_lcb, (uint16_t)(L2CAP_CMD_REJECT_LEN + param_len), L2CAP_CMD_REJECT, rem_id); if (p_buf == NULL) { - LOG_WARN("L2CAP - no buffer cmd_rej"); + log::warn("L2CAP - no buffer cmd_rej"); return; } @@ -411,7 +414,7 @@ void l2cu_send_peer_connect_req(tL2C_CCB* p_ccb) { p_buf = l2cu_build_header(p_ccb->p_lcb, L2CAP_CONN_REQ_LEN, L2CAP_CMD_CONN_REQ, p_ccb->local_id); if (p_buf == NULL) { - LOG_WARN("L2CAP - no buffer for conn_req"); + log::warn("L2CAP - no buffer for conn_req"); return; } @@ -439,7 +442,7 @@ void l2cu_send_peer_connect_rsp(tL2C_CCB* p_ccb, uint16_t result, if (result == L2CAP_CONN_PENDING) { /* if we already sent pending response */ if (p_ccb->flags & CCB_FLAG_SENT_PENDING) { - LOG_DEBUG("Already sent connection pending, not sending again"); + log::debug("Already sent connection pending, not sending again"); return; } else { p_ccb->flags |= CCB_FLAG_SENT_PENDING; @@ -449,7 +452,7 @@ void l2cu_send_peer_connect_rsp(tL2C_CCB* p_ccb, uint16_t result, BT_HDR* p_buf = l2cu_build_header(p_ccb->p_lcb, L2CAP_CONN_RSP_LEN, L2CAP_CMD_CONN_RSP, p_ccb->remote_id); if (p_buf == nullptr) { - LOG_WARN("no buffer for conn_rsp"); + log::warn("no buffer for conn_rsp"); return; } @@ -483,7 +486,7 @@ void l2cu_reject_connection(tL2C_LCB* p_lcb, uint16_t remote_cid, p_buf = l2cu_build_header(p_lcb, L2CAP_CONN_RSP_LEN, L2CAP_CMD_CONN_RSP, rem_id); if (p_buf == NULL) { - LOG_WARN("L2CAP - no buffer for conn_req"); + log::warn("L2CAP - no buffer for conn_req"); return; } @@ -528,15 +531,15 @@ void l2cu_send_credit_based_reconfig_req(tL2C_CCB* p_ccb, p_buf = l2cu_build_header(p_lcb, cmd_len, L2CAP_CMD_CREDIT_BASED_RECONFIG_REQ, p_lcb->signal_id); if (p_buf == NULL) { - LOG_WARN("l2cu_send_reconfig_req - no buffer"); + log::warn("l2cu_send_reconfig_req - no buffer"); return; } p = (uint8_t*)(p_buf + 1) + L2CAP_SEND_CMD_OFFSET + HCI_DATA_PREAMBLE_SIZE + L2CAP_PKT_OVERHEAD + L2CAP_CMD_OVERHEAD; - LOG_VERBOSE("l2cu_send_reconfig_req number of cids: %d mtu:%d mps:%d", - p_lcb->pending_ecoc_reconfig_cnt, p_cfg->mtu, p_cfg->mps); + log::verbose("l2cu_send_reconfig_req number of cids: {} mtu:{} mps:{}", + p_lcb->pending_ecoc_reconfig_cnt, p_cfg->mtu, p_cfg->mps); UINT16_TO_STREAM(p, p_cfg->mtu); UINT16_TO_STREAM(p, p_cfg->mps); @@ -589,7 +592,7 @@ void l2cu_send_peer_config_req(tL2C_CCB* p_ccb, tL2CAP_CFG_INFO* p_cfg) { (uint16_t)(L2CAP_CONFIG_REQ_LEN + cfg_len), L2CAP_CMD_CONFIG_REQ, p_ccb->local_id); if (p_buf == NULL) { - LOG_WARN("L2CAP - no buffer for conn_req"); + log::warn("L2CAP - no buffer for conn_req"); return; } @@ -683,7 +686,7 @@ void l2cu_send_peer_config_rsp(tL2C_CCB* p_ccb, tL2CAP_CFG_INFO* p_cfg) { (uint16_t)(L2CAP_CONFIG_RSP_LEN + cfg_len), L2CAP_CMD_CONFIG_RSP, p_ccb->remote_id); if (p_buf == NULL) { - LOG_WARN("L2CAP - no buffer for conn_req"); + log::warn("L2CAP - no buffer for conn_req"); return; } @@ -758,14 +761,14 @@ void l2cu_send_peer_config_rej(tL2C_CCB* p_ccb, uint8_t* p_data, uint8_t *p, *p_hci_len, *p_data_end; uint8_t cfg_code; - LOG_VERBOSE("l2cu_send_peer_config_rej: data_len=%d, rej_len=%d", data_len, - rej_len); + log::verbose("l2cu_send_peer_config_rej: data_len={}, rej_len={}", data_len, + rej_len); len = BT_HDR_SIZE + HCI_DATA_PREAMBLE_SIZE + L2CAP_PKT_OVERHEAD + L2CAP_CMD_OVERHEAD + L2CAP_CONFIG_RSP_LEN; len1 = 0xFFFF - len; if (rej_len > len1) { - LOG_ERROR("L2CAP - cfg_rej pkt size exceeds buffer design max limit."); + log::error("L2CAP - cfg_rej pkt size exceeds buffer design max limit."); return; } @@ -831,7 +834,7 @@ void l2cu_send_peer_config_rej(tL2C_CCB* p_ccb, uint8_t* p_data, p += cfg_len + L2CAP_CFG_OPTION_OVERHEAD; buf_space -= (cfg_len + L2CAP_CFG_OPTION_OVERHEAD); } else { - LOG_WARN("L2CAP - cfg_rej exceeds allocated buffer"); + log::warn("L2CAP - cfg_rej exceeds allocated buffer"); p_data = p_data_end; /* force loop exit */ break; } @@ -851,8 +854,8 @@ void l2cu_send_peer_config_rej(tL2C_CCB* p_ccb, uint8_t* p_data, p_buf->len = len + 4; - LOG_VERBOSE("L2CAP - cfg_rej pkt hci_len=%d, l2cap_len=%d", len, - (L2CAP_CMD_OVERHEAD + L2CAP_CONFIG_RSP_LEN + rej_len)); + log::verbose("L2CAP - cfg_rej pkt hci_len={}, l2cap_len={}", len, + (L2CAP_CMD_OVERHEAD + L2CAP_CONFIG_RSP_LEN + rej_len)); l2c_link_check_send_pkts(p_ccb->p_lcb, 0, p_buf); } @@ -872,7 +875,7 @@ void l2cu_send_peer_disc_req(tL2C_CCB* p_ccb) { uint8_t* p; if ((!p_ccb) || (p_ccb->p_lcb == NULL)) { - LOG_ERROR("%s L2CAP - ccb or lcb invalid", __func__); + log::error("L2CAP - ccb or lcb invalid"); return; } @@ -885,7 +888,7 @@ void l2cu_send_peer_disc_req(tL2C_CCB* p_ccb) { p_buf = l2cu_build_header(p_ccb->p_lcb, L2CAP_DISC_REQ_LEN, L2CAP_CMD_DISC_REQ, p_ccb->local_id); if (p_buf == NULL) { - LOG_WARN("L2CAP - no buffer for disc_req"); + log::warn("L2CAP - no buffer for disc_req"); return; } @@ -931,7 +934,7 @@ void l2cu_send_peer_disc_rsp(tL2C_LCB* p_lcb, uint8_t remote_id, p_buf = l2cu_build_header(p_lcb, L2CAP_DISC_RSP_LEN, L2CAP_CMD_DISC_RSP, remote_id); if (p_buf == NULL) { - LOG_WARN("L2CAP - no buffer for disc_rsp"); + log::warn("L2CAP - no buffer for disc_rsp"); return; } @@ -963,7 +966,7 @@ void l2cu_send_peer_echo_rsp(tL2C_LCB* p_lcb, uint8_t signal_id, * checking) */ if (!signal_id || signal_id == p_lcb->cur_echo_id) { /* Dump this request since it is illegal */ - LOG_WARN("L2CAP ignoring duplicate echo request (%d)", signal_id); + log::warn("L2CAP ignoring duplicate echo request ({})", signal_id); return; } else p_lcb->cur_echo_id = signal_id; @@ -985,7 +988,7 @@ void l2cu_send_peer_echo_rsp(tL2C_LCB* p_lcb, uint8_t signal_id, p_buf = l2cu_build_header(p_lcb, (uint16_t)(L2CAP_ECHO_RSP_LEN + data_len), L2CAP_CMD_ECHO_RSP, signal_id); if (p_buf == NULL) { - LOG_WARN("L2CAP - no buffer for echo_rsp"); + log::warn("L2CAP - no buffer for echo_rsp"); return; } @@ -1018,11 +1021,11 @@ void l2cu_send_peer_info_req(tL2C_LCB* p_lcb, uint16_t info_type) { p_buf = l2cu_build_header(p_lcb, 2, L2CAP_CMD_INFO_REQ, p_lcb->signal_id); if (p_buf == NULL) { - LOG_WARN("L2CAP - no buffer for info_req"); + log::warn("L2CAP - no buffer for info_req"); return; } - LOG_VERBOSE("l2cu_send_peer_info_req: type 0x%04x", info_type); + log::verbose("l2cu_send_peer_info_req: type 0x{:04x}", info_type); p = (uint8_t*)(p_buf + 1) + L2CAP_SEND_CMD_OFFSET + HCI_DATA_PREAMBLE_SIZE + L2CAP_PKT_OVERHEAD + L2CAP_CMD_OVERHEAD; @@ -1076,7 +1079,7 @@ void l2cu_send_peer_info_rsp(tL2C_LCB* p_lcb, uint8_t remote_id, p_buf = l2cu_build_header(p_lcb, len, L2CAP_CMD_INFO_RSP, remote_id); if (p_buf == NULL) { - LOG_WARN("L2CAP - no buffer for info_rsp"); + log::warn("L2CAP - no buffer for info_rsp"); return; } @@ -1162,13 +1165,13 @@ void l2cu_enqueue_ccb(tL2C_CCB* p_ccb) { if (p_ccb->p_lcb != NULL) p_q = &p_ccb->p_lcb->ccb_queue; if ((!p_ccb->in_use) || (p_q == NULL)) { - LOG_ERROR("%s: CID: 0x%04x ERROR in_use: %u p_lcb: %p", __func__, - p_ccb->local_cid, p_ccb->in_use, p_ccb->p_lcb); + log::error("CID: 0x{:04x} ERROR in_use: {} p_lcb: {}", p_ccb->local_cid, + p_ccb->in_use, fmt::ptr(p_ccb->p_lcb)); return; } - LOG_VERBOSE("l2cu_enqueue_ccb CID: 0x%04x priority: %d", p_ccb->local_cid, - p_ccb->ccb_priority); + log::verbose("l2cu_enqueue_ccb CID: 0x{:04x} priority: {}", p_ccb->local_cid, + p_ccb->ccb_priority); /* If the queue is empty, we go at the front */ if (!p_q->p_first_ccb) { @@ -1236,18 +1239,18 @@ void l2cu_enqueue_ccb(tL2C_CCB* p_ccb) { void l2cu_dequeue_ccb(tL2C_CCB* p_ccb) { tL2C_CCB_Q* p_q = NULL; - LOG_VERBOSE("l2cu_dequeue_ccb CID: 0x%04x", p_ccb->local_cid); + log::verbose("l2cu_dequeue_ccb CID: 0x{:04x}", p_ccb->local_cid); /* Find out which queue the channel is on */ if (p_ccb->p_lcb != NULL) p_q = &p_ccb->p_lcb->ccb_queue; if ((!p_ccb->in_use) || (p_q == NULL) || (p_q->p_first_ccb == NULL)) { - LOG_ERROR( - "l2cu_dequeue_ccb CID: 0x%04x ERROR in_use: %u p_lcb: 0x%p p_q: " - "0x%p p_q->p_first_ccb: 0x%p", - p_ccb->local_cid, p_ccb->in_use, p_ccb->p_lcb, p_q, - p_q ? p_q->p_first_ccb : 0); + log::error( + "l2cu_dequeue_ccb CID: 0x{:04x} ERROR in_use: {} p_lcb: 0x{} p_q: " + "0x{} p_q->p_first_ccb: 0x{}", + p_ccb->local_cid, p_ccb->in_use, fmt::ptr(p_ccb->p_lcb), fmt::ptr(p_q), + fmt::ptr(p_q ? p_q->p_first_ccb : 0)); return; } @@ -1309,7 +1312,7 @@ void l2cu_change_pri_ccb(tL2C_CCB* p_ccb, tL2CAP_CHNL_PRIORITY priority) { if (p_ccb->ccb_priority != priority) { /* If CCB is not the only guy on the queue */ if ((p_ccb->p_next_ccb != NULL) || (p_ccb->p_prev_ccb != NULL)) { - LOG_VERBOSE("Update CCB list in logical link"); + log::verbose("Update CCB list in logical link"); /* Remove CCB from queue and re-queue it at new priority */ l2cu_dequeue_ccb(p_ccb); @@ -1347,9 +1350,9 @@ void l2cu_change_pri_ccb(tL2C_CCB* p_ccb, tL2CAP_CHNL_PRIORITY priority) { * ******************************************************************************/ tL2C_CCB* l2cu_allocate_ccb(tL2C_LCB* p_lcb, uint16_t cid, bool is_eatt) { - LOG_DEBUG("is_dynamic = %d, cid 0x%04x", p_lcb != nullptr, cid); + log::debug("is_dynamic = {}, cid 0x{:04x}", p_lcb != nullptr, cid); if (!l2cb.p_free_ccb_first) { - LOG_ERROR("First free ccb is null for cid 0x%04x", cid); + log::error("First free ccb is null for cid 0x{:04x}", cid); return nullptr; } tL2C_CCB* p_ccb; @@ -1378,7 +1381,7 @@ tL2C_CCB* l2cu_allocate_ccb(tL2C_LCB* p_lcb, uint16_t cid, bool is_eatt) { } } if (p_prev == nullptr) { - LOG_ERROR("Could not find CCB for CID 0x%04x in the free list", cid); + log::error("Could not find CCB for CID 0x{:04x} in the free list", cid); return nullptr; } } @@ -1448,7 +1451,7 @@ tL2C_CCB* l2cu_allocate_ccb(tL2C_LCB* p_lcb, uint16_t cid, bool is_eatt) { if (cid == 0) { p_ccb->config_done = 0; } else { - LOG_DEBUG("cid 0x%04x config_done:0x%x", cid, p_ccb->config_done); + log::debug("cid 0x{:04x} config_done:0x{:x}", cid, p_ccb->config_done); } p_ccb->chnl_state = CST_CLOSED; @@ -1493,14 +1496,15 @@ tL2C_CCB* l2cu_allocate_ccb(tL2C_LCB* p_lcb, uint16_t cid, bool is_eatt) { bool l2cu_start_post_bond_timer(uint16_t handle) { tL2C_LCB* p_lcb = l2cu_find_lcb_by_handle(handle); if (p_lcb == nullptr) { - LOG_WARN("Unable to find link control block for handle:0x%04x", handle); + log::warn("Unable to find link control block for handle:0x{:04x}", handle); return true; } p_lcb->ResetBonding(); /* Only start timer if no control blocks allocated */ if (p_lcb->ccb_queue.p_first_ccb != nullptr) { - LOG_DEBUG("Unable to start post bond timer with existing dynamic channels"); + log::debug( + "Unable to start post bond timer with existing dynamic channels"); return false; } @@ -1520,13 +1524,13 @@ bool l2cu_start_post_bond_timer(uint16_t handle) { } alarm_set_on_mloop(p_lcb->l2c_lcb_timer, timeout_ms, l2c_lcb_timer_timeout, p_lcb); - LOG_DEBUG("Started link IDLE timeout_ms:%lu", (unsigned long)timeout_ms); + log::debug("Started link IDLE timeout_ms:{}", (unsigned long)timeout_ms); return true; } break; default: - LOG_DEBUG("Will not start post bond timer with link state:%s", - link_state_text(p_lcb->link_state).c_str()); + log::debug("Will not start post bond timer with link state:{}", + link_state_text(p_lcb->link_state)); break; } return false; @@ -1547,8 +1551,8 @@ void l2cu_release_ccb(tL2C_CCB* p_ccb) { tL2C_LCB* p_lcb = p_ccb->p_lcb; tL2C_RCB* p_rcb = p_ccb->p_rcb; - LOG_VERBOSE("l2cu_release_ccb: cid 0x%04x in_use: %u", p_ccb->local_cid, - p_ccb->in_use); + log::verbose("l2cu_release_ccb: cid 0x{:04x} in_use: {}", p_ccb->local_cid, + p_ccb->in_use); /* If already released, could be race condition */ if (!p_ccb->in_use) return; @@ -1622,7 +1626,7 @@ void l2cu_release_ccb(tL2C_CCB* p_ccb) { if (!p_lcb->ccb_queue.p_first_ccb) { if (p_lcb->transport == BT_TRANSPORT_LE && p_ccb->local_cid == L2CAP_ATT_CID) { - LOG_WARN("%s - disconnecting the LE link", __func__); + log::warn("disconnecting the LE link"); l2cu_no_dynamic_ccbs(p_lcb); } } @@ -1752,7 +1756,7 @@ void l2cu_disconnect_chnl(tL2C_CCB* p_ccb) { tL2CA_DISCONNECT_IND_CB* p_disc_cb = p_ccb->p_rcb->api.pL2CA_DisconnectInd_Cb; - LOG_WARN("L2CAP - disconnect_chnl CID: 0x%04x", local_cid); + log::warn("L2CAP - disconnect_chnl CID: 0x{:04x}", local_cid); l2cu_send_peer_disc_req(p_ccb); @@ -1761,7 +1765,7 @@ void l2cu_disconnect_chnl(tL2C_CCB* p_ccb) { (*p_disc_cb)(local_cid, false); } else { /* failure on the AMP channel, probably need to disconnect ACL */ - LOG_ERROR("L2CAP - disconnect_chnl CID: 0x%04x Ignored", local_cid); + log::error("L2CAP - disconnect_chnl CID: 0x{:04x} Ignored", local_cid); } } @@ -1964,9 +1968,9 @@ void l2cu_process_peer_cfg_rsp(tL2C_CCB* p_ccb, tL2CAP_CFG_INFO* p_cfg) { else p_ccb->fcrb.max_held_acks = p_ccb->our_cfg.fcr.tx_win_sz / 3; - LOG_VERBOSE( - "l2cu_process_peer_cfg_rsp(): peer tx_win_sz: %d, our tx_win_sz: %d, " - "max_held_acks: %d", + log::verbose( + "l2cu_process_peer_cfg_rsp(): peer tx_win_sz: {}, our tx_win_sz: {}, " + "max_held_acks: {}", p_cfg->fcr.tx_win_sz, p_ccb->our_cfg.fcr.tx_win_sz, p_ccb->fcrb.max_held_acks); } @@ -2084,8 +2088,7 @@ void l2cu_create_conn_br_edr(tL2C_LCB* p_lcb) { if (p_lcb_cur == p_lcb) continue; if (!p_lcb_cur->in_use) continue; if (BTM_IsScoActiveByBdaddr(p_lcb_cur->remote_bd_addr)) { - LOG_VERBOSE("%s Central peripheral switch not allowed when SCO active", - __func__); + log::verbose("Central peripheral switch not allowed when SCO active"); continue; } if (p_lcb->IsLinkRoleCentral()) continue; @@ -2241,16 +2244,16 @@ static void l2cu_set_acl_priority_latency_brcm(tL2C_LCB* p_lcb, // priority to high, if using latency mode check preset latency if (p_lcb->use_latency_mode && p_lcb->preset_acl_latency == L2CAP_LATENCY_LOW) { - LOG_INFO("Set ACL priority: High Priority and Low Latency Mode"); + log::info("Set ACL priority: High Priority and Low Latency Mode"); vs_param = HCI_BRCM_ACL_HIGH_PRIORITY_LOW_LATENCY; p_lcb->set_latency(L2CAP_LATENCY_LOW); } else { - LOG_INFO("Set ACL priority: High Priority Mode"); + log::info("Set ACL priority: High Priority Mode"); vs_param = HCI_BRCM_ACL_HIGH_PRIORITY; } } else { // priority to normal - LOG_INFO("Set ACL priority: Normal Mode"); + log::info("Set ACL priority: Normal Mode"); vs_param = HCI_BRCM_ACL_NORMAL_PRIORITY; p_lcb->set_latency(L2CAP_LATENCY_NORMAL); } @@ -2282,16 +2285,16 @@ static void l2cu_set_acl_priority_latency_syna(tL2C_LCB* p_lcb, // priority to high, if using latency mode check preset latency if (p_lcb->use_latency_mode && p_lcb->preset_acl_latency == L2CAP_LATENCY_LOW) { - LOG_INFO("Set ACL priority: High Priority and Low Latency Mode"); + log::info("Set ACL priority: High Priority and Low Latency Mode"); vs_param = HCI_SYNA_ACL_HIGH_PRIORITY_LOW_LATENCY; p_lcb->set_latency(L2CAP_LATENCY_LOW); } else { - LOG_INFO("Set ACL priority: High Priority Mode"); + log::info("Set ACL priority: High Priority Mode"); vs_param = HCI_SYNA_ACL_HIGH_PRIORITY; } } else { // priority to normal - LOG_INFO("Set ACL priority: Normal Mode"); + log::info("Set ACL priority: Normal Mode"); vs_param = HCI_SYNA_ACL_NORMAL_PRIORITY; p_lcb->set_latency(L2CAP_LATENCY_NORMAL); } @@ -2320,11 +2323,11 @@ static void l2cu_set_acl_priority_unisoc(tL2C_LCB* p_lcb, uint8_t vs_param; if (priority == L2CAP_PRIORITY_HIGH) { // priority to high - LOG_INFO("Set ACL priority: High Priority Mode"); + log::info("Set ACL priority: High Priority Mode"); vs_param = HCI_UNISOC_ACL_HIGH_PRIORITY; } else { // priority to normal - LOG_INFO("Set ACL priority: Normal Mode"); + log::info("Set ACL priority: Normal Mode"); vs_param = HCI_UNISOC_ACL_NORMAL_PRIORITY; } @@ -2353,11 +2356,11 @@ static void l2cu_set_acl_priority_latency_mtk(tL2C_LCB* p_lcb, uint8_t vs_param; if (priority == L2CAP_PRIORITY_HIGH) { // priority to high, if using latency mode check preset latency - LOG_INFO("Set ACL priority: High Priority Mode"); + log::info("Set ACL priority: High Priority Mode"); vs_param = HCI_MTK_ACL_HIGH_PRIORITY; } else { // priority to normal - LOG_INFO("Set ACL priority: Normal Mode"); + log::info("Set ACL priority: Normal Mode"); vs_param = HCI_MTK_ACL_NORMAL_PRIORITY; } @@ -2381,12 +2384,12 @@ bool l2cu_set_acl_priority(const RawAddress& bd_addr, tL2CAP_PRIORITY priority, bool reset_after_rs) { tL2C_LCB* p_lcb; - LOG_VERBOSE("SET ACL PRIORITY %d", priority); + log::verbose("SET ACL PRIORITY {}", priority); /* Find the link control block for the acl channel */ p_lcb = l2cu_find_lcb_by_bd_addr(bd_addr, BT_TRANSPORT_BR_EDR); if (p_lcb == NULL) { - LOG_WARN("L2CAP - no LCB for L2CA_SetAclPriority"); + log::warn("L2CAP - no LCB for L2CA_SetAclPriority"); return (false); } @@ -2440,8 +2443,8 @@ bool l2cu_set_acl_priority(const RawAddress& bd_addr, tL2CAP_PRIORITY priority, ******************************************************************************/ static void l2cu_set_acl_latency_brcm(tL2C_LCB* p_lcb, tL2CAP_LATENCY latency) { - LOG_INFO("Set ACL latency: %s", - latency == L2CAP_LATENCY_LOW ? "Low Latancy" : "Normal Latency"); + log::info("Set ACL latency: {}", + latency == L2CAP_LATENCY_LOW ? "Low Latancy" : "Normal Latency"); uint8_t command[HCI_BRCM_ACL_PRIORITY_PARAM_SIZE]; uint8_t* pp = command; @@ -2466,8 +2469,8 @@ static void l2cu_set_acl_latency_brcm(tL2C_LCB* p_lcb, tL2CAP_LATENCY latency) { ******************************************************************************/ static void l2cu_set_acl_latency_syna(tL2C_LCB* p_lcb, tL2CAP_LATENCY latency) { - LOG_INFO("Set ACL latency: %s", - latency == L2CAP_LATENCY_LOW ? "Low Latancy" : "Normal Latency"); + log::info("Set ACL latency: {}", + latency == L2CAP_LATENCY_LOW ? "Low Latancy" : "Normal Latency"); uint8_t command[HCI_SYNA_ACL_PRIORITY_PARAM_SIZE]; uint8_t* pp = command; @@ -2492,13 +2495,13 @@ static void l2cu_set_acl_latency_syna(tL2C_LCB* p_lcb, tL2CAP_LATENCY latency) { ******************************************************************************/ bool l2cu_set_acl_latency(const RawAddress& bd_addr, tL2CAP_LATENCY latency) { - LOG_INFO("Set ACL low latency: %d", latency); + log::info("Set ACL low latency: {}", latency); /* Find the link control block for the acl channel */ tL2C_LCB* p_lcb = l2cu_find_lcb_by_bd_addr(bd_addr, BT_TRANSPORT_BR_EDR); if (p_lcb == nullptr) { - LOG_WARN("Set latency failed: LCB is null"); + log::warn("Set latency failed: LCB is null"); return false; } /* only change controller's latency when stream using latency mode */ @@ -2558,7 +2561,7 @@ void l2cu_resubmit_pending_sec_req(const RawAddress* p_bda) { tL2C_CCB* p_next_ccb; int xx; - LOG_VERBOSE("l2cu_resubmit_pending_sec_req p_bda: 0x%p", p_bda); + log::verbose("l2cu_resubmit_pending_sec_req p_bda: 0x{}", fmt::ptr(p_bda)); /* If we are called with a BDA, only resubmit for that BDA */ if (p_bda) { @@ -2572,7 +2575,7 @@ void l2cu_resubmit_pending_sec_req(const RawAddress* p_bda) { l2c_csm_execute(p_ccb, L2CEVT_SEC_RE_SEND_CMD, NULL); } } else { - LOG_WARN("l2cu_resubmit_pending_sec_req - unknown BD_ADDR"); + log::warn("l2cu_resubmit_pending_sec_req - unknown BD_ADDR"); } } else { /* No BDA pasesed in, so check all links */ @@ -2621,8 +2624,8 @@ void l2cu_adjust_out_mps(tL2C_CCB* p_ccb) { if (packet_size <= (L2CAP_PKT_OVERHEAD + L2CAP_FCR_OVERHEAD + L2CAP_SDU_LEN_OVERHEAD + L2CAP_FCS_LEN)) { /* something is very wrong */ - LOG_ERROR("l2cu_adjust_out_mps bad packet size: %u will use MPS: %u", - packet_size, p_ccb->peer_cfg.fcr.mps); + log::error("l2cu_adjust_out_mps bad packet size: {} will use MPS: {}", + packet_size, p_ccb->peer_cfg.fcr.mps); p_ccb->tx_mps = p_ccb->peer_cfg.fcr.mps; } else { packet_size -= (L2CAP_PKT_OVERHEAD + L2CAP_FCR_OVERHEAD + @@ -2644,9 +2647,9 @@ void l2cu_adjust_out_mps(tL2C_CCB* p_ccb) { else p_ccb->tx_mps = p_ccb->peer_cfg.fcr.mps; - LOG_VERBOSE( - "l2cu_adjust_out_mps use %d Based on peer_cfg.fcr.mps: %u " - "packet_size: %u", + log::verbose( + "l2cu_adjust_out_mps use {} Based on peer_cfg.fcr.mps: {} " + "packet_size: {}", p_ccb->tx_mps, p_ccb->peer_cfg.fcr.mps, packet_size); } } @@ -2679,8 +2682,9 @@ bool l2cu_initialize_fixed_ccb(tL2C_LCB* p_lcb, uint16_t fixed_cid) { if (p_lcb->link_state == LST_DISCONNECTED) { alarm_cancel(p_lcb->l2c_lcb_timer); } else { - LOG_WARN("Unable to cancel link control block for link connection to device %s", - ADDRESS_TO_LOGGABLE_CSTR(p_lcb->remote_bd_addr)); + log::warn( + "Unable to cancel link control block for link connection to device {}", + ADDRESS_TO_LOGGABLE_CSTR(p_lcb->remote_bd_addr)); } /* Set CID for the connection */ @@ -2726,8 +2730,8 @@ void l2cu_no_dynamic_ccbs(tL2C_LCB* p_lcb) { (p_lcb->p_fixed_ccbs[xx]->fixed_chnl_idle_tout * 1000 > timeout_ms)) { if (p_lcb->p_fixed_ccbs[xx]->fixed_chnl_idle_tout == L2CAP_NO_IDLE_TIMEOUT) { - LOG_VERBOSE("%s NO IDLE timeout set for fixed cid 0x%04x", __func__, - p_lcb->p_fixed_ccbs[xx]->local_cid); + log::verbose("NO IDLE timeout set for fixed cid 0x{:04x}", + p_lcb->p_fixed_ccbs[xx]->local_cid); start_timeout = false; } timeout_ms = p_lcb->p_fixed_ccbs[xx]->fixed_chnl_idle_tout * 1000; @@ -2737,8 +2741,8 @@ void l2cu_no_dynamic_ccbs(tL2C_LCB* p_lcb) { /* If the link is pairing, do not mess with the timeouts */ if (p_lcb->IsBonding()) return; - LOG_VERBOSE("l2cu_no_dynamic_ccbs() with_active_local_clients=%d", - p_lcb->with_active_local_clients); + log::verbose("l2cu_no_dynamic_ccbs() with_active_local_clients={}", + p_lcb->with_active_local_clients); // Inactive connections should not timeout, since the ATT channel might still // be in use even without a GATT client. We only timeout if either a dynamic // channel or a GATT client was used, since then we expect the client to @@ -2748,7 +2752,7 @@ void l2cu_no_dynamic_ccbs(tL2C_LCB* p_lcb) { } if (timeout_ms == 0) { - LOG_VERBOSE("l2cu_no_dynamic_ccbs() IDLE timer 0, disconnecting link"); + log::verbose("l2cu_no_dynamic_ccbs() IDLE timer 0, disconnecting link"); rc = btm_sec_disconnect( p_lcb->Handle(), HCI_ERR_PEER_USER, @@ -2779,7 +2783,7 @@ void l2cu_no_dynamic_ccbs(tL2C_LCB* p_lcb) { if (start_timeout) { alarm_set_on_mloop(p_lcb->l2c_lcb_timer, timeout_ms, l2c_lcb_timer_timeout, p_lcb); - LOG_DEBUG("Started link IDLE timeout_ms:%lu", (unsigned long)timeout_ms); + log::debug("Started link IDLE timeout_ms:{}", (unsigned long)timeout_ms); } else { alarm_cancel(p_lcb->l2c_lcb_timer); } @@ -2898,7 +2902,7 @@ void l2cu_send_peer_ble_par_req(tL2C_LCB* p_lcb, uint16_t min_int, p_buf = l2cu_build_header(p_lcb, L2CAP_CMD_BLE_UPD_REQ_LEN, L2CAP_CMD_BLE_UPDATE_REQ, p_lcb->signal_id); if (p_buf == NULL) { - LOG_WARN("l2cu_send_peer_ble_par_req - no buffer"); + log::warn("l2cu_send_peer_ble_par_req - no buffer"); return; } @@ -2931,7 +2935,7 @@ void l2cu_send_peer_ble_par_rsp(tL2C_LCB* p_lcb, uint16_t reason, p_buf = l2cu_build_header(p_lcb, L2CAP_CMD_BLE_UPD_RSP_LEN, L2CAP_CMD_BLE_UPDATE_RSP, rem_id); if (p_buf == NULL) { - LOG_WARN("l2cu_send_peer_ble_par_rsp - no buffer"); + log::warn("l2cu_send_peer_ble_par_rsp - no buffer"); return; } @@ -2974,7 +2978,7 @@ void l2cu_send_peer_ble_credit_based_conn_req(tL2C_CCB* p_ccb) { l2cu_build_header(p_lcb, L2CAP_CMD_BLE_CREDIT_BASED_CONN_REQ_LEN, L2CAP_CMD_BLE_CREDIT_BASED_CONN_REQ, p_lcb->signal_id); if (p_buf == NULL) { - LOG_WARN("l2cu_send_peer_ble_credit_based_conn_req - no buffer"); + log::warn("l2cu_send_peer_ble_credit_based_conn_req - no buffer"); return; } @@ -2985,9 +2989,9 @@ void l2cu_send_peer_ble_credit_based_conn_req(tL2C_CCB* p_ccb) { mps = p_ccb->local_conn_cfg.mps; initial_credit = p_ccb->local_conn_cfg.credits; - LOG_VERBOSE( - "l2cu_send_peer_ble_credit_based_conn_req PSM:0x%04x local_cid:%d" - " mtu:%d mps:%d initial_credit:%d", + log::verbose( + "l2cu_send_peer_ble_credit_based_conn_req PSM:0x{:04x} local_cid:{} " + "mtu:{} mps:{} initial_credit:{}", p_ccb->p_rcb->real_psm, p_ccb->local_cid, mtu, mps, initial_credit); UINT16_TO_STREAM(p, p_ccb->p_rcb->real_psm); @@ -3032,7 +3036,7 @@ void l2cu_send_peer_credit_based_conn_req(tL2C_CCB* p_ccb) { 2 * p_lcb->pending_ecoc_conn_cnt, L2CAP_CMD_CREDIT_BASED_CONN_REQ, p_ccb->local_id); if (p_buf == NULL) { - LOG_WARN("%s - no buffer", __func__); + log::warn("no buffer"); return; } @@ -3043,9 +3047,9 @@ void l2cu_send_peer_credit_based_conn_req(tL2C_CCB* p_ccb) { mps = p_ccb->local_conn_cfg.mps; initial_credit = p_ccb->local_conn_cfg.credits; - LOG_VERBOSE("%s PSM:0x%04x mtu:%d mps:%d initial_credit:%d, cids_cnt %d", - __func__, p_ccb->p_rcb->real_psm, mtu, mps, initial_credit, - p_lcb->pending_ecoc_conn_cnt); + log::verbose("PSM:0x{:04x} mtu:{} mps:{} initial_credit:{}, cids_cnt {}", + p_ccb->p_rcb->real_psm, mtu, mps, initial_credit, + p_lcb->pending_ecoc_conn_cnt); UINT16_TO_STREAM(p, p_ccb->p_rcb->real_psm); UINT16_TO_STREAM(p, mtu); @@ -3054,7 +3058,7 @@ void l2cu_send_peer_credit_based_conn_req(tL2C_CCB* p_ccb) { for (int i = 0; i < p_lcb->pending_ecoc_conn_cnt; i++) { uint16_t cid = p_lcb->pending_ecoc_connection_cids[i]; - LOG_VERBOSE("\n\t cid: %d", cid); + log::verbose(" cid: {}", cid); UINT16_TO_STREAM(p, cid); } @@ -3080,7 +3084,7 @@ void l2cu_reject_ble_coc_connection(tL2C_LCB* p_lcb, uint8_t rem_id, p_buf = l2cu_build_header(p_lcb, L2CAP_CMD_BLE_CREDIT_BASED_CONN_RES_LEN, L2CAP_CMD_BLE_CREDIT_BASED_CONN_RES, rem_id); if (p_buf == NULL) { - LOG_WARN("l2cu_reject_ble_coc_connection - no buffer"); + log::warn("l2cu_reject_ble_coc_connection - no buffer"); return; } @@ -3117,7 +3121,7 @@ void l2cu_reject_credit_based_conn_req(tL2C_LCB* p_lcb, uint8_t rem_id, p_buf = l2cu_build_header(p_lcb, rsp_len, L2CAP_CMD_CREDIT_BASED_CONN_RES, rem_id); if (p_buf == NULL) { - LOG_WARN("l2cu_reject_credit_based_conn_req - no buffer"); + log::warn("l2cu_reject_credit_based_conn_req - no buffer"); return; } @@ -3150,14 +3154,14 @@ void l2cu_send_peer_credit_based_conn_res(tL2C_CCB* p_ccb, BT_HDR* p_buf; uint8_t* p; - LOG_VERBOSE("%s", __func__); + log::verbose(""); uint8_t rsp_len = L2CAP_CMD_CREDIT_BASED_CONN_RES_MIN_LEN + p_ccb->p_lcb->pending_ecoc_conn_cnt * sizeof(uint16_t); p_buf = l2cu_build_header(p_ccb->p_lcb, rsp_len, L2CAP_CMD_CREDIT_BASED_CONN_RES, p_ccb->remote_id); if (p_buf == NULL) { - LOG_WARN("%s - no buffer", __func__); + log::warn("no buffer"); return; } @@ -3239,12 +3243,12 @@ void l2cu_send_ble_reconfig_rsp(tL2C_LCB* p_lcb, uint8_t rem_id, BT_HDR* p_buf; uint8_t* p; - LOG_VERBOSE("l2cu_send_ble_reconfig_rsp result 0x04%x", result); + log::verbose("l2cu_send_ble_reconfig_rsp result 0x04{:x}", result); p_buf = l2cu_build_header(p_lcb, L2CAP_CMD_CREDIT_BASED_RECONFIG_RES_LEN, L2CAP_CMD_CREDIT_BASED_RECONFIG_RES, rem_id); if (p_buf == NULL) { - LOG_WARN("l2cu_send_peer_ble_credit_based_conn_res - no buffer"); + log::warn("l2cu_send_peer_ble_credit_based_conn_res - no buffer"); return; } @@ -3273,12 +3277,12 @@ void l2cu_send_peer_ble_credit_based_conn_res(tL2C_CCB* p_ccb, BT_HDR* p_buf; uint8_t* p; - LOG_VERBOSE("l2cu_send_peer_ble_credit_based_conn_res"); + log::verbose("l2cu_send_peer_ble_credit_based_conn_res"); p_buf = l2cu_build_header(p_ccb->p_lcb, L2CAP_CMD_BLE_CREDIT_BASED_CONN_RES_LEN, L2CAP_CMD_BLE_CREDIT_BASED_CONN_RES, p_ccb->remote_id); if (p_buf == NULL) { - LOG_WARN("l2cu_send_peer_ble_credit_based_conn_res - no buffer"); + log::warn("l2cu_send_peer_ble_credit_based_conn_res - no buffer"); return; } @@ -3322,7 +3326,7 @@ void l2cu_send_peer_ble_flow_control_credit(tL2C_CCB* p_ccb, p_buf = l2cu_build_header(p_lcb, L2CAP_CMD_BLE_FLOW_CTRL_CREDIT_LEN, L2CAP_CMD_BLE_FLOW_CTRL_CREDIT, p_lcb->signal_id); if (p_buf == NULL) { - LOG_WARN("l2cu_send_peer_ble_credit_based_conn_req - no buffer"); + log::warn("l2cu_send_peer_ble_credit_based_conn_req - no buffer"); return; } @@ -3349,7 +3353,7 @@ void l2cu_send_peer_ble_credit_based_disconn_req(tL2C_CCB* p_ccb) { BT_HDR* p_buf; uint8_t* p; tL2C_LCB* p_lcb = NULL; - LOG_VERBOSE("%s", __func__); + log::verbose(""); if (!p_ccb) return; p_lcb = p_ccb->p_lcb; @@ -3362,7 +3366,7 @@ void l2cu_send_peer_ble_credit_based_disconn_req(tL2C_CCB* p_ccb) { p_buf = l2cu_build_header(p_lcb, L2CAP_DISC_REQ_LEN, L2CAP_CMD_DISC_REQ, p_lcb->signal_id); if (p_buf == NULL) { - LOG_WARN("l2cu_send_peer_ble_credit_based_disconn_req - no buffer"); + log::warn("l2cu_send_peer_ble_credit_based_disconn_req - no buffer"); return; } @@ -3496,9 +3500,9 @@ static void send_congestion_status_to_all_clients(tL2C_CCB* p_ccb, p_ccb->cong_sent = status; if (p_ccb->p_rcb && p_ccb->p_rcb->api.pL2CA_CongestionStatus_Cb) { - LOG_VERBOSE( - "L2CAP - Calling CongestionStatus_Cb (%d), CID: 0x%04x " - "xmit_hold_q.count: %zu buff_quota: %u", + log::verbose( + "L2CAP - Calling CongestionStatus_Cb ({}), CID: 0x{:04x} " + "xmit_hold_q.count: {} buff_quota: {}", status, p_ccb->local_cid, fixed_queue_length(p_ccb->xmit_hold_q), p_ccb->buff_quota); diff --git a/system/types/hci_role.h b/system/types/hci_role.h index eb582b8212bf5d423be4bd4012dd594b03f37534..bdd0940756b5e1b1eadeb2b12604e0448b60c873 100644 --- a/system/types/hci_role.h +++ b/system/types/hci_role.h @@ -47,3 +47,14 @@ inline tHCI_ROLE to_hci_role(const uint8_t& role) { typedef tHCI_ROLE hci_role_t; // LEGACY const auto RoleText = hci_role_text; // LEGACY + +#if __has_include(<bluetooth/log.h>) + +#include <bluetooth/log.h> + +namespace fmt { +template <> +struct formatter<tHCI_ROLE> : enum_formatter<tHCI_ROLE> {}; +} // namespace fmt + +#endif // __has_include(<bluetooth/log.h>)