spot checking crashes borgmatic: OSError: [Errno 90] Message too long #1089

Closed
opened 2025-05-05 06:58:16 +00:00 by freggy · 7 comments

What I'm trying to do and why

Running spot checking on one specific server which has several directories with a lot of files (100 000 files).

Steps to reproduce

No response

Actual behavior

May 03 09:01:56 hostname borgmatic[3777729]: CRITICAL backuphost: Error running actions for repository
May 03 09:01:57 hostname borgmatic[3959204]: [71B blob data]
May 03 09:01:57 hostname borgmatic[3777729]: --- Logging error ---
May 03 09:01:57 hostname borgmatic[3777729]: Traceback (most recent call last):
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 641, in log_error_records
May 03 09:01:57 hostname borgmatic[3777729]:     raise error
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 150, in run_configuration
May 03 09:01:57 hostname borgmatic[3777729]:     yield from run_actions(
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 372, in run_actions
May 03 09:01:57 hostname borgmatic[3777729]:     borgmatic.actions.check.run_check(
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3/dist-packages/borgmatic/actions/check.py", line 765, in run_check
May 03 09:01:57 hostname borgmatic[3777729]:     spot_check(
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3/dist-packages/borgmatic/actions/check.py", line 652, in spot_check
May 03 09:01:57 hostname borgmatic[3777729]:     failing_paths = compare_spot_check_hashes(
May 03 09:01:57 hostname borgmatic[3777729]:                     ^^^^^^^^^^^^^^^^^^^^^^^^^^
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3/dist-packages/borgmatic/actions/check.py", line 509, in compare_spot_check_hashes
May 03 09:01:57 hostname borgmatic[3777729]:     hash_output = borgmatic.execute.execute_command_and_capture_output(
May 03 09:01:57 hostname borgmatic[3777729]:                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3/dist-packages/borgmatic/execute.py", line 361, in execute_command_and_capture_output
May 03 09:01:57 hostname borgmatic[3777729]:     output = subprocess.check_output(
May 03 09:01:57 hostname borgmatic[3777729]:              ^^^^^^^^^^^^^^^^^^^^^^^^
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3.11/subprocess.py", line 466, in check_output
May 03 09:01:57 hostname borgmatic[3777729]:     return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
May 03 09:01:57 hostname borgmatic[3777729]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3.11/subprocess.py", line 571, in run
May 03 09:01:57 hostname borgmatic[3777729]:     raise CalledProcessError(retcode, process.args,
May 03 09:01:57 hostname borgmatic[3777729]: subprocess.CalledProcessError: Command '('xxh64sum', '/foo', '/bar', '/cut/a/huge/list/of/files/here')' returned non-zero exit status 1.
May 03 09:01:57 hostname borgmatic[3777729]: During handling of the above exception, another exception occurred:
May 03 09:01:57 hostname borgmatic[3777729]: Traceback (most recent call last):
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3.11/logging/handlers.py", line 1007, in emit
May 03 09:01:57 hostname borgmatic[3777729]:     self.socket.send(msg)
May 03 09:01:57 hostname borgmatic[3777729]: OSError: [Errno 90] Message too long
May 03 09:01:57 hostname borgmatic[3777729]: During handling of the above exception, another exception occurred:
May 03 09:01:57 hostname borgmatic[3777729]: Traceback (most recent call last):
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3.11/logging/handlers.py", line 1011, in emit
May 03 09:01:57 hostname borgmatic[3777729]:     self.socket.send(msg)
May 03 09:01:57 hostname borgmatic[3777729]: OSError: [Errno 90] Message too long
May 03 09:01:57 hostname borgmatic[3777729]: Call stack:
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/bin/borgmatic", line 8, in <module>
May 03 09:01:57 hostname borgmatic[3777729]:     sys.exit(main())
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 956, in main
May 03 09:01:57 hostname borgmatic[3777729]:     or list(collect_configuration_run_summary_logs(configs, config_paths, arguments))
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 832, in collect_configuration_run_summary_logs
May 03 09:01:57 hostname borgmatic[3777729]:     results = list(run_configuration(config_filename, config, config_paths, arguments))
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 179, in run_configuration
May 03 09:01:57 hostname borgmatic[3777729]:     yield from log_error_records(
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 662, in log_error_records
May 03 09:01:57 hostname borgmatic[3777729]:     yield log_record(levelno=levelno, levelname=level_name, msg=str(error))
May 03 09:01:57 hostname borgmatic[3777729]:   File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 616, in log_record
May 03 09:01:57 hostname borgmatic[3777729]:     logger.handle(record)

Expected behavior

No response

Other notes / implementation ideas

Configuration of spot check:

checks:
    - name: spot
      frequency: 6 days
      only_run_on:
          - weekend
      count_tolerance_percentage: 10
      data_sample_percentage: 1
      data_tolerance_percentage: 0.5

The system on which this happens, has several directories with a very large amount of files (around 100000 files in one directory are possible). This does not happen on systems which don't have such large amount of files.

borgmatic version

1.9.14

borgmatic installation method

Rebuilt Debian Trxie (testing) package on Debian 12 Bookworm

Borg version

1.2.4

Python version

3.11.2

Database version (if applicable)

No response

Operating system and version

Debian 12 Bookworm

### What I'm trying to do and why Running spot checking on one specific server which has several directories with a lot of files (100 000 files). ### Steps to reproduce _No response_ ### Actual behavior ``` May 03 09:01:56 hostname borgmatic[3777729]: CRITICAL backuphost: Error running actions for repository May 03 09:01:57 hostname borgmatic[3959204]: [71B blob data] May 03 09:01:57 hostname borgmatic[3777729]: --- Logging error --- May 03 09:01:57 hostname borgmatic[3777729]: Traceback (most recent call last): May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 641, in log_error_records May 03 09:01:57 hostname borgmatic[3777729]: raise error May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 150, in run_configuration May 03 09:01:57 hostname borgmatic[3777729]: yield from run_actions( May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 372, in run_actions May 03 09:01:57 hostname borgmatic[3777729]: borgmatic.actions.check.run_check( May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3/dist-packages/borgmatic/actions/check.py", line 765, in run_check May 03 09:01:57 hostname borgmatic[3777729]: spot_check( May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3/dist-packages/borgmatic/actions/check.py", line 652, in spot_check May 03 09:01:57 hostname borgmatic[3777729]: failing_paths = compare_spot_check_hashes( May 03 09:01:57 hostname borgmatic[3777729]: ^^^^^^^^^^^^^^^^^^^^^^^^^^ May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3/dist-packages/borgmatic/actions/check.py", line 509, in compare_spot_check_hashes May 03 09:01:57 hostname borgmatic[3777729]: hash_output = borgmatic.execute.execute_command_and_capture_output( May 03 09:01:57 hostname borgmatic[3777729]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3/dist-packages/borgmatic/execute.py", line 361, in execute_command_and_capture_output May 03 09:01:57 hostname borgmatic[3777729]: output = subprocess.check_output( May 03 09:01:57 hostname borgmatic[3777729]: ^^^^^^^^^^^^^^^^^^^^^^^^ May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3.11/subprocess.py", line 466, in check_output May 03 09:01:57 hostname borgmatic[3777729]: return run(*popenargs, stdout=PIPE, timeout=timeout, check=True, May 03 09:01:57 hostname borgmatic[3777729]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3.11/subprocess.py", line 571, in run May 03 09:01:57 hostname borgmatic[3777729]: raise CalledProcessError(retcode, process.args, May 03 09:01:57 hostname borgmatic[3777729]: subprocess.CalledProcessError: Command '('xxh64sum', '/foo', '/bar', '/cut/a/huge/list/of/files/here')' returned non-zero exit status 1. May 03 09:01:57 hostname borgmatic[3777729]: During handling of the above exception, another exception occurred: May 03 09:01:57 hostname borgmatic[3777729]: Traceback (most recent call last): May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3.11/logging/handlers.py", line 1007, in emit May 03 09:01:57 hostname borgmatic[3777729]: self.socket.send(msg) May 03 09:01:57 hostname borgmatic[3777729]: OSError: [Errno 90] Message too long May 03 09:01:57 hostname borgmatic[3777729]: During handling of the above exception, another exception occurred: May 03 09:01:57 hostname borgmatic[3777729]: Traceback (most recent call last): May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3.11/logging/handlers.py", line 1011, in emit May 03 09:01:57 hostname borgmatic[3777729]: self.socket.send(msg) May 03 09:01:57 hostname borgmatic[3777729]: OSError: [Errno 90] Message too long May 03 09:01:57 hostname borgmatic[3777729]: Call stack: May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/bin/borgmatic", line 8, in <module> May 03 09:01:57 hostname borgmatic[3777729]: sys.exit(main()) May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 956, in main May 03 09:01:57 hostname borgmatic[3777729]: or list(collect_configuration_run_summary_logs(configs, config_paths, arguments)) May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 832, in collect_configuration_run_summary_logs May 03 09:01:57 hostname borgmatic[3777729]: results = list(run_configuration(config_filename, config, config_paths, arguments)) May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 179, in run_configuration May 03 09:01:57 hostname borgmatic[3777729]: yield from log_error_records( May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 662, in log_error_records May 03 09:01:57 hostname borgmatic[3777729]: yield log_record(levelno=levelno, levelname=level_name, msg=str(error)) May 03 09:01:57 hostname borgmatic[3777729]: File "/usr/lib/python3/dist-packages/borgmatic/commands/borgmatic.py", line 616, in log_record May 03 09:01:57 hostname borgmatic[3777729]: logger.handle(record) ``` ### Expected behavior _No response_ ### Other notes / implementation ideas Configuration of spot check: ``` checks: - name: spot frequency: 6 days only_run_on: - weekend count_tolerance_percentage: 10 data_sample_percentage: 1 data_tolerance_percentage: 0.5 ``` The system on which this happens, has several directories with a very large amount of files (around 100000 files in one directory are possible). This does not happen on systems which don't have such large amount of files. ### borgmatic version 1.9.14 ### borgmatic installation method Rebuilt Debian Trxie (testing) package on Debian 12 Bookworm ### Borg version 1.2.4 ### Python version 3.11.2 ### Database version (if applicable) _No response_ ### Operating system and version Debian 12 Bookworm
Owner

Thanks for filing this. The interesting thing is that the spot check code already batches calls to the xxh64sum command, feeding it no more than 10,000 files per call even if you've got hundreds of thousands. But it looks like that xxh64sum command is for some reason erroring anyway, and then the logging of that error blows up as well, because the log line is too big for your logging backend. (The logging of commands is already truncated to deal with exactly this sort of thing, but that doesn't help with traceback messages.)

So the question is why xxh64sum is failing. One idea is to try editing borgmatic's hard-coded number of files passed to xxh64sum per call. If you're game to try changing that in the source code, you'd do that by opening /usr/lib/python3/dist-packages/borgmatic/actions/check.py as root and changing SAMPLE_PATHS_SUBSET_COUNT to a lower number like 1000 or even 100.

If that "fixes" the problem, then that indicates that borgmatic was giving too many files to xxh64sum, perhaps too many for whatever shell you're using. (Incidentally, what shell are you using?) If that doesn't fix the problem, then that indicates there's some other reason why xxh64sum is failing. In which case you could try copy and pasting the logged xxh64sum command and running it to see if you can reproduce the problem outside of borgmatic and produce a more useful error message. But that might not even be necessary, because with a lower number of files passed to the command, logging may be able to display the full error without itself erroring.

Thanks for filing this. The interesting thing is that the spot check code already batches calls to the `xxh64sum` command, feeding it no more than 10,000 files per call even if you've got hundreds of thousands. But it looks like that `xxh64sum` command is for some reason erroring anyway, and then the logging of that error blows up as well, because the log line is too big for your logging backend. (The logging of commands is already truncated to deal with exactly this sort of thing, but that doesn't help with traceback messages.) So the question is why `xxh64sum` is failing. One idea is to try editing borgmatic's hard-coded number of files passed to `xxh64sum` per call. If you're game to try changing that in the source code, you'd do that by opening `/usr/lib/python3/dist-packages/borgmatic/actions/check.py` as root and changing `SAMPLE_PATHS_SUBSET_COUNT` to a lower number like `1000` or even `100`. If that "fixes" the problem, then that indicates that borgmatic was giving too many files to `xxh64sum`, perhaps too many for whatever shell you're using. (Incidentally, what shell are you using?) If that doesn't fix the problem, then that indicates there's some other reason why `xxh64sum` is failing. In which case you could try copy and pasting the logged `xxh64sum` command and running it to see if you can reproduce the problem outside of borgmatic and produce a more useful error message. But that might not even be necessary, because with a lower number of files passed to the command, logging may be able to display the full error without itself erroring.
Author

I suspect we are hitting one of these limits:

# xargs --show-limits
Your environment variables take up 2247 bytes
POSIX upper limit on argument length (this system): 2092857
POSIX smallest allowable upper limit on argument length (all systems): 4096
Maximum length of command we could actually use: 2090610
Size of command buffer we are actually using: 131072
Maximum parallelism (--max-procs must be no greater): 2147483647

Many of the files have a path length between 100 to 200 characters.

I'm using bash.

I'll try lowering SAMPLE_PATHS_SUBSET_COUNT

I suspect we are hitting one of these limits: ``` # xargs --show-limits Your environment variables take up 2247 bytes POSIX upper limit on argument length (this system): 2092857 POSIX smallest allowable upper limit on argument length (all systems): 4096 Maximum length of command we could actually use: 2090610 Size of command buffer we are actually using: 131072 Maximum parallelism (--max-procs must be no greater): 2147483647 ``` Many of the files have a path length between 100 to 200 characters. I'm using bash. I'll try lowering SAMPLE_PATHS_SUBSET_COUNT
Owner

Yeah, good insight there about those limits. Let me know what you find!

Yeah, good insight there about those limits. Let me know what you find!
Author

Tried to reproduce it by running
# systemd-run -p LoadCredentialEncrypted=borgmatic:/etc/credstore.encrypted/borgmatic/ borgmatic check -v 2 --only spot --progress --repo backup --force
But after 24 hours it's still running and no errors. Maybe it requires a lucky combination of long paths to trigger.

I think I will just disable spot checking, as I'm not sure this is really useful on this system with such a large amount of files, where only a very tiny part of files could be checked if I don't want this to take so much time.

Tried to reproduce it by running `# systemd-run -p LoadCredentialEncrypted=borgmatic:/etc/credstore.encrypted/borgmatic/ borgmatic check -v 2 --only spot --progress --repo backup --force` But after 24 hours it's still running and no errors. Maybe it requires a lucky combination of long paths to trigger. I think I will just disable spot checking, as I'm not sure this is really useful on this system with such a large amount of files, where only a very tiny part of files could be checked if I don't want this to take so much time.
Owner

Thanks for trying to repro this. But yeah, spot checks are probabilistic by their nature, so one might need to run it several times to trigger the "lucky" combination of long paths—or simply raise SAMPLE_PATHS_SUBSET_COUNT to an ungodly number. I can understand though if you don't want to bother with the spot check on that system.

I'll still leave this ticket open though to see if I can come up with a repro here; if possible, I'd like the spot check to be more reliable rather than less... It's conceivable that lowering SAMPLE_PATHS_SUBSET_COUNT could "solve" the issue on most systems. I might even be able to catch the error and display a helpful error message.

Thanks for trying to repro this. But yeah, spot checks are probabilistic by their nature, so one might need to run it several times to trigger the "lucky" combination of long paths—or simply raise `SAMPLE_PATHS_SUBSET_COUNT` to an ungodly number. I can understand though if you don't want to bother with the spot check on that system. I'll still leave this ticket open though to see if I can come up with a repro here; if possible, I'd like the spot check to be more reliable rather than less... It's conceivable that lowering `SAMPLE_PATHS_SUBSET_COUNT` could "solve" the issue on most systems. I might even be able to catch the error and display a helpful error message.
Owner

Welp, I can't seem to repro this on my system, even with a million files in a directory, SAMPLE_PATHS_SUBSET_COUNT raised by a couple orders of magnitude, and the xxh64sum command deliberately failing. So what I'll do is just arbitrarily lower SAMPLE_PATHS_SUBSET_COUNT by half and hope for the best. I'd be happy to revisit though if anyone has more repro info.

Welp, I can't seem to repro this on my system, even with a million files in a directory, `SAMPLE_PATHS_SUBSET_COUNT` raised by a couple orders of magnitude, and the `xxh64sum` command deliberately failing. So what I'll do is just arbitrarily lower `SAMPLE_PATHS_SUBSET_COUNT` by half and hope for the best. I'd be happy to revisit though if anyone has more repro info.
Owner

Released in borgmatic 2.0.6!

Released in borgmatic 2.0.6!
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#1089
No description provided.