From 5ed0903d6e742e8487d7fd3c4eb5df3c28a34f03 Mon Sep 17 00:00:00 2001 From: Edwin Wu Date: Mon, 14 Jun 2021 23:19:51 -0700 Subject: [PATCH] Internal change PiperOrigin-RevId: 379422825 --- cpp/core/internal/base_pcp_handler.cc | 353 ++++--- cpp/core/internal/p2p_cluster_pcp_handler.cc | 873 ++++++++++-------- .../internal/p2p_cluster_pcp_handler_test.cc | 2 +- cpp/core/internal/pcp_manager.cc | 2 + 4 files changed, 698 insertions(+), 532 deletions(-) diff --git a/cpp/core/internal/base_pcp_handler.cc b/cpp/core/internal/base_pcp_handler.cc index 274cf557..bf6d8bfa 100644 --- a/cpp/core/internal/base_pcp_handler.cc +++ b/cpp/core/internal/base_pcp_handler.cc @@ -53,22 +53,22 @@ BasePcpHandler::BasePcpHandler(Mediums* mediums, bwu_manager_(bwu_manager) {} BasePcpHandler::~BasePcpHandler() { - NEARBY_LOGS(INFO) << "BasePcpHandler: going down; strategy=" - << strategy_.GetName(); + NEARBY_LOGS(INFO) << "Initiating shutdown of BasePcpHandler(" + << strategy_.GetName() << ")"; DisconnectFromEndpointManager(); // Stop all the ongoing Runnables (as gracefully as possible). - NEARBY_LOGS(INFO) << "BasePcpHandler: bringing down executors; strategy=" - << strategy_.GetName(); + NEARBY_LOGS(INFO) << "BasePcpHandler(" << strategy_.GetName() + << ") is bringing down executors."; serial_executor_.Shutdown(); alarm_executor_.Shutdown(); - NEARBY_LOGS(INFO) << "BasePcpHandler: is down; strategy=" - << strategy_.GetName(); + NEARBY_LOGS(INFO) << "BasePcpHandler(" << strategy_.GetName() + << ") has shut down."; } void BasePcpHandler::DisconnectFromEndpointManager() { if (stop_.Set(true)) return; - NEARBY_LOGS(INFO) << "BasePcpHandler: Unregister from EPM; strategy=" - << strategy_.GetName(); + NEARBY_LOGS(INFO) << "BasePcpHandler(" << strategy_.GetName() + << ") unregister from EPM."; // Unregister ourselves from EPM message dispatcher. endpoint_manager_->UnregisterFrameProcessor(V1Frame::CONNECTION_RESPONSE, this); @@ -79,8 +79,8 @@ Status BasePcpHandler::StartAdvertising(ClientProxy* client, const ConnectionOptions& options, const ConnectionRequestInfo& info) { Future response; - NEARBY_LOG(INFO, "StartAdvertising with supported mediums: %s", - GetStringValueOfSupportedMediums(options).c_str()); + NEARBY_LOGS(INFO) << "StartAdvertising with supported mediums: " + << GetStringValueOfSupportedMediums(options); ConnectionOptions advertising_options = options.CompatibleOptions(); RunOnPcpHandlerThread( "start-advertising", @@ -118,7 +118,8 @@ Status BasePcpHandler::StartAdvertising(ClientProxy* client, } void BasePcpHandler::StopAdvertising(ClientProxy* client) { - NEARBY_LOGS(INFO) << "StopAdvertising id=" << client->GetLocalEndpointId(); + NEARBY_LOGS(INFO) << "StopAdvertising local_endpoint_id=" + << client->GetLocalEndpointId(); CountDownLatch latch(1); RunOnPcpHandlerThread("stop-advertising", [this, client, &latch]() RUN_ON_PCP_HANDLER_THREAD() { @@ -133,10 +134,18 @@ std::string BasePcpHandler::GetStringValueOfSupportedMediums( const ConnectionOptions& options) const { std::ostringstream result; result << "{ "; - if (options.allowed.bluetooth) result << "bluetooth "; - if (options.allowed.ble) result << "ble "; - if (options.allowed.web_rtc) result << "webrtc "; - if (options.allowed.wifi_lan) result << "wifilan "; + if (options.allowed.bluetooth) { + result << proto::connections::Medium_Name(Medium::BLUETOOTH) << " "; + } + if (options.allowed.ble) { + result << proto::connections::Medium_Name(Medium::BLE) << " "; + } + if (options.allowed.web_rtc) { + result << proto::connections::Medium_Name(Medium::WEB_RTC) << " "; + } + if (options.allowed.wifi_lan) { + result << proto::connections::Medium_Name(Medium::WIFI_LAN) << " "; + } result << "}"; return result.str(); } @@ -194,8 +203,8 @@ Status BasePcpHandler::StartDiscovery(ClientProxy* client, Future response; ConnectionOptions discovery_options = options.CompatibleOptions(); - NEARBY_LOG(INFO, "StartDiscovery with supported mediums: %s", - GetStringValueOfSupportedMediums(options).c_str()); + NEARBY_LOGS(INFO) << "StartDiscovery with supported mediums:" + << GetStringValueOfSupportedMediums(options); RunOnPcpHandlerThread( "start-discovery", [this, client, service_id, discovery_options, &listener, &response]() RUN_ON_PCP_HANDLER_THREAD() { @@ -249,7 +258,7 @@ void BasePcpHandler::WaitForLatch(const std::string& method_name, Exception await_exception = latch->Await(); if (!await_exception.Ok()) { if (await_exception.Raised(Exception::kTimeout)) { - NEARBY_LOG(INFO, "Blocked in %s", method_name.c_str()); + NEARBY_LOGS(INFO) << "Blocked in " << method_name; } } } @@ -258,18 +267,18 @@ Status BasePcpHandler::WaitForResult(const std::string& method_name, std::int64_t client_id, Future* future) { if (!future) { - NEARBY_LOG(INFO, "No future to wait for; return with error"); + NEARBY_LOGS(INFO) << "No future to wait for; return with error"; return {Status::kError}; } - NEARBY_LOG(INFO, "Waiting for future to complete: %s", method_name.c_str()); + NEARBY_LOGS(INFO) << "Waiting for future to complete: " << method_name; ExceptionOr result = future->Get(); if (!result.ok()) { - NEARBY_LOG(INFO, "Future:[%s] completed with exception: %d", - method_name.c_str(), result.exception()); + NEARBY_LOGS(INFO) << "Future:[" << method_name + << "] completed with exception:" << result.exception(); return {Status::kError}; } - NEARBY_LOG(INFO, "Future:[%s] completed with status: %d", method_name.c_str(), - result.result().value); + NEARBY_LOGS(INFO) << "Future:[" << method_name + << "] completed with status:" << result.result().value; return result.result(); } @@ -299,8 +308,10 @@ EncryptionRunner::ResultListener BasePcpHandler::GetResultListener() { RunOnPcpHandlerThread( "encryption-failure", [this, endpoint_id, channel]() RUN_ON_PCP_HANDLER_THREAD() { - NEARBY_LOG(ERROR, "Encryption failed for %s on medium %d", - endpoint_id.c_str(), channel->GetMedium()); + NEARBY_LOGS(ERROR) + << "Encryption failed for endpoint_id=" << endpoint_id + << " on medium=" + << proto::connections::Medium_Name(channel->GetMedium()); OnEncryptionFailureRunnable(endpoint_id, channel); }); }, @@ -314,9 +325,9 @@ void BasePcpHandler::OnEncryptionSuccessRunnable( // busy running UKEY2. auto it = pending_connections_.find(endpoint_id); if (it == pending_connections_.end()) { - NEARBY_LOG(INFO, - "Connection not found on UKEY negotination complete; id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "Connection not found on UKEY negotination complete; endpoint_id=" + << endpoint_id; return; } @@ -331,8 +342,9 @@ void BasePcpHandler::OnEncryptionSuccessRunnable( } connection_info.SetCryptoContext(std::move(ukey2)); - NEARBY_LOG(INFO, "Register encrypted connection; wait for response; id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "Register encrypted connection; wait for response; endpoint_id=" + << endpoint_id; // Set ourselves up so that we receive all acceptance/rejection messages endpoint_manager_->RegisterFrameProcessor(V1Frame::CONNECTION_RESPONSE, this); @@ -373,7 +385,7 @@ void BasePcpHandler::OnEncryptionSuccessRunnable( std::move(connection_info.channel), connection_info.listener); if (auto future_status = connection_info.result.lock()) { - NEARBY_LOG(INFO, "Connection established; Finalising future OK"); + NEARBY_LOGS(INFO) << "Connection established; Finalising future OK."; future_status->Set({Status::kSuccess}); connection_info.result.reset(); } @@ -383,9 +395,9 @@ void BasePcpHandler::OnEncryptionFailureRunnable( const std::string& endpoint_id, EndpointChannel* endpoint_channel) { auto it = pending_connections_.find(endpoint_id); if (it == pending_connections_.end()) { - NEARBY_LOG(INFO, - "Connection not found on UKEY negotination complete; id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "Connection not found on UKEY negotination complete; endpoint_id=" + << endpoint_id; return; } @@ -398,9 +410,9 @@ void BasePcpHandler::OnEncryptionFailureRunnable( // the map had already updated with the winning EndpointChannel, we closed // it too by accident. if (*endpoint_channel != *info.channel) { - NEARBY_LOG( - INFO, "Not destroying channel [mismatch]: passed=%s; expected=%s", - endpoint_channel->GetName().c_str(), info.channel->GetName().c_str()); + NEARBY_LOGS(INFO) << "Not destroying channel [mismatch]: passed=" + << endpoint_channel->GetName() + << "; expected=" << info.channel->GetName(); return; } @@ -422,8 +434,11 @@ Status BasePcpHandler::RequestConnection(ClientProxy* client, // If we already have a pending connection, then we shouldn't allow any // more outgoing connections to this endpoint. if (pending_connections_.count(endpoint_id)) { - NEARBY_LOG(INFO, "Connection already exists: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "In requestConnection(), connection requested with " + "endpoint(id=" + << endpoint_id + << "), but we already have a pending connection with them."; result->Set({Status::kAlreadyConnectedToEndpoint}); return; } @@ -432,16 +447,18 @@ Status BasePcpHandler::RequestConnection(ClientProxy* client, // listen to them. if (ShouldEnforceTopologyConstraints(client->GetAdvertisingOptions()) && !CanSendOutgoingConnection(client)) { - NEARBY_LOG(INFO, "Outgoing connection not allowed: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "In requestConnection(), client=" << client->GetClientId() + << " attempted a connection with endpoint(id=" << endpoint_id + << "), but outgoing connections are disallowed"; result->Set({Status::kOutOfOrderApiCall}); return; } DiscoveredEndpoint* endpoint = GetDiscoveredEndpoint(endpoint_id); if (endpoint == nullptr) { - NEARBY_LOG(INFO, "Discovered endpoint not found: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "Discovered endpoint not found: endpoint_id=" << endpoint_id; result->Set({Status::kEndpointUnknown}); return; } @@ -453,8 +470,8 @@ Status BasePcpHandler::RequestConnection(ClientProxy* client, endpoint_id, remote_bluetooth_mac_address, client->GetDiscoveryOptions())) NEARBY_LOGS(INFO) - << "Appended remote Bluetooth MAC Address endpoint " - << "[" << remote_bluetooth_mac_address << "]"; + << "Appended remote Bluetooth MAC Address endpoint [" + << remote_bluetooth_mac_address << "]"; } if (AppendWebRTCEndpoint(endpoint_id, client->GetDiscoveryOptions())) @@ -476,16 +493,18 @@ Status BasePcpHandler::RequestConnection(ClientProxy* client, } if (channel == nullptr) { - NEARBY_LOG(INFO, "Endpoint channel not available: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "Endpoint channel not available: endpoint_id=" << endpoint_id; ProcessPreConnectionInitiationFailure(endpoint_id, channel.get(), connect_impl_result.status, result.get()); return; } - NEARBY_LOG(INFO, "Sending connection request: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "In requestConnection(), wrote ConnectionRequestFrame " + "to endpoint_id=" + << endpoint_id; // Generate the nonce to use for this connection. std::int32_t nonce = prng_.NextInt32(); @@ -497,16 +516,16 @@ Status BasePcpHandler::RequestConnection(ClientProxy* client, options.keep_alive_interval_millis, options.keep_alive_timeout_millis); if (!write_exception.Ok()) { - NEARBY_LOG(INFO, "Failed to send connection request: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Failed to send connection request: endpoint_id=" + << endpoint_id; ProcessPreConnectionInitiationFailure(endpoint_id, channel.get(), {Status::kEndpointIoError}, result.get()); return; } - NEARBY_LOG(INFO, "adding connection to pending set: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Adding connection to pending set: endpoint_id=" + << endpoint_id; // We've successfully connected to the device, and are now about to jump // on to the EncryptionRunner thread to start running our encryption @@ -531,20 +550,20 @@ Status BasePcpHandler::RequestConnection(ClientProxy* client, .emplace(endpoint_id, std::move(pendingConnectionInfo)) .first->second.channel.get(); - NEARBY_LOG(INFO, "Initiating secure connection: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Initiating secure connection: endpoint_id=" + << endpoint_id; // Next, we'll set up encryption. When it's done, our future will return // and RequestConnection() will finish. encryption_runner_.StartClient(client, endpoint_id, endpoint_channel, GetResultListener()); }); - NEARBY_LOG(INFO, "Waiting for connection to complete: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Waiting for connection to complete: endpoint_id=" + << endpoint_id; auto status = WaitForResult(absl::StrCat("RequestConnection(", endpoint_id, ")"), client->GetClientId(), result.get()); - NEARBY_LOG(INFO, "Wait is complete: id=%s; status=%d", endpoint_id.c_str(), - status.value); + NEARBY_LOGS(INFO) << "Wait is complete: endpoint_id=" << endpoint_id + << "; status=" << status.value; return status; } @@ -663,7 +682,7 @@ void BasePcpHandler::ProcessPreConnectionInitiationFailure( } if (result != nullptr) { - NEARBY_LOG(INFO, "Connection failed; aborting future"); + NEARBY_LOGS(INFO) << "Connection failed; aborting future"; result->Set(status); } @@ -707,10 +726,12 @@ Status BasePcpHandler::AcceptConnection( RunOnPcpHandlerThread( "accept-connection", [this, client, endpoint_id, payload_listener, &response]() RUN_ON_PCP_HANDLER_THREAD() { - NEARBY_LOG(INFO, "AcceptConnection: id=%s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "AcceptConnection: endpoint_id=" << endpoint_id; if (!pending_connections_.count(endpoint_id)) { - NEARBY_LOG(INFO, "AcceptConnection: no pending connection for id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "AcceptConnection: no pending connection for endpoint_id=" + << endpoint_id; + response.Set({Status::kEndpointUnknown}); return; } @@ -724,10 +745,9 @@ Status BasePcpHandler::AcceptConnection( std::shared_ptr channel = channel_manager_->GetChannelForEndpoint(endpoint_id); if (channel == nullptr) { - NEARBY_LOG( - ERROR, - "Channel destroyed before Accept; bring down connection: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(ERROR) << "Channel destroyed before Accept; bring down " + "connection: endpoint_id=" + << endpoint_id; ProcessPreConnectionResultFailure(client, endpoint_id); response.Set({Status::kEndpointUnknown}); return; @@ -736,15 +756,16 @@ Status BasePcpHandler::AcceptConnection( Exception write_exception = channel->Write(parser::ForConnectionResponse(Status::kSuccess)); if (!write_exception.Ok()) { - NEARBY_LOG(INFO, "AcceptConnection: failed to send response: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "AcceptConnection: failed to send response: endpoint_id=" + << endpoint_id; ProcessPreConnectionResultFailure(client, endpoint_id); response.Set({Status::kEndpointIoError}); return; } - NEARBY_LOG(INFO, "AcceptConnection: accepting locally: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "AcceptConnection: accepting locally: endpoint_id=" + << endpoint_id; connection_info.LocalEndpointAcceptedConnection(endpoint_id, payload_listener); EvaluateConnectionResult(client, endpoint_id, @@ -764,8 +785,9 @@ Status BasePcpHandler::RejectConnection(ClientProxy* client, [this, client, endpoint_id, &response]() RUN_ON_PCP_HANDLER_THREAD() { NEARBY_LOG(INFO, "RejectConnection: id=%s", endpoint_id.c_str()); if (!pending_connections_.count(endpoint_id)) { - NEARBY_LOG(INFO, "RejectConnection: no pending connection for id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "RejectConnection: no pending connection for endpoint_id=" + << endpoint_id; response.Set({Status::kEndpointUnknown}); return; } @@ -779,10 +801,10 @@ Status BasePcpHandler::RejectConnection(ClientProxy* client, std::shared_ptr channel = channel_manager_->GetChannelForEndpoint(endpoint_id); if (channel == nullptr) { - NEARBY_LOG( - ERROR, - "Channel destroyed before Reject; bring down connection: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(ERROR) + << "Channel destroyed before Reject; bring down connection: " + "endpoint_id=" + << endpoint_id; ProcessPreConnectionResultFailure(client, endpoint_id); response.Set({Status::kEndpointUnknown}); return; @@ -791,15 +813,16 @@ Status BasePcpHandler::RejectConnection(ClientProxy* client, Exception write_exception = channel->Write( parser::ForConnectionResponse(Status::kConnectionRejected)); if (!write_exception.Ok()) { - NEARBY_LOG(INFO, "RejectConnection: failed to send response: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "RejectConnection: failed to send response: endpoint_id=" + << endpoint_id; ProcessPreConnectionResultFailure(client, endpoint_id); response.Set({Status::kEndpointIoError}); return; } - NEARBY_LOG(INFO, "RejectConnection: rejecting locally: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "RejectConnection: rejecting locally: endpoint_id=" + << endpoint_id; connection_info.LocalEndpointRejectedConnection(endpoint_id); EvaluateConnectionResult(client, endpoint_id, false /* can_close_immediately */); @@ -818,11 +841,13 @@ void BasePcpHandler::OnIncomingFrame(OfflineFrame& frame, RunOnPcpHandlerThread( "incoming-frame", [this, client, endpoint_id, frame, &latch]() RUN_ON_PCP_HANDLER_THREAD() { - NEARBY_LOG(INFO, "OnConnectionResponse: id=%s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "OnConnectionResponse: endpoint_id=" + << endpoint_id; if (client->HasRemoteEndpointResponded(endpoint_id)) { - NEARBY_LOG(INFO, "OnConnectionResponse: already handled; id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "OnConnectionResponse: already handled; endpoint_id=" + << endpoint_id; return; } @@ -840,13 +865,14 @@ void BasePcpHandler::OnIncomingFrame(OfflineFrame& frame, accepted = connection_response.status() == Status::kSuccess; } if (accepted) { - NEARBY_LOG(INFO, "OnConnectionResponse: remote accepted; id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "OnConnectionResponse: remote accepted; endpoint_id=" + << endpoint_id; client->RemoteEndpointAcceptedConnection(endpoint_id); } else { - NEARBY_LOG(INFO, - "OnConnectionResponse: remote rejected; id=%s; status=%d", - endpoint_id.c_str(), connection_response.status()); + NEARBY_LOGS(INFO) + << "OnConnectionResponse: remote rejected; endpoint_id=" + << endpoint_id << "; status=" << connection_response.status(); client->RemoteEndpointRejectedConnection(endpoint_id); } @@ -890,7 +916,7 @@ void BasePcpHandler::OnEndpointFound( ClientProxy* client, std::shared_ptr endpoint) { // Check if we've seen this endpoint ID before. std::string& endpoint_id = endpoint->endpoint_id; - NEARBY_LOG(INFO, "OnEndpointFound: id='%s' [enter]", endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "OnEndpointFound: id=" << endpoint_id << " [enter]"; auto range = discovered_endpoints_.equal_range(endpoint->endpoint_id); @@ -920,14 +946,14 @@ void BasePcpHandler::OnEndpointFound( // Range is empty: this is the first endpoint we discovered so far. // Report this endpoint_id to client. if (range.first == range.second) { - NEARBY_LOG(INFO, "Adding new endpoint: id=%s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Adding new endpoint: endpoint_id=" << endpoint_id; // And, as it's the first time, report it to the client. client->OnEndpointFound( owned_endpoint->service_id, owned_endpoint->endpoint_id, owned_endpoint->endpoint_info, owned_endpoint->medium); } else { - NEARBY_LOGS(INFO) << "Adding new medium for endpoint: id=" << endpoint_id - << "; medium=" << owned_endpoint->medium; + NEARBY_LOGS(INFO) << "Adding new medium for endpoint: endpoint_id=" + << endpoint_id << "; medium=" << owned_endpoint->medium; } } @@ -936,8 +962,8 @@ void BasePcpHandler::OnEndpointLost( // Look up the DiscoveredEndpoint we have in our cache. const auto* discovered_endpoint = GetDiscoveredEndpoint(endpoint.endpoint_id); if (discovered_endpoint == nullptr) { - NEARBY_LOG(INFO, "No previous endpoint (nothing to lose): id=%s", - endpoint.endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "No previous endpoint (nothing to lose): endpoint_id=" + << endpoint.endpoint_id; return; } @@ -946,10 +972,11 @@ void BasePcpHandler::OnEndpointLost( // device changed their info. We reported onFound for the new info and are // just now figuring out that we lost the old info. if (discovered_endpoint->endpoint_info != endpoint.endpoint_info) { - NEARBY_LOG(INFO, "Previous endpoint name mismatch; passed=%s; expected=%s", - absl::BytesToHexString(endpoint.endpoint_info.data()).c_str(), - absl::BytesToHexString(discovered_endpoint->endpoint_info.data()) - .c_str()); + NEARBY_LOGS(INFO) << "Previous endpoint name mismatch; passed=" + << absl::BytesToHexString(endpoint.endpoint_info.data()) + << "; expected=" + << absl::BytesToHexString( + discovered_endpoint->endpoint_info.data()); return; } @@ -981,10 +1008,11 @@ bool BasePcpHandler::IsPreferred( for (const auto& medium : mediums) { absl::StrAppend(&medium_string, medium, "; "); } - NEARBY_LOG(FATAL, - "Failed to determine preferred medium; bailing out; mediums=%s; " - "new=%d; old=%d", - medium_string.c_str(), new_endpoint.medium, old_endpoint.medium); + NEARBY_LOGS(FATAL) << "Failed to find either " << new_endpoint.medium + << " or " << old_endpoint.medium + << " in the list of locally supported mediums despite " + "expecting to find both, when deciding which medium " + << medium_string << " is preferred."; return false; } @@ -998,10 +1026,11 @@ Exception BasePcpHandler::OnIncomingConnection( // the client stopped advertising and we nulled out state, followed by an // incoming connection where we attempted to check that state. if (!client->IsAdvertising()) { - NEARBY_LOG(WARNING, - "Ignoring incoming connection because client 0x%" PRIX64 - " is no longer advertising.", - client->GetClientId()); + NEARBY_LOGS(WARNING) << "Ignoring incoming connection on medium " + << proto::connections::Medium_Name( + channel->GetMedium()) + << " because client=" << client->GetClientId() + << " is no longer advertising."; return {Exception::kIo}; } @@ -1011,12 +1040,10 @@ Exception BasePcpHandler::OnIncomingConnection( if (!wrapped_frame.ok()) { if (wrapped_frame.exception()) { - NEARBY_LOG( - ERROR, - "Failed to parse incoming connection request; client_id=0x%" PRIX64 - "; device=%s", - client->GetClientId(), - absl::BytesToHexString(remote_endpoint_info.data()).c_str()); + NEARBY_LOGS(ERROR) + << "Failed to parse incoming connection request; client=" + << client->GetClientId() + << "; device=" << absl::BytesToHexString(remote_endpoint_info.data()); ProcessPreConnectionInitiationFailure("", channel.get(), {Status::kError}, nullptr); return {Exception::kSuccess}; @@ -1027,13 +1054,17 @@ Exception BasePcpHandler::OnIncomingConnection( OfflineFrame& frame = wrapped_frame.result(); const ConnectionRequestFrame& connection_request = frame.v1().connection_request(); - NEARBY_LOG(INFO, - "Incoming connection request; client_id=0x%" PRIX64 - "; device=%s; id=%s", - client->GetClientId(), - absl::BytesToHexString(remote_endpoint_info.data()).c_str(), - connection_request.endpoint_id().c_str()); + NEARBY_LOGS(INFO) << "In onIncomingConnection(" + << proto::connections::Medium_Name(channel->GetMedium()) + << ") for client=" << client->GetClientId() + << ", read ConnectionRequestFrame from endpoint(id=" + << connection_request.endpoint_id() << ")"; if (client->IsConnectedToEndpoint(connection_request.endpoint_id())) { + NEARBY_LOGS(ERROR) << "Incoming connection on medium " + << proto::connections::Medium_Name(channel->GetMedium()) + << " was denied because we're " + "already connected to endpoint(id=" + << connection_request.endpoint_id() << ")."; return {Exception::kIo}; } @@ -1048,6 +1079,7 @@ Exception BasePcpHandler::OnIncomingConnection( // listen to them. if (ShouldEnforceTopologyConstraints(client->GetAdvertisingOptions()) && !CanReceiveIncomingConnection(client)) { + NEARBY_LOGS(ERROR) << "Incoming connections are currently disallowed."; return {Exception::kIo}; } @@ -1074,13 +1106,13 @@ Exception BasePcpHandler::OnIncomingConnection( if (options.keep_alive_interval_millis == 0 || options.keep_alive_timeout_millis == 0 || options.keep_alive_interval_millis >= options.keep_alive_timeout_millis) { - NEARBY_LOG(WARNING, - "Incoming connection has wrong keep-alive frame interval=%d, " - "timeout=%d values; correct them as default.", - options.keep_alive_interval_millis, - options.keep_alive_timeout_millis); - options.keep_alive_interval_millis = - FeatureFlags::GetInstance().GetFlags().keep_alive_interval_millis; + NEARBY_LOGS(WARNING) + << "Incoming connection has wrong keep-alive frame interval=" + << options.keep_alive_interval_millis + << ", timeout=" << options.keep_alive_timeout_millis + << " values; correct them as default.", + options.keep_alive_interval_millis = + FeatureFlags::GetInstance().GetFlags().keep_alive_interval_millis; options.keep_alive_timeout_millis = FeatureFlags::GetInstance().GetFlags().keep_alive_timeout_millis; } @@ -1122,21 +1154,38 @@ bool BasePcpHandler::BreakTie(ClientProxy* client, if (it != pending_connections_.end()) { BasePcpHandler::PendingConnectionInfo& info = it->second; - NEARBY_LOG(INFO, "BreakTie: id=%s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "In onIncomingConnection(" + << proto::connections::Medium_Name(endpoint_channel->GetMedium()) + << ") for client=" << client->GetClientId() + << ", found a collision with endpoint " << endpoint_id + << ". We've already sent a connection request to them with nonce " + << info.nonce + << ", but they're also trying to connect to us with nonce " + << incoming_nonce; // Break the lowest connection. In the (extremely) rare case of a tie, break // both. if (info.nonce > incoming_nonce) { // Our connection won! Clean up their connection. endpoint_channel->Close(); - NEARBY_LOG(INFO, "BreakTie: We won; id=%s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "In onIncomingConnection(" + << proto::connections::Medium_Name( + endpoint_channel->GetMedium()) + << ") for client=" << client->GetClientId() + << ", cleaned up the collision with endpoint " + << endpoint_id << " by closing their channel."; return true; } else if (info.nonce < incoming_nonce) { // Aw, we lost. Clean up our connection, and then we'll let their // connection continue on. ProcessTieBreakLoss(client, endpoint_id, &info); - - NEARBY_LOG(INFO, "BreakTie: We lost; id=%s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "In onIncomingConnection(" + << proto::connections::Medium_Name(endpoint_channel->GetMedium()) + << ") for client=" << client->GetClientId() + << ", cleaned up the collision with endpoint " << endpoint_id + << " by closing our channel and notifying our client of the failure."; } else { // Oh. Huh. We both lost. Well, that's awkward. We'll clean up both and // just force the devices to retry. @@ -1144,7 +1193,13 @@ bool BasePcpHandler::BreakTie(ClientProxy* client, ProcessTieBreakLoss(client, endpoint_id, &info); - NEARBY_LOG(INFO, "BreakTie: Both lost; id=%s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "In onIncomingConnection(" + << proto::connections::Medium_Name(endpoint_channel->GetMedium()) + << ") for client=" << client->GetClientId() + << ", cleaned up the collision with endpoint " << endpoint_id + << " by closing both channels. Our nonces were identical, so we " + "couldn't decide which channel to use."; return true; } } @@ -1177,9 +1232,9 @@ bool BasePcpHandler::AppendRemoteBluetoothMacAddressEndpoint( for (auto item = it.first; item != it.second; item++) { if (item->second->medium == proto::connections::Medium::BLUETOOTH) { NEARBY_LOGS(INFO) - << "Cannot append remote Bluetooth MAC Address endpoint, because the " - "endpoint has already been found over Bluetooth " - << "[" << remote_bluetooth_mac_address << "]"; + << "Cannot append remote Bluetooth MAC Address endpoint, because " + "the endpoint has already been found over Bluetooth [" + << remote_bluetooth_mac_address << "]"; return false; } } @@ -1187,10 +1242,10 @@ bool BasePcpHandler::AppendRemoteBluetoothMacAddressEndpoint( auto remote_bluetooth_device = GetRemoteBluetoothDevice(remote_bluetooth_mac_address); if (!remote_bluetooth_device.IsValid()) { - NEARBY_LOGS(INFO) << "Cannot append remote Bluetooth MAC Address endpoint, " - "because a valid " - "Bluetooth device could not be derived " - << "[" << remote_bluetooth_mac_address << "]"; + NEARBY_LOGS(INFO) + << "Cannot append remote Bluetooth MAC Address endpoint, because a " + "valid Bluetooth device could not be derived [" + << remote_bluetooth_mac_address << "]"; return false; } @@ -1243,11 +1298,13 @@ void BasePcpHandler::EvaluateConnectionResult(ClientProxy* client, if (!client->IsConnectionAccepted(endpoint_id) && !client->IsConnectionRejected(endpoint_id)) { if (!client->HasLocalEndpointResponded(endpoint_id)) { - NEARBY_LOG(INFO, "ConnectionResult: local client did not respond; id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "ConnectionResult: local client did not respond; endpoint_id=" + << endpoint_id; } else if (!client->HasRemoteEndpointResponded(endpoint_id)) { - NEARBY_LOG(INFO, "ConnectionResult: remote client did not respond; id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "ConnectionResult: remote client did not respond; endpoint_id=" + << endpoint_id; } return; } @@ -1256,8 +1313,8 @@ void BasePcpHandler::EvaluateConnectionResult(ClientProxy* client, // no longer pending. auto it = pending_connections_.find(endpoint_id); if (it == pending_connections_.end()) { - NEARBY_LOG(INFO, "No pending connection to evaluate; id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "No pending connection to evaluate; endpoint_id=" + << endpoint_id; return; } @@ -1267,7 +1324,8 @@ void BasePcpHandler::EvaluateConnectionResult(ClientProxy* client, Status response_code; if (is_connection_accepted) { - NEARBY_LOG(INFO, "Pending connection accepted; id=%s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Pending connection accepted; endpoint_id=" + << endpoint_id; response_code = {Status::kSuccess}; // Both sides have accepted, so we can now start talking over encrypted @@ -1284,7 +1342,8 @@ void BasePcpHandler::EvaluateConnectionResult(ClientProxy* client, channel_manager_->EncryptChannelForEndpoint(endpoint_id, std::move(context)); } else { - NEARBY_LOG(INFO, "Pending connection rejected; id=%s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Pending connection rejected; endpoint_id=" + << endpoint_id; response_code = {Status::kConnectionRejected}; } diff --git a/cpp/core/internal/p2p_cluster_pcp_handler.cc b/cpp/core/internal/p2p_cluster_pcp_handler.cc index de793744..40223725 100644 --- a/cpp/core/internal/p2p_cluster_pcp_handler.cc +++ b/cpp/core/internal/p2p_cluster_pcp_handler.cc @@ -126,13 +126,16 @@ BasePcpHandler::StartOperationResult P2pClusterPcpHandler::StartAdvertisingImpl( StartBleAdvertising(client, service_id, local_endpoint_id, local_endpoint_info, options, web_rtc_state); if (ble_medium != proto::connections::UNKNOWN_MEDIUM) { - NEARBY_LOG(INFO, "P2pClusterPcpHandler::StartAdvertisingImpl: Ble added"); + NEARBY_LOGS(INFO) + << "P2pClusterPcpHandler::StartAdvertisingImpl: Ble added"; mediums_started_successfully.push_back(ble_medium); } } if (mediums_started_successfully.empty()) { - NEARBY_LOG(INFO, "P2pClusterPcpHandler::StartAdvertisingImpl: not started"); + NEARBY_LOGS(FATAL) << "Failed StartAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << ") for client=" << client->GetClientId(); return { .status = {Status::kBluetoothError}, }; @@ -153,10 +156,10 @@ Status P2pClusterPcpHandler::StopAdvertisingImpl(ClientProxy* client) { bluetooth_medium_.TurnOffDiscoverability(); bluetooth_classic_advertiser_client_id_ = 0; } else { - NEARBY_LOG(INFO, - "Skipped BT TurnOffDiscoverability for client %d, client that " - "turned on discoverability is %d", - client->GetClientId(), bluetooth_classic_advertiser_client_id_); + NEARBY_LOGS(INFO) << "Skipped BT TurnOffDiscoverability for client=" + << client->GetClientId() + << ", client that turned on discoverability is " + << bluetooth_classic_advertiser_client_id_; } bluetooth_medium_.StopAcceptingConnections(client->GetAdvertisingServiceId()); @@ -174,17 +177,16 @@ bool P2pClusterPcpHandler::IsRecognizedBluetoothEndpoint( const std::string& name_string, const std::string& service_id, const BluetoothDeviceName& name) const { if (!name.IsValid()) { - NEARBY_LOG( - INFO, - "P2pClusterPcpHandler::IsRecognizedBluetoothEndpoint: name is invalid"); + NEARBY_LOGS(INFO) + << name_string + << " doesn't conform to the BluetoothDeviceName format, discarding."; return false; } if (name.GetPcp() != GetPcp()) { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::IsRecognizedBluetoothEndpoint: Pcp is " - "not matched; name.Pcp=%d, Pcp=%d", - name.GetPcp(), GetPcp()); + NEARBY_LOGS(INFO) << name_string << " doesn't match on Pcp; expected " + << PcpToStrategy(GetPcp()).GetName() << ", found " + << PcpToStrategy(name.GetPcp()).GetName(); return false; } @@ -192,11 +194,11 @@ bool P2pClusterPcpHandler::IsRecognizedBluetoothEndpoint( GenerateHash(service_id, BluetoothDeviceName::kServiceIdHashLength); if (name.GetServiceIdHash() != expected_service_id_hash) { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::IsRecognizedBluetoothEndpoint: service " - "id hash is " - "not matched; name.service_id_hash=%s, expected=%s", - name.GetServiceIdHash().data(), expected_service_id_hash.data()); + NEARBY_LOGS(INFO) << name_string + << " doesn't match on expected service_id_hash; expected " + << absl::BytesToHexString(expected_service_id_hash.data()) + << ", found " + << absl::BytesToHexString(name.GetServiceIdHash().data()); return false; } @@ -212,11 +214,9 @@ void P2pClusterPcpHandler::BluetoothDeviceDiscoveredHandler( RUN_ON_PCP_HANDLER_THREAD() { // Make sure we are still discovering before proceeding. if (!client->IsDiscovering()) { - NEARBY_LOG( - INFO, - "BT discovery handler (FOUND) [client=%p, service=%s]: not " - "in discovery mode", - client, service_id.c_str()); + NEARBY_LOGS(WARNING) << "Skipping discovery of BluetoothDevice " + << device.GetName() + << " because we are no longer discovering."; return; } @@ -227,15 +227,19 @@ void P2pClusterPcpHandler::BluetoothDeviceDiscoveredHandler( // Make sure the Bluetooth device name points to a valid // endpoint we're discovering. if (!IsRecognizedBluetoothEndpoint(device_name_string, service_id, - device_name)) + device_name)) { + NEARBY_LOGS(INFO) << "Found unrecognized BluetoothDeviceName " + << device_name_string; return; + } // Report the discovered endpoint to the client. NEARBY_LOGS(INFO) - << "Invoking BasePcpHandler::OnEndpointFound() for BT service=" - << service_id << "; id=" << device_name.GetEndpointId() - << "; name=" - << absl::BytesToHexString(device_name.GetEndpointInfo().data()); + << "Found BluetoothDeviceName " << device_name_string + << " (with endpoint_id=" << device_name.GetEndpointId() + << " and endpoint_info=" + << absl::BytesToHexString(device_name.GetEndpointInfo().data()) + << ")."; OnEndpointFound( client, std::make_shared(BluetoothEndpoint{ @@ -255,21 +259,19 @@ void P2pClusterPcpHandler::BluetoothNameChangedHandler( [this, client, service_id, device]() RUN_ON_PCP_HANDLER_THREAD() { // Make sure we are still discovering before proceeding. if (!client->IsDiscovering()) { - NEARBY_LOG( - INFO, - "BT discovery handler (CHANGED) [client=%p, service=%s]: not " - "in discovery mode", - client, service_id.c_str()); + NEARBY_LOGS(WARNING) + << "Ignoring lost BluetoothDevice " << device.GetName() + << " because Connections is no longer discovering."; return; } // Parse the Bluetooth device name. const std::string device_name_string = device.GetName(); BluetoothDeviceName device_name(device_name_string); - NEARBY_LOG(INFO, - "BT discovery handler (CHANGED) [client=%p, service=%s]: " - "processing new name %s", - client, service_id.c_str(), device_name_string.c_str()); + NEARBY_LOGS(INFO) << "BT discovery handler (CHANGED) [client_id=" + << client->GetClientId() + << ", service_id=" << service_id + << "]: processing new name " << device_name_string; // By this point, the BluetoothDevice passed to us has a different name // than what we may have discovered before. We need to iterate over the @@ -281,23 +283,21 @@ void P2pClusterPcpHandler::BluetoothNameChangedHandler( GetDiscoveredEndpoints(proto::connections::Medium::BLUETOOTH)) { BluetoothEndpoint* bluetoothEndpoint = static_cast(endpoint); - NEARBY_LOG( - INFO, - "BT discovery handler (CHANGED) [client=%p, service=%s]: " - "comparing MAC addresses with existing endpoint %s. They have " - "MAC address %s and the new endpoint has MAC address %s.", - client, service_id.c_str(), - bluetoothEndpoint->bluetooth_device.GetName().c_str(), - bluetoothEndpoint->bluetooth_device.GetMacAddress().c_str(), - device.GetMacAddress().c_str()); + NEARBY_LOGS(INFO) + << "BT discovery handler (CHANGED) [client_id=" + << client->GetClientId() << ", service_id=" << service_id + << "]: comparing MAC addresses with existing endpoint " + << bluetoothEndpoint->bluetooth_device.GetName() + << ". They have MAC address " + << bluetoothEndpoint->bluetooth_device.GetMacAddress() + << " and the new endpoint has MAC address " + << device.GetMacAddress(); if (bluetoothEndpoint->bluetooth_device.GetMacAddress() == device.GetMacAddress()) { // Report the BluetoothEndpoint as lost to the client. - NEARBY_LOG( - INFO, - "BT discovery handler (LOST) [client=%p, service=%s]: report " - "to client", - client, service_id.c_str()); + NEARBY_LOGS(INFO) << "Reporting lost BluetoothDevice " + << bluetoothEndpoint->bluetooth_device.GetName() + << ", due to device name change."; OnEndpointLost(client, *endpoint); break; } @@ -307,19 +307,19 @@ void P2pClusterPcpHandler::BluetoothNameChangedHandler( // endpoint we're discovering. if (!IsRecognizedBluetoothEndpoint(device_name_string, service_id, device_name)) { - NEARBY_LOG( - INFO, - "BT discovery handler (CHANGED) [client=%p, service=%s]: The " - "new name is not recognized. Ignoring.", - client, service_id.c_str()); + NEARBY_LOGS(INFO) << "Found unrecognized BluetoothDeviceName " + << device_name_string; return; } // Report the discovered endpoint to the client. - NEARBY_LOGS(INFO) - << "Invoking BasePcpHandler::OnEndpointFound() for BT service=" - << service_id << "; id=" << device_name.GetEndpointId() << "; name=" - << absl::BytesToHexString(device_name.GetEndpointInfo().data()); + NEARBY_LOGS(INFO) << "Found BluetoothDeviceName " << device_name_string + << " (with endpoint_id=" + << device_name.GetEndpointId() + << " and endpoint_info=" + << absl::BytesToHexString( + device_name.GetEndpointInfo().data()) + << ")."; OnEndpointFound( client, std::make_shared(BluetoothEndpoint{ @@ -340,10 +340,10 @@ void P2pClusterPcpHandler::BluetoothDeviceLostHandler( device_name_string]() RUN_ON_PCP_HANDLER_THREAD() { // Make sure we are still discovering before proceeding. if (!client->IsDiscovering()) { - NEARBY_LOG(INFO, - "BT discovery handler (LOST) [client=%p, service=%s]: not " - "in discovery mode", - client, service_id.c_str()); + NEARBY_LOGS(WARNING) + << "Ignoring lost BluetoothDevice " << device_name_string + << " because Connections is no " + "longer discovering."; return; } @@ -357,11 +357,8 @@ void P2pClusterPcpHandler::BluetoothDeviceLostHandler( return; // Report the BluetoothEndpoint as lost to the client. - NEARBY_LOG( - INFO, - "BT discovery handler (LOST) [client=%p, service=%s]: report " - "to client", - client, service_id.c_str()); + NEARBY_LOGS(INFO) << "Processing lost BluetoothDeviceName " + << device_name_string; OnEndpointLost(client, DiscoveredEndpoint{ device_name.GetEndpointId(), device_name.GetEndpointInfo(), service_id, @@ -374,26 +371,23 @@ bool P2pClusterPcpHandler::IsRecognizedBleEndpoint( const std::string& service_id, const BleAdvertisement& advertisement) const { if (!advertisement.IsValid()) { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::IsRecognizedBleEndpoint: advertisement " - "is invalid"); + NEARBY_LOGS(INFO) + << "BleAdvertisement doesn't conform to the format, discarding."; return false; } if (advertisement.GetVersion() != kBleAdvertisementVersion) { - NEARBY_LOG( - INFO, - "P2pClusterPcpHandler::IsRecognizedBluetoothEndpoint: Version is " - "not matched; advertisement.Version=%d, Version=%d", - advertisement.GetVersion(), kBleAdvertisementVersion); + NEARBY_LOGS(INFO) << "BleAdvertisement has an unknown version; expected " + << static_cast(kBleAdvertisementVersion) + << ", found " + << static_cast(advertisement.GetVersion()); return false; } if (advertisement.GetPcp() != GetPcp()) { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::IsRecognizedBluetoothEndpoint: Pcp is " - "not matched; advertisement.Pcp=%d, Pcp=%d", - advertisement.GetPcp(), GetPcp()); + NEARBY_LOGS(INFO) << "BleAdvertisement doesn't match on Pcp; expected " + << PcpToStrategy(GetPcp()).GetName() << ", found " + << PcpToStrategy(advertisement.GetPcp()).GetName(); return false; } @@ -404,12 +398,12 @@ bool P2pClusterPcpHandler::IsRecognizedBleEndpoint( GenerateHash(service_id, BleAdvertisement::kServiceIdHashLength); if (advertisement.GetServiceIdHash() != expected_service_id_hash) { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::IsRecognizedBleEndpoint: service " - "id hash is " - "not matched; advertisement.service_id_hash=%s, expected=%s", - advertisement.GetServiceIdHash().data(), - expected_service_id_hash.data()); + NEARBY_LOGS(INFO) + << "BleAdvertisement doesn't match on expected service_id_hash; " + "expected " + << absl::BytesToHexString(expected_service_id_hash.data()) + << ", found " + << absl::BytesToHexString(advertisement.GetServiceIdHash().data()); return false; } } @@ -427,11 +421,10 @@ void P2pClusterPcpHandler::BlePeripheralDiscoveredHandler( fast_advertisement]() RUN_ON_PCP_HANDLER_THREAD() { // Make sure we are still discovering before proceeding. if (!client->IsDiscovering()) { - NEARBY_LOG( - INFO, - "Ble scanning handler (FOUND) [client=%p, service_id=%s]: not " - "in discovery mode", - client, service_id.c_str()); + NEARBY_LOGS(WARNING) + << "Skipping discovery of BleAdvertisement header " + << absl::BytesToHexString(advertisement_bytes.data()) + << " because we are no longer discovering."; return; } @@ -451,26 +444,29 @@ void P2pClusterPcpHandler::BlePeripheralDiscoveredHandler( advertisement.GetEndpointInfo())); // Report the discovered endpoint to the client. - NEARBY_LOGS(INFO) - << "Invoking BasePcpHandler::OnEndpointFound() for Ble service=" - << service_id << "; id=" << advertisement.GetEndpointId() - << "; name=" - << absl::BytesToHexString(advertisement.GetEndpointInfo().data()); - OnEndpointFound( - client, - std::make_shared(BleEndpoint{ - {advertisement.GetEndpointId(), advertisement.GetEndpointInfo(), - service_id, proto::connections::Medium::BLE, - advertisement.GetWebRtcState()}, - peripheral, - })); + NEARBY_LOGS(INFO) << "Found BleAdvertisement " + << absl::BytesToHexString(advertisement_bytes.data()) + << " (with endpoint_id=" + << advertisement.GetEndpointId() + << ", and endpoint_info=" + << absl::BytesToHexString( + advertisement.GetEndpointInfo().data()) + << ").", + OnEndpointFound(client, + std::make_shared(BleEndpoint{ + {advertisement.GetEndpointId(), + advertisement.GetEndpointInfo(), service_id, + proto::connections::Medium::BLE, + advertisement.GetWebRtcState()}, + peripheral, + })); // Make sure we can connect to this device via Classic Bluetooth. std::string remote_bluetooth_mac_address = advertisement.GetBluetoothMacAddress(); if (remote_bluetooth_mac_address.empty()) { NEARBY_LOGS(INFO) - << "No Bluetooth Classic MAC address found in advertisement"; + << "No Bluetooth Classic MAC address found in advertisement."; return; } @@ -478,8 +474,8 @@ void P2pClusterPcpHandler::BlePeripheralDiscoveredHandler( bluetooth_medium_.GetRemoteDevice(remote_bluetooth_mac_address); if (!remote_bluetooth_device.IsValid()) { NEARBY_LOGS(INFO) - << "A valid Bluetooth device could not be derived from " - "the MAC address " + << "A valid Bluetooth device could not be derived from the MAC " + "address " << remote_bluetooth_mac_address; return; } @@ -509,11 +505,9 @@ void P2pClusterPcpHandler::BlePeripheralLostHandler( [this, client, service_id, &peripheral]() RUN_ON_PCP_HANDLER_THREAD() { // Make sure we are still discovering before proceeding. if (!client->IsDiscovering()) { - NEARBY_LOG( - INFO, - "Ble scanning handler (LOST) [client=%p, service_id=%s]: not " - "in scanning mode", - client, service_id.c_str()); + NEARBY_LOGS(WARNING) + << "Ignoring lost BlePeripheral " << peripheral.GetName() + << " because we are no longer discovering."; return; } @@ -525,10 +519,12 @@ void P2pClusterPcpHandler::BlePeripheralLostHandler( found_ble_endpoints_.erase(item); // Report the discovered endpoint to the client. - NEARBY_LOG(INFO, - "Ble scanning handler (LOST) [client=%p, " - "service_id=%s]: report to client", - client, service_id.c_str()); + NEARBY_LOGS(INFO) + << "Lost BleEndpoint for BlePeripheral " << peripheral.GetName() + << " (with endpoint_id=" << ble_endpoint_state.endpoint_id + << " and endpoint_info=" + << absl::BytesToHexString(ble_endpoint_state.endpoint_info.data()) + << ")."; OnEndpointLost(client, DiscoveredEndpoint{ ble_endpoint_state.endpoint_id, ble_endpoint_state.endpoint_info, @@ -544,17 +540,15 @@ bool P2pClusterPcpHandler::IsRecognizedWifiLanEndpoint( const std::string& service_id, const WifiLanServiceInfo& service_info) const { if (!service_info.IsValid()) { - NEARBY_LOG( - INFO, - "P2pClusterPcpHandler::IsRecognizedWifiLanEndpoint: name is invalid"); + NEARBY_LOGS(INFO) + << "WifiLanServiceInfo doesn't conform to the format, discarding."; return false; } if (service_info.GetPcp() != GetPcp()) { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::IsRecognizedWifiLanEndpoint: Pcp is " - "not matched; name.Pcp=%d, Pcp=%d", - service_info.GetPcp(), GetPcp()); + NEARBY_LOGS(INFO) << "WifiLanServiceInfo doesn't match on Pcp; expected " + << PcpToStrategy(GetPcp()).GetName() << ", found " + << PcpToStrategy(service_info.GetPcp()).GetName(); return false; } @@ -562,12 +556,11 @@ bool P2pClusterPcpHandler::IsRecognizedWifiLanEndpoint( GenerateHash(service_id, BluetoothDeviceName::kServiceIdHashLength); if (service_info.GetServiceIdHash() != expected_service_id_hash) { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::IsRecognizedWifiLanEndpoint: service " - "id hash is " - "not matched; name.service_id_hash=%s, expected=%s", - service_info.GetServiceIdHash().data(), - expected_service_id_hash.data()); + NEARBY_LOGS(INFO) + << "WifiLanServiceInfo doesn't match on expected service_id_hash; " + "expected " + << absl::BytesToHexString(expected_service_id_hash.data()) << ", found " + << absl::BytesToHexString(service_info.GetServiceIdHash().data()); return false; } @@ -579,44 +572,44 @@ void P2pClusterPcpHandler::WifiLanServiceDiscoveredHandler( const std::string& service_id) { RunOnPcpHandlerThread( "p2p-wifi-service-discovered", - [this, client, service_id, - &wifi_lan_service]() RUN_ON_PCP_HANDLER_THREAD() { - // Make sure we are still discovering before proceeding. - if (!client->IsDiscovering()) { - NEARBY_LOG( - INFO, - "WifiLan discovery handler (FOUND) [client=%p, service=%s]: not " - "in discovery mode", - client, service_id.c_str()); - return; - } + [this, client, service_id, &wifi_lan_service]() + RUN_ON_PCP_HANDLER_THREAD() { + // Make sure we are still discovering before proceeding. + if (!client->IsDiscovering()) { + NEARBY_LOGS(WARNING) + << "Skipping discovery of NsdServiceInfo " + << wifi_lan_service.GetServiceInfo().GetServiceInfoName() + << " because we are no longer discovering."; + return; + } - // Parse the WifiLanServiceInfo. - WifiLanServiceInfo service_info(wifi_lan_service.GetServiceInfo()); + // Parse the WifiLanServiceInfo. + WifiLanServiceInfo service_info(wifi_lan_service.GetServiceInfo()); - // Make sure the WifiLan service name points to a valid - // endpoint we're discovering. - if (!IsRecognizedWifiLanEndpoint(service_id, service_info)) return; + // Make sure the WifiLan service name points to a valid + // endpoint we're discovering. + if (!IsRecognizedWifiLanEndpoint(service_id, service_info)) return; - // Report the discovered endpoint to the client. - NEARBY_LOG(INFO, - "Invoking BasePcpHandler::OnEndpointFound() for WifiLan " - "service_id=%s; endpoint_id=%s; endpoint_info=%s", - service_id.c_str(), service_info.GetEndpointId().c_str(), - absl::BytesToHexString(service_info.GetEndpointInfo().data()) - .c_str()); - OnEndpointFound(client, - std::make_shared(WifiLanEndpoint{ - { - service_info.GetEndpointId(), - service_info.GetEndpointInfo(), - service_id, - proto::connections::Medium::WIFI_LAN, - service_info.GetWebRtcState(), - }, - wifi_lan_service, - })); - }); + // Report the discovered endpoint to the client. + NEARBY_LOGS(INFO) + << "Found NsdServiceInfo " + << wifi_lan_service.GetServiceInfo().GetServiceInfoName() + << " (with endpoint_id=" << service_info.GetEndpointId() + << "and endpoint_info=" + << absl::BytesToHexString(service_info.GetEndpointInfo().data()) + << ")."; + OnEndpointFound(client, + std::make_shared(WifiLanEndpoint{ + { + service_info.GetEndpointId(), + service_info.GetEndpointInfo(), + service_id, + proto::connections::Medium::WIFI_LAN, + service_info.GetWebRtcState(), + }, + wifi_lan_service, + })); + }); } void P2pClusterPcpHandler::WifiLanServiceLostHandler( @@ -628,39 +621,40 @@ void P2pClusterPcpHandler::WifiLanServiceLostHandler( &wifi_lan_service, nsd_service_info.GetServiceInfoName().c_str()); RunOnPcpHandlerThread( "p2p-wifi-service-lost", - [this, client, service_id, - nsd_service_info]() RUN_ON_PCP_HANDLER_THREAD() { - // Make sure we are still discovering before proceeding. - if (!client->IsDiscovering()) { - NEARBY_LOG( - INFO, - "WifiLan discovery handler (LOST) [client=%p, service=%s]: not " - "in discovery mode", - client, service_id.c_str()); - return; - } + [this, client, service_id, nsd_service_info]() + RUN_ON_PCP_HANDLER_THREAD() { + // Make sure we are still discovering before proceeding. + if (!client->IsDiscovering()) { + NEARBY_LOGS(WARNING) << "Ignoring lost NsdServiceInfo " + << nsd_service_info.GetServiceInfoName() + << " because we are no longer " + "discovering."; + return; + } - // Parse the WifiLanServiceInfo. - WifiLanServiceInfo service_info(nsd_service_info); + // Parse the WifiLanServiceInfo. + WifiLanServiceInfo service_info(nsd_service_info); - // Make sure the WifiLan service name points to a valid - // endpoint we're discovering. - if (!IsRecognizedWifiLanEndpoint(service_id, service_info)) return; + // Make sure the WifiLan service name points to a valid + // endpoint we're discovering. + if (!IsRecognizedWifiLanEndpoint(service_id, service_info)) return; - // Report the discovered endpoint to the client. - NEARBY_LOG(INFO, - "WifiLan discovery handler (LOST) [client=%p, " - "service_id=%s]: report " - "to client", - client, service_id.c_str()); - OnEndpointLost(client, DiscoveredEndpoint{ - service_info.GetEndpointId(), - service_info.GetEndpointInfo(), - service_id, - proto::connections::Medium::WIFI_LAN, - WebRtcState::kUndefined, - }); - }); + // Report the lost endpoint to the client. + NEARBY_LOGS(INFO) + << "Lost NsdServiceInfo " + << nsd_service_info.GetServiceInfoName() + << " (with endpoint_id=" << service_info.GetEndpointId() + << " and endpoint_info=" + << absl::BytesToHexString(service_info.GetEndpointInfo().data()) + << ")."; + OnEndpointLost(client, DiscoveredEndpoint{ + service_info.GetEndpointId(), + service_info.GetEndpointInfo(), + service_id, + proto::connections::Medium::WIFI_LAN, + WebRtcState::kUndefined, + }); + }); } BasePcpHandler::StartOperationResult P2pClusterPcpHandler::StartDiscoveryImpl( @@ -730,7 +724,11 @@ BasePcpHandler::StartOperationResult P2pClusterPcpHandler::StartDiscoveryImpl( } if (mediums_started_successfully.empty()) { - NEARBY_LOG(INFO, "P2pClusterPcpHandler::StartDiscoveryImpl: nothing added"); + NEARBY_LOGS(FATAL) + << "Failed StartDiscovery() for client=" << client->GetClientId() + << " because we couldn't scan on Bluetooth, BLE, or WifiLan for " + "service_id=" + << service_id; return { .status = {Status::kBluetoothError}, }; @@ -748,10 +746,10 @@ Status P2pClusterPcpHandler::StopDiscoveryImpl(ClientProxy* client) { bluetooth_medium_.StopDiscovery(); bluetooth_classic_discoverer_client_id_ = 0; } else { - NEARBY_LOG(INFO, - "Skipped BT stopDiscovery for client %d, client that started " - "discovery is %d", - client->GetClientId(), bluetooth_classic_discoverer_client_id_); + NEARBY_LOGS(INFO) << "Skipped BT StopDiscovery for client=" + << client->GetClientId() + << ", client that started discovery is " + << bluetooth_classic_discoverer_client_id_; } ble_medium_.StopScanning(client->GetDiscoveryServiceId()); @@ -761,10 +759,10 @@ Status P2pClusterPcpHandler::StopDiscoveryImpl(ClientProxy* client) { Status P2pClusterPcpHandler::InjectEndpointImpl( ClientProxy* client, const std::string& service_id, const OutOfBandConnectionMetadata& metadata) { - NEARBY_LOG(INFO, "InjectEndpoint"); + NEARBY_LOGS(INFO) << "InjectEndpoint."; // Bluetooth is the only supported out-of-band connection medium. if (metadata.medium != Medium::BLUETOOTH) { - NEARBY_LOG(WARNING, "InjectEndpointImpl: Only Bluetooth is supported"); + NEARBY_LOGS(WARNING) << "InjectEndpointImpl: Only Bluetooth is supported."; return {Status::kError}; } @@ -776,7 +774,7 @@ Status P2pClusterPcpHandler::InjectEndpointImpl( GetPcp()); if (!remote_bluetooth_device.IsValid()) { - NEARBY_LOG(WARNING, "InjectEndpointImpl: Invalid parameters"); + NEARBY_LOG(WARNING, "InjectEndpointImpl: Invalid parameters."); return {Status::kError}; } @@ -835,91 +833,97 @@ proto::connections::Medium P2pClusterPcpHandler::StartBluetoothAdvertising( INFO, "P2pClusterPcpHandler::StartBluetoothAdvertising: service=%s: start", service_id.c_str()); - if (bluetooth_medium_.IsAcceptingConnections(service_id)) { - NEARBY_LOG(INFO, "BT is already accepting connections for service=%s", - service_id.c_str()); - return proto::connections::UNKNOWN_MEDIUM; + if (!bluetooth_medium_.IsAcceptingConnections(service_id)) { + if (!bluetooth_radio_.Enable() || + !bluetooth_medium_.StartAcceptingConnections( + service_id, {.accepted_cb = [this, client, local_endpoint_info]( + BluetoothSocket socket) { + if (!socket.IsValid()) { + NEARBY_LOGS(WARNING) + << "Invalid socket in accept callback(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId(); + return; + } + RunOnPcpHandlerThread( + "p2p-bt-on-incoming-connection", + [this, client, local_endpoint_info, + socket = std::move(socket)]() + RUN_ON_PCP_HANDLER_THREAD() mutable { + std::string remote_device_name = + socket.GetRemoteDevice().GetName(); + auto channel = + absl::make_unique( + remote_device_name, socket); + ByteArray remote_device_info{remote_device_name}; + + OnIncomingConnection( + client, remote_device_info, std::move(channel), + proto::connections::Medium::BLUETOOTH); + }); + }})) { + NEARBY_LOGS(WARNING) + << "In StartBluetoothAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " failed to start listening for incoming Bluetooth " + "connections to service_id=" + << service_id; + return proto::connections::UNKNOWN_MEDIUM; + } + NEARBY_LOGS(INFO) + << "In StartBluetoothAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " started listening for incoming Bluetooth connections to " + "service_id=" + << service_id; } - NEARBY_LOG( - INFO, - "P2pClusterPcpHandler::StartBluetoothAdvertising: service=%s: invoking", - service_id.c_str()); - if (!bluetooth_radio_.Enable() || - !bluetooth_medium_.StartAcceptingConnections( - service_id, {.accepted_cb = [this, client, local_endpoint_info]( - BluetoothSocket socket) { - if (!socket.IsValid()) { - NEARBY_LOG(ERROR, "Invalid socket in accept callback: name=%s", - std::string(local_endpoint_info).c_str()); - return; - } - RunOnPcpHandlerThread( - "p2p-bt-on-incoming-connection", - [this, client, local_endpoint_info, - socket = - std::move(socket)]() RUN_ON_PCP_HANDLER_THREAD() mutable { - std::string remote_device_name = - socket.GetRemoteDevice().GetName(); - auto channel = absl::make_unique( - remote_device_name, socket); - ByteArray remote_device_info{remote_device_name}; - - OnIncomingConnection(client, remote_device_info, - std::move(channel), - proto::connections::Medium::BLUETOOTH); - }); - }})) { - NEARBY_LOG(INFO, "BT failed to start accepting connections for service=%s", - service_id.c_str()); - return proto::connections::UNKNOWN_MEDIUM; - } - - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartBluetoothAdvertising: service=%s: " - "make name; id=%s, hash=%s, name=%s", - service_id.c_str(), local_endpoint_id.c_str(), - absl::BytesToHexString(service_id_hash.data()).c_str(), - absl::BytesToHexString(local_endpoint_info.data()).c_str()); // Generate a BluetoothDeviceName with which to become Bluetooth discoverable. // TODO(b/169550050): Implement UWBAddress. std::string device_name(BluetoothDeviceName( kBluetoothDeviceNameVersion, GetPcp(), local_endpoint_id, service_id_hash, local_endpoint_info, ByteArray{}, web_rtc_state)); if (device_name.empty()) { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartBluetoothAdvertising: generate " - "BluetoothDeviceName failed"); + NEARBY_LOGS(WARNING) << "In StartBluetoothAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " failed to generate BluetoothDeviceName {version=" + << static_cast(kBluetoothDeviceNameVersion) + << ", pcp=" << PcpToStrategy(GetPcp()).GetName() + << ", endpoint_id=" << local_endpoint_id + << ", service_id_hash=" + << absl::BytesToHexString(service_id_hash.data()) + << ", endpoint_info=" + << absl::BytesToHexString(local_endpoint_info.data()) + << "}."; bluetooth_medium_.StopAcceptingConnections(service_id); return proto::connections::UNKNOWN_MEDIUM; - } else { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartBluetoothAdvertising: generate " - "BluetoothDeviceName succeeded; device_name=%s", - device_name.c_str()); } + NEARBY_LOGS(INFO) << "In StartBluetoothAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " generated BluetoothDeviceName %s with service_id=" + << service_id; - NEARBY_LOG( - INFO, - "P2pClusterPcpHandler::StartBluetoothAdvertising: service=%s: come up", - service_id.c_str()); // Become Bluetooth discoverable. if (!bluetooth_medium_.TurnOnDiscoverability(device_name)) { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartBluetoothAdvertising: failed to " - "turn on discoverability, device_name=%s", - device_name.c_str()); + NEARBY_LOGS(INFO) + << "In StartBluetoothAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " couldn't start Bluetooth advertising with BluetoothDeviceName " + << device_name; bluetooth_medium_.StopAcceptingConnections(service_id); return proto::connections::UNKNOWN_MEDIUM; - } else { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartBluetoothAdvertising: succeeded to " - "turn on discoverability, device_name=%s", - device_name.c_str()); } - NEARBY_LOG( - INFO, "P2pClusterPcpHandler::StartBluetoothAdvertising: service=%s: done", - service_id.c_str()); + NEARBY_LOGS(INFO) + << "In StartBluetoothAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " started Bluetooth advertising with BluetoothDeviceName " + << device_name; return proto::connections::BLUETOOTH; } @@ -928,22 +932,35 @@ proto::connections::Medium P2pClusterPcpHandler::StartBluetoothDiscovery( const std::string& service_id) { if (bluetooth_radio_.Enable() && bluetooth_medium_.StartDiscovery(std::move(callback))) { - NEARBY_LOG(INFO, "P2pClusterPcpHandler::StartBluetoothDiscovery: ok"); + NEARBY_LOGS(INFO) << "In StartBluetoothDiscovery(), client=" + << client->GetClientId() + << " started scanning for Bluetooth for service_id=" + << service_id; return proto::connections::BLUETOOTH; } else { - NEARBY_LOG(INFO, "P2pClusterPcpHandler::StartBluetoothDiscovery: failed"); + NEARBY_LOGS(INFO) << "In StartBluetoothDiscovery(), client=" + << client->GetClientId() + << " couldn't start scanning on Bluetooth for service_id=" + << service_id; return proto::connections::UNKNOWN_MEDIUM; } } BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::BluetoothConnectImpl( ClientProxy* client, BluetoothEndpoint* endpoint) { + NEARBY_LOGS(VERBOSE) << "Client " << client->GetClientId() + << " is attempting to connect to endpoint(id=" + << endpoint->endpoint_id << ") over Bluetooth Classic."; BluetoothDevice& device = endpoint->bluetooth_device; BluetoothSocket bluetooth_socket = bluetooth_medium_.Connect( device, endpoint->service_id, client->GetCancellationFlag(endpoint->endpoint_id)); if (!bluetooth_socket.IsValid()) { + NEARBY_LOGS(ERROR) + << "In BluetoothConnectImpl(), failed to connect to Bluetooth device " + << device.GetName() << " for endpoint(id=" << endpoint->endpoint_id + << ")."; return BasePcpHandler::ConnectImplResult{ .status = {Status::kBluetoothError}, }; @@ -951,7 +968,9 @@ BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::BluetoothConnectImpl( auto channel = absl::make_unique( endpoint->endpoint_id, bluetooth_socket); - + NEARBY_LOGS(VERBOSE) << "Client" << client->GetClientId() + << " created Bluetooth endpoint channel to endpoint(id=" + << endpoint->endpoint_id << ")."; return BasePcpHandler::ConnectImplResult{ .medium = proto::connections::Medium::BLUETOOTH, .status = {Status::kSuccess}, @@ -972,7 +991,7 @@ proto::connections::Medium P2pClusterPcpHandler::StartBleAdvertising( // well as advertising the Bluetooth MAC address to allow connecting over // Bluetooth Classic. NEARBY_LOGS(INFO) << "P2pClusterPcpHandler::StartBleAdvertising: service_id=" - << service_id << ": start"; + << service_id << " : start"; if (!ble_medium_.IsAcceptingConnections(service_id)) { if (!bluetooth_radio_.Enable() || !ble_medium_.StartAcceptingConnections( @@ -980,8 +999,10 @@ proto::connections::Medium P2pClusterPcpHandler::StartBleAdvertising( BleSocket socket, const std::string& service_id) { if (!socket.IsValid()) { - NEARBY_LOG(INFO, "Invalid socket in accept callback: name=%s", - std::string(local_endpoint_info).c_str()); + NEARBY_LOGS(WARNING) + << "Invalid socket in accept callback(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId(); return; } RunOnPcpHandlerThread( @@ -1002,13 +1023,20 @@ proto::connections::Medium P2pClusterPcpHandler::StartBleAdvertising( proto::connections::Medium::BLE); }); }})) { - NEARBY_LOGS(INFO) - << "Ble failed to start accepting connections for service_id=" + NEARBY_LOGS(WARNING) + << "In StartBleAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " failed to start accepting for incoming BLE connections to " + "service_id=" << service_id; return proto::connections::UNKNOWN_MEDIUM; } NEARBY_LOGS(INFO) - << "Ble succeed to start accepting connections for service_id=" + << "In StartBleAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " started accepting for incoming BLE connections to service_id=" << service_id; } @@ -1021,8 +1049,11 @@ proto::connections::Medium P2pClusterPcpHandler::StartBleAdvertising( service_id, {.accepted_cb = [this, client, local_endpoint_info]( BluetoothSocket socket) { if (!socket.IsValid()) { - NEARBY_LOG(INFO, "Invalid socket in accept callback: name=%s", - std::string(local_endpoint_info).c_str()); + NEARBY_LOGS(WARNING) + << "In BT StartAcceptingConnections.accepted_cb(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << ": Invalid socket in accept callback."; return; } RunOnPcpHandlerThread( @@ -1042,21 +1073,31 @@ proto::connections::Medium P2pClusterPcpHandler::StartBleAdvertising( proto::connections::Medium::BLUETOOTH); }); }})) { - NEARBY_LOGS(INFO) - << "BT failed to start accepting connections for service_id=" + NEARBY_LOGS(WARNING) + << "In BT StartBleAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " failed to start accepting for incoming BLE connections to " + "service_id=" << service_id; ble_medium_.StopAcceptingConnections(service_id); return proto::connections::UNKNOWN_MEDIUM; } NEARBY_LOGS(INFO) - << "BT succeed to start accepting connections for service_id=" + << "In BT StartBleAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " started accepting for incoming BLE connections to service_id=" << service_id; } } - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartBleAdvertising: service=%s, id=%s", - service_id.c_str(), local_endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "In StartBleAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " start to generate BleAdvertisement with service_id=" + << service_id + << ", local endpoint_id=" << local_endpoint_id; // Generate a BleAdvertisement. If a fast advertisement service UUID was // provided, create a fast BleAdvertisement. ByteArray advertisement_bytes; @@ -1079,28 +1120,36 @@ proto::connections::Medium P2pClusterPcpHandler::StartBleAdvertising( bluetooth_mac_address, ByteArray{}, web_rtc_state)); } if (advertisement_bytes.Empty()) { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartBleAdvertising: generate " - "BleAdvertisement failed"); - ble_medium_.StopAcceptingConnections(service_id); + NEARBY_LOGS(WARNING) << "In StartBleAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " failed to create an advertisement.", + ble_medium_.StopAcceptingConnections(service_id); return proto::connections::UNKNOWN_MEDIUM; } - NEARBY_LOG( - INFO, "P2pClusterPcpHandler::StartBleAdvertising: service_id=%s: come up", - service_id.c_str()); + NEARBY_LOGS(INFO) << "In StartBleAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " generated BleAdvertisement with service_id=" + << service_id; if (!ble_medium_.StartAdvertising(service_id, advertisement_bytes, options.fast_advertisement_service_uuid)) { - NEARBY_LOGS(ERROR) - << "P2pClusterPcpHandler::StartBleAdvertising: failed to " - "start advertising, advertisement_bytes=" + NEARBY_LOGS(WARNING) + << "In StartBleAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " couldn't start BLE Advertising with BleAdvertisement " << absl::BytesToHexString(advertisement_bytes.data()); ble_medium_.StopAcceptingConnections(service_id); return proto::connections::UNKNOWN_MEDIUM; } - NEARBY_LOGS(INFO) << "P2pClusterPcpHandler::StartBleAdvertising: service_id=" - << service_id << ": done"; + NEARBY_LOGS(INFO) << "In startBleAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " started BLE Advertising with BleAdvertisement " + << absl::BytesToHexString(advertisement_bytes.data()); return proto::connections::BLE; } @@ -1111,22 +1160,36 @@ proto::connections::Medium P2pClusterPcpHandler::StartBleScanning( if (bluetooth_radio_.Enable() && ble_medium_.StartScanning(service_id, fast_advertisement_service_uuid, std::move(callback))) { - NEARBY_LOGS(INFO) << "P2pClusterPcpHandler::StartBleScanning: ok"; + NEARBY_LOGS(INFO) + << "In StartBleScanning(), client=" << client->GetClientId() + << " started scanning for BLE advertisements for service_id=" + << service_id; return proto::connections::BLE; } else { - NEARBY_LOGS(INFO) << "P2pClusterPcpHandler::StartBleScanning: failed"; + NEARBY_LOGS(INFO) << "In StartBleScanning(), client=" + << client->GetClientId() + << " couldn't start scanning on BLE for service_id=" + << service_id; return proto::connections::UNKNOWN_MEDIUM; } } BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::BleConnectImpl( ClientProxy* client, BleEndpoint* endpoint) { + NEARBY_LOGS(VERBOSE) << "Client " << client->GetClientId() + << " is attempting to connect to endpoint(id=" + << endpoint->endpoint_id << ") over BLE."; + BlePeripheral& peripheral = endpoint->ble_peripheral; BleSocket ble_socket = ble_medium_.Connect(peripheral, endpoint->service_id, client->GetCancellationFlag(endpoint->endpoint_id)); if (!ble_socket.IsValid()) { + NEARBY_LOGS(ERROR) + << "In BleConnectImpl(), failed to connect to BLE device " + << peripheral.GetName() << " for endpoint(id=" << endpoint->endpoint_id + << ")."; return BasePcpHandler::ConnectImplResult{ .status = {Status::kBleError}, }; @@ -1151,55 +1214,52 @@ proto::connections::Medium P2pClusterPcpHandler::StartWifiLanAdvertising( NEARBY_LOG(INFO, "P2pClusterPcpHandler::StartWifiLanAdvertising: service=%s: start", service_id.c_str()); - if (wifi_lan_medium_.IsAcceptingConnections(service_id)) { - NEARBY_LOG(INFO, "WifiLan is already accepting connections for service=%s", - service_id.c_str()); - return proto::connections::UNKNOWN_MEDIUM; + if (!wifi_lan_medium_.IsAcceptingConnections(service_id)) { + if (!wifi_lan_medium_.StartAcceptingConnections( + service_id, {.accepted_cb = [this, client, local_endpoint_info]( + WifiLanSocket socket, + const std::string& service_id) { + if (!socket.IsValid()) { + NEARBY_LOGS(WARNING) + << "Invalid socket in accept callback(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId(); + return; + } + RunOnPcpHandlerThread( + "p2p-wifi-on-incoming-connection", + [this, client, local_endpoint_info, + socket = std::move(socket)]() + RUN_ON_PCP_HANDLER_THREAD() mutable { + std::string remote_service_info_name = + socket.GetRemoteWifiLanService() + .GetServiceInfo() + .GetServiceInfoName(); + auto channel = + absl::make_unique( + remote_service_info_name, socket); + ByteArray remote_service_info{remote_service_info_name}; + + OnIncomingConnection( + client, remote_service_info, std::move(channel), + proto::connections::Medium::WIFI_LAN); + }); + }})) { + NEARBY_LOGS(WARNING) + << "In StartWifiLanAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " failed to start listening for incoming WifiLan connections " + "to service_id=" + << service_id; + return proto::connections::UNKNOWN_MEDIUM; + } + NEARBY_LOGS(INFO) + << "In StartWifiLanAdvertising(%s), client=" << client->GetClientId() + << " started listening for incoming WifiLan connections to service_id=" + << service_id; } - NEARBY_LOG( - INFO, - "P2pClusterPcpHandler::StartWifiLanAdvertising: service=%s: invoking", - service_id.c_str()); - if (!wifi_lan_medium_.StartAcceptingConnections( - service_id, {.accepted_cb = [this, client, local_endpoint_info]( - WifiLanSocket socket, - const std::string& service_id) { - if (!socket.IsValid()) { - NEARBY_LOG(INFO, "Invalid socket in accept callback: name=%s", - std::string(local_endpoint_info).c_str()); - return; - } - RunOnPcpHandlerThread( - "p2p-wifi-on-incoming-connection", - [this, client, local_endpoint_info, - socket = std::move(socket)]() - RUN_ON_PCP_HANDLER_THREAD() mutable { - std::string remote_service_info_name = - socket.GetRemoteWifiLanService() - .GetServiceInfo() - .GetServiceInfoName(); - auto channel = absl::make_unique( - remote_service_info_name, socket); - ByteArray remote_service_info{remote_service_info_name}; - - OnIncomingConnection( - client, remote_service_info, std::move(channel), - proto::connections::Medium::WIFI_LAN); - }); - }})) { - NEARBY_LOG(INFO, - "WifiLan failed to start accepting connections for service=%s", - service_id.c_str()); - return proto::connections::UNKNOWN_MEDIUM; - } - - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartWifiLanAdvertising: service=%s: " - "make name; id=%s, hash=%s, endpoint info=%s", - service_id.c_str(), local_endpoint_id.c_str(), - absl::BytesToHexString(service_id_hash.data()).c_str(), - absl::BytesToHexString(local_endpoint_info.data()).c_str()); // Generate a WifiLanServiceInfo with which to become WifiLan discoverable. // TODO(b/169550050): Implement UWBAddress. WifiLanServiceInfo service_info{kWifiLanServiceInfoVersion, @@ -1211,34 +1271,40 @@ proto::connections::Medium P2pClusterPcpHandler::StartWifiLanAdvertising( web_rtc_state}; NsdServiceInfo nsd_service_info{service_info}; if (!nsd_service_info.IsValid()) { - NEARBY_LOGS(INFO) - << "P2pClusterPcpHandler::StartWifiLanAdvertising: generate " - "NsdServiceInfo failed"; + NEARBY_LOGS(WARNING) << "In StartWifiLanAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " failed to generate WifiLanServiceInfo {version=" + << static_cast(kWifiLanServiceInfoVersion) + << ", pcp=" << PcpToStrategy(GetPcp()).GetName() + << ", endpoint_id=" << local_endpoint_id + << ", service_id_hash=" + << absl::BytesToHexString(service_id_hash.data()) + << ", endpoint_info=" + << absl::BytesToHexString(local_endpoint_info.data()) + << "}."; wifi_lan_medium_.StopAcceptingConnections(service_id); return proto::connections::UNKNOWN_MEDIUM; - } else { - NEARBY_LOGS(INFO) - << "P2pClusterPcpHandler::StartWifiLanAdvertising: generate " - "NsdServiceInfo succeeded; service_info_name=" - << nsd_service_info.GetServiceInfoName(); } - - NEARBY_LOG( - INFO, - "P2pClusterPcpHandler::StartWifiLanAdvertising: service=%s: come up", - service_id.c_str()); + NEARBY_LOGS(INFO) << "In StartWifiLanAdvertising(%s), client=" + << client->GetClientId() << " generated WifiLanServiceInfo " + << nsd_service_info.GetServiceInfoName() + << " with service_id=" << service_id; if (!wifi_lan_medium_.StartAdvertising(service_id, nsd_service_info)) { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartWifiLanAdvertising: failed to " - "start advertising, service_info_name=%s", - nsd_service_info.GetServiceInfoName().c_str()); + NEARBY_LOGS(INFO) << "In StartWifiLanAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " couldn't advertise with WifiLanServiceInfo " + << nsd_service_info.GetServiceInfoName(); wifi_lan_medium_.StopAcceptingConnections(service_id); return proto::connections::UNKNOWN_MEDIUM; } - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartWifiLanAdvertising: service=%s: done", - service_id.c_str()); + NEARBY_LOGS(INFO) << "In StartWifiLanAdvertising(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " advertised with WifiLanServiceInfo " + << nsd_service_info.GetServiceInfoName(); return proto::connections::WIFI_LAN; } @@ -1246,22 +1312,35 @@ proto::connections::Medium P2pClusterPcpHandler::StartWifiLanDiscovery( WifiLanDiscoveredServiceCallback callback, ClientProxy* client, const std::string& service_id) { if (wifi_lan_medium_.StartDiscovery(service_id, std::move(callback))) { - NEARBY_LOG(INFO, "P2pClusterPcpHandler::StartWifiLanDiscovery: ok"); + NEARBY_LOGS(INFO) << "In StartWifiLanDiscovery(), client=" + << client->GetClientId() + << " started scanning for Wifi devices for service_id=" + << service_id; return proto::connections::WIFI_LAN; } else { - NEARBY_LOG(INFO, "P2pClusterPcpHandler::StartWifiLanDiscovery: failed"); + NEARBY_LOGS(INFO) << "In StartWifiLanDiscovery(), client=" + << client->GetClientId() + << " couldn't start scanning on Wifi for service_id=" + << service_id; return proto::connections::UNKNOWN_MEDIUM; } } BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::WifiLanConnectImpl( ClientProxy* client, WifiLanEndpoint* endpoint) { + NEARBY_LOGS(VERBOSE) << "Client " << client->GetClientId() + << " is attempting to connect to endpoint(id=" + << endpoint->endpoint_id << ") over WifiLan."; WifiLanService& wifi_lan_service = endpoint->wifi_lan_service; WifiLanSocket wifi_lan_socket = wifi_lan_medium_.Connect( wifi_lan_service, endpoint->service_id, client->GetCancellationFlag(endpoint->endpoint_id)); if (!wifi_lan_socket.IsValid()) { + NEARBY_LOGS(ERROR) + << "In WifiLanConnectImpl(), failed to connect to service " + << wifi_lan_service.GetServiceInfo().GetServiceInfoName() + << " for endpoint(id=" << endpoint->endpoint_id << ")."; return BasePcpHandler::ConnectImplResult{ .status = {Status::kWifiLanError}, }; @@ -1269,7 +1348,9 @@ BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::WifiLanConnectImpl( auto channel = absl::make_unique( endpoint->endpoint_id, wifi_lan_socket); - + NEARBY_LOGS(VERBOSE) << "Client " << client->GetClientId() + << " created WifiLan endpoint channel to endpoint(id=" + << endpoint->endpoint_id << ")."; return BasePcpHandler::ConnectImplResult{ .medium = proto::connections::Medium::WIFI_LAN, .status = {Status::kSuccess}, @@ -1295,27 +1376,41 @@ P2pClusterPcpHandler::StartListeningForWebRtcConnections( {[this, client, local_endpoint_info](mediums::WebRtcSocketWrapper socket) { if (!socket.IsValid()) { - NEARBY_LOG(INFO, "Invalid socket in accept callback: name=%s", - std::string(local_endpoint_info).c_str()); + NEARBY_LOGS(WARNING) + << "Invalid socket in accept callback(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId(); return; } RunOnPcpHandlerThread( "p2p-rtc-on-incoming-connection", - [this, client, - socket = std::move(socket)]() RUN_ON_PCP_HANDLER_THREAD() { - std::string remote_device_name = "WebRtcSocket"; - auto channel = absl::make_unique( - remote_device_name, socket); - ByteArray remote_device_info{remote_device_name}; + [this, client, socket = std::move(socket)]() + RUN_ON_PCP_HANDLER_THREAD() { + std::string remote_device_name = "WebRtcSocket"; + auto channel = absl::make_unique( + remote_device_name, socket); + ByteArray remote_device_info{remote_device_name}; - OnIncomingConnection(client, remote_device_info, - std::move(channel), - proto::connections::WEB_RTC); - }); + OnIncomingConnection(client, remote_device_info, + std::move(channel), + proto::connections::WEB_RTC); + }); }})) { + NEARBY_LOGS(WARNING) << "In StartListeningForWebRtcConnections(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " failed to start listening for incoming WebRTC " + "connections to service_id=" + << service_id; return proto::connections::UNKNOWN_MEDIUM; } + NEARBY_LOGS(VERBOSE) + << "In StartListeningForWebRtcConnections(" + << absl::BytesToHexString(local_endpoint_info.data()) + << "), client=" << client->GetClientId() + << " started listening for incoming WebRtc connections to service_id=" + << service_id; } return proto::connections::WEB_RTC; @@ -1329,6 +1424,10 @@ BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::WebRtcConnectImpl( Utils::BuildLocationHint(empty_country_code), client->GetCancellationFlag(webrtc_endpoint->endpoint_id)); if (!socket_wrapper.IsValid()) { + NEARBY_LOGS(ERROR) + << "In WebRtcConnectImpl(), failed to connect to WebRTC device for " + "endpoint(id=" + << webrtc_endpoint->endpoint_id << ")."; return BasePcpHandler::ConnectImplResult{.status = {Status::kError}}; } @@ -1336,10 +1435,16 @@ BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::WebRtcConnectImpl( webrtc_endpoint->endpoint_id, socket_wrapper); if (!channel) { + NEARBY_LOGS(ERROR) << "In WebRtcConnectImpl(), failed to create WebRTC " + "endpoint channel for endpoint(id=" + << webrtc_endpoint->endpoint_id << ")."; socket_wrapper.Close(); return BasePcpHandler::ConnectImplResult{.status = {Status::kError}}; } + NEARBY_LOGS(VERBOSE) + << "Client created WebRTC endpoint channel to endpoint(id=" + << webrtc_endpoint->endpoint_id << ")."; return BasePcpHandler::ConnectImplResult{ .medium = proto::connections::Medium::WEB_RTC, .status = {Status::kSuccess}, diff --git a/cpp/core/internal/p2p_cluster_pcp_handler_test.cc b/cpp/core/internal/p2p_cluster_pcp_handler_test.cc index ec82464b..344239df 100644 --- a/cpp/core/internal/p2p_cluster_pcp_handler_test.cc +++ b/cpp/core/internal/p2p_cluster_pcp_handler_test.cc @@ -54,7 +54,7 @@ class P2pClusterPcpHandlerTest NEARBY_LOG(INFO, "SetUp: BT enabled"); } if (options_.allowed.wifi_lan) { - NEARBY_LOG(INFO, "SetUp: Wifi LAN enabled"); + NEARBY_LOG(INFO, "SetUp: WifiLan enabled"); } if (options_.allowed.web_rtc) { NEARBY_LOG(INFO, "SetUp: WebRTC enabled"); diff --git a/cpp/core/internal/pcp_manager.cc b/cpp/core/internal/pcp_manager.cc index a811527a..98de1acf 100644 --- a/cpp/core/internal/pcp_manager.cc +++ b/cpp/core/internal/pcp_manager.cc @@ -48,7 +48,9 @@ void PcpManager::DisconnectFromEndpointManager() { } PcpManager::~PcpManager() { + NEARBY_LOGS(INFO) << "Initiating shutdown of PcpManager."; DisconnectFromEndpointManager(); + NEARBY_LOGS(INFO) << "PcpManager has shut down."; } Status PcpManager::StartAdvertising(ClientProxy* client,