From 65cf26ac89a1dffc679c743771e5230f1c054350 Mon Sep 17 00:00:00 2001 From: PeterSthuka Date: Tue, 25 Aug 2026 09:58:48 +0300 Subject: [PATCH] Cover the decline path in the teardown drain and the log MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The 0.6.0 drain waited on pjsua_call_get_count(), whose documentation says it includes "calls that are no longer active but still in the process of hanging up". That is true of a BYE and false of a decline: PJSUA disconnects the invite session the moment a final response is sent and releases the call slot, so the count is back to zero while the 603 has not been acknowledged. logout() drained nothing and deleted the account immediately — the exact behaviour 0.6.0 claimed to fix. The doc comment asserting otherwise was extrapolated from the pjsua_call_hangup docs, which are about BYE, and never checked. Measured rather than argued this time: the new test declines a real INVITE over loopback UDP and asserts pjsua_call_get_count() == 0 while the 603 is outstanding. Final responses are now tracked by Call-ID and CSeq from the transport hand-off until the ACK, and the drain waits on that alongside PJSUA's count. Entries expire after SIP timer H so one PBX that never ACKs cannot make every later teardown wait the full timeout. The observability moves for the same reason. on_call_tsx_state never fired for a declined call — PJSUA has nothing left to report it against. on_tsx_state cannot replace it either: sip_module.h says it reaches only the module "acting as transaction user", which for an INVITE is the invite session, never an application module. What every registered module does see is the response going out and the request coming in, so the observer watches those, registered ahead of the transaction layer because that is where the ACK to a non-2xx is absorbed. The send line now carries the destination, which is the thing a host could otherwise only get from a packet capture: it separates "nothing was sent" from "it was sent to that address and lost". The end-to-end test is the point of this change. It proves, without a PBX, that the 603 reaches the wire, that it is held until acknowledged, and that the ACK releases it. --- CHANGELOG.md | 33 ++ CallWaveKit/CallWaveClient.m | 333 +++++++++++++----- .../CallWaveTeardownObserverInternal.h | 20 ++ CallWaveKit/README.md | 48 ++- FIELD-TESTING.md | 26 +- .../CallWaveDeclineTeardownTests.m | 244 +++++++++++++ 6 files changed, 596 insertions(+), 108 deletions(-) create mode 100644 CallWaveKit/CallWaveTeardownObserverInternal.h create mode 100644 Tests/CallWaveKitRegistryTests/CallWaveDeclineTeardownTests.m diff --git a/CHANGELOG.md b/CHANGELOG.md index 7e92e45..1e3bf6c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,39 @@ All notable changes to CallWaveKit are recorded here. The project follows [Semantic Versioning](https://semver.org/spec/v2.0.0.html); until 1.0 a minor bump may contain breaking changes, and each one is listed below. +## [Unreleased] + +### Fixed + +- The 0.6.0 teardown drain did not cover a declined call — the case it was + written for. It waited on `pjsua_call_get_count()`, whose documentation says + it includes "calls that are no longer active but still in the process of + hanging up". That holds for a call ended with BYE, where the slot survives + until the transaction finishes, and not for one declined with a final + response: PJSUA disconnects the invite session as soon as the `603` is sent + and releases the slot, so the count is already zero while the response is + unacknowledged. `logout()` therefore drained nothing and deleted the account + immediately, exactly as before 0.6.0. A regression test now declines a real + INVITE over loopback UDP and asserts both that the `603` reaches the wire and + that `pjsua_call_get_count()` is zero while it is outstanding. +- Final responses are now tracked by Call-ID and CSeq, from the transport + hand-off until the peer's ACK, and the drain waits on that as well as on + PJSUA's own count. An entry is reclaimed after 32 seconds — SIP timer H — so a + PBX that never acknowledges cannot make every later teardown wait. + +### Changed + +- The decline path is observed by a `pjsip_module` registered on the endpoint + ahead of the transaction layer, rather than by PJSUA's per-call + `on_call_tsx_state`. That callback never fired for a declined call: PJSUA + stops reporting a call once its invite session is gone, and + `pjsua_call_hangup` is documented not to deliver it at all. `on_tsx_state` + could not replace it either — the header is explicit that it reaches only the + module "acting as transaction user", which for an INVITE is the invite + session. Watching the outgoing response and the incoming ACK does work, and + the new `603 sent to : for Call-ID …` line carries the destination, + which is what separates "nothing was sent" from "it was sent and lost". + ## [0.6.0] - 2026-08-24 > **Not field-tested.** This release ships on its automated suite alone — diff --git a/CallWaveKit/CallWaveClient.m b/CallWaveKit/CallWaveClient.m index abf18a0..f8eacab 100644 --- a/CallWaveKit/CallWaveClient.m +++ b/CallWaveKit/CallWaveClient.m @@ -12,6 +12,7 @@ #import "CallWaveDiagnosticsSnapshotInternal.h" #import "CallWaveTURNConfiguration.h" #import "CallWavePushCompletionGate.h" +#import "CallWaveTeardownObserverInternal.h" #import #import @@ -57,17 +58,36 @@ static NSUInteger gCreatedTransports = 0; static __weak CallWaveClient *gActiveClient = nil; -/// Whether the peer has ACKed the non-2xx final response of the call in that -/// slot. Written from PJSIP's worker thread and from `sipQueue`, which is why -/// it is atomic; read only to tell "the peer confirmed the teardown" apart from -/// "the transaction gave up without ever hearing back". -static _Atomic(bool) gFinalResponseAcked[PJSUA_MAX_CALLS]; +/// One outgoing non-2xx final response to an INVITE, from the moment it is +/// handed to the transport until the peer ACKs it. Keyed by Call-ID and CSeq +/// because by then the pjsua call is already gone: PJSUA disconnects the invite +/// session as soon as a final response is sent, drops the call slot, and stops +/// reporting anything for it — which is why `pjsua_call_get_count()` cannot see +/// a declined call waiting for its ACK, and why the per-call +/// `on_call_tsx_state` never fires for one either. +typedef struct { + pj_bool_t inUse; + char callId[PJSIP_MAX_URL_SIZE]; + int cseq; + int statusCode; + NSTimeInterval sentAt; +} CallWaveFinalResponse; + +/// Small and fixed: an intercom client is configured for one call, a handful at +/// the very most, and an entry lives for at most one transaction. +#define CallWaveMaxTrackedFinalResponses 8 + +/// SIP timer H — how long a UAS INVITE transaction retransmits a final response +/// before giving up. An entry older than this is dead weight and is reclaimed, +/// so one PBX that never ACKs cannot make every later teardown wait. +static const NSTimeInterval CallWaveFinalResponseLifetime = 32.0; + +static CallWaveFinalResponse gFinalResponses[CallWaveMaxTrackedFinalResponses]; +static os_unfair_lock gFinalResponseLock = OS_UNFAIR_LOCK_INIT; static void onIncomingCall(pjsua_acc_id accId, pjsua_call_id callId, pjsip_rx_data *rdata); static void onCallState(pjsua_call_id callId, pjsip_event *event); static void onCallMediaState(pjsua_call_id callId); -static void onCallTsxState(pjsua_call_id callId, pjsip_transaction *tsx, - pjsip_event *event); static void onRegistrationState(pjsua_acc_id accId); static void onPJLog(int level, const char *data, int length); @@ -109,20 +129,213 @@ static BOOL ensurePJThreadRegistered(const char *name) { return YES; } -/// Waits for PJSUA to finish tearing down every call it still holds. +/// Tracks outgoing non-2xx final responses to an INVITE until the peer ACKs +/// them, and logs both ends of that exchange. /// -/// `pjsua_call_hangup` and `pjsua_call_answer` return as soon as the message is -/// with the transaction layer: PJSUA's own header says the hangup process -/// "will continue in the background", and `pjsua_call_get_count()` is -/// documented to include "calls that are no longer active but still in the -/// process of hanging up". A declined call sits in exactly that state while its -/// `603` waits for an ACK. +/// This is a `pjsip_module` rather than PJSUA's `on_call_tsx_state` because the +/// per-call callback is useless here twice over: `pjsua_call_hangup` is +/// documented not to deliver it at all, and for a declined call PJSUA has +/// already disconnected the invite session and released the call slot by the +/// time the response is on the wire, so there is no call left to report against. +/// +/// It is not `on_tsx_state` either — that one only reaches the module acting as +/// the transaction's *user*, which for an INVITE is the invite session, never an +/// application module. What does reach every registered module is the response +/// going out and the request coming in, so those are what this watches: the +/// final response leaving, and the ACK arriving. +/// +/// The priority puts it ahead of the transaction layer, because the ACK to a +/// non-2xx final response is absorbed there and never reaches a module behind +/// it. + +static void forgetFinalResponseLocked(CallWaveFinalResponse *entry) { + entry->inUse = PJ_FALSE; + entry->callId[0] = '\0'; +} + +/// Number of final responses still waiting for an ACK, reclaiming any that have +/// outlived the transaction that would have retransmitted them. +static unsigned pendingFinalResponseCount(void) { + NSTimeInterval now = NSDate.timeIntervalSinceReferenceDate; + unsigned pending = 0; + os_unfair_lock_lock(&gFinalResponseLock); + for (int i = 0; i < CallWaveMaxTrackedFinalResponses; i++) { + CallWaveFinalResponse *entry = &gFinalResponses[i]; + if (!entry->inUse) { + continue; + } + if (now - entry->sentAt > CallWaveFinalResponseLifetime) { + CWLogError(CallWaveLogCategoryCall, + @"%d for Call-ID %s was never ACKed within %.0fs. The peer never " + @"confirmed the teardown and may still have the call up.", + entry->statusCode, entry->callId, CallWaveFinalResponseLifetime); + forgetFinalResponseLocked(entry); + continue; + } + pending++; + } + os_unfair_lock_unlock(&gFinalResponseLock); + return pending; +} + +static void forgetAllFinalResponses(void) { + os_unfair_lock_lock(&gFinalResponseLock); + for (int i = 0; i < CallWaveMaxTrackedFinalResponses; i++) { + forgetFinalResponseLocked(&gFinalResponses[i]); + } + os_unfair_lock_unlock(&gFinalResponseLock); +} + +/// Every response CallWaveKit sends passes through here on its way out. +static pj_status_t onFinalResponseSent(pjsip_tx_data *tdata) { + pjsip_msg *msg = tdata != NULL ? tdata->msg : NULL; + if (msg == NULL || msg->type != PJSIP_RESPONSE_MSG) { + return PJ_SUCCESS; + } + int code = msg->line.status.code; + pjsip_cseq_hdr *cseq = PJSIP_MSG_CSEQ_HDR(msg); + pjsip_cid_hdr *cid = PJSIP_MSG_CID_HDR(msg); + if (code < 300 || cseq == NULL || cid == NULL || + pjsip_method_cmp(&cseq->method, pjsip_get_invite_method()) != 0) { + return PJ_SUCCESS; + } + + NSTimeInterval now = NSDate.timeIntervalSinceReferenceDate; + os_unfair_lock_lock(&gFinalResponseLock); + CallWaveFinalResponse *slot = NULL; + for (int i = 0; i < CallWaveMaxTrackedFinalResponses; i++) { + if (!gFinalResponses[i].inUse) { + slot = &gFinalResponses[i]; + break; + } + } + if (slot != NULL) { + slot->inUse = PJ_TRUE; + slot->cseq = cseq->cseq; + slot->statusCode = code; + slot->sentAt = now; + pj_ansi_snprintf(slot->callId, sizeof(slot->callId), "%.*s", + (int)cid->id.slen, cid->id.ptr); + } + os_unfair_lock_unlock(&gFinalResponseLock); + + // The destination is the part a host cannot get anywhere else without a + // packet capture: it says the response reached the transport and where it + // was addressed. + CWLogInfo(CallWaveLogCategoryCall, + @"%d sent to %s:%d for Call-ID %.*s, waiting for the ACK", + code, tdata->tp_info.dst_name, tdata->tp_info.dst_port, + (int)cid->id.slen, cid->id.ptr); + if (slot == NULL) { + CWLogWarning(CallWaveLogCategoryCall, + @"no free slot to track %d; its ACK will not be reported", code); + } + return PJ_SUCCESS; +} + +/// The ACK to a non-2xx final response is absorbed by the transaction layer, so +/// this has to run before it. Returns PJ_FALSE so it still gets there. +static pj_bool_t onRequestReceived(pjsip_rx_data *rdata) { + pjsip_msg *msg = rdata != NULL ? rdata->msg_info.msg : NULL; + if (msg == NULL || msg->type != PJSIP_REQUEST_MSG || + pjsip_method_cmp(&msg->line.req.method, pjsip_get_ack_method()) != 0) { + return PJ_FALSE; + } + pjsip_cid_hdr *cid = rdata->msg_info.cid; + pjsip_cseq_hdr *cseq = rdata->msg_info.cseq; + if (cid == NULL || cseq == NULL) { + return PJ_FALSE; + } + + int acked = 0; + os_unfair_lock_lock(&gFinalResponseLock); + for (int i = 0; i < CallWaveMaxTrackedFinalResponses; i++) { + CallWaveFinalResponse *entry = &gFinalResponses[i]; + if (!entry->inUse || entry->cseq != cseq->cseq) { + continue; + } + if (pj_strcmp2(&cid->id, entry->callId) != 0) { + continue; + } + acked = entry->statusCode; + forgetFinalResponseLocked(entry); + break; + } + os_unfair_lock_unlock(&gFinalResponseLock); + + if (acked != 0) { + CWLogInfo(CallWaveLogCategoryCall, + @"the peer ACKed %d, the teardown reached it", acked); + } + return PJ_FALSE; +} + +static pjsip_module gTeardownObserver = { + NULL, NULL, + { "callwave-teardown", 17 }, + -1, + PJSIP_MOD_PRIORITY_TSX_LAYER - 1, + NULL, /* load */ + NULL, /* start */ + NULL, /* stop */ + NULL, /* unload */ + &onRequestReceived, /* on_rx_request */ + NULL, /* on_rx_response*/ + NULL, /* on_tx_request */ + &onFinalResponseSent, /* on_tx_response*/ + NULL /* on_tsx_state */ +}; + +BOOL CallWaveTeardownObserverIsRegistered(void) { + return gTeardownObserver.id != -1; +} + +unsigned CallWaveTeardownPendingFinalResponses(void) { + return pendingFinalResponseCount(); +} + +/// Must run on `sipQueue`, after `pjsua_init`. +static void registerTeardownObserver(void) { + if (gTeardownObserver.id != -1) { + return; + } + forgetAllFinalResponses(); + pj_status_t status = + pjsip_endpt_register_module(pjsua_get_pjsip_endpt(), &gTeardownObserver); + if (status != PJ_SUCCESS) { + CWLogError(CallWaveLogCategoryCall, + @"teardown observer not registered (%d); a declined call's ACK " + @"will not be reported and cannot be waited for", status); + } +} + +/// Must run on `sipQueue`, before `pjsua_destroy`. +static void unregisterTeardownObserver(void) { + if (gTeardownObserver.id == -1) { + return; + } + pjsip_endpt_unregister_module(pjsua_get_pjsip_endpt(), &gTeardownObserver); + gTeardownObserver.id = -1; + forgetAllFinalResponses(); +} + +/// Waits for both halves of a teardown to finish: PJSUA's own hangup process, +/// and any final response of ours still waiting for its ACK. +/// +/// The two need separate tracking because PJSUA only covers one of them. +/// `pjsua_call_get_count()` is documented to include "calls that are no longer +/// active but still in the process of hanging up", and for a BYE that is true — +/// the slot stays until the transaction completes. For a call declined with a +/// final response it is not: PJSUA disconnects the invite session the moment +/// the response is sent and releases the slot, so the count is back to zero +/// while the `603` has not even been ACKed yet. Draining on the count alone +/// therefore protected the BYE path and left the decline path exactly as +/// unprotected as it was before — which is what `gFinalResponses` and the +/// teardown observer above exist to fix. /// /// This matters because `pjsua_acc_del` "always deletes the account regardless /// of active calls" — PJSUA's wording — and its own documentation says to hang -/// up first and wait "until the calls are fully disconnected". Deleting the -/// account inside that window is how a decline the phone showed as clean leaves -/// the PBX still ringing. +/// up first and wait "until the calls are fully disconnected". /// /// Must run on `sipQueue`. PJSIP polls its ioqueue on its own worker thread, so /// parking this one does not stall the ACK being waited for. @@ -130,21 +343,24 @@ static BOOL drainCallTeardown(NSTimeInterval timeout) { if (!gPJSUAStarted) { return YES; } - unsigned remaining = pjsua_call_get_count(); - if (remaining == 0) { + unsigned calls = pjsua_call_get_count(); + unsigned responses = pendingFinalResponseCount(); + if (calls == 0 && responses == 0) { return YES; } CWLogInfo(CallWaveLogCategoryCall, - @"waiting for %u call(s) to finish tearing down", remaining); + @"waiting for teardown: %u call(s) hanging up, %u final response(s) " + @"awaiting an ACK", calls, responses); NSDate *deadline = [NSDate dateWithTimeIntervalSinceNow:MAX(timeout, 0)]; - while ((remaining = pjsua_call_get_count()) > 0) { + while ((calls = pjsua_call_get_count()) > 0 || + (responses = pendingFinalResponseCount()) > 0) { if (deadline.timeIntervalSinceNow <= 0) { CWLogWarning(CallWaveLogCategoryCall, - @"%u call(s) still tearing down after %.0f ms; going ahead anyway. " - @"The peer may never receive the final response, and a PBX that " - @"missed it keeps the call up.", - remaining, timeout * 1000.0); + @"still tearing down after %.0f ms (%u call(s), %u response(s) " + @"unACKed); going ahead anyway. A peer that missed the final " + @"response keeps the call up.", + timeout * 1000.0, calls, responses); return NO; } usleep((useconds_t)(CallWaveTeardownPollInterval * USEC_PER_SEC)); @@ -750,7 +966,6 @@ - (pj_status_t)startEngineLocked { config.cb.on_incoming_call = &onIncomingCall; config.cb.on_call_state = &onCallState; config.cb.on_call_media_state = &onCallMediaState; - config.cb.on_call_tsx_state = &onCallTsxState; config.cb.on_reg_state = &onRegistrationState; NSString *userAgent = engine.userAgent; @@ -800,6 +1015,9 @@ - (pj_status_t)startEngineLocked { return status; } + // The endpoint exists from here on, which is what the observer attaches to. + registerTeardownObserver(); + // UDP is created eagerly because it is the default for intercoms; TCP is // best effort. Anything else is created on demand by the account. status = [self ensureTransportLocked:CallWaveTransportUDP]; @@ -1159,6 +1377,7 @@ + (void)destroyRuntimeOnQueue:(dispatch_queue_t)queue { pj_pool_release(gAccountHeaderPool); gAccountHeaderPool = NULL; } + unregisterTeardownObserver(); if (gPJSUACreated) { pjsua_destroy(); } @@ -1602,8 +1821,9 @@ - (BOOL)answerSIPCall:(pjsua_call_id)callId { /// not to deliver `on_call_tsx_state`, so the peer's ACK is unobservable and a /// final response that was lost looks exactly like one that was never /// generated. Choosing here, and answering through `pjsua_call_answer` when the -/// call is still ringing, is what makes `onCallTsxState` below able to report -/// the rest of the exchange. +/// call is still ringing, is what keeps the exchange on a path the teardown +/// observer can report — PJSUA stops speaking about the call entirely once its +/// invite session is gone, which for a final response is immediately. /// /// Must run on `sipQueue`. - (BOOL)endSIPCall:(pjsua_call_id)callId @@ -1627,9 +1847,6 @@ - (BOOL)endSIPCall:(pjsua_call_id)callId BOOL neverAnswered = info.state == PJSIP_INV_STATE_INCOMING || info.state == PJSIP_INV_STATE_EARLY; - if (callId >= 0 && callId < (pjsua_call_id)PJSUA_MAX_CALLS) { - atomic_store(&gFinalResponseAcked[callId], false); - } pj_status_t status; if (neverAnswered) { @@ -3182,60 +3399,6 @@ static void onCallMediaState(pjsua_call_id callId) { [gActiveClient handleMediaStateForCall:callId]; } -/// Reports what happened to a teardown after CallWaveKit handed it over. -/// -/// The INVITE server transaction is the only one that says anything useful -/// here: after a non-2xx final response it sits in COMPLETED, retransmitting on -/// a timer until the peer ACKs, and only then moves to CONFIRMED. Without these -/// lines a host cannot tell a `603` that was lost on the way to the PBX from a -/// `603` that was never generated — and on UDP, with the PBX still ringing and -/// the phone showing a clean decline, that is the whole question. -static void onCallTsxState(pjsua_call_id callId, pjsip_transaction *tsx, - pjsip_event *event) { - if (tsx == NULL || tsx->role != PJSIP_ROLE_UAS || - tsx->method.id != PJSIP_INVITE_METHOD) { - return; - } - // 1xx belongs to the ringing path and 2xx to the answer path; both are - // logged where they are sent. - int code = tsx->status_code; - if (code < 300) { - return; - } - BOOL tracked = callId >= 0 && callId < (pjsua_call_id)PJSUA_MAX_CALLS; - - switch (tsx->state) { - case PJSIP_TSX_STATE_COMPLETED: - if (event != NULL && event->type == PJSIP_EVENT_TIMER) { - CWLogWarning(CallWaveLogCategoryCall, - @"call %d: retransmitting %d, the peer has not ACKed it", - callId, code); - } else { - CWLogInfo(CallWaveLogCategoryCall, - @"call %d: %d is on the wire, waiting for the ACK", callId, code); - } - break; - case PJSIP_TSX_STATE_CONFIRMED: - if (tracked) { - atomic_store(&gFinalResponseAcked[callId], true); - } - CWLogInfo(CallWaveLogCategoryCall, - @"call %d: the peer ACKed %d, the teardown reached it", callId, code); - break; - case PJSIP_TSX_STATE_TERMINATED: - if (tracked && atomic_load(&gFinalResponseAcked[callId])) { - break; - } - CWLogError(CallWaveLogCategoryCall, - @"call %d: the INVITE transaction ended on %d without an ACK. " - @"The peer never confirmed the teardown and may still have the " - @"call up.", callId, code); - break; - default: - break; - } -} - static void onRegistrationState(pjsua_acc_id accId) { pjsua_acc_info info; if (pjsua_acc_get_info(accId, &info) != PJ_SUCCESS) { diff --git a/CallWaveKit/CallWaveTeardownObserverInternal.h b/CallWaveKit/CallWaveTeardownObserverInternal.h new file mode 100644 index 0000000..af6f315 --- /dev/null +++ b/CallWaveKit/CallWaveTeardownObserverInternal.h @@ -0,0 +1,20 @@ +#import + +NS_ASSUME_NONNULL_BEGIN + +/// Test-facing view of the teardown observer. The observer itself is private to +/// `CallWaveClient.m`; these two answer the questions a test has to ask, and a +/// declined call cannot be verified any other way — PJSUA reports nothing about +/// it once the invite session is gone. + +/// Whether the observer is attached to the PJSIP endpoint. `NO` after the +/// engine is stopped, and `NO` if registration failed, in which case a declined +/// call's ACK is neither reported nor waited for. +BOOL CallWaveTeardownObserverIsRegistered(void); + +/// Non-2xx final responses to an INVITE that have gone out and not yet been +/// ACKed. This is the drain condition for the decline path; +/// `pjsua_call_get_count()` is blind to it. +unsigned CallWaveTeardownPendingFinalResponses(void); + +NS_ASSUME_NONNULL_END diff --git a/CallWaveKit/README.md b/CallWaveKit/README.md index 4225444..51523d8 100644 --- a/CallWaveKit/README.md +++ b/CallWaveKit/README.md @@ -106,30 +106,37 @@ completion handler runs — see [Releasing the account while a call is still ending](#releasing-the-account-while-a-call-is-still-ending) before calling `logout()` or `stop()` next to it. -Both paths are logged, in the `call` category: +Both paths are logged, in the `call` category. A decline that worked: ``` [call] declining call 3 with 603: ended by the host (never answered, INVITE state EARLY) [call] 603 handed to the transport for call 3 -[call] call 3: 603 is on the wire, waiting for the ACK -[call] call 3: the peer ACKed 603, the teardown reached it +[call] 603 sent to 10.0.0.9:5060 for Call-ID 4f2c…, waiting for the ACK +[call] the peer ACKed 603, the teardown reached it ``` -A `603` that never reaches the PBX looks like this instead — the phone shows the -same clean decline either way, so this is the only place the difference shows: +The third line is worth more than it looks: it is emitted from the transport +hand-off itself and carries the destination, so it separates "the response left +the device, addressed there" from "PJSUA accepted our call and nothing went out". +The fourth is the one that proves the PBX has it. + +A `603` that reaches the wire but never gets acknowledged shows the first three +and then, once the transaction has given up: ``` -[call] call 3: retransmitting 603, the peer has not ACKed it -[call] call 3: the INVITE transaction ended on 603 without an ACK. The peer - never confirmed the teardown and may still have the call up. +[call] 603 for Call-ID 4f2c… was never ACKed within 32s. The peer never + confirmed the teardown and may still have the call up. ``` -And a teardown that was never generated at all has neither, only: +And a teardown that was never generated at all has none of them, only: ``` [call] no SIP teardown for call 3 (ended by the host): PJSUA no longer knows this call ``` +The phone shows the same clean decline in all three cases, so the log is the +only place they differ. + ## Engine settings Everything that belongs to the PJSUA runtime rather than to an account lives on @@ -213,11 +220,24 @@ retransmissions and the peer's acknowledgement happen afterwards, and PJSUA's own header says the hangup "will continue in the background". `pjsua_acc_del`, meanwhile, "always deletes the account regardless of active calls". -So `logout()` and `stop()` wait for it. Both drain PJSUA's call teardown before -deleting the account or destroying the runtime — up to one second, which covers -a final response whose first packet was lost and had to be retransmitted — and -log `call teardown finished`, or a warning naming how many calls were still -going, if the wait expires. `login(configuration:)` drains the same way when +So `logout()` and `stop()` wait for it, and the wait covers **both** kinds of +teardown, which need tracking separately: + +- **An established call ended with BYE** is tracked by PJSUA itself. + `pjsua_call_get_count()` is documented to include "calls that are no longer + active but still in the process of hanging up", and the call slot survives + until the BYE transaction finishes. +- **A call declined with a final response** is not. PJSUA disconnects the invite + session the moment a `603` is sent and releases the call slot, so its count is + already back to zero while the response has not been acknowledged. CallWaveKit + tracks these itself, by Call-ID and CSeq, from the transport hand-off until the + ACK arrives. + +Both are drained for up to one second — enough for a response whose first packet +was lost and had to be retransmitted — and the wait logs +`waiting for teardown: N call(s) hanging up, M final response(s) awaiting an ACK` +followed by `call teardown finished`, or a warning naming what was still +outstanding if it expires. `login(configuration:)` drains the same way when replacing an account, because per-push credentials mean a new push can arrive while the previous call is still ending. diff --git a/FIELD-TESTING.md b/FIELD-TESTING.md index fedb9ef..bd14027 100644 --- a/FIELD-TESTING.md +++ b/FIELD-TESTING.md @@ -180,17 +180,25 @@ and confirm it against the log. ``` [call] declining call N with 603: … (never answered, INVITE state EARLY) [call] 603 handed to the transport for call N -[call] call N: 603 is on the wire, waiting for the ACK -[call] call N: the peer ACKed 603, the teardown reached it +[call] 603 sent to : for Call-ID …, waiting for the ACK +[call] the peer ACKed 603, the teardown reached it ``` -The last line is the one that proves it. Its absence is the failure, and there -are two shapes of it: - -- `[call] call N: retransmitting 603, the peer has not ACKed it`, then - `[call] call N: the INVITE transaction ended on 603 without an ACK` — the - response was generated and lost. Suspect the network, or something that tore - the account down underneath it. +The last line is the one that proves it. The third narrows down the failure when +it is missing, because it comes from the transport hand-off and names where the +response went. Three shapes of failure: + +- All four lines but the PBX still rings — the response arrived and was + acknowledged, and the PBX is ignoring `603`. Try scenario 3, which ends on + `480` instead: if that one stops the intercom, the PBX wants a different code + and this is a compatibility finding, not a bug. +- First three lines, then + `[call] 603 for Call-ID … was never ACKed within 32s` — the response left the + device and the PBX never confirmed it. Suspect the network path, and capture + it: `rvictl -s ` on a tethered Mac gives a real interface to run + `tcpdump` against, with no build change. +- Two lines and no third — PJSUA accepted the decline but nothing reached the + transport. That is a library bug; attach the log. - No `declining call N` line at all — the response was never generated. Suspect the call binding: check for `[call] no SIP teardown for call N`. diff --git a/Tests/CallWaveKitRegistryTests/CallWaveDeclineTeardownTests.m b/Tests/CallWaveKitRegistryTests/CallWaveDeclineTeardownTests.m new file mode 100644 index 0000000..2119e4a --- /dev/null +++ b/Tests/CallWaveKitRegistryTests/CallWaveDeclineTeardownTests.m @@ -0,0 +1,244 @@ +#import + +#import +#import +#import +#import + +#import "CallWaveClient.h" +#import "CallWaveTeardownObserverInternal.h" + +#if __has_include() +#import +#else +#import +#endif + +// A declined call is the one teardown PJSUA stops speaking about: it disconnects +// the invite session on the final response, releases the call slot, and reports +// nothing further. The 0.6.0 drain keyed on `pjsua_call_get_count()` and so +// covered the BYE path only, while its documentation claimed otherwise — the +// failure reached the field before anything caught it. +// +// Nothing short of a real INVITE proves this path, so that is what these tests +// do: a UDP socket plays the intercom against the engine's own transport on +// loopback, and the assertions are made on the bytes that come back. + +@interface CallWaveDeclineDelegate : NSObject +@property (nonatomic, strong) XCTestExpectation *ringing; +@property (nonatomic, strong, nullable) NSUUID *uuid; +@end + +@implementation CallWaveDeclineDelegate +- (void)callWaveClient:(CallWaveClient *)client + didReceiveCallFrom:(NSString *)caller + uuid:(NSUUID *)uuid { + if (self.uuid == nil) { + self.uuid = uuid; + [self.ringing fulfill]; + } +} +@end + +@interface CallWaveDeclineTeardownTests : XCTestCase +@property (nonatomic, assign) int sock; +@property (nonatomic, strong, nullable) CallWaveClient *client; +@end + +@implementation CallWaveDeclineTeardownTests + +- (void)setUp { + [super setUp]; + _sock = -1; +} + +- (void)tearDown { + if (_sock >= 0) { close(_sock); _sock = -1; } + [_client stop]; + _client = nil; + [super tearDown]; +} + +/// The UDP/IPv4 port PJSUA bound, which is where the intercom would send. +- (int)enginePort { + pjsua_transport_id ids[8]; + unsigned count = (unsigned)(sizeof(ids) / sizeof(ids[0])); + if (pjsua_enum_transports(ids, &count) != PJ_SUCCESS) { + return 0; + } + for (unsigned i = 0; i < count; i++) { + pjsua_transport_info info; + if (pjsua_transport_get_info(ids[i], &info) != PJ_SUCCESS) { + continue; + } + if (info.type == PJSIP_TRANSPORT_UDP && info.local_name.port != 0) { + return info.local_name.port; + } + } + return 0; +} + +- (int)openSocketWithPort:(int *)boundPort { + int s = socket(AF_INET, SOCK_DGRAM, 0); + if (s < 0) { return -1; } + struct sockaddr_in addr = {0}; + addr.sin_family = AF_INET; + addr.sin_addr.s_addr = htonl(INADDR_LOOPBACK); + addr.sin_port = 0; + if (bind(s, (struct sockaddr *)&addr, sizeof(addr)) != 0) { close(s); return -1; } + socklen_t len = sizeof(addr); + if (getsockname(s, (struct sockaddr *)&addr, &len) != 0) { close(s); return -1; } + *boundPort = ntohs(addr.sin_port); + struct timeval timeout = { .tv_sec = 3, .tv_usec = 0 }; + setsockopt(s, SOL_SOCKET, SO_RCVTIMEO, &timeout, sizeof(timeout)); + return s; +} + +- (void)send:(NSString *)message to:(int)port { + struct sockaddr_in addr = {0}; + addr.sin_family = AF_INET; + addr.sin_addr.s_addr = htonl(INADDR_LOOPBACK); + addr.sin_port = htons((uint16_t)port); + NSData *data = [message dataUsingEncoding:NSUTF8StringEncoding]; + sendto(self.sock, data.bytes, data.length, 0, + (struct sockaddr *)&addr, sizeof(addr)); +} + +/// Reads datagrams until one has `needle` on its status line, or time runs out. +- (nullable NSString *)waitForResponseContaining:(NSString *)needle + within:(NSTimeInterval)seconds { + NSDate *deadline = [NSDate dateWithTimeIntervalSinceNow:seconds]; + char buffer[4096]; + while (deadline.timeIntervalSinceNow > 0) { + ssize_t n = recv(self.sock, buffer, sizeof(buffer) - 1, 0); + if (n <= 0) { continue; } + buffer[n] = '\0'; + NSString *message = [NSString stringWithUTF8String:buffer] ?: @""; + if ([message containsString:needle]) { return message; } + } + return nil; +} + +- (NSString *)inviteFromPort:(int)from toPort:(int)to callId:(NSString *)callId { + NSString *body = + @"v=0\r\no=door 1 1 IN IP4 127.0.0.1\r\ns=-\r\nc=IN IP4 127.0.0.1\r\n" + @"t=0 0\r\nm=audio 40002 RTP/AVP 0\r\na=rtpmap:0 PCMU/8000\r\n"; + return [NSString stringWithFormat: + @"INVITE sip:1001@127.0.0.1 SIP/2.0\r\n" + @"Via: SIP/2.0/UDP 127.0.0.1:%d;branch=z9hG4bK-callwave-%@;rport\r\n" + @"Max-Forwards: 70\r\n" + @"From: \"Front door\" ;tag=doortag\r\n" + @"To: \r\n" + @"Call-ID: %@\r\n" + @"CSeq: 1 INVITE\r\n" + @"Contact: \r\n" + @"Content-Type: application/sdp\r\n" + @"Content-Length: %lu\r\n\r\n%@", + from, callId, callId, from, (unsigned long)body.length, body]; +} + +- (CallWaveClient *)startedClient { + CallWaveConfiguration *configuration = + [[CallWaveConfiguration alloc] initWithHost:@"127.0.0.1" + port:65530 + transport:CallWaveTransportUDP + username:@"1001" + password:@"not-a-real-credential" + includesCallsInRecents:NO]; + CallWaveClient *client = + [[CallWaveClient alloc] initWithConfiguration:configuration + options:CallWaveIntegrationOptionNone + provider:nil + engineConfiguration:nil]; + NSError *error = nil; + if (![client startWithError:&error]) { + XCTFail(@"engine did not start: %@", error); + return nil; + } + return client; +} + +- (void)testObserverIsAttachedWhileTheEngineRuns { + self.client = [self startedClient]; + XCTAssertTrue(CallWaveTeardownObserverIsRegistered(), + @"without the observer a declined call's ACK is neither reported " + @"nor waited for"); +} + +/// The whole reported failure in one test: decline a ringing call and prove the +/// final response reaches the wire, that it is tracked until acknowledged, and +/// that the ACK clears it. +- (void)testDecliningARingingCallPutsTheFinalResponseOnTheWireAndWaitsForItsACK { + self.client = [self startedClient]; + int enginePort = [self enginePort]; + if (enginePort == 0) { + XCTSkip(@"no UDP transport to talk to"); + } + int localPort = 0; + self.sock = [self openSocketWithPort:&localPort]; + if (self.sock < 0) { + XCTSkip(@"loopback UDP unavailable in this environment"); + } + + CallWaveDeclineDelegate *delegate = [[CallWaveDeclineDelegate alloc] init]; + delegate.ringing = [self expectationWithDescription:@"ringing"]; + self.client.delegate = delegate; + + NSString *callId = @"callwave-decline-1"; + [self send:[self inviteFromPort:localPort toPort:enginePort callId:callId] + to:enginePort]; + + // 180 proves the INVITE was accepted and the call is ringing. + XCTAssertNotNil([self waitForResponseContaining:@"SIP/2.0 180" within:5], + @"the engine never rang the call"); + [self waitForExpectations:@[delegate.ringing] timeout:5]; + XCTAssertNotNil(delegate.uuid); + + XCTestExpectation *declined = [self expectationWithDescription:@"declined"]; + [self.client endCallWithUUID:delegate.uuid completion:^(NSError *error) { + XCTAssertNil(error); + [declined fulfill]; + }]; + [self waitForExpectations:@[declined] timeout:5]; + + // This is the assertion the field report needed: the 603 leaves the stack. + NSString *decline = [self waitForResponseContaining:@"SIP/2.0 603" within:5]; + XCTAssertNotNil(decline, @"the 603 never reached the wire"); + XCTAssertTrue([decline containsString:callId]); + + // And it is tracked until the peer acknowledges it — the drain condition + // that pjsua_call_get_count() cannot express. + XCTAssertEqual(CallWaveTeardownPendingFinalResponses(), 1u, + @"an unACKed final response has to hold the drain open"); + + // The reason the 0.6.0 drain missed this path, pinned as an assertion: + // PJSUA has already forgotten the call while its final response is still + // unacknowledged, so a drain keyed on this number returns immediately and + // the account is deleted with the 603 in flight. If this ever stops being + // zero, the extra tracking above can go. + XCTAssertEqual(pjsua_call_get_count(), 0u, + @"pjsua_call_get_count() is expected to be blind to a declined " + @"call awaiting its ACK"); + + [self send:[NSString stringWithFormat: + @"ACK sip:1001@127.0.0.1 SIP/2.0\r\n" + @"Via: SIP/2.0/UDP 127.0.0.1:%d;branch=z9hG4bK-callwave-%@;rport\r\n" + @"Max-Forwards: 70\r\n" + @"From: \"Front door\" ;tag=doortag\r\n" + @"To: \r\n" + @"Call-ID: %@\r\n" + @"CSeq: 1 ACK\r\n" + @"Content-Length: 0\r\n\r\n", localPort, callId, callId] + to:enginePort]; + + NSDate *deadline = [NSDate dateWithTimeIntervalSinceNow:5]; + while (CallWaveTeardownPendingFinalResponses() > 0 && + deadline.timeIntervalSinceNow > 0) { + [NSRunLoop.currentRunLoop runUntilDate: + [NSDate dateWithTimeIntervalSinceNow:0.05]]; + } + XCTAssertEqual(CallWaveTeardownPendingFinalResponses(), 0u, + @"the ACK has to release the drain"); +} + +@end