sip: log a refused REGISTER or SUBSCRIBE with its status line and reason headers

A refused final was logged as its bare status code ("re-REGISTER failed
503", "reg-event SUBSCRIBE -> 500") — the unprotected REGISTER's as
"expected 401", without even the code — so a field journal could not say
which node refused or what it said. O2 UK answered a phone's 30-minute
refresh with 503 twenty-one times over seventy minutes and then refused
a fresh registration's reg-event SUBSCRIBE with 500 (alyx, 2026-09-24);
the journal holds nothing but the numbers.

Log the status line with the headers that carry the reason —
Retry-After, Warning, Reason, Server — for a REGISTER's refused final
(initial, protected, refresh) and for a refused SUBSCRIBE the run loop
reads, and dump the refused message under DUMP_SIP as its own fail dump
next to the 200s.

To tell a REGISTER's final from what else arrives, the final is now
matched by Call-ID and CSeq, and a request that arrives on the client
flow while one is awaited is dispatched: a refresh no longer reads such
a request as a failed REGISTER. An INVITE among those requests is a call
like any other, announced on the bus: a Dial whose reconnect it arrived
under meets the call-in-progress rule again before it places its own,
and when a resume, a refresh or a reconnect fails the call that arrived
under it ends with the flow it came in on (486 while the flow still
carries one, and the bus told). The unprotected REGISTER's reply is
matched the same way on the init port.

Tested on the dev phone (KPN) in builds of this series; not every path
has run there.

README.md

@@ -281,7 +281,7 @@ PCSCF=2001:db8::105
 | `RTP_PORT` | `50004` | local RTP port advertised in SDP |
 | `PRECOND` | `0` | `1` offers SDP QoS preconditions |
 | `CODECS` | *(empty — defaults)* | comma-separated codec preference list over `AMR-WB`, `AMR` (or `AMR-NB`), `PCMA`, `PCMU`: restricts and orders both the codecs offered on an outgoing call and those accepted from an inbound offer (default: offer AMR-WB + AMR, accept all four in that order). A bench knob — a network whose gateway transcodes every caller up to AMR-WB otherwise never lets the narrowband path run |
-| `DUMP_SIP` | `0` | `1` writes raw REGISTER-200/SUBSCRIBE-200 dumps, the last inbound INVITE (`imsd-invite-in.raw`) and the last outgoing INVITE (`imsd-invite-out.raw`), mode 0600, for debugging — they contain your IMSI/MSISDN and addresses |
+| `DUMP_SIP` | `0` | `1` writes raw REGISTER-200/SUBSCRIBE-200 dumps, the last refused REGISTER or SUBSCRIBE final (`imsd-register-fail.raw`, `imsd-subscribe-fail.raw`), the last inbound INVITE (`imsd-invite-in.raw`) and the last outgoing INVITE (`imsd-invite-out.raw`), mode 0600, for debugging — they contain your IMSI/MSISDN and addresses. A refused REGISTER, and a refused SUBSCRIBE final the run loop reads, are logged with the status line and any Retry-After / Warning / Reason / Server headers |
 | `DUMP_DIR`, `OUT_DIR` | state dir | where dumps / per-call media stats land |
 | `IMSD_MEDIA` | *(auto)* | path to `imsd-media` (default: next to `imsd`, else `/usr/libexec/imsd-media`) |
 

implementations/main.cpp

@@ -796,8 +796,13 @@ public:
                 Execute(call_->OnInviteResponse(*msg));
                 MaybeDropCall();
             } else if (!subCallid_.empty() && callid == subCallid_ && cseq.ends_with("SUBSCRIBE")) {
-                Log(std::format("reg-event SUBSCRIBE -> {}", *st));
+                if (*st >= 300) {
-                DumpRaw("imsd-subscribe-200.raw", *msg);
+                    Log(std::format("reg-event SUBSCRIBE refused: {}", imsd::sip::RefusalSummary(*msg)));
+                    DumpRaw("imsd-subscribe-fail.raw", *msg);
+                } else {
+                    Log(std::format("reg-event SUBSCRIBE -> {}", *st));
+                    if (*st >= 200) DumpRaw("imsd-subscribe-200.raw", *msg);
+                }
             }
         }
         // shutdown: release an active call, keep the SA/registration for resume
@@ -932,7 +937,7 @@ private:
         // failed FRESH registration is.
         if (resume != "0") {
             try { if (TryResume()) return; }
-            catch (const std::exception& e) { Log(std::format("resume failed: {} — registering fresh", e.what())); sip_.Close(); }
+            catch (const std::exception& e) { Log(std::format("resume failed: {} — registering fresh", e.what())); CloseFlowAfterWait(); }
         }
         FreshRegister();
     }
@@ -1022,16 +1027,14 @@ private:
         if (bind(us, reinterpret_cast<sockaddr*>(&la), ll) != 0) {
             close(us); throw std::runtime_error("bind init port failed");
         }
-        timeval tv{8, 0}; setsockopt(us, SOL_SOCKET, SO_RCVTIMEO, &tv, sizeof tv);
         std::string reg1 = imsd::msg::BuildRegisterInitial(ctx_, callidReg, ftag, rng_.Token(16), spiUc, spiUs);
         sockaddr_storage pa; socklen_t pl = MakeAddr(pcscf_, pcscfPort_, pa);
         sendto(us, reg1.data(), reg1.size(), 0, reinterpret_cast<sockaddr*>(&pa), pl);
-        char buf[65535];
+        std::string resp = AwaitInitialFinal(us, callidReg);
-        ssize_t n = recv(us, buf, sizeof buf, 0);
+        if (imsd::sip::Status(resp) != 401) {
-        close(us);
+            DumpRaw("imsd-register-fail.raw", resp);
-        if (n <= 0) throw std::runtime_error("no 401 to unprotected REGISTER");
+            throw std::runtime_error(std::format("expected 401, got {}", imsd::sip::RefusalSummary(resp)));
-        std::string resp(buf, static_cast<std::size_t>(n));
+        }
-        if (imsd::sip::Status(resp) != 401) throw std::runtime_error("expected 401");
         auto nonceB64 = QuotedAfter(resp, "nonce=\"");
         if (!nonceB64) throw std::runtime_error("no nonce in 401");
         auto raw = imsd::util::FromBase64(*nonceB64);
@@ -1129,13 +1132,10 @@ private:
         std::string auth = imsd::msg::AuthAka(ctx_, *nonceB64, cnonce, response);
         std::string reg2 = imsd::msg::BuildRegisterProtected(ctx_, callidReg, ftag, rng_.Token(16), 2, spiUc, spiUs, auth);
         if (!sip_.Send(reg2)) throw std::runtime_error("send protected REGISTER failed");
-        std::string ok;
+        std::string ok = AwaitFinal(callidReg, 2, "protected REGISTER");
-        for (;;) {
+        if (auto st = imsd::sip::Status(ok); st != 200) {
-            auto m = sip_.RecvMsg(12.0);
+            DumpRaw("imsd-register-fail.raw", ok);
-            if (!m) throw std::runtime_error("no reply to protected REGISTER");
+            throw std::runtime_error(std::format("REGISTER refused: {}", imsd::sip::RefusalSummary(ok)));
-            auto st = imsd::sip::Status(*m);
-            if (st == 200) { ok = *m; break; }
-            if (st && *st >= 300) throw std::runtime_error(std::format("REGISTER failed {}", *st));
         }
         reg_.callid = callidReg; reg_.ftag = ftag; reg_.cseq = 2;
         reg_.spiUc = spiUc; reg_.spiUs = spiUs;
@@ -1149,6 +1149,85 @@ private:
         Log("REGISTERED (fresh)");
     }
 
+    // Closes the flow of a REGISTER wait that failed. A call that arrived
+    // under the wait (AwaitFinal dispatches requests) ends with it: a 486
+    // while the flow still carries one, and the bus told.
+    void CloseFlowAfterWait() {
+        if (call_) {
+            Log(std::format("call {} arrived under a registration that failed; ending it", call_->Uni()));
+            Execute(call_->OnHangup());
+            MaybeDropCall();
+            if (call_) { Execute(call_->Abandon("registration failed")); MaybeDropCall(); }
+        }
+        sip_.Close();
+    }
+
+    // The final of the REGISTER (callid, cseq) just sent, within 12 s of
+    // the send or of its last provisional. A request arriving on the client
+    // flow meanwhile (a NOTIFY, an OPTIONS) is dispatched and answered, not
+    // read as the reply; a provisional of our own transaction keeps the
+    // wait going; a response to another transaction is ignored. Throws
+    // when nothing answers or the flow dies under a dispatched request.
+    std::string AwaitFinal(const std::string& callid, long cseq, std::string_view what) {
+        std::string want = std::format("{} REGISTER", cseq);
+        double deadline = Mono() + 12.0;
+        for (;;) {
+            double left = deadline - Mono();
+            auto m = left > 0 ? sip_.RecvMsg(left) : std::nullopt;
+            if (!m) throw std::runtime_error(std::format("no reply to {}", what));
+            auto st = imsd::sip::Status(*m);
+            if (!st) {
+                reply_ = [this](const std::string& r) { sip_.Send(r); };
+                DispatchRequest(*m);
+                if (!sip_.Alive()) throw std::runtime_error(std::format("flow closed while awaiting the {} reply", what));
+                continue;
+            }
+            if (!imsd::sip::ResponseOf(*m, callid, want)) {
+                Log(std::format("ignoring a response to another transaction while awaiting the {} reply", what));
+                continue;
+            }
+            if (*st >= 200) return *m;
+            Log(std::format("{} -> {} (provisional); waiting for the final", what, *st));
+            deadline = Mono() + 12.0;
+        }
+    }
+
+    // The final of the unprotected REGISTER (callid, CSeq 1) on the init
+    // socket, within 8 s of the send or of its last provisional. The socket
+    // is bound to the init port, not connected: what else it delivers — a
+    // late final of an earlier attempt, a stray datagram — is logged with
+    // its source port and skipped, never judged as the reply. Closes the
+    // socket; throws when nothing answers.
+    std::string AwaitInitialFinal(int us, const std::string& callid) {
+        double deadline = Mono() + 8.0;
+        char buf[65535];
+        for (;;) {
+            double left = deadline - Mono();
+            if (left <= 0) break;
+            long sec = static_cast<long>(left);
+            long usec = static_cast<long>((left - static_cast<double>(sec)) * 1e6);
+            if (sec == 0 && usec == 0) usec = 1000;
+            timeval tv{sec, usec};
+            setsockopt(us, SOL_SOCKET, SO_RCVTIMEO, &tv, sizeof tv);
+            sockaddr_storage src; socklen_t sl = sizeof src;
+            ssize_t n = recvfrom(us, buf, sizeof buf, 0, reinterpret_cast<sockaddr*>(&src), &sl);
+            if (n <= 0) break;
+            std::string m(buf, static_cast<std::size_t>(n));
+            if (!imsd::sip::ResponseOf(m, callid, "1 REGISTER")) {
+                int sp = src.ss_family == AF_INET6 ? ntohs(reinterpret_cast<sockaddr_in6*>(&src)->sin6_port) : ntohs(reinterpret_cast<sockaddr_in*>(&src)->sin_port);
+                std::string_view sv = m;
+                Log(std::format("ignoring a datagram on the init port from port {} that is not the unprotected REGISTER's reply: {}", sp, sv.substr(0, sv.find("\r\n"))));
+                continue;
+            }
+            int st = *imsd::sip::Status(m);
+            if (st >= 200) { close(us); return m; }
+            Log(std::format("unprotected REGISTER -> {} (provisional); waiting for the final", st));
+            deadline = Mono() + 8.0;
+        }
+        close(us);
+        throw std::runtime_error("no 401 to unprotected REGISTER");
+    }
+
     // re-REGISTER over the (resumed or live) SA. Returns (200 msg, used cseq).
     std::pair<std::string, long> Reregister(const std::string& callid, const std::string& ftag, long startCseq, std::uint32_t spiUc, std::uint32_t spiUs) {
         std::string auth = imsd::msg::AuthEmpty(ctx_);
@@ -1157,13 +1236,12 @@ private:
         for (;;) {
             std::string reg = imsd::msg::BuildRegisterProtected(ctx_, callid, ftag, rng_.Token(16), cseq, spiUc, spiUs, auth);
             if (!sip_.Send(reg)) throw std::runtime_error("send re-REGISTER failed");
-            auto m = sip_.RecvMsg(12.0);
+            std::string m = AwaitFinal(callid, cseq, "re-REGISTER");
-            if (!m) throw std::runtime_error("no reply to re-REGISTER");
+            auto st = imsd::sip::Status(m);
-            auto st = imsd::sip::Status(*m);
+            if (st == 200) return {m, cseq};
-            if (st == 200) return {*m, cseq};
             if (st == 401 && !challenged) {
                 challenged = true;
-                auto nonce = QuotedAfter(*m, "nonce=\"");
+                auto nonce = QuotedAfter(m, "nonce=\"");
                 auto raw = nonce ? imsd::util::FromBase64(*nonce) : std::nullopt;
                 if (!raw || raw->size() < 32) throw std::runtime_error("bad 401 nonce on refresh");
                 std::vector<std::uint8_t> rnd(raw->begin(), raw->begin() + 16);
@@ -1176,7 +1254,8 @@ private:
                 cseq++;
                 continue;
             }
-            throw std::runtime_error(std::format("re-REGISTER failed {}", st.value_or(0)));
+            DumpRaw("imsd-register-fail.raw", m);
+            throw std::runtime_error(std::format("re-REGISTER refused: {}", imsd::sip::RefusalSummary(m)));
         }
     }
 
@@ -1273,7 +1352,7 @@ private:
             // recovery is the same as a daemon restart: drop the flow and
             // let MaybeReconnect re-run the connect + true-refresh sequence.
             Log(std::format("keepalive re-REGISTER failed: {}", e.what()));
-            sip_.Close();
+            CloseFlowAfterWait();
         }
         lastRefresh_ = Mono();
         lastKa_ = Mono();
@@ -1310,7 +1389,7 @@ private:
                 return;
             } catch (const std::exception& e) {
                 Log(std::format("reconnect re-REGISTER failed: {}", e.what()));
-                sip_.Close();
+                CloseFlowAfterWait();
             }
         }
         if (registered_) { registered_ = false; EmitStatus(true); }
@@ -1330,31 +1409,41 @@ private:
     }
 
     // ---- command handling -------------------------------------------------
+    // A Dial while a call exists: refused, unless it is an emergency dial,
+    // which preempts whatever exists (TS 22.101) — released, and abandoned
+    // if it lingers awaiting a CANCEL's 487 (the late final is ignored by
+    // Call-ID mismatch). False when the dial was refused.
+    bool ClearForDial(const Cmd& c, bool emergency) {
+        if (!call_) return true;
+        if (!emergency) {
+            Log(std::format("dial({}) refused: call in progress", c.number));
+            CallInfo bad{c.uni, c.number, "terminated", "error", NowEpoch(), 0};
+            PostAdded(bad);
+            PostState(c.uni, "terminated", "error");
+            PostDeleted(c.uni);
+            return false;
+        }
+        Log(std::format("emergency dial: preempting call {}", call_->Uni()));
+        Execute(call_->OnHangup());
+        MaybeDropCall();
+        if (call_) { Execute(call_->Abandon("preempted by emergency dial")); MaybeDropCall(); }
+        return true;
+    }
+
     void HandleCmd(const Cmd& c) {
         if (c.kind == Cmd::Kind::Stop) { quit_.store(true); return; }
         if (c.kind == Cmd::Kind::Dial) {
             bool emergency = imsd::msg::IsEmergency(c.number, emergencyExtra_);
-            if (call_) {
+            if (!ClearForDial(c, emergency)) return;
-                if (!emergency) {
-                    Log(std::format("dial({}) refused: call in progress", c.number));
-                    CallInfo bad{c.uni, c.number, "terminated", "error", NowEpoch(), 0};
-                    PostAdded(bad);
-                    PostState(c.uni, "terminated", "error");
-                    PostDeleted(c.uni);
-                    return;
-                }
-                // an emergency dial preempts whatever exists (TS 22.101):
-                // release it; if it lingers awaiting a CANCEL's 487, abandon
-                // it — the late final is ignored by Call-ID mismatch
-                Log(std::format("emergency dial: preempting call {}", call_->Uni()));
-                Execute(call_->OnHangup());
-                MaybeDropCall();
-                if (call_) { Execute(call_->Abandon("preempted by emergency dial")); MaybeDropCall(); }
-            }
             // a dead client flow fails the INVITE instantly — give the
             // reconnect path one immediate shot first (user action beats
-            // the backoff timer)
+            // the backoff timer). The shot's REGISTER wait dispatches
-            if (!sip_.Alive()) { nextReconnect_ = 0; MaybeReconnect(); }
+            // requests, so an incoming call may have arrived under it: the
+            // same rule again.
+            if (!sip_.Alive()) {
+                nextReconnect_ = 0; MaybeReconnect();
+                if (!ClearForDial(c, emergency)) return;
+            }
             RefreshPani();
             if (emergency)
                 Log(std::format("EMERGENCY dial ({}): urn:service:sos over the live registration, "

interfaces/Imsd-Sip.cppm

@@ -121,6 +121,39 @@ export namespace imsd::sip {
         return v;
     }
 
+    // True for a response of the transaction (callid, cseq) — the reply a
+    // wait for that request may judge. A request, another transaction's
+    // response or anything else a socket delivers is not.
+    bool ResponseOf(std::string_view msg, std::string_view callid, std::string_view cseq) {
+        return Status(msg).has_value() && Header(msg, "Call-ID") == callid && Header(msg, "CSeq") == cseq;
+    }
+
+    // Retry-After of a response (RFC 3261 20.33), in seconds; nullopt when
+    // absent or not a number.
+    std::optional<long> RetryAfter(std::string_view msg) {
+        auto v = Header(msg, "Retry-After");
+        if (!v) return std::nullopt;
+        return LeadingDigits(*v);
+    }
+
+    // A refused final for the journal: its status line, then the headers
+    // that say who refused and for how long — Retry-After (RFC 3261 20.33),
+    // Warning (20.43: the node's own words), Reason (RFC 3326), Server
+    // (20.35). "503 Service Unavailable; Retry-After: 60; Warning: 399
+    // pcscf1.example \"...\"". A bare status code says neither which node
+    // nor why: O2 UK answered a refresh 503 twenty-one times and a
+    // subscription 500 (alyx, 2026-09-24) and the journal could not tell
+    // the P-CSCF from the S-CSCF (ims ledger F17).
+    std::string RefusalSummary(std::string_view msg) {
+        std::string_view line = msg.substr(0, msg.find_first_of("\r\n"));
+        if (line.starts_with("SIP/2.0 ")) line.remove_prefix(8);
+        std::string s(Trim(line));
+        for (std::string_view name : {"Retry-After", "Warning", "Reason", "Server"})
+            for (std::string_view v : Headers(msg, name))
+                s += std::format("; {}: {}", name, v);
+        return s;
+    }
+
     // Where a UDP response to this request must go (RFC 3261 18.2.2): the
     // top Via's sent-by port — unless the Via carries rport, in which case
     // the caller should reply to the request's source port instead

tests/Sip/main.cpp

@@ -196,6 +196,51 @@ int main() {
         Check(!m4.has_value(), "absurd Content-Length: discarded, no overflow");
     }
 
+    // ---- RetryAfter / RefusalSummary (what a refused final is logged as)
+    {
+        std::string r503 =
+            "SIP/2.0 503 Service Unavailable\r\n"
+            "Via: SIP/2.0/TCP [2001:db8::db43]:45062;branch=z9hG4bKx\r\n"
+            "Retry-After: 120\r\n"
+            "Warning: 399 pcscf1.example \"S-CSCF unreachable\"\r\n"
+            "Server: Mavenir-P-CSCF/4.2\r\n"
+            "Content-Length: 0\r\n\r\n";
+        Check(RetryAfter(r503) == 120, "Retry-After parsed");
+        Check(RefusalSummary(r503) == "503 Service Unavailable; Retry-After: 120; Warning: 399 pcscf1.example \"S-CSCF unreachable\"; Server: Mavenir-P-CSCF/4.2", "summary: status line + reason headers in order");
+        std::string r500 =
+            "SIP/2.0 500 Server Internal Error\r\n"
+            "Via: SIP/2.0/TCP [2001:db8::db43]:45062;branch=z9hG4bKx\r\n"
+            "Content-Length: 0\r\n\r\n";
+        Check(!RetryAfter(r500).has_value(), "no Retry-After -> nullopt");
+        Check(RefusalSummary(r500) == "500 Server Internal Error", "summary without reason headers is the status line");
+        std::string two =
+            "SIP/2.0 403 Forbidden\r\n"
+            "Reason: Q.850;cause=21;text=\"Call rejected\"\r\n"
+            "Reason: SIP;cause=403\r\n"
+            "Retry-After: soon\r\n"
+            "Content-Length: 0\r\n\r\n";
+        Check(!RetryAfter(two).has_value(), "non-numeric Retry-After -> nullopt");
+        Check(RefusalSummary(two) == "403 Forbidden; Retry-After: soon; Reason: Q.850;cause=21;text=\"Call rejected\"; Reason: SIP;cause=403", "every instance of a reason header is kept");
+        Check(RefusalSummary("NOTIFY sip:x SIP/2.0\r\nEvent: reg\r\n\r\n") == "NOTIFY sip:x SIP/2.0", "a request summarises to its request line");
+        Check(RefusalSummary("") == "", "empty message -> empty summary");
+    }
+
+    // ---- ResponseOf (which datagram a REGISTER wait may judge)
+    {
+        Check(ResponseOf(Resp200, "12345@host", "2 REGISTER"), "the transaction's own final");
+        Check(!ResponseOf(Resp200, "12345@host", "1 REGISTER"), "another CSeq is not it");
+        std::string stale =
+            "SIP/2.0 408 Request Timeout\r\n"
+            "Via: SIP/2.0/UDP [2001:db8::db43]:5060;branch=z9hG4bKa;rport=5060\r\n"
+            "Call-ID: earlier@[2001:db8::db43]\r\n"
+            "CSeq: 1 REGISTER\r\n"
+            "Content-Length: 0\r\n\r\n";
+        Check(!ResponseOf(stale, "12345@host", "1 REGISTER"), "an earlier attempt's late final is not it");
+        Check(ResponseOf(stale, "earlier@[2001:db8::db43]", "1 REGISTER"), "matched by Call-ID and CSeq");
+        Check(!ResponseOf("NOTIFY sip:x SIP/2.0\r\nCall-ID: 12345@host\r\nCSeq: 2 REGISTER\r\n\r\n", "12345@host", "2 REGISTER"), "a request is never a response");
+        Check(!ResponseOf("", "12345@host", "2 REGISTER"), "nothing is not it");
+    }
+
     if (Failures == 0) std::println("Sip: all tests passed");
     return Failures;
 }