diff --git a/cpp/core/internal/base_pcp_handler.cc b/cpp/core/internal/base_pcp_handler.cc index 0fd75f87..768cd8ad 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_LOG(INFO, "Initiating shutdown of PcpHandler(%s)", + strategy_.GetName().c_str()); DisconnectFromEndpointManager(); // Stop all the ongoing Runnables (as gracefully as possible). - NEARBY_LOGS(INFO) << "BasePcpHandler: bringing down executors; strategy=" - << strategy_.GetName(); + NEARBY_LOG(INFO, "BasePcpHandler: bringing down executors; strategy=%s", + strategy_.GetName().c_str()); serial_executor_.Shutdown(); alarm_executor_.Shutdown(); - NEARBY_LOGS(INFO) << "BasePcpHandler: is down; strategy=" - << strategy_.GetName(); + NEARBY_LOG(INFO, "PcpHandler(%s) has shut down.", + strategy_.GetName().c_str()); } void BasePcpHandler::DisconnectFromEndpointManager() { if (stop_.Set(true)) return; - NEARBY_LOGS(INFO) << "BasePcpHandler: Unregister from EPM; strategy=" - << strategy_.GetName(); + NEARBY_LOG(INFO, "BasePcpHandler: Unregister from EPM; strategy=%s", + strategy_.GetName().c_str()); // Unregister ourselves from EPM message dispatcher. endpoint_manager_->UnregisterFrameProcessor(V1Frame::CONNECTION_RESPONSE, this); @@ -118,7 +118,8 @@ Status BasePcpHandler::StartAdvertising(ClientProxy* client, } void BasePcpHandler::StopAdvertising(ClientProxy* client) { - NEARBY_LOGS(INFO) << "StopAdvertising id=" << client->GetLocalEndpointId(); + NEARBY_LOG(INFO, "StopAdvertising local_endpoint_id=%s", + client->GetLocalEndpointId().c_str()); CountDownLatch latch(1); RunOnPcpHandlerThread("stop-advertising", [this, client, &latch]() RUN_ON_PCP_HANDLER_THREAD() { @@ -310,9 +311,10 @@ 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_LOG( + INFO, + "Connection not found on UKEY negotination complete; endpoint_id=%s", + endpoint_id.c_str()); return; } @@ -327,7 +329,8 @@ void BasePcpHandler::OnEncryptionSuccessRunnable( } connection_info.SetCryptoContext(std::move(ukey2)); - NEARBY_LOG(INFO, "Register encrypted connection; wait for response; id=%s", + NEARBY_LOG(INFO, + "Register encrypted connection; wait for response; endpoint_id=%s", endpoint_id.c_str()); // Set ourselves up so that we receive all acceptance/rejection messages @@ -375,9 +378,10 @@ 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_LOG( + INFO, + "Connection not found on UKEY negotination complete; endpoint_id=%s", + endpoint_id.c_str()); return; } @@ -414,7 +418,10 @@ 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", + NEARBY_LOG(INFO, + "In requestConnection(), connection requested with " + "endpoint(id=%s), " + "but we already have a pending connection with them.", endpoint_id.c_str()); result->Set({Status::kAlreadyConnectedToEndpoint}); return; @@ -424,15 +431,19 @@ 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_LOG( + INFO, + "In requestConnection(), client=%" PRIx64 + " attempted a connection with endpoint(id=%s), but outgoing " + "connections are disallowed", + client->GetClientId(), endpoint_id.c_str()); result->Set({Status::kOutOfOrderApiCall}); return; } DiscoveredEndpoint* endpoint = GetDiscoveredEndpoint(endpoint_id); if (endpoint == nullptr) { - NEARBY_LOG(INFO, "Discovered endpoint not found: id=%s", + NEARBY_LOG(INFO, "Discovered endpoint not found: endpoint_id=%s", endpoint_id.c_str()); result->Set({Status::kEndpointUnknown}); return; @@ -444,13 +455,13 @@ Status BasePcpHandler::RequestConnection(ClientProxy* client, if (AppendRemoteBluetoothMacAddressEndpoint( endpoint_id, remote_bluetooth_mac_address, client->GetDiscoveryOptions())) - NEARBY_LOGS(INFO) - << "Appended remote Bluetooth MAC Address endpoint " - << "[" << remote_bluetooth_mac_address << "]"; + NEARBY_LOG(INFO, + "Appended remote Bluetooth MAC Address endpoint [%s]", + remote_bluetooth_mac_address.c_str()); } if (AppendWebRTCEndpoint(endpoint_id, client->GetDiscoveryOptions())) - NEARBY_LOGS(INFO) << "Appended Web RTC endpoint."; + NEARBY_LOG(INFO, "Appended Web RTC endpoint."); auto discovered_endpoints = GetDiscoveredEndpoints(endpoint_id); std::unique_ptr channel; @@ -468,7 +479,7 @@ Status BasePcpHandler::RequestConnection(ClientProxy* client, } if (channel == nullptr) { - NEARBY_LOG(INFO, "Endpoint channel not available: id=%s", + NEARBY_LOG(INFO, "Endpoint channel not available: endpoint_id=%s", endpoint_id.c_str()); ProcessPreConnectionInitiationFailure(endpoint_id, channel.get(), connect_impl_result.status, @@ -476,7 +487,9 @@ Status BasePcpHandler::RequestConnection(ClientProxy* client, return; } - NEARBY_LOG(INFO, "Sending connection request: id=%s", + NEARBY_LOG(INFO, + "In requestConnection(), wrote ConnectionRequestFrame " + "to endpoint(id=%s)", endpoint_id.c_str()); // Generate the nonce to use for this connection. std::int32_t nonce = prng_.NextInt32(); @@ -487,7 +500,7 @@ Status BasePcpHandler::RequestConnection(ClientProxy* client, channel.get(), client->GetLocalEndpointId(), info.endpoint_info, nonce, GetSupportedConnectionMediumsByPriority(options)); if (!write_exception.Ok()) { - NEARBY_LOG(INFO, "Failed to send connection request: id=%s", + NEARBY_LOG(INFO, "Failed to send connection request: endpoint_id=%s", endpoint_id.c_str()); ProcessPreConnectionInitiationFailure(endpoint_id, channel.get(), {Status::kEndpointIoError}, @@ -495,7 +508,7 @@ Status BasePcpHandler::RequestConnection(ClientProxy* client, return; } - NEARBY_LOG(INFO, "adding connection to pending set: id=%s", + NEARBY_LOG(INFO, "Adding connection to pending set: endpoint_id=%s", endpoint_id.c_str()); // We've successfully connected to the device, and are now about to jump @@ -519,14 +532,14 @@ Status BasePcpHandler::RequestConnection(ClientProxy* client, }) .first->second.channel.get(); - NEARBY_LOG(INFO, "Initiating secure connection: id=%s", + NEARBY_LOG(INFO, "Initiating secure connection: endpoint_id=%s", endpoint_id.c_str()); // 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", + NEARBY_LOG(INFO, "Waiting for connection to complete: endpoint_id=%s", endpoint_id.c_str()); auto status = WaitForResult(absl::StrCat("RequestConnection(", endpoint_id, ")"), @@ -692,10 +705,14 @@ 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_LOG(INFO, "AcceptConnection: endpoint_id=%s", + endpoint_id.c_str()); if (!pending_connections_.count(endpoint_id)) { - NEARBY_LOG(INFO, "AcceptConnection: no pending connection for id=%s", - endpoint_id.c_str()); + NEARBY_LOG( + INFO, + "AcceptConnection: no pending connection for endpoint_id=%s", + endpoint_id.c_str()); + response.Set({Status::kEndpointUnknown}); return; } @@ -709,10 +726,10 @@ 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_LOG(ERROR, + "Channel destroyed before Accept; bring down " + "connection: endpoint_id=%s", + endpoint_id.c_str()); ProcessPreConnectionResultFailure(client, endpoint_id); response.Set({Status::kEndpointUnknown}); return; @@ -721,14 +738,15 @@ 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_LOG( + INFO, "AcceptConnection: failed to send response: endpoint_id=%s", + endpoint_id.c_str()); ProcessPreConnectionResultFailure(client, endpoint_id); response.Set({Status::kEndpointIoError}); return; } - NEARBY_LOG(INFO, "AcceptConnection: accepting locally: id=%s", + NEARBY_LOG(INFO, "AcceptConnection: accepting locally: endpoint_id=%s", endpoint_id.c_str()); connection_info.LocalEndpointAcceptedConnection(endpoint_id, payload_listener); @@ -749,8 +767,10 @@ 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_LOG( + INFO, + "RejectConnection: no pending connection for endpoint_id=%s", + endpoint_id.c_str()); response.Set({Status::kEndpointUnknown}); return; } @@ -764,10 +784,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_LOG(ERROR, + "Channel destroyed before Reject; bring down connection: " + "endpoint_id=%s", + endpoint_id.c_str()); ProcessPreConnectionResultFailure(client, endpoint_id); response.Set({Status::kEndpointUnknown}); return; @@ -776,14 +796,15 @@ 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_LOG( + INFO, "RejectConnection: failed to send response: endpoint_id=%s", + endpoint_id.c_str()); ProcessPreConnectionResultFailure(client, endpoint_id); response.Set({Status::kEndpointIoError}); return; } - NEARBY_LOG(INFO, "RejectConnection: rejecting locally: id=%s", + NEARBY_LOG(INFO, "RejectConnection: rejecting locally: endpoint_id=%s", endpoint_id.c_str()); connection_info.LocalEndpointRejectedConnection(endpoint_id); EvaluateConnectionResult(client, endpoint_id, @@ -803,10 +824,12 @@ 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_LOG(INFO, "OnConnectionResponse: endpoint_id=%s", + endpoint_id.c_str()); if (client->HasRemoteEndpointResponded(endpoint_id)) { - NEARBY_LOG(INFO, "OnConnectionResponse: already handled; id=%s", + NEARBY_LOG(INFO, + "OnConnectionResponse: already handled; endpoint_id=%s", endpoint_id.c_str()); return; } @@ -825,12 +848,14 @@ void BasePcpHandler::OnIncomingFrame(OfflineFrame& frame, accepted = connection_response.status() == Status::kSuccess; } if (accepted) { - NEARBY_LOG(INFO, "OnConnectionResponse: remote accepted; id=%s", + NEARBY_LOG(INFO, + "OnConnectionResponse: remote accepted; endpoint_id=%s", endpoint_id.c_str()); client->RemoteEndpointAcceptedConnection(endpoint_id); } else { NEARBY_LOG(INFO, - "OnConnectionResponse: remote rejected; id=%s; status=%d", + "OnConnectionResponse: remote rejected; endpoint_id=%s; " + "status=%d", endpoint_id.c_str(), connection_response.status()); client->RemoteEndpointRejectedConnection(endpoint_id); } @@ -905,14 +930,16 @@ 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_LOG(INFO, "Adding new endpoint: endpoint_id=%s", + endpoint_id.c_str()); // 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_LOG(INFO, + "Adding new medium for endpoint: endpoint_id=%s; medium=%d", + endpoint_id.c_str(), owned_endpoint->medium); } } @@ -921,7 +948,7 @@ 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", + NEARBY_LOG(INFO, "No previous endpoint (nothing to lose): endpoint_id=%s", endpoint.endpoint_id.c_str()); return; } @@ -967,9 +994,10 @@ bool BasePcpHandler::IsPreferred( 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); + "Failed to find either %d or %d in the list of locally supported " + "mediums despite expecting to find both, when deciding which " + "medium %s is preferred.", + new_endpoint.medium, old_endpoint.medium, medium_string.c_str()); return false; } @@ -983,10 +1011,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_LOG( + WARNING, + "Ignoring incoming connection on medium %d because client=%" PRIX64 + " is no longer advertising", + channel->GetMedium(), client->GetClientId()); return {Exception::kIo}; } @@ -996,12 +1025,11 @@ 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_LOG(ERROR, + "Failed to parse incoming connection request; client=%" PRIx64 + "; device=%s", + client->GetClientId(), + absl::BytesToHexString(remote_endpoint_info.data()).c_str()); ProcessPreConnectionInitiationFailure("", channel.get(), {Status::kError}, nullptr); return {Exception::kSuccess}; @@ -1013,12 +1041,15 @@ Exception BasePcpHandler::OnIncomingConnection( 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(), + "In onIncomingConnection(%d) for client=%" PRIx64 + ", read ConnectionRequestFrame from endpoint(id=%s)", + channel->GetMedium(), client->GetClientId(), connection_request.endpoint_id().c_str()); if (client->IsConnectedToEndpoint(connection_request.endpoint_id())) { + NEARBY_LOG(ERROR, + "Incoming connection on medium %d was denied because we're " + "already connected to endpoint(id=%s).", + channel->GetMedium(), connection_request.endpoint_id().c_str()); return {Exception::kIo}; } @@ -1033,6 +1064,7 @@ Exception BasePcpHandler::OnIncomingConnection( // listen to them. if (ShouldEnforceTopologyConstraints(client->GetAdvertisingOptions()) && !CanReceiveIncomingConnection(client)) { + NEARBY_LOG(ERROR, "Incoming connections are currently disallowed."); return {Exception::kIo}; } @@ -1079,21 +1111,37 @@ 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_LOG( + INFO, + "In onIncomingConnection(%s) for client %d, found a collision with " + "endpoint %s. We've already sent a connection request to them with " + "nonce %d, but they're also trying to connect to us with nonce %d.", + endpoint_channel->GetMedium(), client->GetClientId(), + endpoint_id.c_str(), info.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_LOG( + INFO, + "In onIncomingConnection(%s) for client=%" PRIx64 + ", cleaned up the collision with endpoint(id=%s) by closing their " + "channel.", + endpoint_channel->GetMedium(), client->GetClientId(), + endpoint_id.c_str()); 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_LOG(INFO, + "In onIncomingConnection(%s) for client=%" PRIx64 + ", cleaned up the collision with endpoint %s by closing our " + "channel and notifying our client of the failure.", + endpoint_channel->GetMedium(), client->GetClientId(), + endpoint_id.c_str()); } else { // Oh. Huh. We both lost. Well, that's awkward. We'll clean up both and // just force the devices to retry. @@ -1101,7 +1149,13 @@ bool BasePcpHandler::BreakTie(ClientProxy* client, ProcessTieBreakLoss(client, endpoint_id, &info); - NEARBY_LOG(INFO, "BreakTie: Both lost; id=%s", endpoint_id.c_str()); + NEARBY_LOG(INFO, + "In onIncomingConnection(%d) for client=%" PRIx64 + ", cleaned up the collision with endpoint %s by closing both " + "channels. Our nonces were identical, so we couldn't decide " + "which channel to use.", + endpoint_channel->GetMedium(), client->GetClientId(), + endpoint_id.c_str()); return true; } } @@ -1133,10 +1187,11 @@ bool BasePcpHandler::AppendRemoteBluetoothMacAddressEndpoint( auto endpoint = it.first->second.get(); 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 << "]"; + NEARBY_LOG( + INFO, + "Cannot append remote Bluetooth MAC Address endpoint, because the " + "endpoint has already been found over Bluetooth [%s]", + remote_bluetooth_mac_address.c_str()); return false; } } @@ -1144,10 +1199,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_LOG(INFO, + "Cannot append remote Bluetooth MAC Address endpoint, because a " + "valid Bluetooth device could not be derived [%s]", + remote_bluetooth_mac_address.c_str()); return false; } @@ -1200,11 +1255,15 @@ 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_LOG( + INFO, + "ConnectionResult: local client did not respond; endpoint_id=%s", + endpoint_id.c_str()); } else if (!client->HasRemoteEndpointResponded(endpoint_id)) { - NEARBY_LOG(INFO, "ConnectionResult: remote client did not respond; id=%s", - endpoint_id.c_str()); + NEARBY_LOG( + INFO, + "ConnectionResult: remote client did not respond; endpoint_id=%s", + endpoint_id.c_str()); } return; } @@ -1213,7 +1272,7 @@ 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", + NEARBY_LOG(INFO, "No pending connection to evaluate; endpoint_id=%s", endpoint_id.c_str()); return; } @@ -1224,7 +1283,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_LOG(INFO, "Pending connection accepted; endpoint_id=%s", + endpoint_id.c_str()); response_code = {Status::kSuccess}; // Both sides have accepted, so we can now start talking over encrypted @@ -1241,7 +1301,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_LOG(INFO, "Pending connection rejected; endpoint_id=%s", + endpoint_id.c_str()); 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..002fa016 100644 --- a/cpp/core/internal/p2p_cluster_pcp_handler.cc +++ b/cpp/core/internal/p2p_cluster_pcp_handler.cc @@ -14,6 +14,8 @@ #include "core/internal/p2p_cluster_pcp_handler.h" +#include + #include "core/internal/base_pcp_handler.h" #include "core/internal/ble_advertisement.h" #include "core/internal/ble_endpoint_channel.h" @@ -132,7 +134,9 @@ BasePcpHandler::StartOperationResult P2pClusterPcpHandler::StartAdvertisingImpl( } if (mediums_started_successfully.empty()) { - NEARBY_LOG(INFO, "P2pClusterPcpHandler::StartAdvertisingImpl: not started"); + NEARBY_LOG(FATAL, "Failed StartAdvertising(%s) for client=%" PRIx64, + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId()); return { .status = {Status::kBluetoothError}, }; @@ -154,8 +158,8 @@ Status P2pClusterPcpHandler::StopAdvertisingImpl(ClientProxy* client) { bluetooth_classic_advertiser_client_id_ = 0; } else { NEARBY_LOG(INFO, - "Skipped BT TurnOffDiscoverability for client %d, client that " - "turned on discoverability is %d", + "Skipped BT TurnOffDiscoverability for client=%" PRIx64 + ", client that turned on discoverability is %" PRIx64, client->GetClientId(), bluetooth_classic_advertiser_client_id_); } @@ -175,16 +179,16 @@ bool P2pClusterPcpHandler::IsRecognizedBluetoothEndpoint( const BluetoothDeviceName& name) const { if (!name.IsValid()) { NEARBY_LOG( - INFO, - "P2pClusterPcpHandler::IsRecognizedBluetoothEndpoint: name is invalid"); + VERBOSE, + "%s doesn't conform to the BluetoothDeviceName format, discarding.", + name_string.c_str()); return false; } if (name.GetPcp() != GetPcp()) { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::IsRecognizedBluetoothEndpoint: Pcp is " - "not matched; name.Pcp=%d, Pcp=%d", - name.GetPcp(), GetPcp()); + NEARBY_LOG(VERBOSE, "%s doesn't match on Pcp; expected %d, found %d", + name_string.c_str(), static_cast(GetPcp()), + static_cast(name.GetPcp())); return false; } @@ -192,11 +196,12 @@ 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_LOG( + VERBOSE, + "%s doesn't match on expected service_id_hash; expected %s, found %s", + name_string.c_str(), + absl::BytesToHexString(expected_service_id_hash.data()).c_str(), + absl::BytesToHexString(name.GetServiceIdHash().data()).c_str()); return false; } @@ -208,43 +213,47 @@ void P2pClusterPcpHandler::BluetoothDeviceDiscoveredHandler( BluetoothDevice device) { RunOnPcpHandlerThread( "p2p-bt-device-discovered", - [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 (FOUND) [client=%p, service=%s]: not " - "in discovery mode", - client, service_id.c_str()); - return; - } + [this, client, service_id, device]() RUN_ON_PCP_HANDLER_THREAD() { + // Make sure we are still discovering before proceeding. + if (!client->IsDiscovering()) { + NEARBY_LOG( + WARNING, + "Skipping discovery of BluetoothDevice %s because we are no " + "longer discovering.", + device.GetName().c_str()); + return; + } - // Parse the Bluetooth device name. - const std::string device_name_string = device.GetName(); - BluetoothDeviceName device_name(device_name_string); + // Parse the Bluetooth device name. + const std::string device_name_string = device.GetName(); + BluetoothDeviceName device_name(device_name_string); - // Make sure the Bluetooth device name points to a valid - // endpoint we're discovering. - if (!IsRecognizedBluetoothEndpoint(device_name_string, service_id, - device_name)) - return; + // Make sure the Bluetooth device name points to a valid + // endpoint we're discovering. + if (!IsRecognizedBluetoothEndpoint(device_name_string, service_id, + device_name)) { + NEARBY_LOG(VERBOSE, "Found unrecognized BluetoothDeviceName %s", + device_name_string.c_str()); + 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()); - OnEndpointFound( - client, - std::make_shared(BluetoothEndpoint{ - {device_name.GetEndpointId(), device_name.GetEndpointInfo(), - service_id, proto::connections::Medium::BLUETOOTH, - device_name.GetWebRtcState()}, - device, - })); - }); + // Report the discovered endpoint to the client. + NEARBY_LOG(INFO, + "Found BluetoothDeviceName %s (with endpoint_id=%s and " + "endpoint_info=%s).", + device_name_string.c_str(), + device_name.GetEndpointId().c_str(), + absl::BytesToHexString(device_name.GetEndpointInfo().data()) + .c_str()); + OnEndpointFound( + client, + std::make_shared(BluetoothEndpoint{ + {device_name.GetEndpointId(), device_name.GetEndpointInfo(), + service_id, proto::connections::Medium::BLUETOOTH, + device_name.GetWebRtcState()}, + device, + })); + }); } void P2pClusterPcpHandler::BluetoothNameChangedHandler( @@ -256,10 +265,10 @@ void P2pClusterPcpHandler::BluetoothNameChangedHandler( // 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()); + WARNING, + "Ignoring lost BluetoothDevice %s because Connections is no " + "longer discovering.", + device.GetName().c_str()); return; } @@ -295,9 +304,8 @@ void P2pClusterPcpHandler::BluetoothNameChangedHandler( // 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()); + "Reporting lost BluetoothDevice %s, due to device name change.", + bluetoothEndpoint->bluetooth_device.GetName().c_str()); OnEndpointLost(client, *endpoint); break; } @@ -307,19 +315,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_LOG(VERBOSE, "Found unrecognized BluetoothDeviceName %s", + device_name_string.c_str()); 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_LOG(INFO, + "Found BluetoothDeviceName %s (with endpoint_id=%s and " + "endpoint_info=%s).", + device_name_string.c_str(), + device_name.GetEndpointId().c_str(), + absl::BytesToHexString(device_name.GetEndpointInfo().data()) + .c_str()); OnEndpointFound( client, std::make_shared(BluetoothEndpoint{ @@ -340,10 +348,11 @@ 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_LOG( + WARNING, + "Ignoring lost BluetoothDevice %s because Connections is no " + "longer discovering.", + device_name_string.c_str()); return; } @@ -357,11 +366,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_LOG(INFO, "Processing lost BluetoothDeviceName %s", + device_name_string.c_str()); OnEndpointLost(client, DiscoveredEndpoint{ device_name.GetEndpointId(), device_name.GetEndpointInfo(), service_id, @@ -374,26 +380,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_LOG(VERBOSE, + "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_LOG(INFO, + "BleAdvertisement has an unknown version; expected %d, found %d", + static_cast(kBleAdvertisementVersion), + 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_LOG( + VERBOSE, "BleAdvertisement doesn't match on Pcp; expected %d, found %d", + static_cast(GetPcp()), static_cast(advertisement.GetPcp())); return false; } @@ -404,12 +407,13 @@ 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_LOG( + VERBOSE, + "BleAdvertisement doesn't match on expected service_id_hash; " + "expected %s, found %s", + absl::BytesToHexString(expected_service_id_hash.data()).c_str(), + absl::BytesToHexString(advertisement.GetServiceIdHash().data()) + .c_str()); return false; } } @@ -428,10 +432,10 @@ void P2pClusterPcpHandler::BlePeripheralDiscoveredHandler( // 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()); + WARNING, + "Skipping discovery of BleAdvertisement header %s because we " + "are no longer discovering.", + absl::BytesToHexString(advertisement_bytes.data()).c_str()); return; } @@ -451,11 +455,14 @@ 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()); + NEARBY_LOG( + INFO, + "Found BleAdvertisement %s (with endpoint_id=%s, and " + "endpoint_info=%s).", + absl::BytesToHexString(advertisement_bytes.data()).c_str(), + advertisement.GetEndpointId().c_str(), + absl::BytesToHexString(advertisement.GetEndpointInfo().data()) + .c_str()); OnEndpointFound( client, std::make_shared(BleEndpoint{ @@ -469,18 +476,19 @@ void P2pClusterPcpHandler::BlePeripheralDiscoveredHandler( 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"; + NEARBY_LOG( + INFO, "No Bluetooth Classic MAC address found in advertisement."); return; } BluetoothDevice remote_bluetooth_device = 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 " - << remote_bluetooth_mac_address; + NEARBY_LOG( + INFO, + "A valid Bluetooth device could not be derived from the MAC " + "address %s", + remote_bluetooth_mac_address.c_str()); return; } @@ -509,11 +517,10 @@ 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_LOG(WARNING, + "Ignoring lost BlePeripheral %s because we are no longer " + "discovering.", + peripheral.GetName().c_str()); return; } @@ -525,10 +532,14 @@ 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_LOG( + INFO, + "Lost BleEndpoint for BlePeripheral %s (with endpoint_id=%s " + "and endpoint_info=%s).", + peripheral.GetName().c_str(), + ble_endpoint_state.endpoint_id.c_str(), + absl::BytesToHexString(ble_endpoint_state.endpoint_info.data()) + .c_str()); OnEndpointLost(client, DiscoveredEndpoint{ ble_endpoint_state.endpoint_id, ble_endpoint_state.endpoint_info, @@ -544,17 +555,16 @@ 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_LOG(VERBOSE, + "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_LOG(VERBOSE, + "WifiLanServiceInfo doesn't match on Pcp; expected %d, found %d", + static_cast(GetPcp()), + static_cast(service_info.GetPcp())); return false; } @@ -562,12 +572,12 @@ 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_LOG( + VERBOSE, + "WifiLanServiceInfo doesn't match on expected service_id_hash; " + "expected %s, found %s", + absl::BytesToHexString(expected_service_id_hash.data()).c_str(), + absl::BytesToHexString(service_info.GetServiceIdHash().data()).c_str()); return false; } @@ -584,10 +594,11 @@ void P2pClusterPcpHandler::WifiLanServiceDiscoveredHandler( // 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()); + WARNING, + "Skipping discovery of NsdServiceInfo %s because we are no " + "longer " + "discovering.", + wifi_lan_service.GetServiceInfo().GetServiceInfoName().c_str()); return; } @@ -599,12 +610,14 @@ void P2pClusterPcpHandler::WifiLanServiceDiscoveredHandler( 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()); + NEARBY_LOG( + INFO, + "Found NsdServiceInfo %s (with endpoint_id=%s and " + "endpoint_info=%s).", + wifi_lan_service.GetServiceInfo().GetServiceInfoName().c_str(), + service_info.GetEndpointId().c_str(), + absl::BytesToHexString(service_info.GetEndpointInfo().data()) + .c_str()); OnEndpointFound(client, std::make_shared(WifiLanEndpoint{ { @@ -632,11 +645,10 @@ void P2pClusterPcpHandler::WifiLanServiceLostHandler( 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()); + NEARBY_LOG(WARNING, + "Ignoring lost NsdServiceInfo %s because we are no longer " + "discovering.", + nsd_service_info.GetServiceInfoName().c_str()); return; } @@ -647,12 +659,14 @@ void P2pClusterPcpHandler::WifiLanServiceLostHandler( // endpoint we're discovering. if (!IsRecognizedWifiLanEndpoint(service_id, service_info)) return; - // Report the discovered endpoint to the client. + // Report the lost endpoint to the client. NEARBY_LOG(INFO, - "WifiLan discovery handler (LOST) [client=%p, " - "service_id=%s]: report " - "to client", - client, service_id.c_str()); + "Lost NsdServiceInfo %s (with endpoint_id=%s and " + "endpoint_info=%s).", + nsd_service_info.GetServiceInfoName().c_str(), + service_info.GetEndpointId().c_str(), + absl::BytesToHexString(service_info.GetEndpointInfo().data()) + .c_str()); OnEndpointLost(client, DiscoveredEndpoint{ service_info.GetEndpointId(), service_info.GetEndpointInfo(), @@ -730,7 +744,11 @@ BasePcpHandler::StartOperationResult P2pClusterPcpHandler::StartDiscoveryImpl( } if (mediums_started_successfully.empty()) { - NEARBY_LOG(INFO, "P2pClusterPcpHandler::StartDiscoveryImpl: nothing added"); + NEARBY_LOG(FATAL, + "Failed StartDiscovery() for client=%" PRIx64 + " because we couldn't scan on Bluetooth, BLE, or WifiLan for " + "service_id=%s", + client->GetClientId(), service_id.c_str()); return { .status = {Status::kBluetoothError}, }; @@ -749,8 +767,8 @@ Status P2pClusterPcpHandler::StopDiscoveryImpl(ClientProxy* client) { bluetooth_classic_discoverer_client_id_ = 0; } else { NEARBY_LOG(INFO, - "Skipped BT stopDiscovery for client %d, client that started " - "discovery is %d", + "Skipped BT StopDiscovery for client=%" PRIx64 + ", client that started discovery is %" PRIx64, client->GetClientId(), bluetooth_classic_discoverer_client_id_); } @@ -761,10 +779,10 @@ Status P2pClusterPcpHandler::StopDiscoveryImpl(ClientProxy* client) { Status P2pClusterPcpHandler::InjectEndpointImpl( ClientProxy* client, const std::string& service_id, const OutOfBandConnectionMetadata& metadata) { - NEARBY_LOG(INFO, "InjectEndpoint"); + NEARBY_LOG(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_LOG(WARNING, "InjectEndpointImpl: Only Bluetooth is supported."); return {Status::kError}; } @@ -776,7 +794,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 +853,93 @@ 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_LOG( + WARNING, + "Invalid socket in accept callback(%s), client=%" PRIx64, + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + 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_LOG(WARNING, + "In StartBluetoothAdvertising(%s), client=%" PRIx64 + " failed to start listening for incoming Bluetooth " + "connections to service_id=%s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), service_id.c_str()); + return proto::connections::UNKNOWN_MEDIUM; + } + NEARBY_LOG(INFO, + "In StartBluetoothAdvertising(%s), client=%" PRIx64 + " started listening for incoming Bluetooth connections to " + "service_id=%s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), service_id.c_str()); } - 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_LOG(WARNING, + "In StartBluetoothAdvertising(%s), client=%" PRIx64 + " failed to generate BluetoothDeviceName {version=%d, pcp=%d, " + "endpoint_id=%s, service_id_hash=%s, endpoint_info=%s}.", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), + static_cast(kBluetoothDeviceNameVersion), + static_cast(GetPcp()), local_endpoint_id.c_str(), + absl::BytesToHexString(service_id_hash.data()).c_str(), + absl::BytesToHexString(local_endpoint_info.data()).c_str()); 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_LOG(VERBOSE, + "In StartBluetoothAdvertising(%s), client=%" PRIx64 + " generated BluetoothDeviceName %s with service_id=%s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), device_name.c_str(), service_id.c_str()); - 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_LOG( + INFO, + "In StartBluetoothAdvertising(%s), client=%" PRIx64 + " couldn't start Bluetooth advertising with BluetoothDeviceName %s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), device_name.c_str()); 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_LOG(VERBOSE, + "In StartBluetoothAdvertising(%s), client=%" PRIx64 + " started Bluetooth advertising with BluetoothDeviceName %s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), device_name.c_str()); return proto::connections::BLUETOOTH; } @@ -928,22 +948,37 @@ 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_LOG(VERBOSE, + "In StartBluetoothDiscovery(), client=%" PRIx64 + " started scanning for Bluetooth for service_id=%s", + client->GetClientId(), service_id.c_str()); return proto::connections::BLUETOOTH; } else { - NEARBY_LOG(INFO, "P2pClusterPcpHandler::StartBluetoothDiscovery: failed"); + NEARBY_LOG(INFO, + "In StartBluetoothDiscovery(), client=%" PRIx64 + " couldn't start scanning on Bluetooth for service_id=%s", + client->GetClientId(), service_id.c_str()); return proto::connections::UNKNOWN_MEDIUM; } } BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::BluetoothConnectImpl( ClientProxy* client, BluetoothEndpoint* endpoint) { + NEARBY_LOG( + VERBOSE, + "Client %" PRIx64 + " is attempting to connect to endpoint(id=%s) over Bluetooth Classic.", + client->GetClientId(), endpoint->endpoint_id.c_str()); 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_LOG(ERROR, + "In BluetoothConnectImpl(), failed to connect to Bluetooth " + "device %s for endpoint(id=%s).", + device.GetName().c_str(), endpoint->endpoint_id.c_str()); return BasePcpHandler::ConnectImplResult{ .status = {Status::kBluetoothError}, }; @@ -951,7 +986,10 @@ BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::BluetoothConnectImpl( auto channel = absl::make_unique( endpoint->endpoint_id, bluetooth_socket); - + NEARBY_LOG(VERBOSE, + "Client %" PRIx64 + " created Bluetooth endpoint channel to endpoint(id=%s).", + client->GetClientId(), endpoint->endpoint_id.c_str()); return BasePcpHandler::ConnectImplResult{ .medium = proto::connections::Medium::BLUETOOTH, .status = {Status::kSuccess}, @@ -971,8 +1009,9 @@ proto::connections::Medium P2pClusterPcpHandler::StartBleAdvertising( // request comes in very quickly. BLE allows connecting over BLE itself, as // well as advertising the Bluetooth MAC address to allow connecting over // Bluetooth Classic. - NEARBY_LOGS(INFO) << "P2pClusterPcpHandler::StartBleAdvertising: service_id=" - << service_id << ": start"; + NEARBY_LOG(INFO, + "P2pClusterPcpHandler::StartBleAdvertising: service_id=%s : start", + service_id.c_str()); if (!ble_medium_.IsAcceptingConnections(service_id)) { if (!bluetooth_radio_.Enable() || !ble_medium_.StartAcceptingConnections( @@ -980,8 +1019,11 @@ 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_LOG( + WARNING, + "Invalid socket in accept callback(%s), client=%" PRIx64, + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId()); return; } RunOnPcpHandlerThread( @@ -1002,14 +1044,20 @@ proto::connections::Medium P2pClusterPcpHandler::StartBleAdvertising( proto::connections::Medium::BLE); }); }})) { - NEARBY_LOGS(INFO) - << "Ble failed to start accepting connections for service_id=" - << service_id; + NEARBY_LOG(WARNING, + "In StartBleAdvertising(%s), client=%" PRIx64 + " failed to start accepting for incoming BLE connections to " + "service_id=%s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), service_id.c_str()); return proto::connections::UNKNOWN_MEDIUM; } - NEARBY_LOGS(INFO) - << "Ble succeed to start accepting connections for service_id=" - << service_id; + NEARBY_LOG( + INFO, + "In StartBleAdvertising(%s), client=%" PRIx64 + " started accepting for incoming BLE connections to service_id=%s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), service_id.c_str()); } if (ShouldAdvertiseBluetoothMacOverBle(power_level) || @@ -1021,8 +1069,13 @@ 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_LOG(WARNING, + "In BT StartAcceptingConnections.accepted_cb(%s), " + "client=%" PRIx64 + ": Invalid socket in accept callback.", + absl::BytesToHexString(local_endpoint_info.data()) + .c_str(), + client->GetClientId()); return; } RunOnPcpHandlerThread( @@ -1042,21 +1095,24 @@ proto::connections::Medium P2pClusterPcpHandler::StartBleAdvertising( proto::connections::Medium::BLUETOOTH); }); }})) { - NEARBY_LOGS(INFO) - << "BT failed to start accepting connections for service_id=" - << service_id; + NEARBY_LOG(WARNING, + "In BT StartBleAdvertising(%s), client=%" PRIx64 + " failed to start accepting for incoming BLE connections to " + "service_id=%s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), service_id.c_str()); ble_medium_.StopAcceptingConnections(service_id); return proto::connections::UNKNOWN_MEDIUM; } - NEARBY_LOGS(INFO) - << "BT succeed to start accepting connections for service_id=" - << service_id; + NEARBY_LOG( + INFO, + "In BT StartBleAdvertising(%s), client=%" PRIx64 + " started accepting for incoming BLE connections to service_id=%s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), service_id.c_str()); } } - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartBleAdvertising: service=%s, id=%s", - service_id.c_str(), local_endpoint_id.c_str()); // Generate a BleAdvertisement. If a fast advertisement service UUID was // provided, create a fast BleAdvertisement. ByteArray advertisement_bytes; @@ -1079,28 +1135,38 @@ proto::connections::Medium P2pClusterPcpHandler::StartBleAdvertising( bluetooth_mac_address, ByteArray{}, web_rtc_state)); } if (advertisement_bytes.Empty()) { - NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartBleAdvertising: generate " - "BleAdvertisement failed"); + NEARBY_LOG(WARNING, + "In StartBleAdvertising(%s), client=%" PRIx64 + " failed to create an advertisement.", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId()); 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_LOG(VERBOSE, + "In StartBleAdvertising(%s), client=%" PRIx64 + " generated BleAdvertisement with service_id=%s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), service_id.c_str()); if (!ble_medium_.StartAdvertising(service_id, advertisement_bytes, options.fast_advertisement_service_uuid)) { - NEARBY_LOGS(ERROR) - << "P2pClusterPcpHandler::StartBleAdvertising: failed to " - "start advertising, advertisement_bytes=" - << absl::BytesToHexString(advertisement_bytes.data()); + NEARBY_LOG(WARNING, + "In StartBleAdvertising(%s), client=%" PRIx64 + " couldn't start BLE Advertising with BleAdvertisement %s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), + absl::BytesToHexString(advertisement_bytes.data()).c_str()); ble_medium_.StopAcceptingConnections(service_id); return proto::connections::UNKNOWN_MEDIUM; } - NEARBY_LOGS(INFO) << "P2pClusterPcpHandler::StartBleAdvertising: service_id=" - << service_id << ": done"; + NEARBY_LOG(VERBOSE, + "In startBleAdvertising(%s), client=%" PRIx64 + " started BLE Advertising with BleAdvertisement %s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), + absl::BytesToHexString(advertisement_bytes.data()).c_str()); return proto::connections::BLE; } @@ -1111,22 +1177,37 @@ 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_LOG(VERBOSE, + "In StartBleScanning(), client=%" PRIx64 + " started scanning for BLE advertisements for service_id=%s", + client->GetClientId(), service_id.c_str()); return proto::connections::BLE; } else { - NEARBY_LOGS(INFO) << "P2pClusterPcpHandler::StartBleScanning: failed"; + NEARBY_LOG(INFO, + "In StartBleScanning(), client=%" PRIx64 + " couldn't start scanning on BLE for service_id=%s", + client->GetClientId(), service_id.c_str()); return proto::connections::UNKNOWN_MEDIUM; } } BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::BleConnectImpl( ClientProxy* client, BleEndpoint* endpoint) { + NEARBY_LOG(VERBOSE, + "Client %" PRIx64 + " is attempting to connect to endpoint(id=%s) over BLE.", + client->GetClientId(), endpoint->endpoint_id.c_str()); + 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_LOG(ERROR, + "In BleConnectImpl(), failed to connect to BLE device %s for " + "endpoint(id=%s).", + peripheral.GetName().c_str(), endpoint->endpoint_id.c_str()); return BasePcpHandler::ConnectImplResult{ .status = {Status::kBleError}, }; @@ -1151,55 +1232,55 @@ 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_LOG( + WARNING, + "Invalid socket in accept callback(%s), client=%" PRIx64, + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + 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_LOG(WARNING, + "In StartWifiLanAdvertising(%s), client=%" PRIx64 + " failed to start listening for incoming WifiLan connections " + "to service_id=%s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), service_id.c_str()); + return proto::connections::UNKNOWN_MEDIUM; + } + NEARBY_LOG( + INFO, + "In StartWifiLanAdvertising(%s), client=%" PRIx64 + " started listening for incoming WifiLan connections to service_id=%s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), service_id.c_str()); } - 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 +1292,42 @@ 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_LOG(WARNING, + "In StartWifiLanAdvertising(%s), client=%" PRIx64 + " failed to generate WifiLanServiceInfo {version=%d, pcp=%d, " + "endpoint_id=%s, service_id_hash=%s, endpoint_info=%s}.", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), + static_cast(kWifiLanServiceInfoVersion), + static_cast(GetPcp()), local_endpoint_id.c_str(), + absl::BytesToHexString(service_id_hash.data()).c_str(), + absl::BytesToHexString(local_endpoint_info.data()).c_str()); 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_LOG(INFO, + "In StartWifiLanAdvertising(%s), client=%" PRIx64 + " generated WifiLanServiceInfo %s with service_id=%s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), + nsd_service_info.GetServiceInfoName().c_str(), service_id.c_str()); if (!wifi_lan_medium_.StartAdvertising(service_id, nsd_service_info)) { NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartWifiLanAdvertising: failed to " - "start advertising, service_info_name=%s", + "In StartWifiLanAdvertising(%s), client=%" PRIx64 + " couldn't advertise with WifiLanServiceInfo %s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), nsd_service_info.GetServiceInfoName().c_str()); wifi_lan_medium_.StopAcceptingConnections(service_id); return proto::connections::UNKNOWN_MEDIUM; } NEARBY_LOG(INFO, - "P2pClusterPcpHandler::StartWifiLanAdvertising: service=%s: done", - service_id.c_str()); + "In StartWifiLanAdvertising(%s), client=%" PRIx64 + " advertised with WifiLanServiceInfo %s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), + nsd_service_info.GetServiceInfoName().c_str()); return proto::connections::WIFI_LAN; } @@ -1246,22 +1335,37 @@ 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_LOG(INFO, + "In StartWifiLanDiscovery(), client=%" PRIx64 + " started scanning for Wifi devices for service_id=%s", + client->GetClientId(), service_id.c_str()); return proto::connections::WIFI_LAN; } else { - NEARBY_LOG(INFO, "P2pClusterPcpHandler::StartWifiLanDiscovery: failed"); + NEARBY_LOG(INFO, + "In StartWifiLanDiscovery(), client=%" PRIx64 + " couldn't start scanning on Wifi for service_id=%s", + client->GetClientId(), service_id.c_str()); return proto::connections::UNKNOWN_MEDIUM; } } BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::WifiLanConnectImpl( ClientProxy* client, WifiLanEndpoint* endpoint) { + NEARBY_LOG(VERBOSE, + "Client %" PRIx64 + " is attempting to connect to endpoint(id=%s) over WifiLan.", + client->GetClientId(), endpoint->endpoint_id.c_str()); 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_LOG(ERROR, + "In WifiLanConnectImpl(), failed to connect to service %s for " + "endpoint(id=%s).", + wifi_lan_service.GetServiceInfo().GetServiceInfoName().c_str(), + endpoint->endpoint_id.c_str()); return BasePcpHandler::ConnectImplResult{ .status = {Status::kWifiLanError}, }; @@ -1269,7 +1373,10 @@ BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::WifiLanConnectImpl( auto channel = absl::make_unique( endpoint->endpoint_id, wifi_lan_socket); - + NEARBY_LOG(VERBOSE, + "Client %" PRIx64 + " created WifiLan endpoint channel to endpoint(id=%s).", + client->GetClientId(), endpoint->endpoint_id.c_str()); return BasePcpHandler::ConnectImplResult{ .medium = proto::connections::Medium::WIFI_LAN, .status = {Status::kSuccess}, @@ -1295,27 +1402,42 @@ 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_LOG( + WARNING, + "Invalid socket in accept callback(%s), client=%" PRIx64, + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + 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_LOG(WARNING, + "In StartListeningForWebRtcConnections(%s), client=%" PRIx64 + " failed to start listening for incoming WebRTC connections " + "to service_id=%s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), service_id.c_str()); return proto::connections::UNKNOWN_MEDIUM; } + NEARBY_LOG( + VERBOSE, + "In StartListeningForWebRtcConnections(%s), client=%" PRIx64 + " started listening for incoming WebRtc connections to service_id=%s", + absl::BytesToHexString(local_endpoint_info.data()).c_str(), + client->GetClientId(), service_id.c_str()); } return proto::connections::WEB_RTC; @@ -1329,6 +1451,10 @@ BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::WebRtcConnectImpl( Utils::BuildLocationHint(empty_country_code), client->GetCancellationFlag(webrtc_endpoint->endpoint_id)); if (!socket_wrapper.IsValid()) { + NEARBY_LOG(ERROR, + "In WebRtcConnectImpl(), failed to connect to WebRTC device for " + "endpoint(id=%s).", + webrtc_endpoint->endpoint_id.c_str()); return BasePcpHandler::ConnectImplResult{.status = {Status::kError}}; } @@ -1336,10 +1462,17 @@ BasePcpHandler::ConnectImplResult P2pClusterPcpHandler::WebRtcConnectImpl( webrtc_endpoint->endpoint_id, socket_wrapper); if (!channel) { + NEARBY_LOG(ERROR, + "In WebRtcConnectImpl(), failed to create WebRTC " + "endpoint channel for endpoint(id=%s).", + webrtc_endpoint->endpoint_id.c_str()); socket_wrapper.Close(); return BasePcpHandler::ConnectImplResult{.status = {Status::kError}}; } + NEARBY_LOG(VERBOSE, + "Client created WebRTC endpoint channel to endpoint(id=%s).", + webrtc_endpoint->endpoint_id.c_str()); 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..55796c41 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_LOG(INFO, "Initiating shutdown of PcpManager."); DisconnectFromEndpointManager(); + NEARBY_LOG(INFO, "PcpManager has shut down."); } Status PcpManager::StartAdvertising(ClientProxy* client,