From 5ad01065020834484684eadb1c0072d31457c787 Mon Sep 17 00:00:00 2001 From: gramps Date: Sun, 4 Oct 2026 14:47:09 -0700 Subject: [PATCH] diag: log what the broadcast is actually bound to while a stream runs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The logs answered the question and closed off a whole branch of investigation. The long run: broadcast inserted 14:17:04.577, ffmpeg to rtmp://a.rtmp.youtube.com/live2/5f6z-... at 14:17:05.686, and ffmpeg's own muxing summary at 14:18:56.473 reads video:101229KiB audio:1419KiB muxing overhead: 0.202949% ~99MB of real video plus audio over 112s, which is what 8000+128 kb/s is supposed to produce. No socket error, no 4xx from ingest, no reconnect. And the broadcast still never left `ready`; close-out 403'd invalidTransition again. The 8s run behaved the same way, so "YouTube needed longer" is disproven — 112s is longer. So the RTMP path is provably healthy. That is the finding worth keeping: it kills the entire "the push is broken" theory, which is where this had been heading for a week. The break is between ingest being accepted and the broadcast being told to start. Which puts the binding in frame, and the app was structurally blind to it. Google documents contentDetails.boundStreamId and says enableAutoStart fires "when you start streaming video on the bound live stream" — both valid on insert, neither restricted against reusable streams. But the migration guide also says a broadcast "is not bound to any streams at the time that it's created", and the failure that produces is invisible from the RTMP side precisely because a reusable stream will happily accept bytes for an unbound broadcast. Ingest succeeding proves nothing. Hence LogBroadcastDiagnosticsAsync, riding the existing health poll rather than adding a timer. One greppable line: lifecycle status, privacy, recording, boundStreamId *compared against the stream id we are actually pushing* (BoundMatches: yes / MISMATCH / NO-BINDING / unknown), boundStreamLastUpdate- TimeMs, autoStart/Stop, liveChatId presence, the stream's own streamStatus and activeLiveChatId, and the CDN settings we declared. Deliberately self-limiting: _broadcastSeenLive latches on live/liveStarting so the diagnostic shouts only while the broadcast is stuck and goes quiet once it is healthy. A permanent per-tick log line would be noise; this is the opposite. One test, per the Good Dog rule: BroadcastBindingTests pins the matrix and specifically pins `unknown` when there is no stream id to compare against, so a missing expectation can never be misreported as a match — that is the failure that would make this diagnostic lie. Suite 387/387, 0 warnings. --- Services/YouTubeStreamService.cs | 92 +++++++++++++++++++ .../MainViewModel.Streaming.Operations.cs | 17 +++- ViewModels/MainViewModel.Streaming.cs | 3 + ai.md | 27 ++++++ ytLive.Tests/BroadcastBindingTests.cs | 33 +++++++ 5 files changed, 171 insertions(+), 1 deletion(-) create mode 100644 ytLive.Tests/BroadcastBindingTests.cs diff --git a/Services/YouTubeStreamService.cs b/Services/YouTubeStreamService.cs index 54381cc..9844fbf 100644 --- a/Services/YouTubeStreamService.cs +++ b/Services/YouTubeStreamService.cs @@ -178,6 +178,98 @@ public class YouTubeStreamService : null; } + /// One compact log line answering the only question that matters while a + /// stream is running: is the broadcast actually bound to the stream we are pushing + /// to, and has it moved off `ready`? + /// + /// Added 2026-10-04 after two test runs proved the push itself is healthy — ffmpeg + /// delivered 101,229 KiB video + 1,419 KiB audio over 112s with no socket error, + /// yet `enableAutoStart` never fired and close-out 403'd with `invalidTransition`. + /// The config is correct by Google's documentation (boundStreamId is a valid + /// contentDetails field with no restriction against reusable streams), so the only + /// way forward is to observe rather than guess. Everything the API reports about + /// this broadcast and its stream goes in one greppable line: + /// lifeCycleStatus (so the caller can stop asking once it is live), privacyStatus, the boundStreamId + /// *compared against the stream we think we are pushing*, enableAutoStart/Stop, liveChatId + /// presence, the stream's own status.streamStatus, and the CDN settings we declared. + /// Never throws. + public async Task LogBroadcastDiagnosticsAsync(string broadcastId, string? streamId) + { + if (!await EnsureToken()) return null; + + _http.DefaultRequestHeaders.Authorization = new("Bearer", _auth.CurrentChannel!.AccessToken); + + try + { + var broadcast = await GetJsonAsync($"liveBroadcasts?part=status,contentDetails,snippet&id={Uri.EscapeDataString(broadcastId)}"); + var status = Nested(broadcast, "status"); + var details = Nested(broadcast, "contentDetails"); + var snippet = Nested(broadcast, "snippet"); + + var lifeCycle = Text(status, "lifeCycleStatus") ?? "?"; + var bound = Text(details, "boundStreamId"); + JsonElement? stream = string.IsNullOrWhiteSpace(streamId) + ? null + : await GetJsonAsync($"liveStreams?part=status,cdn&id={Uri.EscapeDataString(streamId)}"); + var streamItem = stream is { } present + && present.TryGetProperty("items", out var streamItems) + && streamItems.GetArrayLength() > 0 + ? streamItems[0] + : default(JsonElement); + + AppLog.Write( + $"Broadcast diag: id={broadcastId} lifeCycle={lifeCycle} privacy={Text(status, "privacyStatus") ?? "?"} " + + $"recording={Text(status, "recordingStatus") ?? "?"} bound={bound ?? "NONE"} " + + $"expect={streamId ?? "none"} boundMatches={BoundMatches(bound, streamId)} " + + $"boundLastUpdate={Text(details, "boundStreamLastUpdateTimeMs") ?? "?"} " + + $"autoStart={Flag(details, "enableAutoStart")} autoStop={Flag(details, "enableAutoStop")} " + + $"liveChatId={(string.IsNullOrWhiteSpace(Text(snippet, "liveChatId")) ? "none" : "present")} | " + + $"streamId={Text(streamItem, "id") ?? "none"} streamStatus={Text(Nested(streamItem, "status"), "streamStatus") ?? "?"} " + + $"activeChat={(string.IsNullOrWhiteSpace(Text(Nested(streamItem, "status"), "activeLiveChatId")) ? "none" : "present")} " + + $"cdn={Text(Nested(streamItem, "cdn"), "ingestionType") ?? "?"}/{Text(Nested(streamItem, "cdn"), "resolution") ?? "?"}@{Text(Nested(streamItem, "cdn"), "frameRate") ?? "?"}"); + return lifeCycle; + } + catch (Exception ex) + { + AppLog.Write($"Broadcast diag failed: {ex.Message}"); + return null; + } + } + + /// The bound stream must be the one we are actually feeding. A mismatch is + /// the failure mode where ingest succeeds (the reusable stream happily accepts the + /// bytes) while the broadcast waits forever for a stream that is not sending. + internal static string BoundMatches(string? boundStreamId, string? expectedStreamId) + { + if (string.IsNullOrWhiteSpace(boundStreamId)) return "NO-BINDING"; + if (string.IsNullOrWhiteSpace(expectedStreamId)) return "unknown"; + return boundStreamId == expectedStreamId ? "yes" : "MISMATCH"; + } + + private async Task GetJsonAsync(string pathAndQuery) + { + var response = await _http.GetAsync($"{ApiBase}/{pathAndQuery}"); + if (!response.IsSuccessStatusCode) + { + AppLog.Write($"Broadcast diag GET {pathAndQuery.Split('?')[0]} failed ({(int)response.StatusCode})"); + return default; + } + return JsonSerializer.Deserialize(await response.Content.ReadAsStringAsync()); + } + + private static JsonElement Nested(JsonElement parent, string name) => + parent.ValueKind == JsonValueKind.Object && parent.TryGetProperty(name, out var child) ? child : default; + + private static string? Text(JsonElement parent, string name) => + parent.ValueKind == JsonValueKind.Object && parent.TryGetProperty(name, out var value) && value.ValueKind == JsonValueKind.String + ? value.GetString() + : null; + + private static string Flag(JsonElement parent, string name) => + parent.ValueKind == JsonValueKind.Object && parent.TryGetProperty(name, out var value) + ? (value.ValueKind == JsonValueKind.True ? "true" : value.ValueKind == JsonValueKind.False ? "false" : value.ValueKind.ToString()) + : "unset"; + /// Returns the channel's reusable stream (TASK 5 design decision 2): /// lists existing streams first and reuses the one with cdn.isReusable=true, /// creating it with variable resolution/frame rate on first use. Binding to a diff --git a/ViewModels/MainViewModel.Streaming.Operations.cs b/ViewModels/MainViewModel.Streaming.Operations.cs index f9b7daa..e47253e 100644 --- a/ViewModels/MainViewModel.Streaming.Operations.cs +++ b/ViewModels/MainViewModel.Streaming.Operations.cs @@ -167,6 +167,7 @@ public partial class MainViewModel : ViewModelBase _currentBroadcastId = await _youtubeStream.CreateBroadcast( StreamTitle, StreamDescription, DateTime.UtcNow, stream.Id); + _broadcastSeenLive = false; if (_currentBroadcastId == null) { AppLog.Write("Broadcast creation failed; check the OAuth session"); @@ -236,7 +237,15 @@ public partial class MainViewModel : ViewModelBase /// One liveStreams.list poll (TASK 5 item 3): updates the YouTube /// health state + the report-by-exception banner. Never throws — a poll - /// failure logs and leaves the last state untouched. + /// failure logs and leaves the last state untouched. + /// + /// Also piggybacks the broadcast diagnostic (2026-10-04) — the health poll was + /// already running during a stream but only ever read the STREAM's health, which + /// is why two test runs could push 100MB to YouTube and still leave the app + /// unable to say whether the broadcast had ever left `ready`. Deliberately + /// self-limiting: it only logs while the broadcast has NOT reached `live`, so it + /// shouts exactly when something is wrong and goes quiet once healthy, rather than + /// adding a permanent per-tick line to the log. private async Task PollHealthAsync() { if (_reusableStream == null || !IsLive) return; @@ -254,6 +263,12 @@ public partial class MainViewModel : ViewModelBase CurrentHealth.ConfigurationIssues.AddRange(health.ConfigurationIssues); OnPropertyChanged(nameof(CurrentHealth)); ApplyHealthIssue(health.ConfigurationIssues); + + if (!string.IsNullOrWhiteSpace(_currentBroadcastId) && !_broadcastSeenLive) + { + var lifeCycle = await _youtubeStream.LogBroadcastDiagnosticsAsync(_currentBroadcastId, _reusableStream.Id); + if (lifeCycle is "live" or "liveStarting") _broadcastSeenLive = true; + } } catch (Exception ex) { diff --git a/ViewModels/MainViewModel.Streaming.cs b/ViewModels/MainViewModel.Streaming.cs index d022b65..2cf1cb5 100644 --- a/ViewModels/MainViewModel.Streaming.cs +++ b/ViewModels/MainViewModel.Streaming.cs @@ -21,6 +21,9 @@ public partial class MainViewModel : ViewModelBase private string _streamDescription = string.Empty; private string _streamVisibility = "Private"; private string? _currentBroadcastId; + /// Latches once the broadcast reaches live so the per-poll broadcast + /// diagnostic stops logging (2026-10-04). Reset at broadcast creation. + private bool _broadcastSeenLive; private string? _reusableStreamUrl; private ReusableStream? _reusableStream; private string? _healthIssueBanner; diff --git a/ai.md b/ai.md index 0e58dc8..741332d 100644 --- a/ai.md +++ b/ai.md @@ -1683,6 +1683,33 @@ These are the hard facts behind every decision. Full list in `TASKS.md`. `enableAutoStart=true`, `enableAutoStop=true`, `enableMonitorStream=false`, `selfDeclaredMadeForKids=false`, `latencyPreference=low`. The encoder starting brings YouTube live. `enableMonitorStream=false` is what lets us skip the testing stage. +- **⛔ CORRECTION (2026-10-04): the push is provably healthy — stop investigating it.** The long + test run settles it: `liveBroadcasts.insert` at 14:17:04.577, ffmpeg `Output #0, flv` to + `rtmp://a.rtmp.youtube.com/live2/5f6z-…` at 14:17:05.686, and at 14:18:56.473 ffmpeg's own + muxing summary reads **`video:101229KiB audio:1419KiB`**, `muxing overhead: 0.202949%` — ~99 MB + of real video plus audio over 112s, which is exactly what 8000+128 kb/s should produce. **No + socket error, no 4xx from ingest, no reconnect.** The broadcast *still* never left `ready`, and + close-out earned 403 `invalidTransition` again. An earlier 8s run behaved identically, so + "YouTube needed longer" is disproven — 112s is longer. The break is between *ingest accepted* + and *broadcast told to start*, nowhere in the RTMP path. +- **The binding is the prime suspect, and the app was blind to it.** `contentDetails.boundStreamId` + ("the live stream bound to the broadcast") and `enableAutoStart` ("start automatically when you + start streaming video **on the bound live stream**") are both valid on insert, with no documented + restriction against a reusable stream. But YouTube's migration guide carries the danger: + **"a liveBroadcast must be bound to exactly one stream before the live broadcast can actually + start. The broadcast is not bound to any streams at the time that it's created."** And this + failure mode is *invisible from the RTMP side*, because **a reusable stream accepts bytes for an + unbound broadcast** — ingest succeeding proves nothing. ⇒ `LogBroadcastDiagnosticsAsync` rides + the **existing** stream-health poll (no second timer) and writes one greppable line: + `lifeCycleStatus`, `privacyStatus`, `recordingStatus`, `boundStreamId` **compared against the + stream id we are actually pushing** (`BoundMatches` → `yes`/`MISMATCH`/`NO-BINDING`/`unknown`), + `boundStreamLastUpdateTimeMs`, `enableAutoStart/Stop`, `liveChatId` presence, the stream's own + `status.streamStatus` + `activeLiveChatId`, and the CDN settings we declared. It is + **self-limiting** — `_broadcastSeenLive` latches on `live`/`liveStarting`, so the line shouts only + while the broadcast is stuck and goes quiet once healthy. **The next run reads this line; it is + the whole experiment.** Guarded by `BroadcastBindingTests.BoundMatches_ComparesTheBroadcastAgainstTheStreamWePush`, + which pins `unknown` for a missing expectation so an absent stream id can never be misreported + as a match. - **Visibility picker (TASK 9 item 6) — DELIBERATE TEST-PHASE LOCK, not drift (2026-09-01).** The "always Private" enforcement in `YouTubeStreamService.CreateBroadcast` stays while the creator runs multi-month real-world testing: non-private test streams would clutter the channel with VODs diff --git a/ytLive.Tests/BroadcastBindingTests.cs b/ytLive.Tests/BroadcastBindingTests.cs new file mode 100644 index 0000000..68e3e2f --- /dev/null +++ b/ytLive.Tests/BroadcastBindingTests.cs @@ -0,0 +1,33 @@ +using Xunit; +using ytLive.Services; + +namespace ytLive.Tests; + +/// +/// Broadcast-binding diagnostics (2026-10-04). Two test streams proved the RTMP push +/// is healthy — ffmpeg delivered 101,229 KiB video + 1,419 KiB audio over 112 seconds +/// with no socket error — yet the broadcast never left `ready` and close-out returned +/// 403 `invalidTransition`. Google's docs say enableAutoStart fires "when you +/// start streaming video on the bound live stream", so the one thing worth asserting +/// about the request we send is that we know which stream we think we are bound to. +/// +public class BroadcastBindingTests +{ + /// The comparison that decides whether the broadcast is even watching the + /// feed we are pushing. A reusable stream happily accepts bytes for an unbound + /// broadcast, so ingest succeeding proves nothing on its own — a MISMATCH or + /// NO-BINDING would look identical from the RTMP side and would hang forever. + /// "unknown" is the honest answer when the app has no stream id to compare against, + /// so a missing expectation is never silently reported as a match. + [Theory] + [InlineData("stream-abc", "stream-abc", "yes")] + [InlineData("stream-abc", "stream-xyz", "MISMATCH")] + [InlineData(null, "stream-abc", "NO-BINDING")] + [InlineData("", "stream-abc", "NO-BINDING")] + [InlineData("stream-abc", null, "unknown")] + [InlineData("stream-abc", "", "unknown")] + public void BoundMatches_ComparesTheBroadcastAgainstTheStreamWePush(string? bound, string? expected, string verdict) + { + Assert.Equal(verdict, YouTubeStreamService.BoundMatches(bound, expected)); + } +}