Add rich video editing diagnostics

docs/local-cv-visual-analysis-guide.md

@@ -41,7 +41,7 @@ VIDEO_EDITING_VISUAL_ANALYSIS_PROVIDER=local-cv
 VIDEO_EDITING_VISUAL_ANALYSIS_ENDPOINT=http://127.0.0.1:8091/v1/analyze-visuals
 VIDEO_EDITING_VISUAL_ANALYSIS_TIMEOUT_MS=30000
 VIDEO_EDITING_VISUAL_ANALYSIS_FALLBACK_TO_HEURISTIC=true
-VIDEO_EDITING_LOCAL_CV_WORKER_AUTO_START=false
+VIDEO_EDITING_LOCAL_CV_WORKER_AUTO_START=true
 VIDEO_EDITING_LOCAL_CV_WORKER_SCRIPT=./tools/run_local_cv_worker.sh
 VIDEO_EDITING_LOCAL_CV_WORKER_STARTUP_WAIT_MS=0
 ```

src/main/java/org/example/videoclips/editing/HighlightSourceAnalyzer.java

@@ -3,6 +3,8 @@ package org.example.videoclips.editing;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty;
 import org.springframework.stereotype.Service;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import java.nio.file.Files;
 import java.nio.file.Path;
@@ -15,6 +17,8 @@ import java.util.List;
 @ConditionalOnProperty(name = "video-clipping.editing.enabled", havingValue = "true", matchIfMissing = true)
 public class HighlightSourceAnalyzer {
 
+    private static final Logger log = LoggerFactory.getLogger(HighlightSourceAnalyzer.class);
+
     private final HighlightProjectStore store;
     private final FfmpegClipInspector inspector;
     private final ThumbnailExtractor thumbnailExtractor;
@@ -68,22 +72,54 @@ public class HighlightSourceAnalyzer {
     }
 
     public HighlightSourceAnalysis analyze(String projectId) {
+        long totalStartedAt = System.nanoTime();
+        log.info("event=highlight_analysis_started project_id={}", projectId);
         HighlightProject project = store.readJson(projectId, "project.json", HighlightProject.class);
+        log.info("event=highlight_analysis_project_loaded project_id={} source_file={} status={}",
+                projectId, project.sourceVideoFileName(), project.status());
         Path source = sourceVideo(projectId);
-        ClipAnalysis inspected = inspector.inspect(source);
+        log.info("event=highlight_analysis_source_discovered project_id={} source_path={}", projectId, source);
+        ClipAnalysis inspected = timed(projectId, "ffprobe_inspection", () -> inspector.inspect(source));
         Path analysisDirectory = store.analysisDirectory(projectId);
         Path frameDirectory = analysisDirectory.resolve("frames");
         Path contactSheetDirectory = analysisDirectory.resolve("contact-sheets");
         Path proxyDirectory = analysisDirectory.resolve("proxies");
         Path audioDirectory = analysisDirectory.resolve("audio");
 
-        List<String> thumbnails = thumbnailExtractor.extract(inspected, frameDirectory);
+        log.info("event=highlight_analysis_media_metadata project_id={} clip_id={} duration_seconds={} codec_video={} "
-        String contactSheet = contactSheetGenerator.generate(inspected, contactSheetDirectory);
+                        + "codec_audio={} width={} height={} frame_rate={}",
-        String proxyPath = proxyGenerator.generate(inspected, proxyDirectory).orElse(null);
+                projectId, inspected.clipId(), inspected.durationSeconds(), inspected.videoCodec(),
-        String waveformPath = waveformGenerator.generate(inspected, audioDirectory);
+                inspected.audioCodec(), inspected.width(), inspected.height(), inspected.frameRate());
-        List<ShotSegment> shotSegments = shotSceneSegmenter.segment(inspected);
+        List<String> thumbnails = timed(projectId, "thumbnail_extraction",
-        SourceAudioAnalysis audioAnalysis = sourceAudioAnalyzer.analyze(inspected);
+                () -> thumbnailExtractor.extract(inspected, frameDirectory));
-        SourceVisualAnalysis visualAnalysis = sourceVisualAnalyzer.analyze(inspected, thumbnails, shotSegments);
+        log.info("event=highlight_analysis_thumbnails_ready project_id={} count={} directory={} thumbnails={}",
+                projectId, thumbnails.size(), frameDirectory, thumbnails);
+        String contactSheet = timed(projectId, "contact_sheet_generation",
+                () -> contactSheetGenerator.generate(inspected, contactSheetDirectory));
+        log.info("event=highlight_analysis_contact_sheet_ready project_id={} path={}", projectId, contactSheet);
+        String proxyPath = timed(projectId, "proxy_generation",
+                () -> proxyGenerator.generate(inspected, proxyDirectory).orElse(null));
+        log.info("event=highlight_analysis_proxy_ready project_id={} enabled={} path={}",
+                projectId, proxyPath != null, proxyPath);
+        String waveformPath = timed(projectId, "waveform_generation",
+                () -> waveformGenerator.generate(inspected, audioDirectory));
+        log.info("event=highlight_analysis_waveform_ready project_id={} path={}", projectId, waveformPath);
+        List<ShotSegment> shotSegments = timed(projectId, "shot_scene_segmentation",
+                () -> shotSceneSegmenter.segment(inspected));
+        log.info("event=highlight_analysis_shots_ready project_id={} shot_segments={} first_shot={} last_shot={}",
+                projectId, shotSegments.size(), shotSegments.isEmpty() ? null : shotSegments.get(0),
+                shotSegments.isEmpty() ? null : shotSegments.get(shotSegments.size() - 1));
+        SourceAudioAnalysis audioAnalysis = timed(projectId, "audio_analysis",
+                () -> sourceAudioAnalyzer.analyze(inspected));
+        log.info("event=highlight_analysis_audio_ready project_id={} sections={} mean_volume_db={} max_volume_db={}",
+                projectId, audioAnalysis.sections().size(), audioAnalysis.meanVolumeDb(), audioAnalysis.maxVolumeDb());
+        SourceVisualAnalysis visualAnalysis = timed(projectId, "visual_analysis",
+                () -> sourceVisualAnalyzer.analyze(inspected, thumbnails, shotSegments));
+        log.info("event=highlight_analysis_visual_ready project_id={} method={} blur_score={} exposure_score={} "
+                        + "motion_score={} composition_score={} face_presence={} object_labels={}",
+                projectId, visualAnalysis.analysisMethod(), visualAnalysis.blurScore(), visualAnalysis.exposureScore(),
+                visualAnalysis.motionScore(), visualAnalysis.compositionScore(), visualAnalysis.facePresence(),
+                visualAnalysis.objectLabels().size());
         ClipAnalysis sourceAnalysis = enriched(inspected, thumbnails, contactSheet, proxyPath);
         HighlightSourceAnalysis analysis = new HighlightSourceAnalysis(
                 projectId,
@@ -101,14 +137,56 @@ public class HighlightSourceAnalyzer {
                 visualAnalysis,
                 Instant.now(clock)
         );
-        store.writeJson(projectId, "analysis/ffprobe.json", sourceAnalysis);
+        timed(projectId, "persist_ffprobe_json", () -> {
-        store.writeJson(projectId, "analysis/scene-segments.json", shotSegments);
+            store.writeJson(projectId, "analysis/ffprobe.json", sourceAnalysis);
-        store.writeJson(projectId, "analysis/audio-analysis.json", audioAnalysis);
+            return null;
-        store.writeJson(projectId, "analysis/visual-analysis.json", visualAnalysis);
+        });
-        store.writeJson(projectId, "analysis/source-analysis.json", analysis);
+        timed(projectId, "persist_scene_segments_json", () -> {
+            store.writeJson(projectId, "analysis/scene-segments.json", shotSegments);
+            return null;
+        });
+        timed(projectId, "persist_audio_analysis_json", () -> {
+            store.writeJson(projectId, "analysis/audio-analysis.json", audioAnalysis);
+            return null;
+        });
+        timed(projectId, "persist_visual_analysis_json", () -> {
+            store.writeJson(projectId, "analysis/visual-analysis.json", visualAnalysis);
+            return null;
+        });
+        timed(projectId, "persist_source_analysis_json", () -> {
+            store.writeJson(projectId, "analysis/source-analysis.json", analysis);
+            return null;
+        });
+        log.info("event=highlight_analysis_completed project_id={} elapsed_ms={} analysis_file={}",
+                projectId, elapsedMillis(totalStartedAt), "analysis/source-analysis.json");
         return analysis;
     }
 
+    private <T> T timed(String projectId, String step, Step<T> action) {
+        long startedAt = System.nanoTime();
+        log.info("event=highlight_analysis_step_started project_id={} step={}", projectId, step);
+        try {
+            T result = action.run();
+            log.info("event=highlight_analysis_step_completed project_id={} step={} elapsed_ms={}",
+                    projectId, step, elapsedMillis(startedAt));
+            return result;
+        } catch (RuntimeException ex) {
+            log.error("event=highlight_analysis_step_failed project_id={} step={} elapsed_ms={} error_type={} "
+                            + "message={}",
+                    projectId, step, elapsedMillis(startedAt), ex.getClass().getSimpleName(), ex.getMessage());
+            throw ex;
+        }
+    }
+
+    private long elapsedMillis(long startedAt) {
+        return (System.nanoTime() - startedAt) / 1_000_000;
+    }
+
+    @FunctionalInterface
+    private interface Step<T> {
+        T run();
+    }
+
     private Path sourceVideo(String projectId) {
         Path sourceDirectory = store.sourceDirectory(projectId);
         try (var files = Files.list(sourceDirectory)) {

src/main/java/org/example/videoclips/editing/HighlightSourceScheduler.java

@@ -82,15 +82,19 @@ public class HighlightSourceScheduler {
 
         long scanId = scanSequence.incrementAndGet();
         long startedAt = System.nanoTime();
+        log.info("event=highlight_scan_started scan_id={} source_directory={} working_directory={} "
+                        + "processed_directory={} rejected_directory={}",
+                scanId, properties.getSourceDirectory(), properties.getWorkingDirectory(),
+                properties.getProcessedDirectory(), properties.getRejectedDirectory());
         try {
             findNextCandidate().ifPresentOrElse(
                     candidate -> processCandidate(scanId, candidate),
-                    () -> log.debug("event=highlight_scan_idle scan_id={} source_directory={}",
+                    () -> log.info("event=highlight_scan_idle scan_id={} source_directory={}",
                             scanId, properties.getSourceDirectory())
             );
         } finally {
             scanning.set(false);
-            log.debug("event=highlight_scan_completed scan_id={} elapsed_ms={}", scanId, elapsedMillis(startedAt));
+            log.info("event=highlight_scan_completed scan_id={} elapsed_ms={}", scanId, elapsedMillis(startedAt));
         }
     }
 
@@ -144,10 +148,20 @@ public class HighlightSourceScheduler {
                 HighlightFolderContract.standard(),
                 now
         );
+        log.info("event=highlight_project_creation_started scan_id={} project_id={} working_file={}",
+                scanId, projectId, workingFile);
         Path projectDirectory = store.createProject(project, manifest);
+        log.info("event=highlight_project_directory_created scan_id={} project_id={} project_directory={}",
+                scanId, projectId, projectDirectory);
         copySourceToProject(workingFile, store.sourceDirectory(projectId).resolve(workingFile.getFileName()));
+        log.info("event=highlight_source_copied_to_project scan_id={} project_id={} source_file={} "
+                        + "project_source_directory={}",
+                scanId, projectId, workingFile.getFileName(), store.sourceDirectory(projectId));
         HighlightSourceAnalysis analysis = analyzer.analyze(projectId);
         Path processedFile = moveToDirectory(workingFile, Path.of(properties.getProcessedDirectory()));
+        log.info("event=highlight_source_moved_to_processed scan_id={} project_id={} processed_file={} "
+                        + "processed_directory={}",
+                scanId, projectId, processedFile.getFileName(), processedFile.getParent());
         log.info("event=highlight_project_created scan_id={} project_id={} source_file={} project_directory={} "
                         + "analysis_file={} elapsed_ms={}",
                 scanId, projectId, processedFile.getFileName(), projectDirectory, "analysis/source-analysis.json",

src/main/java/org/example/videoclips/editing/LocalCvVisualAnalysisProvider.java

@@ -2,6 +2,8 @@ package org.example.videoclips.editing;
 
 import com.fasterxml.jackson.databind.ObjectMapper;
 import org.example.videoclips.config.VideoClippingProperties;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty;
 import org.springframework.stereotype.Component;
@@ -11,6 +13,7 @@ import java.net.URI;
 import java.net.http.HttpClient;
 import java.net.http.HttpRequest;
 import java.net.http.HttpResponse;
+import java.nio.charset.StandardCharsets;
 import java.time.Duration;
 import java.util.List;
 
@@ -18,6 +21,8 @@ import java.util.List;
 @ConditionalOnProperty(name = "video-clipping.editing.enabled", havingValue = "true", matchIfMissing = true)
 public class LocalCvVisualAnalysisProvider implements VisualAnalysisProvider {
 
+    private static final Logger log = LoggerFactory.getLogger(LocalCvVisualAnalysisProvider.class);
+
     private final VideoClippingProperties.Editing.VisualAnalysis properties;
     private final ObjectMapper objectMapper;
     private final HttpExecutor httpExecutor;
@@ -40,20 +45,46 @@ public class LocalCvVisualAnalysisProvider implements VisualAnalysisProvider {
     @Override
     public SourceVisualAnalysis analyze(ClipAnalysis source, List<String> thumbnails, List<ShotSegment> shotSegments) {
         LocalCvRequest request = new LocalCvRequest(source, List.copyOf(thumbnails), List.copyOf(shotSegments));
+        long startedAt = System.nanoTime();
         try {
             String body = objectMapper.writeValueAsString(request);
+            log.info("event=local_cv_request_started clip_id={} endpoint={} timeout_ms={} thumbnails={} "
+                            + "shot_segments={} request_bytes={}",
+                    source.clipId(), properties.getEndpoint(), properties.getTimeoutMs(), thumbnails.size(),
+                    shotSegments.size(), body.getBytes(StandardCharsets.UTF_8).length);
             HttpCall call = new HttpCall(properties.getEndpoint(), properties.getTimeoutMs(), body);
             HttpResult result = httpExecutor.execute(call);
+            log.info("event=local_cv_response_received clip_id={} endpoint={} status_code={} elapsed_ms={} "
+                            + "response_bytes={}",
+                    source.clipId(), properties.getEndpoint(), result.statusCode(), elapsedMillis(startedAt),
+                    result.body() == null ? 0 : result.body().getBytes(StandardCharsets.UTF_8).length);
             if (result.statusCode() < 200 || result.statusCode() >= 300) {
-                throw new IllegalStateException("Local CV service returned HTTP " + result.statusCode());
+                throw new IllegalStateException("Local CV service returned HTTP " + result.statusCode()
+                        + " body=" + preview(result.body()));
             }
             SourceVisualAnalysis analysis = objectMapper.readValue(result.body(), SourceVisualAnalysis.class);
-            return normalized(source, thumbnails, analysis);
+            SourceVisualAnalysis normalized = normalized(source, thumbnails, analysis);
+            log.info("event=local_cv_analysis_completed clip_id={} endpoint={} elapsed_ms={} method={} "
+                            + "object_labels={} representative_thumbnails={}",
+                    source.clipId(), properties.getEndpoint(), elapsedMillis(startedAt),
+                    normalized.analysisMethod(), normalized.objectLabels().size(),
+                    normalized.representativeThumbnails().size());
+            return normalized;
         } catch (InterruptedException ex) {
             Thread.currentThread().interrupt();
+            log.warn("event=local_cv_request_interrupted clip_id={} endpoint={} elapsed_ms={} message={}",
+                    source.clipId(), properties.getEndpoint(), elapsedMillis(startedAt), ex.getMessage());
             throw new IllegalStateException("Interrupted while calling local CV visual analysis service", ex);
         } catch (IOException ex) {
+            log.warn("event=local_cv_request_failed clip_id={} endpoint={} elapsed_ms={} error_type={} message={}",
+                    source.clipId(), properties.getEndpoint(), elapsedMillis(startedAt),
+                    ex.getClass().getSimpleName(), ex.getMessage());
             throw new IllegalStateException("Unable to call local CV visual analysis service", ex);
+        } catch (RuntimeException ex) {
+            log.warn("event=local_cv_analysis_failed clip_id={} endpoint={} elapsed_ms={} error_type={} message={}",
+                    source.clipId(), properties.getEndpoint(), elapsedMillis(startedAt),
+                    ex.getClass().getSimpleName(), ex.getMessage());
+            throw ex;
         }
     }
 
@@ -85,6 +116,18 @@ public class LocalCvVisualAnalysisProvider implements VisualAnalysisProvider {
         return Math.max(0, Math.min(1, Math.round(value * 1000.0) / 1000.0));
     }
 
+    private long elapsedMillis(long startedAt) {
+        return (System.nanoTime() - startedAt) / 1_000_000;
+    }
+
+    private String preview(String body) {
+        if (body == null || body.isBlank()) {
+            return "";
+        }
+        String compact = body.replaceAll("\\s+", " ").trim();
+        return compact.length() <= 300 ? compact : compact.substring(0, 300) + "...";
+    }
+
     record LocalCvRequest(ClipAnalysis source, List<String> thumbnails, List<ShotSegment> shotSegments) {
     }
 

src/main/java/org/example/videoclips/editing/LocalCvWorkerProcessManager.java

@@ -30,7 +30,9 @@ public class LocalCvWorkerProcessManager implements SmartLifecycle {
     private final ProcessLauncher processLauncher;
     private Process process;
     private Thread outputThread;
-    private boolean running;
+    private Thread watcherThread;
+    private volatile boolean running;
+    private volatile boolean stopping;
 
     @Autowired
     public LocalCvWorkerProcessManager(VideoClippingProperties properties) {
@@ -47,12 +49,22 @@ public class LocalCvWorkerProcessManager implements SmartLifecycle {
 
     @Override
     public synchronized void start() {
-        if (running || !shouldStart()) {
+        if (running) {
+            log.info("event=local_cv_worker_start_skipped reason=already_running endpoint={}",
+                    visualAnalysis.getEndpoint());
+            return;
+        }
+        if (!shouldStart()) {
+            log.info("event=local_cv_worker_start_skipped reason=disabled provider={} auto_start={} endpoint={}",
+                    visualAnalysis.getProvider(), visualAnalysis.getLocalCvWorker().isAutoStart(),
+                    visualAnalysis.getEndpoint());
             return;
         }
 
         VideoClippingProperties.Editing.VisualAnalysis.LocalCvWorker worker = visualAnalysis.getLocalCvWorker();
         Path script = Path.of(worker.getScript()).toAbsolutePath().normalize();
+        log.info("event=local_cv_worker_starting script={} endpoint={} startup_wait_ms={}",
+                script, visualAnalysis.getEndpoint(), worker.getStartupWaitMs());
         if (!Files.isRegularFile(script)) {
             throw new IllegalStateException("Local CV worker script does not exist: " + script);
         }
@@ -67,16 +79,25 @@ public class LocalCvWorkerProcessManager implements SmartLifecycle {
         try {
             process = processLauncher.start(processBuilder);
             running = true;
+            stopping = false;
             outputThread = outputReader(process.getInputStream(), script);
             outputThread.start();
-            log.info("event=local_cv_worker_started script={} pid={} host={} port={}",
+            watcherThread = processWatcher(process, script);
-                    script, process.pid(), endpoint.host(), endpoint.port());
+            watcherThread.start();
+            log.info("event=local_cv_worker_started script={} pid={} host={} port={} endpoint={}",
+                    script, process.pid(), endpoint.host(), endpoint.port(), visualAnalysis.getEndpoint());
             waitForStartupWindow(worker.getStartupWaitMs());
+            log.info("event=local_cv_worker_startup_window_completed script={} pid={} alive={}",
+                    script, process.pid(), process.isAlive());
         } catch (IOException ex) {
             running = false;
+            log.error("event=local_cv_worker_start_failed script={} error_type={} message={}",
+                    script, ex.getClass().getSimpleName(), ex.getMessage());
             throw new IllegalStateException("Unable to start local CV worker script: " + script, ex);
         } catch (RuntimeException ex) {
             cleanupFailedStart();
+            log.error("event=local_cv_worker_start_failed script={} error_type={} message={}",
+                    script, ex.getClass().getSimpleName(), ex.getMessage());
             throw ex;
         }
     }
@@ -89,9 +110,12 @@ public class LocalCvWorkerProcessManager implements SmartLifecycle {
         }
         long pid = process.pid();
         if (process.isAlive()) {
+            stopping = true;
+            log.info("event=local_cv_worker_stop_requested pid={}", pid);
             process.destroy();
             try {
                 if (!process.waitFor(Duration.ofSeconds(5).toMillis(), TimeUnit.MILLISECONDS)) {
+                    log.warn("event=local_cv_worker_stop_timeout pid={} action=destroy_forcibly", pid);
                     process.destroyForcibly();
                 }
             } catch (InterruptedException ex) {
@@ -125,6 +149,7 @@ public class LocalCvWorkerProcessManager implements SmartLifecycle {
 
     private void waitForStartupWindow(long startupWaitMs) {
         if (startupWaitMs <= 0) {
+            log.info("event=local_cv_worker_startup_wait_skipped reason=disabled");
             return;
         }
         try {
@@ -141,6 +166,7 @@ public class LocalCvWorkerProcessManager implements SmartLifecycle {
     private void cleanupFailedStart() {
         running = false;
         if (process != null && process.isAlive()) {
+            log.warn("event=local_cv_worker_failed_start_cleanup pid={}", process.pid());
             process.destroyForcibly();
         }
     }
@@ -172,6 +198,29 @@ public class LocalCvWorkerProcessManager implements SmartLifecycle {
         return thread;
     }
 
+    private Thread processWatcher(Process watchedProcess, Path script) {
+        Thread thread = new Thread(() -> {
+            try {
+                int exitCode = watchedProcess.waitFor();
+                running = false;
+                if (stopping) {
+                    log.info("event=local_cv_worker_process_exited script={} pid={} exit_code={} reason=stop_requested",
+                            script, watchedProcess.pid(), exitCode);
+                    stopping = false;
+                } else {
+                    log.warn("event=local_cv_worker_process_exited script={} pid={} exit_code={} reason=unexpected",
+                            script, watchedProcess.pid(), exitCode);
+                }
+            } catch (InterruptedException ex) {
+                Thread.currentThread().interrupt();
+                log.debug("event=local_cv_worker_watcher_interrupted script={} pid={}",
+                        script, watchedProcess.pid());
+            }
+        }, "local-cv-worker-watcher");
+        thread.setDaemon(true);
+        return thread;
+    }
+
     record Endpoint(String host, int port) {
     }
 

src/main/java/org/example/videoclips/editing/SourceVisualAnalyzer.java

@@ -47,10 +47,19 @@ public class SourceVisualAnalyzer {
             List<String> thumbnails,
             List<ShotSegment> shotSegments
     ) {
+        log.info("event=visual_analysis_selected clip_id={} provider={} thumbnails={} shot_segments={} "
+                        + "fallback_to_heuristic={}",
+                source.clipId(), properties.getProvider(), thumbnails.size(), shotSegments.size(),
+                properties.isFallbackToHeuristic());
         if ("local-cv".equalsIgnoreCase(properties.getProvider())) {
             return localCvAnalysis(source, thumbnails, shotSegments);
         }
-        return heuristicProvider.analyze(source, thumbnails, shotSegments);
+        long startedAt = System.nanoTime();
+        SourceVisualAnalysis analysis = heuristicProvider.analyze(source, thumbnails, shotSegments);
+        log.info("event=heuristic_visual_analysis_completed clip_id={} elapsed_ms={} object_labels={} method={}",
+                source.clipId(), elapsedMillis(startedAt), analysis.objectLabels().size(),
+                analysis.analysisMethod());
+        return analysis;
     }
 
     private SourceVisualAnalysis localCvAnalysis(
@@ -58,20 +67,29 @@ public class SourceVisualAnalyzer {
             List<String> thumbnails,
             List<ShotSegment> shotSegments
     ) {
+        long startedAt = System.nanoTime();
         try {
             SourceVisualAnalysis analysis = localCvProvider.analyze(source, thumbnails, shotSegments);
-            log.info("event=local_cv_visual_analysis_completed clip_id={} endpoint={} object_labels={} method={}",
+            log.info("event=local_cv_visual_analysis_completed clip_id={} endpoint={} elapsed_ms={} "
-                    source.clipId(), properties.getEndpoint(), analysis.objectLabels().size(),
+                            + "object_labels={} method={}",
-                    analysis.analysisMethod());
+                    source.clipId(), properties.getEndpoint(), elapsedMillis(startedAt),
+                    analysis.objectLabels().size(), analysis.analysisMethod());
             return analysis;
         } catch (RuntimeException ex) {
             if (!properties.isFallbackToHeuristic()) {
+                log.error("event=local_cv_visual_analysis_failed clip_id={} endpoint={} elapsed_ms={} "
+                                + "fallback=false error_type={} message={} cause_type={} cause_message={}",
+                        source.clipId(), properties.getEndpoint(), elapsedMillis(startedAt),
+                        ex.getClass().getSimpleName(), ex.getMessage(), causeType(ex), causeMessage(ex));
                 throw ex;
             }
-            log.warn("event=local_cv_visual_analysis_fallback clip_id={} endpoint={} error_type={}",
+            log.warn("event=local_cv_visual_analysis_fallback clip_id={} endpoint={} elapsed_ms={} "
-                    source.clipId(), properties.getEndpoint(), ex.getClass().getSimpleName());
+                            + "error_type={} message={} cause_type={} cause_message={}",
+                    source.clipId(), properties.getEndpoint(), elapsedMillis(startedAt),
+                    ex.getClass().getSimpleName(), ex.getMessage(), causeType(ex), causeMessage(ex));
+            long fallbackStartedAt = System.nanoTime();
             SourceVisualAnalysis fallback = heuristicProvider.analyze(source, thumbnails, shotSegments);
-            return new SourceVisualAnalysis(
+            SourceVisualAnalysis fallbackAnalysis = new SourceVisualAnalysis(
                     fallback.clipId(),
                     fallback.blurScore(),
                     fallback.exposureScore(),
@@ -82,6 +100,23 @@ public class SourceVisualAnalyzer {
                     fallback.representativeThumbnails(),
                     "local_cv_failed_fallback_" + fallback.analysisMethod()
             );
+            log.info("event=local_cv_fallback_visual_analysis_completed clip_id={} elapsed_ms={} object_labels={} "
+                            + "method={}",
+                    source.clipId(), elapsedMillis(fallbackStartedAt), fallbackAnalysis.objectLabels().size(),
+                    fallbackAnalysis.analysisMethod());
+            return fallbackAnalysis;
         }
     }
+
+    private long elapsedMillis(long startedAt) {
+        return (System.nanoTime() - startedAt) / 1_000_000;
+    }
+
+    private String causeType(RuntimeException ex) {
+        return ex.getCause() == null ? null : ex.getCause().getClass().getSimpleName();
+    }
+
+    private String causeMessage(RuntimeException ex) {
+        return ex.getCause() == null ? null : ex.getCause().getMessage();
+    }
 }

src/test/java/org/example/videoclips/editing/LocalCvWorkerProcessManagerTest.java

@@ -136,15 +136,19 @@ class LocalCvWorkerProcessManagerTest {
         }
 
         @Override
-        public int waitFor() {
+        public synchronized int waitFor() throws InterruptedException {
-            alive = false;
+            while (alive) {
+                wait();
+            }
             return 0;
         }
 
         @Override
-        public boolean waitFor(long timeout, TimeUnit unit) {
+        public synchronized boolean waitFor(long timeout, TimeUnit unit) throws InterruptedException {
-            alive = false;
+            if (alive) {
-            return true;
+                wait(unit.toMillis(timeout));
+            }
+            return !alive;
         }
 
         @Override
@@ -153,20 +157,22 @@ class LocalCvWorkerProcessManagerTest {
         }
 
         @Override
-        public void destroy() {
+        public synchronized void destroy() {
             destroyed = true;
             alive = false;
+            notifyAll();
         }
 
         @Override
-        public Process destroyForcibly() {
+        public synchronized Process destroyForcibly() {
             destroyed = true;
             alive = false;
+            notifyAll();
             return this;
         }
 
         @Override
-        public boolean isAlive() {
+        public synchronized boolean isAlive() {
             return alive;
         }
 

tools/local_cv_worker.py

@@ -9,6 +9,8 @@ Run:
 from __future__ import annotations
 
 import os
+import logging
+import time
 from pathlib import Path
 from typing import Any
 
@@ -30,6 +32,8 @@ except ImportError:  # pragma: no cover - optional runtime dependency
 
 app = FastAPI(title="Local CV Visual Analysis Worker")
 _yolo_model: Any | None = None
+logging.basicConfig(level=os.getenv("LOCAL_CV_LOG_LEVEL", "INFO"))
+log = logging.getLogger("local_cv_worker")
 
 
 @app.get("/health")
@@ -44,14 +48,33 @@ def health() -> dict[str, Any]:
 
 @app.post("/v1/analyze-visuals")
 def analyze_visuals(payload: dict[str, Any]) -> dict[str, Any]:
+    started_at = time.monotonic()
     source = payload.get("source", {})
     thumbnails = [str(item) for item in payload.get("thumbnails", [])]
     readable_thumbnails = [path for path in thumbnails if Path(path).is_file()]
+    clip_id = source.get("clipId", "source")
+    log.info(
+        "event=local_cv_worker_request_started clip_id=%s thumbnails=%d readable_thumbnails=%d "
+        "shot_segments=%d duration_seconds=%s",
+        clip_id,
+        len(thumbnails),
+        len(readable_thumbnails),
+        len(payload.get("shotSegments", [])),
+        source.get("durationSeconds", 0),
+    )
+    if len(readable_thumbnails) != len(thumbnails):
+        unreadable = [path for path in thumbnails if path not in readable_thumbnails]
+        log.warning(
+            "event=local_cv_worker_unreadable_thumbnails clip_id=%s unreadable_count=%d unreadable=%s",
+            clip_id,
+            len(unreadable),
+            unreadable[:10],
+        )
     quality = quality_scores(readable_thumbnails)
     labels = object_labels(readable_thumbnails)
 
-    return {
+    response = {
-        "clipId": source.get("clipId", "source"),
+        "clipId": clip_id,
         "blurScore": quality["blurScore"],
         "exposureScore": quality["exposureScore"],
         "motionScore": motion_score(payload.get("shotSegments", []), source.get("durationSeconds", 0)),
@@ -61,10 +84,25 @@ def analyze_visuals(payload: dict[str, Any]) -> dict[str, Any]:
         "representativeThumbnails": representative_thumbnails(readable_thumbnails or thumbnails),
         "analysisMethod": "local_cv_worker_opencv_yolo" if labels else "local_cv_worker_opencv",
     }
+    log.info(
+        "event=local_cv_worker_request_completed clip_id=%s elapsed_ms=%d blur_score=%s "
+        "exposure_score=%s object_labels=%d method=%s",
+        clip_id,
+        elapsed_ms(started_at),
+        response["blurScore"],
+        response["exposureScore"],
+        len(response["objectLabels"]),
+        response["analysisMethod"],
+    )
+    return response
 
 
 def quality_scores(thumbnails: list[str]) -> dict[str, float]:
     if cv2 is None or not thumbnails:
+        log.info(
+            "event=local_cv_worker_quality_defaulted reason=%s",
+            "opencv_unavailable" if cv2 is None else "no_readable_thumbnails",
+        )
         return {"blurScore": 0.5, "exposureScore": 0.5}
 
     blur_scores: list[float] = []
@@ -86,8 +124,14 @@ def quality_scores(thumbnails: list[str]) -> dict[str, float]:
 
 
 def object_labels(thumbnails: list[str]) -> list[dict[str, Any]]:
+    started_at = time.monotonic()
     model = yolo_model()
     if model is None or not thumbnails:
+        log.info(
+            "event=local_cv_worker_object_detection_skipped reason=%s thumbnails=%d",
+            "model_unavailable" if model is None else "no_readable_thumbnails",
+            len(thumbnails),
+        )
         return []
 
     labels: dict[str, float] = {}
@@ -101,10 +145,17 @@ def object_labels(thumbnails: list[str]) -> list[dict[str, Any]]:
             confidence = float(box.conf[0])
             labels[label] = max(labels.get(label, 0.0), confidence)
 
-    return [
+    detected = [
         {"label": label, "confidence": round(clamp(confidence), 3), "source": "yolo"}
         for label, confidence in sorted(labels.items(), key=lambda item: item[1], reverse=True)[:10]
     ]
+    log.info(
+        "event=local_cv_worker_object_detection_completed elapsed_ms=%d thumbnails=%d labels=%d",
+        elapsed_ms(started_at),
+        len(thumbnails),
+        len(detected),
+    )
+    return detected
 
 
 def yolo_model() -> Any | None:
@@ -113,7 +164,10 @@ def yolo_model() -> Any | None:
     if YOLO is None or not model_path:
         return None
     if _yolo_model is None:
+        started_at = time.monotonic()
+        log.info("event=local_cv_worker_yolo_model_loading model=%s", model_path)
         _yolo_model = YOLO(model_path)
+        log.info("event=local_cv_worker_yolo_model_loaded model=%s elapsed_ms=%d", model_path, elapsed_ms(started_at))
     return _yolo_model
 
 
@@ -175,3 +229,7 @@ def average_or_default(values: list[float], default: float) -> float:
 
 def clamp(value: float) -> float:
     return max(0.0, min(1.0, value))
+
+
+def elapsed_ms(started_at: float) -> int:
+    return int((time.monotonic() - started_at) * 1000)