diff --git a/docs/input-folder-scheduler-plan.md b/docs/input-folder-scheduler-plan.md index 6796475..92a2c1f 100644 --- a/docs/input-folder-scheduler-plan.md +++ b/docs/input-folder-scheduler-plan.md @@ -266,6 +266,10 @@ This ensures the scheduler never processes the same source file repeatedly. ## Operational Logging +The scheduler uses an initial delay and fixed delay of `5000` ms by default. The initial delay lets startup directory initialization finish; subsequent delays start after the previous scan finishes, so scans never intentionally overlap. Configure both with `video-clipping.folder-scheduler.poll-interval-ms` (minimum `1000` ms). + +Lifecycle logs use stable `event=...` fields and a per-run `scan_id` for correlation. Active work and state transitions log at info or warn/error level; scan start, idle, completion, directory readiness, and probe timing log at debug level. + Log these events: - scheduler started and configured directories diff --git a/src/main/java/org/example/videoclips/folder/FolderFfmpegClipper.java b/src/main/java/org/example/videoclips/folder/FolderFfmpegClipper.java index ade238d..0aa8a76 100644 --- a/src/main/java/org/example/videoclips/folder/FolderFfmpegClipper.java +++ b/src/main/java/org/example/videoclips/folder/FolderFfmpegClipper.java @@ -1,6 +1,8 @@ package org.example.videoclips.folder; 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; @@ -10,12 +12,15 @@ import java.nio.charset.StandardCharsets; import java.nio.file.Files; import java.nio.file.Path; import java.util.List; +import java.util.concurrent.TimeUnit; import java.util.stream.Stream; @Component @ConditionalOnProperty(name = "video-clipping.folder-scheduler.enabled", havingValue = "true") public class FolderFfmpegClipper { + private static final Logger log = LoggerFactory.getLogger(FolderFfmpegClipper.class); + private final VideoClippingProperties.FolderScheduler properties; private final ProcessExecutor processExecutor; @@ -53,6 +58,10 @@ public class FolderFfmpegClipper { ); ProcessResult processResult; + long startedAt = System.nanoTime(); + log.info("event=ffmpeg_started file={} output_directory={} segment_duration_seconds={} preset={}", + sourceFile.getFileName(), outputDirectory, properties.getSegmentDurationSeconds(), + properties.getExactPreset()); try { processResult = processExecutor.execute(command); } catch (InterruptedException ex) { @@ -61,6 +70,8 @@ public class FolderFfmpegClipper { } catch (IOException ex) { throw new IllegalStateException("Unable to run FFmpeg", ex); } + log.info("event=ffmpeg_completed file={} exit_code={} elapsed_ms={}", + sourceFile.getFileName(), processResult.exitCode(), elapsedMillis(startedAt)); if (processResult.exitCode() != 0) { throw new IllegalStateException("FFmpeg exited with code " + processResult.exitCode()); } @@ -72,6 +83,10 @@ public class FolderFfmpegClipper { return new ClipResult(outputDirectory, clipCount); } + private long elapsedMillis(long startedAt) { + return TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startedAt); + } + private Path createOutputDirectory(Path sourceFile) { String fileName = sourceFile.getFileName().toString(); int extensionSeparator = fileName.lastIndexOf('.'); diff --git a/src/main/java/org/example/videoclips/folder/FolderSchedulerDirectoryInitializer.java b/src/main/java/org/example/videoclips/folder/FolderSchedulerDirectoryInitializer.java index 74fc2d1..396eb12 100644 --- a/src/main/java/org/example/videoclips/folder/FolderSchedulerDirectoryInitializer.java +++ b/src/main/java/org/example/videoclips/folder/FolderSchedulerDirectoryInitializer.java @@ -1,6 +1,8 @@ package org.example.videoclips.folder; import org.example.videoclips.config.VideoClippingProperties; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import org.springframework.boot.ApplicationArguments; import org.springframework.boot.ApplicationRunner; import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty; @@ -15,6 +17,8 @@ import java.util.List; @ConditionalOnProperty(name = "video-clipping.folder-scheduler.enabled", havingValue = "true") public class FolderSchedulerDirectoryInitializer implements ApplicationRunner { + private static final Logger log = LoggerFactory.getLogger(FolderSchedulerDirectoryInitializer.class); + private final VideoClippingProperties.FolderScheduler properties; public FolderSchedulerDirectoryInitializer(VideoClippingProperties videoClippingProperties) { @@ -30,11 +34,18 @@ public class FolderSchedulerDirectoryInitializer implements ApplicationRunner { properties.getProcessedDirectory(), properties.getRejectedDirectory() ).forEach(this::createDirectory); + log.info("event=folder_scheduler_initialized fixed_delay_ms={} segment_duration_seconds={} " + + "input_directory={} working_directory={} output_directory={} processed_directory={} " + + "rejected_directory={}", + properties.getPollIntervalMs(), properties.getSegmentDurationSeconds(), + properties.getInputDirectory(), properties.getWorkingDirectory(), properties.getOutputDirectory(), + properties.getProcessedDirectory(), properties.getRejectedDirectory()); } private void createDirectory(String directory) { try { Files.createDirectories(Path.of(directory)); + log.debug("event=directory_ready directory={}", directory); } catch (IOException ex) { throw new IllegalStateException("Unable to create folder scheduler directory: " + directory, ex); } diff --git a/src/main/java/org/example/videoclips/folder/FolderVideoScanScheduler.java b/src/main/java/org/example/videoclips/folder/FolderVideoScanScheduler.java index f5637aa..dcdea3d 100644 --- a/src/main/java/org/example/videoclips/folder/FolderVideoScanScheduler.java +++ b/src/main/java/org/example/videoclips/folder/FolderVideoScanScheduler.java @@ -15,6 +15,8 @@ import java.nio.file.StandardCopyOption; import java.util.Comparator; import java.util.Optional; import java.util.concurrent.atomic.AtomicBoolean; +import java.util.concurrent.atomic.AtomicLong; +import java.util.concurrent.TimeUnit; import java.util.stream.Stream; @Component @@ -27,6 +29,7 @@ public class FolderVideoScanScheduler { private final FolderVideoValidator validator; private final FolderFfmpegClipper clipper; private final AtomicBoolean scanning = new AtomicBoolean(false); + private final AtomicLong scanSequence = new AtomicLong(); public FolderVideoScanScheduler( VideoClippingProperties videoClippingProperties, @@ -38,43 +41,56 @@ public class FolderVideoScanScheduler { this.clipper = clipper; } - @Scheduled(fixedDelayString = "${video-clipping.folder-scheduler.poll-interval-ms:5000}") + @Scheduled( + initialDelayString = "${video-clipping.folder-scheduler.poll-interval-ms:5000}", + fixedDelayString = "${video-clipping.folder-scheduler.poll-interval-ms:5000}" + ) public void scan() { if (!scanning.compareAndSet(false, true)) { - log.debug("Skipping folder video scan because a previous scan is still active"); + log.warn("event=scan_skipped reason=previous_scan_active"); return; } + long scanId = scanSequence.incrementAndGet(); + long startedAt = System.nanoTime(); + log.debug("event=scan_started scan_id={} input_directory={} fixed_delay_ms={}", + scanId, properties.getInputDirectory(), properties.getPollIntervalMs()); try { findNextCandidate().ifPresentOrElse( - candidate -> { - processCandidate(candidate); - }, - () -> log.debug("No folder video candidate found in {}", properties.getInputDirectory()) + candidate -> processCandidate(scanId, candidate), + () -> log.debug("event=scan_idle scan_id={} reason=no_candidate input_directory={}", + scanId, properties.getInputDirectory()) ); } finally { scanning.set(false); + log.debug("event=scan_completed scan_id={} elapsed_ms={}", scanId, elapsedMillis(startedAt)); } } - private void processCandidate(Path candidate) { + private void processCandidate(long scanId, Path candidate) { Path activeFile = candidate; + log.info("event=candidate_selected scan_id={} file={} source_directory={}", + scanId, candidate.getFileName(), candidate.getParent()); try { activeFile = moveToWorking(candidate); - log.info("Claimed folder video candidate for processing: {}", activeFile.getFileName()); - validateCandidate(activeFile); + log.info("event=candidate_claimed scan_id={} file={} working_directory={}", + scanId, activeFile.getFileName(), activeFile.getParent()); + validateCandidate(scanId, activeFile); } catch (RuntimeException ex) { - handleFailure(activeFile, ex); + handleFailure(scanId, activeFile, ex); } } - private void handleFailure(Path activeFile, RuntimeException failure) { - log.error("Folder video processing failed for {} ({})", activeFile.getFileName(), - failure.getClass().getSimpleName()); + private void handleFailure(long scanId, Path activeFile, RuntimeException failure) { + log.error("event=processing_failed scan_id={} file={} error_type={}", + scanId, activeFile.getFileName(), failure.getClass().getSimpleName()); try { Path rejectedFile = moveToDirectory(activeFile, Path.of(properties.getRejectedDirectory())); - log.warn("Moved failed folder video source to rejected storage: {}", rejectedFile.getFileName()); + log.warn("event=failed_source_rejected scan_id={} file={} rejected_directory={}", + scanId, rejectedFile.getFileName(), rejectedFile.getParent()); } catch (RuntimeException rejectionFailure) { + log.error("event=failure_quarantine_failed scan_id={} file={} error_type={}", + scanId, activeFile.getFileName(), rejectionFailure.getClass().getSimpleName()); markFailed(activeFile); } } @@ -82,30 +98,35 @@ public class FolderVideoScanScheduler { void markFailed(Path source) { Path marker = source.resolveSibling(source.getFileName() + ".failed"); if (Files.exists(marker)) { - log.error("Unable to mark failed folder video source because marker already exists: {}", marker.getFileName()); + log.error("event=failure_marker_skipped file={} reason=marker_exists marker={}", + source.getFileName(), marker.getFileName()); return; } try { Files.move(source, marker, StandardCopyOption.ATOMIC_MOVE); - log.warn("Marked folder video source as failed: {}", marker.getFileName()); + log.warn("event=failure_marker_created file={} marker={}", source.getFileName(), marker.getFileName()); } catch (IOException ex) { - log.error("Unable to quarantine or mark failed folder video source: {}", source.getFileName()); + log.error("event=failure_marker_failed file={} error_type={}", + source.getFileName(), ex.getClass().getSimpleName()); } } - private void validateCandidate(Path workingFile) { + private void validateCandidate(long scanId, Path workingFile) { FolderVideoValidator.ValidationResult result = validator.validate(workingFile); if (result.valid()) { - log.info("Validated folder video candidate: {}", workingFile.getFileName()); + log.info("event=validation_succeeded scan_id={} file={}", scanId, workingFile.getFileName()); FolderFfmpegClipper.ClipResult clipResult = clipper.clip(workingFile); - log.info("Generated {} clips in {}", clipResult.clipCount(), clipResult.outputDirectory().getFileName()); + log.info("event=clipping_succeeded scan_id={} file={} clip_count={} output_directory={}", + scanId, workingFile.getFileName(), clipResult.clipCount(), clipResult.outputDirectory()); Path processedFile = moveToDirectory(workingFile, Path.of(properties.getProcessedDirectory())); - log.info("Moved successfully processed source to processed storage: {}", processedFile.getFileName()); + log.info("event=processing_succeeded scan_id={} file={} processed_directory={}", + scanId, processedFile.getFileName(), processedFile.getParent()); return; } Path rejectedFile = moveToDirectory(workingFile, Path.of(properties.getRejectedDirectory())); - log.warn("Rejected invalid folder video candidate {}: {}", rejectedFile.getFileName(), result.reason()); + log.warn("event=validation_rejected scan_id={} file={} reason={} rejected_directory={}", + scanId, rejectedFile.getFileName(), result.reason(), rejectedFile.getParent()); } Path moveToWorking(Path candidate) { @@ -183,4 +204,8 @@ public class FolderVideoScanScheduler { key.append(new BigInteger(number.toString())); number.setLength(0); } + + private long elapsedMillis(long startedAt) { + return TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startedAt); + } } diff --git a/src/main/java/org/example/videoclips/folder/FolderVideoValidator.java b/src/main/java/org/example/videoclips/folder/FolderVideoValidator.java index 7c66cf6..944dedb 100644 --- a/src/main/java/org/example/videoclips/folder/FolderVideoValidator.java +++ b/src/main/java/org/example/videoclips/folder/FolderVideoValidator.java @@ -1,6 +1,8 @@ package org.example.videoclips.folder; 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.nio.file.Path; import java.util.List; import java.util.Locale; import java.util.Set; +import java.util.concurrent.TimeUnit; import java.util.regex.Matcher; import java.util.regex.Pattern; @@ -18,6 +21,7 @@ import java.util.regex.Pattern; @ConditionalOnProperty(name = "video-clipping.folder-scheduler.enabled", havingValue = "true") public class FolderVideoValidator { + private static final Logger log = LoggerFactory.getLogger(FolderVideoValidator.class); private static final Set ALLOWED_EXTENSIONS = Set.of("mp4", "mov", "m4v", "webm", "mkv"); private final VideoClippingProperties.FolderScheduler properties; @@ -40,6 +44,8 @@ public class FolderVideoValidator { ? fileName.substring(extensionSeparator + 1).toLowerCase(Locale.ROOT) : ""; if (!ALLOWED_EXTENSIONS.contains(extension)) { + log.warn("event=ffprobe_skipped file={} reason=unsupported_extension extension={}", + videoFile.getFileName(), extension); return ValidationResult.invalid("unsupported file extension"); } @@ -52,6 +58,8 @@ public class FolderVideoValidator { videoFile.toString() ); ProcessResult result; + long startedAt = System.nanoTime(); + log.debug("event=ffprobe_started file={} binary={}", videoFile.getFileName(), properties.getFfprobeBinary()); try { result = processExecutor.execute(command); } catch (InterruptedException ex) { @@ -60,6 +68,8 @@ public class FolderVideoValidator { } catch (IOException ex) { throw new IllegalStateException("Unable to run ffprobe", ex); } + log.debug("event=ffprobe_completed file={} exit_code={} elapsed_ms={}", + videoFile.getFileName(), result.exitCode(), elapsedMillis(startedAt)); if (result.exitCode() != 0) { return ValidationResult.invalid("ffprobe exited with code " + result.exitCode()); @@ -72,6 +82,10 @@ public class FolderVideoValidator { return ValidationResult.accepted(); } + private long elapsedMillis(long startedAt) { + return TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startedAt); + } + private boolean hasPositiveValue(String output, String key) { Matcher matcher = Pattern.compile("(?m)^" + key + "=([0-9]+(?:\\.[0-9]+)?)$").matcher(output); return matcher.find() && Double.parseDouble(matcher.group(1)) > 0; diff --git a/src/main/resources/application-folder-scheduler-local.properties b/src/main/resources/application-folder-scheduler-local.properties index 5a53758..5b2d2e7 100644 --- a/src/main/resources/application-folder-scheduler-local.properties +++ b/src/main/resources/application-folder-scheduler-local.properties @@ -10,3 +10,4 @@ video-clipping.folder-scheduler.ffmpeg-binary=ffmpeg video-clipping.folder-scheduler.ffprobe-binary=ffprobe video-clipping.folder-scheduler.output-container=mp4 video-clipping.folder-scheduler.exact-preset=veryfast +logging.level.org.example.videoclips.folder=DEBUG diff --git a/src/test/java/org/example/videoclips/folder/FolderSchedulerLocalProfileTest.java b/src/test/java/org/example/videoclips/folder/FolderSchedulerLocalProfileTest.java index 4270ba9..43a4297 100644 --- a/src/test/java/org/example/videoclips/folder/FolderSchedulerLocalProfileTest.java +++ b/src/test/java/org/example/videoclips/folder/FolderSchedulerLocalProfileTest.java @@ -23,5 +23,6 @@ class FolderSchedulerLocalProfileTest { assertEquals("./input/rejected", properties.getProperty("video-clipping.folder-scheduler.rejected-directory")); assertEquals("8", properties.getProperty("video-clipping.folder-scheduler.segment-duration-seconds")); assertEquals("mp4", properties.getProperty("video-clipping.folder-scheduler.output-container")); + assertEquals("DEBUG", properties.getProperty("logging.level.org.example.videoclips.folder")); } }