增强(08-23-isolated-backup-restore-drill): 固化八阶段RTO合同

2026-08-25 20:57:15 +08:00
@@ -29,7 +29,18 @@ CONTAINER_NAME=""
 RUNTIME_CLEANED=0
 RESULT_STATUS="NO_GO"
 RPO_SECONDS=""
-RTO_SECONDS=""
+RTO_SECONDS="NOT_RUN"
+RTO_BATCH_COPY_SECONDS="NOT_RUN"
+RTO_POSTGRES_CONTAINER_START_SECONDS="NOT_RUN"
+RTO_DUMP_LIST_SECONDS="NOT_RUN"
+RTO_TARGET_CONFIRMATION_SECONDS="NOT_RUN"
+RTO_RESTORE_APPLY_SECONDS="NOT_RUN"
+RTO_DATABASE_VERIFY_SECONDS="NOT_RUN"
+RTO_STORAGE_ATTACHMENT_VERIFY_SECONDS="NOT_RUN"
+RTO_FINAL_INTEGRITY_SECONDS="NOT_RUN"
+RTO_ACTIVE_STAGE=""
+RTO_STAGE_STARTED_EPOCH=""
+RTO_FINALIZED=0
 MIGRATION_SUCCESS=""
 MIGRATION_OTHER=""
 MIGRATION_SET_MATCH=""
@@ -66,6 +77,94 @@ require_command() {
  command -v "$1" >/dev/null 2>&1 || fail "required_command_missing"
 }

+rto_now() {
+  date -u +%s
+}
+
+rto_set_stage_seconds() {
+  local stage="$1"
+  local seconds="$2"
+  case "$stage" in
+    batch_copy) RTO_BATCH_COPY_SECONDS="$seconds" ;;
+    postgres_container_start) RTO_POSTGRES_CONTAINER_START_SECONDS="$seconds" ;;
+    dump_list) RTO_DUMP_LIST_SECONDS="$seconds" ;;
+    target_confirmation) RTO_TARGET_CONFIRMATION_SECONDS="$seconds" ;;
+    restore_apply) RTO_RESTORE_APPLY_SECONDS="$seconds" ;;
+    database_verify) RTO_DATABASE_VERIFY_SECONDS="$seconds" ;;
+    storage_attachment_verify) RTO_STORAGE_ATTACHMENT_VERIFY_SECONDS="$seconds" ;;
+    final_integrity) RTO_FINAL_INTEGRITY_SECONDS="$seconds" ;;
+    *) return 1 ;;
+  esac
+}
+
+rto_begin() {
+  local stage="$1"
+  local now
+  [[ -z "$RTO_ACTIVE_STAGE" && "$RTO_FINALIZED" -eq 0 ]] || return 1
+  now="$(rto_now)"
+  [[ "$now" =~ ^[0-9]+$ ]] || return 1
+  rto_set_stage_seconds "$stage" "NOT_RUN" || return 1
+  RTO_ACTIVE_STAGE="$stage"
+  RTO_STAGE_STARTED_EPOCH="$now"
+}
+
+rto_close_active_at() {
+  local now="$1"
+  local elapsed
+  [[ -n "$RTO_ACTIVE_STAGE" && "$RTO_STAGE_STARTED_EPOCH" =~ ^[0-9]+$ \
+    && "$now" =~ ^[0-9]+$ && "$now" -ge "$RTO_STAGE_STARTED_EPOCH" ]] \
+    || return 1
+  elapsed="$((now - RTO_STAGE_STARTED_EPOCH))"
+  rto_set_stage_seconds "$RTO_ACTIVE_STAGE" "$elapsed" || return 1
+}
+
+rto_transition() {
+  local expected_stage="$1"
+  local next_stage="$2"
+  local now
+  [[ "$RTO_ACTIVE_STAGE" == "$expected_stage" && "$RTO_FINALIZED" -eq 0 ]] \
+    || return 1
+  now="$(rto_now)"
+  rto_close_active_at "$now" || return 1
+  rto_set_stage_seconds "$next_stage" "NOT_RUN" || return 1
+  RTO_ACTIVE_STAGE="$next_stage"
+  RTO_STAGE_STARTED_EPOCH="$now"
+}
+
+rto_finalize() {
+  local now
+  local value
+  local total=0
+  local measured=0
+  if [[ "$RTO_FINALIZED" -eq 1 ]]; then
+    return 0
+  fi
+  if [[ -n "$RTO_ACTIVE_STAGE" ]]; then
+    now="$(rto_now)"
+    rto_close_active_at "$now" || return 1
+    RTO_ACTIVE_STAGE=""
+    RTO_STAGE_STARTED_EPOCH=""
+  fi
+  for value in \
+    "$RTO_BATCH_COPY_SECONDS" \
+    "$RTO_POSTGRES_CONTAINER_START_SECONDS" \
+    "$RTO_DUMP_LIST_SECONDS" \
+    "$RTO_TARGET_CONFIRMATION_SECONDS" \
+    "$RTO_RESTORE_APPLY_SECONDS" \
+    "$RTO_DATABASE_VERIFY_SECONDS" \
+    "$RTO_STORAGE_ATTACHMENT_VERIFY_SECONDS" \
+    "$RTO_FINAL_INTEGRITY_SECONDS"; do
+    if [[ "$value" =~ ^[0-9]+$ ]]; then
+      total="$((total + value))"
+      measured=1
+    fi
+  done
+  if [[ "$measured" -eq 1 ]]; then
+    RTO_SECONDS="$total"
+  fi
+  RTO_FINALIZED=1
+}
+
 confirm_postgres_target() {
  local actual_database=""
  local query_exit_code=0
@@ -182,6 +281,15 @@ emit_restore_diagnostics() {
  echo "pg_restore_exit_code=$PG_RESTORE_EXIT_CODE"
  echo "pg_restore_error_count=$PG_RESTORE_ERROR_COUNT"
  echo "restore_error_category=$RESTORE_ERROR_CATEGORY"
+  echo "rto_batch_copy_seconds=$RTO_BATCH_COPY_SECONDS"
+  echo "rto_postgres_container_start_seconds=$RTO_POSTGRES_CONTAINER_START_SECONDS"
+  echo "rto_dump_list_seconds=$RTO_DUMP_LIST_SECONDS"
+  echo "rto_target_confirmation_seconds=$RTO_TARGET_CONFIRMATION_SECONDS"
+  echo "rto_restore_apply_seconds=$RTO_RESTORE_APPLY_SECONDS"
+  echo "rto_database_verify_seconds=$RTO_DATABASE_VERIFY_SECONDS"
+  echo "rto_storage_attachment_verify_seconds=$RTO_STORAGE_ATTACHMENT_VERIFY_SECONDS"
+  echo "rto_final_integrity_seconds=$RTO_FINAL_INTEGRITY_SECONDS"
+  echo "data_restore_rto_seconds=$RTO_SECONDS"
 }

 finish() {
@@ -191,6 +299,10 @@ finish() {
  trap - EXIT HUP INT TERM
  # Emit only allowlisted stage diagnostics while the private runtime still
  # exists. Raw stderr remains mode 0600 and is removed by cleanup_runtime.
+  if ! rto_finalize; then
+    FAILURE_CATEGORY="rto_stage_finalize_failed"
+    exit_code=1
+  fi
  emit_restore_diagnostics
  if [[ "$RUNTIME_CLEANED" -ne 1 ]]; then
    cleanup_runtime || runtime_cleanup="FAIL"
@@ -204,7 +316,6 @@ finish() {
  if [[ "$exit_code" -eq 0 ]]; then
    echo "result=$RESULT_STATUS"
    echo "rpo_seconds=$RPO_SECONDS"
-    echo "data_restore_rto_seconds=$RTO_SECONDS"
    echo "migration_success=$MIGRATION_SUCCESS"
    echo "migration_other=$MIGRATION_OTHER"
    echo "migration_set_match=$MIGRATION_SET_MATCH"
@@ -412,11 +523,13 @@ mkdir -m 0700 "$WORK_DIR"
 private_log="$WORK_DIR/private.log"
 : >"$private_log"
 chmod 0600 "$private_log"
-rto_started_epoch="$(date -u +%s)"
+rto_begin batch_copy || fail "rto_stage_begin_failed"
 cp -a -- "$selected_batch" "$WORK_DIR/batch"
 copied_metadata="$(validate_batch "$WORK_DIR/batch" copy "$SOURCE_RUN_ID")" \
  || fail "copied_batch_invalid"
 [[ "$copied_metadata" == "$batch_metadata" ]] || fail "copied_batch_identity_mismatch"
+rto_transition batch_copy postgres_container_start \
+  || fail "rto_stage_transition_failed"

 env_file="$WORK_DIR/postgres.env"
 postgres_password="$(openssl rand -hex 24)"
@@ -429,6 +542,8 @@ chmod 0600 "$env_file"
 printf '%s\n' '[stage=postgres_container_start]' >>"$private_log"
 docker run -d --rm --name "$CONTAINER_NAME" --network none --env-file "$env_file" \
  "$POSTGRES_IMAGE" >>"$private_log" 2>&1 || fail "postgres_container_start_failed"
+rto_transition postgres_container_start dump_list \
+  || fail "rto_stage_transition_failed"

 PHASE="restore_database"
 DUMP_LIST_STATUS="FAIL"
@@ -444,6 +559,8 @@ if [[ "$DUMP_LIST_EXIT_CODE" -ne 0 ]]; then
  fail "dump_list_failed"
 fi
 DUMP_LIST_STATUS="PASS"
+rto_transition dump_list target_confirmation \
+  || fail "rto_stage_transition_failed"

 TARGET_CONFIRMATION_STATUS="FAIL"
 printf '%s\n' '[stage=target_confirmation]' >>"$private_log"
@@ -452,6 +569,8 @@ if ! confirm_postgres_target; then
  fail "restore_target_confirmation_failed"
 fi
 TARGET_CONFIRMATION_STATUS="PASS"
+rto_transition target_confirmation restore_apply \
+  || fail "rto_stage_transition_failed"

 real_docker_path="$(command -v docker)"
 docker_proxy_dir="$WORK_DIR/docker-proxy"
@@ -530,6 +649,8 @@ if [[ "$RESTORE_SCRIPT_EXIT_CODE" -ne 0 || "$PG_RESTORE_EXIT_CODE" -ne 0 ]]; the
 fi
 RESTORE_APPLY_STATUS="PASS"
 RESTORE_ERROR_CATEGORY="NONE"
+rto_transition restore_apply database_verify \
+  || fail "rto_stage_transition_failed"

 PHASE="verify_database"
 migration_names="$(PGPASSWORD="$postgres_password" docker exec -i -e PGPASSWORD \
@@ -581,6 +702,8 @@ SQL
 )" || fail "table_count_query_failed"
 [[ "$(printf '%s\n' "$TABLE_COUNTS" | sed '/^$/d' | wc -l | tr -d ' ')" == "12" ]] \
  || fail "table_count_key_mismatch"
+rto_transition database_verify storage_attachment_verify \
+  || fail "rto_stage_transition_failed"

 PHASE="restore_storage"
 restored_storage="$WORK_DIR/restored-storage"
@@ -613,6 +736,8 @@ SQL
 read -r ATTACHMENT_TOTAL ATTACHMENT_MISMATCH attachment_s3_count <<<"$attachment_result"
 [[ "$ATTACHMENT_TOTAL" =~ ^[0-9]+$ && "$ATTACHMENT_MISMATCH" == "0" \
  && "$attachment_s3_count" == "0" ]] || fail "attachment_reference_mismatch"
+rto_transition storage_attachment_verify final_integrity \
+  || fail "rto_stage_transition_failed"

 PHASE="post_validation"
 copied_metadata_after="$(validate_batch "$WORK_DIR/batch" copy "$SOURCE_RUN_ID")" \
@@ -621,8 +746,7 @@ source_metadata_after="$(validate_batch "$selected_batch" source "")" \
  || fail "source_archive_postcheck_failed"
 [[ "$copied_metadata_after" == "$batch_metadata" \
  && "$source_metadata_after" == "$batch_metadata" ]] || fail "archive_identity_changed"
-rto_finished_epoch="$(date -u +%s)"
-RTO_SECONDS="$((rto_finished_epoch - rto_started_epoch))"
+rto_finalize || fail "rto_stage_finalize_failed"

 deadman_enabled_after="$(systemctl is-enabled "$DEADMAN_TIMER_UNIT" 2>/dev/null || true)"
 deadman_active_after="$(systemctl is-active "$DEADMAN_TIMER_UNIT" 2>/dev/null || true)"
@@ -432,14 +432,17 @@ finish = re.search(r"\nfinish\(\) \{(?P<body>.*?)\n\}\ntrap finish", text, re.S)
 if not finish:
    raise SystemExit("finish function not found")
 body = finish.group("body")
+finalize_position = body.find("\n  if ! rto_finalize; then")
 emit_position = body.find("\n  emit_restore_diagnostics")
 cleanup_position = body.find("\n    cleanup_runtime ||")
+if finalize_position == -1:
+    raise SystemExit("RTO finalization missing")
 if emit_position == -1:
    raise SystemExit("diagnostic emission missing")
 if cleanup_position == -1:
    raise SystemExit("runtime cleanup call missing")
-if emit_position > cleanup_position:
-    raise SystemExit("diagnostics are emitted after cleanup")
+if not (finalize_position < emit_position < cleanup_position):
+    raise SystemExit("RTO/stage diagnostics are not finalized before cleanup")
 required = {
    'echo "dump_list=$DUMP_LIST_STATUS"',
    'echo "target_confirmation=$TARGET_CONFIRMATION_STATUS"',
@@ -452,14 +455,41 @@ required = {
    'echo "pg_restore_exit_code=$PG_RESTORE_EXIT_CODE"',
    'echo "pg_restore_error_count=$PG_RESTORE_ERROR_COUNT"',
    'echo "restore_error_category=$RESTORE_ERROR_CATEGORY"',
+    'echo "rto_batch_copy_seconds=$RTO_BATCH_COPY_SECONDS"',
+    'echo "rto_postgres_container_start_seconds=$RTO_POSTGRES_CONTAINER_START_SECONDS"',
+    'echo "rto_dump_list_seconds=$RTO_DUMP_LIST_SECONDS"',
+    'echo "rto_target_confirmation_seconds=$RTO_TARGET_CONFIRMATION_SECONDS"',
+    'echo "rto_restore_apply_seconds=$RTO_RESTORE_APPLY_SECONDS"',
+    'echo "rto_database_verify_seconds=$RTO_DATABASE_VERIFY_SECONDS"',
+    'echo "rto_storage_attachment_verify_seconds=$RTO_STORAGE_ATTACHMENT_VERIFY_SECONDS"',
+    'echo "rto_final_integrity_seconds=$RTO_FINAL_INTEGRITY_SECONDS"',
+    'echo "data_restore_rto_seconds=$RTO_SECONDS"',
 }
 missing = sorted(value for value in required if value not in text)
 if missing:
    raise SystemExit(f"diagnostic fields missing: {missing}")
 if 'RESTORE_ERROR_CATEGORY="RESTORE_APPLY_NONZERO"' not in text:
    raise SystemExit("non-zero apply classification missing")
+transitions = [
+    "rto_begin batch_copy",
+    "rto_transition batch_copy postgres_container_start",
+    "rto_transition postgres_container_start dump_list",
+    "rto_transition dump_list target_confirmation",
+    "rto_transition target_confirmation restore_apply",
+    "rto_transition restore_apply database_verify",
+    "rto_transition database_verify storage_attachment_verify",
+    "rto_transition storage_attachment_verify final_integrity",
+]
+positions = [text.find(value) for value in transitions]
+if any(position == -1 for position in positions) or positions != sorted(positions):
+    raise SystemExit("RTO stage transitions missing or out of order")
+target_call_position = text.find("if ! confirm_postgres_target; then")
+if not positions[3] < target_call_position < positions[4]:
+    raise SystemExit("TCP target confirmation is outside its RTO stage boundary")
+if text.count('echo "data_restore_rto_seconds=$RTO_SECONDS"') != 1:
+    raise SystemExit("data restore RTO must be emitted exactly once")
 PY
-pass "diagnostics precede finally-equivalent cleanup and use allowlisted fields"
+pass "eight-stage RTO and restore diagnostics precede cleanup with one vocabulary"

 cat >"$TEST_DIR/mock-target-docker" <<'MOCK_DOCKER'
 #!/usr/bin/env bash
@@ -738,6 +768,107 @@ CONTAINER_NAME=""
 sed -n '1,/^trap finish EXIT HUP INT TERM$/p' "$RUNNER" \
  | sed '$d' >"$TEST_DIR/runner-finalization-functions.sh"

+(
+  # shellcheck disable=SC1090
+  source "$TEST_DIR/runner-finalization-functions.sh"
+  RTO_TEST_NOW=100
+  rto_now() {
+    printf '%s\n' "$RTO_TEST_NOW"
+  }
+  rto_begin batch_copy
+  RTO_TEST_NOW=103
+  rto_transition batch_copy postgres_container_start
+  RTO_TEST_NOW=108
+  rto_transition postgres_container_start dump_list
+  RTO_TEST_NOW=110
+  rto_transition dump_list target_confirmation
+  RTO_TEST_NOW=121
+  rto_transition target_confirmation restore_apply
+  RTO_TEST_NOW=128
+  rto_transition restore_apply database_verify
+  RTO_TEST_NOW=141
+  rto_transition database_verify storage_attachment_verify
+  RTO_TEST_NOW=158
+  rto_transition storage_attachment_verify final_integrity
+  RTO_TEST_NOW=161
+  rto_finalize
+  emit_restore_diagnostics
+) >"$TEST_DIR/captured-rto-success" 2>&1
+for expected in \
+  'rto_batch_copy_seconds=3' \
+  'rto_postgres_container_start_seconds=5' \
+  'rto_dump_list_seconds=2' \
+  'rto_target_confirmation_seconds=11' \
+  'rto_restore_apply_seconds=7' \
+  'rto_database_verify_seconds=13' \
+  'rto_storage_attachment_verify_seconds=17' \
+  'rto_final_integrity_seconds=3' \
+  'data_restore_rto_seconds=61'; do
+  grep -Fxq "$expected" "$TEST_DIR/captured-rto-success" \
+    || fail "successful eight-stage RTO total or boundary mismatch"
+done
+[[ "$(grep -c '^data_restore_rto_seconds=' "$TEST_DIR/captured-rto-success")" -eq 1 ]] \
+  || fail "successful RTO total was not emitted exactly once"
+pass "rendered runner measures eight contiguous stages with an exact total"
+
+set +e
+(
+  # shellcheck disable=SC1090
+  source "$TEST_DIR/runner-finalization-functions.sh"
+  cleanup_runtime() {
+    echo "cleanup_marker=runtime"
+    return 0
+  }
+  cleanup_access() {
+    echo "cleanup_marker=access"
+    return 0
+  }
+  RTO_BATCH_COPY_SECONDS="2"
+  RTO_POSTGRES_CONTAINER_START_SECONDS="4"
+  RTO_DUMP_LIST_SECONDS="1"
+  RTO_ACTIVE_STAGE="target_confirmation"
+  RTO_STAGE_STARTED_EPOCH="200"
+  RTO_TEST_NOW=209
+  rto_now() {
+    printf '%s\n' "$RTO_TEST_NOW"
+  }
+  FAILURE_CATEGORY="restore_target_confirmation_failed"
+  DUMP_LIST_STATUS="PASS"
+  DUMP_LIST_EXIT_CODE="0"
+  TARGET_CONFIRMATION_STATUS="FAIL"
+  TARGET_CONFIRMATION_EXIT_CODE="1"
+  TARGET_CONFIRMATION_ATTEMPT_COUNT="60"
+  RESTORE_EXECUTION_PATH="DOCKER_STDIN"
+  RESTORE_ERROR_CATEGORY="TARGET_QUERY_NONZERO"
+  trap finish EXIT
+  exit 23
+) >"$TEST_DIR/captured-rto-target-failure" 2>&1
+rto_target_failure_exit="$?"
+set -e
+[[ "$rto_target_failure_exit" -eq 23 ]] \
+  || fail "target-confirmation timing failure did not preserve exit code"
+for expected in \
+  'rto_batch_copy_seconds=2' \
+  'rto_postgres_container_start_seconds=4' \
+  'rto_dump_list_seconds=1' \
+  'rto_target_confirmation_seconds=9' \
+  'rto_restore_apply_seconds=NOT_RUN' \
+  'rto_database_verify_seconds=NOT_RUN' \
+  'rto_storage_attachment_verify_seconds=NOT_RUN' \
+  'rto_final_integrity_seconds=NOT_RUN' \
+  'data_restore_rto_seconds=16'; do
+  grep -Fxq "$expected" "$TEST_DIR/captured-rto-target-failure" \
+    || fail "target-confirmation failure RTO boundary mismatch"
+done
+rto_line="$(grep -n '^rto_target_confirmation_seconds=9$' \
+  "$TEST_DIR/captured-rto-target-failure" | cut -d: -f1)"
+rto_cleanup_line="$(grep -n '^cleanup_marker=runtime$' \
+  "$TEST_DIR/captured-rto-target-failure" | cut -d: -f1)"
+[[ "$rto_line" =~ ^[0-9]+$ && "$rto_cleanup_line" =~ ^[0-9]+$ \
+  && "$rto_line" -lt "$rto_cleanup_line" ]] \
+  || fail "failed-stage RTO was not emitted before teardown"
+pass "target-confirmation failure preserves elapsed stages and later NOT_RUN before cleanup"
+
 capture_finalization_case() {
  local output_file="$1"
  local failure_category="$2"
@@ -805,7 +936,13 @@ grep -Fxq 'target_confirmation=NOT_RUN' \
  || fail "target stage ran after dump-list failure"
 grep -Fxq 'restore_apply=NOT_RUN' "$TEST_DIR/captured-dump-list-failure" \
  || fail "apply stage ran after dump-list failure"
-pass "dump-list failure keeps target and apply stages NOT_RUN"
+grep -Fxq 'rto_batch_copy_seconds=NOT_RUN' \
+  "$TEST_DIR/captured-dump-list-failure" \
+  || fail "pre-RTO failure unexpectedly reported a measured stage"
+grep -Fxq 'data_restore_rto_seconds=NOT_RUN' \
+  "$TEST_DIR/captured-dump-list-failure" \
+  || fail "pre-RTO failure unexpectedly reported a measured total"
+pass "pre-RTO failure keeps timing, target and apply fields NOT_RUN"

 capture_finalization_case \
  "$TEST_DIR/captured-target-failure" \
@@ -849,6 +986,16 @@ set +e
  PG_RESTORE_EXIT_CODE="23"
  PG_RESTORE_ERROR_COUNT="UNKNOWN"
  RESTORE_ERROR_CATEGORY="RESTORE_APPLY_NONZERO"
+  RTO_BATCH_COPY_SECONDS="2"
+  RTO_POSTGRES_CONTAINER_START_SECONDS="4"
+  RTO_DUMP_LIST_SECONDS="1"
+  RTO_TARGET_CONFIRMATION_SECONDS="9"
+  RTO_ACTIVE_STAGE="restore_apply"
+  RTO_STAGE_STARTED_EPOCH="300"
+  RTO_TEST_NOW=312
+  rto_now() {
+    printf '%s\n' "$RTO_TEST_NOW"
+  }
  trap finish EXIT
  exit 23
 ) >"$TEST_DIR/captured-finalization" 2>&1
@@ -869,7 +1016,13 @@ grep -Fxq 'temporary_access_cleanup=PASS' "$TEST_DIR/captured-finalization" \
  || fail "access teardown result was not retained"
 grep -Fxq 'pg_restore_exit_code=23' "$TEST_DIR/captured-finalization" \
  || fail "pg_restore exit code disappeared after teardown"
-pass "injected failure emits readable stages before finally-equivalent teardown"
+grep -Fxq 'rto_restore_apply_seconds=12' "$TEST_DIR/captured-finalization" \
+  || fail "restore-apply failure duration missing"
+grep -Fxq 'rto_database_verify_seconds=NOT_RUN' "$TEST_DIR/captured-finalization" \
+  || fail "database verification ran after restore-apply failure"
+grep -Fxq 'data_restore_rto_seconds=28' "$TEST_DIR/captured-finalization" \
+  || fail "restore-apply failure RTO total mismatch"
+pass "injected restore-apply failure preserves diagnostics and RTO before teardown"

 if grep -Eiq 'postgresql://|SELECT[[:space:]]|/tmp/|local_fixture_password' \
  "$TEST_DIR/captured-dump-list-failure" \