Remove DVLOG debug logging throughout LibCast

This patch removes instances of OSP_DVLOG in LibCast or changes them to OSP_VLOG as needed.

Bug: b/159172782
Change-Id: I2fab57cece82af0dc67ad9a596404d563e7707cd
Reviewed-on: https://chromium-review.googlesource.com/c/openscreen/+/3001340
Commit-Queue: Jordan Bayles <jophba@chromium.org>
Reviewed-by: Jordan Bayles <jophba@chromium.org>

14 files changed, 23 insertions, 75 deletions

diff --git a/cast/common/certificate/cast_cert_validator_internal.cc b/cast/common/certificate/cast_cert_validator_internal.cc
index 764ac3e4..7bdcacca 100644
--- a/cast/common/certificate/cast_cert_validator_internal.cc
+++ b/cast/common/certificate/cast_cert_validator_internal.cc
@@ -407,15 +407,11 @@ Error FindCertificatePath(const std::vector<std::string>& der_certs,
       result_path->intermediate_certs;
   target_cert.reset(ParseX509Der(der_certs[0]));
   if (!target_cert) {
-    OSP_DVLOG << "FindCertificatePath: Invalid target certificate";
     return Error::Code::kErrCertsParse;
   }
   for (size_t i = 1; i < der_certs.size(); ++i) {
     intermediate_certs.emplace_back(ParseX509Der(der_certs[i]));
     if (!intermediate_certs.back()) {
-      OSP_DVLOG
-          << "FindCertificatePath: Failed to parse intermediate certificate "
-          << i << " of " << der_certs.size();
       return Error::Code::kErrCertsParse;
     }
   }
@@ -423,12 +419,10 @@ Error FindCertificatePath(const std::vector<std::string>& der_certs,
   // Basic checks on the target certificate.
   Error::Code error = VerifyCertTime(target_cert.get(), time);
   if (error != Error::Code::kNone) {
-    OSP_DVLOG << "FindCertificatePath: Failed to verify certificate time";
     return error;
   }
   bssl::UniquePtr<EVP_PKEY> public_key{X509_get_pubkey(target_cert.get())};
   if (!VerifyPublicKeyLength(public_key.get())) {
-    OSP_DVLOG << "FindCertificatePath: Failed with invalid public key length";
     return Error::Code::kErrCertsVerifyGeneric;
   }
   const X509_ALGOR* sig_alg;
@@ -438,13 +432,11 @@ Error FindCertificatePath(const std::vector<std::string>& der_certs,
   }
   bssl::UniquePtr<ASN1_BIT_STRING> key_usage = GetKeyUsage(target_cert.get());
   if (!key_usage) {
-    OSP_DVLOG << "FindCertificatePath: Failed with no key usage";
     return Error::Code::kErrCertsRestrictions;
   }
   int bit =
       ASN1_BIT_STRING_get_bit(key_usage.get(), KeyUsageBits::kDigitalSignature);
   if (bit == 0) {
-    OSP_DVLOG << "FindCertificatePath: Failed to get digital signature";
     return Error::Code::kErrCertsRestrictions;
   }
 
@@ -478,8 +470,6 @@ Error FindCertificatePath(const std::vector<std::string>& der_certs,
   Error::Code last_error = Error::Code::kNone;
   for (;;) {
     X509_NAME* target_issuer_name = X509_get_issuer_name(path_head);
-    OSP_DVLOG << "FindCertificatePath: Target certificate issuer name: "
-              << X509_NAME_oneline(target_issuer_name, 0, 0);
 
     // The next issuer certificate to add to the current path.
     X509* next_issuer = nullptr;
@@ -488,8 +478,6 @@ Error FindCertificatePath(const std::vector<std::string>& der_certs,
       X509* trust_store_cert = trust_store->certs[i].get();
       X509_NAME* trust_store_cert_name =
           X509_get_subject_name(trust_store_cert);
-      OSP_DVLOG << "FindCertificatePath: Trust store certificate issuer name: "
-                << X509_NAME_oneline(trust_store_cert_name, 0, 0);
       if (X509_NAME_cmp(trust_store_cert_name, target_issuer_name) == 0) {
         CertPathStep& next_step = path[--path_index];
         next_step.cert = trust_store_cert;
@@ -524,8 +512,6 @@ Error FindCertificatePath(const std::vector<std::string>& der_certs,
       if (path_index == first_index) {
         // There are no more paths to try.  Ensure an error is returned.
         if (last_error == Error::Code::kNone) {
-          OSP_DVLOG << "FindCertificatePath: Failed after trying all "
-                       "certificate paths, no matches";
           return Error::Code::kErrCertsVerifyUntrustedCert;
         }
         return last_error;
@@ -556,8 +542,6 @@ Error FindCertificatePath(const std::vector<std::string>& der_certs,
     result_path->path.push_back(path[i].cert);
   }
 
-  OSP_DVLOG
-      << "FindCertificatePath: Succeeded at validating receiver certificates";
   return Error::Code::kNone;
 }
 
diff --git a/cast/common/channel/cast_socket_message_port.cc b/cast/common/channel/cast_socket_message_port.cc
index 0c51304b..bdc33f20 100644
--- a/cast/common/channel/cast_socket_message_port.cc
+++ b/cast/common/channel/cast_socket_message_port.cc
@@ -93,7 +93,6 @@ void CastSocketMessagePort::OnMessage(VirtualConnectionRouter* router,
     return;
   }
 
-  OSP_DVLOG << "Received a cast socket message";
   if (!client_) {
     OSP_DLOG_WARN << "Dropping message due to nullptr client_";
     return;
diff --git a/cast/common/channel/connection_namespace_handler.cc b/cast/common/channel/connection_namespace_handler.cc
index d3b2ea8b..c50b97be 100644
--- a/cast/common/channel/connection_namespace_handler.cc
+++ b/cast/common/channel/connection_namespace_handler.cc
@@ -221,8 +221,8 @@ void ConnectionNamespaceHandler::HandleConnect(CastSocket* socket,
     data.ip_fragment = {};
   }
 
-  OSP_DVLOG << "Connection opened: " << virtual_conn.local_id << ", "
-            << virtual_conn.peer_id << ", " << virtual_conn.socket_id;
+  OSP_VLOG << "Connection opened: " << virtual_conn.local_id << ", "
+           << virtual_conn.peer_id << ", " << virtual_conn.socket_id;
 
   // NOTE: Only send a response for senders that actually sent a version.  This
   // maintains compatibility with older senders that don't send a version and
@@ -242,9 +242,9 @@ void ConnectionNamespaceHandler::HandleClose(CastSocket* socket,
                                ToCastSocketId(socket)};
   const auto reason = GetCloseReason(parsed_message);
   if (RemoveConnection(conn, reason)) {
-    OSP_DVLOG << "Connection closed (reason: " << reason
-              << "): " << conn.local_id << ", " << conn.peer_id << ", "
-              << conn.socket_id;
+    OSP_VLOG << "Connection closed (reason: " << reason
+             << "): " << conn.local_id << ", " << conn.peer_id << ", "
+             << conn.socket_id;
   }
 }
 
diff --git a/cast/protocol/castv2/validation.cc b/cast/protocol/castv2/validation.cc
index 67a9b351..a87dd5e3 100644
--- a/cast/protocol/castv2/validation.cc
+++ b/cast/protocol/castv2/validation.cc
@@ -32,9 +32,6 @@ std::vector<Error> MapErrors(const valijson::ValidationResults& results) {
     errors.emplace_back(Error::Code::kJsonParseError,
                         StringPrintf("Node: %s, Message: %s", context.c_str(),
                                      result.description.c_str()));
-
-    OSP_DVLOG << "JsonCpp validation error: "
-              << errors.at(errors.size() - 1).message();
   }
   return errors;
 }
diff --git a/cast/protocol/castv2/validation_unittest.cc b/cast/protocol/castv2/validation_unittest.cc
index 46ded40a..d6c0e70e 100644
--- a/cast/protocol/castv2/validation_unittest.cc
+++ b/cast/protocol/castv2/validation_unittest.cc
@@ -71,8 +71,6 @@ std::string BuildSchema(const char* definitions,
 }
 
 bool TestValidate(absl::string_view document, absl::string_view schema) {
-  OSP_DVLOG << "Validating document: \"" << document << "\" against schema: \""
-            << schema << "\"";
   ErrorOr<Json::Value> document_root = json::Parse(document);
   EXPECT_TRUE(document_root.is_value());
   ErrorOr<Json::Value> schema_root = json::Parse(schema);
diff --git a/cast/receiver/channel/receiver_socket_factory.cc b/cast/receiver/channel/receiver_socket_factory.cc
index c8ddd691..e5ba479c 100644
--- a/cast/receiver/channel/receiver_socket_factory.cc
+++ b/cast/receiver/channel/receiver_socket_factory.cc
@@ -38,7 +38,6 @@ void ReceiverSocketFactory::OnConnected(
 void ReceiverSocketFactory::OnConnectionFailed(
     TlsConnectionFactory* factory,
     const IPEndpoint& remote_address) {
-  OSP_DVLOG << "Receiving connection from endpoint failed: " << remote_address;
   client_->OnError(this, Error(Error::Code::kConnectionFailed,
                                "Accepting connection failed."));
 }
diff --git a/cast/sender/cast_app_discovery_service_impl.cc b/cast/sender/cast_app_discovery_service_impl.cc
index cdf46bf2..822410c1 100644
--- a/cast/sender/cast_app_discovery_service_impl.cc
+++ b/cast/sender/cast_app_discovery_service_impl.cc
@@ -119,9 +119,6 @@ void CastAppDiscoveryServiceImpl::UpdateAppAvailability(
     return;
   }
 
-  OSP_DVLOG << "App " << app_id << " on receiver " << device_id << " is "
-            << ToString(availability);
-
   UpdateAvailabilityQueries(availability_tracker_.UpdateAppAvailability(
       device_id, app_id, {availability, clock_()}));
 }
diff --git a/cast/sender/cast_platform_client.cc b/cast/sender/cast_platform_client.cc
index d3f39cfb..fda03b9a 100644
--- a/cast/sender/cast_platform_client.cc
+++ b/cast/sender/cast_platform_client.cc
@@ -128,7 +128,6 @@ void CastPlatformClient::OnMessage(VirtualConnectionRouter* router,
   }
   ErrorOr<Json::Value> dict_or_error = json::Parse(message.payload_utf8());
   if (dict_or_error.is_error()) {
-    OSP_DVLOG << "Failed to deserialize CastMessage payload.";
     return;
   }
 
@@ -178,7 +177,7 @@ void CastPlatformClient::HandleResponse(const std::string& device_id,
         } else if (result.value() == kMessageValueAppUnavailable) {
           availability_result = AppAvailabilityResult::kUnavailable;
         } else {
-          OSP_DVLOG << "Invalid availability result: " << result.value();
+          OSP_VLOG << "Invalid availability result: " << result.value();
         }
         it->callback(it->app_id, availability_result);
       }
diff --git a/cast/sender/channel/sender_socket_factory.cc b/cast/sender/channel/sender_socket_factory.cc
index e971976b..abbabfd6 100644
--- a/cast/sender/channel/sender_socket_factory.cc
+++ b/cast/sender/channel/sender_socket_factory.cc
@@ -106,8 +106,6 @@ void SenderSocketFactory::OnConnectionFailed(TlsConnectionFactory* factory,
                                              const IPEndpoint& remote_address) {
   auto it = FindPendingConnection(remote_address);
   if (it == pending_connections_.end()) {
-    OSP_DVLOG << "OnConnectionFailed reported for untracked address: "
-              << remote_address;
     return;
   }
   pending_connections_.erase(it);
diff --git a/cast/streaming/offer_messages.cc b/cast/streaming/offer_messages.cc
index 1795a692..3e816026 100644
--- a/cast/streaming/offer_messages.cc
+++ b/cast/streaming/offer_messages.cc
@@ -360,7 +360,7 @@ Error Offer::TryParse(const Json::Value& root, Offer* out) {
 
     if (!error.ok()) {
       if (error.code() == Error::Code::kUnknownCodec) {
-        OSP_DVLOG << "Dropping audio stream due to unknown codec: " << error;
+        OSP_VLOG << "Dropping audio stream due to unknown codec: " << error;
         continue;
       } else {
         return error;
diff --git a/cast/streaming/receiver.cc b/cast/streaming/receiver.cc
index ee2b0bc5..d08c181c 100644
--- a/cast/streaming/receiver.cc
+++ b/cast/streaming/receiver.cc
@@ -105,13 +105,11 @@ int Receiver::AdvanceToNextFrame() {
       const EncryptedFrame& encrypted_frame =
           entry.collector.PeekAtAssembledFrame();
       if (f == immediate_next_frame) {  // Typical case.
-        OSP_DVLOG << "AdvanceToNextFrame: Next in sequence (" << f << ')';
         return FrameCrypto::GetPlaintextSize(encrypted_frame);
       }
       if (encrypted_frame.dependency != EncodedFrame::DEPENDS_ON_ANOTHER) {
         // Found a frame after skipping past some frames. Drop the ones being
         // skipped, advancing |last_frame_consumed_| before returning.
-        OSP_DVLOG << "AdvanceToNextFrame: Skipping-ahead → " << f;
         DropAllFramesBefore(f);
         return FrameCrypto::GetPlaintextSize(encrypted_frame);
       }
@@ -139,8 +137,6 @@ int Receiver::AdvanceToNextFrame() {
     }
   }
 
-  OSP_DVLOG << "AdvanceToNextFrame: No frames ready. Last consumed was "
-            << last_frame_consumed_ << '.';
   return kNoFramesReady;
 }
 
@@ -161,14 +157,13 @@ EncodedFrame Receiver::ConsumeNextFrame(absl::Span<uint8_t> buffer) {
   frame.reference_time =
       *entry.estimated_capture_time + ResolveTargetPlayoutDelay(frame_id);
 
-  OSP_DVLOG << "ConsumeNextFrame → " << frame.frame_id << ": "
-            << frame.data.size() << " payload bytes, RTP Timestamp "
-            << frame.rtp_timestamp
-                   .ToTimeSinceOrigin<microseconds>(rtp_timebase_)
-                   .count()
-            << " µs, to play-out "
-            << to_microseconds(frame.reference_time - now_()).count()
-            << " µs from now.";
+  OSP_VLOG << "ConsumeNextFrame → " << frame.frame_id << ": "
+           << frame.data.size() << " payload bytes, RTP Timestamp "
+           << frame.rtp_timestamp.ToTimeSinceOrigin<microseconds>(rtp_timebase_)
+                  .count()
+           << " µs, to play-out "
+           << to_microseconds(frame.reference_time - now_()).count()
+           << " µs from now.";
 
   entry.Reset();
   last_frame_consumed_ = frame_id;
@@ -205,8 +200,6 @@ void Receiver::OnReceivedRtpPacket(Clock::time_point arrival_time,
     const FrameId max_allowed_frame_id =
         last_frame_consumed_ + kMaxUnackedFrames;
     if (part->frame_id > max_allowed_frame_id) {
-      OSP_DVLOG << "Dropping RTP packet for " << part->frame_id
-                << ": Too many frames are already in-flight.";
       return;
     }
     do {
@@ -214,7 +207,6 @@ void Receiver::OnReceivedRtpPacket(Clock::time_point arrival_time,
       GetQueueEntry(latest_frame_expected_)
           .collector.set_frame_id(latest_frame_expected_);
     } while (latest_frame_expected_ < part->frame_id);
-    OSP_DVLOG << "Advanced latest frame expected to " << latest_frame_expected_;
   }
 
   // Start-up edge case: Blatantly drop the first packet of all frames until the
@@ -262,9 +254,6 @@ void Receiver::OnReceivedRtpPacket(Clock::time_point arrival_time,
 
     // If a target playout delay change was included in this packet, record it.
     if (part->new_playout_delay > milliseconds::zero()) {
-      OSP_DVLOG << "Target playout delay changes to "
-                << part->new_playout_delay.count() << " ms, as of "
-                << part->frame_id;
       RecordNewTargetPlayoutDelay(part->frame_id, part->new_playout_delay);
     }
 
@@ -321,9 +310,6 @@ void Receiver::OnReceivedRtcpPacket(Clock::time_point arrival_time,
   const Clock::duration measured_offset =
       arrival_time - last_sender_report_->reference_time;
   smoothed_clock_offset_.Update(arrival_time, measured_offset);
-  OSP_DVLOG << "Received Sender Report: Local clock is ahead of Sender's by "
-            << to_microseconds(smoothed_clock_offset_.Current()).count()
-            << " µs (minus one-way network transit time).";
 
   RtcpReportBlock report;
   report.ssrc = rtcp_session_.sender_ssrc();
@@ -356,7 +342,6 @@ void Receiver::SendRtcp() {
   packet_router_->SendRtcpPacket(rtcp_builder_.BuildPacket(
       last_rtcp_send_time_,
       absl::Span<uint8_t>(rtcp_buffer_.get(), rtcp_buffer_capacity_)));
-  OSP_DVLOG << "Sent RTCP packet.";
 
   // Schedule the automatic sending of another RTCP packet, if this method is
   // not called within some bounded amount of time. While incomplete frames
@@ -434,7 +419,6 @@ void Receiver::AdvanceCheckpoint(FrameId new_checkpoint) {
     new_checkpoint = next;
   }
 
-  OSP_DVLOG << "Advancing checkpoint to " << new_checkpoint;
   set_checkpoint_frame(new_checkpoint);
   rtcp_builder_.SetPlayoutDelay(ResolveTargetPlayoutDelay(new_checkpoint));
   SendRtcp();
diff --git a/cast/streaming/receiver_session.cc b/cast/streaming/receiver_session.cc
index 056bbabf..8082af8e 100644
--- a/cast/streaming/receiver_session.cc
+++ b/cast/streaming/receiver_session.cc
@@ -33,8 +33,8 @@ std::unique_ptr<Stream> SelectStream(
   for (auto codec : preferred_codecs) {
     for (const Stream& offered_stream : offered_streams) {
       if (offered_stream.codec == codec) {
-        OSP_DVLOG << "Selected " << CodecToString(codec)
-                  << " as codec for streaming";
+        OSP_VLOG << "Selected " << CodecToString(codec)
+                 << " as codec for streaming";
         return std::make_unique<Stream>(offered_stream);
       }
     }
diff --git a/cast/streaming/rpc_messenger.cc b/cast/streaming/rpc_messenger.cc
index 63176f7c..3ae6c548 100644
--- a/cast/streaming/rpc_messenger.cc
+++ b/cast/streaming/rpc_messenger.cc
@@ -59,12 +59,10 @@ void RpcMessenger::RegisterMessageReceiverCallback(
     ReceiveMessageCallback callback) {
   OSP_DCHECK(receive_callbacks_.find(handle) == receive_callbacks_.end())
       << "must deregister before re-registering";
-  OSP_DVLOG << "registering handle: " << handle;
   receive_callbacks_.emplace_back(handle, std::move(callback));
 }
 
 void RpcMessenger::UnregisterMessageReceiverCallback(RpcMessenger::Handle handle) {
-  OSP_DVLOG << "unregistering handle: " << handle;
   receive_callbacks_.erase_key(handle);
 }
 
@@ -76,19 +74,18 @@ void RpcMessenger::ProcessMessageFromRemote(const uint8_t* message,
                   << "\"";
     return;
   }
-  OSP_DVLOG << "Received RPC message: " << *rpc;
 
   const auto entry = receive_callbacks_.find(rpc->handle());
   if (entry == receive_callbacks_.end()) {
-    OSP_DVLOG << "Dropping message due to unregistered handle: "
-              << rpc->handle();
+    OSP_VLOG << "Dropping message due to unregistered handle: "
+             << rpc->handle();
     return;
   }
   entry->second(std::move(rpc));
 }
 
 void RpcMessenger::SendMessageToRemote(const RpcMessage& rpc) {
-  OSP_DVLOG << "Sending RPC message: " << rpc;
+  OSP_VLOG << "Sending RPC message: " << rpc;
   std::vector<uint8_t> message(rpc.ByteSizeLong());
   rpc.SerializeToArray(message.data(), message.size());
   send_message_cb_(std::move(message));
diff --git a/cast/streaming/session_messenger.cc b/cast/streaming/session_messenger.cc
index 389d87bb..a612b68d 100644
--- a/cast/streaming/session_messenger.cc
+++ b/cast/streaming/session_messenger.cc
@@ -23,7 +23,7 @@ void ReplyIfTimedOut(
         replies) {
   for (auto it = replies->begin(); it != replies->end(); ++it) {
     if (it->first == sequence_number) {
-      OSP_DVLOG
+      OSP_VLOG
           << "Replying with empty message due to timeout for sequence number: "
           << sequence_number;
       it->second(ReceiverMessage{reply_type, sequence_number});
@@ -57,9 +57,9 @@ Error SessionMessenger::SendMessage(const std::string& destination_id,
   if (body_or_error.is_error()) {
     return std::move(body_or_error.error());
   }
-  OSP_DVLOG << "Sending message: DESTINATION[" << destination_id
-            << "], NAMESPACE[" << namespace_ << "], BODY:\n"
-            << body_or_error.value();
+  OSP_VLOG << "Sending message: DESTINATION[" << destination_id
+           << "], NAMESPACE[" << namespace_ << "], BODY:\n"
+           << body_or_error.value();
   message_port_->PostMessage(destination_id, namespace_, body_or_error.value());
   return Error::None();
 }
@@ -180,8 +180,6 @@ void SenderSessionMessenger::OnMessage(const std::string& source_id,
       return;
     }
 
-    OSP_DVLOG << "Received a valid reply from " << source_id
-              << ". Reply body: " << message;
     it->second(std::move(receiver_message.value({})));
 
     // Calling the function callback may result in the checksum of the pointed
@@ -268,8 +266,6 @@ void ReceiverSessionMessenger::OnMessage(const std::string& source_id,
   if (it == callbacks_.end()) {
     OSP_DLOG_INFO << "Received message without a callback, dropping";
   } else {
-    OSP_DVLOG << "Received valid message from " << source_id
-              << ", executing callback. Message body: " << message;
     it->second(sender_message.value());
   }
 }