Logging and stdout behaviour of --files and --stats is confusing #547

New Issue

AndrewDDavis · 2022-06-13T16:26:08Z

AndrewDDavis commented

2022-06-13 16:26:08 +00:00

I had originally posted this in #524, but I don't think that was the right place, sorry for the confusion. Quoting from that thread:

But some stuff like stats or pruning details change from INFO to WARNING depending on the requested log level.

This is done very intentionally, although you could perhaps call it a hack. The behavior is:

At verbosity 1 and 2, output like stats can be INFO, because it's, well, informational output. (It's neither debug info nor is a warning/error.)

At verbosity 0, output like stats cannot be INFO because then it won't show up! (INFO is not displayed at verbosity 0.) So this output needs to get artificially elevated to warning so that it actually displays. And the reason it's given this special treatment is because it's explicitly requested by the user, e.g. via the --stats command-line flag.

If you have ideas for a better approach given these constraints, I'm open!

And the --verbosity, --log-file-verbosity, and --monitoring-verbosity options are not independent... for instance changing the monitoring verbosity changes what's shown in the console also.

Yup, that's due to the logic described above.

In my opinion, the logic of what gets logged, and where, is difficult to figure out for the user and feels buggy. Of course that's just my personal opinion and you're free to design your software as you like.

To explain:

I would like to have --files and --stats info output to the log, and keep stdout relatively clean, to just verify that the backup job ran successfully.
To do this, I run with -v 0 --log-file "$bm_log" --log-file-verbosity 1, then issue create --files --stats on my command line.
I can confirm this adds the appropriate flags to the borg command call: --list --filter AME- --info --stats, and the expected output shows up in the borg logs, which I've redirected with my own logging.conf file.
Given that I know borg outputs the file list and stats at the INFO level, I would not expect to see the info on stdout from borgmatic (because of -v 0), but I would expect to see it in borgmatic's logs, because I'm running with verbosity 1 there.
In fact, borgmatic prints the file list and stats to neither stdout nor the log. I find this confusing.

Based on the logic described above, I'm not sure whether this is a bug, or the intended behaviour.

I would suggest, if it's desirable to artificially elevate the stats etc to warning level, that borgmatic should always do that, regardless of the verbosity level(s) in the command call. Then the behaviour will be more predictable when verbosity levels are changed.
Alternatively, a warning could be issued to stdout when --stats is issued on the command line, but the verbosity level is not sufficient that the information will actually be shown.

Environment

borgmatic version: 1.6.3

borgmatic installation method: pip

Borg version: 1.1.17

Python version: Python 3.10.4

operating system and version: macOS 10.14.6

I had originally posted this in #524, but I don't think that was the right place, sorry for the confusion. Quoting from that thread: > >> But some stuff like stats or pruning details change from INFO to WARNING depending on the requested log level. > > This is done very intentionally, although you could perhaps call it a hack. The behavior is: > > * At verbosity 1 and 2, output like stats can be INFO, because it's, well, informational output. (It's neither debug info nor is a warning/error.) > * At verbosity 0, output like stats cannot be INFO because then it won't show up! (INFO is not displayed at verbosity 0.) So this output needs to get artificially elevated to warning so that it actually displays. And the reason it's given this special treatment is because it's explicitly requested by the user, e.g. via the `--stats` command-line flag. > > If you have ideas for a better approach given these constraints, I'm open! > > > And the --verbosity, --log-file-verbosity, and --monitoring-verbosity options are not independent... for instance changing the monitoring verbosity changes what's shown in the console also. > > Yup, that's due to the logic [described above](https://projects.torsion.org/borgmatic-collective/borgmatic/issues/524#issuecomment-4368). In my opinion, the logic of what gets logged, and where, is difficult to figure out for the user and feels buggy. Of course that's just my personal opinion and you're free to design your software as you like. To explain: - I would like to have `--files` and `--stats` info output to the log, and keep stdout relatively clean, to just verify that the backup job ran successfully. - To do this, I run with `-v 0 --log-file "$bm_log" --log-file-verbosity 1`, then issue `create --files --stats` on my command line. - I can confirm this adds the appropriate flags to the borg command call: `--list --filter AME- --info --stats`, and the expected output shows up in the borg logs, which I've redirected with my own logging.conf file. - Given that I know borg outputs the file list and stats at the INFO level, I would **not** expect to see the info on stdout from borgmatic (because of `-v 0`), but I would expect to see it in borgmatic's logs, because I'm running with verbosity 1 there. - In fact, borgmatic prints the file list and stats to _neither_ stdout nor the log. I find this confusing. Based on the logic described above, I'm not sure whether this is a bug, or the intended behaviour. - I would suggest, if it's desirable to artificially elevate the stats etc to warning level, that borgmatic should *always* do that, regardless of the verbosity level(s) in the command call. Then the behaviour will be more predictable when verbosity levels are changed. - Alternatively, a warning could be issued to stdout when `--stats` is issued on the command line, but the verbosity level is not sufficient that the information will actually be shown. #### Environment **borgmatic version:** 1.6.3 **borgmatic installation method:** pip **Borg version:** 1.1.17 **Python version:** Python 3.10.4 **operating system and version:** macOS 10.14.6

AndrewDDavis changed title from ~~Logging behaviour of --files and --stats is confusing~~ to Logging and stdout behaviour of --files and --stats is confusing

2022-06-13 16:27:07 +00:00

witten commented

2022-06-14 16:52:53 +00:00

Thank you for taking the time to file this! I'd love to make the logging logic more intuitive (and documented). However, I haven't been able to reproduce the issue you've described. I'm running borgmatic master (so, 1.6.3), and when I run the following, I get no output on stdout and full stats/files output in the log file:

borgmatic create -c test.yaml -v 0 --log-file test.log --log-file-verbosity 1 --files --stats

Here's my config file:

location:
    source_directories:
        - /root/tmp

    repositories:
        - test.borg
retention:
    keep_daily: 7

If I change -v 0 to -v 1, then I get stats/files output on both stdout and in the log.

So maybe there's a meaningful difference between our respective command-lines? Can I get a look at your entire command? Thanks!

Thank you for taking the time to file this! I'd love to make the logging logic more intuitive (and documented). However, I haven't been able to reproduce the issue you've described. I'm running borgmatic master (so, 1.6.3), and when I run the following, I get no output on stdout and full stats/files output in the log file: ```bash borgmatic create -c test.yaml -v 0 --log-file test.log --log-file-verbosity 1 --files --stats ``` Here's my config file: ```yaml location: source_directories: - /root/tmp repositories: - test.borg retention: keep_daily: 7 ``` If I change `-v 0` to `-v 1`, then I get stats/files output on both stdout and in the log. So maybe there's a meaningful difference between our respective command-lines? Can I get a look at your entire command? Thanks!

AndrewDDavis commented

2022-06-15 04:02:06 +00:00

Shoot, it was my fault -- having a logging.conf in place for Borg was evidently preventing borgmatic from getting the output. Once I did export -n BORG_LOGGING_CONF and unset BORG_LOGGING_CONF, the output is as you describe, with a quiet stdout and the full stats and file-list blast in borgmatic's log.

Shoot, it was my fault -- having a logging.conf in place for Borg was evidently preventing borgmatic from getting the output. Once I did `export -n BORG_LOGGING_CONF` and `unset BORG_LOGGING_CONF`, the output is as you describe, with a quiet stdout and the full stats and file-list blast in borgmatic's log.

witten commented

2022-06-15 06:32:30 +00:00

Okay, no worries! Glad that's all it was. If you find any other logging irregularities (I'm sure there are some, given the complexity), please don't hesitate to let me know.

witten closed this issue

2022-06-15 06:32:30 +00:00

witten added the

question / support

label 2022-06-15 06:32:37 +00:00

AndrewDDavis commented

2022-06-15 16:04:36 +00:00

Thanks, I will report if I notice any irregularities -- it's strange because I only created the logging.conf for Borg after I noticed what I thought was unexpected behaviour with borgmatic's logging. I did recently upgrade borgmatic from a much earlier version, so maybe it was an issue that got fixed along the way. Or maybe I just had my command lines tangled up all along. :-)

Thanks, I will report if I notice any irregularities -- it's strange because I only created the `logging.conf` for Borg after I noticed what I thought was unexpected behaviour with borgmatic's logging. I did recently upgrade borgmatic from a much earlier version, so maybe it was an issue that got fixed along the way. Or maybe I just had my command lines tangled up all along. :-)

witten commented

2022-06-15 16:05:43 +00:00

Things have definitely changed since early versions of borgmatic logging, so it could very well be that!

Sign in to join this conversation.