borgmatic check - behavior if errors are found #247

New Issue

dmi-github · 2019-11-18T00:15:08Z

dmi-github commented

2019-11-18 00:15:08 +00:00

What I'm trying to do and why

Get information about the success of 'borgmatic check'

Steps to reproduce (if a bug)

I have set up a repository, performed a backup and damaged the repository by tampering with the data inside.

Actual behavior (if a bug)

'borg check' detects the error while performing the repository check. It outputs the found errors and exits with exit code 1.

'borgmatic check' detects the error too(obviously), but it does not behave like something is wrong. Neither the on_error hook is fired nor does it exit with an error code different from 0. In fact, there is no output about the error without specifying at least verbosity level 1(--verbosity 1).

Expected behavior (if a bug)

After rereading the documentation I am not sure if the on_error hook should be fired in this case too(or only for borgmatic create). However, I would expect at least an exit code unequal to 0(this works for borgmatic create)

Other notes / implementation ideas

If the on_error hook is only for the case of backup creation, then there should be an additional hook, e.g. on_verification_error.

Environment

borgmatic version: [1.4.10]

borgmatic installation method: [pip]

Borg version: [1.1.10]

Python version: [3.7.3]

#### What I'm trying to do and why Get information about the success of 'borgmatic check' #### Steps to reproduce (if a bug) I have set up a repository, performed a backup and damaged the repository by tampering with the data inside. #### Actual behavior (if a bug) 'borg check' detects the error while performing the repository check. It outputs the found errors and exits with exit code 1. 'borgmatic check' detects the error too(obviously), but it does not behave like something is wrong. Neither the on_error hook is fired nor does it exit with an error code different from 0. In fact, there is no output about the error without specifying at least verbosity level 1(--verbosity 1). #### Expected behavior (if a bug) After rereading the documentation I am not sure if the on_error hook should be fired in this case too(or only for borgmatic create). However, I would expect at least an exit code unequal to 0(this works for borgmatic create) #### Other notes / implementation ideas If the on_error hook is only for the case of backup creation, then there should be an additional hook, e.g. on_verification_error. #### Environment **borgmatic version:** [1.4.10] **borgmatic installation method:** [pip] **Borg version:** [1.1.10] **Python version:** [3.7.3]

witten commented

2019-11-18 00:17:20 +00:00

Thanks for filing the detailed bug report. I agree.. At minimum the borgmatic check exit status should reflect the validation status. I'll have a look at this when I get a chance!

Thanks for filing the detailed bug report. I agree.. At minimum the `borgmatic check` exit status should reflect the validation status. I'll have a look at this when I get a chance!

witten added the

bug

label 2019-11-18 00:17:28 +00:00

dmi-github commented

2019-11-18 00:27:01 +00:00

That was a blazing fast reply! That would be great!

Thank you for your effort and for providing this helpful piece of software!

That was a blazing fast reply! That would be great! Thank you for your effort and for providing this helpful piece of software!

witten commented

2019-11-18 01:13:15 +00:00

Could I have a look at the specific Borg command-line arguments you're using when borg check detects the error? And the Borg command-line arguments borgmatic uses when borgmatic check doesn't detect the error? (Use --verbosity 2.)

I'm seeing some interesting behavior where using the --repository-only flag, either directly with Borg, or implied with borgmatic via using only the repository check.. results in the same behavior: A Borg exit status of zero. Even though the repository check clearly finds an consistency problem.

In contrast, omitting --repository-only / using more than just the repository check causes both Borg and borgmatic to find the consistency problem and return an exit status of non-zero.

Is this behavior consistent with what you're seeing?

Could I have a look at the specific Borg command-line arguments you're using when `borg check` detects the error? And the Borg command-line arguments borgmatic uses when `borgmatic check` doesn't detect the error? (Use `--verbosity 2`.) I'm seeing some interesting behavior where using the `--repository-only` flag, either directly with Borg, or implied with borgmatic via using only the `repository` check.. results in the same behavior: A Borg exit status of zero. Even though the repository check clearly finds an consistency problem. In contrast, omitting `--repository-only` / using more than just the `repository` check causes both Borg and borgmatic to find the consistency problem and return an exit status of non-zero. Is this behavior consistent with what you're seeing?

dmi-github commented

2019-11-18 01:45:58 +00:00

I don't see any difference between

borg check <repo_path> and borg check --repository-only <repo path>

Both result in an exit status of non-zero and the last line of output is in both cases

Completed repository check, errors found.

Calling borgmatic with
borgmatic check --config <cfg_path> --log-file <log_path> --verbosity 2

calls borg in the following way

/usr/local/bin/borg check --prefix <prefix> --lock-wait <lockwait> --debug --show-rc <repo_path>

and the last lines of output are:

Completed repository check, errors found.
terminating with warning status, rc 1

summary:
<cfg_path>: Successfully ran configuration file

however the exit status is zero

I don't see any difference between `borg check <repo_path>` and `borg check --repository-only <repo path>` Both result in an exit status of non-zero and the last line of output is in both cases ``` Completed repository check, errors found. ``` Calling borgmatic with `borgmatic check --config <cfg_path> --log-file <log_path> --verbosity 2` calls borg in the following way `/usr/local/bin/borg check --prefix <prefix> --lock-wait <lockwait> --debug --show-rc <repo_path>` and the last lines of output are: ``` Completed repository check, errors found. terminating with warning status, rc 1 summary: <cfg_path>: Successfully ran configuration file ``` however the exit status is zero

witten commented

2019-11-18 02:16:04 +00:00

borgmatic intentionally swallows Borg warning status (exit status 1) for most operations, as it's documented as "only" a warning. But borgmatic does pass through Borg error status (exit status 2+), which is documented as an actual error.

Perhaps borgmatic should interpret warnings as errors for borg check commands.

borgmatic intentionally swallows Borg *warning* status (exit status 1) for most operations, as it's [documented](https://borgbackup.readthedocs.io/en/stable/usage/general.html#return-codes) as "only" a warning. But borgmatic does pass through Borg *error* status (exit status 2+), which is documented as an actual error. Perhaps borgmatic should interpret warnings as errors for `borg check` commands.

witten commented

2019-11-18 02:40:48 +00:00

Also, on_error should run for all actions, not just create. I'll clarify that in the docs.

Also, `on_error` should run for *all* actions, not just `create`. I'll clarify that in the docs.

witten referenced this issue from a commit

2019-11-18 03:13:04 +00:00

With "borgmatic check", consider Borg warnings as errors (#247).

witten commented

2019-11-18 03:17:21 +00:00

Okay, a fix for this is released with borgmatic 1.4.12.. Borg warnings are now promoted to errors for purposes of borgmatic check, and the docs now reflect when on_error runs. Please give it a shot and let me know how it works out for you! And thanks again for reporting this.

FYI, if you're doing something in on_error that you think other users might benefit from, feel free to propose it as a feature or an integration.

Okay, a fix for this is released with borgmatic 1.4.12.. Borg warnings are now promoted to errors for purposes of `borgmatic check`, and the docs now reflect when `on_error` runs. Please give it a shot and let me know how it works out for you! And thanks again for reporting this. FYI, if you're doing something in `on_error` that you think other users might benefit from, feel free to propose it as a feature or an integration.

witten closed this issue

2019-11-18 03:17:26 +00:00

dmi-github commented

2019-11-18 13:39:27 +00:00

Can confirm that exit status 1 as well as the call of the on_error hook work with 1.4.12! Thank you for the quick patch!

I partially understand the design decision that borg check classifies the case of a defective repository only as a warning. From borg's perspective it's not a case of runtime error. Interpretation of these warnings as errors from the perspective of automation with borgmatic check seem to be a good decision.

What do you think about the output of borg check? Currently I have to use at least --verbosity 1 with borgmatic check to get any information about the repository errors. This gives me a lot of additional information about borgmatic as well. But in general, if there are no errors at all, I do not need this level of verbosity. However, staying with --verbosity 0, would require that I rerun the repository check manually to get any hint what kind of error occured.

Would it be a good idea to elevate borg check warning output to borgmatic check error output? Are there any other undesired consequences?

I work around it by using two different levels of verbosity and a second log file just for the stderr output of borgmatic like that:
borgmatic check --verbosity 1 --log-file <log_general> --log-file-verbosity 0 2> <log_detail_last_check>.

This works well for my use case and results in a tidy log file. For my liking it may be even better to keep it this way, since the output of borg check is rather long(in case of errors) and I still can decide to aggregate the output with a shell script.

However, I believe that this is not consistent with the output behavior of borgmatic create and may not be what the user expects.

edit:

There seems to be something odd about the level of verbosity in the log file specified by --log-file <log_general>.

On a repository with errors I get different outputs in 'log_general' for

borgmatic check --log-file <log_general> --log-file-verbosity 0

and

borgmatic check --log-file <log_general> --log-file-verbosity 0 --verbosity 1

Can confirm that exit status 1 as well as the call of the on_error hook work with 1.4.12! Thank you for the quick patch! I partially understand the design decision that `borg check` classifies the case of a defective repository only as a warning. From borg's perspective it's not a case of runtime error. Interpretation of these warnings as errors from the perspective of automation with `borgmatic check` seem to be a good decision. What do you think about the output of `borg check`? Currently I have to use at least `--verbosity 1` with `borgmatic check` to get any information about the repository errors. This gives me a lot of additional information about borgmatic as well. But in general, if there are no errors at all, I do not need this level of verbosity. However, staying with `--verbosity 0`, would require that I rerun the repository check manually to get any hint what kind of error occured. Would it be a good idea to elevate `borg check` warning output to `borgmatic check` error output? Are there any other undesired consequences? I work around it by using two different levels of verbosity and a second log file just for the stderr output of borgmatic like that: `borgmatic check --verbosity 1 --log-file <log_general> --log-file-verbosity 0 2> <log_detail_last_check>`. This works well for my use case and results in a tidy log file. For my liking it may be even better to keep it this way, since the output of `borg check` is rather long(in case of errors) and I still can decide to aggregate the output with a shell script. However, I believe that this is not consistent with the output behavior of `borgmatic create` and may not be what the user expects. edit: There seems to be something odd about the level of verbosity in the log file specified by `--log-file <log_general>`. On a repository with errors I get different outputs in 'log_general' for `borgmatic check --log-file <log_general> --log-file-verbosity 0` and `borgmatic check --log-file <log_general> --log-file-verbosity 0 --verbosity 1`

witten commented

2019-11-19 04:16:47 +00:00

What do you think about the output of borg check?

Would it be a good idea to elevate borg check warning output to borgmatic check error output? Are there any other undesired consequences?

I think this discrepency you've identified has nothing to do with borg check, and everything to do with a tweak I made to the way that error output is logged at various verbosity levels (for all actions). I'll have to revisit that tweak because of the issue specifically at verbosity level zero. Good find!

> What do you think about the output of borg check? > Would it be a good idea to elevate borg check warning output to borgmatic check error output? Are there any other undesired consequences? I think this discrepency you've identified has nothing to do with `borg check`, and everything to do with a tweak I made to the way that error output is logged at various verbosity levels (for all actions). I'll have to revisit that tweak because of the issue specifically at verbosity level zero. Good find!

witten commented

2019-11-19 18:12:40 +00:00

Okay, please give borgmatic 1.4.13 a shot and see if it fixes this for you! I've made a change not to suppress command output at verbosity zero.

dmi-github commented

2019-11-20 08:29:42 +00:00

Yes - command output at verbosity zero works now for stdout as well as for the log file. It actually displays only the last 25 lines of borg's output, but I believe that this is intended for verbosity zero - and I am satisfied with this approach. Thank you again for the fix!

It seems that the the output to the log file still gets partially duplicated if I additionally specify --verbosity 1 as mentioned in my previous post. I have appended a log file for clarification. I do not redirect any output from stdout/stderr to the log file.
It contains both cases for comparison. Actually, it does not bother me - just fyi that there is something odd with the logger.

(By taking a closer look, you can also notice, that the on_error hook is fired once before and once after the borg output is written to the log file)

edit:
could not paste the log - here's the link: https://pastebin.com/AzVab9Ci

Yes - command output at verbosity zero works now for stdout as well as for the log file. It actually displays only the last 25 lines of `borg`'s output, but I believe that this is intended for verbosity zero - and I am satisfied with this approach. Thank you again for the fix! It seems that the the output to the log file still gets partially duplicated if I additionally specify `--verbosity 1` as mentioned in my previous post. I have appended a log file for clarification. I do not redirect any output from stdout/stderr to the log file. It contains both cases for comparison. Actually, it does not bother me - just fyi that there is something odd with the logger. (By taking a closer look, you can also notice, that the on_error hook is fired once before and once after the borg output is written to the log file) edit: could not paste the log - here's the link: https://pastebin.com/AzVab9Ci

witten commented

2019-11-21 00:19:02 +00:00

This behavior is both unintuitive.. and expected, given the way that the current code works. What's going on is that if any logger (file, syslog, or console) is higher than verbosity level zero, borgmatic tacks on a summary to the end of the logs, and repeats any errors there, including any command output. The rationale is that if you've got lots of configuration files and repositories, you may have some successes and some errors, and having the summary of what happened plus all the errors collected at the end makes it easier to see what went wrong.

But with the summary at the end, any logger at verbosity zero doesn't see the "summary:" header log, and so it looks like things are repeated for no reason. Maybe this needs to be re-thought a bit? Let me know if you have any suggestions.

This behavior is both unintuitive.. and expected, given the way that the current code works. What's going on is that if *any* logger (file, syslog, or console) is higher than verbosity level zero, borgmatic tacks on a summary to the end of the logs, and repeats any errors there, including any command output. The rationale is that if you've got lots of configuration files and repositories, you may have some successes and some errors, and having the summary of what happened plus all the errors collected at the end makes it easier to see what went wrong. But with the summary at the end, any logger at verbosity zero doesn't see the "summary:" header log, and so it looks like things are repeated for no reason. Maybe this needs to be re-thought a bit? Let me know if you have any suggestions.

witten commented

2019-11-25 18:38:05 +00:00

Well, I've taken another stab at this. Summary logs, including the "summary:" header, now show up regardless of the verbosity level. I think this will be less confusing, if still a little duplicative in certain cases.

Released in borgmatic 1.4.14. Let me know how it works for you.

Well, I've taken another stab at this. Summary logs, including the "summary:" header, now show up regardless of the verbosity level. I think this will be less confusing, if still a little duplicative in certain cases. Released in borgmatic 1.4.14. Let me know how it works for you.

dmi-github commented

2019-11-27 15:17:26 +00:00

Currently I am not able to have a look at it. I will come back to this topic by the end of this week and let you know.

dmi-github commented

2019-12-01 19:29:08 +00:00

checked with borgmatic-1.4.16

As expected I do get a summary(with a "summary" header) for both previously mentioned combinations of verbosity level switches. In fact, borgbackup's command output is only printed in the summary now. You did not mention that explicitly, but I believe that this is intended. Eventually it results in identical output for both cases. This is nice!

As you mentioned, there is duplicated output - but well, this is the nature of a summary I believe ;). I am fine with this solution, even for my use case, where I call borgmatic with a single explicitly specified config file. Thank you for that!

checked with borgmatic-1.4.16 As expected I do get a summary(with a "summary" header) for both previously mentioned combinations of verbosity level switches. In fact, borgbackup's command output is only printed in the summary now. You did not mention that explicitly, but I believe that this is intended. Eventually it results in identical output for both cases. This is nice! As you mentioned, there is duplicated output - but well, this is the nature of a summary I believe ;). I am fine with this solution, even for my use case, where I call borgmatic with a single explicitly specified config file. Thank you for that!

witten commented

2019-12-01 22:59:45 +00:00

In fact, borgbackup’s command output is only printed in the summary now. You did not mention that explicitly, but I believe that this is intended.

That's right for --verbosity 0. Higher verbosity levels have the borgmatic output duplicated above the summary as well.

As you mentioned, there is duplicated output - but well, this is the nature of a summary I believe ;). I am fine with this solution, even for my use case, where I call borgmatic with a single explicitly specified config file. Thank you for that!

Sure thing, glad it's working out for you!

> In fact, borgbackup’s command output is only printed in the summary now. You did not mention that explicitly, but I believe that this is intended. That's right for `--verbosity 0`. Higher verbosity levels have the borgmatic output duplicated above the summary as well. > As you mentioned, there is duplicated output - but well, this is the nature of a summary I believe ;). I am fine with this solution, even for my use case, where I call borgmatic with a single explicitly specified config file. Thank you for that! Sure thing, glad it's working out for you!

shukon referenced this issue

2023-07-28 17:37:56 +00:00

How to catch warnings for files that are not backed up? #733

Sign in to join this conversation.