From ab8b129552da3b1076e5bcf4961d47d505897d00 Mon Sep 17 00:00:00 2001 From: alexiprof Date: Tue, 18 Jun 2024 18:01:05 +0300 Subject: [PATCH] feat grpc: use proper tags in server logs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit add data for logs middlewares Tests: протестировано CI 41e257b6281459d0f700016df8a565e231b3678e --- .../userver/ugrpc/server/middlewares/base.hpp | 1 + grpc/include/userver/ugrpc/server/rpc.hpp | 29 ++++-- grpc/src/ugrpc/server/middlewares/base.cpp | 17 ++-- .../server/middlewares/log/component.cpp | 2 +- .../server/middlewares/log/middleware.cpp | 88 ++++++++++++++----- .../server/middlewares/log/middleware.hpp | 4 + 6 files changed, 102 insertions(+), 39 deletions(-) diff --git a/grpc/include/userver/ugrpc/server/middlewares/base.hpp b/grpc/include/userver/ugrpc/server/middlewares/base.hpp index 76646b8464a2..adefa6488c1d 100644 --- a/grpc/include/userver/ugrpc/server/middlewares/base.hpp +++ b/grpc/include/userver/ugrpc/server/middlewares/base.hpp @@ -53,6 +53,7 @@ class MiddlewareCallContext final { std::optional config_; ::google::protobuf::Message* request_; + bool is_called_from_handle_{false}; }; /// @ingroup userver_base_classes diff --git a/grpc/include/userver/ugrpc/server/rpc.hpp b/grpc/include/userver/ugrpc/server/rpc.hpp index 52aefbd35570..1a822f8fdc95 100644 --- a/grpc/include/userver/ugrpc/server/rpc.hpp +++ b/grpc/include/userver/ugrpc/server/rpc.hpp @@ -31,10 +31,19 @@ std::string FormatLogMessage( } +/// @brief RPCs kinds +enum class CallKind { + kUnaryCall, + kRequestStream, + kResponseStream, + kBidirectionalStream, +}; + /// @brief A non-typed base class for any gRPC call class CallAnyBase { public: - CallAnyBase(impl::CallParams&& params) : params_(std::move(params)) {} + CallAnyBase(impl::CallParams&& params, CallKind call_kind) + : params_(std::move(params)), call_kind_(call_kind) {} /// @brief Complete the RPC with an error /// @@ -60,6 +69,9 @@ class CallAnyBase { tracing::Span& GetSpan() { return params_.call_span; } + /// @brief Get RPCs kind of method + CallKind GetCallKind() const { return call_kind_; } + /// @brief Returns call context for storing per-call custom data /// /// The context can be used to pass data from server middleware to client @@ -109,6 +121,7 @@ class CallAnyBase { private: impl::CallParams params_; + CallKind call_kind_; MiddlewareCallContext* middleware_call_context_{nullptr}; }; @@ -374,7 +387,8 @@ class BidirectionalStream : public CallAnyBase { template UnaryCall::UnaryCall(impl::CallParams&& call_params, impl::RawResponseWriter& stream) - : CallAnyBase(std::move(call_params)), stream_(stream) {} + : CallAnyBase(std::move(call_params), CallKind::kUnaryCall), + stream_(stream) {} template UnaryCall::~UnaryCall() { @@ -420,7 +434,8 @@ bool UnaryCall::IsFinished() const { template InputStream::InputStream( impl::CallParams&& call_params, impl::RawReader& stream) - : CallAnyBase(std::move(call_params)), stream_(stream) {} + : CallAnyBase(std::move(call_params), CallKind::kRequestStream), + stream_(stream) {} template InputStream::~InputStream() { @@ -483,7 +498,8 @@ bool InputStream::IsFinished() const { template OutputStream::OutputStream(impl::CallParams&& call_params, impl::RawWriter& stream) - : CallAnyBase(std::move(call_params)), stream_(stream) {} + : CallAnyBase(std::move(call_params), CallKind::kResponseStream), + stream_(stream) {} template OutputStream::~OutputStream() { @@ -571,7 +587,8 @@ template BidirectionalStream::BidirectionalStream( impl::CallParams&& call_params, impl::RawReaderWriter& stream) - : CallAnyBase(std::move(call_params)), stream_(stream) {} + : CallAnyBase(std::move(call_params), CallKind::kBidirectionalStream), + stream_(stream) {} template BidirectionalStream::~BidirectionalStream() { @@ -655,10 +672,10 @@ void BidirectionalStream::WriteAndFinish( grpc::WriteOptions write_options{}; const auto status = grpc::Status::OK; - LogFinish(status); ApplyResponseHook(&response); + LogFinish(status); impl::WriteAndFinish(stream_, response, write_options, status, GetCallName()); } diff --git a/grpc/src/ugrpc/server/middlewares/base.cpp b/grpc/src/ugrpc/server/middlewares/base.cpp index 6244fc35e24d..8d3a03fa3fcb 100644 --- a/grpc/src/ugrpc/server/middlewares/base.cpp +++ b/grpc/src/ugrpc/server/middlewares/base.cpp @@ -21,18 +21,19 @@ MiddlewareCallContext::MiddlewareCallContext( request_(request) {} void MiddlewareCallContext::Next() { - if (middleware_ == middleware_end_) { - ClearMiddlewaresResources(); - user_call_(); - } else { + if (is_called_from_handle_) { // It is important for non-stream calls if (request_) { (*middleware_)->CallRequestHook(*this, *request_); } - // NOLINTNEXTLINE(readability-qualified-auto) - const auto middleware = middleware_++; - - (*middleware)->Handle(*this); + ++middleware_; + } + if (middleware_ == middleware_end_) { + ClearMiddlewaresResources(); + user_call_(); + } else { + is_called_from_handle_ = true; + (*middleware_)->Handle(*this); } } diff --git a/grpc/src/ugrpc/server/middlewares/log/component.cpp b/grpc/src/ugrpc/server/middlewares/log/component.cpp index aac06653e83a..89426844e024 100644 --- a/grpc/src/ugrpc/server/middlewares/log/component.cpp +++ b/grpc/src/ugrpc/server/middlewares/log/component.cpp @@ -34,7 +34,7 @@ additionalProperties: false description: gRPC handlers log level msg-log-level: type: string - description: log level of message log + description: set up log level for request/response messages body msg-size-log-limit: type: string description: max message size to log, the rest will be truncated diff --git a/grpc/src/ugrpc/server/middlewares/log/middleware.cpp b/grpc/src/ugrpc/server/middlewares/log/middleware.cpp index bd597089928d..d938f3bd128e 100644 --- a/grpc/src/ugrpc/server/middlewares/log/middleware.cpp +++ b/grpc/src/ugrpc/server/middlewares/log/middleware.cpp @@ -1,5 +1,8 @@ #include "middleware.hpp" +#include +#include + #include #include #include @@ -8,48 +11,85 @@ USERVER_NAMESPACE_BEGIN namespace ugrpc::server::middlewares::log { +namespace { + +std::string ProtobufAsJsonString(const google::protobuf::Message& message, + uint64_t max_msg_size) { + google::protobuf::util::JsonPrintOptions options; + options.add_whitespace = false; + grpc::string as_json; + const auto status = + google::protobuf::util::MessageToJsonString(message, &as_json, options); + if (!status.ok()) { + std::string log = + fmt::format("Error getting a json string: {}", status.message().data()); + LOG_WARNING() << log; + return log; + } + return std::string{utils::log::ToLimitedUtf8(as_json, max_msg_size)}; +}; + +} // namespace + Middleware::Middleware(const Settings& settings) : settings_(settings) {} void Middleware::CallRequestHook(const MiddlewareCallContext& context, google::protobuf::Message& request) { - if (settings_.local_log_level) { - auto& span = tracing::Span::CurrentSpan(); - span.SetLocalLogLevel(*settings_.local_log_level); - } + auto& storage = context.GetCall().GetStorageContext(); + auto log = ProtobufAsJsonString(request, settings_.max_msg_size); - const logging::LogExtra log_extra{ - {"grpc_service", std::string(context.GetServiceName())}, - {"grpc_method", std::string(context.GetMethodName())}}; - auto log_func = [&]() -> std::string { - const auto& str = request.Utf8DebugString(); - return utils::log::ToLimitedUtf8(str, settings_.max_msg_size); - }; + logging::LogExtra log_extra{{"grpc_type", "request"}, + {"body", std::move(log)}}; + if (storage.Get(kIsFirstRequest)) { + storage.Set(kIsFirstRequest, false); + log_extra.Extend("type", "request"); + } LOG(settings_.msg_log_level) - << "gRPC request message: " << log_func() << log_extra; + << "gRPC request message" << std::move(log_extra); } void Middleware::CallResponseHook(const MiddlewareCallContext& context, google::protobuf::Message& response) { - if (settings_.local_log_level) { - auto& span = tracing::Span::CurrentSpan(); - span.SetLocalLogLevel(*settings_.local_log_level); + auto& span = context.GetCall().GetSpan(); + const auto call_kind = context.GetCall().GetCallKind(); + auto log = ProtobufAsJsonString(response, settings_.max_msg_size); + + if (call_kind == CallKind::kUnaryCall || + call_kind == CallKind::kRequestStream) { + span.AddTag("grpc_type", "response"); + span.AddNonInheritableTag("type", "response"); + if (logging::ShouldLog(settings_.msg_log_level)) { + span.AddNonInheritableTag("body", std::move(log)); + } else { + span.AddNonInheritableTag("body", "hidden by log level"); + } + } else { + logging::LogExtra log_extra{{"grpc_type", "response"}, + {"body", std::move(log)}}; + LOG(settings_.msg_log_level) + << "gRPC response message" << std::move(log_extra); } - const logging::LogExtra log_extra{ - {"grpc_service", std::string(context.GetServiceName())}, - {"grpc_method", std::string(context.GetMethodName())}}; - auto log_func = [&]() -> std::string { - const auto& str = response.Utf8DebugString(); - return utils::log::ToLimitedUtf8(str, settings_.max_msg_size); - }; - LOG(settings_.msg_log_level) << "gRPC response message: " << log_func(); } void Middleware::Handle(MiddlewareCallContext& context) const { + auto& storage = context.GetCall().GetStorageContext(); + const auto call_kind = context.GetCall().GetCallKind(); + storage.Emplace(kIsFirstRequest, true); + + auto& span = context.GetCall().GetSpan(); if (settings_.local_log_level) { - auto& span = tracing::Span::CurrentSpan(); span.SetLocalLogLevel(*settings_.local_log_level); } + const auto meta_type = + fmt::format("{}/{}", context.GetServiceName(), context.GetMethodName()); + + span.AddTag("meta_type", meta_type); + if (call_kind == CallKind::kResponseStream || + call_kind == CallKind::kBidirectionalStream) { + span.AddNonInheritableTag("type", "response"); + span.AddNonInheritableTag("body", "stream finished"); + } context.Next(); } diff --git a/grpc/src/ugrpc/server/middlewares/log/middleware.hpp b/grpc/src/ugrpc/server/middlewares/log/middleware.hpp index 8de1df8374b5..9a151697b9bf 100644 --- a/grpc/src/ugrpc/server/middlewares/log/middleware.hpp +++ b/grpc/src/ugrpc/server/middlewares/log/middleware.hpp @@ -1,11 +1,15 @@ #pragma once #include +#include +#include USERVER_NAMESPACE_BEGIN namespace ugrpc::server::middlewares::log { +inline const utils::AnyStorageDataTag kIsFirstRequest; + class Middleware final : public MiddlewareBase { public: struct Settings {