From 8f95f44e38e3106def058c2143c5f4471448b8a1 Mon Sep 17 00:00:00 2001 From: achamayou Date: Wed, 9 Sep 2026 22:19:28 +0100 Subject: [PATCH 1/2] Make snapshots acyclic and align private namespaces Break the snapshots-to-host and snapshots-to-consensus dependencies without changing public headers. Refs #3517. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- CMakeLists.txt | 4 ++ scripts/source-dependencies.json | 3 +- src/ds/test/logger.cpp | 67 +++++++++++++++++++ src/ds/test/time_bound_logger_header_test.cpp | 4 ++ src/{host => ds}/time_bound_logger.h | 3 +- src/host/files_cleanup_timer.h | 17 ++--- src/host/ledger.h | 63 ++++++++--------- src/host/lfs_file_handler.h | 10 +-- src/host/run.cpp | 4 +- src/host/test/ledger.cpp | 36 +++++++++- src/node/test/snapshotter.cpp | 7 +- src/snapshots/fetch.h | 3 +- src/snapshots/filenames.h | 10 ++- src/snapshots/snapshot_writer.h | 18 ++--- src/snapshots/test/fetch_header_test.cpp | 4 ++ src/snapshots/test/filenames_header_test.cpp | 4 ++ .../test/snapshot_writer_header_test.cpp | 4 ++ 17 files changed, 195 insertions(+), 66 deletions(-) create mode 100644 src/ds/test/time_bound_logger_header_test.cpp rename src/{host => ds}/time_bound_logger.h (97%) create mode 100644 src/snapshots/test/fetch_header_test.cpp create mode 100644 src/snapshots/test/filenames_header_test.cpp create mode 100644 src/snapshots/test/snapshot_writer_header_test.cpp diff --git a/CMakeLists.txt b/CMakeLists.txt index 47c29fe35779..064432fc2aad 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -640,6 +640,7 @@ if(BUILD_TESTS) add_unit_test( logger_test ${CMAKE_CURRENT_SOURCE_DIR}/src/ds/test/logger.cpp + ${CMAKE_CURRENT_SOURCE_DIR}/src/ds/test/time_bound_logger_header_test.cpp ) add_unit_test( @@ -704,6 +705,8 @@ if(BUILD_TESTS) add_unit_test( ledger_test ${CMAKE_CURRENT_SOURCE_DIR}/src/host/test/ledger.cpp + ${CMAKE_CURRENT_SOURCE_DIR}/src/snapshots/test/filenames_header_test.cpp + ${CMAKE_CURRENT_SOURCE_DIR}/src/snapshots/test/snapshot_writer_header_test.cpp ) target_link_libraries(ledger_test PRIVATE uv) @@ -1607,6 +1610,7 @@ if(BUILD_TESTS) curl_test ${CMAKE_CURRENT_SOURCE_DIR}/src/http_client/test/curl_header_test.cpp ${CMAKE_CURRENT_SOURCE_DIR}/src/http_client/test/curl_test.cpp + ${CMAKE_CURRENT_SOURCE_DIR}/src/snapshots/test/fetch_header_test.cpp ) target_link_libraries(curl_test PRIVATE curl uv http_parser) diff --git a/scripts/source-dependencies.json b/scripts/source-dependencies.json index 69681a50a6b1..23d1a154289a 100644 --- a/scripts/source-dependencies.json +++ b/scripts/source-dependencies.json @@ -35,6 +35,7 @@ "udp": ["ds"], "uv": [], "http": ["ccf-api", "crypto", "ds"], - "http_client": ["ccf-api", "ds", "uv"] + "http_client": ["ccf-api", "ds", "uv"], + "snapshots": ["ccf-api", "ds", "http", "http_client"] } } diff --git a/src/ds/test/logger.cpp b/src/ds/test/logger.cpp index 43e0ddc7667d..56dd77ca70ff 100644 --- a/src/ds/test/logger.cpp +++ b/src/ds/test/logger.cpp @@ -2,10 +2,12 @@ // Licensed under the Apache 2.0 License. #include "ds/internal_logger.h" +#include "ds/time_bound_logger.h" #define DOCTEST_CONFIG_IMPLEMENT_WITH_MAIN #include #include +#include TEST_CASE("Thread IDs are provided by the logger headers") { @@ -46,6 +48,71 @@ class TestLogger : public Base using TestTextLogger = TestLogger; using TestJsonLogger = TestLogger; +TEST_CASE("Time-bound logger duration formatting") +{ + using ccf::ds::TimeBoundLogger; + using namespace std::chrono_literals; + + CHECK(TimeBoundLogger::human_time(0us) == " 0.000us"); + CHECK(TimeBoundLogger::human_time(999us) == "999.000us"); + CHECK(TimeBoundLogger::human_time(1000us) == " 1.000ms"); + CHECK(TimeBoundLogger::human_time(999999us) == "999.999ms"); + CHECK(TimeBoundLogger::human_time(1s) == " 1.000s"); +} + +TEST_CASE("Time-bound logger captures the configured default") +{ + using ccf::ds::TimeBoundLogger; + using namespace std::chrono_literals; + + const auto previous_default = + std::exchange(TimeBoundLogger::default_max_time, 1s); + TimeBoundLogger first("first"); + TimeBoundLogger::default_max_time = 2s; + TimeBoundLogger second("second"); + TimeBoundLogger explicit_threshold("explicit", 3s); + TimeBoundLogger::default_max_time = previous_default; + + CHECK(first.max_time == 1s); + CHECK(second.max_time == 2s); + CHECK(explicit_threshold.max_time == 3s); +} + +TEST_CASE("Time-bound logger reports slow operations at the expected level") +{ + using ccf::ds::TimeBoundLogger; + using namespace std::chrono_literals; + + std::vector logs; + auto previous_loggers = std::exchange(ccf::logger::config::loggers(), {}); + const auto previous_level = + std::exchange(ccf::logger::config::level(), ccf::LoggerLevel::INFO); + ccf::logger::config::loggers().emplace_back( + std::make_unique(logs)); + + { + TimeBoundLogger timer("fast", 1h); + timer.start_time -= 30min; + } + { + TimeBoundLogger timer("slow", 1h); + timer.start_time -= 2h; + } + { + TimeBoundLogger timer("very slow", 1h); + timer.start_time -= 200h; + } + + ccf::logger::config::loggers() = std::move(previous_loggers); + ccf::logger::config::level() = previous_level; + + REQUIRE(logs.size() == 2); + CHECK(logs[0].contains("info")); + CHECK(logs[0].contains("): slow")); + CHECK(logs[1].contains("fail")); + CHECK(logs[1].contains("): very slow")); +} + TEST_CASE("Framework logging macros") { std::vector logs; diff --git a/src/ds/test/time_bound_logger_header_test.cpp b/src/ds/test/time_bound_logger_header_test.cpp new file mode 100644 index 000000000000..8c9a736aedf6 --- /dev/null +++ b/src/ds/test/time_bound_logger_header_test.cpp @@ -0,0 +1,4 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the Apache 2.0 License. + +#include "ds/time_bound_logger.h" diff --git a/src/host/time_bound_logger.h b/src/ds/time_bound_logger.h similarity index 97% rename from src/host/time_bound_logger.h rename to src/ds/time_bound_logger.h index d8fafa065665..86fadcec89a2 100644 --- a/src/host/time_bound_logger.h +++ b/src/ds/time_bound_logger.h @@ -7,8 +7,9 @@ #include #include #include +#include -namespace asynchost +namespace ccf::ds { struct TimeBoundLogger { diff --git a/src/host/files_cleanup_timer.h b/src/host/files_cleanup_timer.h index b40409eceb0b..95803aab5029 100644 --- a/src/host/files_cleanup_timer.h +++ b/src/host/files_cleanup_timer.h @@ -4,9 +4,9 @@ #include "ccf/crypto/hash_provider.h" #include "ccf/crypto/sha256_hash.h" +#include "ds/time_bound_logger.h" #include "ledger_filenames.h" #include "snapshots/filenames.h" -#include "time_bound_logger.h" #include "timer.h" #include @@ -85,7 +85,7 @@ namespace asynchost { std::ifstream f; { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Hashing file - ifstream open({})", path)); f.open(path, std::ios::binary); } @@ -97,7 +97,7 @@ namespace asynchost auto hasher = ccf::crypto::make_incremental_sha256(); std::vector buf(HASH_READ_CHUNK_SIZE); { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Hashing file - read loop({})", path)); while (f.read(reinterpret_cast(buf.data()), buf.size()) || f.gcount() > 0) @@ -234,7 +234,8 @@ namespace asynchost std::vector directories{dir}; try { - return snapshots::find_committed_snapshots_in_directories(directories); + return ccf::snapshots::find_committed_snapshots_in_directories( + directories); } catch (const std::filesystem::filesystem_error& e) { @@ -270,7 +271,7 @@ namespace asynchost committed_snapshots, size_t max_retained) { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( "Cleaning snapshots", std::chrono::seconds(1)); if (committed_snapshots.size() > max_retained) @@ -288,7 +289,7 @@ namespace asynchost max_retained); std::error_code ec; { - TimeBoundLogger log_remove_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_remove_if_slow(fmt::format( "Deleting old snapshot - remove({})", path.filename())); std::filesystem::remove(path, ec); } @@ -309,7 +310,7 @@ namespace asynchost size_t max_retained, std::optional snapshot_watermark = std::nullopt) { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format( "Cleaning ledger chunks from {}, watermark={}", main_dir, @@ -401,7 +402,7 @@ namespace asynchost max_retained); std::error_code ec; { - TimeBoundLogger log_remove_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_remove_if_slow(fmt::format( "Deleting old ledger chunk - remove({})", path.filename())); std::filesystem::remove(path, ec); } diff --git a/src/host/ledger.h b/src/host/ledger.h index 1a03d35ddad3..bf243e94abc4 100644 --- a/src/host/ledger.h +++ b/src/host/ledger.h @@ -10,11 +10,11 @@ #include "ds/internal_logger.h" #include "ds/messaging.h" #include "ds/serialized.h" +#include "ds/time_bound_logger.h" #include "ds/worker_shutdown_gate.h" #include "kv/kv_types.h" #include "kv/serialised_entry_format.h" #include "ledger_filenames.h" -#include "time_bound_logger.h" #include #include @@ -114,7 +114,7 @@ namespace asynchost return 0; } - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Closing ledger file - fclose({})", file_name)); errno = 0; auto* file_to_close = file; @@ -144,7 +144,7 @@ namespace asynchost // Use O_EXCL to atomically fail if the file already exists, and create // with restrictive permissions (0600) rather than relying on umask. { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Creating ledger file - open({})", file_path)); file = files::open_file(file_path, O_RDWR | O_CREAT | O_EXCL, "w+b"); } @@ -186,7 +186,7 @@ namespace asynchost const auto* const mode = committed ? "rb" : "r+b"; { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Opening ledger file - fopen({})", file_path)); // NOLINTNEXTLINE(cppcoreguidelines-owning-memory) file = fopen(file_path.c_str(), mode); @@ -208,7 +208,7 @@ namespace asynchost fseeko(file, 0, SEEK_SET); positions_offset_header_t table_offset = 0; { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Reading positions offset - fread({})", file_path)); if ( fread(&table_offset, sizeof(positions_offset_header_t), 1, file) != 1) @@ -253,7 +253,7 @@ namespace asynchost (total_file_size - table_offset) / sizeof(positions.at(0))); { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Reading positions table ({} entries) - fread({})", positions.size(), file_path)); @@ -277,7 +277,7 @@ namespace asynchost total_len = sizeof(positions_offset_header_t); auto len = total_file_size - total_len; - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Recovering entries from incomplete ledger file {} ({} bytes)", file_path, len)); @@ -378,7 +378,7 @@ namespace asynchost std::vector entry(size); bool read_mismatch = false; { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Reading existing entry for comparison ({} bytes) - fread({})", size, file_name)); @@ -404,7 +404,7 @@ namespace asynchost if (should_write) { { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Writing ledger entry ({} bytes) - fwrite({})", size, file_name)); if (fwrite(data, size, 1, file) != 1) { @@ -415,7 +415,7 @@ namespace asynchost // Committable entries get flushed straight away if (committable) { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Flushing ledger entry - fflush({})", file_name)); if (fflush(file) != 0) { @@ -515,7 +515,7 @@ namespace asynchost fseeko(file, positions.at(from - start_idx), SEEK_SET); { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Reading ledger entries {} to {} ({} bytes) - fread({})", from, to_, @@ -547,7 +547,7 @@ namespace asynchost { // Truncating everything triggers file deletion { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Removing ledger file on truncation - remove({})", file_name)); if (!fs::remove(dir / file_name)) { @@ -564,7 +564,7 @@ namespace asynchost fseeko(file, 0, SEEK_SET); positions_offset_header_t table_offset = 0; { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Resetting positions offset - fwrite({})", file_name)); if (fwrite(&table_offset, sizeof(table_offset), 1, file) != 1) { @@ -580,7 +580,7 @@ namespace asynchost } { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Flushing truncated ledger - fflush({})", file_name)); if (fflush(file) != 0) { @@ -590,7 +590,7 @@ namespace asynchost } { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Truncating ledger file - ftruncate({})", file_name)); if (ftruncate(fileno(file), total_len) != 0) { @@ -627,7 +627,7 @@ namespace asynchost size_t table_offset = ftello(file); { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Writing positions table ({} entries) - fwrite({})", positions.size(), file_name)); @@ -649,7 +649,7 @@ namespace asynchost } { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Writing positions table offset - fwrite({})", file_name)); if (fwrite(&table_offset, sizeof(table_offset), 1, file) != 1) { @@ -659,7 +659,7 @@ namespace asynchost } { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Completing ledger file - fflush({})", file_name)); if (fflush(file) != 0) { @@ -700,7 +700,7 @@ namespace asynchost try { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Renaming ledger file {} to {} - rename()", file_name, new_file_name)); @@ -723,7 +723,7 @@ namespace asynchost { int open_errno = 0; { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Reopening ledger file - fopen({})", new_file_path)); errno = 0; // NOLINTNEXTLINE(cppcoreguidelines-owning-memory) @@ -763,7 +763,7 @@ namespace asynchost // committed_ledger_path_with_idx() is complete and can be safely read and // served to other nodes. { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Committing ledger file - fsync({})", file_name)); if (fsync(fileno(file)) != 0) { @@ -1066,7 +1066,7 @@ namespace asynchost auto ignored_file_name = fmt::format("{}{}", file_name, ledger_ignored_file_suffix); { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Ignoring ledger file - rename({} to {})", file_name, ignored_file_name)); @@ -1083,7 +1083,7 @@ namespace asynchost auto start_idx = get_start_idx_from_file_name(file_name); if (start_idx > idx) { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Deleting divergent ledger file - remove({})", file_name)); if (!fs::remove(ledger_dir / file_name)) { @@ -1302,7 +1302,7 @@ namespace asynchost } else { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Creating ledger directory - create_directory({})", ledger_dir)); if (!fs::create_directory(ledger_dir)) { @@ -1327,7 +1327,7 @@ namespace asynchost void init(size_t idx, size_t recovery_start_idx_ = 0) { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Initing ledger - seqno={}", idx)); std::unique_lock guard(state_lock); @@ -1364,7 +1364,7 @@ namespace asynchost last_idx_file.value()); { - TimeBoundLogger log_rename_if_slow( + ccf::ds::TimeBoundLogger log_rename_if_slow( fmt::format("Removing committed suffix - rename({})", file_name)); files::rename( ledger_dir / file_name, @@ -1449,7 +1449,7 @@ namespace asynchost std::optional read_entry(size_t idx) { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Reading ledger entry at {}", idx)); // Locking is done in read_entries_range @@ -1462,7 +1462,7 @@ namespace asynchost size_t to, std::optional max_entries_size = std::nullopt) { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Reading ledger entries from {} to {}", from, to)); // Locking is done in read_entries_range @@ -1472,7 +1472,7 @@ namespace asynchost size_t write_entry(const uint8_t* data, size_t size, bool committable) { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Writing ledger entry - {} bytes, committable={}", size, committable)); std::unique_lock guard(state_lock); @@ -1565,7 +1565,8 @@ namespace asynchost void truncate(size_t idx, bool recovery_mode = false) { - TimeBoundLogger log_if_slow(fmt::format("Truncating ledger at {}", idx)); + ccf::ds::TimeBoundLogger log_if_slow( + fmt::format("Truncating ledger at {}", idx)); std::unique_lock guard(state_lock); @@ -1649,7 +1650,7 @@ namespace asynchost void commit(size_t idx) { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Committing ledger entry {}", idx)); std::unique_lock guard(state_lock); diff --git a/src/host/lfs_file_handler.h b/src/host/lfs_file_handler.h index 338869cd940f..c6ef401be879 100644 --- a/src/host/lfs_file_handler.h +++ b/src/host/lfs_file_handler.h @@ -4,8 +4,8 @@ #include "ds/files.h" #include "ds/messaging.h" +#include "ds/time_bound_logger.h" #include "indexing/lfs_ringbuffer_types.h" -#include "time_bound_logger.h" #include @@ -22,13 +22,13 @@ namespace asynchost if (std::filesystem::is_directory(root_dir)) { LOG_INFO_FMT("Clearing contents from existing directory {}", root_dir); - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Clearing LFS index directory - remove_all({})", root_dir)); std::filesystem::remove_all(root_dir); } { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Creating LFS index directory - create_directory({})", root_dir)); if (!std::filesystem::create_directory(root_dir)) { @@ -49,7 +49,7 @@ namespace asynchost const auto target_path = root_dir / key; { - TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Writing LFS file ({} bytes) - {}", encrypted.size(), target_path)); @@ -69,7 +69,7 @@ namespace asynchost const auto target_path = root_dir / key; if (std::filesystem::is_regular_file(target_path)) { - TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Reading LFS file - ifstream({})", target_path)); std::ifstream f(target_path, std::ios::binary); f.seekg(0, f.end); diff --git a/src/host/run.cpp b/src/host/run.cpp index 18d8dc409b92..cec71989f67f 100644 --- a/src/host/run.cpp +++ b/src/host/run.cpp @@ -28,6 +28,7 @@ #include "ds/non_blocking.h" #include "ds/notifying.h" #include "ds/oversized.h" +#include "ds/time_bound_logger.h" #include "enclave/entry_points.h" #include "handle_ring_buffer.h" #include "host/env.h" @@ -41,7 +42,6 @@ #include "sig_term.h" #include "tcp.h" #include "ticker.h" -#include "time_bound_logger.h" #include "udp.h" #include @@ -1077,7 +1077,7 @@ namespace ccf // set the host log level ccf::logger::config::level() = log_level; - asynchost::TimeBoundLogger::default_max_time = + ccf::ds::TimeBoundLogger::default_max_time = config.slow_io_logging_threshold; // create the enclave: diff --git a/src/host/test/ledger.cpp b/src/host/test/ledger.cpp index 53a6aa0b338b..7313177894de 100644 --- a/src/host/test/ledger.cpp +++ b/src/host/test/ledger.cpp @@ -15,6 +15,7 @@ #define DOCTEST_CONFIG_IMPLEMENT #include #include +#include #include #include #include @@ -1633,7 +1634,7 @@ TEST_CASE("Snapshot file name" * doctest::test_suite("snapshot")) std::vector snapshot_idx_interval_ranges = { 10, 1000, 10000, std::numeric_limits::max() - 2}; - using namespace snapshots; + using namespace ccf::snapshots; for (auto const& snapshot_idx_interval_range : snapshot_idx_interval_ranges) { @@ -1680,7 +1681,7 @@ TEST_CASE("Generate and commit snapshots" * doctest::test_suite("snapshot")) auto snap_ro_dir = AutoDeleteFolder(snapshot_dir_read_only); fs::create_directory(snapshot_dir_read_only); - using namespace snapshots; + using namespace ccf::snapshots; SnapshotWriter snapshots(snapshot_dir); const std::vector find_dirs{snapshot_dir, snapshot_dir_read_only}; @@ -1747,6 +1748,37 @@ TEST_CASE("Generate and commit snapshots" * doctest::test_suite("snapshot")) } } +TEST_CASE( + "Snapshot writer preserves full-width sequence numbers" * + doctest::test_suite("snapshot")) +{ + auto snap_dir = AutoDeleteFolder(snapshot_dir); + ccf::snapshots::SnapshotWriter writer(snapshot_dir); + + const ccf::SeqNo evidence_idx = std::numeric_limits::max(); + const ccf::SeqNo snapshot_idx = evidence_idx - 1; + writer.persist_snapshot( + snapshot_idx, evidence_idx, dummy_snapshot, dummy_receipt); + + const auto expected_path = fs::path(snapshot_dir) / + fmt::format("snapshot_{}_{}.committed", snapshot_idx, evidence_idx); + REQUIRE(fs::exists(expected_path)); + CHECK( + ccf::snapshots::find_latest_committed_snapshot_in_directory(snapshot_dir) == + expected_path); + CHECK( + ccf::snapshots::get_snapshot_idx_from_file_name( + expected_path.filename().string()) == snapshot_idx); + CHECK( + ccf::snapshots::get_snapshot_evidence_idx_from_file_name( + expected_path.filename().string()) == evidence_idx); + + auto expected_data = dummy_snapshot; + expected_data.insert( + expected_data.end(), dummy_receipt.begin(), dummy_receipt.end()); + CHECK(files::slurp(expected_path.string()) == expected_data); +} + TEST_CASE("Chunking according to entry header flag") { auto dir = AutoDeleteFolder(ledger_dir); diff --git a/src/node/test/snapshotter.cpp b/src/node/test/snapshotter.cpp index 158d5f8fa045..b8476aab537b 100644 --- a/src/node/test/snapshotter.cpp +++ b/src/node/test/snapshotter.cpp @@ -306,7 +306,7 @@ TEST_CASE("Recovery snapshot endorsement scan bounds ledger entry allocation") std::optional latest_committed_snapshot_path(const fs::path& dir) { - return snapshots::find_latest_committed_snapshot_in_directory(dir); + return ccf::snapshots::find_latest_committed_snapshot_in_directory(dir); } std::optional<::consensus::Index> latest_committed_snapshot_idx( @@ -318,7 +318,7 @@ std::optional<::consensus::Index> latest_committed_snapshot_idx( return std::nullopt; } - return snapshots::get_snapshot_idx_from_file_name(path->filename()); + return ccf::snapshots::get_snapshot_idx_from_file_name(path->filename()); } std::optional<::consensus::Index> latest_committed_snapshot_evidence_idx( @@ -330,7 +330,8 @@ std::optional<::consensus::Index> latest_committed_snapshot_evidence_idx( return std::nullopt; } - return snapshots::get_snapshot_evidence_idx_from_file_name(path->filename()); + return ccf::snapshots::get_snapshot_evidence_idx_from_file_name( + path->filename()); } std::vector read_latest_committed_snapshot_data(const fs::path& dir) diff --git a/src/snapshots/fetch.h b/src/snapshots/fetch.h index 03d43df7c118..84cf1905f580 100644 --- a/src/snapshots/fetch.h +++ b/src/snapshots/fetch.h @@ -2,6 +2,7 @@ // Licensed under the Apache 2.0 License. #pragma once +#include "ccf/ds/json.h" #include "ccf/ds/nonstd.h" #include "ccf/rest_verb.h" #include "ds/internal_logger.h" @@ -59,7 +60,7 @@ } \ } while (0) -namespace snapshots +namespace ccf::snapshots { struct SnapshotResponse { diff --git a/src/snapshots/filenames.h b/src/snapshots/filenames.h index aa7ac55ac7f8..62a36efabe90 100644 --- a/src/snapshots/filenames.h +++ b/src/snapshots/filenames.h @@ -2,16 +2,20 @@ // Licensed under the Apache 2.0 License. #pragma once +#include "ds/files.h" #include "ds/internal_logger.h" -#include "host/time_bound_logger.h" +#include "ds/time_bound_logger.h" #include +#include #include #include +#include #include +#include #include -namespace snapshots +namespace ccf::snapshots { namespace fs = std::filesystem; @@ -46,7 +50,7 @@ namespace snapshots auto ignored_file_name = fmt::format("{}.{}", file_name, snapshot_ignored_file_suffix); { - asynchost::TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Ignoring snapshot file - rename({} to {})", file_name, ignored_file_name)); diff --git a/src/snapshots/snapshot_writer.h b/src/snapshots/snapshot_writer.h index 806e72bcd4dc..98431f390b51 100644 --- a/src/snapshots/snapshot_writer.h +++ b/src/snapshots/snapshot_writer.h @@ -3,9 +3,9 @@ #pragma once #include "ccf/ds/logger.h" -#include "consensus/ledger_enclave_types.h" +#include "ccf/tx_id.h" #include "ds/files.h" -#include "host/time_bound_logger.h" +#include "ds/time_bound_logger.h" #include "snapshots/filenames.h" #include @@ -18,7 +18,7 @@ #include #include -namespace snapshots +namespace ccf::snapshots { namespace fs = std::filesystem; @@ -48,12 +48,12 @@ namespace snapshots SnapshotWriter& operator=(const SnapshotWriter&) = delete; void persist_snapshot( - ::consensus::Index snapshot_idx, - ::consensus::Index evidence_idx, + ccf::SeqNo snapshot_idx, + ccf::SeqNo evidence_idx, const std::vector& snapshot, const std::vector& receipt) { - asynchost::TimeBoundLogger log_if_slow( + ccf::ds::TimeBoundLogger log_if_slow( fmt::format("Committing snapshot - snapshot_idx={}", snapshot_idx)); // e.g. snapshot_100_105 @@ -121,7 +121,7 @@ namespace snapshots snapshot.size() + receipt.size()); { - asynchost::TimeBoundLogger log_sync_if_slow( + ccf::ds::TimeBoundLogger log_sync_if_slow( fmt::format("Syncing snapshot - fsync({})", file_name)); // NOLINTNEXTLINE(concurrency-mt-unsafe) if (fsync(snapshot_fd) == -1) @@ -142,7 +142,7 @@ namespace snapshots auto committed_file_name = fmt::format("{}{}", file_name, snapshot_committed_suffix); { - asynchost::TimeBoundLogger log_rename_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_rename_if_slow(fmt::format( "Renaming snapshot to committed - rename({})", file_name)); files::rename( snapshot_dir / file_name, snapshot_dir / committed_file_name); @@ -169,7 +169,7 @@ namespace snapshots static bool write_all( int fd, const std::string& file_name, const uint8_t* data, size_t size) { - asynchost::TimeBoundLogger log_if_slow(fmt::format( + ccf::ds::TimeBoundLogger log_if_slow(fmt::format( "Writing snapshot data ({} bytes) - write({})", size, file_name)); size_t offset = 0; diff --git a/src/snapshots/test/fetch_header_test.cpp b/src/snapshots/test/fetch_header_test.cpp new file mode 100644 index 000000000000..b1ad3102d128 --- /dev/null +++ b/src/snapshots/test/fetch_header_test.cpp @@ -0,0 +1,4 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the Apache 2.0 License. + +#include "snapshots/fetch.h" diff --git a/src/snapshots/test/filenames_header_test.cpp b/src/snapshots/test/filenames_header_test.cpp new file mode 100644 index 000000000000..4bb0d565d5cf --- /dev/null +++ b/src/snapshots/test/filenames_header_test.cpp @@ -0,0 +1,4 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the Apache 2.0 License. + +#include "snapshots/filenames.h" diff --git a/src/snapshots/test/snapshot_writer_header_test.cpp b/src/snapshots/test/snapshot_writer_header_test.cpp new file mode 100644 index 000000000000..03cac0a6393b --- /dev/null +++ b/src/snapshots/test/snapshot_writer_header_test.cpp @@ -0,0 +1,4 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the Apache 2.0 License. + +#include "snapshots/snapshot_writer.h" From f58d3cb8d6734c8e611007123c66c3c4cd41462e Mon Sep 17 00:00:00 2001 From: achamayou Date: Thu, 10 Sep 2026 07:05:01 +0100 Subject: [PATCH 2/2] Restore logger test configuration with RAII Guard global logger sinks, log level, and timing defaults in the new tests. Cover restoration when an exception unwinds the guarded scope. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: a3c18286-7019-45e6-bd42-2f9ef7e10c48 --- src/ds/test/logger.cpp | 69 ++++++++++++++++++++++++++++++++++++------ 1 file changed, 60 insertions(+), 9 deletions(-) diff --git a/src/ds/test/logger.cpp b/src/ds/test/logger.cpp index 56dd77ca70ff..3c831364f598 100644 --- a/src/ds/test/logger.cpp +++ b/src/ds/test/logger.cpp @@ -5,9 +5,13 @@ #include "ds/time_bound_logger.h" #define DOCTEST_CONFIG_IMPLEMENT_WITH_MAIN +#include #include +#include +#include #include #include +#include TEST_CASE("Thread IDs are provided by the logger headers") { @@ -48,6 +52,29 @@ class TestLogger : public Base using TestTextLogger = TestLogger; using TestJsonLogger = TestLogger; +class ScopedLoggerConfig +{ + const ccf::LoggerLevel previous_level = ccf::logger::config::level(); + const std::chrono::microseconds previous_default_max_time = + ccf::ds::TimeBoundLogger::default_max_time; + std::vector> previous_loggers; + +public: + ScopedLoggerConfig() : + previous_loggers(std::exchange(ccf::logger::config::loggers(), {})) + {} + + ScopedLoggerConfig(const ScopedLoggerConfig&) = delete; + ScopedLoggerConfig& operator=(const ScopedLoggerConfig&) = delete; + + ~ScopedLoggerConfig() + { + ccf::logger::config::loggers() = std::move(previous_loggers); + ccf::logger::config::level() = previous_level; + ccf::ds::TimeBoundLogger::default_max_time = previous_default_max_time; + } +}; + TEST_CASE("Time-bound logger duration formatting") { using ccf::ds::TimeBoundLogger; @@ -65,13 +92,12 @@ TEST_CASE("Time-bound logger captures the configured default") using ccf::ds::TimeBoundLogger; using namespace std::chrono_literals; - const auto previous_default = - std::exchange(TimeBoundLogger::default_max_time, 1s); + const ScopedLoggerConfig restore_config; + TimeBoundLogger::default_max_time = 1s; TimeBoundLogger first("first"); TimeBoundLogger::default_max_time = 2s; TimeBoundLogger second("second"); TimeBoundLogger explicit_threshold("explicit", 3s); - TimeBoundLogger::default_max_time = previous_default; CHECK(first.max_time == 1s); CHECK(second.max_time == 2s); @@ -84,9 +110,8 @@ TEST_CASE("Time-bound logger reports slow operations at the expected level") using namespace std::chrono_literals; std::vector logs; - auto previous_loggers = std::exchange(ccf::logger::config::loggers(), {}); - const auto previous_level = - std::exchange(ccf::logger::config::level(), ccf::LoggerLevel::INFO); + const ScopedLoggerConfig restore_config; + ccf::logger::config::level() = ccf::LoggerLevel::INFO; ccf::logger::config::loggers().emplace_back( std::make_unique(logs)); @@ -103,9 +128,6 @@ TEST_CASE("Time-bound logger reports slow operations at the expected level") timer.start_time -= 200h; } - ccf::logger::config::loggers() = std::move(previous_loggers); - ccf::logger::config::level() = previous_level; - REQUIRE(logs.size() == 2); CHECK(logs[0].contains("info")); CHECK(logs[0].contains("): slow")); @@ -113,6 +135,35 @@ TEST_CASE("Time-bound logger reports slow operations at the expected level") CHECK(logs[1].contains("): very slow")); } +TEST_CASE("Logger test configuration is restored during stack unwinding") +{ + using ccf::ds::TimeBoundLogger; + using namespace std::chrono_literals; + + std::vector logs; + const ScopedLoggerConfig restore_original_config; + TimeBoundLogger::default_max_time = 42s; + ccf::logger::config::level() = ccf::LoggerLevel::DEBUG; + ccf::logger::config::loggers().emplace_back( + std::make_unique(logs)); + const auto* previous_logger = ccf::logger::config::loggers().front().get(); + + auto change_config_then_throw = [&logs]() { + const ScopedLoggerConfig restore_config; + TimeBoundLogger::default_max_time = 1s; + ccf::logger::config::level() = ccf::LoggerLevel::INFO; + ccf::logger::config::loggers().emplace_back( + std::make_unique(logs)); + throw std::runtime_error("Unwind logger configuration"); + }; + CHECK_THROWS_AS(change_config_then_throw(), std::runtime_error); + + CHECK(TimeBoundLogger::default_max_time == 42s); + CHECK(ccf::logger::config::level() == ccf::LoggerLevel::DEBUG); + REQUIRE(ccf::logger::config::loggers().size() == 1); + CHECK(ccf::logger::config::loggers().front().get() == previous_logger); +} + TEST_CASE("Framework logging macros") { std::vector logs;