logging / output: implement topical flags set

[ThomasWaldmann]

In the current logging / output implementation, there is one issue:

logging levels (debug, info, warning, error) are not always used to output messages of that "severity", but sometimes a higher level (e.g. warning) is used just to make some output shown (with a logger that would not show less than warning level), e.g. because verbose mode is set. Or a lower level (e.g. debug) is used to make output not shown, even if it has nothing to do with debug output (== output intended for a software developer or power user to analyze issues).

I think this should be done a bit differently:

• debug, info, warning, error are ONLY used for messages of that severity / kind
• within "info" level, output is chosen by another mechanism which is called topical flags above

Users can choose in what kind of output they are interested (e.g. --stats flags would enable all kinds of statistic output, --progress flag would enable progress indication output, --verbose flag would enable output of long lists, like every file that was backed up or extracted, etc.).

So, e.g. create --stats --progress would set:

flags = {STATS, PROGRESS}

The respective places in the code would check if their kind is in vs:

if STATS in flags:
    logger.info("statistics output")

Or, to make this less code, define log(flag, ...) to wrap logging.info with that check and call it like:

log(STATS, "statistics output")

The default log level could then be lowered to INFO, but would be still rather silent if nothing is in the flags set.

[ThomasWaldmann]

Note: it is intentionally a SET and not another level. Because with levels, we would have to define such levels and they would be too inflexible.

[anarcat]

note the relation to #233, the original logging implementation...

so the idea i had there for "sets" was to implement a system of logging filters, based on the different borg modules: https://github.com/borgbackup/borg/pull/233#issuecomment-145100222

of course, that means we would have only module-level granularity (although we could create new loggers on the fly of course), but it would make sense, in my opinion to move stuff like progress and stats to their own modules anyways...

i agree levels are too inflexible for this right now.

[ThomasWaldmann]

this issue has nothing to do with filtering by module. and as I already said, filtering by module is not sufficient anyway.

Note: I changed the term to "topical flags (set)", it is easier to understand.

[anarcat]

well, if topics are modules, that would work easily no?

[ThomasWaldmann]

you don't want to have the modularization driven by logging system inflexibility.

[anarcat]

here's another idea i had to resolve this just now. we could integrate the idea of a UI class somewhere. this would expand the logger module functionality to also cover stuff like user input, --progress, --stats, whether we show file output and so on. instead of calling basic methods like:

print("Archive size: 50 GB")
logging.log("processing files")
print("\rprogress: 50%")
input("are you sure? [Y/n]")

...we could instead use:

ui.display('Archive size: 50 GB')
ui.status('processing files')
ui.progress("progress: %d%%", percent)
ui.prompt('are you sure?', ['yes', 'no'], default='Yes')

This would allow us to control the interaction with the user topically, without having to propagate the args object all over the place. We'd initialize a UI object when we start with the commandline args, and then filtering can happen more naturally.

Even better: this can enable all sorts of UIs as well... A GUI could easily be built on top of this: ui.display could send information in a popup or a widget, ui.status could go in a status bar or notification area, ui.progress could update a status bar, ui.prompt would be a popup with buttons, etc...

i have implemented something like this for Monkeysign: there, i have a ui module that handles commandline parsing for both the GTK and commandline interfaces. it also configures a set of basic abstract functions like the above, that are then implemented in the cli and gtk modules.

[anarcat]

also, two more logging modules we found:

https://pythonhosted.org/Logbook/ https://structlog.readthedocs.org

[ThomasWaldmann]

I'ld prefer to solve and stabilize this for next release in a simpler way than a "UI object" refactoring. The latter might just introduce a lot of more work and delay next release more than needed. So maybe open a separate issue for that.

[ThomasWaldmann]

I played a bit with structlog and logging from stdlib. While structlog is nice, it adds a dependency and I found out while reading the docs, that we can also filter with "logging", see the attached code. test_lg.py.txt

[anarcat]

herm, i did mention logging filters in https://github.com/borgbackup/borg/pull/233#issuecomment-145100222 :p the problem is how to connect that with the commandline in a meaningful way without overloading the commandline or the method calls. should we add extra=whereiam to every logging call? that seems like quite a burden...

this is why i was suggesting using modules. we could use per-class loggers as well...?

[anarcat]

i split the UI refactoring into #314, as requested, but i still believe it would be a valuable split. basically, that filter module is a UI module, in my mind. just a question of semantics. :)

[ThomasWaldmann]

if we agree that borg should be mostly silent by default (except warnings and errors), you have to indicate what you want to see if you want to see it. and the current way to do that is the commandline.

we already do have some topical flags: --stats --progress (anything else already present?) (anything we would need to add here?) --show-unchanged-files

we also have a general flag with currently relatively undefined effect: --verbose -v (once or multiple times)

What we could do with the general flag is to count it (e.g. -vvv = 3) and automatically activate specific predefined sets of topics depending on the count. So that could enable the user to just give -vvv and it would e.g. mean the same as when giving --stats --showmeallfiles.

If somebody is unhappy with the sets we have chosen for different counts, he can still give individual topical flags to activate whatever combination he wants.

That all would happen at the end of argparsing. Then the logging filter would be configured adequately and we're done.

[ThomasWaldmann]

I agree that this extra=dict(topic=FOO) isn't too pretty, but that's what stdlib offers.

To make it prettier, we could make a wrapper function and call it like info(STATS, "some stats", ...).

[anarcat]

i know we need to do some commandline argparsing for now (see also #315 ;). the idea of the UI module was to avoid having an extra dict.

I agree that this extra=dict(topic=FOO) isn't too pretty, but that's what stdlib offers.

To make it prettier, we could make a wrapper function and call it like info(STATS, "some stats", ...).

i am not sure what the difference is between a "wrapper function called info(STATS, "some stats", ...)" and ui.stats("some stats") - isn't that exactly the same thing?

[ThomasWaldmann]

I'm talking about a 2 line function info() while you are talking about another bigger UI refactoring, that is the difference. And I'ld appreciate if ui discussion stays in that separate issue.

[anarcat]

three lines :)

class ui:
   def status(*args):
       logger.info(*args):

but okay, i'll keep any further suggestion in #314... not sure how i can contribute otherwise here.

[anarcat]

(anything we would need to add here?)

236 (no unchanged files) comes to mind...

[ThomasWaldmann]

ah, yes.

[ThomasWaldmann]

Hmm, after looking at all the related code, the above idea seems somehow just boilerplate and also incomplete.

args.progress and args.stats already are the topical flags and they are available at the places where needed.

they do not just function as output filter (as the above described topical flags would work), but also trigger the needed computations (or not).

So, I think this is not needed at all, just #321.