From ce74e092e62f752bc4e9b9c501d0decd3181cbc5 Mon Sep 17 00:00:00 2001 From: Jan Tattermusch Date: Wed, 24 Nov 2021 00:32:13 +0100 Subject: [PATCH] add --log_metadata_and_status feature to interop_client (#28021) --- bazel/grpc_build_system.bzl | 3 +- test/cpp/interop/BUILD | 13 +++++- test/cpp/interop/client.cc | 17 ++++++- test/cpp/interop/client_helper.cc | 44 +++++++++++++++++++ test/cpp/interop/client_helper.h | 18 ++++++++ test/cpp/interop/interop_test.cc | 23 +++++++--- .../interop/interop_test_with_metadata_log.sh | 35 +++++++++++++++ 7 files changed, 144 insertions(+), 9 deletions(-) create mode 100755 test/cpp/interop/interop_test_with_metadata_log.sh diff --git a/bazel/grpc_build_system.bzl b/bazel/grpc_build_system.bzl index 0a78da99cc2..6236419bdeb 100644 --- a/bazel/grpc_build_system.bzl +++ b/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 = []): diff --git a/test/cpp/interop/BUILD b/test/cpp/interop/BUILD index 895f449fbcd..637fd6c4f6c 100644 --- a/test/cpp/interop/BUILD +++ b/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 = [ diff --git a/test/cpp/interop/client.cc b/test/cpp/interop/client.cc index ce7b14990b4..e923f080e2a 100644 --- a/test/cpp/interop/client.cc +++ b/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> + 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 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)); }; } diff --git a/test/cpp/interop/client_helper.cc b/test/cpp/interop/client_helper.cc index 17f2ad25131..21c760ade46 100644 --- a/test/cpp/interop/client_helper.cc +++ b/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 #include @@ -32,6 +33,7 @@ #include #include +#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 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 diff --git a/test/cpp/interop/client_helper.h b/test/cpp/interop/client_helper.h index 2902ab7913f..184285918f9 100644 --- a/test/cpp/interop/client_helper.h +++ b/test/cpp/interop/client_helper.h @@ -103,6 +103,24 @@ class AdditionalMetadataInterceptorFactory const std::multimap 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 diff --git a/test/cpp/interop/interop_test.cc b/test/cpp/interop/interop_test.cc index f0985e7b131..dc428294633 100644 --- a/test/cpp/interop/interop_test.cc +++ b/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, extra_client_flags, {}, + "Extra flags to pass to clients."); + +ABSL_FLAG(std::vector, 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 args; + std::string command = absl::StrCat(root, "/interop_client"); + args.push_back(const_cast(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(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(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(command.c_str())); std::string port_arg = absl::StrCat("--port=", port); args.push_back(const_cast(port_arg.c_str())); - if (!absl::GetFlag(FLAGS_extra_server_flags).empty()) { - args.push_back( - const_cast(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(extra_server_flags[i].c_str())); } args.push_back(nullptr); execv(args[0], args.data()); diff --git a/test/cpp/interop/interop_test_with_metadata_log.sh b/test/cpp/interop/interop_test_with_metadata_log.sh new file mode 100755 index 00000000000..aaf3135a109 --- /dev/null +++ b/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."