diff --git a/crates/asterisk-ami/src/actions.rs b/crates/asterisk-ami/src/actions.rs index 88e2c40..ae6277d 100644 --- a/crates/asterisk-ami/src/actions.rs +++ b/crates/asterisk-ami/src/actions.rs @@ -663,7 +663,7 @@ fn handle_originate( .get_header("Priority") .and_then(|p| p.parse::().ok()) .unwrap_or(1); - let _timeout = action + let timeout_ms = action .get_header("Timeout") .and_then(|t| t.parse::().ok()) .unwrap_or(30000); @@ -802,6 +802,63 @@ fn handle_originate( ch.state = call_channel.state; } + // CP3: a PJSIP origination must NOT run its dialplan app/exten until the + // far end ANSWERS (200 OK). driver.call() only PUTS THE INVITE ON THE + // WIRE; the answer arrives asynchronously (handle_response's 2xx path + // flips the store channel to Up). Running the app now would emit SIP/RTP + // before answer. Wait up to the Originate Timeout for Up; on + // hangup/rejection/timeout, abandon the leg (CANCEL a still-pending + // INVITE) WITHOUT running the app, and report failure. + if tech.eq_ignore_ascii_case("PJSIP") { + let deadline = std::time::Instant::now() + + std::time::Duration::from_millis(timeout_ms.max(1)); + let mut answered = false; + loop { + let (state, hung) = { + let ch = store_chan.lock(); + (ch.state, ch.check_hangup()) + }; + if state == asterisk_types::ChannelState::Up { + answered = true; + break; + } + // A rejection/failure softhangs-up the leg (or drops it to Down/ + // Busy) before answer — stop waiting and do not run the app. + if hung + || state == asterisk_types::ChannelState::Down + || state == asterisk_types::ChannelState::Busy + { + break; + } + if std::time::Instant::now() >= deadline { + break; + } + tokio::time::sleep(std::time::Duration::from_millis(20)).await; + } + if !answered { + warn!( + "Originate: PJSIP channel {} not answered within {}ms; abandoning before app", + chan_name, timeout_ms + ); + // Put the correct request on the wire for the unanswered leg (a + // CANCEL for a still-pending INVITE) and release its resources. + if let Some(handler) = asterisk_sip::get_global_event_handler() { + handler.cancel_or_bye_outbound_leg(&chan_name).await; + } else { + let _ = driver.hangup(&mut call_channel).await; + } + release_originate_leg(&tech, &chan_name, &chan_uid); + crate::event_bus::publish_event( + crate::protocol::AmiEvent::new("OriginateResponse", 0x02) + .with_header("Response", "Failure") + .with_header("Reason", "3") // no answer + .with_header("Channel", &chan_name) + .with_header("Uniqueid", &chan_uid), + ); + return; + } + } + // Create a tokio::sync::Mutex copy for execution on ;1 let pbx_channel = { let guard = store_chan.lock(); diff --git a/tests/cp3-originate-wait/ami_originate.py b/tests/cp3-originate-wait/ami_originate.py new file mode 100755 index 0000000..4290d21 --- /dev/null +++ b/tests/cp3-originate-wait/ami_originate.py @@ -0,0 +1,65 @@ +#!/usr/bin/env python3 +"""Trigger one rustisk outbound Dial via a single authenticated AMI Originate. + + ami_originate.py HOST PORT ENDPOINT ACTION_ID + +Sends `Originate Channel: PJSIP/` asynchronously. rustisk resolves the +endpoint's contact (live registrar binding preferred over static config) and +sends the INVITE to it. Prints the AMI response; exits nonzero if the action was +not queued. +""" + +import socket +import sys + + +def main(): + if len(sys.argv) != 5: + raise SystemExit("usage: ami_originate.py HOST PORT ENDPOINT ACTION_ID") + host, port, endpoint, action_id = sys.argv[1], int(sys.argv[2]), sys.argv[3], sys.argv[4] + + login = ( + "Action: Login\r\n" + "Username: cp3\r\n" + "Secret: cp3-local-only\r\n" + "\r\n" + ) + originate = ( + "Action: Originate\r\n" + "ActionID: %s\r\n" + "Channel: PJSIP/%s\r\n" + "Context: default\r\n" + "Exten: s\r\n" + "Priority: 1\r\n" + "Timeout: 8000\r\n" + "Async: true\r\n" + "\r\n" + ) % (action_id, endpoint) + logoff = "Action: Logoff\r\n\r\n" + + payload = (login + originate + logoff).encode("utf-8") + response = bytearray() + with socket.create_connection((host, port), timeout=4) as mgr: + mgr.settimeout(4) + mgr.sendall(payload) + try: + while b"Response: Goodbye\r\n" not in response: + chunk = mgr.recv(65536) + if not chunk: + break + response.extend(chunk) + except socket.timeout: + pass + + text = response.decode("utf-8", "replace") + sys.stdout.write(text) + # Require the Originate-specific queued message. A bare "Success" is NOT + # sufficient: the Login reply also carries "Success", so matching it would + # green-light a session whose Originate actually failed. + if "successfully queued" not in text: + sys.stderr.write("Originate not queued\n") + sys.exit(2) + + +if __name__ == "__main__": + main() diff --git a/tests/cp3-originate-wait/carrier_delay.py b/tests/cp3-originate-wait/carrier_delay.py new file mode 100755 index 0000000..db0df86 --- /dev/null +++ b/tests/cp3-originate-wait/carrier_delay.py @@ -0,0 +1,181 @@ +#!/usr/bin/env python3 +"""Offline carrier that DELAYS its 200 OK, for the CP3 wait-for-answer harness. + +Proves RECEIVER-SIDE that an AMI Originate does not run the dialplan app until +the far end ANSWERS: the carrier holds its 200 for --answer-delay seconds and +tags every captured datagram `phase=pre` (before it sent the 200) or +`phase=post`. A wait-for-answer-correct rustisk sends NOTHING but the INVITE in +the pre-answer window (no ACK/BYE/CANCEL, no RTP) and only after the 200 does the +app run — so the ACK, the app's DTMF RTP, and the BYE are all `phase=post`. + +RED (app run immediately, before answer): the app runs and tears the unanswered +leg down before the delayed 200; the 200 is never ACKed and no post-answer BYE +appears. + +Captures SIP on :5060 and RTP on :40000 (the SDP-answered media port). +""" + +import argparse +import re +import select +import socket +import sys +import time + +SIP_PORT = 5060 +RTP_PORT = 40000 + + +def log(msg): + sys.stderr.write("[carrier_delay] " + msg + "\n") + sys.stderr.flush() + + +def own_ip_toward(peer_ip): + s = socket.socket(socket.AF_INET, socket.SOCK_DGRAM) + try: + s.connect((peer_ip, 15060)) + return s.getsockname()[0] + finally: + s.close() + + +def get_headers(text, name): + out = [] + for line in text.split("\r\n"): + if line == "": + break + if ":" in line: + hn, hv = line.split(":", 1) + if hn.strip().lower() == name.lower(): + out.append(hv.strip()) + return out + + +def get_header(text, name): + v = get_headers(text, name) + return v[0] if v else None + + +def cseq_of(text): + cs = get_header(text, "CSeq") + return cs.strip() if cs else None + + +def build_response(req_text, code, reason, own, to_tag=None, sdp=None): + vias = get_headers(req_text, "Via") + frm = get_header(req_text, "From") or "" + to = get_header(req_text, "To") or "" + call_id = get_header(req_text, "Call-ID") or "" + cseq = get_header(req_text, "CSeq") or "" + if to_tag and "tag=" not in to: + to = to + ";tag=%s" % to_tag + lines = ["SIP/2.0 %d %s" % (code, reason)] + for v in vias: + lines.append("Via: %s" % v) + lines.append("From: %s" % frm) + lines.append("To: %s" % to) + lines.append("Call-ID: %s" % call_id) + lines.append("CSeq: %s" % cseq) + lines.append("Contact: " % (own, SIP_PORT)) + body = sdp or "" + if body: + lines.append("Content-Type: application/sdp") + lines.append("Content-Length: %d" % len(body)) + lines.append("") + lines.append(body) + return ("\r\n".join(lines)).encode("utf-8") + + +def carrier_sdp(own): + return ( + "v=0\r\no=carrier 0 0 IN IP4 %s\r\ns=-\r\nc=IN IP4 %s\r\n" + "t=0 0\r\nm=audio %d RTP/AVP 0 101\r\na=rtpmap:0 PCMU/8000\r\n" + "a=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-16\r\n" + ) % (own, own, RTP_PORT) + + +def main(): + ap = argparse.ArgumentParser() + ap.add_argument("--caller", required=True) + ap.add_argument("--capture", required=True) + ap.add_argument("--answer-delay", type=float, default=3.0) + args = ap.parse_args() + + own = own_ip_toward(args.caller) + t0 = time.time() + + def cap(line): + with open(args.capture, "a") as f: + f.write(line + "\n") + f.flush() + log(line) + + sip = socket.socket(socket.AF_INET, socket.SOCK_DGRAM) + sip.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1) + sip.bind(("0.0.0.0", SIP_PORT)) + rtp = socket.socket(socket.AF_INET, socket.SOCK_DGRAM) + rtp.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1) + rtp.bind(("0.0.0.0", RTP_PORT)) + + cap("READY own=%s answer_delay=%.2f rel=%.3f" % (own, args.answer_delay, 0.0)) + + answered = False # global (single-call harness) + pending_200 = None # (send_at, invite_text, src) + + def phase(): + return "post" if answered else "pre" + + while True: + # Fire the delayed 200 if due. + if pending_200 is not None and time.time() >= pending_200[0]: + send_at, inv, src = pending_200 + pending_200 = None + ok = build_response(inv, 200, "OK", own, to_tag="cp3del200", sdp=carrier_sdp(own)) + sip.sendto(ok, src) + answered = True + cap("SENT-200 own=%s rel=%.3f" % (own, time.time() - t0)) + + timeout = 0.2 + if pending_200 is not None: + timeout = max(0.01, min(0.2, pending_200[0] - time.time())) + r, _, _ = select.select([sip, rtp], [], [], timeout) + for s in r: + try: + data, src = s.recvfrom(8192) + except OSError: + continue + rel = time.time() - t0 + if s is rtp: + cap("RTP phase=%s own=%s src=%s:%d bytes=%d rel=%.3f" % ( + phase(), own, src[0], src[1], len(data), rel)) + continue + text = data.decode("utf-8", "replace") + first = text.split("\r\n", 1)[0] + if first.startswith("INVITE "): + cap("INVITE phase=%s own=%s src=%s:%d cseq=%s rel=%.3f" % ( + phase(), own, src[0], src[1], cseq_of(text), rel)) + # 100 Trying immediately; 200 OK is DELAYED. + sip.sendto(build_response(text, 100, "Trying", own), src) + if pending_200 is None and not answered: + pending_200 = (time.time() + args.answer_delay, text, src) + elif first.startswith("ACK "): + cap("ACK phase=%s own=%s src=%s:%d cseq=%s rel=%.3f" % ( + phase(), own, src[0], src[1], cseq_of(text), rel)) + elif first.startswith("BYE "): + cap("BYE phase=%s own=%s src=%s:%d cseq=%s rel=%.3f" % ( + phase(), own, src[0], src[1], cseq_of(text), rel)) + sip.sendto(build_response(text, 200, "OK", own), src) + elif first.startswith("CANCEL "): + cap("CANCEL phase=%s own=%s src=%s:%d cseq=%s rel=%.3f" % ( + phase(), own, src[0], src[1], cseq_of(text), rel)) + sip.sendto(build_response(text, 200, "OK", own), src) + # RFC 3261: also 487 the INVITE and cancel the pending 200. + if pending_200 is not None: + _, inv, isrc = pending_200 + pending_200 = None + sip.sendto(build_response(inv, 487, "Request Terminated", own, to_tag="cp3del487"), isrc) + + +if __name__ == "__main__": + main() diff --git a/tests/cp3-originate-wait/config/asterisk.conf.tmpl b/tests/cp3-originate-wait/config/asterisk.conf.tmpl new file mode 100644 index 0000000..08a069b --- /dev/null +++ b/tests/cp3-originate-wait/config/asterisk.conf.tmpl @@ -0,0 +1,4 @@ +[directories] +astetcdir = @CONFIG_DIR@ +astrundir = @RUN_DIR@ +astincludedir = @RUN_DIR@/include diff --git a/tests/cp3-originate-wait/config/extensions.conf b/tests/cp3-originate-wait/config/extensions.conf new file mode 100644 index 0000000..0b8250a --- /dev/null +++ b/tests/cp3-originate-wait/config/extensions.conf @@ -0,0 +1,5 @@ +[default] +exten => s,1,Answer() + same => n,SendDTMF(9876) + same => n,Wait(1) + same => n,Hangup() diff --git a/tests/cp3-originate-wait/config/manager.conf b/tests/cp3-originate-wait/config/manager.conf new file mode 100644 index 0000000..31105fa --- /dev/null +++ b/tests/cp3-originate-wait/config/manager.conf @@ -0,0 +1,9 @@ +[general] +enabled = yes +bindaddr = 0.0.0.0 +port = 15038 + +[cp3] +secret = cp3-local-only +read = all +write = system diff --git a/tests/cp3-originate-wait/config/pjsip.conf.tmpl b/tests/cp3-originate-wait/config/pjsip.conf.tmpl new file mode 100644 index 0000000..671a0ce --- /dev/null +++ b/tests/cp3-originate-wait/config/pjsip.conf.tmpl @@ -0,0 +1,20 @@ +; CP3 wait-for-answer harness. The carrier DELAYS its 200; the Originate must +; not run the [default] app until that 200 arrives. +[transport-udp] +type = transport +protocol = udp +bind = 0.0.0.0:15060 + +[carrier] +type = endpoint +context = default +disallow = all +allow = ulaw +direct_media = no +rtp_symmetric = yes +dtmf_mode = rfc4733 +aors = carrier_aor + +[carrier_aor] +type = aor +contact = sip:carrier@@CORE_S@:5060 diff --git a/tests/cp3-originate-wait/config/rtp.conf b/tests/cp3-originate-wait/config/rtp.conf new file mode 100644 index 0000000..8ef5b32 --- /dev/null +++ b/tests/cp3-originate-wait/config/rtp.conf @@ -0,0 +1,3 @@ +[general] +rtpstart = 31000 +rtpend = 31040 diff --git a/tests/cp3-originate-wait/run.sh b/tests/cp3-originate-wait/run.sh new file mode 100755 index 0000000..08ce4d7 --- /dev/null +++ b/tests/cp3-originate-wait/run.sh @@ -0,0 +1,234 @@ +#!/usr/bin/env bash +# CP3 (flagship) — AMI Originate waits for answer before running the app. +# +# Proves RECEIVER-SIDE, on an isolated `--internal` Docker network, that an AMI +# Originate does NOT run the dialplan app/exten until the far end ANSWERS. The +# offline carrier DELAYS its 200 by --answer-delay and tags every captured +# datagram `phase=pre` (before it sent the 200) or `phase=post`: +# +# PRE-ANSWER SILENCE: in the pre-answer window the carrier receives ONLY the +# INVITE — no ACK/BYE/CANCEL and no RTP (the app has not run). +# POST-ANSWER RUN: after the 200 the answer is ACKed and the app runs — the +# BYE (and the app's DTMF RTP) appear phase=post. +# +# RED (revert CP3 -> app runs immediately): the app runs and tears the unanswered +# leg down before the delayed 200; the 200 is orphaned (no post-answer ACK, no +# BYE). Captured below by reverting the wait. +# +# Isolated Docker only; never touches the live voice stack / carrier / real PIN. +# tests/cp3-originate-wait/run.sh +set -euo pipefail + +HARNESS_DIR="$(cd -- "$(dirname -- "${BASH_SOURCE[0]}")" && pwd)" +REPO_DIR="$(cd -- "$HARNESS_DIR/../.." && pwd)" +RUNTIME_DIR="$REPO_DIR/target/cp3-originate-wait" +CONFIG_DIR="$RUNTIME_DIR/config" +RUN_DIR="$RUNTIME_DIR/run" +RUSTISK_LOG="$RUNTIME_DIR/rustisk.log" +PROOF="$RUNTIME_DIR/PROOF.txt" +CAPTURE="$RUNTIME_DIR/carrier.log" + +RUSTISK_IMAGE="python@sha256:e031123e3d85762b141ad1cbc56452ba69c6e722ebf2f042cc0dc86c47c0d8b3" + +NET="cp3-net-$$" +RUSTISK_CONTAINER="cp3-rustisk-$$" +CARRIER_CONTAINER="cp3-carrier-$$" +THIRD_OCTET="$((20 + ($$ % 200)))" +SUBNET="10.249.$THIRD_OCTET.0/24" +IP_RANGE="10.249.$THIRD_OCTET.32/27" +RUSTISK_IP="10.249.$THIRD_OCTET.2" +SECRET_DIR="" +ANSWER_DELAY="${CP3_ANSWER_DELAY:-2.0}" + +reap_container() { + local c="$1" hp i + docker inspect "$c" >/dev/null 2>&1 || return 0 + hp="" + for i in 1 2 3 4 5; do + hp="$(docker inspect -f '{{.State.Pid}}' "$c" 2>/dev/null || true)" + [[ -n "$hp" && "$hp" != "0" ]] && break + sleep 0.3 + done + if [[ -n "$hp" && "$hp" != "0" ]]; then + kill -TERM "$hp" 2>/dev/null || true + timeout 3 docker wait "$c" >/dev/null 2>&1 || true + if docker inspect -f '{{.State.Running}}' "$c" 2>/dev/null | grep -q true; then + kill -KILL "$hp" 2>/dev/null || true + timeout 3 docker wait "$c" >/dev/null 2>&1 || true + fi + fi + timeout 10 docker rm -f "$c" >/dev/null 2>&1 || true + for _ in $(seq 1 20); do docker inspect "$c" >/dev/null 2>&1 || return 0; sleep 0.25; done + return 1 +} + +cleanup() { + docker logs "$RUSTISK_CONTAINER" >"$RUSTISK_LOG" 2>&1 || true + local leaked=0 + reap_container "$CARRIER_CONTAINER" || leaked=1 + reap_container "$RUSTISK_CONTAINER" || leaked=1 + timeout 10 docker network rm "$NET" >/dev/null 2>&1 || true + if [[ -n "$SECRET_DIR" && "$SECRET_DIR" == /mnt/data/herodevs-agents/cp3-pin-secret.* ]]; then + rm -rf "$SECRET_DIR" + fi + local still_net="" + docker network inspect "$NET" >/dev/null 2>&1 && still_net="$NET" + if (( leaked == 1 )) || [[ -n "$still_net" ]]; then + printf 'CLEANUP WARNING: leaked docker resources — reap by hand (docker rm -f, docker network rm %s)\n' "$NET" >&2 + fi +} +trap cleanup EXIT +trap 'exit 130' INT +trap 'exit 143' TERM + +fail() { printf 'FAIL: %s\n' "$*" >&2; exit 1; } +require_command() { command -v "$1" >/dev/null 2>&1 || fail "required command not found: $1"; } +say() { printf '%s\n' "$*"; } +container_ip() { docker inspect -f "{{(index .NetworkSettings.Networks \"$NET\").IPAddress}}" "$1" 2>/dev/null; } + +wait_for_file_line() { + local file="$1" pattern="$2" timeout="$3" + local deadline=$(( $(date +%s) + timeout )) + while (( $(date +%s) < deadline )); do + [[ -f "$file" ]] && grep -q -- "$pattern" "$file" && return 0 + sleep 0.3 + done + return 1 +} + +wait_for_rustisk_boot() { + local deadline=$(( $(date +%s) + 40 )) + while (( $(date +%s) < deadline )); do + docker logs "$RUSTISK_CONTAINER" 2>&1 | grep -q 'fully booted' && return 0 + if ! docker inspect -f '{{.State.Running}}' "$RUSTISK_CONTAINER" 2>/dev/null | grep -q true; then + docker logs "$RUSTISK_CONTAINER" >"$RUSTISK_LOG" 2>&1 || true + fail "rustisk container exited during boot; see $RUSTISK_LOG" + fi + sleep 0.5 + done + return 1 +} + +wait_for_ami() { + local deadline=$(( $(date +%s) + 20 )) + while (( $(date +%s) < deadline )); do + docker exec "$RUSTISK_CONTAINER" python3 -c \ + "import socket,sys; s=socket.create_connection(('127.0.0.1',15038),2); d=s.recv(64); sys.exit(0 if d else 1)" \ + >/dev/null 2>&1 && return 0 + sleep 0.5 + done + return 1 +} + +# --------------------------------------------------------------------------- +require_command docker; require_command python3; require_command cargo + +say '=== CP3 wait-for-answer harness ===' +rm -rf "$RUNTIME_DIR"; mkdir -p "$CONFIG_DIR" "$RUN_DIR"; : >"$CAPTURE" + +SECRET_DIR="$(mktemp -d /mnt/data/herodevs-agents/cp3-pin-secret.XXXXXX)" +chmod 700 "$SECRET_DIR"; umask 077 +printf '%06d\n' "$(( (RANDOM * 32768 + RANDOM) % 1000000 ))" >"$SECRET_DIR/pin" + +say "Building rustisk (Rust 1.97.0, CARGO_BUILD_JOBS=${CARGO_BUILD_JOBS:-6})..." +( cd "$REPO_DIR" && CARGO_BUILD_JOBS="${CARGO_BUILD_JOBS:-6}" cargo +1.97.0 build -p rustisk-cli ) +[[ -x "$REPO_DIR/target/debug/rustisk" ]] || fail "rustisk debug binary not built" + +sed -e "s|@CONFIG_DIR@|$CONFIG_DIR|g" -e "s|@RUN_DIR@|$RUN_DIR|g" \ + "$HARNESS_DIR/config/asterisk.conf.tmpl" >"$CONFIG_DIR/asterisk.conf" +cp "$HARNESS_DIR/config/manager.conf" "$CONFIG_DIR/manager.conf" +cp "$HARNESS_DIR/config/extensions.conf" "$CONFIG_DIR/extensions.conf" +cp "$HARNESS_DIR/config/rtp.conf" "$CONFIG_DIR/rtp.conf" +printf '[general]\nsecret_file = /run/secrets/rustisk/pin\n' >"$CONFIG_DIR/pin_gate.conf" + +say "Creating isolated --internal network $NET..." +docker network create --internal --subnet "$SUBNET" --ip-range "$IP_RANGE" "$NET" >/dev/null + +say "Starting offline carrier (delays 200 by ${ANSWER_DELAY}s; captures SIP + RTP by phase)..." +docker run -d --rm --name "$CARRIER_CONTAINER" \ + --network "$NET" --user "$(id -u):$(id -g)" \ + --mount "type=bind,src=$HARNESS_DIR/carrier_delay.py,dst=/carrier_delay.py,readonly" \ + --mount "type=bind,src=$RUNTIME_DIR,dst=/runtime" \ + "$RUSTISK_IMAGE" python3 /carrier_delay.py --caller "$RUSTISK_IP" \ + --capture /runtime/carrier.log --answer-delay "$ANSWER_DELAY" >/dev/null +S="" +for _ in $(seq 1 40); do S="$(container_ip "$CARRIER_CONTAINER")"; [[ -n "$S" ]] && break; sleep 0.25; done +[[ -n "$S" ]] || fail "could not read carrier container IP" +wait_for_file_line "$CAPTURE" "READY own=" 15 || fail "carrier never became ready" +say "Carrier IP = $S" + +sed -e "s|@CORE_S@|$S|g" "$HARNESS_DIR/config/pjsip.conf.tmpl" >"$CONFIG_DIR/pjsip.conf" + +say "Starting isolated rustisk at $RUSTISK_IP..." +docker run -d --rm --name "$RUSTISK_CONTAINER" \ + --network "$NET" --ip "$RUSTISK_IP" \ + --ulimit nofile=65536:65536 --user "$(id -u):$(id -g)" \ + --entrypoint /rustisk \ + --mount "type=bind,src=$REPO_DIR/target/debug/rustisk,dst=/rustisk,readonly" \ + --mount "type=bind,src=$HARNESS_DIR/ami_originate.py,dst=/ami_originate.py,readonly" \ + --mount "type=bind,src=$RUNTIME_DIR,dst=$RUNTIME_DIR" \ + --mount "type=bind,src=$SECRET_DIR/pin,dst=/run/secrets/rustisk/pin,readonly" \ + "$RUSTISK_IMAGE" -f -vvv -C "$CONFIG_DIR/asterisk.conf" >/dev/null + +wait_for_rustisk_boot || fail "rustisk did not report fully booted" +wait_for_ami || fail "rustisk AMI never became reachable" +say 'rustisk booted; AMI reachable.' + +say 'AMI Originate PJSIP/carrier ...' +docker exec -i "$RUSTISK_CONTAINER" python3 /ami_originate.py 127.0.0.1 15038 carrier cp3-orig >/dev/null \ + || fail "AMI Originate failed to queue" + +# Wait for the carrier to send its (delayed) 200 and for the post-answer BYE. +wait_for_file_line "$CAPTURE" "SENT-200 " 15 || { docker logs "$RUSTISK_CONTAINER" >"$RUSTISK_LOG" 2>&1 || true; fail "carrier never sent its delayed 200"; } +wait_for_file_line "$CAPTURE" "BYE phase=post" 15 || true # asserted below (RED path won't have it) +sleep 1 + +# ============================================================================ +# Receiver-side assertions +# ============================================================================ +# Pre-answer window MUST be silent except for the INVITE (no ACK/BYE/CANCEL/RTP). +PRE_NOISE="$(grep -E 'phase=pre' "$CAPTURE" | grep -E '^(ACK|BYE|CANCEL|RTP)' || true)" +if [[ -z "$PRE_NOISE" ]]; then SILENCE="PASS"; else SILENCE="FAIL"; fi + +# Post-answer: the answer is ACKed and the app runs (BYE) AFTER the 200. +if grep -q "ACK phase=post" "$CAPTURE" && grep -q "BYE phase=post" "$CAPTURE"; then + POST="PASS" +else + POST="FAIL" +fi + +# Informational: app's DTMF media arrived (only) after answer. +RTP_PRE="$(grep -c 'RTP phase=pre' "$CAPTURE" || true)" +RTP_POST="$(grep -c 'RTP phase=post' "$CAPTURE" || true)" + +VERDICT_OK=1 +[[ "$SILENCE" == "PASS" ]] || VERDICT_OK=0 +[[ "$POST" == "PASS" ]] || VERDICT_OK=0 +[[ "${RTP_PRE:-0}" == "0" ]] || VERDICT_OK=0 + +{ + echo "CP3 wait-for-answer harness — PROOF" + echo "generated: $(date -u +%FT%TZ)" + echo "rustisk HEAD: $(cd "$REPO_DIR" && git rev-parse --short HEAD 2>/dev/null || echo unknown)" + echo "answer delay: ${ANSWER_DELAY}s" + echo + echo "PRE-ANSWER SILENCE (only INVITE before the 200, no ACK/BYE/CANCEL/RTP): $SILENCE" + echo "POST-ANSWER RUN (answer ACKed + app BYE after the 200): $POST" + echo "RTP datagrams pre-answer (must be 0): ${RTP_PRE:-0}" + echo "RTP datagrams post-answer (app media): ${RTP_POST:-0}" + echo + echo "--- carrier capture (receiver-side, phase-tagged, rel = seconds since start) ---" + cat "$CAPTURE" 2>/dev/null || true +} >"$PROOF" + +say '' +say '================ VERDICT ================' +cat "$PROOF" + +if (( VERDICT_OK == 1 )); then + say '' + say "PASS: Originate stayed SILENT before answer and ran the app only after the delayed 200 (receiver-side)." + exit 0 +else + fail "CP3 harness verdict FAILED (see verdict above)" +fi