add --log_metadata_and_status feature to interop_client (#28021)

bazel/grpc_build_system.bzl

@@ -383,12 +383,13 @@ def grpc_generate_one_off_targets():
 def grpc_generate_objc_one_off_targets():
     pass
 
-def grpc_sh_test(name, srcs, args = [], data = []):
+def grpc_sh_test(name, srcs, args = [], data = [], tags = []):
     native.sh_test(
         name = name,
         srcs = srcs,
         args = args,
         data = data,
+        tags = tags,
     )
 
 def grpc_sh_binary(name, srcs, data = []):

test/cpp/interop/BUILD

@@ -12,7 +12,7 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-load("//bazel:grpc_build_system.bzl", "grpc_cc_binary", "grpc_cc_library", "grpc_cc_test", "grpc_package")
+load("//bazel:grpc_build_system.bzl", "grpc_cc_binary", "grpc_cc_library", "grpc_cc_test", "grpc_package", "grpc_sh_test")
 
 licenses(["notice"])
 
@@ -219,6 +219,17 @@ grpc_cc_test(
     ],
 )
 
+grpc_sh_test(
+    name = "interop_test_with_metadata_log",
+    srcs = [
+        "interop_test_with_metadata_log.sh",
+    ],
+    data = [
+        ":interop_test",
+    ],
+    tags = ["no_windows"],
+)
+
 grpc_cc_binary(
     name = "xds_interop_client",
     srcs = [

test/cpp/interop/client.cc

@@ -116,6 +116,10 @@ ABSL_FLAG(int32_t, iteration_interval, 10,
 ABSL_FLAG(std::string, additional_metadata, "",
           "Additional metadata to send in each request, as a "
           "semicolon-separated list of key:value pairs.");
+ABSL_FLAG(
+    bool, log_metadata_and_status, false,
+    "If set to 'true', will print received initial and trailing metadata, "
+    "grpc-status and error message to the console, in a stable format.");
 
 using grpc::testing::CreateChannelForTestCase;
 using grpc::testing::GetServiceAccountJsonKey;
@@ -190,7 +194,14 @@ int main(int argc, char** argv) {
   std::string test_case = absl::GetFlag(FLAGS_test_case);
   if (absl::GetFlag(FLAGS_additional_metadata).empty()) {
     channel_creation_func = [test_case]() {
-      return CreateChannelForTestCase(test_case);
+      std::vector<std::unique_ptr<
+          grpc::experimental::ClientInterceptorFactoryInterface>>
+          factories;
+      if (absl::GetFlag(FLAGS_log_metadata_and_status)) {
+        factories.emplace_back(
+            new grpc::testing::MetadataAndStatusLoggerInterceptorFactory());
+      }
+      return CreateChannelForTestCase(test_case, std::move(factories));
     };
   } else {
     std::multimap<std::string, std::string> additional_metadata;
@@ -206,6 +217,10 @@ int main(int argc, char** argv) {
       factories.emplace_back(
           new grpc::testing::AdditionalMetadataInterceptorFactory(
               additional_metadata));
+      if (absl::GetFlag(FLAGS_log_metadata_and_status)) {
+        factories.emplace_back(
+            new grpc::testing::MetadataAndStatusLoggerInterceptorFactory());
+      }
       return CreateChannelForTestCase(test_case, std::move(factories));
     };
   }

test/cpp/interop/client_helper.cc

@@ -24,6 +24,7 @@
 
 #include "absl/flags/declare.h"
 #include "absl/flags/flag.h"
+#include "absl/strings/match.h"
 
 #include <grpc/grpc.h>
 #include <grpc/support/alloc.h>
@@ -32,6 +33,7 @@
 #include <grpcpp/create_channel.h>
 #include <grpcpp/security/credentials.h>
 
+#include "src/core/lib/slice/b64.h"
 #include "src/cpp/client/secure_credentials.h"
 #include "test/core/security/oauth2_utils.h"
 #include "test/cpp/util/create_test_channel.h"
@@ -139,5 +141,47 @@ std::shared_ptr<Channel> CreateChannelForTestCase(
   }
 }
 
+static void log_metadata_entry(const std::string& prefix,
+                               const grpc::string_ref& key,
+                               const grpc::string_ref& value) {
+  auto key_str = std::string(key.begin(), key.end());
+  auto value_str = std::string(value.begin(), value.end());
+  if (absl::EndsWith(key_str, "-bin")) {
+    auto converted =
+        grpc_base64_encode(value_str.c_str(), value_str.length(), 0, 0);
+    value_str = std::string(converted);
+    gpr_free(converted);
+  }
+  gpr_log(GPR_ERROR, "%s %s: %s", prefix.c_str(), key_str.c_str(),
+          value_str.c_str());
+}
+
+void MetadataAndStatusLoggerInterceptor::Intercept(
+    experimental::InterceptorBatchMethods* methods) {
+  if (methods->QueryInterceptionHookPoint(
+          experimental::InterceptionHookPoints::POST_RECV_INITIAL_METADATA)) {
+    auto initial_metadata = methods->GetRecvInitialMetadata();
+
+    for (const auto& entry : *initial_metadata) {
+      log_metadata_entry("GRPC_INITIAL_METADATA", entry.first, entry.second);
+    }
+  }
+
+  if (methods->QueryInterceptionHookPoint(
+          experimental::InterceptionHookPoints::POST_RECV_STATUS)) {
+    auto trailing_metadata = methods->GetRecvTrailingMetadata();
+    for (const auto& entry : *trailing_metadata) {
+      log_metadata_entry("GRPC_TRAILING_METADATA", entry.first, entry.second);
+    }
+
+    auto status = methods->GetRecvStatus();
+    gpr_log(GPR_ERROR, "GRPC_STATUS %d", status->error_code());
+    gpr_log(GPR_ERROR, "GRPC_ERROR_MESSAGE %s",
+            status->error_message().c_str());
+  }
+
+  methods->Proceed();
+}
+
 }  // namespace testing
 }  // namespace grpc

test/cpp/interop/client_helper.h

@@ -103,6 +103,24 @@ class AdditionalMetadataInterceptorFactory
   const std::multimap<std::string, std::string> additional_metadata_;
 };
 
+class MetadataAndStatusLoggerInterceptor : public experimental::Interceptor {
+ public:
+  explicit MetadataAndStatusLoggerInterceptor() {}
+
+  void Intercept(experimental::InterceptorBatchMethods* methods) override;
+};
+
+class MetadataAndStatusLoggerInterceptorFactory
+    : public experimental::ClientInterceptorFactoryInterface {
+ public:
+  explicit MetadataAndStatusLoggerInterceptorFactory() {}
+
+  experimental::Interceptor* CreateClientInterceptor(
+      experimental::ClientRpcInfo* /*info*/) override {
+    return new MetadataAndStatusLoggerInterceptor();
+  }
+};
+
 }  // namespace testing
 }  // namespace grpc
 

test/cpp/interop/interop_test.cc

@@ -39,7 +39,10 @@
 #include "test/core/util/port.h"
 #include "test/cpp/util/test_config.h"
 
-ABSL_FLAG(std::string, extra_server_flags, "",
+ABSL_FLAG(std::vector<std::string>, extra_client_flags, {},
+          "Extra flags to pass to clients.");
+
+ABSL_FLAG(std::vector<std::string>, extra_server_flags, {},
           "Extra flags to pass to server.");
 
 int test_client(const char* root, const char* host, int port) {
@@ -47,9 +50,17 @@ int test_client(const char* root, const char* host, int port) {
   pid_t cli;
   cli = fork();
   if (cli == 0) {
-    std::string binary_path = absl::StrCat(root, "/interop_client");
+    std::vector<char*> args;
+    std::string command = absl::StrCat(root, "/interop_client");
+    args.push_back(const_cast<char*>(command.c_str()));
     std::string port_arg = absl::StrCat("--server_port=", port);
-    execl(binary_path.c_str(), binary_path.c_str(), port_arg.c_str(), NULL);
+    args.push_back(const_cast<char*>(port_arg.c_str()));
+    auto extra_client_flags = absl::GetFlag(FLAGS_extra_client_flags);
+    for (size_t i = 0; i < extra_client_flags.size(); i++) {
+      args.push_back(const_cast<char*>(extra_client_flags[i].c_str()));
+    }
+    args.push_back(nullptr);
+    execv(args[0], args.data());
     return 1;
   }
   /* wait for client */
@@ -92,9 +103,9 @@ int main(int argc, char** argv) {
     args.push_back(const_cast<char*>(command.c_str()));
     std::string port_arg = absl::StrCat("--port=", port);
     args.push_back(const_cast<char*>(port_arg.c_str()));
-    if (!absl::GetFlag(FLAGS_extra_server_flags).empty()) {
-      args.push_back(
-          const_cast<char*>(absl::GetFlag(FLAGS_extra_server_flags).c_str()));
+    auto extra_server_flags = absl::GetFlag(FLAGS_extra_server_flags);
+    for (size_t i = 0; i < extra_server_flags.size(); i++) {
+      args.push_back(const_cast<char*>(extra_server_flags[i].c_str()));
     }
     args.push_back(nullptr);
     execv(args[0], args.data());

test/cpp/interop/interop_test_with_metadata_log.sh

@@ -0,0 +1,35 @@
+#!/bin/bash
+# Copyright 2021 The gRPC Authors
+#
+# 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
+#
+#     http://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.
+
+set -ex
+
+LOGFILE="$(mktemp)"
+
+# Location of the interop test binary is different depending
+# on whether we are running externally/internally, so we try both.
+INTEROP_TEST_BINARY="test/cpp/interop/interop_test"
+test -x "${INTEROP_TEST_BINARY}" || INTEROP_TEST_BINARY="third_party/grpc/${INTEROP_TEST_BINARY}"
+
+# Test that the --log_metadata_and_status flag generates the expected logs in the right format
+# by running the "custom_metadata" interop test case and inspect the logs afterwards.
+"${INTEROP_TEST_BINARY}" --extra_client_flags="--test_case=custom_metadata,--log_metadata_and_status" 2>&1 | tee "${LOGFILE}"
+
+# grep will return an error if any of the patterns below are not found in the log
+grep -q "GRPC_INITIAL_METADATA x-grpc-test-echo-initial: test_initial_metadata_value" "${LOGFILE}"
+grep -q "GRPC_TRAILING_METADATA x-grpc-test-echo-trailing-bin: CgsKCwoL" "${LOGFILE}"
+grep -q "GRPC_ERROR_MESSAGE " "${LOGFILE}"
+grep -q "GRPC_STATUS 0" "${LOGFILE}"
+
+echo "Passed."