Add more logging for gcs_grpc and some other grpc uses.

PiperOrigin-RevId: 846798126
Change-Id: I112c9dc2d60c688e84f06b57fd476b37ab76cc7d

Author: laramiel

tensorstore/internal/grpc/BUILD

@@ -44,6 +44,7 @@ tensorstore_cc_library(
         "//tensorstore/proto:proto_util",
         "@abseil-cpp//absl/base:core_headers",
         "@abseil-cpp//absl/log:absl_log",
+        "@abseil-cpp//absl/strings",
         "@com_google_protobuf//:protobuf",
         "@grpc//:grpc++",
     ],

tensorstore/internal/grpc/clientauth/BUILD

@@ -66,7 +66,10 @@ tensorstore_cc_library(
     hdrs = ["channel_authentication.h"],
     deps = [
         ":authentication_strategy",
+        "//tensorstore/internal/log:verbose_flag",
         "//tensorstore/util:future",
+        "@abseil-cpp//absl/base:core_headers",
+        "@abseil-cpp//absl/log:absl_log",
         "@grpc//:grpc++",
     ],
 )
@@ -77,7 +80,10 @@ tensorstore_cc_library(
     hdrs = ["call_authentication.h"],
     deps = [
         ":authentication_strategy",
+        "//tensorstore/internal/log:verbose_flag",
         "//tensorstore/util:future",
+        "@abseil-cpp//absl/base:core_headers",
+        "@abseil-cpp//absl/log:absl_log",
         "@grpc//:grpc++",
     ],
 )
@@ -91,9 +97,12 @@ tensorstore_cc_library(
         ":access_token_cache",
         ":authentication_strategy",
         ":iam_stub",
+        "//tensorstore/internal/log:verbose_flag",
         "//tensorstore/util:executor",
         "//tensorstore/util:future",
         "//tensorstore/util:result",
+        "@abseil-cpp//absl/base:core_headers",
+        "@abseil-cpp//absl/log:absl_log",
         "@abseil-cpp//absl/status",
         "@abseil-cpp//absl/synchronization",
         "@abseil-cpp//absl/time",

tensorstore/internal/grpc/clientauth/call_authentication.cc

@@ -19,14 +19,22 @@
 #include <string_view>
 #include <utility>
 
+#include "absl/base/attributes.h"
+#include "absl/log/absl_log.h"
 #include "grpcpp/client_context.h"  // third_party
 #include "grpcpp/security/credentials.h"  // third_party
 #include "grpcpp/support/channel_arguments.h"  // third_party
 #include "tensorstore/internal/grpc/clientauth/authentication_strategy.h"
+#include "tensorstore/internal/log/verbose_flag.h"
 #include "tensorstore/util/future.h"
 
 namespace tensorstore {
 namespace internal_grpc {
+namespace {
+
+ABSL_CONST_INIT internal_log::VerboseFlag verbose_logging("grpc");
+
+}
 
 std::shared_ptr<grpc::ChannelCredentials>
 GrpcCallCredentialsAuthentication::GetChannelCredentials(
@@ -48,6 +56,7 @@ GrpcCallCredentialsAuthentication::ConfigureContext(
 std::shared_ptr<GrpcAuthenticationStrategy>
 CreateAccessTokenAuthenticationStrategy(const std::string& token,
                                         const CaInfo& ca_info) {
+  ABSL_LOG_IF(INFO, verbose_logging) << "Using access_token credentials";
   grpc::SslCredentialsOptions ssl_options;
   auto cainfo = LoadCAInfo(ca_info);
   if (cainfo) ssl_options.pem_root_certs = std::move(*cainfo);
@@ -58,6 +67,7 @@ CreateAccessTokenAuthenticationStrategy(const std::string& token,
 std::shared_ptr<GrpcAuthenticationStrategy>
 CreateServiceAccountAuthenticationStrategy(const std::string& json_object,
                                            const CaInfo& ca_info) {
+  ABSL_LOG_IF(INFO, verbose_logging) << "Using service_account credentials";
   grpc::SslCredentialsOptions ssl_options;
   auto cainfo = LoadCAInfo(ca_info);
   if (cainfo) ssl_options.pem_root_certs = std::move(*cainfo);

tensorstore/internal/grpc/clientauth/channel_authentication.cc

@@ -20,14 +20,22 @@
 #include <utility>
 #include <vector>
 
+#include "absl/base/attributes.h"
+#include "absl/log/absl_log.h"
 #include "grpcpp/client_context.h"  // third_party
 #include "grpcpp/security/credentials.h"  // third_party
 #include "grpcpp/support/channel_arguments.h"  // third_party
 #include "tensorstore/internal/grpc/clientauth/authentication_strategy.h"
+#include "tensorstore/internal/log/verbose_flag.h"
 #include "tensorstore/util/future.h"
 
 namespace tensorstore {
 namespace internal_grpc {
+namespace {
+
+ABSL_CONST_INIT internal_log::VerboseFlag verbose_logging("grpc");
+
+}
 
 std::shared_ptr<grpc::ChannelCredentials>
 GrpcChannelCredentialsAuthentication::GetChannelCredentials(
@@ -48,13 +56,15 @@ GrpcChannelCredentialsAuthentication::ConfigureContext(
 /// Creates an "insecure" authentication strategy with the given token.
 std::shared_ptr<GrpcAuthenticationStrategy>
 CreateInsecureAuthenticationStrategy() {
+  ABSL_LOG_IF(INFO, verbose_logging) << "Using insecure credentials";
   return std::make_shared<GrpcChannelCredentialsAuthentication>(
       grpc::InsecureChannelCredentials());
 }
 
 /// Creates a "google_default" authentication strategy.
 std::shared_ptr<GrpcAuthenticationStrategy>
 CreateGoogleDefaultAuthenticationStrategy() {
+  ABSL_LOG_IF(INFO, verbose_logging) << "Using google_default credentials";
   return std::make_shared<GrpcChannelCredentialsAuthentication>(
       grpc::GoogleDefaultCredentials());
 }
@@ -63,6 +73,7 @@ std::shared_ptr<GrpcAuthenticationStrategy>
 CreateExternalAccountAuthenticationStrategy(
     const std::string& json_object, const std::vector<std::string>& scopes,
     const CaInfo& ca_info) {
+  ABSL_LOG_IF(INFO, verbose_logging) << "Using external_account credentials";
   grpc::SslCredentialsOptions ssl_options;
   auto cainfo = LoadCAInfo(ca_info);
   if (cainfo) ssl_options.pem_root_certs = std::move(*cainfo);

tensorstore/internal/grpc/clientauth/impersonate_service_account.cc

@@ -21,6 +21,8 @@
 #include <utility>
 
 #include "google/iam/credentials/v1/common.pb.h"
+#include "absl/base/attributes.h"
+#include "absl/log/absl_log.h"
 #include "absl/status/status.h"
 #include "absl/synchronization/mutex.h"
 #include "absl/time/time.h"
@@ -31,18 +33,26 @@
 #include "tensorstore/internal/grpc/clientauth/access_token_cache.h"
 #include "tensorstore/internal/grpc/clientauth/authentication_strategy.h"
 #include "tensorstore/internal/grpc/clientauth/iam_stub.h"
+#include "tensorstore/internal/log/verbose_flag.h"
 #include "tensorstore/util/executor.h"
 #include "tensorstore/util/future.h"
 #include "tensorstore/util/result.h"
 
 namespace tensorstore {
 namespace internal_grpc {
+namespace {
 
+ABSL_CONST_INIT internal_log::VerboseFlag verbose_logging("grpc");
+
+}
 /* static */
 std::shared_ptr<GrpcImpersonateServiceAccount>
 GrpcImpersonateServiceAccount::Create(
     const ImpersonateServiceAccountConfig& config, const CaInfo& ca_info,
     std::shared_ptr<GrpcAuthenticationStrategy> base_strategy) {
+  ABSL_LOG_IF(INFO, verbose_logging)
+      << "Using impersonate_service_account credentials";
+
   auto source = CreateIamCredentialsSource(
       base_strategy, /*endpoint=*/{}, config.target_service_account,
       config.lifetime, config.scopes, config.delegates);

tensorstore/internal/grpc/logging_interceptor.cc

@@ -14,10 +14,13 @@
 
 #include "tensorstore/internal/grpc/logging_interceptor.h"
 
+#include <map>
+#include <string>
 #include <string_view>
 
 #include "absl/base/attributes.h"
 #include "absl/log/absl_log.h"
+#include "absl/strings/str_cat.h"
 #include "grpcpp/support/client_interceptor.h"  // third_party
 #include "grpcpp/support/interceptor.h"  // third_party
 #include "google/protobuf/message.h"
@@ -34,7 +37,7 @@ namespace tensorstore {
 namespace internal_grpc {
 namespace {
 
-ABSL_CONST_INIT internal_log::VerboseFlag grpc_logging("grpc_channel");
+ABSL_CONST_INIT internal_log::VerboseFlag verbose_logging("grpc_channel");
 
 // Implements detailed logging for gRPC calls to GCS.
 class LoggingInterceptor : public Interceptor {
@@ -44,46 +47,69 @@ class LoggingInterceptor : public Interceptor {
   std::string_view method_name() const { return info_->method(); }
 
   void Intercept(InterceptorBatchMethods* methods) override {
-    if (!grpc_logging) {
+    if (!verbose_logging) {
       methods->Proceed();
       return;
     }
+
+    std::string log;
+
+    std::multimap<std::string, std::string>* metadata = nullptr;
+    if (methods->QueryInterceptionHookPoint(
+            InterceptionHookPoints::PRE_SEND_INITIAL_METADATA)) {
+      metadata = methods->GetSendInitialMetadata();
+    }
+    if (methods->QueryInterceptionHookPoint(
+            InterceptionHookPoints::PRE_SEND_STATUS)) {
+      metadata = methods->GetSendTrailingMetadata();
+    }
+    if (metadata != nullptr) {
+      absl::StrAppend(&log, "Metadata:");
+      for (const auto& [key, value] : *metadata) {
+        absl::StrAppend(&log, " ", key, ": ", value);
+      }
+    }
+
     if (methods->QueryInterceptionHookPoint(
             InterceptionHookPoints::PRE_SEND_MESSAGE)) {
       auto* message =
           static_cast<const google::protobuf::Message*>(methods->GetSendMessage());
-      bool is_first_message = !started_;
-      started_ = true;
-      if (grpc_logging.Level(2)) {
-        ABSL_LOG(INFO) << "Begin: " << method_name() << " "
-                       << ConciseDebugString(*message);
-      } else if (is_first_message) {
-        ABSL_LOG(INFO) << "Begin: " << method_name();
+      if (verbose_logging.Level(2) && message != nullptr) {
+        absl::StrAppend(&log, log.empty() ? "" : "\n",
+                        "Request: ", ConciseDebugString(*message));
       }
     }
-    if (grpc_logging.Level(2) &&
-        methods->QueryInterceptionHookPoint(
+    if (methods->QueryInterceptionHookPoint(
             InterceptionHookPoints::POST_RECV_MESSAGE)) {
-      ABSL_LOG(INFO) << method_name() << " "
-                     << ConciseDebugString(*static_cast<const google::protobuf::Message*>(
-                            methods->GetRecvMessage()));
+      auto* message =
+          static_cast<const google::protobuf::Message*>(methods->GetRecvMessage());
+      if (verbose_logging.Level(2) && message != nullptr) {
+        absl::StrAppend(&log, log.empty() ? "" : "\n",
+                        "Response: ", ConciseDebugString(*message));
+      }
+    }
+
+    if (methods->QueryInterceptionHookPoint(
+            InterceptionHookPoints::PRE_SEND_STATUS)) {
+      if (auto status = methods->GetSendStatus(); !status.ok()) {
+        absl::StrAppend(&log, log.empty() ? "" : "\n", "Send Status: ",
+                        internal::GrpcStatusToAbslStatus(status));
+      }
     }
+
     if (methods->QueryInterceptionHookPoint(
             InterceptionHookPoints::POST_RECV_STATUS)) {
-      if (auto* status = methods->GetRecvStatus();
-          status != nullptr && !status->ok()) {
-        ABSL_LOG(INFO) << "Error: " << method_name() << " "
-                       << internal::GrpcStatusToAbslStatus(*status);
-      } else {
-        ABSL_LOG(INFO) << "End: " << method_name();
+      if (auto* status = methods->GetRecvStatus(); status != nullptr) {
+        absl::StrAppend(&log, log.empty() ? "" : "\n", "Recv Status: ",
+                        internal::GrpcStatusToAbslStatus(*status));
       }
     }
+    ABSL_LOG_IF(INFO, !log.empty()) << method_name() << " " << log;
     methods->Proceed();
   }
 
  private:
   const ClientRpcInfo* info_;
-  bool started_ = false;
 };
 
 }  // namespace

tensorstore/internal/grpc/utils.cc

@@ -17,9 +17,12 @@
 #include <grpcpp/support/status.h>
 
 #include <string>
+#include <type_traits>
+#include <utility>
 
 #include "absl/status/status.h"
 #include "absl/strings/cord.h"
+#include "grpcpp/support/status.h"  // third_party
 #include "tensorstore/internal/source_location.h"
 #include "tensorstore/util/status.h"
 
@@ -50,20 +53,45 @@ TENSORSTORE_STATUS_ASSERT(UNAUTHENTICATED, kUnauthenticated);
 
 namespace tensorstore {
 namespace internal {
+namespace {
 
-absl::Status GrpcStatusToAbslStatus(grpc::Status s, SourceLocation loc) {
-  if (s.ok()) return absl::OkStatus();
+template <typename T, typename = void>
+struct HasAbslStatusOperator : std::false_type {};
+
+template <typename T>
+struct HasAbslStatusOperator<
+    T, std::void_t<decltype(std::declval<const T&>().operator absl::Status())>>
+    : std::true_type {};
+
+// Overload for when operator exists
+template <typename T,
+          std::enable_if_t<HasAbslStatusOperator<T>::value, int> = 0>
+absl::Status ToAbslStatusImpl(const T& s) {
+  return s.operator absl::Status();
+}
+
+// Overload for when operator does not exist
+template <typename T,
+          std::enable_if_t<!HasAbslStatusOperator<T>::value, int> = 0>
+absl::Status ToAbslStatusImpl(const T& s) {
   auto absl_code = static_cast<absl::StatusCode>(s.error_code());
   absl::Status status(absl_code, s.error_message());
-  MaybeAddSourceLocation(status, loc);
-
   if (!s.error_details().empty()) {
     // NOTE: Is error_details() a serialized protobuf::Any?
     status.SetPayload("grpc.Status.details", absl::Cord(s.error_details()));
   }
   return status;
 }
 
+}  // namespace
+
+absl::Status GrpcStatusToAbslStatus(grpc::Status s, SourceLocation loc) {
+  if (s.ok()) return absl::OkStatus();
+  absl::Status status = ToAbslStatusImpl(s);
+  MaybeAddSourceLocation(status, loc);
+  return status;
+}
+
 grpc::Status AbslStatusToGrpcStatus(const absl::Status& status) {
   if (status.ok()) return grpc::Status::OK;
 

tensorstore/internal/grpc/utils.h

@@ -18,6 +18,7 @@
 #include <grpcpp/support/status.h>
 
 #include "absl/status/status.h"
+#include "grpcpp/support/status.h"  // third_party
 #include "tensorstore/internal/source_location.h"
 
 namespace tensorstore {

tensorstore/internal/tracing/logged_trace_span.h

@@ -95,7 +95,7 @@ class LoggedTraceSpan : public LocalTraceSpan {
     if (id_) {
       EndLog(
           absl::LogInfoStreamer(location.file_name(), location.line()).stream())
-          << status;
+          << " " << status;
       id_ = 0;
     }
     return status;