refactor(common): repetitive code in LogWrapper (#12389)

Move repetitive code in `internal::LogWrapper` to some helper
functions.

generator/integration_tests/tests/golden_kitchen_sink_logging_decorator_test.cc

@@ -199,7 +199,7 @@ TEST_F(LoggingDecoratorTest, StreamingReadRpcNoRpcStreams) {
 
   auto const log_lines = log_.ExtractLines();
   EXPECT_THAT(log_lines, Contains(HasSubstr("StreamingRead(")));
-  EXPECT_THAT(log_lines, Contains(HasSubstr("null stream")));
+  EXPECT_THAT(log_lines, Contains(HasSubstr(">> not null")));
   EXPECT_THAT(log_lines, Not(Contains(StartsWith("Read("))));
 }
 
@@ -215,7 +215,7 @@ TEST_F(LoggingDecoratorTest, StreamingReadRpcWithRpcStreams) {
 
   auto const log_lines = log_.ExtractLines();
   EXPECT_THAT(log_lines, Contains(HasSubstr("StreamingRead(")));
-  EXPECT_THAT(log_lines, Contains(HasSubstr("null stream")));
+  EXPECT_THAT(log_lines, Contains(HasSubstr(">> not null")));
   EXPECT_THAT(log_lines, Contains(StartsWith("Read(")));
 }
 

google/cloud/google_cloud_cpp_grpc_utils.bzl

@@ -102,6 +102,7 @@ google_cloud_cpp_grpc_utils_srcs = [
     "internal/grpc_opentelemetry.cc",
     "internal/grpc_request_metadata.cc",
     "internal/grpc_service_account_authentication.cc",
+    "internal/log_wrapper.cc",
     "internal/minimal_iam_credentials_stub.cc",
     "internal/populate_grpc_options.cc",
     "internal/streaming_read_rpc.cc",

google/cloud/google_cloud_cpp_grpc_utils.cmake

@@ -83,6 +83,7 @@ add_library(
     internal/grpc_request_metadata.h
     internal/grpc_service_account_authentication.cc
     internal/grpc_service_account_authentication.h
+    internal/log_wrapper.cc
     internal/log_wrapper.h
     internal/minimal_iam_credentials_stub.cc
     internal/minimal_iam_credentials_stub.h

google/cloud/internal/log_wrapper.cc

@@ -0,0 +1,60 @@
+// Copyright 2019 Google LLC
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     https://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#include "google/cloud/internal/log_wrapper.h"
+
+namespace google {
+namespace cloud {
+GOOGLE_CLOUD_CPP_INLINE_NAMESPACE_BEGIN
+namespace internal {
+
+void LogRequest(absl::string_view where, absl::string_view args,
+                absl::string_view message) {
+  GCP_LOG(DEBUG) << where << '(' << args << ')' << " << status=" << message;
+}
+
+Status LogResponse(Status response, absl::string_view where,
+                   absl::string_view args, TracingOptions const& options) {
+  GCP_LOG(DEBUG) << where << '(' << args << ')'
+                 << " >> status=" << DebugString(response, options);
+  return response;
+}
+
+void LogResponseFuture(std::future_status status, absl::string_view where,
+                       absl::string_view args,
+                       TracingOptions const& /*options*/) {
+  GCP_LOG(DEBUG) << where << '(' << args << ')'
+                 << " >> future_status=" << DebugFutureStatus(status);
+}
+
+future<Status> LogResponse(future<Status> response, std::string where,
+                           std::string args, TracingOptions const& options) {
+  LogResponseFuture(response.wait_for(std::chrono::microseconds(0)), where,
+                    args, options);
+  return response.then([where = std::move(where), args = std::move(args),
+                        options = std::move(options)](auto f) {
+    return LogResponse(f.get(), where, args, options);
+  });
+}
+
+void LogResponsePtr(bool not_null, absl::string_view where,
+                    absl::string_view args, TracingOptions const& /*options*/) {
+  GCP_LOG(DEBUG) << where << '(' << args << ')' << " >> "
+                 << (not_null ? "not " : "") << "null";
+}
+
+}  // namespace internal
+GOOGLE_CLOUD_CPP_INLINE_NAMESPACE_END
+}  // namespace cloud
+}  // namespace google

google/cloud/internal/log_wrapper.h

@@ -27,10 +27,12 @@
 #include "google/cloud/status_or.h"
 #include "google/cloud/tracing_options.h"
 #include "google/cloud/version.h"
+#include "absl/strings/string_view.h"
 #include <google/protobuf/message.h>
 #include <grpcpp/grpcpp.h>
 #include <chrono>
 #include <string>
+#include <type_traits>
 
 namespace google {
 namespace cloud {
@@ -57,6 +59,51 @@ struct IsFutureStatus : public std::false_type {};
 template <>
 struct IsFutureStatus<future<Status>> : public std::true_type {};
 
+void LogRequest(absl::string_view where, absl::string_view args,
+                absl::string_view message);
+
+Status LogResponse(Status response, absl::string_view where,
+                   absl::string_view args, TracingOptions const& options);
+
+template <typename T>
+StatusOr<T> LogResponse(StatusOr<T> response, absl::string_view where,
+                        absl::string_view args, TracingOptions const& options) {
+  if (!response) {
+    return LogResponse(std::move(response).status(), where, args, options);
+  }
+  GCP_LOG(DEBUG) << where << '(' << args << ')'
+                 << " >> response=" << DebugString(*response, options);
+  return response;
+}
+
+void LogResponseFuture(std::future_status status, absl::string_view where,
+                       absl::string_view args, TracingOptions const& options);
+
+future<Status> LogResponse(future<Status> response, std::string where,
+                           std::string args, TracingOptions const& options);
+
+template <typename T>
+future<StatusOr<T>> LogResponse(future<StatusOr<T>> response, std::string where,
+                                std::string args, TracingOptions options) {
+  LogResponseFuture(response.wait_for(std::chrono::microseconds(0)), where,
+                    args, options);
+  return response.then([where = std::move(where), args = std::move(args),
+                        options = std::move(options)](auto f) {
+    return LogResponse(f.get(), where, args, options);
+  });
+}
+
+void LogResponsePtr(bool not_null, absl::string_view where,
+                    absl::string_view args, TracingOptions const& options);
+
+template <typename T>
+std::unique_ptr<T> LogResponse(std::unique_ptr<T> response,
+                               absl::string_view where, absl::string_view args,
+                               TracingOptions const& options) {
+  LogResponsePtr(!!response, where, args, options);
+  return response;
+}
+
 template <
     typename Functor, typename Request, typename Context,
     typename Result = google::cloud::internal::invoke_result_t<
@@ -65,10 +112,8 @@ template <
                             int>::type = 0>
 Result LogWrapper(Functor&& functor, Context& context, Request const& request,
                   char const* where, TracingOptions const& options) {
-  GCP_LOG(DEBUG) << where << "() << " << DebugString(request, options);
-  auto response = functor(context, request);
-  GCP_LOG(DEBUG) << where << "() >> status=" << DebugString(response, options);
-  return response;
+  LogRequest(where, "", DebugString(request, options));
+  return LogResponse(functor(context, request), where, "", options);
 }
 
 template <typename Functor, typename Request, typename Context,
@@ -77,16 +122,8 @@ template <typename Functor, typename Request, typename Context,
           typename std::enable_if<IsStatusOr<Result>::value, int>::type = 0>
 Result LogWrapper(Functor&& functor, Context& context, Request const& request,
                   char const* where, TracingOptions const& options) {
-  GCP_LOG(DEBUG) << where << "() << " << DebugString(request, options);
-  auto response = functor(context, request);
-  if (!response) {
-    GCP_LOG(DEBUG) << where << "() >> status="
-                   << DebugString(response.status(), options);
-  } else {
-    GCP_LOG(DEBUG) << where
-                   << "() >> response=" << DebugString(*response, options);
-  }
-  return response;
+  LogRequest(where, "", DebugString(request, options));
+  return LogResponse(functor(context, request), where, "", options);
 }
 
 template <typename Functor, typename Request,
@@ -97,11 +134,8 @@ Result LogWrapper(Functor&& functor,
                   std::shared_ptr<grpc::ClientContext> context,
                   Request const& request, char const* where,
                   TracingOptions const& options) {
-  GCP_LOG(DEBUG) << where << "() << " << DebugString(request, options);
-  auto response = functor(std::move(context), request);
-  GCP_LOG(DEBUG) << where << "() >> " << (response ? "not null" : "null")
-                 << " stream";
-  return response;
+  LogRequest(where, "", DebugString(request, options));
+  return LogResponse(functor(std::move(context), request), where, "", options);
 }
 
 template <
@@ -111,11 +145,8 @@ template <
 Result LogWrapper(Functor&& functor, grpc::ClientContext& context,
                   Request const& request, grpc::CompletionQueue* cq,
                   char const* where, TracingOptions const& options) {
-  GCP_LOG(DEBUG) << where << "() << " << DebugString(request, options);
-  auto response = functor(context, request, cq);
-  GCP_LOG(DEBUG) << where << "() >> " << (response ? "not null" : "null")
-                 << " async response reader";
-  return response;
+  LogRequest(where, "", DebugString(request, options));
+  return LogResponse(functor(context, request, cq), where, "", options);
 }
 
 template <
@@ -130,26 +161,10 @@ Result LogWrapper(Functor&& functor, google::cloud::CompletionQueue& cq,
                   TracingOptions const& options) {
   // Because this is an asynchronous request we need a unique identifier so
   // applications can match the request and response in the log.
-  auto prefix = std::string(where) + "(" + RequestIdForLogging() + ")";
-  GCP_LOG(DEBUG) << prefix << " << " << DebugString(request, options);
-  auto response = functor(cq, std::move(context), request);
-  // Ideally we would have an ID to match the request with the asynchronous
-  // response, but for functions with this signature there is nothing that comes
-  // to mind.
-  GCP_LOG(DEBUG) << prefix << " >> future_status="
-                 << DebugFutureStatus(
-                        response.wait_for(std::chrono::microseconds(0)));
-  return response.then([prefix, options](decltype(response) f) {
-    auto response = f.get();
-    if (!response) {
-      GCP_LOG(DEBUG) << prefix << " >> status="
-                     << DebugString(response.status(), options);
-    } else {
-      GCP_LOG(DEBUG) << prefix
-                     << " >> response=" << DebugString(*response, options);
-    }
-    return response;
-  });
+  auto args = RequestIdForLogging();
+  LogRequest(where, args, DebugString(request, options));
+  return LogResponse(functor(cq, std::move(context), request), where,
+                     std::move(args), options);
 }
 
 template <typename Functor, typename Request,
@@ -163,21 +178,10 @@ Result LogWrapper(Functor&& functor, google::cloud::CompletionQueue& cq,
                   TracingOptions const& options) {
   // Because this is an asynchronous request we need a unique identifier so
   // applications can match the request and response in the log.
-  auto prefix = std::string(where) + "(" + RequestIdForLogging() + ")";
-  GCP_LOG(DEBUG) << prefix << " << " << DebugString(request, options);
-  auto response = functor(cq, std::move(context), request);
-  // Ideally we would have an ID to match the request with the asynchronous
-  // response, but for functions with this signature there is nothing that comes
-  // to mind.
-  GCP_LOG(DEBUG) << prefix << " >> future_status="
-                 << DebugFutureStatus(
-                        response.wait_for(std::chrono::microseconds(0)));
-  return response.then([prefix, options](future<Status> f) {
-    auto response = f.get();
-    GCP_LOG(DEBUG) << prefix
-                   << " >> response=" << DebugString(response, options);
-    return response;
-  });
+  auto args = RequestIdForLogging();
+  LogRequest(where, args, DebugString(request, options));
+  return LogResponse(functor(cq, std::move(context), request), where,
+                     std::move(args), options);
 }
 
 template <typename Functor, typename Request, typename Context,
@@ -190,18 +194,10 @@ Result LogWrapper(Functor&& functor, google::cloud::CompletionQueue& cq,
                   char const* where, TracingOptions const& options) {
   // Because this is an asynchronous request we need a unique identifier so
   // applications can match the request and response in the log.
-  auto prefix = std::string(where) + "(" + RequestIdForLogging() + ")";
-  GCP_LOG(DEBUG) << prefix << " << " << DebugString(request, options);
-  auto response = functor(cq, std::move(context), request);
-  GCP_LOG(DEBUG) << prefix << " >> future_status="
-                 << DebugFutureStatus(
-                        response.wait_for(std::chrono::microseconds(0)));
-  return response.then([prefix, options](future<Status> f) {
-    auto response = f.get();
-    GCP_LOG(DEBUG) << prefix
-                   << " >> response=" << DebugString(response, options);
-    return response;
-  });
+  auto args = RequestIdForLogging();
+  LogRequest(where, args, DebugString(request, options));
+  return LogResponse(functor(cq, std::move(context), request), where,
+                     std::move(args), options);
 }
 
 template <
@@ -215,23 +211,10 @@ Result LogWrapper(Functor&& functor, google::cloud::CompletionQueue& cq,
                   char const* where, TracingOptions const& options) {
   // Because this is an asynchronous request we need a unique identifier so
   // applications can match the request and response in the log.
-  auto prefix = std::string(where) + "(" + RequestIdForLogging() + ")";
-  GCP_LOG(DEBUG) << prefix << " << " << DebugString(request, options);
-  auto response = functor(cq, std::move(context), request);
-  GCP_LOG(DEBUG) << prefix << " >> future_status="
-                 << DebugFutureStatus(
-                        response.wait_for(std::chrono::microseconds(0)));
-  return response.then([prefix, options](decltype(response) f) {
-    auto response = f.get();
-    if (!response) {
-      GCP_LOG(DEBUG) << prefix << " >> status="
-                     << DebugString(response.status(), options);
-    } else {
-      GCP_LOG(DEBUG) << prefix
-                     << " >> response=" << DebugString(*response, options);
-    }
-    return response;
-  });
+  auto args = RequestIdForLogging();
+  LogRequest(where, args, DebugString(request, options));
+  return LogResponse(functor(cq, std::move(context), request), where,
+                     std::move(args), options);
 }
 
 }  // namespace internal

google/cloud/internal/log_wrapper_test.cc

@@ -129,7 +129,7 @@ TEST(LogWrapper, FutureStatusWithContextAndCQ) {
               Contains(AllOf(HasSubstr("in-test("), HasSubstr(" << "))));
   EXPECT_THAT(log_lines,
               Contains(AllOf(HasSubstr("in-test("),
-                             HasSubstr(" >> response=" + status_as_string))));
+                             HasSubstr(" >> status=" + status_as_string))));
   EXPECT_THAT(log_lines, Contains(AllOf(HasSubstr("in-test("),
                                         HasSubstr(" >> future_status="))));
 }
@@ -206,7 +206,7 @@ TEST(LogWrapper, FutureStatusWithTestContextAndCQ) {
               Contains(AllOf(HasSubstr("in-test("), HasSubstr(" << "))));
   EXPECT_THAT(log_lines,
               Contains(AllOf(HasSubstr("in-test("),
-                             HasSubstr(" >> response=" + status_as_string))));
+                             HasSubstr(" >> status=" + status_as_string))));
   EXPECT_THAT(log_lines, Contains(AllOf(HasSubstr("in-test("),
                                         HasSubstr(" >> future_status="))));
 }