[CrOS PhoneHub] Wait for disconnection event before invoking callback

Previously, we'd just call DisconnectFromEndpoint() and invoke the
callback immediately. This CL adds a "disconnecting" state which waits
for the OnDisconnected() callback to be called. This works around a race
condition in the Nearby Connections library during shutdown.

Because we're now waiting for an event to be called, this CL also adds
timeouts for each step of this flow.

This CL also tweaks the log level for a few logs to help with
debugging.

Bug: 1152609
Change-Id: Ib23c606e4658f5ad1f5fbf013891d80888683530
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2561469Reviewed-by: James Vecore <vecore@google.com>
Commit-Queue: Kyle Horimoto <khorimoto@chromium.org>
Cr-Commit-Position: refs/heads/master@{#831160}

chrome/browser/chromeos/secure_channel/fake_nearby_connection_broker.h

@@ -21,7 +21,7 @@ class FakeNearbyConnectionBroker : public NearbyConnectionBroker {
   ~FakeNearbyConnectionBroker() override;
 
   using NearbyConnectionBroker::bluetooth_public_address;
-  using NearbyConnectionBroker::Disconnect;
+  using NearbyConnectionBroker::InvokeDisconnectedCallback;
   using NearbyConnectionBroker::NotifyConnected;
   using NearbyConnectionBroker::NotifyMessageReceived;
 

chrome/browser/chromeos/secure_channel/nearby_connection_broker.cc

@@ -6,6 +6,8 @@
 
 #include "base/bind.h"
 #include "base/check.h"
+#include "base/threading/thread_task_runner_handle.h"
+#include "base/time/time.h"
 
 namespace chromeos {
 namespace secure_channel {
@@ -22,19 +24,17 @@ NearbyConnectionBroker::NearbyConnectionBroker(
       on_connected_callback_(std::move(on_connected_callback)),
       on_disconnected_callback_(std::move(on_disconnected_callback)) {
   message_sender_receiver_.set_disconnect_handler(base::BindOnce(
-      &NearbyConnectionBroker::Disconnect, base::Unretained(this)));
+      &NearbyConnectionBroker::OnMojoDisconnection, base::Unretained(this)));
   message_receiver_remote_.set_disconnect_handler(base::BindOnce(
-      &NearbyConnectionBroker::Disconnect, base::Unretained(this)));
+      &NearbyConnectionBroker::OnMojoDisconnection, base::Unretained(this)));
 }
 
 NearbyConnectionBroker::~NearbyConnectionBroker() = default;
 
-void NearbyConnectionBroker::Disconnect() {
+void NearbyConnectionBroker::InvokeDisconnectedCallback() {
   message_sender_receiver_.reset();
   message_receiver_remote_.reset();
-
-  if (on_disconnected_callback_)
-    std::move(on_disconnected_callback_).Run();
+  std::move(on_disconnected_callback_).Run();
 }
 
 void NearbyConnectionBroker::NotifyConnected() {

chrome/browser/chromeos/secure_channel/nearby_connection_broker.h

@@ -42,7 +42,11 @@ class NearbyConnectionBroker : public mojom::NearbyMessageSender {
     return bluetooth_public_address_;
   }
 
-  void Disconnect();
+  // Can be overridden by derived classes to handle MessageSender and
+  // MessageReceiver Mojo pipes being disconnected.
+  virtual void OnMojoDisconnection() {}
+
+  void InvokeDisconnectedCallback();
   void NotifyConnected();
   void NotifyMessageReceived(const std::string& received_message);
 

chrome/browser/chromeos/secure_channel/nearby_connection_broker_impl.cc

@@ -15,6 +15,9 @@ namespace {
 
 NearbyConnectionBrokerImpl::Factory* g_test_factory = nullptr;
 
+constexpr base::TimeDelta kConnectionStatusChangeTimeout =
+    base::TimeDelta::FromSeconds(10);
+
 using location::nearby::connections::mojom::BytesPayload;
 using location::nearby::connections::mojom::ConnectionInfoPtr;
 using location::nearby::connections::mojom::ConnectionOptions;
@@ -28,14 +31,6 @@ using location::nearby::connections::mojom::PayloadPtr;
 using location::nearby::connections::mojom::PayloadTransferUpdatePtr;
 using location::nearby::connections::mojom::Status;
 
-void OnDisconnectFromEndpointResult(const std::string& endpoint_id,
-                                    Status status) {
-  if (status != Status::kSuccess) {
-    PA_LOG(WARNING) << "Failed to disconnect from endpoint with ID "
-                    << endpoint_id;
-  }
-}
-
 }  // namespace
 
 // static
@@ -47,20 +42,21 @@ NearbyConnectionBrokerImpl::Factory::Create(
     mojo::PendingRemote<mojom::NearbyMessageReceiver> message_receiver_remote,
     const mojo::SharedRemote<NearbyConnections>& nearby_connections,
     base::OnceClosure on_connected_callback,
-    base::OnceClosure on_disconnected_callback) {
+    base::OnceClosure on_disconnected_callback,
+    std::unique_ptr<base::OneShotTimer> timer) {
   if (g_test_factory) {
     return g_test_factory->CreateInstance(
         bluetooth_public_address, endpoint_finder,
         std::move(message_sender_receiver), std::move(message_receiver_remote),
         nearby_connections, std::move(on_connected_callback),
-        std::move(on_disconnected_callback));
+        std::move(on_disconnected_callback), std::move(timer));
   }
 
   return base::WrapUnique(new NearbyConnectionBrokerImpl(
       bluetooth_public_address, endpoint_finder,
       std::move(message_sender_receiver), std::move(message_receiver_remote),
       nearby_connections, std::move(on_connected_callback),
-      std::move(on_disconnected_callback)));
+      std::move(on_disconnected_callback), std::move(timer)));
 }
 
 // static
@@ -76,14 +72,16 @@ NearbyConnectionBrokerImpl::NearbyConnectionBrokerImpl(
     mojo::PendingRemote<mojom::NearbyMessageReceiver> message_receiver_remote,
     const mojo::SharedRemote<NearbyConnections>& nearby_connections,
     base::OnceClosure on_connected_callback,
-    base::OnceClosure on_disconnected_callback)
+    base::OnceClosure on_disconnected_callback,
+    std::unique_ptr<base::OneShotTimer> timer)
     : NearbyConnectionBroker(bluetooth_public_address,
                              std::move(message_sender_receiver),
                              std::move(message_receiver_remote),
                              std::move(on_connected_callback),
                              std::move(on_disconnected_callback)),
       endpoint_finder_(endpoint_finder),
-      nearby_connections_(nearby_connections) {
+      nearby_connections_(nearby_connections),
+      timer_(std::move(timer)) {
   TransitionToStatus(ConnectionStatus::kDiscoveringEndpoint);
   endpoint_finder_->FindEndpoint(
       bluetooth_public_address,
@@ -93,27 +91,55 @@ NearbyConnectionBrokerImpl::NearbyConnectionBrokerImpl(
                      base::Unretained(this)));
 }
 
-NearbyConnectionBrokerImpl::~NearbyConnectionBrokerImpl() {
-  if (is_connection_active_) {
-    DCHECK(!remote_endpoint_id_.empty());
-    PA_LOG(VERBOSE) << "Disconnecting from endpoint with ID "
-                    << remote_endpoint_id_;
-    nearby_connections_->DisconnectFromEndpoint(
-        mojom::kServiceId, remote_endpoint_id_,
-        base::BindOnce(&OnDisconnectFromEndpointResult, remote_endpoint_id_));
-  }
-}
+NearbyConnectionBrokerImpl::~NearbyConnectionBrokerImpl() = default;
 
 void NearbyConnectionBrokerImpl::TransitionToStatus(
     ConnectionStatus connection_status) {
-  PA_LOG(VERBOSE) << "Nearby Connection status: " << connection_status_
-                  << " => " << connection_status;
+  PA_LOG(INFO) << "Nearby Connection status: " << connection_status_ << " => "
+               << connection_status;
   connection_status_ = connection_status;
+
+  timer_->Stop();
+
+  // The connected and disconnected states do not expect any further state
+  // changes.
+  if (connection_status_ == ConnectionStatus::kConnected ||
+      connection_status_ == ConnectionStatus::kDisconnected) {
+    return;
+  }
+
+  // If the state does not change within |kConnectionStatusChangeTimeout|, time
+  // out and give up on the connection.
+  timer_->Start(
+      FROM_HERE, kConnectionStatusChangeTimeout,
+      base::BindOnce(
+          &NearbyConnectionBrokerImpl::OnConnectionStatusChangeTimeout,
+          weak_ptr_factory_.GetWeakPtr()));
 }
 
-void NearbyConnectionBrokerImpl::TransitionToDisconnected() {
+void NearbyConnectionBrokerImpl::Disconnect() {
+  if (!need_to_disconnect_endpoint_) {
+    TransitionToDisconnectedAndInvokeCallback();
+    return;
+  }
+
+  if (connection_status_ == ConnectionStatus::kDisconnecting)
+    return;
+
+  TransitionToStatus(ConnectionStatus::kDisconnecting);
+  nearby_connections_->DisconnectFromEndpoint(
+      mojom::kServiceId, remote_endpoint_id_,
+      base::BindOnce(
+          &NearbyConnectionBrokerImpl::OnDisconnectFromEndpointResult,
+          weak_ptr_factory_.GetWeakPtr()));
+}
+
+void NearbyConnectionBrokerImpl::TransitionToDisconnectedAndInvokeCallback() {
+  if (connection_status_ == ConnectionStatus::kDisconnected)
+    return;
+
   TransitionToStatus(ConnectionStatus::kDisconnected);
-  Disconnect();
+  InvokeDisconnectedCallback();
 }
 
 void NearbyConnectionBrokerImpl::OnEndpointDiscovered(
@@ -139,7 +165,7 @@ void NearbyConnectionBrokerImpl::OnEndpointDiscovered(
 
 void NearbyConnectionBrokerImpl::OnDiscoveryFailure() {
   DCHECK_EQ(ConnectionStatus::kDiscoveringEndpoint, connection_status_);
-  TransitionToDisconnected();
+  Disconnect();
 }
 
 void NearbyConnectionBrokerImpl::OnRequestConnectionResult(Status status) {
@@ -149,7 +175,7 @@ void NearbyConnectionBrokerImpl::OnRequestConnectionResult(Status status) {
     return;
 
   PA_LOG(WARNING) << "RequestConnection() failed: " << status;
-  TransitionToDisconnected();
+  Disconnect();
 }
 
 void NearbyConnectionBrokerImpl::OnAcceptConnectionResult(Status status) {
@@ -161,7 +187,7 @@ void NearbyConnectionBrokerImpl::OnAcceptConnectionResult(Status status) {
   }
 
   PA_LOG(WARNING) << "AcceptConnection() failed: " << status;
-  TransitionToDisconnected();
+  Disconnect();
 }
 
 void NearbyConnectionBrokerImpl::OnSendPayloadResult(
@@ -174,7 +200,40 @@ void NearbyConnectionBrokerImpl::OnSendPayloadResult(
     return;
 
   PA_LOG(WARNING) << "OnSendPayloadResult() failed: " << status;
-  TransitionToDisconnected();
+  Disconnect();
+}
+
+void NearbyConnectionBrokerImpl::OnDisconnectFromEndpointResult(Status status) {
+  // If the disconnection was successful, wait for the OnDisconnected()
+  // callback.
+  if (status == Status::kSuccess)
+    return;
+
+  PA_LOG(WARNING) << "Failed to disconnect from endpoint with ID "
+                  << remote_endpoint_id_ << ": " << status;
+  need_to_disconnect_endpoint_ = false;
+  Disconnect();
+}
+
+void NearbyConnectionBrokerImpl::OnConnectionStatusChangeTimeout() {
+  if (connection_status_ == ConnectionStatus::kDisconnecting) {
+    PA_LOG(WARNING) << "Timeout disconnecting from endpoint";
+    TransitionToDisconnectedAndInvokeCallback();
+    return;
+  }
+
+  // If there is a timeout requesting a connection, we should still try to
+  // disconnect from the endpoint in case the endpoint was almost about to be
+  // connected before the timeout occurred.
+  if (connection_status_ == ConnectionStatus::kRequestingConnection)
+    need_to_disconnect_endpoint_ = true;
+
+  PA_LOG(WARNING) << "Timeout changing connection status";
+  Disconnect();
+}
+
+void NearbyConnectionBrokerImpl::OnMojoDisconnection() {
+  Disconnect();
 }
 
 void NearbyConnectionBrokerImpl::SendMessage(const std::string& message,
@@ -214,7 +273,7 @@ void NearbyConnectionBrokerImpl::OnConnectionInitiated(
 
   DCHECK_EQ(ConnectionStatus::kRequestingConnection, connection_status_);
   TransitionToStatus(ConnectionStatus::kAcceptingConnection);
-  is_connection_active_ = true;
+  need_to_disconnect_endpoint_ = true;
 
   nearby_connections_->AcceptConnection(
       mojom::kServiceId, remote_endpoint_id_,
@@ -248,7 +307,7 @@ void NearbyConnectionBrokerImpl::OnConnectionRejected(
   }
 
   PA_LOG(WARNING) << "Connection rejected: " << status;
-  TransitionToDisconnected();
+  Disconnect();
 }
 
 void NearbyConnectionBrokerImpl::OnDisconnected(
@@ -259,9 +318,11 @@ void NearbyConnectionBrokerImpl::OnDisconnected(
     return;
   }
 
-  PA_LOG(WARNING) << "Connection disconnected";
-  is_connection_active_ = false;
-  TransitionToDisconnected();
+  if (connection_status_ != ConnectionStatus::kDisconnecting) {
+    PA_LOG(WARNING) << "Connection disconnected unexpectedly";
+  }
+  need_to_disconnect_endpoint_ = false;
+  Disconnect();
 }
 
 void NearbyConnectionBrokerImpl::OnBandwidthChanged(
@@ -273,7 +334,7 @@ void NearbyConnectionBrokerImpl::OnBandwidthChanged(
     return;
   }
 
-  PA_LOG(VERBOSE) << "Bandwidth changed: " << medium;
+  PA_LOG(INFO) << "Bandwidth changed: " << medium;
 }
 
 void NearbyConnectionBrokerImpl::OnPayloadReceived(
@@ -288,7 +349,7 @@ void NearbyConnectionBrokerImpl::OnPayloadReceived(
   if (!payload->content->is_bytes()) {
     PA_LOG(WARNING) << "OnPayloadReceived(): Received unexpected payload type "
                     << "(was expecting bytes type). Disconnecting.";
-    TransitionToDisconnected();
+    Disconnect();
     return;
   }
 
@@ -322,6 +383,9 @@ std::ostream& operator<<(std::ostream& stream,
     case NearbyConnectionBrokerImpl::ConnectionStatus::kConnected:
       stream << "[Connected]";
       break;
+    case NearbyConnectionBrokerImpl::ConnectionStatus::kDisconnecting:
+      stream << "[Disconnecting]";
+      break;
     case NearbyConnectionBrokerImpl::ConnectionStatus::kDisconnected:
       stream << "[Disconnected]";
       break;

chrome/browser/chromeos/secure_channel/nearby_connection_broker_impl.h

@@ -8,7 +8,9 @@
 #include <memory>
 #include <ostream>
 
+#include "base/memory/ref_counted.h"
 #include "base/memory/weak_ptr.h"
+#include "base/timer/timer.h"
 #include "chrome/browser/chromeos/secure_channel/nearby_connection_broker.h"
 #include "chromeos/services/nearby/public/mojom/nearby_connections.mojom.h"
 #include "mojo/public/cpp/bindings/shared_remote.h"
@@ -28,8 +30,6 @@ class NearbyEndpointFinder;
 //
 // Deleting an instance of this class tears down any active connection and
 // performs cleanup if necessary.
-//
-// TODO(khorimoto): Add the ability to upgrade bandwidth to WebRTC.
 class NearbyConnectionBrokerImpl
     : public NearbyConnectionBroker,
       public location::nearby::connections::mojom::ConnectionLifecycleListener,
@@ -48,7 +48,9 @@ class NearbyConnectionBrokerImpl
             location::nearby::connections::mojom::NearbyConnections>&
             nearby_connections,
         base::OnceClosure on_connected_callback,
-        base::OnceClosure on_disconnected_callback);
+        base::OnceClosure on_disconnected_callback,
+        std::unique_ptr<base::OneShotTimer> timer =
+            std::make_unique<base::OneShotTimer>());
     static void SetFactoryForTesting(Factory* test_factory);
 
     virtual ~Factory() = default;
@@ -65,7 +67,8 @@ class NearbyConnectionBrokerImpl
             location::nearby::connections::mojom::NearbyConnections>&
             nearby_connections,
         base::OnceClosure on_connected_callback,
-        base::OnceClosure on_disconnected_callback) = 0;
+        base::OnceClosure on_disconnected_callback,
+        std::unique_ptr<base::OneShotTimer> timer) = 0;
   };
 
   ~NearbyConnectionBrokerImpl() override;
@@ -78,6 +81,7 @@ class NearbyConnectionBrokerImpl
     kAcceptingConnection,
     kWaitingForConnectionToBeAcceptedByRemoteDevice,
     kConnected,
+    kDisconnecting,
     kDisconnected,
   };
   friend std::ostream& operator<<(
@@ -93,10 +97,12 @@ class NearbyConnectionBrokerImpl
           location::nearby::connections::mojom::NearbyConnections>&
           nearby_connections,
       base::OnceClosure on_connected_callback,
-      base::OnceClosure on_disconnected_callback);
+      base::OnceClosure on_disconnected_callback,
+      std::unique_ptr<base::OneShotTimer> timer);
 
   void TransitionToStatus(ConnectionStatus connection_status);
-  void TransitionToDisconnected();
+  void Disconnect();
+  void TransitionToDisconnectedAndInvokeCallback();
 
   void OnEndpointDiscovered(
       const std::string& endpoint_id,
@@ -109,6 +115,12 @@ class NearbyConnectionBrokerImpl
       location::nearby::connections::mojom::Status status);
   void OnSendPayloadResult(SendMessageCallback callback,
                            location::nearby::connections::mojom::Status status);
+  void OnDisconnectFromEndpointResult(
+      location::nearby::connections::mojom::Status status);
+  void OnConnectionStatusChangeTimeout();
+
+  // NearbyConnectionBroker:
+  void OnMojoDisconnection() override;
 
   // mojom::NearbyMessageSender:
   void SendMessage(const std::string& message,
@@ -141,6 +153,7 @@ class NearbyConnectionBrokerImpl
   NearbyEndpointFinder* endpoint_finder_;
   mojo::SharedRemote<location::nearby::connections::mojom::NearbyConnections>
       nearby_connections_;
+  std::unique_ptr<base::OneShotTimer> timer_;
 
   mojo::Receiver<
       location::nearby::connections::mojom::ConnectionLifecycleListener>
@@ -155,7 +168,7 @@ class NearbyConnectionBrokerImpl
 
   // Starts as false; set to true in OnConnectionInitiated() and back to false
   // in OnDisconnected().
-  bool is_connection_active_ = false;
+  bool need_to_disconnect_endpoint_ = false;
 
   base::WeakPtrFactory<NearbyConnectionBrokerImpl> weak_ptr_factory_{this};
 };

chrome/browser/chromeos/secure_channel/nearby_connector_impl_unittest.cc

@@ -63,7 +63,8 @@ class FakeConnectionBrokerFactory : public NearbyConnectionBrokerImpl::Factory {
           location::nearby::connections::mojom::NearbyConnections>&
           nearby_connections,
       base::OnceClosure on_connected_callback,
-      base::OnceClosure on_disconnected_callback) override {
+      base::OnceClosure on_disconnected_callback,
+      std::unique_ptr<base::OneShotTimer> timer) override {
     auto instance = std::make_unique<FakeNearbyConnectionBroker>(
         bluetooth_public_address, std::move(message_sender_receiver),
         std::move(message_receiver_remote), std::move(on_connected_callback),
@@ -204,7 +205,7 @@ TEST_F(NearbyConnectorImplTest, ConnectAndTransferMessages) {
   // Disconnect.
   base::RunLoop disconnect_run_loop;
   receiver.SetMojoDisconnectHandler(disconnect_run_loop.QuitClosure());
-  broker->Disconnect();
+  broker->InvokeDisconnectedCallback();
   disconnect_run_loop.Run();
   EXPECT_EQ(0u, fake_nearby_process_manager_.GetNumActiveReferences());
 }
@@ -246,14 +247,14 @@ TEST_F(NearbyConnectorImplTest, TwoConnections) {
   // there is still an active connection.
   base::RunLoop disconnect_run_loop1;
   receiver1.SetMojoDisconnectHandler(disconnect_run_loop1.QuitClosure());
-  broker1->Disconnect();
+  broker1->InvokeDisconnectedCallback();
   disconnect_run_loop1.Run();
   EXPECT_EQ(1u, fake_nearby_process_manager_.GetNumActiveReferences());
 
   // Disconnect connection 2. The process reference should have been released.
   base::RunLoop disconnect_run_loop2;
   receiver2.SetMojoDisconnectHandler(disconnect_run_loop2.QuitClosure());
-  broker2->Disconnect();
+  broker2->InvokeDisconnectedCallback();
   disconnect_run_loop2.Run();
   EXPECT_EQ(0u, fake_nearby_process_manager_.GetNumActiveReferences());
 }
@@ -271,7 +272,7 @@ TEST_F(NearbyConnectorImplTest, FailToConnect) {
   on_connect_ = connect_run_loop.QuitClosure();
   base::RunLoop disconnect_run_loop;
   receiver.SetMojoDisconnectHandler(disconnect_run_loop.QuitClosure());
-  broker->Disconnect();
+  broker->InvokeDisconnectedCallback();
   connect_run_loop.Run();
   disconnect_run_loop.Run();