From 074867d4c7c966758eddbe30294c4a9b6459c8dd Mon Sep 17 00:00:00 2001 From: Jack He Date: Wed, 30 Aug 2017 12:00:41 -0700 Subject: [PATCH] RFCOMM: Add more logging during port close * Log MAC address and UUIDs of closed connections * Log reasons for RFCOMM closure when generic CLOSE is used as reason Bug: 65080465 Test: Use profiles that use RFCOMM Change-Id: Iff9f7537989e51d7b98f7cf1241db3f196f501d7 --- stack/rfcomm/port_rfc.cc | 17 ++++++++++------- stack/rfcomm/rfc_port_fsm.cc | 21 +++++++++++++++++++++ stack/rfcomm/rfc_utils.cc | 4 ---- 3 files changed, 31 insertions(+), 11 deletions(-) diff --git a/stack/rfcomm/port_rfc.cc b/stack/rfcomm/port_rfc.cc index 1bc6568a6..f4e84ae1f 100644 --- a/stack/rfcomm/port_rfc.cc +++ b/stack/rfcomm/port_rfc.cc @@ -372,6 +372,8 @@ void PORT_ParNegCnf(tRFC_MCB* p_mcb, uint8_t dlci, uint16_t mtu, uint8_t cl, /* This is illegal-- negotiation fails. */ if ((PORT_FC_DEFAULT == PORT_FC_TS710) && (cl == RFCOMM_PN_CONV_LAYER_CBFC_R)) { + RFCOMM_TRACE_WARNING("%s, negotiation fails, index=%d", __func__, + p_port->inx); rfc_send_disc(p_mcb, p_port->dlci); rfc_port_closed(p_port); return; @@ -940,7 +942,7 @@ uint32_t port_rfc_send_tx_data(tPORT* p_port) { * * Function port_rfc_closed * - * Description This function when RFCOMM side of port is closed + * Description Called when RFCOMM port is closed * ******************************************************************************/ void port_rfc_closed(tPORT* p_port, uint8_t res) { @@ -949,8 +951,8 @@ void port_rfc_closed(tPORT* p_port, uint8_t res) { tRFC_MCB* p_mcb = p_port->rfc.p_mcb; if ((p_port->state == PORT_STATE_OPENING) && (p_port->is_server)) { - /* The servr side has not been informed that connection is up, ignore */ - RFCOMM_TRACE_EVENT("port_rfc_closed in OPENING state ignored"); + /* The server side was not informed that connection is up, ignore */ + RFCOMM_TRACE_WARNING("port_rfc_closed in OPENING state ignored"); rfc_port_timer_stop(p_port); p_port->rfc.state = RFC_STATE_CLOSED; @@ -985,8 +987,6 @@ void port_rfc_closed(tPORT* p_port, uint8_t res) { if (p_port->ev_mask & PORT_EV_CONNECT_ERR) events |= PORT_EV_CONNECT_ERR; } - RFCOMM_TRACE_EVENT("port_rfc_closed state:%d sending events:%x", - p_port->state, events); if ((p_port->p_callback != NULL) && events) p_port->p_callback(events, p_port->inx); @@ -995,8 +995,11 @@ void port_rfc_closed(tPORT* p_port, uint8_t res) { p_port->rfc.state = RFC_STATE_CLOSED; - RFCOMM_TRACE_WARNING("%s RFCOMM connection in state %d closed: %s (res: %d)", - __func__, p_port->state, PORT_GetResultString(res), res); + RFCOMM_TRACE_WARNING( + "%s: RFCOMM connection closed, index=%d, state=%d reason=%s[%d], " + "UUID=%04X, bd_addr=%s, is_server=%d", + __func__, p_port->inx, p_port->state, PORT_GetResultString(res), res, + p_port->uuid, p_port->bd_addr.ToString().c_str(), p_port->is_server); port_release_port(p_port); } diff --git a/stack/rfcomm/rfc_port_fsm.cc b/stack/rfcomm/rfc_port_fsm.cc index 59d2c70ec..5157a75e6 100644 --- a/stack/rfcomm/rfc_port_fsm.cc +++ b/stack/rfcomm/rfc_port_fsm.cc @@ -143,6 +143,7 @@ void rfc_port_sm_state_closed(tPORT* p_port, uint16_t event, void* p_data) { return; case RFC_EVENT_DM: + RFCOMM_TRACE_WARNING("%s, RFC_EVENT_DM, index=%d", __func__, p_port->inx); rfc_port_closed(p_port); return; @@ -192,6 +193,8 @@ void rfc_port_sm_sabme_wait_ua(tPORT* p_port, uint16_t event, void* p_data) { return; case RFC_EVENT_CLEAR: + RFCOMM_TRACE_WARNING("%s, RFC_EVENT_CLEAR, index=%d", __func__, + p_port->inx); rfc_port_closed(p_port); return; @@ -207,6 +210,7 @@ void rfc_port_sm_sabme_wait_ua(tPORT* p_port, uint16_t event, void* p_data) { return; case RFC_EVENT_DM: + RFCOMM_TRACE_WARNING("%s, RFC_EVENT_DM, index=%d", __func__, p_port->inx); p_port->rfc.p_mcb->is_disc_initiator = true; PORT_DlcEstablishCnf(p_port->rfc.p_mcb, p_port->dlci, p_port->rfc.p_mcb->peer_l2cap_mtu, RFCOMM_ERROR); @@ -214,6 +218,8 @@ void rfc_port_sm_sabme_wait_ua(tPORT* p_port, uint16_t event, void* p_data) { return; case RFC_EVENT_DISC: + RFCOMM_TRACE_WARNING("%s, RFC_EVENT_DISC, index=%d", __func__, + p_port->inx); rfc_send_ua(p_port->rfc.p_mcb, p_port->dlci); PORT_DlcEstablishCnf(p_port->rfc.p_mcb, p_port->dlci, p_port->rfc.p_mcb->peer_l2cap_mtu, RFCOMM_ERROR); @@ -275,6 +281,8 @@ void rfc_port_sm_term_wait_sec_check(tPORT* p_port, uint16_t event, return; case RFC_EVENT_CLEAR: + RFCOMM_TRACE_WARNING("%s, RFC_EVENT_CLEAR, index=%d", __func__, + p_port->inx); btm_sec_abort_access_req(p_port->rfc.p_mcb->bd_addr); rfc_port_closed(p_port); return; @@ -330,6 +338,8 @@ void rfc_port_sm_orig_wait_sec_check(tPORT* p_port, uint16_t event, switch (event) { case RFC_EVENT_SEC_COMPLETE: if (*((uint8_t*)p_data) != BTM_SUCCESS) { + RFCOMM_TRACE_ERROR("%s, RFC_EVENT_SEC_COMPLETE, index=%d, result=%d", + __func__, event, p_port->inx, *((uint8_t*)p_data)); p_port->rfc.p_mcb->is_disc_initiator = true; PORT_DlcEstablishCnf(p_port->rfc.p_mcb, p_port->dlci, 0, RFCOMM_SECURITY_ERR); @@ -348,6 +358,8 @@ void rfc_port_sm_orig_wait_sec_check(tPORT* p_port, uint16_t event, return; case RFC_EVENT_CLOSE: + RFCOMM_TRACE_WARNING("%s, RFC_EVENT_CLOSE, index=%d", __func__, + p_port->inx); btm_sec_abort_access_req(p_port->rfc.p_mcb->bd_addr); rfc_port_closed(p_port); return; @@ -390,6 +402,8 @@ void rfc_port_sm_opened(tPORT* p_port, uint16_t event, void* p_data) { return; case RFC_EVENT_CLEAR: + RFCOMM_TRACE_WARNING("%s, RFC_EVENT_CLEAR, index=%d", __func__, + p_port->inx); rfc_port_closed(p_port); return; @@ -421,6 +435,7 @@ void rfc_port_sm_opened(tPORT* p_port, uint16_t event, void* p_data) { return; case RFC_EVENT_DM: + RFCOMM_TRACE_WARNING("%s, RFC_EVENT_DM, index=%d", __func__, p_port->inx); PORT_DlcReleaseInd(p_port->rfc.p_mcb, p_port->dlci); rfc_port_closed(p_port); return; @@ -468,6 +483,8 @@ void rfc_port_sm_disc_wait_ua(tPORT* p_port, uint16_t event, void* p_data) { return; case RFC_EVENT_CLEAR: + RFCOMM_TRACE_WARNING("%s, RFC_EVENT_CLEAR, index=%d", __func__, event, + p_port->inx); rfc_port_closed(p_port); return; @@ -480,6 +497,8 @@ void rfc_port_sm_disc_wait_ua(tPORT* p_port, uint16_t event, void* p_data) { /* Case falls through */ case RFC_EVENT_DM: + RFCOMM_TRACE_WARNING("%s, RFC_EVENT_DM|RFC_EVENT_UA[%d], index=%d", + __func__, event, p_port->inx); rfc_port_closed(p_port); return; @@ -497,6 +516,8 @@ void rfc_port_sm_disc_wait_ua(tPORT* p_port, uint16_t event, void* p_data) { return; case RFC_EVENT_TIMEOUT: + RFCOMM_TRACE_ERROR("%s, RFC_EVENT_TIMEOUT, index=%d", __func__, + p_port->inx); rfc_port_closed(p_port); return; } diff --git a/stack/rfcomm/rfc_utils.cc b/stack/rfcomm/rfc_utils.cc index d4f209c11..7e40355a6 100644 --- a/stack/rfcomm/rfc_utils.cc +++ b/stack/rfcomm/rfc_utils.cc @@ -351,11 +351,7 @@ void rfc_sec_check_complete(UNUSED_ATTR const RawAddress* bd_addr, ******************************************************************************/ void rfc_port_closed(tPORT* p_port) { tRFC_MCB* p_mcb = p_port->rfc.p_mcb; - - RFCOMM_TRACE_DEBUG("rfc_port_closed"); - rfc_port_timer_stop(p_port); - p_port->rfc.state = RFC_STATE_CLOSED; /* If multiplexer channel was up mark it as down */ -- 2.11.0