diff --git a/cpp/core/internal/base_endpoint_channel.cc b/cpp/core/internal/base_endpoint_channel.cc index df5c2d59..aea2a501 100644 --- a/cpp/core/internal/base_endpoint_channel.cc +++ b/cpp/core/internal/base_endpoint_channel.cc @@ -266,23 +266,14 @@ void BaseEndpointChannel::Close( std::string BaseEndpointChannel::GetType() const { MutexLock crypto_lock(&crypto_mutex_); std::string subtype = IsEncryptionEnabledLocked() ? "ENCRYPTED_" : ""; + std::string medium = proto::connections::Medium_Name( + proto::connections::Medium::UNKNOWN_MEDIUM); - switch (GetMedium()) { - case proto::connections::Medium::BLUETOOTH: - return absl::StrCat(subtype, "BLUETOOTH"); - case proto::connections::Medium::BLE: - return absl::StrCat(subtype, "BLE"); - case proto::connections::Medium::MDNS: - return absl::StrCat(subtype, "MDNS"); - case proto::connections::Medium::WIFI_HOTSPOT: - return absl::StrCat(subtype, "WIFI_HOTSPOT"); - case proto::connections::Medium::WIFI_LAN: - return absl::StrCat(subtype, "WIFI_LAN"); - case proto::connections::Medium::WEB_RTC: - return absl::StrCat(subtype, "WEB_RTC"); - default: - return "UNKNOWN"; + if (GetMedium() != proto::connections::Medium::UNKNOWN_MEDIUM) { + medium = + absl::StrCat(subtype, proto::connections::Medium_Name(GetMedium())); } + return medium; } std::string BaseEndpointChannel::GetName() const { return channel_name_; } diff --git a/cpp/core/internal/ble_endpoint_channel.cc b/cpp/core/internal/ble_endpoint_channel.cc index 5c8d479a..5cf3bc2b 100644 --- a/cpp/core/internal/ble_endpoint_channel.cc +++ b/cpp/core/internal/ble_endpoint_channel.cc @@ -54,7 +54,9 @@ int BleEndpointChannel::GetMaxTransmitPacketSize() const { void BleEndpointChannel::CloseImpl() { auto status = ble_socket_.Close(); if (!status.Ok()) { - NEARBY_LOG(INFO, "Failed to close Ble socket: exception=%d", status.value); + NEARBY_LOGS(INFO) + << "Failed to close underlying socket for BleEndpointChannel " + << GetName() << ": exception=" << status.value; } } diff --git a/cpp/core/internal/bluetooth_bwu_handler.cc b/cpp/core/internal/bluetooth_bwu_handler.cc index efbe1c58..bb6e84dc 100644 --- a/cpp/core/internal/bluetooth_bwu_handler.cc +++ b/cpp/core/internal/bluetooth_bwu_handler.cc @@ -79,8 +79,18 @@ ByteArray BluetoothBwuHandler::InitializeUpgradedMediumForEndpoint( &BluetoothBwuHandler::OnIncomingBluetoothConnection, this, client, service_id), })) { + NEARBY_LOGS(ERROR) << "BluetoothBwuHandler couldn't initiate the " + "BLUETOOTH upgrade for endpoint " + << endpoint_id + << " because it failed to start listening for " + "incoming Bluetooth connections."; + return {}; } + NEARBY_LOGS(VERBOSE) + << "BluetoothBwuHandler successfully started listening for incoming " + "Bluetooth connections on serviceid=" + << upgrade_service_id << " while upgrading endpoint " << endpoint_id; } // cache service ID to revert active_service_ids_.emplace(upgrade_service_id); @@ -99,26 +109,50 @@ BluetoothBwuHandler::CreateUpgradedEndpointChannel( upgrade_path_info.bluetooth_credentials(); if (!bluetooth_credentials.has_service_name() || !bluetooth_credentials.has_mac_address()) { + NEARBY_LOG(ERROR, "BluetoothBwuHandler failed to parse UpgradePathInfo."); return nullptr; } const std::string& service_name = bluetooth_credentials.service_name(); const std::string& mac_address = bluetooth_credentials.mac_address(); + NEARBY_LOGS(VERBOSE) << "BluetoothBwuHandler is attempting to connect to " + "available Bluetooth device " + << service_name << ", " << mac_address + << ") for endpoint " << endpoint_id; + BluetoothDevice device = bluetooth_medium_.GetRemoteDevice(mac_address); if (!device.IsValid()) { + NEARBY_LOGS(ERROR) + << "BluetoothBwuHandler failed to derive a valid Bluetooth device " + "from the MAC address (" + << mac_address << ") for endpoint " << endpoint_id; return nullptr; } BluetoothSocket socket = bluetooth_medium_.Connect( device, service_name, client->GetCancellationFlag(endpoint_id)); if (!socket.IsValid()) { + NEARBY_LOGS(ERROR) + << "BluetoothBwuHandler failed to connect to the Bluetooth device (" + << service_name << ", " << mac_address << ") for endpoint " + << endpoint_id; return nullptr; } + NEARBY_LOGS(VERBOSE) + << "BluetoothBwuHandler successfully connected to Bluetooth device (" + << service_name << ", " << mac_address << ") while upgrading endpoint " + << endpoint_id; + auto channel = std::make_unique(service_name, socket); if (channel == nullptr) { + NEARBY_LOGS(ERROR) + << "BluetoothBwuHandler failed to create Bluetooth endpoint " + "channel to the Bluetooth device (" + << service_name << ", " << mac_address << ") for endpoint " + << endpoint_id; socket.Close(); return nullptr; } diff --git a/cpp/core/internal/bluetooth_endpoint_channel.cc b/cpp/core/internal/bluetooth_endpoint_channel.cc index 56939081..7e38e648 100644 --- a/cpp/core/internal/bluetooth_endpoint_channel.cc +++ b/cpp/core/internal/bluetooth_endpoint_channel.cc @@ -54,7 +54,9 @@ int BluetoothEndpointChannel::GetMaxTransmitPacketSize() const { void BluetoothEndpointChannel::CloseImpl() { auto status = bluetooth_socket_.Close(); if (!status.Ok()) { - NEARBY_LOG(INFO, "Failed to close BT socket: exception=%d", status.value); + NEARBY_LOGS(INFO) + << "Failed to close underlying socket for BluetoothEndpointChannel " + << GetName() << ": exception=" << status.value; } } diff --git a/cpp/core/internal/bwu_manager.cc b/cpp/core/internal/bwu_manager.cc index 9d81ef41..406a8fa0 100644 --- a/cpp/core/internal/bwu_manager.cc +++ b/cpp/core/internal/bwu_manager.cc @@ -152,17 +152,30 @@ void BwuManager::InitiateBwuForEndpoint(ClientProxy* client, proposed_medium = new_medium; } auto* handler = SetCurrentBwuHandler(proposed_medium); - - if (!handler) return; + if (!handler) { + NEARBY_LOGS(ERROR) + << "BwuManager cannot initiate bandwidth upgrade for endpoint " + << endpoint_id + << " because the current BandwidthUpgradeMedium cannot be deduced."; + return; + } if (in_progress_upgrades_.contains(endpoint_id)) { + NEARBY_LOGS(INFO) + << "BwuManager is ignoring bandwidth upgrade for endpoint " + << endpoint_id + << " because we're already upgrading bandwidth for that endpoint."; + return; } CancelRetryUpgradeAlarm(endpoint_id); auto channel = channel_manager_->GetChannelForEndpoint(endpoint_id); - if (channel == nullptr) { + NEARBY_LOGS(INFO) + << "BwuManager couldn't complete the upgrade for endpoint " + << endpoint_id + << " because it couldn't find an existing EndpointChannel for it."; return; } @@ -173,6 +186,11 @@ void BwuManager::InitiateBwuForEndpoint(ClientProxy* client, // LAN). Very specifically, this happens now when a device uses P2P_CLUSTER, // connects over Bluetooth, and is not connected to LAN. Bluetooth is the // best medium, and we attempt to upgrade from Bluetooth to Bluetooth. + // if (medium_ == channel->GetMedium()) { + NEARBY_LOGS(INFO) << "BwuManager ignoring the upgrade for endpoint " + << endpoint_id + << " because it is already connected over medium " + << proto::connections::Medium_Name(medium_); if (medium_ == channel->GetMedium()) { return; } @@ -184,11 +202,12 @@ void BwuManager::InitiateBwuForEndpoint(ClientProxy* client, // Because we grab the endpointChannel first thing, it is possible the // endpointChannel is stale by the time we attempt to write over it. if (bytes.Empty()) { - NEARBY_LOG(ERROR, - "Couldn't complete the upgrade for endpoint " - "%s to %d because it failed to initialize the " - "BWU_NEGOTIATION.UPGRADE_PATH_AVAILABLE OfflineFrame.", - endpoint_id.c_str(), medium_); + NEARBY_LOGS(ERROR) + << "BwuManager couldn't complete the upgrade for endpoint " + << endpoint_id << " to medium " + << proto::connections::Medium_Name(medium_) + << " because it failed to initialize the " + "BWU_NEGOTIATION.UPGRADE_PATH_AVAILABLE OfflineFrame."; UpgradePathInfo info; info.set_medium(parser::MediumToUpgradePathInfoMedium(medium_)); @@ -196,18 +215,21 @@ void BwuManager::InitiateBwuForEndpoint(ClientProxy* client, return; } if (!channel->Write(bytes).Ok()) { - NEARBY_LOG(ERROR, - "Couldn't complete the upgrade for endpoint %s to %d because " - "it failed to write the " - "BWU_NEGOTIATION.UPGRADE_PATH_AVAILABLE OfflineFrame.", - endpoint_id.c_str(), medium_); + NEARBY_LOGS(ERROR) + << "BwuManager couldn't complete the upgrade for endpoint " + << endpoint_id << " to medium " + << proto::connections::Medium_Name(medium_) + << " because it failed to write the " + "BWU_NEGOTIATION.UPGRADE_PATH_AVAILABLE OfflineFrame."; return; } - NEARBY_LOG(INFO, - "Successfully wrote the BWU_NEGOTIATION.UPGRADE_PATH_AVAILABLE " - "OfflineFrame while upgrading endpoint %s to %d.", - endpoint_id.c_str(), medium_); + NEARBY_LOGS(INFO) + << "BwuManager successfully wrote the " + "BWU_NEGOTIATION.UPGRADE_PATH_AVAILABLE OfflineFrame while " + "upgrading endpoint " + << endpoint_id << " to medium" + << proto::connections::Medium_Name(medium_); in_progress_upgrades_.emplace(endpoint_id, client); }); } @@ -215,8 +237,9 @@ void BwuManager::InitiateBwuForEndpoint(ClientProxy* client, void BwuManager::OnIncomingFrame(OfflineFrame& frame, const std::string& endpoint_id, ClientProxy* client, Medium medium) { - NEARBY_LOG(INFO, "OnIncomingFrame for endpoint %s with medium: %d", - endpoint_id.c_str(), medium); + NEARBY_LOGS(INFO) << "OnIncomingFrame for endpoint " << endpoint_id + << " with medium " + << proto::connections::Medium_Name(medium); if (parser::GetFrameType(frame) != V1Frame::BANDWIDTH_UPGRADE_NEGOTIATION) return; auto bwu_frame = frame.v1().bandwidth_upgrade_negotiation(); @@ -239,11 +262,17 @@ void BwuManager::OnIncomingFrame(OfflineFrame& frame, void BwuManager::OnEndpointDisconnect(ClientProxy* client, const std::string& endpoint_id, CountDownLatch barrier) { - NEARBY_LOG(INFO, "OnEndpointDisconnect for endpoint %s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "BwuManager has processed endpoint disconnection for endpoint " + << endpoint_id; RunOnBwuManagerThread( "bwu-on-endpoint-disconnect", [this, client, endpoint_id, barrier]() mutable { if (medium_ == Medium::UNKNOWN_MEDIUM) { + NEARBY_LOGS(INFO) + << "BwuManager has processed endpoint disconnection for endpoint " + << endpoint_id + << " because there is no current BandwidthUpgradeMedium."; barrier.CountDown(); return; } @@ -278,7 +307,8 @@ void BwuManager::OnEndpointDisconnect(ClientProxy* client, } BwuHandler* BwuManager::SetCurrentBwuHandler(Medium medium) { - NEARBY_LOG(INFO, "SetCurrentBwuHandler to %d", medium); + NEARBY_LOGS(INFO) << "SetCurrentBwuHandler to medium " + << proto::connections::Medium_Name(medium); handler_ = nullptr; medium_ = medium; if (medium != Medium::UNKNOWN_MEDIUM) { @@ -291,7 +321,8 @@ BwuHandler* BwuManager::SetCurrentBwuHandler(Medium medium) { } void BwuManager::Revert() { - NEARBY_LOG(INFO, "Revert reseting medium %d", medium_); + NEARBY_LOGS(INFO) << "Revert reseting medium " + << proto::connections::Medium_Name(medium_); if (handler_) { handler_->Revert(); handler_ = nullptr; @@ -302,8 +333,8 @@ void BwuManager::Revert() { void BwuManager::OnBwuNegotiationFrame(ClientProxy* client, const BwuNegotiationFrame frame, const string& endpoint_id) { - NEARBY_LOG(INFO, "OnBwuNegotiationFrame for endpoint %s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "BwuManager process incoming OfflineFrame for endpoint " + << endpoint_id; switch (frame.event_type()) { case BwuNegotiationFrame::UPGRADE_PATH_AVAILABLE: ProcessBwuPathAvailableEvent(client, endpoint_id, @@ -320,6 +351,9 @@ void BwuManager::OnBwuNegotiationFrame(ClientProxy* client, ProcessSafeToClosePriorChannelEvent(client, endpoint_id); break; default: + NEARBY_LOGS(WARNING) + << "BwuManager can't process unknown incoming OfflineFrame of type " + << frame.event_type() << ", ignoring it."; break; } } @@ -327,23 +361,37 @@ void BwuManager::OnBwuNegotiationFrame(ClientProxy* client, void BwuManager::OnIncomingConnection( ClientProxy* client, std::unique_ptr mutable_connection) { - NEARBY_LOG(INFO, "OnIncomingConnection service id: %s", - client->GetServiceId().c_str()); + NEARBY_LOGS(INFO) << "BwuManager process incoming connection service_id=" + << client->GetServiceId(); std::shared_ptr connection( mutable_connection.release()); RunOnBwuManagerThread( "bwu-on-incoming-connection", [this, client, connection]() { EndpointChannel* channel = connection->channel.get(); if (channel == nullptr) { + NEARBY_LOG( + ERROR, + "BwuManager failed to create new EndpointChannel for incoming " + "socket."); connection->socket->Close(); return; } + NEARBY_LOGS(VERBOSE) + << "BwuManager successfully created new EndpointChannel for " + "incoming socket"; + ClientIntroduction introduction; if (!ReadClientIntroductionFrame(channel, introduction)) { // This was never a fully EstablishedConnection, no need to provide a // closure reason. channel->Close(); + NEARBY_LOGS(ERROR) + << "BwuManager failed to read " + "BWU_NEGOTIATION.CLIENT_INTRODUCTION OfflineFrame from " + "newly-created EndpointChannel " + << channel->GetName() + << ", so the EndpointChannel was discarded."; return; } @@ -354,6 +402,11 @@ void BwuManager::OnIncomingConnection( return; } + NEARBY_LOGS(VERBOSE) << "BwuManager successfully received " + "BWU_NEGOTIATION.CLIENT_INTRODUCTION " + "OfflineFrame on EndpointChannel " + << channel->GetName(); + const std::string& endpoint_id = introduction.endpoint_id(); ClientProxy* mapped_client; const auto item = in_progress_upgrades_.find(endpoint_id); @@ -397,7 +450,14 @@ void BwuManager::RunUpgradeProtocol( // side to read messages out of sequence new_channel->Pause(); auto old_channel = channel_manager_->GetChannelForEndpoint(endpoint_id); - if (!old_channel) return; + if (!old_channel) { + NEARBY_LOGS(INFO) + << "BwuManager didn't find a previous EndpointChannel for " + << endpoint_id + << " when registering the new EndpointChannel, short-circuiting the " + "upgrade protocol."; + return; + } channel_manager_->ReplaceChannelForEndpoint(client, endpoint_id, std::move(new_channel)); @@ -405,8 +465,17 @@ void BwuManager::RunUpgradeProtocol( // this endpoint by telling the remote device that it will not receive any // more writes over that EndpointChannel. if (!old_channel->Write(parser::ForBwuLastWrite()).Ok()) { + NEARBY_LOGS(ERROR) + << "BwuManager failed to write " + "BWU_NEGOTIATION.LAST_WRITE_TO_PRIOR_CHANNEL OfflineFrame to " + "endpoint " + << endpoint_id << ", short-circuiting the upgrade protocol."; return; } + NEARBY_LOGS(VERBOSE) << "BwuManager successfully wrote " + "BWU_NEGOTIATION.LAST_WRITE_TO_PRIOR_CHANNEL " + "OfflineFrame while upgrading endpoint " + << endpoint_id; // The remainder of this clean shutdown for the previous EndpointChannel will // continue when we receive a corresponding @@ -426,17 +495,16 @@ void BwuManager::RunUpgradeProtocol( void BwuManager::ProcessBwuPathAvailableEvent( ClientProxy* client, const string& endpoint_id, const UpgradePathInfo& upgrade_path_info) { - NEARBY_LOG(INFO, "ProcessBwuPathAvailableEvent for endpoint %s medium %d.", - endpoint_id.c_str(), - parser::UpgradePathInfoMediumToMedium(upgrade_path_info.medium())); + NEARBY_LOGS(INFO) << "ProcessBwuPathAvailableEvent for endpoint " + << endpoint_id << " medium " + << parser::UpgradePathInfoMediumToMedium( + upgrade_path_info.medium()); if (in_progress_upgrades_.contains(endpoint_id)) { - NEARBY_LOG(INFO, "Invoking duplicate ProcessBwuPathAvailableEvent for %s", - endpoint_id.c_str()); - NEARBY_LOG(ERROR, - "BandwidthUpgradeManager received a duplicate bandwidth " - "upgrade for endpoint %s. We're out of sync with the remote " - "device and cannot recover; closing all channels.", - endpoint_id.c_str()); + NEARBY_LOGS(ERROR) + << "BwuManager received a duplicate bandwidth upgrade for endpoint " + << endpoint_id + << ". We're out of sync with the remote device and cannot recover; " + "closing all channels."; auto item = previous_endpoint_channels_.extract(endpoint_id); if (!item.empty()) { @@ -493,6 +561,9 @@ BwuManager::ProcessBwuPathAvailableEventInternal( handler_->CreateUpgradedEndpointChannel(client, client->GetServiceId(), endpoint_id, upgrade_path_info); if (!channel) { + NEARBY_LOGS(ERROR) + << "BwuManager failed to create an endpoint channel to endpoint" + << endpoint_id << ", aborting upgrade."; return nullptr; } @@ -504,11 +575,10 @@ BwuManager::ProcessBwuPathAvailableEventInternal( // closure reason. channel->Close(); - NEARBY_LOG( - ERROR, - "Failed to write BWU_NEGOTIATION.CLIENT_INTRODUCTION OfflineFrame to " - "newly-created EndpointChannel %s, aborting upgrade.", - channel->GetName().c_str()); + NEARBY_LOGS(ERROR) + << "BwuManager failed to write BWU_NEGOTIATION.CLIENT_INTRODUCTION " + "OfflineFrame to newly-created EndpointChannel " + << channel->GetName() << ", aborting upgrade."; return {}; } @@ -519,21 +589,20 @@ BwuManager::ProcessBwuPathAvailableEventInternal( // closure reason. channel->Close(); - NEARBY_LOG( - ERROR, - "Failed to read BWU_NEGOTIATION.CLIENT_INTRODUCTION_ACK OfflineFrame " - "to newly-created EndpointChannel %s, aborting upgrade.", - channel->GetName().c_str()); + NEARBY_LOGS(ERROR) << "BwuManager failed to read " + "BWU_NEGOTIATION.CLIENT_INTRODUCTION_ACK " + "OfflineFrame to newly-created EndpointChannel " + << channel->GetName() << ", aborting upgrade."; return {}; } } - NEARBY_LOG( - INFO, - "Successfully wrote BWU_NEGOTIATION.CLIENT_INTRODUCTION OfflineFrame to " - "newly-created EndpointChannel %s while upgrading endpoint %s.", - channel->GetName().c_str(), endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "BwuManager successfully wrote " + "BWU_NEGOTIATION.CLIENT_INTRODUCTION OfflineFrame to " + "newly-created EndpointChannel " + << channel->GetName() << " while upgrading endpoint " + << endpoint_id; // Set the AnalyticsRecorder so that the future closure of this // EndpointChannel will be recorded. @@ -552,11 +621,11 @@ void BwuManager::RunUpgradeFailedProtocol( std::shared_ptr channel = channel_manager_->GetChannelForEndpoint(endpoint_id); if (!channel) { - NEARBY_LOG(ERROR, - "Couldn't find a previous EndpointChannel for %s " - "when sending an upgrade failure frame, short-circuiting the " - "upgrade protocol.", - endpoint_id.c_str()); + NEARBY_LOGS(ERROR) + << "BwuManager didn't find a previous EndpointChannel for " + << endpoint_id + << " when sending an upgrade failure frame, short-circuiting the " + "upgrade protocol."; return; } @@ -564,11 +633,10 @@ void BwuManager::RunUpgradeFailedProtocol( if (!channel->Write(parser::ForBwuFailure(upgrade_path_info)).Ok()) { channel->Close(DisconnectionReason::IO_ERROR); - NEARBY_LOG( - ERROR, - "Failed to write BANDWIDTH_UPGRADE_NEGOTIATION.UPGRADE_FAILURE " - "OfflineFrame to endpoint %s, short-circuiting the upgrade protocol.", - endpoint_id.c_str()); + NEARBY_LOGS(ERROR) + << "BwuManager failed to write BWU_NEGOTIATION.UPGRADE_FAILURE " + "OfflineFrame to endpoint " + << endpoint_id << ", short-circuiting the upgrade protocol."; return; } @@ -578,6 +646,8 @@ void BwuManager::RunUpgradeFailedProtocol( Revert(); } in_progress_upgrades_.erase(endpoint_id); + NEARBY_LOGS(INFO) << "BwuManager has informed endpoint " << endpoint_id + << " that the bandwidth upgrade failed."; } bool BwuManager::ReadClientIntroductionFrame(EndpointChannel* channel, @@ -588,12 +658,12 @@ bool BwuManager::ReadClientIntroductionFrame(EndpointChannel* channel, CancelableAlarm timeout_alarm( "BwuManager::ReadClientIntroductionFrame", [channel]() { - NEARBY_LOG( - ERROR, - "In BandwidthUpgradeManager, failed to read the " - "ClientIntroductionFrame after %d seconds. Timing out and closing " - "EndpointChannel %s.", - kReadClientIntroductionFrameTimeout, channel->GetType().c_str()); + NEARBY_LOGS(ERROR) << "In BwuManager, failed to read the " + "ClientIntroductionFrame after " + << absl::FormatDuration( + kReadClientIntroductionFrameTimeout) + << ". Timing out and closing EndpointChannel " + << channel->GetType(); channel->Close(); }, kReadClientIntroductionFrameTimeout, &alarm_executor_); @@ -601,13 +671,31 @@ bool BwuManager::ReadClientIntroductionFrame(EndpointChannel* channel, timeout_alarm.Cancel(); if (!data.ok()) return false; auto transfer(parser::FromBytes(data.result())); - if (!transfer.ok()) return false; + if (!transfer.ok()) { + NEARBY_LOGS(ERROR) << "In ReadClientIntroductionFrame, attempted to read a " + "ClientIntroductionFrame from EndpointChannel " + << channel->GetType() + << " but was unable to obtain any OfflineFrame."; + return false; + } OfflineFrame frame = transfer.result(); - if (!frame.has_v1() || !frame.v1().has_bandwidth_upgrade_negotiation()) + if (!frame.has_v1() || !frame.v1().has_bandwidth_upgrade_negotiation()) { + NEARBY_LOGS(ERROR) + << "In ReadClientIntroductionFrame, expected a " + "BANDWIDTH_UPGRADE_NEGOTIATION v1 OfflineFrame but got a " + << parser::GetFrameType(frame) << " frame instead."; return false; + } if (frame.v1().bandwidth_upgrade_negotiation().event_type() != - BandwidthUpgradeNegotiationFrame::CLIENT_INTRODUCTION) + BandwidthUpgradeNegotiationFrame::CLIENT_INTRODUCTION) { + NEARBY_LOGS(ERROR) + << "In ReadClientIntroductionFrame, expected a CLIENT_INTRODUCTION " + "v1 OfflineFrame but got a BANDWIDTH_UPGRADE_NEGOTIATION frame " + "with eventType " + << frame.v1().bandwidth_upgrade_negotiation().event_type() + << " instead."; return false; + } const auto& frame_intro = frame.v1().bandwidth_upgrade_negotiation().client_introduction(); introduction = frame_intro; @@ -615,18 +703,18 @@ bool BwuManager::ReadClientIntroductionFrame(EndpointChannel* channel, } bool BwuManager::ReadClientIntroductionAckFrame(EndpointChannel* channel) { - NEARBY_LOG(INFO, - "ReadClientIntroductionAckFrame with channel name: %s, medium: %d", - channel->GetName().c_str(), channel->GetMedium()); + NEARBY_LOGS(INFO) << "ReadClientIntroductionAckFrame with channel name: " + << channel->GetName() << ", medium: " + << proto::connections::Medium_Name(channel->GetMedium()); CancelableAlarm timeout_alarm( "BwuManager::ReadClientIntroductionAckFrame", [channel]() { - NEARBY_LOG(ERROR, - "In BandwidthUpgradeManager, failed to read the " - "ClientIntroductionAckFrame after %d seconds. Timing out " - "and closing EndpointChannel %s.", - kReadClientIntroductionFrameTimeout, - channel->GetType().c_str()); + NEARBY_LOGS(ERROR) + << "In BwuManager, failed to read the ClientIntroductionAckFrame " + "after " + << absl::FormatDuration(kReadClientIntroductionFrameTimeout) + << ". Timing out and closing EndpointChannel " + << channel->GetType(); channel->Close(); }, kReadClientIntroductionFrameTimeout, &alarm_executor_); @@ -667,12 +755,10 @@ void BwuManager::ProcessLastWriteToPriorChannelEvent( EndpointChannel* previous_endpoint_channel = previous_endpoint_channels_[endpoint_id].get(); if (!previous_endpoint_channel) { - NEARBY_LOG( - ERROR, - "Received a BWU_NEGOTIATION.LAST_WRITE_TO_PRIOR_CHANNEL OfflineFrame " - "for unknown endpoint %s, can't complete the upgrade protocol.", - endpoint_id.c_str()); - + NEARBY_LOGS(ERROR) + << "BwuManager received a BWU_NEGOTIATION.LAST_WRITE_TO_PRIOR_CHANNEL " + "OfflineFrame for unknown endpoint " + << endpoint_id << ", can't complete the upgrade protocol."; successfully_upgraded_endpoints_.emplace(endpoint_id); return; } @@ -683,13 +769,17 @@ void BwuManager::ProcessLastWriteToPriorChannelEvent( // avoid leaks. previous_endpoint_channels_.erase(endpoint_id); - NEARBY_LOG( - ERROR, - "Failed to write BWU_NEGOTIATION.SAFE_TO_CLOSE_PRIOR_CHANNEL " - "OfflineFrame to endpoint %s, short-circuiting the upgrade protocol.", - endpoint_id.c_str()); + NEARBY_LOGS(ERROR) << "BwuManager failed to write " + "BWU_NEGOTIATION.SAFE_TO_CLOSE_PRIOR_CHANNEL " + "OfflineFrame to endpoint " + << endpoint_id + << ", short-circuiting the upgrade protocol."; return; } + NEARBY_LOGS(VERBOSE) << "BwuManager successfully wrote " + "BWU_NEGOTIATION.SAFE_TO_CLOSE_PRIOR_CHANNEL " + "OfflineFrame while trying to upgrade endpoint " + << endpoint_id; // The upgrade protocol's clean shutdown of the prior EndpointChannel will // conclude when we receive a corresponding @@ -717,11 +807,10 @@ void BwuManager::ProcessSafeToClosePriorChannelEvent( auto item = previous_endpoint_channels_.extract(endpoint_id); auto& previous_endpoint_channel = item.mapped(); if (previous_endpoint_channel == nullptr) { - NEARBY_LOG( - ERROR, - "Received a BWU_NEGOTIATION.SAFE_TO_CLOSE_PRIOR_CHANNEL OfflineFrame " - "for unknown endpoint %s, can't complete the upgrade protocol.", - endpoint_id.c_str()); + NEARBY_LOGS(ERROR) + << "BwuManager received a BWU_NEGOTIATION.SAFE_TO_CLOSE_PRIOR_CHANNEL " + "OfflineFrame for unknown endpoint " + << endpoint_id << ", can't complete the upgrade protocol."; return; } @@ -746,15 +835,20 @@ void BwuManager::ProcessSafeToClosePriorChannelEvent( previous_endpoint_channel->Read(); previous_endpoint_channel->Close(DisconnectionReason::UPGRADED); + NEARBY_LOGS(VERBOSE) + << "BwuManager cleanly shut down prior " + << previous_endpoint_channel->GetType() + << " EndpointChannel to conclude upgrade protocol for endpoint " + << endpoint_id; + // Now that the old channel has been drained, we can unpause the new channel std::shared_ptr channel = channel_manager_->GetChannelForEndpoint(endpoint_id); if (!channel) { - NEARBY_LOG(ERROR, - "Attempted to resume the current EndpointChannel with endpoint " - "%s, but none was found", - endpoint_id.c_str()); + NEARBY_LOGS(ERROR) << "BwuManager attempted to resume the current " + "EndpointChannel with endpoint " + << endpoint_id << ", but none was found."; return; } @@ -768,9 +862,10 @@ void BwuManager::ProcessSafeToClosePriorChannelEvent( void BwuManager::ProcessUpgradeFailureEvent( ClientProxy* client, const std::string& endpoint_id, const UpgradePathInfo& upgrade_info) { - NEARBY_LOG(INFO, "ProcessUpgradeFailureEvent for endpoint %s from medium: %d", - endpoint_id.c_str(), - parser::UpgradePathInfoMediumToMedium(upgrade_info.medium())); + NEARBY_LOGS(INFO) << "ProcessUpgradeFailureEvent for endpoint " << endpoint_id + << " from medium: " + << parser::UpgradePathInfoMediumToMedium( + upgrade_info.medium()); // The remote device failed to upgrade to the new medium we set up for them. // That's alright! We'll just try the next available medium (if there is // one). @@ -784,11 +879,11 @@ void BwuManager::ProcessUpgradeFailureEvent( if (channel_manager_->GetConnectedEndpointsCount() > 1) { // We can't change the currentBwuMedium, so there are no more // upgrade attempts for this endpoint. Sorry. - NEARBY_LOG( - ERROR, - "Failed to attempt a new bandwidth upgrade for endpoint %s because we " - "have other connected endpoints and can't try a new upgrade medium.", - endpoint_id.c_str()); + NEARBY_LOGS(ERROR) + << "BwuManager failed to attempt a new bandwidth upgrade for endpoint " + << endpoint_id + << " because we have other connected endpoints and can't try a new " + "upgrade medium."; return; } @@ -917,10 +1012,15 @@ Medium BwuManager::ChooseBestUpgradeMedium(const std::vector& mediums) { // empty). Fall through and return Medium.UNKNOWN_MEDIUM because we cannot // continue with the current upgrade medium, and we are not allowed to // switch. - NEARBY_LOG( - INFO, - "Current upgrade medium %d is not supported by the remote endpoint", - medium_); + std::string mediums_string; + for (const auto& medium : available_mediums) { + absl::StrAppend(&mediums_string, proto::connections::Medium_Name(medium), + "; "); + } + NEARBY_LOGS(INFO) + << "Current upgrade medium " << proto::connections::Medium_Name(medium_) + << " is not supported by the remote endpoint (supported mediums: " + << mediums_string << ")"; } return Medium::UNKNOWN_MEDIUM; @@ -948,7 +1048,8 @@ void BwuManager::RetryUpgradesAfterDelay(ClientProxy* client, retry_upgrade_alarms_.emplace(endpoint_id, std::make_pair(std::move(alarm), delay)); retry_delays_[endpoint_id] = delay; - NEARBY_LOGS(INFO) << "Retry bandwidth upgrade after " << delay; + NEARBY_LOGS(INFO) << "Retry bandwidth upgrade after " + << absl::FormatDuration(delay); } absl::Duration BwuManager::CalculateNextRetryDelay( @@ -970,7 +1071,7 @@ absl::Duration BwuManager::CalculateNextRetryDelay( } void BwuManager::CancelRetryUpgradeAlarm(const std::string& endpoint_id) { - NEARBY_LOG(INFO, "CancelRetryUpgradeAlarm for %s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "CancelRetryUpgradeAlarm for endpoint " << endpoint_id; auto item = retry_upgrade_alarms_.extract(endpoint_id); if (item.empty()) return; auto& pair = item.mapped(); @@ -982,7 +1083,7 @@ void BwuManager::CancelAllRetryUpgradeAlarms() { for (auto& item : retry_upgrade_alarms_) { const std::string& endpoint_id = item.first; CancelableAlarm& cancellable_alarm = item.second.first; - NEARBY_LOG(INFO, "CancelRetryUpgradeAlarm for %s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "CancelRetryUpgradeAlarm for endpoint " << endpoint_id; cancellable_alarm.Cancel(); } retry_upgrade_alarms_.clear(); diff --git a/cpp/core/internal/endpoint_channel_manager.cc b/cpp/core/internal/endpoint_channel_manager.cc index f099fa57..49d2eda9 100644 --- a/cpp/core/internal/endpoint_channel_manager.cc +++ b/cpp/core/internal/endpoint_channel_manager.cc @@ -34,8 +34,10 @@ const absl::Duration kDataTransferDelay = absl::Milliseconds(500); } EndpointChannelManager::~EndpointChannelManager() { + NEARBY_LOG(INFO, "Initiating shutdown of EndpointChannelManager."); MutexLock lock(&mutex_); channel_state_.DestroyAll(); + NEARBY_LOG(INFO, "EndpointChannelManager has shut down."); } void EndpointChannelManager::RegisterChannelForEndpoint( @@ -43,6 +45,8 @@ void EndpointChannelManager::RegisterChannelForEndpoint( std::unique_ptr channel) { MutexLock lock(&mutex_); + NEARBY_LOGS(INFO) << "EndpointChannelManager registered channel of type " + << channel->GetType() << " to endpoint " << endpoint_id; SetActiveEndpointChannel(client, endpoint_id, std::move(channel)); NEARBY_LOG(INFO, "Registered channel: id=%s", endpoint_id.c_str()); @@ -55,8 +59,9 @@ void EndpointChannelManager::ReplaceChannelForEndpoint( auto* endpoint = channel_state_.LookupEndpointData(endpoint_id); if (endpoint != nullptr && endpoint->channel == nullptr) { - NEARBY_LOG(INFO, "Channel is missing while trying to update: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "EndpointChannelManager is missing channel while " + "trying to update: endpoint " + << endpoint_id; } SetActiveEndpointChannel(client, endpoint_id, std::move(channel)); @@ -79,7 +84,7 @@ std::shared_ptr EndpointChannelManager::GetChannelForEndpoint( auto* endpoint = channel_state_.LookupEndpointData(endpoint_id); if (endpoint == nullptr) { - NEARBY_LOG(INFO, "No channel info: id=%s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "No channel info for endpoint " << endpoint_id; return {}; } @@ -148,6 +153,9 @@ bool EndpointChannelManager::ChannelState::RemoveEndpoint( channel->Resume(); channel->Write(parser::ForDisconnection()); + NEARBY_LOGS(INFO) + << "EndpointChannelManager reported the disconnection to endpoint " + << endpoint_id; SystemClock::Sleep(kDataTransferDelay); } endpoints_.erase(item); @@ -164,7 +172,9 @@ bool EndpointChannelManager::UnregisterChannelForEndpoint( return false; } - NEARBY_LOG(INFO, "Unregistered channel: id=%s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) + << "EndpointChannelManager unregistered channel for endpoint " + << endpoint_id; return true; } diff --git a/cpp/core/internal/endpoint_manager.cc b/cpp/core/internal/endpoint_manager.cc index d0d4d0c0..1c0153cd 100644 --- a/cpp/core/internal/endpoint_manager.cc +++ b/cpp/core/internal/endpoint_manager.cc @@ -19,6 +19,7 @@ #include "core/internal/endpoint_channel.h" #include "core/internal/offline_frames.h" +#include "proto/connections/offline_wire_formats.pb.h" #include "platform/base/exception.h" #include "platform/public/count_down_latch.h" #include "platform/public/logging.h" @@ -121,16 +122,17 @@ void EndpointManager::EndpointChannelLoopRunnable( // detail. if (exception.Raised(Exception::kInvalidProtocolBuffer)) { last_failed_medium = channel->GetMedium(); - NEARBY_LOG(INFO, - "Received invalid protobuf message, re-fetching endpoint " - "channel; last_failed_medium=%d", - last_failed_medium); + NEARBY_LOGS(INFO) + << "Received invalid protobuf message, re-fetching endpoint " + "channel; last_failed_medium=" + << proto::connections::Medium_Name(last_failed_medium); continue; } if (exception.Raised(Exception::kIo)) { last_failed_medium = channel->GetMedium(); - NEARBY_LOG(INFO, "Endpoint channel IO exception; last_failed_medium=%d", - last_failed_medium); + NEARBY_LOGS(INFO) + << "Endpoint channel IO exception; last_failed_medium=" + << proto::connections::Medium_Name(last_failed_medium); continue; } if (exception.Raised(Exception::kInterrupted)) { @@ -139,15 +141,15 @@ void EndpointManager::EndpointChannelLoopRunnable( } if (!keep_using_channel.result()) { - NEARBY_LOG(INFO, "Dropping current channel: last medium=%d", - last_failed_medium); + NEARBY_LOGS(INFO) << "Dropping current channel: last medium=" + << proto::connections::Medium_Name(last_failed_medium); break; } } // Indicate we're out of the loop and it is ok to schedule another instance // if needed. - NEARBY_LOG(INFO, "Worker going down; name=%s; id=%s", runnable_name.c_str(), - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Worker going down; worker name=" << runnable_name + << "; endpoint_id=" << endpoint_id; if (auto latch = barrier.lock()) { latch->CountDown(); } else { @@ -159,8 +161,8 @@ void EndpointManager::EndpointChannelLoopRunnable( // Always clear out all state related to this endpoint before terminating // this thread. DiscardEndpoint(client, endpoint_id); - NEARBY_LOG(INFO, "Worker done; name=%s; id=%s", runnable_name.c_str(), - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Worker done; worker name=" << runnable_name + << "; endpoint_id=" << endpoint_id; } ExceptionOr EndpointManager::HandleData( @@ -200,13 +202,16 @@ ExceptionOr EndpointManager::HandleData( // report messages without handlers, except KEEP_ALIVE, which has // no explicit handler. if (frame_type == V1Frame::KEEP_ALIVE) { - NEARBY_LOG(INFO, "KeepAlive message for: id=%s", endpoint_id.c_str()); + NEARBY_LOG(INFO, "KeepAlive message for endpoint %s", + endpoint_id.c_str()); } else if (frame_type == V1Frame::DISCONNECTION) { - NEARBY_LOG(INFO, "Disconnect message for: id=%s", endpoint_id.c_str()); + NEARBY_LOG(INFO, "Disconnect message for endpoint %s", + endpoint_id.c_str()); endpoint_channel->Close(); } else { - NEARBY_LOG(ERROR, "Unhandled message: id=%s, type=%d", - endpoint_id.c_str(), frame_type); + NEARBY_LOGS(ERROR) << "Unhandled message: endpoint_id=" << endpoint_id + << ", frame type=" + << V1Frame::FrameType_Name(frame_type); } continue; } @@ -267,7 +272,7 @@ EndpointManager::EndpointManager(EndpointChannelManager* manager) : channel_manager_(manager) {} EndpointManager::~EndpointManager() { - NEARBY_LOG(INFO, "EndpointManager going down"); + NEARBY_LOG(INFO, "Initiating shutdown of EndpointManager."); CountDownLatch latch(1); RunOnEndpointManagerThread("bring-down-endpoints", [this, &latch]() { NEARBY_LOG(INFO, "Bringing down endpoints"); @@ -280,10 +285,9 @@ EndpointManager::~EndpointManager() { if (state.barrier) { state.barrier->Await(); } else { - NEARBY_LOG( - WARNING, - "State barrier already freed before EM destructor for endpoint %s", - endpoint_id.c_str()); + NEARBY_LOGS(WARNING) + << "State barrier already freed before EM destructor for endpoint" + << endpoint_id; } } latch.CountDown(); @@ -304,13 +308,19 @@ EndpointManager::~EndpointManager() { void EndpointManager::RegisterFrameProcessor( V1Frame::FrameType frame_type, EndpointManager::FrameProcessor* processor) { if (auto frame_processor = GetFrameProcessor(frame_type)) { - NEARBY_LOGS(INFO) << "Frame processor found: updated; type=" << frame_type - << "; processor=" << processor << "; self=" << this; + NEARBY_LOGS(INFO) << "EndpointManager received request to update " + "registration of frame processor " + << processor << " for frame type " + << V1Frame::FrameType_Name(frame_type) << ", self" + << this; frame_processor.set(processor); } else { MutexLock lock(&frame_processors_lock_); - NEARBY_LOGS(INFO) << "Frame processor added; type=" << frame_type - << "; processor=" << processor << "; self=" << this; + NEARBY_LOGS(INFO) << "EndpointManager received request to add registration " + "of frame processor " + << processor << " for frame type " + << V1Frame::FrameType_Name(frame_type) + << ", self=" << this; frame_processors_.emplace(frame_type, processor); } } @@ -324,14 +334,16 @@ void EndpointManager::UnregisterFrameProcessor( if (auto frame_processor = GetFrameProcessor(frame_type)) { if (frame_processor.get() == processor) { frame_processor.reset(); - NEARBY_LOGS(INFO) << "Unregistered: type=" << frame_type - << "; processor=" << processor << "; self=" << this; + NEARBY_LOGS(INFO) << "EndpointManager unregister frame processor " + << processor << " for frame type " + << V1Frame::FrameType_Name(frame_type) + << ", self=" << this; } else { - NEARBY_LOG( - INFO, - "Failed to unregister: type=%d; processor mismatch: passed=%p, " - "expected=%p", - frame_type, processor, frame_processor.get()); + NEARBY_LOGS(INFO) << "EndpointManager cannot unregister frame processor " + << processor + << " because it is not registered for frame type " + << V1Frame::FrameType_Name(frame_type) + << ", expected=" << frame_processor.get(); } } else { NEARBY_LOGS(INFO) << "UnregisterFrameProcessor [not found]: processor=" @@ -350,29 +362,27 @@ EndpointManager::LockedFrameProcessor EndpointManager::GetFrameProcessor( } void EndpointManager::EnsureWorkersTerminated(const std::string& endpoint_id) { - NEARBY_LOG(ERROR, "EnsureWorkersTerminated for endpoint %s", - endpoint_id.c_str()); + NEARBY_LOGS(ERROR) << "EnsureWorkersTerminated for endpoint " << endpoint_id; auto item = endpoints_.find(endpoint_id); if (item != endpoints_.end()) { - NEARBY_LOGS(INFO) << "EndpointState found for id: " << endpoint_id; + NEARBY_LOGS(INFO) << "EndpointState found for endpoint " << endpoint_id; // If another instance of data and keep-alive handlers is running, it will // terminate soon; we should block until it happens. EndpointState& endpoint_state = item->second; - NEARBY_LOGS(INFO) << "Waiting for workers to terminate for id: " + NEARBY_LOGS(INFO) << "Waiting for workers to terminate for endpoint " << endpoint_id; if (endpoint_state.barrier) { endpoint_state.barrier->Await(); } else { - NEARBY_LOG( - WARNING, - "State barrier already freed before EnsureWorkersTerminated for " - "endpoint %s", - endpoint_id.c_str()); + NEARBY_LOGS(WARNING) + << "State barrier already freed before EnsureWorkersTerminated for " + "endpoint " + << endpoint_id; } endpoints_.erase(item); - NEARBY_LOGS(INFO) << "Workers terminated for id: " << endpoint_id; + NEARBY_LOGS(INFO) << "Workers terminated for endpoint " << endpoint_id; } else { - NEARBY_LOGS(INFO) << "EndpointState not found for id: " << endpoint_id; + NEARBY_LOGS(INFO) << "EndpointState not found for endpoint " << endpoint_id; } } @@ -396,8 +406,7 @@ void EndpointManager::RegisterEndpoint(ClientProxy* client, &options, &listener, &latch]() { if (endpoints_.contains(endpoint_id)) { - NEARBY_LOG(WARNING, "Registing duplicate endpoint %s", - endpoint_id.c_str()); + NEARBY_LOGS(WARNING) << "Registing duplicate endpoint " << endpoint_id; if (!FeatureFlags::GetInstance() .GetFlags() .endpoint_manager_ensure_workers_terminated_inside_remove) { @@ -409,16 +418,16 @@ void EndpointManager::RegisterEndpoint(ClientProxy* client, absl::Milliseconds(options.keep_alive_interval_millis); absl::Duration keep_alive_timeout = absl::Milliseconds(options.keep_alive_timeout_millis); - NEARBY_LOGS(INFO) << "Registering endpoint " << endpoint_id.c_str() + NEARBY_LOGS(INFO) << "Registering endpoint " << endpoint_id << " for client " << client->GetClientId() << " with keep-alive frame as interval=" - << absl::FormatDuration(keep_alive_interval).c_str() + << absl::FormatDuration(keep_alive_interval) << ", timeout=" - << absl::FormatDuration(keep_alive_timeout).c_str(); + << absl::FormatDuration(keep_alive_timeout); // Pass ownership of channel to EndpointChannelManager - NEARBY_LOG(INFO, "Registering endpoint with channel manager: id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Registering endpoint with channel manager: endpoint " + << endpoint_id; channel_manager_->RegisterChannelForEndpoint( client, endpoint_id, std::unique_ptr(channel)); @@ -426,7 +435,7 @@ void EndpointManager::RegisterEndpoint(ClientProxy* client, endpoints_.emplace(endpoint_id, EndpointState()).first->second; endpoint_state.client = client; - NEARBY_LOG(INFO, "Starting workers: id=%s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Starting workers: endpoint " << endpoint_id; // For every endpoint, there's normally only one Read handler instance // running on the handlers_executor_ pool. This instance reads data from the // endpoint and delegates incoming frames to various FrameProcessors. @@ -461,6 +470,8 @@ void EndpointManager::RegisterEndpoint(ClientProxy* client, // // Using weak_ptr just in case the barrier is freed, to save the UAF crash // in b/179800119. + NEARBY_LOGS(VERBOSE) << "EndpointManager enabling KeepAlive for endpoint " + << endpoint_id; StartEndpointKeepAliveManager( [this, client, endpoint_id, keep_alive_interval, keep_alive_timeout, barrier = std::weak_ptr(endpoint_state.barrier)]() { @@ -472,8 +483,8 @@ void EndpointManager::RegisterEndpoint(ClientProxy* client, keep_alive_timeout); }); }); - NEARBY_LOG(INFO, "Workers started, notifying client; id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Registering endpoint " << endpoint_id + << ", workers started and notifying client."; // It's now time to let the client know of this new connection so that // they can accept or reject it. @@ -485,7 +496,7 @@ void EndpointManager::RegisterEndpoint(ClientProxy* client, void EndpointManager::UnregisterEndpoint(ClientProxy* client, const std::string& endpoint_id) { - NEARBY_LOG(ERROR, "UnregisterEndpoint for endpoint %s", endpoint_id.c_str()); + NEARBY_LOGS(ERROR) << "UnregisterEndpoint for endpoint " << endpoint_id; CountDownLatch latch(1); RunOnEndpointManagerThread( "unregister-endpoint", [this, client, endpoint_id, &latch]() { @@ -513,9 +524,11 @@ std::vector EndpointManager::SendPayloadChunk( ByteArray bytes = parser::ForDataPayloadTransfer(payload_header, payload_chunk); - return SendTransferFrameBytes(endpoint_ids, bytes, payload_header.id(), - /*offset=*/payload_chunk.offset(), - /*packet_type=*/"DATA"); + return SendTransferFrameBytes( + endpoint_ids, bytes, payload_header.id(), + /*offset=*/payload_chunk.offset(), + /*packet_type=*/ + PayloadTransferFrame::PacketType_Name(PayloadTransferFrame::DATA)); } // Designed to run asynchronously. It is called from IO thread pools, and @@ -523,7 +536,7 @@ std::vector EndpointManager::SendPayloadChunk( // allow synchronous behavior here it will cause a live lock. void EndpointManager::DiscardEndpoint(ClientProxy* client, const std::string& endpoint_id) { - NEARBY_LOG(ERROR, "DiscardEndpoint for endpoint %s", endpoint_id.c_str()); + NEARBY_LOGS(ERROR) << "DiscardEndpoint for endpoint " << endpoint_id; RunOnEndpointManagerThread("discard-endpoint", [this, client, endpoint_id]() { RemoveEndpoint(client, endpoint_id, /*notify=*/ @@ -537,16 +550,18 @@ std::vector EndpointManager::SendControlMessage( const std::vector& endpoint_ids) { ByteArray bytes = parser::ForControlPayloadTransfer(header, control); - return SendTransferFrameBytes(endpoint_ids, bytes, header.id(), - /*offset=*/control.offset(), - /*packet_type=*/"CONTROL"); + return SendTransferFrameBytes( + endpoint_ids, bytes, header.id(), + /*offset=*/control.offset(), + /*packet_type=*/ + PayloadTransferFrame::PacketType_Name(PayloadTransferFrame::CONTROL)); } // @EndpointManagerThread void EndpointManager::RemoveEndpoint(ClientProxy* client, const std::string& endpoint_id, bool notify) { - NEARBY_LOG(ERROR, "RemoveEndpoint for endpoint %s", endpoint_id.c_str()); + NEARBY_LOGS(ERROR) << "RemoveEndpoint for endpoint " << endpoint_id; // Unregistering from channel_manager_ will also serve to terminate // the dedicated handler and KeepAlive threads we started when we registered // this endpoint. @@ -559,7 +574,7 @@ void EndpointManager::RemoveEndpoint(ClientProxy* client, WaitForEndpointDisconnectionProcessing(client, endpoint_id); client->OnDisconnected(endpoint_id, notify); - NEARBY_LOG(INFO, "Removed endpoint; id=%s", endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Removed endpoint for endpoint " << endpoint_id; } if (FeatureFlags::GetInstance() .GetFlags() @@ -571,18 +586,20 @@ void EndpointManager::RemoveEndpoint(ClientProxy* client, // @EndpointManagerThread void EndpointManager::WaitForEndpointDisconnectionProcessing( ClientProxy* client, const std::string& endpoint_id) { - NEARBY_LOGS(INFO) << "Wait: client=" << client << "; id=" << endpoint_id; + NEARBY_LOGS(INFO) << "Wait: client=" << client + << "; endpoint_id=" << endpoint_id; CountDownLatch barrier = NotifyFrameProcessorsOnEndpointDisconnect(client, endpoint_id); - NEARBY_LOGS(INFO) << "Waiting for frame processors to disconnect from: " - << endpoint_id; + NEARBY_LOGS(INFO) + << "Waiting for frame processors to disconnect from endpoint " + << endpoint_id; if (!barrier.Await(kProcessEndpointDisconnectionTimeout).result()) { - NEARBY_LOGS(INFO) << "Failed to disconnect frame processors from: " + NEARBY_LOGS(INFO) << "Failed to disconnect frame processors from endpoint " << endpoint_id; } else { NEARBY_LOGS(INFO) - << "Finished waiting for frame processors to disconnect from: " + << "Finished waiting for frame processors to disconnect from endpoint " << endpoint_id; } } @@ -590,7 +607,7 @@ void EndpointManager::WaitForEndpointDisconnectionProcessing( CountDownLatch EndpointManager::NotifyFrameProcessorsOnEndpointDisconnect( ClientProxy* client, const std::string& endpoint_id) { NEARBY_LOGS(INFO) << "NotifyFrameProcessorsOnEndpointDisconnect: client=" - << client << "; id=" << endpoint_id; + << client << "; endpoint_id=" << endpoint_id; MutexLock lock(&frame_processors_lock_); auto total_size = frame_processors_.size(); NEARBY_LOGS(INFO) << "Total frame processors: " << total_size; @@ -600,7 +617,7 @@ CountDownLatch EndpointManager::NotifyFrameProcessorsOnEndpointDisconnect( for (auto& item : frame_processors_) { LockedFrameProcessor processor(&item.second); NEARBY_LOGS(INFO) << "processor=" << processor.get() - << "; type=" << item.first; + << "; frame type=" << V1Frame::FrameType_Name(item.first); if (processor) { valid++; processor->OnEndpointDisconnect(client, endpoint_id, barrier); @@ -629,7 +646,12 @@ std::vector EndpointManager::SendTransferFrameBytes( if (channel == nullptr) { // We no longer know about this endpoint (it was either explicitly // unregistered, or a read/write error made us unregister it internally). - NEARBY_LOG(INFO, "Channel not available; id=%s", endpoint_id.c_str()); + NEARBY_LOGS(ERROR) << "EndpointManager failed to find EndpointChannel " + "over which to write " + << packet_type << " at offset " << offset + << " of Payload " << payload_id << " to endpoint " + << endpoint_id; + failed_endpoint_ids.push_back(endpoint_id); continue; } @@ -637,8 +659,7 @@ std::vector EndpointManager::SendTransferFrameBytes( Exception write_exception = channel->Write(bytes); if (!write_exception.Ok()) { failed_endpoint_ids.push_back(endpoint_id); - NEARBY_LOG(INFO, "Failed to send packet; endpoint_id=%s", - endpoint_id.c_str()); + NEARBY_LOGS(INFO) << "Failed to send packet; endpoint_id=" << endpoint_id; continue; } } diff --git a/cpp/core/internal/wifi_lan_endpoint_channel.cc b/cpp/core/internal/wifi_lan_endpoint_channel.cc index 12d19b74..ef8be69b 100644 --- a/cpp/core/internal/wifi_lan_endpoint_channel.cc +++ b/cpp/core/internal/wifi_lan_endpoint_channel.cc @@ -52,8 +52,9 @@ proto::connections::Medium WifiLanEndpointChannel::GetMedium() const { void WifiLanEndpointChannel::CloseImpl() { auto status = wifi_lan_socket_.Close(); if (!status.Ok()) { - NEARBY_LOG(INFO, "Failed to close WifiLan socket: exception=%d", - status.value); + NEARBY_LOGS(INFO) + << "Failed to close underlying socket for WifiLanEndpointChannel " + << GetName() << " : exception = " << status.value; } }