feat: json logging

core/src/logging/component.cpp

@@ -252,6 +252,7 @@ additionalProperties: false
                       - tskv
                       - ltsv
                       - raw
+                      - json
                 flush_level:
                     type: string
                     description: messages of this and higher levels get flushed to the file immediately

core/src/logging/json_string_test.cpp

@@ -0,0 +1,44 @@
+#include <userver/logging/json_string.hpp>
+
+#include <gtest/gtest.h>
+
+#include <userver/utest/assert_macros.hpp>
+
+USERVER_NAMESPACE_BEGIN
+
+TEST(JsonString, ConstructFromJson) {
+  using formats::literals::operator""_json;
+
+  auto json = R"({
+    "a": "foo",
+    "b": {
+      "c": "d",
+      "e": [
+        1,
+        2
+      ]
+    }
+  })"_json;
+
+  logging::JsonString json_string(json);
+
+  EXPECT_EQ(json_string.Value(), R"({"a":"foo","b":{"c":"d","e":[1,2]}})");
+}
+
+TEST(JsonString, ConstructFromString) {
+  std::string json = R"({"a":"foo",
+"b":{"c":"d","e":
+[1,2]}})";
+
+  logging::JsonString json_string(json);
+
+  EXPECT_EQ(json_string.Value(), R"({"a":"foo","b":{"c":"d","e":[1,2]}})");
+}
+
+TEST(JsonString, ConstructNull) {
+  logging::JsonString json_string;
+
+  EXPECT_EQ(json_string.Value(), R"(null)");
+}
+
+USERVER_NAMESPACE_END

core/src/logging/log_message_test.cpp

@@ -67,6 +67,11 @@ TEST_F(LoggingTest, TskvEncode) {
       << "escaped sequence is present in the message";
 }
 
+TEST_F(LoggingJsonTest, JsonEncode) {
+  LOG_CRITICAL() << "line\"1\nline 2";
+  EXPECT_THAT(GetStreamString(), testing::HasSubstr("line\\\"1\\nline 2"));
+}
+
 TEST_F(LoggingTest, TskvEncodeKeyWithDot) {
   logging::LogExtra le;
   le.Extend("http.port.ipv4", "4040");
@@ -76,6 +81,8 @@ TEST_F(LoggingTest, TskvEncodeKeyWithDot) {
 }
 
 TEST_F(LoggingTest, LogFormat) {
+  using formats::literals::operator""_json;
+
   // Note: this is a golden test. The order and content of tags is stable, which
   // is an implementation detail, but it makes this test possible. If the order
   // or content of tags change, this test should be fixed to reflect the
@@ -88,8 +95,40 @@ TEST_F(LoggingTest, LogFormat) {
       R"(task_id=[0-9A-F]+\t)"
       R"(thread_id=0x[0-9A-F]+\t)"
       R"(text=test\t)"
-      R"(foo=bar\n)";
-  LOG_CRITICAL() << "test" << logging::LogExtra{{"foo", "bar"}};
+      R"(foo=bar\t)"
+      R"(json={\"a\":\"foo\"}\n)";
+  LOG_CRITICAL() << "test" << logging::LogExtra{{"foo", "bar"}}
+                 << logging::LogExtra{{"json", R"({"a": "foo"})"_json}};
+  logging::LogFlush();
+  EXPECT_TRUE(
+      utils::regex_match(GetStreamString(), utils::regex(kExpectedPattern)))
+      << GetStreamString();
+
+  EXPECT_THAT(GetStreamString(), testing::Not(testing::HasSubstr(" ( /")))
+      << "Path shortening for logs stopped working.";
+}
+
+TEST_F(LoggingJsonTest, LogFormat) {
+  // Note: this is a golden test. The order and content of tags is stable, which
+  // is an implementation detail, but it makes this test possible. If the order
+  // or content of tags change, this test should be fixed to reflect the
+  // changes.
+  constexpr std::string_view kExpectedPattern =
+      R"({)"
+      R"("timestamp":"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}",)"
+      R"("level":"[A-Z]+",)"
+      R"("module":"[\w\d ():./]+",)"
+      R"("task_id":"[0-9A-F]+",)"
+      R"("thread_id":"0x[0-9A-F]+",)"
+      R"("text":"test",)"
+      R"("str":"bar",)"
+      R"("int":"42",)"
+      R"("float":"0.123")"
+      R"(})"
+      R"(\n)";
+  LOG_CRITICAL() << "test" << logging::LogExtra{{"str", "bar"}}
+                 << logging::LogExtra{{"int", 42}}
+                 << logging::LogExtra{{"float", 0.123f}};
   logging::LogFlush();
   EXPECT_TRUE(
       utils::regex_match(GetStreamString(), utils::regex(kExpectedPattern)))
@@ -99,6 +138,82 @@ TEST_F(LoggingTest, LogFormat) {
       << "Path shortening for logs stopped working.";
 }
 
+TEST_F(LoggingJsonTest, LogFormatEmptyTextNonemptyExtra) {
+  // Note: this is a golden test. The order and content of tags is stable, which
+  // is an implementation detail, but it makes this test possible. If the order
+  // or content of tags change, this test should be fixed to reflect the
+  // changes.
+  constexpr std::string_view kExpectedPattern =
+      R"({)"
+      R"("timestamp":"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}",)"
+      R"("level":"[A-Z]+",)"
+      R"("module":"[\w\d ():./]+",)"
+      R"("task_id":"[0-9A-F]+",)"
+      R"("thread_id":"0x[0-9A-F]+",)"
+      R"("text":"",)"
+      R"("str":"bar",)"
+      R"("int":"42",)"
+      R"("float":"0.123")"
+      R"(})"
+      R"(\n)";
+  LOG_CRITICAL() << logging::LogExtra{{"str", "bar"}}
+                 << logging::LogExtra{{"int", 42}}
+                 << logging::LogExtra{{"float", 0.123f}};
+  logging::LogFlush();
+  EXPECT_TRUE(
+      utils::regex_match(GetStreamString(), utils::regex(kExpectedPattern)))
+      << GetStreamString();
+}
+
+TEST_F(LoggingJsonTest, LogFormatEmptyTextEmptyExtra) {
+  // Note: this is a golden test. The order and content of tags is stable, which
+  // is an implementation detail, but it makes this test possible. If the order
+  // or content of tags change, this test should be fixed to reflect the
+  // changes.
+  constexpr std::string_view kExpectedPattern =
+      R"({)"
+      R"("timestamp":"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}",)"
+      R"("level":"[A-Z]+",)"
+      R"("module":"[\w\d ():./]+",)"
+      R"("task_id":"[0-9A-F]+",)"
+      R"("thread_id":"0x[0-9A-F]+",)"
+      R"("text":"")"
+      R"(})"
+      R"(\n)";
+  LOG_CRITICAL() << "";
+  logging::LogFlush();
+  EXPECT_TRUE(
+      utils::regex_match(GetStreamString(), utils::regex(kExpectedPattern)))
+      << GetStreamString();
+}
+
+TEST_F(LoggingJsonTest, LogFormatJsonExtra) {
+  using formats::literals::operator""_json;
+
+  // Note: this is a golden test. The order and content of tags is stable, which
+  // is an implementation detail, but it makes this test possible. If the order
+  // or content of tags change, this test should be fixed to reflect the
+  // changes.
+  constexpr std::string_view kExpectedPattern =
+      R"({)"
+      R"("timestamp":"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}",)"
+      R"("level":"[A-Z]+",)"
+      R"("module":"[\w\d ():./]+",)"
+      R"("task_id":"[0-9A-F]+",)"
+      R"("thread_id":"0x[0-9A-F]+",)"
+      R"("text":"",)"
+      R"("json1":{"a":"foo"},)"
+      R"("json2":{"b":"bar"})"
+      R"(})"
+      R"(\n)";
+  LOG_CRITICAL() << logging::LogExtra{{"json1", R"({"a": "foo"})"_json}}
+                 << logging::LogExtra{{"json2", R"({"b": "bar"})"_json}};
+  logging::LogFlush();
+  EXPECT_TRUE(
+      utils::regex_match(GetStreamString(), utils::regex(kExpectedPattern)))
+      << GetStreamString();
+}
+
 TEST_F(LoggingTest, FloatingPoint) {
   constexpr float f = 3.1415F;
   EXPECT_EQ(ToStringViaLogging(f), ToStringViaStreams(f));

core/src/logging/logging_test.hpp

@@ -136,4 +136,11 @@ class LoggingLtsvTest : public LoggingTestBase {
   }
 };
 
+class LoggingJsonTest : public LoggingTestBase {
+ protected:
+  LoggingJsonTest() : LoggingTestBase(logging::Format::kJson) {
+    SetDefaultLogger(GetStreamLogger());
+  }
+};
+
 USERVER_NAMESPACE_END

core/src/tracing/span_opentracing.cpp

@@ -42,22 +42,32 @@ constexpr utils::TrivialBiMap kGetOpentracingTags = [](auto selector) {
 };
 
 struct LogExtraValueVisitor {
-  std::string string_value;
+  formats::json::StringBuilder& builder;
 
-  void operator()(const std::string& val) { string_value = val; }
+  void operator()(const std::string& val) {
+    builder.Key("value");
+    builder.WriteString(val);
+  }
+
+  void operator()(int val) {
+    builder.Key("value");
+    builder.WriteString(std::to_string(val));
+  }
 
-  void operator()(int val) { string_value = std::to_string(val); }
+  void operator()(const logging::JsonString& val) {
+    builder.Key("value");
+    builder.WriteRawString(val.Value());
+  }
 };
 
 void GetTagObject(formats::json::StringBuilder& builder, std::string_view key,
                   const logging::LogExtra::Value& value,
                   std::string_view type) {
   const formats::json::StringBuilder::ObjectGuard guard(builder);
-  LogExtraValueVisitor visitor;
-  std::visit(visitor, value);
 
-  builder.Key("value");
-  builder.WriteString(visitor.string_value);
+  // writes `value`
+  LogExtraValueVisitor visitor{builder};
+  std::visit(visitor, value);
 
   builder.Key("type");
   builder.WriteString(type);

universal/include/userver/logging/format.hpp

@@ -10,7 +10,7 @@ USERVER_NAMESPACE_BEGIN
 namespace logging {
 
 /// Log formats
-enum class Format { kTskv, kLtsv, kRaw };
+enum class Format { kTskv, kLtsv, kRaw, kJson };
 
 /// Parse Format enum from string
 Format FormatFromString(std::string_view format_str);

universal/include/userver/logging/impl/tag_writer.hpp

@@ -42,9 +42,13 @@ class TagWriter {
   template <typename T>
   void PutTag(TagKey key, const T& value);
 
+  void PutTag(TagKey key, const JsonString& value);
+
   template <typename T>
   void PutTag(RuntimeTagKey key, const T& value);
 
+  void PutTag(RuntimeTagKey key, const JsonString& value);
+
   // The tags must not be duplicated in other Put* calls.
   void PutLogExtra(const LogExtra& extra);
 
@@ -62,6 +66,8 @@ class TagWriter {
 
   void MarkValueEnd() noexcept;
 
+  void PutOptionalOpenCloseSeparator();
+
   LogHelper& lh_;
 };
 
@@ -88,14 +94,18 @@ USERVER_IMPL_CONSTEVAL TagKey::TagKey(const StringType& escaped_key)
 template <typename T>
 void TagWriter::PutTag(TagKey key, const T& value) {
   PutKey(key);
+  PutOptionalOpenCloseSeparator();
   lh_ << value;
+  PutOptionalOpenCloseSeparator();
   MarkValueEnd();
 }
 
 template <typename T>
 void TagWriter::PutTag(RuntimeTagKey key, const T& value) {
   PutKey(key);
+  PutOptionalOpenCloseSeparator();
   lh_ << value;
+  PutOptionalOpenCloseSeparator();
   MarkValueEnd();
 }
 

universal/include/userver/logging/json_string.hpp

@@ -0,0 +1,45 @@
+#pragma once
+
+/// @file userver/logging/json_string.hpp
+/// @brief @copybrief logging::JsonString
+
+#include <string>
+#include <string_view>
+
+#include <userver/formats/json/value.hpp>
+
+USERVER_NAMESPACE_BEGIN
+
+namespace logging {
+
+/// One line json string.
+class JsonString {
+ public:
+  /// @brief Constructs from provided json object.
+  /// The generated json string is an one line string.
+  JsonString(const formats::json::Value& value);
+
+  /// @brief Constructs from provided json string. It is the user's
+  /// responsibility to ensure that the input json string is valid.
+  /// New lines will be removed during construction.
+  explicit JsonString(std::string json) noexcept;
+
+  /// @brief Constructs "null"
+  JsonString() noexcept = default;
+
+  JsonString(JsonString&&) noexcept = default;
+  JsonString(const JsonString&) = default;
+
+  JsonString& operator=(JsonString&&) noexcept = default;
+  JsonString& operator=(const JsonString&) = default;
+
+  /// @brief Returns view to json
+  std::string_view Value() const;
+
+ private:
+  std::string json_;
+};
+
+}  // namespace logging
+
+USERVER_NAMESPACE_END

universal/include/userver/logging/log_extra.hpp

@@ -12,6 +12,7 @@
 
 #include <userver/compiler/select.hpp>
 #include <userver/logging/fwd.hpp>
+#include <userver/logging/json_string.hpp>
 #include <userver/utils/fast_pimpl.hpp>
 
 USERVER_NAMESPACE_BEGIN
@@ -32,7 +33,8 @@ class TagWriter;
 class LogExtra final {
  public:
   using Value = std::variant<std::string, int, long, long long, unsigned int,
-                             unsigned long, unsigned long long, float, double>;
+                             unsigned long, unsigned long long, float, double,
+                             JsonString>;
   using Key = std::string;
   using Pair = std::pair<Key, Value>;
 

universal/include/userver/logging/log_helper.hpp

@@ -146,8 +146,6 @@ class LogHelper final {
   /// Extends internal LogExtra
   LogHelper& operator<<(LogExtra&& extra) noexcept;
 
-  LogHelper& operator<<(const LogExtra::Value& value) noexcept;
-
   LogHelper& operator<<(Hex hex) noexcept;
 
   LogHelper& operator<<(HexShort hex) noexcept;