diff --git a/src/statichost/StaticHost/Live/LiveEndpoints.cs b/src/statichost/StaticHost/Live/LiveEndpoints.cs index 96d88de12..23f815f3e 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; @@ -276,6 +277,7 @@ private static async Task TwitchWebhook( private static async Task YouTubeVerify( HttpContext context, IYouTubeWebSubSubscriptionState subscriptions, + IOptions options, TimeProvider time, ILoggerFactory loggerFactory) { @@ -291,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)) { @@ -334,8 +349,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} 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"); } @@ -365,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) @@ -408,16 +424,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 +449,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/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/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 d4ed37d3f..2544d8127 100644 --- a/src/statichost/StaticHost/Live/README.md +++ b/src/statichost/StaticHost/Live/README.md @@ -51,18 +51,142 @@ 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` | 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 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. | + +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. + +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 +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 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. + +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 +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 +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. 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 Bind from the `Live` section of configuration. In unconfigured local runs, @@ -311,6 +435,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, 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|FullyQualifiedName~LiveEndpointsTests)&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..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"; @@ -34,7 +36,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 +59,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 +84,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 +134,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..36073c282 --- /dev/null +++ b/src/statichost/StaticHost/Live/YouTube/YouTubeDiagnostics.cs @@ -0,0 +1,187 @@ +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) + { + public double? RetryAfterSeconds { get; init; } + public DateTimeOffset? RetryAfterDate { get; init; } + } + + 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); + } + + var retryAfter = response.Headers.RetryAfter; + details = details with + { + RetryAfterSeconds = retryAfter?.Delta?.TotalSeconds, + RetryAfterDate = retryAfter?.Date, + }; + + 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) { } + + 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. + return text.Contains("temporarily unavailable", StringComparison.OrdinalIgnoreCase) + ? "Provider reports temporary unavailability" + : 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) + { + 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}; " + + "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 = + [ + 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, + ]; + 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..cdab0af43 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,31 +157,21 @@ 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; + 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(), @@ -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/InMemoryLiveStatusInfrastructure.cs b/tests/StaticHost.Tests/Live/InMemoryLiveStatusInfrastructure.cs index 6a4959fc6..02176ba5b 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); } @@ -114,9 +117,21 @@ 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; + public YouTubeWebSubSubscriptionData Current + { + get + { + lock (_gate) + { + return _state; + } + } + } + public ValueTask TryBeginSubscriptionAsync( string channelId, DateTimeOffset now, @@ -156,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/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/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 new file mode 100644 index 000000000..9379febd1 --- /dev/null +++ b/tests/StaticHost.Tests/Live/YouTubeDiagnosticsTests.cs @@ -0,0 +1,423 @@ +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("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) + { + 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"]); + 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] + public async Task UnreadableBody_DoesNotMaskHttpFailure() + { + using var response = new HttpResponseMessage(HttpStatusCode.BadGateway) + { + 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(); + 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"]); + Assert.Equal(120d, Assert.Single(logger.Entries).Fields["RetryAfterSeconds"]); + } + + [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); + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task SubscriptionAcceptance_DoesNotReportVerifiedLeaseEvenIfPersistenceFails(bool failPersistence) + { + 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) + { + 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()); + + 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); + 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));