1.0.4: wait up to 10 s in init for an idle mirror's first grain

CHANGELOG.md

@@ -17,9 +17,9 @@
 - The read offset is visible: log `read_offset_applied` (`requested`, `effective`) at every bring-up, `read_offset_grains` per channel in `/api/status` and `/statusz`, gauge `mxl_decklink_read_offset_grains`.
 - Read-only report of how the card signals each SDI output: `smpte_level` (3G-SDI Level A or B, `bmdDeckLinkConfigSMPTELevelAOutput`), `supports_smpte_level_a`, `output_1080p_as_psf` and `link_configuration`, in `GET /api/card` (`status.sdi_output` per sub-device), in `/statusz` per output channel and in the log line `sdi_output_config` at every output bring-up. On small an output configured as HD1080p50 showed as 1080i50 on a receiver; this process sets none of these flags, so the driver default applies (likely Level B). No setting changes them.
 - New setting `CHx_SDI_LEVEL` (`A`, `B` or `driver`; default `A`, owner decision). Before an output starts, `A` sets `bmdDeckLinkConfigSMPTELevelAOutput` and, for HD modes, the single link output (`bmdDeckLinkConfigSDIOutputLinkConfiguration`; the card on small reported Level B on a dual link, which a receiver showed as 1080i50); `B` sets Level B; `driver` changes nothing. A card without Level A support keeps the driver's setting (`sdi_level_not_set`, warning); Level A set but the single link refused logs `sdi_level_partial` (warning); otherwise `sdi_level_set`. The output holds the configuration interface for its playback session (the SDK may drop changes when it is released) and reads the values back after the output is enabled (`sdi_output_config`). `sdi_output` in `/api/card` and `/statusz` shows the values read back afterwards, plus `requested_level`. Not written to the Desktop Video preferences.
-- An output comes up on an idle mirror (the flow exists, no grain yet: `head_index` 0). The preroll now waits up to 1 s for the first grain, then until the source has written that grain + read offset + preroll grains, and starts there with the audio aligned and the read offset in place (no late repeats to build it up); before, it guessed a position from head 0 and failed the bring-up (`preroll_grain_unavailable` twice, healthy after 0.87 s on small). No first grain within 1 s: `preroll_no_grain_yet`, then the usual retry.
-- A source stall costs no output frames. The read deadline now comes from the card's playback clock (`GetScheduledStreamTime`) instead of the time of the completion call, and keeps a margin of a third of a frame (at least 8 ms, was a quarter frame, at least 4 ms). A card that calls back a few ms after a frame completed made the waits at a stall's start and end run past the frame's display time: on small one frame dropped at a stall's start and 2 late + 1 dropped at its end (`output_frames_lost`). New in the fake card of the unit tests: a 4 ms call latency and the playback clock; the stall test now requires 0 late frames (the round-3 deadline gave 2). Each bring-up logs how the clock steps (`stream_time_granularity`); a clock that steps in whole frames is combined with the estimate from the completion calls.
+- An output comes up on an idle mirror (the flow exists, no grain yet: `head_index` 0). The preroll now waits up to 1 s for the first grain, then until the source has written that grain + read offset + preroll grains, and starts there with the audio aligned and the read offset in place (no late repeats to build it up); before, it guessed a position from head 0 and failed the bring-up (`preroll_grain_unavailable` twice, healthy after 0.87 s on small). - A source stall costs no output frames. The read deadline now comes from the card's playback clock (`GetScheduledStreamTime`) instead of the time of the completion call, and keeps a margin of a third of a frame (at least 8 ms, was a quarter frame, at least 4 ms). A card that calls back a few ms after a frame completed made the waits at a stall's start and end run past the frame's display time: on small one frame dropped at a stall's start and 2 late + 1 dropped at its end (`output_frames_lost`). New in the fake card of the unit tests: a 4 ms call latency and the playback clock; the stall test now requires 0 late frames (the round-3 deadline gave 2). Each bring-up logs how the clock steps (`stream_time_granularity`); a clock that steps in whole frames is combined with the estimate from the completion calls.
 - A grain the source marked invalid (a player's gap grain after a freeze) repeats the frame with reason `source_invalid` and logs `source_invalid_grain` at info level; it was counted and logged as a read error (`grain_read_error`, warning).
+- An output on an idle mirror waits for its first grain without failing. The fabrics replication of a mirror without demand can need more than 1 s for the first grain; the preroll gave up after 1 s (`preroll_no_grain_yet`, `channel_bringup_failed`, 500 ms retry; healthy 0.9 s later on small). Now it waits up to 10 s in state `init`, logs `preroll_no_grain_yet` (info) once after 1 s and `preroll_first_grain` with `waited_ms` when the grain comes, and comes up on that grain. Only with no grain after 10 s does the bring-up fail (`preroll_no_grain`, warning) and retry. New unit test: the first grain after 2.5 s, no failed bring-up, healthy within 0.5 s of the grain, audio in sync.
 
 ## 1.0.3
 

SPECIFICATION.md

@@ -87,7 +87,7 @@ At runtime, frame production is driven from `IDeckLinkVideoOutputCallback::Sched
 
 **Read deadline.** When a frame completes, the card still holds `CHx_OUTPUT_PREROLL_GRAINS` − 1 frames. A read in the completion callback (the sync-group wait and the grain) waits at most `CHx_READER_TIMEOUT_MS` and never past the time the frame being scheduled is shown, less a third of a frame (at least 8 ms). That time comes from the card's own playback clock (`GetScheduledStreamTime`): the frame scheduled as the n-th is shown at n frame durations; whatever delays the completion calls (the card's call latency, queued callbacks, clock drift) is accounted for. Without that clock (a backend that does not report it) the estimate below is used. Each bring-up samples the clock for 1.5 frames and logs `stream_time_granularity` (`whole_frames` or `sub_frame`, `step_us`, `frame_us`, `margin_us`); a clock that steps in whole frames lags the real position by up to a frame, so then the earlier of the clock-based and the estimated deadline counts. The completion time is the time of the call when it came while no completion callback ran; a call that came as the previous callback returned (it was queued behind it) completed one frame after the previous completion. So waits in consecutive callbacks share one deadline, and a run of long waits does not drift past it. The audio callback waits at most until the same deadline: it holds the same lock as the completion callback. A grain that comes later than that is not waited for: the frame is repeated (`source_late`) instead of being shown late.
 
-**Preroll.** The preroll starts `CHx_OUTPUT_PREROLL_GRAINS` + `CHx_READ_OFFSET_GRAINS` grains behind the current time, but no later than the source's newest grain allows (its preroll grains end at the newest grain less the offset): a mirrored source arrives a grain or two late, and a mirror created by the route has no history yet. A grain older than the newest one that the source never wrote (a gap, or before a new mirror's first grain) is passed over at once; one it has not written yet is waited for. The audio starts with the grain of the first frame shown. A new session never repeats the previous session's last frame. A flow without any grain yet (an idle mirror the route woke up) is first waited for, up to 1 s; then the preroll also waits until the source has written its first grain + `CHx_READ_OFFSET_GRAINS` + `CHx_OUTPUT_PREROLL_GRAINS` (bounded by that many frames + 3), so it starts at grains the source has and the read offset is in place from the start, not built up by late repeats; if none comes, the bring-up fails (`preroll_no_grain_yet`) and retries. Only when nothing can be shown within `CHx_READER_TIMEOUT_MS` + (preroll + 3) frames does the bring-up fail (`preroll_grain_unavailable` with `grain_index`, `head_index`, `read_offset_grains`) and retry with backoff. Every bring-up logs `read_offset_applied` (`requested`, `effective`).
+**Preroll.** The preroll starts `CHx_OUTPUT_PREROLL_GRAINS` + `CHx_READ_OFFSET_GRAINS` grains behind the current time, but no later than the source's newest grain allows (its preroll grains end at the newest grain less the offset): a mirrored source arrives a grain or two late, and a mirror created by the route has no history yet. A grain older than the newest one that the source never wrote (a gap, or before a new mirror's first grain) is passed over at once; one it has not written yet is waited for. The audio starts with the grain of the first frame shown. A new session never repeats the previous session's last frame. A flow without any grain yet (an idle mirror the route woke up; replicating its first grain can take seconds) is first waited for in state `init`, up to 10 s: `preroll_no_grain_yet` (info, `waited_ms`) is logged once after 1 s and `preroll_first_grain` (`waited_ms`) when it comes; only with no grain after 10 s does the bring-up fail (`preroll_no_grain`, warning) and retry. Then the preroll also waits until the source has written its first grain + `CHx_READ_OFFSET_GRAINS` + `CHx_OUTPUT_PREROLL_GRAINS` (bounded by that many frames + 3), so it starts at grains the source has and the read offset is in place from the start, not built up by late repeats. Only when nothing can be shown within `CHx_READER_TIMEOUT_MS` + (preroll + 3) frames does the bring-up fail (`preroll_grain_unavailable` with `grain_index`, `head_index`, `read_offset_grains`) and retry with backoff. Every bring-up logs `read_offset_applied` (`requested`, `effective`).
 
 **Read position.** An output reads grain *n* when frame *n* − 1 has completed, `CHx_READ_OFFSET_GRAINS` (default 0) grains behind the newest grain: set 1–2 for a mirrored source that arrives with fabrics lag, so its grains are there when read. The position follows the source, not only the card's clock:
 

src/channel/output_channel.cpp

@@ -54,9 +54,11 @@ namespace mxldl::channel
         constexpr std::uint64_t kCatchUpAfterNs = 1'000'000'000ULL;
         // §2.4: a source late for this long marks the channel degraded.
         constexpr std::uint64_t kLateDegradedNs = 1'000'000'000ULL;
-        // How long a preroll waits for the first grain of a flow that has
-        // none yet (an idle mirror the route woke up).
-        constexpr std::uint64_t kFirstGrainWaitNs = 1'000'000'000ULL;
+        // A preroll waits this long for the first grain of a flow that has
+        // none yet (an idle mirror the route woke up), in state init; it
+        // logs preroll_no_grain_yet once after kFirstGrainNoteNs.
+        constexpr std::uint64_t kFirstGrainGiveUpNs = 10'000'000'000ULL;
+        constexpr std::uint64_t kFirstGrainNoteNs = 1'000'000'000ULL;
         // A late run is logged once it has this many frames in a row.
         constexpr std::uint64_t kLateRunLog = 3;
         // Late repeats less than this apart belong to one run (a source
@@ -542,26 +544,48 @@ namespace mxldl::channel
             if (sourceHead == 0)
             {
                 // The flow exists but has no grain yet (an idle mirror the
-                // route just woke up): wait for the first one instead of
-                // guessing a position and failing the bring-up.
-                auto const until = steadyNowNs() + kFirstGrainWaitNs;
-                while (sourceHead == 0 && _running.load() && steadyNowNs() < until)
+                // route just woke up; its replication can take seconds):
+                // wait for the first one in state init, instead of guessing
+                // a position and failing the bring-up. Only after
+                // kFirstGrainGiveUpNs does the bring-up fail (and retry).
+                auto const waitStart = steadyNowNs();
+                bool noted = false;
+                while (sourceHead == 0 && _running.load() && steadyNowNs() - waitStart < kFirstGrainGiveUpNs)
                 {
+                    if (!noted && steadyNowNs() - waitStart >= kFirstGrainNoteNs)
+                    {
+                        noted = true;
+                        log::info("preroll_no_grain_yet",
+                            {
+                                {"channel_index", _cfg.index},
+                                {"channel_label", _cfg.label},
+                                {"waited_ms", kFirstGrainNoteNs / 1'000'000ULL},
+                                {"details", "the source flow has no grain yet (an idle mirror?); waiting for its first grain"},
+                            });
+                    }
                     std::this_thread::sleep_for(std::chrono::milliseconds(2));
                     sourceHead = _videoReader->headIndex();
                 }
+                auto const waitedMs = (steadyNowNs() - waitStart) / 1'000'000ULL;
                 if (sourceHead == 0)
                 {
-                    log::warn("preroll_no_grain_yet",
-                        {
-                            {"channel_index", _cfg.index},
-                            {"channel_label", _cfg.label},
-                            {"waited_ms", kFirstGrainWaitNs / 1'000'000ULL},
-                            {"details", "the source flow has no grain yet"},
-                        });
+                    if (_running.load())
+                    {
+                        log::warn("preroll_no_grain",
+                            {
+                                {"channel_index", _cfg.index},
+                                {"channel_label", _cfg.label},
+                                {"waited_ms", waitedMs},
+                                {"details", "no grain from the source flow; the bring-up fails and retries"},
+                            });
+                    }
                     tearDownStreaming();
                     return false;
                 }
+                if (noted)
+                {
+                    log::info("preroll_first_grain", {{"channel_index", _cfg.index}, {"channel_label", _cfg.label}, {"waited_ms", waitedMs}});
+                }
                 // Let the source write the preroll's grains and the read
                 // offset past its first one (first + offset + preroll), so
                 // the preroll starts at a grain the source has, shows only

tests/unit/test_flow_reopen.cpp

@@ -1477,3 +1477,40 @@ TEST_CASE("each bring-up logs how the card's playback clock steps")
         video.reset();
     }
 }
+
+TEST_CASE("an idle mirror whose first grain needs 2.5 s: the output waits in init and comes up on that grain")
+{
+    // A mirror without demand can take seconds to replicate its first grain.
+    // That is no failure: no channel_bringup_failed, no failed state.
+    Rig rig("idlelong");
+    rig.withAudio();
+    auto audio = std::make_unique<AudioSource>(*rig.domain, rig.audio, kStamped);
+    auto video = std::make_unique<VideoSource>(*rig.domain, rig.video, kGen1, true);
+    std::this_thread::sleep_for(50ms);
+    LogCapture logs;
+    channel::OutputChannel out(rig.global, rig.ch, *rig.sub, *rig.domain, rig.metrics, "test");
+    out.start();
+    bool sawFailed = false;
+    auto const until = std::chrono::steady_clock::now() + 2500ms;
+    while (std::chrono::steady_clock::now() < until)
+    {
+        sawFailed = sawFailed || out.status().state.load() == channel::State::Failed;
+        std::this_thread::sleep_for(20ms);
+    }
+    CHECK_FALSE(sawFailed);
+    CHECK(out.status().state.load() == channel::State::Init);
+    video->paused = false; // the first grain
+    auto const firstGrain = std::chrono::steady_clock::now();
+    REQUIRE(waitUntil([&] { return out.status().state.load() == channel::State::Healthy; }, 2s));
+    CHECK(std::chrono::steady_clock::now() - firstGrain < 500ms);
+    CHECK(logs.of("channel_bringup_failed").empty());
+    CHECK(logs.of("preroll_no_grain").empty());
+    CHECK(logs.of("preroll_no_grain_yet").size() == 1);
+    CHECK(logs.of("preroll_first_grain").size() == 1);
+    CHECK(rig.reconnects() == 0.0);
+    REQUIRE(waitUntil([&] { return rig.played->pairCount() >= 30; }, 3s));
+    CHECK(rig.played->avOffset(5) == -rig.ch.outputPrerollGrains);
+    out.stop();
+    video.reset();
+    audio.reset();
+}