diff --git a/.gitignore b/.gitignore index 4d298d1..51a6c82 100755 --- a/.gitignore +++ b/.gitignore @@ -7,6 +7,7 @@ build **/fastrg_northbound **/.libs unit_test/unit-tester +northbound/controller/test/test_etcd_watch_teardown **/*.gcda **/*.gcno coverage/ diff --git a/e2e_test/phases/local_validation_fixtures.txt b/e2e_test/phases/local_validation_fixtures.txt index 95f632b..2e9445c 100644 --- a/e2e_test/phases/local_validation_fixtures.txt +++ b/e2e_test/phases/local_validation_fixtures.txt @@ -998,3 +998,73 @@ Error: 401 Unauthorized # expect-output: err # expect-status: 1 --- +==== fixture: node_shutdown_clean +# expect-output: pass +# expect-status: 0 +--- +log: ok +log_last: FastRG[INFO][2026-10-09 03:17:05]: src/fastrg.c:915> bye! +apport: ok +kernel: ok +==== fixture: node_shutdown_abort_without_bye +# expect-output: no_bye +# expect-status: 1 +--- +log: ok +log_last: malloc_consolidate(): unaligned fastbin chunk detected +apport: ok +apport_new: INFO: apport (pid 80952) 2026-10-09 00:00:10,762: executable: /root/fastrg/fastrg-node/fastrg (command line "/root/fastrg/fastrg-node/fastrg -l 1-8 -n 4 --socket-mem 17408 -a 0000:07:00.0 -a 0000:08:00.0") +kernel: ok +==== fixture: node_shutdown_bye_not_last +# expect-output: no_bye +# expect-status: 1 +--- +log: ok +log_last: free(): invalid pointer +apport: ok +kernel: ok +==== fixture: node_shutdown_apport_record +# expect-output: apport_record +# expect-status: 1 +--- +log: ok +log_last: FastRG[INFO][2026-10-09 03:17:05]: src/fastrg.c:915> bye! +apport: ok +apport_new: INFO: apport (pid 80952) 2026-10-09 00:00:10,762: executable: /root/fastrg/fastrg-node/fastrg (command line "/root/fastrg/fastrg-node/fastrg -l 1-8 -n 4 --socket-mem 17408 -a 0000:07:00.0 -a 0000:08:00.0") +kernel: ok +==== fixture: node_shutdown_kernel_trap +# expect-output: kernel_trap +# expect-status: 1 +--- +log: ok +log_last: FastRG[INFO][2026-10-09 03:17:05]: src/fastrg.c:915> bye! +apport: ok +kernel: ok +kernel_new: Oct 08 23:33:50 openrg-node kernel: traps: fastrg[51080] general protection fault ip:75335c8a9d3d sp:7ffe0e411340 error:0 in libc.so.6[75335c828000+189000] +==== fixture: node_shutdown_log_unreadable +# expect-output: collector_failed +# expect-status: 1 +--- +log: unreadable +apport: ok +kernel: ok +==== fixture: node_shutdown_apport_unhooked +# expect-output: collector_failed +# expect-status: 1 +--- +log: ok +log_last: FastRG[INFO][2026-10-09 03:17:05]: src/fastrg.c:915> bye! +apport: unhooked +kernel: ok +==== fixture: node_shutdown_kernel_unreadable +# expect-output: collector_failed +# expect-status: 1 +--- +log: ok +log_last: FastRG[INFO][2026-10-09 03:17:05]: src/fastrg.c:915> bye! +apport: ok +kernel: unreadable +==== fixture: node_shutdown_no_evidence +# expect-output: collector_failed +# expect-status: 1 +--- diff --git a/e2e_test/phases/node_shutdown_lib.sh b/e2e_test/phases/node_shutdown_lib.sh new file mode 100644 index 0000000..e2be8b5 --- /dev/null +++ b/e2e_test/phases/node_shutdown_lib.sh @@ -0,0 +1,163 @@ +#!/usr/bin/env bash +# shellcheck shell=bash +# --------------------------------------------------------------------------- +# Crash check for a SIGTERM stop of the node, shared by every step that stops +# fastrg. The process being gone does not prove a clean stop: a crash during +# teardown ends it too. A clean stop ends the node's stdout log with "bye!" +# and leaves no new apport record and no new kernel trap line. +# +# Usage: take a mark before the SIGTERM, check it once the process is gone. +# _mark=$(e2e_node_stop_mark) +# ssh_node "pkill -x fastrg"; +# _crash=$(e2e_node_shutdown_check "$_mark") || _issue="... ${_crash}" +# --------------------------------------------------------------------------- + +# Run on the node before the SIGTERM. Prints " +# "; the stdout file is "-" when fastrg is not running +# or its stdout is not a regular file. +_E2E_NODE_STOP_MARK_SCRIPT=' +pid=$(pgrep -xo fastrg) +out=- +[ -n "$pid" ] && out=$(readlink -f "/proc/$pid/fd/1" 2>/dev/null) +[ -f "$out" ] || out=- +printf "%s %s %s\n" "$out" "$(stat -c "%i %s" /var/log/apport.log 2>/dev/null || echo "- 0")" "$(date +%s)" +' + +# Run on the node after the stop, with LOG/INODE/SIZE/SINCE set from the mark. +# Each source reports ": ok" only when it could really be read, so a +# broken collector never reads as "no crash"; apport counts only while it is +# the core handler, and the kernel source must hold at least one line. +_E2E_NODE_SHUTDOWN_EVIDENCE_SCRIPT=' +if [ -f "$LOG" ] && [ -r "$LOG" ]; then + echo "log: ok" + printf "log_last: %s\n" "$(tail -n 50 "$LOG" | grep -av "^[[:space:]]*$" | tail -n 1)" +else + echo "log: unreadable" +fi +A=/var/log/apport.log +case "$(cat /proc/sys/kernel/core_pattern 2>/dev/null)" in +*apport*) + if [ -e "$A" ] && [ ! -r "$A" ]; then + echo "apport: unreadable" + else + echo "apport: ok" + if [ "$(stat -c %i "$A" 2>/dev/null || echo -)" = "$INODE" ]; then + tail -c +"$((SIZE + 1))" "$A" 2>/dev/null + else + [ "$INODE" = - ] || tail -c +"$((SIZE + 1))" "$A.1" 2>/dev/null + cat "$A" 2>/dev/null + fi | grep -aE "executable: [^ ]*/fastrg( |$)" | sed "s/^/apport_new: /" + fi + ;; +*) + echo "apport: unhooked" + ;; +esac +if journalctl -k -n 1 -q --no-pager 2>/dev/null | grep -q . && + KLOG=$(journalctl -k -q --no-pager --since "@$SINCE" 2>/dev/null); then + echo "kernel: ok" + printf "%s\n" "$KLOG" | grep -aE "traps: |segfault at |general protection" | sed "s/^/kernel_new: /" +else + echo "kernel: unreadable" +fi +' + +# Where the coming stop's crash evidence starts. Empty when the node could not +# be reached, which the check reports as a collector failure. +e2e_node_stop_mark() { + ssh_node "$_E2E_NODE_STOP_MARK_SCRIPT" 2>/dev/null | tail -n 1 || true +} + +# The evidence a stop left on the node since a mark: the ": ok" lines +# plus log_last / apport_new / kernel_new lines. Wrapped so a drill can alter it. +_e2e_node_shutdown_evidence() { + local _log="$1" _inode="$2" _size="$3" _since="$4" + + ssh_node "LOG=$(printf '%q' "$_log"); INODE=$(printf '%q' "$_inode"); + SIZE=$(printf '%q' "$_size"); SINCE=$(printf '%q' "$_since"); + ${_E2E_NODE_SHUTDOWN_EVIDENCE_SCRIPT}" 2>/dev/null || true +} + +# Verdict on a stop's evidence: pass | collector_failed | no_bye | +# apport_record | kernel_trap. +e2e_node_shutdown_verdict() { + local _evidence="${1:-}" _source _last + + for _source in log apport kernel; do + if ! printf '%s\n' "$_evidence" | grep -qx "${_source}: ok"; then + printf 'collector_failed' + return 1 + fi + done + _last=$(printf '%s\n' "$_evidence" | sed -n 's/^log_last: //p' | tail -n 1) + if [[ "$_last" != *'bye!' ]]; then + printf 'no_bye' + return 1 + fi + if printf '%s\n' "$_evidence" | grep -q '^apport_new: '; then + printf 'apport_record' + return 1 + fi + if printf '%s\n' "$_evidence" | grep -q '^kernel_new: '; then + printf 'kernel_trap' + return 1 + fi + printf 'pass' + return 0 +} + +local_validation_register node_shutdown_verdict e2e_node_shutdown_verdict \ + node_shutdown_clean \ + node_shutdown_abort_without_bye \ + node_shutdown_bye_not_last \ + node_shutdown_apport_record \ + node_shutdown_kernel_trap \ + node_shutdown_log_unreadable \ + node_shutdown_apport_unhooked \ + node_shutdown_kernel_unreadable \ + node_shutdown_no_evidence + +# Prints "pass" after a clean stop; otherwise the verdict with the evidence +# behind it, and returns non-zero. Read-only on the node. +e2e_node_shutdown_check() { + local _mark="${1:-}" _log="" _inode="" _size="" _since="" _evidence="" _verdict="" + + read -r _log _inode _size _since <<< "$_mark" || true + if [[ -z "$_log" || ! "$_inode" =~ ^([0-9]+|-)$ || ! "$_size" =~ ^[0-9]+$ || \ + ! "$_since" =~ ^[0-9]+$ ]]; then + printf "collector_failed (no usable stop mark: '%s')" "$_mark" + return 1 + fi + _evidence=$(_e2e_node_shutdown_evidence "$_log" "$_inode" "$_size" "$_since") + if _verdict=$(e2e_node_shutdown_verdict "$_evidence"); then + printf 'pass' + return 0 + fi + case "$_verdict" in + no_bye) + printf "no_bye (%s last line: '%s')" "$_log" \ + "$(printf '%s\n' "$_evidence" | sed -n 's/^log_last: //p' | tail -n 1 | cut -c 1-200)" ;; + apport_record) + printf "apport_record (%s)" \ + "$(printf '%s\n' "$_evidence" | sed -n 's/^apport_new: //p' | head -n 1 | cut -c 1-200)" ;; + kernel_trap) + printf "kernel_trap (%s)" \ + "$(printf '%s\n' "$_evidence" | sed -n 's/^kernel_new: //p' | head -n 1 | cut -c 1-200)" ;; + *) + printf "%s (stdout log %s; evidence: '%s')" "${_verdict:-collector_failed}" "$_log" \ + "$(printf '%s' "$_evidence" | grep -E '^(log|apport|kernel): ' | tr '\n' ' ')" ;; + esac + return 1 +} + +# Drill: the stop's stdout log loses its "bye!", as a crash in teardown leaves +# it. The phase's own cleanup restores the real collector via the function below. +_e2e_inject_node_shutdown_no_bye() { + sabotage_copy_function _e2e_node_shutdown_evidence _e2e_node_shutdown_evidence_real + sabotage_override_function _e2e_node_shutdown_evidence \ + '_e2e_node_shutdown_evidence_real "$@" | sed "/^log_last: /s/bye!/(no bye)/"' +} + +_e2e_restore_node_shutdown_functions() { + restore_phase_functions node_shutdown_lib.sh +} diff --git a/e2e_test/phases/phase17_etcd_offline_queue.sh b/e2e_test/phases/phase17_etcd_offline_queue.sh index 7d693e6..78700b3 100644 --- a/e2e_test/phases/phase17_etcd_offline_queue.sh +++ b/e2e_test/phases/phase17_etcd_offline_queue.sh @@ -52,6 +52,15 @@ _cleanup_phase17_etcd_offline_queue() { fi } +# Drill: the Step 70c stop leaves a stdout log without "bye!". +_p17_cleanup_shutdown_drill() { + _e2e_restore_node_shutdown_functions + _cleanup_phase17_etcd_offline_queue +} + +case_validation_register shutdown_bye_missing_step70c phase17_etcd_offline_queue \ + _e2e_inject_node_shutdown_no_bye _p17_cleanup_shutdown_drill 'Step 70c:' + # Raw node gRPC ApplyConfig call (bypasses the controller entirely — same # invocation shape as phase9 Step 38, but with full DHCP fields so a # non-SDN-guard ApplyConfig can actually succeed). @@ -449,7 +458,8 @@ phase17_etcd_offline_queue() { info "Step 70c: gracefully stopping fastrg with the dirty edit persisted..." _P17C_RESTART_NEEDED=1 - local _p17c_stopped=0 + local _p17c_stopped=0 _p17c_stop_mark="" _p17c_stop_crash="" + _p17c_stop_mark=$(e2e_node_stop_mark) ssh_node "pkill -x fastrg" >/dev/null 2>&1 || true for _i in $(seq 1 30); do if ! ssh_node "pgrep -x fastrg >/dev/null 2>&1"; then @@ -460,6 +470,8 @@ phase17_etcd_offline_queue() { done if [[ $_p17c_stopped -ne 1 ]]; then _p17c_issue="${_p17c_issue:+${_p17c_issue}; }fastrg did not exit within 30s of SIGTERM" + elif ! _p17c_stop_crash=$(e2e_node_shutdown_check "$_p17c_stop_mark"); then + _p17c_issue="${_p17c_issue:+${_p17c_issue}; }shutdown_crash=${_p17c_stop_crash}" fi # Kafka baseline while the node is down: every message after this offset diff --git a/e2e_test/phases/phase19_node_restart.sh b/e2e_test/phases/phase19_node_restart.sh index f3b96b1..95ff374 100644 --- a/e2e_test/phases/phase19_node_restart.sh +++ b/e2e_test/phases/phase19_node_restart.sh @@ -174,6 +174,15 @@ case_validation_register registration_host_os_rest_missing phase19_node_restart _p19_inject_registration_host_os_rest_missing _p19_cleanup_registration_drill \ 'Step 77a:' +# Drill: the Step 76 stop leaves a stdout log without "bye!". +_p19_cleanup_shutdown_drill() { + _e2e_restore_node_shutdown_functions + _cleanup_phase19_node_restart +} + +case_validation_register shutdown_bye_missing_step76 phase19_node_restart \ + _e2e_inject_node_shutdown_no_bye _p19_cleanup_shutdown_drill 'Step 76:' + phase19_node_restart() { local _hsi1_key="configs/${NODE_UUID}/hsi/1" local _hsi2_key="configs/${NODE_UUID}/hsi/2" @@ -226,6 +235,8 @@ phase19_node_restart() { local _step74_issue="" local _step76_issue="" local _step77a_issue="" + local _p19_stop_mark="" + local _p19_stop_crash="" local _p19_reg_before="" local _p19_reg_record="" local _p19_rest_record="" @@ -311,6 +322,7 @@ phase19_node_restart() { info " Sending SIGTERM to fastrg and waiting up to 30s for a clean exit..." _P19_RESTART_NEEDED=1 + _p19_stop_mark=$(e2e_node_stop_mark) if ! ssh_node "pkill -x fastrg" >/dev/null 2>&1; then _step73_issue="${_step73_issue} SIGTERM_delivery=failed" fi @@ -323,11 +335,13 @@ phase19_node_restart() { done if [[ $_shutdown_done -ne 1 ]]; then _step73_issue="${_step73_issue} shutdown_timeout=30s" + elif ! _p19_stop_crash=$(e2e_node_shutdown_check "$_p19_stop_mark"); then + _step73_issue="${_step73_issue} shutdown_crash=${_p19_stop_crash}" fi if [[ -z "$_step73_issue" ]]; then pass "Step 76: Snapshot + graceful shutdown" \ - "users 1/2 Data phase; desire_status=connect; revisions=${_hsi1_rev_before}/${_hsi2_rev_before}/${_count_rev_before}; clean SIGTERM exit" + "users 1/2 Data phase; desire_status=connect; revisions=${_hsi1_rev_before}/${_hsi2_rev_before}/${_count_rev_before}; clean SIGTERM exit (log ends with bye!, no crash record)" else fail "Step 76: Snapshot + graceful shutdown" "${_step73_issue# }" fi @@ -554,6 +568,7 @@ phase19_node_restart() { # Stop gracefully, then block etcd BEFORE the cold start. _P19_RESTART_NEEDED=1 + _p19_stop_mark=$(e2e_node_stop_mark) ssh_node "pkill -x fastrg" >/dev/null 2>&1 || true for _i in $(seq 1 20); do [[ "$(_p19_process_state)" == "stopped" ]] && break @@ -563,6 +578,8 @@ phase19_node_restart() { fail "Step 80: snapshot is the boot base while etcd is down" "fastrg did not stop within 20s" return fi + # Reported with the step's verdict; the restart below still has to run. + _p19_stop_crash=$(e2e_node_shutdown_check "$_p19_stop_mark") || true ssh_node "iptables -I OUTPUT 1 -p tcp -d ${_p19_etcd_host} --dport ${_p19_etcd_port} -j REJECT --reject-with tcp-reset" \ >/dev/null 2>&1 && _P19_ETCD_BLOCKED=1 if [[ $_P19_ETCD_BLOCKED -ne 1 ]]; then @@ -621,6 +638,10 @@ phase19_node_restart() { done [[ $_p79_sync -eq 1 ]] || _step79_issue="${_step79_issue:+${_step79_issue}; }no etcd watch event observed within 150s of unblocking (watchers did not recover)" + if [[ "$_p19_stop_crash" != "pass" ]]; then + _step79_issue="${_step79_issue:+${_step79_issue}; }shutdown_crash=${_p19_stop_crash}" + fi + if [[ -z "$_step79_issue" ]]; then _P19_RESTART_NEEDED=0 pass "Step 80: snapshot is the boot base while etcd is down" \ diff --git a/e2e_test/phases/phase33_shutdown_inactive.sh b/e2e_test/phases/phase33_shutdown_inactive.sh index f8852c2..7c7b038 100644 --- a/e2e_test/phases/phase33_shutdown_inactive.sh +++ b/e2e_test/phases/phase33_shutdown_inactive.sh @@ -195,11 +195,21 @@ _cleanup_phase33_shutdown_inactive() { return 0 } +# Drill: the Step 137 stop leaves a stdout log without "bye!". +_p33_cleanup_shutdown_drill() { + _e2e_restore_node_shutdown_functions + _cleanup_phase33_shutdown_inactive +} + +case_validation_register shutdown_bye_missing_step137 phase33_shutdown_inactive \ + _e2e_inject_node_shutdown_no_bye _p33_cleanup_shutdown_drill 'Step 137:' + phase33_shutdown_inactive() { local _issue135="" _issue136="" local _config_log_path="" _log_baseline=0 local _entry="" _presence="" _status="" _reason="" local _stopped=0 _relaunched=0 _recovered=0 + local _stop_mark="" _stop_crash="" local _controller_ok=0 _shutdown_seconds=0 local _hsi="" _status1="" _status2="" local _i @@ -225,6 +235,7 @@ phase33_shutdown_inactive() { info " log baseline: ${_log_baseline} lines in ${_P33_LOG_PATH}" _P33_RESTART_NEEDED=1 + _stop_mark=$(e2e_node_stop_mark) if ! ssh_node "pkill -x fastrg" >/dev/null 2>&1; then _issue135="${_issue135} SIGTERM_delivery=failed" fi @@ -236,7 +247,11 @@ phase33_shutdown_inactive() { fi sleep 1 done - [[ $_stopped -eq 1 ]] || _issue135="${_issue135} fastrg_still_running_after_30s" + if [[ $_stopped -ne 1 ]]; then + _issue135="${_issue135} fastrg_still_running_after_30s" + elif ! _stop_crash=$(e2e_node_shutdown_check "$_stop_mark"); then + _issue135="${_issue135} shutdown_crash=${_stop_crash}" + fi # The application log is truncated on every start, so this must be # read before Step 138 cold-starts the node. @@ -263,7 +278,7 @@ phase33_shutdown_inactive() { if [[ -z "$_issue135" ]]; then pass "Step 137: graceful stop marks node inactive" \ - "node still listed after SIGTERM (exited in ${_shutdown_seconds}s): status=${_status}, inactive_reason=${_reason}; shutdown report logged" + "node still listed after SIGTERM (exited in ${_shutdown_seconds}s, log ends with bye!, no crash record): status=${_status}, inactive_reason=${_reason}; shutdown report logged" else fail "Step 137: graceful stop marks node inactive" "${_issue135# }" _p33_failure_evidence diff --git a/e2e_test/phases/phase40_offline_cli_writes.sh b/e2e_test/phases/phase40_offline_cli_writes.sh index 4b69842..1ccb4da 100644 --- a/e2e_test/phases/phase40_offline_cli_writes.sh +++ b/e2e_test/phases/phase40_offline_cli_writes.sh @@ -190,6 +190,15 @@ case_validation_register offline_snat_add_skipped phase40_offline_cli_writes \ case_validation_register offline_dns_record_add_skipped phase40_offline_cli_writes \ _p40_inject_dns_record_add_skipped _p40_cleanup_drill 'Step 182:' +# Drill: the Step 184 stop leaves a stdout log without "bye!". +_p40_cleanup_shutdown_drill() { + _e2e_restore_node_shutdown_functions + _cleanup_phase40_offline_cli_writes +} + +case_validation_register shutdown_bye_missing_step184 phase40_offline_cli_writes \ + _e2e_inject_node_shutdown_no_bye _p40_cleanup_shutdown_drill 'Step 184:' + # --------------------------------------------------------------------------- # Node-side readings. All of them go straight to the node, which is the only # side that can answer while etcd is unreachable. @@ -452,7 +461,7 @@ phase40_offline_cli_writes() { local _waited=0 _released=0 _marker="" _missing="" _kafka="" local _etcd_hsi="" _etcd_dns="" _conntrack="" _dig_off="" _dig_on="" local _stopped=0 _recovered=0 _started_at=0 _elapsed=0 _reported=0 - local _seen=0 _gone=0 + local _seen=0 _gone=0 _stop_mark="" _stop_crash="pass" bold "═══════════════════════════════════════════════════════" bold " Phase 40 — Offline node CLI config writes (Steps 176-184)" @@ -968,6 +977,7 @@ phase40_offline_cli_writes() { # this step is about to read back. _P40_NODE_STOPPED=1 if _p40_node_running; then + _stop_mark=$(e2e_node_stop_mark) ssh_node "pkill -x fastrg" >/dev/null 2>&1 || true for _i in $(seq 1 30); do if ! _p40_node_running; then @@ -976,6 +986,10 @@ phase40_offline_cli_writes() { fi sleep 1 done + # Reported with the step's verdict; the cold start below still has to run. + if [[ $_stopped -eq 1 ]]; then + _stop_crash=$(e2e_node_shutdown_check "$_stop_mark") || true + fi else _stopped=1 fi @@ -1021,6 +1035,8 @@ phase40_offline_cli_writes() { _issue="${_issue:+${_issue}; }hsi/${USER_ID} still dirty='${_dirty_hsi}' ${_waited}s after the reconnect" [[ "$_dirty_dns" == "false" ]] || \ _issue="${_issue:+${_issue}; }dns/${USER_ID} still dirty='${_dirty_dns}' ${_waited}s after the reconnect" + [[ "$_stop_crash" == "pass" ]] || \ + _issue="${_issue:+${_issue}; }shutdown_crash=${_stop_crash}" if [[ -z "$_issue" ]]; then pass "Step 184: cold start with etcd unreachable keeps the static DNS records" \ diff --git a/e2e_test/run_e2e_test.sh b/e2e_test/run_e2e_test.sh index 2c059e0..06bed32 100755 --- a/e2e_test/run_e2e_test.sh +++ b/e2e_test/run_e2e_test.sh @@ -455,6 +455,11 @@ if [[ -z "${_FASTRG_E2E_RELOCATED:-}" ]]; then exit $_ssh_rc fi + # The final node stop is checked inside the runner-side cleanup, after + # RESULT, and its output stays on the runner; show its verdict here. + ssh $_SSH_OPTS "${_E2E_RUNNER_USER}@${_E2E_RUNNER_HOST}" \ + "grep -a 'Final stop:' ${_E2E_CLEANUP_LOG} 2>/dev/null" 2>/dev/null || true + # Clean up uploaded files from runner (always, regardless of test result) info "Cleaning up uploaded files from runner ${_E2E_RUNNER_HOST}:${_E2E_REMOTE_DIR} ..." ssh $_SSH_OPTS "${_E2E_RUNNER_USER}@${_E2E_RUNNER_HOST}" \ @@ -952,6 +957,8 @@ source "${_E2E_PHASES_DIR}/rss_probe_lib.sh" source "${_E2E_PHASES_DIR}/progress_lib.sh" # The node->etcd block every offline phase shares — not a phase either. source "${_E2E_PHASES_DIR}/etcd_block_lib.sh" +# The crash check every SIGTERM stop of the node shares — not a phase either. +source "${_E2E_PHASES_DIR}/node_shutdown_lib.sh" source "${_E2E_PHASES_DIR}/phase0_setup.sh" source "${_E2E_PHASES_DIR}/phase1_subscriber_count_tests.sh" source "${_E2E_PHASES_DIR}/phase2_etcd_config_sync.sh" @@ -1302,6 +1309,10 @@ stop_orphan_watchdog() { } cleanup_fastrg() { + # The status the run is exiting with; only a clean run is turned into a + # failure by an unclean final node stop below. + local _e2e_exit_status=$? + local _e2e_final_stop_failed=0 _e2e_stop_mark="" _e2e_stop_crash="" _e2e_stop_state="" _e2e_stop_i set +eu # Prevent set -e / set -u from interrupting cleanup, ensure all cleanup steps are executed # From here on the run is being torn down, and a signal arriving now would @@ -1367,8 +1378,24 @@ cleanup_fastrg() { if [[ "${_FASTRG_STARTED_BY_SCRIPT:-0}" -eq 1 ]]; then info "Stopping fastrg (started by this script)..." + _e2e_stop_mark=$(e2e_node_stop_mark) ssh_node "pkill -x fastrg 2>/dev/null || true" || true - info "fastrg stopped." + for _e2e_stop_i in $(seq 1 30); do + _e2e_stop_state=$(ssh_node \ + "if pgrep -x fastrg >/dev/null 2>&1; then echo running; else echo stopped; fi" 2>/dev/null) + [[ "$_e2e_stop_state" == "stopped" ]] && break + sleep 1 + done + # "Final stop:" lines are relayed to the caller after the run. + if [[ "$_e2e_stop_state" != "stopped" ]]; then + error "Final stop: fastrg not seen stopped within 30s of SIGTERM (state: ${_e2e_stop_state:-node unreachable})" + _e2e_final_stop_failed=1 + elif _e2e_stop_crash=$(e2e_node_shutdown_check "$_e2e_stop_mark"); then + info "Final stop: fastrg stopped cleanly (log ends with bye!, no crash record)" + else + error "Final stop: fastrg did not stop cleanly: ${_e2e_stop_crash}" + _e2e_final_stop_failed=1 + fi # A config-apply failure emitted while phase17 removes its offline # test user can race with controller rollback and resurrect an older @@ -1409,6 +1436,11 @@ cleanup_fastrg() { _trace_interrupt "cleanup: finished normally" info "Cleanup complete." + + # RESULT is already printed by now, so the exit status carries this one. + if [[ "$_e2e_final_stop_failed" -eq 1 && "$_e2e_exit_status" -eq 0 ]]; then + exit 1 + fi } # --------------------------------------------------------------------------- diff --git a/northbound/controller/Makefile b/northbound/controller/Makefile index b08d8e7..33802f9 100644 --- a/northbound/controller/Makefile +++ b/northbound/controller/Makefile @@ -52,12 +52,19 @@ TEST_CLIENT_SRC = $(TEST_DIR)/test_controller.c TEST_SERVER_SRC = $(TEST_DIR)/test_controller_server.cpp TEST_ETCD_SRC = $(TEST_DIR)/test_etcd_client.cpp TEST_ETCD_CAS_SRC = $(TEST_DIR)/test_etcd_cas.cpp +TEST_ETCD_WATCH_TEARDOWN = $(TEST_DIR)/test_etcd_watch_teardown +TEST_ETCD_WATCH_TEARDOWN_SRC = $(TEST_DIR)/test_etcd_watch_teardown.cpp TEST_KAFKA_RETRY = $(TEST_DIR)/test_kafka_retry TEST_KAFKA_RETRY_SRC = $(TEST_DIR)/test_kafka_retry.cpp TEST_KAFKA_PRODUCER = $(TEST_DIR)/test_kafka_producer TEST_KAFKA_PRODUCER_SRC = $(TEST_DIR)/test_kafka_producer.cpp -.PHONY: all clean test test-client test-server test-etcd test-etcd-cas test-kafka-retry test-kafka-producer run-tests +# The watch teardown test links an ASan build of etcd_client.cpp; the +# production etcd_client.o is left uninstrumented. +ASAN_FLAGS = -fsanitize=address -fsanitize-recover=address -fno-omit-frame-pointer +ETCD_CLIENT_ASAN_OBJ = $(TEST_DIR)/etcd_client_asan.o + +.PHONY: all clean test test-client test-server test-etcd test-etcd-cas test-etcd-watch-teardown test-kafka-retry test-kafka-producer run-tests all: $(OBJECTS) @@ -93,13 +100,14 @@ kafka_producer.o: kafka_producer.cpp kafka_producer.h kafka_retry_policy.h kafka $(CXX) $(CXXFLAGS) -c kafka_producer.cpp -o kafka_producer.o # Test targets -test: test-client test-server test-etcd test-etcd-cas test-kafka-retry test-kafka-producer +test: test-client test-server test-etcd test-etcd-cas test-etcd-watch-teardown test-kafka-retry test-kafka-producer @echo "✅ All controller tests built successfully" @echo "Usage:" @echo " ./$(TEST_CLIENT) - Run controller client test" @echo " ./$(TEST_SERVER) - Run controller server test" @echo " ./$(TEST_ETCD) - Run etcd client test" @echo " ./$(TEST_ETCD_CAS) - Run etcd CAS put test" + @echo " ./$(TEST_ETCD_WATCH_TEARDOWN) - Run etcd watch teardown test (ASan)" @echo " make run-tests - Run automated test suite" @echo " ./run_tests.sh - Run automated test suite (alternative)" @@ -119,6 +127,9 @@ test-etcd: $(TEST_ETCD) test-etcd-cas: $(TEST_ETCD_CAS) @echo "✅ Etcd CAS put test built: $(TEST_ETCD_CAS)" +test-etcd-watch-teardown: $(TEST_ETCD_WATCH_TEARDOWN) + @echo "✅ Etcd watch teardown test built: $(TEST_ETCD_WATCH_TEARDOWN)" + test-kafka-retry: $(TEST_KAFKA_RETRY) @echo "✅ Kafka retry policy test built: $(TEST_KAFKA_RETRY)" @@ -153,6 +164,15 @@ $(TEST_ETCD_CAS): $(TEST_ETCD_CAS_SRC) etcd_client.o config_snapshot.o kafka_pro config_snapshot.o kafka_producer.o $(EVENTS_PROTO_OBJ) ../../src/dbg.o \ $(LDFLAGS) -laddress_sorting -lpthread +$(ETCD_CLIENT_ASAN_OBJ): etcd_client.cpp etcd_client.h + $(CXX) $(CXXFLAGS) $(ASAN_FLAGS) -c etcd_client.cpp -o $(ETCD_CLIENT_ASAN_OBJ) + +$(TEST_ETCD_WATCH_TEARDOWN): $(TEST_ETCD_WATCH_TEARDOWN_SRC) $(ETCD_CLIENT_ASAN_OBJ) config_snapshot.o kafka_producer.o $(EVENTS_PROTO_OBJ) + $(CXX) $(CXXFLAGS) $(ASAN_FLAGS) -I. -o $(TEST_ETCD_WATCH_TEARDOWN) $(TEST_ETCD_WATCH_TEARDOWN_SRC) \ + $(ETCD_CLIENT_ASAN_OBJ) config_snapshot.o kafka_producer.o $(EVENTS_PROTO_OBJ) ../../src/dbg.o \ + $(LDFLAGS) -laddress_sorting -lpthread + clean: rm -f $(OBJECTS) $(PROTO_SOURCES) $(PROTO_HEADERS) $(EVENTS_PROTO_SRC) $(EVENTS_PROTO_HDR) rm -f $(TEST_CLIENT) $(TEST_SERVER) $(TEST_ETCD) $(TEST_ETCD_CAS) $(TEST_KAFKA_RETRY) $(TEST_KAFKA_PRODUCER) + rm -f $(TEST_ETCD_WATCH_TEARDOWN) $(ETCD_CLIENT_ASAN_OBJ) diff --git a/northbound/controller/etcd_client.cpp b/northbound/controller/etcd_client.cpp index 15f97c6..f79ec25 100644 --- a/northbound/controller/etcd_client.cpp +++ b/northbound/controller/etcd_client.cpp @@ -77,6 +77,15 @@ class EtcdClientImpl { std::unique_ptr hsi_watcher_; std::unique_ptr user_count_watcher_; std::unique_ptr dns_record_watcher_; + + // Shared with the watchers' wait callbacks, which etcd-cpp-api runs on + // detached threads that can outlive this object. + struct WatchCallbackGuard { + std::mutex mutex; + bool alive = true; // guarded by mutex; false once stop_watch() begins + }; + std::shared_ptr callback_guard_ = std::make_shared(); + std::atomic watch_running_; std::atomic shutting_down_{false}; // set once during teardown; blocks new reconnect attempts std::atomic etcd_reachable_{false}; // last-known etcd reachability (watchdog/init) @@ -355,6 +364,24 @@ class EtcdClientImpl { return ETCD_SUCCESS; } + // Wait callback for one watcher; touches this only while the guard is alive. + std::function make_wait_callback(const char *watcher_name) { + return [this, guard = callback_guard_, watcher_name](bool cancelled) { + std::lock_guard lock(guard->mutex); + if (!guard->alive) + return; + + update_watch_activity(); // update activity time + + // A stream that ended without Cancel() was dropped by etcd. + if (!cancelled && watch_running_) { + FastRG_LOG(WARN, fastrg_ccb->fp, NULL, NULL, + "%s watcher disconnected, triggering reconnect...", watcher_name); + trigger_reconnect(); + } + }; + } + // Create or recreate watchers - separated for reconnection support etcd_status_t create_watchers() { try { @@ -396,15 +423,7 @@ class EtcdClientImpl { trigger_reconnect(); } }, - [this](bool connected) { - update_watch_activity(); // update activity time - - // Connection status callback - if (!connected && watch_running_) { - FastRG_LOG(WARN, fastrg_ccb->fp, NULL, NULL, "HSI watcher disconnected, triggering reconnect..."); - trigger_reconnect(); - } - }, + make_wait_callback("HSI"), true // recursive ); @@ -431,16 +450,7 @@ class EtcdClientImpl { trigger_reconnect(); } }, - [this](bool connected) { - update_watch_activity(); // update activity time - - // Connection status callback - if (!connected && watch_running_) { - FastRG_LOG(WARN, fastrg_ccb->fp, NULL, NULL, - "User count watcher disconnected, triggering reconnect..."); - trigger_reconnect(); - } - }, + make_wait_callback("User count"), true // recursive ); @@ -462,14 +472,7 @@ class EtcdClientImpl { trigger_reconnect(); } }, - [this](bool connected) { - update_watch_activity(); - if (!connected && watch_running_) { - FastRG_LOG(WARN, fastrg_ccb->fp, NULL, NULL, - "DNS record watcher disconnected, triggering reconnect..."); - trigger_reconnect(); - } - }, + make_wait_callback("DNS record"), true // recursive ); @@ -856,7 +859,14 @@ class EtcdClientImpl { void stop_watch() { FastRG_LOG(INFO, fastrg_ccb->fp, NULL, NULL, "Stopping watch..."); - // Mark teardown first so any in-flight watch/connection callback that + // Clear alive under the guard lock: a callback already inside finishes + // first, and any later one returns without touching this. + { + std::lock_guard lock(callback_guard_->mutex); + callback_guard_->alive = false; + } + + // Mark teardown so any in-flight watch/connection callback that // calls trigger_reconnect() becomes a no-op and cannot spawn a thread // that would outlive cleanup. shutting_down_ = true; @@ -879,8 +889,8 @@ class EtcdClientImpl { // Now signal and join the watchdog. stop_watchdog(); - // Cancel and destroy every watcher. reset() blocks until the watcher's - // in-flight callback returns, so after this no watch callback can run. + // Cancel() joins each watcher's thread, so no response callback runs + // after this; detached wait callbacks are fenced by callback_guard_. if (hsi_watcher_) { hsi_watcher_->Cancel(); hsi_watcher_.reset(); diff --git a/northbound/controller/run_tests.sh b/northbound/controller/run_tests.sh index 2a95db7..934ceea 100755 --- a/northbound/controller/run_tests.sh +++ b/northbound/controller/run_tests.sh @@ -305,9 +305,31 @@ else echo "⚠️ etcd server is not available. Skipping etcd CAS put test." fi -# Test 5: Kafka retry policy (no broker, no WAL, no etcd needed) +# Test 5: etcd client teardown under ASan — a watcher callback that touches the +# freed client is reported by AddressSanitizer echo "" -echo "🔧 Test 5: Kafka retry policy test" +echo "🔧 Test 5: etcd watch teardown test (ASan)" +echo "------------------------------------------" +if [ "$ETCD_READY" -eq 1 ]; then + if [ -f "./test/test_etcd_watch_teardown" ]; then + ./test/test_etcd_watch_teardown + if [ $? -ne 0 ]; then + echo "❌ etcd watch teardown test failed." + TEST_FAILED=1 + else + echo "✅ etcd watch teardown test completed!" + fi + else + echo "❌ test_etcd_watch_teardown executable not found." + TEST_FAILED=1 + fi +else + echo "⚠️ etcd server is not available. Skipping etcd watch teardown test." +fi + +# Test 6: Kafka retry policy (no broker, no WAL, no etcd needed) +echo "" +echo "🔧 Test 6: Kafka retry policy test" if [ -f "./test/test_kafka_retry" ]; then ./test/test_kafka_retry if [ $? -ne 0 ]; then @@ -321,10 +343,10 @@ else TEST_FAILED=1 fi -# Test 6: Kafka producer pure functions — WAL serialization and event payload +# Test 7: Kafka producer pure functions — WAL serialization and event payload # builders (no broker, no WAL file, no etcd needed) echo "" -echo "🔧 Test 6: Kafka producer unit tests" +echo "🔧 Test 7: Kafka producer unit tests" if [ -f "./test/test_kafka_producer" ]; then ./test/test_kafka_producer if [ $? -ne 0 ]; then diff --git a/northbound/controller/test/test_etcd_watch_teardown.cpp b/northbound/controller/test/test_etcd_watch_teardown.cpp new file mode 100644 index 0000000..deecd44 --- /dev/null +++ b/northbound/controller/test/test_etcd_watch_teardown.cpp @@ -0,0 +1,190 @@ +#include "../etcd_client.h" +#include "../../../src/fastrg.h" + +#include + +#include +#include + +#include +#include +#include +#include +#include + +// Teardown test for the etcd client, built with AddressSanitizer: bring the +// client and its watchers up against etcd, stop and free it, then give the +// watchers' detached wait callbacks time to run. A callback that touches the +// freed client shows up as an ASan report. Needs etcd on 127.0.0.1:2379. + +// While set, every new thread sleeps THREAD_START_DELAY before it starts. +static std::atomic delay_new_threads{false}; +static std::atomic delayed_threads{0}; +static const std::chrono::milliseconds THREAD_START_DELAY(50); + +struct DelayedStart { + void *(*start_routine)(void *); + void *arg; +}; + +static void *delayed_thread_start(void *p) +{ + DelayedStart start = *(DelayedStart *)p; + delete (DelayedStart *)p; + std::this_thread::sleep_for(THREAD_START_DELAY); + return start.start_routine(start.arg); +} + +extern "C" { +// etcd_client.o calls these from its watcher-thread self-event filter and its +// event hand-off; the real definitions live in src/etcd_integration.c and +// src/fastrg.c. This standalone test links only etcd_client.o, so provide +// minimal stand-ins. +int parse_user_id(const char *user_id_str, int max_count) +{ + if (!user_id_str || user_id_str[0] == '\0') + return -1; + char *endptr; + long val = strtol(user_id_str, &endptr, 10); + if (endptr == user_id_str || *endptr != '\0') + return -1; + int ccb_id = (int)val - 1; + return (ccb_id < 0 || ccb_id >= max_count) ? -1 : ccb_id; +} + +// No control-plane loop here: take ownership and drop the event, which is what +// the loop does once it has dispatched one. +STATUS fastrg_gen_etcd_event(FastRG_t *fastrg_ccb, etcd_event_t *ev) +{ + (void)fastrg_ccb; + etcd_event_free(ev); + return SUCCESS; +} + +// Keep going after a report so every iteration is counted (needs +// -fsanitize-recover=address); leaks in the gRPC/etcd libraries are out of scope. +const char *__asan_default_options(void) +{ + return "halt_on_error=0:suppress_equal_pcs=0:detect_leaks=0"; +} + +// Overrides libc's pthread_create for this binary so delay_new_threads can +// hold back the threads etcd-cpp-api starts during teardown. +int pthread_create(pthread_t *thread, const pthread_attr_t *attr, + void *(*start_routine)(void *), void *arg) noexcept +{ + using pthread_create_fn = int (*)(pthread_t *, const pthread_attr_t *, + void *(*)(void *), void *); + static pthread_create_fn real_pthread_create = + (pthread_create_fn)dlsym(RTLD_NEXT, "pthread_create"); + + if (!delay_new_threads.load()) + return real_pthread_create(thread, attr, start_routine, arg); + + DelayedStart *start = new DelayedStart{start_routine, arg}; + int ret = real_pthread_create(thread, attr, delayed_thread_start, start); + if (ret != 0) + delete start; + else + delayed_threads++; + return ret; +} +} + +static const char *ETCD_ENDPOINTS = "http://127.0.0.1:2379"; +static const char *TEST_NODE_UUID = "watch-teardown-test-node"; +static const int DEFAULT_ITERATIONS = 20; +// Lets the three watch streams come up before they are cancelled. +static const std::chrono::milliseconds WATCH_SETTLE(200); +// Long enough for the detached wait callbacks to have run. +static const std::chrono::milliseconds CALLBACK_GRACE(500); + +static FastRG_t test_fastrg_ccb; +static std::atomic asan_reports{0}; + +static void count_asan_report(const char *report) +{ + (void)report; + asan_reports++; +} + +static void sync_request_callback(const char *node_id, void *user_data) +{ + (void)node_id; + (void)user_data; +} + +// Runs start_watch -> stop_watch -> cleanup the given number of times and +// returns how many iterations drew an ASan report, or -1 when the scenario +// could not be set up. +static int test_etcd_client_cleanup(int iterations) +{ + int caught = 0; + + for (int i = 1; i <= iterations; i++) { + int before = asan_reports.load(); + int delayed_before = delayed_threads.load(); + + if (etcd_client_init(ETCD_ENDPOINTS, &test_fastrg_ccb) != ETCD_SUCCESS) { + fprintf(stderr, "FAIL: iteration %d: etcd_client_init failed\n", i); + etcd_client_cleanup(); + return -1; + } + // start_watch also returns success when etcd is down (it falls back to + // background reconnects); only a reachable etcd means the watchers exist. + if (etcd_client_start_watch(TEST_NODE_UUID, sync_request_callback) != ETCD_SUCCESS || + !etcd_client_is_connected()) { + fprintf(stderr, "FAIL: iteration %d: watchers did not start (is etcd up on %s?)\n", + i, ETCD_ENDPOINTS); + etcd_client_stop_watch(); + etcd_client_cleanup(); + return -1; + } + std::this_thread::sleep_for(WATCH_SETTLE); + + // Wait callbacks run on detached threads; the delay mimics their scheduling lag under load. + delay_new_threads = true; + etcd_client_stop_watch(); + etcd_client_cleanup(); + delay_new_threads = false; + std::this_thread::sleep_for(CALLBACK_GRACE); + + // No delayed thread means the override is not in effect and the test + // would pass without exercising the race. + if (delayed_threads.load() == delayed_before) { + fprintf(stderr, "FAIL: iteration %d: no thread was delayed during teardown\n", i); + return -1; + } + + int reports = asan_reports.load() - before; + if (reports > 0) + caught++; + printf("iteration %d/%d: %d ASan report(s), %d delayed thread(s)\n", i, iterations, + reports, delayed_threads.load() - delayed_before); + fflush(stdout); + } + return caught; +} + +int main(int argc, char **argv) +{ + int iterations = (argc > 1) ? atoi(argv[1]) : DEFAULT_ITERATIONS; + if (iterations <= 0) + iterations = DEFAULT_ITERATIONS; + + __asan_set_error_report_callback(count_asan_report); + test_fastrg_ccb.fp = stdout; + test_fastrg_ccb.user_count = 8; + + int caught = test_etcd_client_cleanup(iterations); + if (caught < 0) + return 1; + + printf("etcd watch teardown: ASan caught %d of %d iterations\n", caught, iterations); + if (caught > 0) { + fprintf(stderr, "FAIL: a watcher callback touched the freed etcd client\n"); + return 1; + } + printf("PASS: no ASan report across %d iterations\n", iterations); + return 0; +}