[chromecast][BLE] Disconnect if operations timeout

Bug: internal b/112359125
Test: cast_bluetooth_unittests. BLE sanity check.
Change-Id: Ia0815f0251a276a8b0b01315eb4a1d588b3c7e69
Reviewed-on: https://chromium-review.googlesource.com/1171921
Commit-Queue: Bailey Forrest <bcf@chromium.org>
Reviewed-by: Stephen Lanham <slan@chromium.org>
Cr-Commit-Position: refs/heads/master@{#583118}

chromecast/device/bluetooth/le/gatt_client_manager_impl_test.cc

@@ -8,11 +8,12 @@
 #include "base/memory/ptr_util.h"
 #include "base/message_loop/message_loop.h"
 #include "base/test/mock_callback.h"
+#include "base/test/test_mock_time_task_runner.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "chromecast/device/bluetooth/bluetooth_util.h"
 #include "chromecast/device/bluetooth/le/remote_characteristic.h"
 #include "chromecast/device/bluetooth/le/remote_descriptor.h"
-#include "chromecast/device/bluetooth/le/remote_device.h"
+#include "chromecast/device/bluetooth/le/remote_device_impl.h"
 #include "chromecast/device/bluetooth/le/remote_service.h"
 #include "chromecast/device/bluetooth/shlib/mock_gatt_client.h"
 #include "testing/gmock/include/gmock/gmock.h"
@@ -109,8 +110,10 @@ std::vector<bluetooth_v2_shlib::Gatt::Service> GenerateServices() {
 class GattClientManagerTest : public ::testing::Test {
  public:
   void SetUp() override {
+    fake_task_runner_ = new base::TestMockTimeTaskRunner();
     message_loop_ =
         std::make_unique<base::MessageLoop>(base::MessageLoop::TYPE_DEFAULT);
+    message_loop_->SetTaskRunner(fake_task_runner_);
     gatt_client_ = std::make_unique<bluetooth_v2_shlib::MockGattClient>();
     gatt_client_manager_ =
         std::make_unique<GattClientManagerImpl>(gatt_client_.get());
@@ -118,7 +121,7 @@ class GattClientManagerTest : public ::testing::Test {
 
     // Normally bluetooth_manager does this.
     gatt_client_->SetDelegate(gatt_client_manager_.get());
-    gatt_client_manager_->Initialize(base::ThreadTaskRunnerHandle::Get());
+    gatt_client_manager_->Initialize(fake_task_runner_);
     gatt_client_manager_->AddObserver(observer_.get());
   }
 
@@ -126,6 +129,7 @@ class GattClientManagerTest : public ::testing::Test {
     gatt_client_->SetDelegate(nullptr);
     gatt_client_manager_->RemoveObserver(observer_.get());
     gatt_client_manager_->Finalize();
+    fake_task_runner_ = nullptr;
   }
 
   scoped_refptr<RemoteDevice> GetDevice(const bluetooth_v2_shlib::Addr& addr) {
@@ -177,6 +181,7 @@ class GattClientManagerTest : public ::testing::Test {
     ASSERT_TRUE(device->IsConnected());
   }
 
+  scoped_refptr<base::TestMockTimeTaskRunner> fake_task_runner_;
   base::MockCallback<RemoteDevice::StatusCallback> cb_;
   std::unique_ptr<base::MessageLoop> message_loop_;
   std::unique_ptr<GattClientManagerImpl> gatt_client_manager_;
@@ -237,7 +242,7 @@ TEST_F(GattClientManagerTest, RemoteDeviceConnect) {
   delegate->OnConnectChanged(kTestAddr1, true /* status */,
                              false /* connected */);
   EXPECT_FALSE(device->IsConnected());
-  base::RunLoop().RunUntilIdle();
+  fake_task_runner_->RunUntilIdle();
 }
 
 TEST_F(GattClientManagerTest, RemoteDeviceConnectConcurrent) {
@@ -368,7 +373,7 @@ TEST_F(GattClientManagerTest, RemoteDeviceRequestMtu) {
   EXPECT_CALL(*observer_, OnMtuChanged(device, kMtu));
   delegate->OnMtuChanged(kTestAddr1, true, kMtu);
   EXPECT_EQ(kMtu, device->GetMtu());
-  base::RunLoop().RunUntilIdle();
+  fake_task_runner_->RunUntilIdle();
 }
 
 TEST_F(GattClientManagerTest, RemoteDeviceConnectionParameterUpdate) {
@@ -492,7 +497,7 @@ TEST_F(GattClientManagerTest, RemoteDeviceCharacteristic) {
   EXPECT_CALL(*observer_,
               OnCharacteristicNotification(device, characteristic, kTestData3));
   delegate->OnNotification(kTestAddr1, characteristic->handle(), kTestData3);
-  base::RunLoop().RunUntilIdle();
+  fake_task_runner_->RunUntilIdle();
 }
 
 TEST_F(GattClientManagerTest,
@@ -536,7 +541,7 @@ TEST_F(GattClientManagerTest,
   EXPECT_CALL(*observer_,
               OnCharacteristicNotification(device, characteristic, kTestData1));
   delegate->OnNotification(kTestAddr1, characteristic->handle(), kTestData1);
-  base::RunLoop().RunUntilIdle();
+  fake_task_runner_->RunUntilIdle();
 }
 
 TEST_F(GattClientManagerTest, RemoteDeviceDescriptor) {
@@ -821,5 +826,49 @@ TEST_F(GattClientManagerTest, Queuing) {
   base::RunLoop().RunUntilIdle();
 }
 
+TEST_F(GattClientManagerTest, CommandTimeout) {
+  const std::vector<uint8_t> kTestData = {0x7, 0x8, 0x9};
+  const auto kServices = GenerateServices();
+  const auto kAuthReq = bluetooth_v2_shlib::Gatt::Client::AUTH_REQ_MITM;
+  const auto kWriteType = bluetooth_v2_shlib::Gatt::WRITE_TYPE_DEFAULT;
+
+  // Connect a device and get services.
+  Connect(kTestAddr1);
+  scoped_refptr<RemoteDevice> device = GetDevice(kTestAddr1);
+  bluetooth_v2_shlib::Gatt::Client::Delegate* delegate =
+      gatt_client_->delegate();
+  delegate->OnServicesAdded(kTestAddr1, kServices);
+  std::vector<scoped_refptr<RemoteService>> services =
+      GetServices(device.get());
+  ASSERT_EQ(kServices.size(), services.size());
+
+  auto service = services[0];
+  std::vector<scoped_refptr<RemoteCharacteristic>> characteristics =
+      service->GetCharacteristics();
+  ASSERT_GE(characteristics.size(), 1ul);
+  auto characteristic1 = characteristics[0];
+
+  // Issue a write to one characteristic.
+  EXPECT_CALL(*gatt_client_,
+              WriteCharacteristic(kTestAddr1, characteristic1->characteristic(),
+                                  kAuthReq, kWriteType, kTestData))
+      .WillOnce(Return(true));
+  characteristic1->WriteAuth(kAuthReq, kWriteType, kTestData, cb_.Get());
+
+  // Let the command timeout
+  base::TestMockTimeTaskRunner::ScopedContext context(fake_task_runner_);
+  // We should request a disconnect.
+  EXPECT_CALL(*gatt_client_, Disconnect(kTestAddr1)).WillOnce(Return(true));
+  fake_task_runner_->FastForwardBy(RemoteDeviceImpl::kCommandTimeout);
+
+  // Make sure we issued a disconnect.
+  testing::Mock::VerifyAndClearExpectations(gatt_client_.get());
+
+  // The operation should fail.
+  EXPECT_CALL(cb_, Run(false));
+  delegate->OnConnectChanged(kTestAddr1, true /* status */,
+                             false /* connected */);
+}
+
 }  // namespace bluetooth
 }  // namespace chromecast

chromecast/device/bluetooth/le/remote_device_impl.cc

@@ -6,6 +6,7 @@
 
 #include "base/bind.h"
 #include "chromecast/base/bind_to_task_runner.h"
+#include "chromecast/device/bluetooth/bluetooth_util.h"
 #include "chromecast/device/bluetooth/le/gatt_client_manager_impl.h"
 #include "chromecast/device/bluetooth/le/remote_characteristic_impl.h"
 #include "chromecast/device/bluetooth/le/remote_descriptor_impl.h"
@@ -50,6 +51,9 @@ namespace bluetooth {
     EXEC_CB_AND_RET(cb, ret);             \
   } while (0)
 
+// static
+constexpr base::TimeDelta RemoteDeviceImpl::kCommandTimeout;
+
 RemoteDeviceImpl::RemoteDeviceImpl(
     const bluetooth_v2_shlib::Addr& addr,
     base::WeakPtr<GattClientManagerImpl> gatt_client_manager,
@@ -150,7 +154,7 @@ void RemoteDeviceImpl::RequestMtu(int mtu, StatusCallback cb) {
   CHECK_CONNECTED(cb);
   mtu_callbacks_.push(std::move(cb));
   EnqueueOperation(
-      base::BindOnce(&RemoteDeviceImpl::RequestMtuImpl, this, mtu));
+      __func__, base::BindOnce(&RemoteDeviceImpl::RequestMtuImpl, this, mtu));
 }
 
 void RemoteDeviceImpl::ConnectionParameterUpdate(int min_interval,
@@ -216,8 +220,9 @@ void RemoteDeviceImpl::ReadCharacteristic(
   handle_to_characteristic_read_cbs_[characteristic->handle()].push(
       std::move(cb));
 
-  EnqueueOperation(base::BindOnce(&RemoteDeviceImpl::ReadCharacteristicImpl,
-                                  this, std::move(characteristic), auth_req));
+  EnqueueOperation(
+      __func__, base::BindOnce(&RemoteDeviceImpl::ReadCharacteristicImpl, this,
+                               std::move(characteristic), auth_req));
 }
 
 void RemoteDeviceImpl::WriteCharacteristic(
@@ -229,9 +234,10 @@ void RemoteDeviceImpl::WriteCharacteristic(
   DCHECK(io_task_runner_->BelongsToCurrentThread());
   handle_to_characteristic_write_cbs_[characteristic->handle()].push(
       std::move(cb));
-  EnqueueOperation(base::BindOnce(&RemoteDeviceImpl::WriteCharacteristicImpl,
-                                  this, std::move(characteristic), auth_req,
-                                  write_type, std::move(value)));
+  EnqueueOperation(
+      __func__, base::BindOnce(&RemoteDeviceImpl::WriteCharacteristicImpl, this,
+                               std::move(characteristic), auth_req, write_type,
+                               std::move(value)));
 }
 
 void RemoteDeviceImpl::ReadDescriptor(
@@ -241,7 +247,8 @@ void RemoteDeviceImpl::ReadDescriptor(
   DCHECK(io_task_runner_->BelongsToCurrentThread());
   handle_to_descriptor_read_cbs_[descriptor->handle()].push(std::move(cb));
 
-  EnqueueOperation(base::BindOnce(&RemoteDeviceImpl::ReadDescriptorImpl, this,
+  EnqueueOperation(__func__,
+                   base::BindOnce(&RemoteDeviceImpl::ReadDescriptorImpl, this,
                                   std::move(descriptor), auth_req));
 }
 
@@ -252,9 +259,10 @@ void RemoteDeviceImpl::WriteDescriptor(
     RemoteDescriptor::StatusCallback cb) {
   DCHECK(io_task_runner_->BelongsToCurrentThread());
   handle_to_descriptor_write_cbs_[descriptor->handle()].push(std::move(cb));
-  EnqueueOperation(base::BindOnce(&RemoteDeviceImpl::WriteDescriptorImpl, this,
-                                  std::move(descriptor), auth_req,
-                                  std::move(value)));
+  EnqueueOperation(
+      __func__,
+      base::BindOnce(&RemoteDeviceImpl::WriteDescriptorImpl, this,
+                     std::move(descriptor), auth_req, std::move(value)));
 }
 
 scoped_refptr<RemoteService> RemoteDeviceImpl::GetServiceByUuidSync(
@@ -454,14 +462,15 @@ void RemoteDeviceImpl::ConnectComplete(bool success) {
   }
 }
 
-void RemoteDeviceImpl::EnqueueOperation(base::OnceClosure op) {
+void RemoteDeviceImpl::EnqueueOperation(const std::string& name,
+                                        base::OnceClosure op) {
   DCHECK(io_task_runner_->BelongsToCurrentThread());
-  command_queue_.push_back(std::move(op));
+  command_queue_.emplace_back(name, std::move(op));
 
   // Run the operation if this is the only operation in the queue. Otherwise, it
   // will be executed when the current operation completes.
   if (command_queue_.size() == 1) {
-    std::move(command_queue_.front()).Run();
+    RunNextOperation();
   }
 }
 
@@ -469,13 +478,25 @@ void RemoteDeviceImpl::NotifyQueueOperationComplete() {
   DCHECK(io_task_runner_->BelongsToCurrentThread());
   DCHECK(!command_queue_.empty());
   command_queue_.pop_front();
+  command_timeout_timer_.Stop();
 
   // Run the next operation if there is one in the queue.
   if (!command_queue_.empty()) {
-    std::move(command_queue_.front()).Run();
+    RunNextOperation();
   }
 }
 
+void RemoteDeviceImpl::RunNextOperation() {
+  DCHECK(io_task_runner_->BelongsToCurrentThread());
+  DCHECK(!command_queue_.empty());
+  auto& front = command_queue_.front();
+  command_timeout_timer_.Start(
+      FROM_HERE, kCommandTimeout,
+      base::BindRepeating(&RemoteDeviceImpl::OnCommandTimeout, this,
+                          front.first));
+  std::move(front.second).Run();
+}
+
 void RemoteDeviceImpl::RequestMtuImpl(int mtu) {
   DCHECK(io_task_runner_->BelongsToCurrentThread());
   if (gatt_client_manager_->gatt_client()->RequestMtu(addr_, mtu)) {
@@ -573,6 +594,7 @@ void RemoteDeviceImpl::ClearServices() {
   uuid_to_service_.clear();
   handle_to_characteristic_.clear();
   command_queue_.clear();
+  command_timeout_timer_.Stop();
 
   while (!mtu_callbacks_.empty()) {
     LOG(ERROR) << "RequestMtu failed: disconnected";
@@ -621,5 +643,16 @@ void RemoteDeviceImpl::ClearServices() {
   handle_to_descriptor_write_cbs_.clear();
 }
 
+void RemoteDeviceImpl::OnCommandTimeout(const std::string& name) {
+  DCHECK(io_task_runner_->BelongsToCurrentThread());
+  // Get the last byte because whole address is PII.
+  std::string addr_str = util::AddrToString(addr_);
+  addr_str = addr_str.substr(addr_str.size() - 2);
+
+  LOG(ERROR) << name << "(" << addr_str << ")"
+             << " timed out. Disconnecting";
+  Disconnect(base::DoNothing());
+}
+
 }  // namespace bluetooth
 }  // namespace chromecast

chromecast/device/bluetooth/le/remote_device_impl.h

@@ -9,11 +9,14 @@
 #include <deque>
 #include <map>
 #include <queue>
+#include <string>
+#include <utility>
 #include <vector>
 
 #include "base/memory/weak_ptr.h"
 #include "base/single_thread_task_runner.h"
 #include "base/threading/thread_checker.h"
+#include "base/timer/timer.h"
 #include "chromecast/device/bluetooth/le/remote_characteristic.h"
 #include "chromecast/device/bluetooth/le/remote_descriptor.h"
 #include "chromecast/device/bluetooth/le/remote_device.h"
@@ -27,6 +30,11 @@ class RemoteDescriptorImpl;
 
 class RemoteDeviceImpl : public RemoteDevice {
  public:
+  // If commands take longer than this amount of time, we will disconnect the
+  // device.
+  static constexpr base::TimeDelta kCommandTimeout =
+      base::TimeDelta::FromSeconds(30);
+
   // RemoteDevice implementation
   void Connect(StatusCallback cb) override;
   bool ConnectSync() override;
@@ -106,11 +114,14 @@ class RemoteDeviceImpl : public RemoteDevice {
 
   // Add an operation to the queue. Certain operations can only be executed
   // serially.
-  void EnqueueOperation(base::OnceClosure op);
+  void EnqueueOperation(const std::string& name, base::OnceClosure op);
 
   // Notify that the currently queued operation has completed.
   void NotifyQueueOperationComplete();
 
+  // Run the next queued operation.
+  void RunNextOperation();
+
   void RequestMtuImpl(int mtu);
   void ReadCharacteristicImpl(
       scoped_refptr<RemoteCharacteristicImpl> descriptor,
@@ -127,6 +138,8 @@ class RemoteDeviceImpl : public RemoteDevice {
                            std::vector<uint8_t> value);
   void ClearServices();
 
+  void OnCommandTimeout(const std::string& command_name);
+
   const base::WeakPtr<GattClientManagerImpl> gatt_client_manager_;
   const bluetooth_v2_shlib::Addr addr_;
 
@@ -152,7 +165,12 @@ class RemoteDeviceImpl : public RemoteDevice {
   std::map<uint16_t, scoped_refptr<RemoteCharacteristicImpl>>
       handle_to_characteristic_;
 
-  std::deque<base::OnceClosure> command_queue_;
+  // Timer for commands on |command_queue_|. If any command times out, we will
+  // force disconnect of this device.
+  base::OneShotTimer command_timeout_timer_;
+
+  // Queue of operation name and the operation itself.
+  std::deque<std::pair<std::string, base::OnceClosure>> command_queue_;
   std::queue<StatusCallback> mtu_callbacks_;
   std::map<uint16_t, std::queue<RemoteCharacteristic::ReadCallback>>
       handle_to_characteristic_read_cbs_;