diff --git a/tests/test_log_sys.py b/tests/test_log_sys.py index 3870e825..1894bd1f 100644 --- a/tests/test_log_sys.py +++ b/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? diff --git a/tractor/ipc/_chan.py b/tractor/ipc/_chan.py index 10a800e4..a2450585 100644 --- a/tractor/ipc/_chan.py +++ b/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,10 +322,12 @@ class Channel: ''' __tracebackhide__: bool = hide_tb try: - log.transport( - '=> send IPC msg:\n\n' - f'{pformat(payload)}\n' - ) + 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' + ) # assert self._transport # but why typing? await self._transport.send( payload, diff --git a/tractor/ipc/_transport.py b/tractor/ipc/_transport.py index 0a38d14d..dd3be179 100644 --- a/tractor/ipc/_transport.py +++ b/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`. diff --git a/tractor/log.py b/tractor/log.py index 6c8c9bc8..a87dd7c1 100644 --- a/tractor/log.py +++ b/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? diff --git a/tractor/msg/_ops.py b/tractor/msg/_ops.py index a134306f..1b342ca6 100644 --- a/tractor/msg/_ops.py +++ b/tractor/msg/_ops.py @@ -306,15 +306,15 @@ class PldRx(Struct): ): try: pld: PayloadT = self._pld_dec.decode(pld) - log.runtime( - f'Decoded payload for\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' - ) + 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'{msg}\n' + f'where, ' + f'{type(msg).__name__}.pld={pld!r}\n' + ) return pld except TypeError as typerr: __tracebackhide__: bool = False diff --git a/tractor/runtime/_rpc.py b/tractor/runtime/_rpc.py index 6c0fb32a..d2c9ea30 100644 --- a/tractor/runtime/_rpc.py +++ b/tractor/runtime/_rpc.py @@ -1003,20 +1003,18 @@ async def process_messages( task_status.started(loop_cs) async for msg in chan: - log.transport( # type: ignore - f'IPC msg from peer\n' - f'<= {chan.aid.reprol()}\n\n' + 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! - # f'{pretty_struct.pformat(msg)}\n' - f'{msg}\n' - ) + # 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' + ) match msg: # msg for an ongoing IPC ctx session, deliver msg to @@ -1262,11 +1260,12 @@ async def process_messages( log.exception(message) raise RuntimeError(message) - log.transport( - 'Waiting on next IPC msg from\n' - f'peer: {chan.aid.reprol()}\n' - f'|_{chan}\n' - ) + if log.at_least_level('transport'): + log.transport( + 'Waiting on next IPC msg from\n' + f'peer: {chan.aid.reprol()}\n' + f'|_{chan}\n' + ) # END-OF `async for`: # IPC disconnected via `trio.EndOfChannel`, likely