Some strings (such as "Starting a backup.") wrongly sent to stderr since 1.7.6 #634

New Issue

Write · 2023-01-28T15:35:11Z

Write commented

2023-01-28 15:35:11 +00:00

What I'm trying to do and why

I have a crontab set to start a borgmatic backup everyday, if anything is sent to stderr, I receive an email. Today, after upgrading to 1.7.6 I found out that some strings are wrongly sent to stderr instead of stdout for no apparent reason.

Steps to reproduce (if a bug)

Run a backup that output stderr/stdout to different files, eg: borgmatic break-lock -e repokey rcreate rinfo prune compact create -v 1 --syslog-verbosity 1 2>> error 1>> output

Actual behavior (if a bug)

Wait for backup to be completed, if no error happens, 'error' file will contains strings such as (full output of my 'error' file from my latest backup):

Starting actions.
Starting a backup.
Starting a backup.
Starting a backup.
Completed actions.

Expected behavior (if a bug)

Output theses string to stdout instead of stderr

Environment

borgmatic version: 1.7.6

borgmatic installation method: pip3 install --user --upgrade borgmatic borgbackup

Borg version: 1.2.3

Python version: Python 3.9.2

operating system and version:

No LSB modules are available.
Distributor ID: Debian
Description:    Debian GNU/Linux 11 (bullseye)
Release:        11
Codename:       bullseye

#### What I'm trying to do and why I have a crontab set to start a borgmatic backup everyday, if anything is sent to stderr, I receive an email. Today, after upgrading to 1.7.6 I found out that some strings are wrongly sent to stderr instead of stdout for no apparent reason. #### Steps to reproduce (if a bug) Run a backup that output stderr/stdout to different files, eg: `borgmatic break-lock -e repokey rcreate rinfo prune compact create -v 1 --syslog-verbosity 1 2>> error 1>> output` #### Actual behavior (if a bug) Wait for backup to be completed, if no error happens, '`error`' file will contains strings such as (full output of my '`error`' file from my latest backup): ``` Starting actions. Starting a backup. Starting a backup. Starting a backup. Completed actions. ``` #### Expected behavior (if a bug) Output theses string to stdout instead of stderr #### Environment **borgmatic version:** 1.7.6 **borgmatic installation method:** `pip3 install --user --upgrade borgmatic borgbackup` **Borg version:** 1.2.3 **Python version:** Python 3.9.2 **operating system and version:** ``` No LSB modules are available. Distributor ID: Debian Description: Debian GNU/Linux 11 (bullseye) Release: 11 Codename: bullseye ```

Write changed title from ~~Some strings (such as "Starting a backup.") wrongly output to stderr since 1.7.6~~ to Some strings (such as "Starting a backup.") wrongly sent to stderr since 1.7.6

2023-01-28 15:35:59 +00:00

witten commented

2023-01-28 18:51:31 +00:00

Thanks for filing this. I'm not yet sure exactly what's going on, but my guess is that the changes introduced as part of #602 are causing it. And it looks like those messages you're seeing on stderr are coming from your hooks configuration, e.g. something like:

hooks:
   before_actions:
       - echo "Starting actions."

So you can comment out or remove those hooks in order to prevent them from going to stderr. They are just example hook commands, so you should hopefully not even need them; the built-in borgmatic logging should be sufficient to track when actions and backups begin and end.

In any case, I'll look into this!

Thanks for filing this. I'm not yet sure exactly what's going on, but my guess is that the changes introduced as part of #602 are causing it. And it looks like those messages you're seeing on stderr are coming from your hooks configuration, e.g. something like: ```yaml hooks: before_actions: - echo "Starting actions." ``` So you can comment out or remove those hooks in order to prevent them from going to stderr. They are just example hook commands, so you should hopefully not even need them; the built-in borgmatic logging should be sufficient to track when actions and backups begin and end. In any case, I'll look into this!

Write commented

2023-01-28 19:02:57 +00:00

Thanks for filing this. I'm not yet sure exactly what's going on, but my guess is that the changes introduced as part of #602 are causing it. And it looks like those messages you're seeing on stderr are coming from your hooks configuration, e.g. something like:
hooks:
   before_actions:
       - echo "Starting actions."
So you can comment out or remove those hooks in order to prevent them from going to stderr. They are just example hook commands, so you should hopefully not even need them; the built-in borgmatic logging should be sufficient to track when actions and backups begin and end.

In any case, I'll look into this!

Duh,... Didn't even think about this. Thanks a lot.

> Thanks for filing this. I'm not yet sure exactly what's going on, but my guess is that the changes introduced as part of #602 are causing it. And it looks like those messages you're seeing on stderr are coming from your hooks configuration, e.g. something like: > > ```yaml > hooks: > before_actions: > - echo "Starting actions." > ``` > > So you can comment out or remove those hooks in order to prevent them from going to stderr. They are just example hook commands, so you should hopefully not even need them; the built-in borgmatic logging should be sufficient to track when actions and backups begin and end. > > In any case, I'll look into this! Duh,... Didn't even think about this. Thanks a lot.

👍 1

witten commented

2023-01-29 00:39:42 +00:00

Okay, I had a chance to look into this. Even though the behavior you're seeing is a change from pre-1.7.6 borgmatic, I believe it's as intended. Prior to 1.7.6, command hook output was logged as warning and went to stdout. Since 1.7.6 (and #602 specifically), command hook output is logged as warning and goes to stderr. Which to my eye seems more useful; if your command outputs something and you're running borgmatic in a cron job, you probably wants to see what that something is as it could indicate a problem.

So I'll close this for now as "works as expected", but please feel free to continue the conversation or open a new ticket. And thanks again for filing this one!

Okay, I had a chance to look into this. Even though the behavior you're seeing *is* a change from pre-1.7.6 borgmatic, I believe it's as intended. Prior to 1.7.6, command hook output was logged as warning and went to stdout. Since 1.7.6 (and #602 specifically), command hook output is logged as warning and goes to stderr. Which to my eye seems more useful; if your command outputs something and you're running borgmatic in a cron job, you probably wants to *see* what that something is as it could indicate a problem. So I'll close this for now as "works as expected", but please feel free to continue the conversation or open a new ticket. And thanks again for filing this one!

witten closed this issue

2023-01-29 00:39:42 +00:00

witten added the

question / support

label 2023-01-29 00:39:48 +00:00

Sign in to join this conversation.