Rework logging/verbosity system #90

floli · 2018-08-22T19:39:28Z

floli commented

2018-08-22 19:39:28 +00:00

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

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

borgmatic/borg/create.py Outdated

						
				@ -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 ())

witten commented

2018-09-01 21:51:48 +00:00

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

borgmatic/borg/create.py Outdated

						
				@ -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 ())

witten commented

2018-09-01 21:54:39 +00:00

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

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

borgmatic/borg/prune.py Outdated

						
				@ -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 ())

witten commented

2018-09-01 21:59:15 +00:00

Any reason not to combine these two lines?

borgmatic/commands/borgmatic.py Outdated

						
				@ -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)',

witten commented

2018-09-01 22:00:41 +00:00

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

borgmatic/commands/borgmatic.py Outdated

						
				@ -122,3 +122,3 @@

				    checks.

				    '''

				    logger.info('{}: Parsing configuration file'.format(config_filename))

				    logger.debug('{}: Parsing configuration file'.format(config_filename))

witten commented

2018-09-01 22:02:21 +00:00

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.

borgmatic/tests/unit/borg/test_check.py Outdated

						
				@ -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)

witten commented

2018-09-01 22:03:44 +00:00

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.

borgmatic/tests/unit/borg/test_extract.py Outdated

						
				@ -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)

witten commented

2018-09-01 22:06:37 +00:00

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.

borgmatic/tests/unit/test_verbosity.py Outdated

						
				@ -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

witten commented

2018-09-01 22:07:57 +00:00

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

borgmatic/verbosity.py Outdated

						
				@ -13,3 +13,3 @@

				        VERBOSITY_SOME: logging.INFO,

				        VERBOSITY_LOTS: logging.DEBUG,

				    }.get(verbosity, logging.WARNING)

				    }.get(verbosity, logging.INFO)

witten commented

2018-09-01 22:10:26 +00:00

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

borgmatic/borg/prune.py Outdated

floli commented

2018-09-02 10:22:56 +00:00

Not really. Done.

floli reviewed 2018-09-02 11:11:19 +00:00

borgmatic/tests/unit/borg/test_extract.py Outdated

floli commented

2018-09-02 11:11:19 +00:00

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

floli reviewed 2018-09-02 11:14:06 +00:00

borgmatic/tests/unit/test_verbosity.py Outdated

floli commented

2018-09-02 11:14:06 +00:00

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

borgmatic/commands/borgmatic.py Outdated

floli commented

2018-09-02 14:28:19 +00:00

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

borgmatic/borg/create.py Outdated

floli commented

2018-09-02 14:42:04 +00:00

Oh, wasn't aware of that, done.

floli reviewed 2018-09-02 15:12:31 +00:00

borgmatic/borg/create.py Outdated

floli commented

2018-09-02 15:12:31 +00:00

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

borgmatic/tests/unit/borg/test_check.py Outdated

floli commented

2018-09-02 15:16:01 +00:00

Done.

floli reviewed 2018-09-02 15:21:03 +00:00

borgmatic/commands/borgmatic.py Outdated

floli commented

2018-09-02 15:21:03 +00:00

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

floli commented

2018-09-02 15:52:59 +00:00

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

Thanks for making all the changes!

borgmatic/borg/create.py Outdated

						
				@ -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 ())

witten commented

2018-09-02 18:25:42 +00:00

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

witten commented

2018-09-02 18:31:22 +00:00

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

borgmatic/borg/create.py Outdated

floli commented

2018-09-04 18:12:42 +00:00

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

borgmatic/borg/create.py Outdated

witten commented

2018-09-05 05:34:29 +00:00

Looks great, thanks!

floli commented

2018-09-05 18:20:55 +00:00

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 ``` ?

witten commented

2018-09-06 04:49:20 +00:00

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

witten commented

2018-09-06 04:53:14 +00:00

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.

floli commented

2018-09-07 08:44:51 +00:00

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

witten commented

2018-09-08 20:56:02 +00:00

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

witten referenced this issue from a commit

2025-02-24 19:30:36 +00:00

Add "verify_tls" option to Uptime Kuma hook.

Sign in to join this conversation.

2 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: borgmatic-collective/borgmatic#90