TypeError in logging when using retcode 75 in actions #900

New issue

Closed

opened 2024-07-20 04:34:57 +00:00 by 2rs2ts · 2 comments

2rs2ts commented 2024-07-20 04:34:57 +00:00

Copy link

What I'm trying to do and why

I have some before_backup actions to check to make sure that the files I'm about to back up aren't in use.

before_backup:
    - bash -c 'if nc -v -w 1 -z myservice.local 8443 ; then exit 75 ; fi'

During my last backup, I got an exception because the test exited with the 75 retcode: TypeError: unsupported operand type(s) for +: 'CalledProcessError' and 'str'. After a couple retries, though, the nc command started failing (a good thing!) and the backup went as normal. So, I think this is just a problem with the logging code.

Steps to reproduce

Have a before_backup command that returns the 75 exit code; maybe having it also write something to stdout is necessary, I'm not sure.

Actual behavior

This is from my cron error mail; I think verbosity 2 isn't needed here, but I can repro with higher verbosity if requested.

/root/.config/borgmatic/config.yaml: Running 2 commands for pre-backup hook
Connection to myservice.local 8443 port [tcp/*] succeeded!
my-borg-db: Error running actions for repository
--- Logging error ---
Traceback (most recent call last):
File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 621, in log_error_records
raise error
File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 145, in run_configuration
yield from run_actions(
File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 330, in run_actions
yield from borgmatic.actions.create.run_create(
File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/actions/create.py", line 69, in run_create
borgmatic.hooks.command.execute_hook(
File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/hooks/command.py", line 69, in execute_hook
execute.execute_command(
File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/execute.py", line 312, in execute_command
log_outputs(
File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/execute.py", line 210, in log_outputs
raise subprocess.CalledProcessError(
subprocess.CalledProcessError: Command 'bash -c 'if nc -v -w 1 -z myservice.local 8443 ; then exit 75 ; fi'' returned non-zero exit status 75.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/usr/local/lib/python3.11/logging/__init__.py", line 1113, in emit
stream.write(msg + self.terminator)
~~~~^~~~~~~~~~~~~~~~~
TypeError: unsupported operand type(s) for +: 'CalledProcessError' and 'str'
Call stack:
File "/root/.local/bin/borgmatic", line 8, in <module>
sys.exit(main())
File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 922, in main
or list(collect_configuration_run_summary_logs(configs, config_paths, arguments))
File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 804, in collect_configuration_run_summary_logs
results = list(run_configuration(config_filename, config, config_paths, arguments))
File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 160, in run_configuration
tuple( # Consume the generator so as to trigger logging.
File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 642, in log_error_records
yield log_record(levelno=levelno, levelname=level_name, msg=error)
File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 599, in log_record
logger.handle(record)
File "/usr/local/lib/python3.11/logging/__init__.py", line 1644, in handle
self.callHandlers(record)
File "/usr/local/lib/python3.11/logging/__init__.py", line 1706, in callHandlers
hdlr.handle(record)
File "/usr/local/lib/python3.11/logging/__init__.py", line 978, in handle
self.emit(record)
File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/logger.py", line 76, in emit
self.log_level_to_handler[record.levelno].emit(record)
Message: CalledProcessError(75, "bash -c 'if nc -v -w 1 -z myservice.local 8443 ; then exit 75 ; fi'", 'Connection to myservice.local 8443 port [tcp/*] succeeded!')
Arguments: ()
my-borg-db: Retrying... attempt 1/3

Expected behavior

It Just Works™

Other notes / implementation ideas

This before_backup test has worked for forever, I haven't changed it in a long time. However, I recently upgraded a bunch of stuff in the jail I use for borgmatic, including:

• the python version (3.9 something to 3.11.9)
• borg version (not sure what it was before, might have been 1.1.x or 1.2.x)
• borgmatic version (also not sure what it was at before, but I'm pretty sure it was a 1.8.x version)
• the FreeBSD base for the jail (I think it was 13.2-RELEASE-p2, but it might have been a 13.1 version instead.)

I also switched from pip installing both borg and borgmatic, to using the BSD port for borg and pipx for borgmatic (pipx per your documentation's recommendation.)

As for how this is invoked, it's a cronjob, run as root, that does the following:

jexec ioc-borg /root/.local/bin/borgmatic --verbosity 1 --syslog-verbosity 1 --stats

I should note that on a macOS host that does a different backup job, I did not experience this issue. The test it does is different ([ ! -f ~/Library/myservice/myservice.pid ] || exit 75), but it still makes use of the retcode 75 trick and it uses the same log verbosity. That host is also running python 3.11 and borgmatic 1.8.13, but it's on borg 1.4.0, with all of these installed by homebrew (though I'm pretty sure the python version being used there is actually coming from pyenv globals.)

So, this could be a problem of my jail's setup, I'm not sure, but I double-checked and I don't think anything is amiss there; if it were something like the borgmatic code using the logging module from some other python version, I'd expect there to be a lot more wrong and for my backups to fail. I feel like it's more likely something to do with the way the logging module is used that's sensitive to something about the difference in the before_backup commands... maybe the fact that the nc-based one has output while the [-based one does not?

borgmatic version

1.8.13

borgmatic installation method

pipx install

Borg version

borg 1.2.8

Python version

Python 3.11.9

Database version (if applicable)

No response

Operating system and version

FreeBSD 13.2-RELEASE-p4

### What I'm trying to do and why I have some `before_backup` actions to check to make sure that the files I'm about to back up aren't in use. ```yaml before_backup: - bash -c 'if nc -v -w 1 -z myservice.local 8443 ; then exit 75 ; fi' ``` During my last backup, I got an exception because the test exited with the 75 retcode: `TypeError: unsupported operand type(s) for +: 'CalledProcessError' and 'str'`. After a couple retries, though, the `nc` command started failing (a good thing!) and the backup went as normal. So, I think this is just a problem with the logging code. ### Steps to reproduce Have a `before_backup` command that returns the 75 exit code; maybe having it also write something to stdout is necessary, I'm not sure. ### Actual behavior This is from my cron error mail; I think verbosity 2 isn't needed here, but I can repro with higher verbosity if requested. ``` /root/.config/borgmatic/config.yaml: Running 2 commands for pre-backup hook Connection to myservice.local 8443 port [tcp/*] succeeded! my-borg-db: Error running actions for repository --- Logging error --- Traceback (most recent call last): File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 621, in log_error_records raise error File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 145, in run_configuration yield from run_actions( File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 330, in run_actions yield from borgmatic.actions.create.run_create( File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/actions/create.py", line 69, in run_create borgmatic.hooks.command.execute_hook( File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/hooks/command.py", line 69, in execute_hook execute.execute_command( File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/execute.py", line 312, in execute_command log_outputs( File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/execute.py", line 210, in log_outputs raise subprocess.CalledProcessError( subprocess.CalledProcessError: Command 'bash -c 'if nc -v -w 1 -z myservice.local 8443 ; then exit 75 ; fi'' returned non-zero exit status 75. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/local/lib/python3.11/logging/__init__.py", line 1113, in emit stream.write(msg + self.terminator) ~~~~^~~~~~~~~~~~~~~~~ TypeError: unsupported operand type(s) for +: 'CalledProcessError' and 'str' Call stack: File "/root/.local/bin/borgmatic", line 8, in <module> sys.exit(main()) File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 922, in main or list(collect_configuration_run_summary_logs(configs, config_paths, arguments)) File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 804, in collect_configuration_run_summary_logs results = list(run_configuration(config_filename, config, config_paths, arguments)) File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 160, in run_configuration tuple( # Consume the generator so as to trigger logging. File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 642, in log_error_records yield log_record(levelno=levelno, levelname=level_name, msg=error) File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/commands/borgmatic.py", line 599, in log_record logger.handle(record) File "/usr/local/lib/python3.11/logging/__init__.py", line 1644, in handle self.callHandlers(record) File "/usr/local/lib/python3.11/logging/__init__.py", line 1706, in callHandlers hdlr.handle(record) File "/usr/local/lib/python3.11/logging/__init__.py", line 978, in handle self.emit(record) File "/root/.local/pipx/venvs/borgmatic/lib/python3.11/site-packages/borgmatic/logger.py", line 76, in emit self.log_level_to_handler[record.levelno].emit(record) Message: CalledProcessError(75, "bash -c 'if nc -v -w 1 -z myservice.local 8443 ; then exit 75 ; fi'", 'Connection to myservice.local 8443 port [tcp/*] succeeded!') Arguments: () my-borg-db: Retrying... attempt 1/3 ``` ### Expected behavior It Just Works™ ### Other notes / implementation ideas This `before_backup` test has worked for forever, I haven't changed it in a long time. However, I recently upgraded a bunch of stuff in the jail I use for borgmatic, including: * the python version (3.9 something to 3.11.9) * borg version (not sure what it was before, might have been 1.1.x or 1.2.x) * borgmatic version (also not sure what it was at before, but I'm pretty sure it was a 1.8.x version) * the FreeBSD base for the jail (I think it was 13.2-RELEASE-p2, but it might have been a 13.1 version instead.) I also switched from `pip install`ing both borg and borgmatic, to using the BSD port for borg and `pipx` for borgmatic (`pipx` per your documentation's recommendation.) As for how this is invoked, it's a cronjob, run as root, that does the following: ```bash jexec ioc-borg /root/.local/bin/borgmatic --verbosity 1 --syslog-verbosity 1 --stats ``` **I should note that on a macOS host that does a different backup job, I did not experience this issue.** The test it does is different (`[ ! -f ~/Library/myservice/myservice.pid ] || exit 75`), but it still makes use of the retcode 75 trick and it uses the same log verbosity. That host is also running python 3.11 and borgmatic 1.8.13, but it's on borg 1.4.0, with all of these installed by homebrew (though I'm pretty sure the python version being used there is actually coming from pyenv globals.) So, this could be a problem of my jail's setup, I'm not sure, but I double-checked and I don't think anything is amiss there; if it were something like the borgmatic code using the `logging` module from some other python version, I'd expect there to be a lot more wrong and for my backups to fail. I feel like it's more likely something to do with the way the logging module is used that's sensitive to something about the difference in the `before_backup` commands... maybe the fact that the `nc`-based one has output while the `[`-based one does not? ### borgmatic version 1.8.13 ### borgmatic installation method pipx install ### Borg version borg 1.2.8 ### Python version Python 3.11.9 ### Database version (if applicable) _No response_ ### Operating system and version FreeBSD 13.2-RELEASE-p4

witten added the

bug

label 2024-07-20 05:21:27 +00:00

witten commented 2024-07-20 05:21:45 +00:00

Owner

Copy link

Thank you for the super detailed bug report. The good news is this was already fixed in main prior to your ticket being filed and will be part of the next release! (In case you're curious, here are the changesets: d44dc93509 and 27e7ece2f5)

Thank you for the super detailed bug report. The good news is this was already fixed in main prior to your ticket being filed and will be part of the next release! (In case you're curious, here are the changesets: d44dc93509dc2baa4af36181fae0765438906ce5 and 27e7ece2f5e192be7b024598d1933f66eadc14ed)

witten closed this issue 2024-07-20 05:21:53 +00:00

witten commented 2024-08-30 00:46:53 +00:00

Owner

Copy link

Released in borgmatic 1.8.14!

Released in borgmatic 1.8.14!

Sign in to join this conversation.

No Branch/Tag specified

Branches Tags

main

parallel-borgmatic

command-hook-steps

2.1.7

2.1.6

2.1.5

2.1.4

2.1.3

2.1.2

2.1.1

2.1.0

2.0.13

2.0.12

2.0.11

2.0.10

2.0.9

2.0.8

2.0.7

2.0.6

2.0.5

2.0.4

2.0.3

2.0.2

2.0.1

2.0.0

1.9.14

1.9.13

1.9.12

1.9.11

1.9.10

1.9.9

1.9.8

1.9.7

1.9.6

1.9.5

1.9.4

1.9.3

1.9.2

1.9.1

1.9.0

1.8.14

1.8.13

1.8.12

1.8.11

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   

blocked

  

breaking

  

bug

  

data loss

  

design finalized

  

good first issue

  

new feature area

  

question / support

  

security

  

waiting for response

No labels

blocked

breaking

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

Subscribe

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#900

No description provided.