refactor grpc: refactor grpc logging

commit_hash:736dbd4ec685f07d363e4d2c77fbf0c00db9edc4

.mapping.json

@@ -1972,6 +1972,8 @@
   "grpc/src/ugrpc/impl/code_statistics.cpp":"taxi/uservices/userver/grpc/src/ugrpc/impl/code_statistics.cpp",
   "grpc/src/ugrpc/impl/completion_queue_pool_base.cpp":"taxi/uservices/userver/grpc/src/ugrpc/impl/completion_queue_pool_base.cpp",
   "grpc/src/ugrpc/impl/deadline_timepoint.cpp":"taxi/uservices/userver/grpc/src/ugrpc/impl/deadline_timepoint.cpp",
+  "grpc/src/ugrpc/impl/grpc_native_logging.cpp":"taxi/uservices/userver/grpc/src/ugrpc/impl/grpc_native_logging.cpp",
+  "grpc/src/ugrpc/impl/grpc_native_logging.hpp":"taxi/uservices/userver/grpc/src/ugrpc/impl/grpc_native_logging.hpp",
   "grpc/src/ugrpc/impl/grpc_string_logging.hpp":"taxi/uservices/userver/grpc/src/ugrpc/impl/grpc_string_logging.hpp",
   "grpc/src/ugrpc/impl/internal_tag.hpp":"taxi/uservices/userver/grpc/src/ugrpc/impl/internal_tag.hpp",
   "grpc/src/ugrpc/impl/logging.cpp":"taxi/uservices/userver/grpc/src/ugrpc/impl/logging.cpp",

grpc/src/ugrpc/client/client_factory.cpp

@@ -3,7 +3,7 @@
 #include <userver/engine/async.hpp>
 #include <userver/utils/algo.hpp>
 
-#include <ugrpc/impl/logging.hpp>
+#include <ugrpc/impl/grpc_native_logging.hpp>
 
 USERVER_NAMESPACE_BEGIN
 

grpc/src/ugrpc/client/common_component.cpp

@@ -5,7 +5,7 @@
 #include <userver/logging/level_serialization.hpp>
 #include <userver/yaml_config/merge_schemas.hpp>
 
-#include <ugrpc/impl/logging.hpp>
+#include <ugrpc/impl/grpc_native_logging.hpp>
 #include <userver/ugrpc/client/middlewares/base.hpp>
 #include <userver/ugrpc/server/server_component.hpp>
 

grpc/src/ugrpc/client/middlewares/log/component.cpp

@@ -11,9 +11,9 @@ namespace ugrpc::client::middlewares::log {
 
 Settings Parse(const yaml_config::YamlConfig& config, formats::parse::To<Settings>) {
     Settings settings;
-    settings.max_msg_size = config["msg-size-log-limit"].As<std::size_t>(settings.max_msg_size);
     settings.log_level = config["log-level"].As<logging::Level>(settings.log_level);
-    settings.log_level = config["msg-log-level"].As<logging::Level>(settings.msg_log_level);
+    settings.msg_log_level = config["msg-log-level"].As<logging::Level>(settings.msg_log_level);
+    settings.max_msg_size = config["msg-size-log-limit"].As<std::size_t>(settings.max_msg_size);
     settings.trim_secrets = config["trim-secrets"].As<bool>(settings.trim_secrets);
     return settings;
 }

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

@@ -2,7 +2,7 @@
 
 #include <userver/logging/log_extra.hpp>
 
-#include <ugrpc/impl/protobuf_utils.hpp>
+#include <ugrpc/impl/logging.hpp>
 
 USERVER_NAMESPACE_BEGIN
 
@@ -14,16 +14,11 @@ bool IsSingleRequest(CallKind kind) { return CallKind::kUnaryCall == kind || Cal
 
 bool IsSingleResponse(CallKind kind) { return CallKind::kUnaryCall == kind || CallKind::kOutputStream == kind; }
 
-std::string ToLogString(const google::protobuf::Message& message, const Settings& settings) {
-    if (logging::ShouldLog(settings.msg_log_level)) {
-        if (settings.trim_secrets) {
-            return ugrpc::impl::ToLogString(message, settings.max_msg_size);
-        } else {
-            return ugrpc::impl::ToString(message, settings.max_msg_size);
-        }
-    } else {
-        return "hidden by log level";
-    }
+std::string GetMessageForLogging(const google::protobuf::Message& message, const Settings& settings) {
+    return ugrpc::impl::GetMessageForLogging(
+        message,
+        ugrpc::impl::MessageLoggingOptions{settings.msg_log_level, settings.max_msg_size, settings.trim_secrets}
+    );
 }
 
 class SpanLogger {
@@ -59,7 +54,7 @@ void Middleware::PreStartCall(MiddlewareCallContext& context) const {
 
 void Middleware::PreSendMessage(MiddlewareCallContext& context, const google::protobuf::Message& message) const {
     SpanLogger logger{context.GetSpan(), settings_.log_level};
-    logging::LogExtra extra{{"grpc_type", "request"}, {"body", ToLogString(message, settings_)}};
+    logging::LogExtra extra{{"grpc_type", "request"}, {"body", GetMessageForLogging(message, settings_)}};
     if (IsSingleRequest(context.GetCallKind())) {
         logger.Log("gRPC request", std::move(extra));
     } else {
@@ -69,7 +64,7 @@ void Middleware::PreSendMessage(MiddlewareCallContext& context, const google::pr
 
 void Middleware::PostRecvMessage(MiddlewareCallContext& context, const google::protobuf::Message& message) const {
     SpanLogger logger{context.GetSpan(), settings_.log_level};
-    logging::LogExtra extra{{"grpc_type", "response"}, {"body", ToLogString(message, settings_)}};
+    logging::LogExtra extra{{"grpc_type", "response"}, {"body", GetMessageForLogging(message, settings_)}};
     if (IsSingleResponse(context.GetCallKind())) {
         logger.Log("gRPC response", std::move(extra));
     } else {

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

@@ -10,15 +10,15 @@ USERVER_NAMESPACE_BEGIN
 namespace ugrpc::client::middlewares::log {
 
 struct Settings {
+    /// gRPC logging level
+    logging::Level log_level{logging::Level::kDebug};
+
     /// Max gRPC message size, the rest will be truncated
     std::size_t max_msg_size{512};
 
     /// gRPC message body logging level
     logging::Level msg_log_level{logging::Level::kDebug};
 
-    /// gRPC logging level
-    logging::Level log_level{logging::Level::kDebug};
-
     /// Whether to trim the fields marked as secret from the message
     bool trim_secrets{true};
 };

grpc/src/ugrpc/impl/grpc_native_logging.cpp

@@ -0,0 +1,83 @@
+#include <ugrpc/impl/grpc_native_logging.hpp>
+
+#include <stdexcept>
+
+#include <fmt/format.h>
+#include <grpc/support/log.h>
+
+#include <userver/engine/mutex.hpp>
+#include <userver/logging/log.hpp>
+#include <userver/utils/assert.hpp>
+#include <userver/utils/underlying_value.hpp>
+
+USERVER_NAMESPACE_BEGIN
+
+namespace ugrpc::impl {
+
+namespace {
+
+logging::Level ToLogLevel(::gpr_log_severity severity) noexcept {
+    switch (severity) {
+        case ::GPR_LOG_SEVERITY_DEBUG:
+            return logging::Level::kDebug;
+        case ::GPR_LOG_SEVERITY_INFO:
+            return logging::Level::kInfo;
+        case ::GPR_LOG_SEVERITY_ERROR:
+            [[fallthrough]];
+        default:
+            return logging::Level::kError;
+    }
+}
+
+::gpr_log_severity ToGprLogSeverity(logging::Level level) {
+    switch (level) {
+        case logging::Level::kDebug:
+            return ::GPR_LOG_SEVERITY_DEBUG;
+        case logging::Level::kInfo:
+            return ::GPR_LOG_SEVERITY_INFO;
+        case logging::Level::kError:
+            return ::GPR_LOG_SEVERITY_ERROR;
+        default:
+            throw std::logic_error(fmt::format(
+                "grpcpp log level {} is not allowed. Allowed options: "
+                "debug, info, error.",
+                logging::ToString(level)
+            ));
+    }
+}
+
+void LogFunction(::gpr_log_func_args* args) noexcept {
+    UASSERT(args);
+    const auto lvl = ToLogLevel(args->severity);
+    if (!logging::ShouldLog(lvl)) return;
+
+    auto& logger = logging::GetDefaultLogger();
+    const auto location = utils::impl::SourceLocation::Custom(args->line, args->file, "");
+    logging::LogHelper(logger, lvl, location) << args->message;
+
+    // We used to call LogFlush for kError logging level here,
+    // but that might lead to a thread switch (there is a coroutine-aware
+    // .Wait somewhere down the call chain), which breaks the grpc-core badly:
+    // its ExecCtx/ApplicationCallbackExecCtx are attached to a current thread
+    // (thread_local that is), and switching threads violates that, obviously.
+}
+
+engine::Mutex native_log_level_mutex;
+auto native_log_level = logging::Level::kNone;
+
+}  // namespace
+
+void SetupNativeLogging() { ::gpr_set_log_function(&LogFunction); }
+
+void UpdateNativeLogLevel(logging::Level min_log_level_override) {
+    std::lock_guard lock(native_log_level_mutex);
+
+    if (utils::UnderlyingValue(min_log_level_override) < utils::UnderlyingValue(native_log_level)) {
+        ::gpr_set_log_verbosity(ToGprLogSeverity(min_log_level_override));
+        native_log_level = min_log_level_override;
+    }
+}
+
+}  // namespace ugrpc::impl
+
+USERVER_NAMESPACE_END

grpc/src/ugrpc/impl/grpc_native_logging.hpp

@@ -0,0 +1,18 @@
+#pragma once
+
+#include <userver/logging/level.hpp>
+
+USERVER_NAMESPACE_BEGIN
+
+namespace ugrpc::impl {
+
+// Thread-safe. Can be called multiple times if needed.
+void SetupNativeLogging();
+
+// Thread-safe. Can be called multiple times if needed, the most verbose log
+// level is chosen. Only kDebug, kInfo, kError levels are allowed.
+void UpdateNativeLogLevel(logging::Level min_log_level);
+
+}  // namespace ugrpc::impl
+
+USERVER_NAMESPACE_END

grpc/src/ugrpc/impl/logging.cpp

@@ -1,81 +1,37 @@
 #include <ugrpc/impl/logging.hpp>
 
-#include <stdexcept>
+#include <memory>
 
-#include <fmt/format.h>
-#include <grpc/impl/codegen/log.h>
-
-#include <userver/engine/mutex.hpp>
 #include <userver/logging/log.hpp>
-#include <userver/utils/assert.hpp>
-#include <userver/utils/underlying_value.hpp>
+#include <userver/utils/log.hpp>
+
+#include <ugrpc/impl/protobuf_utils.hpp>
 
 USERVER_NAMESPACE_BEGIN
 
 namespace ugrpc::impl {
 
 namespace {
 
-logging::Level ToLogLevel(::gpr_log_severity severity) noexcept {
-    switch (severity) {
-        case ::GPR_LOG_SEVERITY_DEBUG:
-            return logging::Level::kDebug;
-        case ::GPR_LOG_SEVERITY_INFO:
-            return logging::Level::kInfo;
-        case ::GPR_LOG_SEVERITY_ERROR:
-            [[fallthrough]];
-        default:
-            return logging::Level::kError;
-    }
-}
-
-::gpr_log_severity ToGprLogSeverity(logging::Level level) {
-    switch (level) {
-        case logging::Level::kDebug:
-            return ::GPR_LOG_SEVERITY_DEBUG;
-        case logging::Level::kInfo:
-            return ::GPR_LOG_SEVERITY_INFO;
-        case logging::Level::kError:
-            return ::GPR_LOG_SEVERITY_ERROR;
-        default:
-            throw std::logic_error(fmt::format(
-                "grpcpp log level {} is not allowed. Allowed options: "
-                "debug, info, error.",
-                logging::ToString(level)
-            ));
-    }
-}
-
-void LogFunction(::gpr_log_func_args* args) noexcept {
-    UASSERT(args);
-    const auto lvl = ToLogLevel(args->severity);
-    if (!logging::ShouldLog(lvl)) return;
-
-    auto& logger = logging::GetDefaultLogger();
-    const auto location = utils::impl::SourceLocation::Custom(args->line, args->file, "");
-    logging::LogHelper(logger, lvl, location) << args->message;
-
-    // We used to call LogFlush for kError logging level here,
-    // but that might lead to a thread switch (there is a coroutine-aware
-    // .Wait somewhere down the call chain), which breaks the grpc-core badly:
-    // its ExecCtx/ApplicationCallbackExecCtx are attached to a current thread
-    // (thread_local that is), and switching threads violates that, obviously.
+std::string ToLimitedString(const google::protobuf::Message& message, std::size_t max_size) {
+    return utils::log::ToLimitedUtf8(message.Utf8DebugString(), max_size);
 }
 
-engine::Mutex native_log_level_mutex;
-auto native_log_level = logging::Level::kNone;
-
 }  // namespace
 
-void SetupNativeLogging() { ::gpr_set_log_function(&LogFunction); }
-
-void UpdateNativeLogLevel(logging::Level min_log_level_override) {
-    std::lock_guard lock(native_log_level_mutex);
+std::string GetMessageForLogging(const google::protobuf::Message& message, MessageLoggingOptions options) {
+    if (!logging::ShouldLog(options.log_level)) {
+        return "hidden by log level";
+    }
 
-    if (utils::UnderlyingValue(min_log_level_override) < utils::UnderlyingValue(native_log_level)) {
-        ::gpr_set_log_verbosity(ToGprLogSeverity(min_log_level_override));
-        native_log_level = min_log_level_override;
+    if (!options.trim_secrets || !HasSecrets(message)) {
+        return ToLimitedString(message, options.max_size);
     }
+
+    std::unique_ptr<google::protobuf::Message> trimmed{message.New()};
+    trimmed->CopyFrom(message);
+    TrimSecrets(*trimmed);
+    return ToLimitedString(*trimmed, options.max_size);
 }
 
 }  // namespace ugrpc::impl

grpc/src/ugrpc/impl/logging.hpp

@@ -1,19 +1,22 @@
 #pragma once
 
-#include <optional>
+#include <string>
+
+#include <google/protobuf/message.h>
 
 #include <userver/logging/level.hpp>
 
 USERVER_NAMESPACE_BEGIN
 
 namespace ugrpc::impl {
 
-// Thread-safe. Can be called multiple times if needed.
-void SetupNativeLogging();
+struct MessageLoggingOptions {
+    logging::Level log_level{logging::Level::kDebug};
+    std::size_t max_size{512};
+    bool trim_secrets{true};
+};
 
-// Thread-safe. Can be called multiple times if needed, the most verbose log
-// level is chosen. Only kDebug, kInfo, kError levels are allowed.
-void UpdateNativeLogLevel(logging::Level min_log_level);
+std::string GetMessageForLogging(const google::protobuf::Message& message, MessageLoggingOptions options = {});
 
 }  // namespace ugrpc::impl