diff --git a/docs/local-cv-visual-analysis-guide.md b/docs/local-cv-visual-analysis-guide.md index 92f7455..cbc3dfd 100644 --- a/docs/local-cv-visual-analysis-guide.md +++ b/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 ``` diff --git a/src/main/java/org/example/videoclips/editing/HighlightSourceAnalyzer.java b/src/main/java/org/example/videoclips/editing/HighlightSourceAnalyzer.java index e00397f..641356a 100644 --- a/src/main/java/org/example/videoclips/editing/HighlightSourceAnalyzer.java +++ b/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 thumbnails = thumbnailExtractor.extract(inspected, frameDirectory); - String contactSheet = contactSheetGenerator.generate(inspected, contactSheetDirectory); - String proxyPath = proxyGenerator.generate(inspected, proxyDirectory).orElse(null); - String waveformPath = waveformGenerator.generate(inspected, audioDirectory); - List shotSegments = shotSceneSegmenter.segment(inspected); - SourceAudioAnalysis audioAnalysis = sourceAudioAnalyzer.analyze(inspected); - SourceVisualAnalysis visualAnalysis = sourceVisualAnalyzer.analyze(inspected, thumbnails, shotSegments); + log.info("event=highlight_analysis_media_metadata project_id={} clip_id={} duration_seconds={} codec_video={} " + + "codec_audio={} width={} height={} frame_rate={}", + projectId, inspected.clipId(), inspected.durationSeconds(), inspected.videoCodec(), + inspected.audioCodec(), inspected.width(), inspected.height(), inspected.frameRate()); + List thumbnails = timed(projectId, "thumbnail_extraction", + () -> thumbnailExtractor.extract(inspected, frameDirectory)); + 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 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); - store.writeJson(projectId, "analysis/scene-segments.json", shotSegments); - store.writeJson(projectId, "analysis/audio-analysis.json", audioAnalysis); - store.writeJson(projectId, "analysis/visual-analysis.json", visualAnalysis); - store.writeJson(projectId, "analysis/source-analysis.json", analysis); + timed(projectId, "persist_ffprobe_json", () -> { + store.writeJson(projectId, "analysis/ffprobe.json", sourceAnalysis); + return null; + }); + 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 timed(String projectId, String step, Step 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 run(); + } + private Path sourceVideo(String projectId) { Path sourceDirectory = store.sourceDirectory(projectId); try (var files = Files.list(sourceDirectory)) { diff --git a/src/main/java/org/example/videoclips/editing/HighlightSourceScheduler.java b/src/main/java/org/example/videoclips/editing/HighlightSourceScheduler.java index acbe173..71a1cc7 100644 --- a/src/main/java/org/example/videoclips/editing/HighlightSourceScheduler.java +++ b/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", diff --git a/src/main/java/org/example/videoclips/editing/LocalCvVisualAnalysisProvider.java b/src/main/java/org/example/videoclips/editing/LocalCvVisualAnalysisProvider.java index 5c21d43..04e7b26 100644 --- a/src/main/java/org/example/videoclips/editing/LocalCvVisualAnalysisProvider.java +++ b/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 thumbnails, List 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 thumbnails, List shotSegments) { } diff --git a/src/main/java/org/example/videoclips/editing/LocalCvWorkerProcessManager.java b/src/main/java/org/example/videoclips/editing/LocalCvWorkerProcessManager.java index 166feb7..e92d45f 100644 --- a/src/main/java/org/example/videoclips/editing/LocalCvWorkerProcessManager.java +++ b/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={}", - script, process.pid(), endpoint.host(), endpoint.port()); + watcherThread = processWatcher(process, script); + 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) { } diff --git a/src/main/java/org/example/videoclips/editing/SourceVisualAnalyzer.java b/src/main/java/org/example/videoclips/editing/SourceVisualAnalyzer.java index 60e8dc8..373ab70 100644 --- a/src/main/java/org/example/videoclips/editing/SourceVisualAnalyzer.java +++ b/src/main/java/org/example/videoclips/editing/SourceVisualAnalyzer.java @@ -47,10 +47,19 @@ public class SourceVisualAnalyzer { List thumbnails, List 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 thumbnails, List 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={}", - source.clipId(), properties.getEndpoint(), analysis.objectLabels().size(), - analysis.analysisMethod()); + log.info("event=local_cv_visual_analysis_completed clip_id={} endpoint={} elapsed_ms={} " + + "object_labels={} method={}", + 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={}", - source.clipId(), properties.getEndpoint(), ex.getClass().getSimpleName()); + log.warn("event=local_cv_visual_analysis_fallback clip_id={} endpoint={} elapsed_ms={} " + + "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(); + } } diff --git a/src/test/java/org/example/videoclips/editing/LocalCvWorkerProcessManagerTest.java b/src/test/java/org/example/videoclips/editing/LocalCvWorkerProcessManagerTest.java index 1a12e66..3e7fd15 100644 --- a/src/test/java/org/example/videoclips/editing/LocalCvWorkerProcessManagerTest.java +++ b/src/test/java/org/example/videoclips/editing/LocalCvWorkerProcessManagerTest.java @@ -136,15 +136,19 @@ class LocalCvWorkerProcessManagerTest { } @Override - public int waitFor() { - alive = false; + public synchronized int waitFor() throws InterruptedException { + while (alive) { + wait(); + } return 0; } @Override - public boolean waitFor(long timeout, TimeUnit unit) { - alive = false; - return true; + public synchronized boolean waitFor(long timeout, TimeUnit unit) throws InterruptedException { + if (alive) { + 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; } diff --git a/tools/local_cv_worker.py b/tools/local_cv_worker.py index 7c4a132..de8bb4c 100644 --- a/tools/local_cv_worker.py +++ b/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 { - "clipId": source.get("clipId", "source"), + response = { + "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)