From 439c72786a274f903b6cfceea728aeecdf1d70f8 Mon Sep 17 00:00:00 2001 From: Euripedes Rocha Filho Date: Fri, 17 Apr 2026 13:59:00 +0200 Subject: [PATCH] ci: Introduce log capture and matchers To allow our tests to use internal esp-mqtt state without exposing it directly we add this utility to capture it. --- .gitlab/ci/test.yml | 2 +- test/host/README.md | 42 +++++ test/host/main/CMakeLists.txt | 2 +- test/host/main/test_log_intercept.cpp | 213 ++++++++++++++++++++++++++ test/host/main/test_log_intercept.hpp | 96 ++++++++++++ test/host/main/test_log_matchers.cpp | 64 ++++++++ test/host/main/test_log_matchers.hpp | 101 ++++++++++++ test/host/main/test_log_parser.cpp | 71 +++++++++ test/host/main/test_mqtt_client.cpp | 8 + test/host/sdkconfig.defaults | 2 + 10 files changed, 599 insertions(+), 2 deletions(-) create mode 100644 test/host/main/test_log_intercept.cpp create mode 100644 test/host/main/test_log_intercept.hpp create mode 100644 test/host/main/test_log_matchers.cpp create mode 100644 test/host/main/test_log_matchers.hpp create mode 100644 test/host/main/test_log_parser.cpp diff --git a/.gitlab/ci/test.yml b/.gitlab/ci/test.yml index 54c89fc..58cd4af 100644 --- a/.gitlab/ci/test.yml +++ b/.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 diff --git a/test/host/README.md b/test/host/README.md index a62087a..6f3a1d4 100644 --- a/test/host/README.md +++ b/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. diff --git a/test/host/main/CMakeLists.txt b/test/host/main/CMakeLists.txt index e258192..be82cf2 100644 --- a/test/host/main/CMakeLists.txt +++ b/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) diff --git a/test/host/main/test_log_intercept.cpp b/test/host/main/test_log_intercept.cpp new file mode 100644 index 0000000..1315e41 --- /dev/null +++ b/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 +#include +#include +#include +#include + +namespace test::esp_log +{ + +namespace +{ +std::optional 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 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 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(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(n), cap); + }); + ingest(fragment); + } + + return (original_vprintf != nullptr) ? original_vprintf(format, args) : 0; +} + +} // namespace test::esp_log diff --git a/test/host/main/test_log_intercept.hpp b/test/host/main/test_log_intercept.hpp new file mode 100644 index 0000000..c26b0df --- /dev/null +++ b/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 +#include +#include +#include +#include +#include +#include +#include + +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 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 &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 substrings, + std::string_view tag = {}) const; + + bool contains_in_order(std::initializer_list substrings, + std::string_view tag = {}) const + { + return contains_in_order(std::span {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 captured_entries{}; +}; + +} // namespace test::esp_log diff --git a/test/host/main/test_log_matchers.cpp b/test/host/main/test_log_matchers.cpp new file mode 100644 index 0000000..7235f2b --- /dev/null +++ b/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. + */ + +#include "test_log_matchers.hpp" +#include +#include +#include +#include + +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 views; + views.reserve(expected_messages.size()); + + for (const auto &s : expected_messages) { + views.emplace_back(s); + } + + return captured_log.contains_in_order(std::span {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 diff --git a/test/host/main/test_log_matchers.hpp b/test/host/main/test_log_matchers.hpp new file mode 100644 index 0000000..5693ca0 --- /dev/null +++ b/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 +#include +#include +#include +#include +#include + +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 expected_messages) + : expected_messages(expected_messages.begin(), expected_messages.end()) {} + explicit LogsInOrder(std::string_view expected_tag, + std::initializer_list 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 expected_messages; + std::optional 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 expected_messages) +{ + return LogsInOrder{expected_messages}; +} + +inline LogsInOrder LogsInOrderIn(std::string_view expected_tag, + std::initializer_list expected_messages) +{ + return LogsInOrder{expected_tag, expected_messages}; +} + +} // namespace test::esp_log::matchers diff --git a/test/host/main/test_log_parser.cpp b/test/host/main/test_log_parser.cpp new file mode 100644 index 0000000..47c7307 --- /dev/null +++ b/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 +#include + +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"})); +} diff --git a/test/host/main/test_mqtt_client.cpp b/test/host/main/test_mqtt_client.cpp index be5b2ca..f5ff253 100644 --- a/test/host/main/test_mqtt_client.cpp +++ b/test/host/main/test_mqtt_client.cpp @@ -11,9 +11,13 @@ #include #include "esp_transport.h" #include +#include #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 } diff --git a/test/host/sdkconfig.defaults b/test/host/sdkconfig.defaults index d86d082..cf0a16d 100644 --- a/test/host/sdkconfig.defaults +++ b/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