Combine split tool warning logs into a single line

AGENTS.md

@@ -198,11 +198,21 @@ Serilog log levels describe the **nature** of an event, applied uniformly across
   - A "modification" is a write to the **media file**, including in-place metadata edits (MkvPropEdit flags/language/title) and container remuxes/renames. Sidecar cache writes and the results file are bookkeeping, not media modifications - they are Debug/Information, not Warnings.
   - **The media-manipulation code itself does not emit Warning.** Doing a remux or re-encode is that code's job, not a warning. Only the decision to run it is the Warning. Do not sprinkle Warnings through `Convert`, the media-tool wrappers, or the worker methods.
 - **Information** - the high-level narrative of what the app is doing, readable end to end at the default level with no low-level mechanics: startup (banner, settings, tool versions), discovery (`Discovered N files`), batch lifecycle (`Starting {Command}, processing N files`, progress, `Completed`, the run summary), the per-file entry, read-only outcomes of note (skips), a worker **doing its job** (e.g. `Convert.ReMux` logging `Remux using MkvMerge`), and the intended output of read-only commands (`getmediainfo` / `getsidecarinfo` / `gettagmap` dumps).
-- **Debug** - troubleshooting detail; *how* the work is done: raw tool invocations and command lines (`Executing MkvMerge : args`), read/probe mechanics (`Getting media info`, `Reading media info from sidecar`, temp files, packet probes), per-track structural dumps during normal processing, inspection sub-steps (verify, bitrate, idet counting), and sidecar cache bookkeeping.
+- **Debug** - troubleshooting detail; *how* the work is done: raw tool invocations and command lines (`Executing MkvMerge : GetMediaPropsJson : args`, which carry the operation so a per-method "doing X" line is not needed), read/probe mechanics (`Reading media info from sidecar`, temp files, packet probes), per-track structural dumps during normal processing, inspection sub-steps (verify, bitrate, idet counting), and sidecar cache bookkeeping.
 - **Verbose** - very granular: filesystem-watcher events, per-packet/byte-level progress.
 
 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. The previously non-buffered mkvpropedit and 7-Zip executions now buffer their output, so their failures log the error text instead of nothing.
+    - 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,13 @@ 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 +259,13 @@ 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 +304,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 +334,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