RFCOMM: Update sm_cb where relevant

- Update the state and open_timestamp in new rfc_set_state function
- Update the event when we call port_sm_execute
- Update the close_reason when we close the port

Bug: 374989690
Test: atest RfcommTest
Flag: EXEMPT no-op
Change-Id: Icaa04a7caa3b52ae3e988109b11f72ec509fad09

6 files changed, 45 insertions, 19 deletions

diff --git a/system/stack/Android.bp b/system/stack/Android.bp
index 783117ddc3..38e5507dd6 100644
--- a/system/stack/Android.bp
+++ b/system/stack/Android.bp
@@ -495,6 +495,7 @@ cc_fuzz {
         "libbluetooth_l2cap_pdl",
         "libbluetooth_log",
         "libbluetooth_smp_pdl",
+        "libbt-common",
         "libbt-platform-protos-lite",
     ],
 }
diff --git a/system/stack/fuzzers/rfcomm_fuzzer.cc b/system/stack/fuzzers/rfcomm_fuzzer.cc
index 3418f3a6ed..82897723c6 100644
--- a/system/stack/fuzzers/rfcomm_fuzzer.cc
+++ b/system/stack/fuzzers/rfcomm_fuzzer.cc
@@ -52,10 +52,6 @@ void SnoopLogger::AcceptlistRfcommDlci(uint16_t, uint16_t, uint8_t) {}
 void SnoopLogger::SetRfcommPortOpen(uint16_t, uint16_t, uint8_t, uint16_t, bool) {}
 void SnoopLogger::SetRfcommPortClose(uint16_t, uint16_t, uint8_t, uint16_t) {}
 }  // namespace hal
-
-namespace common {
-uint64_t time_get_os_boottime_ms() { return 0; }
-}  // namespace common
 }  // namespace bluetooth
 
 namespace {
diff --git a/system/stack/rfcomm/port_rfc.cc b/system/stack/rfcomm/port_rfc.cc
index 14a9cb5bf0..4dc7590d96 100644
--- a/system/stack/rfcomm/port_rfc.cc
+++ b/system/stack/rfcomm/port_rfc.cc
@@ -991,7 +991,7 @@ void port_rfc_closed(tPORT* p_port, uint8_t res) {
     log::warn("port_rfc_closed in OPENING state ignored");
 
     rfc_port_timer_stop(p_port);
-    p_port->rfc.sm_cb.state = RFC_STATE_CLOSED;
+    rfc_set_state(RFC_STATE_CLOSED, p_port);
 
     if (p_mcb) {
       p_mcb->port_handles[p_port->dlci] = 0;
@@ -1049,8 +1049,8 @@ void port_rfc_closed(tPORT* p_port, uint8_t res) {
     p_port->p_mgmt_callback(static_cast<tPORT_RESULT>(res2), p_port->handle);
   }
 
-  p_port->rfc.sm_cb.state = RFC_STATE_CLOSED;
-
+  rfc_set_state(RFC_STATE_CLOSED, p_port);
+  p_port->rfc.sm_cb.close_reason = static_cast<tPORT_RESULT>(res);
   log::info(
           "RFCOMM connection closed, port_handle={}, state={}, reason={}[{}], "
           "UUID=0x{:x}, bd_addr={}, is_server={}",
diff --git a/system/stack/rfcomm/rfc_int.h b/system/stack/rfcomm/rfc_int.h
index b773ee2dc2..95ca7c6d07 100644
--- a/system/stack/rfcomm/rfc_int.h
+++ b/system/stack/rfcomm/rfc_int.h
@@ -237,6 +237,7 @@ void rfc_sec_check_complete(RawAddress bd_addr, tBT_TRANSPORT transport, void* p
 void rfc_inc_credit(tPORT* p_port, uint8_t credit);
 void rfc_dec_credit(tPORT* p_port);
 void rfc_check_send_cmd(tRFC_MCB* p_mcb, BT_HDR* p_buf);
+void rfc_set_state(tRFC_PORT_STATE state, tPORT* p_port);
 
 /*
  * Functions provided by the rfc_ts_frames.cc
diff --git a/system/stack/rfcomm/rfc_port_fsm.cc b/system/stack/rfcomm/rfc_port_fsm.cc
index be47e22617..dec82b672b 100644
--- a/system/stack/rfcomm/rfc_port_fsm.cc
+++ b/system/stack/rfcomm/rfc_port_fsm.cc
@@ -74,7 +74,9 @@ static void rfc_set_port_settings(PortSettings* port_settings, MX_FRAME* p_frame
  *
  ******************************************************************************/
 void rfc_port_sm_execute(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
-  log::assert_that(p_port != nullptr, "NULL port event {}", event);
+  log::assert_that(p_port != nullptr, "NULL port, event {}", event);
+
+  p_port->rfc.sm_cb.last_event = event;
 
   // logs for state RFC_STATE_OPENED handled in rfc_port_sm_opened()
   if (p_port->rfc.sm_cb.state != RFC_STATE_OPENED) {
@@ -122,7 +124,7 @@ void rfc_port_sm_execute(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
 void rfc_port_sm_state_closed(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
   switch (event) {
     case RFC_PORT_EVENT_OPEN:
-      p_port->rfc.sm_cb.state = RFC_STATE_ORIG_WAIT_SEC_CHECK;
+      rfc_set_state(RFC_STATE_ORIG_WAIT_SEC_CHECK, p_port);
       btm_sec_mx_access_request(p_port->rfc.p_mcb->bd_addr, true, p_port->sec_mask,
                                 &rfc_sec_check_complete, p_port);
       return;
@@ -143,7 +145,7 @@ void rfc_port_sm_state_closed(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data
       rfc_timer_stop(p_port->rfc.p_mcb);
 
       /* Open will be continued after security checks are passed */
-      p_port->rfc.sm_cb.state = RFC_STATE_TERM_WAIT_SEC_CHECK;
+      rfc_set_state(RFC_STATE_TERM_WAIT_SEC_CHECK, p_port);
       btm_sec_mx_access_request(p_port->rfc.p_mcb->bd_addr, false, p_port->sec_mask,
                                 &rfc_sec_check_complete, p_port);
       return;
@@ -199,7 +201,7 @@ void rfc_port_sm_sabme_wait_ua(tPORT* p_port, tRFC_PORT_EVENT event, void* p_dat
       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;
-      p_port->rfc.sm_cb.state = RFC_STATE_DISC_WAIT_UA;
+      rfc_set_state(RFC_STATE_DISC_WAIT_UA, p_port);
       return;
 
     case RFC_PORT_EVENT_CLEAR:
@@ -213,7 +215,7 @@ void rfc_port_sm_sabme_wait_ua(tPORT* p_port, tRFC_PORT_EVENT event, void* p_dat
 
     case RFC_PORT_EVENT_UA:
       rfc_port_timer_stop(p_port);
-      p_port->rfc.sm_cb.state = RFC_STATE_OPENED;
+      rfc_set_state(RFC_STATE_OPENED, p_port);
 
       if (uuid_logging_acceptlist.find(p_port->uuid) != uuid_logging_acceptlist.end()) {
         // Find Channel Control Block by Channel ID
@@ -267,7 +269,7 @@ void rfc_port_sm_sabme_wait_ua(tPORT* p_port, tRFC_PORT_EVENT event, void* p_dat
       return;
 
     case RFC_PORT_EVENT_TIMEOUT:
-      p_port->rfc.sm_cb.state = RFC_STATE_CLOSED;
+      rfc_set_state(RFC_STATE_CLOSED, p_port);
       PORT_DlcEstablishCnf(p_port->rfc.p_mcb, p_port->dlci, p_port->rfc.p_mcb->peer_l2cap_mtu,
                            RFCOMM_ERROR);
       return;
@@ -334,7 +336,7 @@ void rfc_port_sm_term_wait_sec_check(tPORT* p_port, tRFC_PORT_EVENT event, void*
 
     case RFC_PORT_EVENT_DISC:
       btm_sec_abort_access_req(p_port->rfc.p_mcb->bd_addr);
-      p_port->rfc.sm_cb.state = RFC_STATE_CLOSED;
+      rfc_set_state(RFC_STATE_CLOSED, p_port);
       rfc_send_ua(p_port->rfc.p_mcb, p_port->dlci);
 
       PORT_DlcReleaseInd(p_port->rfc.p_mcb, p_port->dlci);
@@ -351,7 +353,7 @@ void rfc_port_sm_term_wait_sec_check(tPORT* p_port, tRFC_PORT_EVENT event, void*
         }
       } else {
         rfc_send_ua(p_port->rfc.p_mcb, p_port->dlci);
-        p_port->rfc.sm_cb.state = RFC_STATE_OPENED;
+        rfc_set_state(RFC_STATE_OPENED, p_port);
 
         if (uuid_logging_acceptlist.find(p_port->uuid) != uuid_logging_acceptlist.end()) {
           // Find Channel Control Block by Channel ID
@@ -409,7 +411,7 @@ void rfc_port_sm_orig_wait_sec_check(tPORT* p_port, tRFC_PORT_EVENT event, void*
                    rfcomm_port_state_text(p_port->rfc.sm_cb.state), p_port->handle);
         rfc_send_sabme(p_port->rfc.p_mcb, p_port->dlci);
         rfc_port_timer_start(p_port, RFC_PORT_T1_TIMEOUT);
-        p_port->rfc.sm_cb.state = RFC_STATE_SABME_WAIT_UA;
+        rfc_set_state(RFC_STATE_SABME_WAIT_UA, p_port);
       }
       return;
 
@@ -462,7 +464,7 @@ void rfc_port_sm_opened(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
       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;
-      p_port->rfc.sm_cb.state = RFC_STATE_DISC_WAIT_UA;
+      rfc_set_state(RFC_STATE_DISC_WAIT_UA, p_port);
       return;
 
     case RFC_PORT_EVENT_CLEAR:
@@ -510,7 +512,7 @@ void rfc_port_sm_opened(tPORT* p_port, tRFC_PORT_EVENT event, void* p_data) {
     case RFC_PORT_EVENT_DISC:
       log::info("RFC_PORT_EVENT_DISC bd_addr:{} port_handle:{} dlci:{} scn:{}", p_port->bd_addr,
                 p_port->handle, p_port->dlci, p_port->scn);
-      p_port->rfc.sm_cb.state = RFC_STATE_CLOSED;
+      rfc_set_state(RFC_STATE_CLOSED, p_port);
       rfc_send_ua(p_port->rfc.p_mcb, p_port->dlci);
       if (!fixed_queue_is_empty(p_port->rx.queue)) {
         /* give a chance to upper stack to close port properly */
diff --git a/system/stack/rfcomm/rfc_utils.cc b/system/stack/rfcomm/rfc_utils.cc
index 87beaaf566..d9389eda07 100644
--- a/system/stack/rfcomm/rfc_utils.cc
+++ b/system/stack/rfcomm/rfc_utils.cc
@@ -28,6 +28,7 @@
 
 #include <cstdint>
 
+#include "common/time_util.h"
 #include "internal_include/bt_target.h"
 #include "osi/include/allocator.h"
 #include "stack/include/bt_hdr.h"
@@ -341,7 +342,7 @@ void rfc_sec_check_complete(RawAddress /* bd_addr */, tBT_TRANSPORT /* transport
 void rfc_port_closed(tPORT* p_port) {
   tRFC_MCB* p_mcb = p_port->rfc.p_mcb;
   rfc_port_timer_stop(p_port);
-  p_port->rfc.sm_cb.state = RFC_STATE_CLOSED;
+  rfc_set_state(RFC_STATE_CLOSED, p_port);
 
   /* If multiplexer channel was up mark it as down */
   if (p_mcb) {
@@ -434,3 +435,28 @@ void rfc_check_send_cmd(tRFC_MCB* p_mcb, BT_HDR* p_buf) {
     }
   }
 }
+
+/*******************************************************************************
+ *
+ * Function         rfc_set_state
+ *
+ * Description      This function updates the RfcommPortSm control block with a
+ *                  new state
+ *
+ ******************************************************************************/
+void rfc_set_state(tRFC_PORT_STATE state, tPORT* p_port) {
+  // nothing is going to change if the state doesn't change
+  if (p_port->rfc.sm_cb.state == state) {
+    log::debug("Already at state {}, no need to update", rfcomm_port_state_text(state));
+    return;
+  }
+
+  p_port->rfc.sm_cb.state_prior = p_port->rfc.sm_cb.state;
+  p_port->rfc.sm_cb.state = state;
+
+  if (state == RFC_STATE_OPENED) {
+    p_port->rfc.sm_cb.open_timestamp = bluetooth::common::time_gettimeofday_us();
+  } else if (state == RFC_STATE_CLOSED && p_port->rfc.sm_cb.open_timestamp != 0) {
+    p_port->rfc.sm_cb.close_timestamp = bluetooth::common::time_gettimeofday_us();
+  }
+}