feat components: boot logger

commit_hash:186dacb5820cf5cd80f98b15b723b0bc2924b868

Author: segoon

.mapping.json

@@ -665,6 +665,7 @@
   "core/functional_tests/basic_chaos/tests-nonchaos/handlers/test_log_request_headers.py":"taxi/uservices/userver/core/functional_tests/basic_chaos/tests-nonchaos/handlers/test_log_request_headers.py",
   "core/functional_tests/basic_chaos/tests-nonchaos/metrics/test_has_reopening_error_metric.py":"taxi/uservices/userver/core/functional_tests/basic_chaos/tests-nonchaos/metrics/test_has_reopening_error_metric.py",
   "core/functional_tests/basic_chaos/tests-nonchaos/middlewares/test_testsuite_middleware.py":"taxi/uservices/userver/core/functional_tests/basic_chaos/tests-nonchaos/middlewares/test_testsuite_middleware.py",
+  "core/functional_tests/basic_chaos/tests-nonchaos/test_boot_log.py":"taxi/uservices/userver/core/functional_tests/basic_chaos/tests-nonchaos/test_boot_log.py",
   "core/functional_tests/basic_chaos/tests-nonchaos/test_dynamic_debug_log.py":"taxi/uservices/userver/core/functional_tests/basic_chaos/tests-nonchaos/test_dynamic_debug_log.py",
   "core/functional_tests/basic_chaos/tests-restart/conftest.py":"taxi/uservices/userver/core/functional_tests/basic_chaos/tests-restart/conftest.py",
   "core/functional_tests/basic_chaos/tests-restart/test_restart.py":"taxi/uservices/userver/core/functional_tests/basic_chaos/tests-restart/test_restart.py",

core/functional_tests/basic_chaos/tests-nonchaos/test_boot_log.py

@@ -0,0 +1,147 @@
+import json
+
+import pytest
+
+from testsuite.daemons import spawn
+
+
+def default_stderr_handler(line: str):
+    pass
+
+
+@pytest.fixture(scope='session')
+def boot_log_path(service_tmpdir):
+    return str(service_tmpdir / 'boot.log')
+
+
+@pytest.fixture(scope='session')
+def enable_boot_logger(boot_log_path):
+    def patch_config(config_yaml, _config_vars) -> None:
+        config_yaml['components_manager']['boot-log-path'] = boot_log_path
+
+    return patch_config
+
+
+@pytest.fixture(scope='session')
+def break_logger_config(boot_log_path):
+    def patch_config(config_yaml, _config_vars) -> None:
+        config_yaml['components_manager']['components']['logging']['loggers']['default']['file_path'] = '/'
+
+    return patch_config
+
+
+@pytest.fixture
+def assert_service_boot_fails(
+    service_binary,
+    service_config_path_temp,
+    service_env,
+    create_daemon_scope,
+    ensure_daemon_started,
+    service_http_ping_url,
+):
+    async def func(stderr_handler=default_stderr_handler):
+        async with create_daemon_scope(
+            args=[
+                str(service_binary),
+                '--config',
+                str(service_config_path_temp),
+            ],
+            env=service_env,
+            ping_url=service_http_ping_url,
+            stderr_handler=stderr_handler,
+        ) as scope:
+            with pytest.raises((spawn.HealthCheckError, spawn.ExitCodeError)):
+                await ensure_daemon_started(scope)
+
+    return func
+
+
+def read_boot_log(path: str) -> list[dict[str, str | int]]:
+    with open(path) as ifile:
+        content = ifile.read()
+
+    logs = []
+    for line in content.splitlines():
+        line = line.strip()
+        if not line:
+            continue
+
+        try:
+            logs.append(json.loads(line))
+        except BaseException:
+            pytest.fail('Invalid JSON string in bool log: {line}')
+    return logs
+
+
+@pytest.mark.uservice_oneshot(config_hooks=['enable_boot_logger'])
+async def test_boot_ok(service_client, boot_log_path):
+    logs = read_boot_log(boot_log_path)
+
+    assert logs[0]['event_type'] == 'component_system_is_starting'
+
+    components = list(
+        map(lambda x: x['component_name'], filter(lambda x: x['event_type'] == 'component_is_starting', logs))
+    )
+
+    checked_components = {
+        'dns-client',
+        'http-client',
+        'logging',
+        'logging-configurator',
+        'manager-controller',
+        'os-signal-processor',
+        'server',
+        'statistics-storage',
+        'tests-control',
+        'testsuite-support',
+    }
+    assert checked_components.issubset(components)
+
+    assert logs[-1]['event_type'] == 'component_system_is_started'
+
+
+@pytest.mark.uservice_oneshot(config_hooks=['enable_boot_logger', 'break_logger_config'])
+async def test_boot_fail(
+    assert_service_boot_fails,
+    boot_log_path,
+):
+    await assert_service_boot_fails()
+
+    logs = read_boot_log(boot_log_path)
+    logging_events = list(filter(lambda x: x.get('component_name') == 'logging', logs))
+
+    # 'logging' component is at least created
+    assert logging_events[0]['event_type'] == 'component_is_starting'
+
+    # Boot failure may lead to crash, so the last log item event_type is anything, but 'component_system_is_started'
+    assert logs[-1]['event_type'] != 'component_system_is_started'
+
+
+@pytest.fixture(scope='session')
+def unix_socket_logger_with_truncate():
+    def patch_config(config_yaml, _config_vars) -> None:
+        config_yaml['components_manager']['components']['logging']['loggers']['unix'] = {
+            'file_path': 'unix:/path',
+            'truncate-on-start': True,
+        }
+
+    return patch_config
+
+
+@pytest.mark.uservice_oneshot(config_hooks=['unix_socket_logger_with_truncate'])
+async def test_unix_socket_with_truncate(
+    assert_service_boot_fails,
+    _service_logfile_path,
+):
+    stderr = bytes()
+
+    def handler(line: bytes):
+        nonlocal stderr
+        stderr += line
+
+    await assert_service_boot_fails(stderr_handler=handler)
+
+    expected_msg = (
+        "Cannot start component logging: truncate-on-start cannot be combined with unix socket path for logger 'unix'"
+    )
+    assert expected_msg in stderr.decode('utf-8')

core/functional_tests/signal_during_boot/tests/test_rotate_logs.py

@@ -17,6 +17,10 @@ async def check_ready():
     await sync.wait_until(check_ready)
 
 
+def stderr_handler(line: str):
+    pass
+
+
 async def test_boot_logs(
     service_binary,
     service_config_path_temp,
@@ -36,6 +40,7 @@ async def _checker(*, session, process) -> bool:
         ],
         health_check=_checker,
         env=service_env,
+        stderr_handler=stderr_handler,
     ) as scope:
         daemon = await ensure_daemon_started(scope)
 

core/src/components/component_context_impl.cpp

@@ -18,6 +18,7 @@
 #include <components/manager.hpp>
 #include <components/manager_config.hpp>
 #include <engine/task/task_processor.hpp>
+#include <logging/tp_logger_utils.hpp>
 
 USERVER_NAMESPACE_BEGIN
 
@@ -96,6 +97,21 @@ ComponentContextImpl::ComponentContextImpl(const Manager& manager, std::vector<s
         UINVARIANT(success, "Duplicate component names");
     }
 
+    if (!manager_.GetConfig().boot_log_path.empty()) {
+        logging::LoggerConfig config;
+        config.logger_name = "boot";
+        config.file_path = manager_.GetConfig().boot_log_path;
+        config.level = logging::Level::kTrace;
+        config.format = logging::Format::kJson;
+        config.truncate_on_start = true;
+        config.queue_overflow_behavior = logging::QueueOverflowBehavior::kBlock;
+
+        boot_logger_ = logging::impl::MakeTpLogger(config);
+    }
+
+    LOG_DEBUG() << "Starting component system";
+    EmitBootEvent(Event::kComponentSystemIsStarting);
+
     StartPrintAddingComponentsTask();
 }
 
@@ -104,6 +120,9 @@ RawComponentBase* ComponentContextImpl::AddComponent(
     const ComponentConfig& config,
     const ComponentAdderBase& adder
 ) {
+    LOG_DEBUG() << "Starting component " << name;
+    EmitBootEvent(Event::kStarting, {{"component_name", name}});
+
     auto& component_info = GetComponentInfo(*this, name);
     const LoadingComponentScope loading_component_scope(*this, component_info);
 
@@ -125,6 +144,10 @@ RawComponentBase* ComponentContextImpl::AddComponent(
             << fmt::format("\"{0}\" [label=\"{0}\n{1}\"]; ", name, compiler::GetTypeName(typeid(*component)))
             << component_info.GetDependencies();
     }
+
+    LOG_DEBUG() << "Started component " << name;
+    EmitBootEvent(Event::kStarted, {{"component_name", name}});
+
     return component;
 }
 
@@ -143,6 +166,9 @@ void ComponentContextImpl::OnAllComponentsLoaded() {
 
     // In case no exception flies out, the service is fully loaded at this point.
     service_lifetime_stage_ = ServiceLifetimeStage::kRunning;
+
+    LOG_INFO() << "All components loaded";
+    EmitBootEvent(Event::kComponentSystemIsStarted);
 }
 
 void ComponentContextImpl::OnGracefulShutdownStarted() {
@@ -372,6 +398,14 @@ void ComponentContextImpl::ProcessSingleComponentLifetimeStageSwitching(
         }
 
         LOG_DEBUG() << "Call " << params.stage_switch_handler_name << " for component '" << name << "'";
+        EmitBootEvent(
+            Event::kSwitching,
+            {
+                {"component_name", name},
+                {"stage_switch_handler_name", params.stage_switch_handler_name},
+            }
+        );
+
         (component_info.*params.stage_switch_handler)();
     } catch (const impl::StageSwitchingCancelledException& ex) {
         LOG_WARNING() << params.stage_switch_handler_name << " failed for component '" << name << "': " << ex;
@@ -442,6 +476,13 @@ RawComponentBase* ComponentContextImpl::DoFindComponent(std::string_view name, C
     LOG_DEBUG()
         << "Component '" << name << "' is not loaded yet, component '" << current_component.GetName()
         << "' is waiting for it to load";
+    EmitBootEvent(
+        Event::kWaitingForComponent,
+        {
+            {"component_name", current_component.GetName()},
+            {"dependency_name", name},
+        }
+    );
 
     const SearchingComponentScope finder(*this, current_component);
 
@@ -456,6 +497,14 @@ void ComponentContextImpl::AddDependency(ComponentInfo& dependency, ComponentInf
     }
 
     LOG_DEBUG() << "Resolving dependency " << current_component.GetName() << " -> " << dependency.GetName();
+    EmitBootEvent(
+        Event::kFindComponent,
+        {
+            {"component_name", current_component.GetName()},
+            {"dependency_name", dependency.GetName()},
+        }
+    );
+
     CheckForDependencyCycle(current_component, dependency, *data);
 
     current_component.AddItDependsOn(dependency);
@@ -522,6 +571,7 @@ void ComponentContextImpl::PrepareComponentLifetimeStageSwitching() {
 }
 
 void ComponentContextImpl::CancelComponentLifetimeStageSwitching() {
+    EmitBootEvent(Event::kLoadingIsCancelled);
     for (auto& component_item : components_) {
         component_item->SetStageSwitchingCancelled(true);
     }
@@ -580,6 +630,41 @@ void ComponentContextImpl::PrintAddingComponents() const {
     trace_plugin_.PrintStacksByComponentNames(ExtractNamesFromInfo(busy_components));
 }
 
+std::string_view ComponentContextImpl::ToString(Event event)
+{
+    switch (event) {
+        case Event::kComponentSystemIsStarting:
+            return "component_system_is_starting";
+        case Event::kStarting:
+            return "component_is_starting";
+        case Event::kStarted:
+            return "component_is_created";
+        case Event::kComponentSystemIsStarted:
+            return "component_system_is_started";
+        case Event::kLoadingIsCancelled:
+            return "loading_is_cancelled";
+        case Event::kSwitching:
+            return "component_is_switching_stage";
+        case Event::kWaitingForComponent:
+            return "waiting_for_component";
+        case Event::kFindComponent:
+            return "find_component";
+    }
+}
+
+void ComponentContextImpl::EmitBootEvent(Event event, logging::LogExtra log_extra) const {
+    if (!boot_logger_) {
+        return;
+    }
+
+    log_extra.Extend("event_type", std::string{ToString(event)});
+    LOG_INFO_TO(*boot_logger_) << log_extra;
+
+    if (event == Event::kComponentSystemIsStarted) {
+        boot_logger_->Flush();
+    }
+}
+
 }  // namespace components::impl
 
 USERVER_NAMESPACE_END

core/src/components/component_context_impl.hpp

@@ -175,7 +175,22 @@ class ComponentContextImpl {
     void StopPrintAddingComponentsTask();
     void PrintAddingComponents() const;
 
+    enum class Event {
+        kComponentSystemIsStarting,
+        kStarting,
+        kStarted,
+        kComponentSystemIsStarted,
+        kLoadingIsCancelled,
+        kSwitching,
+        kWaitingForComponent,
+        kFindComponent,
+    };
+    static std::string_view ToString(Event event);
+
+    void EmitBootEvent(Event event, logging::LogExtra log_extra = {}) const;
+
     const Manager& manager_;
+    logging::LoggerPtr boot_logger_;
 
     ComponentMap components_;
     std::atomic_flag components_load_cancelled_ ATOMIC_FLAG_INIT;

core/src/components/manager.cpp

@@ -440,8 +440,6 @@ void Manager::AddComponents(const ComponentList& component_list) {
 
     auto stop_time = std::chrono::steady_clock::now();
     load_duration_ = std::chrono::duration_cast<std::chrono::milliseconds>(stop_time - start_time);
-
-    LOG_INFO() << "All components loaded";
 }
 
 void Manager::AddComponentImpl(
@@ -459,14 +457,11 @@ void Manager::AddComponentImpl(
         return;
     }
 
-    LOG_DEBUG() << "Starting component " << name;
-
     auto* component = component_context_->AddComponent(name, config_it->second, adder);
     if (auto* signal_processor = dynamic_cast<os_signals::ProcessorComponent*>(component)) {
         const std::lock_guard<std::shared_timed_mutex> lock(context_mutex_);
         signal_processor_ = signal_processor;
     }
-    LOG_DEBUG() << "Started component " << name;
 }
 
 void Manager::ClearComponents() noexcept {

core/src/components/manager_config.cpp

@@ -143,6 +143,9 @@ additionalProperties: false
         description: 'dictionary of "component name": "options"'
         additionalProperties: true
         properties: {}
+    boot-log-path:
+        type: string
+        description: if non-empty, defines path to boot logs
     task_processors:
         type: object
         description: dictionary of task processors to create and their options
@@ -293,6 +296,7 @@ ManagerConfig Parse(const yaml_config::YamlConfig& value, formats::parse::To<Man
         );
     }
     config.components = yaml_config::ParseMapToArray<components::ComponentConfig>(value["components"]);
+    config.boot_log_path = value["boot-log-path"].As<std::string>({});
     config.task_processors = yaml_config::ParseMapToArray<engine::TaskProcessorConfig>(value["task_processors"]);
     config.default_task_processor = value["default_task_processor"].As<std::string>("main-task-processor");
     config.fs_task_processor = value["fs_task_processor"].As<std::string>("fs-task-processor");