diff --git a/tests/conftest.py b/tests/conftest.py index b84f4105..47837fa5 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -65,7 +65,11 @@ def loglevel(request): import tractor orig = tractor.log._default_loglevel level = tractor.log._default_loglevel = request.config.option.loglevel - tractor.log.get_console_log(level) + log = tractor.log.get_console_log( + level=level, + name='tractor', # <- enable root logger + ) + log.info(f'Test-harness logging level: {level}\n') yield level tractor.log._default_loglevel = orig diff --git a/tests/devx/conftest.py b/tests/devx/conftest.py index 9a5c90a5..11ec9ed2 100644 --- a/tests/devx/conftest.py +++ b/tests/devx/conftest.py @@ -34,7 +34,10 @@ if TYPE_CHECKING: # a fn that sub-instantiates a `pexpect.spawn()` # and returns it. -type PexpectSpawner = Callable[[str], pty_spawn.spawn] +type PexpectSpawner = Callable[ + [str], + pty_spawn.spawn, +] @pytest.fixture @@ -109,7 +112,11 @@ def ctlc( 'https://github.com/goodboy/tractor/issues/320' ) - if mark.name == 'ctlcs_bish': + if ( + mark.name == 'ctlcs_bish' + and + use_ctlc + ): pytest.skip( f'Test {node} prolly uses something from the stdlib (namely `asyncio`..)\n' f'The test and/or underlying example script can *sometimes* run fine ' diff --git a/tests/test_log_sys.py b/tests/test_log_sys.py new file mode 100644 index 00000000..87328007 --- /dev/null +++ b/tests/test_log_sys.py @@ -0,0 +1,185 @@ +''' +`tractor.log`-wrapping unit tests. + +''' +from pathlib import Path +import shutil +from types import ModuleType + +import pytest +import tractor +from tractor import ( + _code_load, + log, +) + + +def test_root_pkg_not_duplicated_in_logger_name(): + ''' + When both `pkg_name` and `name` are passed and they have + a common `.< >` prefix, ensure that it is not + duplicated in the child's `StackLevelAdapter.name: str`. + + ''' + project_name: str = 'pylib' + pkg_path: str = 'pylib.subpkg.mod' + + assert not tractor.current_actor( + err_on_no_runtime=False, + ) + proj_log = log.get_logger( + pkg_name=project_name, + mk_sublog=False, + ) + + sublog = log.get_logger( + pkg_name=project_name, + name=pkg_path, + ) + + assert proj_log is not sublog + assert sublog.name.count(proj_log.name) == 1 + assert 'mod' not in sublog.name + + +def test_implicit_mod_name_applied_for_child( + testdir: pytest.Pytester, + loglevel: str, +): + ''' + Verify that when `.log.get_logger(pkg_name='pylib')` is called + from a given sub-mod from within the `pylib` pkg-path, we + implicitly set the equiv of `name=__name__` from the caller's + module. + + ''' + # tractor.log.get_console_log(level=loglevel) + proj_name: str = 'snakelib' + mod_code: str = ( + f'import tractor\n' + f'\n' + # if you need to trace `testdir` stuff @ import-time.. + # f'breakpoint()\n' + f'log = tractor.log.get_logger(pkg_name="{proj_name}")\n' + ) + + # create a sub-module for each pkg layer + _lib = testdir.mkpydir(proj_name) + pkg: Path = Path(_lib) + pkg_init_mod: Path = pkg / "__init__.py" + pkg_init_mod.write_text(mod_code) + + subpkg: Path = pkg / 'subpkg' + subpkg.mkdir() + subpkgmod: Path = subpkg / "__init__.py" + subpkgmod.touch() + subpkgmod.write_text(mod_code) + + _submod: Path = testdir.makepyfile( + _mod=mod_code, + ) + + pkg_submod = pkg / 'mod.py' + pkg_subpkg_submod = subpkg / 'submod.py' + shutil.copyfile( + _submod, + pkg_submod, + ) + shutil.copyfile( + _submod, + pkg_subpkg_submod, + ) + testdir.chdir() + # NOTE, to introspect the py-file-module-layout use (in .xsh + # syntax): `ranger @str(testdir)` + + # XXX NOTE, once the "top level" pkg mod has been + # imported, we can then use `import` syntax to + # import it's sub-pkgs and modules. + subpkgmod: ModuleType = _code_load.load_module_from_path( + Path(pkg / '__init__.py'), + module_name=proj_name, + ) + + pkg_root_log = log.get_logger( + pkg_name=proj_name, + mk_sublog=False, + ) + # the top level pkg-mod, created just now, + # by above API call. + assert pkg_root_log.name == proj_name + assert not pkg_root_log.logger.getChildren() + # + # ^TODO! test this same output but created via a `get_logger()` + # call in the `snakelib.__init__py`!! + + # NOTE, the pkg-level "init mod" should of course + # have the same name as the package ns-path. + import snakelib as init_mod + assert init_mod.log.name == proj_name + + # NOTE, a first-pkg-level sub-module should only + # use the package-name since the leaf-node-module + # will be included in log headers by default. + from snakelib import mod + assert mod.log.name == proj_name + + from snakelib import subpkg + assert ( + subpkg.log.name + == + subpkg.__package__ + == + f'{proj_name}.subpkg' + ) + + from snakelib.subpkg import submod + assert ( + submod.log.name + == + submod.__package__ + == + f'{proj_name}.subpkg' + ) + + sub_logs = pkg_root_log.logger.getChildren() + assert len(sub_logs) == 1 # only one nested sub-pkg module + assert submod.log.logger in sub_logs + + +# TODO, moar tests against existing feats: +# ------ - ------ +# - [ ] color settings? +# - [ ] header contents like, +# - actor + thread + task names from various conc-primitives, +# - [ ] `StackLevelAdapter` extensions, +# - our custom levels/methods: `transport|runtime|cance|pdb|devx` +# - [ ] custom-headers support? +# + +# TODO, test driven dev of new-ideas/long-wanted feats, +# ------ - ------ +# - [ ] https://github.com/goodboy/tractor/issues/244 +# - [ ] @catern mentioned using a sync / deterministic sys +# and in particular `svlogd`? +# |_ https://smarden.org/runit/svlogd.8 + +# - [ ] using adapter vs. filters? +# - https://stackoverflow.com/questions/60691759/add-information-to-every-log-message-in-python-logging/61830838#61830838 + +# - [ ] `.at_least_level()` optimization which short circuits wtv +# `logging` is doing behind the scenes when the level filters +# the emission..? + +# - [ ] use of `.log.get_console_log()` in subactors and the +# subtleties of ensuring it actually emits from a subproc. + +# - [ ] this idea of activating per-subsys emissions with some +# kind of `.name` filter passed to the runtime or maybe configured +# via the root `StackLevelAdapter`? + +# - [ ] use of `logging.dict.dictConfig()` to simplify the impl +# of any of ^^ ?? +# - https://stackoverflow.com/questions/7507825/where-is-a-complete-example-of-logging-config-dictconfig +# - https://docs.python.org/3/library/logging.config.html#configuration-dictionary-schema +# - https://docs.python.org/3/library/logging.config.html#logging.config.dictConfig diff --git a/tests/test_resource_cache.py b/tests/test_resource_cache.py index 10eb3d84..5f0e7fca 100644 --- a/tests/test_resource_cache.py +++ b/tests/test_resource_cache.py @@ -17,9 +17,8 @@ from tractor.log import ( get_console_log, get_logger, ) -log = get_logger(__name__) - +log = get_logger() _resource: int = 0 diff --git a/tractor/_addr.py b/tractor/_addr.py index d8d11227..26706cdb 100644 --- a/tractor/_addr.py +++ b/tractor/_addr.py @@ -37,7 +37,7 @@ from .ipc._uds import UDSAddress if TYPE_CHECKING: from ._runtime import Actor -log = get_logger(__name__) +log = get_logger() # TODO, maybe breakout the netns key to a struct? @@ -259,6 +259,8 @@ def wrap_address( case _: # import pdbp; pdbp.set_trace() + # from tractor.devx import mk_pdb + # mk_pdb().set_trace() raise TypeError( f'Can not wrap unwrapped-address ??\n' f'type(addr): {type(addr)!r}\n' diff --git a/tractor/_code_load.py b/tractor/_code_load.py new file mode 100644 index 00000000..65effaa1 --- /dev/null +++ b/tractor/_code_load.py @@ -0,0 +1,48 @@ +# tractor: structured concurrent "actors". +# Copyright 2018-eternity Tyler Goodlet. + +# This program is free software: you can redistribute it and/or modify +# it under the terms of the GNU Affero General Public License as published by +# the Free Software Foundation, either version 3 of the License, or +# (at your option) any later version. + +# This program is distributed in the hope that it will be useful, +# but WITHOUT ANY WARRANTY; without even the implied warranty of +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +# GNU Affero General Public License for more details. + +# You should have received a copy of the GNU Affero General Public License +# along with this program. If not, see . + +''' +(Hot) coad (re-)load utils for python. + +''' +import importlib +from pathlib import Path +import sys +from types import ModuleType + +# ?TODO, move this into internal libs? +# -[ ] we already use it in `modden.config._pymod` as well +def load_module_from_path( + path: Path, + module_name: str|None = None, +) -> ModuleType: + ''' + Taken from SO, + https://stackoverflow.com/a/67208147 + + which is based on stdlib docs, + https://docs.python.org/3/library/importlib.html#importing-a-source-file-directly + + ''' + module_name = module_name or path.stem + spec = importlib.util.spec_from_file_location( + module_name, + str(path), + ) + module = importlib.util.module_from_spec(spec) + sys.modules[module_name] = module + spec.loader.exec_module(module) + return module diff --git a/tractor/_context.py b/tractor/_context.py index da31e423..8ace1b4d 100644 --- a/tractor/_context.py +++ b/tractor/_context.py @@ -113,7 +113,7 @@ if TYPE_CHECKING: CallerInfo, ) -log = get_logger(__name__) +log = get_logger() class Unresolved: @@ -2391,16 +2391,18 @@ async def open_context_from_portal( case trio.Cancelled(): logmeth = log.cancel cause: str = 'cancelled' + msg: str = ( + f'ctx {ctx.side!r}-side {cause!r} with,\n' + f'{ctx.repr_outcome()!r}\n' + ) # XXX explicitly report on any non-graceful-taskc cases case _: cause: str = 'errored' logmeth = log.exception + msg: str = f'ctx {ctx.side!r}-side {cause!r} with,\n' - logmeth( - f'ctx {ctx.side!r}-side {cause!r} with,\n' - f'{ctx.repr_outcome()!r}\n' - ) + logmeth(msg) if debug_mode(): # async with debug.acquire_debug_lock(portal.actor.uid): diff --git a/tractor/_discovery.py b/tractor/_discovery.py index a332ab73..edc43d86 100644 --- a/tractor/_discovery.py +++ b/tractor/_discovery.py @@ -53,7 +53,7 @@ if TYPE_CHECKING: from ._runtime import Actor -log = get_logger(__name__) +log = get_logger() @acm diff --git a/tractor/_entry.py b/tractor/_entry.py index 68e72501..c8b5cc3f 100644 --- a/tractor/_entry.py +++ b/tractor/_entry.py @@ -50,7 +50,7 @@ if TYPE_CHECKING: from ._spawn import SpawnMethodKey -log = get_logger(__name__) +log = get_logger() def _mp_main( @@ -72,11 +72,15 @@ def _mp_main( spawn_ctx: mp.context.BaseContext = try_set_start_method(start_method) assert spawn_ctx + # XXX, enable root log at level if actor.loglevel is not None: log.info( - f'Setting loglevel for {actor.uid} to {actor.loglevel}' + f'Setting loglevel for {actor.uid} to {actor.loglevel!r}' + ) + get_console_log( + level=actor.loglevel, + name='tractor', ) - get_console_log(actor.loglevel) # TODO: use scops headers like for `trio` below! # (well after we libify it maybe..) @@ -126,8 +130,12 @@ def _trio_main( parent_addr=parent_addr ) + # XXX, enable root log at level if actor.loglevel is not None: - get_console_log(actor.loglevel) + get_console_log( + level=actor.loglevel, + name='tractor', + ) log.info( f'Starting `trio` subactor from parent @ ' f'{parent_addr}\n' diff --git a/tractor/_portal.py b/tractor/_portal.py index 69133528..a914bb80 100644 --- a/tractor/_portal.py +++ b/tractor/_portal.py @@ -69,7 +69,7 @@ from ._streaming import ( if TYPE_CHECKING: from ._runtime import Actor -log = get_logger(__name__) +log = get_logger() class Portal: diff --git a/tractor/_root.py b/tractor/_root.py index d7b3359b..2fb7755d 100644 --- a/tractor/_root.py +++ b/tractor/_root.py @@ -289,10 +289,12 @@ async def open_root_actor( for uw_addr in uw_reg_addrs ] - loglevel = ( + loglevel: str = ( loglevel - or log._default_loglevel - ).upper() + or + log._default_loglevel + ) + loglevel: str = loglevel.upper() if ( debug_mode @@ -323,7 +325,10 @@ async def open_root_actor( ) assert loglevel - _log = log.get_console_log(loglevel) + _log = log.get_console_log( + level=loglevel, + name='tractor', + ) assert _log # TODO: factor this into `.devx._stackscope`!! diff --git a/tractor/_streaming.py b/tractor/_streaming.py index 4683f35d..fb870f1c 100644 --- a/tractor/_streaming.py +++ b/tractor/_streaming.py @@ -59,7 +59,7 @@ if TYPE_CHECKING: from .ipc import Channel -log = get_logger(__name__) +log = get_logger() # TODO: the list diff --git a/tractor/_supervise.py b/tractor/_supervise.py index 22ef62b4..301c44e8 100644 --- a/tractor/_supervise.py +++ b/tractor/_supervise.py @@ -62,7 +62,7 @@ if TYPE_CHECKING: from .ipc import IPCServer -log = get_logger(__name__) +log = get_logger() class ActorNursery: diff --git a/tractor/devx/_frame_stack.py b/tractor/devx/_frame_stack.py index c99d3ecd..9c722def 100644 --- a/tractor/devx/_frame_stack.py +++ b/tractor/devx/_frame_stack.py @@ -49,7 +49,7 @@ from tractor.msg import ( import wrapt -log = get_logger(__name__) +log = get_logger() # TODO: yeah, i don't love this and we should prolly just # write a decorator that actually keeps a stupid ref to the func diff --git a/tractor/devx/_stackscope.py b/tractor/devx/_stackscope.py index 11d2a1ef..1257ec1b 100644 --- a/tractor/devx/_stackscope.py +++ b/tractor/devx/_stackscope.py @@ -51,7 +51,7 @@ from tractor import ( ) from tractor.devx import debug -log = logmod.get_logger(__name__) +log = logmod.get_logger() if TYPE_CHECKING: diff --git a/tractor/devx/debug/__init__.py b/tractor/devx/debug/__init__.py index faf9f2f7..d8476095 100644 --- a/tractor/devx/debug/__init__.py +++ b/tractor/devx/debug/__init__.py @@ -59,7 +59,7 @@ from ._sigint import ( _ctlc_ignore_header as _ctlc_ignore_header ) -log = get_logger(__name__) +log = get_logger() # ---------------- # XXX PKG TODO XXX diff --git a/tractor/devx/debug/_post_mortem.py b/tractor/devx/debug/_post_mortem.py index 32d10074..da9a35b2 100644 --- a/tractor/devx/debug/_post_mortem.py +++ b/tractor/devx/debug/_post_mortem.py @@ -84,7 +84,7 @@ _crash_msg: str = ( 'Opening a pdb REPL in crashed actor' ) -log = get_logger(__package__) +log = get_logger() class BoxedMaybeException(Struct): diff --git a/tractor/devx/debug/_sigint.py b/tractor/devx/debug/_sigint.py index 80f79e58..c2a16f62 100644 --- a/tractor/devx/debug/_sigint.py +++ b/tractor/devx/debug/_sigint.py @@ -47,7 +47,7 @@ if TYPE_CHECKING: Actor, ) -log = get_logger(__name__) +log = get_logger() _ctlc_ignore_header: str = ( 'Ignoring SIGINT while debug REPL in use' diff --git a/tractor/devx/debug/_sync.py b/tractor/devx/debug/_sync.py index cf4bb334..854805c7 100644 --- a/tractor/devx/debug/_sync.py +++ b/tractor/devx/debug/_sync.py @@ -58,7 +58,7 @@ from ._sigint import ( _ctlc_ignore_header as _ctlc_ignore_header ) -log = get_logger(__package__) +log = get_logger() async def maybe_wait_for_debugger( diff --git a/tractor/devx/debug/_trace.py b/tractor/devx/debug/_trace.py index a23d2e23..c1219c30 100644 --- a/tractor/devx/debug/_trace.py +++ b/tractor/devx/debug/_trace.py @@ -93,7 +93,7 @@ if TYPE_CHECKING: # from ._post_mortem import BoxedMaybeException from ._repl import PdbREPL -log = get_logger(__package__) +log = get_logger() _pause_msg: str = 'Opening a pdb REPL in paused actor' _repl_fail_msg: str|None = ( @@ -628,7 +628,7 @@ def _set_trace( log.pdb( f'{_pause_msg}\n' f'>(\n' - f'|_{actor.uid}\n' + f'|_{actor.aid.uid}\n' f' |_{task}\n' # @ {actor.uid}\n' # f'|_{task}\n' # ^-TODO-^ more compact pformating? diff --git a/tractor/devx/debug/_tty_lock.py b/tractor/devx/debug/_tty_lock.py index 3f9576a3..9573b242 100644 --- a/tractor/devx/debug/_tty_lock.py +++ b/tractor/devx/debug/_tty_lock.py @@ -81,7 +81,7 @@ if TYPE_CHECKING: BoxedMaybeException, ) -log = get_logger(__name__) +log = get_logger() class LockStatus( diff --git a/tractor/ipc/_chan.py b/tractor/ipc/_chan.py index dcb0d6ad..64973fd4 100644 --- a/tractor/ipc/_chan.py +++ b/tractor/ipc/_chan.py @@ -60,7 +60,7 @@ if TYPE_CHECKING: from ._transport import MsgTransport -log = get_logger(__name__) +log = get_logger() _is_windows = platform.system() == 'Windows' diff --git a/tractor/ipc/_server.py b/tractor/ipc/_server.py index 55374b0a..0ce5ae3c 100644 --- a/tractor/ipc/_server.py +++ b/tractor/ipc/_server.py @@ -72,7 +72,7 @@ if TYPE_CHECKING: from .._supervise import ActorNursery -log = log.get_logger(__name__) +log = log.get_logger() async def maybe_wait_on_canced_subs( diff --git a/tractor/ipc/_shm.py b/tractor/ipc/_shm.py index 2360f893..2a5fbb82 100644 --- a/tractor/ipc/_shm.py +++ b/tractor/ipc/_shm.py @@ -59,7 +59,7 @@ except ImportError: pass -log = get_logger(__name__) +log = get_logger() SharedMemory = disable_mantracker() diff --git a/tractor/ipc/_tcp.py b/tractor/ipc/_tcp.py index a1f511d5..b05f2829 100644 --- a/tractor/ipc/_tcp.py +++ b/tractor/ipc/_tcp.py @@ -41,7 +41,7 @@ from tractor.ipc._transport import ( ) -log = get_logger(__name__) +log = get_logger() class TCPAddress( diff --git a/tractor/ipc/_transport.py b/tractor/ipc/_transport.py index 8c76c8ad..704c13a6 100644 --- a/tractor/ipc/_transport.py +++ b/tractor/ipc/_transport.py @@ -56,7 +56,7 @@ from tractor.msg import ( if TYPE_CHECKING: from tractor._addr import Address -log = get_logger(__name__) +log = get_logger() # (codec, transport) diff --git a/tractor/ipc/_uds.py b/tractor/ipc/_uds.py index e23fd8d2..eb53c6b2 100644 --- a/tractor/ipc/_uds.py +++ b/tractor/ipc/_uds.py @@ -63,7 +63,7 @@ if TYPE_CHECKING: from ._runtime import Actor -log = get_logger(__name__) +log = get_logger() def unwrap_sockpath( @@ -166,6 +166,10 @@ class UDSAddress( ) if actor: sockname: str = '::'.join(actor.uid) + f'@{pid}' + # ?^TODO, for `multiaddr`'s parser we can't use the `::` + # above^, SO maybe a `.` or something else here? + # sockname: str = '.'.join(actor.uid) + f'@{pid}' + # -[ ] CURRENTLY using `.` BREAKS TEST SUITE tho.. else: prefix: str = '' if is_root_process(): diff --git a/tractor/log.py b/tractor/log.py index 329562b1..3ff5384b 100644 --- a/tractor/log.py +++ b/tractor/log.py @@ -14,11 +14,23 @@ # You should have received a copy of the GNU Affero General Public License # along with this program. If not, see . -""" -Log like a forester! +''' +An enhanced logging subsys. -""" +An extended logging layer using (for now) the stdlib's `logging` ++ `colorlog` which embeds concurrency-primitive/runtime info into +records (headers) to help you better grok your distributed systems +built on `tractor`. + + +''' from collections.abc import Mapping +from functools import partial +from inspect import ( + FrameInfo, + getmodule, + stack, +) import sys import logging from logging import ( @@ -26,20 +38,24 @@ from logging import ( Logger, StreamHandler, ) -import colorlog # type: ignore +from types import ModuleType +import warnings +import colorlog # type: ignore +# ?TODO, some other (modern) alt libs? +# import coloredlogs +# import colored_traceback.auto # ?TODO, need better config? import trio from ._state import current_actor -_proj_name: str = 'tractor' _default_loglevel: str = 'ERROR' # Super sexy formatting thanks to ``colorlog``. # (NOTE: we use the '{' format style) # Here, `thin_white` is just the layperson's gray. -LOG_FORMAT = ( +LOG_FORMAT: str = ( # "{bold_white}{log_color}{asctime}{reset}" "{log_color}{asctime}{reset}" " {bold_white}{thin_white}({reset}" @@ -51,7 +67,7 @@ LOG_FORMAT = ( " {reset}{bold_white}{thin_white}{message}" ) -DATE_FORMAT = '%b %d %H:%M:%S' +DATE_FORMAT: str = '%b %d %H:%M:%S' # FYI, ERROR is 40 # TODO: use a `bidict` to avoid the :155 check? @@ -75,7 +91,10 @@ STD_PALETTE = { 'TRANSPORT': 'cyan', } -BOLD_PALETTE = { +BOLD_PALETTE: dict[ + str, + dict[int, str], +] = { 'bold': { level: f"bold_{color}" for level, color in STD_PALETTE.items()} } @@ -97,9 +116,26 @@ def at_least_level( return False -# TODO: this isn't showing the correct '{filename}' -# as it did before.. +# TODO, compare with using a "filter" instead? +# - https://stackoverflow.com/questions/60691759/add-information-to-every-log-message-in-python-logging/61830838#61830838 +# |_corresponding dict-config, +# https://stackoverflow.com/questions/7507825/where-is-a-complete-example-of-logging-config-dictconfig/7507842#7507842 +# - [ ] what's the benefit/tradeoffs? +# class StackLevelAdapter(LoggerAdapter): + ''' + A (software) stack oriented logger "adapter". + + ''' + @property + def level(self) -> str: + ''' + The currently set `str` emit level (in lowercase). + + ''' + return logging.getLevelName( + self.getEffectiveLevel() + ).lower() def at_least_level( self, @@ -248,9 +284,14 @@ def pformat_task_uid( return f'{task.name}[{tid_part}]' +_curr_actor_no_exc = partial( + current_actor, + err_on_no_runtime=False, +) + _conc_name_getters = { 'task': pformat_task_uid, - 'actor': lambda: current_actor(), + 'actor': lambda: _curr_actor_no_exc(), 'actor_name': lambda: current_actor().name, 'actor_uid': lambda: current_actor().uid[1][:6], } @@ -282,9 +323,16 @@ class ActorContextInfo(Mapping): return f'no {key} context' +_proj_name: str = 'tractor' + + def get_logger( name: str|None = None, - _root_name: str = _proj_name, + # ^NOTE, setting `name=_proj_name=='tractor'` enables the "root + # logger" for `tractor` itself. + pkg_name: str = _proj_name, + # XXX, deprecated, use ^ + _root_name: str|None = None, logger: Logger|None = None, @@ -293,49 +341,287 @@ def get_logger( # |_https://stackoverflow.com/questions/7507825/where-is-a-complete-example-of-logging-config-dictconfig # |_https://docs.python.org/3/library/logging.config.html#configuration-dictionary-schema subsys_spec: str|None = None, + mk_sublog: bool = True, + _strict_debug: bool = False, ) -> StackLevelAdapter: ''' Return the `tractor`-library root logger or a sub-logger for `name` if provided. - ''' - log: Logger - log = rlog = logger or logging.getLogger(_root_name) + When `name` is left null we try to auto-detect the caller's + `mod.__name__` and use that as a the sub-logger key. + This allows for example creating a module level instance like, + .. code:: python + + log = tractor.log.get_logger(_root_name='mylib') + + and by default all console record headers will show the caller's + (of any `log.()`-method) correct sub-pkg's + + py-module-file. + + ''' + if _root_name: + msg: str = ( + 'The `_root_name: str` param of `get_logger()` is now deprecated.\n' + 'Use the new `pkg_name: str` instead, it is the same usage.\n' + ) + warnings.warn( + msg, + DeprecationWarning, + stacklevel=2, + ) + + pkg_name: str = _root_name + + def get_caller_mod( + frames_up:int = 2 + ): + ''' + Attempt to get the module which called `tractor.get_logger()`. + + ''' + callstack: list[FrameInfo] = stack() + caller_fi: FrameInfo = callstack[frames_up] + caller_mod: ModuleType = getmodule(caller_fi.frame) + return caller_mod + + # --- Auto--naming-CASE --- + # ------------------------- + # Implicitly introspect the caller's module-name whenever `name` + # if left as the null default. + # + # When the `pkg_name` is `in` in the `mod.__name__` we presume + # this instance can be created as a sub-`StackLevelAdapter` and + # that the intention is to get free module-path tracing and + # filtering (well once we implement that) oriented around the + # py-module code hierarchy of the consuming project. + # + if ( + mk_sublog + and + name is None + and + pkg_name + ): + if (caller_mod := get_caller_mod()): + # ?XXX how is this `caller_mod.__name__` defined? + # => well by how the mod is imported.. XD + # |_https://stackoverflow.com/a/15883682 + # + # if pkg_name in caller_mod.__package__: + # from tractor.devx.debug import mk_pdb + # mk_pdb().set_trace() + + mod_ns_path: str = caller_mod.__name__ + mod_pkg_ns_path: str = caller_mod.__package__ + if ( + mod_pkg_ns_path in mod_ns_path + or + pkg_name in mod_ns_path + ): + # proper_mod_name = mod_ns_path.lstrip( + proper_mod_name = mod_pkg_ns_path.removeprefix( + f'{pkg_name}.' + ) + name = proper_mod_name + + elif ( + pkg_name + # and + # pkg_name in mod_ns_path + ): + name = mod_ns_path + + if _strict_debug: + msg: str = ( + f'@ {get_caller_mod()}\n' + f'Generating sub-logger name,\n' + f'{pkg_name}.{name}\n' + ) + if _curr_actor_no_exc(): + _root_log.debug(msg) + elif pkg_name != _proj_name: + print( + f'=> tractor.log.get_logger():\n' + f'{msg}\n' + ) + + # build a root logger instance + log: Logger + rlog = log = ( + logger + or + logging.getLogger(pkg_name) + ) + + # XXX, lowlevel debuggin.. + # if pkg_name != _proj_name: + # from tractor.devx.debug import mk_pdb + # mk_pdb().set_trace() + + # NOTE: for handling for modules that use the unecessary, + # `get_logger(__name__)` + # + # we make the following stylistic choice: + # - always avoid duplicate project-package token + # in msg output: i.e. tractor.tractor.ipc._chan.py in header + # looks ridiculous XD + # - never show the leaf module name in the {name} part + # since in python the {filename} is always this same + # module-file. if ( name and - name != _proj_name + # ?TODO? more correct? + # _proj_name not in name + name != pkg_name ): + # ex. modden.runtime.progman + # -> rname='modden', _, pkg_path='runtime.progman' + if ( + pkg_name + and + pkg_name in name + ): + proper_name: str = name.removeprefix( + f'{pkg_name}.' + ) + msg: str = ( + f'@ {get_caller_mod()}\n' + f'Duplicate pkg-name in sub-logger `name`-key?\n' + f'pkg_name = {pkg_name!r}\n' + f'name = {name!r}\n' + f'\n' + f'=> You should change your input params to,\n' + f'get_logger(\n' + f' pkg_name={pkg_name!r}\n' + f' name={proper_name!r}\n' + f')' + ) + # assert _duplicate == rname + if _curr_actor_no_exc(): + _root_log.warning(msg) + else: + print( + f'=> tractor.log.get_logger() ERROR:\n' + f'{msg}\n' + ) - # NOTE: for handling for modules that use `get_logger(__name__)` - # we make the following stylistic choice: - # - always avoid duplicate project-package token - # in msg output: i.e. tractor.tractor.ipc._chan.py in header - # looks ridiculous XD - # - never show the leaf module name in the {name} part - # since in python the {filename} is always this same - # module-file. + name = proper_name - sub_name: None|str = None - rname, _, sub_name = name.partition('.') - pkgpath, _, modfilename = sub_name.rpartition('.') + rname: str = pkg_name + pkg_path: str = name - # NOTE: for tractor itself never include the last level - # module key in the name such that something like: eg. - # 'tractor.trionics._broadcast` only includes the first - # 2 tokens in the (coloured) name part. - if rname == 'tractor': - sub_name = pkgpath - if _root_name in sub_name: - duplicate, _, sub_name = sub_name.partition('.') + # ( + # rname, + # _, + # pkg_path, + # ) = name.partition('.') - if not sub_name: + # For ex. 'modden.runtime.progman' + # -> pkgpath='runtime', _, leaf_mod='progman' + ( + subpkg_path, + _, + leaf_mod, + ) = pkg_path.rpartition('.') + + # NOTE: special usage for passing `name=__name__`, + # + # - remove duplication of any root-pkg-name in the + # (sub/child-)logger name; i.e. never include the + # `pkg_name` *twice* in the top-most-pkg-name/level + # + # -> this happens normally since it is added to `.getChild()` + # and as the name of its root-logger. + # + # => So for ex. (module key in the name) something like + # `name='tractor.trionics._broadcast` is passed, + # only includes the first 2 sub-pkg name-tokens in the + # child-logger's name; the colored "pkg-namespace" header + # will then correctly show the same value as `name`. + if ( + # XXX, TRY to remove duplication cases + # which get warn-logged on below! + ( + # when, subpkg_path == pkg_path + subpkg_path + and + rname == pkg_name + ) + # ) or ( + # # when, pkg_path == leaf_mod + # pkg_path + # and + # leaf_mod == pkg_path + # ) + ): + pkg_path = subpkg_path + + # XXX, do some double-checks for duplication of, + # - root-pkg-name, already in root logger + # - leaf-module-name already in `{filename}` header-field + if ( + _strict_debug + and + pkg_name + and + pkg_name in pkg_path + ): + _duplicate, _, pkg_path = pkg_path.partition('.') + if _duplicate: + msg: str = ( + f'@ {get_caller_mod()}\n' + f'Duplicate pkg-name in sub-logger key?\n' + f'pkg_name = {pkg_name!r}\n' + f'pkg_path = {pkg_path!r}\n' + ) + # assert _duplicate == rname + if _curr_actor_no_exc(): + _root_log.warning(msg) + else: + print( + f'=> tractor.log.get_logger() ERROR:\n' + f'{msg}\n' + ) + # XXX, should never get here? + breakpoint() + if ( + _strict_debug + and + leaf_mod + and + leaf_mod in pkg_path + ): + msg: str = ( + f'@ {get_caller_mod()}\n' + f'Duplicate leaf-module-name in sub-logger key?\n' + f'leaf_mod = {leaf_mod!r}\n' + f'pkg_path = {pkg_path!r}\n' + ) + if _curr_actor_no_exc(): + _root_log.warning(msg) + else: + print( + f'=> tractor.log.get_logger() ERROR:\n' + f'{msg}\n' + ) + + # mk/get underlying (sub-)`Logger` + if ( + not pkg_path + and + leaf_mod == pkg_name + ): + # breakpoint() log = rlog - else: - log = rlog.getChild(sub_name) + + elif mk_sublog: + # breakpoint() + log = rlog.getChild(pkg_path) log.level = rlog.level @@ -350,8 +636,13 @@ def get_logger( for name, val in CUSTOM_LEVELS.items(): logging.addLevelName(val, name) - # ensure customs levels exist as methods - assert getattr(logger, name.lower()), f'Logger does not define {name}' + # ensure our custom adapter levels exist as methods + assert getattr( + logger, + name.lower() + ), ( + f'Logger does not define {name}' + ) return logger @@ -425,4 +716,4 @@ def get_loglevel() -> str: # global module logger for tractor itself -log: StackLevelAdapter = get_logger('tractor') +_root_log: StackLevelAdapter = get_logger('tractor') diff --git a/tractor/msg/_codec.py b/tractor/msg/_codec.py index 1e9623af..e8a0379e 100644 --- a/tractor/msg/_codec.py +++ b/tractor/msg/_codec.py @@ -68,7 +68,7 @@ from tractor.log import get_logger if TYPE_CHECKING: from tractor._context import Context -log = get_logger(__name__) +log = get_logger() # TODO: unify with `MsgCodec` by making `._dec` part this? diff --git a/tractor/msg/_ops.py b/tractor/msg/_ops.py index aa215a81..ac6322e6 100644 --- a/tractor/msg/_ops.py +++ b/tractor/msg/_ops.py @@ -77,7 +77,7 @@ if TYPE_CHECKING: from tractor._streaming import MsgStream -log = get_logger(__name__) +log = get_logger() _def_any_pldec: MsgDec[Any] = mk_dec(spec=Any) diff --git a/tractor/msg/types.py b/tractor/msg/types.py index 17d99449..6176ca90 100644 --- a/tractor/msg/types.py +++ b/tractor/msg/types.py @@ -51,7 +51,7 @@ from tractor.log import get_logger # from tractor._addr import UnwrappedAddress -log = get_logger('tractor.msgspec') +log = get_logger() # type variable for the boxed payload field `.pld` PayloadT = TypeVar('PayloadT') @@ -202,7 +202,10 @@ class SpawnSpec( # TODO: similar to the `Start` kwargs spec needed below, we need # a hard `Struct` def for all of these fields! _parent_main_data: dict - _runtime_vars: dict[str, Any] + _runtime_vars: ( + dict[str, Any] + #|RuntimeVars # !TODO + ) # ^NOTE see `._state._runtime_vars: dict` # module import capability diff --git a/tractor/to_asyncio.py b/tractor/to_asyncio.py index bd46a5ab..21566beb 100644 --- a/tractor/to_asyncio.py +++ b/tractor/to_asyncio.py @@ -71,7 +71,7 @@ from outcome import ( Outcome, ) -log: StackLevelAdapter = get_logger(__name__) +log: StackLevelAdapter = get_logger() __all__ = [ diff --git a/tractor/trionics/_broadcast.py b/tractor/trionics/_broadcast.py index 2286e70d..eb3894cf 100644 --- a/tractor/trionics/_broadcast.py +++ b/tractor/trionics/_broadcast.py @@ -42,7 +42,7 @@ from trio.lowlevel import current_task from msgspec import Struct from tractor.log import get_logger -log = get_logger(__name__) +log = get_logger() # TODO: use new type-vars syntax from 3.12 # https://realpython.com/python312-new-features/#dedicated-type-variable-syntax diff --git a/tractor/trionics/_mngrs.py b/tractor/trionics/_mngrs.py index 57897c4e..577eb050 100644 --- a/tractor/trionics/_mngrs.py +++ b/tractor/trionics/_mngrs.py @@ -49,7 +49,7 @@ if TYPE_CHECKING: from tractor import ActorNursery -log = get_logger(__name__) +log = get_logger() # A regular invariant generic type T = TypeVar("T") diff --git a/tractor/trionics/_taskc.py b/tractor/trionics/_taskc.py index 0298912d..7d00b4fd 100644 --- a/tractor/trionics/_taskc.py +++ b/tractor/trionics/_taskc.py @@ -34,7 +34,7 @@ from typing import ( import trio from tractor.log import get_logger -log = get_logger(__name__) +log = get_logger() if TYPE_CHECKING: @@ -246,23 +246,12 @@ async def maybe_raise_from_masking_exc( type(exc_match) # masked type ) + # Add to masked `exc_ctx` if do_warn: exc_ctx.add_note(note) - if ( - do_warn - and - type(exc_match) in always_warn_on - ): - log.warning(note) - - if ( - do_warn - and - raise_unmasked - ): + # don't unmask already known "special" cases.. if len(masked) < 2: - # don't unmask already known "special" cases.. if ( _mask_cases and @@ -283,11 +272,26 @@ async def maybe_raise_from_masking_exc( ) raise exc_match - raise exc_ctx from exc_match + # ^?TODO, see above but, possibly unmasking sub-exc + # entries if there are > 1 + # else: + # await pause(shield=True) + + if type(exc_match) in always_warn_on: + import traceback + trace: list[str] = traceback.format_exception( + type(exc_ctx), + exc_ctx, + exc_ctx.__traceback__ + ) + tb_str: str = ''.join(trace) + log.warning(tb_str) + # XXX, for debug + # from tractor import pause + # await pause(shield=True) + + if raise_unmasked: + raise exc_ctx from exc_match - # ??TODO, see above but, possibly unmasking sub-exc - # entries if there are > 1 - # else: - # await pause(shield=True) else: raise