Don't color syslog output #197

New Issue

witten · 2019-06-17T18:24:31Z

witten commented

2019-06-17 18:24:31 +00:00

What I'm trying to do and why

View syslog output.

Steps to reproduce

Log to syslog from borgmatic, presumably with a non-systemd syslog daemon?

Actual behavior

Color codes in syslog end up looking like:

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

Expected behavior

No color codes in syslog.

#### What I'm trying to do and why View syslog output. #### Steps to reproduce Log to syslog from borgmatic, presumably with a non-systemd syslog daemon? #### Actual behavior Color codes in syslog end up looking like: ```console 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 ``` #### Expected behavior No color codes in syslog.

witten added the

bug

label 2019-06-17 18:26:33 +00:00

witten referenced this issue from a commit

2019-06-17 18:53:46 +00:00

Don't color syslog output (#197).

witten commented

2019-06-17 18:54:02 +00:00

Fixed in master. This will be part of the next release!

witten closed this issue

2019-06-17 18:54:02 +00:00

witten commented

2019-06-17 19:19:08 +00:00

Just released as part of borgmatic 1.3.7.

🎉 1

sdellenb commented

2019-06-26 12:56:49 +00:00

The syslog unicode color characters seem to be back since 1.3.8 (or 1.3.9).
Setting output.color=false disables the colors for the console, but still puts them in syslog. 😿

Also, --syslog-verbosity 0 has no effect. Warnings get sent to syslog anyways. Example command is borgmatic list -v 2 --syslog-verbosity 0. It even includes the debugging messages (from -v 2) as "WARNING".

The syslog unicode color characters seem to be back since 1.3.8 (or 1.3.9). Setting `output.color=false` disables the colors for the console, but still puts them in syslog. :crying_cat_face: Also, `--syslog-verbosity 0` has no effect. Warnings get sent to syslog anyways. Example command is `borgmatic list -v 2 --syslog-verbosity 0`. It even includes the debugging messages (from `-v 2`) as "WARNING".

witten commented

2019-06-26 16:32:14 +00:00

The syslog unicode color characters seem to be back since 1.3.8 (or 1.3.9).
Setting output.color=false disables the colors for the console, but still puts them in syslog. 😿

Oh no! Do you know what syslog daemon you're using? systemd? rsyslog? And you're seeing color escape codes in the log output? The color formatting is only applied to the console logging handler now, so I'm a bit unsure what might be going on. Any more info you can provide would be helpful.

Also, --syslog-verbosity 0 has no effect. Warnings get sent to syslog anyways. Example command is borgmatic list -v 2 --syslog-verbosity 0. It even includes the debugging messages (from -v 2) as “WARNING”.

Well, this is actually by design! What's going on is that verbosity level zero does surface both warnings and errors, but suppresses any logs below that log level. The idea is that this is a useful default log level for, say, a cron job, where you don't want to get the play-by-play if everything was successful but you definitely want to see logs if something went wrong.

Then, as perhaps an abuse of this property, borgmatic logs Borg's list output at the WARNING level, with the idea that if you run borgmatic list, you actually want to see list output regardless of verbosity level. It would be pretty weird if, at verbosity level zero, you ran borgmatic list and didn't get any list output at all!

I'm certainly open to revisiting any of this, but that's the current thinking anyway. Let me know your thoughts!

> The syslog unicode color characters seem to be back since 1.3.8 (or 1.3.9). Setting output.color=false disables the colors for the console, but still puts them in syslog. :crying_cat_face: Oh no! Do you know what syslog daemon you're using? systemd? rsyslog? And you're seeing color escape codes in the log output? The color formatting is only applied to the console logging handler now, so I'm a bit unsure what might be going on. Any more info you can provide would be helpful. > Also, --syslog-verbosity 0 has no effect. Warnings get sent to syslog anyways. Example command is borgmatic list -v 2 --syslog-verbosity 0. It even includes the debugging messages (from -v 2) as “WARNING”. Well, this is actually by design! What's going on is that verbosity level zero *does* surface both warnings and errors, but suppresses any logs below that log level. The idea is that this is a useful default log level for, say, a cron job, where you don't want to get the play-by-play if everything was successful but you definitely want to see logs if something went wrong. Then, as perhaps an abuse of this property, borgmatic logs Borg's `list` output at the `WARNING` level, with the idea that if you run `borgmatic list`, you actually want to see list output regardless of verbosity level. It would be pretty weird if, at verbosity level zero, you ran `borgmatic list` and didn't get any list output at all! I'm certainly open to revisiting any of this, but that's the current thinking anyway. Let me know your thoughts!

witten reopened this issue

2019-06-26 16:32:14 +00:00

sdellenb commented

2019-06-27 06:56:24 +00:00

Do you know what syslog daemon you’re using? systemd? rsyslog? And you’re seeing color escape codes in the log output?

I'm using rsyslog-8.24.0 (the default on CentOS 7.6).

UPDATE: Oops, my bad U+FEFF is actually the 'ZERO WIDTH NO-BREAK SPACE', not a color code. I'm bad at unicode. There are no color escape codes in the syslog at all anymore. 😥

One of this night's backup runs writes this to /var/log/messages:

Jun 27 04:30:02 netcup-optane borgmatic: WARNING <U+FEFF>2019-06-27 04:30:02 - Starting a backup job.
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>------------------------------------------------------------------------------
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Archive name: netcup-optane-2019-06-27T04:30:18.366386
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Archive fingerprint: 2e479de2b31ef12c381cfb62a2a1f04cfa00b609c19a2e587c2ac786ffc53353
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Time (start): Thu, 2019-06-27 04:30:19
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Time (end):   Thu, 2019-06-27 04:33:09
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Duration: 2 minutes 49.73 seconds
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Number of files: 517310
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Utilization of max. archive size: 0%
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>------------------------------------------------------------------------------
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>                       Original size      Compressed size    Deduplicated size
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>This archive:               46.74 GB             38.99 GB             87.54 MB
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>All archives:                1.90 TB              1.59 TB             47.70 GB
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>                       Unique chunks         Total chunks
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Chunk index:                  325127             20029796
Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>------------------------------------------------------------------------------
Jun 27 04:34:15 netcup-optane borgmatic: WARNING <U+FEFF>2019-06-27 04:34:14 - Backup created.

Well, this is actually by design! What’s going on is that verbosity level zero does surface both warnings and errors, but suppresses any logs below that log level.

Ah, then I misunderstood the recent commit (de94001508) that made "error" the default logging level (even if it was temporary).

Can I disable syslog logging completely when running interactively (e.g. with a setting in the config file = less typing in the console) and override it with a parameter when running in the daily cron job?

I think that would be ideal for my use case:
When I'm typing the borgmatic commands into the console, I see the output and don't want my typos (happens quite a lot, especially with borg patterns°...) to spam the syslog with ERROR and CRITICAL. 😊

° example, command was borgmatic extract --archive netcup-centos-2019-06-20T03:00:16.946917 --restore-path "sh:**/openfire/openfire.xml" (path doesn't exist in backup, I was missing the intermediate "conf" directory).

Jun 26 15:22:13 netcup-centos borgmatic: ERROR <U+FEFF>2019-06-26 15:22:13 - Error while creating a backup.
Jun 26 15:22:13 netcup-centos borgmatic: CRITICAL <U+FEFF>/etc/borgmatic/config.yaml: Error running configuration file
Jun 26 15:22:13 netcup-centos borgmatic: CRITICAL <U+FEFF>Include pattern '**/openfire/openfire.xml' never matched.
Jun 26 15:22:13 netcup-centos borgmatic: CRITICAL <U+FEFF>Command 'borg extract borgbackup@borgbackup:netcup-centos::netcup-centos-2019-06-20T03:00:16.946917 sh:**/openfire/openfire.xml' returned non-zero exit status 1.
Jun 26 15:22:13 netcup-centos borgmatic: CRITICAL <U+FEFF>
Jun 26 15:22:13 netcup-centos borgmatic: CRITICAL <U+FEFF>Need some help? https://torsion.org/borgmatic/#issues

> Do you know what syslog daemon you’re using? systemd? rsyslog? And you’re seeing color escape codes in the log output? I'm using rsyslog-8.24.0 (the default on CentOS 7.6). __UPDATE: Oops, my bad U+FEFF is actually the 'ZERO WIDTH NO-BREAK SPACE', not a color code. I'm bad at unicode. There are no color escape codes in the syslog at all anymore.__ :disappointed_relieved: One of this night's backup runs writes this to /var/log/messages: ``` Jun 27 04:30:02 netcup-optane borgmatic: WARNING <U+FEFF>2019-06-27 04:30:02 - Starting a backup job. Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>------------------------------------------------------------------------------ Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Archive name: netcup-optane-2019-06-27T04:30:18.366386 Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Archive fingerprint: 2e479de2b31ef12c381cfb62a2a1f04cfa00b609c19a2e587c2ac786ffc53353 Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Time (start): Thu, 2019-06-27 04:30:19 Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Time (end): Thu, 2019-06-27 04:33:09 Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Duration: 2 minutes 49.73 seconds Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Number of files: 517310 Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Utilization of max. archive size: 0% Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>------------------------------------------------------------------------------ Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF> Original size Compressed size Deduplicated size Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>This archive: 46.74 GB 38.99 GB 87.54 MB Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>All archives: 1.90 TB 1.59 TB 47.70 GB Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF> Unique chunks Total chunks Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>Chunk index: 325127 20029796 Jun 27 04:33:16 netcup-optane borgmatic: WARNING <U+FEFF>------------------------------------------------------------------------------ Jun 27 04:34:15 netcup-optane borgmatic: WARNING <U+FEFF>2019-06-27 04:34:14 - Backup created. ``` > Well, this is actually by design! What’s going on is that verbosity level zero does surface both warnings and errors, but suppresses any logs below that log level. Ah, then I misunderstood the recent commit (de94001508) that made "error" the default logging level (even if it was temporary). Can I disable syslog logging completely when running interactively (e.g. with a setting in the config file = less typing in the console) and override it with a parameter when running in the daily cron job? I think that would be ideal for my use case: When I'm typing the borgmatic commands into the console, I see the output and don't want my typos (happens quite a lot, especially with borg patterns°...) to spam the syslog with ERROR and CRITICAL. :blush: ° example, command was `borgmatic extract --archive netcup-centos-2019-06-20T03:00:16.946917 --restore-path "sh:**/openfire/openfire.xml"` (path doesn't exist in backup, I was missing the intermediate "conf" directory). ``` Jun 26 15:22:13 netcup-centos borgmatic: ERROR <U+FEFF>2019-06-26 15:22:13 - Error while creating a backup. Jun 26 15:22:13 netcup-centos borgmatic: CRITICAL <U+FEFF>/etc/borgmatic/config.yaml: Error running configuration file Jun 26 15:22:13 netcup-centos borgmatic: CRITICAL <U+FEFF>Include pattern '**/openfire/openfire.xml' never matched. Jun 26 15:22:13 netcup-centos borgmatic: CRITICAL <U+FEFF>Command 'borg extract borgbackup@borgbackup:netcup-centos::netcup-centos-2019-06-20T03:00:16.946917 sh:**/openfire/openfire.xml' returned non-zero exit status 1. Jun 26 15:22:13 netcup-centos borgmatic: CRITICAL <U+FEFF> Jun 26 15:22:13 netcup-centos borgmatic: CRITICAL <U+FEFF>Need some help? https://torsion.org/borgmatic/#issues ```

witten referenced this issue from a commit

2019-06-27 17:04:50 +00:00

Remove unicode byte order mark from syslog output. (Related to #197.)

witten commented

2019-06-27 17:09:07 +00:00

UPDATE: Oops, my bad U+FEFF is actually the ‘ZERO WIDTH NO-BREAK SPACE’, not a color code. I’m bad at unicode. There are no color escape codes in the syslog at all anymore. 😥

Yeah, this is actually a unicode byte order mark. I thought I was being clever by including it in case the message contained unicode, but I didn't realize that rsyslog would render it literally. I'll remove it!

Ah, then I misunderstood the recent commit (de94001508) that made “error” the default logging level (even if it was temporary).

I was being perhaps needlessly succinct in that commit message.. It's errors and warnings (and "warnings") as you've discovered!

Can I disable syslog logging completely when running interactively (e.g. with a setting in the config file = less typing in the console) and override it with a parameter when running in the daily cron job?

I think that would be ideal for my use case: When I’m typing the borgmatic commands into the console, I see the output and don’t want my typos (happens quite a lot, especially with borg patterns°…) to spam the syslog with ERROR and CRITICAL.

This seems like a valid use case to me.. Let me think about the best way to solve this. One related idea is that we can generally detect when the terminal is interactive or not. Maybe when interactive, we should never log to syslog (unless requested), and when non-interactive, always log to syslog?

> UPDATE: Oops, my bad U+FEFF is actually the ‘ZERO WIDTH NO-BREAK SPACE’, not a color code. I’m bad at unicode. There are no color escape codes in the syslog at all anymore. :disappointed_relieved: Yeah, this is actually a [unicode byte order mark](https://en.wikipedia.org/wiki/Byte_order_mark). I thought I was being clever by including it in case the message contained unicode, but I didn't realize that rsyslog would render it literally. I'll remove it! > Ah, then I misunderstood the recent commit (de94001508) that made “error” the default logging level (even if it was temporary). I was being perhaps needlessly succinct in that commit message.. It's errors *and* warnings (and "warnings") as you've discovered! > Can I disable syslog logging completely when running interactively (e.g. with a setting in the config file = less typing in the console) and override it with a parameter when running in the daily cron job? > I think that would be ideal for my use case: When I’m typing the borgmatic commands into the console, I see the output and don’t want my typos (happens quite a lot, especially with borg patterns°…) to spam the syslog with ERROR and CRITICAL. This seems like a valid use case to me.. Let me think about the best way to solve this. One related idea is that we can generally detect when the terminal is interactive or not. Maybe when interactive, we should never log to syslog (unless requested), and when non-interactive, always log to syslog?

👍 1

witten referenced this issue from a commit

2019-06-27 21:42:10 +00:00

Only log to syslog when run from a non-interactive console (e.g. a cron job). Related to #197.

witten commented

2019-06-27 21:51:32 +00:00

Okay, I just released borgmatic 1.3.12. This removes the byte order mark, and disables syslog output entirely when the console is interactive. At the moment, this is not override-able. But we can always revisit in the future if there's a valid use case for logging to syslog at an interactive console.

Let me know how it works out for you, and thanks for reporting the various issues!

Okay, I just released borgmatic 1.3.12. This removes the byte order mark, and disables syslog output entirely when the console is interactive. At the moment, this is not override-able. But we can always revisit in the future if there's a valid use case for logging to syslog at an interactive console. Let me know how it works out for you, and thanks for reporting the various issues!

🎉 1

witten closed this issue

2019-06-27 21:51:33 +00:00

Sign in to join this conversation.