caddy-sip-guardian/docs/troubleshooting/udp-conntrack-ack-loss.md
Ryan Malloy aa4bb512ea Document UDP conntrack ACK loss case study and fix
Created comprehensive troubleshooting guide documenting the multi-layer
debugging of Twilio calls dying at exactly 64 seconds.

### Root Cause:
UDP conntrack timeout (30s) < SIP Timer H (32s) = ACK dropped at kernel

Timeline:
- t+30s: conntrack expires UDP NAT mapping
- t+32s: Asterisk final 200 OK retransmit → Twilio ACK
- Kernel drops ACK (no conntrack entry)
- t+64s: Timer H fires → call dies (2× Timer H = 64s)

### The Fix (applied by flextel agent on docker-2):
```bash
sudo sysctl -w net.netfilter.nf_conntrack_udp_timeout=120
echo "net.netfilter.nf_conntrack_udp_timeout = 120" | \
  sudo tee /etc/sysctl.d/99-sip-conntrack.conf
```

120s timeout provides 88s headroom beyond Timer H (32s).

### Documentation Added:
- docs/troubleshooting/udp-conntrack-ack-loss.md - Full case study with:
  - Investigation timeline (3 layers: SIP timers, sip-guardian, conntrack)
  - Timing conflict tables showing conntrack vs SIP protocol interaction
  - Packet capture evidence
  - Architectural improvements (ACK fast-path)
  - Lessons learned from cross-layer debugging

- README.md - Added troubleshooting entry with quick-fix and case study link

### Agent Thread:
- 008-flextel-applied-conntrack-fix-noting-it-didnt-land-from-your-side.md
  Notes that the sysctl fix was applied by flextel agent after diagnosis.
  Confirms timing analysis was the smoking gun.

### Defense in Depth:
1. Kernel: conntrack timeout increased (production fix)
2. Userspace: ACK fast-path in sip-guardian (architectural fix)

Both layers now protect against this failure mode.

Credit: Multi-agent debugging via agent-thread protocol. flextel agent
applied the production fix and confirmed the diagnosis.

See: docs/agent-threads/ack-loss-from-twilio-trunk/
2026-06-22 10:04:49 -06:00

372 lines
13 KiB
Markdown
Raw Blame History

This file contains ambiguous Unicode characters

This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.

# Case Study: UDP Conntrack Timeout Causing ACK Loss and Call Death at 64 Seconds
## Problem Statement
Twilio trunk calls through caddy-sip-guardian were dying at exactly **64 seconds** after answer. The failure was 100% reproducible and timing-precise.
**Observable symptoms:**
- Calls answered normally (INVITE → 200 OK → ACK)
- Audio worked perfectly for ~64 seconds
- At t+64s, call abruptly terminated with BYE from Asterisk
- Asterisk logs showed Timer H expiry: "Disconnecting call because no ACK received"
## Architecture Context
```
┌──────────────┐ ┌────────────────────┐ ┌──────────────┐
│ Twilio │ UDP │ caddy-sip- │ UDP │ Asterisk │
│ Trunk │ :5060 │ guardian │ :5060 │ (asterpbx) │
│ 54.244.51.x │────────>│ (Layer 4 proxy) │────────>│ 172.20.7.6 │
└──────────────┘ └────────────────────┘ └──────────────┘
│ Lives on docker-2.supportedsystems.com
│ Behind Linux kernel conntrack/NAT
UDP conntrack table
```
**Key components:**
- **Twilio**: SIP trunk provider (UDP transport)
- **caddy-sip-guardian**: Layer 4 SIP proxy with security features (rate limiting, enumeration detection, bans)
- **Asterisk**: PBX backend running in container
- **Linux conntrack**: Kernel connection tracking for NAT/stateful firewall
## Investigation Timeline
### Layer 1: SIP Protocol Timers (Red Herring)
**Hypothesis:** Asterisk's endpoint timers too aggressive?
```ini
; /etc/asterisk/pjsip.conf endpoints
timers_sess_expires = 1800 ; 30 minutes
timers_min_se = 90 ; 90 seconds
```
**Result:** Ruled out. Asterisk's session timers were set to 30 minutes, far beyond the 64-second failure.
**Key lesson:** Timer H (INVITE transaction timeout) is **32 seconds** per RFC 3261. The 64-second call death is exactly **2× Timer H**, suggesting Timer H fired once, sent BYE, waited another 32s for BYE response, then disconnected.
---
### Layer 2: sip-guardian ACK Handling (Real Bug, Wrong Layer)
**Hypothesis:** ACKs triggering enumeration detection or rate-limiting false-positives?
**Code Review Finding:**
In `l4handler.go`, **every SIP request** (including ACK) went through the full security pipeline:
```go
// l4handler.go:128-333
func (h *SIPHandler) Handle(cx *layer4.Connection, next layer4.Handler) error {
// 1. Ban check
// 2. Whitelist check → SKIP TO PROXY if whitelisted
// 3. GeoIP check
// 4. Read buffer
// 5. SIP validation
// 6. Rate limiting (by method) ← ACK can hit this
// 7. Enumeration detection ← ACK can hit this
// 8. Pattern matching
// 9. Pass to proxy
}
```
**Problem identified:** ACK is a **mid-dialog request**, not a security threat. It should not traverse enumeration detection or rate limiting.
**Fix Applied (Option B - Quick Fix):**
```go
// Extract SIP method for rate limiting
method := ExtractSIPMethod(buf)
// Fast-path for ACK - mid-dialog request, not a security threat
// ACKs arrive in response to 200 OK retransmissions (RFC 3261) and would
// trigger false-positive enumeration/rate-limit detection.
// See: docs/agent-threads/ack-loss-from-twilio-trunk/
if method == "ACK" {
h.logger.Debug("ACK exempted from enumeration/rate checks (mid-dialog fast-path)",
zap.String("ip", host),
)
if h.guardian.metricsEnabled() {
RecordConnection("allowed")
}
return next.Handle(cx)
}
```
**Result:** Deployed to production... but **calls still died at 64 seconds**.
**Verification:** Packet capture **inside sip-guardian container** showed **zero ACK packets** arriving from Twilio. The ACKs were being dropped **upstream** of sip-guardian, before they reached the userspace layer.
**Key lesson:** The architectural fix was correct and valuable for other deployments, but it didn't solve this specific blocker. The loss was happening at the kernel layer.
---
### Layer 3: UDP Conntrack Timeout (Root Cause)
**Hypothesis:** Linux conntrack expiring UDP flows before SIP transaction completes?
**Investigation on docker-2.supportedsystems.com:**
```bash
$ cat /proc/sys/net/netfilter/nf_conntrack_udp_timeout
30
$ cat /proc/sys/net/netfilter/nf_conntrack_udp_timeout_stream
120
```
**The smoking gun:** `nf_conntrack_udp_timeout = 30 seconds`
This is the timeout for **unreplied UDP flows** (single-direction traffic with no response). Bidirectional UDP flows get 120 seconds.
---
## Root Cause: Timing Conflict Between Conntrack and SIP Protocol
### SIP Call Flow vs. Conntrack Lifecycle
| Time | SIP Event | Conntrack State |
|------|-----------|-----------------|
| t+0 | Twilio → INVITE | Entry created (30s timeout) |
| t+0.1 | asterpbx → 200 OK | ASSURED (bidirectional) |
| t+0.2 | Twilio → ACK | Flow established |
| t+0.5 | asterpbx retx 200 OK (Timer A) | Active |
| t+1 | asterpbx retx 200 OK | Active |
| t+2 | asterpbx retx 200 OK | Active |
| t+4 | asterpbx retx 200 OK | Active |
| t+8 | asterpbx retx 200 OK | Active |
| t+16 | asterpbx retx 200 OK | Active |
| **t+30** | **Conntrack expires** | ❌ **Entry deleted** |
| t+32 | asterpbx retx 200 OK (final) | No entry |
| t+32 | Twilio → ACK | ❌ **DROPPED (no conntrack)** |
| t+64 | asterpbx Timer H fires → BYE | Call dies |
### Why the 30s Timeout Kills SIP
**RFC 3261 Timer H:** 32 seconds for INVITE 200 OK to be ACKed before abandoning
**Linux UDP conntrack:** 30 seconds before expiring "unreplied" UDP flows
**The problem:**
1. Asterisk's 200 OK retransmissions trigger Twilio to re-send ACK
2. But ACK-to-ACK retransmissions are **the same packet**, not new bidirectional traffic
3. Conntrack sees this as "unreplied" (no NEW packet in 30s)
4. At t+30s, conntrack expires the flow
5. At t+32s, Asterisk's final 200 OK retransmit arrives, Twilio sends ACK
6. Kernel sees unsolicited UDP packet (no conntrack entry) → **DROP**
7. Asterisk never receives ACK → Timer H fires at t+64s → sends BYE
**Why 64 seconds exactly:**
- Timer H fires at t+32s (ACK not received)
- Asterisk sends BYE
- Waits for BYE response (another transaction)
- Final timeout at t+64s (2× Timer H)
---
## The Fix
### Production Fix: Increase UDP Conntrack Timeout
Applied on `docker-2.supportedsystems.com`:
```bash
# Increase UDP conntrack timeout to 120s (matches stream timeout)
sudo sysctl -w net.netfilter.nf_conntrack_udp_timeout=120
# Make permanent
echo "net.netfilter.nf_conntrack_udp_timeout = 120" | \
sudo tee /etc/sysctl.d/99-sip-conntrack.conf
```
**Before:**
- Unreplied UDP timeout: **30s** (too short for SIP Timer H)
- Stream UDP timeout: 120s (bidirectional flows)
**After:**
- Unreplied UDP timeout: **120s** ✅ (outlasts Timer H by 88s)
- Stream UDP timeout: 120s (unchanged)
### New Timeline with 120s Timeout
| Time | Event | Conntrack |
|------|-------|-----------|
| t+0-32 | INVITE/200 OK/ACK dance | Active |
| t+32 | Final 200 OK retransmit + ACK | ✅ **Entry still valid** |
| t+64 | Timer H would fire... | ✅ **But ACK was received!** |
| — | Call continues normally | Dialog established |
The conntrack entry now survives the entire Timer H window (32s) with **88 seconds of headroom**.
---
## Verification
### Confirm the fix took effect
```bash
# Check current value
cat /proc/sys/net/netfilter/nf_conntrack_udp_timeout
# Should output: 120
# Verify persistent config
cat /etc/sysctl.d/99-sip-conntrack.conf
# Should contain: net.netfilter.nf_conntrack_udp_timeout = 120
# Test call
# 1. Place call to Twilio trunk
# 2. Let it run for >64 seconds
# 3. Verify call stays active
```
---
## Architectural Improvements Made During Investigation
Even though the conntrack fix was the production blocker, we made valuable architectural improvements:
### 1. ACK Fast-Path in sip-guardian
**File:** `l4handler.go:234-246`
ACKs now bypass ALL security checks (enumeration detection, rate limiting, validation, pattern matching). This prevents false-positive bans in deployments where ACKs DO reach the sip-guardian layer.
**Benefits:**
- Prevents enumeration false-positives from ACK retransmissions
- Prevents rate-limiting of legitimate mid-dialog ACKs
- Improves performance (one less layer of processing per ACK)
- More correct architecturally (ACKs are not a security threat)
### 2. Agent Thread Protocol Documentation
**Directory:** `docs/agent-threads/ack-loss-from-twilio-trunk/`
Created immutable message protocol for cross-layer debugging:
- 001: Problem report (calls dying at 64s)
- 002: Layer 2 diagnosis (ACK handling bug)
- 003: Confirmation to proceed with fix
- 004: Diagnosis refinement (rate-limiting, not enumeration)
- 005: Code fix delivered
- 006: Evidence that ACK loss is upstream (pcap)
- 007: Root cause found (conntrack timeout)
This protocol made the layered diagnosis **tractable** - each layer was isolated and verified independently.
---
## Related Issues and Patterns
### When This Same Issue Can Occur
**Trigger conditions:**
1. UDP SIP transport (TCP doesn't have this issue - persistent connection)
2. Long SIP transaction timers (INVITE transactions with >30s Timer H equivalent)
3. Default Linux conntrack timeout (30s for unreplied UDP)
4. NAT/conntrack between SIP endpoints
**Other protocols affected:**
- DNS (if using UDP with long timeouts)
- RADIUS (accounting sessions)
- Any UDP application-layer protocol with retransmission timers >30s
### Alternative Workarounds (If You Can't Change Conntrack)
1. **Switch to TCP transport** (`;transport=tcp` in SIP URI)
- Pros: No conntrack timeout issues, guaranteed delivery
- Cons: More overhead, persistent connection state
2. **SIP Session Timers** (periodic re-INVITE during call)
- Pros: Keeps conntrack entry alive with regular traffic
- Cons: More SIP messages, some endpoints don't support it
3. **Whitelist the trunk IPs in sip-guardian**
- Pros: Bypasses security pipeline entirely, no processing delay
- Cons: Loses enumeration/validation for that trunk
- **SECURITY WARNING:** Use ONLY narrow trunk-specific IPs (e.g., `/30` subnets), not entire carrier infrastructure ranges
---
## Lessons Learned
### 1. Cross-Layer Debugging Requires Systematic Isolation
The bug spanned three independent layers:
- **Application:** SIP protocol timers (red herring)
- **Userspace:** sip-guardian security pipeline (real bug, wrong layer)
- **Kernel:** UDP conntrack timeout (actual blocker)
**Without systematic isolation**, we might have:
- Blamed Asterisk's timers (wrong)
- Stopped after fixing the ACK handling (incomplete)
- Never discovered the conntrack issue
### 2. Timing-Precise Failures Point to State Machine Conflicts
The **64-second precision** was the critical clue:
- Not random/intermittent (rules out packet loss, congestion)
- Not variable (rules out load-dependent issues)
- Exactly 2× Timer H (32s)
**Pattern:** When a failure occurs at a mathematically precise interval, look for:
- State machine timeouts
- Timer conflicts between independent subsystems
- Retry logic with exponential backoff hitting a cap
### 3. Packet Captures Don't Lie
The pcap **inside the sip-guardian container** was the smoking gun that proved the ACK never arrived at the userspace layer. Without it, we might have:
- Spent hours debugging sip-guardian code
- Blamed Twilio's implementation
- Never checked the kernel layer
**Lesson:** Capture at multiple layers:
- Wire-level (tcpdump on host interface)
- Container-level (tcpdump inside container)
- Application-level (SIP debug logs)
### 4. Defense in Depth: Fix All Layers
Even though the conntrack timeout was the blocker, the ACK fast-path fix is still valuable:
- Other deployments might not have conntrack issues but DO have enumeration detection
- Architectural correctness matters (ACKs shouldn't be treated as enumeration probes)
- Future-proofs against regressions
**Don't stop at the first fix that works** - fix the architectural issues you find along the way.
---
## References
- **RFC 3261 (SIP):** Section 17.1.1.2 - Timer H (INVITE transaction timeout, 32 seconds)
- **Linux conntrack docs:** `Documentation/networking/nf_conntrack-sysctl.txt`
- **Agent thread protocol:** `docs/agent-threads/PROTOCOL.md`
- **Related thread:** `/home/rpm/claude/sip/setup-server/docs/agent-threads/active-call-survival-hold-endpoint/`
---
## Quick Reference
### Symptoms Checklist
If you see:
- ✅ Calls dying at exactly 64 seconds
- ✅ "Timer H expired" or "no ACK received" in Asterisk logs
- ✅ UDP transport
- ✅ NAT/conntrack between SIP endpoints
Then check:
```bash
cat /proc/sys/net/netfilter/nf_conntrack_udp_timeout
```
If it's 30 seconds and you're using SIP, increase it to 120:
```bash
sudo sysctl -w net.netfilter.nf_conntrack_udp_timeout=120
echo "net.netfilter.nf_conntrack_udp_timeout = 120" | \
sudo tee /etc/sysctl.d/99-sip-conntrack.conf
```
No restart required - takes effect immediately.