From ba0d8d7c900f0d78646a921131b7feba967a0591 Mon Sep 17 00:00:00 2001 From: calebtt Date: Fri, 25 Sep 2026 19:58:59 -0500 Subject: [PATCH 1/3] Recover registration after outages and stop on hard failures A failed registration refresh scheduled a reconnect that called SIPRegistrationUserAgent.Start() on an agent that was still running, which threw "already running" and ended the client's retry chain after one attempt. OnRegistrationTemporaryFailure also never cleared IsRegistered, so the client reported registered for the whole outage. Recovery came only from SIPSorcery's own retry, 300 s after the failure. SipClient now: - clears IsRegistered and raises RegistrationStatusChanged on any failure, with or without auto-reconnect; - stops the current registration agent (no unregister) and starts a fresh one on every start, so "already running" cannot happen and late events from an old agent are ignored; StartRegistration() is safe to call again; - keeps the default retry schedule (5 attempts at 2 s x n, then the agent's own retry stays armed), and adds optional extended retry (RegistrationRetryOptions.Extended: 30 s doubling to 5 min, never stops); - classifies hard failures by SIP status (401/407 after authentication, 402, 403, 404) and stops the agent, so rejected credentials are not sent again by SIPSorcery's repeating timer; the health check does not restart registration after a hard failure or while an attempt is in flight; - exposes RegistrationState and LastRegistrationError; - treats a loopback registrar given as host:port as loopback (no STUN). sipbot serve gains --extended-retry / SIP_EXTENDED_RETRY and --sip-trace / SIP_TRACE (both off, read by sipbot only) and reports both on its startup line. JSONL event and field names are unchanged; status.registered is now false while registration is failing. Tests: a scripted loopback registrar covers hard failures (first and authenticated REGISTER, both retry modes), re-registering after a hard failure, SIPSorcery's repeating-timer case, the default schedule, extended backoff and its reset, recovery with and without auto-reconnect, the health check, and Dispose with a reconnect pending. Closes #13 Co-Authored-By: Claude Opus 5.5 --- AGENTS.md | 6 +- Config/SipBotSettings.cs | 61 ++++ Network/SipClient.cs | 263 ++++++++++++++---- tests/SipBotLib.Tests/FakeRegistrar.cs | 115 ++++++++ .../RegistrationHardFailureTests.cs | 110 ++++++++ .../RegistrationTemporaryFailureTests.cs | 171 ++++++++++++ .../RegistrationTestHarness.cs | 79 ++++++ tools/sipbot/Program.cs | 21 +- tools/sipbot/ServeHost.cs | 27 +- 9 files changed, 796 insertions(+), 57 deletions(-) create mode 100644 tests/SipBotLib.Tests/FakeRegistrar.cs create mode 100644 tests/SipBotLib.Tests/RegistrationHardFailureTests.cs create mode 100644 tests/SipBotLib.Tests/RegistrationTemporaryFailureTests.cs create mode 100644 tests/SipBotLib.Tests/RegistrationTestHarness.cs diff --git a/AGENTS.md b/AGENTS.md index e814b25..23588e9 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -99,7 +99,11 @@ Env-only is enough if `SIP_SERVER` and `SIP_USERNAME` are set. Never commit real Transfer / dial targets: bare extension (`102`), `user@host`, full `sip:` URI, `tel:` URI, or a PSTN number (`+1…`, punctuation OK). Bare extensions become `sip:{ext}@{SIP_SERVER}`. Phone numbers are reduced to digits (leading `+` stripped) so typical PBX outbound routes match. A `tel:` URI is always that number on `SIP_SERVER`: `;phone-context`, `;ext`, and a trailing `@host` are not a SIP target. Dial failure JSONL is `dial failed: ()` when the far end sent one (e.g. `603 Decline`). -Flags: `--auto-answer`, `--play FILE` (with auto-answer), `--settings PATH`, `--config N`, `--pcmu-only`, `--no-keepalive`. `sipbot serve --help` states the play/resample rule. +Flags: `--auto-answer`, `--play FILE` (with auto-answer), `--settings PATH`, `--config N`, `--pcmu-only`, `--no-keepalive`, `--extended-retry`, `--sip-trace`. `sipbot serve --help` states the play/resample rule. + +**Registration:** `status.registered` is `false` while registration is failing (it used to stay `true` through an outage). After a temporary failure (timeout, 5xx) sipbot retries: by default up to 5 attempts at 2 s × n, then SIPSorcery's own retry every 300 s. `--extended-retry` (or `SIP_EXTENDED_RETRY=1`) retries forever instead, 30 s doubling to at most 5 min; use it for always-on hosts. A hard failure (wrong password, 402, 403, 404) is never retried: restart sipbot after fixing the account. The first stderr line reports `extendedRetry=` and `sipTrace=`. + +**SIP trace:** `--sip-trace` (or `SIP_TRACE=1`) logs every SIP message sent and received to stderr. Lab use only: the messages include headers such as digest `Authorization` responses. Off by default. Both switches are read by sipbot only, not by the library's settings loader. ## Minimal inbound flow diff --git a/Config/SipBotSettings.cs b/Config/SipBotSettings.cs index 75c8638..70fa630 100644 --- a/Config/SipBotSettings.cs +++ b/Config/SipBotSettings.cs @@ -161,4 +161,65 @@ public class SipConfig [JsonPropertyName("fromname")] public string FromName { get; set; } = string.Empty; + + /// + /// How retries registration after a failure. The defaults keep the + /// library's original schedule. + /// + [JsonPropertyName("registrationRetry")] + public RegistrationRetryOptions RegistrationRetry { get; set; } = new(); +} + +/// +/// Registration retry settings for . +/// +/// +/// A temporary failure (timeout, 5xx, and any status that is not a hard failure) is retried. +/// A hard failure (401/407 after authentication, 402, 403, 404) is never retried automatically: +/// the client stops registering until is called again. +/// +public class RegistrationRetryOptions +{ + /// + /// Extended retry, for always-on hosts: after a temporary failure the client retries forever, + /// the delay doubling from up to + /// . Off by default. + /// + [JsonPropertyName("extended")] + public bool Extended { get; set; } + + [JsonPropertyName("extendedInitialDelayMs")] + public int ExtendedInitialDelayMs { get; set; } = 30_000; + + [JsonPropertyName("extendedMaxDelayMs")] + public int ExtendedMaxDelayMs { get; set; } = 300_000; + + /// + /// Default retry: after a temporary failure the client makes up to this many attempts, + /// attempt n after × n. After the last one the registration + /// agent's own retry stays armed, so the process still recovers without a restart. + /// + [JsonPropertyName("defaultMaxAttempts")] + public int DefaultMaxAttempts { get; set; } = 5; + + [JsonPropertyName("defaultBaseDelayMs")] + public int DefaultBaseDelayMs { get; set; } = 2_000; + + // Timings below are passed through to SIPSorcery or drive the health check. They are not + // part of the settings file; tests shorten them. + + /// Seconds between the registration agent's own retries after a failure (SIPSorcery default 300). + [JsonIgnore] + internal int AgentFailureRetrySeconds { get; set; } = 300; + + /// Seconds the registration agent waits for a REGISTER response (SIPSorcery default 60). + [JsonIgnore] + internal int AgentAttemptTimeoutSeconds { get; set; } = 60; + + [JsonIgnore] + internal int HealthCheckIntervalMs { get; set; } = 30_000; + + /// How long registration must be missing before the health check acts. + [JsonIgnore] + internal int HealthCheckStaleMs { get; set; } = 120_000; } \ No newline at end of file diff --git a/Network/SipClient.cs b/Network/SipClient.cs index 66a6125..4941487 100644 --- a/Network/SipClient.cs +++ b/Network/SipClient.cs @@ -10,15 +10,29 @@ namespace SipBot; +/// Where 's registration stands. +public enum RegistrationState +{ + /// has not been called. + NotStarted, + /// A REGISTER is in progress and no result has arrived yet. + Registering, + Registered, + /// The last attempt failed temporarily; a retry is scheduled or the agent's own retry is armed. + TemporaryFailure, + /// + /// The registrar rejected the account (401/407 after authentication, 402, 403, 404). Nothing is + /// retried until is called again. + /// + HardFailure +} + /// /// Enhanced SIP client with improved error handling, monitoring, and resource management. /// public class SipClient : IDisposable { private const int DefaultRegistrationExpirySeconds = 60; - private const int MaxReconnectionAttempts = 5; - private const int ReconnectionDelayMs = 2000; - private const int HealthCheckIntervalMs = 30000; // 30 seconds private const int BlindTransferTimeoutSeconds = 10; private readonly string _sipUsername; @@ -28,6 +42,7 @@ public class SipClient : IDisposable private readonly int _registrationExpirySeconds; private readonly bool _enableAutoReconnection; private readonly bool _enableHealthMonitoring; + private readonly RegistrationRetryOptions _retry; private SIPTransport _sipTransport; private SIPUserAgent _userAgent; @@ -41,6 +56,10 @@ public class SipClient : IDisposable private volatile bool _isShutdown = false; private volatile bool _isRegistered = false; private int _reconnectionAttempts = 0; + private bool _reconnectPending; + private bool _registrationStarted; + private RegistrationState _registrationState = RegistrationState.NotStarted; + private string? _lastRegistrationError; private Timer? _healthCheckTimer; private Timer? _reconnectionTimer; @@ -77,7 +96,19 @@ public class SipClient : IDisposable public event Action? DtmfDigitReceived; // Properties + /// + /// True after a successful REGISTER. Cleared by any registration failure, temporary or hard, + /// so it is false while registration is failing. + /// public bool IsRegistered => _isRegistered; + + public RegistrationState RegistrationState => _registrationState; + + /// + /// SIP status (e.g. 403 Forbidden) or error text from the most recent registration + /// failure. Kept after a later success so the last problem stays visible. + /// + public string? LastRegistrationError => _lastRegistrationError; public bool IsCallActive => _userAgent?.IsCallActive ?? false; /// @@ -90,6 +121,11 @@ private static bool IsLoopbackHost(string host) { if (string.IsNullOrWhiteSpace(host)) return false; var h = host.Trim(); + // Strip a port: "127.0.0.1:5070", "localhost:5070", "[::1]:5070". + if (h.StartsWith('[') && h.Contains(']')) + h = h[1..h.IndexOf(']')]; + else if (h.Count(c => c == ':') == 1) + h = h[..h.IndexOf(':')]; if (h.Equals("localhost", StringComparison.OrdinalIgnoreCase)) return true; if (h is "127.0.0.1" or "::1") return true; return IPAddress.TryParse(h, out var ip) && IPAddress.IsLoopback(ip); @@ -115,6 +151,7 @@ public SipClient( _registrationExpirySeconds = Math.Max(30, registrationExpirySeconds); // Minimum 30 seconds _enableAutoReconnection = enableAutoReconnection; _enableHealthMonitoring = enableHealthMonitoring; + _retry = sipSettings.RegistrationRetry ?? new RegistrationRetryOptions(); InitializeTransport(); InitializeRegistrationAgent(); @@ -242,19 +279,7 @@ private void InitializeRegistrationAgent() { try { - _registrationAgent = new SIPRegistrationUserAgent( - _sipTransport, - _sipUsername, - _sipPassword, - _sipServer, - _registrationExpirySeconds - ); - - _registrationAgent.RegistrationSuccessful += OnRegistrationSuccessful; - _registrationAgent.RegistrationFailed += OnRegistrationFailed; - _registrationAgent.RegistrationTemporaryFailure += OnRegistrationTemporaryFailure; - _registrationAgent.RegistrationRemoved += OnRegistrationRemoved; - + _registrationAgent = CreateRegistrationAgent(); IncrementMetric("registration_agent_initialized"); } catch (Exception ex) @@ -294,6 +319,62 @@ private SIPUserAgent CreateNewUserAgent(SIPTransport sipTransport) return userAgent; } + private SIPRegistrationUserAgent CreateRegistrationAgent() + { + var agent = new SIPRegistrationUserAgent( + _sipTransport, + _sipUsername, + _sipPassword, + _sipServer, + _registrationExpirySeconds, + maxRegistrationAttemptTimeout: _retry.AgentAttemptTimeoutSeconds, + registerFailureRetryInterval: _retry.AgentFailureRetrySeconds); + + agent.RegistrationSuccessful += OnRegistrationSuccessful; + agent.RegistrationFailed += OnRegistrationFailed; + agent.RegistrationTemporaryFailure += OnRegistrationTemporaryFailure; + agent.RegistrationRemoved += OnRegistrationRemoved; + return agent; + } + + private void DetachRegistrationAgent(SIPRegistrationUserAgent agent) + { + agent.RegistrationSuccessful -= OnRegistrationSuccessful; + agent.RegistrationFailed -= OnRegistrationFailed; + agent.RegistrationTemporaryFailure -= OnRegistrationTemporaryFailure; + agent.RegistrationRemoved -= OnRegistrationRemoved; + } + + /// + /// Stops the current registration agent without an unregister and detaches it, so it can + /// neither send another REGISTER (including SIPSorcery's repeating timer after a hard failure) + /// nor report late results. Caller holds . + /// + private void StopRegistrationAgentLocked() + { + DetachRegistrationAgent(_registrationAgent); + _registrationAgent.Stop(sendZeroExpiryRegister: false); + } + + /// + /// Stops the current agent (no unregister) and starts a fresh one. A fresh agent never throws + /// "already running", and its results cannot be confused with a late event from the old one. + /// Caller holds . + /// + private void RestartRegistrationAgentLocked() + { + StopRegistrationAgentLocked(); + _registrationAgent = CreateRegistrationAgent(); + _lastRegistrationAttempt = DateTime.UtcNow; + _registrationState = RegistrationState.Registering; + _registrationAgent.Start(); + } + + /// + /// Starts registration, or restarts it if it is already running. Safe to call again at any + /// time, including after a hard failure (see ): the + /// current agent is stopped without an unregister, then a new one starts. + /// public void StartRegistration() { if (_isDisposed) @@ -305,8 +386,10 @@ public void StartRegistration() { try { - _lastRegistrationAttempt = DateTime.UtcNow; - _registrationAgent.Start(); + StopReconnectionTimer(); + _registrationStarted = true; + _reconnectionAttempts = 0; + RestartRegistrationAgentLocked(); StatusMessage?.Invoke(this, $"Registration attempt for {_sipUsername}@{_sipServer} started."); IncrementMetric("registration_attempts"); Log.Information($"Starting SIP registration for {_sipUsername}@{_sipServer}"); @@ -727,6 +810,7 @@ private void OnRegistrationSuccessful(SIPURI uri, SIPResponse resp) _isRegistered = true; _reconnectionAttempts = 0; _lastSuccessfulRegistration = DateTime.UtcNow; + _registrationState = RegistrationState.Registered; } StatusMessage?.Invoke(this, $"Registration successful for {uri}. Expires: {resp.Header.Expires}"); @@ -735,31 +819,57 @@ private void OnRegistrationSuccessful(SIPURI uri, SIPResponse resp) Log.Debug($"SIP registration successful for {uri}"); } - private void OnRegistrationFailed(SIPURI uri, SIPResponse resp, string error) + // SIPSorcery reports some of these as RegistrationFailed and others (e.g. a 402 on the + // first REGISTER) as RegistrationTemporaryFailure, so classify by status, not by event. + // A 401/407 only surfaces after SIPSorcery has already answered the challenge, i.e. the + // credentials were rejected. + private static bool IsHardRegistrationFailure(SIPResponse? resp) => resp?.Status is + SIPResponseStatusCodesEnum.Unauthorised or + SIPResponseStatusCodesEnum.ProxyAuthenticationRequired or + SIPResponseStatusCodesEnum.PaymentRequired or + SIPResponseStatusCodesEnum.Forbidden or + SIPResponseStatusCodesEnum.NotFound; + + private void OnRegistrationFailed(SIPURI uri, SIPResponse resp, string error) => + HandleRegistrationFailure(uri, resp, error); + + private void OnRegistrationTemporaryFailure(SIPURI uri, SIPResponse resp, string error) => + HandleRegistrationFailure(uri, resp, error); + + private void HandleRegistrationFailure(SIPURI uri, SIPResponse? resp, string error) { + bool hard = IsHardRegistrationFailure(resp); lock (_lockObject) { _isRegistered = false; + _lastRegistrationError = resp != null ? $"{(int)resp.Status} {resp.ReasonPhrase}".Trim() : error; + if (hard) + { + // SIPSorcery stops re-arming after a hard failure, but a failure on the first + // REGISTER after Start() leaves Start()'s repeating timer running, which would + // send the rejected credentials again every (Expires - 5) s. Stop the agent so no + // further REGISTER goes out until StartRegistration() is called. + _registrationState = RegistrationState.HardFailure; + StopReconnectionTimer(); + StopRegistrationAgentLocked(); + } + else + { + _registrationState = RegistrationState.TemporaryFailure; + } } - StatusMessage?.Invoke(this, $"Registration failed for {uri}: {error}"); + StatusMessage?.Invoke(this, hard + ? $"Registration rejected for {uri}: {error}. Not retrying until StartRegistration() is called." + : $"Registration temporary failure for {uri}: {error}"); RegistrationStatusChanged?.Invoke(this); - IncrementMetric("failed_registrations"); - Log.Warning($"SIP registration failed for {uri}: {error}"); + IncrementMetric(hard ? "failed_registrations" : "temporary_registration_failures"); + if (hard) + Log.Error("SIP registration rejected for {Uri}: {Error}. Not retrying until StartRegistration() is called", uri, error); + else + Log.Warning("SIP registration temporary failure for {Uri}: {Error}", uri, error); - if (_enableAutoReconnection) - { - ScheduleReconnection(); - } - } - - private void OnRegistrationTemporaryFailure(SIPURI uri, SIPResponse resp, string error) - { - StatusMessage?.Invoke(this, $"Registration temporary failure for {uri}: {error}"); - IncrementMetric("temporary_registration_failures"); - Log.Warning($"SIP registration temporary failure for {uri}: {error}"); - - if (_enableAutoReconnection) + if (!hard && _enableAutoReconnection) { ScheduleReconnection(); } @@ -770,6 +880,7 @@ private void OnRegistrationRemoved(SIPURI uri, SIPResponse resp) lock (_lockObject) { _isRegistered = false; + _registrationState = RegistrationState.TemporaryFailure; } StatusMessage?.Invoke(this, $"Registration removed for {uri}"); @@ -861,7 +972,7 @@ private void IncomingCallCancelled(ISIPServerUserAgent uas, SIPRequest cancelReq // Health monitoring and reconnection private void StartHealthMonitoring() { - _healthCheckTimer = new Timer(PerformHealthCheck, null, HealthCheckIntervalMs, HealthCheckIntervalMs); + _healthCheckTimer = new Timer(PerformHealthCheck, null, _retry.HealthCheckIntervalMs, _retry.HealthCheckIntervalMs); Log.Debug("Health monitoring started"); } @@ -876,20 +987,28 @@ private void PerformHealthCheck(object? state) try { var timeSinceLastRegistration = DateTime.UtcNow - _lastSuccessfulRegistration; - - // If we haven't registered successfully in the last 2 minutes, try to re-register. - // Route through ScheduleReconnection() so this respects the same MaxReconnectionAttempts/ - // backoff as registration-failure driven reconnects, instead of hammering the server with - // an uncapped StartRegistration() call every HealthCheckIntervalMs. - if (timeSinceLastRegistration.TotalMinutes > 2 && !_isRegistered) + + // Only after the host has started registration, never after a hard failure (the + // registrar rejected the account; retrying would just repeat the rejection), and + // never during shutdown. + if (!_registrationStarted || _isShutdown || _registrationState == RegistrationState.HardFailure) + return; + + // If we haven't registered successfully recently, try to re-register. Route through + // ScheduleReconnection() so this respects the same attempt cap and backoff as + // failure-driven reconnects, instead of hammering the server every check. + if (timeSinceLastRegistration.TotalMilliseconds > _retry.HealthCheckStaleMs && !_isRegistered) { - Log.Warning("Health check: No successful registration in 2+ minutes, scheduling re-registration"); if (_enableAutoReconnection) { + Log.Warning("Health check: no successful registration recently, scheduling re-registration"); ScheduleReconnection(); } - else + else if (_registrationState != RegistrationState.Registering) { + // Restart only after the current attempt has failed, so the health check never + // cuts an in-flight REGISTER short. + Log.Warning("Health check: no successful registration recently, restarting registration"); StartRegistration(); } } @@ -903,22 +1022,54 @@ private void PerformHealthCheck(object? state) } } + /// + /// Schedules one reconnect attempt after a temporary failure. At most one attempt is pending + /// at a time, so the health check and failure events cannot stack REGISTERs. + /// + /// + /// Default retry: attempt n after × n, + /// up to . After the last, the + /// registration agent is left running, so its own retry still recovers the process. + /// Extended retry: the agent is stopped (the client owns the retries) and attempts continue + /// forever, the delay doubling from the initial delay up to the cap. + /// private void ScheduleReconnection() { lock (_lockObject) { - if (_reconnectionAttempts >= MaxReconnectionAttempts) - { - Log.Error($"Maximum reconnection attempts ({MaxReconnectionAttempts}) reached"); + if (_isShutdown || _reconnectPending || _registrationState == RegistrationState.HardFailure) return; + + long delay; + if (_retry.Extended) + { + _reconnectionAttempts++; + double backoff = _retry.ExtendedInitialDelayMs * Math.Pow(2, Math.Min(_reconnectionAttempts - 1, 30)); + delay = (long)Math.Min(backoff, _retry.ExtendedMaxDelayMs); + StopRegistrationAgentLocked(); } + else + { + if (_reconnectionAttempts >= _retry.DefaultMaxAttempts) + { + if (_reconnectionAttempts == _retry.DefaultMaxAttempts) + { + _reconnectionAttempts++; + Log.Warning( + "Reconnection attempts ({Max}) used; the registration agent's own retry is still armed", + _retry.DefaultMaxAttempts); + } + return; + } - _reconnectionAttempts++; - var delay = ReconnectionDelayMs * _reconnectionAttempts; // Exponential backoff + _reconnectionAttempts++; + delay = (long)_retry.DefaultBaseDelayMs * _reconnectionAttempts; + } _reconnectionTimer?.Dispose(); _reconnectionTimer = new Timer(AttemptReconnection, null, delay, Timeout.Infinite); - + _reconnectPending = true; + Log.Information($"Scheduling reconnection attempt {_reconnectionAttempts} in {delay}ms"); } } @@ -927,14 +1078,22 @@ private void StopReconnectionTimer() { _reconnectionTimer?.Dispose(); _reconnectionTimer = null; + _reconnectPending = false; } private void AttemptReconnection(object? state) { try { - Log.Information($"Attempting reconnection (attempt {_reconnectionAttempts})"); - StartRegistration(); + lock (_lockObject) + { + _reconnectPending = false; + if (_isShutdown || _isDisposed || _registrationState == RegistrationState.HardFailure) + return; + + Log.Information($"Attempting reconnection (attempt {_reconnectionAttempts})"); + RestartRegistrationAgentLocked(); + } IncrementMetric("reconnection_attempts"); } catch (Exception ex) diff --git a/tests/SipBotLib.Tests/FakeRegistrar.cs b/tests/SipBotLib.Tests/FakeRegistrar.cs new file mode 100644 index 0000000..f4eaee3 --- /dev/null +++ b/tests/SipBotLib.Tests/FakeRegistrar.cs @@ -0,0 +1,115 @@ +using System.Diagnostics; +using System.Net; +using SIPSorcery.SIP; + +namespace SipBotLib.Tests; + +/// +/// A scripted SIP registrar on loopback UDP. Every REGISTER is recorded with a timestamp and +/// answered as says. With , an unauthenticated +/// REGISTER first gets a 401 digest challenge, so the script's answer lands on the +/// authenticated REGISTER. +/// +public sealed class FakeRegistrar : IDisposable +{ + public enum Reply { Ok, Drop, ServiceUnavailable, Forbidden, NotFound, PaymentRequired, Unauthorized } + + public sealed record Register(TimeSpan At, bool Authenticated, long Expires); + + private readonly SIPTransport _transport = new(); + private readonly object _lock = new(); + private readonly List _registers = new(); + private readonly HashSet _branches = new(); + private readonly Stopwatch _clock = Stopwatch.StartNew(); + + public int Port { get; } + public string Server => $"127.0.0.1:{Port}"; + public volatile bool ChallengeFirst; + private Reply _script = Reply.Ok; + + public Reply Script + { + get { lock (_lock) return _script; } + set { lock (_lock) _script = value; } + } + + public FakeRegistrar() + { + var channel = new SIPUDPChannel(IPAddress.Loopback, 0); + _transport.AddSIPChannel(channel); + Port = channel.Port; + _transport.SIPTransportRequestReceived += OnRequest; + } + + public TimeSpan Now => _clock.Elapsed; + + public IReadOnlyList Registers + { + get { lock (_lock) return _registers.ToList(); } + } + + public int Count + { + get { lock (_lock) return _registers.Count; } + } + + /// Waits until at least REGISTERs have arrived. + public async Task WaitForCountAsync(int count, TimeSpan timeout) + { + var deadline = _clock.Elapsed + timeout; + while (_clock.Elapsed < deadline) + { + if (Count >= count) + return true; + await Task.Delay(20); + } + return Count >= count; + } + + private Task OnRequest(SIPEndPoint localEP, SIPEndPoint remoteEP, SIPRequest req) + { + if (req.Method != SIPMethodsEnum.REGISTER) + return Task.CompletedTask; + + bool authenticated = req.Header.AuthenticationHeaders.Count > 0; + Reply reply; + lock (_lock) + { + // Count transactions, not packets: a dropped REGISTER is retransmitted by the + // client's transaction layer for ~32 s, even after the agent has been stopped. + if (_branches.Add(req.Header.Vias.TopViaHeader?.Branch ?? Guid.NewGuid().ToString())) + _registers.Add(new Register(_clock.Elapsed, authenticated, req.Header.Expires)); + reply = ChallengeFirst && !authenticated ? Reply.Unauthorized : _script; + } + + SIPResponse response; + switch (reply) + { + case Reply.Drop: + return Task.CompletedTask; + case Reply.Ok: + response = SIPResponse.GetResponse(req, SIPResponseStatusCodesEnum.Ok, null); + response.Header.Contact = req.Header.Contact; + response.Header.Expires = req.Header.Expires >= 0 ? req.Header.Expires : 60; + break; + case Reply.Unauthorized: + response = SIPResponse.GetResponse(req, SIPResponseStatusCodesEnum.Unauthorised, null); + response.Header.AuthenticationHeaders.Add(new SIPAuthenticationHeader( + SIPAuthorisationHeadersEnum.WWWAuthenticate, "lab", Guid.NewGuid().ToString("N"))); + break; + default: + response = SIPResponse.GetResponse(req, reply switch + { + Reply.ServiceUnavailable => SIPResponseStatusCodesEnum.ServiceUnavailable, + Reply.Forbidden => SIPResponseStatusCodesEnum.Forbidden, + Reply.NotFound => SIPResponseStatusCodesEnum.NotFound, + Reply.PaymentRequired => SIPResponseStatusCodesEnum.PaymentRequired, + _ => throw new InvalidOperationException(reply.ToString()) + }, null); + break; + } + return _transport.SendResponseAsync(response); + } + + public void Dispose() => _transport.Shutdown(); +} diff --git a/tests/SipBotLib.Tests/RegistrationHardFailureTests.cs b/tests/SipBotLib.Tests/RegistrationHardFailureTests.cs new file mode 100644 index 0000000..4e7d28c --- /dev/null +++ b/tests/SipBotLib.Tests/RegistrationHardFailureTests.cs @@ -0,0 +1,110 @@ +using SipBot; +using Xunit; +using static SipBotLib.Tests.FakeRegistrar; + +namespace SipBotLib.Tests; + +/// +/// A hard failure (402/403/404, or 401 after authentication) stops the registration agent: no +/// further REGISTER until StartRegistration() is called, whatever the retry mode. +/// +public class RegistrationHardFailureTests +{ + public static TheoryData HardFailures() + { + var data = new TheoryData(); + foreach (bool extended in new[] { false, true }) + { + // On the first REGISTER. SIPSorcery reports the 402 as a temporary failure. + data.Add(Reply.Forbidden, false, "403", extended); + data.Add(Reply.NotFound, false, "404", extended); + data.Add(Reply.PaymentRequired, false, "402", extended); + // On the authenticated REGISTER, after a 401 challenge. + data.Add(Reply.Forbidden, true, "403", extended); + data.Add(Reply.NotFound, true, "404", extended); + data.Add(Reply.PaymentRequired, true, "402", extended); + data.Add(Reply.Unauthorized, true, "401", extended); + } + return data; + } + + [Theory] + [MemberData(nameof(HardFailures))] + public async Task Hard_failure_stops_registration(Reply reply, bool challengeFirst, string status, bool extended) + { + using var h = new RegistrationTestHarness(extended: extended, healthMonitoring: true); + h.Registrar.ChallengeFirst = challengeFirst; + h.Registrar.Script = reply; + + h.Client.StartRegistration(); + + Assert.True(await h.WaitForState(RegistrationState.HardFailure, TimeSpan.FromSeconds(5)), + $"state is {h.Client.RegistrationState}"); + int count = h.Registrar.Count; + await Task.Delay(1500); + + Assert.Equal(count, h.Registrar.Count); + Assert.False(h.Client.IsRegistered); + Assert.StartsWith(status, h.Client.LastRegistrationError); + Assert.True(h.StatusChanges > 0); + Assert.False(h.SawAlreadyRunning); + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task StartRegistration_re_registers_after_a_hard_failure(bool extended) + { + using var h = new RegistrationTestHarness(extended: extended); + h.Registrar.Script = Reply.Ok; + h.Client.StartRegistration(); + Assert.True(await h.WaitForState(RegistrationState.Registered, TimeSpan.FromSeconds(5))); + var lastSuccess = h.Client.LastSuccessfulRegistration; + + // 200, then the registrar starts refusing the account. + h.Registrar.Script = Reply.Forbidden; + h.Client.StartRegistration(); + Assert.True(await h.WaitForState(RegistrationState.HardFailure, TimeSpan.FromSeconds(5))); + Assert.Equal(lastSuccess, h.Client.LastSuccessfulRegistration); + Assert.StartsWith("403", h.Client.LastRegistrationError); + + // Re-registering while the 403 persists: one REGISTER, then silence again. Each Start() + // arms a fresh repeating timer, so the client has to stop the agent again. + int before = h.Registrar.Count; + h.Client.StartRegistration(); + Assert.True(await h.Registrar.WaitForCountAsync(before + 1, TimeSpan.FromSeconds(5))); + Assert.True(await h.WaitForState(RegistrationState.HardFailure, TimeSpan.FromSeconds(5))); + await Task.Delay(1500); + Assert.Equal(before + 1, h.Registrar.Count); + + // Once the account is accepted again, StartRegistration() recovers. + h.Registrar.Script = Reply.Ok; + h.Client.StartRegistration(); + Assert.True(await h.WaitForState(RegistrationState.Registered, TimeSpan.FromSeconds(5))); + Assert.True(h.Client.IsRegistered); + Assert.False(h.SawAlreadyRunning); + } +} + +/// +/// The case that makes stopping the agent necessary: a hard failure on the first REGISTER after +/// Start() leaves SIPSorcery's repeating timer (period Expires - 5 s = 25 s here) running, which +/// would send the rejected credentials again. Separate class so xUnit runs it in parallel. +/// +public class RegistrationHardFailureRepeatingTimerTests +{ + [Fact] + public async Task No_REGISTER_for_a_full_refresh_period_after_a_hard_failure_on_the_first_REGISTER() + { + using var h = new RegistrationTestHarness(); + h.Registrar.Script = Reply.Forbidden; + + h.Client.StartRegistration(); + Assert.True(await h.WaitForState(RegistrationState.HardFailure, TimeSpan.FromSeconds(5))); + Assert.Equal(1, h.Registrar.Count); + + await Task.Delay(TimeSpan.FromSeconds(28)); + + Assert.Equal(1, h.Registrar.Count); + } +} diff --git a/tests/SipBotLib.Tests/RegistrationTemporaryFailureTests.cs b/tests/SipBotLib.Tests/RegistrationTemporaryFailureTests.cs new file mode 100644 index 0000000..07e1fa9 --- /dev/null +++ b/tests/SipBotLib.Tests/RegistrationTemporaryFailureTests.cs @@ -0,0 +1,171 @@ +using SipBot; +using Xunit; +using static SipBotLib.Tests.FakeRegistrar; + +namespace SipBotLib.Tests; + +/// +/// Default retry after a temporary failure: at most five attempts at base × n, no "already +/// running", then the registration agent's own retry is still armed. +/// +public class RegistrationDefaultRetryTests +{ + [Fact] + public async Task Five_attempts_at_base_times_n_then_the_agent_retry_remains() + { + using var h = new RegistrationTestHarness(); + h.Registrar.Script = Reply.ServiceUnavailable; + + h.Client.StartRegistration(); + + // Initial REGISTER + 5 client attempts + 1 from the agent's own 2 s retry. + Assert.True(await h.Registrar.WaitForCountAsync(7, TimeSpan.FromSeconds(15)), $"got {h.Registrar.Count}"); + double[] gaps = h.GapsMs(); + for (int n = 1; n <= 5; n++) + { + double expected = 100 * n; + Assert.InRange(gaps[n - 1], expected * 0.8, expected + 400); + } + Assert.InRange(gaps[5], 1600, 3500); + Assert.False(h.Client.IsRegistered); + Assert.Equal(RegistrationState.TemporaryFailure, h.Client.RegistrationState); + Assert.StartsWith("503", h.Client.LastRegistrationError); + Assert.False(h.SawAlreadyRunning); + } + + [Fact] + public async Task Dispose_while_a_reconnect_is_pending_sends_nothing_more() + { + using var h = new RegistrationTestHarness(tune: r => r.DefaultBaseDelayMs = 1000); + h.Registrar.Script = Reply.ServiceUnavailable; + h.Client.StartRegistration(); + Assert.True(await h.WaitForState(RegistrationState.TemporaryFailure, TimeSpan.FromSeconds(5))); + + h.Client.Dispose(); + int count = h.Registrar.Count; + await Task.Delay(2500); + + Assert.Equal(count, h.Registrar.Count); + Assert.Empty(h.Errors); + } +} + +/// +/// A temporary failure after a successful registration clears the registered flag and reports +/// the change, with or without auto-reconnect, and registration comes back without "already +/// running". Waits for a real refresh (25 s), so it is its own class. +/// +public class RegistrationTemporaryFailureTests +{ + [Theory] + [InlineData(true)] + [InlineData(false)] + public async Task Timeout_after_success_clears_the_flag_and_recovers(bool autoReconnect) + { + using var h = new RegistrationTestHarness(autoReconnect: autoReconnect, healthMonitoring: !autoReconnect); + h.Registrar.Script = Reply.Ok; + h.Client.StartRegistration(); + Assert.True(await h.WaitForState(RegistrationState.Registered, TimeSpan.FromSeconds(5))); + var lastSuccess = h.Client.LastSuccessfulRegistration; + int changes = h.StatusChanges; + + // Drop the refresh REGISTER (25 s after registering). The agent gives up after 2 s. + h.Registrar.Script = Reply.Drop; + Assert.True(await h.WaitForState(RegistrationState.TemporaryFailure, TimeSpan.FromSeconds(35)), + $"state is {h.Client.RegistrationState}"); + Assert.False(h.Client.IsRegistered); + Assert.True(h.StatusChanges > changes); + Assert.NotNull(h.Client.LastRegistrationError); + Assert.Equal(lastSuccess, h.Client.LastSuccessfulRegistration); + + // Recovery: a client attempt (auto-reconnect on) or the health check (off). + h.Registrar.Script = Reply.Ok; + Assert.True(await h.WaitForState(RegistrationState.Registered, TimeSpan.FromSeconds(10))); + Assert.True(h.Client.IsRegistered); + Assert.False(h.SawAlreadyRunning); + Assert.Empty(h.Errors); + + // After a hard failure the health check must not start registration again. + h.Registrar.Script = Reply.Forbidden; + h.Client.StartRegistration(); + Assert.True(await h.WaitForState(RegistrationState.HardFailure, TimeSpan.FromSeconds(5))); + int count = h.Registrar.Count; + await Task.Delay(1500); + Assert.Equal(count, h.Registrar.Count); + } +} + +/// +/// Extended retry: the delay doubles to the cap and retries never stop; the health check cannot +/// add REGISTERs on top; a hard failure still stops everything. +/// +public class RegistrationExtendedRetryTests +{ + [Fact] + public async Task Delay_doubles_to_the_cap_and_retries_do_not_stop() + { + using var h = new RegistrationTestHarness(extended: true); + h.Registrar.Script = Reply.ServiceUnavailable; + + h.Client.StartRegistration(); + await Task.Delay(TimeSpan.FromSeconds(8)); // 20 × the 400 ms cap + + double[] gaps = h.GapsMs(); + Assert.True(gaps.Length >= 12, $"only {gaps.Length + 1} REGISTERs in 8 s"); + Assert.InRange(gaps[0], 80, 500); + Assert.InRange(gaps[1], 160, 600); + foreach (double gap in gaps.Skip(2)) + Assert.InRange(gap, 320, 800); + Assert.False(h.SawAlreadyRunning); + + h.Registrar.Script = Reply.Ok; + Assert.True(await h.WaitForState(RegistrationState.Registered, TimeSpan.FromSeconds(3))); + } + + [Fact] + public async Task Health_check_adds_no_REGISTERs_and_a_hard_failure_stops_retries() + { + using var h = new RegistrationTestHarness(extended: true, healthMonitoring: true, + tune: r => { r.HealthCheckIntervalMs = 50; r.HealthCheckStaleMs = 100; }); + h.Registrar.Script = Reply.ServiceUnavailable; + + h.Client.StartRegistration(); + await Task.Delay(2000); + + // One REGISTER in flight at a time: never closer together than the first backoff step. + Assert.All(h.GapsMs(), gap => Assert.True(gap >= 80, $"gap {gap} ms")); + + h.Registrar.Script = Reply.Forbidden; + Assert.True(await h.WaitForState(RegistrationState.HardFailure, TimeSpan.FromSeconds(3))); + int count = h.Registrar.Count; + await Task.Delay(1500); + Assert.Equal(count, h.Registrar.Count); + Assert.False(h.SawAlreadyRunning); + } +} + +/// +/// After a success the extended backoff starts over: the first retry of the next outage comes +/// after the initial delay again. Waits for a real refresh (25 s), so it is its own class. +/// +public class RegistrationExtendedRetryResetTests +{ + [Fact] + public async Task Backoff_restarts_after_a_successful_registration() + { + using var h = new RegistrationTestHarness(extended: true); + h.Registrar.Script = Reply.ServiceUnavailable; + h.Client.StartRegistration(); + await Task.Delay(1500); // backoff climbs to the 400 ms cap + h.Registrar.Script = Reply.Ok; + Assert.True(await h.WaitForState(RegistrationState.Registered, TimeSpan.FromSeconds(3))); + + // Second outage at the next refresh (25 s later). + h.Registrar.Script = Reply.ServiceUnavailable; + int before = h.Registrar.Count; + Assert.True(await h.Registrar.WaitForCountAsync(before + 2, TimeSpan.FromSeconds(35))); + + double firstRetryGap = h.GapsMs(before)[0]; + Assert.InRange(firstRetryGap, 80, 350); + } +} diff --git a/tests/SipBotLib.Tests/RegistrationTestHarness.cs b/tests/SipBotLib.Tests/RegistrationTestHarness.cs new file mode 100644 index 0000000..413e0af --- /dev/null +++ b/tests/SipBotLib.Tests/RegistrationTestHarness.cs @@ -0,0 +1,79 @@ +using System.Collections.Concurrent; +using System.Net; +using SIPSorcery.SIP; +using SipBot; + +namespace SipBotLib.Tests; + +/// +/// A SipClient registered against a , with timings shortened so the +/// registration tests run in seconds: dropped REGISTERs fail after 2 s, the registration agent's +/// own retry is 2 s, default attempts are 100 ms × n, and extended retry doubles from 100 ms to +/// 400 ms. +/// +internal sealed class RegistrationTestHarness : IDisposable +{ + public FakeRegistrar Registrar { get; } = new(); + public SipClient Client { get; } + public ConcurrentQueue Errors { get; } = new(); + private int _statusChanges; + public int StatusChanges => Volatile.Read(ref _statusChanges); + + public RegistrationTestHarness( + bool extended = false, + bool autoReconnect = true, + bool healthMonitoring = false, + Action? tune = null) + { + var transport = new SIPTransport(); + transport.AddSIPChannel(new SIPUDPChannel(IPAddress.Loopback, 0)); + + var config = new SipConfig { Server = Registrar.Server, Username = "101", Password = "secret" }; + var retry = config.RegistrationRetry; + retry.Extended = extended; + retry.AgentAttemptTimeoutSeconds = 2; + retry.AgentFailureRetrySeconds = 2; + retry.DefaultBaseDelayMs = 100; + retry.ExtendedInitialDelayMs = 100; + retry.ExtendedMaxDelayMs = 400; + retry.HealthCheckIntervalMs = 200; + retry.HealthCheckStaleMs = 300; + tune?.Invoke(retry); + + // Expires 30 is SipClient's minimum; the agent refreshes 5 s before expiry (every 25 s). + Client = new SipClient(transport, config, registrationExpirySeconds: 30, + enableAutoReconnection: autoReconnect, enableHealthMonitoring: healthMonitoring); + Client.ErrorOccurred += (_, ex) => Errors.Enqueue(ex); + Client.RegistrationStatusChanged += _ => Interlocked.Increment(ref _statusChanges); + } + + public bool SawAlreadyRunning => Errors.Any(e => e.Message.Contains("already running")); + + public static async Task WaitUntil(Func condition, TimeSpan timeout) + { + var deadline = DateTime.UtcNow + timeout; + while (DateTime.UtcNow < deadline) + { + if (condition()) + return true; + await Task.Delay(20); + } + return condition(); + } + + public Task WaitForState(RegistrationState state, TimeSpan timeout) => + WaitUntil(() => Client.RegistrationState == state, timeout); + + /// Gaps in milliseconds between consecutive REGISTERs, from index . + public double[] GapsMs(int from = 0) + { + var at = Registrar.Registers.Select(r => r.At.TotalMilliseconds).ToArray(); + return Enumerable.Range(from + 1, Math.Max(0, at.Length - from - 1)).Select(i => at[i] - at[i - 1]).ToArray(); + } + + public void Dispose() + { + Client.Dispose(); + Registrar.Dispose(); + } +} diff --git a/tools/sipbot/Program.cs b/tools/sipbot/Program.cs index 757c527..48781b9 100644 --- a/tools/sipbot/Program.cs +++ b/tools/sipbot/Program.cs @@ -35,12 +35,27 @@ { Description = "Disable continuous outbound RTP keep-alive (NAT pinholes may fail)" }; +var extendedRetryOpt = new Option("--extended-retry") +{ + Description = "Retry registration after temporary failures forever (30 s doubling to 5 min) " + + "instead of 5 attempts then SIPSorcery's 300 s retry. Also SIP_EXTENDED_RETRY=1" +}; +var sipTraceOpt = new Option("--sip-trace") +{ + Description = "Log every SIP message sent and received to stderr (lab use; includes headers " + + "such as digest Authorization). Also SIP_TRACE=1" +}; var serve = new Command("serve", "Register with the PBX and run the JSONL control daemon. " + AudioCaps.PlayHelp) { - settingsOpt, configOpt, autoAnswerOpt, playOpt, pcmuOnlyOpt, noKeepAliveOpt + settingsOpt, configOpt, autoAnswerOpt, playOpt, pcmuOnlyOpt, noKeepAliveOpt, extendedRetryOpt, sipTraceOpt }; +// Read here rather than in SipBotSettings, so a program that uses the library's settings loader +// never picks these up from its environment. +static bool EnvFlag(string name) => + Environment.GetEnvironmentVariable(name)?.Trim().ToLowerInvariant() is "1" or "true" or "yes" or "on"; + serve.SetAction(async (parseResult, ct) => { var options = new ServeOptions @@ -50,7 +65,9 @@ AutoAnswer = parseResult.GetValue(autoAnswerOpt), AutoAnswerPlay = parseResult.GetValue(playOpt), PcmuOnly = parseResult.GetValue(pcmuOnlyOpt), - NoKeepAlive = parseResult.GetValue(noKeepAliveOpt) + NoKeepAlive = parseResult.GetValue(noKeepAliveOpt), + ExtendedRetry = parseResult.GetValue(extendedRetryOpt) || EnvFlag("SIP_EXTENDED_RETRY"), + SipTrace = parseResult.GetValue(sipTraceOpt) || EnvFlag("SIP_TRACE") }; using var cts = Shutdown.CreateCts(); diff --git a/tools/sipbot/ServeHost.cs b/tools/sipbot/ServeHost.cs index 6e32fb8..dc3544d 100644 --- a/tools/sipbot/ServeHost.cs +++ b/tools/sipbot/ServeHost.cs @@ -35,13 +35,18 @@ public async Task RunAsync(CancellationTokenSource runCts) var cancellationToken = runCts.Token; var cfg = SipBotSettings.LoadActiveConfig(_options.SettingsPath, _options.ConfigIndex); int localPort = SipBotSettings.GetLocalBindPort(0); + if (_options.ExtendedRetry) + cfg.RegistrationRetry.Extended = true; Log.Information( - "sipbot serve user={User} server={Server} localPort={Port} autoAnswer={Auto} keepAlive={KA} wideband={WB}", - cfg.Username, cfg.Server, localPort, _options.AutoAnswer, !_options.NoKeepAlive, !_options.PcmuOnly); + "sipbot serve user={User} server={Server} localPort={Port} autoAnswer={Auto} keepAlive={KA} wideband={WB} extendedRetry={XR} sipTrace={Trace}", + cfg.Username, cfg.Server, localPort, _options.AutoAnswer, !_options.NoKeepAlive, !_options.PcmuOnly, + cfg.RegistrationRetry.Extended, _options.SipTrace); _transport = new SIPTransport(); _transport.AddSIPChannel(new SIPUDPChannel(IPAddress.Any, localPort)); + if (_options.SipTrace) + EnableSipTrace(_transport); _client = new SipClient(_transport, cfg, registrationExpirySeconds: 120); WireClient(_client); @@ -80,6 +85,22 @@ public async Task RunAsync(CancellationTokenSource runCts) private AgentAudioEndPoint NewEndpoint() => new(!_options.NoKeepAlive, !_options.PcmuOnly); + /// + /// Lab-only full SIP message trace (--sip-trace / SIP_TRACE). Off by default: the messages + /// include SIP headers such as digest Authorization responses. + /// + private static void EnableSipTrace(SIPTransport transport) + { + transport.SIPRequestOutTraceEvent += (_, remote, req) => + Log.Information("SIP >> {Remote}\n{Message}", remote, req.ToString()); + transport.SIPRequestInTraceEvent += (_, remote, req) => + Log.Information("SIP << {Remote}\n{Message}", remote, req.ToString()); + transport.SIPResponseOutTraceEvent += (_, remote, resp) => + Log.Information("SIP >> {Remote}\n{Message}", remote, resp.ToString()); + transport.SIPResponseInTraceEvent += (_, remote, resp) => + Log.Information("SIP << {Remote}\n{Message}", remote, resp.ToString()); + } + private void WireClient(SipClient client) { client.StatusMessage += (_, msg) => Log.Information("[status] {Msg}", msg); @@ -528,6 +549,8 @@ sealed class ServeOptions public string? AutoAnswerPlay { get; init; } public bool PcmuOnly { get; init; } public bool NoKeepAlive { get; init; } + public bool ExtendedRetry { get; init; } + public bool SipTrace { get; init; } } static class Shutdown From 7a784abf624e82d606f142a1b7f4447638e27a34 Mon Sep 17 00:00:00 2001 From: calebtt Date: Fri, 25 Sep 2026 20:05:57 -0500 Subject: [PATCH 2/3] Keep the health check from interrupting a registration attempt in flight Found in a live outage test against the lab PBX with --extended-retry: with REGISTERs being dropped, the health check fired 3 s into a reconnect attempt and scheduled the next one. In extended mode that stopped the in-flight agent, so its own failure was never reported and the backoff skipped a step; in default mode the scheduled attempt cut the in-flight one short. The health check now does nothing while an attempt is in flight (RegistrationState.Registering), in both modes. New test: every REGISTER dropped, 2 s per attempt, health check every 100 ms; without the fix attempts were cut short after 176-600 ms. Co-Authored-By: Claude Opus 5.5 --- Network/SipClient.cs | 12 ++++---- .../RegistrationTemporaryFailureTests.cs | 28 +++++++++++++++++++ 2 files changed, 34 insertions(+), 6 deletions(-) diff --git a/Network/SipClient.cs b/Network/SipClient.cs index 4941487..d44e72d 100644 --- a/Network/SipClient.cs +++ b/Network/SipClient.cs @@ -989,9 +989,11 @@ private void PerformHealthCheck(object? state) var timeSinceLastRegistration = DateTime.UtcNow - _lastSuccessfulRegistration; // Only after the host has started registration, never after a hard failure (the - // registrar rejected the account; retrying would just repeat the rejection), and - // never during shutdown. - if (!_registrationStarted || _isShutdown || _registrationState == RegistrationState.HardFailure) + // registrar rejected the account; retrying would just repeat the rejection), never + // while an attempt is in flight (it reports its own result; interrupting it would stop + // that agent and skip a backoff step), and never during shutdown. + if (!_registrationStarted || _isShutdown + || _registrationState is RegistrationState.HardFailure or RegistrationState.Registering) return; // If we haven't registered successfully recently, try to re-register. Route through @@ -1004,10 +1006,8 @@ private void PerformHealthCheck(object? state) Log.Warning("Health check: no successful registration recently, scheduling re-registration"); ScheduleReconnection(); } - else if (_registrationState != RegistrationState.Registering) + else { - // Restart only after the current attempt has failed, so the health check never - // cuts an in-flight REGISTER short. Log.Warning("Health check: no successful registration recently, restarting registration"); StartRegistration(); } diff --git a/tests/SipBotLib.Tests/RegistrationTemporaryFailureTests.cs b/tests/SipBotLib.Tests/RegistrationTemporaryFailureTests.cs index 07e1fa9..eac7e78 100644 --- a/tests/SipBotLib.Tests/RegistrationTemporaryFailureTests.cs +++ b/tests/SipBotLib.Tests/RegistrationTemporaryFailureTests.cs @@ -144,6 +144,34 @@ public async Task Health_check_adds_no_REGISTERs_and_a_hard_failure_stops_retrie } } +/// +/// The health check leaves an attempt in flight alone. Found live: with REGISTERs being dropped, +/// the health check (auto-reconnect on) scheduled the next attempt 3 s into the current one, which +/// stopped the in-flight agent and skipped a backoff step. Here every REGISTER is dropped, each +/// attempt waits 2 s for a response, and the health check fires every 100 ms. +/// +public class RegistrationHealthCheckInFlightTests +{ + [Theory] + [InlineData(true)] + [InlineData(false)] + public async Task Health_check_does_not_interrupt_an_attempt_in_flight(bool extended) + { + using var h = new RegistrationTestHarness(extended: extended, healthMonitoring: true, + tune: r => { r.HealthCheckIntervalMs = 100; r.HealthCheckStaleMs = 100; }); + h.Registrar.Script = Reply.Drop; + + h.Client.StartRegistration(); + await Task.Delay(TimeSpan.FromSeconds(7)); + + // Each attempt runs its full 2 s before the next REGISTER; the health check adds none. + double[] gaps = h.GapsMs(); + Assert.True(gaps.Length >= 2, $"only {gaps.Length + 1} REGISTERs in 7 s"); + Assert.All(gaps, gap => Assert.True(gap >= 1800, $"gap {gap} ms: an attempt was cut short")); + Assert.False(h.SawAlreadyRunning); + } +} + /// /// After a success the extended backoff starts over: the first retry of the next outage comes /// after the initial delay again. Waits for a real refresh (25 s), so it is its own class. From 02d9d4d56a9f9691870af0fbc0678804d643cd48 Mon Sep 17 00:00:00 2001 From: calebtt Date: Fri, 25 Sep 2026 20:16:23 -0500 Subject: [PATCH 3/3] Count reconnect attempts against failures in the in-flight health check test On the CI runner a REGISTER can leave late (SIPSorcery sends it via a blocking call on a thread-pool thread) while its attempt timeout is already running, so gaps between REGISTERs came out short even with the fix. Assert the bug's own signature instead: every reconnect attempt must follow a reported temporary failure, taken from the client's metrics. Without the fix both cases still fail. Co-Authored-By: Claude Opus 5.5 --- .../RegistrationTemporaryFailureTests.cs | 15 +++++++++++---- 1 file changed, 11 insertions(+), 4 deletions(-) diff --git a/tests/SipBotLib.Tests/RegistrationTemporaryFailureTests.cs b/tests/SipBotLib.Tests/RegistrationTemporaryFailureTests.cs index eac7e78..f4c9575 100644 --- a/tests/SipBotLib.Tests/RegistrationTemporaryFailureTests.cs +++ b/tests/SipBotLib.Tests/RegistrationTemporaryFailureTests.cs @@ -152,6 +152,9 @@ public async Task Health_check_adds_no_REGISTERs_and_a_hard_failure_stops_retrie /// public class RegistrationHealthCheckInFlightTests { + private static long Metric(SipClient client, string name) => + client.Metrics.TryGetValue(name, out var value) ? value : 0; + [Theory] [InlineData(true)] [InlineData(false)] @@ -164,10 +167,14 @@ public async Task Health_check_does_not_interrupt_an_attempt_in_flight(bool exte h.Client.StartRegistration(); await Task.Delay(TimeSpan.FromSeconds(7)); - // Each attempt runs its full 2 s before the next REGISTER; the health check adds none. - double[] gaps = h.GapsMs(); - Assert.True(gaps.Length >= 2, $"only {gaps.Length + 1} REGISTERs in 7 s"); - Assert.All(gaps, gap => Assert.True(gap >= 1800, $"gap {gap} ms: an attempt was cut short")); + // Every reconnect attempt must follow a reported failure. An attempt the health check + // starts while another is in flight has no failure behind it (it also stops the in-flight + // agent, whose failure is then never reported). Counted from the client's own metrics, + // so a slow runner that delays a REGISTER cannot fail the test. + long failures = Metric(h.Client, "temporary_registration_failures"); + long attempts = Metric(h.Client, "reconnection_attempts"); + Assert.True(failures >= 2, $"only {failures} failures in 7 s"); + Assert.True(attempts <= failures, $"{attempts} reconnect attempts for {failures} failures"); Assert.False(h.SawAlreadyRunning); } }