New option for specific logfile #233

palto42 · 2019-10-31T09:58:24Z

palto42 commented

2019-10-31 09:58:24 +00:00

Instead of logging to console/stdout or syslog I wanted to write the log to a specific file.

For this purpose I added an option --log-file which accepts a /path/filename string.

If this option is specified, it disables the logging to console and syslog. It also uses a specific logging format, assuming that the logfile is dedicated for borgmatic.

Instead of logging to console/stdout or syslog I wanted to write the log to a specific file. For this purpose I added an option `--log-file` which accepts a /path/filename string. If this option is specified, it disables the logging to console and syslog. It also uses a specific logging format, assuming that the logfile is dedicated for borgmatic.

witten commented

2019-10-31 16:52:31 +00:00

Thank you for submitting this! This sounds like a great addition. A few of questions/comments:

Could you talk a little more about your motivation behind this feature? Is it that syslog just isn't meeting your needs? Don't want your borgmatic output mixed in with other logs? Something else? And what's your thinking behind the suppression of the console logging? I want to make sure I capture the reasoning in the documentation, and also so that I make sure I understand the choices here!
When a log file is given, instead of suppressing/replacing console output entirely, what do you think of leaving the console and syslog handlers in place and adding a separate log file handler that doesn't affect the other handlers? And maybe supporting an independent log level just for the log file handler, as is done for syslog? My reasoning here is that a user may want to vary the log file log level independent of the console log level, and it seems more consistent with the existing console and syslog handler (which have independent log levels).
Would it be possible to write a test for the new parameter? You can check out the existing test_configure_logging_*() tests for examples.
Feel free to add yourself to the AUTHORS file if you like!

Thank you for submitting this! This sounds like a great addition. A few of questions/comments: * Could you talk a little more about your motivation behind this feature? Is it that syslog just isn't meeting your needs? Don't want your borgmatic output mixed in with other logs? Something else? And what's your thinking behind the suppression of the console logging? I want to make sure I capture the reasoning in the documentation, and also so that I make sure I understand the choices here! * When a log file is given, instead of suppressing/replacing console output entirely, what do you think of leaving the console and syslog handlers in place and adding a separate log file handler that doesn't affect the other handlers? And maybe supporting an independent log level just for the log file handler, as is done for syslog? My reasoning here is that a user may want to vary the log file log level independent of the console log level, and it seems more consistent with the existing console and syslog handler (which have independent log levels). * Would it be possible to write a test for the new parameter? You can check out the existing `test_configure_logging_*()` tests for examples. * Feel free to add yourself to the AUTHORS file if you like!

palto42 commented

2019-10-31 17:38:03 +00:00

My motivation for this new feature is to have a dedicated log file for the backups and don't mix it with syslog messages. For other non-system services there are typically also separate log file (e.g. Nginx, MariaDB).

If I specify a dedicated log file, I have no need for console of syslog output and want to avoid duplication. If a backup job with specified logfile is running, I can always follow the output with a tail -f /path/to/logfile if needed. In my view it would add unnecessary complexity to keep all 3 log options in parallel, but this is just my personal view/use case.

I can see some benefit to keep the console output in case of an interactive session (if users don't want to use tail). For concurrent syslog and logfile I don't see a real use case, but maybe I'm missing one.

What's not clear to me is the reason for keeping the console handler in case of a non-interactive session. If I run borgmatic from cron or systemd, then I usually don't want to send anything to stdout. As I was trying bormatic on the console, I even struggled a with output redirection via >file 2>&1 where borgmatic still sent all messages to the console instead of the redircet file.

Will have a look at the code for a feature test later (after we agreed on the feature details).

My motivation for this new feature is to have a dedicated log file for the backups and don't mix it with syslog messages. For other non-system services there are typically also separate log file (e.g. Nginx, MariaDB). If I specify a dedicated log file, I have no need for console of syslog output and want to avoid duplication. If a backup job with specified logfile is running, I can always follow the output with a `tail -f /path/to/logfile` if needed. In my view it would add unnecessary complexity to keep all 3 log options in parallel, but this is just my personal view/use case. I can see some benefit to keep the console output in case of an interactive session (if users don't want to use `tail`). For concurrent syslog and logfile I don't see a real use case, but maybe I'm missing one. What's not clear to me is the reason for keeping the console handler in case of a non-interactive session. If I run borgmatic from cron or systemd, then I usually don't want to send anything to stdout. As I was trying bormatic on the console, I even struggled a with output redirection via `>file 2>&1` where borgmatic still sent all messages to the console instead of the redircet file. Will have a look at the code for a feature test later (after we agreed on the feature details).

witten commented

2019-10-31 18:05:05 +00:00

My motivation for this new feature is to have a dedicated log file for the backups and don’t mix it with syslog messages. For other non-system services there are typically also separate log file (e.g. Nginx, MariaDB).

Got it, thanks. That makes sense. I'm guessing that a filtered syslog view isn't sufficient for that? E.g., with systemd, something like journalctl -xe --unit borgmatic?

If I specify a dedicated log file, I have no need for console of syslog output and want to avoid duplication. If a backup job with specified logfile is running, I can always follow the output with a tail -f /path/to/logfile if needed. In my view it would add unnecessary complexity to keep all 3 log options in parallel, but this is just my personal view/use case.

I can see some benefit to keep the console output in case of an interactive session (if users don’t want to use tail). For concurrent syslog and logfile I don’t see a real use case, but maybe I’m missing one.

What’s not clear to me is the reason for keeping the console handler in case of a non-interactive session. If I run borgmatic from cron or systemd, then I usually don’t want to send anything to stdout.

The main use case I can see for console output for a non-interactive session (with or without logs also going to a file) is to see error messages from a cron/systemd job. For instance, even with console --verbosity 0 (the default), you'll get console error messages directly in your inbox if you're running it with cron. Seems like a pretty common use case, especially for those users who aren't using some of the fancier monitoring options.

Here are a few ways I can think of to reduce the complexity a bit of having all three log options:

Instead of making the log file handler replace the console output, make it replace the syslog handler. That way, a user can still get cron-based error emails while logging to file. And most users won't want to log to both file and syslog simultaneously.
And/or, make syslog and log file output use the same verbosity level. (Although maybe renamed to not just apply to syslog.) That way you don't have to add yet a third log level.

As I was trying bormatic on the console, I even struggled a with output redirection via >file 2>&1 where borgmatic still sent all messages to the console instead of the redircet file.

Yeah, shell redirection is kind of obnoxious especially once stderr is added to the mix.

Will have a look at the code for a feature test later (after we agreed on the feature details).

Cool!

> My motivation for this new feature is to have a dedicated log file for the backups and don’t mix it with syslog messages. For other non-system services there are typically also separate log file (e.g. Nginx, MariaDB). Got it, thanks. That makes sense. I'm guessing that a filtered syslog view isn't sufficient for that? E.g., with systemd, something like `journalctl -xe --unit borgmatic`? > If I specify a dedicated log file, I have no need for console of syslog output and want to avoid duplication. If a backup job with specified logfile is running, I can always follow the output with a tail -f /path/to/logfile if needed. In my view it would add unnecessary complexity to keep all 3 log options in parallel, but this is just my personal view/use case. > I can see some benefit to keep the console output in case of an interactive session (if users don’t want to use tail). For concurrent syslog and logfile I don’t see a real use case, but maybe I’m missing one. > What’s not clear to me is the reason for keeping the console handler in case of a non-interactive session. If I run borgmatic from cron or systemd, then I usually don’t want to send anything to stdout. The main use case I can see for console output for a non-interactive session (with or without logs also going to a file) is to see error messages from a cron/systemd job. For instance, even with console `--verbosity 0` (the default), you'll get console error messages directly in your inbox if you're running it with cron. Seems like a pretty common use case, especially for those users who aren't using some of the fancier monitoring options. Here are a few ways I can think of to reduce the complexity a bit of having all three log options: * Instead of making the log file handler replace the console output, make it replace the syslog handler. That way, a user can still get cron-based error emails while logging to file. And most users won't want to log to both file and syslog simultaneously. * And/or, make syslog and log file output use the same verbosity level. (Although maybe renamed to not just apply to syslog.) That way you don't have to add yet a third log level. > As I was trying bormatic on the console, I even struggled a with output redirection via >file 2>&1 where borgmatic still sent all messages to the console instead of the redircet file. Yeah, shell redirection is kind of obnoxious especially once stderr is added to the mix. > Will have a look at the code for a feature test later (after we agreed on the feature details). Cool!

palto42 commented

2019-10-31 18:55:13 +00:00

Agree with your proposal to replace the syslog handler instead of console handler. But if a logfile is specified, it should also be used in an interactive session.

Thanks for explaining the rationale to keep the console handler for non-interactive session. Need some more testing to see if I still want to disable it in cron (or higher level like ERROR or CRITICAL).

On more question on the syslog-verbosity:

In which case will the condition if syslog_log_level is None:be true?
- In arguments.py it has a default value of 0, no it should never be None as far as I can see.

Agree with your proposal to replace the syslog handler instead of console handler. But if a logfile is specified, it should also be used in an interactive session. Thanks for explaining the rationale to keep the console handler for non-interactive session. Need some more testing to see if I still want to disable it in cron (or higher level like ERROR or CRITICAL). On more question on the syslog-verbosity: * In which case will the condition `if syslog_log_level is None:`be true? * In arguments.py it has a default value of 0, no it should never be None as far as I can see.

witten commented

2019-10-31 20:44:31 +00:00

Agree with your proposal to replace the syslog handler instead of console handler. But if a logfile is specified, it should also be used in an interactive session.

Yup, that makes sense to me.

In which case will the condition if syslog_log_level is None: be true?

syslog_log_level can be None when configure_logging() is called during an early error condition. For instance, look for configure_logging(logging.CRITICAL) in borgmatic/commands/borgmatic.py. The rationale is that something has gone wrong even before the arguments have been successfully parsed, and we want to quickly configure logging so we can explode loudly (in a nice way).

In arguments.py it has a default value of 0, no it should never be None as far as I can see.

For a normal situation when arguments are parsed successfully, that is correct. It'll only be None if something went wrong parsing arguments.

> Agree with your proposal to replace the syslog handler instead of console handler. But if a logfile is specified, it should also be used in an interactive session. Yup, that makes sense to me. > * In which case will the condition if `syslog_log_level is None:` be true? `syslog_log_level` can be `None` when `configure_logging()` is called during an early error condition. For instance, look for `configure_logging(logging.CRITICAL)` in `borgmatic/commands/borgmatic.py`. The rationale is that something has gone wrong even before the arguments have been successfully parsed, and we want to quickly configure logging so we can explode loudly (in a nice way). > * In arguments.py it has a default value of 0, no it should never be None as far as I can see. For a normal situation when arguments are parsed successfully, that is correct. It'll only be `None` if something went wrong parsing arguments.

witten commented

2019-10-31 21:20:47 +00:00

Oh, one more question: For your uses, do you think this log file value makes more sense as a command-line flag or a configuration file option? It occurred to me that you might not want to type it every time.

palto42 commented

2019-11-01 18:04:38 +00:00

I updated the logger.py code so that the file-logger replaces the syslog handler and not the console output. I intend to look into some test code the next days.

The command line flag is sufficient for my use case, just one more flag in addition to the verbosity.

Another topic I might evaluate is some "tuning" of the log output. With verbosity 0 I get nothing (except errors) and with verbosity 1 I get a bit too much detail (e.g. all individual files). What I would like to see in my log is just some basic info like tasks executed (prune, create, checks).

I updated the `logger.py` code so that the file-logger replaces the syslog handler and not the console output. I intend to look into some test code the next days. The command line flag is sufficient for my use case, just one more flag in addition to the verbosity. Another topic I might evaluate is some "tuning" of the log output. With verbosity 0 I get nothing (except errors) and with verbosity 1 I get a bit too much detail (e.g. all individual files). What I would like to see in my log is just some basic info like tasks executed (prune, create, checks).

witten commented

2019-11-01 18:41:24 +00:00

Code changes look good. Thank you!

Another topic I might evaluate is some “tuning” of the log output. With verbosity 0 I get nothing (except errors) and with verbosity 1 I get a bit too much detail (e.g. all individual files). What I would like to see in my log is just some basic info like tasks executed (prune, create, checks).

This may not be quite what you're looking for, but the --stats flag with the default borgmatic verbosity of 0 will give you some basic summary information, without all the individual files play-by-play.

Code changes look good. Thank you! > Another topic I might evaluate is some “tuning” of the log output. With verbosity 0 I get nothing (except errors) and with verbosity 1 I get a bit too much detail (e.g. all individual files). What I would like to see in my log is just some basic info like tasks executed (prune, create, checks). This may not be quite what you're looking for, but the `--stats` flag with the default borgmatic verbosity of 0 will give you some basic summary information, without all the individual files play-by-play.

palto42 commented

2019-11-01 19:53:04 +00:00

Thanks for your hint with the --stats option. Main issue with this approach is that it will send the stats to both syslog and console so that it would cause an email with cron. But I will look into this topic separately from this PR.

Thanks for your hint with the `--stats` option. Main issue with this approach is that it will send the stats to both syslog and console so that it would cause an email with cron. But I will look into this topic separately from this PR.

palto42 commented

2019-11-02 13:45:27 +00:00

I added some exception handling for the logfile handler and 2 test cases.

Test that no syslog handler is created if --log-file provided
Test the no file handler is created if --log-file is None

Should I add any additional test cases?

I added some exception handling for the logfile handler and 2 test cases. * Test that no syslog handler is created if --log-file provided * Test the no file handler is created if --log-file is None Should I add any additional test cases?

witten commented

2019-11-02 17:42:45 +00:00

Looks great! Thank you for adding tests.

witten referenced this issue from a commit

2019-11-02 17:43:40 +00:00

Log to file instead of syslog via command-line "--log-file" flag (#233).

witten closed this pull request

2019-11-02 17:43:40 +00:00

witten closed this pull request

2019-11-02 17:43:40 +00:00

witten commented

2019-11-02 18:26:32 +00:00

One thing I did is move the error handling (path not found, permissions) up a level to the calling function. That way it's a little more consistent with some of the other types of errors that can occur.

I also added a separate --log-file-verbosity to reduce confusion.. Setting --syslog-verbosity to influence a non-syslog log file might be a little counter-intuitive!

Anyway, I just released this as part of borgmatic 1.4.5. Thanks again!

One thing I did is move the error handling (path not found, permissions) up a level to the calling function. That way it's a little more consistent with some of the other types of errors that can occur. I also added a separate `--log-file-verbosity` to reduce confusion.. Setting `--syslog-verbosity` to influence a non-syslog log file might be a little counter-intuitive! Anyway, I just released this as part of borgmatic 1.4.5. Thanks again!

witten commented

2019-11-02 19:54:33 +00:00

Oh, and docs here: https://torsion.org/borgmatic/docs/how-to/inspect-your-backups/#logging

👍 1

palto42 referenced this pull request

2019-12-22 09:20:20 +00:00

New command option to log information about executed task at verbosity 0 #272

Sign in to join this conversation.

No reviewers