Add additional logging when error occurs

libby/keygrabber/collection.py

@@ -28,6 +28,7 @@ class TickResult:
 
     samples: Tuple[Sample, ...]
     read_errors: int
+    first_error: Optional[str] = None
 
 
 # Config plus the runtime state the control keywords expose; each attribute is
@@ -134,12 +135,16 @@ def tick(self, client: Client, timestamp: datetime) -> TickResult:
 
         samples: List[Sample] = []
         read_errors = 0
+        first_error: Optional[str] = None
         for qualified_name, response in responses.items():
             if not response.get("ok"):
                 read_errors += 1
+                if first_error is None:
+                    first_error = (f"{qualified_name}: "
+                                   f"{response.get('error', 'no error given')}")
                 continue
             samples.append(self._sample(qualified_name, response, timestamp))
-        return TickResult(tuple(samples), read_errors)
+        return TickResult(tuple(samples), read_errors, first_error)
 
     def _read_individually(
         self,

libby/keygrabber/daemon.py

@@ -373,7 +373,10 @@ def _run_tick(self, collection: Collection) -> None:
                 collection.last_sample = datetime.now(timezone.utc)
                 self._note_success(collection)
             elif collection.keyword_count:
-                self._note_failure(collection, "every read failed")
+                self._note_failure(
+                    collection,
+                    f"every read failed ({result.read_errors} errors), "
+                    f"first: {result.first_error}")
         except LibbyError as exc:
             self.counters.add(read_errors=1)
             self._note_failure(collection, str(exc))

tests/test_keygrabber_collection.py

@@ -161,6 +161,21 @@ def test_failed_read_is_counted_not_raised(self):
         self.assertEqual(result.read_errors, 1)
         self.assertEqual([s.keyword for s in result.samples], ["isconnected"])
 
+    def test_first_failed_read_is_reported(self):
+        """Keep the first error's message, so a failed tick can say why."""
+        client = _FakeClient(values={
+            "positionvalue": {"ok": False, "error": "hardware unreachable"},
+            "isconnected": {"ok": False, "error": "timed out"},
+        })
+        result = self._ticked(client)
+        self.assertEqual(result.read_errors, 2)
+        self.assertEqual(result.first_error,
+                         "hsfei.adc.isconnected: timed out")
+
+    def test_clean_tick_reports_no_error(self):
+        """Leave first_error unset when every read succeeded."""
+        self.assertIsNone(self._ticked(_FakeClient()).first_error)
+
     def test_null_value_is_kept_as_a_sample(self):
         """Leave a null for the sink to judge, so a backend may store it."""
         client = _FakeClient(values={