Backup, JSON, systemd, and repeated progress logs

organicveggie · October 20, 2021, 7:30pm

I have a strange one that quite possibly may be my mistake, but I’m uncertain.

I run forget and backup via Bash scripts which are triggered by systemd timers on Ubuntu 20.04. When I launch the backup process via systemctl with restic producing normal text output, I see the output I expect in the journald logs:

...
Oct 20 09:28:09 host1 restic-backup.sh[982684]: [0:00] 100.00%  25 / 25 snapshots
Oct 20 09:28:10 host1 restic-backup.sh[982697]: using parent snapshot 37dc982c
Oct 20 09:28:11 host1 restic-backup.sh[982697]: Files:           0 new,     4 changed,  6523 unmodified
Oct 20 09:28:11 host1 restic-backup.sh[982697]: Dirs:            0 new,     5 changed,  2011 unmodified
Oct 20 09:28:11 host1 restic-backup.sh[982697]: Added to the repo: 173.197 KiB
Oct 20 09:28:11 host1 restic-backup.sh[982697]: processed 6527 files, 687.945 MiB in 0:01
Oct 20 09:28:11 host1 restic-backup.sh[982697]: snapshot c1fb982f saved
Oct 20 09:28:11 host1 restic-backup.sh[982683]: Finished restic backup

When I add the --json flag and run the script by hand, I get the results I expect:

$ /usr/local/sbin/restic-backup.sh
Starting restic backup
using temporary cache in /tmp/restic-check-cache-966009993
repository 7477442f opened successfully, password is correct
created new cache in /tmp/restic-check-cache-966009993
create exclusive lock for repository
load indexes
check all packs
check snapshots, trees and blobs
no errors were found26 snapshots
[0:00] 100.00%  26 / 26 snapshots
{"message_type":"status","percent_done":0}
{"message_type":"status","percent_done":0.016352636412683117,"total_files":677,"files_done":17,"total_bytes":1214055,"bytes_done":19853}
{"message_type":"status","percent_done":0.08357231648752914,"total_files":1133,"files_done":174,"total_bytes":3422138,"bytes_done":285996}
{"message_type":"status","percent_done":0.0034864367706821065,"total_files":1853,"files_done":314,"total_bytes":133255249,"bytes_done":464586}
<snip>
{"message_type":"status","percent_done":0.9960340865076655,"total_files":6527,"files_done":6222,"total_bytes":721364953,"bytes_done":718504082}
{"message_type":"summary","files_new":0,"files_changed":1,"files_unmodified":6526,"dirs_new":0,"dirs_changed":2,"dirs_unmodified":2014,"data_blobs":1,"tree_blobs":3,"data_added":71017,"total_files_processed":6527,"total_bytes_processed":721364953,"total_duration":0.918486206,"snapshot_id":"bcc5c5b1"}
Finished restic backup

But when I add the --json flag and let systemd launch the backup service, I get a slew of redundant progress messages in the logs:

$ systemctl show -p InvocationID --value restic-backup.service
9e69f66111b34811b787a93895150cfd
$ journalctl -o short-iso _SYSTEMD_INVOCATION_ID=9e69f66111b34811b787a93895150cfd |wc -l
37501
$ journalctl -o short-iso SYSLOG_IDENTIFIER=restic-backup.sh _SYSTEMD_INVOCATION_ID=9e69f66111b34811b787a93895150cfd |tail -n 10
2021-10-20T09:32:51-0700 Z97X-UD5H restic-backup.sh[983408]: {"message_type":"status","seconds_elapsed":1,"seconds_remaining":4,"percent_done":0.9999629840896144,"total_files":6527,"files_done":6477,"total_bytes":721365481,"bytes_done":721338779}
2021-10-20T09:32:51-0700 Z97X-UD5H restic-backup.sh[983408]: {"message_type":"status","seconds_elapsed":1,"seconds_remaining":4,"percent_done":0.9999629840896144,"total_files":6527,"files_done":6478,"total_bytes":721365481,"bytes_done":721338779}
2021-10-20T09:32:51-0700 Z97X-UD5H restic-backup.sh[983408]: {"message_type":"status","seconds_elapsed":1,"seconds_remaining":4,"percent_done":0.9999629840896144,"total_files":6527,"files_done":6478,"total_bytes":721365481,"bytes_done":721338779}
2021-10-20T09:32:51-0700 Z97X-UD5H restic-backup.sh[983408]: {"message_type":"status","seconds_elapsed":1,"seconds_remaining":4,"percent_done":0.9999629840896144,"total_files":6527,"files_done":6478,"total_bytes":721365481,"bytes_done":721338779}
2021-10-20T09:32:51-0700 Z97X-UD5H restic-backup.sh[983408]: {"message_type":"status","seconds_elapsed":1,"seconds_remaining":4,"percent_done":0.99996356077371,"total_files":6527,"files_done":6478,"total_bytes":721365481,"bytes_done":721339195}
2021-10-20T09:32:51-0700 Z97X-UD5H restic-backup.sh[983408]: {"message_type":"status","seconds_elapsed":1,"seconds_remaining":4,"percent_done":0.99996356077371,"total_files":6527,"files_done":6479,"total_bytes":721365481,"bytes_done":721339195}
2021-10-20T09:32:51-0700 Z97X-UD5H restic-backup.sh[983408]: {"message_type":"status","seconds_elapsed":1,"seconds_remaining":4,"percent_done":0.99996356077371,"total_files":6527,"files_done":6479,"total_bytes":721365481,"bytes_done":721339195}
2021-10-20T09:32:51-0700 Z97X-UD5H restic-backup.sh[983408]: {"message_type":"status","seconds_elapsed":1,"seconds_remaining":4,"percent_done":0.99996356077371,"total_files":6527,"files_done":6479,"total_bytes":721365481,"bytes_done":721339195}
2021-10-20T09:32:51-0700 Z97X-UD5H restic-backup.sh[983408]: {"message_type":"status","seconds_elapsed":1,"seconds_remaining":4,"percent_done":0.9999654294519812,"total_files":6527,"files_done":6479,"total_bytes":721365481,"bytes_done":721340543}
2021-10-20T09:32:51-0700 Z97X-UD5H restic-backup.sh[983408]: {"message_type":"status","seconds_elapsed":1,"seconds_remaining":4,"percent_done":0.9999654294519812,"total_files":6527,"files_done":6480,"total_bytes":721365481,"bytes_done":721340543}
$ journalctl -o short-iso _SYSTEMD_INVOCATION_ID=9e69f66111b34811b787a93895150cfd |grep "message_type"|grep "status"| wc -l
37475

And the summary information seems to be missing:

$ journalctl -o short-iso _SYSTEMD_INVOCATION_ID=9e69f66111b34811b787a93895150cfd |grep "summary"| wc -l
0

Any ideas on what is going on here?

rawtaz · October 20, 2021, 7:55pm

Is that you, Broccoli?

organicveggie · October 20, 2021, 7:57pm

How did you guess?

rawtaz · October 20, 2021, 8:15pm

It’s probably a matter of restic detecting a non-interactive terminal and thereby adjusting it’s output. Look in Manual — restic 0.12.1 documentation and search for “interactive”, it says a bit about it.

You could try setting the RESTIC_PROGRESS_FPS environment variable for restic when it’s ran by systemd to e.g. the value 0.016666 and see if this makes the {"message_type":"status","seconds_elapsed" ... messages reccur in a slower fashion, should be once every second I suppose.

I haven’t been able to find exactly where in the code restic determines that the seconds_elapsed and seconds_remaining keys should only be output when the terminal is non-interactive, assuming this is the case. In json.go it seems that they’re defined to be omitted if empty, but I didn’t see where they’d be empty when running non-interactively. If someone knows how this works, please let me know

What does your systemd file look like if I may ask?

organicveggie · October 20, 2021, 8:33pm

You could try setting the RESTIC_PROGRESS_FPS

I can confirm that works as a usable workaround.

Here is /etc/systemd/system/restic-backup.service:

[Unit]
Description=Run backup job
Documentation=man:restic(1)
Documentation=https://restic.readthedocs.io/en/stable/
Requires=local-fs.target
Requires=network.target
OnFailure=restic-backup-failure.service

[Service]
Type=oneshot
Environment="RESTIC_CACHE_DIR=/var/cache/restic"
ExecStartPre=/usr/local/sbin/restic-forget.sh
ExecStart=/usr/local/sbin/restic-backup.sh
ExecStartPost=/usr/local/sbin/restic-export.sh

# Security hardening (see man 7 systemd.exec)
PrivateTmp=true
ProtectHome=read-only
ProtectSystem=full
ProtectKernelModules=true
ProtectKernelTunables=true
ProtectControlGroups=true
MemoryDenyWriteExecute=true
ExecPaths=/usr/local/sbin/restic-forget.sh
ExecPaths=/usr/local/sbin/restic-export.sh
ReadOnlyPaths=/etc/restic
ReadOnlyPaths=/usr/local/sbin/restic-forget.sh
ReadOnlyPaths=/usr/local/sbin/restic-export.sh
ReadWritePaths=-/var/lib/node-exporter
ReadWritePaths=-/var/cache/restic

And here’s what /usr/local/sbin/restic-backup.sh looks like:

#!/bin/bash
set -eu

# Load repository config via environment variables
source '/etc/restic/restic-env.sh'

echo "Starting restic backup"

# Check if repository is okay
restic check

# Create new backup
export RESTIC_PROGRESS_FPS=0.016666
restic backup \
       --one-file-system \
       --exclude-caches \
       --files-from '/etc/restic/includes' \
       --exclude-file '/etc/restic/excludes' \
       --tag automated \
       --json

echo "Finished restic backup"

exit 0

organicveggie · October 20, 2021, 8:40pm

Couple places, although as a new user to the forums, I can only post 2 links at a time.

github.com

restic/restic/blob/fb5d9345a7c6eedf6fac17a277d261fb9f3ba6f0/internal/ui/termstatus/terminal_unix.go#L25


      
          	return posixClearCurrentLine
          }
          
          // moveCursorUp moves the cursor to the line n lines above the current one.
          func moveCursorUp(wr io.Writer, fd uintptr) func(io.Writer, uintptr, int) {
          	return posixMoveCursorUp
          }
          
          // CanUpdateStatus returns true if status lines can be printed, the process
          // output is not redirected to a file or pipe.
          func CanUpdateStatus(fd uintptr) bool {
          	if !terminal.IsTerminal(int(fd)) {
          		return false
          	}
          	term := os.Getenv("TERM")
          	if term == "" {
          		return false
          	}
          	// TODO actually read termcap db and detect if terminal supports what we need
          	return term != "dumb"
          }

Which is used by:

github.com

restic/restic/blob/fb5d9345a7c6eedf6fac17a277d261fb9f3ba6f0/cmd/restic/global.go#L155


      
          func stdinIsTerminal() bool {
          	return terminal.IsTerminal(int(os.Stdin.Fd()))
          }
          
          func stdoutIsTerminal() bool {
          	// mintty on windows can use pipes which behave like a posix terminal,
          	// but which are not a terminal handle
          	return terminal.IsTerminal(int(os.Stdout.Fd())) || stdoutCanUpdateStatus()
          }
          
          func stdoutCanUpdateStatus() bool {
          	return termstatus.CanUpdateStatus(os.Stdout.Fd())
          }
          
          func stdoutTerminalWidth() int {
          	w, _, err := terminal.GetSize(int(os.Stdout.Fd()))
          	if err != nil {
          		return 0
          	}
          	return w
          }

organicveggie · October 20, 2021, 8:41pm

Which is called by:

github.com

restic/restic/blob/fb5d9345a7c6eedf6fac17a277d261fb9f3ba6f0/cmd/restic/progress.go#L17

    
      
          	"strings"
          	"time"
          
          
	"github.com/restic/restic/internal/ui/progress"
          	"github.com/restic/restic/internal/ui/termstatus"
          )
          
          
// calculateProgressInterval returns the interval configured via RESTIC_PROGRESS_FPS
          // or if unset returns an interval for 60fps on interactive terminals and 0 (=disabled)
          // for non-interactive terminals or when run using the --quiet flag
          func calculateProgressInterval(show bool, json bool) time.Duration {
          	interval := time.Second / 60
          	fps, err := strconv.ParseFloat(os.Getenv("RESTIC_PROGRESS_FPS"), 64)
          	if err == nil && fps > 0 {
          		if fps > 60 {
          			fps = 60
          		}
          		interval = time.Duration(float64(time.Second) / fps)
          	} else if !json && !stdoutCanUpdateStatus() || !show {
          		interval = 0
          	}

and

github.com

restic/restic/blob/fb5d9345a7c6eedf6fac17a277d261fb9f3ba6f0/cmd/restic/progress.go#L37

    
      
          	}
          	return interval
          }
          
          
// newProgressMax returns a progress.Counter that prints to stdout.
          func newProgressMax(show bool, max uint64, description string) *progress.Counter {
          	if !show {
          		return nil
          	}
          	interval := calculateProgressInterval(show, false)
          	canUpdateStatus := stdoutCanUpdateStatus()
          
          
	return progress.New(interval, max, func(v uint64, max uint64, d time.Duration, final bool) {
          		var status string
          		if max == 0 {
          			status = fmt.Sprintf("[%s]          %d %s", formatDuration(d), v, description)
          		} else {
          			status = fmt.Sprintf("[%s] %s  %d / %d %s",
          				formatDuration(d), formatPercent(v, max), v, max, description)
          		}

organicveggie · October 20, 2021, 8:50pm

I tried to post links to what I think is the relevant spots in the restic source code, but I ran into a couple of issues:

As a new forum user, I can only post 2 links at a time
I tried to split things across multiple posts, but they were all flagged as spam

Basically, I think the key bits are:

JSONProgress
cmd_backup.runBackup calls:

progressReporter.SetMinUpdatePause(calculateProgressInterval(!gopts.Quiet, gopts.JSON))

calculateProgressInterval() uses stdoutCanUpdateStatus()
which calls termstatus.CanUpdateStatus(os.Stdout.Fd())
which resides in terminal_unix.go
and that uses golang.org/x/crypto/ssh/terminal and the TERM environment variable

rawtaz · October 20, 2021, 9:19pm

Thanks for the walkthrough. So basically this is what makes the seconds keys appear only when on a non-interactive terminal with JSON:

} else if !json && !stdoutCanUpdateStatus() || !show {
		interval = 0
}

MichaelEischer · October 23, 2021, 6:13pm

The log output spam on non-interactive terminals is probably already fixed as a side effect of the following PR, which has been merged but is not yet included in a released version:

github.com/restic/restic

Refactor backup progress

restic:master ← amozoss:upstream-master

opened 11:33PM - 03 Feb 21 UTC

amozoss

+794 -930

What does this PR change? What problem does it solve? ----------------------------------------------------- `ui/backup.go` and `ui/json/backup.go` are almost identical to one another (copy paste). This change refactors the shared logic into `progress.go`. `ui/backup.go` and `ui/json/backup.go` have already begun to diverge, for example ``` // for the last item "/", current is nil if current != nil { p.summary.ProcessedBytes += current.Size } ``` `p.summary.ProcessedBytes += current.Size` was done outside of the lock in json/backup.go , but ui/backup.go had the above This will continue to be a "hope we don't forget to update the other place" problem.. This change also allows the progress reporting/printing to be shared with restore status (forth coming after this is merged).  Was the change discussed in an issue or in the forum before? ------------------------------------------------------------ No it wasn't  Checklist --------- - [X] I have read the [Contribution Guidelines](https://github.com/restic/restic/blob/master/CONTRIBUTING.md#providing-patches) - [X] I have enabled [maintainer edits for this PR](https://help.github.com/en/github/collaborating-with-issues-and-pull-requests/allowing-changes-to-a-pull-request-branch-created-from-a-fork) - [ ] I have added tests for all changes in this PR - [ ] I have added documentation for the changes (in the manual) - [ ] There's a new file in `changelog/unreleased/` that describes the changes for our users (template [here](https://github.com/restic/restic/blob/master/changelog/TEMPLATE)) - [X] I have run `gofmt` on the code in all commits - [X] All commit messages are formatted in the same style as [the other commits in the repo](https://github.com/restic/restic/blob/master/CONTRIBUTING.md#git-commits) - [X] I'm done, this Pull Request is ready for review

@organicveggie Which restic version do you use?

organicveggie · October 23, 2021, 7:08pm

@MichaelEischer Good to know. I’m running 0.12.1:

$ restic version
restic 0.12.1 compiled with go1.16.6 on linux/amd64