From 8fc85320e9b7059746ddeacc4f3c6897b2de8bae Mon Sep 17 00:00:00 2001 From: JSLMPR Date: Fri, 10 Jul 2026 18:58:57 +0200 Subject: [PATCH] Add cinematic edit observability --- docs/cinematic-video-editing-service-plan.md | 2 +- .../editing/AiDirectorPromptGenerator.java | 4 ++ .../videoclips/editing/EditObservability.java | 63 +++++++++++++++++++ .../editing/EditPlanInboxScanner.java | 2 + .../videoclips/editing/EditPlanService.java | 11 ++++ .../editing/EditProjectAnalyzer.java | 23 ++++++- .../editing/EditProjectService.java | 17 ++++- .../editing/FfmpegEditRenderer.java | 53 ++++++++++++++-- .../editing/StoryboardPromptGenerator.java | 11 ++++ .../editing/EditObservabilityTest.java | 37 +++++++++++ 10 files changed, 214 insertions(+), 9 deletions(-) create mode 100644 src/main/java/org/example/videoclips/editing/EditObservability.java create mode 100644 src/test/java/org/example/videoclips/editing/EditObservabilityTest.java diff --git a/docs/cinematic-video-editing-service-plan.md b/docs/cinematic-video-editing-service-plan.md index e9f10ad..55db9e0 100644 --- a/docs/cinematic-video-editing-service-plan.md +++ b/docs/cinematic-video-editing-service-plan.md @@ -804,7 +804,7 @@ It writes the script only and requires an imported audio file. 21. [x] Add basic transition support: cut, crossfade, fade in, fade out. 22. [x] Add SFX cue support. 23. [x] Add optional generated voiceover adapter interface. -24. [ ] Add structured logs and metrics for analysis, planning, and rendering durations. +24. [x] Add structured logs and metrics for analysis, planning, and rendering durations. 25. [ ] Add integration test with generated fixture clips and a short edit plan. 26. [ ] Add documentation for running a local cinematic edit with Codex or Claude as director. 27. [ ] Run `mvn verify` and update this checklist. diff --git a/src/main/java/org/example/videoclips/editing/AiDirectorPromptGenerator.java b/src/main/java/org/example/videoclips/editing/AiDirectorPromptGenerator.java index a4cefe6..0e65cd6 100644 --- a/src/main/java/org/example/videoclips/editing/AiDirectorPromptGenerator.java +++ b/src/main/java/org/example/videoclips/editing/AiDirectorPromptGenerator.java @@ -3,6 +3,8 @@ package org.example.videoclips.editing; import org.example.videoclips.config.VideoClippingProperties; import org.springframework.boot.autoconfigure.condition.ConditionalOnExpression; import org.springframework.stereotype.Component; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import java.io.IOException; import java.nio.file.Files; @@ -14,6 +16,7 @@ import java.nio.file.Path; public class AiDirectorPromptGenerator { private static final String README_FILE_NAME = "director-readme.md"; + private static final Logger log = LoggerFactory.getLogger(AiDirectorPromptGenerator.class); private final EditProjectStore store; private final StoryboardPromptGenerator storyboardPromptGenerator; @@ -43,6 +46,7 @@ public class AiDirectorPromptGenerator { } catch (IOException ex) { throw new IllegalStateException("Unable to write AI director files for project: " + projectId, ex); } + log.info("event=ai_director_prompt_generated project_id={} path={}", projectId, promptPath); return new DirectorPromptFiles(promptPath.toString(), readmePath.toString()); } diff --git a/src/main/java/org/example/videoclips/editing/EditObservability.java b/src/main/java/org/example/videoclips/editing/EditObservability.java new file mode 100644 index 0000000..52de9fa --- /dev/null +++ b/src/main/java/org/example/videoclips/editing/EditObservability.java @@ -0,0 +1,63 @@ +package org.example.videoclips.editing; + +import io.micrometer.core.instrument.MeterRegistry; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty; +import org.springframework.stereotype.Component; + +import java.time.Duration; + +@Component +@ConditionalOnProperty(name = "video-clipping.editing.enabled", havingValue = "true", matchIfMissing = true) +public class EditObservability { + + private static final Logger log = LoggerFactory.getLogger(EditObservability.class); + + private final MeterRegistry registry; + + public EditObservability(MeterRegistry registry) { + this.registry = registry; + } + + public void projectCreated(String projectId) { + registry.counter("video.clipping.edit.projects.created").increment(); + log.info("event=edit_project_created project_id={}", projectId); + } + + public void analysisStarted(String projectId, int candidateCount) { + log.info("event=edit_analysis_started project_id={} candidate_count={}", projectId, candidateCount); + } + + public void analysisCompleted(String projectId, long elapsedNanos, int clipCount, int errorCount) { + registry.timer("video.clipping.edit.analysis.duration").record(Duration.ofNanos(elapsedNanos)); + log.info("event=edit_analysis_completed project_id={} elapsed_ms={} clip_count={} error_count={}", + projectId, elapsedNanos / 1_000_000, clipCount, errorCount); + } + + public void promptGenerated(String event, String projectId, String path) { + log.info("event={} project_id={} path={}", event, projectId, path); + } + + public void planSaved(String projectId, int decisionCount, String source) { + log.info("event=edit_plan_saved project_id={} decision_count={} source={}", + projectId, decisionCount, source); + } + + public void renderStarted(String projectId, int decisionCount) { + log.info("event=edit_render_started project_id={} decision_count={}", projectId, decisionCount); + } + + public void renderCompleted(String projectId, long elapsedNanos, String outputPath, double durationSeconds) { + registry.timer("video.clipping.edit.render.duration").record(Duration.ofNanos(elapsedNanos)); + log.info("event=edit_render_completed project_id={} elapsed_ms={} output={} duration_seconds={}", + projectId, elapsedNanos / 1_000_000, outputPath, durationSeconds); + } + + public void renderFailed(String projectId, long elapsedNanos, RuntimeException failure) { + registry.counter("video.clipping.edit.render.failures").increment(); + registry.timer("video.clipping.edit.render.duration").record(Duration.ofNanos(elapsedNanos)); + log.error("event=edit_render_failed project_id={} elapsed_ms={} error_type={} message={}", + projectId, elapsedNanos / 1_000_000, failure.getClass().getSimpleName(), failure.getMessage()); + } +} diff --git a/src/main/java/org/example/videoclips/editing/EditPlanInboxScanner.java b/src/main/java/org/example/videoclips/editing/EditPlanInboxScanner.java index 5bf2195..bcd55b3 100644 --- a/src/main/java/org/example/videoclips/editing/EditPlanInboxScanner.java +++ b/src/main/java/org/example/videoclips/editing/EditPlanInboxScanner.java @@ -121,6 +121,8 @@ public class EditPlanInboxScanner { projectService.updateProject(projectId, EditProjectStatus.PLANNED, Path.of(project.inputDirectory()), null); log.info("event=edit_plan_imported project_id={} decision_count={} auto_render={}", projectId, plan.decisions().size(), autoRender); + log.info("event=edit_plan_saved project_id={} decision_count={} source=inbox", + projectId, plan.decisions().size()); if (autoRender) { renderer.orElseThrow(() -> new IllegalStateException( "Automatic rendering is enabled but no EditRenderer is available")).render(projectId); diff --git a/src/main/java/org/example/videoclips/editing/EditPlanService.java b/src/main/java/org/example/videoclips/editing/EditPlanService.java index 86799ae..9e4e163 100644 --- a/src/main/java/org/example/videoclips/editing/EditPlanService.java +++ b/src/main/java/org/example/videoclips/editing/EditPlanService.java @@ -15,11 +15,19 @@ public class EditPlanService { private final EditProjectStore store; private final EditProjectService projectService; private final EditPlanValidator validator; + private final EditObservability observability; public EditPlanService(EditProjectStore store, EditProjectService projectService, EditPlanValidator validator) { + this(store, projectService, validator, null); + } + + @org.springframework.beans.factory.annotation.Autowired + public EditPlanService(EditProjectStore store, EditProjectService projectService, EditPlanValidator validator, + EditObservability observability) { this.store = store; this.projectService = projectService; this.validator = validator; + this.observability = observability; } public EditPlan save(String projectId, SaveEditPlanRequest request) { @@ -30,6 +38,9 @@ public class EditPlanService { store.writeJson(projectId, "edit-plan.json", plan); EditProjectResponse project = projectService.getProject(projectId); projectService.updateProject(projectId, EditProjectStatus.PLANNED, Path.of(project.inputDirectory()), null); + if (observability != null) { + observability.planSaved(projectId, plan.decisions().size(), "api"); + } return plan; } } diff --git a/src/main/java/org/example/videoclips/editing/EditProjectAnalyzer.java b/src/main/java/org/example/videoclips/editing/EditProjectAnalyzer.java index f67f009..3010396 100644 --- a/src/main/java/org/example/videoclips/editing/EditProjectAnalyzer.java +++ b/src/main/java/org/example/videoclips/editing/EditProjectAnalyzer.java @@ -22,6 +22,7 @@ public class EditProjectAnalyzer { private final ContactSheetGenerator contactSheetGenerator; private final ProxyGenerator proxyGenerator; private final Clock clock; + private final EditObservability observability; @Autowired public EditProjectAnalyzer( @@ -30,9 +31,11 @@ public class EditProjectAnalyzer { FfmpegClipInspector inspector, ThumbnailExtractor thumbnailExtractor, ContactSheetGenerator contactSheetGenerator, - ProxyGenerator proxyGenerator + ProxyGenerator proxyGenerator, + EditObservability observability ) { - this(store, discovery, inspector, thumbnailExtractor, contactSheetGenerator, proxyGenerator, Clock.systemUTC()); + this(store, discovery, inspector, thumbnailExtractor, contactSheetGenerator, proxyGenerator, + Clock.systemUTC(), observability); } EditProjectAnalyzer( @@ -43,6 +46,14 @@ public class EditProjectAnalyzer { ContactSheetGenerator contactSheetGenerator, ProxyGenerator proxyGenerator, Clock clock + ) { + this(store, discovery, inspector, thumbnailExtractor, contactSheetGenerator, proxyGenerator, clock, null); + } + + EditProjectAnalyzer( + EditProjectStore store, EditClipDiscovery discovery, FfmpegClipInspector inspector, + ThumbnailExtractor thumbnailExtractor, ContactSheetGenerator contactSheetGenerator, + ProxyGenerator proxyGenerator, Clock clock, EditObservability observability ) { this.store = store; this.discovery = discovery; @@ -51,10 +62,15 @@ public class EditProjectAnalyzer { this.contactSheetGenerator = contactSheetGenerator; this.proxyGenerator = proxyGenerator; this.clock = clock; + this.observability = observability; } public EditProjectAnalysis analyze(String projectId, Path inputDirectory) { + long startedAt = System.nanoTime(); List candidates = discovery.discover(inputDirectory); + if (observability != null) { + observability.analysisStarted(projectId, candidates.size()); + } if (candidates.isEmpty()) { throw new BadRequestException("Edit project input directory does not contain valid video clips"); } @@ -84,6 +100,9 @@ public class EditProjectAnalyzer { EditProjectAnalysis analysis = new EditProjectAnalysis(projectId, List.copyOf(clips), List.copyOf(errors), Instant.now(clock)); store.writeJson(projectId, "analysis.json", analysis); + if (observability != null) { + observability.analysisCompleted(projectId, System.nanoTime() - startedAt, clips.size(), errors.size()); + } return analysis; } diff --git a/src/main/java/org/example/videoclips/editing/EditProjectService.java b/src/main/java/org/example/videoclips/editing/EditProjectService.java index 59e8003..bbdc403 100644 --- a/src/main/java/org/example/videoclips/editing/EditProjectService.java +++ b/src/main/java/org/example/videoclips/editing/EditProjectService.java @@ -20,15 +20,25 @@ public class EditProjectService { private final EditProjectStore store; private final Clock clock; + private final EditObservability observability; + + public EditProjectService(EditProjectStore store) { + this(store, Clock.systemUTC(), null); + } @Autowired - public EditProjectService(EditProjectStore store) { - this(store, Clock.systemUTC()); + public EditProjectService(EditProjectStore store, EditObservability observability) { + this(store, Clock.systemUTC(), observability); } EditProjectService(EditProjectStore store, Clock clock) { + this(store, clock, null); + } + + EditProjectService(EditProjectStore store, Clock clock, EditObservability observability) { this.store = store; this.clock = clock; + this.observability = observability; } public EditProjectResponse createProject(CreateEditProjectRequest request) { @@ -56,6 +66,9 @@ public class EditProjectService { null ); store.writeJson(projectId, "project.json", project); + if (observability != null) { + observability.projectCreated(projectId); + } return response(project); } diff --git a/src/main/java/org/example/videoclips/editing/FfmpegEditRenderer.java b/src/main/java/org/example/videoclips/editing/FfmpegEditRenderer.java index 21fb9ee..0b5380a 100644 --- a/src/main/java/org/example/videoclips/editing/FfmpegEditRenderer.java +++ b/src/main/java/org/example/videoclips/editing/FfmpegEditRenderer.java @@ -28,38 +28,80 @@ public class FfmpegEditRenderer implements EditRenderer { private final EditPlanValidator validator; private final ProcessExecutor executor; private final VoiceoverGenerator voiceoverGenerator; + private final EditObservability observability; public FfmpegEditRenderer(VideoClippingProperties properties, EditProjectStore store, EditProjectService projectService, EditPlanValidator validator) { - this(properties, store, projectService, validator, null, FfmpegEditRenderer::execute); + this(properties, store, projectService, validator, null, null, FfmpegEditRenderer::execute); + } + + public FfmpegEditRenderer(VideoClippingProperties properties, EditProjectStore store, + EditProjectService projectService, EditPlanValidator validator, + VoiceoverGenerator voiceoverGenerator) { + this(properties, store, projectService, validator, voiceoverGenerator, null, FfmpegEditRenderer::execute); } @Autowired public FfmpegEditRenderer(VideoClippingProperties properties, EditProjectStore store, EditProjectService projectService, EditPlanValidator validator, - VoiceoverGenerator voiceoverGenerator) { - this(properties, store, projectService, validator, voiceoverGenerator, FfmpegEditRenderer::execute); + VoiceoverGenerator voiceoverGenerator, EditObservability observability) { + this(properties, store, projectService, validator, voiceoverGenerator, observability, + FfmpegEditRenderer::execute); } FfmpegEditRenderer(VideoClippingProperties properties, EditProjectStore store, EditProjectService projectService, EditPlanValidator validator, ProcessExecutor executor) { - this(properties, store, projectService, validator, null, executor); + this(properties, store, projectService, validator, null, null, executor); } FfmpegEditRenderer(VideoClippingProperties properties, EditProjectStore store, EditProjectService projectService, EditPlanValidator validator, VoiceoverGenerator voiceoverGenerator, ProcessExecutor executor) { + this(properties, store, projectService, validator, voiceoverGenerator, null, executor); + } + + FfmpegEditRenderer(VideoClippingProperties properties, EditProjectStore store, + EditProjectService projectService, EditPlanValidator validator, + VoiceoverGenerator voiceoverGenerator, EditObservability observability, + ProcessExecutor executor) { this.properties = properties.getEditing(); this.store = store; this.projectService = projectService; this.validator = validator; this.executor = executor; this.voiceoverGenerator = voiceoverGenerator; + this.observability = observability; } @Override public void render(String projectId) { + long startedAt = System.nanoTime(); + try { + renderInternal(projectId, startedAt); + } catch (RuntimeException ex) { + if (observability != null) { + observability.renderFailed(projectId, System.nanoTime() - startedAt, ex); + } + markFailed(projectId, ex); + throw ex; + } + } + + private void markFailed(String projectId, RuntimeException failure) { + try { + EditProjectResponse project = projectService.getProject(projectId); + projectService.updateProject(projectId, EditProjectStatus.FAILED, + Path.of(project.inputDirectory()), failure.getMessage()); + } catch (RuntimeException ignored) { + // Preserve the render failure when project-state persistence is also unavailable. + } + } + + private void renderInternal(String projectId, long startedAt) { EditPlan plan = validator.validate(projectId, store.readJson(projectId, "edit-plan.json", EditPlan.class)); + if (observability != null) { + observability.renderStarted(projectId, plan.decisions().size()); + } EditProjectAnalysis analysis = store.readJson(projectId, "analysis.json", EditProjectAnalysis.class); EditProjectResponse project = projectService.getProject(projectId); if (voiceoverGenerator != null && !plan.voiceover().isEmpty()) { @@ -102,6 +144,9 @@ public class FfmpegEditRenderer implements EditRenderer { List.copyOf(commands), Instant.now()); store.writeJson(projectId, "render-manifest.json", manifest); projectService.updateProject(projectId, EditProjectStatus.RENDERED, Path.of(project.inputDirectory()), null); + if (observability != null) { + observability.renderCompleted(projectId, System.nanoTime() - startedAt, output.toString(), duration); + } } List segmentCommand(String source, EditDecision decision, Path output) { diff --git a/src/main/java/org/example/videoclips/editing/StoryboardPromptGenerator.java b/src/main/java/org/example/videoclips/editing/StoryboardPromptGenerator.java index 8b43ff0..9a4710b 100644 --- a/src/main/java/org/example/videoclips/editing/StoryboardPromptGenerator.java +++ b/src/main/java/org/example/videoclips/editing/StoryboardPromptGenerator.java @@ -3,6 +3,7 @@ package org.example.videoclips.editing; import org.example.videoclips.api.dto.StoryboardPromptResponse; import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty; import org.springframework.stereotype.Component; +import org.springframework.beans.factory.annotation.Autowired; import java.io.IOException; import java.nio.file.Files; @@ -14,9 +15,16 @@ import java.util.List; public class StoryboardPromptGenerator { private final EditProjectStore store; + private final EditObservability observability; public StoryboardPromptGenerator(EditProjectStore store) { + this(store, null); + } + + @Autowired + public StoryboardPromptGenerator(EditProjectStore store, EditObservability observability) { this.store = store; + this.observability = observability; } public StoryboardPromptResponse generate(String projectId) { @@ -28,6 +36,9 @@ public class StoryboardPromptGenerator { } catch (IOException ex) { throw new IllegalStateException("Unable to write storyboard prompt for project: " + projectId, ex); } + if (observability != null) { + observability.promptGenerated("storyboard_prompt_generated", projectId, promptPath.toString()); + } return new StoryboardPromptResponse(projectId, promptPath.toString()); } diff --git a/src/test/java/org/example/videoclips/editing/EditObservabilityTest.java b/src/test/java/org/example/videoclips/editing/EditObservabilityTest.java new file mode 100644 index 0000000..95968cf --- /dev/null +++ b/src/test/java/org/example/videoclips/editing/EditObservabilityTest.java @@ -0,0 +1,37 @@ +package org.example.videoclips.editing; + +import io.micrometer.core.instrument.simple.SimpleMeterRegistry; +import org.junit.jupiter.api.Test; + +import static org.assertj.core.api.Assertions.assertThat; + +class EditObservabilityTest { + + @Test + void recordsProjectAnalysisAndSuccessfulRenderMetrics() { + SimpleMeterRegistry registry = new SimpleMeterRegistry(); + EditObservability observability = new EditObservability(registry); + + observability.projectCreated("project"); + observability.analysisStarted("project", 35); + observability.analysisCompleted("project", 2_000_000, 35, 0); + observability.renderStarted("project", 12); + observability.renderCompleted("project", 5_000_000, "final.mp4", 60); + + assertThat(registry.counter("video.clipping.edit.projects.created").count()).isEqualTo(1); + assertThat(registry.timer("video.clipping.edit.analysis.duration").count()).isEqualTo(1); + assertThat(registry.timer("video.clipping.edit.render.duration").count()).isEqualTo(1); + assertThat(registry.counter("video.clipping.edit.render.failures").count()).isZero(); + } + + @Test + void recordsRenderFailures() { + SimpleMeterRegistry registry = new SimpleMeterRegistry(); + EditObservability observability = new EditObservability(registry); + + observability.renderFailed("project", 3_000_000, new IllegalStateException("ffmpeg failed")); + + assertThat(registry.counter("video.clipping.edit.render.failures").count()).isEqualTo(1); + assertThat(registry.timer("video.clipping.edit.render.duration").count()).isEqualTo(1); + } +}