Add exception info to logger warnings for better debugging (#307)

* Include stacktraces in CT002 warning logs

Pass exc_info=True so before_send, event_listener, and response-build
failures include the underlying traceback, making issues like #305
diagnosable.

* Auto-attach traceback to WARNING+ logs from except blocks

Install a LogRecord filter in config/logger.py that, whenever a log
record of WARNING level or above is emitted while an exception is in
flight (sys.exc_info() is set) and no exc_info was passed explicitly,
attaches the active exception so the traceback is included. Call sites
that want to stay terse can opt out with exc_info=False; this is done
in the MQTT and MQTT Insights reconnect loops where the message alone
is enough.

Also pass exc_info=True explicitly at the most important catch-all
log sites (Shelly event listener, Home Assistant/HomeWizard WebSocket
loops, throttled powermeter fetch, Marstek auto-registration) so the
intent is obvious at the call site.

---------

Co-authored-by: Claude <noreply@anthropic.com>

Author: tomquist

src/astrameter/config/logger.py

@@ -1,4 +1,22 @@
 import logging
+import sys
+
+
+class _AutoExcInfoFilter(logging.Filter):
+    """Attach the active traceback to WARNING+ records logged from except blocks.
+
+    When a log call happens while ``sys.exc_info()`` is set (i.e. inside an
+    ``except`` block) and the caller did not pass ``exc_info`` explicitly, we
+    attach the current exception so the traceback is emitted. Call sites that
+    want the old terse behavior can opt out by passing ``exc_info=False``.
+    """
+
+    def filter(self, record: logging.LogRecord) -> bool:
+        if record.exc_info is None and record.levelno >= logging.WARNING:
+            exc = sys.exc_info()
+            if exc[0] is not None:
+                record.exc_info = exc
+        return True
 
 
 def setLogLevel(inLevel: str):
@@ -11,6 +29,14 @@ def setLogLevel(inLevel: str):
         datefmt="%Y-%m-%d %H:%M:%S",
         force=True,
     )
+    _install_auto_exc_info_filter()
+
+
+def _install_auto_exc_info_filter() -> None:
+    """Attach the auto-exc-info filter to every root handler exactly once."""
+    for handler in logging.getLogger().handlers:
+        if not any(isinstance(f, _AutoExcInfoFilter) for f in handler.filters):
+            handler.addFilter(_AutoExcInfoFilter())
 
 
 levels = {

src/astrameter/config/logger_test.py

@@ -1,4 +1,5 @@
 import importlib
+import io
 import logging
 import re
 from unittest.mock import patch
@@ -47,3 +48,74 @@ def test_set_log_level_configures_timestamped_log_output():
         formatted,
     )
     assert kwargs["force"] is True
+
+
+def test_warning_inside_except_block_includes_traceback():
+    setLogLevel("warning")
+    root = logging.getLogger()
+    buffer = io.StringIO()
+    handler = logging.StreamHandler(buffer)
+    handler.setFormatter(logging.Formatter("%(levelname)s:%(message)s"))
+    # Copy the auto-exc-info filter from the root stream handler installed by
+    # setLogLevel so this test handler sees the same behavior.
+    for existing in root.handlers:
+        for flt in existing.filters:
+            handler.addFilter(flt)
+    root.addHandler(handler)
+    try:
+        try:
+            raise RuntimeError("boom")
+        except RuntimeError as exc:
+            logging.getLogger("astrameter.test").warning("failed: %s", exc)
+    finally:
+        root.removeHandler(handler)
+
+    output = buffer.getvalue()
+    assert "WARNING:failed: boom" in output
+    assert "Traceback (most recent call last):" in output
+    assert "RuntimeError: boom" in output
+
+
+def test_warning_outside_except_block_has_no_traceback():
+    setLogLevel("warning")
+    root = logging.getLogger()
+    buffer = io.StringIO()
+    handler = logging.StreamHandler(buffer)
+    handler.setFormatter(logging.Formatter("%(levelname)s:%(message)s"))
+    for existing in root.handlers:
+        for flt in existing.filters:
+            handler.addFilter(flt)
+    root.addHandler(handler)
+    try:
+        logging.getLogger("astrameter.test").warning("plain warning")
+    finally:
+        root.removeHandler(handler)
+
+    output = buffer.getvalue()
+    assert "WARNING:plain warning" in output
+    assert "Traceback" not in output
+
+
+def test_exc_info_false_opts_out_of_auto_traceback():
+    setLogLevel("warning")
+    root = logging.getLogger()
+    buffer = io.StringIO()
+    handler = logging.StreamHandler(buffer)
+    handler.setFormatter(logging.Formatter("%(levelname)s:%(message)s"))
+    for existing in root.handlers:
+        for flt in existing.filters:
+            handler.addFilter(flt)
+    root.addHandler(handler)
+    try:
+        try:
+            raise RuntimeError("boom")
+        except RuntimeError as exc:
+            logging.getLogger("astrameter.test").warning(
+                "suppressed: %s", exc, exc_info=False
+            )
+    finally:
+        root.removeHandler(handler)
+
+    output = buffer.getvalue()
+    assert "WARNING:suppressed: boom" in output
+    assert "Traceback" not in output

src/astrameter/ct002/ct002.py

@@ -248,7 +248,9 @@ def _call_event_listener(self, consumer_id: str, data: dict[str, Any]) -> None:
         try:
             self.event_listener(self._device_id, consumer_id, data)
         except Exception as exc:
-            logger.warning("event_listener failed for %s: %s", consumer_id, exc)
+            logger.warning(
+                "event_listener failed for %s: %s", consumer_id, exc, exc_info=True
+            )
 
     def _update_consumer_report(self, consumer_id, phase, power, device_type=""):
         normalized_phase = str(phase).upper() if phase else "A"
@@ -462,7 +464,7 @@ async def _call_before_send(self, addr, fields, consumer_id):
         try:
             return await self.before_send(addr, fields, consumer_id)
         except Exception as exc:
-            logger.warning("before_send failed for %s: %s", addr, exc)
+            logger.warning("before_send failed for %s: %s", addr, exc, exc_info=True)
             return None
 
     def _validate_ct_mac(self, request_fields):
@@ -565,6 +567,7 @@ async def _handle_request(self, data, addr, transport):
                 addr,
                 fields,
                 exc,
+                exc_info=True,
             )
             return
         logger.debug(

src/astrameter/main.py

@@ -547,9 +547,11 @@ def main():
                         "Credentials are only needed for one-time registration. You can remove MARSTEK mailbox/password from config now."
                     )
             except MarstekApiError as exc:
-                logger.error("Marstek auto-registration failed: %s", exc)
+                logger.error("Marstek auto-registration failed: %s", exc, exc_info=True)
             except Exception as exc:
-                logger.error("Unexpected Marstek auto-registration error: %s", exc)
+                logger.error(
+                    "Unexpected Marstek auto-registration error: %s", exc, exc_info=True
+                )
 
     # Map SIGTERM to KeyboardInterrupt so asyncio.run cancels tasks and
     # runs finally-cleanup the same way it does for SIGINT (Ctrl+C).

src/astrameter/mqtt_insights/service.py

@@ -228,10 +228,12 @@ async def _run(self) -> None:
                 raise
             except (aiomqtt.MqttError, OSError) as exc:
                 self._connected.clear()
+                # Reconnect loop — traceback would be noisy, keep it terse.
                 logger.warning(
                     "MQTT Insights connection error: %s. Reconnecting in %ss...",
                     exc,
                     RECONNECT_DELAY,
+                    exc_info=False,
                 )
                 await asyncio.sleep(RECONNECT_DELAY)
             except Exception:

src/astrameter/powermeter/homeassistant.py

@@ -112,7 +112,7 @@ async def _ws_loop(self) -> None:
             except asyncio.CancelledError:
                 raise
             except Exception as e:
-                logger.error(f"Home Assistant WebSocket error: {e}")
+                logger.error("Home Assistant WebSocket error: %s", e, exc_info=True)
             # Reset protocol state for reconnection; keep _entity_values
             # (stale values are preferable to ValueError during brief disconnect;
             # subscribe_entities re-sends initial states on reconnect)

src/astrameter/powermeter/homewizard.py

@@ -90,7 +90,7 @@ async def _ws_loop(self) -> None:
             except asyncio.CancelledError:
                 raise
             except Exception as e:
-                logger.error(f"HomeWizard WebSocket error: {e}")
+                logger.error("HomeWizard WebSocket error: %s", e, exc_info=True)
             await asyncio.sleep(5)
 
     async def _handle_message(

src/astrameter/powermeter/mqtt.py

@@ -130,8 +130,12 @@ async def _run(self) -> None:
                                 )
             except aiomqtt.MqttError as e:
                 self._connected_event.clear()
+                # Reconnect loop — traceback would be noisy, keep it terse.
                 logger.warning(
-                    f"MQTT connection error: {e}. Reconnecting in {RECONNECT_DELAY}s..."
+                    "MQTT connection error: %s. Reconnecting in %ss...",
+                    e,
+                    RECONNECT_DELAY,
+                    exc_info=False,
                 )
                 await asyncio.sleep(RECONNECT_DELAY)
 

src/astrameter/powermeter/throttling.py

@@ -78,7 +78,9 @@ async def get_powermeter_watts(self) -> list[float]:
             # interval before retrying — avoids hammering a failing source.
             self._last_update_time = time.monotonic()
             if self._last_values is not None:
-                logger.warning("Throttling: Error getting fresh values: %s", e)
+                logger.warning(
+                    "Throttling: Error getting fresh values: %s", e, exc_info=True
+                )
                 logger.debug(
                     "Throttling: Using cached values due to error: %s",
                     self._last_values,

src/astrameter/shelly/shelly.py

@@ -174,7 +174,9 @@ def _call_event_listener(self, battery_ip: str, data: dict[str, Any]) -> None:
         try:
             self.event_listener(self._device_id, battery_ip, data)
         except Exception as exc:
-            logger.warning("event_listener failed for %s: %s", battery_ip, exc)
+            logger.warning(
+                "event_listener failed for %s: %s", battery_ip, exc, exc_info=True
+            )
 
     async def _safe_handle_request(self, transport, data, addr):
         try: