fix(producer): report unavailable frame checks in debug logs (#6200)

* fix(producer): report unavailable frame checks in debug logs

* chore: prepare conflict resolution against current main

* fix(producer): retain scoped diagnostics with current artifact handling

docs/packages/producer.mdx

@@ -100,6 +100,19 @@ segment starts on a keyframe. HLS is SDR only (`hdrMode: "force-hdr"` is
 rejected), refuses GPU encoding (GPU encoders ignore the keyframe lock), and is
 not available in distributed rendering, Lambda, or Cloud Run.
 
+## Inspect output validation
+
+A matching output duration does not prove that every expected frame is present.
+WebM and HLS often omit the frame count from their metadata. When no usable count
+is available, the producer skips the frame-count check and continues checking
+duration and requested dimensions.
+
+Set `debug: true` in `createRenderJob()` or use `npx hyperframes render --debug`
+to retain `render.log` in the render's working directory. Its
+`artifact_frame_count_unavailable` debug event records the output path and
+expected frame count whenever this check is skipped. Normal output stays quiet;
+a custom `logger` can also collect the event through its `debug` method.
+
 ## Cancel a render
 
 Pass an abort signal to the final argument:

packages/producer/src/services/render/artifactTransaction.test.ts

@@ -226,10 +226,14 @@ describe("ArtifactTransaction", () => {
   it("does not probe duration when the caller passes no expectation", async () => {
     const dir = tempDir();
     const destination = join(dir, "render.mp4");
-    const transaction = new ArtifactTransaction(destination, "file", undefined, neverCalled);
+    const debug = vi.fn();
+    const transaction = new ArtifactTransaction(destination, "file", undefined, neverCalled, {
+      debug,
+    });
     writeFileSync(transaction.stagingPath, "any-non-empty-bytes");
 
     await expect(transaction.validate()).resolves.toBeUndefined();
+    expect(debug).not.toHaveBeenCalled();
 
     transaction.rollback();
   });
@@ -346,16 +350,18 @@ describe("ArtifactTransaction", () => {
     }
   });
 
-  it.each([undefined, 0, -1, Number.NaN])(
-    "validates video duration quietly when the probe returns %s frames",
+  it.each([undefined, 0, -1, Number.NaN, Number.POSITIVE_INFINITY])(
+    "reports an unavailable frame-count check at debug level for %s frames",
     async (frames) => {
       const dir = tempDir();
       const probe: ArtifactDurationProbe = async () => ({ durationSeconds: 4, frames });
+      const debug = vi.fn();
       const transaction = new ArtifactTransaction(
         join(dir, "render.webm"),
         "file",
         undefined,
         probe,
+        { debug },
       );
       writeFileSync(transaction.stagingPath, "video");
       const warn = vi.spyOn(console, "warn").mockImplementation(() => {});
@@ -364,6 +370,14 @@ describe("ArtifactTransaction", () => {
         await expect(
           transaction.validate({ expectedDurationSeconds: 4, fps: 30, expectedFrames: 120 }),
         ).resolves.toBeUndefined();
+        expect(debug).toHaveBeenCalledExactlyOnceWith(
+          "[Render] Frame-count validation skipped: no usable frame count was reported.",
+          {
+            event: "artifact_frame_count_unavailable",
+            artifact: transaction.destinationPath,
+            expectedFrames: 120,
+          },
+        );
         expect(warn).not.toHaveBeenCalled();
       } finally {
         warn.mockRestore();
@@ -373,6 +387,131 @@ describe("ArtifactTransaction", () => {
     },
   );
 
+  it("keeps stdout and stderr quiet when frame counts are unavailable with the default logger", async () => {
+    const dir = tempDir();
+    const probe: ArtifactDurationProbe = async () => ({ durationSeconds: 4 });
+    const transaction = new ArtifactTransaction(join(dir, "render.webm"), "file", undefined, probe);
+    writeFileSync(transaction.stagingPath, "video");
+    const stdout = vi.spyOn(process.stdout, "write").mockImplementation(() => true);
+    const stderr = vi.spyOn(process.stderr, "write").mockImplementation(() => true);
+    const consoleWrites = (["log", "info", "debug", "warn", "error"] as const).map((method) =>
+      vi.spyOn(console, method).mockImplementation(() => {}),
+    );
+
+    try {
+      await expect(
+        transaction.validate({ expectedDurationSeconds: 4, fps: 30, expectedFrames: 120 }),
+      ).resolves.toBeUndefined();
+      expect(stdout).not.toHaveBeenCalled();
+      expect(stderr).not.toHaveBeenCalled();
+      for (const write of consoleWrites) expect(write).not.toHaveBeenCalled();
+    } finally {
+      stdout.mockRestore();
+      stderr.mockRestore();
+      for (const write of consoleWrites) write.mockRestore();
+      transaction.rollback();
+      rmSync(dir, { recursive: true, force: true });
+    }
+  });
+
+  it("does not report unavailable frame counts when only duration is expected", async () => {
+    const dir = tempDir();
+    const probe: ArtifactDurationProbe = async () => ({ durationSeconds: 4 });
+    const debug = vi.fn();
+    const transaction = new ArtifactTransaction(
+      join(dir, "render.webm"),
+      "file",
+      undefined,
+      probe,
+      {
+        debug,
+      },
+    );
+    writeFileSync(transaction.stagingPath, "video");
+
+    try {
+      await expect(transaction.validate({ expectedDurationSeconds: 4 })).resolves.toBeUndefined();
+      expect(debug).not.toHaveBeenCalled();
+    } finally {
+      transaction.rollback();
+      rmSync(dir, { recursive: true, force: true });
+    }
+  });
+
+  it.each([120, 119, 90])(
+    "checks a reported count of %s without an unavailable-count event",
+    async (frames) => {
+      const dir = tempDir();
+      const probe: ArtifactDurationProbe = async () => ({ durationSeconds: 4, frames });
+      const debug = vi.fn();
+      const transaction = new ArtifactTransaction(
+        join(dir, "render.mp4"),
+        "file",
+        undefined,
+        probe,
+        {
+          debug,
+        },
+      );
+      writeFileSync(transaction.stagingPath, "video");
+
+      try {
+        const validation = transaction.validate({
+          expectedDurationSeconds: 4,
+          fps: 30,
+          expectedFrames: 120,
+        });
+        if (frames >= 119) await expect(validation).resolves.toBeUndefined();
+        else await expect(validation).rejects.toThrow(/truncated.*120 frames.*90 frames/);
+        expect(debug).not.toHaveBeenCalled();
+      } finally {
+        transaction.rollback();
+        rmSync(dir, { recursive: true, force: true });
+      }
+    },
+  );
+
+  it.each([1920, 1280])(
+    "preserves validation with a throwing logger and a probed width of %s",
+    async (width) => {
+      const dir = tempDir();
+      const probe: ArtifactDurationProbe = async () => ({
+        durationSeconds: 4,
+        width,
+        height: 1080,
+      });
+      const debug = vi.fn(() => {
+        throw new Error("debug sink unavailable");
+      });
+      const transaction = new ArtifactTransaction(
+        join(dir, "render.webm"),
+        "file",
+        undefined,
+        probe,
+        {
+          debug,
+        },
+      );
+      writeFileSync(transaction.stagingPath, "video");
+
+      try {
+        const validation = transaction.validate({
+          expectedDurationSeconds: 4,
+          fps: 30,
+          expectedFrames: 120,
+          expectedWidth: 1920,
+          expectedHeight: 1080,
+        });
+        if (width === 1920) await expect(validation).resolves.toBeUndefined();
+        else await expect(validation).rejects.toThrow("expected 1920x1080, probed 1280x1080");
+        expect(debug).toHaveBeenCalledOnce();
+      } finally {
+        transaction.rollback();
+        rmSync(dir, { recursive: true, force: true });
+      }
+    },
+  );
+
   it("rejects a video whose probed duration is far shorter than the captured duration", async () => {
     // Field packet from #3395: expected 52.2s (1566 frames), artifact
     // contained 41.333s (1240 frames). The gate must catch the 11s
@@ -383,7 +522,10 @@ describe("ArtifactTransaction", () => {
       expect(path).toBe(transaction.stagingPath);
       return { durationSeconds: 41.333 };
     };
-    const transaction = new ArtifactTransaction(destination, "file", undefined, probedShortfall);
+    const debug = vi.fn();
+    const transaction = new ArtifactTransaction(destination, "file", undefined, probedShortfall, {
+      debug,
+    });
     writeFileSync(transaction.stagingPath, "fake-mp4-bytes-that-are-non-empty");
 
     await expect(
@@ -393,6 +535,7 @@ describe("ArtifactTransaction", () => {
         expectedFrames: 1566,
       }),
     ).rejects.toThrow(/truncated/);
+    expect(debug).not.toHaveBeenCalled();
 
     transaction.rollback();
   });
@@ -518,12 +661,14 @@ describe("ArtifactTransaction", () => {
     const dir = tempDir();
     const destination = join(dir, "render.mp4");
     const probe: ArtifactDurationProbe = async () => ({ durationSeconds: 0 });
-    const transaction = new ArtifactTransaction(destination, "file", undefined, probe);
+    const debug = vi.fn();
+    const transaction = new ArtifactTransaction(destination, "file", undefined, probe, { debug });
     writeFileSync(transaction.stagingPath, "fake-mp4-bytes-that-are-non-empty");
 
-    await expect(transaction.validate({ expectedDurationSeconds: 10.0, fps: 30 })).rejects.toThrow(
-      /no usable duration/,
-    );
+    await expect(
+      transaction.validate({ expectedDurationSeconds: 10.0, fps: 30, expectedFrames: 300 }),
+    ).rejects.toThrow(/no usable duration/);
+    expect(debug).not.toHaveBeenCalled();
 
     transaction.rollback();
   });
@@ -587,11 +732,14 @@ describe("ArtifactTransaction", () => {
   // ffprobe reports `nb_frames=N/A` through the hls demuxer, so the frame
   // check is inert for a playlist probe. Assert it stays inert rather than
   // failing a package whose duration is correct.
-  it("passes an HLS package whose probe reports no frame count", async () => {
+  it("reports a skipped HLS frame-count check without rejecting the package", async () => {
     const dir = tempDir();
     const destination = join(dir, "render-hls");
     const probe: ArtifactDurationProbe = async () => ({ durationSeconds: 4.0 });
-    const transaction = new ArtifactTransaction(destination, "directory", undefined, probe);
+    const debug = vi.fn();
+    const transaction = new ArtifactTransaction(destination, "directory", undefined, probe, {
+      debug,
+    });
     stageHlsDirectory(transaction);
     const warn = vi.spyOn(console, "warn").mockImplementation(() => {});
     try {
@@ -604,6 +752,10 @@ describe("ArtifactTransaction", () => {
           requiredFiles: ["master.m3u8"],
         }),
       ).resolves.toBeUndefined();
+      expect(debug).toHaveBeenCalledExactlyOnceWith(
+        "[Render] Frame-count validation skipped: no usable frame count was reported.",
+        { event: "artifact_frame_count_unavailable", artifact: destination, expectedFrames: 120 },
+      );
       expect(warn).not.toHaveBeenCalled();
     } finally {
       warn.mockRestore();

packages/producer/src/services/render/artifactTransaction.ts

@@ -1,6 +1,7 @@
 import { closeSync, existsSync, fstatSync, openSync, readSync, readdirSync, rmSync } from "node:fs";
 import { basename, dirname, extname, join, resolve } from "node:path";
 import { HLS_MASTER_PLAYLIST, HLS_VIDEO_PLAYLIST, renameWithRetry } from "@hyperframes/engine";
+import { defaultLogger, type ProducerLogger } from "../../logger.js";
 import { extractMediaMetadata } from "../../utils/ffprobe.js";
 import type { RenderOutputFormat } from "./renderFormat.js";
 import { TRANSACTION_BACKUP, createOwnedRenderDir } from "./renderDirOwner.js";
@@ -51,11 +52,9 @@ export type ArtifactDurationProbe = (path: string) => Promise<ArtifactDurationPr
 
 async function defaultArtifactDurationProbe(path: string): Promise<ArtifactDurationProbeResult> {
   const meta = await extractMediaMetadata(path);
-  // Forward the probed frame count when ffprobe reported one. The frame
-  // count check (#3395) catches the multi-worker encode mode where the
-  // container duration is reported correctly but the decoded stream is
-  // shorter. When the demuxer cannot determine frames, the frame-count check
-  // is skipped quietly and duration validation still applies.
+  // WebM and HLS can omit frame counts even when duration is available.
+  // Keep that absence visible to validation; duration alone cannot prove
+  // every expected frame is present.
   return {
     durationSeconds: meta.durationSeconds,
     frames: meta.frames,
@@ -224,13 +223,17 @@ function assertDurationWithinTolerance(
   );
 }
 
+function hasUsableFrameCount(frames: number | undefined): frames is number {
+  return frames !== undefined && Number.isFinite(frames) && frames > 0;
+}
+
 function assertFrameCountWithinTolerance(
   expectedFrames: number,
   probedFrames: number | undefined,
   stagingPath: string,
   toleranceFrames = 1,
 ): void {
-  if (probedFrames === undefined || !Number.isFinite(probedFrames) || probedFrames <= 0) {
+  if (!hasUsableFrameCount(probedFrames)) {
     return;
   }
   const shortfall = expectedFrames - probedFrames;
@@ -288,6 +291,7 @@ export class ArtifactTransaction {
     private readonly kind: ArtifactKind,
     private readonly fileSystem: ArtifactTransactionFileSystem = defaultFileSystem,
     durationProbe: ArtifactDurationProbe = defaultArtifactDurationProbe,
+    private readonly logger: Pick<ProducerLogger, "debug"> = defaultLogger,
   ) {
     this.destinationPath = resolve(destinationPath);
     this.transactionDirectory = createSiblingTransactionDirectory(this.destinationPath);
@@ -382,8 +386,20 @@ export class ArtifactTransaction {
     );
 
     if (expected.expectedFrames !== undefined) {
-      // ffprobe reports `nb_frames=N/A` through the hls demuxer, so a playlist
-      // without frame metadata relies on the duration check above.
+      if (!hasUsableFrameCount(probed.frames)) {
+        try {
+          this.logger.debug(
+            "[Render] Frame-count validation skipped: no usable frame count was reported.",
+            {
+              event: "artifact_frame_count_unavailable",
+              artifact: this.destinationPath,
+              expectedFrames: expected.expectedFrames,
+            },
+          );
+        } catch {
+          // A diagnostic sink failure must not change the validation result.
+        }
+      }
       assertFrameCountWithinTolerance(expected.expectedFrames, probed.frames, probePath);
     }
     assertSizeMatches(expected, probed, probePath);

packages/producer/src/services/render/hlsRender.integration.test.ts

@@ -26,7 +26,7 @@ import {
 } from "node:fs";
 import { tmpdir } from "node:os";
 import { join } from "node:path";
-import { afterAll, beforeAll, describe, expect, it } from "vitest";
+import { afterAll, beforeAll, describe, expect, it, vi } from "vitest";
 import { getFfmpegBinary, getFfprobeBinary, resolveConfig } from "@hyperframes/engine";
 import { createRenderJob, executeRenderJob } from "../renderOrchestrator.js";
 
@@ -98,6 +98,8 @@ function extinfDurations(playlistPath: string): number[] {
 describe.skipIf(!HAS_FFMPEG)("format: hls — real render", () => {
   let root: string;
   let outputDir: string;
+  let renderJobId: string;
+  const debug = vi.fn();
 
   beforeAll(async () => {
     root = mkdtempSync(join(tmpdir(), "hf-hls-render-"));
@@ -130,9 +132,10 @@ describe.skipIf(!HAS_FFMPEG)("format: hls — real render", () => {
       hlsSegmentSeconds: SEGMENT_SECONDS,
       hdrMode: "force-sdr",
       workers: 1,
-      logger: { info() {}, warn() {}, error() {}, debug() {} },
+      logger: { info() {}, warn() {}, error() {}, debug },
       producerConfig: resolveConfig({ browserGpuMode: "software" }),
     });
+    renderJobId = job.id;
     await executeRenderJob(job, root, outputDir);
   }, 600_000);
 
@@ -140,6 +143,18 @@ describe.skipIf(!HAS_FFMPEG)("format: hls — real render", () => {
     if (root) rmSync(root, { recursive: true, force: true });
   });
 
+  it("reports unavailable playlist frame counts through the scoped render logger", () => {
+    expect(debug).toHaveBeenCalledWith(
+      "[Render] Frame-count validation skipped: no usable frame count was reported.",
+      expect.objectContaining({
+        event: "artifact_frame_count_unavailable",
+        artifact: outputDir,
+        expectedFrames: DURATION_SECONDS * FPS,
+        renderJobId,
+      }),
+    );
+  });
+
   it("publishes a directory with a master playlist referencing both renditions", () => {
     const master = readFileSync(join(outputDir, "master.m3u8"), "utf-8");
 

packages/producer/src/services/renderOrchestrator.ts

@@ -2937,6 +2937,9 @@ async function executeRenderPipeline(input: {
   const artifactTransaction = new ArtifactTransaction(
     outputPath,
     isPngSequence || isHls ? "directory" : "file",
+    undefined,
+    undefined,
+    log,
   );
   const stagedOutputPath = artifactTransaction.stagingPath;
   const needsAlpha = outputNeedsAlpha(outputFormat);