Use new `pkg_name` in log-sys test suites

That is when no `name` is passed to `get_logger()`, try to introspect
the caller's `module.__name__` and use it to infer/get the "namespace
path" to that module the same as if using `name=__name__` as in the most
common usage.

Further, change the `_root_name` to be `pkg_name: str`, a public and
more obvious param name, and deprecate the former. This obviously adds
the necessary impl to make the new
`test_sys_log::test_implicit_mod_name_applied_for_child` test pass.

Impl detalles for `get_logger()`,
- add `pkg_name` and deprecate `_root_name`, include failover logic
  and a warning.
- implement calling module introspection using
  `inspect.stack()/getmodule()` to get both the `.__name__` and
  `.__package__` info alongside adjusted logic to set the `name`
  when not provided but only when a new `mk_sublog: bool` is set.
- tweak the `name` processing for implicitly set case,
  - rename `sub_name` -> `pkg_path: str` which is the path
    to the calling module minus that module's name component.
  - only partition `name` if `pkg_name` is `in` it.
  - use the `_root_log` for `pkg_name` duplication warnings.

Other/related,
- add types to various public mod vars missing them.
- rename `.log.log` -> `.log._root_log`.

examples/trio/lockacquire_not_unmasked.py

@@ -0,0 +1,85 @@
+from contextlib import (
+    asynccontextmanager as acm,
+)
+from functools import partial
+
+import tractor
+import trio
+
+
+log = tractor.log.get_logger(
+    name=__name__
+)
+
+_lock: trio.Lock|None = None
+
+
+@acm
+async def acquire_singleton_lock(
+) -> None:
+    global _lock
+    if _lock is None:
+        log.info('Allocating LOCK')
+        _lock = trio.Lock()
+
+    log.info('TRYING TO LOCK ACQUIRE')
+    async with _lock:
+        log.info('ACQUIRED')
+        yield _lock
+
+    log.info('RELEASED')
+
+
+
+async def hold_lock_forever(
+    task_status=trio.TASK_STATUS_IGNORED
+):
+    async with (
+        tractor.trionics.maybe_raise_from_masking_exc(),
+        acquire_singleton_lock() as lock,
+    ):
+        task_status.started(lock)
+        await trio.sleep_forever()
+
+
+async def main(
+    ignore_special_cases: bool,
+    loglevel: str = 'info',
+    debug_mode: bool = True,
+):
+    async with (
+        trio.open_nursery() as tn,
+
+        # tractor.trionics.maybe_raise_from_masking_exc()
+        # ^^^ XXX NOTE, interestingly putting the unmasker
+        # here does not exhibit the same behaviour ??
+    ):
+        if not ignore_special_cases:
+            from tractor.trionics import _taskc
+            _taskc._mask_cases.clear()
+
+        _lock = await tn.start(
+            hold_lock_forever,
+        )
+        with trio.move_on_after(0.2):
+            await tn.start(
+                hold_lock_forever,
+            )
+
+        tn.cancel_scope.cancel()
+
+
+# XXX, manual test as script
+if __name__ == '__main__':
+    tractor.log.get_console_log(level='info')
+    for case in [True, False]:
+        log.info(
+            f'\n'
+            f'------ RUNNING SCRIPT TRIAL ------\n'
+            f'ignore_special_cases: {case!r}\n'
+        )
+        trio.run(partial(
+            main,
+            ignore_special_cases=case,
+            loglevel='info',
+        ))

examples/trio/send_chan_aclose_masks_beg.py

@@ -9,8 +9,10 @@ import tractor
 import trio
 
 
-log = tractor.log.get_logger(__name__)
-tractor.log.get_console_log('info')
+log = tractor.log.get_logger(
+    name=__name__
+)
+
 
 @cm
 def teardown_on_exc(
@@ -54,6 +56,7 @@ def teardown_on_exc(
 async def finite_stream_to_rent(
     tx: trio.abc.SendChannel,
     child_errors_mid_stream: bool,
+    raise_unmasked: bool,
 
     task_status: trio.TaskStatus[
         trio.CancelScope,
@@ -68,20 +71,41 @@ async def finite_stream_to_rent(
         # inside the child  task!
         #
         # TODO, uncomment next LoC to see the supprsessed beg[RTE]!
-        # tractor.trionics.maybe_raise_from_masking_exc(),
+        tractor.trionics.maybe_raise_from_masking_exc(
+            raise_unmasked=raise_unmasked,
+        ),
 
         tx as tx,  # .aclose() is the guilty masker chkpt!
-        trio.open_nursery() as _tn,
+
+        # XXX, this ONLY matters in the
+        # `child_errors_mid_stream=False` case oddly!?
+        # THAT IS, if no tn is opened in that case then the
+        # test will not fail; it raises the RTE correctly?
+        #
+        # -> so it seems this new scope somehow affects the form of
+        #    eventual in the parent EG?
+        tractor.trionics.maybe_open_nursery(
+            nursery=(
+                None
+                if not child_errors_mid_stream
+                else True
+            ),
+        ) as _tn,
     ):
         # pass our scope back to parent for supervision\
         # control.
-        task_status.started(_tn.cancel_scope)
+        cs: trio.CancelScope|None = (
+            None
+            if _tn is True
+            else _tn.cancel_scope
+        )
+        task_status.started(cs)
 
         with teardown_on_exc(
             raise_from_handler=not child_errors_mid_stream,
         ):
             for i in range(100):
-                log.info(
+                log.debug(
                     f'Child tx {i!r}\n'
                 )
                 if (
@@ -107,23 +131,31 @@ async def main(
     #   bug and raises.
     #
     child_errors_mid_stream: bool,
+
+    raise_unmasked: bool = False,
+    loglevel: str = 'info',
 ):
+    tractor.log.get_console_log(level=loglevel)
+
+    # the `.aclose()` being checkpoints on these
+    # is the source of the problem..
     tx, rx = trio.open_memory_channel(1)
 
     async with (
+        tractor.trionics.collapse_eg(),
         trio.open_nursery() as tn,
         rx as rx,
     ):
-
         _child_cs = await tn.start(
             partial(
                 finite_stream_to_rent,
                 child_errors_mid_stream=child_errors_mid_stream,
+                raise_unmasked=raise_unmasked,
                 tx=tx,
             )
         )
         async for msg in rx:
-            log.info(
+            log.debug(
                 f'Rent rx {msg!r}\n'
             )
 
@@ -139,7 +171,25 @@ async def main(
                 tn.cancel_scope.cancel()
 
 
+# XXX, manual test as script
 if __name__ == '__main__':
-
+    tractor.log.get_console_log(level='info')
     for case in [True, False]:
-        trio.run(main, case)
+        log.info(
+            f'\n'
+            f'------ RUNNING SCRIPT TRIAL ------\n'
+            f'child_errors_midstream: {case!r}\n'
+        )
+        try:
+            trio.run(partial(
+                main,
+                child_errors_mid_stream=case,
+                # raise_unmasked=True,
+                loglevel='info',
+            ))
+        except Exception as _exc:
+            exc = _exc
+            log.exception(
+                'Should have raised an RTE or Cancelled?\n'
+            )
+            breakpoint()

tests/test_docs_examples.py

@@ -95,6 +95,7 @@ def run_example_in_subproc(
             and 'integration' not in p[0]
             and 'advanced_faults' not in p[0]
             and 'multihost' not in p[0]
+            and 'trio' not in p[0]
         )
     ],
     ids=lambda t: t[1],

tests/test_log_sys.py

@@ -0,0 +1,177 @@
+'''
+`tractor.log`-wrapping unit tests.
+
+'''
+import importlib
+from pathlib import Path
+import shutil
+import sys
+from types import ModuleType
+
+import pytest
+import tractor
+
+
+def test_root_pkg_not_duplicated_in_logger_name():
+    '''
+    When both `pkg_name` and `name` are passed and they have
+    a common `<root_name>.< >` prefix, ensure that it is not
+    duplicated in the child's `StackLevelAdapter.name: str`.
+
+    '''
+    project_name: str = 'pylib'
+    pkg_path: str = 'pylib.subpkg.mod'
+
+    proj_log = tractor.log.get_logger(
+        pkg_name=project_name,
+        mk_sublog=False,
+    )
+
+    sublog = tractor.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
+
+
+# ?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
+
+
+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'
+        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)
+    subpkg: Path = pkg / 'subpkg'
+    subpkg.mkdir()
+
+    pkgmod: Path = subpkg / "__init__.py"
+    pkgmod.touch()
+
+    _submod: Path = testdir.makepyfile(
+        _mod=mod_code,
+    )
+
+    pkg_mod = pkg / 'mod.py'
+    pkg_subpkg_submod = subpkg / 'submod.py'
+    shutil.copyfile(
+        _submod,
+        pkg_mod,
+    )
+    shutil.copyfile(
+        _submod,
+        pkg_subpkg_submod,
+    )
+    testdir.chdir()
+
+    # 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.
+    pkgmod = load_module_from_path(
+        Path(pkg / '__init__.py'),
+        module_name=proj_name,
+    )
+    pkg_root_log = tractor.log.get_logger(
+        pkg_name=proj_name,
+        mk_sublog=False,
+    )
+    assert pkg_root_log.name == proj_name
+    assert not pkg_root_log.logger.getChildren()
+
+    from snakelib import mod
+    assert mod.log.name == proj_name
+
+    from snakelib.subpkg import submod
+    assert (
+        submod.log.name
+        ==
+        submod.__package__  # ?TODO, use this in `.get_logger()` instead?
+        ==
+        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
+
+    # breakpoint()
+
+
+# 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

tests/test_trioisms.py

@@ -6,11 +6,18 @@ want to see changed.
 from contextlib import (
     asynccontextmanager as acm,
 )
+from types import ModuleType
+
+from functools import partial
 
 import pytest
+from _pytest import pathlib
 from tractor.trionics import collapse_eg
 import trio
 from trio import TaskStatus
+from tractor._testing import (
+    examples_dir,
+)
 
 
 @pytest.mark.parametrize(
@@ -106,8 +113,9 @@ def test_acm_embedded_nursery_propagates_enter_err(
     debug_mode: bool,
 ):
     '''
-    Demo how a masking `trio.Cancelled` could be handled by unmasking from the
-    `.__context__` field when a user (by accident) re-raises from a `finally:`.
+    Demo how a masking `trio.Cancelled` could be handled by unmasking
+    from the `.__context__` field when a user (by accident) re-raises
+    from a `finally:`.
 
     '''
     import tractor
@@ -158,13 +166,13 @@ def test_acm_embedded_nursery_propagates_enter_err(
     assert len(assert_eg.exceptions) == 1
 
 
-
 def test_gatherctxs_with_memchan_breaks_multicancelled(
     debug_mode: bool,
 ):
     '''
-    Demo how a using an `async with sndchan` inside a `.trionics.gather_contexts()` task
-    will break a strict-eg-tn's multi-cancelled absorption..
+    Demo how a using an `async with sndchan` inside
+    a `.trionics.gather_contexts()` task will break a strict-eg-tn's
+    multi-cancelled absorption..
 
     '''
     from tractor import (
@@ -190,7 +198,6 @@ def test_gatherctxs_with_memchan_breaks_multicancelled(
                 f'Closed {task!r}\n'
             )
 
-
     async def main():
         async with (
             # XXX should ensure ONLY the KBI
@@ -211,3 +218,85 @@ def test_gatherctxs_with_memchan_breaks_multicancelled(
 
     with pytest.raises(KeyboardInterrupt):
         trio.run(main)
+
+
+@pytest.mark.parametrize(
+    'raise_unmasked', [
+        True,
+        pytest.param(
+            False,
+            marks=pytest.mark.xfail(
+                reason="see examples/trio/send_chan_aclose_masks.py"
+            )
+        ),
+    ]
+)
+@pytest.mark.parametrize(
+    'child_errors_mid_stream',
+    [True, False],
+)
+def test_unmask_aclose_as_checkpoint_on_aexit(
+    raise_unmasked: bool,
+    child_errors_mid_stream: bool,
+    debug_mode: bool,
+):
+    '''
+    Verify that our unmasker util works over the common case where
+    a mem-chan's `.aclose()` is included in an `@acm` stack
+    and it being currently a checkpoint, can `trio.Cancelled`-mask an embedded
+    exception from user code resulting in a silent failure which
+    appears like graceful cancellation.
+
+    This test suite is mostly implemented as an example script so it
+    could more easily be shared with `trio`-core peeps as `tractor`-less
+    minimum reproducing example.
+
+    '''
+    mod: ModuleType = pathlib.import_path(
+        examples_dir()
+        / 'trio'
+        / 'send_chan_aclose_masks_beg.py',
+        root=examples_dir(),
+        consider_namespace_packages=False,
+    )
+    with pytest.raises(RuntimeError):
+        trio.run(partial(
+            mod.main,
+            raise_unmasked=raise_unmasked,
+            child_errors_mid_stream=child_errors_mid_stream,
+        ))
+
+
+
+@pytest.mark.parametrize(
+    'ignore_special_cases', [
+        True,
+        pytest.param(
+            False,
+            marks=pytest.mark.xfail(
+                reason="see examples/trio/lockacquire_not_umasked.py"
+            )
+        ),
+    ]
+)
+def test_cancelled_lockacquire_in_ipctx_not_unmasked(
+    ignore_special_cases: bool,
+    loglevel: str,
+    debug_mode: bool,
+):
+    mod: ModuleType = pathlib.import_path(
+        examples_dir()
+        / 'trio'
+        / 'lockacquire_not_unmasked.py',
+        root=examples_dir(),
+        consider_namespace_packages=False,
+    )
+    async def _main():
+        with trio.fail_after(2):
+            await mod.main(
+                ignore_special_cases=ignore_special_cases,
+                loglevel=loglevel,
+                debug_mode=debug_mode,
+            )
+
+    trio.run(_main)

tractor/log.py

@@ -14,11 +14,22 @@
 # You should have received a copy of the GNU Affero General Public License
 # along with this program.  If not, see <https://www.gnu.org/licenses/>.
 
-"""
-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 inspect import (
+    FrameInfo,
+    getmodule,
+    stack,
+)
 import sys
 import logging
 from logging import (
@@ -26,8 +37,10 @@ from logging import (
     Logger,
     StreamHandler,
 )
-import colorlog  # type: ignore
+from types import ModuleType
+import warnings
 
+import colorlog  # type: ignore
 import trio
 
 from ._state import current_actor
@@ -39,7 +52,7 @@ _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 +64,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 +88,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,10 +113,17 @@ 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".
 
+    '''
     def at_least_level(
         self,
         level: str,
@@ -284,7 +307,9 @@ class ActorContextInfo(Mapping):
 
 def get_logger(
     name: str|None = None,
-    _root_name: str = _proj_name,
+    pkg_name: str = _proj_name,
+    # XXX, deprecated, use ^
+    _root_name: str|None = None,
 
     logger: Logger|None = None,
 
@@ -293,22 +318,89 @@ 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,
 
 ) -> StackLevelAdapter:
     '''
     Return the `tractor`-library root logger or a sub-logger for
     `name` if provided.
 
+    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.<level>()`-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 or pkg_name
     log: Logger
-    log = rlog = logger or logging.getLogger(_root_name)
+    log = rlog = logger or logging.getLogger(pkg_name)
+
+    # 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 get free module-path tracing and
+    # filtering (well once we implement that) oriented around the
+    # py-module code hierarchy of the consuming project.
+    if (
+        pkg_name != _proj_name
+        and
+        name is None
+        and
+        mk_sublog
+    ):
+        callstack: list[FrameInfo] = stack()
+        caller_fi: FrameInfo = callstack[1]
+        caller_mod: ModuleType = getmodule(caller_fi.frame)
+        if caller_mod:
+            # ?how is this `mod.__name__` defined?
+            # -> well by how the mod is imported..
+            # |_https://stackoverflow.com/a/15883682
+            mod_name: str = caller_mod.__name__
+            mod_pkg: str = caller_mod.__package__
+            log.info(
+                f'Generating sub-logger name,\n'
+                f'{mod_pkg}.{mod_name}\n'
+            )
+            # if pkg_name in caller_mod.__package__:
+            #     from tractor.devx.debug import mk_pdb
+            #     mk_pdb().set_trace()
+
+            if (
+                pkg_name
+                # and
+                # pkg_name in mod_name
+            ):
+                name = mod_name
+
+    # XXX, lowlevel debuggin..
+    # if pkg_name != _proj_name:
+        # from tractor.devx.debug import mk_pdb
+        # mk_pdb().set_trace()
 
     if (
-        name
-        and
         name != _proj_name
+        and
+        name
     ):
-
         # NOTE: for handling for modules that use `get_logger(__name__)`
         # we make the following stylistic choice:
         # - always avoid duplicate project-package token
@@ -318,24 +410,63 @@ def get_logger(
         #   since in python the {filename} is always this same
         #   module-file.
 
-        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
+        # ex. modden.runtime.progman
+        # -> rname='modden', _, pkg_path='runtime.progman'
+        if pkg_name in name:
+            rname, _, pkg_path = name.partition('.')
 
-        if _root_name in sub_name:
-            duplicate, _, sub_name = sub_name.partition('.')
+        # ex. modden.runtime.progman
+        # -> pkgpath='runtime', _, leaf_mod='progman'
+        subpkg_path, _, leaf_mod = pkg_path.rpartition('.')
 
-        if not sub_name:
+        # 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 rname == pkg_name:
+            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 pkg_name in pkg_path:
+            _duplicate, _, pkg_path = pkg_path.partition('.')
+            if _duplicate:
+                # assert _duplicate == rname
+                _root_log.warning(
+                    f'Duplicate pkg-name in sub-logger key?\n'
+                    f'pkg_name = {pkg_name!r}\n'
+                    f'pkg_path = {pkg_path!r}\n'
+                )
+
+        if (
+            leaf_mod
+            and
+            leaf_mod in pkg_path
+        ):
+            _root_log.warning(
+                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 not pkg_path:
             log = rlog
-        else:
-            log = rlog.getChild(sub_name)
+        elif mk_sublog:
+            log = rlog.getChild(pkg_path)
 
         log.level = rlog.level
 
@@ -350,8 +481,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 +561,4 @@ def get_loglevel() -> str:
 
 
 # global module logger for tractor itself
-log: StackLevelAdapter = get_logger('tractor')
+_root_log: StackLevelAdapter = get_logger('tractor')

tractor/trionics/_taskc.py

@@ -72,7 +72,7 @@ _mask_cases: dict[
     dict[
         int,  # inner-frame index into `inspect.getinnerframes()`
         # `FrameInfo.function/filename: str`s to match
-        tuple[str, str],
+        dict[str, str],
     ],
 ] = {
     trio.WouldBlock: {
@@ -163,6 +163,7 @@ async def maybe_raise_from_masking_exc(
     # ^XXX, special case(s) where we warn-log bc likely
     # there will be no operational diff since the exc
     # is always expected to be consumed.
+
 ) -> BoxedMaybeException:
     '''
     Maybe un-mask and re-raise exception(s) suppressed by a known
@@ -263,6 +264,8 @@ async def maybe_raise_from_masking_exc(
                 if len(masked) < 2:
                     # don't unmask already known "special" cases..
                     if (
+                        _mask_cases
+                        and
                         (cases := _mask_cases.get(type(exc_ctx)))
                         and
                         (masker_frame := is_expected_masking_case(
@@ -272,7 +275,8 @@ async def maybe_raise_from_masking_exc(
                         ))
                     ):
                         log.warning(
-                            f'Ignoring already-known/non-ideally-valid masker code @\n'
+                            f'Ignoring already-known, non-ideal-but-valid '
+                            f'masker code @\n'
                             f'{masker_frame}\n'
                             f'\n'
                             f'NOT raising {exc_ctx} from masker {exc_match!r}\n'