Add logging #53

Closed
opened 2018-01-14 09:37:54 +00:00 by henfri · 29 comments

From my perspective, a significant weakness of borg is, that no logging is done. This must be handled by the wrapper scripts.
As borgmatic is one of them, I write here :-)

As far as I see, borgmatic is also not writing logs. I would suggest two logs:
One that logs each run of borgmatic and shows top level information (one line!):
Date, Success, Folder, Size, Transferred Data

And another (!) logfile per run of borgmatic that holds all information that borg threw on the stdout and stderr.

What is your view on this?

Greetings,

Hendrik

From my perspective, a significant weakness of borg is, that no logging is done. This must be handled by the wrapper scripts. As borgmatic is one of them, I write here :-) As far as I see, borgmatic is also not writing logs. I would suggest two logs: One that logs each run of borgmatic and shows top level information (one line!): Date, Success, Folder, Size, Transferred Data And another (!) logfile per run of borgmatic that holds all information that borg threw on the stdout and stderr. What is your view on this? Greetings, Hendrik
Owner

Something like this seems pretty useful, yes. You can simulate it now by redirecting borgmatic -v 2 output to your own log file. That's not as good as real logging, but it's a start.

Something like this seems pretty useful, yes. You can simulate it now by redirecting `borgmatic -v 2` output to your own log file. That's not as good as real logging, but it's a start.

Hello,

I'm trying to implement logging but I'm not sure how to do it properly.

For now, I'm just writing json ouput to files:

  • --create output goes to a new file every run (to get history of backups created)
  • --info / --list output overwrite a file every run (to get the current state of the repo)

I think the most relevant information we can use is the return code of each command (and the attached error if any)

However, I can't find a way to catch return codes or this kind of error: Repository /tmp/borg002 does not exist.

What do you think ? Do you have any ideas of how we could properly handle logging ?

Hello, I'm trying to implement logging but I'm not sure how to do it properly. For now, I'm just writing json ouput to files: - --create output goes to a new file every run (to get history of backups created) - --info / --list output overwrite a file every run (to get the current state of the repo) I think the most relevant information we can use is the return code of each command (and the attached error if any) However, I can't find a way to catch return codes or this kind of error: `Repository /tmp/borg002 does not exist.` What do you think ? Do you have any ideas of how we could properly handle logging ?
Owner

While I haven't spend much time looking into it, my first thought was to use something like the Python syslog module to add support for (optional) logging to syslog. That way, we don't have to build all of our own support for: multiple-file logging, log rotation, log levels, etc. We can just log everything to syslog and let decades of Unix technology handle the rest.

In terms of what to log, my inclination is: Everything. Pick a log level (such as INFO or DEBUG or make it configurable) and set up a Python log handler to just log all of the existing logger.whatever() messages to syslog. This would include the return code of each command and any errors. The benefit of using the existing Python logging system is that we don't have to log twice for each of: file logging, and standard out/error logging. We just log once and let the configured log handlers send everything to the right places.

One way to catch return codes would be to use the existing subprocess.check_call() or the new Python 3.5+ subprocess.run(check=True, ...) and catch any exception, pulling the exit code off of the caught subprocess.CalledProcessError instance, specifically the returncode attribute.

I could also see in the future supporting other logging backends beside just syslog. But let's not get ahead of ourselves.

Lastly, you should be aware of some related efforts that may affect logging: #94 and #100. Hope this helps. Let me know if you have any other questions.

While I haven't spend much time looking into it, my first thought was to use something like the Python [syslog module](https://docs.python.org/3/library/syslog.html) to add support for (optional) logging to syslog. That way, we don't have to build all of our own support for: multiple-file logging, log rotation, log levels, etc. We can just log everything to syslog and let decades of Unix technology handle the rest. In terms of what to log, my inclination is: Everything. Pick a log level (such as `INFO` or `DEBUG` or make it configurable) and set up a Python log handler to just log all of the existing `logger.whatever()` messages to syslog. This would include the return code of each command *and* any errors. The benefit of using the existing Python logging system is that we don't have to log twice for each of: file logging, and standard out/error logging. We just log once and let the configured log handlers send everything to the right places. One way to catch return codes would be to use the existing `subprocess.check_call()` or the new Python 3.5+ `subprocess.run(check=True, ...)` and catch any exception, pulling the exit code off of the caught [`subprocess.CalledProcessError`](https://docs.python.org/3/library/subprocess.html#subprocess.CalledProcessError) instance, specifically the `returncode` attribute. I could also see in the future supporting other logging backends beside just syslog. But let's not get ahead of ourselves. Lastly, you should be aware of some related efforts that may affect logging: #94 and #100. Hope this helps. Let me know if you have any other questions.
Author

Hello,

I understand your thoughts.
The problem I see is:
Would you see that borgmatic has thrown an error at each backup during the last four weeks if it is hidden in hunderts of other lines of messages.

I suggest to use https://docs.python.org/3/library/logging.handlers.html#module-logging.handlers

The idea here is, that you use the python module 'logger' (as implemented already) and then you or the user can later decide whether to log to a file or to syslog by chosing the handler.

But what I really need is a simple piece of information:

  1. When was the last successful backup
  2. How many unsuccessful backups did I have since then

And this, I need for each target in one always up to date file.
This is not 'logging' but more a 'cockpit' if you like.
Use this for Inspiration https://i1.wp.com/www.accuratereviews.com/wordpress/wp-content/uploads/2015/09/crashplan.jpg
(I am not asking for a GUI. Just look for the content)

Regards,
Hendrik

Hello, I understand your thoughts. The problem I see is: Would you see that borgmatic has thrown an error at each backup during the last four weeks if it is hidden in hunderts of other lines of messages. I suggest to use https://docs.python.org/3/library/logging.handlers.html#module-logging.handlers The idea here is, that you use the python module 'logger' (as implemented already) and then you or the user can later decide whether to log to a file or to syslog by chosing the handler. But what I really need is a simple piece of information: 1) When was the last successful backup 2) How many unsuccessful backups did I have since then And this, I need for each target in one always up to date file. This is not 'logging' but more a 'cockpit' if you like. Use this for Inspiration https://i1.wp.com/www.accuratereviews.com/wordpress/wp-content/uploads/2015/09/crashplan.jpg (I am not asking for a GUI. Just look for the content) Regards, Hendrik
Owner

Maybe the "last successful backup" part you're looking for is what this ticket talks about? witten/borgmatic#86

Do you think if that ticket was expanded to also include "how many unsuccessful backups did I have since then", then your "cockpit" needs would be met?

I'm not trying to get out of adding real logging support to borgmatic. I'm just wondering if a more targeted feature (e.g., that linked ticket) would get closer to what you're looking for.

Maybe the "last successful backup" part you're looking for is what this ticket talks about? https://projects.torsion.org/witten/borgmatic/issues/86 Do you think if that ticket was expanded to also include "how many unsuccessful backups did I have since then", then your "cockpit" needs would be met? I'm not trying to get out of adding real logging support to borgmatic. I'm just wondering if a more targeted feature (e.g., that linked ticket) would get closer to what you're looking for.
Author

Hello,

yes, that comes close to what I have in mind and I am happy with splitting the issue here (#52) to the pure logging and continuing the discussion on the cockpit in #86 or in a new issue.

Regards,
Hendrik

Hello, yes, that comes close to what I have in mind and I am happy with splitting the issue here (#52) to the pure logging and continuing the discussion on the cockpit in #86 or in a new issue. Regards, Hendrik
Owner

Sounds good!

Sounds good!
Contributor

Yes, interested in this! I'm doing this for now ...

borgmatic -v 2 -c /etc/borgmatic.d/hostname 2>&1 | tee /var/log/borgmatic/hostname.log

Yes, interested in this! I'm doing this for now ... > borgmatic -v 2 -c /etc/borgmatic.d/hostname 2>&1 | tee /var/log/borgmatic/hostname.log
Owner

Started this work in a branch. (See link above.) Seems to be working, with the exception of actual Borg output (because we don't capture that). Example on a systemd machine:

# borgmatic --list -v 2

And then in another shell

# journalctl -f
May 26 16:32:45 flux borgmatic[17161]: DEBUG Ensuring legacy configuration is upgraded
May 26 16:32:45 flux borgmatic[17161]: INFO /etc/borgmatic/config.yaml: Parsing configuration file
May 26 16:32:45 flux borgmatic[17161]: INFO example.borg: Listing archives
May 26 16:32:45 flux borgmatic[17161]: DEBUG borg list example.borg --remote-path borg1 --debug --show-rc
...

So a couple of questions:

  • Should this just be enabled by default? E.g. without a config option or command-line flag to turn it on?
  • Is it okay that the verbosity level set on the command-line would affect both stdout and syslog logs, with no way to vary them? Alternatively, one idea would be just to always log DEBUG to syslog, and save the --verbosity flag for stdout only.
  • This new feature is log-to-syslog only, not log-to-file. That okay?
Started this work in a branch. (See link above.) Seems to be working, with the exception of actual Borg output (because we don't capture that). Example on a systemd machine: ```bash # borgmatic --list -v 2 ``` And then in another shell ```bash # journalctl -f May 26 16:32:45 flux borgmatic[17161]: DEBUG Ensuring legacy configuration is upgraded May 26 16:32:45 flux borgmatic[17161]: INFO /etc/borgmatic/config.yaml: Parsing configuration file May 26 16:32:45 flux borgmatic[17161]: INFO example.borg: Listing archives May 26 16:32:45 flux borgmatic[17161]: DEBUG borg list example.borg --remote-path borg1 --debug --show-rc ... ``` So a couple of questions: * Should this just be enabled by default? E.g. without a config option or command-line flag to turn it on? * Is it okay that the verbosity level set on the command-line would affect both stdout and syslog logs, with no way to vary them? Alternatively, one idea would be just to always log DEBUG to syslog, and save the `--verbosity` flag for stdout only. * This new feature is log-to-syslog only, not log-to-file. That okay?
Contributor

Nice 🔥 I am not sure about the first questions but ...

This new feature is log-to-syslog only, not log-to-file. That okay?

I think this is totally fine. For my purposes, I want a place where I can look up the logs. If journalctl is retaining them, then that is fine, no? For reference, https://www.freedesktop.org/software/systemd/man/systemd-journald.service.html#:

The journal service stores log data either persistently below /var/log/journal or in a volatile way below /run/log/journal/ (in the latter case it is lost at reboot). By default, log data is stored persistently if /var/log/journal/ exists during boot, with an implicit fallback to volatile storage otherwise. Use Storage= in journald.conf(5) to configure where log data is placed, independently of the existence of /var/log/journal/.

Nice :fire: I am not sure about the first questions but ... > This new feature is log-to-syslog only, not log-to-file. That okay? I think this is totally fine. For my purposes, I want a place where I can look up the logs. If `journalctl` is retaining them, then that is fine, no? For reference, https://www.freedesktop.org/software/systemd/man/systemd-journald.service.html#: > The journal service stores log data either persistently below /var/log/journal or in a volatile way below /run/log/journal/ (in the latter case it is lost at reboot). By default, log data is stored persistently if /var/log/journal/ exists during boot, with an implicit fallback to volatile storage otherwise. Use Storage= in journald.conf(5) to configure where log data is placed, independently of the existence of /var/log/journal/.
Owner

Is it okay that the verbosity level set on the command-line would affect both stdout and syslog logs, with no way to vary them?

Well, I thought about this some more, and I think it would be super obnoxious to have these respective log levels coupled. Typically you would always want syslog log level as DEBUG or thereabouts, which would mean your console log level would have to be DEBUG too. And that would be inconvenient because you'd have to redirect it to /dev/null or something in order to use borgmatic in a cron job.

So I made the log levels decoupled and added a --syslog-verbosity flag separate from the existing --verbosity one. A couple of immediate implications of this is that: 1. Borg's own verbosity can only be driven off of one of them, and 2. Borg's output still only goes to the console, not syslog. But if we naively try to capture Borg's output in order to log it so it goes to both console and syslog, we'd be giving up "real-time" Borg output to the console. Ugh.

> Is it okay that the verbosity level set on the command-line would affect both stdout and syslog logs, with no way to vary them? Well, I thought about this some more, and I think it would be super obnoxious to have these respective log levels coupled. Typically you would always want syslog log level as DEBUG or thereabouts, which would mean your console log level would have to be DEBUG too. And that would be inconvenient because you'd have to redirect it to /dev/null or something in order to use borgmatic in a cron job. So I made the log levels decoupled and added a `--syslog-verbosity` flag separate from the existing `--verbosity` one. A couple of immediate implications of this is that: 1. Borg's own verbosity can only be driven off of one of them, and 2. Borg's output still only goes to the console, not syslog. But if we naively try to capture Borg's output in order to log it so it goes to both console and syslog, we'd be giving up "real-time" Borg output to the console. Ugh.
Owner

And I think you're right about the "log to file" question. Thanks for weighing in on that.

And I think you're right about the "log to file" question. Thanks for weighing in on that.
Owner

So some progress here. I've figured out how to capture Borg output and stream it real-time into the Python logging system. That way, Borg's output goes both to the console and syslog without any delay. There's still potentially the limitation that Borg's own verbosity can only be driven off one log level at a time. But I think a solution to that is to execute Borg with the maximum log level that borgmatic is currently using across both console and syslog. Sort of a compromise.

Anyway, I've implemented this and written up some basic docs (pushed), and the work that remains is to add some additional automated test coverage.

So some progress here. I've figured out how to capture Borg output and *stream* it real-time into the Python logging system. That way, Borg's output goes both to the console and syslog without any delay. There's still potentially the limitation that Borg's own verbosity can only be driven off one log level at a time. But I think a solution to that is to execute Borg with the *maximum* log level that borgmatic is currently using across both console and syslog. Sort of a compromise. Anyway, I've implemented this and written up some basic docs (pushed), and the work that remains is to add some additional automated test coverage.
Owner

Done and merged to master. This'll go out as part of the next release. (Hopefully soon.)

Done and merged to master. This'll go out as part of the next release. (Hopefully soon.)
Author

Nice!
Thanks!

Where can I find the documentation?

Nice! Thanks! Where can I find the documentation?
Owner
Right now, it's here in source: https://projects.torsion.org/witten/borgmatic/src/branch/master/docs/how-to/inspect-your-backups.md#logging When it's released, it'll be here: https://torsion.org/borgmatic/docs/how-to/inspect-your-backups/#logging
Author

Thanks!

Thanks!
Owner

Just released as part of borgmatic 1.3.6. Enjoy! And please let me know if you have any feedback on the feature or problems with it.. I made a lot of assumptions in implementing it, and it also required a fair amount of refactoring.

Just released as part of borgmatic 1.3.6. Enjoy! And please let me know if you have any feedback on the feature or problems with it.. I made a lot of assumptions in implementing it, and it also required a fair amount of refactoring.
Author

Hello,

if I understand correctly, the logging goes to syslog only, right?
There, it's hidden in a lot of other -unimportant- stuff.
Do you have a recommendation how to filter the borg related stuff out of the syslog into an own file with linux tools?

Greetings,
Hendrik

Hello, if I understand correctly, the logging goes to syslog only, right? There, it's hidden in a lot of other -unimportant- stuff. Do you have a recommendation how to filter the borg related stuff out of the syslog into an own file with linux tools? Greetings, Hendrik
Owner

It only goes to the local syslog-compatible daemon, yes. If that's systemd's journal, then you can do something like journalctl -xe -t borgmatic and redirect that to a file. If you're instead using something like rsyslog, you can just grep borgmatic /var/log/syslog.

Could you say more about your use case with having the borgmatic logs in its own file? How do you intend to consume it from there? Thanks.

It only goes to the local syslog-compatible daemon, yes. If that's systemd's journal, then you can do something like `journalctl -xe -t borgmatic` and redirect that to a file. If you're instead using something like rsyslog, you can just `grep borgmatic /var/log/syslog`. Could you say more about your use case with having the borgmatic logs in its own file? How do you intend to consume it from there? Thanks.
Author

Hello,

Thanks for the hints.

Could you say more about your use case with having the
borgmatic logs in its own file? How do you intend to consume
it from there? Thanks.

Let me answer with a question:
How do you keep an eye on the health of your backups? How do you get aware of problems?

Do you actually browse the syslog every day?

In fact I am doing that with the help of 'logcheck', which filters the syslog for 'abnormal' situations. But there is still a lot of rubbish in it.

I would like to have a borgmatic-warning.log and a borgmatic-error.log that I could look at once a week for example.

Greetings,
Hendrik

Hello, Thanks for the hints. > Could you say more about your use case with having the > borgmatic logs in its own file? How do you intend to consume > it from there? Thanks. Let me answer with a question: How do you keep an eye on the health of your backups? How do you get aware of problems? Do you actually browse the syslog every day? In fact I am doing that with the help of 'logcheck', which filters the syslog for 'abnormal' situations. But there is still a lot of rubbish in it. I would like to have a borgmatic-warning.log and a borgmatic-error.log that I could look at once a week for example. Greetings, Hendrik
Author

Another remark:

borgmatic --syslog-verbosity 0

Would it make sense to allow 'Info', 'Debug', ... etc here?

And I suggest to set the defaul level not too verbose. Currently borg is flooding the syslog with INFO level messages.

Another remark: borgmatic --syslog-verbosity 0 Would it make sense to allow 'Info', 'Debug', ... etc here? And I suggest to set the defaul level not too verbose. Currently borg is flooding the syslog with INFO level messages.
Owner

Let me answer with a question: How do you keep an eye on the health of your backups? How do you get aware of problems?

I generally use my backup provider's built-in activity monitoring until someone gets around to actually implementing witten/borgmatic#126. 😄

Would it make sense to allow ‘Info’, ‘Debug’, … etc here?

Perhaps as an alias/convenience, although my rationale for not using those as the main values was that users shouldn't have to be aware of Python log levels.

And I suggest to set the defaul level not too verbose. Currently borg is flooding the syslog with INFO level messages.

Okay, I can certainly change the default syslog verbosity to 0 instead 1.

Thanks for the feedback.

> Let me answer with a question: How do you keep an eye on the health of your backups? How do you get aware of problems? I generally use my backup provider's built-in activity monitoring until someone gets around to actually implementing https://projects.torsion.org/witten/borgmatic/issues/126. :smile: > Would it make sense to allow ‘Info’, ‘Debug’, … etc here? Perhaps as an alias/convenience, although my rationale for not using those as the main values was that users shouldn't have to be aware of Python log levels. > And I suggest to set the defaul level not too verbose. Currently borg is flooding the syslog with INFO level messages. Okay, I can certainly change the default syslog verbosity to 0 instead 1. Thanks for the feedback.

Great addition! I have a few questions:

For some reason borgmatic -l produces a WARNING line in the syslog for each backup listed, maybe because it was yellow in the console?

Unfortunately, all the color codes are also logged to syslog, which messes up the strings with unicode control characters. Example:

Jun 17 10:49:16 netcup-optane borgmatic: CRITICAL #033[31m#033[31mError parsing arguments: /opt/pipenvs/borgmatic/.venv/bin/borgmatic list#033[0m#033[0m

Can the output be made monochronous?

Is it possible to configure the syslog facility used?

Great addition! I have a few questions: For some reason `borgmatic -l` produces a `WARNING` line in the syslog for each backup listed, maybe because it was yellow in the console? Unfortunately, all the color codes are also logged to syslog, which messes up the strings with unicode control characters. Example: ``` Jun 17 10:49:16 netcup-optane borgmatic: CRITICAL #033[31m#033[31mError parsing arguments: /opt/pipenvs/borgmatic/.venv/bin/borgmatic list#033[0m#033[0m ``` Can the output be made monochronous? Is it possible to configure the syslog facility used?
Owner

For some reason borgmatic -l produces a WARNING line in the syslog for each backup listed, maybe because it was yellow in the console?

That's correct. It's kind of a hack.. It's logged as WARNING so that it shows up regardless of --verbosity level. Because it would be weird if you did borgmatic --list and saw no output because you're implicitly at --verbosity 0.

Can the output be made monochronous?

Good catch! Yes, I'll fix this. I filed witten/borgmatic#197 to track it. Please follow along there.

Is it possible to configure the syslog facility used?

Not yet. Please feel free to file a ticket for this though with a little info on what you'd like to use this for, any ideas on how you'd like to set it, etc.

Thanks for the feedback.

> For some reason borgmatic -l produces a WARNING line in the syslog for each backup listed, maybe because it was yellow in the console? That's correct. It's kind of a hack.. It's logged as WARNING so that it shows up regardless of `--verbosity` level. Because it would be weird if you did `borgmatic --list` and saw no output because you're implicitly at `--verbosity 0`. > Can the output be made monochronous? Good catch! Yes, I'll fix this. I filed https://projects.torsion.org/witten/borgmatic/issues/197 to track it. Please follow along there. > Is it possible to configure the syslog facility used? Not yet. Please feel free to file a ticket for this though with a little info on what you'd like to use this for, any ideas on how you'd like to set it, etc. Thanks for the feedback.
Owner

Would it make sense to allow ‘Info’, ‘Debug’, … etc here?

Perhaps as an alias/convenience, although my rationale for not using those as the main values was that users shouldn’t have to be aware of Python log levels.

BTW, I decided not to do this for now, since the levels don't correspond 100% with "error", "info", "debug" in Python. But if you feel strongly about this, please feel free to open a separate ticket and we can discuss further!

>> Would it make sense to allow ‘Info’, ‘Debug’, … etc here? > Perhaps as an alias/convenience, although my rationale for not using those as the main values was that users shouldn’t have to be aware of Python log levels. BTW, I decided not to do this for now, since the levels don't correspond 100% with "error", "info", "debug" in Python. But if you feel strongly about this, please feel free to open a separate ticket and we can discuss further!
Author

Hello,

as I am my own backup provider...

How do you keep an eye on the health of your backups? How do you get aware of problems?

What would you advise me?

Regards,
Hendrik

Hello, as I am my own backup provider... > How do you keep an eye on the health of your backups? How do you get aware of problems? What would you advise me? Regards, Hendrik
Owner

A couple of different ideas:

  1. Make sure cron job errors go to your email, so at least you'll see if anything blows up. This of course won't tell you if the cron job just isn't firing at all.
  2. Set up a separate cron job to run borgmatic --list periodically (say, once a week) and email you the results to check on.
  3. Convince someone to implement witten/borgmatic#126 😄
A couple of different ideas: 1. Make sure cron job errors go to your email, so at least you'll see if anything blows up. This of course won't tell you if the cron job just isn't firing at all. 2. Set up a separate cron job to run `borgmatic --list` periodically (say, once a week) and email you the results to check on. 3. Convince someone to implement https://projects.torsion.org/witten/borgmatic/issues/126 :smile:
Author

Hello,

  1. I had already
  2. Added, thanks for the hint.
  3. beg

Greetings,
Hendrik

Hello, 1) I had already 2) Added, thanks for the hint. 3) *beg* Greetings, Hendrik
Sign in to join this conversation.
No Milestone
No Assignees
5 Participants
Notifications
Due Date
The due date is invalid or out of range. Please use the format 'yyyy-mm-dd'.

No due date set.

Dependencies

No dependencies set.

Reference: borgmatic-collective/borgmatic#53
No description provided.