From a522ac2b1756408a7daf8f4f6af447c605e502d0 Mon Sep 17 00:00:00 2001 From: David Pine <7679720+IEvangelist@users.noreply.github.com> Date: Wed, 16 Sep 2026 15:06:17 -0500 Subject: [PATCH 1/4] Improve YouTube live-status failure diagnostics Add safe operation-specific diagnostics, discovery observations, and fallback regression coverage without changing polling or retry policies. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../StaticHost/Live/LiveEndpoints.cs | 33 +- src/statichost/StaticHost/Live/README.md | 91 ++++- .../StaticHost/Live/YouTube/YouTubeClient.cs | 15 +- .../Live/YouTube/YouTubeDiagnostics.cs | 155 ++++++++ .../YouTube/YouTubeLiveConfirmationQueue.cs | 3 +- .../Live/YouTube/YouTubeWebSubService.cs | 91 +++-- .../Live/YouTubeDiagnosticsTests.cs | 360 ++++++++++++++++++ .../Live/YouTubeWebSubServiceTests.cs | 4 +- 8 files changed, 708 insertions(+), 44 deletions(-) create mode 100644 src/statichost/StaticHost/Live/YouTube/YouTubeDiagnostics.cs create mode 100644 tests/StaticHost.Tests/Live/YouTubeDiagnosticsTests.cs diff --git a/src/statichost/StaticHost/Live/LiveEndpoints.cs b/src/statichost/StaticHost/Live/LiveEndpoints.cs index 96d88de12..80da227d0 100644 --- a/src/statichost/StaticHost/Live/LiveEndpoints.cs +++ b/src/statichost/StaticHost/Live/LiveEndpoints.cs @@ -1,3 +1,4 @@ +using System.Diagnostics; using System.Security.Cryptography; using System.Text; using System.Text.Json.Serialization; @@ -334,8 +335,9 @@ private static async Task YouTubeVerify( return Results.NotFound(); } - logger.LogInformation("YouTube WebSub subscription verified for {Topic}; granted lease {LeaseSeconds}s.", - topic, leaseSeconds); + logger.LogInformation( + "YouTube {Operation} verified; granted lease {LeaseSeconds}s. Verification establishes or renews the lease and resets subscription backoff.", + "WebSubVerification", leaseSeconds); return Results.Text(challenge, "text/plain"); } @@ -408,16 +410,21 @@ internal static async Task ConfirmYouTubeLiveStatusAsync( var channelId = youtube.ChannelId; if (string.IsNullOrWhiteSpace(channelId)) { - channelId = await ytClient.ResolveChannelIdAsync(youtube.ChannelHandle, cancellationToken).ConfigureAwait(false); + channelId = await ConfirmOperationAsync("NotificationChannelResolution", YouTubeDiagnostics.ChannelsEndpoint, + () => ytClient.ResolveChannelIdAsync(youtube.ChannelHandle, cancellationToken)).ConfigureAwait(false); } if (string.IsNullOrWhiteSpace(channelId)) { - logger.LogWarning("Could not resolve YouTube channel id for webhook confirmation."); + logger.LogWarning("YouTube {Operation} returned no channel; notification confirmation is unavailable, not confirmed offline.", + "NotificationChannelResolution"); return; } - var live = await ytClient.GetCurrentLiveAsync(channelId, cancellationToken).ConfigureAwait(false); + var live = await ConfirmOperationAsync("NotificationConfirmation", YouTubeDiagnostics.SearchEndpoint, + () => ytClient.GetCurrentLiveAsync(channelId, cancellationToken)).ConfigureAwait(false); + logger.LogInformation("YouTube {Operation} succeeded at {CheckedAt}; observed live {ObservedLive}.", + "NotificationConfirmation", DateTimeOffset.UtcNow, live.Live); await broadcaster.UpdateAsync( new LiveStatusUpdate { @@ -428,6 +435,22 @@ await broadcaster.UpdateAsync( youtube.OfflineConfirmationCount), }, cancellationToken).ConfigureAwait(false); + + async Task ConfirmOperationAsync(string operation, string endpoint, Func> action) + { + var started = Stopwatch.GetTimestamp(); + try + { + return await action().ConfigureAwait(false); + } + catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) { throw; } + catch (Exception exception) + { + YouTubeDiagnostics.LogFailure(logger, exception, operation, endpoint, + elapsedMs: Stopwatch.GetElapsedTime(started).TotalMilliseconds); + throw; + } + } } // --- Dev-only ----------------------------------------------------------- diff --git a/src/statichost/StaticHost/Live/README.md b/src/statichost/StaticHost/Live/README.md index d4ed37d3f..d4f140a30 100644 --- a/src/statichost/StaticHost/Live/README.md +++ b/src/statichost/StaticHost/Live/README.md @@ -51,18 +51,90 @@ restart the retry sequence. Successful verification resets the backoff; acceptance of the subscription POST alone does not. A channel change starts a fresh sequence. -Each failed attempt logs one concise warning for expected HTTP errors or -timeouts, including the failure count and next retry deadline. Exception -details and hub error response bodies are available at Debug; unexpected -exceptions remain Error-level with their stack traces. Successful verification -is logged at Information. Shutdown or leadership cancellation does not count -as an upstream failure. +Each failed attempt logs one warning for expected HTTP errors or timeouts, +including the failure count and next retry deadline. Unexpected failures are +Error-level, with a bounded `SafeStackTrace` rendered from stack frames alone, +without exception messages, argument values, or source file paths. Expected +HTTP and timeout warnings omit stack traces. Diagnostics intentionally omit +raw exception messages, URLs with query strings, and response bodies, which +can contain credentials. HTTP acceptance is logged separately from successful callback +verification: only verification establishes or renews the lease and resets +backoff. Shutdown or leadership cancellation does not count as an upstream +failure. The live and idle polling intervals remain unchanged during subscription backoff. Google documents feed notifications for uploads and video title/description updates, not guaranteed broadcast start/stop events, so fallback polling is still necessary. +### YouTube operational diagnostics + +In the Aspire dashboard, open **Structured logs**, select the `aspiredev` +resource, and filter for `YouTube` (the `StaticHost.Live.YouTube` categories). +Information, Warning, and Error events are sufficient; enabling Debug or +logging HTTP request bodies is not required. + +| `Operation` | Meaning | +| --- | --- | +| `ChannelResolution` | Resolve the configured handle through `channels.list`. A missing channel means detection is unavailable, not offline. | +| `OfflineDiscovery` | Quota-limited `search.list` check for a broadcast while no live video is known. | +| `KnownVideoStatus` | Low-cost `videos.list` check of the currently known live video. | +| `WebSubSubscribe` | Subscription POST accepted or failed; acceptance does **not** prove callback verification. | +| `WebSubVerification` | A matching callback verified the subscription or renewal, with the granted `LeaseSeconds`. | +| `NotificationChannelResolution` / `NotificationConfirmation` | Resolve the channel or run the confirming search after a signed notification. | +| `BackgroundTick` | A failure outside the provider calls, such as state coordination. | + +Failed provider operations include the query-free outbound `Endpoint`, +`ElapsedMs` measured with a monotonic clock, numeric `StatusCode`, +standard `StatusReason` (not an untrusted reason phrase), `FailureType`, +`IsTimeout`, `HttpRequestError`, `SocketError`, and `InnerFailureType` where +available. Google JSON errors add bounded `ProviderReason` and `ProviderDomain` +codes, for example `quotaExceeded` / `youtube.quota` or `accessNotConfigured` / +`usageLimits`. These distinguish quota exhaustion from API configuration, +network, and hub failures. + +The duration covers the client operation, including any existing Data API +resilience retries and response parsing, but not the later Redis backoff write. +For example, `WebSubSubscribe` with endpoint +`pubsubhubbub.appspot.com/subscribe` and status 503 identifies an outbound hub +failure, not an inbound website 503. Duration and status alone cannot establish +the underlying provider cause. + +`ProviderDetail` contains only a fixed classification, such as temporary +unavailability, invalid topic, or callback verification failure. Unknown or +malformed bodies are omitted; `BodyTruncated` indicates the diagnostic read +exceeded 4,096 characters. No raw HTML, provider message, API key, webhook +secret, verification token, authorization header, or subscription form is +logged by these diagnostics. Subscription failures also expose `FailureCount` +and `RetryAt`; a hub 503 does not stop polling or prove why a broadcast was +missed. + +Successful discovery logs `LastSuccessfulDiscoveryAt`, `LastDiscoveryLive`, +and `NextDiscoveryAt`. The worker includes its last successful discovery time +and result in subsequent failure logs, so operators can distinguish a +successful offline observation from unavailable detection. These are +process-local diagnostic values, not new Redis or public snapshot fields; +they start empty after a restart, channel change, or before the first successful +discovery. +The reset happens before resolving changed channel settings, so a failed +resolution cannot report a previous channel's successful discovery. +A later successful check advances the timestamp, indicating polling recovery. +Known-video and notification checks log `CheckedAt` and `ObservedLive`. +These observations precede the guarded state update: an offline observation +does not bypass the configured two-check confirmation rule. + +Without a useful notification, a new broadcast may take up to the configured +30-minute discovery interval (plus request/tick delays) to be detected. +Failures can extend that delay. `search.list` costs 100 quota units: the +default idle schedule makes at most 48 scheduled searches per day (4,800 +units) for a continuously running leader. Known-video checks cost one unit +every two minutes (up to 720 per day while continuously live). Channel +resolution, notification confirmation searches, request retries, and +restarts/leader changes can add usage; the usual 10,000-unit daily project +budget is shared with other callers. These logging changes do not alter +polling intervals, retry policies, leader coordination, or quota usage, and +do not fix the upstream subscription failure. + ## Configuration Bind from the `Live` section of configuration. In unconfigured local runs, @@ -311,6 +383,13 @@ dotnet test .\tests\Aspire.Dev.AppHost.Tests\Aspire.Dev.AppHost.Tests.csproj --c dotnet test .\tests\StaticHost.Tests\StaticHost.Tests.csproj --configuration Release --filter "Category!=RedisIntegration" ``` +For the focused YouTube diagnostics and polling regressions, explicitly keep +frontend build scripts and package installation disabled: + +```powershell +dotnet test .\tests\StaticHost.Tests\StaticHost.Tests.csproj --configuration Release --filter "FullyQualifiedName~YouTube&Category!=RedisIntegration" -p:ShouldRunBuildScript=false -p:ShouldRunNpmInstall=false +``` + The real-Redis group has the xUnit trait `Category=RedisIntegration` and requires a running container runtime, such as Docker. Following the [Aspire testing pattern](https://aspire.dev/testing/overview/), its shared fixture diff --git a/src/statichost/StaticHost/Live/YouTube/YouTubeClient.cs b/src/statichost/StaticHost/Live/YouTube/YouTubeClient.cs index 106715fea..ba8fc2420 100644 --- a/src/statichost/StaticHost/Live/YouTube/YouTubeClient.cs +++ b/src/statichost/StaticHost/Live/YouTube/YouTubeClient.cs @@ -34,7 +34,8 @@ private HttpClient ApiClient() var url = $"channels?part=id&forHandle={Uri.EscapeDataString(clean)}&key={Uri.EscapeDataString(apiKey)}"; using var response = await ApiClient().GetAsync(url, cancellationToken).ConfigureAwait(false); - response.EnsureSuccessStatusCode(); + await YouTubeDiagnostics.EnsureSuccessAsync(response, cancellationToken, + apiKey, options.CurrentValue.YouTube.WebhookSecret).ConfigureAwait(false); using var stream = await response.Content.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false); using var doc = await JsonDocument.ParseAsync(stream, cancellationToken: cancellationToken).ConfigureAwait(false); @@ -56,7 +57,8 @@ public async Task GetCurrentLiveAsync(string channelId, Cance var url = $"search?part=id&channelId={Uri.EscapeDataString(channelId)}&eventType=live&type=video&key={Uri.EscapeDataString(apiKey)}"; using var response = await ApiClient().GetAsync(url, cancellationToken).ConfigureAwait(false); - response.EnsureSuccessStatusCode(); + await YouTubeDiagnostics.EnsureSuccessAsync(response, cancellationToken, + apiKey, options.CurrentValue.YouTube.WebhookSecret).ConfigureAwait(false); using var stream = await response.Content.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false); using var doc = await JsonDocument.ParseAsync(stream, cancellationToken: cancellationToken).ConfigureAwait(false); @@ -80,7 +82,8 @@ public async Task GetVideoLiveStatusAsync(string videoId, Can var url = $"videos?part=liveStreamingDetails&id={Uri.EscapeDataString(videoId)}&key={Uri.EscapeDataString(apiKey)}"; using var response = await ApiClient().GetAsync(url, cancellationToken).ConfigureAwait(false); - response.EnsureSuccessStatusCode(); + await YouTubeDiagnostics.EnsureSuccessAsync(response, cancellationToken, + apiKey, options.CurrentValue.YouTube.WebhookSecret).ConfigureAwait(false); using var stream = await response.Content.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false); using var doc = await JsonDocument.ParseAsync(stream, cancellationToken: cancellationToken).ConfigureAwait(false); @@ -129,9 +132,9 @@ public async Task SubscribeAsync( using var response = await c.PostAsync("subscribe", form, cancellationToken).ConfigureAwait(false); if (!response.IsSuccessStatusCode) { - var body = await response.Content.ReadAsStringAsync(cancellationToken).ConfigureAwait(false); - logger.LogDebug("YouTube WebSub subscribe failed: {Status} {Body}", response.StatusCode, body); - response.EnsureSuccessStatusCode(); + logger.LogDebug("YouTube WebSub hub returned HTTP {StatusCode}.", (int)response.StatusCode); + await YouTubeDiagnostics.EnsureSuccessAsync(response, cancellationToken, + options.CurrentValue.YouTube.ApiKey, secret, verifyToken).ConfigureAwait(false); } } } diff --git a/src/statichost/StaticHost/Live/YouTube/YouTubeDiagnostics.cs b/src/statichost/StaticHost/Live/YouTube/YouTubeDiagnostics.cs new file mode 100644 index 000000000..7149c7316 --- /dev/null +++ b/src/statichost/StaticHost/Live/YouTube/YouTubeDiagnostics.cs @@ -0,0 +1,155 @@ +using System.Diagnostics; +using System.Net.Sockets; +using System.Text.Json; +using Microsoft.AspNetCore.WebUtilities; +using Polly.Timeout; + +namespace StaticHost.Live.YouTube; + +internal static class YouTubeDiagnostics +{ + internal const string ChannelsEndpoint = "www.googleapis.com/youtube/v3/channels"; + internal const string SearchEndpoint = "www.googleapis.com/youtube/v3/search"; + internal const string VideosEndpoint = "www.googleapis.com/youtube/v3/videos"; + internal const string SubscribeEndpoint = "pubsubhubbub.appspot.com/subscribe"; + private const string DetailsKey = "YouTube.ResponseDiagnostics"; + private const string LoggedKey = "YouTube.FailureLogged"; + private const int BodyLimit = 4096; + + private sealed record ResponseDetails(string? Reason, string? Domain, string Detail, bool Truncated); + + internal static async Task EnsureSuccessAsync( + HttpResponseMessage response, CancellationToken cancellationToken, params string[] secrets) + { + if (response.IsSuccessStatusCode) return; + + ResponseDetails details; + try + { + using var stream = await response.Content.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false); + using var reader = new StreamReader(stream); + var buffer = new char[BodyLimit + 1]; + var count = await reader.ReadBlockAsync(buffer.AsMemory(), cancellationToken).ConfigureAwait(false); + details = DescribeBody(new string(buffer, 0, Math.Min(count, BodyLimit)), count > BodyLimit, secrets); + } + catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) { throw; } + catch (Exception) + { + // Diagnostic decoding must never replace the original HTTP failure. + details = new(null, null, "Response body could not be read; body omitted", false); + } + + try + { + response.EnsureSuccessStatusCode(); + } + catch (HttpRequestException exception) + { + exception.Data[DetailsKey] = details; + throw; + } + } + + private static ResponseDetails DescribeBody(string body, bool truncated, string[] secrets) + { + try + { + using var doc = JsonDocument.Parse(body); + if (doc.RootElement.ValueKind == JsonValueKind.Object && + doc.RootElement.TryGetProperty("error", out var error) && + error.ValueKind == JsonValueKind.Object && + error.TryGetProperty("errors", out var errors) && + errors.ValueKind == JsonValueKind.Array && errors.GetArrayLength() > 0 && + errors[0].ValueKind == JsonValueKind.Object) + { + return new( + ReadCode(errors[0], "reason", secrets), + ReadCode(errors[0], "domain", secrets), + "Google structured error; message omitted", truncated); + } + } + catch (JsonException) { } + + // Only fixed classifications leave this boundary, never echoed HTML, URLs, + // callback values or arbitrary provider messages. + var detail = body.Contains("temporarily unavailable", StringComparison.OrdinalIgnoreCase) + ? "Provider reports temporary unavailability" + : body.Contains("invalid topic", StringComparison.OrdinalIgnoreCase) + ? "Provider reports an invalid topic" + : body.Contains("verification failed", StringComparison.OrdinalIgnoreCase) + ? "Provider reports callback verification failure" + : "Unrecognized provider response; body omitted"; + return new(null, null, detail, truncated); + } + + private static string? ReadCode(JsonElement error, string name, string[] secrets) + { + if (!error.TryGetProperty(name, out var property) || property.ValueKind != JsonValueKind.String) + return null; + var value = property.GetString(); + if (string.IsNullOrEmpty(value) || value.Length > 64 || + value.Any(c => !char.IsAsciiLetterOrDigit(c) && c is not '.' and not '_' and not '-') || + secrets.Any(secret => !string.IsNullOrEmpty(secret) && value.Contains(secret, StringComparison.Ordinal))) + return null; + return value; + } + + internal static void LogFailure( + ILogger logger, Exception exception, string operation, string endpoint, + YouTubeWebSubRetryState? retry = null, + DateTimeOffset? lastSuccessfulDiscoveryAt = null, bool? lastDiscoveryLive = null, + bool skipIfLogged = false, double? elapsedMs = null) + { + if (skipIfLogged && exception.Data[LoggedKey] is true) + { + exception.Data.Remove(LoggedKey); + return; + } + exception.Data[LoggedKey] = true; + var details = exception.Data[DetailsKey] as ResponseDetails; + var http = exception as HttpRequestException; + var status = http?.StatusCode is { } code ? (int?)code : null; + var timeout = exception is OperationCanceledException or TimeoutException or TimeoutRejectedException; + SocketException? socket = null; + var inner = exception.InnerException; + for (var depth = 0; inner is not null && depth < 4; depth++, inner = inner.InnerException) + { + socket ??= inner as SocketException; + timeout |= inner is TimeoutException or TimeoutRejectedException; + } + var expected = http is not null || timeout || exception is JsonException; + var message = + "YouTube {Operation} failed at {Endpoint} after {ElapsedMs} ms: {FailureType}, HTTP {StatusCode} {StatusReason}; " + + "provider reason {ProviderReason}, domain {ProviderDomain}, detail {ProviderDetail}, truncated {BodyTruncated}; " + + "timeout {IsTimeout}, network {HttpRequestError}, socket {SocketError}, inner failure {InnerFailureType}. " + + "Last successful discovery {LastSuccessfulDiscoveryAt}, live {LastDiscoveryLive}. Failure is not an offline observation."; + List fields = + [ + operation, endpoint, elapsedMs, exception.GetType().Name, status, + status is { } number ? ReasonPhrases.GetReasonPhrase(number) : null, + details?.Reason, details?.Domain, details?.Detail, details?.Truncated, + timeout, http?.HttpRequestError, socket?.SocketErrorCode, exception.InnerException?.GetType().Name, + lastSuccessfulDiscoveryAt, lastDiscoveryLive, + ]; + if (operation == "WebSubSubscribe") + { + message += " Attempt {FailureCount}. Next subscription attempt no earlier than {RetryAt}. " + + "Live-status polling remains independently scheduled; this does not indicate a successful poll."; + fields.Add(retry?.FailureCount); + fields.Add(retry?.RetryAt); + } + else if (operation == "BackgroundTick") + { + message += " The worker will retry on its normal tick schedule."; + } + if (!expected) + { + // Render frames independently: exception messages, ToString overrides, + // source paths and argument values must not enter the log. + var stack = new StackTrace(exception, fNeedFileInfo: false).ToString(); + message += " Safe stack trace: {SafeStackTrace}"; + fields.Add(stack.Length > 8192 ? stack[..8192] + " [truncated]" : stack); + } + logger.Log(expected ? LogLevel.Warning : LogLevel.Error, message, fields.ToArray()); + } +} diff --git a/src/statichost/StaticHost/Live/YouTube/YouTubeLiveConfirmationQueue.cs b/src/statichost/StaticHost/Live/YouTube/YouTubeLiveConfirmationQueue.cs index e2eff8064..1d5caf43f 100644 --- a/src/statichost/StaticHost/Live/YouTube/YouTubeLiveConfirmationQueue.cs +++ b/src/statichost/StaticHost/Live/YouTube/YouTubeLiveConfirmationQueue.cs @@ -61,7 +61,8 @@ await LiveStatusEndpointRouteBuilderExtensions.ConfirmYouTubeLiveStatusAsync( } catch (Exception ex) { - logger.LogWarning(ex, "Confirming poll after YouTube webhook failed."); + YouTubeDiagnostics.LogFailure(logger, ex, "NotificationConfirmation", "local coordination/state", + skipIfLogged: true); } } } diff --git a/src/statichost/StaticHost/Live/YouTube/YouTubeWebSubService.cs b/src/statichost/StaticHost/Live/YouTube/YouTubeWebSubService.cs index f60955e26..fc2b8a06f 100644 --- a/src/statichost/StaticHost/Live/YouTube/YouTubeWebSubService.cs +++ b/src/statichost/StaticHost/Live/YouTube/YouTubeWebSubService.cs @@ -1,5 +1,5 @@ +using System.Diagnostics; using Microsoft.Extensions.Options; -using Polly.Timeout; namespace StaticHost.Live.YouTube; @@ -30,6 +30,10 @@ public sealed class YouTubeWebSubService( private DateTimeOffset _nextDiscoveryPollAt = DateTimeOffset.MinValue; private string? _resolvedChannelHandle; private string? _resolvedChannelId; + private DateTimeOffset? _lastSuccessfulDiscoveryAt; + private bool? _lastDiscoveryLive; + private string? _diagnosticConfiguredChannelId; + private string? _diagnosticChannelHandle; /// protected override async Task ExecuteAsync(CancellationToken stoppingToken) @@ -63,7 +67,9 @@ private async Task RunLeaderAsync(CancellationToken stoppingToken) catch (OperationCanceledException) when (stoppingToken.IsCancellationRequested) { return; } catch (Exception ex) { - logger.LogError(ex, "YouTube WebSub tick failed; will retry."); + YouTubeDiagnostics.LogFailure(logger, ex, "BackgroundTick", "local coordination/state", + lastSuccessfulDiscoveryAt: _lastSuccessfulDiscoveryAt, lastDiscoveryLive: _lastDiscoveryLive, + skipIfLogged: true); } try @@ -80,6 +86,15 @@ internal async Task TickAsync(CancellationToken cancellationToken) var opts = options.CurrentValue; var youtube = opts.YouTube; + if (!string.Equals(_diagnosticConfiguredChannelId, youtube.ChannelId, StringComparison.Ordinal) || + !string.Equals(_diagnosticChannelHandle, youtube.ChannelHandle, StringComparison.OrdinalIgnoreCase)) + { + _diagnosticConfiguredChannelId = youtube.ChannelId; + _diagnosticChannelHandle = youtube.ChannelHandle; + _lastSuccessfulDiscoveryAt = null; + _lastDiscoveryLive = null; + } + var channelId = youtube.ChannelId; if (string.IsNullOrEmpty(channelId)) { @@ -92,12 +107,19 @@ internal async Task TickAsync(CancellationToken cancellationToken) channelId = _resolvedChannelId ?? ""; if (string.IsNullOrEmpty(channelId)) { - channelId = await client.ResolveChannelIdAsync(youtube.ChannelHandle, cancellationToken).ConfigureAwait(false) ?? ""; + channelId = await RunOperationAsync("ChannelResolution", YouTubeDiagnostics.ChannelsEndpoint, + () => client.ResolveChannelIdAsync(youtube.ChannelHandle, cancellationToken), + cancellationToken).ConfigureAwait(false) ?? ""; + if (!string.IsNullOrEmpty(channelId)) + { + logger.LogInformation("YouTube {Operation} succeeded at {CheckedAt}.", "ChannelResolution", _time.GetUtcNow()); + } } if (string.IsNullOrEmpty(channelId)) { - logger.LogWarning("Could not resolve YouTube channel id for {Handle}.", youtube.ChannelHandle); + logger.LogWarning("YouTube {Operation} returned no channel; live detection is unavailable, not confirmed offline.", + "ChannelResolution"); return; } @@ -115,6 +137,7 @@ internal async Task TickAsync(CancellationToken cancellationToken) if (request is not null) { var requestSent = false; + var started = Stopwatch.GetTimestamp(); try { var callback = $"{opts.PublicBaseUrl.TrimEnd('/')}/api/live/youtube/webhook"; @@ -134,35 +157,25 @@ await client.SubscribeAsync( } catch (Exception ex) { + var elapsedMs = Stopwatch.GetElapsedTime(started).TotalMilliseconds; var retry = await _subscriptions.MarkRequestFailedAsync( request, CancellationToken.None).ConfigureAwait(false); - if (ex is HttpRequestException or OperationCanceledException or TimeoutRejectedException) - { - if (retry is not null) - { - logger.LogWarning( - "YouTube WebSub subscribe failed ({FailureType}, HTTP {StatusCode}); attempt {FailureCount}. " + - "Next subscription attempt no earlier than {RetryAt}. Live-status polling continues.", - ex.GetType().Name, - (ex as HttpRequestException)?.StatusCode, - retry.FailureCount, - retry.RetryAt); - } - logger.LogDebug(ex, "YouTube WebSub subscription request failure details."); - } - else - { - logger.LogError(ex, "Unexpected YouTube WebSub subscription failure."); - } + YouTubeDiagnostics.LogFailure(logger, ex, "WebSubSubscribe", YouTubeDiagnostics.SubscribeEndpoint, + retry, _lastSuccessfulDiscoveryAt, _lastDiscoveryLive, elapsedMs: elapsedMs); } if (requestSent) { + var elapsedMs = Stopwatch.GetElapsedTime(started).TotalMilliseconds; await _subscriptions.MarkRequestSentAsync( request, _time.GetUtcNow(), cancellationToken).ConfigureAwait(false); + logger.LogInformation( + "YouTube {Operation} accepted at {AcceptedAt} after {ElapsedMs} ms; HTTP acceptance does not establish a verified lease. " + + "Only a matching verification callback establishes or renews the subscription.", + "WebSubSubscribe", _time.GetUtcNow(), elapsedMs); } } @@ -171,12 +184,24 @@ await _subscriptions.MarkRequestSentAsync( var current = observed.Snapshot.YouTube; if (current.Live && !string.IsNullOrEmpty(current.VideoId)) { - live = await client.GetVideoLiveStatusAsync(current.VideoId, cancellationToken).ConfigureAwait(false); + live = await RunOperationAsync("KnownVideoStatus", YouTubeDiagnostics.VideosEndpoint, + () => client.GetVideoLiveStatusAsync(current.VideoId, cancellationToken), + cancellationToken).ConfigureAwait(false); + logger.LogInformation("YouTube {Operation} succeeded at {CheckedAt}; observed live {ObservedLive}.", + "KnownVideoStatus", _time.GetUtcNow(), live.Live); } else if (now >= _nextDiscoveryPollAt) { _nextDiscoveryPollAt = now.AddSeconds(youtube.DiscoveryPollingIntervalSeconds); - live = await client.GetCurrentLiveAsync(channelId, cancellationToken).ConfigureAwait(false); + live = await RunOperationAsync("OfflineDiscovery", YouTubeDiagnostics.SearchEndpoint, + () => client.GetCurrentLiveAsync(channelId, cancellationToken), + cancellationToken).ConfigureAwait(false); + _lastSuccessfulDiscoveryAt = _time.GetUtcNow(); + _lastDiscoveryLive = live.Live; + logger.LogInformation( + "YouTube {Operation} succeeded; last successful discovery {LastSuccessfulDiscoveryAt}, live {LastDiscoveryLive}. " + + "Next discovery no earlier than {NextDiscoveryAt}.", + "OfflineDiscovery", _lastSuccessfulDiscoveryAt, _lastDiscoveryLive, _nextDiscoveryPollAt); } if (live is null) @@ -195,4 +220,22 @@ await broadcaster.UpdateAsync( }, cancellationToken).ConfigureAwait(false); } + + private async Task RunOperationAsync( + string operation, string endpoint, Func> action, CancellationToken cancellationToken) + { + var started = Stopwatch.GetTimestamp(); + try + { + return await action().ConfigureAwait(false); + } + catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) { throw; } + catch (Exception exception) + { + YouTubeDiagnostics.LogFailure(logger, exception, operation, endpoint, + lastSuccessfulDiscoveryAt: _lastSuccessfulDiscoveryAt, lastDiscoveryLive: _lastDiscoveryLive, + elapsedMs: Stopwatch.GetElapsedTime(started).TotalMilliseconds); + throw; + } + } } diff --git a/tests/StaticHost.Tests/Live/YouTubeDiagnosticsTests.cs b/tests/StaticHost.Tests/Live/YouTubeDiagnosticsTests.cs new file mode 100644 index 000000000..a56acabec --- /dev/null +++ b/tests/StaticHost.Tests/Live/YouTubeDiagnosticsTests.cs @@ -0,0 +1,360 @@ +using System.Net.Sockets; +using System.Runtime.CompilerServices; +using Microsoft.Extensions.Logging; + +namespace StaticHost.Tests.Live; + +public sealed class YouTubeDiagnosticsTests +{ + [Theory] + [InlineData("""{"error":{"errors":[{"reason":"quotaExceeded","domain":"youtube.quota"}],"message":"key=api-key secret verify-token"}}""", "quotaExceeded", "youtube.quota", false)] + [InlineData("""{"error":{"errors":[{"reason":"api-key","domain":"verify-token"}]}}""", null, null, false)] + [InlineData("""{"error":{"errors":[{"reason":"https://example.com/?key=api-key","domain":123}]}}""", null, null, false)] + [InlineData("""{"error":[]}""", null, null, false)] + [InlineData("""{"error":""", null, null, false)] + [InlineData("Temporarily unavailable api-key secret verify-token", null, null, false)] + [InlineData("oversized", null, null, true)] + public async Task HttpFailure_ReportsOnlyBoundedSafeDiagnostics( + string body, string? reason, string? domain, bool truncated) + { + if (truncated) body = new string('x', 5000) + "api-key secret verify-token"; + using var response = new HttpResponseMessage(HttpStatusCode.ServiceUnavailable) + { + Content = new StringContent(body), + ReasonPhrase = "api-key secret verify-token", + }; + var exception = await Assert.ThrowsAsync(() => + YouTubeDiagnostics.EnsureSuccessAsync(response, CancellationToken.None, "api-key", "secret", "verify-token")); + var logger = new YouTubeRecordingLogger(); + + YouTubeDiagnostics.LogFailure(logger, exception, "WebSubSubscribe", YouTubeDiagnostics.SubscribeEndpoint); + + Assert.Equal(HttpStatusCode.ServiceUnavailable, exception.StatusCode); + var entry = Assert.Single(logger.Entries); + Assert.Equal(LogLevel.Warning, entry.Level); + Assert.Null(entry.Exception); + Assert.False(entry.Fields.ContainsKey("SafeStackTrace")); + Assert.Equal(503, entry.Fields["StatusCode"]); + Assert.Equal("Service Unavailable", entry.Fields["StatusReason"]); + Assert.Equal(reason, entry.Fields["ProviderReason"]); + Assert.Equal(domain, entry.Fields["ProviderDomain"]); + Assert.Equal(truncated, entry.Fields["BodyTruncated"]); + Assert.DoesNotContain("api-key", entry.Message); + Assert.DoesNotContain("verify-token", entry.Message); + Assert.DoesNotContain("secret", entry.Message); + Assert.DoesNotContain("", entry.Message); + Assert.True(entry.Message.Length < 1000); + if (body.StartsWith("", StringComparison.Ordinal)) + Assert.Equal("Provider reports temporary unavailability", entry.Fields["ProviderDetail"]); + } + + [Fact] + public async Task UnreadableBody_DoesNotMaskHttpFailure() + { + using var response = new HttpResponseMessage(HttpStatusCode.BadGateway) + { + Content = new StreamContent(new UnreadableStream()), + }; + var exception = await Assert.ThrowsAsync(() => + YouTubeDiagnostics.EnsureSuccessAsync(response, CancellationToken.None)); + var logger = new YouTubeRecordingLogger(); + YouTubeDiagnostics.LogFailure(logger, exception, "OfflineDiscovery", YouTubeDiagnostics.SearchEndpoint); + Assert.Equal(HttpStatusCode.BadGateway, exception.StatusCode); + Assert.Equal("Response body could not be read; body omitted", + Assert.Single(logger.Entries).Fields["ProviderDetail"]); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void TransportFailure_ReportsCodesWithoutExceptionMessages(bool timeout) + { + Exception exception = timeout + ? new TaskCanceledException("https://example.com/?key=secret") + : new HttpRequestException(HttpRequestError.NameResolutionError, "key=secret", + new SocketException((int)SocketError.HostNotFound)); + var logger = new YouTubeRecordingLogger(); + + YouTubeDiagnostics.LogFailure(logger, exception, "ChannelResolution", YouTubeDiagnostics.ChannelsEndpoint); + + var entry = Assert.Single(logger.Entries); + Assert.Equal(timeout, entry.Fields["IsTimeout"]); + Assert.Null(entry.Exception); + Assert.DoesNotContain("secret", entry.Message); + if (!timeout) + { + Assert.Equal(HttpRequestError.NameResolutionError, entry.Fields["HttpRequestError"]); + Assert.Equal(SocketError.HostNotFound, entry.Fields["SocketError"]); + } + } + + [Fact] + public void UnexpectedFailure_ReportsRealStackFramesWithoutSecretMessages() + { + var exception = Assert.Throws(ThrowUnexpectedFailure); + var logger = new YouTubeRecordingLogger(); + + YouTubeDiagnostics.LogFailure(logger, exception, "BackgroundTick", "local coordination/state"); + + var entry = Assert.Single(logger.Entries); + Assert.Equal(LogLevel.Error, entry.Level); + Assert.Null(entry.Exception); + var stack = Assert.IsType(entry.Fields["SafeStackTrace"]); + Assert.Contains(nameof(ThrowUnexpectedFailure), stack); + Assert.DoesNotContain(".cs:", stack); + Assert.DoesNotContain("api-key-secret", entry.Message); + Assert.DoesNotContain("verify-token-secret", entry.Message); + Assert.DoesNotContain("https://", entry.Message); + Assert.DoesNotContain("Next subscription attempt", entry.Message); + Assert.DoesNotContain("polling", entry.Message); + Assert.Contains("worker will retry on its normal tick schedule", entry.Message); + } + + [MethodImpl(MethodImplOptions.NoInlining)] + private static void ThrowUnexpectedFailure() => + throw new InvalidOperationException("https://provider.example/?key=api-key-secret", + new Exception("verify-token-secret")); + + [Fact] + public async Task SubscriptionUnavailable_OfflineThenLive_DiscoveryHonorsQuotaAndReportsRecovery() + { + var time = new FakeTimeProvider(DateTimeOffset.UnixEpoch); + var searches = 0; + var apiHandler = new RecordingHttpMessageHandler(_ => + LiveTestHelpers.JsonResponse(++searches == 1 + ? """{"items":[]}""" + : """{"items":[{"id":{"videoId":"live-video"}}]}""")); + var hubHandler = new RecordingHttpMessageHandler(_ => new HttpResponseMessage(HttpStatusCode.ServiceUnavailable) + { + Content = new StringContent("Temporarily unavailable"), + }); + var factory = new TestHttpClientFactory(); + factory.AddClient(YouTubeClient.HttpClientName, apiHandler); + factory.AddClient(YouTubeClient.PubSubHttpClientName, hubHandler); + var options = Options(); + var client = new YouTubeClient(factory, options, NullLogger.Instance); + var logger = new YouTubeRecordingLogger(); + using var broadcaster = LiveTestHelpers.CreateBroadcaster(timeProvider: time); + using var service = new YouTubeWebSubService(client, broadcaster, options, logger, time, + new YouTubeWebSubSubscriptionState(time), new SingleInstanceLiveStatusCoordination()); + + await service.TickAsync(CancellationToken.None); + Assert.False(broadcaster.Current.YouTube.Live); + for (var tick = 1; tick < 15; tick++) + { + time.Advance(TimeSpan.FromMinutes(2)); + await service.TickAsync(CancellationToken.None); + Assert.Equal(1, searches); + } + Assert.Equal(4, hubHandler.Requests.Count); + time.Advance(TimeSpan.FromMinutes(2)); + await service.TickAsync(CancellationToken.None); + + Assert.Equal(2, searches); + Assert.Equal(4, hubHandler.Requests.Count); + Assert.True(broadcaster.Current.YouTube.Live); + Assert.Equal("live-video", broadcaster.Current.YouTube.VideoId); + var warnings = logger.Entries.Where(entry => entry.Level == LogLevel.Warning).ToArray(); + Assert.Equal(4, warnings.Length); + Assert.All(warnings, entry => + { + Assert.Equal("WebSubSubscribe", entry.Fields["Operation"]); + Assert.Equal(503, entry.Fields["StatusCode"]); + Assert.True(Assert.IsType(entry.Fields["ElapsedMs"]) >= 0); + Assert.NotNull(entry.Fields["RetryAt"]); + }); + var checks = logger.Entries.Where(entry => entry.Level == LogLevel.Information && + Equals(entry.Fields["Operation"], "OfflineDiscovery")).ToArray(); + Assert.Equal(2, checks.Length); + Assert.Equal(false, checks[0].Fields["LastDiscoveryLive"]); + Assert.Equal(DateTimeOffset.UnixEpoch, checks[0].Fields["LastSuccessfulDiscoveryAt"]); + Assert.Equal(true, checks[1].Fields["LastDiscoveryLive"]); + Assert.Equal(time.GetUtcNow(), checks[1].Fields["LastSuccessfulDiscoveryAt"]); + } + + [Fact] + public async Task DiscoveryFailure_IsNotOffline_AndRetainsLastSuccessfulCheck() + { + var time = new FakeTimeProvider(DateTimeOffset.UnixEpoch); + var calls = 0; + var handler = new RecordingHttpMessageHandler(_ => ++calls != 2 + ? LiveTestHelpers.JsonResponse("""{"items":[]}""") + : new HttpResponseMessage(HttpStatusCode.Forbidden) + { + Content = new StringContent("""{"error":{"errors":[{"reason":"quotaExceeded","domain":"youtube.quota"}]}}"""), + }); + var factory = new TestHttpClientFactory(); + factory.AddClient(YouTubeClient.HttpClientName, handler); + var options = Options(webhookSecret: ""); + var client = new YouTubeClient(factory, options, NullLogger.Instance); + var logger = new YouTubeRecordingLogger(); + using var broadcaster = LiveTestHelpers.CreateBroadcaster(timeProvider: time); + using var service = new YouTubeWebSubService(client, broadcaster, options, logger, time, + new YouTubeWebSubSubscriptionState(time), new SingleInstanceLiveStatusCoordination()); + await service.TickAsync(CancellationToken.None); + time.Advance(TimeSpan.FromMinutes(30)); + + await Assert.ThrowsAsync(() => service.TickAsync(CancellationToken.None)); + await service.TickAsync(CancellationToken.None); + + Assert.Equal(2, calls); + var failure = Assert.Single(logger.Entries, entry => entry.Level == LogLevel.Warning); + Assert.Equal("OfflineDiscovery", failure.Fields["Operation"]); + Assert.Equal("quotaExceeded", failure.Fields["ProviderReason"]); + Assert.Equal(DateTimeOffset.UnixEpoch, failure.Fields["LastSuccessfulDiscoveryAt"]); + Assert.Equal(false, failure.Fields["LastDiscoveryLive"]); + Assert.Single(logger.Entries, entry => entry.Level == LogLevel.Information); + + time.Advance(TimeSpan.FromMinutes(30)); + await service.TickAsync(CancellationToken.None); + Assert.Equal(3, calls); + var recovered = logger.Entries.Last(); + Assert.Equal(LogLevel.Information, recovered.Level); + Assert.Equal(time.GetUtcNow(), recovered.Fields["LastSuccessfulDiscoveryAt"]); + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task ChangedChannelSettings_ClearDiscoveryHistoryBeforeFailedResolution(bool changeConfiguredId) + { + var changed = false; + var searches = 0; + var handler = new RecordingHttpMessageHandler(request => + { + if (changed) return new HttpResponseMessage(HttpStatusCode.ServiceUnavailable); + if (request.RequestUri!.AbsolutePath.EndsWith("/channels", StringComparison.Ordinal)) + return LiveTestHelpers.JsonResponse("""{"items":[{"id":"old-channel"}]}"""); + searches++; + return LiveTestHelpers.JsonResponse("""{"items":[]}"""); + }); + var factory = new TestHttpClientFactory(); + factory.AddClient(YouTubeClient.HttpClientName, handler); + var options = Options(webhookSecret: ""); + options.CurrentValue.YouTube.ChannelId = changeConfiguredId ? "old-channel" : ""; + options.CurrentValue.YouTube.ChannelHandle = "@old-handle"; + var logger = new YouTubeRecordingLogger(); + using var broadcaster = LiveTestHelpers.CreateBroadcaster(); + var time = new FakeTimeProvider(DateTimeOffset.UnixEpoch); + using var service = new YouTubeWebSubService( + new YouTubeClient(factory, options, NullLogger.Instance), + broadcaster, options, logger, time, new YouTubeWebSubSubscriptionState(time), + new SingleInstanceLiveStatusCoordination()); + await service.TickAsync(CancellationToken.None); + var discovery = Assert.Single(logger.Entries, entry => Equals(entry.Fields["Operation"], "OfflineDiscovery")); + Assert.Equal(DateTimeOffset.UnixEpoch, discovery.Fields["LastSuccessfulDiscoveryAt"]); + Assert.Equal(false, discovery.Fields["LastDiscoveryLive"]); + + changed = true; + if (changeConfiguredId) + options.CurrentValue.YouTube.ChannelId = ""; + else + options.CurrentValue.YouTube.ChannelHandle = "@new-handle"; + time.Advance(TimeSpan.FromMinutes(2)); + await Assert.ThrowsAsync(() => service.TickAsync(CancellationToken.None)); + + var failure = Assert.Single(logger.Entries, entry => entry.Level == LogLevel.Warning); + Assert.Equal("ChannelResolution", failure.Fields["Operation"]); + Assert.Null(failure.Fields["LastSuccessfulDiscoveryAt"]); + Assert.Null(failure.Fields["LastDiscoveryLive"]); + Assert.Equal(1, searches); + } + + [Theory] + [InlineData("ChannelResolution", YouTubeDiagnostics.ChannelsEndpoint)] + [InlineData("KnownVideoStatus", YouTubeDiagnostics.VideosEndpoint)] + [InlineData("NotificationChannelResolution", YouTubeDiagnostics.ChannelsEndpoint)] + [InlineData("NotificationConfirmation", YouTubeDiagnostics.SearchEndpoint)] + public async Task FailedChecks_IdentifyOperationAndEndpoint_WithoutChangingState(string operation, string endpoint) + { + var handler = new RecordingHttpMessageHandler(_ => new HttpResponseMessage(HttpStatusCode.Forbidden) + { + Content = new StringContent("""{"error":{"errors":[{"reason":"accessNotConfigured","domain":"usageLimits"}]}}"""), + }); + var factory = new TestHttpClientFactory(); + factory.AddClient(YouTubeClient.HttpClientName, handler); + var options = Options(webhookSecret: ""); + if (operation.EndsWith("ChannelResolution", StringComparison.Ordinal)) + options.CurrentValue.YouTube.ChannelId = ""; + var client = new YouTubeClient(factory, options, NullLogger.Instance); + var logger = new YouTubeRecordingLogger(); + using var broadcaster = LiveTestHelpers.CreateBroadcaster(); + if (operation == "KnownVideoStatus") + broadcaster.Update(new LiveStatusUpdate { YouTube = new YouTubeStatus(true, "video") }); + var before = broadcaster.Current; + using var service = new YouTubeWebSubService(client, broadcaster, options, logger, + new FakeTimeProvider(), new YouTubeWebSubSubscriptionState(), new SingleInstanceLiveStatusCoordination()); + + var exception = await Assert.ThrowsAsync(() => + operation.StartsWith("Notification", StringComparison.Ordinal) + ? LiveStatusEndpointRouteBuilderExtensions.ConfirmYouTubeLiveStatusAsync( + options.CurrentValue.YouTube, client, broadcaster, logger, CancellationToken.None) + : service.TickAsync(CancellationToken.None)); + YouTubeDiagnostics.LogFailure(logger, exception, "BackgroundTick", "local coordination/state", skipIfLogged: true); + + Assert.Equal(before, broadcaster.Current); + Assert.Single(handler.Requests); + var failure = Assert.Single(logger.Entries); + Assert.Equal(operation, failure.Fields["Operation"]); + Assert.Equal(endpoint, failure.Fields["Endpoint"]); + Assert.Equal(403, failure.Fields["StatusCode"]); + Assert.True(Assert.IsType(failure.Fields["ElapsedMs"]) >= 0); + Assert.Equal("accessNotConfigured", failure.Fields["ProviderReason"]); + Assert.Null(failure.Exception); + Assert.False(failure.Fields.ContainsKey("SafeStackTrace")); + Assert.DoesNotContain("Next subscription attempt", failure.Message); + Assert.DoesNotContain("polling", failure.Message); + } + + [Fact] + public async Task SubscriptionAcceptance_DoesNotReportVerifiedLease() + { + var factory = new TestHttpClientFactory(); + factory.AddClient(YouTubeClient.HttpClientName, + new RecordingHttpMessageHandler(_ => LiveTestHelpers.JsonResponse("""{"items":[]}"""))); + factory.AddClient(YouTubeClient.PubSubHttpClientName, + new RecordingHttpMessageHandler(_ => new HttpResponseMessage(HttpStatusCode.Accepted))); + var options = Options(); + var logger = new YouTubeRecordingLogger(); + var time = new FakeTimeProvider(DateTimeOffset.UnixEpoch); + var state = new YouTubeWebSubSubscriptionState(time); + using var broadcaster = LiveTestHelpers.CreateBroadcaster(); + using var service = new YouTubeWebSubService( + new YouTubeClient(factory, options, NullLogger.Instance), + broadcaster, options, logger, time, state, new SingleInstanceLiveStatusCoordination()); + + await service.TickAsync(CancellationToken.None); + + var accepted = Assert.Single(logger.Entries, entry => Equals(entry.Fields["Operation"], "WebSubSubscribe")); + Assert.Equal(LogLevel.Information, accepted.Level); + Assert.Equal(time.GetUtcNow(), accepted.Fields["AcceptedAt"]); + Assert.True(Assert.IsType(accepted.Fields["ElapsedMs"]) >= 0); + Assert.Contains("HTTP acceptance does not establish a verified lease", accepted.Message); + Assert.Equal(DateTimeOffset.MinValue, await state.GetRenewAtAsync()); + } + + private static TestOptionsMonitor Options(string webhookSecret = "secret") => + new(new LiveStatusOptions + { + PublicBaseUrl = "https://example.com", + YouTube = new YouTubeOptions { ApiKey = "api-key", ChannelId = "channel", WebhookSecret = webhookSecret }, + }); + + private sealed class UnreadableStream : MemoryStream + { + public override ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) => + ValueTask.FromException(new IOException("key=secret")); + } +} + +internal sealed class YouTubeRecordingLogger : ILogger +{ + internal sealed record Entry(LogLevel Level, Exception? Exception, string Message, Dictionary Fields); + public List Entries { get; } = []; + public IDisposable? BeginScope(TState state) where TState : notnull => null; + public bool IsEnabled(LogLevel logLevel) => true; + public void Log(LogLevel logLevel, EventId eventId, TState state, + Exception? exception, Func formatter) => + Entries.Add(new(logLevel, exception, formatter(state, exception), + ((IEnumerable>)state!).ToDictionary(pair => pair.Key, pair => pair.Value))); +} diff --git a/tests/StaticHost.Tests/Live/YouTubeWebSubServiceTests.cs b/tests/StaticHost.Tests/Live/YouTubeWebSubServiceTests.cs index 502740134..393a66ec8 100644 --- a/tests/StaticHost.Tests/Live/YouTubeWebSubServiceTests.cs +++ b/tests/StaticHost.Tests/Live/YouTubeWebSubServiceTests.cs @@ -370,14 +370,14 @@ public async Task TickAsync_BacksOffSubscriptionsWithoutStoppingLivePolling(stri if (failureKind == "unexpected") { Assert.Equal(LogLevel.Error, report.Level); - Assert.Same(failure, report.Exception); + Assert.Null(report.Exception); } else { Assert.Equal(LogLevel.Warning, report.Level); Assert.Null(report.Exception); Assert.Contains("Next subscription attempt", report.Message, StringComparison.Ordinal); - Assert.Contains(logger.Entries, entry => entry.Level == LogLevel.Debug && entry.Exception == failure); + Assert.DoesNotContain(logger.Entries, entry => entry.Exception is not null); } time.Advance(TimeSpan.FromMinutes(2)); From b0d47bdd3b39e705064151ad4c4f37dba7990f71 Mon Sep 17 00:00:00 2001 From: David Pine <7679720+IEvangelist@users.noreply.github.com> Date: Wed, 16 Sep 2026 16:20:47 -0500 Subject: [PATCH 2/4] Correct YouTube WebSub callback handling and diagnostics Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../StaticHost/Live/LiveEndpoints.cs | 18 +- src/statichost/StaticHost/Live/README.md | 33 +++- .../Live/YouTube/YouTubeDiagnostics.cs | 48 ++++- .../Live/InMemoryLiveStatusInfrastructure.cs | 14 ++ .../Live/LiveEndpointsTests.cs | 178 ++++++++++++++++-- .../Live/YouTubeDiagnosticsTests.cs | 50 +++++ 6 files changed, 309 insertions(+), 32 deletions(-) diff --git a/src/statichost/StaticHost/Live/LiveEndpoints.cs b/src/statichost/StaticHost/Live/LiveEndpoints.cs index 80da227d0..7d407e50a 100644 --- a/src/statichost/StaticHost/Live/LiveEndpoints.cs +++ b/src/statichost/StaticHost/Live/LiveEndpoints.cs @@ -277,6 +277,7 @@ private static async Task TwitchWebhook( private static async Task YouTubeVerify( HttpContext context, IYouTubeWebSubSubscriptionState subscriptions, + IOptions options, TimeProvider time, ILoggerFactory loggerFactory) { @@ -292,6 +293,19 @@ private static async Task YouTubeVerify( var verifyToken = query["hub.verify_token"].ToString(); var logger = loggerFactory.CreateLogger("StaticHost.Live.YouTube.WebSub"); + if (string.Equals(mode, "denied", StringComparison.Ordinal)) + { + var channelId = options.Value.YouTube.ChannelId; + bool? matchesConfiguredTopic = string.IsNullOrEmpty(channelId) + ? null + : string.Equals(topic, YouTubeWebSubSubscriptionTransitions.TopicFor(channelId), StringComparison.Ordinal); + YouTubeDiagnostics.LogUntrustedDenial( + logger, query["hub.reason"].ToString(), !string.IsNullOrEmpty(topic), matchesConfiguredTopic); + return string.IsNullOrEmpty(topic) + ? Results.BadRequest("Invalid WebSub denial report.") + : Results.Ok(); + } + if (!int.TryParse(query["hub.lease_seconds"], out var leaseSeconds) || string.IsNullOrEmpty(challenge)) { @@ -367,8 +381,8 @@ private static async Task YouTubeWebhook( var signature = context.Request.Headers["X-Hub-Signature"].ToString(); if (!YouTubeWebhookHandler.IsValidSignature(youtube.WebhookSecret, bodyBytes, signature)) { - logger.LogWarning("YouTube WebSub signature mismatch."); - return Results.Unauthorized(); + logger.LogWarning("YouTube WebSub signature missing or invalid; acknowledging and discarding the notification without processing."); + return Results.Ok(); } if (env.IsDevelopment() && options.Value.EnableDevEndpoint && !youtube.IsConfigured) diff --git a/src/statichost/StaticHost/Live/README.md b/src/statichost/StaticHost/Live/README.md index d4f140a30..46fca0de6 100644 --- a/src/statichost/StaticHost/Live/README.md +++ b/src/statichost/StaticHost/Live/README.md @@ -81,6 +81,7 @@ logging HTTP request bodies is not required. | `KnownVideoStatus` | Low-cost `videos.list` check of the currently known live video. | | `WebSubSubscribe` | Subscription POST accepted or failed; acceptance does **not** prove callback verification. | | `WebSubVerification` | A matching callback verified the subscription or renewal, with the granted `LeaseSeconds`. | +| `WebSubDenialReport` | An untrusted, unauthenticated `hub.mode=denied` report; not proof that Google denied a subscription. No state or polling changes. | | `NotificationChannelResolution` / `NotificationConfirmation` | Resolve the channel or run the confirming search after a signed notification. | | `BackgroundTick` | A failure outside the provider calls, such as state coordination. | @@ -101,13 +102,35 @@ failure, not an inbound website 503. Duration and status alone cannot establish the underlying provider cause. `ProviderDetail` contains only a fixed classification, such as temporary -unavailability, invalid topic, or callback verification failure. Unknown or +unavailability, transient error, invalid topic, or callback verification failure. Unknown or malformed bodies are omitted; `BodyTruncated` indicates the diagnostic read exceeded 4,096 characters. No raw HTML, provider message, API key, webhook secret, verification token, authorization header, or subscription form is logged by these diagnostics. Subscription failures also expose `FailureCount` -and `RetryAt`; a hub 503 does not stop polling or prove why a broadcast was -missed. +and `RetryAt`. A valid provider `Retry-After` header is recorded as typed +`RetryAfterSeconds` or `RetryAfterDate`, never as raw header text. These fields +are diagnostic only and do not change the persisted retry schedule. For +example, a 503 with `Transient error; please try again later` and +`Retry-After: 120` reports a transient error and 120 seconds; it does not stop +polling or prove why a broadcast was missed. + +The callback acknowledges notifications with missing, invalid, or mismatched +signatures with HTTP 200, as required by PubSubHubbub authenticated content +distribution, but discards them before parsing, state updates, coordination, +or confirmation queuing. A warning explicitly records the discard. HTTP 200 +does not mean that a notification was authenticated or processed. Development +overrides still require both a valid signature and the dev command secret. + +A denial GET requires `hub.topic`, but not a challenge, lease, or verification +token. The static callback cannot authenticate these reports, so it logs only +topic presence, a nullable comparison with the configured channel's topic, +reason presence/length, and a bounded fixed classification. If only a channel +handle is configured, topic correlation is unavailable. Even a matching topic +does not authenticate the sender. Denials never confirm, revoke, clear, or +otherwise change subscription state, live status, backoff, or polling. +Subscribe verification still requires the matching `hub.verify_token`, +challenge, and valid lease; repeated matching verifications retain the original +renewal deadline. Successful discovery logs `LastSuccessfulDiscoveryAt`, `LastDiscoveryLive`, and `NextDiscoveryAt`. The worker includes its last successful discovery time @@ -383,11 +406,11 @@ dotnet test .\tests\Aspire.Dev.AppHost.Tests\Aspire.Dev.AppHost.Tests.csproj --c dotnet test .\tests\StaticHost.Tests\StaticHost.Tests.csproj --configuration Release --filter "Category!=RedisIntegration" ``` -For the focused YouTube diagnostics and polling regressions, explicitly keep +For the focused YouTube diagnostics, callback authorization, and polling regressions, explicitly keep frontend build scripts and package installation disabled: ```powershell -dotnet test .\tests\StaticHost.Tests\StaticHost.Tests.csproj --configuration Release --filter "FullyQualifiedName~YouTube&Category!=RedisIntegration" -p:ShouldRunBuildScript=false -p:ShouldRunNpmInstall=false +dotnet test .\tests\StaticHost.Tests\StaticHost.Tests.csproj --configuration Release --filter "(FullyQualifiedName~YouTube|FullyQualifiedName~LiveEndpointsTests)&Category!=RedisIntegration" -p:ShouldRunBuildScript=false -p:ShouldRunNpmInstall=false ``` The real-Redis group has the xUnit trait `Category=RedisIntegration` and requires diff --git a/src/statichost/StaticHost/Live/YouTube/YouTubeDiagnostics.cs b/src/statichost/StaticHost/Live/YouTube/YouTubeDiagnostics.cs index 7149c7316..36073c282 100644 --- a/src/statichost/StaticHost/Live/YouTube/YouTubeDiagnostics.cs +++ b/src/statichost/StaticHost/Live/YouTube/YouTubeDiagnostics.cs @@ -16,7 +16,11 @@ internal static class YouTubeDiagnostics private const string LoggedKey = "YouTube.FailureLogged"; private const int BodyLimit = 4096; - private sealed record ResponseDetails(string? Reason, string? Domain, string Detail, bool Truncated); + private sealed record ResponseDetails(string? Reason, string? Domain, string Detail, bool Truncated) + { + public double? RetryAfterSeconds { get; init; } + public DateTimeOffset? RetryAfterDate { get; init; } + } internal static async Task EnsureSuccessAsync( HttpResponseMessage response, CancellationToken cancellationToken, params string[] secrets) @@ -39,6 +43,13 @@ internal static async Task EnsureSuccessAsync( details = new(null, null, "Response body could not be read; body omitted", false); } + var retryAfter = response.Headers.RetryAfter; + details = details with + { + RetryAfterSeconds = retryAfter?.Delta?.TotalSeconds, + RetryAfterDate = retryAfter?.Date, + }; + try { response.EnsureSuccessStatusCode(); @@ -70,16 +81,35 @@ private static ResponseDetails DescribeBody(string body, bool truncated, string[ } catch (JsonException) { } + return new(null, null, ClassifyProviderText(body), truncated); + } + + internal static void LogUntrustedDenial( + ILogger logger, string reason, bool topicPresent, bool? matchesConfiguredTopic) + { + var truncated = reason.Length > BodyLimit; + logger.LogWarning( + "YouTube {Operation}: untrusted, unauthenticated denial report; not proof of a hub decision. " + + "Topic present {TopicPresent}, matches configured topic {MatchesConfiguredTopic}; " + + "reason present {ReasonPresent}, length {ReasonLength}, detail {ProviderDetail}, truncated {BodyTruncated}. " + + "Subscription state and live-status polling are unchanged.", + "WebSubDenialReport", topicPresent, matchesConfiguredTopic, reason.Length > 0, reason.Length, + ClassifyProviderText(truncated ? reason[..BodyLimit] : reason), truncated); + } + + private static string ClassifyProviderText(string text) + { // Only fixed classifications leave this boundary, never echoed HTML, URLs, // callback values or arbitrary provider messages. - var detail = body.Contains("temporarily unavailable", StringComparison.OrdinalIgnoreCase) + return text.Contains("temporarily unavailable", StringComparison.OrdinalIgnoreCase) ? "Provider reports temporary unavailability" - : body.Contains("invalid topic", StringComparison.OrdinalIgnoreCase) - ? "Provider reports an invalid topic" - : body.Contains("verification failed", StringComparison.OrdinalIgnoreCase) - ? "Provider reports callback verification failure" - : "Unrecognized provider response; body omitted"; - return new(null, null, detail, truncated); + : text.Contains("transient error", StringComparison.OrdinalIgnoreCase) + ? "Provider reports a transient error" + : text.Contains("invalid topic", StringComparison.OrdinalIgnoreCase) + ? "Provider reports an invalid topic" + : text.Contains("verification failed", StringComparison.OrdinalIgnoreCase) + ? "Provider reports callback verification failure" + : "Unrecognized provider response; body omitted"; } private static string? ReadCode(JsonElement error, string name, string[] secrets) @@ -121,6 +151,7 @@ internal static void LogFailure( var message = "YouTube {Operation} failed at {Endpoint} after {ElapsedMs} ms: {FailureType}, HTTP {StatusCode} {StatusReason}; " + "provider reason {ProviderReason}, domain {ProviderDomain}, detail {ProviderDetail}, truncated {BodyTruncated}; " + + "provider Retry-After seconds {RetryAfterSeconds}, date {RetryAfterDate}; " + "timeout {IsTimeout}, network {HttpRequestError}, socket {SocketError}, inner failure {InnerFailureType}. " + "Last successful discovery {LastSuccessfulDiscoveryAt}, live {LastDiscoveryLive}. Failure is not an offline observation."; List fields = @@ -128,6 +159,7 @@ internal static void LogFailure( operation, endpoint, elapsedMs, exception.GetType().Name, status, status is { } number ? ReasonPhrases.GetReasonPhrase(number) : null, details?.Reason, details?.Domain, details?.Detail, details?.Truncated, + details?.RetryAfterSeconds, details?.RetryAfterDate, timeout, http?.HttpRequestError, socket?.SocketErrorCode, exception.InnerException?.GetType().Name, lastSuccessfulDiscoveryAt, lastDiscoveryLive, ]; diff --git a/tests/StaticHost.Tests/Live/InMemoryLiveStatusInfrastructure.cs b/tests/StaticHost.Tests/Live/InMemoryLiveStatusInfrastructure.cs index 6a4959fc6..8dbc0c4ed 100644 --- a/tests/StaticHost.Tests/Live/InMemoryLiveStatusInfrastructure.cs +++ b/tests/StaticHost.Tests/Live/InMemoryLiveStatusInfrastructure.cs @@ -37,6 +37,8 @@ public ValueTask UpdateAsync( internal sealed class SingleInstanceLiveStatusCoordination : ILiveStatusCoordination { + public int YouTubeConfirmationRequests { get; private set; } + private const string CompletedMessage = "completed"; private readonly ConcurrentDictionary _twitchMessageIds = @@ -70,6 +72,7 @@ public ValueTask TryQueueYouTubeConfirmationAsync( CancellationToken cancellationToken = default) { cancellationToken.ThrowIfCancellationRequested(); + YouTubeConfirmationRequests++; return ValueTask.FromResult(true); } @@ -117,6 +120,17 @@ internal sealed class YouTubeWebSubSubscriptionState(TimeProvider? timeProvider private readonly Lock _gate = new(); private YouTubeWebSubSubscriptionData _state = YouTubeWebSubSubscriptionData.Empty; + public YouTubeWebSubSubscriptionData Current + { + get + { + lock (_gate) + { + return _state; + } + } + } + public ValueTask TryBeginSubscriptionAsync( string channelId, DateTimeOffset now, diff --git a/tests/StaticHost.Tests/Live/LiveEndpointsTests.cs b/tests/StaticHost.Tests/Live/LiveEndpointsTests.cs index aecc63861..e6edbed22 100644 --- a/tests/StaticHost.Tests/Live/LiveEndpointsTests.cs +++ b/tests/StaticHost.Tests/Live/LiveEndpointsTests.cs @@ -3,6 +3,7 @@ using Microsoft.AspNetCore.Hosting; using Microsoft.AspNetCore.TestHost; using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; namespace StaticHost.Tests.Live; @@ -201,25 +202,150 @@ public async Task YouTubeVerification_RejectsMalformedOrUnsolicitedConfirmation( } [Theory] - [InlineData(true, HttpStatusCode.OK)] - [InlineData(false, HttpStatusCode.Unauthorized)] - public async Task YouTubeWebhook_ValidatesSignatureBeforeQueuing(bool valid, HttpStatusCode expected) + [InlineData("valid")] + [InlineData("invalid")] + [InlineData("missing")] + [InlineData("tampered")] + public async Task YouTubeWebhook_AcknowledgesButOnlyQueuesValidSignatures(string signature) { await using var server = await LiveHttpServer.StartAsync(); - const string body = "video-123"; - using var request = new HttpRequestMessage(HttpMethod.Post, "/api/live/youtube/webhook") + await server.Broadcaster.UpdateAsync(new LiveStatusUpdate { - Content = new StringContent(body, Encoding.UTF8, "application/atom+xml"), - }; - request.Headers.Add("X-Hub-Signature", valid - ? "sha1=" + Convert.ToHexStringLower(HMACSHA1.HashData( - Encoding.UTF8.GetBytes(LiveHttpServer.WebhookSecret), Encoding.UTF8.GetBytes(body))) - : "sha1=invalid"); + YouTube = new YouTubeStatus(true, "existing-video"), + }); + var before = await server.Broadcaster.GetStateAsync(); + using var request = YouTubeRequest(signature); + using var response = await server.Client.SendAsync(request); + + Assert.Equal(HttpStatusCode.OK, response.StatusCode); + AssertNoStore(response); + Assert.Equal(before, await server.Broadcaster.GetStateAsync()); + Assert.Equal(signature == "valid" ? 1 : 0, server.Coordination.YouTubeConfirmationRequests); + if (signature != "valid") + { + var warning = Assert.Single(server.Logs.Entries); + Assert.Equal(LogLevel.Warning, warning.Level); + Assert.Contains("acknowledging and discarding", warning.Message); + } + } + + [Theory] + [InlineData("valid", false, HttpStatusCode.Unauthorized, false)] + [InlineData("valid", true, HttpStatusCode.OK, true)] + [InlineData("missing", true, HttpStatusCode.OK, false)] + [InlineData("tampered", true, HttpStatusCode.OK, false)] + public async Task YouTubeWebhook_DevOverrideStillRequiresSignatureAndCommandSecret( + string signature, bool correctSecret, HttpStatusCode expected, bool live) + { + await using var server = await LiveHttpServer.StartAsync(Environments.Development, youtubeConfigured: false); + using var request = YouTubeRequest(signature); + request.Headers.Add("X-Aspire-Live-Dev-Command-Key", + correctSecret ? "Key: local-test-command" : "Key: wrong-key"); using var response = await server.Client.SendAsync(request); Assert.Equal(expected, response.StatusCode); + Assert.Equal(live, (await server.Broadcaster.GetCurrentAsync()).YouTube.Live); + Assert.Equal(0, server.Coordination.YouTubeConfirmationRequests); + } + + [Theory] + [InlineData("pending")] + [InlineData("confirmed")] + [InlineData("backoff")] + public async Task YouTubeDenial_WithoutChallengeOrLease_DoesNotMutateState(string subscriptionState) + { + await using var server = await LiveHttpServer.StartAsync(); + var pending = Assert.IsType( + await server.Subscriptions.TryBeginSubscriptionAsync("channel-123", server.Time.GetUtcNow())); + if (subscriptionState == "confirmed") + { + using var confirmation = await server.Client.GetAsync(VerificationUrl(pending, "challenge")); + Assert.Equal(HttpStatusCode.OK, confirmation.StatusCode); + } + else if (subscriptionState == "backoff") + { + await server.Subscriptions.MarkRequestFailedAsync(pending); + } + await server.Broadcaster.UpdateAsync(new LiveStatusUpdate { YouTube = new YouTubeStatus(true, "existing-video") }); + var beforeLive = await server.Broadcaster.GetStateAsync(); + var beforeSubscription = server.Subscriptions.Current; + server.Logs.Entries.Clear(); + + using var response = await server.Client.GetAsync( + $"/api/live/youtube/webhook?hub.mode=denied&hub.topic={Uri.EscapeDataString(pending.Topic)}" + + "&hub.reason=Transient%20error%3B%20please%20try%20again%20later"); + + Assert.Equal(HttpStatusCode.OK, response.StatusCode); AssertNoStore(response); + Assert.Equal(beforeSubscription, server.Subscriptions.Current); + Assert.Equal(beforeLive, await server.Broadcaster.GetStateAsync()); + Assert.Equal(0, server.Coordination.YouTubeConfirmationRequests); + var entry = Assert.Single(server.Logs.Entries); + Assert.Equal(LogLevel.Warning, entry.Level); + Assert.Equal("WebSubDenialReport", entry.Fields["Operation"]); + Assert.Equal(true, entry.Fields["MatchesConfiguredTopic"]); + Assert.Equal("Provider reports a transient error", entry.Fields["ProviderDetail"]); + Assert.Contains("untrusted, unauthenticated", entry.Message); + Assert.DoesNotContain(pending.Topic, entry.Message); + if (subscriptionState == "pending") + { + using var confirmation = await server.Client.GetAsync(VerificationUrl(pending, "still-pending")); + Assert.Equal(HttpStatusCode.OK, confirmation.StatusCode); + } + } + + [Theory] + [InlineData(null, true, false)] + [InlineData("unknown", true, false)] + [InlineData("oversized", true, false)] + [InlineData("unknown", false, false)] + [InlineData("unknown", true, true)] + public async Task YouTubeDenial_UntrustedInputIsBoundedAndNotLogged( + string? reason, bool topicPresent, bool configured) + { + await using var server = await LiveHttpServer.StartAsync(youtubeConfigured: configured); + const string sensitive = "https://attacker.invalid/?secret=test-webhook-secret&token=private-token\r\nforged-log"; + reason = reason is null ? null : reason == "oversized" ? new string('x', 5000) + sensitive : sensitive; + var url = "/api/live/youtube/webhook?hub.mode=denied"; + if (topicPresent) url += "&hub.topic=" + Uri.EscapeDataString(sensitive); + if (reason is not null) url += "&hub.reason=" + Uri.EscapeDataString(reason); + url += "&hub.verify_token=private-token&hub.challenge=private-challenge"; + var before = server.Subscriptions.Current; + + using var response = await server.Client.GetAsync(url); + + Assert.Equal(topicPresent ? HttpStatusCode.OK : HttpStatusCode.BadRequest, response.StatusCode); + Assert.Equal(before, server.Subscriptions.Current); Assert.False((await server.Broadcaster.GetCurrentAsync()).IsLive); + Assert.Equal(0, server.Coordination.YouTubeConfirmationRequests); + var entry = Assert.Single(server.Logs.Entries); + Assert.Equal(topicPresent, entry.Fields["TopicPresent"]); + Assert.Equal(configured ? (bool?)false : null, entry.Fields["MatchesConfiguredTopic"]); + Assert.Equal(reason is not null, entry.Fields["ReasonPresent"]); + Assert.Equal(reason?.Length ?? 0, entry.Fields["ReasonLength"]); + Assert.Equal(reason?.Length > 4096, entry.Fields["BodyTruncated"]); + Assert.Equal("Unrecognized provider response; body omitted", entry.Fields["ProviderDetail"]); + Assert.DoesNotContain("attacker", entry.Message); + Assert.DoesNotContain("private-", entry.Message); + Assert.DoesNotContain(LiveHttpServer.WebhookSecret, entry.Message); + Assert.DoesNotContain("forged-log", entry.Message); + Assert.True(entry.Message.Length < 700); + } + + private static HttpRequestMessage YouTubeRequest(string signature) + { + const string body = "video-123"; + var request = new HttpRequestMessage(HttpMethod.Post, "/api/live/youtube/webhook") + { + Content = new StringContent(signature == "tampered" ? body + " " : body, Encoding.UTF8, "application/atom+xml"), + }; + if (signature != "missing") + { + request.Headers.Add("X-Hub-Signature", signature == "invalid" ? "sha1=invalid" : + "sha1=" + Convert.ToHexStringLower(HMACSHA1.HashData( + Encoding.UTF8.GetBytes(LiveHttpServer.WebhookSecret), Encoding.UTF8.GetBytes(body)))); + } + return request; } private static void AssertNoStore(HttpResponseMessage response) => @@ -265,24 +391,29 @@ private static string VerificationUrl( private sealed class LiveHttpServer( WebApplication app, HttpClient client, FakeTimeProvider time, - TaskCompletionSource streamEnded) : IAsyncDisposable + TaskCompletionSource streamEnded, YouTubeRecordingLogger logs) : IAsyncDisposable { public const string WebhookSecret = "test-webhook-secret"; public HttpClient Client { get; } = client; public FakeTimeProvider Time { get; } = time; public TaskCompletionSource StreamEnded { get; } = streamEnded; public LiveStatusBroadcaster Broadcaster => app.Services.GetRequiredService(); - public IYouTubeWebSubSubscriptionState Subscriptions => - app.Services.GetRequiredService(); + public YouTubeRecordingLogger Logs { get; } = logs; + public SingleInstanceLiveStatusCoordination Coordination => + (SingleInstanceLiveStatusCoordination)app.Services.GetRequiredService(); + public YouTubeWebSubSubscriptionState Subscriptions => + (YouTubeWebSubSubscriptionState)app.Services.GetRequiredService(); public static async Task StartAsync( - string environment = "Production", bool enableDev = true) + string environment = "Production", bool enableDev = true, bool youtubeConfigured = true) { var builder = WebApplication.CreateBuilder(new WebApplicationOptions { EnvironmentName = environment, }); builder.WebHost.UseTestServer(); + var logs = new YouTubeRecordingLogger(); + builder.Logging.AddProvider(new YouTubeLoggerProvider(logs)); var time = new FakeTimeProvider(DateTimeOffset.UnixEpoch); var options = new LiveStatusOptions { @@ -290,7 +421,12 @@ public static async Task StartAsync( DevCommandSecret = "local-test-command", CoalesceWindowMs = 0, Twitch = new TwitchOptions { WebhookSecret = WebhookSecret }, - YouTube = new YouTubeOptions { WebhookSecret = WebhookSecret, ApiKey = "unused-test-key" }, + YouTube = new YouTubeOptions + { + WebhookSecret = WebhookSecret, + ApiKey = youtubeConfigured ? "unused-test-key" : "", + ChannelId = youtubeConfigured ? "channel-123" : "", + }, }; builder.Services.AddSingleton(time); builder.Services.AddSingleton>(Options.Create(options)); @@ -319,7 +455,15 @@ public static async Task StartAsync( }); app.MapLiveStatus(); await app.StartAsync(); - return new LiveHttpServer(app, app.GetTestClient(), time, streamEnded); + return new LiveHttpServer(app, app.GetTestClient(), time, streamEnded, logs); + } + + private sealed class YouTubeLoggerProvider(ILogger logger) : ILoggerProvider + { + public ILogger CreateLogger(string categoryName) => + categoryName.StartsWith("StaticHost.Live.YouTube.", StringComparison.Ordinal) + ? logger : NullLogger.Instance; + public void Dispose() { } } public async ValueTask DisposeAsync() diff --git a/tests/StaticHost.Tests/Live/YouTubeDiagnosticsTests.cs b/tests/StaticHost.Tests/Live/YouTubeDiagnosticsTests.cs index a56acabec..e78beb7af 100644 --- a/tests/StaticHost.Tests/Live/YouTubeDiagnosticsTests.cs +++ b/tests/StaticHost.Tests/Live/YouTubeDiagnosticsTests.cs @@ -13,6 +13,7 @@ public sealed class YouTubeDiagnosticsTests [InlineData("""{"error":[]}""", null, null, false)] [InlineData("""{"error":""", null, null, false)] [InlineData("Temporarily unavailable api-key secret verify-token", null, null, false)] + [InlineData("Transient error; please try again later api-key secret verify-token", null, null, false)] [InlineData("oversized", null, null, true)] public async Task HttpFailure_ReportsOnlyBoundedSafeDiagnostics( string body, string? reason, string? domain, bool truncated) @@ -46,6 +47,53 @@ public async Task HttpFailure_ReportsOnlyBoundedSafeDiagnostics( Assert.True(entry.Message.Length < 1000); if (body.StartsWith("", StringComparison.Ordinal)) Assert.Equal("Provider reports temporary unavailability", entry.Fields["ProviderDetail"]); + if (body.StartsWith("Transient error", StringComparison.Ordinal)) + Assert.Equal("Provider reports a transient error", entry.Fields["ProviderDetail"]); + } + + [Theory] + [InlineData(null, null, null)] + [InlineData("120", 120d, null)] + [InlineData("Wed, 16 Sep 2026 21:00:00 GMT", null, "2026-09-16T21:00:00Z")] + [InlineData("api-key secret verify-token", null, null)] + [InlineData("-120", null, null)] + [InlineData("oversized", null, null)] + public async Task HttpFailure_ReportsTypedRetryAfterWithoutRawHeaders( + string? header, double? seconds, string? date) + { + using var response = new HttpResponseMessage(HttpStatusCode.ServiceUnavailable) + { + Content = new StringContent("Transient error; please try again later"), + }; + if (header == "oversized") header = new string('9', 5000) + "api-key secret verify-token"; + if (header is not null) response.Headers.TryAddWithoutValidation("Retry-After", header); + var exception = await Assert.ThrowsAsync(() => + YouTubeDiagnostics.EnsureSuccessAsync(response, CancellationToken.None, "api-key", "secret", "verify-token")); + var logger = new YouTubeRecordingLogger(); + + YouTubeDiagnostics.LogFailure(logger, exception, "WebSubSubscribe", YouTubeDiagnostics.SubscribeEndpoint); + + var entry = Assert.Single(logger.Entries); + Assert.Equal(seconds, entry.Fields["RetryAfterSeconds"]); + Assert.Equal(date is null ? (DateTimeOffset?)null : DateTimeOffset.Parse(date), entry.Fields["RetryAfterDate"]); + Assert.Equal("Provider reports a transient error", entry.Fields["ProviderDetail"]); + Assert.DoesNotContain("api-key", entry.Message); + Assert.DoesNotContain("secret", entry.Message); + Assert.DoesNotContain("verify-token", entry.Message); + Assert.True(entry.Message.Length < 1000); + } + + [Fact] + public void DenialClassification_DoesNotReadBeyondDiagnosticLimit() + { + var logger = new YouTubeRecordingLogger(); + + YouTubeDiagnostics.LogUntrustedDenial( + logger, new string('x', 4096) + "Transient error", topicPresent: true, matchesConfiguredTopic: null); + + var entry = Assert.Single(logger.Entries); + Assert.Equal(true, entry.Fields["BodyTruncated"]); + Assert.Equal("Unrecognized provider response; body omitted", entry.Fields["ProviderDetail"]); } [Fact] @@ -55,6 +103,7 @@ public async Task UnreadableBody_DoesNotMaskHttpFailure() { Content = new StreamContent(new UnreadableStream()), }; + response.Headers.RetryAfter = new System.Net.Http.Headers.RetryConditionHeaderValue(TimeSpan.FromSeconds(120)); var exception = await Assert.ThrowsAsync(() => YouTubeDiagnostics.EnsureSuccessAsync(response, CancellationToken.None)); var logger = new YouTubeRecordingLogger(); @@ -62,6 +111,7 @@ public async Task UnreadableBody_DoesNotMaskHttpFailure() Assert.Equal(HttpStatusCode.BadGateway, exception.StatusCode); Assert.Equal("Response body could not be read; body omitted", Assert.Single(logger.Entries).Fields["ProviderDetail"]); + Assert.Equal(120d, Assert.Single(logger.Entries).Fields["RetryAfterSeconds"]); } [Theory] From a323d6d919b56bde521d90c1c79c0a355b0a37aa Mon Sep 17 00:00:00 2001 From: David Pine <7679720+IEvangelist@users.noreply.github.com> Date: Wed, 16 Sep 2026 16:36:35 -0500 Subject: [PATCH 3/4] Correct YouTube quota bucket guidance Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../StaticHost/Live/LiveStatusOptions.cs | 6 +-- src/statichost/StaticHost/Live/README.md | 38 ++++++++++++++----- 2 files changed, 31 insertions(+), 13 deletions(-) diff --git a/src/statichost/StaticHost/Live/LiveStatusOptions.cs b/src/statichost/StaticHost/Live/LiveStatusOptions.cs index 381ffe530..adb9868f1 100644 --- a/src/statichost/StaticHost/Live/LiveStatusOptions.cs +++ b/src/statichost/StaticHost/Live/LiveStatusOptions.cs @@ -109,9 +109,9 @@ public sealed class YouTubeOptions public int PollingIntervalSeconds { get; set; } = 120; /// - /// How often to run the quota-expensive search.list discovery request - /// while offline. Defaults to 30 minutes, which stays below the standard - /// YouTube Data API daily quota. + /// How often to run search.list discovery while offline. + /// Defaults to 30 minutes; this limits scheduled searches, but does not + /// enforce the project's daily Search Queries quota across all callers. /// [Range(30 * 60, 24 * 60 * 60)] public int DiscoveryPollingIntervalSeconds { get; set; } = 30 * 60; diff --git a/src/statichost/StaticHost/Live/README.md b/src/statichost/StaticHost/Live/README.md index 46fca0de6..e3c24c4d7 100644 --- a/src/statichost/StaticHost/Live/README.md +++ b/src/statichost/StaticHost/Live/README.md @@ -77,7 +77,7 @@ logging HTTP request bodies is not required. | `Operation` | Meaning | | --- | --- | | `ChannelResolution` | Resolve the configured handle through `channels.list`. A missing channel means detection is unavailable, not offline. | -| `OfflineDiscovery` | Quota-limited `search.list` check for a broadcast while no live video is known. | +| `OfflineDiscovery` | Interval-limited `search.list` check for a broadcast while no live video is known; not a daily quota guard. | | `KnownVideoStatus` | Low-cost `videos.list` check of the currently known live video. | | `WebSubSubscribe` | Subscription POST accepted or failed; acceptance does **not** prove callback verification. | | `WebSubVerification` | A matching callback verified the subscription or renewal, with the granted `LeaseSeconds`. | @@ -148,15 +148,33 @@ does not bypass the configured two-check confirmation rule. Without a useful notification, a new broadcast may take up to the configured 30-minute discovery interval (plus request/tick delays) to be detected. -Failures can extend that delay. `search.list` costs 100 quota units: the -default idle schedule makes at most 48 scheduled searches per day (4,800 -units) for a continuously running leader. Known-video checks cost one unit -every two minutes (up to 720 per day while continuously live). Channel -resolution, notification confirmation searches, request retries, and -restarts/leader changes can add usage; the usual 10,000-unit daily project -budget is shared with other callers. These logging changes do not alter -polling intervals, retry policies, leader coordination, or quota usage, and -do not fix the upstream subscription failure. +Failures can extend that delay. Google's current +[quota guide](https://developers.google.com/youtube/v3/determine_quota_cost) and +[`search.list` reference](https://developers.google.com/youtube/v3/docs/search/list) +describe a separate Search Queries bucket: one unit per search call, with a +default limit of 100 calls per day. Other endpoints used here (`channels.list` +and `videos.list`) each cost one unit in the general bucket, whose default daily +allocation is 10,000 units. Actual project limits and usage must be checked in +Google Cloud; daily quotas reset at midnight Pacific Time. + +The default idle schedule permits approximately 48 scheduled searches per +24 hours for a continuously running leader before retries. Known-video checks +can make 720 calls per 24 hours while continuously live. A Pacific calendar day +can be 23 or 25 hours at daylight-saving transitions. + +These intervals are **not project-wide daily quota enforcement**. Notification +confirmation searches use a separate Redis gate that admits a confirmation +every 30 seconds, not the discovery interval. Data API resilience retries, +restarts/leader changes (the next discovery timestamp is process-local), and +other clients sharing the Google Cloud project can add usage. A budget must +account for each outbound attempt across these paths and all replicas, not just +successful worker ticks. The current implementation does not maintain such a +shared daily budget. + +The WebSub subscription POST does not use a Data API key. Its Retry-After and +subscription backoff are separate from Data API quota accounting; the observed +hub 503 does not establish quota exhaustion. These diagnostic changes do not +alter polling intervals, retry policies, or leader coordination. ## Configuration From d53eae0b71f8d88dbd16beb4463074a334c03902 Mon Sep 17 00:00:00 2001 From: David Pine <7679720+IEvangelist@users.noreply.github.com> Date: Thu, 17 Sep 2026 08:46:04 -0500 Subject: [PATCH 4/4] Address YouTube diagnostic review feedback Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../StaticHost/Live/LiveEndpoints.cs | 2 +- .../LiveStatusServiceCollectionExtensions.cs | 9 ++- src/statichost/StaticHost/Live/README.md | 15 ++++- .../StaticHost/Live/YouTube/YouTubeClient.cs | 2 + .../Live/YouTube/YouTubeWebSubService.cs | 8 +-- .../Live/InMemoryLiveStatusInfrastructure.cs | 5 ++ .../Live/YouTubeClientTests.cs | 55 +++++++++++++++++++ .../Live/YouTubeDiagnosticsTests.cs | 21 +++++-- 8 files changed, 104 insertions(+), 13 deletions(-) diff --git a/src/statichost/StaticHost/Live/LiveEndpoints.cs b/src/statichost/StaticHost/Live/LiveEndpoints.cs index 7d407e50a..23f815f3e 100644 --- a/src/statichost/StaticHost/Live/LiveEndpoints.cs +++ b/src/statichost/StaticHost/Live/LiveEndpoints.cs @@ -350,7 +350,7 @@ private static async Task YouTubeVerify( } logger.LogInformation( - "YouTube {Operation} verified; granted lease {LeaseSeconds}s. Verification establishes or renews the lease and resets subscription backoff.", + "YouTube {Operation} acknowledged; callback lease {LeaseSeconds}s. A matching retry does not extend the lease or reset subscription backoff.", "WebSubVerification", leaseSeconds); return Results.Text(challenge, "text/plain"); } diff --git a/src/statichost/StaticHost/Live/LiveStatusServiceCollectionExtensions.cs b/src/statichost/StaticHost/Live/LiveStatusServiceCollectionExtensions.cs index cbfb9fc95..751f5345c 100644 --- a/src/statichost/StaticHost/Live/LiveStatusServiceCollectionExtensions.cs +++ b/src/statichost/StaticHost/Live/LiveStatusServiceCollectionExtensions.cs @@ -47,11 +47,16 @@ public static TBuilder AddLiveStatus(this TBuilder builder) .AddStandardResilienceHandler(); builder.Services.AddHttpClient(TwitchAppTokenProvider.HttpClientName) .AddStandardResilienceHandler(); - builder.Services.AddHttpClient(YouTubeClient.HttpClientName) + builder.Services.AddHttpClient(YouTubeClient.HttpClientName, + client => client.MaxResponseContentBufferSize = YouTubeClient.ResponseBufferLimit) .AddStandardResilienceHandler(); // Subscription POST retries are scheduled in Redis, not inside the HTTP request. builder.Services.AddHttpClient(YouTubeClient.PubSubHttpClientName, - client => client.Timeout = TimeSpan.FromSeconds(30)); + client => + { + client.Timeout = TimeSpan.FromSeconds(30); + client.MaxResponseContentBufferSize = YouTubeClient.ResponseBufferLimit; + }); builder.Services.AddSingleton(); builder.Services.AddSingleton(); diff --git a/src/statichost/StaticHost/Live/README.md b/src/statichost/StaticHost/Live/README.md index e3c24c4d7..2544d8127 100644 --- a/src/statichost/StaticHost/Live/README.md +++ b/src/statichost/StaticHost/Live/README.md @@ -80,7 +80,7 @@ logging HTTP request bodies is not required. | `OfflineDiscovery` | Interval-limited `search.list` check for a broadcast while no live video is known; not a daily quota guard. | | `KnownVideoStatus` | Low-cost `videos.list` check of the currently known live video. | | `WebSubSubscribe` | Subscription POST accepted or failed; acceptance does **not** prove callback verification. | -| `WebSubVerification` | A matching callback verified the subscription or renewal, with the granted `LeaseSeconds`. | +| `WebSubVerification` | A matching callback was acknowledged, with its `LeaseSeconds`; matching retries do not extend the original lease or reset backoff. | | `WebSubDenialReport` | An untrusted, unauthenticated `hub.mode=denied` report; not proof that Google denied a subscription. No state or polling changes. | | `NotificationChannelResolution` / `NotificationConfirmation` | Resolve the channel or run the confirming search after a signed notification. | | `BackgroundTick` | A failure outside the provider calls, such as state coordination. | @@ -101,6 +101,9 @@ For example, `WebSubSubscribe` with endpoint failure, not an inbound website 503. Duration and status alone cannot establish the underlying provider cause. +HTTP acceptance is logged before recording the sent request in Redis, so a +subsequent persistence failure does not hide the provider's successful response. + `ProviderDetail` contains only a fixed classification, such as temporary unavailability, transient error, invalid topic, or callback verification failure. Unknown or malformed bodies are omitted; `BodyTruncated` indicates the diagnostic read @@ -114,12 +117,20 @@ example, a 503 with `Transient error; please try again later` and `Retry-After: 120` reports a transient error and 120 seconds; it does not stop polling or prove why a broadcast was missed. -The callback acknowledges notifications with missing, invalid, or mismatched +Both named YouTube HTTP clients cap response buffering at 1 MiB, including +responses without a Content-Length header. The existing request timeouts still +cover buffering. Responses exceeding that limit fail before diagnostic body +classification; they are logged as request failures, not offline observations. +The 4,096-character classification limit applies within that response-size cap. + +When `WebhookSecret` is configured, the callback acknowledges notifications with missing, invalid, or mismatched signatures with HTTP 200, as required by PubSubHubbub authenticated content distribution, but discards them before parsing, state updates, coordination, or confirmation queuing. A warning explicitly records the discard. HTTP 200 does not mean that a notification was authenticated or processed. Development overrides still require both a valid signature and the dev command secret. +If `WebhookSecret` is empty, the callback instead returns HTTP 503 before +signature validation and logs the missing configuration. A denial GET requires `hub.topic`, but not a challenge, lease, or verification token. The static callback cannot authenticate these reports, so it logs only diff --git a/src/statichost/StaticHost/Live/YouTube/YouTubeClient.cs b/src/statichost/StaticHost/Live/YouTube/YouTubeClient.cs index ba8fc2420..153ee6036 100644 --- a/src/statichost/StaticHost/Live/YouTube/YouTubeClient.cs +++ b/src/statichost/StaticHost/Live/YouTube/YouTubeClient.cs @@ -11,6 +11,8 @@ public sealed class YouTubeClient( IOptionsMonitor options, ILogger logger) : IYouTubeClient { + internal const int ResponseBufferLimit = 1024 * 1024; + /// Name of the registered for the Data API. public const string HttpClientName = "youtube"; diff --git a/src/statichost/StaticHost/Live/YouTube/YouTubeWebSubService.cs b/src/statichost/StaticHost/Live/YouTube/YouTubeWebSubService.cs index fc2b8a06f..cdab0af43 100644 --- a/src/statichost/StaticHost/Live/YouTube/YouTubeWebSubService.cs +++ b/src/statichost/StaticHost/Live/YouTube/YouTubeWebSubService.cs @@ -168,14 +168,14 @@ await client.SubscribeAsync( if (requestSent) { var elapsedMs = Stopwatch.GetElapsedTime(started).TotalMilliseconds; - await _subscriptions.MarkRequestSentAsync( - request, - _time.GetUtcNow(), - cancellationToken).ConfigureAwait(false); logger.LogInformation( "YouTube {Operation} accepted at {AcceptedAt} after {ElapsedMs} ms; HTTP acceptance does not establish a verified lease. " + "Only a matching verification callback establishes or renews the subscription.", "WebSubSubscribe", _time.GetUtcNow(), elapsedMs); + await _subscriptions.MarkRequestSentAsync( + request, + _time.GetUtcNow(), + cancellationToken).ConfigureAwait(false); } } diff --git a/tests/StaticHost.Tests/Live/InMemoryLiveStatusInfrastructure.cs b/tests/StaticHost.Tests/Live/InMemoryLiveStatusInfrastructure.cs index 8dbc0c4ed..02176ba5b 100644 --- a/tests/StaticHost.Tests/Live/InMemoryLiveStatusInfrastructure.cs +++ b/tests/StaticHost.Tests/Live/InMemoryLiveStatusInfrastructure.cs @@ -117,6 +117,7 @@ public ValueTask DisposeAsync() internal sealed class YouTubeWebSubSubscriptionState(TimeProvider? timeProvider = null) : IYouTubeWebSubSubscriptionState { + public Exception? MarkRequestSentException { get; set; } private readonly Lock _gate = new(); private YouTubeWebSubSubscriptionData _state = YouTubeWebSubSubscriptionData.Empty; @@ -170,6 +171,10 @@ public ValueTask MarkRequestSentAsync( CancellationToken cancellationToken = default) { cancellationToken.ThrowIfCancellationRequested(); + if (MarkRequestSentException is { } exception) + { + return ValueTask.FromException(exception); + } lock (_gate) { diff --git a/tests/StaticHost.Tests/Live/YouTubeClientTests.cs b/tests/StaticHost.Tests/Live/YouTubeClientTests.cs index 7ecc32120..f574d1a72 100644 --- a/tests/StaticHost.Tests/Live/YouTubeClientTests.cs +++ b/tests/StaticHost.Tests/Live/YouTubeClientTests.cs @@ -142,6 +142,61 @@ public async Task PubSubHttpClient_HasBoundedTimeoutAndDoesNotRetryPosts() Assert.Single(handler.Requests); } + [Theory] + [InlineData(YouTubeClient.HttpClientName, HttpStatusCode.OK, true)] + [InlineData(YouTubeClient.HttpClientName, HttpStatusCode.OK, false)] + [InlineData(YouTubeClient.HttpClientName, HttpStatusCode.BadRequest, true)] + [InlineData(YouTubeClient.HttpClientName, HttpStatusCode.BadRequest, false)] + [InlineData(YouTubeClient.PubSubHttpClientName, HttpStatusCode.OK, true)] + [InlineData(YouTubeClient.PubSubHttpClientName, HttpStatusCode.OK, false)] + [InlineData(YouTubeClient.PubSubHttpClientName, HttpStatusCode.BadRequest, true)] + [InlineData(YouTubeClient.PubSubHttpClientName, HttpStatusCode.BadRequest, false)] + public async Task NamedYouTubeClients_BoundResponseBuffering( + string clientName, HttpStatusCode status, bool hasContentLength) + { + var builder = Host.CreateApplicationBuilder(); + builder.AddLiveStatus(); + using var content = new OversizedContent(hasContentLength); + var handler = new RecordingHttpMessageHandler(_ => new HttpResponseMessage(status) { Content = content }); + builder.Services.AddHttpClient(clientName).ConfigurePrimaryHttpMessageHandler(() => handler); + using var host = builder.Build(); + using var client = host.Services.GetRequiredService().CreateClient(clientName); + using var request = new HttpRequestMessage( + clientName == YouTubeClient.PubSubHttpClientName ? HttpMethod.Post : HttpMethod.Get, + "https://example.com/provider"); + + Assert.Equal(YouTubeClient.ResponseBufferLimit, client.MaxResponseContentBufferSize); + await Assert.ThrowsAsync(() => client.SendAsync(request)); + + Assert.Single(handler.Requests); + Assert.InRange(content.BytesAttempted, 0, YouTubeClient.ResponseBufferLimit + 1024); + if (!hasContentLength) + { + Assert.True(content.BytesAttempted > YouTubeClient.ResponseBufferLimit); + } + } + + private sealed class OversizedContent(bool hasContentLength) : HttpContent + { + public int BytesAttempted { get; private set; } + + protected override bool TryComputeLength(out long length) + { + length = YouTubeClient.ResponseBufferLimit * 2; + return hasContentLength; + } + + protected override async Task SerializeToStreamAsync(Stream stream, System.Net.TransportContext? context) + { + var chunk = new byte[1024]; + for (var written = 0; written < YouTubeClient.ResponseBufferLimit * 2; written += chunk.Length) + { + BytesAttempted += chunk.Length; + await stream.WriteAsync(chunk); + } + } + } + private static YouTubeClient CreateClient( RecordingHttpMessageHandler? apiHandler = null, RecordingHttpMessageHandler? pubSubHandler = null, diff --git a/tests/StaticHost.Tests/Live/YouTubeDiagnosticsTests.cs b/tests/StaticHost.Tests/Live/YouTubeDiagnosticsTests.cs index e78beb7af..9379febd1 100644 --- a/tests/StaticHost.Tests/Live/YouTubeDiagnosticsTests.cs +++ b/tests/StaticHost.Tests/Live/YouTubeDiagnosticsTests.cs @@ -356,8 +356,10 @@ public async Task FailedChecks_IdentifyOperationAndEndpoint_WithoutChangingState Assert.DoesNotContain("polling", failure.Message); } - [Fact] - public async Task SubscriptionAcceptance_DoesNotReportVerifiedLease() + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task SubscriptionAcceptance_DoesNotReportVerifiedLeaseEvenIfPersistenceFails(bool failPersistence) { var factory = new TestHttpClientFactory(); factory.AddClient(YouTubeClient.HttpClientName, @@ -367,13 +369,24 @@ public async Task SubscriptionAcceptance_DoesNotReportVerifiedLease() var options = Options(); var logger = new YouTubeRecordingLogger(); var time = new FakeTimeProvider(DateTimeOffset.UnixEpoch); - var state = new YouTubeWebSubSubscriptionState(time); + var state = new YouTubeWebSubSubscriptionState(time) + { + MarkRequestSentException = failPersistence ? new IOException("State persistence failed") : null, + }; using var broadcaster = LiveTestHelpers.CreateBroadcaster(); using var service = new YouTubeWebSubService( new YouTubeClient(factory, options, NullLogger.Instance), broadcaster, options, logger, time, state, new SingleInstanceLiveStatusCoordination()); - await service.TickAsync(CancellationToken.None); + if (failPersistence) + { + var failure = await Assert.ThrowsAsync(() => service.TickAsync(CancellationToken.None)); + Assert.Same(state.MarkRequestSentException, failure); + } + else + { + await service.TickAsync(CancellationToken.None); + } var accepted = Assert.Single(logger.Entries, entry => Equals(entry.Fields["Operation"], "WebSubSubscribe")); Assert.Equal(LogLevel.Information, accepted.Level);