Inconsistent treatment of borg exit codes when using "retries" option #1170

Closed
opened 2025-10-27 01:57:01 +00:00 by dpantel · 7 comments

What I'm trying to do and why

When using the "retries" option in borgmatic, most of the time borg error exit codes are treated as warnings and upgraded to errors only if there is no success after retrying the set number of times. This seems like the correct action to me.

However, occasionally, the exit code is tagged as an error, despite there being more retries. This does not seem consistent to me, but perhaps I am missing something subtle.

Below are two log snippets,1 hour apart, demonstrating this behavior. Note the difference in the 4th line from the bottom.

Steps to reproduce

No response

Actual behavior

[2025-10-26 13:17:37,686] INFO: borgbase: Creating archive
[2025-10-26 13:17:37,810] INFO: using builtin fallback logging configuration
[2025-10-26 13:17:37,852] INFO: 33 self tests completed in 0.04 seconds
[2025-10-26 13:17:37,853] INFO: SSH command line: ['ssh', '....repo.borgbase.com', 'borg', 'serve', '--debug']
[2025-10-26 13:22:38,070] INFO: Remote: Connection to 154.9.154.202 port 22 timed out
[2025-10-26 13:22:38,072] INFO: Connection closed by remote host. Is borg working on the server?
[2025-10-26 13:22:38,072] INFO: Traceback (most recent call last):
[2025-10-26 13:22:38,072] INFO:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 5391, in main
[2025-10-26 13:22:38,072] INFO:     exit_code = archiver.run(args)
[2025-10-26 13:22:38,072] INFO:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 5309, in run
[2025-10-26 13:22:38,073] INFO:     rc = func(args)
[2025-10-26 13:22:38,073] INFO:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 169, in wrapper
[2025-10-26 13:22:38,073] INFO:     repository = RemoteRepository(location.omit_archive(), create=create, exclusive=argument(args, exclusive),
[2025-10-26 13:22:38,073] INFO:                                   lock_wait=self.lock_wait, lock=lock, append_only=append_only,
[2025-10-26 13:22:38,073] INFO:                                   make_parent_dirs=make_parent_dirs, args=args)
[2025-10-26 13:22:38,073] INFO:   File "/usr/lib/python3/dist-packages/borg/remote.py", line 594, in __init__
[2025-10-26 13:22:38,073] INFO:     raise ConnectionClosedWithHint('Is borg working on the server?') from None
[2025-10-26 13:22:38,073] INFO: borg.remote.ConnectionClosedWithHint: Connection closed by remote host. Is borg working on the server?
[2025-10-26 13:22:38,092] INFO: Platform: Linux nas 6.12.48+deb13-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.12.48-1 (2025-09-20) x86_64
[2025-10-26 13:22:38,092] INFO: Linux: Unknown Linux
[2025-10-26 13:22:38,092] INFO: Borg: 1.4.0  Python: CPython 3.13.5 msgpack: 1.0.3 fuse: pyfuse3 3.4.0 [pyfuse3,llfuse]
[2025-10-26 13:22:38,092] INFO: PID: 30250  CWD: /
[2025-10-26 13:22:38,092] INFO: sys.argv: ['/usr/bin/borg', 'create', '--patterns-from', '/tmp/borgmatic-_68zv770/borgmatic/tmpesfh0rjp', '--compression', 'auto,zstd',   '--debug', '--show-rc', 'ssh://....repo.borgbase.com/./repo::test.{now:%Y%m%dT%H%M}']
[2025-10-26 13:22:38,092] INFO: SSH_ORIGINAL_COMMAND: None
[2025-10-26 13:22:38,092] ERROR: terminating with error status, rc 81
[2025-10-26 13:22:38,092] WARNING: borgbase: Error running actions for repository
[2025-10-26 13:22:38,092] WARNING: borgbase: Command 'borg create --patterns-from /tmp/borgmatic-_68zv770/borgmatic/tmpesfh0rjp --compression auto,zstd --debug --show-   rc ssh://....repo.borgbase.com/./repo::test.{now:%Y%m%dT%H%M}' returned non-zero exit status 81.
[2025-10-26 13:22:38,092] WARNING: borgbase: Retrying... attempt 1/3
[2025-10-26 14:17:38,600] INFO: using builtin fallback logging configuration
[2025-10-26 14:17:38,639] INFO: 33 self tests completed in 0.04 seconds
[2025-10-26 14:17:38,640] INFO: SSH command line: ['ssh', '....repo.borgbase.com', 'borg', 'serve', '--debug']
[2025-10-26 14:22:38,853] INFO: Remote: Connection to 154.9.154.202 port 22 timed out
[2025-10-26 14:22:38,856] INFO: Connection closed by remote host. Is borg working on the server?
[2025-10-26 14:22:38,856] INFO: Traceback (most recent call last):
[2025-10-26 14:22:38,856] INFO:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 5391, in main
[2025-10-26 14:22:38,856] INFO:     exit_code = archiver.run(args)
[2025-10-26 14:22:38,856] INFO:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 5309, in run
[2025-10-26 14:22:38,856] INFO:     rc = func(args) 
[2025-10-26 14:22:38,856] INFO:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 169, in wrapper
[2025-10-26 14:22:38,856] INFO:     repository = RemoteRepository(location.omit_archive(), create=create, exclusive=argument(args, exclusive),
[2025-10-26 14:22:38,856] INFO:                                   lock_wait=self.lock_wait, lock=lock, append_only=append_only,
[2025-10-26 14:22:38,856] INFO:                                   make_parent_dirs=make_parent_dirs, args=args)
[2025-10-26 14:22:38,856] INFO:   File "/usr/lib/python3/dist-packages/borg/remote.py", line 594, in __init__
[2025-10-26 14:22:38,856] INFO:     raise ConnectionClosedWithHint('Is borg working on the server?') from None
[2025-10-26 14:22:38,856] INFO: borg.remote.ConnectionClosedWithHint: Connection closed by remote host. Is borg working on the server?
[2025-10-26 14:22:38,856] INFO: Platform: Linux nas 6.12.48+deb13-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.12.48-1 (2025-09-20) x86_64
[2025-10-26 14:22:38,856] INFO: Linux: Unknown Linux
[2025-10-26 14:22:38,856] INFO: Borg: 1.4.0  Python: CPython 3.13.5 msgpack: 1.0.3 fuse: pyfuse3 3.4.0 [pyfuse3,llfuse]
[2025-10-26 14:22:38,856] INFO: PID: 30612  CWD: /
[2025-10-26 14:22:38,856] INFO: sys.argv: ['/usr/bin/borg', 'create', '--patterns-from', '/tmp/borgmatic-4caq036e/borgmatic/tmpd_yl6m7w', '--compression', 'auto,zstd',   '--debug', '--show-rc', 'ssh://....repo.borgbase.com/./repo::test.{now:%Y%m%dT%H%M}']
[2025-10-26 14:22:38,856] INFO: SSH_ORIGINAL_COMMAND: None 
[2025-10-26 14:22:38,856] INFO: terminating with error status, rc 81
[2025-10-26 14:22:38,876] WARNING: borgbase: Error running actions for repository
[2025-10-26 14:22:38,876] WARNING: borgbase: Command 'borg create --patterns-from /tmp/borgmatic-4caq036e/borgmatic/tmpd_yl6m7w --compression auto,zstd --debug --show-   rc ssh://....repo.borgbase.com/./repo::test.{now:%Y%m%dT%H%M}' returned non-zero exit status 81.
[2025-10-26 14:22:38,876] WARNING: borgbase: Retrying... attempt 1/3

Expected behavior

No response

Other notes / implementation ideas

No response

borgmatic version

1.9.14

borgmatic installation method

debian repo

Borg version

1.4.0

Python version

3.13.5

Database version (if applicable)

No response

Operating system and version

debian 13.1 (trixie)

### What I'm trying to do and why When using the "retries" option in borgmatic, most of the time borg error exit codes are treated as warnings and upgraded to errors only if there is no success after retrying the set number of times. This seems like the correct action to me. However, occasionally, the exit code is tagged as an error, despite there being more retries. This does not seem consistent to me, but perhaps I am missing something subtle. Below are two log snippets,1 hour apart, demonstrating this behavior. Note the difference in the 4th line from the bottom. ### Steps to reproduce _No response_ ### Actual behavior ``` [2025-10-26 13:17:37,686] INFO: borgbase: Creating archive [2025-10-26 13:17:37,810] INFO: using builtin fallback logging configuration [2025-10-26 13:17:37,852] INFO: 33 self tests completed in 0.04 seconds [2025-10-26 13:17:37,853] INFO: SSH command line: ['ssh', '....repo.borgbase.com', 'borg', 'serve', '--debug'] [2025-10-26 13:22:38,070] INFO: Remote: Connection to 154.9.154.202 port 22 timed out [2025-10-26 13:22:38,072] INFO: Connection closed by remote host. Is borg working on the server? [2025-10-26 13:22:38,072] INFO: Traceback (most recent call last): [2025-10-26 13:22:38,072] INFO: File "/usr/lib/python3/dist-packages/borg/archiver.py", line 5391, in main [2025-10-26 13:22:38,072] INFO: exit_code = archiver.run(args) [2025-10-26 13:22:38,072] INFO: File "/usr/lib/python3/dist-packages/borg/archiver.py", line 5309, in run [2025-10-26 13:22:38,073] INFO: rc = func(args) [2025-10-26 13:22:38,073] INFO: File "/usr/lib/python3/dist-packages/borg/archiver.py", line 169, in wrapper [2025-10-26 13:22:38,073] INFO: repository = RemoteRepository(location.omit_archive(), create=create, exclusive=argument(args, exclusive), [2025-10-26 13:22:38,073] INFO: lock_wait=self.lock_wait, lock=lock, append_only=append_only, [2025-10-26 13:22:38,073] INFO: make_parent_dirs=make_parent_dirs, args=args) [2025-10-26 13:22:38,073] INFO: File "/usr/lib/python3/dist-packages/borg/remote.py", line 594, in __init__ [2025-10-26 13:22:38,073] INFO: raise ConnectionClosedWithHint('Is borg working on the server?') from None [2025-10-26 13:22:38,073] INFO: borg.remote.ConnectionClosedWithHint: Connection closed by remote host. Is borg working on the server? [2025-10-26 13:22:38,092] INFO: Platform: Linux nas 6.12.48+deb13-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.12.48-1 (2025-09-20) x86_64 [2025-10-26 13:22:38,092] INFO: Linux: Unknown Linux [2025-10-26 13:22:38,092] INFO: Borg: 1.4.0 Python: CPython 3.13.5 msgpack: 1.0.3 fuse: pyfuse3 3.4.0 [pyfuse3,llfuse] [2025-10-26 13:22:38,092] INFO: PID: 30250 CWD: / [2025-10-26 13:22:38,092] INFO: sys.argv: ['/usr/bin/borg', 'create', '--patterns-from', '/tmp/borgmatic-_68zv770/borgmatic/tmpesfh0rjp', '--compression', 'auto,zstd', '--debug', '--show-rc', 'ssh://....repo.borgbase.com/./repo::test.{now:%Y%m%dT%H%M}'] [2025-10-26 13:22:38,092] INFO: SSH_ORIGINAL_COMMAND: None [2025-10-26 13:22:38,092] ERROR: terminating with error status, rc 81 [2025-10-26 13:22:38,092] WARNING: borgbase: Error running actions for repository [2025-10-26 13:22:38,092] WARNING: borgbase: Command 'borg create --patterns-from /tmp/borgmatic-_68zv770/borgmatic/tmpesfh0rjp --compression auto,zstd --debug --show- rc ssh://....repo.borgbase.com/./repo::test.{now:%Y%m%dT%H%M}' returned non-zero exit status 81. [2025-10-26 13:22:38,092] WARNING: borgbase: Retrying... attempt 1/3 ``` ``` [2025-10-26 14:17:38,600] INFO: using builtin fallback logging configuration [2025-10-26 14:17:38,639] INFO: 33 self tests completed in 0.04 seconds [2025-10-26 14:17:38,640] INFO: SSH command line: ['ssh', '....repo.borgbase.com', 'borg', 'serve', '--debug'] [2025-10-26 14:22:38,853] INFO: Remote: Connection to 154.9.154.202 port 22 timed out [2025-10-26 14:22:38,856] INFO: Connection closed by remote host. Is borg working on the server? [2025-10-26 14:22:38,856] INFO: Traceback (most recent call last): [2025-10-26 14:22:38,856] INFO: File "/usr/lib/python3/dist-packages/borg/archiver.py", line 5391, in main [2025-10-26 14:22:38,856] INFO: exit_code = archiver.run(args) [2025-10-26 14:22:38,856] INFO: File "/usr/lib/python3/dist-packages/borg/archiver.py", line 5309, in run [2025-10-26 14:22:38,856] INFO: rc = func(args) [2025-10-26 14:22:38,856] INFO: File "/usr/lib/python3/dist-packages/borg/archiver.py", line 169, in wrapper [2025-10-26 14:22:38,856] INFO: repository = RemoteRepository(location.omit_archive(), create=create, exclusive=argument(args, exclusive), [2025-10-26 14:22:38,856] INFO: lock_wait=self.lock_wait, lock=lock, append_only=append_only, [2025-10-26 14:22:38,856] INFO: make_parent_dirs=make_parent_dirs, args=args) [2025-10-26 14:22:38,856] INFO: File "/usr/lib/python3/dist-packages/borg/remote.py", line 594, in __init__ [2025-10-26 14:22:38,856] INFO: raise ConnectionClosedWithHint('Is borg working on the server?') from None [2025-10-26 14:22:38,856] INFO: borg.remote.ConnectionClosedWithHint: Connection closed by remote host. Is borg working on the server? [2025-10-26 14:22:38,856] INFO: Platform: Linux nas 6.12.48+deb13-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.12.48-1 (2025-09-20) x86_64 [2025-10-26 14:22:38,856] INFO: Linux: Unknown Linux [2025-10-26 14:22:38,856] INFO: Borg: 1.4.0 Python: CPython 3.13.5 msgpack: 1.0.3 fuse: pyfuse3 3.4.0 [pyfuse3,llfuse] [2025-10-26 14:22:38,856] INFO: PID: 30612 CWD: / [2025-10-26 14:22:38,856] INFO: sys.argv: ['/usr/bin/borg', 'create', '--patterns-from', '/tmp/borgmatic-4caq036e/borgmatic/tmpd_yl6m7w', '--compression', 'auto,zstd', '--debug', '--show-rc', 'ssh://....repo.borgbase.com/./repo::test.{now:%Y%m%dT%H%M}'] [2025-10-26 14:22:38,856] INFO: SSH_ORIGINAL_COMMAND: None [2025-10-26 14:22:38,856] INFO: terminating with error status, rc 81 [2025-10-26 14:22:38,876] WARNING: borgbase: Error running actions for repository [2025-10-26 14:22:38,876] WARNING: borgbase: Command 'borg create --patterns-from /tmp/borgmatic-4caq036e/borgmatic/tmpd_yl6m7w --compression auto,zstd --debug --show- rc ssh://....repo.borgbase.com/./repo::test.{now:%Y%m%dT%H%M}' returned non-zero exit status 81. [2025-10-26 14:22:38,876] WARNING: borgbase: Retrying... attempt 1/3 ``` ### Expected behavior _No response_ ### Other notes / implementation ideas _No response_ ### borgmatic version 1.9.14 ### borgmatic installation method debian repo ### Borg version 1.4.0 ### Python version 3.13.5 ### Database version (if applicable) _No response_ ### Operating system and version debian 13.1 (trixie)
Owner

I'm not sure why this behavior would differ from one borgmatic run to another, but a Borg exit code 81 getting tagged as an error log level is the expected behavior. The rationale is that: 1. Borg exiting with code 81 is an error from Borg's perspective, and 2. borgmatic's decision to put the error on hold and work through the retries is only made after that Borg error is logged.

A question for you though: Is the error log level causing issues for you? Or is the problem just that the behavior is inconsistent?

For the latter issue, if possible I'd recommend upgrading borgmatic (ideally to 2.0.10+) to see if that helps. If not, we can diagnose from there.

Thank you!

I'm not sure why this behavior would differ from one borgmatic run to another, but a Borg exit code 81 getting tagged as an error log level is the expected behavior. The rationale is that: 1. Borg exiting with code 81 *is* an error from Borg's perspective, and 2. borgmatic's decision to put the error on hold and work through the retries is only made *after* that Borg error is logged. A question for you though: Is the error log level causing issues for you? Or is the problem just that the behavior is inconsistent? For the latter issue, if possible I'd recommend upgrading borgmatic (ideally to 2.0.10+) to see if that helps. If not, we can diagnose from there. Thank you!
Owner

Ooh, I managed to get a repro of the inconsistent log levels with 2.0.10/main, so you don't need to upgrade to see if that fixes it. (It still might be a good idea to upgrade though because any fix will be on a newer version of borgmatic.)

I'll try to dig into this and see what's going on with the log level.

Ooh, I managed to get a repro of the inconsistent log levels with 2.0.10/main, so you don't need to upgrade to see if that fixes it. (It still might be a good idea to upgrade though because any fix will be on a newer version of borgmatic.) I'll try to dig into this and see what's going on with the log level.
Owner

So here's what appears to be going on... The inconsistent logging is due to a race condition. During the normal course of operation, borgmatic consumes Borg's log output line-by-line and turns it into borgmatic log messages. Any output lines (like terminating with error status, rc 81) that borgmatic receives before Borg exits get logged at log level INFO, because we don't yet have an official exit status at that point (even if we have a description of one). But if borgmatic happens to receive that output line after Borg has exited, then we know for sure that an error has occurred—and therefore log that line with log level ERROR. Hence the inconsistent behavior.

I'm not yet sure what to do about this. One option is always logging as INFO for both of the two cases described above, but that might have the side effect of making Borg errors harder to see in borgmatic output. There is the borgmatic summary logged at the end which elevates Borg log message log levels to error as needed, so maybe that's sufficient.

So here's what appears to be going on... The inconsistent logging is due to a race condition. During the normal course of operation, borgmatic consumes Borg's log output line-by-line and turns it into borgmatic log messages. Any output lines (like `terminating with error status, rc 81`) that borgmatic receives *before* Borg exits get logged at log level `INFO`, because we don't yet have an official exit status at that point (even if we have a description of one). But if borgmatic happens to receive that output line *after* Borg has exited, then we know for sure that an error has occurred—and therefore log that line with log level `ERROR`. Hence the inconsistent behavior. I'm not yet sure what to do about this. One option is always logging as `INFO` for both of the two cases described above, but that might have the side effect of making Borg errors harder to see in borgmatic output. There is the borgmatic summary logged at the end which elevates Borg log message log levels to error as needed, so maybe that's sufficient.
Author

That makes a lot of sense.

I think the decision of how to treat this hangs heavily on the actual issue borg is having. IMO, if it's a"recoverable" error, such as intermittent connection issues, and borgmatic has retries available, the borg error is more of a "warning". If it's an unrecoverable error, then borgmatic should throw an error and halt that config file. That decision would be made easier, if we had all the borg error exit codes defined, but I know that's a work in progress.

Oh well. Thank you for looking into this. Shall we close this?

That makes a lot of sense. I think the decision of how to treat this hangs heavily on the actual issue borg is having. IMO, if it's a"recoverable" error, such as intermittent connection issues, and borgmatic has retries available, the borg error is more of a "warning". If it's an unrecoverable error, then borgmatic should throw an error and halt that config file. That decision would be made easier, if we had all the borg error exit codes defined, but I know that's a work in progress. Oh well. Thank you for looking into this. Shall we close this?
Owner

I think the decision of how to treat this hangs heavily on the actual issue borg is having. IMO, if it's a"recoverable" error, such as intermittent connection issues, and borgmatic has retries available, the borg error is more of a "warning". If it's an unrecoverable error, then borgmatic should throw an error and halt that config file. That decision would be made easier, if we had all the borg error exit codes defined, but I know that's a work in progress.

Yeah, for purposes of retrying, borgmatic doesn't currently draw a distinction between recoverable and unrecoverable Borg errors. Maybe that suggests a potential new feature: A way to define what exit codes should be retried, similar to (or as part of) the separate warning/errors customization feature.

Oh well. Thank you for looking into this. Shall we close this?

Not quite yet. I'm going to try to at least make the behavior consistent if not 100% correct. 😄

> I think the decision of how to treat this hangs heavily on the actual issue borg is having. IMO, if it's a"recoverable" error, such as intermittent connection issues, and borgmatic has retries available, the borg error is more of a "warning". If it's an unrecoverable error, then borgmatic should throw an error and halt that config file. That decision would be made easier, if we had all the borg error exit codes defined, but I know that's a work in progress. Yeah, for purposes of retrying, borgmatic doesn't currently draw a distinction between recoverable and unrecoverable Borg errors. Maybe that suggests a potential new feature: A way to define what exit codes should be retried, similar to (or as part of) the separate [warning/errors customization feature](https://torsion.org/borgmatic/how-to/customize-warnings-and-errors/). > Oh well. Thank you for looking into this. Shall we close this? Not quite yet. I'm going to try to at least make the behavior consistent if not 100% correct. 😄
Owner

Okay, I switched the ERROR log level to INFO for consistency, so now it shows up at the same log level regardless of whether the log entry comes in before/after Borg exits.

It does have the unfortunate side effect of making Borg's exit status log a little harder to see since it's no longer (sometimes) ERROR, but I rationalize that away by the fact that the summary at the bottom does still mark everything as ERROR.

This will be part of the next release. Thanks for filing this!

Okay, I switched the `ERROR` log level to `INFO` for consistency, so now it shows up at the same log level regardless of whether the log entry comes in before/after Borg exits. It does have the unfortunate side effect of making Borg's exit status log a little harder to see since it's no longer (sometimes) `ERROR`, but I rationalize that away by the fact that the summary at the bottom does still mark everything as `ERROR`. This will be part of the next release. Thanks for filing this!
Owner

Released in borgmatic 2.0.11!

Released in borgmatic 2.0.11!
Sign in to join this conversation.
No milestone
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#1170
No description provided.