Quellcode durchsuchen

test(load): crash recovery mid-eviction scenario

Validates v1.6.1 durability + v1.7.0 eviction under hard failure:

  1. Start server, insert 20k docs across 3 writers
  2. Wait for first 'Eviction chunk' log line
  3. Sleep 2s to ensure we're in the eviction storm
  4. kill -9 inserter + server
  5. Restart server with --force-readwrite
  6. Verify every logged ID is byte-exact

The inserter appends each successful ID to /tmp/smartbotic-loadtest-crash/
inserted.log before moving on. The verifier reads that log and checks
every entry — so the test is robust against the inserter being killed
mid-flight.

If recovery is non-trivial, --force-readwrite bypasses the auto-readonly
guard. The operator can inspect server2.log for 'Database booted in
READ-ONLY mode' to see whether the non-trivial path triggered.
fszontagh vor 3 Monaten
Ursprung
Commit
26b45f1983

+ 50 - 0
tests/load_test/README.md

@@ -215,3 +215,53 @@ kill $SERVER_PID
 - No sample during the run ever saw settings shrink
 
 If `bulk.evictedStubCount` is `0`, either the run was too short, or the bulk workload produced less than ~32 MB — raise `duration_sec` or `bulk_writers`.
+
+---
+
+## Test 5 — Crash recovery mid-eviction (`run_crash_test.sh`)
+
+The most complex scenario — starts a server, starts an inserter, waits until eviction has started firing, `kill -9`s both, restarts the server with `--force-readwrite`, and verifies every successfully-logged insert is still retrievable byte-exactly.
+
+This is the one that validates v1.6.1 (snapshot durability + recovery) + v1.7.0 (eviction) working together under a hard failure mode.
+
+### Build
+
+    cd tests/load_test
+    g++ -std=c++20 -O2 -I/usr/include load_test_crash_insert.cpp \
+        -lsmartbotic-db-client $(pkg-config --libs grpc++) \
+        -lspdlog -lfmt -pthread -o load_test_crash_insert
+    g++ -std=c++20 -O2 -I/usr/include load_test_crash_verify.cpp \
+        -lsmartbotic-db-client $(pkg-config --libs grpc++) \
+        -lspdlog -lfmt -pthread -o load_test_crash_verify
+    chmod +x run_crash_test.sh
+
+### Run
+
+    ./run_crash_test.sh
+
+Exit code:
+- 0 — every logged insert recovered byte-exactly (PASS)
+- non-zero — either the server refused to restart or content mismatched (see script output)
+
+### What it does under the hood
+
+1. Wipes `/tmp/smartbotic-loadtest-crash/`, makes fresh dirs
+2. Writes `config_crash.json` based on `config.json` with the crash data dir
+3. Starts server, begins inserting 20k deterministic docs across 3 writer threads
+4. Waits for the first "Eviction chunk" log line, then sleeps 2 s more to ensure we're in the middle of an eviction storm
+5. `kill -9` the inserter + the server
+6. Restarts the server with `--force-readwrite` (accepts auto-readonly non-trivial-recovery state)
+7. Reads every ID that the inserter successfully logged before the crash; verifies content matches `makeContent(i)`
+
+### PASS criteria
+
+- Every ID in `/tmp/smartbotic-loadtest-crash/inserted.log` is retrievable
+- Every content byte-exact matches its expected value
+- Zero not-found, zero mismatches
+
+### If the server refuses to restart (exit code 10)
+
+The recovery system decided the snapshot+WAL combination was unrecoverable. `run_crash_test.sh` then dumps the last 30 lines of `server2.log` — look for `RECOVERY REFUSED`. Escalate manually:
+
+    smartbotic-database --config /tmp/smartbotic-loadtest-crash/config_crash.json \
+        --recovery-mode=snapshot_fallback --force-readwrite

+ 187 - 0
tests/load_test/load_test_crash_insert.cpp

@@ -0,0 +1,187 @@
+// Test 5a — Crash-recovery insert phase
+//
+// Inserts deterministic docs as fast as possible into collection "crash"
+// across `writers` threads. Every successful insert is appended to an
+// on-disk log so the verifier (which runs after kill -9 + restart) can
+// check every "logged" ID independently of whether the inserter was
+// killed mid-flight.
+//
+// Usage: ./load_test_crash_insert [num_docs=20000] [writers=3] [doc_bytes_inner=1500]
+//
+// Designed to be killed by the orchestrator (run_crash_test.sh) once the
+// server has started evicting. Also exits 0 on its own if all N inserts
+// complete; exit 2 if a write fails permanently after retries.
+
+#include <smartbotic/database/client.hpp>
+
+#include <atomic>
+#include <chrono>
+#include <cstdio>
+#include <cstdlib>
+#include <filesystem>
+#include <fstream>
+#include <iomanip>
+#include <iostream>
+#include <mutex>
+#include <string>
+#include <thread>
+#include <vector>
+
+using namespace smartbotic::database;
+using Clock = std::chrono::steady_clock;
+
+// Deterministic content per-id. Includes the id inside the payload so
+// misdirected reads after recovery would fail the content check.
+// `doc_bytes_inner` controls roughly how much filler padding to generate.
+static std::string makeContent(int i, int innerBytes) {
+    std::string tag = "doc-" + std::to_string(i) + "-crash";
+    // Each padded line is ~9 bytes; compute how many lines we need.
+    int lines = innerBytes / 9;
+    if (lines < 1) lines = 1;
+    std::string pad;
+    pad.reserve(lines * 9);
+    for (int k = 0; k < lines; ++k) {
+        char buf[32];
+        std::snprintf(buf, sizeof(buf), "%08d-", i * 1000 + k);
+        pad += buf;
+    }
+    return tag + "-" + pad;
+}
+
+int main(int argc, char* argv[]) {
+    int numDocs = 20000;
+    int writers = 3;
+    int docBytesInner = 1500;
+    if (argc > 1) numDocs = std::stoi(argv[1]);
+    if (argc > 2) writers = std::stoi(argv[2]);
+    if (argc > 3) docBytesInner = std::stoi(argv[3]);
+
+    if (writers < 1) writers = 1;
+
+    const std::string logDir = "/tmp/smartbotic-loadtest-crash";
+    const std::string logPath = logDir + "/inserted.log";
+
+    std::filesystem::create_directories(logDir);
+
+    // Append mode so multiple runs don't clobber. The orchestrator truncates
+    // this between runs.
+    std::ofstream logFile(logPath, std::ios::app);
+    if (!logFile) {
+        std::cerr << "ERROR: could not open log file " << logPath << "\n";
+        return 1;
+    }
+    std::mutex logMutex;
+
+    std::cout << "=== smartbotic-database v1.7.0 load test — crash insert ===\n"
+              << "Server:         localhost:9005\n"
+              << "Target docs:    " << numDocs << "\n"
+              << "Writers:        " << writers << "\n"
+              << "Doc bytes:      ~" << docBytesInner << "\n"
+              << "Log file:       " << logPath << "\n"
+              << "\n";
+
+    Client::Config cfg;
+    cfg.address = "localhost:9005";
+    cfg.timeoutMs = 5000;
+    cfg.writeRetries = 8;
+    cfg.writeRetryBackoffMs = 50;
+    cfg.writeRetryMaxBackoffMs = 2000;
+
+    // Bootstrap connection for collection creation + progress stats.
+    Client boot(cfg);
+    if (!boot.connect()) {
+        std::cerr << "ERROR: initial connect failed\n";
+        return 1;
+    }
+    if (!boot.createCollection("crash")) {
+        std::cout << "(collection 'crash' already exists — continuing)\n";
+    }
+
+    std::atomic<uint64_t> inserted{0};
+    std::atomic<uint64_t> permanentFails{0};
+    std::atomic<bool> done{false};
+    auto t0 = Clock::now();
+
+    std::thread progress([&]() {
+        uint64_t lastInserted = 0;
+        auto lastTick = Clock::now();
+        while (!done.load()) {
+            std::this_thread::sleep_for(std::chrono::milliseconds(500));
+            if (done.load()) break;
+            auto now = Clock::now();
+            auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(
+                now - t0).count();
+            uint64_t cur = inserted.load();
+            auto dt = std::chrono::duration_cast<std::chrono::milliseconds>(
+                now - lastTick).count();
+            double rate = (dt > 0) ? double(cur - lastInserted) * 1000.0 / double(dt) : 0.0;
+            lastInserted = cur;
+            lastTick = now;
+
+            std::cout << "  [t=" << std::setw(6) << elapsed << "ms] "
+                      << "inserted=" << std::setw(7) << cur
+                      << "/" << numDocs
+                      << " fails=" << std::setw(4) << permanentFails.load()
+                      << " rate=" << std::fixed << std::setprecision(0) << rate << " ops/s"
+                      << "\n";
+            std::cout.flush();
+        }
+    });
+
+    auto worker = [&](int threadIndex) {
+        Client wdb(cfg);
+        if (!wdb.connect()) {
+            std::cerr << "[writer " << threadIndex << "] connect failed\n";
+            return;
+        }
+        for (int i = threadIndex; i < numDocs; i += writers) {
+            std::string id = "crash-" + std::to_string(i);
+            nlohmann::json doc{
+                {"i", i},
+                {"content", makeContent(i, docBytesInner)}
+            };
+            try {
+                wdb.insert("crash", doc, id);
+                // Successfully persisted (past client retry loop). Log it to
+                // disk BEFORE moving on so the verifier sees only acked IDs.
+                {
+                    std::lock_guard<std::mutex> lg(logMutex);
+                    logFile << id << "\n";
+                    logFile.flush();
+                }
+                inserted.fetch_add(1, std::memory_order_relaxed);
+            } catch (const std::exception& e) {
+                // Permanently failed after client-side retries. Count it but
+                // do NOT log the id, so the verifier correctly doesn't look
+                // for it post-recovery.
+                permanentFails.fetch_add(1, std::memory_order_relaxed);
+            }
+        }
+    };
+
+    std::vector<std::thread> threads;
+    threads.reserve(writers);
+    for (int t = 0; t < writers; ++t) {
+        threads.emplace_back(worker, t);
+    }
+    for (auto& th : threads) th.join();
+
+    done.store(true);
+    progress.join();
+
+    auto tEnd = Clock::now();
+    auto elapsedMs = std::chrono::duration_cast<std::chrono::milliseconds>(
+        tEnd - t0).count();
+
+    std::cout << "\n=== Insert phase summary ===\n"
+              << "Elapsed:           " << elapsedMs << " ms\n"
+              << "Inserted (logged): " << inserted.load() << "\n"
+              << "Permanent fails:   " << permanentFails.load() << "\n";
+
+    if (permanentFails.load() > 0) {
+        std::cerr << "WARN: some inserts failed permanently after retry — those "
+                  << "IDs are NOT in the log and will not be verified\n";
+        return 2;
+    }
+    return 0;
+}

+ 183 - 0
tests/load_test/load_test_crash_verify.cpp

@@ -0,0 +1,183 @@
+// Test 5b — Crash-recovery verify phase
+//
+// Reads every id from the log file (one per line, written by
+// load_test_crash_insert) and confirms the doc is retrievable from the
+// database with byte-exact content. Exits 0 on full PASS, non-zero if
+// any doc is missing or corrupted.
+//
+// Usage: ./load_test_crash_verify <logged_ids_file>
+
+#include <smartbotic/database/client.hpp>
+
+#include <chrono>
+#include <cstdio>
+#include <cstdlib>
+#include <fstream>
+#include <iomanip>
+#include <iostream>
+#include <string>
+#include <vector>
+
+using namespace smartbotic::database;
+using Clock = std::chrono::steady_clock;
+
+// MUST match load_test_crash_insert::makeContent exactly.
+static std::string makeContent(int i, int innerBytes) {
+    std::string tag = "doc-" + std::to_string(i) + "-crash";
+    int lines = innerBytes / 9;
+    if (lines < 1) lines = 1;
+    std::string pad;
+    pad.reserve(lines * 9);
+    for (int k = 0; k < lines; ++k) {
+        char buf[32];
+        std::snprintf(buf, sizeof(buf), "%08d-", i * 1000 + k);
+        pad += buf;
+    }
+    return tag + "-" + pad;
+}
+
+// Extract the integer suffix after "crash-". Returns -1 on parse failure.
+static int parseIdSuffix(const std::string& id) {
+    const std::string prefix = "crash-";
+    if (id.rfind(prefix, 0) != 0) return -1;
+    try {
+        return std::stoi(id.substr(prefix.size()));
+    } catch (...) {
+        return -1;
+    }
+}
+
+int main(int argc, char* argv[]) {
+    if (argc < 2) {
+        std::cerr << "Usage: " << argv[0] << " <logged_ids_file> [doc_bytes_inner=1500]\n";
+        return 1;
+    }
+    std::string logPath = argv[1];
+    int docBytesInner = 1500;
+    if (argc > 2) docBytesInner = std::stoi(argv[2]);
+
+    std::ifstream in(logPath);
+    if (!in) {
+        std::cerr << "ERROR: could not open log file " << logPath << "\n";
+        return 1;
+    }
+
+    std::vector<std::string> ids;
+    {
+        std::string line;
+        while (std::getline(in, line)) {
+            if (!line.empty()) ids.push_back(line);
+        }
+    }
+
+    std::cout << "=== smartbotic-database v1.7.0 load test — crash verify ===\n"
+              << "Server:         localhost:9005\n"
+              << "Logged IDs:     " << ids.size() << "\n"
+              << "Doc bytes:      ~" << docBytesInner << "\n"
+              << "\n";
+
+    if (ids.empty()) {
+        std::cout << "no IDs to verify — inserter never logged any successful writes\n"
+                  << "Verdict: PASS (vacuously — nothing to check)\n";
+        return 0;
+    }
+
+    Client::Config cfg;
+    cfg.address = "localhost:9005";
+    cfg.timeoutMs = 5000;
+    Client db(cfg);
+    if (!db.connect()) {
+        std::cerr << "ERROR: connect failed — server may still be refusing writes\n";
+        return 1;
+    }
+
+    uint64_t matched = 0;
+    uint64_t mismatched = 0;
+    uint64_t notFound = 0;
+    uint64_t parseError = 0;
+    uint64_t readError = 0;
+    std::vector<std::string> firstMismatches;
+    std::vector<std::string> firstNotFound;
+
+    auto t0 = Clock::now();
+
+    for (size_t idx = 0; idx < ids.size(); ++idx) {
+        const std::string& id = ids[idx];
+        int i = parseIdSuffix(id);
+        if (i < 0) {
+            parseError++;
+            continue;
+        }
+        try {
+            auto doc = db.get("crash", id);
+            if (!doc) {
+                notFound++;
+                if (firstNotFound.size() < 10) firstNotFound.push_back(id);
+                continue;
+            }
+            if (!doc->contains("content")) {
+                mismatched++;
+                if (firstMismatches.size() < 10) firstMismatches.push_back(id);
+                continue;
+            }
+            std::string expected = makeContent(i, docBytesInner);
+            std::string got = (*doc)["content"].get<std::string>();
+            if (got == expected) {
+                matched++;
+            } else {
+                mismatched++;
+                if (firstMismatches.size() < 10) firstMismatches.push_back(id);
+            }
+        } catch (const std::exception&) {
+            readError++;
+        }
+
+        if (idx > 0 && idx % 1000 == 0) {
+            auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(
+                Clock::now() - t0).count();
+            std::cout << "  [t=" << std::setw(6) << elapsed << "ms] "
+                      << "verified=" << std::setw(7) << idx << "/" << ids.size()
+                      << " matched=" << matched
+                      << " mismatch=" << mismatched
+                      << " not-found=" << notFound
+                      << " errors=" << readError
+                      << "\n";
+            std::cout.flush();
+        }
+    }
+
+    auto elapsedMs = std::chrono::duration_cast<std::chrono::milliseconds>(
+        Clock::now() - t0).count();
+
+    std::cout << "\n=== Verify summary ===\n"
+              << "Elapsed:           " << elapsedMs << " ms\n"
+              << "Total logged IDs:  " << ids.size() << "\n"
+              << "  Matched content: " << matched << "\n"
+              << "  Mismatched:      " << mismatched << "\n"
+              << "  Not found:       " << notFound << "\n"
+              << "  Parse errors:    " << parseError << "\n"
+              << "  Read errors:     " << readError << "\n";
+
+    if (!firstMismatches.empty()) {
+        std::cout << "\nFirst content-mismatched ids:";
+        for (const auto& id : firstMismatches) std::cout << " " << id;
+        std::cout << "\n";
+    }
+    if (!firstNotFound.empty()) {
+        std::cout << "First not-found ids:";
+        for (const auto& id : firstNotFound) std::cout << " " << id;
+        std::cout << "\n";
+    }
+
+    bool pass = (mismatched == 0) && (notFound == 0) && (readError == 0)
+             && (parseError == 0)
+             && (matched == ids.size());
+
+    std::cout << "\nVerdict: "
+              << (pass
+                  ? "PASS — every logged insert recovered byte-exactly"
+                  : "FAIL — durability broke across crash boundary")
+              << "\n";
+
+    return pass ? 0 : 2;
+}

+ 143 - 0
tests/load_test/run_crash_test.sh

@@ -0,0 +1,143 @@
+#!/usr/bin/env bash
+# Crash-recovery load test orchestrator.
+#
+# 1) Wipe /tmp/smartbotic-loadtest-crash, write a fresh config pointing at it.
+# 2) Start smartbotic-database, launch load_test_crash_insert in the background.
+# 3) Wait until the server log shows the first "Eviction chunk:" line, then
+#    sleep 2 s to ensure we are firmly inside an eviction storm.
+# 4) kill -9 the inserter + the server.
+# 5) Restart the server with --force-readwrite so any auto-readonly guard from
+#    a non-trivial recovery path is bypassed.
+# 6) Run load_test_crash_verify against the inserted-IDs log and propagate
+#    its exit code.
+#
+# Usage:   ./run_crash_test.sh
+# Exit:    0 on PASS, non-zero on FAIL / orchestration error.
+
+set -euo pipefail
+
+cd "$(dirname "$0")"
+
+DATADIR=/tmp/smartbotic-loadtest-crash
+LOG="$DATADIR/inserted.log"
+CONFIG="./config_crash.json"
+SERVER_ADDR="localhost:9005"
+EVICTION_TIMEOUT_SEC=30
+
+echo "=== Phase 0: reset data dir ==="
+rm -rf "$DATADIR"
+mkdir -p "$DATADIR/data" "$DATADIR/files"
+: > "$LOG"
+
+echo "Generating $CONFIG from ./config.json, overriding data_directory..."
+python3 - "$CONFIG" "$DATADIR" <<'PY'
+import json, sys
+out_path, datadir = sys.argv[1], sys.argv[2]
+with open("config.json") as f:
+    c = json.load(f)
+c["storage"]["data_directory"] = f"{datadir}/data"
+c["storage"]["files"] = {"max_file_size_mb": 100}
+with open(out_path, "w") as f:
+    json.dump(c, f, indent=2)
+PY
+
+cleanup() {
+    # Best-effort cleanup — ignore errors.
+    if [[ -n "${SERVER_PID:-}" ]]; then kill -9 "$SERVER_PID" 2>/dev/null || true; fi
+    if [[ -n "${INSERT_PID:-}" ]]; then kill -9 "$INSERT_PID" 2>/dev/null || true; fi
+}
+trap cleanup EXIT
+
+echo ""
+echo "=== Phase 1: start server + begin inserting ==="
+smartbotic-database --config "$CONFIG" > "$DATADIR/server1.log" 2>&1 &
+SERVER_PID=$!
+sleep 2
+
+if ! kill -0 "$SERVER_PID" 2>/dev/null; then
+    echo "server failed to start:"
+    tail -40 "$DATADIR/server1.log"
+    exit 1
+fi
+
+./load_test_crash_insert 20000 3 1500 > "$DATADIR/insert.log" 2>&1 &
+INSERT_PID=$!
+
+echo "waiting up to ${EVICTION_TIMEOUT_SEC}s for first 'Eviction chunk:' in server log..."
+waited=0
+while ! grep -q "Eviction chunk:" "$DATADIR/server1.log"; do
+    sleep 0.5
+    waited=$((waited + 1))
+    if [ $waited -ge $((EVICTION_TIMEOUT_SEC * 2)) ]; then
+        echo "timed out waiting for eviction — config may be too loose or inserter died early"
+        echo "--- tail server1.log ---"
+        tail -30 "$DATADIR/server1.log"
+        echo "--- tail insert.log ---"
+        tail -30 "$DATADIR/insert.log"
+        exit 1
+    fi
+    # Bail early if the inserter died on us (e.g. server crashed).
+    if ! kill -0 "$INSERT_PID" 2>/dev/null; then
+        echo "inserter exited before eviction fired — see $DATADIR/insert.log"
+        tail -30 "$DATADIR/insert.log"
+        exit 1
+    fi
+done
+first_evict=$(grep -m1 "Eviction chunk:" "$DATADIR/server1.log" | head -c 200)
+echo "first eviction observed: $first_evict"
+
+echo "sleeping 2s to land in the middle of an eviction storm..."
+sleep 2
+
+echo ""
+echo "=== Phase 2: kill -9 inserter + server ==="
+kill -9 "$INSERT_PID" 2>/dev/null || true
+kill -9 "$SERVER_PID" 2>/dev/null || true
+INSERT_PID=""
+SERVER_PID=""
+sleep 1
+
+inserted_count=$(wc -l < "$LOG" | tr -d ' ')
+echo "inserter had logged $inserted_count successful IDs before crash"
+
+if [ "$inserted_count" -eq 0 ]; then
+    echo "inserter logged zero successful writes — nothing to verify, orchestration failure"
+    echo "--- tail insert.log ---"
+    tail -30 "$DATADIR/insert.log"
+    exit 1
+fi
+
+echo ""
+echo "=== Phase 3: restart server with --force-readwrite ==="
+smartbotic-database --config "$CONFIG" --force-readwrite > "$DATADIR/server2.log" 2>&1 &
+SERVER_PID=$!
+sleep 3
+
+if ! kill -0 "$SERVER_PID" 2>/dev/null; then
+    echo "server failed to restart — possible RECOVERY REFUSED"
+    echo "--- tail server2.log ---"
+    tail -30 "$DATADIR/server2.log"
+    exit 1
+fi
+
+if grep -q "Database booted in READ-ONLY mode after non-trivial" "$DATADIR/server2.log"; then
+    echo "note: non-trivial recovery triggered auto-readonly; --force-readwrite accepted it"
+fi
+
+echo ""
+echo "=== Phase 4: verify every logged ID ==="
+set +e
+./load_test_crash_verify "$LOG"
+VERDICT=$?
+set -e
+
+kill "$SERVER_PID" 2>/dev/null || true
+SERVER_PID=""
+
+echo ""
+if [ "$VERDICT" -eq 0 ]; then
+    echo "=== Orchestrator: PASS ==="
+else
+    echo "=== Orchestrator: FAIL (verifier exit=$VERDICT) ==="
+fi
+exit "$VERDICT"