Merge pull request #458 from mahmoudhas/fix/guard-hot-path-log-rendering

Guard hot-path log calls to avoid payload rendering when disabled

tests/test_log_sys.py

@@ -2,16 +2,19 @@
 `tractor.log`-wrapping unit tests.
 
 '''
+import logging
 from pathlib import Path
 import shutil
 from types import ModuleType
 
 import pytest
 import tractor
+import trio
 from tractor import (
     _code_load,
     log,
 )
+from tractor.ipc import _chan
 
 
 def test_root_pkg_not_duplicated_in_logger_name():
@@ -222,6 +225,88 @@ def test_add_log_level_pluggable():
             delattr(log.StackLevelAdapter, name.lower())
 
 
+@pytest.mark.parametrize(
+    'suppression',
+    [
+        'level',
+        'logger',
+        'global',
+    ],
+)
+def test_log_guard_skips_payload_formatting(
+    monkeypatch: pytest.MonkeyPatch,
+    suppression: str,
+):
+    '''
+    Suppressed transport logs must not render payloads.
+
+    The original hot-path guard compared only the effective logger
+    level. A logger disabled through its `Logger.disabled` flag or
+    the global `logging.disable()` threshold could therefore still
+    call `pformat()` before `Logger.isEnabledFor()` discarded the
+    record.
+
+    Exercise effective-level, per-logger, and global suppression
+    independently. A poisoned `_chan.pformat()` proves rendering is
+    skipped, while the fake transport proves `Channel.send()` still
+    transmits the original payload and traceback-hiding flag.
+
+    '''
+    sent: list[tuple[object, bool]] = []
+
+    class FakeTransport:
+        async def send(
+            self,
+            payload: object,
+            hide_tb: bool = False,
+        ) -> None:
+            sent.append((payload, hide_tb))
+
+    def fail_pformat(payload: object) -> str:
+        raise AssertionError(
+            f'suppressed log rendered payload: {payload!r}'
+        )
+
+    chan_log = log.get_logger(
+        name=f'guard_test.{suppression}',
+    )
+    std_log = chan_log.logger
+    orig_level: int = std_log.level
+    orig_disable: int = logging.root.manager.disable
+    transport_level: int = log.CUSTOM_LEVELS['TRANSPORT']
+
+    monkeypatch.setattr(_chan, 'log', chan_log)
+    monkeypatch.setattr(_chan, 'pformat', fail_pformat)
+    try:
+        logging.disable(logging.NOTSET)
+        std_log.setLevel(transport_level)
+
+        if suppression == 'level':
+            std_log.setLevel(logging.INFO)
+        elif suppression == 'logger':
+            monkeypatch.setattr(std_log, 'disabled', True)
+        else:
+            logging.disable(logging.CRITICAL)
+
+        assert not chan_log.isEnabledFor(transport_level)
+
+        transport = FakeTransport()
+        chan = _chan.Channel(transport=transport)
+        payload = object()
+
+        async def send_payload() -> None:
+            await chan.send(
+                payload,
+                hide_tb=True,
+            )
+
+        trio.run(send_payload)
+        assert sent == [(payload, True)]
+    finally:
+        std_log.setLevel(orig_level)
+        logging.disable(orig_disable)
+
+
 # TODO, moar tests against existing feats:
 # ------ - ------
 # - [ ] color settings?

tractor/ipc/_chan.py

@@ -198,9 +198,6 @@ class Channel:
         # assert transport.raddr == addr
         chan = Channel(transport=transport)
 
-        # ?TODO, compact this into adapter level-methods?
-        # -[ ] would avoid extra repr-calcs if level not active?
-        #   |_ how would the `calc_if_level` look though? func?
         if log.at_least_level('runtime'):
             from tractor.devx import (
                 pformat as _pformat,
@@ -325,6 +322,8 @@ class Channel:
         '''
         __tracebackhide__: bool = hide_tb
         try:
+            if log.at_least_level('transport'):
+                # don't materialize the payload repr if not necessary
                 log.transport(
                     '=> send IPC msg:\n\n'
                     f'{pformat(payload)}\n'

tractor/ipc/_transport.py

@@ -309,7 +309,10 @@ class MsgpackTransport(MsgTransport):
             log.transport(f'received header {size}')  # type: ignore
             msg_bytes: bytes = await self.recv_stream.receive_exactly(size)
 
-            log.transport(f"received {msg_bytes}")  # type: ignore
+            if log.at_least_level('transport'):
+                log.transport(  # type: ignore
+                    f'received {msg_bytes}'
+                )
             try:
                 # NOTE: lookup the `trio.Task.context`'s var for
                 # the current `MsgCodec`.

tractor/log.py

@@ -111,9 +111,7 @@ def at_least_level(
     if isinstance(level, str):
         level: int = CUSTOM_LEVELS[level.upper()]
 
-    if log.getEffectiveLevel() <= level:
-        return True
-    return False
+    return log.isEnabledFor(level)
 
 
 # TODO, compare with using a "filter" instead?

tractor/msg/_ops.py

@@ -306,12 +306,12 @@ class PldRx(Struct):
             ):
                 try:
                     pld: PayloadT = self._pld_dec.decode(pld)
+                    if log.at_least_level('runtime'):
+                        # don't materialize the payload repr if not necessary
                         log.runtime(
                             f'Decoded payload for\n'
-                        # f'\n'
+                            f'\n'
                             f'{msg}\n'
-                        # ^TODO?, ideally just render with `,
-                        # pld={decode}` in the `msg.pformat()`??
                             f'where, '
                             f'{type(msg).__name__}.pld={pld!r}\n'
                         )

tractor/runtime/_rpc.py

@@ -1003,17 +1003,15 @@ async def process_messages(
             task_status.started(loop_cs)
 
             async for msg in chan:
+                if log.at_least_level('transport'):
                     log.transport(   # type: ignore
                         f'IPC msg from peer\n'
                         f'<= {chan.aid.reprol()}\n\n'
 
-                    # TODO: use of the pprinting of structs is
-                    # FRAGILE and should prolly not be
-                    #
-                    # avoid fmting depending on loglevel for perf?
-                    # -[ ] specifically `pretty_struct.pformat()` sub-call..?
-                    #   - how to only log-level-aware actually call this?
-                    # -[ ] use `.msg.pretty_struct` here now instead!
+                        # TODO: pretty-printing structs is FRAGILE;
+                        # -[ ] add a non-raising log formatter with
+                        #      native-repr fallback before using
+                        #      `.msg.pretty_struct` here.
                         # f'{pretty_struct.pformat(msg)}\n'
                         f'{msg}\n'
                     )
@@ -1262,6 +1260,7 @@ async def process_messages(
                         log.exception(message)
                         raise RuntimeError(message)
 
+                if log.at_least_level('transport'):
                     log.transport(
                         'Waiting on next IPC msg from\n'
                         f'peer: {chan.aid.reprol()}\n'