feat grpc: use proper tags in server logs

add data for logs middlewares

Tests: протестировано CI
41e257b6281459d0f700016df8a565e231b3678e

grpc/include/userver/ugrpc/server/middlewares/base.hpp

@@ -53,6 +53,7 @@ class MiddlewareCallContext final {
 
   std::optional<dynamic_config::Snapshot> config_;
   ::google::protobuf::Message* request_;
+  bool is_called_from_handle_{false};
 };
 
 /// @ingroup userver_base_classes

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 <typename Response>
 UnaryCall<Response>::UnaryCall(impl::CallParams&& call_params,
                                impl::RawResponseWriter<Response>& stream)
-    : CallAnyBase(std::move(call_params)), stream_(stream) {}
+    : CallAnyBase(std::move(call_params), CallKind::kUnaryCall),
+      stream_(stream) {}
 
 template <typename Response>
 UnaryCall<Response>::~UnaryCall() {
@@ -420,7 +434,8 @@ bool UnaryCall<Response>::IsFinished() const {
 template <typename Request, typename Response>
 InputStream<Request, Response>::InputStream(
     impl::CallParams&& call_params, impl::RawReader<Request, Response>& stream)
-    : CallAnyBase(std::move(call_params)), stream_(stream) {}
+    : CallAnyBase(std::move(call_params), CallKind::kRequestStream),
+      stream_(stream) {}
 
 template <typename Request, typename Response>
 InputStream<Request, Response>::~InputStream() {
@@ -483,7 +498,8 @@ bool InputStream<Request, Response>::IsFinished() const {
 template <typename Response>
 OutputStream<Response>::OutputStream(impl::CallParams&& call_params,
                                      impl::RawWriter<Response>& stream)
-    : CallAnyBase(std::move(call_params)), stream_(stream) {}
+    : CallAnyBase(std::move(call_params), CallKind::kResponseStream),
+      stream_(stream) {}
 
 template <typename Response>
 OutputStream<Response>::~OutputStream() {
@@ -571,7 +587,8 @@ template <typename Request, typename Response>
 BidirectionalStream<Request, Response>::BidirectionalStream(
     impl::CallParams&& call_params,
     impl::RawReaderWriter<Request, Response>& stream)
-    : CallAnyBase(std::move(call_params)), stream_(stream) {}
+    : CallAnyBase(std::move(call_params), CallKind::kBidirectionalStream),
+      stream_(stream) {}
 
 template <typename Request, typename Response>
 BidirectionalStream<Request, Response>::~BidirectionalStream() {
@@ -655,10 +672,10 @@ void BidirectionalStream<Request, Response>::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());
 }
 

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);
   }
 }
 

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

grpc/src/ugrpc/server/middlewares/log/middleware.cpp

@@ -1,5 +1,8 @@
 #include "middleware.hpp"
 
+#include <fmt/core.h>
+#include <google/protobuf/util/json_util.h>
+
 #include <userver/logging/log_extra.hpp>
 #include <userver/tracing/span.hpp>
 #include <userver/utils/log.hpp>
@@ -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();
 }

grpc/src/ugrpc/server/middlewares/log/middleware.hpp

@@ -1,11 +1,15 @@
 #pragma once
 
 #include <userver/ugrpc/server/middlewares/base.hpp>
+#include <userver/ugrpc/server/storage_context.hpp>
+#include <userver/utils/any_storage.hpp>
 
 USERVER_NAMESPACE_BEGIN
 
 namespace ugrpc::server::middlewares::log {
 
+inline const utils::AnyStorageDataTag<StorageContext, bool> kIsFirstRequest;
+
 class Middleware final : public MiddlewareBase {
  public:
   struct Settings {