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..d44e72d 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), 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 + // 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 { + 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..f4c9575 --- /dev/null +++ b/tests/SipBotLib.Tests/RegistrationTemporaryFailureTests.cs @@ -0,0 +1,206 @@ +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); + } +} + +/// +/// 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 +{ + private static long Metric(SipClient client, string name) => + client.Metrics.TryGetValue(name, out var value) ? value : 0; + + [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)); + + // 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); + } +} + +/// +/// 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