Merge branch 'feature-test-log-component' into 'master'

MR: ci: Introduce log capture and matchers
See merge request espressif/esp-mqtt!297

.gitlab/ci/test.yml

@@ -1,5 +1,5 @@
 host_tests:
-    image: espressif/idf:latest
+    image: espressif/idf:release-v6.0
     stage: test
     tags: [build]
     timeout: 1h

test/host/README.md

@@ -27,4 +27,46 @@ Just run:
 
 The test executable have some options provided by the test framework. 
 
+# Log capture
 
+Some behaviors inside `esp-mqtt` only surface through log output (e.g. debug
+breadcrumbs on internal decisions). The `test::esp_log::Capture` utility in
+`main/test_log_intercept.{hpp,cpp}` lets tests assert on those without the
+component having to expose internal state through its public API.
+
+`Capture` is an RAII guard: construction installs a `vprintf` hook on the
+esp-log system, destruction restores the previous one. While alive, it parses
+each log line into `Entry { level, tag, message }` records and still forwards
+the text to the original `vprintf` so test output stays visible. Only one
+`Capture` may be alive at a time; constructing a second one throws
+`std::logic_error`.
+
+Asserting on captured output uses either `Capture`'s own predicates or the
+Catch2 matchers in `main/test_log_matchers.{hpp,cpp}`:
+
+```cpp
+#include "test_log_intercept.hpp"
+#include "test_log_matchers.hpp"
+
+TEST_CASE("client logs its core-selection decision") {
+    esp_log_level_set("mqtt_client", ESP_LOG_DEBUG);
+    test::esp_log::Capture log;
+
+    // ... exercise the code under test ...
+
+    // Plain boolean check (no matcher machinery):
+    REQUIRE(log.contains("mqtt_client", "Core selection"));
+
+    // Catch2 matcher (nicer failure output on REQUIRE_THAT):
+    using namespace test::esp_log::matchers;
+    REQUIRE_THAT(log, HasMessageIn("mqtt_client", "Core selection"));
+}
+```
+
+The log parser assumes the stock esp-log text format with colors disabled;
+`test/host/sdkconfig.defaults` sets `CONFIG_LOG_COLORS=n` and
+`CONFIG_LOG_DEFAULT_LEVEL_DEBUG=y` so DEBUG-level messages are visible (call
+sites still need `esp_log_level_set(tag, ESP_LOG_DEBUG)` for their tag). A
+guard test in `main/test_log_parser.cpp` round-trips real `ESP_LOGx` output
+through `Capture`, so if the IDF log format ever changes the failure surfaces
+there rather than in every downstream test.

test/host/main/CMakeLists.txt

@@ -1,4 +1,4 @@
-idf_component_register(SRCS  "test_mqtt_client.cpp"
+idf_component_register(SRCS  "test_mqtt_client.cpp" "test_log_intercept.cpp" "test_log_matchers.cpp" "test_log_parser.cpp"
                        REQUIRES cmock mqtt esp_timer esp_hw_support http_parser log
                        WHOLE_ARCHIVE)
 

test/host/main/test_log_intercept.cpp

@@ -0,0 +1,213 @@
+/*
+ * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ * Log interceptor: RAII install/restore, coalesce esp-log fragments into full
+ * lines, parse them into structured Entry records, and forward to the original
+ * vprintf.
+ */
+
+#include "test_log_intercept.hpp"
+#include "esp_log.h"
+#include <algorithm>
+#include <cstdarg>
+#include <cstdio>
+#include <stdexcept>
+#include <string_view>
+
+namespace test::esp_log
+{
+
+namespace
+{
+std::optional<esp_log_level_t> level_from_char(char c)
+{
+    switch (c) {
+    case 'E': return ESP_LOG_ERROR;
+
+    case 'W': return ESP_LOG_WARN;
+
+    case 'I': return ESP_LOG_INFO;
+
+    case 'D': return ESP_LOG_DEBUG;
+
+    case 'V': return ESP_LOG_VERBOSE;
+
+    default:  return std::nullopt;
+    }
+}
+} // namespace
+
+std::optional<Entry> parse_line(std::string_view line)
+{
+    while (!line.empty() && (line.back() == '\n' || line.back() == '\r')) {
+        line.remove_suffix(1);
+    }
+
+    if (line.size() < 2) {
+        return std::nullopt;
+    }
+
+    auto level = level_from_char(line[0]);
+
+    if (!level) {
+        return std::nullopt;
+    }
+
+    if (line[1] != ' ') {
+        return std::nullopt;
+    }
+
+    line.remove_prefix(2);
+
+    // Optional "(timestamp) " segment.
+    if (!line.empty() && line.front() == '(') {
+        auto close = line.find(") ");
+
+        if (close == std::string_view::npos) {
+            return std::nullopt;
+        }
+
+        line.remove_prefix(close + 2);
+    }
+
+    auto sep = line.find(": ");
+
+    if (sep == std::string_view::npos) {
+        return std::nullopt;
+    }
+
+    Entry e;
+    e.level = *level;
+    e.tag.assign(line.substr(0, sep));
+    e.message.assign(line.substr(sep + 2));
+    return e;
+}
+
+Capture *Capture::s_current = nullptr;
+
+int Capture::capture_vprintf_cb(const char *format, va_list args)
+{
+    if (s_current == nullptr) {
+        return vprintf(format, args);
+    }
+
+    return s_current->register_and_forward(format, args);
+}
+
+Capture::Capture()
+{
+    if (s_current != nullptr) {
+        throw std::logic_error{"Another test::esp_log::Capture is already active"};
+    }
+
+    original_vprintf = esp_log_set_vprintf(capture_vprintf_cb);
+    s_current = this;
+}
+
+Capture::~Capture()
+{
+    if (s_current == this) {
+        s_current = nullptr;
+
+        if (original_vprintf != nullptr) {
+            esp_log_set_vprintf(original_vprintf);
+        }
+    }
+}
+
+void Capture::clear()
+{
+    captured_entries.clear();
+    partial_line.clear();
+}
+
+bool Capture::contains(std::string_view substring) const
+{
+    return std::ranges::any_of(captured_entries, [substring](const Entry & e) {
+        return e.message.contains(substring);
+    });
+}
+
+bool Capture::contains(std::string_view tag, std::string_view substring) const
+{
+    return std::ranges::any_of(captured_entries, [tag, substring](const Entry & e) {
+        return e.tag == tag && e.message.contains(substring);
+    });
+}
+
+bool Capture::contains_in_order(std::span<const std::string_view> substrings,
+                                std::string_view tag) const
+{
+    auto it = captured_entries.begin();
+
+    for (const auto &expected : substrings) {
+        it = std::find_if(it, captured_entries.end(), [&](const Entry & e) {
+            return (tag.empty() || e.tag == tag) && e.message.contains(expected);
+        });
+
+        if (it == captured_entries.end()) {
+            return false;
+        }
+
+        ++it;
+    }
+
+    return true;
+}
+
+void Capture::ingest(std::string_view chunk)
+{
+    partial_line.append(chunk);
+    size_t start = 0;
+
+    while (true) {
+        auto nl = partial_line.find('\n', start);
+
+        if (nl == std::string::npos) {
+            break;
+        }
+
+        std::string_view line{partial_line.data() + start, nl - start};
+
+        if (auto entry = parse_line(line)) {
+            captured_entries.push_back(std::move(*entry));
+        }
+
+        start = nl + 1;
+    }
+
+    if (start > 0) {
+        partial_line.erase(0, start);
+    }
+}
+
+int Capture::register_and_forward(const char *format, va_list args)
+{
+    va_list measure_args;
+    va_copy(measure_args, args);
+    auto needed = static_cast<size_t>(vsnprintf(nullptr, 0, format, measure_args));
+    va_end(measure_args);
+
+    if (needed > 0) {
+        std::string fragment;
+        fragment.resize_and_overwrite(needed, [&](char *buf, size_t cap) -> size_t {
+            va_list args_copy;
+            va_copy(args_copy, args);
+            int n = vsnprintf(buf, cap + 1, format, args_copy);
+            va_end(args_copy);
+
+            if (n < 0) {
+                return 0;
+            }
+
+            return std::min(static_cast<size_t>(n), cap);
+        });
+        ingest(fragment);
+    }
+
+    return (original_vprintf != nullptr) ? original_vprintf(format, args) : 0;
+}
+
+} // namespace test::esp_log

test/host/main/test_log_intercept.hpp

@@ -0,0 +1,96 @@
+/*
+ * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ * Log interceptor for host tests: RAII guard that installs a vprintf hook,
+ * coalesces log fragments into structured entries, and restores the original
+ * vprintf on destruction.
+ */
+
+#pragma once
+
+#include <esp_log_level.h>
+#include <esp_log_write.h>
+#include <initializer_list>
+#include <optional>
+#include <span>
+#include <string>
+#include <string_view>
+#include <vector>
+
+namespace test::esp_log
+{
+
+struct Entry {
+    esp_log_level_t level = ESP_LOG_NONE;
+    std::string tag;
+    std::string message;
+};
+
+/**
+ * Parse one fully-formatted esp-log line (without trailing newline) into an
+ * Entry. Expected shape with colors disabled: "X (ts) tag: message" or
+ * "X tag: message" when timestamps are disabled. Returns nullopt for lines
+ * that do not match the esp-log format.
+ */
+std::optional<Entry> parse_line(std::string_view line);
+
+/**
+ * Capture installs a global esp-log vprintf hook on construction and restores
+ * the previous one on destruction. Only one Capture may be active at a time;
+ * overlapping instances trigger an assertion. The hook is single-threaded by
+ * design: if your test emits logs from a secondary thread, serialize them
+ * before asserting (this matches host-test usage where tasks are mocked).
+ */
+class Capture
+{
+public:
+    Capture();
+    ~Capture();
+
+    Capture(const Capture &) = delete;
+    Capture &operator=(const Capture &) = delete;
+
+    /** Clear captured entries so assertions see only logs after this call. */
+    void clear();
+
+    /** Access the raw list of parsed entries, in capture order. */
+    const std::vector<Entry> &entries() const
+    {
+        return captured_entries;
+    }
+
+    /** True if any captured entry's message contains substring. */
+    bool contains(std::string_view substring) const;
+
+    /** True if any captured entry with the given tag has a message containing substring. */
+    bool contains(std::string_view tag, std::string_view substring) const;
+
+    /**
+     * True if all substrings appear in order across captured messages (each as
+     * a substring of some entry's message). If tag is non-empty, only entries
+     * with that tag are considered.
+     */
+    bool contains_in_order(std::span<const std::string_view> substrings,
+                           std::string_view tag = {}) const;
+
+    bool contains_in_order(std::initializer_list<std::string_view> substrings,
+                           std::string_view tag = {}) const
+    {
+        return contains_in_order(std::span<const std::string_view> {substrings}, tag);
+    }
+
+private:
+    static int capture_vprintf_cb(const char *format, va_list args);
+    int register_and_forward(const char *format, va_list args);
+    void ingest(std::string_view chunk);
+
+    static Capture *s_current;
+
+    vprintf_like_t original_vprintf = nullptr;
+    std::string partial_line{};
+    std::vector<Entry> captured_entries{};
+};
+
+} // namespace test::esp_log

test/host/main/test_log_matchers.cpp

@@ -0,0 +1,64 @@
+/*
+ * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ * Matchers are thin wrappers over Capture predicates; the heavy lifting lives
+ * in Capture. This file only holds describe() text and the LogsInOrder glue
+ * from stored std::string messages to a span<const std::string_view>.
+ */
+
+#include "test_log_matchers.hpp"
+#include <format>
+#include <span>
+#include <string_view>
+#include <vector>
+
+namespace test::esp_log::matchers
+{
+
+std::string ContainsMessage::describe() const
+{
+    return std::format(R"(contains message "{}")", expected_message);
+}
+
+std::string ContainsMessageWithTag::describe() const
+{
+    return std::format(R"(contains message "{}" with tag "{}")",
+    expected_message, expected_tag);
+}
+
+bool LogsInOrder::match(const Capture &captured_log) const
+{
+    std::vector<std::string_view> views;
+    views.reserve(expected_messages.size());
+
+    for (const auto &s : expected_messages) {
+        views.emplace_back(s);
+    }
+
+    return captured_log.contains_in_order(std::span<const std::string_view> {views},
+                                          expected_tag ? std::string_view{*expected_tag}
+                                          : std::string_view{});
+}
+
+std::string LogsInOrder::describe() const
+{
+    std::string list = "[";
+
+    if (!expected_messages.empty()) {
+        for (const auto &expected : expected_messages) {
+            list += std::format(R"("{}", )", expected);
+        }
+
+        list.resize(list.size() - 2);
+    }
+
+    list += ']';
+    const std::string scope = expected_tag
+                              ? std::format(R"(with tag "{}")", *expected_tag)
+                              : std::string{"(any tag)"};
+    return std::format("logs {} in order {}", list, scope);
+}
+
+} // namespace test::esp_log::matchers

test/host/main/test_log_matchers.hpp

@@ -0,0 +1,101 @@
+/*
+ * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ * Catch2 matchers over test::esp_log::Capture. These are thin wrappers around
+ * Capture's predicates; they add describe() text for Catch2 failure output.
+ * For plain boolean checks use Capture::contains / Capture::contains_in_order
+ * directly.
+ */
+
+#pragma once
+
+#include "test_log_intercept.hpp"
+#include <catch2/matchers/catch_matchers_templated.hpp>
+#include <initializer_list>
+#include <optional>
+#include <string>
+#include <string_view>
+#include <vector>
+
+namespace test::esp_log::matchers
+{
+
+class ContainsMessage : public Catch::Matchers::MatcherGenericBase
+{
+public:
+    explicit ContainsMessage(std::string_view expected_message)
+        : expected_message(expected_message) {}
+
+    bool match(const Capture &captured_log) const
+    {
+        return captured_log.contains(expected_message);
+    }
+
+    std::string describe() const override;
+
+private:
+    std::string expected_message;
+};
+
+class ContainsMessageWithTag : public Catch::Matchers::MatcherGenericBase
+{
+public:
+    ContainsMessageWithTag(std::string_view expected_tag, std::string_view expected_message)
+        : expected_tag(expected_tag), expected_message(expected_message) {}
+
+    bool match(const Capture &captured_log) const
+    {
+        return captured_log.contains(expected_tag, expected_message);
+    }
+
+    std::string describe() const override;
+
+private:
+    std::string expected_tag;
+    std::string expected_message;
+};
+
+class LogsInOrder : public Catch::Matchers::MatcherGenericBase
+{
+public:
+    explicit LogsInOrder(std::initializer_list<std::string_view> expected_messages)
+        : expected_messages(expected_messages.begin(), expected_messages.end()) {}
+    explicit LogsInOrder(std::string_view expected_tag,
+                         std::initializer_list<std::string_view> expected_messages)
+        : expected_messages(expected_messages.begin(), expected_messages.end()),
+          expected_tag(std::string{expected_tag}) {}
+
+    bool match(const Capture &captured_log) const;
+
+    std::string describe() const override;
+
+private:
+    std::vector<std::string> expected_messages;
+    std::optional<std::string> expected_tag;
+};
+
+inline ContainsMessage HasMessage(std::string_view expected_message)
+{
+    return ContainsMessage{expected_message};
+}
+
+inline ContainsMessageWithTag HasMessageIn(std::string_view expected_tag,
+                                           std::string_view expected_message)
+{
+    return ContainsMessageWithTag{expected_tag, expected_message};
+}
+
+inline LogsInOrder LogsInOrderAny(std::initializer_list<std::string_view> expected_messages)
+{
+    return LogsInOrder{expected_messages};
+}
+
+inline LogsInOrder LogsInOrderIn(std::string_view expected_tag,
+                                 std::initializer_list<std::string_view> expected_messages)
+{
+    return LogsInOrder{expected_tag, expected_messages};
+}
+
+} // namespace test::esp_log::matchers

test/host/main/test_log_parser.cpp

@@ -0,0 +1,71 @@
+/*
+ * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ * Guard test: exercises test::esp_log::parse_line and an end-to-end Capture
+ * round-trip through the real esp-log plumbing. Any upstream change to the
+ * text format lands loudly here instead of in downstream matcher tests.
+ */
+
+#include "test_log_intercept.hpp"
+#include "test_log_matchers.hpp"
+#include <catch2/catch_test_macros.hpp>
+#include <catch2/matchers/catch_matchers.hpp>
+
+extern "C" {
+#include "esp_log.h"
+}
+
+using namespace test::esp_log;
+using namespace test::esp_log::matchers;
+
+TEST_CASE("parse_line extracts level, tag, and message", "[log_parser]")
+{
+    SECTION("with timestamp") {
+        auto entry = parse_line("I (123) mqtt_client: hello world");
+        REQUIRE(entry.has_value());
+        REQUIRE(entry->level == ESP_LOG_INFO);
+        REQUIRE(entry->tag == "mqtt_client");
+        REQUIRE(entry->message == "hello world");
+    }
+    SECTION("without timestamp") {
+        auto entry = parse_line("W tag: warn msg");
+        REQUIRE(entry.has_value());
+        REQUIRE(entry->level == ESP_LOG_WARN);
+        REQUIRE(entry->tag == "tag");
+        REQUIRE(entry->message == "warn msg");
+    }
+    SECTION("trailing newline is stripped") {
+        auto entry = parse_line("E (1) t: boom\n");
+        REQUIRE(entry.has_value());
+        REQUIRE(entry->message == "boom");
+    }
+    SECTION("non-log line returns nullopt") {
+        REQUIRE_FALSE(parse_line("not a log line").has_value());
+        REQUIRE_FALSE(parse_line("").has_value());
+        REQUIRE_FALSE(parse_line("I no-colon-here").has_value());
+    }
+}
+
+TEST_CASE("Capture round-trips real esp_log output", "[log_parser]")
+{
+    Capture logs;
+    static const char *TAG = "log_parser_test";
+    esp_log_level_set(TAG, ESP_LOG_DEBUG);
+    ESP_LOGI(TAG, "hello %d", 42);
+    ESP_LOGW(TAG, "careful");
+    REQUIRE(logs.entries().size() == 2);
+    const auto &first = logs.entries()[0];
+    REQUIRE(first.level == ESP_LOG_INFO);
+    REQUIRE(first.tag == TAG);
+    REQUIRE(first.message == "hello 42");
+    const auto &second = logs.entries()[1];
+    REQUIRE(second.level == ESP_LOG_WARN);
+    REQUIRE(second.tag == TAG);
+    REQUIRE(second.message == "careful");
+    REQUIRE_THAT(logs, HasMessage("hello 42"));
+    REQUIRE_THAT(logs, HasMessageIn(TAG, "careful"));
+    REQUIRE_THAT(logs, LogsInOrderIn(TAG, {"hello", "careful"}));
+    REQUIRE_THAT(logs, LogsInOrderAny({"hello", "careful"}));
+}

test/host/main/test_mqtt_client.cpp

@@ -11,9 +11,13 @@
 #include <type_traits>
 #include "esp_transport.h"
 #include <catch2/catch_test_macros.hpp>
+#include <catch2/matchers/catch_matchers.hpp>
 
 #include "mqtt_client.h"
+#include "test_log_intercept.hpp"
+#include "test_log_matchers.hpp"
 extern "C" {
+#include "esp_log.h"
 #include "Mockesp_event.h"
 #include "Mockesp_transport.h"
 #include "Mockesp_transport_ssl.h"
@@ -105,7 +109,11 @@ SCENARIO("MQTT Client Operation")
                 }
             }
             SECTION("After Start Client Is Cleanly destroyed") {
+                esp_log_level_set("mqtt_client", ESP_LOG_DEBUG);
+                test::esp_log::Capture log;
                 REQUIRE(esp_mqtt_client_start(client.get()) == ESP_OK);
+                using namespace test::esp_log::matchers;
+                REQUIRE_THAT(log, HasMessageIn("mqtt_client", "Core selection"));
                 // Only need to start the client, destroy is called automatically at the end of
                 // scope
             }

test/host/sdkconfig.defaults

@@ -1,6 +1,8 @@
 CONFIG_IDF_TARGET="linux"
+CONFIG_LOG_DEFAULT_LEVEL_DEBUG=y
 CONFIG_COMPILER_CXX_EXCEPTIONS=y
 CONFIG_COMPILER_CXX_RTTI=y
 CONFIG_COMPILER_CXX_EXCEPTIONS_EMG_POOL_SIZE=0
 CONFIG_COMPILER_STACK_CHECK_MODE_NONE=y
 CONFIG_UNITY_ENABLE_IDF_TEST_RUNNER=n
+CONFIG_LOG_COLORS=n