diff --git a/runtime-light/stdlib/diagnostics/backtrace.h b/runtime-light/stdlib/diagnostics/backtrace.h index 712002318f..815adaa770 100644 --- a/runtime-light/stdlib/diagnostics/backtrace.h +++ b/runtime-light/stdlib/diagnostics/backtrace.h @@ -8,6 +8,7 @@ #include #include #include +#include #include #include #include @@ -67,11 +68,12 @@ struct std::formatter 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(); } }; diff --git a/runtime-light/utils/logs.h b/runtime-light/utils/logs.h index 3aa69143f3..d294ea1069 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 = 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))...)}; - 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(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(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)}; + } 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)}; + } + 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(tagged_entries.data(), tagged_entries.size())); } template diff --git a/tests/python/lib/file_utils.py b/tests/python/lib/file_utils.py index 967a5478a7..8088df2216 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"] @@ -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) 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() diff --git a/tests/python/lib/web_server.py b/tests/python/lib/web_server.py index 4db9ad1718..4986c2ed83 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,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 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 diff --git a/tests/python/tests/json_logs/test_warnings.py b/tests/python/tests/json_logs/test_warnings.py index c331069010..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 @@ -5,12 +6,26 @@ 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)