Rework logging/verbosity system #90

Merged
witten merged 12 commits from :master into master 2018-09-08 20:53:38 +00:00
Collaborator

This pull request re-engineers the logging/verbosity system.

  • verbosity is removed as an function argument. Instead a logger is acquired with logger = logging.getLogger(__name__) which is then used like
+ (('--list') if logger.isEnabledFor(logging.INFO) else ())
+ (('--debug') if logger.isEnabledFor(logging.DEBUG) else ())
  • The verbosity command line argument maps -v 1 to INFO, -v 2 to DEBUG
  • The unknown verbosity is mapped to INFO. It was WARNING before, but think it's more on the safe side. If confused, better print too much logging than too little.
  • For testing there is insert_logging_mock.
  • All tests pass.

== Remarks ==

  • I changed the logging related options passed to borg here and there, e.g. --filter AME, --stat. Everything in good faith, but borgmatic output won't be exactly the same.
  • The logging packages works with hierarchical log levels, thus, if isEnabledFor(DEBUG) is true, isEnabledFor(INFO) is also true.
  • Partly due to the previous point, --filter AME is enabled for logging DEBUG and INFO.
  • For options which are mutually exclusive for DEBUG and INFO, like --debug --info, I let the latter option overwrite the first.

I appreciate your comments and hope we can work towards a merge into master!

This pull request re-engineers the logging/verbosity system. * `verbosity` is removed as an function argument. Instead a logger is acquired with `logger = logging.getLogger(__name__)` which is then used like ``` + (('--list') if logger.isEnabledFor(logging.INFO) else ()) + (('--debug') if logger.isEnabledFor(logging.DEBUG) else ()) ``` * The verbosity command line argument maps `-v 1` to INFO, `-v 2` to DEBUG * The unknown verbosity is mapped to `INFO`. It was `WARNING` before, but think it's more on the safe side. If confused, better print too much logging than too little. + For testing there is `insert_logging_mock`. + All tests pass. == Remarks == * I changed the logging related options passed to borg here and there, e.g. `--filter AME`, `--stat`. Everything in good faith, but borgmatic output won't be exactly the same. * The logging packages works with hierarchical log levels, thus, if `isEnabledFor(DEBUG)` is true, `isEnabledFor(INFO)` is also true. * Partly due to the previous point, `--filter AME` is enabled for logging DEBUG and INFO. * For options which are mutually exclusive for DEBUG and INFO, like `--debug --info`, I let the latter option overwrite the first. I appreciate your comments and hope we can work towards a merge into master!
witten reviewed 2018-09-01 21:56:23 +00:00
witten left a comment
Owner

Awesome, thanks for taking on refactor of this scope! Don't forget to add yourself to AUTHORS if you like. And feel free to update NEWS (or I'd be happy to do that).

Awesome, thanks for taking on refactor of this scope! Don't forget to add yourself to AUTHORS if you like. And feel free to update NEWS (or I'd be happy to do that).
@ -154,3 +151,1 @@
VERBOSITY_SOME: ('--info',) if dry_run else ('--info', '--stats'),
VERBOSITY_LOTS: ('--debug', '--list', '--show-rc') if dry_run else ('--debug', '--list', '--show-rc', '--stats'),
}.get(verbosity, ())
+ (('--list', '--filter', 'AME', '--info', '--stats') if logger.isEnabledFor(logging.INFO) else ())
Owner

You'll need to retain the logic that omits --stats during a dry run, because --stats and --dry-run can't be specified together. More info here: https://borgbackup.readthedocs.io/en/stable/usage/create.html#description

You'll need to retain the logic that omits `--stats` during a dry run, because `--stats` and `--dry-run` can't be specified together. More info here: https://borgbackup.readthedocs.io/en/stable/usage/create.html#description
@ -155,2 +151,2 @@
VERBOSITY_LOTS: ('--debug', '--list', '--show-rc') if dry_run else ('--debug', '--list', '--show-rc', '--stats'),
}.get(verbosity, ())
+ (('--list', '--filter', 'AME', '--info', '--stats') if logger.isEnabledFor(logging.INFO) else ())
+ (('--debug', '--show-rc') if logger.isEnabledFor(logging.DEBUG) else ())
Owner

For options which are mutually exclusive for DEBUG and INFO, like --debug --info, I let the latter option overwrite the first.

Does that mean Borg just ignores the --info and respects only the --debug flag?

> For options which are mutually exclusive for DEBUG and INFO, like --debug --info, I let the latter option overwrite the first. Does that mean Borg just ignores the `--info` and respects only the `--debug` flag?
witten reviewed 2018-09-01 22:11:38 +00:00
witten left a comment
Owner

Made it all the way through. Generally looks great. See minor feedback throughout!

Made it all the way through. Generally looks great. See minor feedback throughout!
@ -59,2 +55,2 @@
VERBOSITY_LOTS: ('--debug', '--stats', '--list', '--show-rc'),
}.get(verbosity, ())
+ (('--stats',) if logger.isEnabledFor(logging.INFO) else ())
+ (('--info',) if logger.isEnabledFor(logging.INFO) else ())
Owner

Any reason not to combine these two lines?

Any reason not to combine these two lines?
@ -93,3 +93,3 @@
'-v', '--verbosity',
type=int,
help='Display verbose progress (1 for some, 2 for lots)',
help='Display verbose progress (1 for INFO, 2 for DEBUG)',
Owner

Might be nice to leave these as "some" and "lots", if only because not all users are Python programmers, and so won't necessarily be familiar with Python log levels. (I don't feel strongly about this.)

Might be nice to leave these as "some" and "lots", if only because not all users are Python programmers, and so won't necessarily be familiar with Python log levels. (I don't feel strongly about this.)
@ -122,3 +122,3 @@
checks.
'''
logger.info('{}: Parsing configuration file'.format(config_filename))
logger.debug('{}: Parsing configuration file'.format(config_filename))
Owner

Any reason for the switch to debug here? I think the idea with it being info is that you could easily see what borgmatic is doing with just the first (-v 1) verbosity level. Especially useful if you've got multiple configuration files and you want to see what's being done for each.

Any reason for the switch to `debug` here? I think the idea with it being `info` is that you could easily see what borgmatic is doing with just the first (`-v 1`) verbosity level. Especially useful if you've got multiple configuration files and you want to see what's being done for each.
@ -20,0 +19,4 @@
def insert_logging_mock(log_level):
logging = flexmock(module.logging.Logger)
logging.should_receive('isEnabledFor').replace_with(lambda x : x >= log_level)
Owner

Super minor: It'd be great to use a more descriptive variable than just x here. Similar elsewhere this pattern occurs.

Super minor: It'd be great to use a more descriptive variable than just `x` here. Similar elsewhere this pattern occurs.
@ -23,1 +23,4 @@
def insert_logging_mock(log_level):
logging = flexmock(module.logging.Logger)
logging.should_receive('isEnabledFor').replace_with(lambda x : x >= log_level)
Owner

Given that this occurs several times, you could factor it out into a common test file. For instance, the existing borgmatic/tests/unit/test_verbosity.py might be a good candidate.

Given that this occurs several times, you could factor it out into a common test file. For instance, the existing `borgmatic/tests/unit/test_verbosity.py` might be a good candidate.
@ -9,3 +9,3 @@
def test_verbosity_to_log_level_maps_unknown_verbosity_to_warning_level():
assert module.verbosity_to_log_level('my pants') == logging.WARNING
assert module.verbosity_to_log_level('my pants') == logging.INFO
Owner

Note that the name of this test function is now incorrect!

Note that the name of this test function is now incorrect!
@ -13,3 +13,3 @@
VERBOSITY_SOME: logging.INFO,
VERBOSITY_LOTS: logging.DEBUG,
}.get(verbosity, logging.WARNING)
}.get(verbosity, logging.INFO)
Owner

The unknown verbosity is mapped to INFO. It was WARNING before, but think it’s more on the safe side. If confused, better print too much logging than too little.

Does this mean that if you omit -v/--verbosity from the borgmatic command-line, you'll know get INFO logs instead of WARNING? So now you'll get a fair amount of log spew whereas before it was pretty silent. That seems a little unexpected unless -v/--verbosity is specified. What's your thinking there?

> The unknown verbosity is mapped to INFO. It was WARNING before, but think it’s more on the safe side. If confused, better print too much logging than too little. Does this mean that if you omit `-v`/`--verbosity` from the borgmatic command-line, you'll know get `INFO` logs instead of `WARNING`? So now you'll get a fair amount of log spew whereas before it was pretty silent. That seems a little unexpected unless `-v`/`--verbosity` is specified. What's your thinking there?
floli reviewed 2018-09-02 10:22:56 +00:00
Author
Collaborator

Not really. Done.

Not really. Done.
floli reviewed 2018-09-02 11:11:19 +00:00
Author
Collaborator

Yeah, already had this on my agenda. Done now.

Yeah, already had this on my agenda. Done now.
floli reviewed 2018-09-02 11:14:06 +00:00
Author
Collaborator

Done. Also added an assertion to the previous function to test that VERBOSTIY_LOTS maps to DEBUG.

Done. Also added an assertion to the previous function to test that `VERBOSTIY_LOTS` maps to `DEBUG`.
floli reviewed 2018-09-02 14:28:19 +00:00
Author
Collaborator

INFO and DEBUG are pretty much universal for log levels. But I am fine and have changed it back to some and lots. Done.

INFO and DEBUG are pretty much universal for log levels. But I am fine and have changed it back to some and lots. Done.
floli reviewed 2018-09-02 14:42:04 +00:00
Author
Collaborator

Oh, wasn't aware of that, done.

Oh, wasn't aware of that, done.
floli reviewed 2018-09-02 15:12:31 +00:00
Author
Collaborator

Exactly. Unfortunately I am not sure if this is documented behavior of borg or python argparse. I think best will be to ask borg's mailing list. Even cooler would be to not call the borg executable, but use a python API. But that leads us too far... ;-)

Exactly. Unfortunately I am not sure if this is documented behavior of borg or python argparse. I think best will be to ask borg's mailing list. Even cooler would be to not call the borg executable, but use a python API. But that leads us too far... ;-)
floli reviewed 2018-09-02 15:16:01 +00:00
Author
Collaborator

Done.

Done.
floli reviewed 2018-09-02 15:21:03 +00:00
Author
Collaborator

Definitely a matter of taste here. Switched it back to info, as you proposed.

Definitely a matter of taste here. Switched it back to info, as you proposed.
Author
Collaborator

Ok, just pushed a commit that should address most of the issues.

AFAIK, issues left are

  • Default log level, when no --verbosity parameter is specified, was WARNING (almost silent) now INFO.

  • Can we rely that --debug overwrites a preceding --info parameter.

Anything I forgot?

Ok, just pushed a commit that should address most of the issues. AFAIK, issues left are + Default log level, when no --verbosity parameter is specified, was WARNING (almost silent) now INFO. + Can we rely that --debug overwrites a preceding --info parameter. Anything I forgot?
witten reviewed 2018-09-02 18:30:11 +00:00
witten left a comment
Owner

Thanks for making all the changes!

Thanks for making all the changes!
@ -155,2 +151,2 @@
VERBOSITY_LOTS: ('--debug', '--list', '--show-rc') if dry_run else ('--debug', '--list', '--show-rc', '--stats'),
}.get(verbosity, ())
+ (('--list', '--filter', 'AME', '--info') if logger.isEnabledFor(logging.INFO) else ())
+ (('--stats',) if not dry_run and logger.isEnabledFor(logging.INFO) else ())
Owner

If you wanted to avoid relying on the undocumented behavior (--debug overriding --info), one idea is that you could break out the construction of flags to a separate if/elif similar to the code elsewhere. For instance, something like:

 verbosity_flags = ()

 if logger.isEnabledFor(logging.DEBUG):
     verbosity_flags = ('--list', '--filter', 'AME', '--debug', '--show-rc')
 elif logger.isEnabledFor(logging.INFO):
     verbosity_flags = ('--list', '--filter', 'AME', '--info')

Another option would be to use getEffectiveLevel() instead of isEnabledFor() to sidestep falling through the hierarchy from DEBUG to INFO. That also has the side benefit of letting you keep things inline and non-imperative:

+ (('--list', '--filter', 'AME') if logger.isEnabledFor(logging.INFO) else ())
+ (('--info',) if logger.getEffectiveLevel() == logging.INFO else ())
+ (('--debug', '--show-rc') if logger.getEffectiveLevel() == logging.DEBUG else ())
If you wanted to avoid relying on the undocumented behavior (`--debug` overriding `--info`), one idea is that you could break out the construction of flags to a separate `if`/`elif` similar to the code elsewhere. For instance, something like: ```python verbosity_flags = () if logger.isEnabledFor(logging.DEBUG): verbosity_flags = ('--list', '--filter', 'AME', '--debug', '--show-rc') elif logger.isEnabledFor(logging.INFO): verbosity_flags = ('--list', '--filter', 'AME', '--info') ``` Another option would be to use `getEffectiveLevel()` instead of `isEnabledFor()` to sidestep falling through the hierarchy from `DEBUG` to `INFO`. That also has the side benefit of letting you keep things inline and non-imperative: ```python + (('--list', '--filter', 'AME') if logger.isEnabledFor(logging.INFO) else ()) + (('--info',) if logger.getEffectiveLevel() == logging.INFO else ()) + (('--debug', '--show-rc') if logger.getEffectiveLevel() == logging.DEBUG else ()) ```
Owner

Yup, I think those are the two remaining topics! I added some ideas above on how to tackle the second one.

Yup, I think those are the two remaining topics! I added some ideas above on how to tackle the second one.
floli reviewed 2018-09-04 18:12:42 +00:00
Author
Collaborator

I already thought about using getEffectiveLevel. I would use it only for --info. More generally: only for parameters that should not be enabled at a higher log level. --debug should also be enabled if the log level is even higher than debug (not used, but it should be possible).

I have addressed this in the recent commit.

I already thought about using `getEffectiveLevel`. I would use it *only* for `--info`. More generally: only for parameters that should not be enabled at a higher log level. `--debug` should also be enabled if the log level is even higher than debug (not used, but it should be possible). I have addressed this in the recent commit.
witten reviewed 2018-09-05 05:34:29 +00:00
Owner

Looks great, thanks!

Looks great, thanks!
Author
Collaborator

One more idea: I think the unit tests should be renamed from

test_create_archive_with_verbosity_lots_calls_borg_with_debug_parameter

to

test_create_archive_with_log_debug_calls_borg_with_debug_parameter

?

One more idea: I think the unit tests should be renamed from ``` test_create_archive_with_verbosity_lots_calls_borg_with_debug_parameter ``` to ``` test_create_archive_with_log_debug_calls_borg_with_debug_parameter ``` ?
Owner

Sure, that makes sense to me given all the changes.

Sure, that makes sense to me given all the changes.
Owner

Default log level, when no --verbosity parameter is specified, was WARNING (almost silent) now INFO.

Also, part of the motivation for the "almost silent" default verbosity: A big use case for borgmatic is running it regularly via cron. And if I recall correctly, by default the stock cron will just succeed silently if the command it's running has no output upon success t(sort of a Unix-y default), but will send email if the command has output on stdout/stderr.

> Default log level, when no --verbosity parameter is specified, was WARNING (almost silent) now INFO. Also, part of the motivation for the "almost silent" default verbosity: A big use case for borgmatic is running it regularly via cron. And if I recall correctly, by default the stock cron will just succeed silently if the command it's running has no output upon success t(sort of a Unix-y default), but will send email if the command has output on stdout/stderr.
Author
Collaborator

Ok, reverted the default log level to WARNING, renamed the test functions and also some doc string that were still mentioning verbosity as a function argument.

I did not rename the verbosity_flags variable used in some functions. My idea is that flags that go to borg and influence the output behavior are still verbosity, while of course derived from borgmatic's log level. By calling them log level we would make assumptions of the inner workings of borg and also something like --show-rc probably does not affect borg's log level.

I also updated the NEWS file.

Is there anything left that stands between that PR and a merge? :-)

Ok, reverted the default log level to WARNING, renamed the test functions and also some doc string that were still mentioning verbosity as a function argument. I did not rename the `verbosity_flags` variable used in some functions. My idea is that flags that go to borg and influence the output behavior are still verbosity, while of course derived from borgmatic's log level. By calling them log level we would make assumptions of the inner workings of borg and also something like `--show-rc` probably does not affect borg's log level. I also updated the NEWS file. Is there anything left that stands between that PR and a merge? :-)
witten closed this pull request 2018-09-08 20:53:38 +00:00
Owner

Looks great, merged! Thanks again for all your hard work here.

Looks great, merged! Thanks again for all your hard work here.
Sign in to join this conversation.
No reviewers
No Milestone
No Assignees
2 Participants
Notifications
Due Date
The due date is invalid or out of range. Please use the format 'yyyy-mm-dd'.

No due date set.

Dependencies

No dependencies set.

Reference: borgmatic-collective/borgmatic#90
No description provided.