backup: --quiet ignored with --json

[organicveggie]

Output of restic version

restic 0.12.1 compiled with go1.16.6 on linux/amd64

How did you run restic exactly?

$ export RESTIC_REPOSITORY='rest:https://user:password@rest.example.com/desktop'
$ export RESTIC_PASSWORD='topsecret`

$ restic backup --one-file-system --exclude-caches --files-from '/etc/restic/includes' --exclude-file '/etc/restic/excludes' --tag automated --quiet

$ restic backup --one-file-system --exclude-caches --files-from '/etc/restic/includes' --exclude-file '/etc/restic/excludes' --tag automated --quiet --json
<SNIP>
{"message_type":"status","seconds_elapsed":1,"percent_done":0.9999917653598668,"total_files":6527,"files_done":6526,"total_bytes":720857245,"bytes_done":720851309}
{"message_type":"status","seconds_elapsed":1,"percent_done":0.9999917653598668,"total_files":6527,"files_done":6526,"total_bytes":720857245,"bytes_done":720851309}
{"message_type":"status","seconds_elapsed":1,"percent_done":0.9999944108212439,"total_files":6527,"files_done":6526,"total_bytes":720857245,"bytes_done":720853216}
{"message_type":"status","seconds_elapsed":1,"percent_done":0.9999944108212439,"total_files":6527,"files_done":6527,"total_bytes":720857245,"bytes_done":720853216}
{"message_type":"status","seconds_elapsed":1,"percent_done":0.9999944108212439,"total_files":6527,"files_done":6527,"total_bytes":720857245,"bytes_done":720853216}
{"message_type":"status","seconds_elapsed":1,"percent_done":0.9999944108212439,"total_files":6527,"files_done":6527,"total_bytes":720857245,"bytes_done":720853216}
{"message_type":"status","seconds_elapsed":1,"percent_done":1,"total_files":6527,"files_done":6527,"total_bytes":720857245,"bytes_done":720857245}
{"message_type":"status","seconds_elapsed":1,"percent_done":1,"total_files":6527,"files_done":6527,"total_bytes":720857245,"bytes_done":720857245}
{"message_type":"status","seconds_elapsed":1,"percent_done":1,"total_files":6527,"files_done":6527,"total_bytes":720857245,"bytes_done":720857245}
{"message_type":"status","seconds_elapsed":1,"percent_done":1,"total_files":6527,"files_done":6527,"total_bytes":720857245,"bytes_done":720857245}
{"message_type":"status","seconds_elapsed":1,"percent_done":1,"total_files":6527,"files_done":6527,"total_bytes":720857245,"bytes_done":720857245}
{"message_type":"status","seconds_elapsed":1,"percent_done":1,"total_files":6527,"files_done":6527,"total_bytes":720857245,"bytes_done":720857245}
{"message_type":"status","seconds_elapsed":1,"percent_done":1,"total_files":6527,"files_done":6527,"total_bytes":720857245,"bytes_done":720857245}
{"message_type":"status","seconds_elapsed":1,"percent_done":1,"total_files":6527,"files_done":6527,"total_bytes":720857245,"bytes_done":720857245}
{"message_type":"status","seconds_elapsed":1,"percent_done":1,"total_files":6527,"files_done":6527,"total_bytes":720857245,"bytes_done":720857245}
{"message_type":"status","seconds_elapsed":1,"percent_done":1,"total_files":6527,"files_done":6527,"total_bytes":720857245,"bytes_done":720857245}
{"message_type":"summary","files_new":0,"files_changed":0,"files_unmodified":6527,"dirs_new":0,"dirs_changed":0,"dirs_unmodified":2016,"data_blobs":0,"tree_blobs":0,"data_added":0,"total_files_processed":6527,"total_bytes_processed":720857245,"total_duration":1.329332897,"snapshot_id":"833f79af"}

What backend/server/service did you use to store the repository?

restic rest-server

Expected behavior

restic backup --quiet --json should not print progress information. This would align with the non-json behavior.

Actual behavior

restic backup --quiet --json prints progress status lines.

Steps to reproduce the behavior

See above.

Do you have any idea what may have caused this?

Yes, the logic in the calculateProgressInterval() function looks to be incorrect.

Do you have an idea how to solve the issue?

Yes, swap the order if the if statements in calculateProgressInterval() in progress.go (PR to follow):

if !json && !stdoutCanUpdateStatus() || !show {
    interval = 0
} else if err == nil && fps > 0 {
    if fps > 60 {
        fps = 60
    }
    interval = time.Duration(float64(time.Second) / fps)
}

Did restic help you today? Did it make you happy in any way?

[rawtaz]

Nice avatar, looks smart! :)

What is the use case of specifying these two options (--quiet and --json) at the same time? If you don't want output, you specify --quiet and have no reason to specify --json, and vice versa if you want JSON output you specify --json and have no reason to specify --quiet.

If this was "fixed", one could open an issue about --quiet silencing --json, just like this issue is about --json overriding --quiet and thereby making noise. There's no good fix even if this was to be considered unwanted behavior (by some) - whichever way you turn this around, there's a conflict. Hence one option has to override the other, and in this case it's --json overriding --quiet.

[organicveggie]

Thanks. I try to rotate my avatar through a few random pieces of produce every year. Typically broccoli, rutabagas, turnips, etc. What can I say, I'm easily amused. :)

Anyway, my use case is metrics collection for monitoring.

Rather than email immediately on failures of things like backups, I prefer to collect metrics about what happened, monitor the metrics, and alert on them when necessary. Specifically, I like to take metrics, feed them into InfluxDB, and then alert on them using Grafana.

For example, let's say I have a system which uses a systemd timer to take snapshots every hour and something causes the backups to start failing. If I have a simple failure handler that emails me, I run into a number of issues:

• Easily overwhelmed by emails
• No way to silence emails
• Could be noisy if a system is flaky and causes things to fail occasionally
• No way to delegate to other people

In fact, I don't necessarily care if a single backup fails; I'm more interested in multiple backups failing in a row. So, feeding metrics to a monitoring and alerting system ends up being more effective. I can collect a metric indicating success or failure and alert on that. In fact, that's pretty valuable. However, that's not the only thing I want to track. Given that I expect some degree of churn on a machine, I'd also like to make sure we actually see new files, changed files, etc. And that we processed > 0 files.

In normal text mode, restic backup does output the information I'm looking for:

# restic backup --one-file-system --exclude-caches --files-from '/etc/restic/includes' --exclude-file '/etc/restic/excludes'
repository 7477442f opened successfully, password is correct
using parent snapshot 932770c1

Files:           0 new,     3 changed,  6524 unmodified
Dirs:            0 new,     4 changed,  2012 unmodified
Added to the repo: 603.625 KiB

processed 6527 files, 687.514 MiB in 0:00
snapshot d1124b4a saved

However, I don't really enjoy parsing text output which can change. I'd rather get structured data that is easier to work with, such as the output from --json. However, I don't care about the progress updates and it really just clogs up the systemd logs.

Currently, the help documentation for --quiet says:

do not output comprehensive progress report

That leads me to think that --quiet and --json are not incompatible with one another.

[rawtaz]

So put another way, the issue you are having is that when using --json, which is what you need for your use case (getting structured info out of the backup run), you do not want to see the progress information, but you are.

I'm thinking that the text in the documentation is a bit off, because as you can tell from a regular non---json backup run, --quiet silences not only the progress output but also other output (e.g. password accepted, using parent snapshot, snapshot saved, ..).

Can you not simply filter out the status updates in the JSON output? I'm not sure why you're trying to configure this using options instead of filtering of the structured data to get only what you want.

[organicveggie]

Independent of exactly what the behavior should be, I think it's still a bug that the combination of --quiet and --json prints progress updates. Albeit, a pretty minor bug. Even if we ignore my use-case and just focused on the suggestion from rawtaz@ that --quiet should silence --json, that's not currently the case.

However, my assessment of what to change is incorrect. I forgot my rules of operator precedence for Golang. On further examination, I'm actually not sure why I'm seeing this behavior. With --quiet and --json, the Progress.MinUpdatePause value should be set to 0, which should skip the printing. I'm guessing the progress channel is getting signaled... which forces the update.

[organicveggie]

Can you not simply filter out the status updates in the JSON output?

Ummm .... I'm pretty sure I have some very very good reasons why I don't want to do that... Lots and lots of really great reasons... So many I can't possibly list them all. :)

backs away slowly

In all seriousness, I feel like I had a reason ... but I can't remember what it was. Either it will come back to me or it wasn't very important.

[rawtaz]

Hey, that's fine. Even if you don't know right now why you don't filter it out, you may very well have decided not to due to some reason earlier.

How do you feed the output to InfluxDB, running the backup script using telegraf or something? In general one can use jq to filter out the stuff you don't want, but perhaps another way is better in your case.

I meant earlier that currently --json takes precedence, and even if that were to change to --quiet taking precedence, someone would consider that problematic and and it done the other way around :) Personally I might feel it makes more sense that --quiet takes precedence, but I don't think it's relevant to change it, not unless there's some much bigger practical issue due to how it currently works.

[organicveggie]

Ah hah! I figured out why I ended up down this path in the first place! It's actually a weird interaction between systemd, journald, and restic json logging. I'll close this issue and post on the forum instead. Thanks!

For posterity, a few comments.

How do you feed the output to InfluxDB, running the backup script using telegraf or something?

I typically use Telegraf to feed data into InfluxDB. In this particular case, I use systemd timers to manage executing the backup processes, which makes Telegraf integration a bit tricky. At this point, I will likely push the data directly into InfluDB using either the influx CLI or write a light-weight wrapper tool in Go using the InfluxDB client library.

I meant earlier that currently --json takes precedence

Ah! That makes a lot more sense. I've been focused on my non-interactive use case, so progress updates in JSON format aren't of value. However, I'm guessing that it's intended to support a web UI.