diff --git a/src/SQLInsight.Agent/Configuration/AgentRequestService.cs b/src/SQLInsight.Agent/Configuration/AgentRequestService.cs index d6636c0..c5204f4 100644 --- a/src/SQLInsight.Agent/Configuration/AgentRequestService.cs +++ b/src/SQLInsight.Agent/Configuration/AgentRequestService.cs @@ -61,7 +61,7 @@ public sealed partial class AgentRequestService( { nextHousekeeping = now.AddMinutes(10); await repository.PublishAgentKeyAsync(key.Describe(now), stoppingToken).ConfigureAwait(false); - await repository.CleanUpAgentRequestsAsync(now, RequestTimeout + TimeSpan.FromMinutes(1), TimeSpan.FromMinutes(30), TimeSpan.FromDays(30), stoppingToken) + await repository.CleanUpAgentRequestsAsync(now, StaleAfter, TimeSpan.FromMinutes(30), TimeSpan.FromDays(30), stoppingToken) .ConfigureAwait(false); } @@ -86,8 +86,9 @@ public sealed partial class AgentRequestService( public async Task HandleAsync(AgentRequestRow request, CancellationToken cancellationToken) { ArgumentNullException.ThrowIfNull(request); + var limit = TimeoutOf(request.Kind); using var timeout = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); - timeout.CancelAfter(RequestTimeout); + timeout.CancelAfter(limit); string? result = null; string? error = null; try @@ -104,7 +105,7 @@ public sealed partial class AgentRequestService( } catch (OperationCanceledException) when (!cancellationToken.IsCancellationRequested) { - error = $"Agenten fik ikke svar inden for {RequestTimeout.TotalMinutes:0} minutter."; + error = $"Agenten fik ikke svar inden for {limit.TotalMinutes:0} minutter."; } // Anything else (a lock timeout, a repository error while storing a discovery …) is the request's result too, so it // is never left as Running for the web UI to wait on. @@ -117,6 +118,15 @@ public sealed partial class AgentRequestService( await repository.CompleteAgentRequestAsync(request.RequestId, error is null, result, error, timeProvider.GetUtcNow(), CancellationToken.None).ConfigureAwait(false); } + /// How long a request may take: a synthetic check run now may take its own timeout plus the lookup of its service. + public TimeSpan TimeoutOf(string kind) => + serverRequests is not null && Servers.ServerRequestHandler.Handles(kind) ? Longest(RequestTimeout, Servers.ServerRequestHandler.RequestTimeout) : RequestTimeout; + + /// A request still Running after this was lost (the agent stopped): the longest request plus a minute. + private static TimeSpan StaleAfter => Longest(RequestTimeout, Servers.ServerRequestHandler.RequestTimeout) + TimeSpan.FromMinutes(1); + + private static TimeSpan Longest(TimeSpan a, TimeSpan b) => a > b ? a : b; + private static int Require(AgentRequestRow request) => request.ConfiguredInstanceId ?? throw new InvalidOperationException("Anmodningen mangler en instans."); diff --git a/src/SQLInsight.Agent/Servers/ServerRequestHandler.cs b/src/SQLInsight.Agent/Servers/ServerRequestHandler.cs index 0f0cb29..aa027b5 100644 --- a/src/SQLInsight.Agent/Servers/ServerRequestHandler.cs +++ b/src/SQLInsight.Agent/Servers/ServerRequestHandler.cs @@ -1,5 +1,6 @@ using SQLInsight.Core.Configuration; using SQLInsight.Core.Servers; +using SQLInsight.Core.SyntheticChecks; using SQLInsight.Repository; using SQLInsight.Servers; @@ -11,6 +12,18 @@ namespace SQLInsight.Agent.Servers; /// public sealed class ServerRequestHandler(InsightRepository repository, IWindowsServerSource source, SyntheticCheckService checks, TimeProvider time) { + /// Margin for reading the request and storing its result. + public static readonly TimeSpan Margin = TimeSpan.FromSeconds(30); + + /// + /// How long such a request may take: a check's longest timeout, the lookup of its Windows service and storing the + /// result, so "Kør nu" always gets its result stored. + /// + public static readonly TimeSpan RequestTimeout = TimeSpan.FromSeconds(SyntheticCheckLimits.MaxTimeoutSeconds) + SyntheticCheckService.ServiceLookupTimeout + Margin; + + /// How long a server test may take: what is not done by then is reported as not answered, in time to be stored. + public static readonly TimeSpan TestTimeout = RequestTimeout - Margin; + public static bool Handles(string kind) => ServerRequestKind.Handles(kind); /// The request's result as JSON. Throws for a server or check that does not exist. @@ -33,7 +46,7 @@ public sealed class ServerRequestHandler(InsightRepository repository, IWindowsS var server = await repository.GetWindowsServerAsync(serverId, cancellationToken).ConfigureAwait(false) ?? throw new KeyNotFoundException($"Server {serverId} findes ikke."); var account = OperatingSystem.IsWindows() ? CimWindowsServerSource.AgentAccount(server.Host) : null; - var result = await WindowsServerTester.TestAsync(source, server.Host, account, time.GetUtcNow(), cancellationToken).ConfigureAwait(false); + var result = await WindowsServerTester.TestAsync(source, server.Host, account, time.GetUtcNow(), TestTimeout, cancellationToken).ConfigureAwait(false); if (result.Reachable) { await repository.RecordServerAreasAsync(serverId, result.Areas, cancellationToken).ConfigureAwait(false); @@ -42,10 +55,11 @@ public sealed class ServerRequestHandler(InsightRepository repository, IWindowsS return result; } - public async Task RunAsync(int checkId, CancellationToken cancellationToken) + /// "Kør nu": joins a run of the check that is going on, or runs it within the limit on parallel checks; a paused check is not run. + public async Task RunAsync(int checkId, CancellationToken cancellationToken) { var check = await repository.GetSyntheticCheckAsync(checkId, cancellationToken).ConfigureAwait(false) ?? throw new KeyNotFoundException($"Tjek {checkId} findes ikke."); - return await checks.RunCheckAsync(check, cancellationToken).ConfigureAwait(false); + return await checks.RunNowAsync(check, cancellationToken).ConfigureAwait(false); } } diff --git a/src/SQLInsight.Agent/Servers/SyntheticCheckService.cs b/src/SQLInsight.Agent/Servers/SyntheticCheckService.cs index 333dde5..e97969f 100644 --- a/src/SQLInsight.Agent/Servers/SyntheticCheckService.cs +++ b/src/SQLInsight.Agent/Servers/SyntheticCheckService.cs @@ -12,7 +12,8 @@ namespace SQLInsight.Agent.Servers; /// /// Runs the synthetic checks on their schedule (and on request from SQLInsight Web), as the agent's identity: stores /// each result, looks up the linked Windows service when a check fails ("svarer ikke, selv om tjenesten kører"), -/// evaluates the rules and notifies. Never changes anything on the servers it checks. +/// evaluates the rules and notifies. A check runs once at a time, and at most MaxParallelChecks run together, also when +/// asked to run now. Never changes anything on the servers it checks. /// public sealed partial class SyntheticCheckService( IOptions options, @@ -27,9 +28,17 @@ public sealed partial class SyntheticCheckService( IOptions agentOptions, Configuration.RepositoryReadiness readiness) : BackgroundService { - private readonly Dictionary _running = []; + /// The answer to "Kør nu" for a paused check: it is not run. + public const string PausedMessage = "Tjekket er sat på pause."; + + /// How long looking up the state of a failing check's Windows service may take. + public static readonly TimeSpan ServiceLookupTimeout = TimeSpan.FromSeconds(30); + + private readonly Dictionary> _running = []; + private readonly Dictionary _attempts = []; private readonly Dictionary _reported = []; private readonly Lock _lock = new(); + private readonly SemaphoreSlim _throttle = new(Math.Clamp(options.Value.MaxParallelChecks, 1, 32)); protected override async Task ExecuteAsync(CancellationToken stoppingToken) { @@ -40,37 +49,37 @@ public sealed partial class SyntheticCheckService( } await readiness.Ready.WaitAsync(stoppingToken).ConfigureAwait(false); - using var throttle = new SemaphoreSlim(Math.Max(1, settings.MaxParallelChecks)); using var timer = new PeriodicTimer(agentOptions.Value.Tick, time); - do + try { - try + do { - var now = time.GetUtcNow(); - foreach (var check in await repository.GetSyntheticChecksAsync(stoppingToken).ConfigureAwait(false)) + try { - if (check.Paused || (check.LastRunAt is { } last && last.AddSeconds(check.IntervalSeconds) > now.UtcDateTime)) + var now = time.GetUtcNow(); + var checks = await repository.GetSyntheticChecksAsync(stoppingToken).ConfigureAwait(false); + Prune(checks); + foreach (var check in checks.Where(c => IsDue(c, now))) { - continue; - } - - lock (_lock) - { - if (_running.TryGetValue(check.CheckId, out var task) && !task.IsCompleted) + lock (_lock) { - continue; + _attempts[check.CheckId] = now; } - _running[check.CheckId] = RunThrottledAsync(check, throttle, stoppingToken); + _ = Start(check, stoppingToken); } } + catch (Exception ex) when (!stoppingToken.IsCancellationRequested) + { + LogRoundFailed(logger, ex); + } } - catch (Exception ex) when (ex is not OperationCanceledException) - { - LogRoundFailed(logger, ex); - } + while (await timer.WaitForNextTickAsync(stoppingToken).ConfigureAwait(false)); + } + catch (OperationCanceledException) when (stoppingToken.IsCancellationRequested) + { + // Stopping: the running checks end below. } - while (await timer.WaitForNextTickAsync(stoppingToken).ConfigureAwait(false)); Task[] remaining; lock (_lock) @@ -78,27 +87,118 @@ public sealed partial class SyntheticCheckService( remaining = [.. _running.Values]; } - await Task.WhenAll(remaining).ConfigureAwait(false); + await ServerMonitoringService.WaitQuietlyAsync(remaining).ConfigureAwait(false); } - private async Task RunThrottledAsync(SyntheticCheckRow check, SemaphoreSlim throttle, CancellationToken cancellationToken) + public override void Dispose() { - await throttle.WaitAsync(cancellationToken).ConfigureAwait(false); + base.Dispose(); + _throttle.Dispose(); + } + + /// + /// Due when its interval (never under a minute) has passed since the last stored result and since the agent last + /// started it: a run that could not be stored is not repeated every few seconds. + /// + private bool IsDue(SyntheticCheckRow check, DateTimeOffset now) + { + if (check.Paused) + { + return false; + } + + var interval = SyntheticCheckOptions.IntervalOf(check.IntervalSeconds); + if (check.LastRunAt is { } last && new DateTimeOffset(DateTime.SpecifyKind(last, DateTimeKind.Utc)) + interval > now) + { + return false; + } + + lock (_lock) + { + return !(_attempts.TryGetValue(check.CheckId, out var attempted) && attempted + interval > now) + && !(_running.TryGetValue(check.CheckId, out var running) && !running.IsCompleted); + } + } + + /// Forgets checks that were removed. + private void Prune(IReadOnlyList checks) + { + var ids = checks.Select(c => c.CheckId).ToHashSet(); + lock (_lock) + { + foreach (var id in _running.Where(r => !ids.Contains(r.Key) && r.Value.IsCompleted).Select(r => r.Key).ToList()) + { + _running.Remove(id); + } + + foreach (var id in _attempts.Keys.Where(id => !ids.Contains(id)).ToList()) + { + _attempts.Remove(id); + } + + foreach (var id in _reported.Keys.Where(id => !ids.Contains(id)).ToList()) + { + _reported.Remove(id); + } + } + } + + /// The check's run that is going on, or a new one under the limit on parallel checks. + private Task Start(SyntheticCheckRow check, CancellationToken cancellationToken) + { + lock (_lock) + { + if (_running.TryGetValue(check.CheckId, out var running) && !running.IsCompleted) + { + return running; + } + + var task = RunThrottledAsync(check, cancellationToken); + _running[check.CheckId] = task; + return task; + } + } + + /// + /// "Kør nu" from SQLInsight Web: joins the check's run if one is going on, or runs it under the same limit as the + /// scheduled runs. A paused check is not run (and nothing is stored or evaluated). + /// + public async Task RunNowAsync(SyntheticCheckRow check, CancellationToken cancellationToken) + { + ArgumentNullException.ThrowIfNull(check); + if (check.Paused) + { + return new SyntheticCheckResult { At = time.GetUtcNow(), Success = false, Message = PausedMessage }; + } + + var result = await Start(check, cancellationToken).WaitAsync(cancellationToken).ConfigureAwait(false); + return result ?? throw new InvalidOperationException("Tjekket kunne ikke køres eller resultatet ikke gemmes. Se agentens log."); + } + + /// One run; null when it could not be stored (logged once per change). + private async Task RunThrottledAsync(SyntheticCheckRow check, CancellationToken cancellationToken) + { + await _throttle.WaitAsync(cancellationToken).ConfigureAwait(false); try { - await RunCheckAsync(check, cancellationToken).ConfigureAwait(false); + return await RunCheckAsync(check, cancellationToken).ConfigureAwait(false); } - catch (Exception ex) when (ex is not OperationCanceledException) + catch (Exception ex) when (!cancellationToken.IsCancellationRequested) { - LogCheckFailed(logger, ex, check.Name); + if (IsNews(check.CheckId, "fejl: " + ex.Message, remember: true)) + { + LogCheckFailed(logger, ex, check.Name); + } + + return null; } finally { - throttle.Release(); + _throttle.Release(); } } - /// Runs a check once, stores the result and its findings. Used on schedule and for "Kør nu" in SQLInsight Web. + /// Runs a check once, stores the result and its findings. Used on schedule and for "Kør nu" (through ). public async Task RunCheckAsync(SyntheticCheckRow check, CancellationToken cancellationToken) { ArgumentNullException.ThrowIfNull(check); @@ -115,7 +215,23 @@ public sealed partial class SyntheticCheckService( } var timeout = TimeSpan.FromSeconds(Math.Clamp(check.TimeoutSeconds, 1, SyntheticCheckLimits.MaxTimeoutSeconds)); - var result = await runner.RunAsync(new SyntheticCheckRun(check.Kind, settings, timeout, password), cancellationToken).ConfigureAwait(false); + SyntheticCheckResult result; + try + { + result = await runner.RunAsync(new SyntheticCheckRun(check.Kind, settings, timeout, password), cancellationToken).ConfigureAwait(false); + } + catch (Exception ex) when (!cancellationToken.IsCancellationRequested) + { + // Not a failure the runner foresaw: still the check's result, so it is stored, waits its interval, and is logged once. + var message = "Tjekket kunne ikke køres: " + ex.Message; + if (IsNews(check.CheckId, message, remember: false)) + { + LogCheckFailed(logger, ex, check.Name); + } + + result = new SyntheticCheckResult { At = now, Success = false, DurationMs = (int)Math.Min(int.MaxValue, (time.GetUtcNow() - now).TotalMilliseconds), Message = message }; + } + if (!result.Success && check.ServerId is { } serverId && settings.ServiceName is { Length: > 0 } service) { result = await WithServiceStateAsync(result, serverId, service, cancellationToken).ConfigureAwait(false); @@ -152,7 +268,10 @@ public sealed partial class SyntheticCheckService( return (password, error); } - /// The state of the Windows service behind a failing check: the difference between "nede" and "kører, men svarer ikke". + /// + /// The state of the Windows service behind a failing check: the difference between "nede" and "kører, men svarer + /// ikke". Takes at most . + /// private async Task WithServiceStateAsync(SyntheticCheckResult result, int serverId, string service, CancellationToken cancellationToken) { var server = await repository.GetWindowsServerAsync(serverId, cancellationToken).ConfigureAwait(false); @@ -161,10 +280,12 @@ public sealed partial class SyntheticCheckService( return result; } + using var lookup = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); + lookup.CancelAfter(ServiceLookupTimeout); try { - using var session = await servers.ConnectAsync(server.Host, cancellationToken).ConfigureAwait(false); - var state = await session.GetServiceAsync(service, cancellationToken).ConfigureAwait(false); + using var session = await servers.ConnectAsync(server.Host, lookup.Token).ConfigureAwait(false); + var state = await session.GetServiceAsync(service, lookup.Token).ConfigureAwait(false); return result with { ServiceState = state?.State ?? "NotFound", @@ -173,24 +294,34 @@ public sealed partial class SyntheticCheckService( } catch (ServerAccessException ex) { - return result with { Details = [.. result.Details, new SyntheticCheckDetail("Tjeneste", $"{service} på {server.Name} kunne ikke aflæses: {ex.Message}")] }; + // The reason names the agent's account: kept on-prem. + return result with { Details = [.. result.Details, new SyntheticCheckDetail("Tjeneste", $"{service} på {server.Name} kunne ikke aflæses: {ex.Message}", Sensitive: true)] }; + } + catch (OperationCanceledException) when (!cancellationToken.IsCancellationRequested) + { + return result with + { + Details = [.. result.Details, new SyntheticCheckDetail("Tjeneste", + $"{service} på {server.Name} kunne ikke aflæses: serveren svarede ikke inden for {ServiceLookupTimeout.TotalSeconds:0} sekunder.")], + }; } } private async Task StoreAsync(SyntheticCheckRow check, SyntheticCheckResult result, CancellationToken cancellationToken) { await repository.RecordSyntheticCheckResultAsync(check.CheckId, result, cancellationToken).ConfigureAwait(false); - var recent = (await repository.GetSyntheticCheckResultsAsync(check.CheckId, 10, cancellationToken: cancellationToken).ConfigureAwait(false)) + var settings = options.Value; + var recent = (await repository.GetSyntheticCheckResultsAsync(check.CheckId, settings.RecentResults, cancellationToken: cancellationToken).ConfigureAwait(false)) .Select(r => r.ToResult()).ToList(); - var settings = check.Settings; - var identity = new SyntheticCheckIdentity(check.CheckId, check.Name, check.Kind, settings.Target(check.Kind)) + var checkSettings = check.Settings; + var identity = new SyntheticCheckIdentity(check.CheckId, check.Name, check.Kind, checkSettings.Target(check.Kind)) { ServerName = check.ServerName, - ServiceName = settings.ServiceName, - WarnMilliseconds = settings.WarnMilliseconds, - Https = settings.Url?.Scheme == Uri.UriSchemeHttps, + ServiceName = checkSettings.ServiceName, + WarnMilliseconds = checkSettings.WarnMilliseconds, + Https = checkSettings.Url?.Scheme == Uri.UriSchemeHttps, }; - var results = ScopedRuleEngine.Evaluate(SyntheticCheckRules.Create(), new SyntheticCheckRuleContext(identity, result.At, recent, options.Value)); + var results = ScopedRuleEngine.Evaluate(SyntheticCheckRules.Create(), new SyntheticCheckRuleContext(identity, result.At, recent, settings)); var changes = await repository.SaveScopedRuleResultsAsync(FindingScope.Check, check.CheckId, results, result.At, cancellationToken).ConfigureAwait(false); var events = ServerNotifications.For(check.Name, changes, notificationOptions.Value.WebUrl, result.At).ToList(); if (events.Count > 0) @@ -198,19 +329,33 @@ public sealed partial class SyntheticCheckService( await notifications.DispatchAsync(events, cancellationToken).ConfigureAwait(false); } - lock (_lock) + if (IsNews(check.CheckId, result.Success ? "ok" : result.Message, remember: true)) { - var state = result.Success ? "ok" : result.Message; - if (!_reported.TryGetValue(check.CheckId, out var previous) || previous != state) - { - _reported[check.CheckId] = state; - LogResult(logger, check.Name, result.Success, result.Message); - } + LogResult(logger, check.Name, result.Success, result.Message); } return result; } + /// Whether a check's state differs from the last one logged (the same failure every run is not news). + private bool IsNews(int checkId, string state, bool remember) + { + lock (_lock) + { + if (_reported.TryGetValue(checkId, out var previous) && previous == state) + { + return false; + } + + if (remember) + { + _reported[checkId] = state; + } + + return true; + } + } + [LoggerMessage(Level = LogLevel.Information, Message = "Synthetic check {Check}: success {Success}: {Message}")] private static partial void LogResult(ILogger logger, string check, bool success, string message); diff --git a/tests/SQLInsight.IntegrationTests/ServerAgentTests.cs b/tests/SQLInsight.IntegrationTests/ServerAgentTests.cs index 1975934..3a8fc7c 100644 --- a/tests/SQLInsight.IntegrationTests/ServerAgentTests.cs +++ b/tests/SQLInsight.IntegrationTests/ServerAgentTests.cs @@ -236,6 +236,13 @@ public sealed class ServerAgentTests(SqlServerFixture sql) : IAsyncLifetime public BusinessConnectorInstallation? Find() => null; } + /// Fails in a way the check runner does not foresee. + private sealed class BrokenSql : ISqlConnectionFactory + { + public Task OpenAsync(ConnectionTarget target, CancellationToken cancellationToken = default) => + throw new NotSupportedException("Uventet fejl i driveren."); + } + [Fact] public async Task A_server_that_hangs_is_cut_off_at_the_cycle_deadline_and_backed_off() { @@ -262,6 +269,28 @@ public sealed class ServerAgentTests(SqlServerFixture sql) : IAsyncLifetime Assert.Equal(DateTimeOffset.MinValue, monitor.RetryAt); } + [Fact] + public async Task Run_now_leaves_a_paused_check_alone_and_an_unexpected_error_is_a_stored_failure() + { + var paused = await _repository.AddSyntheticCheckAsync(new SyntheticCheckInput("Pause", SyntheticCheckKind.Tcp, null, + new SyntheticCheckSettings { Host = "127.0.0.1", Port = ClosedPort() }, null, null, 300, 5, Paused: true), "anna", DateTimeOffset.UtcNow); + var sql = await _repository.AddSyntheticCheckAsync(new SyntheticCheckInput("SQL", SyntheticCheckKind.Sql, null, new SyntheticCheckSettings { Server = "sql01" }, + null, null, 300, 5), "anna", DateTimeOffset.UtcNow); + var service = Checks(new FakeServer(), sql: new BrokenSql()); + + var declined = await service.RunNowAsync((await _repository.GetSyntheticCheckAsync(paused))!, CancellationToken.None); + var failed = await service.RunNowAsync((await _repository.GetSyntheticCheckAsync(sql))!, CancellationToken.None); + + Assert.False(declined.Success); + Assert.Equal(SyntheticCheckService.PausedMessage, declined.Message); + Assert.Empty(await _repository.GetSyntheticCheckResultsAsync(paused)); + Assert.Null((await _repository.GetSyntheticCheckAsync(paused))!.LastRunAt); + Assert.Empty(await _repository.GetServerRuleStatesAsync(FindingScope.Check, paused)); + Assert.False(failed.Success); + Assert.StartsWith("Tjekket kunne ikke køres: Uventet fejl i driveren.", failed.Message, StringComparison.Ordinal); + Assert.NotNull((await _repository.GetSyntheticCheckAsync(sql))!.LastRunAt); // stored: waits its interval instead of running every 15 seconds + } + private static int ClosedPort() { using var probe = new TcpListener(IPAddress.Loopback, 0);