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

diff --git a/stack/rfcomm/port_rfc.cc b/stack/rfcomm/port_rfc.cc
index 1bc6568..f4e84ae 100644 (file)
--- 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 59d2c70..5157a75 100644 (file)
--- 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 d4f209c..7e40355 100644 (file)
--- 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 */