list command with archive parameter writes all content of the archive to syslog as WARNING #242

Closed
opened 2019-11-12 10:23:12 +00:00 by hdogan · 6 comments

What I'm trying to do and why

Steps to reproduce (if a bug)

borgmatic list --archive <archive name>

Actual behavior (if a bug)

All output (content of archive) also written to syslog, each line marked as WARNING.

Expected behavior (if a bug)

It should only list content to stdout.

Other notes / implementation ideas

None

Environment

borgmatic version: 1.4.8

borgmatic installation method: pip3

Borg version: 1.1.10

Python version: 3.6.8

operating system and version: Ubuntu 18.04LTS

#### What I'm trying to do and why #### Steps to reproduce (if a bug) `borgmatic list --archive <archive name>` #### Actual behavior (if a bug) All output (content of archive) *also* written to syslog, each line marked as *WARNING*. #### Expected behavior (if a bug) It should only list content to stdout. #### Other notes / implementation ideas None #### Environment **borgmatic version:** 1.4.8 **borgmatic installation method:** pip3 **Borg version:** 1.1.10 **Python version:** 3.6.8 **operating system and version:** Ubuntu 18.04LTS
Owner

Thank you for filing this! I'm looking at the code that decides whether to log to syslog, and it skips syslog logging if the console is interactive. The idea is to support exactly what you're doing: borgmatic list at the interactive console without mucking up syslog. So a question for you: Are you running borgmatic list interactively, or are you running it some other way like in a cron job? If the latter, then what are you using it for there?

It's also possible that the interactive console detection is just broken in certain cases.

Thank you for filing this! I'm looking at the code that decides whether to log to syslog, and it skips syslog logging if the console is interactive. The idea is to support exactly what you're doing: `borgmatic list` at the interactive console without mucking up syslog. So a question for you: Are you running `borgmatic list` interactively, or are you running it some other way like in a cron job? If the latter, then what are you using it for there? It's also possible that the interactive console detection is just broken in certain cases.
witten added the
waiting for response
label 2019-11-18 01:26:10 +00:00
Collaborator

I have a similar problem where I run borgmatic from a systemd service unit. The pre-backup scripts produces output to stdout (not to stderr) and it ends up in the log as:

Jun 13 12:47:45 asaru borgmatic[5674]: /crypt/ecpubkey.pem
Jun 13 12:47:45 asaru borgmatic[5674]: /crypt/ecprivkey.pem
Jun 13 12:47:45 asaru borgmatic[5674]: WARNING /crypt/ecpubkey.pem
Jun 13 12:47:45 asaru borgmatic[5674]: WARNING /crypt/ecprivkey.pem

The last lines are also WARNING log level, which makes filtering the log for real warnings hard.

command is /root/.local/bin/borgmatic --verbosity 1 also tried with --syslog-verbosity 1 instead.

As the pre-backup script outputs to stdout which is attached to the journal, I want borgmatic to not touch (re-echo) the output. Other borgmatic output should be like --verbosity 1. Is that possible?

I have a similar problem where I run borgmatic from a systemd service unit. The pre-backup scripts produces output to stdout (not to stderr) and it ends up in the log as: ``` Jun 13 12:47:45 asaru borgmatic[5674]: /crypt/ecpubkey.pem Jun 13 12:47:45 asaru borgmatic[5674]: /crypt/ecprivkey.pem Jun 13 12:47:45 asaru borgmatic[5674]: WARNING /crypt/ecpubkey.pem Jun 13 12:47:45 asaru borgmatic[5674]: WARNING /crypt/ecprivkey.pem ``` The last lines are also WARNING log level, which makes filtering the log for real warnings hard. command is `/root/.local/bin/borgmatic --verbosity 1` also tried with `--syslog-verbosity 1` instead. As the pre-backup script outputs to stdout which is attached to the journal, I want borgmatic to not touch (re-echo) the output. Other borgmatic output should be like `--verbosity 1`. Is that possible?
Owner

I'm seeing this behavior too. In regards to the double output, the solution might be to suppress stdout output entirely if the console is not interactive. Not sure.. I'll have to think that through.

As for the WARNING-level output: All list output is logged as WARNING as a work-around to make list output show up at the console (interactive session) even when --verbosity is 0 (the default). For instance, if list output was instead logged as INFO level, it wouldn't show up at the default borgmatic verbosity.

However, I get how that might obscure real warnings in the system logs. I don't have any real good ideas there. It might be possible to make certain handlers treat particular log entries differently, e.g. changing their log level dynamically. However, at the point the log handler has the log entry, it has no idea where it came from.

Anyway, let me know if you have thoughts on any of this.

I'm seeing this behavior too. In regards to the double output, the solution might be to suppress stdout output entirely if the console is not interactive. Not sure.. I'll have to think that through. As for the `WARNING`-level output: All list output is logged as `WARNING` as a work-around to make list output show up at the console (interactive session) even when `--verbosity` is `0` (the default). For instance, if list output was instead logged as `INFO` level, it wouldn't show up at the default borgmatic verbosity. However, I get how that might obscure real warnings in the system logs. I don't have any real good ideas there. It might be possible to make certain handlers treat particular log entries differently, e.g. changing their log level dynamically. However, at the point the log handler has the log entry, it has no idea where it came from. Anyway, let me know if you have thoughts on any of this.
witten added
bug
and removed
waiting for response
labels 2020-06-17 19:16:35 +00:00
Collaborator

I am not really into how logging is done within borgmatic and what the idea behind is.

However, I think dynamically adapting the log output is an uphill battle.

Currently, there are:

  -v {-1,0,1,2}, --verbosity {-1,0,1,2}
                        Display verbose progress to the console (from only
                        errors to very verbose: -1, 0, 1, or 2)
  --syslog-verbosity {-1,0,1,2}
                        Log verbose progress to syslog (from only errors to
                        very verbose: -1, 0, 1, or 2). Ignored when console is
                        interactive or --log-file is given
  --log-file-verbosity {-1,0,1,2}
                        Log verbose progress to log file (from only errors to
                        very verbose: -1, 0, 1, or 2). Only used when --log-
                        file is given
  --monitoring-verbosity {-1,0,1,2}
                        Log verbose progress to monitoring integrations that
                        support logging (from only errors to very verbose: -1,
                        0, 1, or 2)

Where I don't even know what monitoring-verbosity really is. ;-) IMHO that is too much automatism, e.g. ignoring syslog-verbosity when console is detected (maybe I still want to have the output in syslog?)

On the other hand, I don't know what the best way to simplify is here and how to treat output of pre-/post-backup scripts.

All the best!

I am not really into how logging is done within borgmatic and what the idea behind is. However, I think dynamically adapting the log output is an uphill battle. Currently, there are: ``` -v {-1,0,1,2}, --verbosity {-1,0,1,2} Display verbose progress to the console (from only errors to very verbose: -1, 0, 1, or 2) --syslog-verbosity {-1,0,1,2} Log verbose progress to syslog (from only errors to very verbose: -1, 0, 1, or 2). Ignored when console is interactive or --log-file is given --log-file-verbosity {-1,0,1,2} Log verbose progress to log file (from only errors to very verbose: -1, 0, 1, or 2). Only used when --log- file is given --monitoring-verbosity {-1,0,1,2} Log verbose progress to monitoring integrations that support logging (from only errors to very verbose: -1, 0, 1, or 2) ``` Where I don't even know what monitoring-verbosity really is. ;-) IMHO that is too much automatism, e.g. ignoring syslog-verbosity when console is detected (maybe I still want to have the output in syslog?) On the other hand, I don't know what the best way to simplify is here and how to treat output of pre-/post-backup scripts. All the best!
Owner

Where I don't even know what monitoring-verbosity really is. ;-)

It's for logging to monitoring services like Healthchecks, Cronitor, Cronhub, etc.

IMHO that is too much automatism, e.g. ignoring syslog-verbosity when console is detected (maybe I still want to have the output in syslog?)

This "feature" was originally added because users were surprised when they ran borgmatic list and similiar interactive commands at the console and saw the output of those commands in their logs. They expected logs to only contain the output of non-interactive cron jobs, etc.

I'm open to ideas though if there's a way to allow the user to opt-in to syslog logging for interactive commands, while leaving it off by default. I'm also open to ideas on how to make this behavior more obvious.

> Where I don't even know what monitoring-verbosity really is. ;-) It's for logging to monitoring services like Healthchecks, Cronitor, Cronhub, etc. > IMHO that is too much automatism, e.g. ignoring syslog-verbosity when console is detected (maybe I still want to have the output in syslog?) This "feature" was originally added because users were surprised when they ran `borgmatic list` and similiar interactive commands at the console and saw the output of those commands in their logs. They expected logs to only contain the output of non-interactive cron jobs, etc. I'm open to ideas though if there's a way to allow the user to opt-in to syslog logging for interactive commands, while leaving it off by default. I'm also open to ideas on how to make this behavior more obvious.
Owner

@floli I think your double output issue may have been fixed by #379. Please let me know if that's not the case.

As for the original issue for which this ticket was filed, I don't have repro steps here—interactive list output does not show up in syslog for me. Closing for the time being, but please reopen if this is still occurring.

@floli I think your double output issue may have been fixed by #379. Please let me know if that's not the case. As for the original issue for which this ticket was filed, I don't have repro steps here—interactive list output does not show up in syslog for me. Closing for the time being, but please reopen if this is still occurring.
Sign in to join this conversation.
No Milestone
No Assignees
3 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#242
No description provided.