Combine split tool warning logs into a single line

AGENTS.md

@@ -203,6 +203,16 @@ Serilog log levels describe the **nature** of an event, applied uniformly across
 
 The elevation trigger (Warning) must be preserved: keep exactly one decision-Warning per media modification, with the action at Information and the underlying tool at Debug.
 
+### Tool execution and failure logging
+
+- **Always consume a tool's output.** A subprocess whose stdout/stderr is not read can deadlock once it fills the pipe buffer, so never run a tool without consuming its pipes: `MediaTool.Execute` buffers them (summarize when the output is huge), and `ExecuteStreamStdErr` streams stderr line by line for the unbounded `-f null` verify pass. `Execute`, its cancellation path, and `LogFailedResult` record the **operation** (the calling method, captured via `[CallerMemberName]`, rendered with `:l`) so a command line ties to its purpose in a parallel log without correlating separate lines.
+- **Tools write errors to different streams.** ffmpeg, ffprobe, HandBrake, and 7-Zip use **stderr**; the mkvtoolnix tools (mkvmerge, mkvpropedit) write everything including errors to **stdout** (confirmed from the mkvtoolnix source - all output goes through the one stdout object) and override `GetErrorOutput` to it. MediaInfo also emits to stdout but keeps the stderr default; its errors are caught by the `LogFailedResult` fallback, which reads the other captured stream when the tool's declared stream is empty, so an error is never lost.
+- **Do not add a per-method debug line that just restates the command about to run** (e.g. `Getting media info`); the `Executing {Tool} : {operation} : args` line from `Execute` already covers it.
+
+### Failure-handling philosophy
+
+An **expected, recoverable** failure escalates through the standard repair tiers (detect -> surgical -> remux -> re-encode -> fail); an **unexpected or logic** failure (e.g. tool output that will not parse) aborts the file and stays a hard error, so the bug surfaces and gets fixed rather than being masked by a fallback that silently mis-processes at scale.
+
 ## Project Structure
 
 - **PlexCleaner** (`PlexCleaner/PlexCleaner.csproj`)

HISTORY.md

@@ -8,16 +8,23 @@ Utility to optimize media files for Direct Play in Plex, Emby, Jellyfin, etc.
   - Repair non-monotonic DTS muxer warnings losslessly instead of failing repair permanently.
     - `ffmpeg -f null` can exit `0` yet emit `Application provided invalid, non monotonically increasing dts to muxer` for files that may decode and play correctly.
     - The previous "any stderr means failure" rule promoted this muxer-interleaving artifact to a hard `VerifyFailed`/`RepairFailed`, and a re-encode could not fix it because Matroska stores no DTS and ffmpeg re-derives a non-monotonic timeline on read.
-    - Verify now classifies the decode diagnostics deterministically as clean, a timestamp-only failure, or a decode error; a timestamp-only failure is repaired losslessly when the break is demux-visible and otherwise stays reported, and everything else fails (fail-closed, so an unrecognized diagnostic fails as a decode error).
+    - Verify now classifies the decode diagnostics deterministically as clean, a timestamp-only failure, or a decode error; a timestamp-only failure is a repairable failure and everything else fails (fail-closed, so an unrecognized diagnostic fails as a decode error).
     - The classification streams the output line by line, so memory stays bounded even when a file emits a warning per packet ([#827](https://github.com/ptr727/PlexCleaner/issues/827)).
-  - Added a lossless timestamp repair as the first repair tier.
-    - When verification detects a demux-visible non-monotonic DTS on an audio stream, the audio packet timestamps are rewritten to be strictly monotonic using the `setts` bitstream filter with a stream copy (no re-encode), then re-verified. A video-stream DTS is not audio-repairable (a video `setts` would reorder B-frames) and stays reported.
-    - A regression gate compares the per-stream coded payload hash and the per-stream start and duration before and after, discarding the result unless every stream is byte-identical and no stream shifted beyond the A/V-sync tolerance, so the repair can neither alter the media nor drift the audio out of sync. The full re-encode repair remains for genuine decode corruption.
+  - Added a lossless timestamp repair as the first repair tier, escalating to remux and re-encode when it cannot apply.
+    - When verification detects a demux-visible non-monotonic DTS on an audio stream, the audio packet timestamps are rewritten to be strictly monotonic using the `setts` bitstream filter with a stream copy (no re-encode), then re-verified.
+    - A regression gate compares the per-stream coded payload hash and the per-stream start and duration before and after, discarding the result unless every stream is byte-identical and no stream shifted beyond the A/V-sync tolerance, so the lossless repair can neither alter the media nor drift the audio out of sync.
+    - A non-monotonic DTS the `setts` repair cannot fix - a video stream (where a `setts` would reorder B-frames), or a break visible only after decode - falls through to a remux and then a full re-encode that rebuilds the timestamps, matching the general detect -> surgical -> remux -> re-encode -> fail escalation, instead of stopping at `RepairFailed`. The re-encode tier also repairs genuine decode corruption.
   - Consolidated the bitrate and DTS packet analyses into a single `ffprobe -show_packets` pass, computing the per-second bitrate and the per-stream DTS monotonicity together instead of reading packets twice.
   - Switched closed caption detection to `ffprobe -analyze_frames -show_entries stream=closed_captions`, replacing the `movie=...[out0+subcc]` lavfi filter and its QuickScan snippet-remux workaround; QuickScan now bounds the scan with `-read_intervals`.
   - Added the `DtsTimestampRepair` example plugin.
     - It revisits files that a previous version marked `RepairFailed`, re-verifies them, clears the flag when the only problem was timestamps, and losslessly repairs the timestamps when the DTS is demux-visible. Not available in AOT builds.
   - Restricted `--testsnippets` to slow re-encode and deinterlace operations. Fast remux, stream-copy, and the lossless timestamp repair now always produce full output, so a repair or remux is validated on the whole file rather than an unrepresentative leading clip; a snippet had caused the timestamp-repair byte-identical gate to fail during testing.
+  - Hardened interlace detection against interleaved `idet` output. On a source with non-monotonic DTS, `ffmpeg -fflags +genpts` emits muxer warnings between the `idet` stat lines; the parser now matches each stat line independently instead of requiring a contiguous block, so a full-file scan no longer fails to parse and abort the file. The raw output is logged on a parse failure.
+  - Improved tool execution logging for troubleshooting.
+    - A tool failure now logs the tool's error output on a single line with the exit code, the operation, and the file name, instead of a bare exit code with the error text discarded or split across lines.
+    - The error text is read from the stream the tool writes to (stderr for the ffmpeg family, HandBrake, and 7-Zip; stdout for the mkvtoolnix tools), falling back to the other captured stream so output on an unexpected stream, such as MediaInfo's stdout, is never lost. All tool output is now captured, fixing mkvpropedit and 7-Zip failures that previously logged no error text.
+    - The operation (the calling method, via `[CallerMemberName]`) is included in the execution, cancellation, and failure lines, so a command can be tied to its purpose in a parallel log without correlating separate lines. Redundant per-operation debug lines already covered by the command execution log were removed.
+    - Added per-file elapsed processing time to the `ProcessFiles` result line, formatted consistently with the run total.
 - Version 3.20:
   - Switched tool downloads and the application version check to the resilient HTTP client in `ptr727.Utilities` (retry with backoff and a circuit breaker via `Microsoft.Extensions.Http.Resilience`), replacing the plain `HttpClient`.
   - Enabled closed caption removal for H.265/HEVC video: the SEI NAL unit lookup keyed on `h265` never matched FFprobe's `hevc` codec name, so HEVC files were incorrectly reported as an "Unsupported video format for Closed Captions removal". HEVC video (excluding HDR10 and HDR10+ content, which remains guarded) is now cleaned using the `filter_units=remove_types=39` bitstream filter, same as H.264 and MPEG-2.

PlexCleaner/Bitrate.cs

@@ -1,6 +1,5 @@
 using System.Diagnostics;
 using ptr727.Utilities;
-using Serilog;
 
 namespace PlexCleaner;
 

PlexCleaner/ConfigFileJsonSchema.cs

@@ -11,7 +11,6 @@
 using System.Text.Json.Nodes;
 using System.Text.Json.Schema;
 using System.Text.Json.Serialization;
-using Serilog;
 
 namespace PlexCleaner;
 

PlexCleaner/Convert.cs

@@ -1,5 +1,4 @@
 using System.Diagnostics;
-using Serilog;
 
 namespace PlexCleaner;
 

PlexCleaner/ConvertOptions.cs

@@ -1,5 +1,4 @@
 using System.Text.Json.Serialization;
-using Serilog;
 
 namespace PlexCleaner;
 

PlexCleaner/Extensions.cs

@@ -1,5 +1,3 @@
-using Serilog;
-
 namespace PlexCleaner;
 
 public static class Extensions

PlexCleaner/FfMpegIdetInfo.cs

@@ -1,7 +1,6 @@
 using System.Diagnostics;
 using System.Globalization;
 using System.Text.RegularExpressions;
-using Serilog;
 
 namespace PlexCleaner;
 

PlexCleaner/FfMpegTool.cs

@@ -4,7 +4,6 @@
 using System.Text.RegularExpressions;
 using CliWrap;
 using CliWrap.Buffered;
-using Serilog;
 
 // https://ffmpeg.org/ffmpeg.html
 
@@ -221,7 +220,7 @@ public bool ReMuxToFormat(string inputName, string outputName, string format)
 
             // Execute command
             return Execute(command, true, true, out BufferedCommandResult result)
-                && (result.ExitCode == 0 || LogFailedResult(result));
+                && (result.ExitCode == 0 || LogFailedResult(result, inputName));
         }
 
         private static void CreateTrackArgs(
@@ -321,7 +320,7 @@ string outputName
 
             // Execute command
             return Execute(command, true, true, out BufferedCommandResult result)
-                && (result.ExitCode == 0 || LogFailedResult(result));
+                && (result.ExitCode == 0 || LogFailedResult(result, inputName));
         }
 
         public bool ConvertToMkv(string inputName, string outputName)
@@ -349,7 +348,7 @@ public bool ConvertToMkv(string inputName, string outputName)
 
             // Execute command
             return Execute(command, true, true, out BufferedCommandResult result)
-                && (result.ExitCode == 0 || LogFailedResult(result));
+                && (result.ExitCode == 0 || LogFailedResult(result, inputName));
         }
 
         public bool SetTimestamps(string inputName, string outputName)
@@ -382,7 +381,7 @@ public bool SetTimestamps(string inputName, string outputName)
 
             // Execute command
             return Execute(command, true, true, out BufferedCommandResult result)
-                && (result.ExitCode == 0 || LogFailedResult(result));
+                && (result.ExitCode == 0 || LogFailedResult(result, inputName));
         }
 
         public bool GetStreamHashes(string fileName, out Dictionary<int, string> streamHashes)
@@ -406,7 +405,7 @@ public bool GetStreamHashes(string fileName, out Dictionary<int, string> streamH
             }
             if (result.ExitCode != 0)
             {
-                return LogFailedResult(result);
+                return LogFailedResult(result, fileName);
             }
 
             // Parse lines of the form "index,type,md5=value"
@@ -455,7 +454,7 @@ public bool RemoveNalUnits(string inputName, int nalUnit, string outputName)
 
             // Execute command
             return Execute(command, true, true, out BufferedCommandResult result)
-                && (result.ExitCode == 0 || LogFailedResult(result));
+                && (result.ExitCode == 0 || LogFailedResult(result, inputName));
         }
 
         public bool GetIdetText(string fileName, out string text)
@@ -481,7 +480,7 @@ public bool GetIdetText(string fileName, out string text)
                 return false;
             }
             text = result.StandardError.Trim();
-            return result.ExitCode == 0 || LogFailedResult(result);
+            return result.ExitCode == 0 || LogFailedResult(result, fileName);
         }
 
         [GeneratedRegex(

PlexCleaner/FfProbeTool.cs

@@ -1,10 +1,10 @@
+using System.Runtime.CompilerServices;
 using System.Text;
 using System.Text.Json;
 using System.Text.Json.Serialization;
 using System.Text.Json.Stream;
 using CliWrap;
 using CliWrap.Buffered;
-using Serilog;
 
 // https://ffmpeg.org/ffprobe.html
 
@@ -56,13 +56,15 @@ protected override bool GetLatestVersionWindows(out MediaToolInfo mediaToolInfo)
         public bool GetPackets(
             Command command,
             Func<FfMpegToolJsonSchema.Packet, bool> packetFunc,
-            out string error
+            out string error,
+            [CallerMemberName] string operation = ""
         )
         {
             // Wrap async function in a task
             (bool result, string error) result = GetPacketsAsync(
                     command,
-                    async packet => await Task.FromResult(packetFunc(packet))
+                    async packet => await Task.FromResult(packetFunc(packet)),
+                    operation
                 )
                 .GetAwaiter()
                 .GetResult();
@@ -72,7 +74,8 @@ out string error
 
         public async Task<(bool result, string error)> GetPacketsAsync(
             Command command,
-            Func<FfMpegToolJsonSchema.Packet, Task<bool>> packetFunc
+            Func<FfMpegToolJsonSchema.Packet, Task<bool>> packetFunc,
+            [CallerMemberName] string operation = ""
         )
         {
             int processId = -1;
@@ -165,8 +168,9 @@ out string error
                     .ExecuteAsync(CancellationToken.None, Program.CancelToken());
                 processId = task.ProcessId;
                 Log.Debug(
-                    "Executing {ToolType} : ProcessId: {ProcessId}, Arguments: {Arguments}",
+                    "Executing {ToolType} : {Operation:l} : ProcessId: {ProcessId}, Arguments: {Arguments}",
                     GetToolType(),
+                    operation,
                     processId,
                     command.Arguments
                 );
@@ -178,8 +182,9 @@ out string error
             catch (OperationCanceledException)
             {
                 Log.Error(
-                    "Cancelled execution of {ToolType} : ProcessId: {ProcessId}, Arguments: {Arguments}",
+                    "Cancelled execution of {ToolType} : {Operation:l} : ProcessId: {ProcessId}, Arguments: {Arguments}",
                     GetToolType(),
+                    operation,
                     processId,
                     command.Arguments
                 );
@@ -212,15 +217,14 @@ public bool GetClosedCaptions(string fileName, out bool hasClosedCaptions)
                 .Build();
 
             // Execute command
-            Log.Debug("Getting closed caption info : {FileName}", fileName);
             if (!Execute(command, false, true, out BufferedCommandResult result))
             {
                 return false;
             }
             if (result.ExitCode != 0)
             {
                 Log.Error("Failed to get closed caption info : {FileName}", fileName);
-                return LogFailedResult(result);
+                return LogFailedResult(result, fileName);
             }
 
             // Any video stream reporting closed captions, FromJson throws on malformed output
@@ -256,15 +260,14 @@ public bool GetStreamTimings(
                 .Build();
 
             // Execute command
-            Log.Debug("Getting stream timings : {FileName}", fileName);
             if (!Execute(command, false, true, out BufferedCommandResult result))
             {
                 return false;
             }
             if (result.ExitCode != 0)
             {
                 Log.Error("Failed to get stream timings : {FileName}", fileName);
-                return LogFailedResult(result);
+                return LogFailedResult(result, fileName);
             }
 
             // FromJson throws on malformed output
@@ -303,7 +306,6 @@ bool quickScan
                 .Build();
 
             // Get packet list
-            Log.Debug("Getting analysis packets : {FileName}", fileName);
             if (!GetPackets(command, packetFunc, out string error))
             {
                 Log.Error("Failed to get analysis packets : {FileName}", fileName);
@@ -334,28 +336,23 @@ public bool GetMediaPropsJson(string fileName, out string json)
                 .Build();
 
             // Execute command
-            Log.Debug("{ToolType} : Getting media info : {FileName}", GetToolType(), fileName);
             if (!Execute(command, false, true, out BufferedCommandResult result))
             {
                 return false;
             }
             if (result.ExitCode != 0)
             {
-                Log.Error(
-                    "{ToolType} : Failed to get media info : {FileName}",
-                    GetToolType(),
-                    fileName
-                );
-                return LogFailedResult(result);
+                return LogFailedResult(result, fileName);
             }
-            if (result.StandardError.Length > 0)
+            string warning = CleanForLog(result.StandardError.Trim());
+            if (!string.IsNullOrEmpty(warning))
             {
                 Log.Warning(
-                    "{ToolType} : Warning getting media info : {FileName}",
+                    "{ToolType} : Warning getting media info : {Warning} : {FileName}",
                     GetToolType(),
+                    warning,
                     fileName
                 );
-                Log.Warning("{ToolType} : {Warning}", GetToolType(), result.StandardError.Trim());
             }
 
             // Get JSON output

PlexCleaner/GitHubRelease.cs

@@ -1,6 +1,5 @@
 using System.Text.Json.Nodes;
 using ptr727.Utilities;
-using Serilog;
 
 namespace PlexCleaner;
 

PlexCleaner/GlobalUsings.cs

@@ -1,2 +1,3 @@
+global using Serilog;
 global using ConfigFileJsonSchema = PlexCleaner.ConfigFileJsonSchema4;
 global using SidecarFileJsonSchema = PlexCleaner.SidecarFileJsonSchema5;

PlexCleaner/HandBrakeTool.cs

@@ -2,7 +2,6 @@
 using System.Text.RegularExpressions;
 using CliWrap;
 using CliWrap.Buffered;
-using Serilog;
 
 // https://handbrake.fr/docs/en/latest/cli/command-line-reference.html
 
@@ -124,7 +123,7 @@ bool deInterlace
 
             // Execute command
             return Execute(command, true, true, out BufferedCommandResult result)
-                && (result.ExitCode == 0 || LogFailedResult(result));
+                && (result.ExitCode == 0 || LogFailedResult(result, inputName));
         }
 
         [GeneratedRegex(

PlexCleaner/IProcessPlugin.cs

@@ -17,7 +17,7 @@ public interface IPluginHost
     string Runtime { get; }
 
     // Plugin log events flow to the host sinks and end-of-run summary
-    Serilog.ILogger Logger { get; }
+    ILogger Logger { get; }
 }
 
 public interface IProcessPlugin

PlexCleaner/LoggerFactory.cs

@@ -1,5 +1,4 @@
 using System.Globalization;
-using Serilog;
 using Serilog.Debugging;
 using Serilog.Events;
 using Serilog.Sinks.SystemConsole.Themes;

PlexCleaner/MatroskaStructure.cs

@@ -1,5 +1,4 @@
 using NEbml.Core;
-using Serilog;
 
 namespace PlexCleaner;