Report a device that sends no data for 5 minutes

If the server had no data for the device, bmspy-ups slept and read again with no report. A battery that stopped answering during a power failure gave no email and no shutdown.

bmspy-ups now sends one email after 5 minutes with no data, and one more when the data returns. A new email for a loss needs another 5 minutes with no data after that return. The same rule applies to the wait at startup.

bmspy/ups.py

@@ -7,13 +7,15 @@ import smtplib
 import ssl
 import socket
 from collections import deque
-from collections.abc import Collection
+from collections.abc import Callable, Collection
 
 from bmspy import client
 from bmspy.classes import UPS, BMSScalarField
 
 DAEMON_UPDATE_PERIOD = 30
 STARTUP_RETRY_PERIOD = 5
+# Report a device that sends no data for this many seconds.
+DATA_LOSS_PERIOD = 300
 USAGE_ERROR_STATUS = 2
 
 scheduled_shutdown = False
@@ -64,7 +66,43 @@ def _resolve_ups_device(data: Collection[str], requested: str | None) -> str | N
     return next(iter(data))
 
 
-def _wait_for_ups_device(socket_path: str, requested: str | None) -> str | None:
+class _DataMonitor:
+    """Report when the device stops sending data, and when the data returns.
+
+    One email goes out after DATA_LOSS_PERIOD seconds with no data. The next
+    email is the one for the return of the data, so a long failure sends one
+    email and not one for each read.
+    """
+
+    def __init__(self, send_email: Callable[..., None]) -> None:
+        self.send_email = send_email
+        self.last_data = time.monotonic()
+        self.reported = False
+
+    def update(self, name: str, has_data: bool) -> None:
+        """Record the result of one read of the device *name*."""
+        now = time.monotonic()
+        if has_data:
+            self.last_data = now
+            if self.reported:
+                self.reported = False
+                self.send_email(
+                    text="data from UPS '{}' regained".format(name),
+                    level="Data recovery alert",
+                )
+        elif not self.reported and now - self.last_data >= DATA_LOSS_PERIOD:
+            self.reported = True
+            self.send_email(
+                text="no data from UPS '{}' for {} minutes".format(
+                    name, DATA_LOSS_PERIOD // 60
+                ),
+                level="Data loss alert",
+            )
+
+
+def _wait_for_ups_device(
+    socket_path: str, requested: str | None, data_monitor: _DataMonitor | None = None,
+) -> str | None:
     """Select the device to monitor, then wait until the server has data for it.
 
     The selection uses the configured device names, not the devices that have
@@ -76,6 +114,8 @@ def _wait_for_ups_device(socket_path: str, requested: str | None) -> str | None:
         return None
     waiting = False
     while name not in client.read_data(socket_path, "ups", ups=name):
+        if data_monitor is not None:
+            data_monitor.update(name, False)
         if not waiting:
             print("UPS '{}' has no data yet, waiting...".format(name))
             waiting = True
@@ -249,7 +289,20 @@ def main() -> None:
     client.handle_registration(args.socket, "ups", debug)
     atexit.register(client.handle_registration, args.socket, "ups", debug)
 
-    device_name = _wait_for_ups_device(args.socket, args.device)
+    def send_email(text: str, level: str) -> None:
+        handle_email(
+            text=text,
+            level=level,
+            recipient=args.recipient,
+            mailserver=args.mailserver,
+            port=args.port,
+            mailuser=args.mailuser,
+            mailpass=args.mailpass,
+            debug=debug,
+        )
+
+    data_monitor = _DataMonitor(send_email)
+    device_name = _wait_for_ups_device(args.socket, args.device, data_monitor)
     if device_name is None:
         # A wrong or missing --device is a usage error, as in argparse. A retry
         # cannot fix it, so the service file does not restart on this status.
@@ -259,6 +312,7 @@ def main() -> None:
     while True:
         data = client.read_data(args.socket, "ups", ups=device_name)
         device_obj = data.get(device_name)
+        data_monitor.update(device_name, device_obj is not None)
         if device_obj is None:
             time.sleep(DAEMON_UPDATE_PERIOD)
             continue

tests/test_ups.py

@@ -469,13 +469,18 @@ class TestUpsMain:
     def _events(self, readings, argv=None):
         """Run main() over (current, charge ratio) readings, 30 seconds apart.
 
-        Return (reading number, event) for each email and each shutdown call.
+        A reading of None is a read in which the server has no data for the
+        device. Return (reading number, event) for each email and each
+        shutdown call.
         """
-        sequence = [self._make_data(*reading) for reading in readings]
-        for data, (current, _) in zip(sequence, readings):
-            if current is None:
+        sequence = [{} if reading is None else self._make_data(*reading) for reading in readings]
+        for data, reading in zip(sequence, readings):
+            if reading is not None and reading[0] is None:
                 del data["testups"]._fields["bms_current_amps"]
-        events, number = [], [0]
+        events, number, clock = [], [0], [1000.0]
+
+        def sleep(seconds):
+            clock[0] += seconds
 
         def read(*args, **kwargs):
             if number[0] > len(sequence):
@@ -487,7 +492,8 @@ class TestUpsMain:
         with patch("sys.argv", ["bmspy-ups"] + (argv or [])), \
              patch("bmspy.ups.client.read_data", side_effect=read), \
              patch("bmspy.ups.client.handle_registration"), \
-             patch("bmspy.ups.time.sleep"), \
+             patch("bmspy.ups.time.sleep", side_effect=sleep), \
+             patch("bmspy.ups.time.monotonic", side_effect=lambda: clock[0]), \
              patch("bmspy.ups.handle_shutdown",
                    side_effect=lambda action, **kw: events.append((number[0] - 1, action))), \
              patch("bmspy.ups.handle_email",
@@ -555,6 +561,34 @@ class TestUpsMain:
         events = self._events([(None, 0.95)] * 5 + [(None, 0.20)] * 2)
         assert events == [(7, "shutdown"), (7, "Critical alert")]
 
+    def test_no_data_for_five_minutes_is_reported_once_and_the_return_once(self):
+        """Readings are 30 seconds apart, so the tenth read with no data is at 5 minutes."""
+        readings = (
+            [(1.0, 0.95)] * 3      # readings 1 to 3: data
+            + [None] * 25          # 4 to 28: no data for 12.5 minutes
+            + [(1.0, 0.95)] * 3    # 29 to 31: the data returns
+            + [None] * 9           # 32 to 40: 4.5 minutes, below the limit
+            + [(1.0, 0.95)] * 2    # 41 and 42
+            + [None] * 12          # 43 to 54: no data for 6 minutes
+        )
+        assert self._events(readings) == [
+            (13, "Data loss alert"), (29, "Data recovery alert"), (52, "Data loss alert"),
+        ]
+
+    def test_data_loss_email_names_the_device(self):
+        send_email = MagicMock()
+        with patch("bmspy.ups.time.monotonic", side_effect=[0, 299, 300, 900, 901]):
+            monitor = ups_mod._DataMonitor(send_email)
+            monitor.update("network", False)   # 299 seconds: below the limit
+            send_email.assert_not_called()
+            monitor.update("network", False)   # 300 seconds
+            monitor.update("network", False)   # no second email
+            monitor.update("network", True)
+        assert [c.kwargs for c in send_email.call_args_list] == [
+            {"text": "no data from UPS 'network' for 5 minutes", "level": "Data loss alert"},
+            {"text": "data from UPS 'network' regained", "level": "Data recovery alert"},
+        ]
+
     def test_main_not_enough_history_debug_2(self, capsys):
         """With debug=2 and < 4 readings, prints 'not enough readings'."""
         data_seq = [self._make_data(0.0, 0.95)] * 5
@@ -680,6 +714,30 @@ class TestUpsMainDeviceSelection:
         # The reason is reported once, not on each retry.
         assert capsys.readouterr().out.count("UPS 'ups1' has no data yet") == 1
 
+    def test_no_data_at_startup_for_five_minutes_is_reported(self):
+        """The startup wait reads every 5 seconds, so read 61 is at 5 minutes."""
+        clock = [1000.0]
+
+        def sleep(seconds):
+            clock[0] += seconds
+
+        reads = [{}] * 70 + [self._make_data("ups1"), self._make_data("ups1"), StopIteration("done")]
+        mock_email = MagicMock()
+        with patch("sys.argv", ["bmspy-ups", "--to", "admin@example.com"]), \
+             patch("bmspy.ups.client.list_devices", return_value=["ups1"]), \
+             patch("bmspy.ups.client.read_data", side_effect=reads) as read_data, \
+             patch("bmspy.ups.client.handle_registration"), \
+             patch("bmspy.ups.time.sleep", side_effect=sleep), \
+             patch("bmspy.ups.time.monotonic", side_effect=lambda: clock[0]), \
+             patch("bmspy.ups.handle_email", mock_email):
+            with pytest.raises(StopIteration):
+                ups_mod.main()
+        assert [(c.kwargs["level"], c.kwargs["recipient"]) for c in mock_email.call_args_list] == [
+            ("Data loss alert", "admin@example.com"), ("Data recovery alert", "admin@example.com"),
+        ]
+        # The loss email goes out during the wait, and the other one after it.
+        assert read_data.call_count == 73
+
     def test_main_selects_from_configured_devices_not_from_those_with_data(self):
         """One device with data must not be picked when the server has several."""
         with patch("sys.argv", ["bmspy-ups", "--device", "ups2"]), \