use the logging module

[ThomasWaldmann]

python's logging module would give a lot of flexibility and configurability for logging.
log level, logging to multiple logs, remote logging, ...

https://docs.python.org/3.2/library/logging.html

Problem: widespread changes, bad for merging other pending stuff. Thus: maybe delay until later.

---

💰 there is a bounty for this

[FirefighterBlu3]

you can start logging with simple logging to the console stream with nearly all default logging values. aka, same as print

more advanced logging can be added as time permits

[ThomasWaldmann]

@FirefighterBlu3 i know the logging module, but the problem is "causing merge conflicts by widespread changes" (changing all/most print -> logging calls).

[ThomasWaldmann]

hmm, where does one draw the line (if any) between logging and normal console output?

logging output often has some structure (e.g. time stamp, level, msg), while normal output (print()) has not.

[ThomasWaldmann]

jborg/attic#312 will likely also be fixed / fixable once we stop using print.

[anarcat]

hmm, where does one draw the line (if any) between logging and normal console output?

logging output often has some structure (e.g. time stamp, level, msg), while normal output (print()) has not.

the basic logging tutorial has an answer for this:

Task you want to perform	The best tool for the task
Display console output for ordinary usage of a command line script or program	print()
Report events that occur during normal operation of a program (e.g. for status monitoring or fault investigation)	logging.info() (or logging.debug() for very detailed output for diagnostic purposes)
Issue a warning regarding a particular runtime event	warnings.warn() in library code if the issue is avoidable and the client application should be modified to eliminate the warning logging.warning() if there is nothing the client application can do about the situation, but the event should still be noted
Report an error regarding a particular runtime event	Raise an exception
Report suppression of an error without raising an exception (e.g. error handler in a long-running server process)	logging.error(), logging.exception() or logging.critical() as appropriate for the specific error and application domain

i personnally use logging.warning() all the time. Somehow I always remember more easily to do:

import logging

logging.warning('hello world')

than:

from __future__ import print_function

print("hello world")

... for me it's simply a way to stay 2.x and 3.x compatible.

that said, the logging module has its own set of peculiarities, especially the logging handlers and stuff like that. i have, however, some good experience configuring it to log to files, syslog and stderr. i would encourage such a switch and could work on a patch when we're ready.

some code sample for the logging setup, from the bup-cron project, that support syslog, automatically rotated logfiles and verbosity-sensitive output:

https://github.com/anarcat/bup-cron/blob/master/bup_cron/__init__.py#L799

i also used something like this in another project, for the verbosity-sensitive bit, but that also features some interactivity on the terminal:

def logsetup(args):
    '''setup logging'''
    global pipe
    levels = { None: logging.WARNING,
               0: logging.WARNING,
               1: logging.INFO,
               2: logging.DEBUG }
    # so the spinner works
    sys.stderr = os.fdopen(sys.stderr.fileno(), 'w', 0)
    if args.nopager:
        pipe = None
        stream = sys.stdout
    else:
        pipe = subprocess.Popen('less', stdin=subprocess.PIPE, close_fds=True)
        stream = pipe.stdin
    sh = logging.StreamHandler(stream)
    l = logging.getLogger('')
    l.setLevel(levels[args.verbose])
    l.addHandler(sh)
    logging.raiseExceptions = False
    logging.debug('parsed arguments {}'.format(args))

the "spinner" is some sort of logarithmic progress output that keeps the user informed that stuff is happening. it uses sys.stderr.write(".") to indicate progress, basically:

                    # throbber: put a dot every modulo(log10(i))
                    if (i % 10**factor) == 0:
                        sys.stderr.write(".")
                    # and every time we go one log10 higher, slow down the throbber
                    if (i % 10**(factor+1)) == 0:
                        sys.stderr.write("\r%d" % i)
                        factor = math.floor(float(math.log10(i)))

it makes sense to do this on a release boundary, because people should make PRs on those... of course, it would invalidate pending pull requests, but i see only one right now (#150) so it seems like a good time to clean that up.

let me know.

[ThomasWaldmann]

Well, that logging tutorial excerpt doesn't make it much clearer for me.

E.g. think about borg create. When the repo is encrypted, it starts with asking for the passphrase.
Is that print to stdout? print to stderr? guess it is rather not logging.*.

After entering the passphrase, it might be in verbose mode and outputs 1 line per file.
logging,info? maybe with different formats depending on whether it goes to console (no date, maybe also no time?) or to a log file (include datetime)?

Alternatively, it might output progress indication.
print to stdout? print to stderr? guess it is rather not logging.*.

I don't think print and logging.warning should be seen as equivalent in any case (or the one as solution for portability).

About stdout vs. stderr: we have to consider that borg extract --stdout will make borg output file data on stdout, so we can't output other stuff there at least for that usecase. Does that mean we just use stderr even if it is not an error msg we are outputting there?

I agree that now is a good time, no PRs open that I would consider merging right now.

[anarcat]

E.g. think about borg create. When the repo is encrypted, it starts with asking for the passphrase.
Is that print to stdout? print to stderr? guess it is rather not logging.*.

sys.stderr. in fact, there's the getpass library we should use: it defaults to /dev/tty if available, or sys.stderr.

After entering the passphrase, it might be in verbose mode and outputs 1 line per file.
logging,info?

logging.debug(), i would say.

maybe with different formats depending on whether it goes to console (no date, maybe also no time?) or to a log file (include datetime)?

not sure.

Alternatively, it might output progress indication.
print to stdout? print to stderr? guess it is rather not logging.*.

sys.stderr.write(...)

I don't think print and logging.warning should be seen as equivalent in any case (or the one as solution for portability).

they are not, of course. i was just saying i started using the logging module more partially for that reason.

About stdout vs. stderr: we have to consider that borg extract --stdout will make borg output file data on stdout, so we can't output other stuff there at least for that usecase. Does that mean we just use stderr even if it is not an error msg we are outputting there?

yes, that is what it means.

[anarcat]

one example of something that could be improved... there's a check-specific code here that should be made more generic:

class Repository:
# [...]
    def check(self, repair=False):
        error_found = False
#[...]
        def report_error(msg):
            nonlocal error_found
            error_found = True
            print(msg, file=sys.stderr)

report_error, in my mind, should be in main(). it should know about different types of exceptions and how to handle them, and it should not print stuff to the outside world.

this kind of stuff makes unit testing, among other things, much harder, because i can't call Repository.check() directly without messing around with sys.stderr to catch errors, something that is done in ArchiverTestCaseBase.cmd() with something that seems totally confusing to me.

this also applies to #57 of course...

[anarcat]

turns out this refactoring wouldn't be so bad after all... there are only 77 calls to print the borg module:

borg$ grep -r 'print(' borg | wc -l
77

it would be easy if not trivial to do the conversion. should i work on a PR?

[anarcat]

alright, i went crazy and did #233. feedback welcome.

[ThomasWaldmann]

the big changes were merged, we'll continue in new issues in case something more needs fixing.

thanks @anarcat!

[anarcat]

:) i'd be happy to discuss any issues you raised here that were not addressed in the PR. in particular, i believe you were concerned about verbosity levels and output control, as well as coherence between print() vs logger.log(). for verbosity, there is #303 now, but maybe you'd like to detail some of your other concerns in another issue...