restic: Log file on Windows contains progress status text, escape characters and extra line breaks

I can also confirm the issue shows up for me in powershell after updating to v0.12.0, and reverting to v0.11.0 fixes the issue.

I did a bit of testing; as far as I can tell, the issue currently seems to only affect powershell, and only when redirecting restic output to a log file. If the output isn’t redirected, there’s no problem. I checked with both Tee-Object, Out-File and normal redirection as below, both in a simple powershell script and just in a live terminal:

D:\restic\restic.exe --repo 'C:\restic_repo' --password-file 'C:\repopass' --verbose backup 'C:\Morrowind' | Out-File 'D:\restic\logs\testlog.txt'
D:\restic\restic.exe --repo 'C:\restic_repo' --password-file 'C:\repopass' --verbose backup 'C:\Morrowind' > 'D:\restic\logs\testlog.txt'
& D:\restic\restic.exe --repo 'C:\restic_repo' --password-file 'C:\repopass' --verbose backup 'C:\Morrowind' 3>&1 2>> $ErrorLog | Tee-Object -Append $SuccessLog

Whether restic is run by a powershell script or in a live terminal doesn’t seem to matter; the unwanted characters still end up in the output file.

I suspect normal redirection being affected as well as the two piped versions in my tests is because of this:

Using the redirection operator with a file target is functionally equivalent to piping to Out-File with no extra parameters. (https://docs.microsoft.com/en-us/powershell/module/microsoft.powershell.core/about/about_redirection?view=powershell-7.1)

It looks like you already have a very good idea of what’s causing the behaviour, so I’m not sure how useful the below paragraphs will be…

That said, I was curious, so I did some digging, and think what I found might explain why the reports on which versions/terminals are affected appear to conflict at times in this thread.

I started with a git bisect between v0.11.0 and v0.12.0, which pointed to this commit (PR https://github.com/restic/restic/pull/3150) as where the problem first appeared for me (in powershell):

PS D:\restic> git bisect bad
b48f579530be5de1de08773a9ba27d241fcc9c1f is the first bad commit

Which is a little weird, given that particular PR was supposed to resolve this specific problem.

Bearing that in mind, I went backwards further, as v0.10.0 and v0.9.6 are mentioned at the beginning of this issue. I found I could reproduce the problem on 0.9.6 (again, still in powershell), but not on 0.10.0, which is the inverse of the original issue report.

Using the downloadable restic binaries, I was able to pin the first appearance of the problem down to between v0.8.3 and v0.9.0. Unfortunately, I was unable to bisect fully due to problems building some of the older restic commits (may be user error, not sure). I narrowed it down somewhat though:

PS D:\restic> git bisect skip
There are only 'skip'ped commits left to test.
The first bad commit could be any of:
38926d85760ab7ced41c088c94237db634088caf
a5c0cf23244c6da77434cc93a2eb3aa80c5dd1e4
9fac2ca832459801a730ad3cfcf24af2c23db22d
f279731168104727b1f47a5f9fcf460590f2792d
1af96fc6dd782176983386f8fa602552da9f5fbf
76b616451fcca84674f514d2bc41122f30bc4834
c703d21d5524835f8405f52b2d3ce6cee3e04df9
fd12a3af20c0fc7cd296c0f11f02d1f786b07538
0e78ac92d875e85c43aba9b315baca4be93d1383
We cannot bisect more!

Anyway, while bisecting, I checked again using cmd, and was surprised to find that the symptoms were the inverse of powershell; so when powershell works fine, cmd doesn’t, and vice versa.

When using cmd, redirected output is normal for the 0.9.x series and 0.12.0, but has problems in versions v0.10.0 and v0.11.0. Powershell is the opposite, it has the problems with redirected output with the v0.9.x series and v0.12.0, but doesn’t with v0.10.0 or v0.11.0. For the 0.8.x series of releases, both cmd and powershell appear to work fine.

Based on the above, I think the changes in PR 3105 and PR https://github.com/restic/restic/pull/2608 caused the problem to switch between powershell and cmd (and possibly other terminals?). This was apparently because of the isPipe condition being flipped, and is why there’s some confusion over which terminals/verions are affected here.

tldr; redirected output looks like it has had this issue in powershell since v0.9.0. PR 2608 unintentionally fixed it for powershell but broke it for cmd (and possibly others?), then PR 3105 reverted this.

Hope the above helps!

@MichaelEischer I am not sure, but I believe it was v0.11 cause I set my backup and got notified since 29 Dec last year. Note that v0.11 tagged on Nov 5 2020.

Yes, the result is obtained with powershell and pushed via discord webhook for notification. Please find my code and its corresponding output below.

$env:RESTIC_PASSWORD = "REDACTED"
$env:RESTIC_REPOSITORY = "REDACTED"

$discord_webhook = "REDACTED"
function send_message {
    [System.Collections.ArrayList]$embedArray = @()
    $embedObject = [PSCustomObject]@{
        title = 'New Restic Backup'
        color = $args[0]
        description = $args[1]
        footer = [PSCustomObject]@{
            text = $args[2]
        }
    }
    $embedArray.Add($embedObject)
    $payload = [PSCustomObject]@{
        embeds = $embedArray
    }

    Invoke-RestMethod -Uri $discord_webhook `
        -Body ($payload | ConvertTo-Json -Depth 4) `
        -Method Post -ContentType 'application/json'
}

cmd /c restic backup --use-fs-snapshot `
    $env:USERPROFILE `
    G:\ `
    --exclude="$env:USERPROFILE\Dropbox" `
    --exclude="$env:LOCALAPPDATA" `
    --exclude="G:\System Volume Information" | Tee-Object -Variable output_string
# Variable from Tee-Object is a list
$output_string = $output_string | Out-String

if ( $LastExitCode -eq 0 )
{
    send_message "3066993" "$output_string" "Successful on '$env:computername'"
} else {
    send_message "15158332" "$output_string" "Failed at '$env:computername'"
}

result before (presumably v0.11)

result now (v0.12)