Send --stats output to healthchecks #524

New Issue

Sdub76 · 2022-04-29T16:27:21Z

Sdub76 commented

2022-04-29 16:27:21 +00:00

What I'm trying to do and why

Right now when I ping Healthchecks, it only sends the output of the actions specificed in the hooks: section to the healthchecks log. if the --stats option is specified, it would be very nice to send this as log output to Healthchecks... much more helpful than seeing the output of my MongoDB dump script.

#### What I'm trying to do and why Right now when I ping Healthchecks, it only sends the output of the actions specificed in the hooks: section to the healthchecks log. if the --stats option is specified, it would be very nice to send this as log output to Healthchecks... much more helpful than seeing the output of my MongoDB dump script.

Sdub76 changed title from ~~Send summary to healthchecks~~ to Send --stats output to healthchecks

2022-04-29 16:27:40 +00:00

witten commented

2022-04-29 16:29:02 +00:00

Thanks for filing this! Have you tried tried tweaking your --monitoring-verbosity? For instance: borgmatic create --monitoring-verbosity 2?

Thanks for filing this! Have you tried tried tweaking your `--monitoring-verbosity`? For instance: `borgmatic create --monitoring-verbosity 2`?

Sdub76 commented

2022-04-29 18:40:08 +00:00

I wasn't aware of that... I had just been piping the shell output to a log file. After playing with it I still have a few questions.

I like to use the --files option on for logging so I can go back and see if a particular file is being backed up as expected.

it seems that mointoring-verbosity=0 supresses everything including the --stats output. monitoring-verbosity=1 shows both stats and the complete file listing, which I don't want transmitted for privacy reasons.

Is there a way to suppress the changed file listing in the monitor log?

Also I don't know if it's a bug but the following commands produce different monitoring output:

borgmatic prune create --stats --log-file-verbosity=1 --monitoring-verbosity=1 --log-file /home/xxxx/borgmatic/logs/backup-"`date +"%a-%H"`".log
 
borgmatic prune create --stats --log-file-verbosity=2 --monitoring-verbosity=1 --log-file /home/xxxx/borgmatic/logs/backup-"`date +"%a-%H"`".log

edit: Is there a difference between level -1 and level 0 logging?

I wasn't aware of that... I had just been piping the shell output to a log file. After playing with it I still have a few questions. I like to use the --files option on for logging so I can go back and see if a particular file is being backed up as expected. it seems that mointoring-verbosity=0 supresses everything including the --stats output. monitoring-verbosity=1 shows both stats and the complete file listing, which I don't want transmitted for privacy reasons. **Is there a way to suppress the changed file listing in the monitor log?** **Also I don't know if it's a bug but the following commands produce different monitoring output:** ``` borgmatic prune create --stats --log-file-verbosity=1 --monitoring-verbosity=1 --log-file /home/xxxx/borgmatic/logs/backup-"`date +"%a-%H"`".log borgmatic prune create --stats --log-file-verbosity=2 --monitoring-verbosity=1 --log-file /home/xxxx/borgmatic/logs/backup-"`date +"%a-%H"`".log ``` edit: Is there a difference between level -1 and level 0 logging?

witten commented

2022-04-29 18:49:39 +00:00

Is there a way to suppress the changed file listing in the monitor log?

Not without suppressing it entirely (e.g., ommitting --files). That's because --files and --stats output are currently logged at the same log level.

Also I don't know if it's a bug but the following commands produce different monitoring output:

Some of this might be "by design" or at least a side-effect of the design. Since Borg doesn't have the concept of multiple logging backends (file, monitoring, etc.), borgmatic determines the highest log level requested (so, "2" in the second command) and in turn requests that log level of Borg. Therefore, the resultant logs sent to monitoring may be more verbose than they would be if the highest log level was "1".

> Is there a way to suppress the changed file listing in the monitor log? Not without suppressing it entirely (e.g., ommitting `--files`). That's because `--files` and `--stats` output are currently logged at the same log level. > Also I don't know if it's a bug but the following commands produce different monitoring output: Some of this might be "by design" or at least a side-effect of the design. Since Borg doesn't have the concept of multiple logging backends (file, monitoring, etc.), borgmatic determines the highest log level requested (so, "2" in the second command) and in turn requests that log level of Borg. Therefore, the resultant logs sent to monitoring may be more verbose than they would be if the highest log level was "1".

witten added the

question / support

label 2022-04-29 18:49:46 +00:00

Sdub76 commented

2022-04-29 19:11:51 +00:00

It seems like the Borgmatic -> Borg log levels are generally:

Level -1: Nothing
Level 0: CRITCAL + ERROR + WARNING
Level 1: CRITCAL + ERROR + WARNING + INFO
Level 2: CRITCAL + ERROR + WARNING + INFO + DEBUG

But some stuff like stats or pruning details change from INFO to WARNING depending on the requested log level. And the --verbosity, --log-file-verbosity, and --monitoring-verbosity options are not independent... for instance changing the monitoring verbosity changes what's shown in the console also.

It seems like the Borgmatic -> Borg log levels are generally: Level -1: Nothing Level 0: CRITCAL + ERROR + WARNING Level 1: CRITCAL + ERROR + WARNING + INFO Level 2: CRITCAL + ERROR + WARNING + INFO + DEBUG But some stuff like stats or pruning details change from INFO to WARNING depending on the requested log level. And the --verbosity, --log-file-verbosity, and --monitoring-verbosity options are not independent... for instance changing the monitoring verbosity changes what's shown in the console also.

Sdub76 commented

2022-04-29 19:15:44 +00:00

The only implementation suggestion/change I would suggest would be to set the log level to DEBUG in the underlying Borg command, then filter the output to the various log backends, maybe per the table in my previous post.

It's something to consider as a logging enhancement, independent of the request to send the stats and not files to the monitoring back-end. It would certainly make the behavior much easier to understand.

The file/stats question may be a request for Borg to reclassify --files as DEBUG output and --stats as INFO output.

For what it's worth, I think I'm going to migrate to a self-hosted Healthchecks implementation. That way I don't care if I send the more verbose logs including personal info.

The only implementation suggestion/change I would suggest would be to set the log level to DEBUG in the underlying Borg command, then filter the output to the various log backends, maybe per the table in my previous post. It's something to consider as a logging enhancement, independent of the request to send the stats and not files to the monitoring back-end. It would certainly make the behavior much easier to understand. The file/stats question may be a request for Borg to reclassify --files as DEBUG output and --stats as INFO output. For what it's worth, I think I'm going to migrate to a self-hosted Healthchecks implementation. That way I don't care if I send the more verbose logs including personal info.

Sdub76 commented

2022-05-03 00:17:38 +00:00

Is it possible to have the logs not append to each other? My cron job automatically rolls the log files weekly, but it doesn't work if the logs are appended instead of overwritten.

borgmatic prune create --log-file /mnt/logs/backup-"date +"%a-%H"".log

I don't really need my logs hanging around forever...

Is it possible to have the logs not append to each other? My cron job automatically rolls the log files weekly, but it doesn't work if the logs are appended instead of overwritten. borgmatic prune create --log-file /mnt/logs/backup-"`date +"%a-%H"`".log I don't really need my logs hanging around forever...

witten commented

2022-05-03 23:56:07 +00:00

Level -1: Nothing
Level 0: CRITCAL + ERROR + WARNING
Level 1: CRITCAL + ERROR + WARNING + INFO
Level 2: CRITCAL + ERROR + WARNING + INFO + DEBUG

That's correct, with the exception that level "-1" is critical + errors only.

But some stuff like stats or pruning details change from INFO to WARNING depending on the requested log level.

This is done very intentionally, although you could perhaps call it a hack. The behavior is:

At verbosity 1 and 2, output like stats can be INFO, because it's, well, informational output. (It's neither debug info nor is a warning/error.)
At verbosity 0, output like stats cannot be INFO because then it won't show up! (INFO is not displayed at verbosity 0.) So this output needs to get artificially elevated to warning so that it actually displays. And the reason it's given this special treatment is because it's explicitly requested by the user, e.g. via the --stats command-line flag.

If you have ideas for a better approach given these constraints, I'm open!

And the --verbosity, --log-file-verbosity, and --monitoring-verbosity options are not independent... for instance changing the monitoring verbosity changes what's shown in the console also.

Yup, that's due to the logic described above.

The only implementation suggestion/change I would suggest would be to set the log level to DEBUG in the underlying Borg command, then filter the output to the various log backends, maybe per the table in my previous post.

Could you talk a little more about how that might work? Individual lines of the output that borgmatic receives from Borg are log-level-less. borgmatic simply requests either --debug or --info or whatever from Borg.. and then receives plain ol' stdout/stderr back.. and that's it. There's no parsing of the output that comes back beyond that.

For what it's worth, I think I'm going to migrate to a self-hosted Healthchecks implementation. That way I don't care if I send the more verbose logs including personal info.

Makes sense!

Is it possible to have the logs not append to each other? My cron job automatically rolls the log files weekly, but it doesn't work if the logs are appended instead of overwritten.

What's the problem specifically with appending? How does it break log rotation? Thanks.

> Level -1: Nothing Level 0: CRITCAL + ERROR + WARNING Level 1: CRITCAL + ERROR + WARNING + INFO Level 2: CRITCAL + ERROR + WARNING + INFO + DEBUG That's correct, with the exception that level "-1" is critical + errors only. > But some stuff like stats or pruning details change from INFO to WARNING depending on the requested log level. This is done very intentionally, although you could perhaps call it a hack. The behavior is: * At verbosity 1 and 2, output like stats can be INFO, because it's, well, informational output. (It's neither debug info nor is a warning/error.) * At verbosity 0, output like stats cannot be INFO because then it won't show up! (INFO is not displayed at verbosity 0.) So this output needs to get artificially elevated to warning so that it actually displays. And the reason it's given this special treatment is because it's explicitly requested by the user, e.g. via the `--stats` command-line flag. If you have ideas for a better approach given these constraints, I'm open! > And the --verbosity, --log-file-verbosity, and --monitoring-verbosity options are not independent... for instance changing the monitoring verbosity changes what's shown in the console also. Yup, that's due to the logic [described above](https://projects.torsion.org/borgmatic-collective/borgmatic/issues/524#issuecomment-4368). > The only implementation suggestion/change I would suggest would be to set the log level to DEBUG in the underlying Borg command, then filter the output to the various log backends, maybe per the table in my previous post. Could you talk a little more about how that might work? Individual lines of the output that borgmatic receives from Borg are log-level-less. borgmatic simply requests either `--debug` or `--info` or whatever from Borg.. and then receives plain ol' stdout/stderr back.. and that's it. There's no parsing of the output that comes back beyond that. > For what it's worth, I think I'm going to migrate to a self-hosted Healthchecks implementation. That way I don't care if I send the more verbose logs including personal info. Makes sense! > Is it possible to have the logs not append to each other? My cron job automatically rolls the log files weekly, but it doesn't work if the logs are appended instead of overwritten. What's the problem specifically with appending? How does it break log rotation? Thanks.

Firesphere commented

2022-05-09 06:30:35 +00:00

I have seen this behaviour (sending just stats) from b3vis/borgmatic Docker container, but I've not been able to replicate it myself yet.

The crontab entry doesn't look that out of the ordinary to me, so I'm unsure where it's coming from:
53 */4 * * * PATH=$PATH:/usr/bin /usr/bin/borgmatic --stats -v 0 2>&1

I have seen this behaviour (sending just stats) from `b3vis/borgmatic` Docker container, but I've not been able to replicate it myself yet. The crontab entry doesn't look that out of the ordinary to me, so I'm unsure where it's coming from: `53 */4 * * * PATH=$PATH:/usr/bin /usr/bin/borgmatic --stats -v 0 2>&1`

Sdub76 commented

2022-05-09 13:37:41 +00:00

The issue I was having with appending logfiles is that my cron job was piping console output to log files named "backup-Mon", "backup-Tue", etc. that were overwritten the following week just by nature of having the same name. Using the --log-file option causes the output to append, so I have 7 logfilles that just grow forever.

To solve the logfile rotation issue, I had theborgmatic docker container maintainer (b3vis) add "logrotate" to the container. Now my cron job looks like "logrotate --opts; borgmatic --opts" where I'm simply using "backup.log" as my backup log filename. This seems like a proper resolution to this issue, though an option for "--overwrite-logs" might be nice.

The idea I had for the log file verbosity was to have the maximum detail coming out of Borg at all times, then filter the output to screen/syslog/file-log/monitor-log per the Borgmatic command-line options.

I've solved this issue by writing my own hc-ping script and disabling the built-in HC feature in the Borgmatic config file. My Borgmatic command is using a relatively verbose setting, then this "hc-ping" script filters the output down before posting to Healthchecks. My config.yaml has start/stop/error hooks similar to: "hc-ping -c finish -u XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX -l /mnt/logs/backup.log"

If this explicit filtering were built into Borgmatic, I could revert to the built-in HC support. (I want add/modify file details in my log files, but I don't want to send that level of detail to Healthchecks. In my instance, I'm self-hosting Healthchecks so my $hc_base is different. Splitting out the $curl_cmd here has another benefit in that I can specify a proxy, or even use "ssh user@host /usr/bin/curl" if my borgmatic container doesn't have internet access.

#!/bin/sh

export hc_base="https://hc-ping.com"
export curl_cmd="/usr/bin/curl"

while getopts "c:l:u:" flag
do
    case "${flag}" in
        c) command=${OPTARG};;
        l) logfile=${OPTARG};;
        u) hc_uuid=${OPTARG};;
    esac
done

case $command in

  start)

    echo "*********** Pinging Healthchecks Start ************"
    export result=$($curl_cmd -s -X POST $hc_base/$hc_uuid/start)
    ;;

  finish)

    echo "*********** Pinging Healthchecks Finish ************"
    if [ ! -z "$logfile" ];
    then
      cat $logfile | grep -v 'INFO: [AM] ' > /tmp/tmplog
      export result=$($curl_cmd -s -X POST --data-binary @/tmp/tmplog $hc_base/$hc_uuid)
      rm /tmp/tmplog
    else
      export result=$($curl_cmd -s -X POST $hc_base/$hc_uuid)
    fi
    ;;

  error)

    echo "*********** Pinging Healthchecks Error ************"
    cat $logfile | grep -E -B10 '(CRITICAL: |ERROR: )' > /tmp/tmplog
    export result=$($curl_cmd -s -X POST --data-binary @/tmp/tmplog $hc_base/$hc_uuid/fail)
    rm /tmp/tmplog
    ;;

esac

if [ "$result" = "OK" ]; then echo "Success"; else echo "   **** ERROR Contacting Healthchecks"; fi

exit 0

The issue I was having with appending logfiles is that my cron job was piping console output to log files named "backup-Mon", "backup-Tue", etc. that were overwritten the following week just by nature of having the same name. Using the --log-file option causes the output to append, so I have 7 logfilles that just grow forever. To solve the logfile rotation issue, I had theborgmatic docker container maintainer (b3vis) add "logrotate" to the container. Now my cron job looks like "logrotate --opts; borgmatic --opts" where I'm simply using "backup.log" as my backup log filename. This seems like a proper resolution to this issue, though an option for "--overwrite-logs" might be nice. --- The idea I had for the log file verbosity was to have the maximum detail coming out of Borg at all times, then filter the output to screen/syslog/file-log/monitor-log per the Borgmatic command-line options. I've solved this issue by writing my own hc-ping script and disabling the built-in HC feature in the Borgmatic config file. My Borgmatic command is using a relatively verbose setting, then this "hc-ping" script filters the output down before posting to Healthchecks. My config.yaml has start/stop/error hooks similar to: "hc-ping -c finish -u XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX -l /mnt/logs/backup.log" If this explicit filtering were built into Borgmatic, I could revert to the built-in HC support. (I want add/modify file details in my log files, but I don't want to send that level of detail to Healthchecks. In my instance, I'm self-hosting Healthchecks so my $hc_base is different. Splitting out the $curl_cmd here has another benefit in that I can specify a proxy, or even use "ssh user@host /usr/bin/curl" if my borgmatic container doesn't have internet access. ``` #!/bin/sh export hc_base="https://hc-ping.com" export curl_cmd="/usr/bin/curl" while getopts "c:l:u:" flag do case "${flag}" in c) command=${OPTARG};; l) logfile=${OPTARG};; u) hc_uuid=${OPTARG};; esac done case $command in start) echo "*********** Pinging Healthchecks Start ************" export result=$($curl_cmd -s -X POST $hc_base/$hc_uuid/start) ;; finish) echo "*********** Pinging Healthchecks Finish ************" if [ ! -z "$logfile" ]; then cat $logfile | grep -v 'INFO: [AM] ' > /tmp/tmplog export result=$($curl_cmd -s -X POST --data-binary @/tmp/tmplog $hc_base/$hc_uuid) rm /tmp/tmplog else export result=$($curl_cmd -s -X POST $hc_base/$hc_uuid) fi ;; error) echo "*********** Pinging Healthchecks Error ************" cat $logfile | grep -E -B10 '(CRITICAL: |ERROR: )' > /tmp/tmplog export result=$($curl_cmd -s -X POST --data-binary @/tmp/tmplog $hc_base/$hc_uuid/fail) rm /tmp/tmplog ;; esac if [ "$result" = "OK" ]; then echo "Success"; else echo " **** ERROR Contacting Healthchecks"; fi exit 0 ```

Sdub76 commented

2022-05-09 18:06:13 +00:00

#518
#512
#525

Other related recent issues that might find this custom script useful.

#518 #512 #525 Other related recent issues that might find this custom script useful.

witten commented

2022-05-20 18:34:11 +00:00

Glad to hear that you've got logrotate going to solve the logging issue. I would prefer to lean on external tools like logrotate for that rather than putting that functionality into borgmatic. Also note that you could use a logging daemon like systemd, which borgmatic supports natively.. although I'm not sure the Docker image does. And even with the Docker image, I imagine logs (if not redirected to file) go to Docker's own logging system.

I'm also glad to hear you have a work-around for the Healthchecks output issue!

The idea I had for the log file verbosity was to have the maximum detail coming out of Borg at all times, then filter the output to screen/syslog/file-log/monitor-log per the Borgmatic command-line options.

Could you say a little more about how that would work? With borgmatic --verbosity 2 now, the maximum detail will come out of Borg. But then how would the output get filtered further?

Thanks!

Glad to hear that you've got logrotate going to solve the logging issue. I would prefer to lean on external tools like logrotate for that rather than putting that functionality into borgmatic. Also note that you could use a logging daemon like systemd, which borgmatic supports natively.. although I'm not sure the Docker image does. And even with the Docker image, I imagine logs (if not redirected to file) go to Docker's own logging system. I'm also glad to hear you have a work-around for the Healthchecks output issue! > The idea I had for the log file verbosity was to have the maximum detail coming out of Borg at all times, then filter the output to screen/syslog/file-log/monitor-log per the Borgmatic command-line options. Could you say a little more about how that would work? With `borgmatic --verbosity 2` now, the maximum detail will come out of Borg. But then how would the output get filtered further? Thanks!

witten added the

waiting for response

label 2022-05-24 21:19:16 +00:00

AndrewDDavis referenced this issue

2022-06-13 16:26:08 +00:00

Logging and stdout behaviour of --files and --stats is confusing #547

witten commented

2022-10-05 06:05:52 +00:00

Closing this for now, but feel free to follow up. We can always reopen it. Thanks!

witten closed this issue

2022-10-05 06:05:53 +00:00

Sign in to join this conversation.