Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(common): make the RPC log even more readable #9561

Merged
merged 2 commits into from
Jul 26, 2022
Merged

feat(common): make the RPC log even more readable #9561

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
8c27711
feat(common): make the RPC log even more readable
devbww Jul 25, 2022
363fcae
I think MSVC is mistaken that `(b ? "X" : "Y")` is not of type
devbww Jul 25, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
48 changes: 48 additions & 0 deletions google/cloud/internal/log_wrapper.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,10 @@
#include "google/cloud/internal/log_wrapper.h"
#include "google/cloud/internal/absl_str_cat_quiet.h"
#include "google/cloud/internal/status_payload_keys.h"
#include "absl/time/time.h"
#include <google/protobuf/duration.pb.h>
#include <google/protobuf/text_format.h>
#include <google/protobuf/timestamp.pb.h>
#include <google/rpc/error_details.pb.h>
#include <atomic>
#include <sstream>
Expand All @@ -25,6 +28,47 @@ namespace cloud {
GOOGLE_CLOUD_CPP_INLINE_NAMESPACE_BEGIN
namespace internal {

namespace {

class DurationMessagePrinter
: public google::protobuf::TextFormat::MessagePrinter {
public:
~DurationMessagePrinter() override = default;
void Print(google::protobuf::Message const& message, bool single_line_mode,
google::protobuf::TextFormat::BaseTextGenerator* generator)
const override {
auto const* reflection = message.GetReflection();
auto const* descriptor = message.GetDescriptor();
auto seconds = reflection->GetInt64(message, descriptor->field(0));
auto nanos = reflection->GetInt32(message, descriptor->field(1));
auto d = absl::Seconds(seconds) + absl::Nanoseconds(nanos);
generator->PrintLiteral("\"");
generator->PrintString(absl::FormatDuration(d));
generator->PrintLiteral("\"");
generator->Print(single_line_mode ? " " : "\n", 1);
}
};

class TimestampMessagePrinter
: public google::protobuf::TextFormat::MessagePrinter {
public:
~TimestampMessagePrinter() override = default;
void Print(google::protobuf::Message const& message, bool single_line_mode,
google::protobuf::TextFormat::BaseTextGenerator* generator)
const override {
auto const* reflection = message.GetReflection();
auto const* descriptor = message.GetDescriptor();
auto seconds = reflection->GetInt64(message, descriptor->field(0));
auto nanos = reflection->GetInt32(message, descriptor->field(1));
auto t = absl::FromUnixSeconds(seconds) + absl::Nanoseconds(nanos);
auto constexpr kFormat = "\"%E4Y-%m-%dT%H:%M:%E*SZ\"";
generator->PrintString(absl::FormatTime(kFormat, t, absl::UTCTimeZone()));
generator->Print(single_line_mode ? " " : "\n", 1);
}
};

} // namespace

std::string DebugString(google::protobuf::Message const& m,
TracingOptions const& options) {
std::string str;
Expand All @@ -36,6 +80,10 @@ std::string DebugString(google::protobuf::Message const& m,
options.truncate_string_field_longer_than());
p.SetPrintMessageFieldsInIndexOrder(true);
p.SetExpandAny(true);
p.RegisterMessagePrinter(google::protobuf::Duration::descriptor(),
new DurationMessagePrinter);
p.RegisterMessagePrinter(google::protobuf::Timestamp::descriptor(),
new TimestampMessagePrinter);
p.PrintToString(m, &str);
return absl::StrCat(m.GetTypeName(), " {",
(options.single_line_mode() ? " " : "\n"), str, "}");
Expand Down
23 changes: 23 additions & 0 deletions google/cloud/internal/log_wrapper_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,9 @@
#include "google/cloud/testing_util/scoped_log.h"
#include "google/cloud/tracing_options.h"
#include <google/bigtable/v2/bigtable.grpc.pb.h>
#include <google/protobuf/duration.pb.h>
#include <google/protobuf/text_format.h>
#include <google/protobuf/timestamp.pb.h>
#include <google/rpc/error_details.pb.h>
#include <google/rpc/status.pb.h>
#include <google/spanner/v1/mutation.pb.h>
Expand Down Expand Up @@ -161,6 +163,27 @@ TEST(LogWrapper, TruncateString) {
}
}

TEST(LogWrapper, Duration) {
google::protobuf::Duration duration;
duration.set_seconds((11 * 60 + 22) * 60 + 33);
duration.set_nanos(123456789);
std::string const expected =
R"(google.protobuf.Duration { "11h22m33.123456789s" })";
EXPECT_EQ(expected, DebugString(duration, TracingOptions{}.SetOptions(
"single_line_mode=on")));
}

TEST(LogWrapper, Timestamp) {
google::protobuf::Timestamp timestamp;
timestamp.set_seconds(1658470436);
timestamp.set_nanos(123456789);
std::string const expected = R"(google.protobuf.Timestamp {
"2022-07-22T06:13:56.123456789Z"
})";
EXPECT_EQ(expected, DebugString(timestamp, TracingOptions{}.SetOptions(
"single_line_mode=off")));
}

TEST(LogWrapper, FutureStatus) {
struct Case {
std::future_status actual;
Expand Down
3 changes: 1 addition & 2 deletions google/cloud/internal/streaming_read_rpc_logging_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -85,8 +85,7 @@ TEST_F(StreamingReadRpcLoggingTest, Read) {
absl::visit(ResultVisitor(), result);
auto log_lines = log_.ExtractLines();
EXPECT_THAT(log_lines, Contains(HasSubstr("Read")));
EXPECT_THAT(log_lines, Contains(HasSubstr("seconds")));
EXPECT_THAT(log_lines, Contains(HasSubstr("42")));
EXPECT_THAT(log_lines, Contains(HasSubstr("42s")));

result = reader.Read();
absl::visit(ResultVisitor(), result);
Expand Down
4 changes: 2 additions & 2 deletions google/cloud/internal/streaming_write_rpc_logging_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -76,7 +76,7 @@ TEST_F(StreamingWriteRpcLoggingTest, Write) {
stream.Write(request, grpc::WriteOptions{});
auto const lines = log_.ExtractLines();
EXPECT_THAT(lines, Contains(AllOf(HasSubstr("Write"), HasSubstr("test-id"),
HasSubstr("123456"))));
HasSubstr("1970-01-02T10:17:36Z"))));
EXPECT_THAT(lines, Contains(AllOf(HasSubstr("Write"), HasSubstr("test-id"),
HasSubstr("true"))));
}
Expand All @@ -94,7 +94,7 @@ TEST_F(StreamingWriteRpcLoggingTest, CloseWithSuccess) {
EXPECT_THAT(lines, Contains(AllOf(HasSubstr("Close"), HasSubstr("test-id"),
HasSubstr("(void)"))));
EXPECT_THAT(lines, Contains(AllOf(HasSubstr("Close"), HasSubstr("test-id"),
HasSubstr("123456"))));
HasSubstr("34h17m36s"))));
}

TEST_F(StreamingWriteRpcLoggingTest, CloseWithError) {
Expand Down