Make snapshots acyclic and align private namespaces

CMakeLists.txt

@@ -651,6 +651,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(
@@ -715,6 +716,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)
 
@@ -1618,6 +1621,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)
 

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"]
   }
 }

src/ds/test/logger.cpp

@@ -2,10 +2,16 @@
 // 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 <chrono>
 #include <doctest/doctest.h>
+#include <memory>
+#include <stdexcept>
 #include <thread>
+#include <utility>
+#include <vector>
 
 TEST_CASE("Thread IDs are provided by the logger headers")
 {
@@ -46,6 +52,118 @@ class TestLogger : public Base
 using TestTextLogger = TestLogger<ccf::logger::TextConsoleLogger>;
 using TestJsonLogger = TestLogger<ccf::logger::JsonConsoleLogger>;
 
+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<std::unique_ptr<ccf::logger::AbstractLogger>> 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;
+  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 ScopedLoggerConfig restore_config;
+  TimeBoundLogger::default_max_time = 1s;
+  TimeBoundLogger first("first");
+  TimeBoundLogger::default_max_time = 2s;
+  TimeBoundLogger second("second");
+  TimeBoundLogger explicit_threshold("explicit", 3s);
+
+  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<std::string> logs;
+  const ScopedLoggerConfig restore_config;
+  ccf::logger::config::level() = ccf::LoggerLevel::INFO;
+  ccf::logger::config::loggers().emplace_back(
+    std::make_unique<TestTextLogger>(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;
+  }
+
+  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("Logger test configuration is restored during stack unwinding")
+{
+  using ccf::ds::TimeBoundLogger;
+  using namespace std::chrono_literals;
+
+  std::vector<std::string> 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<TestTextLogger>(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<TestTextLogger>(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<std::string> logs;

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"

src/host/time_bound_logger.h → src/ds/time_bound_logger.h

@@ -7,8 +7,9 @@
 #include <chrono>
 #include <fmt/format.h>
 #include <string>
+#include <utility>
 
-namespace asynchost
+namespace ccf::ds
 {
   struct TimeBoundLogger
   {

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 <algorithm>
@@ -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<uint8_t> 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<char*>(buf.data()), buf.size()) ||
                f.gcount() > 0)
@@ -234,7 +234,8 @@ namespace asynchost
       std::vector<std::filesystem::path> 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<size_t> 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);
         }