diff --git a/CMakeLists.txt b/CMakeLists.txt index f382495388f..b2fb6b5be1a 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -637,11 +637,6 @@ if(BUILD_TESTS) ) target_link_libraries(openapi_test PRIVATE http_parser) - add_unit_test( - logger_json_test - ${CMAKE_CURRENT_SOURCE_DIR}/src/ds/test/logger_json_test.cpp - ) - add_unit_test( kv_test ${CMAKE_CURRENT_SOURCE_DIR}/src/kv/test/kv_test.cpp diff --git a/src/crypto/test/cbor.cpp b/src/crypto/test/cbor.cpp index 733eca76674..1d6b957439d 100644 --- a/src/crypto/test/cbor.cpp +++ b/src/crypto/test/cbor.cpp @@ -5,6 +5,7 @@ #include "ccf/ds/hex.h" +#include #include #include #include @@ -1646,28 +1647,41 @@ TEST_CASE("CBOR: tagged array Tag(20000, [{'x': 1}, {'y': 2}])") REQUIRE(result == expected_repr); } -TEST_CASE("CBOR: helper function make_signed") +// See +// https://github.com/doctest/doctest/blob/master/doc/markdown/parameterized-tests.md +#define DOCTEST_VALUE_PARAMETERIZED_DATA(data, data_container) \ + static size_t _doctest_subcase_idx = 0; \ + std::for_each( \ + data_container.begin(), data_container.end(), [&](const auto& in) { \ + DOCTEST_SUBCASE((std::string(#data_container "[") + \ + std::to_string(_doctest_subcase_idx++) + "]") \ + .c_str()) \ + { \ + data = in; \ + } \ + }); \ + _doctest_subcase_idx = 0 + +TEST_CASE("CBOR: helper function make_signed with positive and negative values") { - auto value = make_signed(42); - REQUIRE(value != nullptr); - REQUIRE(value->as_signed() == 42); + std::vector> signed_cases{ + {42, "Signed: 42"}, {-42, "Signed: -42"}}; - const std::string expected_repr = "Signed: 42"; - const std::string result = to_string(value); - REQUIRE(result == expected_repr); -} + std::pair test_case; + DOCTEST_VALUE_PARAMETERIZED_DATA(test_case, signed_cases); -TEST_CASE("CBOR: helper function make_signed") -{ - auto value = make_signed(-42); + const auto& [input_value, expected_repr] = test_case; + + auto value = make_signed(input_value); REQUIRE(value != nullptr); - REQUIRE(value->as_signed() == -42); + REQUIRE(value->as_signed() == input_value); - const std::string expected_repr = "Signed: -42"; const std::string result = to_string(value); REQUIRE(result == expected_repr); } +#undef DOCTEST_VALUE_PARAMETERIZED_DATA + TEST_CASE("CBOR: helper function make_string") { auto value = make_string("hello"); diff --git a/src/ds/test/logger.cpp b/src/ds/test/logger.cpp index 42916f8981c..2e4d2a3aae6 100644 --- a/src/ds/test/logger.cpp +++ b/src/ds/test/logger.cpp @@ -5,6 +5,10 @@ #define DOCTEST_CONFIG_IMPLEMENT_WITH_MAIN #include +#include +#include +#include +#include template class TestLogger : public Base @@ -178,4 +182,77 @@ TEST_CASE("Custom logging macros") } ccf::logger::config::loggers().clear(); -} \ No newline at end of file +} + +TEST_CASE("Test custom log format") +{ + auto test_log_file = + (std::filesystem::temp_directory_path() / + ("test_json_logger_" + std::to_string(::getpid()) + ".txt")) + .string(); + std::error_code ec; + std::filesystem::remove(test_log_file, ec); + + struct LoggerConfigGuard + { + ccf::LoggerLevel old_level = ccf::logger::config::level(); + ~LoggerConfigGuard() + { + ccf::logger::config::loggers().clear(); + ccf::logger::config::level() = old_level; + } + }; + LoggerConfigGuard logger_config_guard; + + // Start from a clean logger set so this test does not depend on loggers + // registered by earlier test cases sharing this binary. + ccf::logger::config::loggers().clear(); + ccf::logger::config::add_json_console_logger(); + ccf::logger::config::level() = ccf::LoggerLevel::DEBUG; + std::string log_msg_debug = "log_msg_debug"; + std::string log_msg_trace = "log_msg_trace"; + + struct CoutRdbufGuard + { + std::streambuf* old_buf = nullptr; + explicit CoutRdbufGuard(std::streambuf* new_buf) : + old_buf(std::cout.rdbuf(new_buf)) + {} + ~CoutRdbufGuard() + { + std::cout.rdbuf(old_buf); + } + }; + + { + std::ofstream out(test_log_file); + REQUIRE(out.is_open()); + CoutRdbufGuard cout_guard(out.rdbuf()); + + LOG_DEBUG_FMT("{}", log_msg_debug); + LOG_TRACE_FMT("{}", log_msg_trace); + LOG_DEBUG_FMT("{}", log_msg_debug); + LOG_TRACE_FMT("{}", log_msg_trace); + LOG_DEBUG_FMT("{}", log_msg_debug); + + std::cout.flush(); + } + std::ifstream f(test_log_file); + std::string line; + size_t line_count = 0; + while (std::getline(f, line)) + { + line_count++; + auto j = nlohmann::json::parse(line); + auto host_ts = j.find("h_ts"); + REQUIRE(host_ts != j.end()); + REQUIRE(j["msg"] == log_msg_debug); + REQUIRE(j["file"] == __FILE__); + auto line_number = j.find("number"); + REQUIRE(line_number != j.end()); + REQUIRE(j["level"] == "debug"); + } + f.close(); + std::filesystem::remove(test_log_file, ec); + REQUIRE(line_count == 3); +} diff --git a/src/ds/test/logger_json_test.cpp b/src/ds/test/logger_json_test.cpp deleted file mode 100644 index 5f77f076aa6..00000000000 --- a/src/ds/test/logger_json_test.cpp +++ /dev/null @@ -1,50 +0,0 @@ -// Copyright (c) Microsoft Corporation. All rights reserved. -// Licensed under the Apache 2.0 License. -#include "ds/internal_logger.h" - -#define DOCTEST_CONFIG_IMPLEMENT_WITH_MAIN -#include -#include -#include - -TEST_CASE("Test custom log format") -{ - std::string test_log_file = "./test_json_logger.txt"; - remove(test_log_file.c_str()); - ccf::logger::config::add_json_console_logger(); - ccf::logger::config::level() = ccf::LoggerLevel::DEBUG; - std::string log_msg_dbg = "log_msg_dbg"; - std::string log_msg_trace = "log_msg_trace"; - - std::ofstream out(test_log_file.c_str()); - std::streambuf* coutbuf = std::cout.rdbuf(); - std::cout.rdbuf(out.rdbuf()); - - LOG_DEBUG_FMT("{}", log_msg_dbg); - LOG_TRACE_FMT("{}", log_msg_trace); - LOG_DEBUG_FMT("{}", log_msg_dbg); - LOG_TRACE_FMT("{}", log_msg_trace); - LOG_DEBUG_FMT("{}", log_msg_dbg); - - out.flush(); - out.close(); - - std::cout.rdbuf(coutbuf); - - std::ifstream f(test_log_file); - std::string line; - size_t line_count = 0; - while (std::getline(f, line)) - { - line_count++; - auto j = nlohmann::json::parse(line); - auto host_ts = j.find("h_ts"); - REQUIRE(host_ts != j.end()); - REQUIRE(j["msg"] == log_msg_dbg); - REQUIRE(j["file"] == __FILE__); - auto line_number = j.find("number"); - REQUIRE(line_number != j.end()); - REQUIRE(j["level"] == "debug"); - } - REQUIRE(line_count == 3); -} diff --git a/src/http/test/http_test.cpp b/src/http/test/http_test.cpp index 627637041ff..7d37275a475 100644 --- a/src/http/test/http_test.cpp +++ b/src/http/test/http_test.cpp @@ -703,136 +703,68 @@ DOCTEST_TEST_CASE("Query parser getters") } } -DOCTEST_TEST_CASE("parse_want_repr_digest - single supported algorithm") +DOCTEST_TEST_CASE("parse_want_repr_digest") { - { - auto [algo, md] = ccf::http::parse_want_repr_digest("sha-256=1"); - DOCTEST_CHECK(algo == "sha-256"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA256); - } - - { - auto [algo, md] = ccf::http::parse_want_repr_digest("sha-384=5"); - DOCTEST_CHECK(algo == "sha-384"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA384); - } - - { - auto [algo, md] = ccf::http::parse_want_repr_digest("sha-512=10"); - DOCTEST_CHECK(algo == "sha-512"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA512); - } -} - -DOCTEST_TEST_CASE( - "parse_want_repr_digest - multiple algorithms with priorities") -{ - { - auto [algo, md] = - ccf::http::parse_want_repr_digest("sha-256=1, sha-512=10"); - DOCTEST_CHECK(algo == "sha-512"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA512); - } + auto check = []( + const std::string& header, + const std::string& expected_algo, + ccf::crypto::MDType expected_md) { + auto [algo, md] = ccf::http::parse_want_repr_digest(header); + DOCTEST_CHECK(algo == expected_algo); + DOCTEST_CHECK(md == expected_md); + }; + DOCTEST_SUBCASE("single supported algorithm") { - auto [algo, md] = - ccf::http::parse_want_repr_digest("sha-512=3, sha-256=7, sha-384=5"); - DOCTEST_CHECK(algo == "sha-256"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA256); + check("sha-256=1", "sha-256", ccf::crypto::MDType::SHA256); + check("sha-384=5", "sha-384", ccf::crypto::MDType::SHA384); + check("sha-512=10", "sha-512", ccf::crypto::MDType::SHA512); } + DOCTEST_SUBCASE("multiple algorithms with priorities") { - auto [algo, md] = - ccf::http::parse_want_repr_digest("sha-384=10, sha-256=10"); + check("sha-256=1, sha-512=10", "sha-512", ccf::crypto::MDType::SHA512); + check( + "sha-512=3, sha-256=7, sha-384=5", + "sha-256", + ccf::crypto::MDType::SHA256); // Equal preference - first one wins - DOCTEST_CHECK(algo == "sha-384"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA384); - } -} - -DOCTEST_TEST_CASE("parse_want_repr_digest - unknown algorithms are ignored") -{ - { - auto [algo, md] = ccf::http::parse_want_repr_digest("md5=10, sha-256=1"); - DOCTEST_CHECK(algo == "sha-256"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA256); + check("sha-384=10, sha-256=10", "sha-384", ccf::crypto::MDType::SHA384); } + DOCTEST_SUBCASE("unknown algorithms are ignored") { - auto [algo, md] = - ccf::http::parse_want_repr_digest("crc32=5, sha-384=3, unknown=10"); - DOCTEST_CHECK(algo == "sha-384"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA384); + check("md5=10, sha-256=1", "sha-256", ccf::crypto::MDType::SHA256); + check( + "crc32=5, sha-384=3, unknown=10", "sha-384", ccf::crypto::MDType::SHA384); } -} -DOCTEST_TEST_CASE("parse_want_repr_digest - defaults to sha-256 when no match") -{ + DOCTEST_SUBCASE("defaults to sha-256 when no match") { - auto [algo, md] = ccf::http::parse_want_repr_digest("md5=10"); - DOCTEST_CHECK(algo == "sha-256"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA256); + check("md5=10", "sha-256", ccf::crypto::MDType::SHA256); + check("unknown=5", "sha-256", ccf::crypto::MDType::SHA256); + check("", "sha-256", ccf::crypto::MDType::SHA256); } - { - auto [algo, md] = ccf::http::parse_want_repr_digest("unknown=5"); - DOCTEST_CHECK(algo == "sha-256"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA256); - } - - { - auto [algo, md] = ccf::http::parse_want_repr_digest(""); - DOCTEST_CHECK(algo == "sha-256"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA256); - } -} - -DOCTEST_TEST_CASE("parse_want_repr_digest - malformed entries are skipped") -{ + DOCTEST_SUBCASE("malformed entries are skipped") { // Preference of 0 is invalid (must be >= 1) - auto [algo, md] = ccf::http::parse_want_repr_digest("sha-256=0"); - DOCTEST_CHECK(algo == "sha-256"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA256); - } - - { + check("sha-256=0", "sha-256", ccf::crypto::MDType::SHA256); // Negative preference is invalid - auto [algo, md] = ccf::http::parse_want_repr_digest("sha-512=-1"); - DOCTEST_CHECK(algo == "sha-256"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA256); - } - - { + check("sha-512=-1", "sha-256", ccf::crypto::MDType::SHA256); // Non-numeric preference is skipped, but valid entry is used - auto [algo, md] = - ccf::http::parse_want_repr_digest("sha-256=abc, sha-384=5"); - DOCTEST_CHECK(algo == "sha-384"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA384); + check("sha-256=abc, sha-384=5", "sha-384", ccf::crypto::MDType::SHA384); } -} -DOCTEST_TEST_CASE("parse_want_repr_digest - whitespace handling") -{ + DOCTEST_SUBCASE("whitespace handling") { - auto [algo, md] = ccf::http::parse_want_repr_digest(" sha-256 = 1 "); - DOCTEST_CHECK(algo == "sha-256"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA256); + check(" sha-256 = 1 ", "sha-256", ccf::crypto::MDType::SHA256); + check("sha-256=1 , sha-512=10", "sha-512", ccf::crypto::MDType::SHA512); } + DOCTEST_SUBCASE("algorithm without explicit preference") { - auto [algo, md] = - ccf::http::parse_want_repr_digest("sha-256=1 , sha-512=10"); - DOCTEST_CHECK(algo == "sha-512"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA512); + // No "=" means preference defaults to 1 + check("sha-512", "sha-512", ccf::crypto::MDType::SHA512); } -} - -DOCTEST_TEST_CASE( - "parse_want_repr_digest - algorithm without explicit preference") -{ - // No "=" means preference defaults to 1 - auto [algo, md] = ccf::http::parse_want_repr_digest("sha-512"); - DOCTEST_CHECK(algo == "sha-512"); - DOCTEST_CHECK(md == ccf::crypto::MDType::SHA512); } \ No newline at end of file diff --git a/tests/e2e_logging.py b/tests/e2e_logging.py index 12ab0e72663..c2c293985c6 100644 --- a/tests/e2e_logging.py +++ b/tests/e2e_logging.py @@ -29,6 +29,7 @@ import random import re import infra.crypto +import infra.commit from infra.runner import ConcurrentRunner from hashlib import sha256 from infra.member import AckException @@ -1871,43 +1872,37 @@ def test_tx_statuses(network, args): return network -@reqs.description("Running transactions against logging app") -@reqs.supports_methods("/app/receipt", "/app/log/private") -@reqs.at_least_n_nodes(2) @app.scoped_txs() -def test_receipts(network, args): +def issue_txs_for_receipt_check(network, args): + """ + Issue a batch of fresh private-only transactions, and record their + seqnos (and expected, empty claims digest) so that test_random_receipts + can validate that their receipts become available promptly after commit, + alongside its regular random sampling of already-committed seqnos. + Waits for all transactions to be committed before returning, and returns a + mapping of seqno -> expected claims digest (None outside the COSE case). + """ cose_only = args.package.endswith("_cose_only") - primary, _ = network.find_primary_and_any_backup() msg = "Hello world" - LOG.info("Write/Read on primary") - if cose_only: - service_key = get_service_key(network) - with primary.client("user0") as c: - for j in range(10): - idx = j + 10000 - r = network.txs.issue(network, 1, idx=idx, send_public=False, msg=msg) - fetch_and_verify_cose_receipt( - c, r.view, r.seqno, service_key, b"\0" * 32 - ) - else: - with primary.client("user0") as c: - for j in range(10): - idx = j + 10000 - r = network.txs.issue(network, 1, idx=idx, send_public=False, msg=msg) - start_time = time.time() - while time.time() < (start_time + 3.0): - rc = c.get(f"/app/receipt?transaction_id={r.view}.{r.seqno}") - if rc.status_code == http.HTTPStatus.OK: - receipt = rc.body.json() - verify_receipt(receipt, network.cert) - break - elif rc.status_code == http.HTTPStatus.ACCEPTED: - time.sleep(0.5) - else: - assert False, rc + LOG.info("Write on primary") + additional_seqnos = {} + last_view = None + last_seqno = None + for j in range(10): + idx = j + 10000 + r = network.txs.issue(network, 1, idx=idx, send_public=False, msg=msg) + additional_seqnos[r.seqno] = b"\0" * 32 if cose_only else None + last_view = r.view + last_seqno = r.seqno + + # Wait for the last transaction to be committed (which guarantees all + # earlier transactions are also committed, since they commit in order) + primary, _ = network.find_primary() + with primary.client("user0") as c: + infra.commit.wait_for_commit(c, seqno=last_seqno, view=last_view, timeout=3) - return network + return additional_seqnos @reqs.description("Validate random receipts") @@ -1920,6 +1915,7 @@ def test_random_receipts( additional_seqnos=MappingProxyType({}), node=None, log_capture=None, + require_additional_receipts=False, ): cose_only = args.package.endswith("_cose_only") @@ -1960,6 +1956,11 @@ def claims_digest_from_receipt(receipt_bytes): interesting_prefix = [genesis_seqno, likely_first_sig_seqno] seqnos = range(len(interesting_prefix) + 1, max_seqno) random_sample_count = 20 if lts else 50 + # Track which of the known, already-committed additional_seqnos we + # successfully fetched and verified a receipt for, so that a receipt + # which never becomes available fails loudly rather than being + # silently skipped when the per-seqno poll loop times out. + verified_additional_seqnos = set() for s in ( interesting_prefix + sorted( @@ -1986,6 +1987,7 @@ def claims_digest_from_receipt(receipt_bytes): assert ( claim_digest == additional_seqnos[s] ), f"Claim digest mismatch for seqno {s}" + verified_additional_seqnos.add(s) ccf.cose.verify_receipt( receipt_bytes, service_key, claim_digest ) @@ -2027,6 +2029,8 @@ def claims_digest_from_receipt(receipt_bytes): generic=True, skip_cert_chain_checks=lts, ) + if s in additional_seqnos: + verified_additional_seqnos.add(s) break elif rc.status_code == http.HTTPStatus.ACCEPTED: time.sleep(0.1) @@ -2035,6 +2039,13 @@ def claims_digest_from_receipt(receipt_bytes): if view > max_view: assert False, rc + if require_additional_receipts: + missing = set(additional_seqnos) - verified_additional_seqnos + assert not missing, ( + "Receipts for known-committed seqnos were never verified: " + f"{sorted(missing)}" + ) + return network @@ -2680,9 +2691,17 @@ def do_main_tests(network, args): test_liveness(network, args) test_rekey(network, args) test_liveness(network, args) - test_random_receipts(network, args, False) + additional_seqnos = {} + if args.package.startswith("samples/apps/logging/logging"): + additional_seqnos = issue_txs_for_receipt_check(network, args) + test_random_receipts( + network, + args, + False, + additional_seqnos=additional_seqnos, + require_additional_receipts=True, + ) if args.package.startswith("samples/apps/logging/logging"): - test_receipts(network, args) test_historical_query_sparse(network, args) test_historical_receipts(network, args) test_historical_receipts_with_claims(network, args)