syslog verbosity isn't honored when specified #665

New Issue

winny · 2023-04-02T18:44:12Z

winny commented

2023-04-02 18:44:12 +00:00

What I'm trying to do and why

Test borgmatic syslog logging on an interactive console.

Steps to reproduce (if a bug)

I specify --syslog-verbosity 1 on the console and it doesn't log to syslog.

Actual behavior (if a bug)

It seems borgmatic checks if stderr is a TTY or if TERM is equal to dumb. And since neither of those criteria are met, my --syslog-verbosity 1 arg isn't honored.

Expected behavior (if a bug)

I don't believe it should do this. Maybe it should just honor --syslog-verbosity straight up? Thoughts?

Other notes / implementation ideas

Alternatively, perhaps this should be documented in both the CLI usage info and website documentation, as to avoid further confusion?

Environment

borgmatic version: 1.7.4

Use sudo borgmatic --version or sudo pip show borgmatic | grep ^Version

borgmatic installation method: Alpine community repository

Borg version: borg 1.2.2

Use sudo borg --version

Python version: Python 3.10.10

Database version (if applicable): N/A

operating system and version:

# cat /etc/alpine-release 
3.17.3

#### What I'm trying to do and why Test borgmatic syslog logging on an interactive console. #### Steps to reproduce (if a bug) I specify --syslog-verbosity 1 on the console and it doesn't log to syslog. #### Actual behavior (if a bug) It seems borgmatic checks if stderr is a TTY or if TERM is equal to dumb. And since neither of those criteria are met, my --syslog-verbosity 1 arg isn't honored. #### Expected behavior (if a bug) I don't believe it should do this. Maybe it should just honor --syslog-verbosity straight up? Thoughts? #### Other notes / implementation ideas Alternatively, perhaps this should be documented in both the CLI usage info and website documentation, as to avoid further confusion? #### Environment **borgmatic version:** `1.7.4` Use `sudo borgmatic --version` or `sudo pip show borgmatic | grep ^Version` **borgmatic installation method:** Alpine community repository **Borg version:** `borg 1.2.2` Use `sudo borg --version` **Python version:** `Python 3.10.10` **Database version (if applicable):** N/A **operating system and version:** ``` # cat /etc/alpine-release 3.17.3 ```

witten commented

2023-04-02 20:52:50 +00:00

Thanks for taking the time to file this! I think what you've discovered is an unfortunate (and undocumented) side effect of some intentional behavior. What's going on is that borgmatic detects whether you're at an interactive terminal and, if so, implicitly disables syslog logging. The idea is that if you're running one-off actions like borgmatic list, borgmatic mount, etc., you probably don't want your logs filling up with those actions. Logging is more suited to non-interactive use cases like cron jobs where you're not getting immediate output.

That's the theory anyway. It sounds like though you've got a use case for borgmatic logging to syslog even when run interactively. Could you tell me a little about this use case? Is it just that you're testing borgmatic out to make sure that the syslog output meets your needs? Or making sure that a command you'll later put into a cron job will log correctly? Something else?

Some potential solutions:

If at an interactive terminal, only disable syslog logging when --syslog-verbosity is zero. So setting, for instance, --syslog-verbosity 1 would force borgmatic to log to syslog.
Add another flag for explicitly selecting whether syslog logging gets disabled or not.
Make syslog log disabling depend on the specific borgmatic action run. E.g. maybe for list or mount it gets disabled at an interactive terminal, but for create logging doesn't get disabled.
Document whatever solution we settle on so the user isn't (as) surprised.

Once I better understand what you're trying to do and why, we can settle on the appropriate solution.

Thanks for taking the time to file this! I think what you've discovered is an unfortunate (and undocumented) side effect of some intentional behavior. What's going on is that borgmatic detects whether you're at an interactive terminal and, if so, implicitly disables syslog logging. The idea is that if you're running one-off actions like `borgmatic list`, `borgmatic mount`, etc., you probably don't want your logs filling up with those actions. Logging is more suited to non-interactive use cases like cron jobs where you're not getting immediate output. That's the theory anyway. It sounds like though you've got a use case for borgmatic logging to syslog even when run interactively. Could you tell me a little about this use case? Is it just that you're testing borgmatic out to make sure that the syslog output meets your needs? Or making sure that a command you'll later put into a cron job will log correctly? Something else? Some potential solutions: * If at an interactive terminal, only disable syslog logging when `--syslog-verbosity` is zero. So setting, for instance, `--syslog-verbosity 1` would force borgmatic to log to syslog. * Add another flag for explicitly selecting whether syslog logging gets disabled or not. * Make syslog log disabling depend on the specific borgmatic action run. E.g. maybe for `list` or `mount` it gets disabled at an interactive terminal, but for `create` logging doesn't get disabled. * Document whatever solution we settle on so the user isn't (as) surprised. Once I better understand what you're trying to do and why, we can settle on the appropriate solution.

witten added the

waiting for response

label 2023-04-18 16:48:02 +00:00

witten removed the

waiting for response

label 2023-06-28 18:37:51 +00:00

martin.von.wittich commented

2023-08-07 11:17:32 +00:00

I have two use cases for this:

I'm not using a cron job to create backups because I'm backing up manually with sudo -s borgmatic .... I'm using a backup hard disk that I put in a hot-swap cage, and I only insert it when I actually want to run or access my backups. Admittedly, I haven't had need for a log of the create output here yet, but I figure the ability to log that wouldn't hurt.
Recently I wanted to run a borg check of my repository. This took much longer than I initially anticipated, and I had to leave my computer running overnight, which I rarely ever do. In the morning I had completely forgotten about it and accidentally turned my computer off instead of on, so I never learned about the borg check result which at this point very likely had finished. Logging the result would have been useful here.

I have two use cases for this: - I'm not using a cron job to create backups because I'm backing up manually with `sudo -s borgmatic ...`. I'm using a backup hard disk that I put in a hot-swap cage, and I only insert it when I actually want to run or access my backups. Admittedly, I haven't had need for a log of the `create` output here yet, but I figure the ability to log that wouldn't hurt. - Recently I wanted to run a `borg check` of my repository. This took much longer than I initially anticipated, and I had to leave my computer running overnight, which I rarely ever do. In the morning I had completely forgotten about it and accidentally turned my computer off instead of on, so I never learned about the `borg check` result which at this point very likely had finished. Logging the result would have been useful here.

witten commented

2023-08-07 16:51:13 +00:00

Not the OP, but I'll take it! This is helpful. So what do you think of borgmatic:

removing the logic that suppresses logging to syslog when run interactively,
changing the default syslog verbosity to -1 (no syslog output), and
allowing the user to specify --syslog-verbosity 2 to opt into syslog logging on the command-line, from a cron job, or from anywhere else?

Not the OP, but I'll take it! This is helpful. So what do you think of borgmatic: 1. removing the logic that suppresses logging to syslog when run interactively, 2. changing the default syslog verbosity to -1 (no syslog output), and 3. allowing the user to specify `--syslog-verbosity 2` to opt into syslog logging on the command-line, from a cron job, or from anywhere else?

martin.von.wittich commented

2023-08-07 23:41:29 +00:00

Not the OP, but I'll take it! This is helpful. So what do you think of borgmatic:

removing the logic that suppresses logging to syslog when run interactively,

changing the default syslog verbosity to -1 (no syslog output), and

allowing the user to specify --syslog-verbosity 2 to opt into syslog logging on the command-line, from a cron job, or from anywhere else?

Seems good to me, but I'm not absolutely certain how syslog output for cronjobs works currently, and how this change might affect users who rely on the current behavior. Currently, --syslog-verbosity defaults to 0 which is "default", but from the documentation, I can't quite figure out what "default" is exactly. If the current borgmatic version logs cronjob output (or at least errors?) to syslog, then this change might break expected behavior for users?

Possibly a more backwards compatible solution:

when run interactively: default to syslog verbosity -1 (no syslog output)
when run non-interactively: default to syslog verbosity 0 (as the current version does, I believe?)
allow the user to specify any --syslog-verbosity to override the given default.
Interactive users would now be able to e.g. specify --syslog-verbosity 2 to enable syslog logging, while cronjob users now be able to e.g. specify --syslog-verbosity -1 if they wanted to opt out of logging for some reason.

Thereby the default behavior wouldn't change at all for existing users, but it would now be possible to override the default behavior by specifying the --syslog-verbosity option.

> Not the OP, but I'll take it! This is helpful. So what do you think of borgmatic: > > 1. removing the logic that suppresses logging to syslog when run interactively, > 2. changing the default syslog verbosity to -1 (no syslog output), and > 3. allowing the user to specify `--syslog-verbosity 2` to opt into syslog logging on the command-line, from a cron job, or from anywhere else? Seems good to me, but I'm not absolutely certain how syslog output for cronjobs works currently, and how this change might affect users who rely on the current behavior. Currently, `--syslog-verbosity` defaults to 0 which is "default", but from the documentation, I can't quite figure out what "default" is exactly. If the current `borgmatic` version logs cronjob output (or at least errors?) to syslog, then this change might break expected behavior for users? Possibly a more backwards compatible solution: 1. when run interactively: default to syslog verbosity -1 (no syslog output) 1. when run non-interactively: default to syslog verbosity 0 (as the current version does, I believe?) 1. allow the user to specify any `--syslog-verbosity` to override the given default. Interactive users would now be able to e.g. specify `--syslog-verbosity 2` to enable syslog logging, while cronjob users now be able to e.g. specify `--syslog-verbosity -1` if they wanted to opt out of logging for some reason. Thereby the default behavior wouldn't change at all for existing users, but it would now be possible to override the default behavior by specifying the `--syslog-verbosity` option.

witten commented

2023-08-08 19:35:00 +00:00

That would certainly be more backwards-compatible, but I'm actually not too worried about that because: 1. The current default of 0 is actually not that useful as a syslog verbosity, as a user's syslog verbosity expectations are typically higher than what you expect on the command-line, and 2. Almost everyone running borgmatic non-interactively likely already overrides the syslog verbosity anyway, as per these sample cron and systemd command-lines.

So how about this as a riff on your idea?

when run interactively: default to syslog verbosity -1 (no syslog output) .. Or actually -2 might be better because that would suppress errors as well.
when run non-interactively: default to syslog verbosity 1, as that's what all the sample configurations use
allow the user to specify any --syslog-verbosity to override the given default. Interactive users would now be able to e.g. specify --syslog-verbosity 2 to enable syslog logging, while cronjob users now be able to e.g. specify --syslog-verbosity -1 if they wanted to opt out of logging for some reason.

Currently, --syslog-verbosity defaults to 0 which is "default", but from the documentation, I can't quite figure out what "default" is exactly.

Yeah, I didn't have a good name for it. (Suggestions welcome!) This level shows output from Borg (e.g. for list or info actions), and of course it'll show errors—but not a whole lot else.

That would certainly be more backwards-compatible, but I'm actually not too worried about that because: 1. The current default of 0 is actually not that useful as a syslog verbosity, as a user's syslog verbosity expectations are typically higher than what you expect on the command-line, and 2. Almost everyone running borgmatic non-interactively likely already overrides the syslog verbosity anyway, as per these sample [cron](https://projects.torsion.org/borgmatic-collective/borgmatic/src/branch/main/sample/cron/borgmatic#L3) and [systemd](https://projects.torsion.org/borgmatic-collective/borgmatic/src/branch/main/sample/systemd/borgmatic.service#L64) command-lines. So how about this as a riff on your idea? 1. when run interactively: default to syslog verbosity -1 (no syslog output) .. Or actually -2 might be better because that would suppress errors as well. 2. when run non-interactively: default to syslog verbosity 1, as that's what all the sample configurations use 3. allow the user to specify any --syslog-verbosity to override the given default. Interactive users would now be able to e.g. specify --syslog-verbosity 2 to enable syslog logging, while cronjob users now be able to e.g. specify --syslog-verbosity -1 if they wanted to opt out of logging for some reason. > Currently, --syslog-verbosity defaults to 0 which is "default", but from the documentation, I can't quite figure out what "default" is exactly. Yeah, I didn't have a good name for it. (Suggestions welcome!) This level shows output from Borg (e.g. for `list` or `info` actions), and of course it'll show errors—but not a whole lot else.

witten referenced this issue

2023-08-29 21:02:57 +00:00

weird logging results #749

alsoeric commented

2023-08-30 19:31:27 +00:00

I recently posted (#749) about the weird experience I had with logging. As far as I'm concerned, the current logging code is broken. As a result, I don't worry about backward compatibility, and what I suggest here could be the moving forward syntax and functionality.

The advantage of these commands is that they specify where you log in and how verbose. Since it is the same command for all logging destinations, there is no need to search for destination-specific logging commands. Because the syntax of the command is different from the original, you can leave the original logging commands in place for a transitional period.

here is an example of the terse form specifying logging.

--log-to stderr=2,syslog=-1,file=/tmp/xxx;3 to specify where to send the log information and what level of verbosity.

a more easily read variant

--log-to stderr,verbosity=2
--log-to stdout,verbosity=1
--log-to syslog,verbosity=3
--log-to file, name =$safetemp,verbosity=2

and to turn off logging
--log-to stdout=none|false|off

Which reminds me, you might want to add something $safetemp as a way of providing a pseudo-constant returning a safe temporary file name. I called it a pseudo-constant because it's the same for the duration of a Borgmatic run. We can talk about that in a different ticket.

I recently posted (#749) about the weird experience I had with logging. As far as I'm concerned, the current logging code is broken. As a result, I don't worry about backward compatibility, and what I suggest here could be the moving forward syntax and functionality. The advantage of these commands is that they specify where you log in and how verbose. Since it is the same command for all logging destinations, there is no need to search for destination-specific logging commands. Because the syntax of the command is different from the original, you can leave the original logging commands in place for a transitional period. here is an example of the terse form specifying logging. --log-to stderr=2,syslog=-1,file=/tmp/xxx;3 to specify where to send the log information and what level of verbosity. a more easily read variant --log-to stderr,verbosity=2 --log-to stdout,verbosity=1 --log-to syslog,verbosity=3 --log-to file, name =$safetemp,verbosity=2 and to turn off logging --log-to stdout=none|false|off Which reminds me, you might want to add something $safetemp as a way of providing a pseudo-constant returning a safe temporary file name. I called it a pseudo-constant because it's the same for the duration of a Borgmatic run. We can talk about that in a different ticket.

witten referenced this issue

2023-09-16 23:03:18 +00:00

weird logging results #749

witten commented

2023-09-16 23:18:51 +00:00

Thanks for following up here and writing up a proposal for revised logging flags. However I'm not convinced that these changes are necessary to fix the logging problems, and in general borgmatic's flag style is to explode out values into multiple flags where possible instead of using mini dialects to pack multiple values into single flags. (The one major exception I can think of that is --override.)

So while I do really appreciate you taking the time to put this together, I don't think I'm going to adopt this proposal now. However I am pretty motivated to fix the current logging brokenness, and I think a big piece of that is likely fixing the implicit logging changes that happen when an interactive terminal is detected vs. not detected. In other words, I think the brokenness is in the underlying semantics—the way the code behind the flags ignores the user's stated preference.

Also a side note: borgmatic (intentionally) logs to both stdout and stderr when console logging is enabled. But you can always redirect the output if that's not what you want.

And yeah, feel free to file the $safetemp idea as a separate ticket. That sounds interesting and I'd like to hear more about the use case you have for it.

Thanks for following up here and writing up a proposal for revised logging flags. However I'm not convinced that these changes are necessary to fix the logging problems, and in general borgmatic's flag style is to explode out values into multiple flags where possible instead of using mini dialects to pack multiple values into single flags. (The one major exception I can think of that is `--override`.) So while I do really appreciate you taking the time to put this together, I don't think I'm going to adopt this proposal now. However I am pretty motivated to fix the current logging brokenness, and I think a big piece of that is likely fixing the implicit logging changes that happen when an interactive terminal is detected vs. not detected. In other words, I think the brokenness is in the underlying semantics—the way the code _behind_ the flags ignores the user's stated preference. Also a side note: borgmatic (intentionally) logs to both stdout and stderr when console logging is enabled. But you can always redirect the output if that's not what you want. And yeah, feel free to file the `$safetemp` idea as a separate ticket. That sounds interesting and I'd like to hear more about the use case you have for it.

witten referenced this issue from a commit

2023-09-29 21:17:05 +00:00

Simplify logging logic (#665).

witten commented

2023-09-29 21:21:45 +00:00

I have implemented a version of this in main and it will be part of the next release! After some further simplification, this is the logic I ended up with:

Syslog verbosity is now disabled by default, but setting the "--syslog-verbosity" flag enables it regardless of whether you're at an
interactive console. I believe this addresses the original ask in the ticket.
"--log-file-verbosity" and "--monitoring-verbosity" now both default to 1 (info about steps borgmatic is taking) instead of 0 (direct answers to actions only).
Both syslog logging and file logging can be enabled simultaneously now, whereas before you could only use one or the other.

I have implemented a version of this in main and it will be part of the next release! After some further simplification, this is the logic I ended up with: * Syslog verbosity is now disabled by default, but setting the "--syslog-verbosity" flag enables it regardless of whether you're at an interactive console. I believe this addresses the original ask in the ticket. * "--log-file-verbosity" and "--monitoring-verbosity" now both default to 1 (info about steps borgmatic is taking) instead of 0 (direct answers to actions only). * Both syslog logging and file logging can be enabled simultaneously now, whereas before you could only use one or the other.

witten closed this issue

2023-09-29 21:21:45 +00:00

witten commented

2023-09-30 20:38:59 +00:00

This has been released as part of borgmatic 1.8.3!

witten referenced this issue

2023-10-07 01:42:33 +00:00

Traceback when usage error occurs #768

witten referenced this issue from a commit

2023-11-07 05:14:19 +00:00

Update documentation about logging changes from version 1.8.3 (#665).

Sign in to join this conversation.