Improve folder scheduler diagnostics

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

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('.');

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);
         }

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 -> {
+                    candidate -> processCandidate(scanId, candidate),
-                        processCandidate(candidate);
+                    () -> log.debug("event=scan_idle scan_id={} reason=no_candidate input_directory={}",
-                    },
+                            scanId, properties.getInputDirectory())
-                    () -> log.debug("No folder video candidate found in {}", 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());
+            log.info("event=candidate_claimed scan_id={} file={} working_directory={}",
-            validateCandidate(activeFile);
+                    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) {
+    private void handleFailure(long scanId, Path activeFile, RuntimeException failure) {
-        log.error("Folder video processing failed for {} ({})", activeFile.getFileName(),
+        log.error("event=processing_failed scan_id={} file={} error_type={}",
-                failure.getClass().getSimpleName());
+                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);
+    }
 }

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<String> 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;

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

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"));
     }
 }