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