Finer grained verbosity level #64

New Issue

floli · 2018-05-28T09:50:57Z

floli commented

2018-05-28 09:50:57 +00:00

Hello,

currently, borgmatic supports three levels of verbosity, which correspond to logging.WARNING, logging.INFO and logging.DEBUG.

If I read commands/borgmatic.py and verbosity_to_log_level(verbosity) correctly

no -v corresponds to args.verbosity = 0 => WARNING
-v 1 corresponds to args.verbosity = 1 => INFO
-v 2 corresponds to args.verbosity = 2 => DEBUG

In practice that means:

logging.WARNING (no command line -v given)

# borgmatic
Mo 28. Mai 11:18:56 CEST 2018 - Starting a backup job.
Mo 28. Mai 11:20:11 CEST 2018 - Backup created.

logging.INFO (-v 1)

# borgmatic -v 1
[... more output, but nothing on progress...]

logging.DEBUG (-v 2)

# borgmatic -v 2
output on how borg is called and the list of files that are taken info consideration.

I think there is a gap between -v 1 and -v 2 and that the output of borgmatic and borg is inconsistent (at -v 1, borgmatic already writing debug like information, borg not even progress information).

In my own borg backup script I had --verbose --filter AME --list --stats which imho is what most people want for logging. List just the changed files and print a final report.

Can something like that be achieved with borgmatic? (set the --filter AME on the output).

So far... I will try to write up a proposal on how I would organise the log levels, probably next week.

Hello, currently, borgmatic supports three levels of verbosity, which correspond to `logging.WARNING`, `logging.INFO` and `logging.DEBUG`. If I read `commands/borgmatic.py` and `verbosity_to_log_level(verbosity)` correctly 1. `no -v` corresponds to `args.verbosity = 0` => `WARNING` 2. `-v 1` corresponds to `args.verbosity = 1` => `INFO` 3. `-v 2` corresponds to `args.verbosity = 2` => `DEBUG` In practice that means: * `logging.WARNING` (no command line -v given) ``` # borgmatic Mo 28. Mai 11:18:56 CEST 2018 - Starting a backup job. Mo 28. Mai 11:20:11 CEST 2018 - Backup created. ``` * `logging.INFO` (-v 1) ``` # borgmatic -v 1 [... more output, but nothing on progress...] ``` * `logging.DEBUG` (-v 2) ``` # borgmatic -v 2 output on how borg is called and the list of files that are taken info consideration. ``` I think there is a gap between -v 1 and -v 2 and that the output of borgmatic and borg is inconsistent (at -v 1, borgmatic already writing debug like information, borg not even progress information). In my own borg backup script I had `--verbose --filter AME --list --stats` which imho is what most people want for logging. List just the changed files and print a final report. Can something like that be achieved with borgmatic? (set the --filter AME on the output). So far... I will try to write up a proposal on how I would organise the log levels, probably next week.

👍 1

witten commented

2018-05-28 21:57:17 +00:00

Here's an idea: What about changing borgmatic to unconditionally use --filter AMI when borgmatic is at verbosity level 2? I can't think of a situation in which you'd want to see unchanged files anyway. And on the first backup of a particular system, all files should show up as additions.

Thoughts?

Here's an idea: What about changing borgmatic to unconditionally use `--filter AMI` when borgmatic is at verbosity level 2? I can't think of a situation in which you'd want to see unchanged files anyway. And on the first backup of a particular system, all files should show up as additions. Thoughts?

👍 1

floli commented

2018-05-29 08:39:55 +00:00

I assume, you meant --filter AME?

Looking at python standard loglevels, I would propose.

DEBUG (-v 2): --list (no filter)
INFO (-v 1): --list --filter AME
WARNING and above (-v 0): --list --filter E

I would rather make INFO more verbose. DEBUG show thinks like

security: read previous location 'ssh://example.org:23/./horus'
security: read manifest timestamp '2018-05-28T20:55:38.831301'
security: determined newest manifest timestamp as 2018-05-28T20:55:38.831301
security: repository checks ok, allowing access
Verified integrity of /root/.cache/borg/0c6840c080fb1ab3f410181dbf236d349b2ca9d6d7fa1ac1ca2089deb5111dd9/chunks

which is perfect for DEBUG.

--filter AME is imho what you rathe want to have on INFO, i.e. normal procedure with somewhat elevated verboseness.

I assume, you meant `--filter AME`? Looking at python standard loglevels, I would propose. * `DEBUG` (`-v 2`): `--list` (no filter) * `INFO` (`-v 1`): `--list --filter AME` * `WARNING and above` (`-v 0`): `--list --filter E` I would rather make INFO more verbose. DEBUG show thinks like ``` security: read previous location 'ssh://example.org:23/./horus' security: read manifest timestamp '2018-05-28T20:55:38.831301' security: determined newest manifest timestamp as 2018-05-28T20:55:38.831301 security: repository checks ok, allowing access Verified integrity of /root/.cache/borg/0c6840c080fb1ab3f410181dbf236d349b2ca9d6d7fa1ac1ca2089deb5111dd9/chunks ``` which is perfect for DEBUG. `--filter AME` is imho what you rathe want to have on INFO, i.e. normal procedure with somewhat elevated verboseness.

witten commented

2018-06-07 04:35:25 +00:00

Yup, I meant to type --filter AME. What you propose makes sense to me! Some folks might be a little surprised by the increase in logs, but the impact is likely small.

Yup, I meant to type `--filter AME`. What you propose makes sense to me! Some folks might be a little surprised by the increase in logs, but the impact is likely small.

floli commented

2018-06-14 10:22:38 +00:00

Hello,

I'm currently working on some changes to the logging system. Main change is that I remove the verbosity variable and instead rely on the loggers setting. Example from info.py

    full_command = (
        (local_path, 'info', repository)
        + (('--remote-path', remote_path) if remote_path else ())
        + (('--lock-wait', str(lock_wait)) if lock_wait else ())
        + (('--debug') if logger.isEnabledFor(logging.DEBUG) else ())
        + (('--info')  if logger.isEnabledFor(logging.INFO)  else ())
    )

I haven't comitted anything yet. My first goal is to make the change and get the tests working, without any functional (log level -> output level) changes.

What is your opinion on that?

Hello, I'm currently working on some changes to the logging system. Main change is that I remove the `verbosity` variable and instead rely on the loggers setting. Example from `info.py` ``` full_command = ( (local_path, 'info', repository) + (('--remote-path', remote_path) if remote_path else ()) + (('--lock-wait', str(lock_wait)) if lock_wait else ()) + (('--debug') if logger.isEnabledFor(logging.DEBUG) else ()) + (('--info') if logger.isEnabledFor(logging.INFO) else ()) ) ``` I haven't comitted anything yet. My first goal is to make the change and get the tests working, without any functional (log level -> output level) changes. What is your opinion on that?

floli commented

2018-06-14 10:44:27 +00:00

Editing comments does not work for me with Firefox.

The code of course, should be

    full_command = (
        (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 ())
        + (('--debug',) if logger.isEnabledFor(logging.DEBUG) else ())
    )

producing --info --debug for loglevel DEBUG, the latter option overwrites previous ones.

Editing comments does not work for me with Firefox. The code of course, should be ``` full_command = ( (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 ()) + (('--debug',) if logger.isEnabledFor(logging.DEBUG) else ()) ) ``` producing `--info --debug` for loglevel DEBUG, the latter option overwrites previous ones.

witten commented

2018-06-15 04:26:54 +00:00

Sounds like it could certainly work, although it may be a little magical if it's relying on implicit global state. Are you thinking that logger is global, or passed in explicitly?

What's your thinking/motivation behind the logging changes? Just that it's annoying to pass verbosity in everywhere? Or is there something that you can't easily do with verbosity that you can with logger?

Sounds like it could certainly work, although it may be a little magical if it's relying on implicit global state. Are you thinking that `logger` is global, or passed in explicitly? What's your thinking/motivation behind the logging changes? Just that it's annoying to pass `verbosity` in everywhere? Or is there something that you can't easily do with `verbosity` that you can with `logger`?

floli commented

2018-06-15 10:47:18 +00:00

logger is returned from the python logging framework, like

logger = logging.getLogger(__name__)

in info.py. So it is a global state, but likewise the behavior logger.debug(msg) relies on the same global state.

Right now, borgmatic has two "global" states. The setup of the logging framework and the verbosity level. Since the log level is derived from the verbosity in borgmatic.py, they have essentially the same value.

They are also logically the same. The log level determines what borgmatic prints, the verbosity (which results in --info or --debug parameters passed to borg) determines the log level of borg.

Since they are set to the same value and mean the same, I think it's the most consistent way to derive the log level of borg directly from the log level of borgmatic.

`logger` is returned from the python logging framework, like ``` logger = logging.getLogger(__name__) ``` in `info.py`. So it is a global state, but likewise the behavior `logger.debug(msg)` relies on the same global state. Right now, borgmatic has two "global" states. The setup of the logging framework and the verbosity level. Since the log level is derived from the verbosity in borgmatic.py, they have essentially the same value. They are also logically the same. The log level determines what borgmatic prints, the verbosity (which results in `--info` or `--debug` parameters passed to borg) determines the log level of borg. Since they are set to the same value and mean the same, I think it's the most consistent way to derive the log level of borg directly from the log level of borgmatic.

witten commented

2018-06-17 21:09:37 +00:00

Okay.. Thanks for explaining. Makes sense to me. One thing to watch out for is that it may be a little more difficult (but still possible) to mock out a global logger in automated tests in order to properly set up the desired test state. One way around that would be to explicitly pass the value of logger.getEffectiveLevel() into a function that needs to do level-based logic. That way, you still get the benefits of consistent log level you're talking about, but also have dependencies explicitly passed in.

Note that I don't feel particularly strongly about this.. I'm sure any way you decide to do this would work.

Okay.. Thanks for explaining. Makes sense to me. One thing to watch out for is that it may be a little more difficult (but still possible) to mock out a global `logger` in automated tests in order to properly set up the desired test state. One way around that would be to explicitly pass the value of `logger.getEffectiveLevel()` into a function that needs to do level-based logic. That way, you still get the benefits of consistent log level you're talking about, but also have dependencies explicitly passed in. Note that I don't feel particularly strongly about this.. I'm sure any way you decide to do this would work.

floli commented

2018-07-01 18:55:04 +00:00

Hey! I am a little bit stucked with adapting the tests. When I run pytest, I get failed tests, but no real error message, e.g. the real reason of the failure of https://gist.github.com/floli/66c363d84517fa1fcfccf273e0b5e15b was that I removed the keyword argument verbosity and thus got a not-expected-keyword error message. I found it out, when I used pdb to step through, but the error message from the test was not helpful.

floli commented

2018-07-01 19:34:13 +00:00

Modeled after insert_subprocess_mock, I created

def insert_logging_mock(log_level):
    logging = flexmock(module.logging.Logger)
    logging.should_receive('isEnabledFor').replace_with(lambda x : x >= log_level)

which seems to work fine. Some tests need to be adapted to expect not --debug but --info --debug, as I wrote above.

Modeled after `insert_subprocess_mock`, I created ``` def insert_logging_mock(log_level): logging = flexmock(module.logging.Logger) logging.should_receive('isEnabledFor').replace_with(lambda x : x >= log_level) ``` which seems to work fine. Some tests need to be adapted to expect not `--debug` but `--info --debug`, as I wrote above.

witten commented

2018-07-01 22:11:59 +00:00

In terms of the failed tests without a real error message, that's one of the major limitations/annoyances I've found with flexmock. If the method signature doesn't match, then you're just kind of out of luck. Many other Python mocking frameworks don't have that same problem, but have even worse problems IMO. (Example: unittest.mock.)

In terms of the failed tests without a real error message, that's one of *the* major limitations/annoyances I've found with flexmock. If the method signature doesn't match, then you're just kind of out of luck. Many other Python mocking frameworks don't have that same problem, but have even worse problems IMO. (Example: [`unittest.mock`](https://docs.python.org/3/library/unittest.mock.html).)

witten commented

2018-09-09 18:17:17 +00:00

Now that your logging refactor has landed, I think this is done! If not, please let me know, or open a new ticket with any additional work. Thanks.

witten closed this issue

2018-09-09 18:17:17 +00:00

witten referenced this issue from a commit

2018-09-09 18:18:52 +00:00

Attach #64 to logging rewrite in NEWS.

witten commented

2018-09-27 04:37:17 +00:00

Finally released (borgmatic 1.2.3)!

witten referenced this issue

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

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

witten commented

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

FYI, some discussion about perhaps altering or backing out some of these changes: witten/borgmatic#272 ... Specifically the per-file detail at verbosity 1. You may want to weigh in there.

EDIT: Corrected ticket number.

FYI, some discussion about perhaps altering or backing out some of these changes: https://projects.torsion.org/witten/borgmatic/pulls/272 ... Specifically the per-file detail at verbosity 1. You may want to weigh in there. EDIT: Corrected ticket number.

witten referenced this issue from a commit

2023-04-01 06:20:55 +00:00

Fix randomly failing test: test_log_outputs_kills_other_processes_when_one_errors (#635).

Sign in to join this conversation.