search

borgbackup / borg

Deduplicating archiver with compression and authenticated encryption.
https://www.borgbackup.org/
Other
10.84k stars 734 forks source link

prune --stats works only with --verbose #526

Closed pszxzsd closed 8 years ago

pszxzsd commented 8 years ago

borg prune --stats only actually prints stats when --verbose is specified too.

I'm using the 0.29.0 32bit Linux binary.

ThomasWaldmann commented 8 years ago

yes, this is expected.

--verbose lowers the log level to INFO (default is WARNING).

--stats emits informative output using the logging system and level INFO.

pszxzsd commented 8 years ago

But borg create --stats prints stats without needing --verbose, as expected. If prune --stats is supposed not to do anything by itself, it's really counter-intuitive.

ThomasWaldmann commented 8 years ago

oh, yeah, that sounds inconsistent. i'll look into it.

rpodgorny commented 8 years ago

i can see you've committed a patch that restores a consistency - this is a good thing. on the other hand, i don't think --verbose should be needed to print --stats and the original behavior was better and far more intuitive:

1) having an option flag which does nothing by itself confuses people (at least it confused me) 2) having to use the --verbose flag raises the verbosity too much. user just wants the stats, not a list of kept archives and whatnot.

ThomasWaldmann commented 8 years ago

well, --verbose (== --info) and --debug work by adjusting the log level. all messages are emitted at correct log level. statistics are informational, so INFO is used.

as silent-by-default behaviour was desired, the default log level is warning. that means, you can't get INFO messages without --info (or --verbose).

rpodgorny commented 8 years ago

yes, i understand the log level logic and it makes perfect sense. still, i don't think it's intuitive for the (uneducated) end user as of now. maybe, if the --stats flag automatically lowers the level to INFO or something. i don't know, really.

ThomasWaldmann commented 8 years ago

well, there is another issue: if we automatically enable info log level by --stats, the other stuff emitted at info level also appears (for create, this is the verbose file listing).

rpodgorny commented 8 years ago

exactly! ...so, in other words, is there a way to just show stats without the other stuff (file lists, kept archives, ...)? if not, that's certainly not what the users want/expect.

ThomasWaldmann commented 8 years ago

reopened because of remaining issues after merging the PR.

anarcat commented 8 years ago

i believe, in #74, that we agree on using print for topical flags, and that in #302 we discussed various ways of implementing on screen display that was independent of the logging system levels.

i do believe we should print out those stats without --verbose, otherwise the flags are useless, from the user's perspective (i know they trigger the computation or not, but that's only a mostly undetectable performance change from the user's perspective).

the solution i was proposing in #302 was to use a user interface abstraction layer, that could eventually support a GUI and such. this specific idea was split into #314 and postponed for later, maybe it would be one way to fix this problem.

another, naive and simple way, is to log those stats with a higher priority (say warning), but that is usually a no-no in the current paradigm. it would fix the problem, but would open another, which could be described as a user story: "how do i get just the REAL warnings?" my response would be "turn off --stats", but maybe that wouldn't be appropriate for everyone.

short of those two options, i think the only way to fix this is to actually force-print, to stderr (we still do that some places, don't we?) the stats, and also log them to the logger. yes, it will mean duplicated data streams if verbosity is high enough, but maybe we could also use a probe to see if a given message would print or not... logger.isEnabledFor('INFO') comes to mind here - we could check that and simply print if INFO is not enabled?

ThomasWaldmann commented 8 years ago

I wanted to feed stats into same channel as the file list borg create outputs in verbose mode. borg create usually runs non-interactively as cron job and output shall go into logging, not one part to stderr and the other part to logging (which is not necessarily stderr).

the problem that currently the file list always appears will be solved by adding a --list topical flag (this effect is because we changed interpretation of --verbose to change the log level).

anarcat commented 8 years ago

On 2016-01-14 10:54:48, TW wrote:

I wanted to feed stats into same channel as the file list borg create outputs in verbose mode. borg create usually runs non-interactively as cron job and output shall go into logging, not one part to stderr and the other part to logging (which is not necessarily stderr).

i understand that. it seems, however, that there is a user expectation that --stats will necessarily output something on stderr, independently of logging settings.

the problem that currently the file list always appears will be solved by adding a --list topical flag (this effect is because we changed interpretation of --verbose to change the log level).

i am not sure how --list relates to this problem, other than it is the same problem we're trying to fix.

hence a wrapper function.

what are you proposing to fix this issue?

ThomasWaldmann commented 8 years ago

well, expectations can be fixed by documentation and we already have there, under Usage/General:

"All log messages created with at least the set level will be output."

anarcat commented 8 years ago

On 2016-01-14 11:28:08, TW wrote:

well, expectations can be fixed by documentation.

i disagree.

rpodgorny commented 8 years ago

i have to disagree as well. if borg aspires to gain wider adoption, it has to be intuitive. users don't really care about log levels - they just want borg to do what they expect it to do. unfortunately, this sometimes goes against "doing it right" from the programmer's point of view but in the end, it's the users who decide what's "right" and "wrong". i think even the existence of this bug report is the evidence - user specified --stats and borg didn't show any. simple as that.

ThomasWaldmann commented 8 years ago

ok, i rephrase it to "you have to read the docs, so your expectations match reality".

ThomasWaldmann commented 8 years ago

https://github.com/borgbackup/borg/pull/553 adds the --list option, so there is a usable and consistent way now to get the output one wants.

I tagged it "won't fix" because while re-establishing consistency and the ability to get what one wants, I won't "fix" (change) that one must set the correct logging level to see messages emitted at that logging level.

anarcat commented 8 years ago

specifically, my personnal use case here is i run borg through a cronjob with --stats. i consistently get a nice summary of the backup job and then nothing else, which is nice because i don't have all the other noise that --verbose would do.

what's the use case of --stats without --verbose anyways? does it even make sense?

anarcat commented 8 years ago

so i just got bit by this. --stats seems to do nothing here. i'll try with --verbose for the next job, but whereas my previous (pre 0.29) cron jobs would show:

/etc/cron.daily/borg:
------------------------------------------------------------------------------
Archive name: marcos-2016-02-05
Archive fingerprint: ad9fa8871a18cb300d2709a0e2cf0081098713cd11e3d2a55fbad55c3f81ab26
Start time: Fri 05 Feb 2016 07:37:25 AM 
End time: Fri 05 Feb 2016 07:51:57 AM 
Duration: 14 minutes 32.23 seconds
Number of files: 1678836

                       Original size      Compressed size    Deduplicated size
This archive:              208.25 GB            179.82 GB            912.41 MB
All archives:              119.36 TB            105.19 TB            549.65 GB

                       Unique chunks         Total chunks
Chunk index:                12759167           2388470164
------------------------------------------------------------------------------

i am afraid the next job will show a bunch more garbage that I do not need, and which will make it harder to pinpoint problems.

too bad.

rpodgorny commented 8 years ago

since "broken" for me. this is what 0.30 shows on --verbose --stats:

borg prune --verbose --stats --keep-within 7d --keep-daily 30 --keep-monthly 12 --keep-yearly 10 backup@milhouse.podgorny.cz:borg/taurus
Keeping archive: 20160206T050001                      Sat, 2016-02-06 05:01:22
Keeping archive: 20160205T050001                      Fri, 2016-02-05 05:00:39
Keeping archive: 20160204T050001                      Thu, 2016-02-04 05:00:37
Keeping archive: 20160203T050001                      Wed, 2016-02-03 05:02:01
Keeping archive: 20160202T050001                      Tue, 2016-02-02 05:00:47
Keeping archive: 20160201T050001                      Mon, 2016-02-01 05:02:35
Keeping archive: 20160131T050001                      Sun, 2016-01-31 05:01:28
Keeping archive: 20160130T050001                      Sat, 2016-01-30 05:01:36
Keeping archive: 20160129T050001                      Fri, 2016-01-29 05:01:07
Keeping archive: 20160128T050001                      Thu, 2016-01-28 05:00:39
Keeping archive: 20160127T050001                      Wed, 2016-01-27 05:00:38
Keeping archive: 20160126T050001                      Tue, 2016-01-26 05:01:07
Keeping archive: 20160125T050001                      Mon, 2016-01-25 05:01:12
Keeping archive: 20160124T050001                      Sun, 2016-01-24 05:04:52
Keeping archive: 20160123T050001                      Sat, 2016-01-23 05:01:01
Keeping archive: 20160122T050001                      Fri, 2016-01-22 05:01:22
Keeping archive: 20160121T050001                      Thu, 2016-01-21 05:12:36
Keeping archive: 20160120T050001                      Wed, 2016-01-20 05:01:03
Keeping archive: 20160119T050002                      Tue, 2016-01-19 05:01:17
Keeping archive: 20160118T050001                      Mon, 2016-01-18 05:01:14
Keeping archive: 20160117T050001                      Sun, 2016-01-17 05:03:38
Keeping archive: 20160116T050001                      Sat, 2016-01-16 05:00:51
Keeping archive: 20160115T050001                      Fri, 2016-01-15 05:03:56
Keeping archive: 20160114T050001                      Thu, 2016-01-14 05:00:54
Keeping archive: 20160113T050001                      Wed, 2016-01-13 05:00:58
Keeping archive: 20160112T050001                      Tue, 2016-01-12 05:01:02
Keeping archive: 20160111T050001                      Mon, 2016-01-11 05:01:49
Keeping archive: 20160110T050001                      Sun, 2016-01-10 05:02:54
Keeping archive: 20160109T050001                      Sat, 2016-01-09 05:01:09
Keeping archive: 20160108T050001                      Fri, 2016-01-08 05:02:05
Keeping archive: 20160107T050001                      Thu, 2016-01-07 05:15:27
Keeping archive: 20151226T050001                      Sat, 2015-12-26 05:00:57
Keeping archive: 20151225T050001                      Fri, 2015-12-25 05:02:07
Keeping archive: 20151224T050001                      Thu, 2015-12-24 05:09:29
Keeping archive: 20151223T050001                      Wed, 2015-12-23 05:01:22
Keeping archive: 20151222T050001                      Tue, 2015-12-22 05:02:00
Keeping archive: 20151221T050001                      Mon, 2015-12-21 05:01:17
Keeping archive: 20151130T050001                      Mon, 2015-11-30 05:02:01
Pruning archive: 20151220T050001                      Sun, 2015-12-20 05:09:44
Pruning archive: 20151219T050001                      Sat, 2015-12-19 05:01:25
------------------------------------------------------------------------------
                       Original size      Compressed size    Deduplicated size
Deleted data:               -3.67 GB             -1.59 GB            -21.94 MB
All archives:               71.63 GB             30.92 GB              1.70 GB
                       Unique chunks         Total chunks
Chunk index:                  154786              3970730
------------------------------------------------------------------------------

...for me, it's a regression since i want stats and stats only. :-( ...i'm with anarcat on this one...

pszxzsd commented 8 years ago

Create got the --list option, the same logic could be applied to prune.

anarcat commented 8 years ago

@pszxzsd --stats is supposed to be exactly that. or do you mean that the archive listing should be displayed only if --list is shown?

maybe that list should be sent at the --debug level?

the create output is not as bad as prune, but still annoying:

/etc/cron.daily/borg:
reading files cache
processing files
------------------------------------------------------------------------------
Archive name: marcos-2016-02-07
Archive fingerprint: 3a98497d743a9653e7a6124d9d367b09c0eaf99b627e3d2a198cf5d629512a7d
Start time: Sun Feb  7 07:36:16 2016
End time: Sun Feb  7 07:51:26 2016
Duration: 15 minutes 10.23 seconds
Number of files: 1679060
------------------------------------------------------------------------------
                       Original size      Compressed size    Deduplicated size
This archive:              208.32 GB            180.16 GB            627.40 MB
All archives:              119.78 TB            105.55 TB            551.35 GB

                       Unique chunks         Total chunks
Chunk index:                12816417           2397878749
------------------------------------------------------------------------------
fsironman commented 8 years ago

looking trough my old cron output:

this was 0.29

logger: Backup: Starting Borg Backup
------------------------------------------------------------------------------
Archive name: root-2016-01-23
Archive fingerprint: 8b8a477f7758466e180c8ba207473bc27c46f0532026c0b73c411f7f5965aa1e
Start time: Sat Jan 23 08:56:09 2016
End time: Sat Jan 23 09:02:00 2016
Duration: 5 minutes 50.63 seconds
Number of files: 74351

                       Original size      Compressed size    Deduplicated size
This archive:                9.88 GB              3.82 GB            254.03 MB
All archives:               32.20 GB             14.36 GB              3.61 GB

                       Unique chunks         Total chunks
Chunk index:                  161307               711072
------------------------------------------------------------------------------
logger: Backup: Borg Backup finished

this is 0.30 after the upgrade suddenly no output anymore

logger: Backup: Starting Borg Backup
logger: Backup: Borg Backup finished

this is after enabling stats output again with --verbose

logger: Backup: Starting Borg Backup
reading files cache
processing files
------------------------------------------------------------------------------
Archive name: root-2016-02-06
Archive fingerprint: b8e598dd93f04de8aef34f4dfb1c3057febd01e30a62c04016709699f1fe6e5a
Start time: Sat Feb  6 09:18:45 2016
End time: Sat Feb  6 09:19:36 2016
Duration: 50.79 seconds
Number of files: 74590
------------------------------------------------------------------------------
                       Original size      Compressed size    Deduplicated size
This archive:                9.93 GB              3.84 GB             22.81 MB
All archives:              171.68 GB             69.00 GB              4.93 GB

                       Unique chunks         Total chunks
Chunk index:                  188037              3316822
------------------------------------------------------------------------------
logger: Backup: Borg Backup finished

I think the behaviour from 0.29 should be restored. If i get the output from my cronjob mailed i really dont care that it is reading the file cache or is processing the files. I just want to see the stats and the option --stats should just enable this regardless of log level.

pszxzsd commented 8 years ago

@anarcat I meant to list archives only when adding a --list option to prune. I opened a new issue about this: #658.

glandium commented 8 years ago

The same issue was raised in #665. Not having looked at the code, if the logging is done with python's logging module, then stats could be sent to its own logger with a different log level, which is set to INFO when stats is enabled.