Logging [4/6] #10

jrabinow · 2021-10-29T10:25:48Z

Better logging for snapborg

enzingerm · 2021-11-04T20:37:31Z

Thanks for this PR, I'm sure snapborg can benefit from better output formatting/logging. Setting up and configuring the loggers in each module seems a bit repetitive to me (there might be more modules to come). Maybe we can create a custom log module which provides a function which takes the logger name (__name__) and returns a configured logger instance with handler and formatter already attached?

snapborg/borg.py

jrabinow · 2021-11-04T22:41:09Z

Maybe we can create a custom log module which provides a function which takes the logger name (name) and returns a configured logger instance with handler and formatter already attached?

Done :-)

I thought that init_snapborg_logger would be best in the existing utils module. If the code ever grows in length, it should be easy to refactor. Does that work for you?

enzingerm · 2021-11-05T10:10:07Z

I thought that init_snapborg_logger would be best in the existing utils module. If the code ever grows in length, it should be easy to refactor. Does that work for you?

Yep that would be fine for me. However, after testing I think this approach still needs some tuning. Snapborg can be launched in two scenarios:

headless/automated for example started by a systemd timer (this is how I do it at the moment).
In this case prepending the whole timestamp to each output line seems detrimental to me, as the systemd journal already does this for me. However, the severity of each message as well as the source (python module?) might be beneficial as well as being able to specify the loglevel (e.g. via -v/-vv/...)
interactively started as a command line tool (e.g. plug in ext. HDD, then run snapborg backup)
In this case prepending a timestamp seems like a good idea to me as you can check how long each step took afterwards.

What do you think?

jrabinow · 2021-11-05T21:20:34Z

I think that makes a lot of sense, I've implemented your suggestions. Without any -v flag, only warnings and above are logged, with -v, info and above are logged. And for debug, you can use the -vv flag.

This means that by default, snapborg won't log any output if the run is successful. I'm not sure if that's what you wanted, I just went off what made sense for -v and -vv per your comment. I can easily change that if you'd like to have successful runs logged too, let me know your preference.

Also of note is that for detecting headless mode, I stole the code from
borg.py:34: self.is_interactive = os.isatty(sys.stdout.fileno()) but I don't have any .service/.timer files to test whether headless mode detection actually works or not. If you could provide me yours (they might actually be something worthwhile including in the repo), I could give testing headless mode a shot.

jrabinow · 2021-11-23T01:01:28Z

Hey there @enzingerm , did you have the chance to review? I'd be happy to take any feedback into account.

enzingerm

Sorry for the delay. I commented on some minor issues. Generally It there should be a distinction between mandatory program output which should not be logged and further information which doesn't need to be shown for the program to work. Of course commands like list have mandatory output but what is the output one would expect from calls like backup? Empty as long as no error occurs? One line for each snapper config which is being processed? One line for each snapshot which is being transferred? I'm not sure so maybe this should be addressed later. It would also be nice to have a mapping from the python log level of each message to systemd's journal log levels.

enzingerm · 2021-11-04T20:38:13Z

snapborg/borg.py

-                if not print_output:
-                    print(f"Borg command execution gave warnings:\n{e.output.decode()}")
+                if log_output:
+                    LOG.info(f"Borg command execution gave warnings:\n{e.output.decode()}")


maybe use .warning(...) here?

Also, I think it'd be better to remove the if completely. Printing snapborg warnings shouldn't depend on whether or not the borg output was printed beforehand.

enzingerm · 2021-11-25T15:44:43Z

snapborg/borg.py

                                        env=env)
        except CalledProcessError as e:
            if e.returncode == 1:
+                LOG.info(line)


undefined variable: line

Whoops, serves me right for stacking my PRs on top of one another. Good catch.

enzingerm · 2021-11-25T16:20:16Z

snapborg/borg.py

    return password


-def launch_borg(args, password=None, print_output=False, dryrun=False):


I'm not so happy about this rename. This parameter should control whether or not the borg output actually is printed to stdout, which is a different concept from logging program actions, I suppose.

Today, the behavior is to print when calling snapborg from a shell, and stay silent otherwise.

On one hand, I think that borg output when calling snapborg from a command-line just adds to noise. Per my suggestion in the main thread, I don't think we should be printing output to the console unless an error of some sort happened or unless it was explicitly requested with verbose mode (-v).
On the other, I deduce (perhaps incorrectly) from your comment that you find borg output useful.

I haven't discussed printing borg output independently from putting the entire program into verbose mode, say with a --print-borg-output switch. I could add such a switch and set it to False by default, would that work?

Another approach would be to log (or print, if you don't want the dates as a prefix) if snapborg is explicitly put into verbose mode, or in case of error. This is the approach that I described in the main review thread, and that I implemented here.

What's your preference?
I also went with logging because that gives the dates and times, but do you prefer printing?

enzingerm · 2021-11-25T16:23:37Z

snapborg/borg.py

            borg_invocation,
            self.passphrase,
-            print_output=self.is_interactive,
+            log_output=False,


Why unconditionally disable print_output here?

According to my suggestion in the main thread, this should print output if running in verbose mode (-v) or if something unexpected happened. I'll change the code so that that's what happens, does that work for you?

EDIT: looks like I should change that in the other launch_borg callsites as well.

EDIT2: https://github.com/enzingerm/snapborg/pull/10/files#r757020346 as I'd like to better understand what your needs are.

enzingerm · 2021-11-25T16:57:15Z

snapborg/util.py

+        formatter = logging.Formatter("%(asctime)s - %(levelname)s - %(message)s")
+    else:
+        # if running in non-interactive mode, typically through systemd
+        formatter = logging.Formatter("%(levelname)s - %(name)s:%(lineno)d - %(message)s")


I'm not sure if it's neccessary to include module name and line number. But it doesn't hurt, either (other than the output becomes a little less readable). Maybe in the future this should be controllable via a parameter or environment variable.

jrabinow · 2021-11-29T00:00:59Z

what is the output one would expect from calls like backup? Empty as long as no error occurs? One line for each snapper config which is being processed? One line for each snapshot which is being transferred? I'm not sure so maybe this should be addressed later.

So I was saying this earlier:

This means that by default, snapborg won't log any output if the run is successful. I'm not sure if that's what you wanted, I just went off what made sense for -v and -vv per your comment. I can easily change that if you'd like to have successful runs logged too, let me know your preference.

Basically this approach is inspired by the unix tool principles. We assume that programs run correctly and that any message printed to screen is something that is intended to be read and/or acted upon. I'm paraphrasing this from memory but the essence of the idea was that "a program that runs correctly doesn't print anything except to say that something unexpected happened".
We don't have to do it this way ofc, I like this approach but I understand the want for confirmation.
To that effect we have progress bars that flash across the terminal, they disappear once the run is completed successfully or show at what point the program bailed if that's what happens. I'm afraid I don't know how to do progress bars.

Additionally, we have systemd logs. I think that output and systemd logs are separate things, and that if there's any requirements/opinions to be had on output, it's best to differentiate both sooner rather than later.

Lastly, we have the current context. Concerning subprocesses, I'm not sure if it's possible to only print out borg output if it's an error (I'm on an apple right now, so I can't test stuff), but I think this is something we should be aiming for if it's easily feasible. Also, this is a bit of a sysadmin tool. These are the kinds of tools for which it's very useful to go back and look at the logs several months later, to diagnose when things stopped working. It's also great for checking that "last night's backup ran ok". I think that both these usecases are best served with systemd logs.

Putting all of this together along with your comments, I suggest the following approach:

no output to terminal unless the output is an end unto itself (snapborg list) or if something unexpected happens.
log results by snapper config <-> borg repo pair to systemd, both in interactive and in non-interactive mode.
development info logged to terminal when run in debug mode (-vv).
optional / to be implemented by someone else: progress bar showing backup progress.

Does that work/what are your thoughts on this approach?

Where I can, I'll answer your comments accordingly.

EDIT: It would also be nice to have a mapping from the python log level of each message to systemd's journal log levels. since I'm not familiar with using snapborg with systemd, would you know how to implement this one? Or do you have a resource I could learn from?

jrabinow changed the title ~~Logging~~ Logging [4/6] Oct 29, 2021

jrabinow force-pushed the logging branch 3 times, most recently from 944effa to 59cc01a Compare October 31, 2021 01:35

jrabinow mentioned this pull request Oct 31, 2021

Allow snapborg to backup individual snapshots to multiple borg repos [6/6] #12

Open

jrabinow force-pushed the logging branch from 59cc01a to 715cc9f Compare November 3, 2021 02:06

jrabinow force-pushed the logging branch from 715cc9f to 0417e95 Compare November 4, 2021 22:37

jrabinow commented Nov 4, 2021

View reviewed changes

snapborg/borg.py Show resolved Hide resolved

jrabinow force-pushed the logging branch 4 times, most recently from 6d04d76 to 2604891 Compare November 5, 2021 05:17

log to stderr instead of printing to stdout

fcfd058

jrabinow force-pushed the logging branch from 2604891 to fcfd058 Compare November 5, 2021 19:42

add support for verbose flag

1ab1c16

enzingerm requested changes Nov 25, 2021

View reviewed changes

		return password


		def launch_borg(args, password=None, print_output=False, dryrun=False):

Logging [4/6] #10

Are you sure you want to change the base?

Logging [4/6] #10

Uh oh!

Conversation

jrabinow commented Oct 29, 2021

Uh oh!

enzingerm commented Nov 4, 2021

Uh oh!

Uh oh!

jrabinow commented Nov 4, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

enzingerm commented Nov 5, 2021

Uh oh!

jrabinow commented Nov 5, 2021

Uh oh!

jrabinow commented Nov 23, 2021

Uh oh!

enzingerm left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jrabinow commented Nov 29, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

jrabinow commented Nov 4, 2021 •

edited

Loading

jrabinow commented Nov 29, 2021 •

edited

Loading