diff --git a/NEWS b/NEWS index 02dc7887..aaf65212 100644 --- a/NEWS +++ b/NEWS @@ -7,9 +7,12 @@ * #835: Add support for the NO_COLOR environment variable. See the documentation for more information: https://torsion.org/borgmatic/docs/how-to/set-up-backups/#colored-output + * #839: Add log sending for the Apprise logging hook, enabled by default. See the documentation for + more information: + https://torsion.org/borgmatic/docs/how-to/monitor-your-backups/#apprise-hook * Switch from Drone to Gitea Actions for continuous integration. * Rename scripts/run-end-to-end-dev-tests to scripts/run-end-to-end-tests and use it in both dev - and CI for increased dev-CI parity. + and CI for better dev-CI parity. * Clarify documentation about restoring a database: borgmatic does not create the database upon restore. diff --git a/borgmatic/commands/borgmatic.py b/borgmatic/commands/borgmatic.py index ad790450..11552190 100644 --- a/borgmatic/commands/borgmatic.py +++ b/borgmatic/commands/borgmatic.py @@ -180,7 +180,7 @@ def run_configuration(config_filename, config, config_paths, arguments): try: if monitoring_hooks_are_activated: - # send logs irrespective of error + # Send logs irrespective of error. dispatch.call_hooks( 'ping_monitor', config, diff --git a/borgmatic/config/schema.yaml b/borgmatic/config/schema.yaml index 032f9789..65a775ed 100644 --- a/borgmatic/config/schema.yaml +++ b/borgmatic/config/schema.yaml @@ -1432,6 +1432,19 @@ properties: label: kodi - url: "line://Token@User" label: line + send_logs: + type: boolean + description: | + Send borgmatic logs to Apprise services as part the + "finish", "fail", and "log" states. Defaults to true. + example: false + logs_size_limit: + type: integer + description: | + Number of bytes of borgmatic logs to send to Apprise + services. Set to 0 to send all logs and disable this + truncation. Defaults to 1500. + example: 100000 start: type: object required: ['body'] @@ -1477,6 +1490,21 @@ properties: description: | Specify the message body. example: Your backups have failed. + log: + type: object + required: ['body'] + properties: + title: + type: string + description: | + Specify the message title. If left unspecified, no + title is sent. + example: Ping! + body: + type: string + description: | + Specify the message body. + example: Here is some info about your backups. states: type: array items: @@ -1485,13 +1513,15 @@ properties: - start - finish - fail + - log uniqueItems: true description: | - List of one or more monitoring states to ping for: "start", - "finish", and/or "fail". Defaults to pinging for failure - only. For each selected state, corresponding configuration - for the message title and body should be given. If any is - left unspecified, a generic message is emitted instead. + List of one or more monitoring states to ping for: + "start", "finish", "fail", and/or "log". Defaults to + pinging for failure only. For each selected state, + corresponding configuration for the message title and body + should be given. If any is left unspecified, a generic + message is emitted instead. example: - start - finish diff --git a/borgmatic/hooks/apprise.py b/borgmatic/hooks/apprise.py index 212bf7df..d1a55fc4 100644 --- a/borgmatic/hooks/apprise.py +++ b/borgmatic/hooks/apprise.py @@ -1,16 +1,36 @@ import logging import operator +import borgmatic.hooks.logs +import borgmatic.hooks.monitor + logger = logging.getLogger(__name__) -def initialize_monitor( - ping_url, config, config_filename, monitoring_log_level, dry_run -): # pragma: no cover +DEFAULT_LOGS_SIZE_LIMIT_BYTES = 100000 +HANDLER_IDENTIFIER = 'apprise' + + +def initialize_monitor(hook_config, config, config_filename, monitoring_log_level, dry_run): ''' - No initialization is necessary for this monitor. + Add a handler to the root logger that stores in memory the most recent logs emitted. That way, + we can send them all to an Apprise notification service upon a finish or failure state. But skip + this if the "send_logs" option is false. ''' - pass + if hook_config.get('send_logs') is False: + return + + logs_size_limit = max( + hook_config.get('logs_size_limit', DEFAULT_LOGS_SIZE_LIMIT_BYTES) + - len(borgmatic.hooks.logs.PAYLOAD_TRUNCATION_INDICATOR), + 0, + ) + + borgmatic.hooks.logs.add_handler( + borgmatic.hooks.logs.Forgetful_buffering_handler( + HANDLER_IDENTIFIER, logs_size_limit, monitoring_log_level + ) + ) def ping_monitor(hook_config, config, config_filename, state, monitoring_log_level, dry_run): @@ -59,9 +79,20 @@ def ping_monitor(hook_config, config, config_filename, state, monitoring_log_lev if dry_run: return + body = state_config.get('body') + + if state in ( + borgmatic.hooks.monitor.State.FINISH, + borgmatic.hooks.monitor.State.FAIL, + borgmatic.hooks.monitor.State.LOG, + ): + formatted_logs = borgmatic.hooks.logs.format_buffered_logs_for_payload(HANDLER_IDENTIFIER) + if formatted_logs: + body += f'\n\n{formatted_logs}' + result = apprise_object.notify( title=state_config.get('title', ''), - body=state_config.get('body'), + body=body, body_format=NotifyFormat.TEXT, notify_type=state_to_notify_type[state.name.lower()], ) @@ -70,10 +101,9 @@ def ping_monitor(hook_config, config, config_filename, state, monitoring_log_lev logger.warning(f'{config_filename}: Error sending some Apprise notifications') -def destroy_monitor( - ping_url_or_uuid, config, config_filename, monitoring_log_level, dry_run -): # pragma: no cover +def destroy_monitor(hook_config, config, config_filename, monitoring_log_level, dry_run): ''' - No destruction is necessary for this monitor. + Remove the monitor handler that was added to the root logger. This prevents the handler from + getting reused by other instances of this monitor. ''' - pass + borgmatic.hooks.logs.remove_handler(HANDLER_IDENTIFIER) diff --git a/borgmatic/hooks/healthchecks.py b/borgmatic/hooks/healthchecks.py index ae0772c5..8c63f217 100644 --- a/borgmatic/hooks/healthchecks.py +++ b/borgmatic/hooks/healthchecks.py @@ -2,6 +2,7 @@ import logging import requests +import borgmatic.hooks.logs from borgmatic.hooks import monitor logger = logging.getLogger(__name__) @@ -13,61 +14,8 @@ MONITOR_STATE_TO_HEALTHCHECKS = { monitor.State.LOG: 'log', } -PAYLOAD_TRUNCATION_INDICATOR = '...\n' -DEFAULT_PING_BODY_LIMIT_BYTES = 100000 - - -class Forgetful_buffering_handler(logging.Handler): - ''' - A buffering log handler that stores log messages in memory, and throws away messages (oldest - first) once a particular capacity in bytes is reached. But if the given byte capacity is zero, - don't throw away any messages. - ''' - - def __init__(self, byte_capacity, log_level): - super().__init__() - - self.byte_capacity = byte_capacity - self.byte_count = 0 - self.buffer = [] - self.forgot = False - self.setLevel(log_level) - - def emit(self, record): - message = record.getMessage() + '\n' - self.byte_count += len(message) - self.buffer.append(message) - - if not self.byte_capacity: - return - - while self.byte_count > self.byte_capacity and self.buffer: - self.byte_count -= len(self.buffer[0]) - self.buffer.pop(0) - self.forgot = True - - -def format_buffered_logs_for_payload(): - ''' - Get the handler previously added to the root logger, and slurp buffered logs out of it to - send to Healthchecks. - ''' - try: - buffering_handler = next( - handler - for handler in logging.getLogger().handlers - if isinstance(handler, Forgetful_buffering_handler) - ) - except StopIteration: - # No handler means no payload. - return '' - - payload = ''.join(message for message in buffering_handler.buffer) - - if buffering_handler.forgot: - return PAYLOAD_TRUNCATION_INDICATOR + payload - - return payload +DEFAULT_PING_BODY_LIMIT_BYTES = 1500 +HANDLER_IDENTIFIER = 'healthchecks' def initialize_monitor(hook_config, config, config_filename, monitoring_log_level, dry_run): @@ -81,12 +29,14 @@ def initialize_monitor(hook_config, config, config_filename, monitoring_log_leve ping_body_limit = max( hook_config.get('ping_body_limit', DEFAULT_PING_BODY_LIMIT_BYTES) - - len(PAYLOAD_TRUNCATION_INDICATOR), + - len(borgmatic.hooks.logs.PAYLOAD_TRUNCATION_INDICATOR), 0, ) - logging.getLogger().addHandler( - Forgetful_buffering_handler(ping_body_limit, monitoring_log_level) + borgmatic.hooks.logs.add_handler( + borgmatic.hooks.logs.Forgetful_buffering_handler( + HANDLER_IDENTIFIER, ping_body_limit, monitoring_log_level + ) ) @@ -117,7 +67,7 @@ def ping_monitor(hook_config, config, config_filename, state, monitoring_log_lev logger.debug(f'{config_filename}: Using Healthchecks ping URL {ping_url}') if state in (monitor.State.FINISH, monitor.State.FAIL, monitor.State.LOG): - payload = format_buffered_logs_for_payload() + payload = borgmatic.hooks.logs.format_buffered_logs_for_payload(HANDLER_IDENTIFIER) else: payload = '' @@ -138,8 +88,4 @@ def destroy_monitor(hook_config, config, config_filename, monitoring_log_level, Remove the monitor handler that was added to the root logger. This prevents the handler from getting reused by other instances of this monitor. ''' - logger = logging.getLogger() - - for handler in tuple(logger.handlers): - if isinstance(handler, Forgetful_buffering_handler): - logger.removeHandler(handler) + borgmatic.hooks.logs.remove_handler(HANDLER_IDENTIFIER) diff --git a/borgmatic/hooks/logs.py b/borgmatic/hooks/logs.py new file mode 100644 index 00000000..3cc6e605 --- /dev/null +++ b/borgmatic/hooks/logs.py @@ -0,0 +1,91 @@ +import logging + +PAYLOAD_TRUNCATION_INDICATOR = '...\n' + + +class Forgetful_buffering_handler(logging.Handler): + ''' + A buffering log handler that stores log messages in memory, and throws away messages (oldest + first) once a particular capacity in bytes is reached. But if the given byte capacity is zero, + don't throw away any messages. + + The given identifier is used to distinguish the instance of this handler used for one monitoring + hook from those instances used for other monitoring hooks. + ''' + + def __init__(self, identifier, byte_capacity, log_level): + super().__init__() + + self.identifier = identifier + self.byte_capacity = byte_capacity + self.byte_count = 0 + self.buffer = [] + self.forgot = False + self.setLevel(log_level) + + def emit(self, record): + message = record.getMessage() + '\n' + self.byte_count += len(message) + self.buffer.append(message) + + if not self.byte_capacity: + return + + while self.byte_count > self.byte_capacity and self.buffer: + self.byte_count -= len(self.buffer[0]) + self.buffer.pop(0) + self.forgot = True + + +def add_handler(handler): # pragma: no cover + ''' + Add the given handler to the global logger. + ''' + logging.getLogger().addHandler(handler) + + +def get_handler(identifier): + ''' + Given the identifier for an existing Forgetful_buffering_handler instance, return the handler. + + Raise ValueError if the handler isn't found. + ''' + try: + return next( + handler + for handler in logging.getLogger().handlers + if isinstance(handler, Forgetful_buffering_handler) and handler.identifier == identifier + ) + except StopIteration: + raise ValueError(f'A buffering handler for {identifier} was not found') + + +def format_buffered_logs_for_payload(identifier): + ''' + Get the handler previously added to the root logger, and slurp buffered logs out of it to + send to Healthchecks. + ''' + try: + buffering_handler = get_handler(identifier) + except ValueError: + # No handler means no payload. + return '' + + payload = ''.join(message for message in buffering_handler.buffer) + + if buffering_handler.forgot: + return PAYLOAD_TRUNCATION_INDICATOR + payload + + return payload + + +def remove_handler(identifier): + ''' + Given the identifier for an existing Forgetful_buffering_handler instance, remove it. + ''' + logger = logging.getLogger() + + try: + logger.removeHandler(get_handler(identifier)) + except ValueError: + pass diff --git a/docs/how-to/develop-on-borgmatic.md b/docs/how-to/develop-on-borgmatic.md index a722430e..9b443486 100644 --- a/docs/how-to/develop-on-borgmatic.md +++ b/docs/how-to/develop-on-borgmatic.md @@ -35,6 +35,14 @@ pipx ensurepath pipx install --editable . ``` +Or to work on the [Apprise +hook](https://torsion.org/borgmatic/docs/how-to/monitor-your-backups/#apprise-hook), +change that last line to: + +```bash +pipx install --editable .[Apprise] +``` + To get oriented with the borgmatic source code, have a look at the [source code reference](https://torsion.org/borgmatic/docs/reference/source-code/). @@ -141,6 +149,9 @@ the following deviations from it: separate from their contents. * Within multiline constructs, use standard four-space indentation. Don't align indentation with an opening delimiter. + * In general, spell out words in variable names instead of shortening them. + So, think `index` instead of `idx`. There are some notable exceptions to + this though (like `config`). borgmatic code uses the [Black](https://black.readthedocs.io/en/stable/) code formatter, the [Flake8](http://flake8.pycqa.org/en/latest/) code checker, and @@ -148,9 +159,12 @@ the [isort](https://github.com/timothycrosley/isort) import orderer, so certain code style requirements will be enforced when running automated tests. See the Black, Flake8, and isort documentation for more information. + ## Continuous integration -Each commit to main triggers [a continuous integration +Each commit to +[main](https://projects.torsion.org/borgmatic-collective/borgmatic/branches) +triggers [a continuous integration build](https://projects.torsion.org/borgmatic-collective/borgmatic/actions) which runs the test suite and updates [documentation](https://torsion.org/borgmatic/). These builds are also linked diff --git a/docs/how-to/monitor-your-backups.md b/docs/how-to/monitor-your-backups.md index 7485230d..da938711 100644 --- a/docs/how-to/monitor-your-backups.md +++ b/docs/how-to/monitor-your-backups.md @@ -149,7 +149,7 @@ backup begins, ends, or errors, but only when any of the `create`, `prune`, Then, if the actions complete successfully, borgmatic notifies Healthchecks of the success and includes borgmatic logs in the payload data sent to Healthchecks. This means that borgmatic logs show up in the Healthchecks UI, -although be aware that Healthchecks currently has a 10-kilobyte limit for the +although be aware that Healthchecks currently has a 100-kilobyte limit for the logs in each ping. If an error occurs during any action or hook, borgmatic notifies Healthchecks, @@ -385,7 +385,7 @@ pipx](https://torsion.org/borgmatic/docs/how-to/set-up-backups/#installation), run the following to install Apprise so borgmatic can use it: ```bash -sudo pipx install --editable --force borgmatic[Apprise] +sudo pipx install --force borgmatic[Apprise] ``` Omit `sudo` if borgmatic is installed as a non-root user. @@ -429,6 +429,37 @@ apprise: - fail ``` +New in version 1.8.9 borgmatic +logs are automatically included in the body data sent to your Apprise services +when a backup finishes or fails. + +You can customize the verbosity of the logs that are sent with borgmatic's +`--monitoring-verbosity` flag. The `--list` and `--stats` flags may also be of +use. See `borgmatic create --help` for more information. + +If you don't want any logs sent, you can disable this feature by setting +`send_logs` to `false`: + +```yaml +apprise: + services: + - url: gotify://hostname/token + label: gotify + send_logs: false +``` + +Or to limit the size of logs sent to Apprise services: + +```yaml +apprise: + services: + - url: gotify://hostname/token + label: gotify + logs_size_limit: 500 +``` + +This may be necessary for some services that reject large requests. + See the [configuration reference](https://torsion.org/borgmatic/docs/reference/configuration/) for details. diff --git a/tests/integration/hooks/test_apprise.py b/tests/integration/hooks/test_apprise.py new file mode 100644 index 00000000..075eacc6 --- /dev/null +++ b/tests/integration/hooks/test_apprise.py @@ -0,0 +1,28 @@ +import logging + +from flexmock import flexmock + +from borgmatic.hooks import apprise as module + + +def test_destroy_monitor_removes_apprise_handler(): + logger = logging.getLogger() + original_handlers = list(logger.handlers) + module.borgmatic.hooks.logs.add_handler( + module.borgmatic.hooks.logs.Forgetful_buffering_handler( + identifier=module.HANDLER_IDENTIFIER, byte_capacity=100, log_level=1 + ) + ) + + module.destroy_monitor(flexmock(), flexmock(), flexmock(), flexmock(), flexmock()) + + assert logger.handlers == original_handlers + + +def test_destroy_monitor_without_apprise_handler_does_not_raise(): + logger = logging.getLogger() + original_handlers = list(logger.handlers) + + module.destroy_monitor(flexmock(), flexmock(), flexmock(), flexmock(), flexmock()) + + assert logger.handlers == original_handlers diff --git a/tests/integration/hooks/test_healthchecks.py b/tests/integration/hooks/test_healthchecks.py index 687b4873..5db77d96 100644 --- a/tests/integration/hooks/test_healthchecks.py +++ b/tests/integration/hooks/test_healthchecks.py @@ -8,7 +8,11 @@ from borgmatic.hooks import healthchecks as module def test_destroy_monitor_removes_healthchecks_handler(): logger = logging.getLogger() original_handlers = list(logger.handlers) - logger.addHandler(module.Forgetful_buffering_handler(byte_capacity=100, log_level=1)) + module.borgmatic.hooks.logs.add_handler( + module.borgmatic.hooks.logs.Forgetful_buffering_handler( + identifier=module.HANDLER_IDENTIFIER, byte_capacity=100, log_level=1 + ) + ) module.destroy_monitor(flexmock(), flexmock(), flexmock(), flexmock(), flexmock()) diff --git a/tests/unit/hooks/test_apprise.py b/tests/unit/hooks/test_apprise.py index 446507b5..28bd45d4 100644 --- a/tests/unit/hooks/test_apprise.py +++ b/tests/unit/hooks/test_apprise.py @@ -13,10 +13,63 @@ def mock_apprise(): add=lambda servers: None, notify=lambda title, body, body_format, notify_type: None ) flexmock(apprise.Apprise).new_instances(apprise_mock) + return apprise_mock -def test_ping_monitor_adheres_dry_run(): +def test_initialize_monitor_with_send_logs_false_does_not_add_handler(): + flexmock(module.borgmatic.hooks.logs).should_receive('add_handler').never() + + module.initialize_monitor( + hook_config={'send_logs': False}, + config={}, + config_filename='test.yaml', + monitoring_log_level=1, + dry_run=False, + ) + + +def test_initialize_monitor_with_send_logs_true_adds_handler_with_default_log_size_limit(): + truncation_indicator_length = 4 + flexmock(module.borgmatic.hooks.logs).should_receive('Forgetful_buffering_handler').with_args( + module.HANDLER_IDENTIFIER, + module.DEFAULT_LOGS_SIZE_LIMIT_BYTES - truncation_indicator_length, + 1, + ).once() + flexmock(module.borgmatic.hooks.logs).should_receive('add_handler').once() + + module.initialize_monitor( + hook_config={'send_logs': True}, + config={}, + config_filename='test.yaml', + monitoring_log_level=1, + dry_run=False, + ) + + +def test_initialize_monitor_without_send_logs_adds_handler_with_default_log_size_limit(): + truncation_indicator_length = 4 + flexmock(module.borgmatic.hooks.logs).should_receive('Forgetful_buffering_handler').with_args( + module.HANDLER_IDENTIFIER, + module.DEFAULT_LOGS_SIZE_LIMIT_BYTES - truncation_indicator_length, + 1, + ).once() + flexmock(module.borgmatic.hooks.logs).should_receive('add_handler').once() + + module.initialize_monitor( + hook_config={}, + config={}, + config_filename='test.yaml', + monitoring_log_level=1, + dry_run=False, + ) + + +def test_ping_monitor_respects_dry_run(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return('loggy log') mock_apprise().should_receive('notify').never() module.ping_monitor( @@ -29,7 +82,9 @@ def test_ping_monitor_adheres_dry_run(): ) -def test_ping_monitor_does_not_hit_with_no_states(): +def test_ping_monitor_with_no_states_does_not_notify(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler').never() + flexmock(module.borgmatic.hooks.logs).should_receive('format_buffered_logs_for_payload').never() mock_apprise().should_receive('notify').never() module.ping_monitor( @@ -42,7 +97,11 @@ def test_ping_monitor_does_not_hit_with_no_states(): ) -def test_ping_monitor_hits_fail_by_default(): +def test_ping_monitor_notifies_fail_by_default(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return('') mock_apprise().should_receive('notify').with_args( title='A borgmatic FAIL event happened', body='A borgmatic FAIL event happened', @@ -61,7 +120,34 @@ def test_ping_monitor_hits_fail_by_default(): ) -def test_ping_monitor_hits_with_finish_default_config(): +def test_ping_monitor_with_logs_appends_logs_to_body(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return('loggy log') + mock_apprise().should_receive('notify').with_args( + title='A borgmatic FAIL event happened', + body='A borgmatic FAIL event happened\n\nloggy log', + body_format=NotifyFormat.TEXT, + notify_type=NotifyType.FAILURE, + ).once() + + for state in borgmatic.hooks.monitor.State: + module.ping_monitor( + {'services': [{'url': f'ntfys://{TOPIC}', 'label': 'ntfys'}]}, + {}, + 'config.yaml', + state, + monitoring_log_level=1, + dry_run=False, + ) + + +def test_ping_monitor_with_finish_default_config_notifies(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return('') mock_apprise().should_receive('notify').with_args( title='A borgmatic FINISH event happened', body='A borgmatic FINISH event happened', @@ -79,7 +165,9 @@ def test_ping_monitor_hits_with_finish_default_config(): ) -def test_ping_monitor_hits_with_start_default_config(): +def test_ping_monitor_with_start_default_config_notifies(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler').never() + flexmock(module.borgmatic.hooks.logs).should_receive('format_buffered_logs_for_payload').never() mock_apprise().should_receive('notify').with_args( title='A borgmatic START event happened', body='A borgmatic START event happened', @@ -97,7 +185,11 @@ def test_ping_monitor_hits_with_start_default_config(): ) -def test_ping_monitor_hits_with_fail_default_config(): +def test_ping_monitor_with_fail_default_config_notifies(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return('') mock_apprise().should_receive('notify').with_args( title='A borgmatic FAIL event happened', body='A borgmatic FAIL event happened', @@ -115,7 +207,11 @@ def test_ping_monitor_hits_with_fail_default_config(): ) -def test_ping_monitor_hits_with_log_default_config(): +def test_ping_monitor_with_log_default_config_notifies(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return('') mock_apprise().should_receive('notify').with_args( title='A borgmatic LOG event happened', body='A borgmatic LOG event happened', @@ -134,6 +230,10 @@ def test_ping_monitor_hits_with_log_default_config(): def test_ping_monitor_passes_through_custom_message_title(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return('') mock_apprise().should_receive('notify').with_args( title='foo', body='bar', @@ -156,6 +256,10 @@ def test_ping_monitor_passes_through_custom_message_title(): def test_ping_monitor_passes_through_custom_message_body(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return('') mock_apprise().should_receive('notify').with_args( title='', body='baz', @@ -177,7 +281,37 @@ def test_ping_monitor_passes_through_custom_message_body(): ) +def test_ping_monitor_passes_through_custom_message_body_and_appends_logs(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return('loggy log') + mock_apprise().should_receive('notify').with_args( + title='', + body='baz\n\nloggy log', + body_format=NotifyFormat.TEXT, + notify_type=NotifyType.FAILURE, + ).once() + + module.ping_monitor( + { + 'services': [{'url': f'ntfys://{TOPIC}', 'label': 'ntfys'}], + 'states': ['fail'], + 'fail': {'body': 'baz'}, + }, + {}, + 'config.yaml', + borgmatic.hooks.monitor.State.FAIL, + monitoring_log_level=1, + dry_run=False, + ) + + def test_ping_monitor_pings_multiple_services(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return('') mock_apprise().should_receive('add').with_args([f'ntfys://{TOPIC}', f'ntfy://{TOPIC}']).once() module.ping_monitor( @@ -196,6 +330,8 @@ def test_ping_monitor_pings_multiple_services(): def test_ping_monitor_logs_info_for_no_services(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler').never() + flexmock(module.borgmatic.hooks.logs).should_receive('format_buffered_logs_for_payload').never() flexmock(module.logger).should_receive('info').once() module.ping_monitor( @@ -209,6 +345,10 @@ def test_ping_monitor_logs_info_for_no_services(): def test_ping_monitor_logs_warning_when_notify_fails(): + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return('') mock_apprise().should_receive('notify').and_return(False) flexmock(module.logger).should_receive('warning').once() @@ -221,3 +361,15 @@ def test_ping_monitor_logs_warning_when_notify_fails(): monitoring_log_level=1, dry_run=False, ) + + +def test_destroy_monitor_does_not_raise(): + flexmock(module.borgmatic.hooks.logs).should_receive('remove_handler') + + module.destroy_monitor( + hook_config={}, + config={}, + config_filename='test.yaml', + monitoring_log_level=1, + dry_run=False, + ) diff --git a/tests/unit/hooks/test_healthchecks.py b/tests/unit/hooks/test_healthchecks.py index e3ab4386..479b0e34 100644 --- a/tests/unit/hooks/test_healthchecks.py +++ b/tests/unit/hooks/test_healthchecks.py @@ -3,72 +3,6 @@ from flexmock import flexmock from borgmatic.hooks import healthchecks as module -def test_forgetful_buffering_handler_emit_collects_log_records(): - handler = module.Forgetful_buffering_handler(byte_capacity=100, log_level=1) - handler.emit(flexmock(getMessage=lambda: 'foo')) - handler.emit(flexmock(getMessage=lambda: 'bar')) - - assert handler.buffer == ['foo\n', 'bar\n'] - assert not handler.forgot - - -def test_forgetful_buffering_handler_emit_collects_log_records_with_zero_byte_capacity(): - handler = module.Forgetful_buffering_handler(byte_capacity=0, log_level=1) - handler.emit(flexmock(getMessage=lambda: 'foo')) - handler.emit(flexmock(getMessage=lambda: 'bar')) - - assert handler.buffer == ['foo\n', 'bar\n'] - assert not handler.forgot - - -def test_forgetful_buffering_handler_emit_forgets_log_records_when_capacity_reached(): - handler = module.Forgetful_buffering_handler(byte_capacity=len('foo\nbar\n'), log_level=1) - handler.emit(flexmock(getMessage=lambda: 'foo')) - assert handler.buffer == ['foo\n'] - handler.emit(flexmock(getMessage=lambda: 'bar')) - assert handler.buffer == ['foo\n', 'bar\n'] - handler.emit(flexmock(getMessage=lambda: 'baz')) - assert handler.buffer == ['bar\n', 'baz\n'] - handler.emit(flexmock(getMessage=lambda: 'quux')) - assert handler.buffer == ['quux\n'] - assert handler.forgot - - -def test_format_buffered_logs_for_payload_flattens_log_buffer(): - handler = module.Forgetful_buffering_handler(byte_capacity=100, log_level=1) - handler.buffer = ['foo\n', 'bar\n'] - logger = flexmock(handlers=[handler]) - logger.should_receive('removeHandler') - flexmock(module.logging).should_receive('getLogger').and_return(logger) - - payload = module.format_buffered_logs_for_payload() - - assert payload == 'foo\nbar\n' - - -def test_format_buffered_logs_for_payload_inserts_truncation_indicator_when_logs_forgotten(): - handler = module.Forgetful_buffering_handler(byte_capacity=100, log_level=1) - handler.buffer = ['foo\n', 'bar\n'] - handler.forgot = True - logger = flexmock(handlers=[handler]) - logger.should_receive('removeHandler') - flexmock(module.logging).should_receive('getLogger').and_return(logger) - - payload = module.format_buffered_logs_for_payload() - - assert payload == '...\nfoo\nbar\n' - - -def test_format_buffered_logs_for_payload_without_handler_produces_empty_payload(): - logger = flexmock(handlers=[module.logging.Handler()]) - logger.should_receive('removeHandler') - flexmock(module.logging).should_receive('getLogger').and_return(logger) - - payload = module.format_buffered_logs_for_payload() - - assert payload == '' - - def mock_logger(): logger = flexmock() logger.should_receive('addHandler') @@ -81,8 +15,10 @@ def test_initialize_monitor_creates_log_handler_with_ping_body_limit(): monitoring_log_level = 1 mock_logger() - flexmock(module).should_receive('Forgetful_buffering_handler').with_args( - ping_body_limit - len(module.PAYLOAD_TRUNCATION_INDICATOR), monitoring_log_level + flexmock(module.borgmatic.hooks.logs).should_receive('Forgetful_buffering_handler').with_args( + module.HANDLER_IDENTIFIER, + ping_body_limit - len(module.borgmatic.hooks.logs.PAYLOAD_TRUNCATION_INDICATOR), + monitoring_log_level, ).once() module.initialize_monitor( @@ -94,8 +30,10 @@ def test_initialize_monitor_creates_log_handler_with_default_ping_body_limit(): monitoring_log_level = 1 mock_logger() - flexmock(module).should_receive('Forgetful_buffering_handler').with_args( - module.DEFAULT_PING_BODY_LIMIT_BYTES - len(module.PAYLOAD_TRUNCATION_INDICATOR), + flexmock(module.borgmatic.hooks.logs).should_receive('Forgetful_buffering_handler').with_args( + module.HANDLER_IDENTIFIER, + module.DEFAULT_PING_BODY_LIMIT_BYTES + - len(module.borgmatic.hooks.logs.PAYLOAD_TRUNCATION_INDICATOR), monitoring_log_level, ).once() @@ -107,8 +45,8 @@ def test_initialize_monitor_creates_log_handler_with_zero_ping_body_limit(): monitoring_log_level = 1 mock_logger() - flexmock(module).should_receive('Forgetful_buffering_handler').with_args( - ping_body_limit, monitoring_log_level + flexmock(module.borgmatic.hooks.logs).should_receive('Forgetful_buffering_handler').with_args( + module.HANDLER_IDENTIFIER, ping_body_limit, monitoring_log_level ).once() module.initialize_monitor( @@ -118,7 +56,7 @@ def test_initialize_monitor_creates_log_handler_with_zero_ping_body_limit(): def test_initialize_monitor_creates_log_handler_when_send_logs_true(): mock_logger() - flexmock(module).should_receive('Forgetful_buffering_handler').once() + flexmock(module.borgmatic.hooks.logs).should_receive('Forgetful_buffering_handler').once() module.initialize_monitor( {'send_logs': True}, {}, 'test.yaml', monitoring_log_level=1, dry_run=False @@ -127,7 +65,7 @@ def test_initialize_monitor_creates_log_handler_when_send_logs_true(): def test_initialize_monitor_bails_when_send_logs_false(): mock_logger() - flexmock(module).should_receive('Forgetful_buffering_handler').never() + flexmock(module.borgmatic.hooks.logs).should_receive('Forgetful_buffering_handler').never() module.initialize_monitor( {'send_logs': False}, {}, 'test.yaml', monitoring_log_level=1, dry_run=False @@ -135,7 +73,7 @@ def test_initialize_monitor_bails_when_send_logs_false(): def test_ping_monitor_hits_ping_url_for_start_state(): - flexmock(module).should_receive('Forgetful_buffering_handler') + flexmock(module.borgmatic.hooks.logs).should_receive('Forgetful_buffering_handler').never() hook_config = {'ping_url': 'https://example.com'} flexmock(module.requests).should_receive('post').with_args( 'https://example.com/start', data=''.encode('utf-8'), verify=True @@ -154,7 +92,10 @@ def test_ping_monitor_hits_ping_url_for_start_state(): def test_ping_monitor_hits_ping_url_for_finish_state(): hook_config = {'ping_url': 'https://example.com'} payload = 'data' - flexmock(module).should_receive('format_buffered_logs_for_payload').and_return(payload) + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return(payload) flexmock(module.requests).should_receive('post').with_args( 'https://example.com', data=payload.encode('utf-8'), verify=True ).and_return(flexmock(ok=True)) @@ -172,7 +113,10 @@ def test_ping_monitor_hits_ping_url_for_finish_state(): def test_ping_monitor_hits_ping_url_for_fail_state(): hook_config = {'ping_url': 'https://example.com'} payload = 'data' - flexmock(module).should_receive('format_buffered_logs_for_payload').and_return(payload) + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return(payload) flexmock(module.requests).should_receive('post').with_args( 'https://example.com/fail', data=payload.encode('utf'), verify=True ).and_return(flexmock(ok=True)) @@ -190,7 +134,10 @@ def test_ping_monitor_hits_ping_url_for_fail_state(): def test_ping_monitor_hits_ping_url_for_log_state(): hook_config = {'ping_url': 'https://example.com'} payload = 'data' - flexmock(module).should_receive('format_buffered_logs_for_payload').and_return(payload) + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return(payload) flexmock(module.requests).should_receive('post').with_args( 'https://example.com/log', data=payload.encode('utf'), verify=True ).and_return(flexmock(ok=True)) @@ -208,7 +155,10 @@ def test_ping_monitor_hits_ping_url_for_log_state(): def test_ping_monitor_with_ping_uuid_hits_corresponding_url(): hook_config = {'ping_url': 'abcd-efgh-ijkl-mnop'} payload = 'data' - flexmock(module).should_receive('format_buffered_logs_for_payload').and_return(payload) + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return(payload) flexmock(module.requests).should_receive('post').with_args( f"https://hc-ping.com/{hook_config['ping_url']}", data=payload.encode('utf-8'), @@ -228,7 +178,10 @@ def test_ping_monitor_with_ping_uuid_hits_corresponding_url(): def test_ping_monitor_skips_ssl_verification_when_verify_tls_false(): hook_config = {'ping_url': 'https://example.com', 'verify_tls': False} payload = 'data' - flexmock(module).should_receive('format_buffered_logs_for_payload').and_return(payload) + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return(payload) flexmock(module.requests).should_receive('post').with_args( 'https://example.com', data=payload.encode('utf-8'), verify=False ).and_return(flexmock(ok=True)) @@ -246,7 +199,10 @@ def test_ping_monitor_skips_ssl_verification_when_verify_tls_false(): def test_ping_monitor_executes_ssl_verification_when_verify_tls_true(): hook_config = {'ping_url': 'https://example.com', 'verify_tls': True} payload = 'data' - flexmock(module).should_receive('format_buffered_logs_for_payload').and_return(payload) + flexmock(module.borgmatic.hooks.logs).should_receive('get_handler') + flexmock(module.borgmatic.hooks.logs).should_receive( + 'format_buffered_logs_for_payload' + ).and_return(payload) flexmock(module.requests).should_receive('post').with_args( 'https://example.com', data=payload.encode('utf-8'), verify=True ).and_return(flexmock(ok=True)) @@ -262,7 +218,7 @@ def test_ping_monitor_executes_ssl_verification_when_verify_tls_true(): def test_ping_monitor_dry_run_does_not_hit_ping_url(): - flexmock(module).should_receive('Forgetful_buffering_handler') + flexmock(module.borgmatic.hooks.logs).should_receive('Forgetful_buffering_handler').never() hook_config = {'ping_url': 'https://example.com'} flexmock(module.requests).should_receive('post').never() @@ -277,7 +233,7 @@ def test_ping_monitor_dry_run_does_not_hit_ping_url(): def test_ping_monitor_does_not_hit_ping_url_when_states_not_matching(): - flexmock(module).should_receive('Forgetful_buffering_handler') + flexmock(module.borgmatic.hooks.logs).should_receive('Forgetful_buffering_handler').never() hook_config = {'ping_url': 'https://example.com', 'states': ['finish']} flexmock(module.requests).should_receive('post').never() @@ -292,7 +248,7 @@ def test_ping_monitor_does_not_hit_ping_url_when_states_not_matching(): def test_ping_monitor_hits_ping_url_when_states_matching(): - flexmock(module).should_receive('Forgetful_buffering_handler') + flexmock(module.borgmatic.hooks.logs).should_receive('Forgetful_buffering_handler').never() hook_config = {'ping_url': 'https://example.com', 'states': ['start', 'finish']} flexmock(module.requests).should_receive('post').with_args( 'https://example.com/start', data=''.encode('utf-8'), verify=True @@ -309,7 +265,7 @@ def test_ping_monitor_hits_ping_url_when_states_matching(): def test_ping_monitor_with_connection_error_logs_warning(): - flexmock(module).should_receive('Forgetful_buffering_handler') + flexmock(module.borgmatic.hooks.logs).should_receive('Forgetful_buffering_handler').never() hook_config = {'ping_url': 'https://example.com'} flexmock(module.requests).should_receive('post').with_args( 'https://example.com/start', data=''.encode('utf-8'), verify=True @@ -327,7 +283,7 @@ def test_ping_monitor_with_connection_error_logs_warning(): def test_ping_monitor_with_other_error_logs_warning(): - flexmock(module).should_receive('Forgetful_buffering_handler') + flexmock(module.borgmatic.hooks.logs).should_receive('Forgetful_buffering_handler').never() hook_config = {'ping_url': 'https://example.com'} response = flexmock(ok=False) response.should_receive('raise_for_status').and_raise( diff --git a/tests/unit/hooks/test_logs.py b/tests/unit/hooks/test_logs.py new file mode 100644 index 00000000..3c57d3a8 --- /dev/null +++ b/tests/unit/hooks/test_logs.py @@ -0,0 +1,103 @@ +import pytest +from flexmock import flexmock + +from borgmatic.hooks import logs as module + + +def test_forgetful_buffering_handler_emit_collects_log_records(): + handler = module.Forgetful_buffering_handler(identifier='test', byte_capacity=100, log_level=1) + handler.emit(flexmock(getMessage=lambda: 'foo')) + handler.emit(flexmock(getMessage=lambda: 'bar')) + + assert handler.buffer == ['foo\n', 'bar\n'] + assert not handler.forgot + + +def test_forgetful_buffering_handler_emit_collects_log_records_with_zero_byte_capacity(): + handler = module.Forgetful_buffering_handler(identifier='test', byte_capacity=0, log_level=1) + handler.emit(flexmock(getMessage=lambda: 'foo')) + handler.emit(flexmock(getMessage=lambda: 'bar')) + + assert handler.buffer == ['foo\n', 'bar\n'] + assert not handler.forgot + + +def test_forgetful_buffering_handler_emit_forgets_log_records_when_capacity_reached(): + handler = module.Forgetful_buffering_handler( + identifier='test', byte_capacity=len('foo\nbar\n'), log_level=1 + ) + handler.emit(flexmock(getMessage=lambda: 'foo')) + assert handler.buffer == ['foo\n'] + handler.emit(flexmock(getMessage=lambda: 'bar')) + assert handler.buffer == ['foo\n', 'bar\n'] + handler.emit(flexmock(getMessage=lambda: 'baz')) + assert handler.buffer == ['bar\n', 'baz\n'] + handler.emit(flexmock(getMessage=lambda: 'quux')) + assert handler.buffer == ['quux\n'] + assert handler.forgot + + +def test_get_handler_matches_by_identifier(): + handlers = [ + flexmock(), + flexmock(), + module.Forgetful_buffering_handler(identifier='other', byte_capacity=100, log_level=1), + module.Forgetful_buffering_handler(identifier='test', byte_capacity=100, log_level=1), + flexmock(), + ] + flexmock(module.logging.getLogger(), handlers=handlers) + + assert module.get_handler('test') == handlers[3] + + +def test_get_handler_without_match_raises(): + handlers = [ + flexmock(), + module.Forgetful_buffering_handler(identifier='other', byte_capacity=100, log_level=1), + ] + flexmock(module.logging.getLogger(), handlers=handlers) + + with pytest.raises(ValueError): + assert module.get_handler('test') + + +def test_format_buffered_logs_for_payload_flattens_log_buffer(): + handler = module.Forgetful_buffering_handler(identifier='test', byte_capacity=100, log_level=1) + handler.buffer = ['foo\n', 'bar\n'] + flexmock(module).should_receive('get_handler').and_return(handler) + + payload = module.format_buffered_logs_for_payload(identifier='test') + + assert payload == 'foo\nbar\n' + + +def test_format_buffered_logs_for_payload_inserts_truncation_indicator_when_logs_forgotten(): + handler = module.Forgetful_buffering_handler(identifier='test', byte_capacity=100, log_level=1) + handler.buffer = ['foo\n', 'bar\n'] + handler.forgot = True + flexmock(module).should_receive('get_handler').and_return(handler) + + payload = module.format_buffered_logs_for_payload(identifier='test') + + assert payload == '...\nfoo\nbar\n' + + +def test_format_buffered_logs_for_payload_without_handler_produces_empty_payload(): + flexmock(module).should_receive('get_handler').and_raise(ValueError) + + payload = module.format_buffered_logs_for_payload(identifier='test') + + assert payload == '' + + +def test_remove_handler_with_matching_handler_does_not_raise(): + flexmock(module).should_receive('get_handler').and_return(flexmock()) + flexmock(module.logging.getLogger()).should_receive('removeHandler') + + module.remove_handler('test') + + +def test_remove_handler_without_matching_handler_does_not_raise(): + flexmock(module).should_receive('get_handler').and_raise(ValueError) + + module.remove_handler('test')