#90 Rework logging/verbosity system

Merged
witten merged 12 commits from floli:master into master 6 months ago
floli commented 6 months ago

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 6 months ago
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
@@ -154,3 +151,1 @@
154
-            VERBOSITY_SOME: ('--info',) if dry_run else ('--info', '--stats'),
155
-            VERBOSITY_LOTS: ('--debug', '--list', '--show-rc') if dry_run else ('--debug', '--list', '--show-rc', '--stats'),
156
-        }.get(verbosity, ())
151
+        + (('--list', '--filter', 'AME', '--info', '--stats') if logger.isEnabledFor(logging.INFO) else ())
witten

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
@@ -155,2 +151,2 @@
155
-            VERBOSITY_LOTS: ('--debug', '--list', '--show-rc') if dry_run else ('--debug', '--list', '--show-rc', '--stats'),
156
-        }.get(verbosity, ())
151
+        + (('--list', '--filter', 'AME', '--info', '--stats') if logger.isEnabledFor(logging.INFO) else ())
152
+        + (('--debug', '--show-rc') if logger.isEnabledFor(logging.DEBUG) else ())
witten

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 6 months ago
Made it all the way through. Generally looks great. See minor feedback throughout!
borgmatic/borg/prune.py
@@ -59,2 +55,2 @@
59
-            VERBOSITY_LOTS: ('--debug', '--stats', '--list', '--show-rc'),
60
-        }.get(verbosity, ())
55
+        + (('--stats',) if logger.isEnabledFor(logging.INFO) else ())
56
+        + (('--info',)  if logger.isEnabledFor(logging.INFO)  else ())
witten

Any reason not to combine these two lines?

Any reason not to combine these two lines?
borgmatic/commands/borgmatic.py
@@ -93,3 +93,3 @@
93 93
         '-v', '--verbosity',
94 94
         type=int,
95
-        help='Display verbose progress (1 for some, 2 for lots)',
95
+        help='Display verbose progress (1 for INFO, 2 for DEBUG)',
witten

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.)
borgmatic/commands/borgmatic.py
@@ -122,3 +122,3 @@
122 122
     checks.
123 123
     '''
124
-    logger.info('{}: Parsing configuration file'.format(config_filename))
124
+    logger.debug('{}: Parsing configuration file'.format(config_filename))
witten

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
@@ -20,0 +19,4 @@
19
+    
20
+def insert_logging_mock(log_level):
21
+    logging = flexmock(module.logging.Logger)
22
+    logging.should_receive('isEnabledFor').replace_with(lambda x : x >= log_level)
witten

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
@@ -23,1 +23,4 @@
23 23
 
24
+def insert_logging_mock(log_level):
25
+    logging = flexmock(module.logging.Logger)
26
+    logging.should_receive('isEnabledFor').replace_with(lambda x : x >= log_level)
witten

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
@@ -9,3 +9,3 @@
9 9
 
10 10
 def test_verbosity_to_log_level_maps_unknown_verbosity_to_warning_level():
11
-    assert module.verbosity_to_log_level('my pants') == logging.WARNING
11
+    assert module.verbosity_to_log_level('my pants') == logging.INFO
witten

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

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

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 commented 6 months ago
Poster

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 6 months ago
Thanks for making all the changes!
borgmatic/borg/create.py
@@ -155,2 +151,2 @@
155
-            VERBOSITY_LOTS: ('--debug', '--list', '--show-rc') if dry_run else ('--debug', '--list', '--show-rc', '--stats'),
156
-        }.get(verbosity, ())
151
+        + (('--list', '--filter', 'AME', '--info') if logger.isEnabledFor(logging.INFO) else ())
152
+        + (('--stats',) if not dry_run and logger.isEnabledFor(logging.INFO) else ())
witten

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 6 months ago
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 commented 6 months ago
Poster

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 6 months ago
Owner

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

Sure, that makes sense to me given all the changes.
witten commented 6 months ago
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.
floli commented 6 months ago
Poster

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 commented 6 months ago
Owner

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

Looks great, merged! Thanks again for all your hard work here.
The pull request has been merged.
Sign in to join this conversation.
No Milestone
No Assignees
2 Participants
Due Date

No due date set.

Dependencies

This pull request currently doesn't have any dependencies.

Loading…
Cancel
Save
There is no content yet.