Some inbound calls answer normally at the SIP level, but the PBX never accepts a single RTP packet from the carrier. Asterisk already logs the evidence: a Strict RTP "learning" line that never turns into a lock or a source switch. Here's how I turned that into an alert, corroborated it with Homer RTCP, avoided the early-media trap, and used one SIP header to decide where to send the ticket.
Tested on: Asterisk 18 (ViciDial build, chan_sip, strictrtp=seqno, ConfBridge/softmix agent bridges), Loki, Homer with heplify-server on PostgreSQL 16. Check your Asterisk version's res_rtp_asterisk.c for the exact log wording.
What does inbound dead air look like?
The agent answers and hears nothing. SIP looks normal (INVITE, 183, 200 OK, ACK, BYE), the CDR shows a short answered call, and the agent gets blamed. The first one I caught sat in the agent's bridge for about 6 seconds. Asterisk's log showed the carrier's media address set from SDP, then nothing: no packet from that stream was ever accepted.
Then it stopped being a one-off. One morning, 26 answered inbound calls in 44 minutes had no carrier RTP accepted at the PBX, across three inbound trunks: 26 of the 125 calls on those trunks that reached an agent bridge, about one in five. The previous day's 12 business hours had 1,330 bridged calls on the same trunks and none like this. What this shows is that no carrier RTP was accepted at the PBX; assigning blame needs packet captures or carrier evidence.
Which Asterisk log lines show whether RTP arrived?
With strict RTP enabled (strictrtp=yes, the default, or seqno), res_rtp_asterisk.c logs the source-learning state of every RTP stream at verbose level 4. Real lines from my server, with addresses, IDs and dates replaced:
[15:33:36] VERBOSE[17871][C-0001a2b3] res_rtp_asterisk.c: 0x7f7f... -- Strict RTP learning after remote address set to: 198.51.100.23:45892
[13:42:40] VERBOSE[3563][C-0001a0f0] res_rtp_asterisk.c: 0x7f7e... -- Strict RTP learning complete - Locking on source address 203.0.113.10:10256
[13:43:01] VERBOSE[6158][C-0001a0f3] res_rtp_asterisk.c: 0x7f7f... -- Strict RTP switching to RTP target address 203.0.113.20:30818 as source
[13:43:01] VERBOSE[6158][C-0001a0f3] res_rtp_asterisk.c: 0x7f7e... -- Strict RTP switching source address to 192.0.2.108:41882
What matters is where in the source each one is printed (Asterisk 18):
- "learning after remote address set to" comes from
ast_rtp_remote_address_set(). It fires when the far end's address is set from SDP. No packet is involved. Call it the open. - "Locking on source address", "switching to RTP target address ... as source" and "switching source address to" are all printed in
ast_rtp_read(), the incoming-packet path. Each one means a packet arrived and Asterisk accepted that source. Call any of them a close.
A missing close doesn't mean zero packets hit the NIC. Strict RTP silently drops packets (debug level only) while it qualifies a different source address, which takes 4 sequential packets by default. So an open with no close means Asterisk never accepted a stream for that call. A real 50-packet-per-second stream bridged for several seconds should get through probation from any address, so an unpaired open is a strong candidate, but only a candidate.
Also, SDP says where the carrier wants to receive media, not where it sends from. A different source shows up as "switching source address to
Prerequisites: messages must log verbose at level 4 or higher, and you must match all three close forms. Over about four months my messages file had 414,530 opens, 369,649 "Locking", 234,563 "switching to RTP target" and 101,985 "switching source address" lines. Match only "Locking" and you'll flag healthy calls.
How do I tell an answered inbound call from a ring that went nowhere?
Unanswered calls also leave unpaired opens, since many carriers send nothing before the answer: 16 of 42 in a two-hour window around the incident. So for each unpaired open, read the lines with the same C- ID and check:
- Bridge evidence. In my ViciDial build the customer channel goes into a ConfBridge softmix conference:
Channel SIP/<trunk>-xxxx joined 'softmix' base-bridge. Ring-group overflow viaDial()logsapp_dial.c: SIP/... answeredinstead. The first such line is the join;left 'softmix'is the leave. MeetMe-based ViciDial setups log different lines. - Direction. The context must name the inbound trunk's channel and inbound dialplan context. With one peer name for both directions, a silent outbound leg looks identical at the RTP layer.
- DID and caller ID, for the alert.
MixMonitorand my dialplan'sPhone call from ...line both run before the200 OK, so neither proves an answer.
Here's the first incident, filtered to its C- ID:
15:33:36 Strict RTP learning after remote address set to: 198.51.100.23:45892
15:33:36 Executing [process@trunkinbound:10] Verbose("SIP/carrier_in-...", "Phone call from ...")
15:33:40 Executing [...] ConfBridge("SIP/carrier_in-...", "...,vici_agent_bridge,vici_customer_user")
15:33:40 Channel SIP/carrier_in-... joined 'softmix' base-bridge <...>
15:33:46 Channel SIP/carrier_in-... left 'softmix' base-bridge <...>
An open, a join, a leave six seconds later, no close.
This covers calls that reached a bridge. In the incident window one more call never locked: the PBX answered it into the queue and the carrier hung up 7 seconds later, before any agent. If queue dead air matters to you, anchor on the PBX's 200 OK instead.
How long should I wait for a close?
Don't measure the hold from the open, which happens when the call arrives: ring-group overflow calls ring a long time (48 s in a 12-hour sample).
Anchor on the join instead. From the raw log file over 12 business hours: 1,330 bridged inbound calls on the three trunks, every one closed, median close in the same second as the join, latest 2 s after it. These time the logged transition, not packet arrival, at one-second resolution. During the incident the latest healthy close was 5 s after the join.
My rule: no close for the call by join + 20 s. That's several times the worst case, and the candidate is ready well under a minute after the agent picks up.
What does the detector code look like?
My watcher reads the logs from Loki, but tailing messages works the same. This is the core matching logic, simplified from my production script with documentation-range addresses. It runs as shown:
import re
# One entry per inbound door. The SAME matcher is used for opens and closes.
CARRIERS = {
"carrier_a": {"media": (r"203\.0\.113\.\d+", r"198\.51\.100\.\d+"), "chan": "SIP/carrier_a_in_"},
"carrier_b_nl": {"media": (r"192\.0\.2\.190",), "chan": "SIP/carrier_b_nl-"},
"carrier_b_de": {"media": (r"192\.0\.2\.163",), "chan": "SIP/carrier_b_de-"},
}
for c in CARRIERS.values():
c["re"] = re.compile(r"(?:%s):\d+" % "|".join(c["media"]))
# [C-call tag] ... res_rtp_asterisk.c: 0x<RTP instance> -- Strict RTP <event>
RE_STRICT = re.compile(r"\[(C-[0-9a-f]+)\] res_rtp_asterisk\.c: (0x[0-9a-f]+) -- Strict RTP (.*)$")
RE_OPEN = re.compile(r"learning after remote address set to: (\S+)")
RE_CLOSE = re.compile(r"learning complete - Locking on source address (\S+)"
r"|switching to RTP target address (\S+) as source"
r"|switching source address to (\S+)")
def media_carrier(ip_port):
for name, c in CARRIERS.items():
if c["re"].fullmatch(ip_port or ""):
return name
return None
def parse_lines(lines):
"""lines: [(ts_ns, text)] for ONE PBX, complete for the window.
Returns (opens, closes, multi).
opens: the FIRST carrier-facing stream of each call (the inbound leg's).
closes: {(call_tag, rtp_instance): [(ts_ns, seq)]}, carrier-range only.
multi: call tags that opened more than one carrier-facing RTP instance
(e.g. an overflow dialled out through a carrier). Flag those for review.
seq is the position after a stable sort by time, so same-second lines
keep their order."""
ordered = sorted(enumerate(lines), key=lambda x: (x[1][0], x[0]))
opens, closes, first, instances = [], {}, {}, {}
for seq, (_, (ts, line)) in enumerate(ordered):
m = RE_STRICT.search(line)
if not m:
continue
cid, inst, event = m.groups()
o = RE_OPEN.match(event)
if o:
if not media_carrier(o.group(1)):
continue
instances.setdefault(cid, set()).add(inst)
if cid not in first: # later re-opens (re-INVITE) and other legs: not covered
first[cid] = {"ts_ns": ts, "seq": seq, "cid": cid, "inst": inst,
"ip_port": o.group(1), "trunk": media_carrier(o.group(1))}
opens.append(first[cid])
continue
c = RE_CLOSE.match(event)
if c:
ip_port = next(g for g in c.groups() if g)
# any address in a carrier range, so a learned source change pairs
if media_carrier(ip_port):
closes.setdefault((cid, inst), []).append((ts, seq))
multi = {cid for cid, s in instances.items() if len(s) > 1}
return opens, closes, multi
def first_close(closes, o, upto_ns):
"""First close of the SAME call and SAME RTP instance after the open and
no later than upto_ns. Another call reusing the port, or another leg of
this call, can't pair it."""
for ts, seq in closes.get((o["cid"], o["inst"]), []):
if (ts, seq) > (o["ts_ns"], o["seq"]) and ts <= upto_ns:
return ts
return None
Every Strict RTP line carries the call's C- tag and the RTP instance pointer (0x...), so closes are keyed by both, not by port. Carriers reuse ports, so a match keyed on port can let a later call's lock "close" a dead one. Keying on the instance stops another leg of the same call from closing it too, for example an overflow dialled back out through a carrier. Calls with more than one carrier-facing instance come back in multi, so you can review them; my two days of raw logs had none. Only carrier-range closes count, so a ring-group phone's stream doesn't. The input must be complete and in time order; the stable sort keeps same-second lines in file order.
A Loki query that feeds it:
{server="pbx", job="asterisk"} |= "Strict RTP" |~ "203\\.0\\.113\\.\\d+|198\\.51\\.100\\.\\d+|192\\.0\\.2\\.190|192\\.0\\.2\\.163"
LogQL literals use Go escaping, so a regex \. is written \\.. query_range returns newest-first by default and silently stops at limit, so use direction=forward, split any window that hits the limit until none does, and merge before parsing. Then check the pipeline against the source: for one 12-hour window, two Loki runs gave 2,121 and 2,016 opens where the raw messages file had 2,284. All numbers here come from the raw file.
Each pass keeps as a candidate any bridged inbound call with no close by join + 20 s plus an ingest margin, and sends it to Homer before posting.
Opens and closes must use the same matcher: an alias of mine that matched one carrier's two POP ranges for opens but one for closes made every healthy call on the other POP a false candidate.
What can Homer RTCP add?
Your own RTCP corroborates the log signal; it comes from the same reception state, so it isn't independent proof. The carrier's RTCP, where it sends any, is the closest thing to independent evidence short of packet captures at both ends.
Your side. In Asterisk 18 a report carries a reception block once the far end's SSRC is recorded (themssrc_valid), which happens after a packet passes strict RTP and then stays set. RFC 3550 only requires blocks for sources heard since the previous report, so another stack may drop the block between bursts; check yours. heplify stores RTCP as JSON in hep_proto_5_default. In 128,786 reports around the incident, report_blocks was a non-empty array or null, never empty, missing or unparseable, but the SQL below still treats those as unclear rather than "nothing received".
Here are my side's reports for one dead call, in seconds relative to the 200 OK:
T-0.6 {"sender_information":{"packets":250,...},"report_blocks":null} <- before the answer
T+4.4 {"sender_information":{"packets":491,...},"report_blocks":null}
T+9.4 {"sender_information":{"packets":741,...},"report_blocks":null}
T+14.4 {"sender_information":{"packets":991,...},"report_blocks":null}
We sent 50 packets a second; no far-end SSRC was ever recorded.
The carrier's side. Under RFC 3550, a participant that has sent RTP since its last report sends a Sender Report; otherwise a Receiver Report. heplify's decoder only fills sender_information for a Sender Report, so a Receiver Report shows zeros. The stored type is useless here (on compound packets it's the last sub-packet, 202 on most of my rows), so I test for a non-zero NTP timestamp; in one hour of my data it always coincided with a non-zero packet count. In that dead call every carrier report had a zero NTP timestamp, and a report block for our stream with the sequence number climbing about 200 every 4 s.
Over one hour on that carrier's trunks, all 85 calls where our side reported reception got real Sender Reports from the carrier (1,680 of 1,723 carrier reports had a sender timestamp). The dead calls got Receiver Reports only. That corroborates the log signal: the carrier's RTCP stack didn't consider itself a sender at its SBC. Corroboration, not proof, and silent about further upstream. The other carrier's relay sent no RTCP my capture saw.
Why is RTCP from before the answer meaningless?
The first report above was emitted before the 200 OK. My PBX replies with 183 Session Progress with SDP and starts early media (ringback) at once, then sends the final 200 OK on answer. So it emits RTCP during the ring, when a healthy carrier usually isn't sending yet.
In the hour before the incident, all 148 bridged calls with my RTCP had our 183 before the 200 OK. 48 had a report before the answer, and all 48 pre-answer reports had no receiver block. From 2 s after the answer it flipped: 2,420 reports, all with a block, and no healthy call where they were all empty.
In the incident window a call torn down 3.7 s after the answer had one pre-answer report from my side, with no block. On RTCP alone it looks dead, but the Asterisk log shows it locked at the answer.
The rule I use:
- Refuted: any report from your side, at any time, has a non-empty block. Asterisk accepted a packet. Don't post.
- Confirmed: at least one report from your side 2 s or more after the
200 OK, and none of your reports for the call, read through the end of the call, has a block. - Unknown: no post-answer report yet (very short calls, capture lag). Re-check next pass, and say so if it never settles.
All 26 incident calls came back confirmed: 1 to 5 post-answer reports each from my side, read 20 minutes past the answer (so through the end of every call), none with a block, and no Sender Report from either carrier.
How do I find the right Homer dialog for a log line?
Homer doesn't know the C- ID, but the carrier's SDP has the media ip:port. It's one statement, so no result from a previous call can leak in. Run it with psql -v pbx_ip=... -v sig_ips=a,b -v media_ip=... -v media_port=... -v open_ts='YYYY-MM-DD HH:MM:SS+00' -f. RTCP is joined to the dialog by sid, which only works if your heplify correlates RTCP to the SIP Call-ID (mine does; check a known call first). My raw columns are bytea; if yours are text, drop the convert_from(...) wrappers.
-- One statement, no carried-over variables. Inputs: pbx_ip, sig_ips (comma list),
-- media_ip, media_port, open_ts. Output: one row with a verdict.
WITH inv AS ( -- carrier INVITEs whose SDP carries the open's media endpoint
SELECT i.sid,
coalesce(substring(convert_from(i.raw,'UTF8') from '(?i)\nx-oid:\s*([^\r\n]+)'), '') AS x_oid
FROM hep_proto_1_call i
WHERE i.create_date BETWEEN :'open_ts'::timestamptz - interval '90 seconds'
AND :'open_ts'::timestamptz + interval '3 seconds'
AND i.protocol_header->>'dstIp' = :'pbx_ip'
AND i.protocol_header->>'srcIp' = ANY (string_to_array(:'sig_ips', ','))
AND convert_from(i.raw,'UTF8') LIKE 'INVITE %'
AND convert_from(i.raw,'UTF8') ~ ('\nc=IN IP4 ' || replace(:'media_ip', '.', '\.') || '\r?\n')
AND convert_from(i.raw,'UTF8') ~ ('\nm=audio ' || :'media_port' || ' ')
), d AS ( -- exactly one dialog, or nothing
SELECT min(sid) AS sid, min(x_oid) AS x_oid, count(DISTINCT sid) AS n FROM inv
), a AS ( -- first 200 to an INVITE, sent by the PBX
SELECT d.*, (SELECT min(k.create_date) FROM hep_proto_1_call k
WHERE d.n = 1 AND k.sid = d.sid
AND k.create_date BETWEEN :'open_ts'::timestamptz - interval '90 seconds'
AND :'open_ts'::timestamptz + interval '10 minutes'
AND k.protocol_header->>'srcIp' = :'pbx_ip'
AND convert_from(k.raw,'UTF8') ~ '^SIP/2\.0 200 '
AND convert_from(k.raw,'UTF8') ~* '\ncseq:\s*[0-9]+\s+invite') AS t200
FROM d
), r AS ( -- every RTCP report of that dialog, classified
SELECT p.create_date, p.protocol_header->>'srcIp' AS src, x.j,
CASE WHEN x.j IS NULL THEN 'unparsed'
WHEN NOT x.j ? 'report_blocks' THEN 'missing'
WHEN jsonb_typeof(x.j->'report_blocks') = 'null' THEN 'none'
WHEN jsonb_typeof(x.j->'report_blocks') <> 'array' THEN 'malformed'
WHEN jsonb_array_length(x.j->'report_blocks') = 0 THEN 'empty'
ELSE 'blocks' END AS rb
FROM a
JOIN hep_proto_5_default p
ON p.sid = a.sid
AND p.create_date BETWEEN a.t200 - interval '2 minutes' AND a.t200 + interval '20 minutes'
CROSS JOIN LATERAL (SELECT CASE WHEN convert_from(p.raw,'UTF8') IS JSON
THEN convert_from(p.raw,'UTF8')::jsonb END AS j) x
WHERE a.n = 1 AND a.t200 IS NOT NULL
), s AS (
SELECT
count(*) FILTER (WHERE rb IN ('unparsed','missing','malformed','empty')) AS unclear,
count(*) FILTER (WHERE src = :'pbx_ip' AND rb = 'blocks') AS pbx_with_block,
count(*) FILTER (WHERE src = :'pbx_ip' AND create_date >= (SELECT t200 FROM a) + interval '2 seconds') AS pbx_post,
count(*) FILTER (WHERE src = :'pbx_ip' AND rb = 'none'
AND create_date >= (SELECT t200 FROM a) + interval '2 seconds') AS pbx_post_none,
count(*) FILTER (WHERE src <> :'pbx_ip' AND jsonb_typeof(j->'sender_information') = 'object'
AND (j->'sender_information'->>'ntp_timestamp_sec') ~ '^[0-9]+$'
AND (j->'sender_information'->>'ntp_timestamp_sec')::numeric > 0) AS far_end_sr
FROM r
)
SELECT a.n AS dialogs, a.t200, a.x_oid, s.*,
CASE WHEN a.n <> 1 OR a.t200 IS NULL THEN 'unknown'
WHEN s.pbx_with_block > 0 THEN 'refuted'
WHEN s.unclear > 0 OR s.pbx_post = 0 THEN 'unknown'
WHEN s.pbx_post_none = s.pbx_post THEN 'confirmed'
ELSE 'unknown' END AS verdict
FROM a, s;
The INVITE window allows 3 s of clock skew after the open. The verdict is unknown unless exactly one dialog matched and it has a PBX 200 whose CSeq method is INVITE, or if any report is unclear (unparsed, missing, malformed or empty report_blocks). All 26 incident calls came back confirmed, each matching exactly 1 dialog with no carrier re-INVITEs and no sendonly/inactive. A healthy control call came back refuted. The 3.7 s early-media call came back unknown. Always bound create_date: a day-wide version of a similar join hit my 5-minute timeout.
How did one SIP header point to a shared upstream?
The 26 calls came through three doors: 14 on Carrier A's direct trunk, 7 via Carrier B's NL-labelled SBC and 5 via its DE-labelled SBC. Three trunks failing in the same 44 minutes suggested something shared upstream.
The clue was in Carrier B's INVITEs, which carry an extra header:
INVITE sip:... (from Carrier B's SBC)
Call-ID: <a UUID, Carrier B's own format>
X-OID: <an ID in Carrier A's Call-ID format>
INVITE sip:... (from Carrier A's direct trunk)
Call-ID: <Carrier A's format>
Carrier B's own Call-IDs are UUIDs. The X-OID value has the same distinctive multi-field layout as Carrier A's Call-IDs on my direct trunk. It was on all 12 Carrier B dead calls, and that day on 651 of 651 inbound dialogs from the DE-labelled SBC and 346 of 349 from the NL-labelled one. The three without it showed one of our own extension or agent names in the From display name; I didn't dig further.
That doesn't prove Carrier A originated them. Shared SBC software could produce the same format, and simultaneous failures don't locate a fault. But it changed what I did: I widened the watcher, which had missed the 12 Carrier B calls, and put X-OID in every alert and ticket. Carrier B can confirm it against the upstream leg in its own signalling trace. Look at a full INVITE from each of your trunks for similar headers.
How do I keep the watcher from going silently blind?
A detector that finds nothing looks healthy. Each guard is a reason to investigate, not a diagnosis:
- Empty is never clean. No strict-RTP lines? Check the PBX stream has any recent lines; warn after 24 hours without them.
- Freshness. Newest PBX line older than 45 s? Skip the pass without advancing coverage. Tune it to your traffic.
- Coverage per trunk. Hourly, for each trunk with 10+ inbound calls, count how many opened a stream on a mapped address. Below half means the media moved, the log format changed, or the classifier broke. One carrier's media move left my watcher blind until this check existed.
- Keep Homer off the critical path. Short timeout, per-pass budget. A candidate still unsettled after 10 minutes is posted as "unconfirmed" only if bridged within 20 s of the open, in the bridge 5 s or more, and still unclosed.
- Replay. A
--dry-runmode with--start/--endruns the same rule over a past window and writes nothing. I replayed this version over the previous week before switching.
What doesn't this catch?
- Silent RTP. Packets can flow with 0% loss and carry near-silence. For a complaint, check the recording's inbound leg.
- Media that stops later. A stream that locks and then dies mid-call is out of scope. So is a re-INVITE whose new stream never locks.
- Calls that never reach a bridge. See the queued call above.
- Who hung up. Don't assume it was the caller giving up. In the 26 incident calls, the first
BYEcame from the PBX side on 15 and from the carrier on 11.
FAQ
Could my own firewall or NAT be the cause? Possibly; this method alone can't rule it out. What pointed away from my side: 99 calls on the same trunks were fine in the same minutes, the trunks were clean the day before, and Carrier B's RTCP showed no Sender Reports on its dead calls. For certainty, capture packets on the PBX interface during an occurrence and compare with the carrier's capture.