Skip to content

fix(filesystem): record why a file mutation failed, not only that it did - #916

Open
m4bard wants to merge 1 commit into
Listenarrs:canaryfrom
m4bard:fix/surface-file-mutation-cause
Open

fix(filesystem): record why a file mutation failed, not only that it did#916
m4bard wants to merge 1 commit into
Listenarrs:canaryfrom
m4bard:fix/surface-file-mutation-cause

Conversation

@m4bard

@m4bard m4bard commented Aug 31, 2026

Copy link
Copy Markdown

A failed file mutation records that it failed and discards why. I went looking for the cause of a real import failure, could not find one, and the reason turned out to be that the information is thrown away in three places on the way out.

Checked against canary a630572e (1.3.4).

Where the detail goes

FileMover.PerformActionOn catches everything and rewraps (listenarr.infrastructure/FileSystem/FileMover.Actions.cs:307-311):

catch (Exception exception) when (exception is not (OperationCanceledException or OutOfMemoryException or StackOverflowException))
{
    LogMutation(FileMutationOutcome.Failed, action, source, destination, exception.Message);
    throw new InvalidOperationException($"Unable to perform {action} on {source} to {destination}", exception);
}

LogMutation then formats a template and calls _logger.LogError(template, arguments) at :439. The overload takes no exception, so the caught object never reaches the logger: no type, no stack, no inner exception. The Reason argument carries exception.Message and nothing else, and it goes through SanitizeText.

DownloadProcessingJobProcessor catches the wrapper and blocks the download with a fixed string (listenarr.infrastructure/Downloads/Processing/DownloadProcessingJobProcessor.cs:135-138):

download.Blocked(
    "Unable to import the download",
    $"See the log of job {job.Id} for more information")

The job's own ProcessingLog records "Unable to perform HardlinkCopy on <source> to <destination>", which is the wrapper's message rather than the cause.

So the operator is told to see the log, and the log has an Errno-free sentence with the same wording.

Why this is worth fixing on its own

I was handed a report of 221 downloads blocked over eleven days, 155 of them with the identical "Unable to perform HardlinkCopy" signature, on a deployment whose download directory and library are genuinely on different filesystems. Everything needed to characterise it was recorded except the one thing that identifies it.

I could not determine the cause, and I do not think anyone could from what is persisted. IsOnSameVolume, EXDEV, a permissions error and a full disk all arrive at the operator as the same sentence.

For what it is worth I could not reproduce it either. Cross-device HardlinkCopy between two real filesystems falls back to a plain copy correctly on this commit, including when the source path is a symlink whose own inode is on the destination's filesystem, which is the shape that deployment has. All thirty-three existing hardlink tests pass. So I am not reporting a hardlink bug. I am reporting that when one happens, nothing says what it was.

Suggested change, smallest first

Pass the exception to the logger. LogMutation could take an optional Exception? and use the LogError(exception, template, args) overload on the Failed branch. That alone would have answered this.

Beyond that, download.Blocked currently receives a constant. Giving it the inner exception's type and message, rather than a pointer to a log line that does not contain them, would let the queue explain itself without a log dive.

A related design point, offered rather than argued

Sonarr does not decide in advance whether a hardlink is possible. DiskTransferService.cs:319-331 on v5-develop calls TryCreateHardLink and falls through to a copy when it returns false, and NzbDrone.Mono/Disk/DiskProvider.cs:433-455 returns false for a symbolic link source and for Errno.EXDEV specifically.

Listenarr predicts instead, with IsOnSameVolume, and only attempts the link when the prediction says yes. The prediction is right in every case I could construct. My reservation is that it has to be right about bind mounts, overlay filesystems and dataset boundaries, where an attempt would simply be told no by the kernel.

I mention it because if the underlying failure does turn out to be a case where the prediction and the kernel disagree, attempting rather than predicting removes the whole class rather than the instance. That is your call, not mine, and it is a bigger change than the logging one.

What I have and have not established

Established by reading a630572e: the three places the detail is dropped, with line numbers. Established by running on this machine: cross-device and cross-device-symlink HardlinkCopy both fall back correctly, and the existing hardlink suite is green.

Not established: the cause of the reported failures. That is the point of the issue rather than a gap in it. If you take the logging change I can ask the reporter to retry and come back with an actual exception.

Worked through with Claude Code at my direction. The citations are source-reading against the stated commit and the fallback results are runs on this machine; the underlying failure is a third-party report I could not reproduce, and I have said so rather than inferred a cause. I reviewed this before posting.

A report of 221 downloads blocked over eleven days arrived with 155 of
them carrying the identical message "Unable to perform HardlinkCopy",
and no way to tell what any of them actually hit. The information is
discarded in two places on the way out.

FileMover.PerformActionOn catches, calls LogMutation with
exception.Message, and rewraps in InvalidOperationException. LogMutation
then calls _logger.LogError(template, arguments), the overload that
takes no exception, so the caught object never reaches the logger: no
type, no stack, no inner exception. It now takes the exception and uses
the overload that records it.

ImportResult.Exception stored exception.Message, which for a mutation
failure is the wrapper naming the operation rather than the cause. It
now walks the InnerException chain. That matters separately from the
log because the row outlives the log file, and it is what an operator
reads when a download is blocked.

The effect is that a cross-device link, a permissions error and a full
disk stop being the same sentence. I could not diagnose the report
behind this and do not believe anyone could from what was persisted.

Deliberately narrow. A sweep of the codebase found 146 catch blocks
across 92 files logging Error or Warning without passing the exception,
and 63 whose entire body is a Debug.WriteLine that the compiler removes
from a Release build. Both are worth addressing and neither belongs in
a change tied to one incident.

Tests: the wrapper-plus-cause shape FileMover actually produces, a
three-deep chain, and a control asserting an exception with no inner
cause still reads exactly as before, so the added text is signal on the
failing case rather than noise on every case. All three fail with the
change reverted, which I checked. Full suite 3121 passed, 0 failed,
130 skipped.

Not included: a fix for the underlying hardlink failure. Cross-device
HardlinkCopy falls back to a plain copy correctly on this commit,
including when the source path is a symlink whose own inode sits on the
destination filesystem, and the existing hardlink suite is green. This
change is what makes the next occurrence diagnosable.


Co-Authored-By: Claude <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant