[k2] add trace as tag in log (#1361)

Author: astrophysik

runtime-light/stdlib/diagnostics/backtrace.h

@@ -8,6 +8,7 @@
 #include <cstdint>
 #include <expected>
 #include <format>
+#include <iterator>
 #include <ranges>
 #include <span>
 #include <type_traits>
@@ -67,11 +68,12 @@ struct std::formatter<std::invoke_result_t<decltype(kphp::diagnostic::backtrace_
 
   template<typename FmtContext>
   auto format(const addresses_t& addresses, FmtContext& ctx) const noexcept {
-    size_t level{};
-    for (const auto* addr : addresses) {
-      format_to(ctx.out(), "# {} : {:p}\n", level++, addr);
+    format_to(ctx.out(), "[");
+    if (!addresses.empty()) {
+      std::ranges::for_each(addresses | std::views::take(addresses.size() - 1), [&ctx](void* addr) noexcept { format_to(ctx.out(), "\"{:p}\", ", addr); });
+      format_to(ctx.out(), "\"{:p}\"", *std::prev(addresses.end()));
     }
-
+    format_to(ctx.out(), "]");
     return ctx.out();
   }
 };

runtime-light/utils/logs.h

@@ -10,6 +10,7 @@
 #include <optional>
 #include <source_location>
 #include <span>
+#include <string_view>
 #include <type_traits>
 #include <utility>
 
@@ -42,28 +43,37 @@ enum class level : size_t { error = 1, warn, info, debug, trace };
 
 template<typename... Args>
 void log(level level, std::optional<std::span<void* const>> trace, std::format_string<impl::wrapped_arg_t<Args>...> fmt, Args&&... args) noexcept {
-  static constexpr size_t LOG_BUFFER_SIZE = 1024UZ * 4UZ;
   if (std::to_underlying(level) > k2::log_level_enabled()) {
     return;
   }
 
+  static constexpr size_t LOG_BUFFER_SIZE = 512UZ;
   std::array<char, LOG_BUFFER_SIZE> log_buffer;
   auto [out, size]{std::format_to_n<decltype(log_buffer.data()), impl::wrapped_arg_t<Args>...>(log_buffer.data(), log_buffer.size() - 1, fmt,
                                                                                                impl::wrap_log_argument(std::forward<Args>(args))...)};
-  if (trace.has_value()) {
-    if (auto backtrace_symbols{kphp::diagnostic::backtrace_symbols(*trace)}; !backtrace_symbols.empty()) {
-      const auto [trace_out, trace_size]{std::format_to_n(out, std::distance(out, log_buffer.end()) - 1, "\nBacktrace\n{}", backtrace_symbols)};
-      out = trace_out;
-      size += trace_size;
-    } else if (auto backtrace_addresses{kphp::diagnostic::backtrace_addresses(*trace)}; !backtrace_addresses.empty()) {
-      const auto [trace_out, trace_size]{std::format_to_n(out, std::distance(out, log_buffer.end()) - 1, "\nBacktrace\n{}", backtrace_addresses)};
-      out = trace_out;
-      size += trace_size;
-    }
+  *out = '\0';
+  auto message{std::string_view{log_buffer.data(), static_cast<std::string_view::size_type>(size)}};
+  if (!trace.has_value()) {
+    k2::log(std::to_underlying(level), message, std::nullopt);
+    return;
   }
 
-  *out = '\0';
-  k2::log(std::to_underlying(level), std::string_view{log_buffer.data(), static_cast<std::string_view::size_type>(size)}, std::nullopt);
+  static constexpr std::string_view backtrace_key = "trace";
+  static constexpr size_t BACKTRACE_BUFFER_SIZE = 1024UZ * 4UZ;
+  std::array<char, BACKTRACE_BUFFER_SIZE> backtrace_buffer;
+  std::string_view backtrace{"[]"};
+  if (auto backtrace_symbols{kphp::diagnostic::backtrace_symbols(*trace)}; !backtrace_symbols.empty()) {
+    const auto [trace_out, trace_size]{std::format_to_n(backtrace_buffer.data(), backtrace_buffer.size() - 1, "\n{}", backtrace_symbols)};
+    *trace_out = '\0';
+    backtrace = std::string_view{backtrace_buffer.data(), static_cast<std::string_view::size_type>(trace_size)};
+  } else if (auto backtrace_addresses{kphp::diagnostic::backtrace_addresses(*trace)}; !backtrace_addresses.empty()) {
+    const auto [trace_out, trace_size]{std::format_to_n(backtrace_buffer.data(), backtrace_buffer.size() - 1, "{}", backtrace_addresses)};
+    *trace_out = '\0';
+    backtrace = std::string_view{backtrace_buffer.data(), static_cast<std::string_view::size_type>(trace_size)};
+  }
+  std::array<k2::LogTaggedEntry, 1> tagged_entries{
+      {k2::LogTaggedEntry{.key = backtrace_key.data(), .value = backtrace.data(), .key_len = backtrace_key.size(), .value_len = backtrace.size()}}};
+  k2::log(std::to_underlying(level), message, std::span(tagged_entries.data(), tagged_entries.size()));
 }
 
 template<typename... Args>

tests/python/lib/file_utils.py

@@ -3,6 +3,7 @@
 import re
 import sys
 import shutil
+import time
 
 _SUPPORTED_PHP_VERSIONS = ["php7.4", "php8", "php8.1", "php8.2", "php8.3"]
 
@@ -120,5 +121,13 @@ def search_php_bin(php_version: str):
 
     return None
 
+
 def search_k2_bin():
     return os.getenv("K2_BIN")
+
+
+def wait_for_file_creation(file_path, check_interval=0.1, attempts=20):
+    for i in range(attempts):
+        if os.path.exists(file_path):
+            break
+        time.sleep(check_interval)

tests/python/lib/k2_server.py

@@ -39,8 +39,15 @@ def start(self, start_msgs=None):
         else:
             start_msgs = start_msgs or []
             start_msgs.append("Starting to accept clients.")
+
         super(K2Server, self).start(start_msgs)
 
+        if self._is_json_log_enabled():
+            self.assert_json_log_tags(expect=[
+                {"msg": "Starting to accept clients.", "tags": set()}
+            ])
+
+
     def stop(self):
         super(K2Server, self).stop()
 

tests/python/lib/web_server.py

@@ -5,6 +5,7 @@
 from .engine import Engine
 from .http_client import send_http_request, send_http_request_raw
 from .port_generator import get_port
+from .file_utils import wait_for_file_creation
 
 
 class WebServer(Engine):
@@ -23,11 +24,11 @@ def __init__(self, web_server_bin, working_dir, options=None):
         self._json_log_file = None
         self._json_logs = []
 
-
     def start(self, start_msgs=None):
         super(WebServer, self).start(start_msgs)
         self._json_logs = []
         if (self._json_log_file is not None):
+            wait_for_file_creation(self._json_log_file)
             self._json_log_file_read_fd = open(self._json_log_file, 'r')
 
     def stop(self):
@@ -91,6 +92,36 @@ def _read_new_json_logs(self):
     def _process_json_log(self, log_record):
         return log_record
 
+    def assert_json_log_tags(self, expect, message="Can't wait expected json log", timeout=60):
+        """
+        Check web server json log contains tags
+        :param expect: Expected json record
+        :param message: Error message in case of failure
+        :param timeout: Json records waiting time
+        """
+        start = time.time()
+        expected_records = expect[:]
+
+        while expected_records:
+            self._assert_availability()
+            self._read_new_json_logs()
+            self._json_logs = list(filter(None, self._json_logs))
+            for index, json_log_record in enumerate(self._json_logs):
+                if not expected_records:
+                    return
+                expected_record = expected_records[0]
+                expected_msg = expected_record["msg"]
+                got_msg = json_log_record["msg"]
+                if re.search(expected_msg, got_msg):
+                    if expected_record["tags"].issubset(json_log_record.keys()):
+                        expected_records.pop(0)
+                        self._json_logs[index] = None
+
+            time.sleep(0.05)
+            if time.time() - start > timeout:
+                expected_str = json.dumps(obj=expected_records, indent=2)
+                raise RuntimeError("{}; Missed messages: {}".format(message, expected_str))
+
     def assert_json_log(self, expect, message="Can't wait expected json log", timeout=60):
         """
         Check kphp server json log

tests/python/tests/conftest.py

@@ -1,4 +1,4 @@
 import os
 import pytest
 
-from python.lib.conftest_impl import skip_k2_unsupported_test, skip_k2_unsupported_test_suite
+from python.lib.conftest_impl import skip_k2_unsupported_test, skip_k2_unsupported_test_suite, skip_kphp_unsupported_test, skip_kphp_unsupported_test_suite

tests/python/tests/json_logs/test_warnings.py

@@ -1,16 +1,31 @@
+import os
 import socket
 import pytest
 
 from python.lib.testcase import WebServerAutoTestCase
 from python.lib.kphp_server import KphpServer
 
 
-@pytest.mark.k2_skip_suite
 class TestJsonLogsWarnings(WebServerAutoTestCase):
     @classmethod
     def extra_class_setup(cls):
         cls.web_server.ignore_log_errors()
+        if cls.should_use_k2():
+            cls.web_server.update_options({"--log-file": os.path.join(cls.web_server._working_dir, "data/log-file")})
 
+    @pytest.mark.kphp_skip
+    def test_warning_backtrace(self):
+        resp = self.web_server.http_post(
+            json=[
+                {"op": "warning", "msg": "hello"},
+            ])
+        self.assertEqual(resp.text, "ok")
+        self.web_server.assert_json_log_tags(
+            expect=[
+                {"msg": "hello", "tags": {"trace"}}
+            ])
+
+    @pytest.mark.k2_skip
     def test_warning_no_context(self):
         resp = self.web_server.http_post(
             json=[
@@ -24,6 +39,7 @@ def test_warning_no_context(self):
                 {"version": 0, "hostname": socket.gethostname(), "type": 2, "env": "", "msg": "world", "tags": {"uncaught": False}}
             ])
 
+    @pytest.mark.k2_skip
     def test_warning_with_special_chars(self):
         resp = self.web_server.http_post(json=[{"op": "warning", "msg": 'aaa"bbb"\nccc'}])
         self.assertEqual(resp.text, "ok")
@@ -33,6 +49,7 @@ def test_warning_with_special_chars(self):
                 "tags": {"uncaught": False}
             }])
 
+    @pytest.mark.k2_skip
     def test_warning_with_tags(self):
         resp = self.web_server.http_post(
             json=[
@@ -46,6 +63,7 @@ def test_warning_with_tags(self):
                 "tags": {"uncaught": False, "a": "b"}
             }])
 
+    @pytest.mark.k2_skip
     def test_warning_with_extra_info(self):
         resp = self.web_server.http_post(
             json=[
@@ -59,6 +77,7 @@ def test_warning_with_extra_info(self):
                 "tags": {"uncaught": False}, "extra_info": {"a": "b"}
             }])
 
+    @pytest.mark.k2_skip
     def test_warning_with_env(self):
         resp = self.web_server.http_post(
             json=[
@@ -69,6 +88,7 @@ def test_warning_with_env(self):
         self.web_server.assert_json_log(
             expect=[{"version": 0, "hostname": socket.gethostname(), "type": 2, "msg": "aaa", "env": "abc", "tags": {"uncaught": False}}])
 
+    @pytest.mark.k2_skip
     def test_warning_with_env_special_chars(self):
         resp = self.web_server.http_post(
             json=[
@@ -79,6 +99,7 @@ def test_warning_with_env_special_chars(self):
         self.web_server.assert_json_log(
             expect=[{"version": 0, "hostname": socket.gethostname(), "type": 2, "msg": "aaa", "env": "a b c/d\\e?f", "tags": {"uncaught": False}}])
 
+    @pytest.mark.k2_skip
     def test_warning_with_long_env(self):
         resp = self.web_server.http_post(
             json=[
@@ -89,6 +110,7 @@ def test_warning_with_long_env(self):
         self.web_server.assert_json_log(
             expect=[{"version": 0, "hostname": socket.gethostname(), "type": 2, "msg": "aaa", "env": "", "tags": {"uncaught": False}}])
 
+    @pytest.mark.k2_skip
     def test_warning_with_full_context(self):
         resp = self.web_server.http_post(
             json=[
@@ -102,6 +124,7 @@ def test_warning_with_full_context(self):
                 "tags": {"uncaught": False, "a": "b"}, "extra_info": {"c": "d"}
             }])
 
+    @pytest.mark.k2_skip
     def test_warning_override_context(self):
         resp = self.web_server.http_post(
             json=[
@@ -132,6 +155,7 @@ def test_warning_override_context(self):
                 }
             ])
 
+    @pytest.mark.k2_skip
     def test_warning_vector_context(self):
         resp = self.web_server.http_post(
             json=[
@@ -145,6 +169,7 @@ def test_warning_vector_context(self):
                 "tags": {"uncaught": False, "0": "a", "1": "b"}, "extra_info": {"0": "c", "1": "d"}
             }], timeout=1)
 
+    @pytest.mark.k2_skip
     def test_error_tag_context(self):
         if isinstance(self.web_server, KphpServer):
             self.web_server.set_error_tag(100500)