Handle BQR root inflammation event

* When Bluetooth process recieves BQR root inflammation event, wait
  5 seconds for possible DEBUG_INFO events, then abort.
* Fix the DEBUG_INFO not working problem.
* Do not immediately abort when HAL service dies if abort_timer has
  already started, so we won't interrupt log collecting procedure.

Bug: 144572644
Bug: 144592765
Test: Manual
Change-Id: Ibe6c341a3e9aabec33de8d3f90c4a6a3403d06bc

diff --git a/btif/include/btif_bqr.h b/btif/include/btif_bqr.h
index 4407b0d..ecf69f1 100644 (file)
--- a/btif/include/btif_bqr.h
+++ b/btif/include/btif_bqr.h
@@ -67,6 +67,11 @@ static constexpr int8_t kCriWarnRssi = -80;
 static constexpr uint8_t kCriWarnUnusedCh = 55;
 // The queue size of recording the BQR events.
 static constexpr uint8_t kBqrEventQueueSize = 25;
+// The minimum size of the ROOT_INFLAMMATION event
+// HCI_VENDOR_SPECIFIC_EVT(1) + BQR sub event(1) + BQR report ID(1) +
+// error code(1) + vendor error code(1) = 5
+static constexpr uint8_t kRootInflammationPacketMinSize = 5;
+
 // The Property of BQR event mask configuration.
 static constexpr const char* kpPropertyEventMask =
     "persist.bluetooth.bqr.event_mask";
@@ -90,7 +95,8 @@ enum BqrQualityReportId : uint8_t {
   QUALITY_REPORT_ID_MONITOR_MODE = 0x01,
   QUALITY_REPORT_ID_APPROACH_LSTO = 0x02,
   QUALITY_REPORT_ID_A2DP_AUDIO_CHOPPY = 0x03,
-  QUALITY_REPORT_ID_SCO_VOICE_CHOPPY = 0x04
+  QUALITY_REPORT_ID_SCO_VOICE_CHOPPY = 0x04,
+  QUALITY_REPORT_ID_ROOT_INFLAMMATION = 0x05
 };
 
 // Packet Type definition

diff --git a/hci/Android.bp b/hci/Android.bp
index ddfef50..7e4c52a 100644 (file)
--- a/hci/Android.bp
+++ b/hci/Android.bp
@@ -35,6 +35,7 @@ cc_library_static {
         "system/bt/stack/include",
         "system/bt/utils/include",
         "system/bt/bta/include",
+        "system/bt/btif/include",
         "system/libhwbinder/include",
     ],
 }

diff --git a/hci/src/hci_layer.cc b/hci/src/hci_layer.cc
index da6054b..198f904 100644 (file)
--- a/hci/src/hci_layer.cc
+++ b/hci/src/hci_layer.cc
@@ -36,10 +36,12 @@
 #include <mutex>
 
 #include "btcore/include/module.h"
+#include "btif/include/btif_bqr.h"
 #include "btsnoop.h"
 #include "buffer_allocator.h"
 #include "common/message_loop_thread.h"
 #include "common/metrics.h"
+#include "common/once_timer.h"
 #include "hci_inject.h"
 #include "hci_internals.h"
 #include "hcidefs.h"
@@ -55,6 +57,7 @@
 #define BT_HCI_TIMEOUT_TAG_NUM 1010000
 
 using bluetooth::common::MessageLoopThread;
+using bluetooth::common::OnceTimer;
 
 extern void hci_initialize();
 extern void hci_transmit(BT_HDR* packet);
@@ -111,7 +114,7 @@ static std::queue<base::Closure> command_queue;
 static alarm_t* command_response_timer;
 static list_t* commands_pending_response;
 static std::recursive_timed_mutex commands_pending_response_mutex;
-static alarm_t* hci_timeout_abort_timer;
+static OnceTimer abort_timer;
 
 // The hand-off point for data going to a higher layer, set by the higher layer
 static base::Callback<void(const base::Location&, BT_HDR*)> send_data_upwards;
@@ -166,6 +169,14 @@ void iso_data_received(BT_HDR* packet) {
   packet_fragmenter->reassemble_and_dispatch(packet);
 }
 
+void hal_service_died() {
+  if (abort_timer.IsScheduled()) {
+    LOG(ERROR) << "abort_timer is scheduled, wait for timeout";
+    return;
+  }
+  abort();
+}
+
 // Module lifecycle functions
 
 static future_t* hci_module_shut_down();
@@ -264,12 +275,6 @@ static future_t* hci_module_shut_down() {
 
   packet_fragmenter->cleanup();
 
-  // Clean up abort timer, if it exists.
-  if (hci_timeout_abort_timer != NULL) {
-    alarm_free(hci_timeout_abort_timer);
-    hci_timeout_abort_timer = NULL;
-  }
-
   if (hci_firmware_log_fd != INVALID_FD) {
     hci_close_firmware_log_file(hci_firmware_log_fd);
     hci_firmware_log_fd = INVALID_FD;
@@ -442,7 +447,7 @@ static void fragmenter_transmit_finished(BT_HDR* packet,
 }
 
 // Abort.  The chip has had time to write any debugging information.
-static void hci_timeout_abort(void* unused_data) {
+static void hci_timeout_abort(void) {
   LOG_ERROR(LOG_TAG, "%s restarting the Bluetooth process.", __func__);
   hci_close_firmware_log_file(hci_firmware_log_fd);
 
@@ -451,6 +456,12 @@ static void hci_timeout_abort(void* unused_data) {
   abort();
 }
 
+static void hci_root_inflamed_abort(uint8_t error_code,
+                                    uint8_t vendor_error_code) {
+  LOG(FATAL) << __func__ << ": error_code = " << std::to_string(error_code)
+             << ", vendor_error_code = " << std::to_string(vendor_error_code);
+}
+
 static void command_timed_out_log_info(void* original_wait_entry) {
   LOG_ERROR(LOG_TAG, "%s: %d commands pending response", __func__,
             get_num_waiting_commands());
@@ -500,7 +511,7 @@ static void command_timed_out(void* original_wait_entry) {
   }
 
   // Don't request a firmware dump for multiple hci timeouts
-  if (hci_timeout_abort_timer != NULL || hci_firmware_log_fd != INVALID_FD) {
+  if (hci_firmware_log_fd != INVALID_FD) {
     return;
   }
 
@@ -526,13 +537,13 @@ static void command_timed_out(void* original_wait_entry) {
   osi_free(bt_hdr);
   LOG_ERROR(LOG_TAG, "%s: Setting a timer to restart.", __func__);
 
-  hci_timeout_abort_timer = alarm_new("hci.hci_timeout_aborter");
-  if (!hci_timeout_abort_timer) {
+  // alarm_default_callbacks thread post to hci_thread.
+  if (!abort_timer.Schedule(
+          hci_thread.GetWeakPtr(), FROM_HERE, base::Bind(hci_timeout_abort),
+          base::TimeDelta::FromMilliseconds(COMMAND_TIMEOUT_RESTART_MS))) {
     LOG_ERROR(LOG_TAG, "%s unable to create an abort timer.", __func__);
     abort();
   }
-  alarm_set(hci_timeout_abort_timer, COMMAND_TIMEOUT_RESTART_MS,
-            hci_timeout_abort, nullptr);
 }
 
 // Event/packet receiving functions
@@ -619,15 +630,62 @@ static bool filter_incoming_event(BT_HDR* packet) {
     }
 
     goto intercepted;
-  } else if (event_code == HCI_VSE_SUBCODE_DEBUG_INFO_SUB_EVT) {
-    if (hci_firmware_log_fd == INVALID_FD)
-      hci_firmware_log_fd = hci_open_firmware_log_file();
+  } else if (event_code == HCI_VENDOR_SPECIFIC_EVT) {
+    uint8_t sub_event_code;
+    STREAM_TO_UINT8(sub_event_code, stream);
 
-    if (hci_firmware_log_fd != INVALID_FD)
-      hci_log_firmware_debug_packet(hci_firmware_log_fd, packet);
+    if (sub_event_code == HCI_VSE_SUBCODE_DEBUG_INFO_SUB_EVT) {
+      if (hci_firmware_log_fd == INVALID_FD)
+        hci_firmware_log_fd = hci_open_firmware_log_file();
 
-    buffer_allocator->free(packet);
-    return true;
+      if (hci_firmware_log_fd != INVALID_FD)
+        hci_log_firmware_debug_packet(hci_firmware_log_fd, packet);
+
+      buffer_allocator->free(packet);
+      return true;
+    } else if (sub_event_code == HCI_VSE_SUBCODE_BQR_SUB_EVT) {
+      uint8_t bqr_report_id;
+      STREAM_TO_UINT8(bqr_report_id, stream);
+
+      if (bqr_report_id ==
+              bluetooth::bqr::QUALITY_REPORT_ID_ROOT_INFLAMMATION &&
+          packet->len >= bluetooth::bqr::kRootInflammationPacketMinSize) {
+        uint8_t error_code;
+        uint8_t vendor_error_code;
+        STREAM_TO_UINT8(error_code, stream);
+        STREAM_TO_UINT8(vendor_error_code, stream);
+        // TODO(ugoyu) Report to bluetooth metrics here
+
+        LOG(ERROR) << __func__
+                   << ": Root inflammation event! setting timer to restart.";
+        {
+          // Try to stop hci command and startup timers
+          std::unique_lock<std::recursive_timed_mutex> lock(
+              commands_pending_response_mutex, std::defer_lock);
+          if (lock.try_lock_for(std::chrono::milliseconds(
+                  COMMAND_PENDING_MUTEX_ACQUIRE_TIMEOUT_MS))) {
+            if (alarm_is_scheduled(startup_timer)) {
+              alarm_cancel(startup_timer);
+            }
+            if (alarm_is_scheduled(command_response_timer)) {
+              alarm_cancel(command_response_timer);
+            }
+          } else {
+            LOG(ERROR) << __func__ << ": Failed to obtain mutex";
+          }
+        }
+
+        // HwBinder thread post to hci_thread
+        if (!abort_timer.Schedule(hci_thread.GetWeakPtr(), FROM_HERE,
+                                  base::Bind(hci_root_inflamed_abort,
+                                             error_code, vendor_error_code),
+                                  base::TimeDelta::FromMilliseconds(
+                                      COMMAND_TIMEOUT_RESTART_MS))) {
+          LOG(ERROR) << "Failed to schedule abort_timer!";
+          hci_root_inflamed_abort(error_code, vendor_error_code);
+        }
+      }
+    }
   }
 
   return false;

diff --git a/hci/src/hci_layer_android.cc b/hci/src/hci_layer_android.cc
index c4aded1..d9708a1 100644 (file)
--- a/hci/src/hci_layer_android.cc
+++ b/hci/src/hci_layer_android.cc
@@ -54,6 +54,7 @@ extern void hci_event_received(const base::Location& from_here, BT_HDR* packet);
 extern void acl_event_received(BT_HDR* packet);
 extern void sco_data_received(BT_HDR* packet);
 extern void iso_data_received(BT_HDR* packet);
+extern void hal_service_died();
 
 android::sp<V1_0::IBluetoothHci> btHci;
 android::sp<V1_1::IBluetoothHci> btHci_1_1;
@@ -62,7 +63,7 @@ class BluetoothHciDeathRecipient : public hidl_death_recipient {
  public:
   virtual void serviceDied(uint64_t /*cookie*/, const android::wp<::android::hidl::base::V1_0::IBase>& /*who*/) {
     LOG_ERROR(LOG_TAG, "Bluetooth HAL service died!");
-    abort();
+    hal_service_died();
   }
 };
 android::sp<BluetoothHciDeathRecipient> bluetoothHciDeathRecipient = new BluetoothHciDeathRecipient();