Rework logging/verbosity system #90

Merged
witten merged 12 commits from :master into master 2018-09-08 20:53:38 +00:00
10 changed files with 14 additions and 11 deletions
Showing only changes of commit bfbb3bd72e - Show all commits

View File

@ -148,7 +148,8 @@ def create_archive(
+ (('--remote-path', remote_path) if remote_path else ())
+ (('--umask', str(umask)) if umask else ())
+ (('--lock-wait', str(lock_wait)) if lock_wait else ())
+ (('--list', '--filter', 'AME', '--info') if logger.isEnabledFor(logging.INFO) else ())
+ (('--list', '--filter', 'AME',) if logger.isEnabledFor(logging.INFO) else ())

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
Outdated
Review

Oh, wasn't aware of that, done.

Oh, wasn't aware of that, done.
+ (( '--info',) if logger.getEffectiveLevel() == logging.INFO else ())

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?
Outdated
Review

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... ;-)

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 ()) ```
Outdated
Review

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.

Looks great, thanks!

Looks great, thanks!
+ (('--stats',) if not dry_run and logger.isEnabledFor(logging.INFO) else ())
+ (('--debug', '--show-rc') if logger.isEnabledFor(logging.DEBUG) else ())
+ (('--dry-run',) if dry_run else ())

View File

@ -13,12 +13,12 @@ def extract_last_archive_dry_run(repository, lock_wait=None, local_path='borg',
'''
remote_path_flags = ('--remote-path', remote_path) if remote_path else ()
lock_wait_flags = ('--lock-wait', str(lock_wait)) if lock_wait else ()
verbosity_flags = ()
if logger.isEnabledFor(logging.DEBUG):
verbosity_flags = ('--debug', '--show-rc')
elif logger.isEnabledFor(logging.INFO):
verbosity_flags = ('--info',)
else:
verbosity_flags = ()
full_list_command = (
local_path, 'list',

View File

@ -16,7 +16,7 @@ def display_archives_info(repository, storage_config, local_path='borg', remote_
(local_path, 'info', repository)
+ (('--remote-path', remote_path) if remote_path else ())
+ (('--lock-wait', str(lock_wait)) if lock_wait else ())
+ (('--info',) if logger.isEnabledFor(logging.INFO) else ())
+ (('--info',) if logger.getEffectiveLevel() == logging.INFO else ())
+ (('--debug', '--show-rc') if logger.isEnabledFor(logging.DEBUG) else ())
+ (('--json',) if json else ())
)

View File

@ -16,7 +16,7 @@ def list_archives(repository, storage_config, local_path='borg', remote_path=Non
(local_path, 'list', repository)
+ (('--remote-path', remote_path) if remote_path else ())
+ (('--lock-wait', str(lock_wait)) if lock_wait else ())
+ (('--info',) if logger.isEnabledFor(logging.INFO) else ())
+ (('--info',) if logger.getEffectiveLevel() == logging.INFO else ())
+ (('--debug', '--show-rc') if logger.isEnabledFor(logging.DEBUG) else ())
+ (('--json',) if json else ())
)

View File

@ -52,7 +52,8 @@ def prune_archives(dry_run, repository, storage_config, retention_config, local_
+ (('--remote-path', remote_path) if remote_path else ())
+ (('--umask', str(umask)) if umask else ())
+ (('--lock-wait', str(lock_wait)) if lock_wait else ())
+ (('--stats', '--info') if logger.isEnabledFor(logging.INFO) else ())
+ (('--stats',) if not dry_run and logger.isEnabledFor(logging.INFO) else ())
+ (( '--info',) if logger.getEffectiveLevel() == logging.INFO else ())

Any reason not to combine these two lines?

Any reason not to combine these two lines?
Outdated
Review

Not really. Done.

Not really. Done.
+ (('--debug', '--list', '--show-rc') if logger.isEnabledFor(logging.DEBUG) else ())
+ (('--dry-run',) if dry_run else ())
)

View File

@ -293,7 +293,7 @@ def test_create_archive_with_verbosity_lots_calls_borg_with_debug_parameter():
flexmock(module).should_receive('_write_pattern_file').and_return(None)
flexmock(module).should_receive('_make_pattern_flags').and_return(())
flexmock(module).should_receive('_make_exclude_flags').and_return(())
insert_subprocess_mock(CREATE_COMMAND + ('--list', '--filter', 'AME', '--info', '--stats', '--debug', '--show-rc'))
insert_subprocess_mock(CREATE_COMMAND + ('--list', '--filter', 'AME','--stats', '--debug', '--show-rc'))
insert_logging_mock(logging.DEBUG)
module.create_archive(
@ -359,7 +359,7 @@ def test_create_archive_with_dry_run_and_verbosity_lots_calls_borg_without_stats
flexmock(module).should_receive('_make_pattern_flags').and_return(())
flexmock(module).should_receive('_make_pattern_flags').and_return(())
flexmock(module).should_receive('_make_exclude_flags').and_return(())
insert_subprocess_mock(CREATE_COMMAND + ('--list', '--filter', 'AME', '--info', '--debug', '--show-rc', '--dry-run'))
insert_subprocess_mock(CREATE_COMMAND + ('--list', '--filter', 'AME', '--debug', '--show-rc', '--dry-run'))
insert_logging_mock(logging.DEBUG)
module.create_archive(

View File

@ -34,7 +34,7 @@ def test_display_archives_info_with_verbosity_some_calls_borg_with_info_paramete
def test_display_archives_info_with_verbosity_lots_calls_borg_with_debug_parameter():
insert_subprocess_mock(INFO_COMMAND + ('--info', '--debug', '--show-rc'))
insert_subprocess_mock(INFO_COMMAND + ('--debug', '--show-rc'))
insert_logging_mock(logging.DEBUG)
module.display_archives_info(

View File

@ -35,7 +35,7 @@ def test_list_archives_with_verbosity_some_calls_borg_with_info_parameter():
def test_list_archives_with_verbosity_lots_calls_borg_with_debug_parameter():
insert_subprocess_mock(LIST_COMMAND + ('--info', '--debug', '--show-rc'))
insert_subprocess_mock(LIST_COMMAND + ('--debug', '--show-rc'))
insert_logging_mock(logging.DEBUG)
module.list_archives(

View File

@ -93,7 +93,7 @@ def test_prune_archives_with_verbosity_lots_calls_borg_with_debug_parameter():
flexmock(module).should_receive('_make_prune_flags').with_args(retention_config).and_return(
BASE_PRUNE_FLAGS,
)
insert_subprocess_mock(PRUNE_COMMAND + ('--stats', '--info', '--debug', '--list', '--show-rc'))
insert_subprocess_mock(PRUNE_COMMAND + ('--stats', '--debug', '--list', '--show-rc'))
insert_logging_mock(logging.DEBUG)
module.prune_archives(

View File

@ -8,6 +8,7 @@ def insert_logging_mock(log_level):
""" Mocks the isEnabledFor from python logging. """
logging = flexmock(module.logging.Logger)
logging.should_receive('isEnabledFor').replace_with(lambda lvl : lvl >= log_level)
logging.should_receive('getEffectiveLevel').replace_with(lambda: log_level)

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

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

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`.
def test_verbosity_to_log_level_maps_known_verbosity_to_log_level():