How to log propertly (syslog) from hook shell scripts? #789

New Issue

ptomulik · 2023-11-14T11:47:16Z

ptomulik commented

2023-11-14 11:47:16 +00:00

What I'm trying to do and why

I have a bash script used as borgmatic hook. It's communicating its activities via stdout and warning/errors via stderr. This works fine, except for the case when I run bogmatic (from crontab) with --syslog-verbosity 1, something along the lines:

borgmatic --verbosity -1 --syslog-verbosity 1

All messages from my script appear in log as WARNINGs. Here is an example:

Nov 14 01:07:46 ns3210044 borgmatic[768873]: WARNING borgmatic-hook after_actions: info: script started
Nov 14 01:07:46 ns3210044 borgmatic[768873]: WARNING borgmatic-hook after_actions: info: nothing to be done
Nov 14 01:07:46 ns3210044 borgmatic[768873]: WARNING borgmatic-hook after_actions: info: script finished

As the stdout/stderr get mixed and pushed as warnings to syslog, is there any other way (stream/file descriptor) for a hook script to use appropriatelly logging facility (as an alternative to stdout/stderr)?

Anyway, conversion of script outputs to WARNING is pobably due to this line:

da034c316a/borgmatic/hooks/command.py (L72)

Steps to reproduce

No response

Actual behavior

All messages printed to stdout/stderr by a hook are logged as WARNINGs.

Expected behavior

It'd be nice to have a better control inhook scripts on what's logged as INFO vs WARNING vs ERROR.

Other notes / implementation ideas

No response

borgmatic version

1.7.7

borgmatic installation method

apt

Borg version

borg 1.2.4

Python version

Python 3.11.2

Database version (if applicable)

No response

Operating system and version

VERSION="12 (bookworm)"

### What I'm trying to do and why I have a bash script used as borgmatic hook. It's communicating its activities via stdout and warning/errors via stderr. This works fine, except for the case when I run bogmatic (from crontab) with ``--syslog-verbosity 1``, something along the lines: ```console borgmatic --verbosity -1 --syslog-verbosity 1 ``` All messages from my script appear in log as WARNINGs. Here is an example: ```console Nov 14 01:07:46 ns3210044 borgmatic[768873]: WARNING borgmatic-hook after_actions: info: script started Nov 14 01:07:46 ns3210044 borgmatic[768873]: WARNING borgmatic-hook after_actions: info: nothing to be done Nov 14 01:07:46 ns3210044 borgmatic[768873]: WARNING borgmatic-hook after_actions: info: script finished ``` As the stdout/stderr get mixed and pushed as warnings to syslog, is there any other way (stream/file descriptor) for a hook script to use appropriatelly logging facility (as an alternative to stdout/stderr)? Anyway, conversion of script outputs to WARNING is pobably due to this line: https://projects.torsion.org/borgmatic-collective/borgmatic/src/commit/da034c316aad5bd8b93dd1fcf4bac5d83b87ea12/borgmatic/hooks/command.py#L72 ### Steps to reproduce _No response_ ### Actual behavior All messages printed to stdout/stderr by a hook are logged as WARNINGs. ### Expected behavior It'd be nice to have a better control inhook scripts on what's logged as INFO vs WARNING vs ERROR. ### Other notes / implementation ideas _No response_ ### borgmatic version 1.7.7 ### borgmatic installation method apt ### Borg version borg 1.2.4 ### Python version Python 3.11.2 ### Database version (if applicable) _No response_ ### Operating system and version VERSION="12 (bookworm)"

ptomulik changed title from ~~how to log propertly (syslog) from hook shell script~~ to How to log propertly (syslog) from hook shell scripts?

2023-11-14 12:01:00 +00:00

witten commented

2023-11-15 00:30:08 +00:00

First of all, thank you for taking the time to file this. And nice sleuthing to track down the cause! I think you've discovered the long-languishing #485. Although this part is new..

As the stdout/stderr get mixed and pushed as warnings to syslog, is there any other way (stream/file descriptor) for a hook script to use appropriatelly logging facility (as an alternative to stdout/stderr)?

The short answer is no, not currently. But I'm curious as to your use case here. May I ask what the hook script is doing and what kinds of logs it's generating that would benefit from more granularity than just stdout/stderr? Without knowing anything about it, my first thought is that it might work better as something written in Python (and maybe built into borgmatic) so that it could take advantage of Python's logging facilities. Or would stdout/stderr be sufficient if borgmatic actually "supported" them properly for hook commands?

First of all, thank you for taking the time to file this. And nice sleuthing to track down the cause! I think you've discovered the long-languishing #485. Although this part is new.. > As the stdout/stderr get mixed and pushed as warnings to syslog, is there any other way (stream/file descriptor) for a hook script to use appropriatelly logging facility (as an alternative to stdout/stderr)? The short answer is no, not currently. But I'm curious as to your use case here. May I ask what the hook script is doing and what kinds of logs it's generating that would benefit from more granularity than just stdout/stderr? Without knowing anything about it, my first thought is that it might work better as something written in Python (and maybe built into borgmatic) so that it could take advantage of Python's logging facilities. Or would stdout/stderr be sufficient if borgmatic actually "supported" them properly for hook commands?

ptomulik commented

2023-11-15 00:46:06 +00:00

[...] is there any other way (stream/file descriptor) for a hook script to use appropriatelly logging facility (as an alternative to stdout/stderr)?

The short answer is no, not currently. But I'm curious as to your use case here. May I ask what the hook script is doing and what kinds of logs it's generating that would benefit from more granularity than just stdout/stderr? [...] Or would stdout/stderr be sufficient if borgmatic actually "supported" them properly for hook commands?

I wrote a bash script which works as {before,after}_anything hook and handles ZFS snapshoting/mounting & unmonuting/cleaning-up. It performs several checks, and a series of critical operations (as making snapshots of several ZFS volumes which are then mounted in an appropriate order to form a hierarchy of dirs&files). I like to have a backlog of these operations and their results to have a clear indication at which point my hook failed, if such thing happens. So I run the hook in verbose mode printing most critical commands with their parameters to stdout as well as warnings and error messages to stderr.

> > [...] is there any other way (stream/file descriptor) for a hook script to use appropriatelly logging facility (as an alternative to stdout/stderr)? > > The short answer is no, not currently. But I'm curious as to your use case here. May I ask what the hook script is doing and what kinds of logs it's generating that would benefit from more granularity than just stdout/stderr? [...] Or would stdout/stderr be sufficient if borgmatic actually "supported" them properly for hook commands? I wrote [a bash script](https://projects.torsion.org/borgmatic-collective/borgmatic/issues/261#issuecomment-7436) which works as ``{before,after}_anything`` hook and handles ZFS snapshoting/mounting & unmonuting/cleaning-up. It performs several checks, and a series of critical operations (as making snapshots of several ZFS volumes which are then mounted in an appropriate order to form a hierarchy of dirs&files). I like to have a backlog of these operations and their results to have a clear indication at which point my hook failed, if such thing happens. So I run the hook in verbose mode printing most critical commands with their parameters to stdout as well as warnings and error messages to stderr.

ptomulik commented

2023-11-16 12:35:01 +00:00

[...] Or would stdout/stderr be sufficient if borgmatic actually "supported" them properly for hook commands?

Of course, it'd be fine, however as I see, there are at least three "input channels" - INFO, WARNING, ERROR to syslog in borgmatic, but we have only two output streams - stdout & stderr - from hook scripts. I'm afraid implementing "correct redirection" from stdout/stderr to "syslog channels" is simply not possible, until we agree for some message syntax and parsing (which may be a backward compatibility break, OTOH).

> [...] Or would stdout/stderr be sufficient if borgmatic actually "supported" them properly for hook commands? Of course, it'd be fine, however as I see, there are at least three "input channels" - INFO, WARNING, ERROR to syslog in borgmatic, but we have only two output streams - stdout & stderr - from hook scripts. I'm afraid implementing "correct redirection" from stdout/stderr to "syslog channels" is simply not possible, until we agree for some message syntax and parsing (which may be a backward compatibility break, OTOH).

witten commented

2023-12-05 22:24:36 +00:00

I wrote a bash script which works as {before,after}_anything hook and handles ZFS snapshoting/mounting & unmonuting/cleaning-up. It performs several checks, and a series of critical operations (as making snapshots of several ZFS volumes which are then mounted in an appropriate order to form a hierarchy of dirs&files). I like to have a backlog of these operations and their results to have a clear indication at which point my hook failed, if such thing happens. So I run the hook in verbose mode printing most critical commands with their parameters to stdout as well as warnings and error messages to stderr.

#485 sounds like it would solve the issue of command hook stdout and stderr not being distinguished within borgmatic, but ultimately I think an actual ZFS hook (#261) would make more sense here and would allow much more flexible logging than trying to add additional logging capabilities to shell scripts (beyond stdout/stderr).

> I wrote a bash script which works as {before,after}_anything hook and handles ZFS snapshoting/mounting & unmonuting/cleaning-up. It performs several checks, and a series of critical operations (as making snapshots of several ZFS volumes which are then mounted in an appropriate order to form a hierarchy of dirs&files). I like to have a backlog of these operations and their results to have a clear indication at which point my hook failed, if such thing happens. So I run the hook in verbose mode printing most critical commands with their parameters to stdout as well as warnings and error messages to stderr. #485 sounds like it would solve the issue of command hook stdout and stderr not being distinguished within borgmatic, but ultimately I think an actual ZFS hook (#261) would make more sense here and would allow much more flexible logging than trying to add additional logging capabilities to shell scripts (beyond stdout/stderr).

witten commented

2023-12-23 02:00:06 +00:00

I'm closing this for now in favor of #485 and #261, but please feel free to weigh in there if you have any other thoughts. Thanks!

witten closed this issue

2023-12-23 02:00:07 +00:00

Sign in to join this conversation.