borgmatic-collective/borgmatic
borgmatic-collective
/
borgmatic
15
57
Fork 40
Code Issues 54 Pull Requests 1 Actions Packages Releases 121 Activity

weird logging results #749

New Issue
Closed
opened 2023-08-29 19:07:15 +00:00 by alsoeric · 2 comments
alsoeric commented 2023-08-29 19:07:15 +00:00
Copy Link

What I'm trying to do and why

I'm using ntfy.sh to notify me of failures in backup and I'm trying to record the actual backup outputs to syslog. in theory, the documentation says borgmatic should log to syslog if the shell is noninteractive but I've not been able to get to work.

Steps to reproduce

backup.sh is the script I use to run the backup. pw-config and home are the common and specific borgmatic config files.. I've tried various combinations of verbosity and syslog-verbosity what I don't get any output. However, when I explicitly write the output of borgmatic to syslog, then I get double entries

this code fragment creates double entries in syslog as shown in the example of actual behavior.

borgmatic --no-color --verbosity 1 --list --stats -c "$config_file" 2> "$temp_stderr" | {
    while IFS= read -r line; do
	    echo "$line" | logger -t bm-stdout-$config_name
    done
}

this code fragments and other variants with different values for velocity and syslog-verbosity create no entries in syslog
borgmatic --no-color --verbosity -2 --syslog-verbosity 1 --list --stats -c "$config_file" > /dev/null

Actual behavior

this is just a fragment of the entire log from a run but it demonstrates the problem. I'm getting duplicate entries, and one set of them have the wrong tag and preface each line with "ANSWER" or "WARNING"

Aug 29 14:25:49 lake borgmatic: ANSWER Repository: ssh://mumble.rsync.net
Aug 29 14:25:49 lake borgmatic: ANSWER Archive name: home-2023-08-29_14:25
Aug 29 14:25:49 lake borgmatic: ANSWER Archive fingerprint: 5d50a985d91c389bbb87e332bd0ec3aa9b5551899cf3056ab93b1d41d9f604c7
Aug 29 14:25:49 lake borgmatic: ANSWER Time (start): Tue, 2023-08-29 14:25:48
Aug 29 14:25:49 lake borgmatic: ANSWER Time (end): Tue, 2023-08-29 14:25:48
Aug 29 14:25:49 lake borgmatic: ANSWER Duration: 0.61 seconds
Aug 29 14:25:49 lake borgmatic: ANSWER Number of files: 3221
Aug 29 14:25:49 lake borgmatic: ANSWER Utilization of max. archive size: 0%
Aug 29 14:25:49 lake borgmatic: ANSWER ------------------------------------------------------------------------------
Aug 29 14:25:49 lake borgmatic: ANSWER Original size Compressed size Deduplicated size
Aug 29 14:25:49 lake borgmatic: ANSWER This archive: 64.58 MB 48.90 MB 1.81 kB
Aug 29 14:25:49 lake borgmatic: ANSWER All archives: 9.54 GB 8.67 GB 4.19 GB
Aug 29 14:25:49 lake borgmatic: ANSWER Unique chunks Total chunks
Aug 29 14:25:49 lake borgmatic: ANSWER Chunk index: 19021 70947
Aug 29 14:25:49 lake borgmatic: ANSWER ------------------------------------------------------------------------------
Aug 29 14:25:49 lake bm-stdout-home: ------------------------------------------------------------------------------
Aug 29 14:25:49 lake bm-stdout-home: Repository: ssh://mumble.rsync.net
Aug 29 14:25:49 lake bm-stdout-home: Archive name: home-2023-08-29_14:25
Aug 29 14:25:49 lake bm-stdout-home: Archive fingerprint: 5d50a985d91c389bbb87e332bd0ec3aa9b5551899cf3056ab93b1d41d9f604c7
Aug 29 14:25:49 lake bm-stdout-home: Time (start): Tue, 2023-08-29 14:25:48
Aug 29 14:25:49 lake bm-stdout-home: Time (end): Tue, 2023-08-29 14:25:48
Aug 29 14:25:49 lake bm-stdout-home: Duration: 0.61 seconds
Aug 29 14:25:49 lake bm-stdout-home: Number of files: 3221
Aug 29 14:25:49 lake bm-stdout-home: Utilization of max. archive size: 0%
Aug 29 14:25:49 lake bm-stdout-home: ------------------------------------------------------------------------------
Aug 29 14:25:49 lake bm-stdout-home: Original size Compressed size Deduplicated size
Aug 29 14:25:49 lake bm-stdout-home: This archive: 64.58 MB 48.90 MB 1.81 kB
Aug 29 14:25:49 lake bm-stdout-home: All archives: 9.54 GB 8.67 GB 4.19 GB
Aug 29 14:25:49 lake bm-stdout-home: Unique chunks Total chunks
Aug 29 14:25:49 lake bm-stdout-home: Chunk index: 19021 70947
Aug 29 14:25:49 lake bm-stdout-home: ------------------------------------------------------------------------------

Expected behavior

Aug 29 14:25:49 lake bm-stdout-home: ------------------------------------------------------------------------------
Aug 29 14:25:49 lake bm-stdout-home: Repository: ssh://mumble.rsync.net
Aug 29 14:25:49 lake bm-stdout-home: Archive name: home-2023-08-29_14:25
Aug 29 14:25:49 lake bm-stdout-home: Archive fingerprint: 5d50a985d91c389bbb87e332bd0ec3aa9b5551899cf3056ab93b1d41d9f604c7
Aug 29 14:25:49 lake bm-stdout-home: Time (start): Tue, 2023-08-29 14:25:48
Aug 29 14:25:49 lake bm-stdout-home: Time (end): Tue, 2023-08-29 14:25:48
Aug 29 14:25:49 lake bm-stdout-home: Duration: 0.61 seconds
Aug 29 14:25:49 lake bm-stdout-home: Number of files: 3221
Aug 29 14:25:49 lake bm-stdout-home: Utilization of max. archive size: 0%
Aug 29 14:25:49 lake bm-stdout-home: ------------------------------------------------------------------------------
Aug 29 14:25:49 lake bm-stdout-home: Original size Compressed size Deduplicated size
Aug 29 14:25:49 lake bm-stdout-home: This archive: 64.58 MB 48.90 MB 1.81 kB
Aug 29 14:25:49 lake bm-stdout-home: All archives: 9.54 GB 8.67 GB 4.19 GB
Aug 29 14:25:49 lake bm-stdout-home: Unique chunks Total chunks
Aug 29 14:25:49 lake bm-stdout-home: Chunk index: 19021 70947
Aug 29 14:25:49 lake bm-stdout-home: ------------------------------------------------------------------------------

Other notes / implementation ideas

No response

borgmatic version

borgmatic --version 1.8.1

borgmatic installation method

pip3

Borg version

borg --version borg 1.2.4

Python version

python3 --version Python 3.10.12

Database version (if applicable)

No response

Operating system and version

PRETTY_NAME="Ubuntu 22.04.3 LTS"

### What I'm trying to do and why I'm using ntfy.sh to notify me of failures in backup and I'm trying to record the actual backup outputs to syslog. in theory, the documentation says borgmatic should log to syslog if the shell is noninteractive but I've not been able to get to work. ### Steps to reproduce backup.sh is the script I use to run the backup. pw-config and home are the common and specific borgmatic config files.. I've tried various combinations of verbosity and syslog-verbosity what I don't get any output. However, when I explicitly write the output of borgmatic to syslog, then I get double entries this code fragment creates double entries in syslog as shown in the example of actual behavior. ``` borgmatic --no-color --verbosity 1 --list --stats -c "$config_file" 2> "$temp_stderr" | { while IFS= read -r line; do echo "$line" | logger -t bm-stdout-$config_name done } ``` this code fragments and other variants with different values for velocity and syslog-verbosity create no entries in syslog `borgmatic --no-color --verbosity -2 --syslog-verbosity 1 --list --stats -c "$config_file" > /dev/null ` ### Actual behavior this is just a fragment of the entire log from a run but it demonstrates the problem. I'm getting duplicate entries, and one set of them have the wrong tag and preface each line with "ANSWER" or "WARNING" Aug 29 14:25:49 lake borgmatic: ANSWER Repository: ssh://mumble.rsync.net Aug 29 14:25:49 lake borgmatic: ANSWER Archive name: home-2023-08-29_14:25 Aug 29 14:25:49 lake borgmatic: ANSWER Archive fingerprint: 5d50a985d91c389bbb87e332bd0ec3aa9b5551899cf3056ab93b1d41d9f604c7 Aug 29 14:25:49 lake borgmatic: ANSWER Time (start): Tue, 2023-08-29 14:25:48 Aug 29 14:25:49 lake borgmatic: ANSWER Time (end): Tue, 2023-08-29 14:25:48 Aug 29 14:25:49 lake borgmatic: ANSWER Duration: 0.61 seconds Aug 29 14:25:49 lake borgmatic: ANSWER Number of files: 3221 Aug 29 14:25:49 lake borgmatic: ANSWER Utilization of max. archive size: 0% Aug 29 14:25:49 lake borgmatic: ANSWER ------------------------------------------------------------------------------ Aug 29 14:25:49 lake borgmatic: ANSWER Original size Compressed size Deduplicated size Aug 29 14:25:49 lake borgmatic: ANSWER This archive: 64.58 MB 48.90 MB 1.81 kB Aug 29 14:25:49 lake borgmatic: ANSWER All archives: 9.54 GB 8.67 GB 4.19 GB Aug 29 14:25:49 lake borgmatic: ANSWER Unique chunks Total chunks Aug 29 14:25:49 lake borgmatic: ANSWER Chunk index: 19021 70947 Aug 29 14:25:49 lake borgmatic: ANSWER ------------------------------------------------------------------------------ Aug 29 14:25:49 lake bm-stdout-home: ------------------------------------------------------------------------------ Aug 29 14:25:49 lake bm-stdout-home: Repository: ssh://mumble.rsync.net Aug 29 14:25:49 lake bm-stdout-home: Archive name: home-2023-08-29_14:25 Aug 29 14:25:49 lake bm-stdout-home: Archive fingerprint: 5d50a985d91c389bbb87e332bd0ec3aa9b5551899cf3056ab93b1d41d9f604c7 Aug 29 14:25:49 lake bm-stdout-home: Time (start): Tue, 2023-08-29 14:25:48 Aug 29 14:25:49 lake bm-stdout-home: Time (end): Tue, 2023-08-29 14:25:48 Aug 29 14:25:49 lake bm-stdout-home: Duration: 0.61 seconds Aug 29 14:25:49 lake bm-stdout-home: Number of files: 3221 Aug 29 14:25:49 lake bm-stdout-home: Utilization of max. archive size: 0% Aug 29 14:25:49 lake bm-stdout-home: ------------------------------------------------------------------------------ Aug 29 14:25:49 lake bm-stdout-home: Original size Compressed size Deduplicated size Aug 29 14:25:49 lake bm-stdout-home: This archive: 64.58 MB 48.90 MB 1.81 kB Aug 29 14:25:49 lake bm-stdout-home: All archives: 9.54 GB 8.67 GB 4.19 GB Aug 29 14:25:49 lake bm-stdout-home: Unique chunks Total chunks Aug 29 14:25:49 lake bm-stdout-home: Chunk index: 19021 70947 Aug 29 14:25:49 lake bm-stdout-home: ------------------------------------------------------------------------------ ### Expected behavior Aug 29 14:25:49 lake bm-stdout-home: ------------------------------------------------------------------------------ Aug 29 14:25:49 lake bm-stdout-home: Repository: ssh://mumble.rsync.net Aug 29 14:25:49 lake bm-stdout-home: Archive name: home-2023-08-29_14:25 Aug 29 14:25:49 lake bm-stdout-home: Archive fingerprint: 5d50a985d91c389bbb87e332bd0ec3aa9b5551899cf3056ab93b1d41d9f604c7 Aug 29 14:25:49 lake bm-stdout-home: Time (start): Tue, 2023-08-29 14:25:48 Aug 29 14:25:49 lake bm-stdout-home: Time (end): Tue, 2023-08-29 14:25:48 Aug 29 14:25:49 lake bm-stdout-home: Duration: 0.61 seconds Aug 29 14:25:49 lake bm-stdout-home: Number of files: 3221 Aug 29 14:25:49 lake bm-stdout-home: Utilization of max. archive size: 0% Aug 29 14:25:49 lake bm-stdout-home: ------------------------------------------------------------------------------ Aug 29 14:25:49 lake bm-stdout-home: Original size Compressed size Deduplicated size Aug 29 14:25:49 lake bm-stdout-home: This archive: 64.58 MB 48.90 MB 1.81 kB Aug 29 14:25:49 lake bm-stdout-home: All archives: 9.54 GB 8.67 GB 4.19 GB Aug 29 14:25:49 lake bm-stdout-home: Unique chunks Total chunks Aug 29 14:25:49 lake bm-stdout-home: Chunk index: 19021 70947 Aug 29 14:25:49 lake bm-stdout-home: ------------------------------------------------------------------------------ ### Other notes / implementation ideas _No response_ ### borgmatic version # borgmatic --version 1.8.1 ### borgmatic installation method pip3 ### Borg version # borg --version borg 1.2.4 ### Python version # python3 --version Python 3.10.12 ### Database version (if applicable) _No response_ ### Operating system and version PRETTY_NAME="Ubuntu 22.04.3 LTS"
home.yaml.txt
1.7 KiB
backup.sh.txt
1.5 KiB
pw-config.yaml.txt
453 B
witten commented 2023-08-29 21:02:57 +00:00
Owner
Copy Link

Thanks for filing this one. In the case of your script, I suspect you're getting doubled entries because borgmatic is (apparently) logging to syslog and you're redirecting stdout to syslog as well.

But for the second case of running borgmatic interactively, my guess is that borgmatic is detecting an interactive session and therefore refusing to log to syslog. I'm not sure exactly why your script isn't affected by this though. Maybe the act of piping makes it non-interactive.

Anyway, the workaround for now is to run borgmatic non-interactively (e.g., from a cron job or systemd service) if you want it to actually log to syslog. Ultimately, I think the fix is to implement something like #665, so even if borgmatic's behavior differs based on whether it's run interactively, the user can still choose to override things and force it to log to syslog. So feel free to weigh in on that ticket!

Thanks for filing this one. In the case of your script, I suspect you're getting doubled entries because borgmatic is (apparently) logging to syslog _and_ you're redirecting stdout to syslog as well. But for the second case of running borgmatic interactively, my guess is that borgmatic is detecting an interactive session and therefore refusing to log to syslog. I'm not sure exactly why your script isn't affected by this though. Maybe the act of piping makes it non-interactive. Anyway, the workaround for now is to run borgmatic non-interactively (e.g., from a cron job or systemd service) if you want it to actually log to syslog. Ultimately, I think the fix is to implement something like #665, so even if borgmatic's behavior differs based on whether it's run interactively, the user can still choose to override things and force it to log to syslog. So feel free to weigh in on that ticket!
witten added the
question / support
 label 2023-09-16 23:02:31 +00:00
witten commented 2023-09-16 23:03:18 +00:00
Owner
Copy Link

I think this one is answered, and any remaining work is in #665, but please let me know if that's not the case from your perspective.

I think this one is answered, and any remaining work is in #665, but please let me know if that's not the case from your perspective.
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
main
spot-check
1.8.10
1.8.9
1.8.8
1.8.7
1.8.6
1.8.5
1.8.4
1.8.3
1.8.2
1.8.1
1.8.0
1.7.15
1.7.14
1.7.13
1.7.12
1.7.11
1.7.10
1.7.9
1.7.8
1.7.7
1.7.6
1.7.5
1.7.4
1.7.3
1.7.2
1.7.1
1.7.0
1.6.6
1.6.5
1.6.4
1.6.3
1.6.2
1.6.1
1.6.0
1.5.24
1.5.23
1.5.22
1.5.21
1.5.20
1.5.19
1.5.18
1.5.17
1.5.16
1.5.15
1.5.14
1.5.13
1.5.12
1.5.11
1.5.10
1.5.9
1.5.8
1.5.7
1.5.7.dev0
1.5.6
1.5.5
1.5.4
1.5.3
1.5.2
1.5.1
1.5.0
1.4.22
1.4.21
1.4.20
1.4.19
1.4.18
1.4.17
1.4.16
1.4.15
1.4.14
1.4.13
1.4.12
1.4.11
1.4.10
1.4.9
1.4.8
1.4.7
1.4.6
1.4.5
1.4.4
1.4.3
1.4.2
1.4.1
1.4.0
1.3.26
1.3.25
1.3.24
1.3.23
1.3.22
1.3.21
1.3.20
1.3.19
1.3.18
1.3.17
1.3.16
1.3.15
1.3.14
1.3.13
1.3.12
1.3.11
1.3.10
1.3.9
1.3.8
1.3.7
1.3.6
1.3.5
1.3.4
1.3.3
1.3.2
1.3.1
1.3.0
1.2.18
1.2.17
1.2.16
1.2.15
1.2.14
1.2.13
1.2.12
1.2.11
1.2.10
1.2.9
1.2.8
1.2.7
1.2.6
1.2.5
1.2.4
1.2.3
1.2.2
1.2.1
1.2.0
1.1.15
1.1.14
1.1.13
1.1.12
1.1.11
1.1.10
1.1.9
1.1.7
1.1.6
1.1.5
1.1.4
1.1.3
1.1.2
1.1.1
1.1.0
1.0.3
1.0.2
1.0.1
1.0.0
0.1.8
0.1.7
0.1.6
0.1.5
0.1.4
0.1.3
0.1.2
0.1.1
0.1.0
0.0.7
0.0.6
0.0.5
0.0.4
0.0.3
0.0.2
Labels
Clear labels   
bug

   
data loss

   
design finalized

   
good first issue

   
new feature area

   
question / support

   
security

   
waiting for response
No Label
bug
data loss
design finalized
good first issue
new feature area
question / support
security
waiting for response
Milestone
Clear milestone
No items
No Milestone
Assignees
Clear assignees
No Assignees
2 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#749
No description provided.
Delete Branch "%!s(<nil>)"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?