fix components: clean up startup failure logs

* On startup failure, only the first component's exception is now logged with `level=ERROR` (and others are logged with `level=WARNING`), making it easy to distinguish the root cause.
* On startup failure, `OnLoadingCancelled` hook debug logs are no longer attached to an unrelated span.
commit_hash:0b7349183a8acf832b5909957fb90190f1688eea

Author: Anton3

.mapping.json

@@ -1514,6 +1514,7 @@
   "core/src/components/component_list_test.hpp":"taxi/uservices/userver/core/src/components/component_list_test.hpp",
   "core/src/components/component_sample_test.cpp":"taxi/uservices/userver/core/src/components/component_sample_test.cpp",
   "core/src/components/component_sample_test.hpp":"taxi/uservices/userver/core/src/components/component_sample_test.hpp",
+  "core/src/components/component_start_failure_log_test.cpp":"taxi/uservices/userver/core/src/components/component_start_failure_log_test.cpp",
   "core/src/components/config_not_required_test.cpp":"taxi/uservices/userver/core/src/components/config_not_required_test.cpp",
   "core/src/components/config_schema_validation_test.cpp":"taxi/uservices/userver/core/src/components/config_schema_validation_test.cpp",
   "core/src/components/container_test.cpp":"taxi/uservices/userver/core/src/components/container_test.cpp",
@@ -6444,6 +6445,7 @@
   "universal/utest/src/utest/current_process_open_files.cpp":"taxi/uservices/userver/universal/utest/src/utest/current_process_open_files.cpp",
   "universal/utest/src/utest/current_process_open_files_test.cpp":"taxi/uservices/userver/universal/utest/src/utest/current_process_open_files_test.cpp",
   "universal/utest/src/utest/log_capture_fixture.cpp":"taxi/uservices/userver/universal/utest/src/utest/log_capture_fixture.cpp",
+  "universal/utest/src/utest/log_capture_fixture_test.cpp":"taxi/uservices/userver/universal/utest/src/utest/log_capture_fixture_test.cpp",
   "universal/utest/src/utest/parameter_names_test.cpp":"taxi/uservices/userver/universal/utest/src/utest/parameter_names_test.cpp",
   "universal/version.hpp.in":"taxi/uservices/userver/universal/version.hpp.in",
   "version.txt":"taxi/uservices/userver/version.txt",

core/src/components/component_start_failure_log_test.cpp

@@ -0,0 +1,145 @@
+#include <algorithm>
+#include <optional>
+#include <ranges>
+#include <string>
+#include <vector>
+
+#include <fmt/format.h>
+#include <gtest/gtest.h>
+
+#include <userver/components/component_base.hpp>
+#include <userver/components/component_context.hpp>
+#include <userver/components/component_list.hpp>
+#include <userver/components/run.hpp>
+#include <userver/components/statistics_storage.hpp>
+#include <userver/engine/exception.hpp>
+#include <userver/engine/sleep.hpp>
+#include <userver/engine/task/cancel.hpp>
+#include <userver/fs/blocking/read.hpp>
+#include <userver/fs/blocking/temp_directory.hpp>
+#include <userver/logging/component.hpp>
+#include <userver/logging/log.hpp>
+#include <userver/os_signals/component.hpp>
+#include <userver/utest/log_capture_fixture.hpp>
+#include <userver/utest/utest.hpp>
+
+#include <components/component_list_test.hpp>
+
+USERVER_NAMESPACE_BEGIN
+
+namespace {
+
+// Sleeps in its constructor until the sibling component fails and cancels component loading.
+class SlowStartingComponent final : public components::ComponentBase {
+public:
+    static constexpr std::string_view kName = "slow-component";
+
+    SlowStartingComponent(const components::ComponentConfig& config, const components::ComponentContext& context)
+        : ComponentBase(config, context)
+    {
+        engine::InterruptibleSleepFor(utest::kMaxTestWaitTime);
+        if (engine::current_task::ShouldCancel()) {
+            throw engine::WaitInterruptedException(engine::current_task::CancellationReason());
+        }
+    }
+};
+
+// Yields several times so the slow component starts waiting, then throws.
+class FailingComponent final : public components::ComponentBase {
+public:
+    static constexpr std::string_view kName = "failing-component";
+
+    FailingComponent(const components::ComponentConfig& config, const components::ComponentContext& context)
+        : ComponentBase(config, context)
+    {
+        for (int i = 0; i < 10; ++i) {
+            engine::Yield();
+        }
+        throw std::runtime_error("FailingComponent constructor intentionally throws");
+    }
+};
+
+constexpr std::string_view kCannotStartComponentLogTextPrefix = "Cannot start component";
+constexpr std::string_view kOnLoadingCancelledLogTextPrefix = "Call OnLoadingCancelled() for component";
+
+std::size_t CountCannotStartComponentLogs(
+    const std::vector<utest::LogRecord>& records,
+    std::optional<std::string_view> level = std::nullopt,
+    std::optional<std::string_view> component_name = std::nullopt
+) {
+    return std::ranges::count_if(records, [&](const utest::LogRecord& record) {
+        return record.GetText().starts_with(kCannotStartComponentLogTextPrefix) &&
+               (!level || record.GetTagOptional("level") == *level) &&
+               (!component_name || record.GetTagOptional("component_name") == *component_name);
+    });
+}
+
+std::size_t CountOnLoadingCancelledLogs(
+    const std::vector<utest::LogRecord>& records,
+    std::optional<std::string_view> level = std::nullopt,
+    std::optional<std::string_view> component_name = std::nullopt
+) {
+    return std::ranges::count_if(records, [&](const utest::LogRecord& record) {
+        return record.GetText().starts_with(kOnLoadingCancelledLogTextPrefix) &&
+               !record.GetTagOptional("component_name") && (!level || record.GetTagOptional("level") == *level) &&
+               (!component_name ||
+                record.GetText() == fmt::format("Call OnLoadingCancelled() for component '{}'", *component_name));
+    });
+}
+
+}  // namespace
+
+using ComponentStartFailureLog = ComponentList;
+
+TEST_F(ComponentStartFailureLog, RootCauseAndCancelledComponentLogs) {
+    const auto temp_root = fs::blocking::TempDirectory::Create();
+    const std::string logs_path = temp_root.GetPath() + "/log.txt";
+
+    const std::string config = tests::MergeYaml(
+        tests::kMinimalStaticConfig,
+        fmt::format(
+            R"(
+            components_manager:
+                components:
+                    slow-component: {{}}
+                    failing-component: {{}}
+                    statistics-storage: {{}}
+                    logging:
+                        loggers:
+                            default:
+                                file_path: {}
+                                format: tskv
+                                level: debug
+            )",
+            logs_path
+        )
+    );
+
+    auto component_list =
+        components::ComponentList()
+            .Append<os_signals::ProcessorComponent>()
+            .Append<components::StatisticsStorage>()
+            .Append<components::Logging>()
+            .Append<SlowStartingComponent>()
+            .Append<FailingComponent>();
+
+    UEXPECT_THROW_MSG(
+        components::RunOnce(components::InMemoryConfig{config}, component_list),
+        std::runtime_error,
+        "FailingComponent constructor intentionally throws"
+    );
+
+    logging::LogFlush();
+
+    const auto records = utest::ParseTskvLogRecords(fs::blocking::ReadFileContents(logs_path));
+
+    ASSERT_EQ(CountCannotStartComponentLogs(records, "ERROR", FailingComponent::kName), 1) << records;
+    ASSERT_EQ(CountCannotStartComponentLogs(records, "WARNING", SlowStartingComponent::kName), 1) << records;
+    ASSERT_EQ(CountCannotStartComponentLogs(records), 2) << records;
+
+    ASSERT_EQ(CountOnLoadingCancelledLogs(records, "DEBUG", SlowStartingComponent::kName), 1) << records;
+    ASSERT_EQ(CountOnLoadingCancelledLogs(records, "DEBUG", FailingComponent::kName), 1) << records;
+    ASSERT_EQ(CountOnLoadingCancelledLogs(records, "DEBUG"), std::ranges::distance(component_list)) << records;
+}
+
+USERVER_NAMESPACE_END

core/src/components/manager.cpp

@@ -18,7 +18,7 @@
 #include <userver/components/component_list.hpp>
 #include <userver/engine/async.hpp>
 #include <userver/engine/task/current_task.hpp>
-#include <userver/engine/wait_any.hpp>
+#include <userver/engine/wait_all_checked.hpp>
 #include <userver/hostinfo/cpu_limit.hpp>
 #include <userver/logging/component.hpp>
 #include <userver/logging/log.hpp>
@@ -366,51 +366,45 @@ components::ComponentConfigMap Manager::MakeComponentConfigMap(const ComponentLi
     return component_config_map;
 }
 
+struct ComponentAddResult {
+    bool has_components_load_cancelled_exception{false};
+};
+
 void Manager::AddComponents(const ComponentList& component_list) {
+    auto start_time = std::chrono::steady_clock::now();
+
     const auto component_config_map = MakeComponentConfigMap(component_list);
+    ValidateConfigs(component_list, component_config_map, config_->validate_components_configs);
+    std::vector<engine::TaskWithResult<ComponentAddResult>> tasks;
 
-    auto start_time = std::chrono::steady_clock::now();
-    std::vector<engine::TaskWithResult<void>> tasks;
-    bool is_load_cancelled = false;
     try {
-        ValidateConfigs(component_list, component_config_map, config_->validate_components_configs);
-
         for (const auto& adder : component_list) {
             const auto& component_name = adder->GetComponentName();
             auto task_name = "boot/" + component_name;
-            tasks.push_back(utils::CriticalAsync(std::move(task_name), [&]() {
+
+            tasks.push_back(utils::CriticalAsync(std::move(task_name), [&]() -> ComponentAddResult {
                 tracing::Span::CurrentSpan().AddTag("component_name", component_name);
                 tracing::Span::CurrentSpan().SetLogLevel(logging::Level::kDebug);
                 try {
                     AddComponentImpl(component_config_map, component_name, *adder);
+                    return {};
                 } catch (const ComponentsLoadCancelledException& ex) {
                     LOG_WARNING() << "Cannot start component " << component_name << ": " << ex;
-                    component_context_->CancelComponentsLoad();
-                    throw;
+                    // Keep the parent task waiting for the root cause of the startup failure.
+                    return {.has_components_load_cancelled_exception = true};
                 } catch (const std::exception& ex) {
-                    LOG_ERROR() << "Cannot start component " << component_name << ": " << ex;
-                    component_context_->CancelComponentsLoad();
+                    // The exception is likely the root cause of the startup failure
+                    // if it happened not because of a task cancellation.
+                    const auto log_level =
+                        engine::current_task::ShouldCancel() ? logging::Level::kWarning : logging::Level::kError;
+                    LOG(log_level) << "Cannot start component " << component_name << ": " << ex;
                     throw std::runtime_error(fmt::format("Cannot start component {}: {}", component_name, ex.what()));
-                } catch (...) {
-                    component_context_->CancelComponentsLoad();
-                    throw;
                 }
             }));
         }
 
         // Wait for tasks in completion order and rethrow exceptions as soon as possible.
-        auto wait_any = engine::MakeWaitAny(tasks);
-        for (std::size_t completed = 0; completed < tasks.size(); ++completed) {
-            const auto idx = wait_any.Wait();
-            if (!idx.has_value()) {
-                throw engine::WaitInterruptedException(engine::current_task::CancellationReason());
-            }
-            try {
-                tasks[*idx].Get();
-            } catch (const ComponentsLoadCancelledException&) {
-                is_load_cancelled = true;
-            }
-        }
+        engine::WaitAllChecked(tasks);
     } catch (const std::exception& ex) {
         component_context_->CancelComponentsLoad();
 
@@ -431,12 +425,12 @@ void Manager::AddComponents(const ComponentList& component_list) {
         throw;
     }
 
+    const bool is_load_cancelled = std::ranges::any_of(tasks, [](auto& task) {
+        return task.Get().has_components_load_cancelled_exception;
+    });
     if (is_load_cancelled) {
         ClearComponents();
-        throw std::logic_error(
-            "Components load cancelled, but only ComponentsLoadCancelledExceptions "
-            "were caught"
-        );
+        throw std::logic_error("Components load cancelled, but only ComponentsLoadCancelledExceptions were caught");
     }
 
     LOG_INFO()

universal/src/utils/text_light_test.cpp

@@ -1,3 +1,4 @@
+#include <gmock/gmock.h>
 #include <gtest/gtest.h>
 
 #include <climits>

universal/utest/include/userver/utest/log_capture_fixture.hpp

@@ -87,6 +87,10 @@ LogRecord GetSingleLog(
     const utils::impl::SourceLocation& source_location = utils::impl::SourceLocation::Current()
 );
 
+/// @returns log records parsed from TSKV file contents.
+/// Each line must be a complete TSKV record ending with `\n`.
+std::vector<LogRecord> ParseTskvLogRecords(std::string_view tskv_log_contents);
+
 /// @ingroup userver_utest
 ///
 /// @brief A mocked logger that stores the log records in memory.

universal/utest/src/utest/log_capture_fixture.cpp

@@ -6,10 +6,8 @@
 #include <fmt/format.h>
 #include <boost/algorithm/cxx11/all_of.hpp>
 
-#include <userver/utils/algo.hpp>
 #include <userver/utils/encoding/tskv_parser.hpp>
 #include <userver/utils/encoding/tskv_parser_read.hpp>
-#include <userver/utils/text_light.hpp>
 
 USERVER_NAMESPACE_BEGIN
 
@@ -150,6 +148,28 @@ LogRecord GetSingleLog(utils::span<const LogRecord> log, const utils::impl::Sour
     return single_record;
 }
 
+std::vector<LogRecord> ParseTskvLogRecords(std::string_view tskv_log_contents) {
+    std::vector<LogRecord> result;
+    while (true) {
+        const auto newline_pos = tskv_log_contents.find('\n');
+        if (newline_pos == std::string_view::npos) {
+            break;
+        }
+        result.emplace_back(
+            utils::impl::InternalTag{},
+            logging::Level::kInfo,
+            std::string(tskv_log_contents.substr(0, newline_pos + 1))
+        );
+        tskv_log_contents.remove_prefix(newline_pos + 1);
+    }
+    if (!tskv_log_contents.empty()) {
+        throw std::runtime_error(
+            fmt::format(R"(TSKV log contents must end with '\n', leftover: "{}")", tskv_log_contents)
+        );
+    }
+    return result;
+}
+
 LogCaptureLogger::LogCaptureLogger(logging::Format format)
     : logger_(utils::MakeSharedRef<impl::ToStringLogger>(format))
 {}

universal/utest/src/utest/log_capture_fixture_test.cpp

@@ -0,0 +1,55 @@
+#include <userver/utest/log_capture_fixture.hpp>
+
+#include <string>
+
+#include <gmock/gmock.h>
+#include <gtest/gtest.h>
+
+#include <userver/utest/assert_macros.hpp>
+
+USERVER_NAMESPACE_BEGIN
+
+namespace {
+
+constexpr std::string_view kLine1 = "tskv\ttext=hello\tlevel=INFO\n";
+constexpr std::string_view kLine2 = "tskv\ttext=world\tlevel=DEBUG\n";
+
+}  // namespace
+
+TEST(ParseTskvLogRecords, Empty) { EXPECT_THAT(utest::ParseTskvLogRecords(""), testing::IsEmpty()); }
+
+TEST(ParseTskvLogRecords, SingleRecord) {
+    const auto records = utest::ParseTskvLogRecords(kLine1);
+    ASSERT_EQ(records.size(), 1);
+    EXPECT_EQ(records[0].GetText(), "hello");
+    EXPECT_EQ(records[0].GetTagOptional("level"), "INFO");
+    EXPECT_EQ(records[0].GetLogRaw(), kLine1);
+}
+
+TEST(ParseTskvLogRecords, MultipleRecords) {
+    const std::string content = std::string(kLine1) + std::string(kLine2);
+    const auto records = utest::ParseTskvLogRecords(content);
+    ASSERT_EQ(records.size(), 2);
+    EXPECT_EQ(records[0].GetText(), "hello");
+    EXPECT_EQ(records[1].GetText(), "world");
+    EXPECT_EQ(records[0].GetLogRaw(), kLine1);
+    EXPECT_EQ(records[1].GetLogRaw(), kLine2);
+}
+
+TEST(ParseTskvLogRecords, NoTrailingNewline) {
+    UEXPECT_THROW_MSG(
+        utest::ParseTskvLogRecords("tskv\ttext=hello"),
+        std::runtime_error,
+        R"(TSKV log contents must end with '\n')"
+    );
+}
+
+TEST(ParseTskvLogRecords, LeftoverAfterLastNewline) {
+    UEXPECT_THROW_MSG(utest::ParseTskvLogRecords("tskv\ttext=hello\nleftover"), std::runtime_error, "leftover");
+}
+
+TEST(ParseTskvLogRecords, InvalidRecord) {
+    UEXPECT_THROW_MSG(utest::ParseTskvLogRecords("garbage\n"), std::runtime_error, "Invalid log record");
+}
+
+USERVER_NAMESPACE_END