diff --git a/src/backy/backup.py b/src/backy/backup.py index 0da06907..c7b77931 100644 --- a/src/backy/backup.py +++ b/src/backy/backup.py @@ -667,7 +667,7 @@ async def _pull_metadata(self, api: APIClient): log.warning("pull-error", exc_info=True) remote_revs = [] log.debug( - "pull-found-matching-server", + "pull-found-revs", revs=len(remote_revs), ) diff --git a/src/backy/logging.py b/src/backy/logging.py index 2efde303..40893d31 100644 --- a/src/backy/logging.py +++ b/src/backy/logging.py @@ -11,13 +11,15 @@ import structlog +from backy import utils + try: import colorama except ImportError: colorama = None _MISSING = "{who} requires the {package} package installed." -_EVENT_WIDTH = 30 # pad the event name to so many characters +_EVENT_WIDTH = 35 # pad the event name to so many characters if sys.stderr.isatty() and colorama: COLORIZED_TTY_OUTPUT = True @@ -228,6 +230,10 @@ def write(line): + RESET_ALL + " " ) + if len(subsystem + event) > self._pad_event and hasattr( + utils, "log_data" + ): + raise RuntimeWarning("logline to long: " + subsystem + event) logger_name = event_dict.pop("logger", None) if logger_name is not None: diff --git a/src/backy/scheduler.py b/src/backy/scheduler.py index 83dcfcc7..ae89b4c8 100644 --- a/src/backy/scheduler.py +++ b/src/backy/scheduler.py @@ -225,16 +225,10 @@ async def run_forever(self): self.update_status("finished") async def pull_metadata(self): - try: - await self.backup.pull_metadata(self.daemon.peers, self.taskid) - except Exception: - self.log.exception("pull-metadata-failed") + await self.backup.pull_metadata(self.daemon.peers, self.taskid) async def push_metadata(self): - try: - await self.backup.push_metadata(self.daemon.peers, self.taskid) - except Exception: - self.log.exception("push-metadata-failed") + await self.backup.push_metadata(self.daemon.peers, self.taskid) async def run_backup(self, tags): self.log.info("backup-started", tags=", ".join(tags)) diff --git a/src/backy/tests/test_client.py b/src/backy/tests/test_client.py index 04c89aef..9b537b02 100644 --- a/src/backy/tests/test_client.py +++ b/src/backy/tests/test_client.py @@ -166,12 +166,12 @@ async def test_cli_run(daemon, cli_client, monkeypatch): assert ( Ellipsis( """\ -... D ~[ABCD] api/new-conn path='/v1/jobs/test01/run' query='' -... D ~cli[ABCD] api/auth-passed \n\ -... I ~cli[ABCD] api/run-job \n\ -... I ~cli[ABCD] api/get-job name='test01' -... D ~cli[ABCD] api/request-result status_code=202 -... I - CLIClient/triggered-run job='test01' +... D ~[ABCD] api/new-conn path='/v1/jobs/test01/run' query='' +... D ~cli[ABCD] api/auth-passed \n\ +... I ~cli[ABCD] api/run-job \n\ +... I ~cli[ABCD] api/get-job name='test01' +... D ~cli[ABCD] api/request-result status_code=202 +... I - CLIClient/triggered-run job='test01' """ ) == utils.log_data @@ -189,13 +189,13 @@ async def test_cli_run_missing(daemon, cli_client): assert ( Ellipsis( """\ -... D ~[ABCD] api/new-conn path='/v1/jobs/aaaa/run' query='' -... D ~cli[ABCD] api/auth-passed \n\ -... I ~cli[ABCD] api/run-job \n\ -... I ~cli[ABCD] api/get-job name='aaaa' -... W ~cli[ABCD] api/get-job-not-found name='aaaa' -... D ~cli[ABCD] api/request-result status_code=404 -... E - CLIClient/unknown-job job='aaaa' +... D ~[ABCD] api/new-conn path='/v1/jobs/aaaa/run' query='' +... D ~cli[ABCD] api/auth-passed \n\ +... I ~cli[ABCD] api/run-job \n\ +... I ~cli[ABCD] api/get-job name='aaaa' +... W ~cli[ABCD] api/get-job-not-found name='aaaa' +... D ~cli[ABCD] api/request-result status_code=404 +... E - CLIClient/unknown-job job='aaaa' """ ) == utils.log_data @@ -216,22 +216,22 @@ async def test_cli_runall(daemon, cli_client, monkeypatch): assert ( Ellipsis( """\ -... D ~[ABCD] api/new-conn path='/v1/jobs' query='' -... D ~cli[ABCD] api/auth-passed \n\ -... I ~cli[ABCD] api/get-jobs \n\ -... D ~cli[ABCD] api/request-result response=... -... D ~[ABCD] api/new-conn path='/v1/jobs/test01/run' query='' -... D ~cli[ABCD] api/auth-passed \n\ -... I ~cli[ABCD] api/run-job \n\ -... I ~cli[ABCD] api/get-job name='test01' -... D ~cli[ABCD] api/request-result status_code=202 -... I - CLIClient/triggered-run job='test01' -... D ~[ABCD] api/new-conn path='/v1/jobs/foo00/run' query='' -... D ~cli[ABCD] api/auth-passed \n\ -... I ~cli[ABCD] api/run-job \n\ -... I ~cli[ABCD] api/get-job name='foo00' -... D ~cli[ABCD] api/request-result status_code=202 -... I - CLIClient/triggered-run job='foo00' +... D ~[ABCD] api/new-conn path='/v1/jobs' query='' +... D ~cli[ABCD] api/auth-passed \n\ +... I ~cli[ABCD] api/get-jobs \n\ +... D ~cli[ABCD] api/request-result response=... +... D ~[ABCD] api/new-conn path='/v1/jobs/test01/run' query='' +... D ~cli[ABCD] api/auth-passed \n\ +... I ~cli[ABCD] api/run-job \n\ +... I ~cli[ABCD] api/get-job name='test01' +... D ~cli[ABCD] api/request-result status_code=202 +... I - CLIClient/triggered-run job='test01' +... D ~[ABCD] api/new-conn path='/v1/jobs/foo00/run' query='' +... D ~cli[ABCD] api/auth-passed \n\ +... I ~cli[ABCD] api/run-job \n\ +... I ~cli[ABCD] api/get-job name='foo00' +... D ~cli[ABCD] api/request-result status_code=202 +... I - CLIClient/triggered-run job='foo00' """ ) == utils.log_data @@ -249,12 +249,12 @@ async def test_cli_reload(daemon, cli_client, monkeypatch): assert ( Ellipsis( """\ -... I - CLIClient/reloading-daemon \n\ -... D ~[ABCD] api/new-conn path='/v1/reload' query='' -... D ~cli[ABCD] api/auth-passed \n\ -... I ~cli[ABCD] api/reload-daemon \n\ -... D ~cli[ABCD] api/request-result status_code=204 -... I - CLIClient/reloaded-daemon \n\ +... I - CLIClient/reloading-daemon \n\ +... D ~[ABCD] api/new-conn path='/v1/reload' query='' +... D ~cli[ABCD] api/auth-passed \n\ +... I ~cli[ABCD] api/reload-daemon \n\ +... D ~cli[ABCD] api/request-result status_code=204 +... I - CLIClient/reloaded-daemon \n\ """ ) == utils.log_data @@ -270,11 +270,11 @@ async def test_cli_check_ok(daemon, cli_client): assert ( Ellipsis( """\ -... D ~[ABCD] api/new-conn path='/v1/status' query='filter=' -... D ~cli[ABCD] api/auth-passed \n\ -... I ~cli[ABCD] api/get-status filter='' -... D ~cli[ABCD] api/request-result response=... -... I - CLIClient/check-exit exitcode=0 jobs=2 +... D ~[ABCD] api/new-conn path='/v1/status' query='filter=' +... D ~cli[ABCD] api/auth-passed \n\ +... I ~cli[ABCD] api/get-status filter='' +... D ~cli[ABCD] api/request-result response=... +... I - CLIClient/check-exit exitcode=0 jobs=2 """ ) == utils.log_data @@ -296,12 +296,12 @@ async def test_cli_check_too_old(daemon, clock, cli_client, log): assert ( Ellipsis( """\ -... D ~[ABCD] api/new-conn path='/v1/status' query='filter=' -... D ~cli[ABCD] api/auth-passed \n\ -... I ~cli[ABCD] api/get-status filter='' -... D ~cli[ABCD] api/request-result response=... -... C test01 CLIClient/check-sla-violation last_time='2015-08-30 07:06:47+00:00' sla_overdue=172800.0 -... I - CLIClient/check-exit exitcode=2 jobs=2 +... D ~[ABCD] api/new-conn path='/v1/status' query='filter=' +... D ~cli[ABCD] api/auth-passed \n\ +... I ~cli[ABCD] api/get-status filter='' +... D ~cli[ABCD] api/request-result response=... +... C test01 CLIClient/check-sla-violation last_time='2015-08-30 07:06:47+00:00' sla_overdue=172800.0 +... I - CLIClient/check-exit exitcode=2 jobs=2 """ ) == utils.log_data @@ -323,12 +323,12 @@ async def test_cli_check_manual_tags(daemon, cli_client, log): assert ( Ellipsis( """\ -... D ~[ABCD] api/new-conn path='/v1/status' query='filter=' -... D ~cli[ABCD] api/auth-passed \n\ -... I ~cli[ABCD] api/get-status filter='' -... D ~cli[ABCD] api/request-result response=... -... I test01 CLIClient/check-manual-tags manual_tags='manual:test' -... I - CLIClient/check-exit exitcode=0 jobs=2 +... D ~[ABCD] api/new-conn path='/v1/status' query='filter=' +... D ~cli[ABCD] api/auth-passed \n\ +... I ~cli[ABCD] api/get-status filter='' +... D ~cli[ABCD] api/request-result response=... +... I test01 CLIClient/check-manual-tags manual_tags='manual:test' +... I - CLIClient/check-exit exitcode=0 jobs=2 """ ) == utils.log_data @@ -347,12 +347,12 @@ async def test_cli_check_quarantine(daemon, cli_client, log): assert ( Ellipsis( """\ -... D ~[ABCD] api/new-conn path='/v1/status' query='filter=' -... D ~cli[ABCD] api/auth-passed \n\ -... I ~cli[ABCD] api/get-status filter='' -... D ~cli[ABCD] api/request-result response=... -... W test01 CLIClient/check-quarantined reports=1 -... I - CLIClient/check-exit exitcode=1 jobs=2 +... D ~[ABCD] api/new-conn path='/v1/status' query='filter=' +... D ~cli[ABCD] api/auth-passed \n\ +... I ~cli[ABCD] api/get-status filter='' +... D ~cli[ABCD] api/request-result response=... +... W test01 CLIClient/check-quarantined reports=1 +... I - CLIClient/check-exit exitcode=1 jobs=2 """ ) == utils.log_data diff --git a/src/backy/tests/test_daemon.py b/src/backy/tests/test_daemon.py index 76b3f3d9..663e20ff 100644 --- a/src/backy/tests/test_daemon.py +++ b/src/backy/tests/test_daemon.py @@ -337,44 +337,44 @@ async def wait_for_job_finished(): assert ( Ellipsis( """\ -... D test01[...] job/loop-started \n\ -... D test01[...] quarantine/scan entries=0 -... I test01[...] job/waiting next_tags='daily' next_time='2015-09-02 07:32:51' -... E test01[...] job/exception exception_class='builtins.Exception' exception_msg='' +... D test01[...] job/loop-started \n\ +... D test01[...] quarantine/scan entries=0 +... I test01[...] job/waiting next_tags='daily' next_time='2015-09-02 07:32:51' +... E test01[...] job/exception exception_class='builtins.Exception' exception_msg='' exception>\tTraceback (most recent call last): exception>\t File "/.../src/backy/scheduler.py", line ..., in run_forever exception>\t await self.run_backup(next_tags) exception>\t File "/.../src/backy/tests/test_daemon.py", line ..., in failing_coroutine exception>\t raise Exception() exception>\tException -... W test01[...] job/backoff backoff=120 -... D test01[...] quarantine/scan entries=0 -... I test01[...] job/waiting next_tags='daily' next_time='2015-09-01 09:08:47' -... E test01[...] job/exception exception_class='builtins.Exception' exception_msg='' +... W test01[...] job/backoff backoff=120 +... D test01[...] quarantine/scan entries=0 +... I test01[...] job/waiting next_tags='daily' next_time='2015-09-01 09:08:47' +... E test01[...] job/exception exception_class='builtins.Exception' exception_msg='' exception>\tTraceback (most recent call last): exception>\t File "/.../src/backy/scheduler.py", line ..., in run_forever exception>\t await self.run_backup(next_tags) exception>\t File "/.../src/backy/tests/test_daemon.py", line ..., in failing_coroutine exception>\t raise Exception() exception>\tException -... W test01[...] job/backoff backoff=240 -... D test01[...] quarantine/scan entries=0 -... I test01[...] job/waiting next_tags='daily' next_time='2015-09-01 09:10:47' -... E test01[...] job/exception exception_class='builtins.Exception' exception_msg='' +... W test01[...] job/backoff backoff=240 +... D test01[...] quarantine/scan entries=0 +... I test01[...] job/waiting next_tags='daily' next_time='2015-09-01 09:10:47' +... E test01[...] job/exception exception_class='builtins.Exception' exception_msg='' exception>\tTraceback (most recent call last): exception>\t File "/.../src/backy/scheduler.py", line ..., in run_forever exception>\t await self.run_backup(next_tags) exception>\t File "/.../src/backy/tests/test_daemon.py", line ..., in failing_coroutine exception>\t raise Exception() exception>\tException -... W test01[...] job/backoff backoff=480 -... D test01[...] quarantine/scan entries=0 -... I test01[...] job/waiting next_tags='daily' next_time='2015-09-01 09:14:47' -... I test01[...] backup/pull-start \n\ -... I test01[...] backup/push-start \n\ -... I test01[...] job/stop \n\ -... D test01[...] quarantine/scan entries=0 -... I test01[...] job/waiting next_tags='daily' next_time='2015-09-02 07:32:51' +... W test01[...] job/backoff backoff=480 +... D test01[...] quarantine/scan entries=0 +... I test01[...] job/waiting next_tags='daily' next_time='2015-09-01 09:14:47' +... I test01[...] backup/pull-start \n\ +... I test01[...] backup/push-start \n\ +... I test01[...] job/stop \n\ +... D test01[...] quarantine/scan entries=0 +... I test01[...] job/waiting next_tags='daily' next_time='2015-09-02 07:32:51' """ ) == utils.log_data diff --git a/src/backy/tests/test_main.py b/src/backy/tests/test_main.py index 12bb88e8..c71d9be4 100644 --- a/src/backy/tests/test_main.py +++ b/src/backy/tests/test_main.py @@ -138,9 +138,9 @@ def test_call_status(capsys, backup, argv, monkeypatch): assert ( Ellipsis( """\ -... D command/invoked args='... -v -b ... status' -... D command/parsed func='status' func_args={'yaml_': False} -... D command/successful \n\ +... D command/invoked args='... -v -b ... status' +... D command/parsed func='status' func_args={'yaml_': False} +... D command/successful \n\ """ ) == utils.log_data @@ -187,10 +187,10 @@ def test_call_backup(tmpdir, capsys, argv, monkeypatch): assert ( Ellipsis( """\ -... D command/invoked args='... -v backup manual:test' -... D command/parsed func='backup' func_args={'force': False, 'tags': 'manual:test'} -... D quarantine/scan entries=0 -... D command/successful \n\ +... D command/invoked args='... -v backup manual:test' +... D command/parsed func='backup' func_args={'force': False, 'tags': 'manual:test'} +... D quarantine/scan entries=0 +... D command/successful \n\ """ ) == utils.log_data @@ -248,11 +248,11 @@ def test_call_client( assert ( Ellipsis( f"""\ -... D command/invoked args='... -v client -c ... {action}{" "*bool(args)}{", ".join(args.values())}' -... D command/parsed func='client' func_args={{'config': '...', 'peer': None, \ +... D command/invoked args='... -v client -c ... {action}{" "*bool(args)}{", ".join(args.values())}' +... D command/parsed func='client' func_args={{'config': '...', 'peer': None, \ 'url': None, 'token': None{", "*bool(args)}{str(args)[1:-1]}, 'apifunc': '{action}'}} -... D daemon/read-config ... -... D command/successful \n\ +... D daemon/read-config ... +... D command/successful \n\ """ ) == utils.log_data @@ -282,9 +282,9 @@ def test_call_scheduler(capsys, backup, argv, monkeypatch, tmpdir): assert ( Ellipsis( """\ -... D command/invoked args='... -v -b ... scheduler' -... D command/parsed func='scheduler' func_args={'config': '/etc/backy.conf'} -... D command/successful \n\ +... D command/invoked args='... -v -b ... scheduler' +... D command/parsed func='scheduler' func_args={'config': '/etc/backy.conf'} +... D command/successful \n\ """ ) == utils.log_data @@ -317,11 +317,11 @@ def test_call_tags(capsys, backup, argv, monkeypatch, action): assert ( Ellipsis( f"""\ -... D quarantine/scan entries=0 -... D command/invoked args='... -v -b ... tags {action} last manual:a' -... D command/parsed func='tags' func_args={{'autoremove': False, 'force': False, 'expect': None, \ +... D quarantine/scan entries=0 +... D command/invoked args='... -v -b ... tags {action} last manual:a' +... D command/parsed func='tags' func_args={{'autoremove': False, 'force': False, 'expect': None, \ 'action': '{action}', 'revision': 'last', 'tags': 'manual:a'}} -... D command/successful \n\ +... D command/successful \n\ """ ) == utils.log_data @@ -348,10 +348,10 @@ def test_call_expire(capsys, backup, argv, monkeypatch): assert ( Ellipsis( """\ -... D quarantine/scan entries=0 -... D command/invoked args='... -v -b ... expire' -... D command/parsed func='expire' func_args={} -... D command/successful \n\ +... D quarantine/scan entries=0 +... D command/invoked args='... -v -b ... expire' +... D command/parsed func='expire' func_args={} +... D command/successful \n\ """ ) == utils.log_data @@ -379,9 +379,9 @@ def do_raise(*args, **kw): assert ( Ellipsis( """\ -... D command/invoked args='... -l ... -b ... status' -... D command/parsed func='status' func_args={'yaml_': False} -... E command/failed exception_class='builtins.RuntimeError' exception_msg='test' +... D command/invoked args='... -l ... -b ... status' +... D command/parsed func='status' func_args={'yaml_': False} +... E command/failed exception_class='builtins.RuntimeError' exception_msg='test' exception>\tTraceback (most recent call last): exception>\t File ".../src/backy/main.py", line ..., in main exception>\t func(**func_args)