With multiple config files in borgmatic.d, cumulative logs are sent to the healthchecks endpoints #328

New Issue

Closed

opened 2020-06-16 22:23:36 +00:00 by s1shed · 3 comments

s1shed commented 2020-06-16 22:23:36 +00:00

Contributor

Copy Link

Apologies for the potentially unclear bug title (and thank you very much for your work on this excellent tool!)

What I'm trying to do and why

I have multiple config files in /etc/borgmatic.d. Each config file has its own unique hooks.healthchecks configuration.

Actual behavior (if a bug)

Assuming all borg runs / hooks generate output that is POSTed to healthchecks, each subsequent healthcheck ping will include the previous logs and its own output (if any).

Expected behavior (if a bug)

Each submission to healthchecks should consist of the data generated by that borg run itself.

Other notes

With three borgmatic config files in /etc/borgmatic.d that echo a string in the before_backup and after_backup hooks, healthchecks gets the following payload from the last (3rd) backup job when running borgmatic without specifying a config file with the --config parameter:

Starting a backup job.
Backup created.
Starting a backup job.
Backup created.
Starting a backup job.

The first job sent the first line to its healthchecks endpoint. The second job sent the first three lines. The third job sent the five lines shown here. The after_backup text of the third job was swallowed.

If I run the first job by itself using borgmatic --config /etc/borgmatic.d/conf.yaml only the before_backup hook's text is sent to healthchecks.

Environment

borgmatic version: 1.5.6

borgmatic installation method: pip3 install --user borgmatic

Borg version: 1.1.5

Python version: Python 3.6.9

operating system and version: Ubuntu 16.04

Apologies for the potentially unclear bug title (and thank you very much for your work on this excellent tool!) #### What I'm trying to do and why I have multiple config files in `/etc/borgmatic.d`. Each config file has its own unique `hooks.healthchecks` configuration. #### Actual behavior (if a bug) Assuming all borg runs / hooks generate output that is `POST`ed to healthchecks, each subsequent healthcheck ping will include the previous logs and its own output (if any). #### Expected behavior (if a bug) Each submission to healthchecks should consist of the data generated by that borg run itself. #### Other notes With three borgmatic config files in `/etc/borgmatic.d` that echo a string in the `before_backup` and `after_backup` hooks, healthchecks gets the following payload from the last (3rd) backup job when running borgmatic without specifying a config file with the `--config` parameter: ``` Starting a backup job. Backup created. Starting a backup job. Backup created. Starting a backup job. ``` The first job sent the first line to its healthchecks endpoint. The second job sent the first three lines. The third job sent the five lines shown here. The `after_backup` text of the third job was swallowed. If I run the first job by itself using `borgmatic --config /etc/borgmatic.d/conf.yaml` only the `before_backup` hook's text is sent to healthchecks. #### Environment **borgmatic version:** 1.5.6 **borgmatic installation method:** `pip3 install --user borgmatic` **Borg version:** 1.1.5 **Python version:** Python 3.6.9 **operating system and version:** Ubuntu 16.04

witten commented 2020-06-17 17:55:31 +00:00

Owner

Copy Link

I appreciate the bug report. I think I know what's going on here, but the way to fix it isn't entirely obvious:

after_backups output getting omitted from what's sent to Healthchecks: Since the implementation of #292 the Healthchecks "finish" ping (which is what sends accumulated logs to Healthchecks) was moved to happen before the after_backups hook, meaning that any output from the after_backups hook doesn't get sent to Healthchecks.

The rationale is that #292 moved the Healthchecks "start" ping to happen after the before_backups hook, and so it made sense for the before/after hooks to effectively "wrap" the Healthchecks interactions. The current ordering is: 1. run before hooks, 2. do Healthchecks start ping, 3. run actions, 4. do Healthchecks finish ping (and transmit logs), 5. run after hooks.

I could swap the order of the Healthchecks finish and the after hooks, but that might be a little unexpected, given the order of the before hooks and Healthchecks start. Thoughts? Do you need to see the output of the after_backups hook on Healthchecks?

The reason that you're still seeing the output of the before_backup output is that the Healthchecks log is initialized even before before_backup runs, so its output is still captured and sent to Healthchecks... Which leads me to the second problem you're seeing:

Healthchecks logs from previous borgmatic configuration file runs bleed over to subsequent configuration files: When the first configuration file initializes Healthchecks logging, that same logger ends up implicitly used for each subseqent configuration file, and the logger never gets cleared. That's why you're seeing output for all configuration files sent for the final "job".

The fix here is either to clear logs upon sending a finish ping to Healthchecks, or implement the concept of hook cleanup to correspond to the existing hook initialization.

I appreciate the bug report. I think I know what's going on here, but the way to fix it isn't entirely obvious: **`after_backups` output getting omitted from what's sent to Healthchecks:** Since the implementation of #292 the Healthchecks "finish" ping (which is what sends accumulated logs to Healthchecks) was moved to happen *before* the `after_backups` hook, meaning that any output from the `after_backups` hook doesn't get sent to Healthchecks. The rationale is that #292 moved the Healthchecks "start" ping to happen *after* the `before_backups` hook, and so it made sense for the before/after hooks to effectively "wrap" the Healthchecks interactions. The current ordering is: 1. run before hooks, 2. do Healthchecks start ping, 3. run actions, 4. do Healthchecks finish ping (and transmit logs), 5. run after hooks. I could swap the order of the Healthchecks finish and the after hooks, but that might be a little unexpected, given the order of the before hooks and Healthchecks start. Thoughts? Do you need to see the output of the `after_backups` hook on Healthchecks? The reason that you're still seeing the output of the `before_backup` output is that the Healthchecks log is initialized even before `before_backup` runs, so its output is still captured and sent to Healthchecks... Which leads me to the second problem you're seeing: **Healthchecks logs from previous borgmatic configuration file runs bleed over to subsequent configuration files**: When the first configuration file initializes Healthchecks logging, that same logger ends up implicitly used for each subseqent configuration file, and the logger never gets cleared. That's why you're seeing output for all configuration files sent for the final "job". The fix here is either to clear logs upon sending a finish ping to Healthchecks, or implement the concept of hook cleanup to correspond to the existing hook initialization.

witten added the bug label 2020-06-17 17:55:37 +00:00

witten referenced this issue from a commit 2020-06-23 18:03:42 +00:00

Fix duplicate logging to Healthchecks and send "after_*" hooks output to Healthchecks (#328).

witten commented 2020-06-23 18:08:31 +00:00

Owner

Copy Link

This should be fixed in master. I'm now destroying the Healthchecks logging handler after each configuration file is processed, so it doesn't carry over to the logs of the next configuration file.

I've also moved the Healthchecks "finish" ping to after borgmatic's after_* hooks, so their output should now get sent to Healthchecks.

Thanks again for reporting. I post here when it's released.

This should be fixed in master. I'm now destroying the Healthchecks logging handler after each configuration file is processed, so it doesn't carry over to the logs of the next configuration file. I've also moved the Healthchecks "finish" ping to after borgmatic's `after_*` hooks, so their output should now get sent to Healthchecks. Thanks again for reporting. I post here when it's released.

witten closed this issue 2020-06-23 18:08:31 +00:00

witten commented 2020-06-23 18:27:46 +00:00

Owner

Copy Link

Released in borgmatic 1.5.7!

Released in borgmatic 1.5.7!

witten referenced this issue 2020-06-26 03:22:34 +00:00

Monitors other than Healthchecks traceback when run #336

Sign in to join this conversation.

No Branch/Tag Specified

Branches Tags

main

command-hook-steps

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 Label bug

Milestone

No items

No Milestone

Assignees

Clear assignees

witten

No Assignees

2 Participants

Notifications

Subscribe

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: borgmatic-collective/borgmatic#328