From ae8a48590c00a1ed9e051960e6f2dba403f3b71a Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Mon, 7 Jul 2025 14:17:14 +0300 Subject: [PATCH 01/22] add trace tag --- .idea/misc.xml | 3 ++ runtime-light/k2-platform/k2-header.h | 7 ++++ runtime-light/stdlib/diagnostics/backtrace.h | 19 --------- runtime-light/utils/logs.h | 36 ++++++++++------- tests/python/lib/web_server.py | 39 +++++++++++++++++++ tests/python/tests/json_logs/test_warnings.py | 25 +++++++++++- 6 files changed, 96 insertions(+), 33 deletions(-) diff --git a/.idea/misc.xml b/.idea/misc.xml index 9f883b3c5b..307dd609cd 100644 --- a/.idea/misc.xml +++ b/.idea/misc.xml @@ -1,5 +1,8 @@ + + diff --git a/runtime-light/k2-platform/k2-header.h b/runtime-light/k2-platform/k2-header.h index 6b32163045..c9beb0c8dc 100644 --- a/runtime-light/k2-platform/k2-header.h +++ b/runtime-light/k2-platform/k2-header.h @@ -313,6 +313,13 @@ void k2_free_descriptor(uint64_t descriptor); */ uint8_t k2_take_update(uint64_t* update_d); +struct LogKeyValuePair { + const char * key; + const char * value; + size_t key_len; + size_t value_len; +}; + /** * Represents a key-value pair that can be added to a log. * Each instance of this struct must contain valid, non-null pointers for both the key and the value. diff --git a/runtime-light/stdlib/diagnostics/backtrace.h b/runtime-light/stdlib/diagnostics/backtrace.h index 712002318f..4ab690f72c 100644 --- a/runtime-light/stdlib/diagnostics/backtrace.h +++ b/runtime-light/stdlib/diagnostics/backtrace.h @@ -57,25 +57,6 @@ inline auto backtrace_symbols(std::span addresses) noexcept { } // namespace kphp::diagnostic -template<> -struct std::formatter>> { - using addresses_t = std::invoke_result_t>; - template - constexpr auto parse(ParseContext& ctx) const noexcept { - return ctx.begin(); - } - - template - 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); - } - - return ctx.out(); - } -}; - template<> struct std::formatter>> { using symbols_info_t = std::invoke_result_t>; diff --git a/runtime-light/utils/logs.h b/runtime-light/utils/logs.h index 3aa69143f3..b8983c37af 100644 --- a/runtime-light/utils/logs.h +++ b/runtime-light/utils/logs.h @@ -10,6 +10,7 @@ #include #include #include +#include #include #include @@ -42,28 +43,37 @@ enum class level : size_t { error = 1, warn, info, debug, trace }; template void log(level level, std::optional> trace, std::format_string...> 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 = 512; std::array log_buffer; auto [out, size]{std::format_to_n...>(log_buffer.data(), log_buffer.size() - 1, fmt, impl::wrap_log_argument(std::forward(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::span(log_buffer.data(), size + 1)}; + 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(size)}, std::nullopt); + static constexpr std::string_view backtrace_key = "trace"; + static constexpr size_t BACKTRACE_BUFFER_SIZE = 1024UZ * 4UZ; + std::array 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(trace_size + 1)}; + } 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(trace_size + 1)}; + } + std::array kv_pairs = {{ + k2::LogKeyValuePair{.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(kv_pairs.data(), kv_pairs.size())); } template diff --git a/tests/python/lib/web_server.py b/tests/python/lib/web_server.py index 4db9ad1718..5c5cf318ad 100644 --- a/tests/python/lib/web_server.py +++ b/tests/python/lib/web_server.py @@ -28,6 +28,7 @@ def start(self, start_msgs=None): super(WebServer, self).start(start_msgs) self._json_logs = [] if (self._json_log_file is not None): + time.sleep(1.0 / 1e1) self._json_log_file_read_fd = open(self._json_log_file, 'r') def stop(self): @@ -91,6 +92,42 @@ 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[:] + print(expected_records) + + 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): + expected_record_copy = expected_record.copy() + expected_record_copy["msg"] = "" + json_log_record_copy = json_log_record.copy() + json_log_record_copy["msg"] = "" + print("match") + if set(expected_record_copy.keys()).issubset(json_log_record_copy.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 @@ -100,6 +137,7 @@ def assert_json_log(self, expect, message="Can't wait expected json log", timeou """ start = time.time() expected_records = expect[:] + print(expected_records) while expected_records: self._assert_availability() @@ -116,6 +154,7 @@ def assert_json_log(self, expect, message="Can't wait expected json log", timeou expected_record_copy["msg"] = "" json_log_record_copy = json_log_record.copy() json_log_record_copy["msg"] = "" + print("match") if expected_record_copy == json_log_record_copy: expected_records.pop(0) self._json_logs[index] = None diff --git a/tests/python/tests/json_logs/test_warnings.py b/tests/python/tests/json_logs/test_warnings.py index c331069010..a37df1ab72 100644 --- a/tests/python/tests/json_logs/test_warnings.py +++ b/tests/python/tests/json_logs/test_warnings.py @@ -5,12 +5,25 @@ 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": "log-file"}) + 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", "trace": ""} + ]) + + @pytest.mark.k2_skip def test_warning_no_context(self): resp = self.web_server.http_post( json=[ @@ -24,6 +37,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 +47,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 +61,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 +75,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 +86,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 +97,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 +108,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 +122,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 +153,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 +167,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) From 105e92efd89139c22c2d35318020dd1cf713259c Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Mon, 7 Jul 2025 14:17:37 +0300 Subject: [PATCH 02/22] remove misc --- .idea/misc.xml | 3 --- 1 file changed, 3 deletions(-) diff --git a/.idea/misc.xml b/.idea/misc.xml index 307dd609cd..9f883b3c5b 100644 --- a/.idea/misc.xml +++ b/.idea/misc.xml @@ -1,8 +1,5 @@ - - From 9b8094cb3b058f986eade5984f58abbd42e95080 Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Mon, 7 Jul 2025 14:19:00 +0300 Subject: [PATCH 03/22] format file --- runtime-light/k2-platform/k2-header.h | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/runtime-light/k2-platform/k2-header.h b/runtime-light/k2-platform/k2-header.h index c9beb0c8dc..d9e01248fa 100644 --- a/runtime-light/k2-platform/k2-header.h +++ b/runtime-light/k2-platform/k2-header.h @@ -314,8 +314,8 @@ void k2_free_descriptor(uint64_t descriptor); uint8_t k2_take_update(uint64_t* update_d); struct LogKeyValuePair { - const char * key; - const char * value; + const char* key; + const char* value; size_t key_len; size_t value_len; }; From fb39ae1896c390a76df39730ad01a16448ee1fd8 Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Mon, 7 Jul 2025 14:27:24 +0300 Subject: [PATCH 04/22] rewrite api --- runtime-light/utils/logs.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/runtime-light/utils/logs.h b/runtime-light/utils/logs.h index b8983c37af..d7fc4b812b 100644 --- a/runtime-light/utils/logs.h +++ b/runtime-light/utils/logs.h @@ -52,7 +52,7 @@ void log(level level, std::optional> trace, std::format_s auto [out, size]{std::format_to_n...>(log_buffer.data(), log_buffer.size() - 1, fmt, impl::wrap_log_argument(std::forward(args))...)}; *out = '\0'; - auto message{std::span(log_buffer.data(), size + 1)}; + auto message{std::string_view{log_buffer.data(), static_cast(size + 1)}}; if (!trace.has_value()) { k2::log(std::to_underlying(level), message, std::nullopt); return; From 4de63b3ff30697a2b0a6c0a2c9c866b21a936ab3 Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Mon, 7 Jul 2025 14:30:48 +0300 Subject: [PATCH 05/22] small fix --- tests/python/lib/web_server.py | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/tests/python/lib/web_server.py b/tests/python/lib/web_server.py index 5c5cf318ad..3f9ec0b6c3 100644 --- a/tests/python/lib/web_server.py +++ b/tests/python/lib/web_server.py @@ -28,7 +28,7 @@ def start(self, start_msgs=None): super(WebServer, self).start(start_msgs) self._json_logs = [] if (self._json_log_file is not None): - time.sleep(1.0 / 1e1) + time.sleep(0.1) self._json_log_file_read_fd = open(self._json_log_file, 'r') def stop(self): @@ -137,7 +137,6 @@ def assert_json_log(self, expect, message="Can't wait expected json log", timeou """ start = time.time() expected_records = expect[:] - print(expected_records) while expected_records: self._assert_availability() @@ -154,7 +153,6 @@ def assert_json_log(self, expect, message="Can't wait expected json log", timeou expected_record_copy["msg"] = "" json_log_record_copy = json_log_record.copy() json_log_record_copy["msg"] = "" - print("match") if expected_record_copy == json_log_record_copy: expected_records.pop(0) self._json_logs[index] = None From fa5c8353095f80b692480d5adc6e69831656b74c Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Mon, 7 Jul 2025 15:02:55 +0300 Subject: [PATCH 06/22] small fix --- runtime-light/utils/logs.h | 2 ++ 1 file changed, 2 insertions(+) diff --git a/runtime-light/utils/logs.h b/runtime-light/utils/logs.h index d7fc4b812b..936b87f785 100644 --- a/runtime-light/utils/logs.h +++ b/runtime-light/utils/logs.h @@ -70,6 +70,8 @@ void log(level level, std::optional> trace, std::format_s 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(trace_size + 1)}; + } else { + backtrace = "can't resolve trace"; } std::array kv_pairs = {{ k2::LogKeyValuePair{.key = backtrace_key.data(), .value = backtrace.data(), .key_len = backtrace_key.size(), .value_len = backtrace.size()}}}; From 9195775d6383d3b9cd739936c2e45f903f442036 Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Mon, 7 Jul 2025 17:45:25 +0300 Subject: [PATCH 07/22] format file --- runtime-light/utils/logs.h | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/runtime-light/utils/logs.h b/runtime-light/utils/logs.h index 936b87f785..27abc16f1b 100644 --- a/runtime-light/utils/logs.h +++ b/runtime-light/utils/logs.h @@ -73,8 +73,8 @@ void log(level level, std::optional> trace, std::format_s } else { backtrace = "can't resolve trace"; } - std::array kv_pairs = {{ - k2::LogKeyValuePair{.key = backtrace_key.data(), .value = backtrace.data(), .key_len = backtrace_key.size(), .value_len = backtrace.size()}}}; + std::array kv_pairs = { + {k2::LogKeyValuePair{.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(kv_pairs.data(), kv_pairs.size())); } From aa5c1b53a92a6837fe9898c6cf2dcc5716638f4e Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Tue, 8 Jul 2025 15:22:59 +0300 Subject: [PATCH 08/22] fix tests --- tests/python/lib/web_server.py | 7 +------ tests/python/tests/json_logs/test_warnings.py | 3 ++- 2 files changed, 3 insertions(+), 7 deletions(-) diff --git a/tests/python/lib/web_server.py b/tests/python/lib/web_server.py index 3f9ec0b6c3..58d41c1d88 100644 --- a/tests/python/lib/web_server.py +++ b/tests/python/lib/web_server.py @@ -114,12 +114,7 @@ def assert_json_log_tags(self, expect, message="Can't wait expected json log", t expected_msg = expected_record["msg"] got_msg = json_log_record["msg"] if re.search(expected_msg, got_msg): - expected_record_copy = expected_record.copy() - expected_record_copy["msg"] = "" - json_log_record_copy = json_log_record.copy() - json_log_record_copy["msg"] = "" - print("match") - if set(expected_record_copy.keys()).issubset(json_log_record_copy.keys()): + if expected_record["tags"].issubset(json_log_record.keys()): expected_records.pop(0) self._json_logs[index] = None diff --git a/tests/python/tests/json_logs/test_warnings.py b/tests/python/tests/json_logs/test_warnings.py index a37df1ab72..a28b5ea741 100644 --- a/tests/python/tests/json_logs/test_warnings.py +++ b/tests/python/tests/json_logs/test_warnings.py @@ -12,6 +12,7 @@ def extra_class_setup(cls): if cls.should_use_k2(): cls.web_server.update_options({"--log-file": "log-file"}) + @pytest.mark.kphp_skip def test_warning_backtrace(self): resp = self.web_server.http_post( json=[ @@ -20,7 +21,7 @@ def test_warning_backtrace(self): self.assertEqual(resp.text, "ok") self.web_server.assert_json_log_tags( expect=[ - {"msg": "hello", "trace": ""} + {"msg": "hello", "tags": {"trace"}} ]) @pytest.mark.k2_skip From 5bbd8c71c396859a99c8c53043b6a43d3f4c331a Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Tue, 8 Jul 2025 15:25:30 +0300 Subject: [PATCH 09/22] fix doc message --- runtime-light/k2-platform/k2-header.h | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/runtime-light/k2-platform/k2-header.h b/runtime-light/k2-platform/k2-header.h index d9e01248fa..a935a33ded 100644 --- a/runtime-light/k2-platform/k2-header.h +++ b/runtime-light/k2-platform/k2-header.h @@ -313,6 +313,14 @@ void k2_free_descriptor(uint64_t descriptor); */ uint8_t k2_take_update(uint64_t* update_d); +/** + * Represents a key-value pair that can be added to a log. + * Each instance of this struct must contain valid, non-null pointers for both the key and the value. + * The lengths of the key and value are specified by `key_len` and `value_len`, respectively. + * + * If an instance is intended to represent only a key without an associated value, + * the `value` pointer should point to an empty string (""), and `value_len` should be set to zero. + */ struct LogKeyValuePair { const char* key; const char* value; From fc69d4e3ed63c3a5125936c80caadf9bf722a679 Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Tue, 8 Jul 2025 16:09:58 +0300 Subject: [PATCH 10/22] fix conftest.py --- tests/python/tests/conftest.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/python/tests/conftest.py b/tests/python/tests/conftest.py index 3184e57a6a..4af7ee6c4a 100644 --- a/tests/python/tests/conftest.py +++ b/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 From b3ef3e8c8679ee979b1218cdb28b1a344b2de3a0 Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Tue, 8 Jul 2025 17:54:27 +0300 Subject: [PATCH 11/22] fix file creation wait --- tests/python/lib/file_utils.py | 5 +++++ tests/python/lib/web_server.py | 4 ++-- 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/tests/python/lib/file_utils.py b/tests/python/lib/file_utils.py index 967a5478a7..73dd068616 100644 --- a/tests/python/lib/file_utils.py +++ b/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"] @@ -122,3 +123,7 @@ def search_php_bin(php_version: str): def search_k2_bin(): return os.getenv("K2_BIN") + +def wait_for_file_creation(file_path, check_interval=0.1): + while not os.path.exists(file_path): + time.sleep(check_interval) \ No newline at end of file diff --git a/tests/python/lib/web_server.py b/tests/python/lib/web_server.py index 58d41c1d88..aa9003d8b6 100644 --- a/tests/python/lib/web_server.py +++ b/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,12 +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): - time.sleep(0.1) + wait_for_file_creation(self._json_log_file) self._json_log_file_read_fd = open(self._json_log_file, 'r') def stop(self): From bd3fb86a01c6fb14a6cf93c5cf45dcc9bae52a7a Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Wed, 9 Jul 2025 12:17:32 +0300 Subject: [PATCH 12/22] change log file path --- tests/python/tests/json_logs/test_warnings.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/tests/python/tests/json_logs/test_warnings.py b/tests/python/tests/json_logs/test_warnings.py index a28b5ea741..3dfdd9a00c 100644 --- a/tests/python/tests/json_logs/test_warnings.py +++ b/tests/python/tests/json_logs/test_warnings.py @@ -1,3 +1,4 @@ +import os import socket import pytest @@ -10,7 +11,7 @@ class TestJsonLogsWarnings(WebServerAutoTestCase): def extra_class_setup(cls): cls.web_server.ignore_log_errors() if cls.should_use_k2(): - cls.web_server.update_options({"--log-file": "log-file"}) + 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): From 188488e794c9eb7d7f21edeb2ccb4149aabdb08b Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Wed, 9 Jul 2025 13:31:22 +0300 Subject: [PATCH 13/22] fix tests --- tests/python/lib/k2_server.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/tests/python/lib/k2_server.py b/tests/python/lib/k2_server.py index 4bb0a70d79..07a6592c91 100644 --- a/tests/python/lib/k2_server.py +++ b/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() From d72079003030a325d7a1959c47095619cee5c976 Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Fri, 11 Jul 2025 16:53:35 +0300 Subject: [PATCH 14/22] small fix --- runtime-light/k2-platform/k2-header.h | 15 --------------- tests/python/lib/file_utils.py | 10 +++++++--- 2 files changed, 7 insertions(+), 18 deletions(-) diff --git a/runtime-light/k2-platform/k2-header.h b/runtime-light/k2-platform/k2-header.h index a935a33ded..6b32163045 100644 --- a/runtime-light/k2-platform/k2-header.h +++ b/runtime-light/k2-platform/k2-header.h @@ -328,21 +328,6 @@ struct LogKeyValuePair { size_t value_len; }; -/** - * Represents a key-value pair that can be added to a log. - * Each instance of this struct must contain valid, non-null pointers for both the key and the value. - * The lengths of the key and value are specified by `key_len` and `value_len`, respectively. - * - * If an instance is intended to represent only a key without an associated value, - * the `value` pointer should point to an empty string (""), and `value_len` should be set to zero. - */ -struct LogKeyValuePair { - const char* key; - const char* value; - size_t key_len; - size_t value_len; -}; - /** * Writes a structured log message. Only UTF-8 encoded strings are supported. * diff --git a/tests/python/lib/file_utils.py b/tests/python/lib/file_utils.py index 73dd068616..8088df2216 100644 --- a/tests/python/lib/file_utils.py +++ b/tests/python/lib/file_utils.py @@ -121,9 +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): - while not os.path.exists(file_path): - time.sleep(check_interval) \ No newline at end of file + +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) From 1eb056e04cbfc8d14bf786631d6a92c7d354ca34 Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Mon, 14 Jul 2025 16:43:23 +0300 Subject: [PATCH 15/22] save addresses as strings --- runtime-light/stdlib/diagnostics/backtrace.h | 22 ++++++++++++++++++++ runtime-light/utils/logs.h | 4 ++-- 2 files changed, 24 insertions(+), 2 deletions(-) diff --git a/runtime-light/stdlib/diagnostics/backtrace.h b/runtime-light/stdlib/diagnostics/backtrace.h index 4ab690f72c..fe15426202 100644 --- a/runtime-light/stdlib/diagnostics/backtrace.h +++ b/runtime-light/stdlib/diagnostics/backtrace.h @@ -4,10 +4,12 @@ #pragma once +#include #include #include #include #include +#include #include #include #include @@ -57,6 +59,26 @@ inline auto backtrace_symbols(std::span addresses) noexcept { } // namespace kphp::diagnostic +template<> +struct std::formatter>> { + using addresses_t = std::invoke_result_t>; + template + constexpr auto parse(ParseContext& ctx) const noexcept { + return ctx.begin(); + } + + template + auto format(const addresses_t& addresses, FmtContext& ctx) const noexcept { + format_to(ctx.out(), "["); + if (!addresses.empty()) { + std::for_each(addresses.begin(), std::prev(addresses.end()), [&](void* addr) { format_to(ctx.out(), "\"{:p}\", ", addr); }); + format_to(ctx.out(), "\"{:p}\"", *std::prev(addresses.end())); + } + format_to(ctx.out(), "]"); + return ctx.out(); + } +}; + template<> struct std::formatter>> { using symbols_info_t = std::invoke_result_t>; diff --git a/runtime-light/utils/logs.h b/runtime-light/utils/logs.h index 27abc16f1b..22503f9f1a 100644 --- a/runtime-light/utils/logs.h +++ b/runtime-light/utils/logs.h @@ -73,8 +73,8 @@ void log(level level, std::optional> trace, std::format_s } else { backtrace = "can't resolve trace"; } - std::array kv_pairs = { - {k2::LogKeyValuePair{.key = backtrace_key.data(), .value = backtrace.data(), .key_len = backtrace_key.size(), .value_len = backtrace.size()}}}; + std::array kv_pairs = { + {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(kv_pairs.data(), kv_pairs.size())); } From 7785d5e068e42a50f3bddce22a9291afd3dcfaef Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Mon, 14 Jul 2025 16:48:17 +0300 Subject: [PATCH 16/22] small fixes --- runtime-light/utils/logs.h | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/runtime-light/utils/logs.h b/runtime-light/utils/logs.h index 22503f9f1a..4863a78e71 100644 --- a/runtime-light/utils/logs.h +++ b/runtime-light/utils/logs.h @@ -52,7 +52,7 @@ void log(level level, std::optional> trace, std::format_s auto [out, size]{std::format_to_n...>(log_buffer.data(), log_buffer.size() - 1, fmt, impl::wrap_log_argument(std::forward(args))...)}; *out = '\0'; - auto message{std::string_view{log_buffer.data(), static_cast(size + 1)}}; + auto message{std::string_view{log_buffer.data(), static_cast(size)}}; if (!trace.has_value()) { k2::log(std::to_underlying(level), message, std::nullopt); return; @@ -65,11 +65,11 @@ void log(level level, std::optional> trace, std::format_s 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(trace_size + 1)}; + backtrace = std::string_view{backtrace_buffer.data(), static_cast(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(trace_size + 1)}; + backtrace = std::string_view{backtrace_buffer.data(), static_cast(trace_size)}; } else { backtrace = "can't resolve trace"; } From ee45515627b18aca2cd6f94a7d1390b90bcfb834 Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Mon, 14 Jul 2025 16:49:31 +0300 Subject: [PATCH 17/22] format file --- runtime-light/utils/logs.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/runtime-light/utils/logs.h b/runtime-light/utils/logs.h index 4863a78e71..05251d8593 100644 --- a/runtime-light/utils/logs.h +++ b/runtime-light/utils/logs.h @@ -73,7 +73,7 @@ void log(level level, std::optional> trace, std::format_s } else { backtrace = "can't resolve trace"; } - std::array kv_pairs = { + std::array kv_pairs = { {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(kv_pairs.data(), kv_pairs.size())); } From 7ea658bb129e32c888451152d377ec16d7374c37 Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Mon, 14 Jul 2025 19:09:47 +0300 Subject: [PATCH 18/22] apply review --- runtime-light/stdlib/diagnostics/backtrace.h | 2 +- runtime-light/utils/logs.h | 6 +++--- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/runtime-light/stdlib/diagnostics/backtrace.h b/runtime-light/stdlib/diagnostics/backtrace.h index fe15426202..d90f1f5893 100644 --- a/runtime-light/stdlib/diagnostics/backtrace.h +++ b/runtime-light/stdlib/diagnostics/backtrace.h @@ -71,7 +71,7 @@ struct std::formatter> trace, std::format_s return; } - static constexpr size_t LOG_BUFFER_SIZE = 512; + static constexpr size_t LOG_BUFFER_SIZE = 512UZ; std::array log_buffer; auto [out, size]{std::format_to_n...>(log_buffer.data(), log_buffer.size() - 1, fmt, impl::wrap_log_argument(std::forward(args))...)}; @@ -73,9 +73,9 @@ void log(level level, std::optional> trace, std::format_s } else { backtrace = "can't resolve trace"; } - std::array kv_pairs = { + std::array 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(kv_pairs.data(), kv_pairs.size())); + k2::log(std::to_underlying(level), message, std::span(tagged_entries.data(), tagged_entries.size())); } template From dbf816cc1d6d44917c7cec9edfc29396e1a97cc0 Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Mon, 14 Jul 2025 19:14:50 +0300 Subject: [PATCH 19/22] remove less include --- runtime-light/stdlib/diagnostics/backtrace.h | 1 - 1 file changed, 1 deletion(-) diff --git a/runtime-light/stdlib/diagnostics/backtrace.h b/runtime-light/stdlib/diagnostics/backtrace.h index d90f1f5893..815adaa770 100644 --- a/runtime-light/stdlib/diagnostics/backtrace.h +++ b/runtime-light/stdlib/diagnostics/backtrace.h @@ -4,7 +4,6 @@ #pragma once -#include #include #include #include From 1bb14da6b114063e4f21862fdce6f27fe30d3e4e Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Tue, 15 Jul 2025 12:30:08 +0300 Subject: [PATCH 20/22] remove less print --- tests/python/lib/web_server.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/python/lib/web_server.py b/tests/python/lib/web_server.py index aa9003d8b6..4986c2ed83 100644 --- a/tests/python/lib/web_server.py +++ b/tests/python/lib/web_server.py @@ -101,7 +101,6 @@ def assert_json_log_tags(self, expect, message="Can't wait expected json log", t """ start = time.time() expected_records = expect[:] - print(expected_records) while expected_records: self._assert_availability() From 14279b2141b9835c8d956c3a0c7da11d9f877879 Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Tue, 15 Jul 2025 12:34:38 +0300 Subject: [PATCH 21/22] small fix --- runtime-light/utils/logs.h | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/runtime-light/utils/logs.h b/runtime-light/utils/logs.h index c2408a995a..bbb867d155 100644 --- a/runtime-light/utils/logs.h +++ b/runtime-light/utils/logs.h @@ -61,7 +61,7 @@ void log(level level, std::optional> trace, std::format_s static constexpr std::string_view backtrace_key = "trace"; static constexpr size_t BACKTRACE_BUFFER_SIZE = 1024UZ * 4UZ; std::array backtrace_buffer; - std::string_view backtrace; + 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'; @@ -70,8 +70,6 @@ void log(level level, std::optional> trace, std::format_s 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(trace_size)}; - } else { - backtrace = "can't resolve trace"; } std::array tagged_entries{ {k2::LogTaggedEntry{.key = backtrace_key.data(), .value = backtrace.data(), .key_len = backtrace_key.size(), .value_len = backtrace.size()}}}; From 2f675c4ce4f5b3d0da4c2359c45a1310b7001525 Mon Sep 17 00:00:00 2001 From: Vadim Sadokhov Date: Tue, 15 Jul 2025 12:56:31 +0300 Subject: [PATCH 22/22] small fix --- runtime-light/utils/logs.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/runtime-light/utils/logs.h b/runtime-light/utils/logs.h index bbb867d155..d294ea1069 100644 --- a/runtime-light/utils/logs.h +++ b/runtime-light/utils/logs.h @@ -61,7 +61,7 @@ void log(level level, std::optional> trace, std::format_s static constexpr std::string_view backtrace_key = "trace"; static constexpr size_t BACKTRACE_BUFFER_SIZE = 1024UZ * 4UZ; std::array backtrace_buffer; - std::string_view backtrace = "[]"; + 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';