Show elapsed time as (h:)mm:ss and add it to the notification

Replace the timing decorator with a start time kept by Backup.run(), so the final
notification can report how long the backup took.

simple_backup/simple_backup.py

@@ -25,9 +25,8 @@ import shlex
 import sys
 import warnings
 from collections import deque
-from collections.abc import Callable, Iterator
+from collections.abc import Iterator
 from datetime import datetime
-from functools import wraps
 from getpass import GetPassWarning, getpass
 from glob import glob
 from logging import StreamHandler
@@ -35,7 +34,7 @@ from shutil import get_terminal_size, rmtree, which
 from subprocess import PIPE, STDOUT, Popen
 from tempfile import mkstemp
 from timeit import default_timer
-from typing import Any, ParamSpec, TypedDict, TypeVar
+from typing import Any, TypedDict
 
 try:
     import paramiko
@@ -69,9 +68,6 @@ if journal:
     j_handler.setFormatter(j_format)
     logger.addHandler(j_handler)
 
-P = ParamSpec('P')
-R = TypeVar('R')
-
 # Seconds to wait for the TCP connection to the SSH server
 SSH_TIMEOUT = 15
 
@@ -80,25 +76,15 @@ PROGRESS_RE = re.compile(r'\s*(\S+)\s+\d+%\s+\S+\s+\d+:\d\d:\d\d(?:\s+\(xfr#\d+,
 PROGRESS_BAR_WIDTH = 30
 
 
-def timing(func: Callable[P, R]) -> Callable[P, R]:
-    """Decorator to measure execution time of a function
+def _format_duration(seconds: float) -> str:
+    """Format seconds as mm:ss, or h:mm:ss from one hour"""
 
-        Parameters:
-            func: Function to decorate
-    """
-    @wraps(func)
-    def wrapper(*args: P.args, **kwargs: P.kwargs) -> R:
-        start = default_timer()
+    s = round(seconds)
 
-        value = func(*args, **kwargs)
+    if s >= 3600:
+        return f'{s // 3600}:{s // 60 % 60:02d}:{s % 60:02d}'
 
-        end = default_timer()
-
-        logger.info('Elapsed time: %.3f seconds', end - start)
-
-        return value
-
-    return wrapper
+    return f'{s // 60:02d}:{s % 60:02d}'
 
 
 class MyFormatter(argparse.RawTextHelpFormatter, argparse.ArgumentDefaultsHelpFormatter):
@@ -233,6 +219,7 @@ class Backup:
         # Passed to sshpass through rsync's environment only
         self._password: str | None = None
         self._removed_count = 0
+        self._start_time = 0.0
 
     def check_params(self, homedir: str = '') -> int:
         """Check if parameters for the backup are valid"""
@@ -669,14 +656,19 @@ class Backup:
                     'Rsync error (return code %d) - Check rsync(1) for details', returncode)
 
     # Function to read configuration file
-    @timing
     def run(self) -> int:
         """Perform the backup"""
 
+        self._start_time = default_timer()
+
         try:
             return self._run()
         finally:
             self._remove_temp_files()
+            logger.info('Elapsed time: %s', self._elapsed())
+
+    def _elapsed(self) -> str:
+        return _format_duration(default_timer() - self._start_time)
 
     def close(self) -> None:
         """Close the SSH connection, if open"""
@@ -831,14 +823,14 @@ class Backup:
             logger.error(
                 'Some errors occurred while performing the backup')
 
-            _notify(
-                'Some errors occurred while performing the backup. Check log for details')
+            _notify(f'Some errors occurred while performing the backup (elapsed time {self._elapsed()}). '
+                    'Check log for details')
 
             return 4
 
         logger.info('Backup completed')
 
-        _notify('Backup completed')
+        _notify(f'Backup completed in {self._elapsed()}')
 
         return 0
 

tests/test_local.py

@@ -88,6 +88,18 @@ class TestRsync:
         assert 'Backup completed' in caplog.text
         assert 'rsync: sent' in caplog.text
 
+    def test_elapsed_time(self, src: Path, out: Path, monkeypatch: pytest.MonkeyPatch,
+                          caplog: pytest.LogCaptureFixture) -> None:
+        notifications: list[str] = []
+        monkeypatch.setattr(sb, '_notify', notifications.append)
+        # Start, then the notification and the log line
+        monkeypatch.setattr(sb, 'default_timer', iter([0.0, 863.187, 863.2]).__next__)
+
+        assert run_backup(out, [str(src)]) == 0
+
+        assert notifications[-1] == 'Backup completed in 14:23'
+        assert 'Elapsed time: 14:23' in caplog.text
+
     def test_hard_links(self, src: Path, out: Path) -> None:
         assert run_backup(out, [str(src)]) == 0
         (src / 'changed.txt').write_text('second')
@@ -231,6 +243,13 @@ class TestReadRecords:
         assert list(sb._read_records(stream)) == ['file', '', 'namé', '�']
 
 
+@pytest.mark.parametrize(('seconds', 'text'), [
+    (0.4, '00:00'), (59.6, '01:00'), (863.187, '14:23'), (3599.4, '59:59'), (3600, '1:00:00'), (37230, '10:20:30'),
+])
+def test_format_duration(seconds: float, text: str) -> None:
+    assert sb._format_duration(seconds) == text
+
+
 class TestProgressBar:
     @pytest.fixture(autouse=True)
     def terminal(self, monkeypatch: pytest.MonkeyPatch) -> None: