paivana

test_payment_backend_failure.sh (15803B)

---

 #!/usr/bin/env bash
 # Distinguish a merchant transport failure from an elapsed order timeout.
 
 set -eu
 
 function here() {
     cd -- "$(dirname -- "$0")" && pwd
 }
 
 SRCDIR="${SRCDIR:-$(here)}"
 BUILDDIR="${BUILDDIR:-$PWD}"
 PAIVANA_HTTPD="${PAIVANA_HTTPD:-$BUILDDIR/../backend/paivana-httpd}"
 PORT_BASE="${PAIVANA_PORT_BASE:-18400}"
 MERCHANT_BACKEND_PORT=$((PORT_BASE + 120))
 PAIVANA_PORT=$((PORT_BASE + 121))
 SCRATCH="$(mktemp -d -t paivana-payment-failure.XXXXXX)"
 MERCHANT_SOCKET="$SCRATCH/merchant.sock"
 PUBLIC_MERCHANT_URL="https://public-merchant.example/instances/paivana/"
 INTERNAL_MERCHANT_URL="http://merchant.invalid/instances/paivana/"
 STUB_PID=""
 PROXY_PID=""
 PAIVANA_PID=""
 
 function cleanup() {
     set +e
     [ -n "$STUB_PID" ] && kill -TERM "$STUB_PID" 2>/dev/null
     [ -n "$PROXY_PID" ] && kill -TERM "$PROXY_PID" 2>/dev/null
     [ -n "$PAIVANA_PID" ] && kill -TERM "$PAIVANA_PID" 2>/dev/null
     wait "$STUB_PID" 2>/dev/null
     wait "$PROXY_PID" 2>/dev/null
     wait "$PAIVANA_PID" 2>/dev/null
     if [ "${KEEP_TMP:-0}" = "1" ]; then
         echo "Temp files kept in $SCRATCH" >&2
     else
         rm -rf "$SCRATCH"
     fi
     return 0
 }
 trap cleanup EXIT
 
 function port_is_free() {
     ! (exec 3<>"/dev/tcp/127.0.0.1/$1") 2>/dev/null
 }
 
 function wait_for_port() {
     local port="$1" pid="$2" tries=50
     while [ "$tries" -gt 0 ]; do
         if ! port_is_free "$port"; then
             return 0
         fi
         kill -0 "$pid" 2>/dev/null || return 1
         sleep 0.1
         tries=$((tries - 1))
     done
     return 1
 }
 
 function wait_for_unix_socket() {
     local path="$1" pid="$2" tries=50
     while [ "$tries" -gt 0 ]; do
         if [ -S "$path" ] &&
            grep -Fxq "READY $path" "$SCRATCH/proxy.log"
         then
             return 0
         fi
         kill -0 "$pid" 2>/dev/null || return 1
         sleep 0.1
         tries=$((tries - 1))
     done
     return 1
 }
 
 function fail() {
     echo "FAIL: $*" >&2
     echo "==> paivana.log <==" >&2
     tail -n 80 "$SCRATCH/paivana.log" >&2 || true
     echo "==> merchant.log <==" >&2
     tail -n 40 "$SCRATCH/merchant.log" >&2 || true
     echo "==> proxy.log <==" >&2
     tail -n 60 "$SCRATCH/proxy.log" >&2 || true
     exit 1
 }
 
 function start_stub() {
     PAIVANA_STUB_BASE_PATH=/instances/paivana \
       python3 "$SRCDIR/payment_backend_stub.py" "$MERCHANT_BACKEND_PORT" \
         >>"$SCRATCH/merchant.log" 2>&1 &
     STUB_PID=$!
     wait_for_port "$MERCHANT_BACKEND_PORT" "$STUB_PID" \
         || fail "merchant stub did not start"
 }
 
 function start_proxy() {
     python3 "$SRCDIR/merchant_fault_proxy.py" \
         --listen-unix "$MERCHANT_SOCKET" \
         --upstream-port "$MERCHANT_BACKEND_PORT" \
         --fault-path /instances/paivana/private/orders/diagnostic-order \
         --fault-count 3 \
         >>"$SCRATCH/proxy.log" 2>&1 &
     PROXY_PID=$!
     wait_for_unix_socket "$MERCHANT_SOCKET" "$PROXY_PID" \
         || fail "merchant fault frontend did not start"
 }
 
 function redemption_body() {
     local order="$1"
     printf '{"order_id":"%s","website":"http://127.0.0.1:%u/article",' \
            "$order" "$PAIVANA_PORT"
     printf '"expiration":{"t_s":2000000000},'
     printf '"nonce":"000G40R40M30E209185GR38E1W"}'
 }
 
 function redeem() {
     local order="$1"
     curl -sS -o "$SCRATCH/response.json" -w '%{http_code} %{time_total}\n' \
          -H 'Content-Type: application/json' -X POST \
          "http://127.0.0.1:$PAIVANA_PORT/.well-known/paivana" \
          -d "$(redemption_body "$order")"
 }
 
 function expect_error() {
     local want_code="$1" want_detail="$2" want_merchant_status="$3"
     python3 - "$SCRATCH/response.json" "$want_code" "$want_detail" \
         "$want_merchant_status" <<'PY'
 import json
 import sys
 
 with open(sys.argv[1], encoding="utf-8") as f:
     body = json.load(f)
 if body.get("code") != int(sys.argv[2]):
     raise SystemExit(f"error code {body.get('code')}, want {sys.argv[2]}: {body}")
 if body.get("detail") != sys.argv[3]:
     raise SystemExit(f"detail {body.get('detail')!r}, want {sys.argv[3]!r}")
 if body.get("merchant_http_status") != int(sys.argv[4]):
     raise SystemExit(
         f"merchant_http_status {body.get('merchant_http_status')!r}, "
         f"want {sys.argv[4]}: {body}"
     )
 PY
 }
 
 command -v curl >/dev/null 2>&1 || { echo "SKIP: curl not found"; exit 77; }
 command -v python3 >/dev/null 2>&1 || { echo "SKIP: python3 not found"; exit 77; }
 [ -x "$PAIVANA_HTTPD" ] || { echo "SKIP: paivana-httpd not found"; exit 77; }
 if ! port_is_free "$MERCHANT_BACKEND_PORT" || \
    ! port_is_free "$PAIVANA_PORT"; then
     echo "SKIP: test ports are occupied; change PAIVANA_PORT_BASE" >&2
     exit 77
 fi
 
 mkdir -p "$SCRATCH/configd" "$SCRATCH/prefix/share/paivana/templates"
 cp "$BUILDDIR/../frontend/paywall.en.must" \
    "$SCRATCH/prefix/share/paivana/templates/"
 export PAIVANA_BASE_CONFIG="$SCRATCH/configd"
 export PAIVANA_PREFIX="$SCRATCH/prefix/"
 
 cat >"$SCRATCH/paivana.conf" <<EOF
 [paivana]
 DESTINATION_BASE_URL = http://127.0.0.1:9/
 BASE_URL = http://127.0.0.1:$PAIVANA_PORT/
 MERCHANT_BACKEND_URL = $PUBLIC_MERCHANT_URL
 MERCHANT_BACKEND_INTERNAL_URL = $INTERNAL_MERCHANT_URL
 MERCHANT_BACKEND_UNIX_PATH = $MERCHANT_SOCKET
 MERCHANT_ACCESS_TOKEN = secret-token:stub
 SECRET = payment-backend-failure-test
 SERVE = tcp
 PORT = $PAIVANA_PORT
 BIND_TO = 127.0.0.1
 # Small values make the payment-reservation boundary testable without a large
 # load: two ordinary and two payment slots still satisfy the same accounting
 # relationships as the 352+32 production defaults.
 CONNECTION_LIMIT = 4
 PAYMENT_CONNECTION_LIMIT = 2
 EOF
 
 function expect_invalid_internal_url() {
     local value="$1" label="$2"
     local cfg="$SCRATCH/invalid-internal.conf"
     local log="$SCRATCH/invalid-internal.log"
 
     sed "s|^MERCHANT_BACKEND_INTERNAL_URL =.*|MERCHANT_BACKEND_INTERNAL_URL = $value|" \
         "$SCRATCH/paivana.conf" > "$cfg"
     if timeout 3 "$PAIVANA_HTTPD" -c "$cfg" -L WARNING >"$log" 2>&1; then
         fail "Paivana accepted $label internal merchant URL"
     fi
     grep -q 'MERCHANT_BACKEND_INTERNAL_URL' "$log" || \
         fail "Paivana did not diagnose $label internal merchant URL"
 }
 
 expect_invalid_internal_url 'not-a-web-url/' malformed
 expect_invalid_internal_url 'http://merchant.invalid/instances/paivana' \
     unterminated
 
 start_stub
 start_proxy
 "$PAIVANA_HTTPD" -c "$SCRATCH/paivana.conf" -L DEBUG \
     >"$SCRATCH/paivana.log" 2>&1 &
 PAIVANA_PID=$!
 wait_for_port "$PAIVANA_PORT" "$PAIVANA_PID" || fail "paivana did not start"
 grep -q 'GET /instances/paivana/private/templates ' \
     "$SCRATCH/merchant.log" || fail "template request lost merchant instance prefix"
 grep -q 'GET /instances/paivana/private/templates/premium ' \
     "$SCRATCH/merchant.log" || fail "template detail lost merchant instance prefix"
 
 # The server-side URL is deliberately unreachable over TCP and cleartext over
 # the Unix socket, while every browser-facing value must retain public HTTPS.
 status=$(curl -sS -D "$SCRATCH/paywall.headers" \
     -o "$SCRATCH/paywall.body" -w '%{http_code}' \
     "http://127.0.0.1:$PAIVANA_PORT/.well-known/paivana/templates/premium")
 [ "$status" = 402 ] || fail "paywall page returned HTTP $status"
 grep -qi '^Paivana: taler://pay-template/public-merchant.example/instances/paivana/premium' \
     "$SCRATCH/paywall.headers" || fail "paywall header did not use public URL"
 grep -qi "connect-src 'self' https://public-merchant.example" \
     "$SCRATCH/paywall.headers" || fail "paywall CSP did not use public URL"
 grep -q 'https://public-merchant.example/instances/paivana/' \
     "$SCRATCH/paywall.body" || fail "paywall body did not use public URL"
 if grep -q 'merchant.invalid' "$SCRATCH/paywall.body"; then
     fail "internal merchant URL leaked into paywall body"
 fi
 
 # Warm the merchant pool with an ordinary order lookup.  Together with the
 # startup template requests this leaves a known-good persistent connection in
 # Paivana's merchant curl context, which is what the production process has
 # between its infrequent genuine payment attempts.
 read -r status elapsed < <(redeem warm-order)
 [ "$status" = "404" ] || fail "merchant warm-up returned HTTP $status"
 expect_error 9802 warm-order 404 || fail "unexpected warm-up response JSON"
 [ "$(grep -c '/private/orders/warm-order' "$SCRATCH/merchant.log")" = 1 ] || \
     fail "merchant warm-up did not use exactly one request"
 
 # The frontend has kept the merchant connection from warm-order alive.
 # Let it become genuinely idle, then have the frontend reset the next three
 # matching transport attempts before forwarding or access-logging them.  The
 # first fault must therefore be an idle reused TCP connection.  libcurl retries
 # that reused-connection failure internally, and Paivana retries the completed
 # status-zero operation once more; the observed topology therefore requires
 # three resets.  A fresh request remains healthy once that window has passed.
 sleep 0.3
 read -r status elapsed < <(redeem diagnostic-order)
 [ "$status" = "502" ] || fail "diagnostic trigger returned HTTP $status"
 expect_error 9801 diagnostic-order 0 || fail "unexpected diagnostic-trigger JSON"
 for _ in $(seq 1 50); do
     grep -q 'Forced-fresh merchant diagnostic for order `diagnostic-order' \
         "$SCRATCH/paivana.log" && break
     sleep 0.1
 done
 grep -q 'Forced-fresh merchant diagnostic for order `diagnostic-order.*completed HTTP status 404' \
     "$SCRATCH/paivana.log" || fail "successful fresh-connection diagnostic missing"
 grep -q 'Forced-fresh merchant diagnostic for order `diagnostic-order.*new connections 1' \
     "$SCRATCH/paivana.log" || fail "fresh diagnostic did not report a new connection"
 grep -q "retrying once within the original 5 s deadline" \
     "$SCRATCH/paivana.log" || fail "Paivana application retry diagnostic missing"
 grep -q 'FAULT index=1 .*path=/instances/paivana/private/orders/diagnostic-order reused=yes' \
     "$SCRATCH/proxy.log" || fail "first fault did not use the idle merchant connection"
 [ "$(grep -c 'FAULT .*path=/instances/paivana/private/orders/diagnostic-order' "$SCRATCH/proxy.log")" = 3 ] || \
     fail "frontend did not cover libcurl and Paivana retry attempts"
 [ "$(grep -c '/private/orders/diagnostic-order' "$SCRATCH/merchant.log")" = 1 ] || \
     fail "merchant saw a failed order request or missed the fresh diagnostic"
 [ "$(grep -c 'ACCESS .*path=/instances/paivana/private/orders/diagnostic-order' "$SCRATCH/proxy.log")" = 1 ] || \
     fail "frontend access log contains a failed order request"
 if grep -q 'secret-token:stub' "$SCRATCH/paivana.log"; then
     fail "merchant bearer token leaked into Paivana's log"
 fi
 
 for _ in $(seq 1 5); do
     status=$(curl -sS -H 'Authorization: Bearer secret-token:stub' \
         --unix-socket "$MERCHANT_SOCKET" \
         -o /dev/null -w '%{http_code}' \
         "${INTERNAL_MERCHANT_URL}private/orders/diagnostic-order")
     [ "$status" = "404" ] || fail "fresh merchant curl returned HTTP $status"
 done
 [ "$(grep -c '/private/orders/diagnostic-order' "$SCRATCH/merchant.log")" = 6 ] || \
     fail "fresh order-status curls did not all reach the merchant"
 
 # A normal merchant response resets both warning sampling and the consecutive
 # operational failure count.  The diagnostic itself deliberately does not.
 read -r status elapsed < <(redeem diagnostic-recovery-order)
 [ "$status" = "404" ] || fail "diagnostic recovery returned HTTP $status"
 expect_error 9802 diagnostic-recovery-order 404 || \
     fail "unexpected diagnostic-recovery JSON"
 grep -q 'answered order .*diagnostic-recovery-order.* after 1 consecutive lookup' \
     "$SCRATCH/paivana.log" || fail "diagnostic recovery log missing"
 
 # A refused connection completes immediately.  It must no longer be
 # presented as a five-second timeout.
 kill -TERM "$STUB_PID"
 wait "$STUB_PID" || true
 STUB_PID=""
 read -r status elapsed < <(redeem transport-failure)
 [ "$status" = "502" ] || fail "early transport failure returned HTTP $status"
 expect_error 9801 transport-failure 0 || fail "unexpected early-failure JSON"
 python3 - "$elapsed" <<'PY' || fail "early failure took $elapsed seconds"
 import sys
 raise SystemExit(0 if float(sys.argv[1]) < 2.0 else 1)
 PY
 grep -q "early transport failure" "$SCRATCH/paivana.log" \
     || fail "early-failure diagnostic missing from log"
 grep -q "1 concurrent merchant lookup including this one" "$SCRATCH/paivana.log" \
     || fail "active lookup count missing from log"
 for _ in $(seq 1 50); do
     grep -q 'Forced-fresh merchant diagnostic for order `transport-failure' \
         "$SCRATCH/paivana.log" && break
     sleep 0.1
 done
 grep -q 'Forced-fresh merchant diagnostic for order `transport-failure.*completed HTTP status 0' \
     "$SCRATCH/paivana.log" || fail "failed fresh-connection diagnostic missing"
 
 # A real HTTP response proves recovery and resets the consecutive
 # transport-failure counter.
 start_stub
 read -r status elapsed < <(redeem recovered-order)
 [ "$status" = "404" ] || fail "recovered backend returned HTTP $status"
 expect_error 9802 recovered-order 404 || fail "unexpected recovery JSON"
 grep -q 'answered order .*recovered-order.* after 1 consecutive lookup' \
     "$SCRATCH/paivana.log" || fail "recovery diagnostic missing from log"
 
 # A backend that holds the long poll beyond Paivana's own deadline is a
 # genuine timeout and must retain the 504/code-11 response.
 read -r status elapsed < <(redeem timeout-order)
 [ "$status" = "504" ] || fail "elapsed deadline returned HTTP $status"
 expect_error 11 timeout-order 0 || fail "unexpected timeout JSON"
 python3 - "$elapsed" <<'PY' || fail "timeout returned after only $elapsed seconds"
 import sys
 raise SystemExit(0 if float(sys.argv[1]) >= 4.5 else 1)
 PY
 grep -q "by the 5 s deadline" "$SCRATCH/paivana.log" \
     || fail "deadline diagnostic missing from log"
 
 # Two long polls fill the payment budget.  A third redemption must receive an
 # immediate, machine-readable overload response while the first two remain
 # suspended, and repeated timeout diagnostics in the same minute are sampled.
 timeout_pids=()
 for n in 1 2; do
     curl -sS -o "$SCRATCH/timeout-$n.json" -w '%{http_code}' \
          -H 'Content-Type: application/json' -X POST \
          "http://127.0.0.1:$PAIVANA_PORT/.well-known/paivana" \
          -d "$(redemption_body timeout-order)" \
          >"$SCRATCH/timeout-$n.status" &
     timeout_pids+=("$!")
 done
 sleep 0.3
 status="$(curl -sS --max-time 2 -D "$SCRATCH/payment-overload.headers" \
     -o "$SCRATCH/response.json" -w '%{http_code}' \
     -H 'Content-Type: application/json' -X POST \
     "http://127.0.0.1:$PAIVANA_PORT/.well-known/paivana" \
     -d "$(redemption_body third-order)")" || \
     fail "over-capacity payment request failed"
 [ "$status" = "503" ] || fail "third payment returned HTTP $status, want 503"
 python3 - "$SCRATCH/response.json" <<'PY' || fail "payment overload JSON is wrong"
 import json
 import sys
 with open(sys.argv[1], encoding="utf-8") as f:
     body = json.load(f)
 raise SystemExit(0 if body.get("code") == 77 else 1)
 PY
 grep -qi '^Retry-After: 1' "$SCRATCH/payment-overload.headers" || \
     fail "payment overload response lacks Retry-After: 1"
 grep -qi '^Connection: close' "$SCRATCH/payment-overload.headers" || \
     fail "payment overload response lacks Connection: close"
 wait "${timeout_pids[0]}" || fail "first concurrent timeout request failed"
 wait "${timeout_pids[1]}" || fail "second concurrent timeout request failed"
 [ "$(cat "$SCRATCH/timeout-1.status")" = 504 ] || \
     fail "first admitted payment did not complete with 504"
 [ "$(cat "$SCRATCH/timeout-2.status")" = 504 ] || \
     fail "second admitted payment did not complete with 504"
 [ "$(grep -c 'by the 5 s deadline' "$SCRATCH/paivana.log")" = 1 ] || \
     fail "timeout diagnostic was not sampled to one warning per minute"
 
 echo "payment backend failure diagnostics: OK"