Add logging #53
Labels
No Label
bug
data loss
design finalized
good first issue
new feature area
question / support
security
waiting for response
No Milestone
No Assignees
5 Participants
Notifications
Due Date
No due date set.
Dependencies
No dependencies set.
Reference: borgmatic-collective/borgmatic#53
Loading…
Reference in New Issue
No description provided.
Delete Branch "%!s(<nil>)"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
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
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:
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 ?
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
orDEBUG
or make it configurable) and set up a Python log handler to just log all of the existinglogger.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 caughtsubprocess.CalledProcessError
instance, specifically thereturncode
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.
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:
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
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.
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
Sounds good!
Yes, interested in this! I'm doing this for now ...
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:
And then in another shell
So a couple of questions:
--verbosity
flag for stdout only.Nice 🔥 I am not sure about the first questions but ...
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#: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.And I think you're right about the "log to file" question. Thanks for weighing in on that.
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.
Done and merged to master. This'll go out as part of the next release. (Hopefully soon.)
Nice!
Thanks!
Where can I find the documentation?
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
Thanks!
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.
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
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 justgrep 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.
Hello,
Thanks for the hints.
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
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.
I generally use my backup provider's built-in activity monitoring until someone gets around to actually implementing witten/borgmatic#126. 😄
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.
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 aWARNING
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:
Can the output be made monochronous?
Is it possible to configure the syslog facility used?
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 didborgmatic --list
and saw no output because you're implicitly at--verbosity 0
.Good catch! Yes, I'll fix this. I filed witten/borgmatic#197 to track it. Please follow along there.
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.
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!
Hello,
as I am my own backup provider...
What would you advise me?
Regards,
Hendrik
A couple of different ideas:
borgmatic --list
periodically (say, once a week) and email you the results to check on.Hello,
Greetings,
Hendrik