diff --git a/system/btif/src/btif_sock_rfc.cc b/system/btif/src/btif_sock_rfc.cc
index e5746dc3bcdd975330d5953164b1048b31ba9270..cff0648f6f729f2e93544293b18fbed485c5cd95 100644
--- a/system/btif/src/btif_sock_rfc.cc
+++ b/system/btif/src/btif_sock_rfc.cc
@@ -682,7 +682,13 @@ static void on_rfc_outgoing_congest(tBTA_JV_RFCOMM_CONG* p, uint32_t id) {
static uint32_t rfcomm_cback(tBTA_JV_EVT event, tBTA_JV* p_data,
uint32_t rfcomm_slot_id) {
uint32_t id = 0;
- LOG_INFO("handling event:%d id:%u", event, rfcomm_slot_id);
+
+ // Write events are too frequent to log at info level
+ if (event != BTA_JV_RFCOMM_WRITE_EVT) {
+ LOG_INFO("handling event:%d id:%u", event, rfcomm_slot_id);
+ } else {
+ LOG_VERBOSE("handling event:%d id:%u", event, rfcomm_slot_id);
+ }
switch (event) {
case BTA_JV_RFCOMM_START_EVT:
diff --git a/system/stack/rfcomm/rfc_port_fsm.cc b/system/stack/rfcomm/rfc_port_fsm.cc
index 08d7fb392f221f76a015079fdd8149612fbb6cd5..295fc7d1cad6692741fa2c41c29e8bdaee925d88 100644
--- a/system/stack/rfcomm/rfc_port_fsm.cc
+++ b/system/stack/rfcomm/rfc_port_fsm.cc
@@ -84,9 +84,13 @@ static void rfc_set_port_state(tPORT_STATE* port_pars, MX_FRAME* p_frame);
******************************************************************************/
void rfc_port_sm_execute(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
CHECK(p_port != nullptr) << __func__ << ": NULL port event " << event;
- log::info("bd_addr:{}, port:{}, state:{}, event:{}",
- ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle,
- p_port->rfc.state, event);
+
+ // logs for state RFC_STATE_OPENED handled in rfc_port_sm_opened()
+ if (p_port->rfc.state != RFC_STATE_OPENED) {
+ log::info("bd_addr:{}, index:{}, state:{}, event:{}",
+ ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle,
+ p_port->rfc.state, event);
+ }
switch (p_port->rfc.state) {
case RFC_STATE_CLOSED:
rfc_port_sm_state_closed(p_port, event, p_data);
@@ -460,10 +464,14 @@ void rfc_port_sm_orig_wait_sec_check(tPORT* p_port, tRFC_PORT_EVENT event,
void rfc_port_sm_opened(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
switch (event) {
case RFC_PORT_EVENT_OPEN:
- log::error("Port error state {} event {}", p_port->rfc.state, event);
+ log::error("Port error, bd_addr={}, state={}, event={}",
+ ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->rfc.state,
+ event);
return;
case RFC_PORT_EVENT_CLOSE:
+ log::info("RFC_PORT_EVENT_CLOSE bd_addr={}, index={}",
+ ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
rfc_port_timer_start(p_port, RFC_DISC_TIMEOUT);
rfc_send_disc(p_port->rfc.p_mcb, p_port->dlci);
p_port->rfc.expected_rsp = 0;
@@ -471,7 +479,8 @@ void rfc_port_sm_opened(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
return;
case RFC_PORT_EVENT_CLEAR:
- log::warn("RFC_PORT_EVENT_CLEAR, index={}", p_port->handle);
+ log::warn("RFC_PORT_EVENT_CLEAR, bd_addr={}, index={}",
+ ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
rfc_port_closed(p_port);
return;
@@ -481,6 +490,8 @@ void rfc_port_sm_opened(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
/* There might be an initial case when we reduced rx_max and credit_rx is
* still */
/* bigger. Make sure that we do not send 255 */
+ log::verbose("RFC_PORT_EVENT_DATA bd_addr={}, index={}",
+ ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
if ((p_port->rfc.p_mcb->flow == PORT_FC_CREDIT) &&
(((BT_HDR*)p_data)->len < p_port->peer_mtu) &&
(!p_port->rx.user_fc) &&
@@ -496,19 +507,27 @@ void rfc_port_sm_opened(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
return;
case RFC_PORT_EVENT_UA:
+ log::verbose("RFC_PORT_EVENT_UA bd_addr={}, index={}",
+ ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
return;
case RFC_PORT_EVENT_SABME:
+ log::verbose("RFC_PORT_EVENT_SABME bd_addr={}, index={}",
+ ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
rfc_send_ua(p_port->rfc.p_mcb, p_port->dlci);
return;
case RFC_PORT_EVENT_DM:
- log::warn("RFC_EVENT_DM, index={}", p_port->handle);
+ log::info("RFC_EVENT_DM, bd_addr={}, index={}",
+ ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
PORT_DlcReleaseInd(p_port->rfc.p_mcb, p_port->dlci);
rfc_port_closed(p_port);
return;
case RFC_PORT_EVENT_DISC:
+ log::info("RFC_PORT_EVENT_DISC, bd_addr={}, index={}",
+ ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle,
+ p_port->rfc.state, event);
p_port->rfc.state = RFC_STATE_CLOSED;
rfc_send_ua(p_port->rfc.p_mcb, p_port->dlci);
if (!fixed_queue_is_empty(p_port->rx.queue)) {
@@ -520,16 +539,20 @@ void rfc_port_sm_opened(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
return;
case RFC_PORT_EVENT_UIH:
+ log::verbose("RFC_PORT_EVENT_UIH bd_addr={}, index={}",
+ ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->handle);
rfc_port_uplink_data(p_port, (BT_HDR*)p_data);
return;
case RFC_PORT_EVENT_TIMEOUT:
PORT_TimeOutCloseMux(p_port->rfc.p_mcb);
- log::error("Port error state {} event {}", p_port->rfc.state, event);
+ log::error("Port error, bd_addr={}, state={}, event={}",
+ ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->rfc.state,
+ event);
return;
default:
- log::error("Received unexpected event:{} in state:{}", event,
- p_port->rfc.state);
+ log::error("Received unexpected event {}, bd_addr={}, state={}", event,
+ ADDRESS_TO_LOGGABLE_CSTR(p_port->bd_addr), p_port->rfc.state);
}
log::warn("Port state opened Event ignored {}", event);
}