New command option to log information about executed task at verbosity 0 #272

palto42 · 2019-12-21T11:32:42Z

palto42 commented

2019-12-21 11:32:42 +00:00

To complement the --stats option I added a --tasks option to include the executed task in the logging at verbosity >= 0.

In order to easily identify the tasks in the log the level name is set to "TASK", regardless of the actual log level.

In addition I suggest to log the summary header always with level name "INFO".

Example output for --tasks at verbosity 0:

[2019-12-21 11:28:57,106] TASK: /home/user/.config/borgmatic/config.yaml: Processing configuration file
[2019-12-21 11:28:57,106] TASK: /borg/archive/main: Pruning archives
[2019-12-21 11:28:58,346] TASK: /borg/archive/main: Creating archive
[2019-12-21 11:29:04,129] TASK: /borg/archive/main: Running consistency checks
[2019-12-21 11:29:04,130] INFO: 
[2019-12-21 11:29:04,130] INFO: summary:
[2019-12-21 11:29:04,129] INFO: /home/user/.config/borgmatic/config.yaml: Successfully ran configuration file

To complement the --stats option I added a --tasks option to include the executed task in the logging at verbosity >= 0. In order to easily identify the tasks in the log the level name is set to "TASK", regardless of the actual log level. In addition I suggest to log the summary header always with level name "INFO". Example output for --tasks at verbosity 0: ``` [2019-12-21 11:28:57,106] TASK: /home/user/.config/borgmatic/config.yaml: Processing configuration file [2019-12-21 11:28:57,106] TASK: /borg/archive/main: Pruning archives [2019-12-21 11:28:58,346] TASK: /borg/archive/main: Creating archive [2019-12-21 11:29:04,129] TASK: /borg/archive/main: Running consistency checks [2019-12-21 11:29:04,130] INFO: [2019-12-21 11:29:04,130] INFO: summary: [2019-12-21 11:29:04,129] INFO: /home/user/.config/borgmatic/config.yaml: Successfully ran configuration file ```

witten commented

2019-12-22 00:07:14 +00:00

I appreciate you taking the time to put together this PR, and for updating tests as well! Could you say a bit about your motivation with this feature? Specifically:

What gap are you trying to solve with this feature?
What are you trying to do that --verbosity 1 doesn't work for? Is it just too verbose? Is it the individual file listing in particular, or something else?
How are you wanting to consume your logs? A log file via --log-file? What do you do with those logs / how do you read them?
Are you wanting to programmatically consume the "TASK" information? Why do you want that called out at a separate log level specifically?

Thanks!

I appreciate you taking the time to put together this PR, and for updating tests as well! Could you say a bit about your motivation with this feature? Specifically: * What gap are you trying to solve with this feature? * What are you trying to do that `--verbosity 1` doesn't work for? Is it just too verbose? Is it the individual file listing in particular, or something else? * How are you wanting to consume your logs? A log file via `--log-file`? What do you do with those logs / how do you read them? * Are you wanting to programmatically consume the "TASK" information? Why do you want that called out at a separate log level specifically? Thanks!

palto42 commented

2019-12-22 09:20:20 +00:00

Thanks for the quick feedback!

I would like to have a logging which provides some minimal information about the backup execution (besides any error messages), as mentioned in my previous pull request witten/borgmatic#233 (comment)

The verbosity level 1 provides too much detail with the individual files backed up and in level 0 I get nothing. I tried the --stats, but this is not really what I was looking for.

Currently I'm consuming the logs via log-file, but in my view this option is useful for other purposes as well. For example if used in cron, you could get a short notification mail with just the tasks done. It also adds some context to potential error messages (and --stats) to understand during which backup task the problem occurred.

This idea to use a different level name "TASK" was two fold, first to easily distinguish it from other messages and second to always use the same name regardless of the actual log-level. But this is a minor topic for me and I can remove it if you think this is a bad idea.

In case you accept the PR in general but would like to get rid of the "TASK" name, should I use fixed name "INFO" or the real log-level (which would be "WARNING" with --verbosity 0 and "INFO" otherwise).

Thanks for the quick feedback! I would like to have a logging which provides some minimal information about the backup execution (besides any error messages), as mentioned in my previous pull request https://projects.torsion.org/witten/borgmatic/pulls/233#issuecomment-2040 The verbosity level 1 provides too much detail with the individual files backed up and in level 0 I get nothing. I tried the --stats, but this is not really what I was looking for. Currently I'm consuming the logs via log-file, but in my view this option is useful for other purposes as well. For example if used in cron, you could get a short notification mail with just the tasks done. It also adds some context to potential error messages (and --stats) to understand during which backup task the problem occurred. This idea to use a different level name "TASK" was two fold, first to easily distinguish it from other messages and second to always use the same name regardless of the actual log-level. But this is a minor topic for me and I can remove it if you think this is a bad idea. In case you accept the PR in general but would like to get rid of the "TASK" name, should I use fixed name "INFO" or the real log-level (which would be "WARNING" with --verbosity 0 and "INFO" otherwise).

witten commented

2020-01-08 19:02:39 +00:00

Sorry for the delay in getting back to this. If the underlying problem is that verbosity 1 provides too much detail about the individual files backed up, then maybe we should just solve that? (You're not the first to report this.) My thinking is that, if at all possible, it would be great to keep --verbosity as the main way to influence, well, verbosity.. rather than having different flags for different permutations. (I know --stats is already an exception to this.)

A couple of different ideas for that:

Just remove the changed file detail from verbosity 1.
Or, shift the existing verbosity 2 to a new verbosity 3 level, shift the existing verbosity 1 (including the per-file detail) to verbosity 2, and make a new verbosity 1 that omits changed file details.
Or, add a flag that influences whether per-file detail is shown (with any verbosity level), perhaps changing the defaults at verbosity 1. This option would be a different flag for a different permutation, but at least it'd be closer to the underlying feature in question (the per-file detail being on or off).

Relevant background on this: witten/borgmatic#64 .. That's the ticket that introduced the per-file detail at verbosity 1.

Thoughts?

Sorry for the delay in getting back to this. If the underlying problem is that verbosity 1 provides too much detail about the individual files backed up, then maybe we should just solve that? (You're not the first to report this.) My thinking is that, if at all possible, it would be great to keep `--verbosity` as the main way to influence, well, verbosity.. rather than having different flags for different permutations. (I know `--stats` is already an exception to this.) A couple of different ideas for that: 1. Just remove the changed file detail from verbosity 1. 2. Or, shift the existing verbosity 2 to a new verbosity 3 level, shift the existing verbosity 1 (including the per-file detail) to verbosity 2, and make a new verbosity 1 that omits changed file details. 3. Or, add a flag that influences whether per-file detail is shown (with any verbosity level), perhaps changing the defaults at verbosity 1. This option would be a different flag for a different permutation, but at least it'd be closer to the underlying feature in question (the per-file detail being on or off). Relevant background on this: https://projects.torsion.org/witten/borgmatic/issues/64 .. That's the ticket that introduced the per-file detail at verbosity 1. Thoughts?

witten referenced this pull request

2020-01-08 19:04:34 +00:00

Finer grained verbosity level #64

palto42 commented

2020-01-08 20:17:54 +00:00

Thanks for your comments and ideas.

I was actually also thinking about the option to somehow disable the file details, but struggled a bit to understand and tweak the current logic (was afraid to break things).

To me the option 2 looks best since it avoids adding another option. Main down side would be that current users will need to adjust their config if they use verbosity >= 1. I first thought it would also allow to manage the borg command logging details per logger, but actually all logger will get the same level of detail or nothing since all borg command output will be at same level (except errors I think).

Regarding current logic and required changes to implement option 2:

    + (
        ('--list', '--filter', 'AME-')
        if logger.isEnabledFor(logging.INFO) and not json and not progress
        else ()
    )
    + (('--info',) if logger.getEffectiveLevel() == logging.INFO and not json else ())

Do I correctly understand that for logging levels INFO (v1) and DEBUG (v2) the --list option is added and without --progress flag the --filter AME- is applied to only show add/modify/error (and none of this with json)?

So for getting current verbosity 1 output but without any file details, it would require another flag like json in this logic to disable the --list and --filter from borg command (without changing the logging level).

Both v1 and v2 would use INFO log-level and new v3 the DEBUG level (as current v2).

Thanks for your comments and ideas. I was actually also thinking about the option to somehow disable the file details, but struggled a bit to understand and tweak the current logic (was afraid to break things). To me the option 2 looks best since it avoids adding another option. Main down side would be that current users will need to adjust their config if they use verbosity >= 1. I first thought it would also allow to manage the borg command logging details per logger, but actually all logger will get the same level of detail or nothing since all borg command output will be at same level (except errors I think). Regarding current logic and required changes to implement option 2: ``` + ( ('--list', '--filter', 'AME-') if logger.isEnabledFor(logging.INFO) and not json and not progress else () ) + (('--info',) if logger.getEffectiveLevel() == logging.INFO and not json else ()) ``` Do I correctly understand that for logging levels INFO (v1) and DEBUG (v2) the `--list` option is added and without `--progress` flag the `--filter AME-` is applied to only show add/modify/error (and none of this with `json`)? So for getting current verbosity 1 output but without any file details, it would require another flag like `json` in this logic to disable the `--list` and `--filter` from borg command (without changing the logging level). Both v1 and v2 would use INFO log-level and new v3 the DEBUG level (as current v2).

witten commented

2020-01-09 19:12:31 +00:00

Do I correctly understand that for logging levels INFO (v1) and DEBUG (v2) the --list option is added and without --progress flag the --filter AME- is applied to only show add/modify/error (and none of this with json)?

The way that I'd phrase it is: For logging levels INFO (v1) and DEBUG (v2), both --list and --filter AMI- flags are included to show added/modified/errored files. But if json and/or progress are set, then neither --list nor --filter AMI- are included.

So for getting current verbosity 1 output but without any file details, it would require another flag like json in this logic to disable the --list and --filter from borg command (without changing the logging level).

Yes, you are correct. So perhaps this is actually a point against this approach (option #2), as it would be making a departure from the neat correspondence between borgmatic verbosity levels and Python log levels.

The more we talk through this, the more I think option #1 or #3 would make the most sense.

> Do I correctly understand that for logging levels INFO (v1) and DEBUG (v2) the --list option is added and without --progress flag the --filter AME- is applied to only show add/modify/error (and none of this with json)? The way that I'd phrase it is: For logging levels INFO (v1) and DEBUG (v2), both `--list` and `--filter AMI-` flags are included to show added/modified/errored files. But if `json` and/or `progress` are set, then neither `--list` nor `--filter AMI-` are included. > So for getting current verbosity 1 output but without any file details, it would require another flag like json in this logic to disable the --list and --filter from borg command (without changing the logging level). Yes, you are correct. So perhaps this is actually a point against this approach (option #2), as it would be making a departure from the neat correspondence between borgmatic verbosity levels and Python log levels. The more we talk through this, the more I think option #1 or #3 would make the most sense.

palto42 commented

2020-01-11 09:52:02 +00:00

I'm trying a new approach with extra option --brief to implement option 3, which will reduce the output at INFO level by suppressing the borg --file and --stats (if not borgmatic --stats is used as well) options.

This looks quite promising, but I need some more testing and code for "tests".

Since I'm using a new branch brief for this development, I assume that I need to close this pull-request and make a new one (if you agree with the new approach)?

I'm trying a new approach with extra option `--brief` to implement option 3, which will reduce the output at INFO level by suppressing the borg `--file` and `--stats` (if not borgmatic `--stats` is used as well) options. This looks quite promising, but I need some more testing and code for "tests". Since I'm using a new branch [brief](https://projects.torsion.org/palto42/borgmatic/src/branch/brief) for this development, I assume that I need to close this pull-request and make a new one (if you agree with the new approach)?

palto42 commented

2020-01-11 15:43:29 +00:00

Also trying reverse approach of option 1 in branch list-files which by default is less detailed in v1 (no --list and --stats) and has new option "--files" to re-add the details.

Also trying reverse approach of option 1 in branch [list-files](https://projects.torsion.org/palto42/borgmatic/src/branch/list-files) which by default is less detailed in v1 (no --list and --stats) and has new option "--files" to re-add the details.

witten commented

2020-01-17 22:33:48 +00:00

Looks promising! I have a slight preference for the --files approach, just because it's a more specific flag name. However if it has that name, I would not expect --files to influence whether stats are included or not in the output. If you don't want stats included at verbosity 1, then maybe just change the default to have stats off unless you request them with --stats!

Similar thoughts if you go with the --brief approach. That could essentially just be called --no-files or something, and not impact stats.

Anyway, let me know if I can help with a PR and/or tests.

Looks promising! I have a slight preference for the `--files` approach, just because it's a more specific flag name. However if it has that name, I would not expect `--files` to influence whether stats are included or not in the output. If you don't want stats included at verbosity 1, then maybe just change the default to have stats off unless you request them with `--stats`! Similar thoughts if you go with the `--brief` approach. That could essentially just be called `--no-files` or something, and not impact stats. Anyway, let me know if I can help with a PR and/or tests.

witten commented

2020-01-17 22:50:19 +00:00

Related tickets:

Related tickets: * https://projects.torsion.org/witten/borgmatic/issues/277 * https://projects.torsion.org/witten/borgmatic/issues/282

palto42 referenced this pull request

2020-01-18 14:13:38 +00:00

By default only brief logging output at verbosity 1 #283

palto42 commented

2020-01-18 14:13:53 +00:00

In principle I share your preference for --filesand also agree to restrict it to the file listing and not influence stats.

To avoid that the --stats option always changes the borg output to WARNING level, I also modified the related logic:

if json:
    output_log_level = None
elif stats and logger.getEffectiveLevel() == logging.WARNING:
    output_log_level = logging.WARNING
else:
    output_log_level = logging.INFO

It would only change the output_log_level if the lowest log level used by any handler is WARNING. For example if one uses v0 and another v1, then the stats would only be shown in v1 as INFO. With one at v0 and second at v-1, the stats would be shown in v0 as WARNING (but not in v-1).

I have updated my branch list-files accordingly, created a new PR #283 for that branch and will close this one.

In principle I share your preference for `--files`and also agree to restrict it to the file listing and not influence stats. To avoid that the `--stats` option always changes the borg output to WARNING level, I also modified the related logic: ``` if json: output_log_level = None elif stats and logger.getEffectiveLevel() == logging.WARNING: output_log_level = logging.WARNING else: output_log_level = logging.INFO ``` It would only change the output_log_level if the lowest log level used by any handler is WARNING. For example if one uses v0 and another v1, then the stats would only be shown in v1 as INFO. With one at v0 and second at v-1, the stats would be shown in v0 as WARNING (but not in v-1). I have updated my branch [list-files](https://projects.torsion.org/palto42/borgmatic/src/branch/list-files) accordingly, created a new PR #283 for that branch and will close this one.

palto42 closed this pull request

2020-01-18 14:13:53 +00:00