HCI: Send Debug packet when HCI timeout

Bug: 183061492
Test: cert/run
      atest bluetooth_test_gd
Tag: #gd-refactor
Change-Id: I6b35e11dd802138469b0024611113eb822b08637

diff --git a/gd/hci/hci_layer.cc b/gd/hci/hci_layer.cc
index 8fea49a..a6474b1 100644 (file)
--- a/gd/hci/hci_layer.cc
+++ b/gd/hci/hci_layer.cc
@@ -49,8 +49,8 @@ static void fail_if_reset_complete_not_success(CommandCompleteView complete) {
   ASSERT(reset_complete.GetStatus() == ErrorCode::SUCCESS);
 }
 
-static void on_hci_timeout(OpCode op_code) {
-  ASSERT_LOG(false, "Timed out waiting for 0x%02hx (%s)", op_code, OpCodeText(op_code).c_str());
+static void abort_after_time_out(OpCode op_code) {
+  ASSERT_LOG(false, "Done waiting for debug information after HCI timeout (%s)", OpCodeText(op_code).c_str());
 }
 
 class CommandQueueEntry {
@@ -87,12 +87,14 @@ class CommandQueueEntry {
 struct HciLayer::impl {
   impl(hal::HciHal* hal, HciLayer& module) : hal_(hal), module_(module) {
     hci_timeout_alarm_ = new Alarm(module.GetHandler());
+    hci_abort_alarm_ = new Alarm(module.GetHandler());
   }
 
   ~impl() {
     incoming_acl_buffer_.Clear();
     incoming_iso_buffer_.Clear();
     delete hci_timeout_alarm_;
+    delete hci_abort_alarm_;
     command_queue_.clear();
   }
 
@@ -167,6 +169,21 @@ struct HciLayer::impl {
     send_next_command();
   }
 
+  void on_hci_timeout(OpCode op_code) {
+    LOG_ERROR("Timed out waiting for 0x%02hx (%s)", op_code, OpCodeText(op_code).c_str());
+
+    LOG_ERROR("Flushing %zd waiting commands", command_queue_.size());
+    // Clear any waiting commands (there is an abort coming anyway)
+    command_queue_.clear();
+    command_credits_ = 1;
+    waiting_command_ = OpCode::NONE;
+    enqueue_command(
+        ControllerDebugInfoBuilder::Create(), module_.GetHandler()->BindOnce(&fail_if_reset_complete_not_success));
+    // Don't time out for this one;
+    hci_timeout_alarm_->Cancel();
+    hci_abort_alarm_->Schedule(BindOnce(&abort_after_time_out, op_code), kHciTimeoutRestartMs);
+  }
+
   void send_next_command() {
     if (command_credits_ == 0) {
       return;
@@ -187,7 +204,7 @@ struct HciLayer::impl {
     OpCode op_code = cmd_view.GetOpCode();
     waiting_command_ = op_code;
     command_credits_ = 0;  // Only allow one outstanding command
-    hci_timeout_alarm_->Schedule(BindOnce(&on_hci_timeout, op_code), kHciTimeoutMs);
+    hci_timeout_alarm_->Schedule(BindOnce(&impl::on_hci_timeout, common::Unretained(this), op_code), kHciTimeoutMs);
   }
 
   void register_event(EventCode event, ContextualCallback<void(EventView)> handler) {
@@ -291,6 +308,7 @@ struct HciLayer::impl {
   OpCode waiting_command_{OpCode::NONE};
   uint8_t command_credits_{1};  // Send reset first
   Alarm* hci_timeout_alarm_{nullptr};
+  Alarm* hci_abort_alarm_{nullptr};
 
   // Acl packets
   BidiQueue<AclView, AclBuilder> acl_queue_{3 /* TODO: Set queue depth */};

diff --git a/gd/hci/hci_layer.h b/gd/hci/hci_layer.h
index 4db0c19..895bb6c 100644 (file)
--- a/gd/hci/hci_layer.h
+++ b/gd/hci/hci_layer.h
@@ -100,6 +100,7 @@ class HciLayer : public Module, public CommandInterface<CommandBuilder> {
   }
 
   static constexpr std::chrono::milliseconds kHciTimeoutMs = std::chrono::milliseconds(2000);
+  static constexpr std::chrono::milliseconds kHciTimeoutRestartMs = std::chrono::milliseconds(5000);
 
   static const ModuleFactory Factory;
 

diff --git a/gd/hci/hci_layer_test.cc b/gd/hci/hci_layer_test.cc
index 7ea31e4..83db622 100644 (file)
--- a/gd/hci/hci_layer_test.cc
+++ b/gd/hci/hci_layer_test.cc
@@ -545,6 +545,26 @@ TEST_F(HciTest, vendorSpecificEventUnknown) {
   ASSERT_NE(event_status, std::future_status::ready);
 }
 
+TEST_F(HciTest, hciTimeOut) {
+  auto event_future = upper->GetReceivedEventFuture();
+  auto reset_command_future = hal->GetSentCommandFuture();
+  upper->SendHciCommandExpectingComplete(ResetBuilder::Create());
+  auto reset_command_sent_status = reset_command_future.wait_for(kTimeout);
+  ASSERT_EQ(reset_command_sent_status, std::future_status::ready);
+  auto reset = hal->GetSentCommand();
+  ASSERT_TRUE(reset.IsValid());
+  ASSERT_EQ(reset.GetOpCode(), OpCode::RESET);
+
+  auto debug_command_future = hal->GetSentCommandFuture();
+  auto event_status = event_future.wait_for(HciLayer::kHciTimeoutMs);
+  ASSERT_NE(event_status, std::future_status::ready);
+  auto debug_command_sent_status = debug_command_future.wait_for(kTimeout);
+  ASSERT_EQ(debug_command_sent_status, std::future_status::ready);
+  auto debug = hal->GetSentCommand();
+  ASSERT_TRUE(debug.IsValid());
+  ASSERT_EQ(debug.GetOpCode(), OpCode::CONTROLLER_DEBUG_INFO);
+}
+
 TEST_F(HciTest, noOpCredits) {
   ASSERT_EQ(0, hal->GetNumSentCommands());