diff --git a/AGENTS.md b/AGENTS.md index 2c9aa55a..82f6bad6 100644 --- a/AGENTS.md +++ b/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`) diff --git a/HISTORY.md b/HISTORY.md index 4e74fa0e..9674a8bd 100644 --- a/HISTORY.md +++ b/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. diff --git a/PlexCleaner/Bitrate.cs b/PlexCleaner/Bitrate.cs index a1d47668..754b47e9 100644 --- a/PlexCleaner/Bitrate.cs +++ b/PlexCleaner/Bitrate.cs @@ -1,6 +1,5 @@ using System.Diagnostics; using ptr727.Utilities; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/ConfigFileJsonSchema.cs b/PlexCleaner/ConfigFileJsonSchema.cs index 09f3f7b1..55144ffb 100644 --- a/PlexCleaner/ConfigFileJsonSchema.cs +++ b/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; diff --git a/PlexCleaner/Convert.cs b/PlexCleaner/Convert.cs index a9043c34..e2edb3db 100644 --- a/PlexCleaner/Convert.cs +++ b/PlexCleaner/Convert.cs @@ -1,5 +1,4 @@ using System.Diagnostics; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/ConvertOptions.cs b/PlexCleaner/ConvertOptions.cs index b2e26089..c23071b6 100644 --- a/PlexCleaner/ConvertOptions.cs +++ b/PlexCleaner/ConvertOptions.cs @@ -1,5 +1,4 @@ using System.Text.Json.Serialization; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/Extensions.cs b/PlexCleaner/Extensions.cs index bb4e1c79..45f4fed0 100644 --- a/PlexCleaner/Extensions.cs +++ b/PlexCleaner/Extensions.cs @@ -1,5 +1,3 @@ -using Serilog; - namespace PlexCleaner; public static class Extensions diff --git a/PlexCleaner/FfMpegIdetInfo.cs b/PlexCleaner/FfMpegIdetInfo.cs index 822c697f..a16dbe25 100644 --- a/PlexCleaner/FfMpegIdetInfo.cs +++ b/PlexCleaner/FfMpegIdetInfo.cs @@ -1,7 +1,6 @@ using System.Diagnostics; using System.Globalization; using System.Text.RegularExpressions; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/FfMpegTool.cs b/PlexCleaner/FfMpegTool.cs index 9ec8de06..9766e4af 100644 --- a/PlexCleaner/FfMpegTool.cs +++ b/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 streamHashes) @@ -406,7 +405,7 @@ public bool GetStreamHashes(string fileName, out Dictionary 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( diff --git a/PlexCleaner/FfProbeTool.cs b/PlexCleaner/FfProbeTool.cs index 51c39599..67e6e84d 100644 --- a/PlexCleaner/FfProbeTool.cs +++ b/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 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> packetFunc + Func> 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 diff --git a/PlexCleaner/GitHubRelease.cs b/PlexCleaner/GitHubRelease.cs index 5b420384..0461a40c 100644 --- a/PlexCleaner/GitHubRelease.cs +++ b/PlexCleaner/GitHubRelease.cs @@ -1,6 +1,5 @@ using System.Text.Json.Nodes; using ptr727.Utilities; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/GlobalUsings.cs b/PlexCleaner/GlobalUsings.cs index d9c83552..31d7a820 100644 --- a/PlexCleaner/GlobalUsings.cs +++ b/PlexCleaner/GlobalUsings.cs @@ -1,2 +1,3 @@ +global using Serilog; global using ConfigFileJsonSchema = PlexCleaner.ConfigFileJsonSchema4; global using SidecarFileJsonSchema = PlexCleaner.SidecarFileJsonSchema5; diff --git a/PlexCleaner/HandBrakeTool.cs b/PlexCleaner/HandBrakeTool.cs index ffd133ff..a22c2d53 100644 --- a/PlexCleaner/HandBrakeTool.cs +++ b/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( diff --git a/PlexCleaner/IProcessPlugin.cs b/PlexCleaner/IProcessPlugin.cs index 2b8e1f96..b400e7f3 100644 --- a/PlexCleaner/IProcessPlugin.cs +++ b/PlexCleaner/IProcessPlugin.cs @@ -1,3 +1,5 @@ +using System.Diagnostics.CodeAnalysis; + namespace PlexCleaner; public static class PluginApi @@ -16,7 +18,13 @@ public interface IPluginHost string OperatingSystem { get; } string Runtime { get; } - // Plugin log events flow to the host sinks and end-of-run summary + // Plugin log events flow to the host sinks and end-of-run summary. Fully qualified so plugin authors + // are not left guessing between Serilog.ILogger and Microsoft.Extensions.Logging.ILogger + [SuppressMessage( + "Style", + "IDE0001:Simplify Names", + Justification = "Disambiguate the public plugin logger type" + )] Serilog.ILogger Logger { get; } } diff --git a/PlexCleaner/LoggerFactory.cs b/PlexCleaner/LoggerFactory.cs index 67577846..9b4566e8 100644 --- a/PlexCleaner/LoggerFactory.cs +++ b/PlexCleaner/LoggerFactory.cs @@ -1,5 +1,4 @@ using System.Globalization; -using Serilog; using Serilog.Debugging; using Serilog.Events; using Serilog.Sinks.SystemConsole.Themes; diff --git a/PlexCleaner/MatroskaStructure.cs b/PlexCleaner/MatroskaStructure.cs index 752099a3..d1b586c8 100644 --- a/PlexCleaner/MatroskaStructure.cs +++ b/PlexCleaner/MatroskaStructure.cs @@ -1,5 +1,4 @@ using NEbml.Core; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/MediaInfoTool.cs b/PlexCleaner/MediaInfoTool.cs index 031ae9c0..8f69b167 100644 --- a/PlexCleaner/MediaInfoTool.cs +++ b/PlexCleaner/MediaInfoTool.cs @@ -3,7 +3,6 @@ using System.Text.RegularExpressions; using CliWrap; using CliWrap.Buffered; -using Serilog; // http://manpages.ubuntu.com/manpages/zesty/man1/mediainfo.1.html @@ -111,28 +110,23 @@ public bool GetMediaPropsJson(string fileName, out string json) .Build(); // Execute command - Log.Debug("Getting media info : {FileName}", 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 diff --git a/PlexCleaner/MediaProps.cs b/PlexCleaner/MediaProps.cs index 3e217e2e..cd556f38 100644 --- a/PlexCleaner/MediaProps.cs +++ b/PlexCleaner/MediaProps.cs @@ -1,5 +1,4 @@ using System.Diagnostics; -using Serilog; using Serilog.Events; namespace PlexCleaner; diff --git a/PlexCleaner/MediaTool.cs b/PlexCleaner/MediaTool.cs index d75df70e..0eb9c7a3 100644 --- a/PlexCleaner/MediaTool.cs +++ b/PlexCleaner/MediaTool.cs @@ -1,8 +1,8 @@ +using System.Runtime.CompilerServices; using System.Runtime.InteropServices; using System.Text; using CliWrap; using CliWrap.Buffered; -using Serilog; namespace PlexCleaner; @@ -94,70 +94,54 @@ protected bool GetLatestGitHubRelease(string repo, out string version) return GitHubRelease.GetLatestRelease(repo, out version); } - public bool Execute(Command command, out CommandResult commandResult) - { - commandResult = null!; - int processId = -1; - try - { - CommandTask task = command - .WithValidation(CommandResultValidation.None) - .ExecuteAsync(CancellationToken.None, Program.CancelToken()); - processId = task.ProcessId; - Log.Debug( - "Executing {ToolType} : ProcessId: {ProcessId}, Arguments: {Arguments}", - GetToolType(), - processId, - command.Arguments - ); - - commandResult = task.Task.GetAwaiter().GetResult(); - return task.Task.IsCompletedSuccessfully; - } - catch (OperationCanceledException) - { - Log.Error( - "Cancelled execution of {ToolType} : ProcessId: {ProcessId}, Arguments: {Arguments}", - GetToolType(), - processId, - command.Arguments - ); - return false; - } - catch (Exception e) when (Log.Logger.LogAndHandle(e)) - { - return false; - } - } - - public bool Execute(Command command, out BufferedCommandResult bufferedCommandResult) => - Execute(command, false, false, out bufferedCommandResult); + public bool Execute( + Command command, + out BufferedCommandResult bufferedCommandResult, + [CallerMemberName] string operation = "" + ) => Execute(command, false, false, out bufferedCommandResult, operation); - // Stream carrying tool error text; stderr by default, stdout for MkvMerge + // Stream carrying tool error text; stderr by default, stdout for the mkvtoolnix tools protected virtual string GetErrorOutput(BufferedCommandResult result) => result.StandardError; - protected bool LogFailedResult(BufferedCommandResult result) + protected bool LogFailedResult( + BufferedCommandResult result, + string fileName, + [CallerMemberName] string operation = "" + ) { // ffmpeg can exit 0 yet report a fatal error on stderr (see FfMpegTool), so failures may carry // an error summary. Log the summary as its own value with the " : " separator in the template. // Folding the separator into a quoted string value instead puts the quote right after the exit // code, rendering: ExitCode: 0" : ... instead of the correct ExitCode: 0 : "...". - string summary = CleanForLog(Summarize(GetErrorOutput(result).Trim())); + // Prefer the stream the tool writes errors to (GetErrorOutput); if it is empty, fall back to the + // other captured stream so an error on an unexpected stream is still logged. + string stdErr = result.StandardError.Trim(); + string stdOut = result.StandardOutput.Trim(); + string primary = GetErrorOutput(result).Trim(); + string error = + !string.IsNullOrEmpty(primary) ? primary + : !string.IsNullOrEmpty(stdErr) ? stdErr + : stdOut; + string summary = CleanForLog(Summarize(error)); if (string.IsNullOrEmpty(summary)) { Log.Error( - "Failed execution of {ToolType} : ExitCode: {ExitCode}", + "Failed execution of {ToolType} : {Operation:l} : ExitCode: {ExitCode} : {FileName}", GetToolType(), - result.ExitCode + operation, + result.ExitCode, + fileName ); } else { Log.Error( - "Failed execution of {ToolType} : ExitCode: {ExitCode} : {Error}", + "Failed execution of {ToolType} : {Operation:l} : ExitCode: {ExitCode} : {Error} : {FileName}", GetToolType(), + operation, result.ExitCode, - summary + summary, + fileName ); } return false; @@ -179,21 +163,12 @@ protected static string CleanForLog(string text) return builder.ToString().Trim(); } - protected bool LogFailedResult(CommandResult result) - { - Log.Error( - "Failed execution of {ToolType} : ExitCode: {ExitCode}", - GetToolType(), - result.ExitCode - ); - return false; - } - public bool Execute( Command command, bool stdOutSummary, bool stdErrSummary, - out BufferedCommandResult bufferedCommandResult + out BufferedCommandResult bufferedCommandResult, + [CallerMemberName] string operation = "" ) { bufferedCommandResult = null!; @@ -216,8 +191,9 @@ out BufferedCommandResult bufferedCommandResult .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 ); @@ -235,8 +211,9 @@ out BufferedCommandResult bufferedCommandResult 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 ); @@ -248,7 +225,12 @@ out BufferedCommandResult bufferedCommandResult } } - public bool ExecuteStreamStdErr(Command command, Action lineAction, out int exitCode) + public bool ExecuteStreamStdErr( + Command command, + Action lineAction, + out int exitCode, + [CallerMemberName] string operation = "" + ) { exitCode = -1; int processId = -1; @@ -277,8 +259,9 @@ public bool ExecuteStreamStdErr(Command command, Action lineAction, out .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 ); @@ -290,8 +273,9 @@ public bool ExecuteStreamStdErr(Command command, Action lineAction, out 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 ); diff --git a/PlexCleaner/MediaToolInfo.cs b/PlexCleaner/MediaToolInfo.cs index 9dfe4abc..29c6d260 100644 --- a/PlexCleaner/MediaToolInfo.cs +++ b/PlexCleaner/MediaToolInfo.cs @@ -1,5 +1,3 @@ -using Serilog; - namespace PlexCleaner; public class MediaToolInfo diff --git a/PlexCleaner/MkvMergeTool.cs b/PlexCleaner/MkvMergeTool.cs index 4223b4e4..6c61801a 100644 --- a/PlexCleaner/MkvMergeTool.cs +++ b/PlexCleaner/MkvMergeTool.cs @@ -3,7 +3,6 @@ using CliWrap; using CliWrap.Buffered; using ptr727.Utilities; -using Serilog; // https://mkvtoolnix.download/doc/mkvmerge.html @@ -120,30 +119,15 @@ public bool GetMediaPropsJson(string fileName, out string json) .Build(); // Execute command - Log.Debug("Getting media info : {FileName}", 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); - } - if (result.StandardError.Length > 0) - { - // TODO: This probably never gets hit due to mkvmerge not using stderr - Log.Warning( - "{ToolType} : Warning getting media info : {FileName}", - GetToolType(), - fileName - ); - Log.Warning("{ToolType} : {Warning}", GetToolType(), result.StandardError.Trim()); + return LogFailedResult(result, fileName); } + // Ignore "if (result.StandardError.Length > 0)" pattern, mkv tools only emit to stdout // Get JSON from stdout json = result.StandardOutput; @@ -267,7 +251,7 @@ string outputName // Execute command return Execute(command, true, true, out BufferedCommandResult result) - && (result.ExitCode is 0 or 1 || LogFailedResult(result)); + && (result.ExitCode is 0 or 1 || LogFailedResult(result, inputName)); } public bool ReMuxToMkv(string inputName, string outputName) @@ -284,7 +268,7 @@ public bool ReMuxToMkv(string inputName, string outputName) // Execute command return Execute(command, true, true, out BufferedCommandResult result) - && (result.ExitCode is 0 or 1 || LogFailedResult(result)); + && (result.ExitCode is 0 or 1 || LogFailedResult(result, inputName)); } public bool RemoveSubtitles(string inputName, string outputName) @@ -301,7 +285,7 @@ public bool RemoveSubtitles(string inputName, string outputName) // Execute command return Execute(command, true, true, out BufferedCommandResult result) - && (result.ExitCode is 0 or 1 || LogFailedResult(result)); + && (result.ExitCode is 0 or 1 || LogFailedResult(result, inputName)); } public bool MergeToMkv( @@ -335,7 +319,7 @@ string outputName // Execute command return Execute(command, true, true, out BufferedCommandResult result) - && (result.ExitCode is 0 or 1 || LogFailedResult(result)); + && (result.ExitCode is 0 or 1 || LogFailedResult(result, sourceOne)); } [GeneratedRegex( diff --git a/PlexCleaner/MkvPropEditTool.cs b/PlexCleaner/MkvPropEditTool.cs index bf88362b..987203e4 100644 --- a/PlexCleaner/MkvPropEditTool.cs +++ b/PlexCleaner/MkvPropEditTool.cs @@ -25,6 +25,10 @@ public class Tool : MediaTool public IGlobalOptions GetBuilder() => Builder.Create(GetToolPath()); + // mkvpropedit, like all mkvtoolnix tools, writes errors to stdout, not stderr + protected override string GetErrorOutput(BufferedCommandResult result) => + result.StandardOutput; + public override bool GetInstalledVersion(out MediaToolInfo mediaToolInfo) { // Get version info @@ -70,8 +74,8 @@ public bool SetTrackLanguage( .Build(); // Execute command - return Execute(command, out CommandResult result) - && (result.ExitCode is 0 || LogFailedResult(result)); + return Execute(command, out BufferedCommandResult result) + && (result.ExitCode is 0 || LogFailedResult(result, fileName)); } public bool SetTrackFlags(string fileName, MediaProps mediaProps) @@ -101,8 +105,8 @@ public bool SetTrackFlags(string fileName, MediaProps mediaProps) .Build(); // Execute command - return Execute(command, out CommandResult result) - && (result.ExitCode is 0 || LogFailedResult(result)); + return Execute(command, out BufferedCommandResult result) + && (result.ExitCode is 0 || LogFailedResult(result, fileName)); } public bool ClearDefaultFlags(string fileName, IEnumerable trackList) @@ -130,8 +134,8 @@ public bool ClearDefaultFlags(string fileName, IEnumerable trackList .Build(); // Execute command - return Execute(command, out CommandResult result) - && (result.ExitCode is 0 || LogFailedResult(result)); + return Execute(command, out BufferedCommandResult result) + && (result.ExitCode is 0 || LogFailedResult(result, fileName)); } public bool ClearTags(string fileName, MediaProps mediaProps) @@ -166,8 +170,8 @@ public bool ClearTags(string fileName, MediaProps mediaProps) .Build(); // Execute command - return Execute(command, out CommandResult result) - && (result.ExitCode is 0 || LogFailedResult(result)); + return Execute(command, out BufferedCommandResult result) + && (result.ExitCode is 0 || LogFailedResult(result, fileName)); } public bool ClearAttachments(string fileName, MediaProps mediaProps) @@ -194,8 +198,8 @@ public bool ClearAttachments(string fileName, MediaProps mediaProps) .Build(); // Execute command - return Execute(command, out CommandResult result) - && (result.ExitCode is 0 || LogFailedResult(result)); + return Execute(command, out BufferedCommandResult result) + && (result.ExitCode is 0 || LogFailedResult(result, fileName)); } } } diff --git a/PlexCleaner/Monitor.cs b/PlexCleaner/Monitor.cs index 6a4efb69..c2f97a32 100644 --- a/PlexCleaner/Monitor.cs +++ b/PlexCleaner/Monitor.cs @@ -1,5 +1,3 @@ -using Serilog; - namespace PlexCleaner; public class Monitor diff --git a/PlexCleaner/PluginLoader.cs b/PlexCleaner/PluginLoader.cs index 2544ee00..58458845 100644 --- a/PlexCleaner/PluginLoader.cs +++ b/PlexCleaner/PluginLoader.cs @@ -3,7 +3,6 @@ using System.Reflection; using System.Runtime.InteropServices; using System.Runtime.Loader; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/Process.cs b/PlexCleaner/Process.cs index 69994586..e35919a7 100644 --- a/PlexCleaner/Process.cs +++ b/PlexCleaner/Process.cs @@ -1,5 +1,4 @@ using System.Diagnostics; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/ProcessDriver.cs b/PlexCleaner/ProcessDriver.cs index b4545247..24c0f6fe 100644 --- a/PlexCleaner/ProcessDriver.cs +++ b/PlexCleaner/ProcessDriver.cs @@ -1,6 +1,5 @@ using System.Collections.Concurrent; using System.Diagnostics; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/ProcessFile.cs b/PlexCleaner/ProcessFile.cs index e2926d63..83b51913 100644 --- a/PlexCleaner/ProcessFile.cs +++ b/PlexCleaner/ProcessFile.cs @@ -1,5 +1,4 @@ using System.Diagnostics; -using Serilog; using Serilog.Events; namespace PlexCleaner; @@ -1760,7 +1759,6 @@ public bool Verify(bool conditional, out bool canRepair) public static VerifyResult VerifyMediaStreams(FileInfo fileInfo) { // Verify - Log.Debug("Verifying media streams : {FileName}", fileInfo.FullName); VerifyResult verifyResult = Tools.FfMpeg.VerifyMedia(fileInfo.FullName); // Log the classified outcome so a failure is diagnosable, unless it was a cancellation @@ -1920,7 +1918,6 @@ private bool VerifyBitrate() // https://en.wikipedia.org/wiki/YIFY // Calculate bitrate - Log.Debug("Calculating bitrate info : {FileName}", FileInfo.FullName); if (!GetBitrateInfo(out BitrateInfo? bitrateInfo) || bitrateInfo == null) { // Error @@ -2579,7 +2576,6 @@ out DtsInfo? dtsInfo private bool GetIdetInfo(out FfMpegIdetInfo? idetInfo) { // Count the frame types using the idet filter - Log.Debug("Counting interlaced frames : {FileName}", FileInfo.FullName); if (!FfMpegIdetInfo.GetIdetInfo(FileInfo.FullName, out idetInfo) || idetInfo == null) { // Cancel requested diff --git a/PlexCleaner/ProcessOptions.cs b/PlexCleaner/ProcessOptions.cs index a141c9ee..9e1fd05d 100644 --- a/PlexCleaner/ProcessOptions.cs +++ b/PlexCleaner/ProcessOptions.cs @@ -1,6 +1,5 @@ using System.Text.Json.Serialization; using System.Text.RegularExpressions; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/Program.cs b/PlexCleaner/Program.cs index ede7475b..e22b31fa 100644 --- a/PlexCleaner/Program.cs +++ b/PlexCleaner/Program.cs @@ -1,7 +1,6 @@ using System.Diagnostics; using System.Runtime.InteropServices; using ptr727.Utilities; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/SevenZipTool.cs b/PlexCleaner/SevenZipTool.cs index 5f6f9113..4f60f1fa 100644 --- a/PlexCleaner/SevenZipTool.cs +++ b/PlexCleaner/SevenZipTool.cs @@ -3,7 +3,6 @@ using System.Text.RegularExpressions; using CliWrap; using CliWrap.Buffered; -using Serilog; // 7za [...] [...] [<@listfiles...>] @@ -137,8 +136,8 @@ public bool UnZip(IGlobalOptions options, string inputFile, string outputFolder) .Build(); // Execute command - return Execute(command, out CommandResult result) - && (result.ExitCode == 0 || LogFailedResult(result)); + return Execute(command, out BufferedCommandResult result) + && (result.ExitCode == 0 || LogFailedResult(result, inputFile)); } public bool BootstrapDownload() diff --git a/PlexCleaner/SidecarFile.cs b/PlexCleaner/SidecarFile.cs index 9e34faa4..0a01ca1a 100644 --- a/PlexCleaner/SidecarFile.cs +++ b/PlexCleaner/SidecarFile.cs @@ -2,7 +2,6 @@ using System.Diagnostics; using System.Security.Cryptography; using ptr727.Utilities; -using Serilog; using Serilog.Events; namespace PlexCleaner; diff --git a/PlexCleaner/SidecarFileJsonSchema.cs b/PlexCleaner/SidecarFileJsonSchema.cs index 0ccd36c3..490319e0 100644 --- a/PlexCleaner/SidecarFileJsonSchema.cs +++ b/PlexCleaner/SidecarFileJsonSchema.cs @@ -3,7 +3,6 @@ using System.Text.Json; using System.Text.Json.Serialization; using ptr727.Utilities; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/SubtitleProps.cs b/PlexCleaner/SubtitleProps.cs index e8dbbb38..57b77f4f 100644 --- a/PlexCleaner/SubtitleProps.cs +++ b/PlexCleaner/SubtitleProps.cs @@ -1,5 +1,4 @@ using System.Globalization; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/TagMapSet.cs b/PlexCleaner/TagMapSet.cs index f300a643..2e6dc84f 100644 --- a/PlexCleaner/TagMapSet.cs +++ b/PlexCleaner/TagMapSet.cs @@ -1,5 +1,3 @@ -using Serilog; - namespace PlexCleaner; public class TagMapSet diff --git a/PlexCleaner/ToolInfoJsonSchema.cs b/PlexCleaner/ToolInfoJsonSchema.cs index 902420a4..aca3c18b 100644 --- a/PlexCleaner/ToolInfoJsonSchema.cs +++ b/PlexCleaner/ToolInfoJsonSchema.cs @@ -1,7 +1,6 @@ using System.ComponentModel; using System.Text.Json; using System.Text.Json.Serialization; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/Tools.cs b/PlexCleaner/Tools.cs index 249e2f74..79bb1e73 100644 --- a/PlexCleaner/Tools.cs +++ b/PlexCleaner/Tools.cs @@ -1,7 +1,6 @@ using System.Diagnostics; using System.Runtime.InteropServices; using ptr727.Utilities; -using Serilog; namespace PlexCleaner; @@ -30,8 +29,9 @@ public static bool VerifyTools() && !Program.Config.ToolsOptions.UseSystem ) { - Log.Warning("Folder tools are not supported on Linux"); - Log.Warning("Set 'ToolsOptions:UseSystem' to 'true' on Linux"); + Log.Warning( + "Folder tools are not supported on Linux, forcing 'ToolsOptions:UseSystem' to 'true'" + ); Program.Config.ToolsOptions.UseSystem = true; } diff --git a/PlexCleaner/ToolsOptions.cs b/PlexCleaner/ToolsOptions.cs index 6c16c273..78a8355c 100644 --- a/PlexCleaner/ToolsOptions.cs +++ b/PlexCleaner/ToolsOptions.cs @@ -1,6 +1,5 @@ using System.Runtime.InteropServices; using System.Text.Json.Serialization; -using Serilog; namespace PlexCleaner; diff --git a/PlexCleaner/TrackProps.cs b/PlexCleaner/TrackProps.cs index 95d2929b..b7cd8a5c 100644 --- a/PlexCleaner/TrackProps.cs +++ b/PlexCleaner/TrackProps.cs @@ -1,6 +1,5 @@ using System.Diagnostics; using System.Globalization; -using Serilog; using Serilog.Events; namespace PlexCleaner; diff --git a/PlexCleaner/VideoProps.cs b/PlexCleaner/VideoProps.cs index 43928ddc..4ac1f424 100644 --- a/PlexCleaner/VideoProps.cs +++ b/PlexCleaner/VideoProps.cs @@ -1,4 +1,3 @@ -using Serilog; using Serilog.Events; // TODO: Find a better way to create profile levels diff --git a/PlexCleanerTests/ToolFailureLogFormatTests.cs b/PlexCleanerTests/ToolFailureLogFormatTests.cs index 5f9c3a3c..88a6a87a 100644 --- a/PlexCleanerTests/ToolFailureLogFormatTests.cs +++ b/PlexCleanerTests/ToolFailureLogFormatTests.cs @@ -47,13 +47,23 @@ protected override bool GetLatestVersionWindows(out MediaToolInfo mediaToolInfo) return false; } - public bool InvokeLogFailedResult(BufferedCommandResult result) => LogFailedResult(result); + public bool InvokeLogFailedResult( + BufferedCommandResult result, + string fileName, + string operation + ) => LogFailedResult(result, fileName, operation); } // Call LogFailedResult with the given exit code and stderr, capturing the emitted event by // temporarily redirecting the static Serilog logger, then render it through the {Message} template // the console and file sinks use - private static string RenderLogFailedResult(int exitCode, string stderr) + private static string RenderLogFailedResult( + int exitCode, + string stderr, + string fileName = "file.mkv", + string stdout = "", + string operation = "Verify" + ) { CapturingSink sink = new(); ILogger original = Log.Logger; @@ -66,10 +76,10 @@ private static string RenderLogFailedResult(int exitCode, string stderr) exitCode, DateTimeOffset.MinValue, DateTimeOffset.MinValue, - string.Empty, + stdout, stderr ); - _ = tool.InvokeLogFailedResult(result).Should().BeFalse(); + _ = tool.InvokeLogFailedResult(result, fileName, operation).Should().BeFalse(); } finally { @@ -97,14 +107,29 @@ public void LogFailedResult_WithStderr_SeparatorStaysOutsideQuotes() // The error text is quoted as its own value, opening after the " : " separator _ = rendered.Should().Contain("ExitCode: 0 : \""); _ = rendered.Should().Contain(Stderr); + // The file name follows as the last quoted value + _ = rendered.Should().EndWith("\"file.mkv\""); // The stray-quote bug rendered "ExitCode: 0\" : ..." with the quote right after the number _ = rendered.Should().NotContain("ExitCode: 0\""); } [Fact] - public void LogFailedResult_WithoutStderr_HasNoTrailingSeparatorOrQuote() + public void LogFailedResult_WithoutStderr_HasNoErrorValueButKeepsFileName() { + // With no output on either stream the error value is omitted, leaving the operation, exit code + // and file name string rendered = RenderLogFailedResult(2, string.Empty); - _ = rendered.Should().Be("Failed execution of FfMpeg : ExitCode: 2"); + _ = rendered + .Should() + .Be("Failed execution of FfMpeg : Verify : ExitCode: 2 : \"file.mkv\""); + } + + [Fact] + public void LogFailedResult_ErrorOnStdout_FallsBackToStdout() + { + // A tool that writes its error to stdout with an empty stderr (e.g. mkvtoolnix) is still logged + const string StdoutError = "Error: the file could not be opened for reading"; + string rendered = RenderLogFailedResult(2, string.Empty, stdout: StdoutError); + _ = rendered.Should().Contain(StdoutError); } }