Hide `._rpc._invoke()` frame, again..

A partial revert of commit c05d08e426 since it seem we already
suppress tpt-closed errors lower down in `.ipc.Channel.send()`; given
that i'm pretty sure this new handler code should basically never run?

Left in a todo to remove the masked content once i'm done more
thoroughly testing under `piker`.

examples/trio/send_chan_aclose_masks_beg.py

@@ -0,0 +1,145 @@
+from contextlib import (
+    contextmanager as cm,
+    # TODO, any diff in async case(s)??
+    # asynccontextmanager as acm,
+)
+from functools import partial
+
+import tractor
+import trio
+
+
+log = tractor.log.get_logger(__name__)
+tractor.log.get_console_log('info')
+
+@cm
+def teardown_on_exc(
+    raise_from_handler: bool = False,
+):
+    '''
+    You could also have a teardown handler which catches any exc and
+    does some required teardown. In this case the problem is
+    compounded UNLESS you ensure the handler's scope is OUTSIDE the
+    `ux.aclose()`.. that is in the caller's enclosing scope.
+
+    '''
+    try:
+        yield
+    except BaseException as _berr:
+        berr = _berr
+        log.exception(
+            f'Handling termination teardown in child due to,\n'
+            f'{berr!r}\n'
+        )
+        if raise_from_handler:
+            # XXX teardown ops XXX
+            # on termination these steps say need to be run to
+            # ensure wider system consistency (like the state of
+            # remote connections/services).
+            #
+            # HOWEVER, any bug in this teardown code is also
+            # masked by the `tx.aclose()`!
+            # this is also true if `_tn.cancel_scope` is
+            # `.cancel_called` by the parent in a graceful
+            # request case..
+
+            # simulate a bug in teardown handler.
+            raise RuntimeError(
+                'woopsie teardown bug!'
+            )
+
+        raise  # no teardown bug.
+
+
+async def finite_stream_to_rent(
+    tx: trio.abc.SendChannel,
+    child_errors_mid_stream: bool,
+
+    task_status: trio.TaskStatus[
+        trio.CancelScope,
+    ] = trio.TASK_STATUS_IGNORED,
+):
+    async with (
+        # XXX without this unmasker the mid-streaming RTE is never
+        # reported since it is masked by the `tx.aclose()`
+        # call which in turn raises `Cancelled`!
+        #
+        # NOTE, this is WITHOUT doing any exception handling
+        # inside the child  task!
+        #
+        # TODO, uncomment next LoC to see the supprsessed beg[RTE]!
+        # tractor.trionics.maybe_raise_from_masking_exc(),
+
+        tx as tx,  # .aclose() is the guilty masker chkpt!
+        trio.open_nursery() as _tn,
+    ):
+        # pass our scope back to parent for supervision\
+        # control.
+        task_status.started(_tn.cancel_scope)
+
+        with teardown_on_exc(
+            raise_from_handler=not child_errors_mid_stream,
+        ):
+            for i in range(100):
+                log.info(
+                    f'Child tx {i!r}\n'
+                )
+                if (
+                    child_errors_mid_stream
+                    and
+                    i == 66
+                ):
+                    # oh wait but WOOPS there's a bug
+                    # in that teardown code!?
+                    raise RuntimeError(
+                        'woopsie, a mid-streaming bug!?'
+                    )
+
+                await tx.send(i)
+
+
+async def main(
+    # TODO! toggle this for the 2 cases!
+    # 1. child errors mid-stream while parent is also requesting
+    #   (graceful) cancel of that child streamer.
+    #
+    # 2. child contains a teardown handler which contains a
+    #   bug and raises.
+    #
+    child_errors_mid_stream: bool,
+):
+    tx, rx = trio.open_memory_channel(1)
+
+    async with (
+        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,
+                tx=tx,
+            )
+        )
+        async for msg in rx:
+            log.info(
+                f'Rent rx {msg!r}\n'
+            )
+
+            # simulate some external cancellation
+            # request **JUST BEFORE** the child errors.
+            if msg == 65:
+                log.cancel(
+                    f'Cancelling parent on,\n'
+                    f'msg={msg}\n'
+                    f'\n'
+                    f'Simulates OOB cancel request!\n'
+                )
+                tn.cancel_scope.cancel()
+
+
+if __name__ == '__main__':
+
+    for case in [True, False]:
+        trio.run(main, case)

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

@@ -117,11 +117,9 @@ def test_acm_embedded_nursery_propagates_enter_err(
         async with (
             trio.open_nursery() as tn,
             tractor.trionics.maybe_raise_from_masking_exc(
-                tn=tn,
                 unmask_from=(
-                    trio.Cancelled
+                    (trio.Cancelled,) if unmask_from_canc
-                    if unmask_from_canc
+                    else ()
-                    else None
                 ),
             )
         ):
@@ -136,7 +134,6 @@ def test_acm_embedded_nursery_propagates_enter_err(
         with tractor.devx.maybe_open_crash_handler(
             pdb=debug_mode,
         ) as bxerr:
-            if bxerr:
             assert not bxerr.value
 
             async with (
@@ -145,6 +142,7 @@ def test_acm_embedded_nursery_propagates_enter_err(
                 assert not tn.cancel_scope.cancel_called
                 assert 0
 
+        if debug_mode:
             assert (
                 (err := bxerr.value)
                 and

tractor/_rpc.py

@@ -284,6 +284,10 @@ async def _errors_relayed_via_ipc(
     try:
         yield  # run RPC invoke body
 
+    except TransportClosed:
+        log.exception('Tpt disconnect during remote-exc relay?')
+        raise
+
     # box and ship RPC errors for wire-transit via
     # the task's requesting parent IPC-channel.
     except (
@@ -319,6 +323,9 @@ async def _errors_relayed_via_ipc(
                         and debug_kbis
                     )
                 )
+                # TODO? better then `debug_filter` below?
+                and
+                not isinstance(err, TransportClosed)
             ):
                 # XXX QUESTION XXX: is there any case where we'll
                 # want to debug IPC disconnects as a default?
@@ -327,13 +334,25 @@ async def _errors_relayed_via_ipc(
                 # recovery logic - the only case is some kind of
                 # strange bug in our transport layer itself? Going
                 # to keep this open ended for now.
-                log.debug(
+
-                    'RPC task crashed, attempting to enter debugger\n'
+                if _state.debug_mode():
-                    f'|_{ctx}'
+                    log.exception(
+                        f'RPC task crashed!\n'
+                        f'Attempting to enter debugger\n'
+                        f'\n'
+                        f'{ctx}'
                     )
+
                 entered_debug = await debug._maybe_enter_pm(
                     err,
                     api_frame=inspect.currentframe(),
+
+                    # don't REPL any psuedo-expected tpt-disconnect
+                    # debug_filter=lambda exc: (
+                    #     type (exc) not in {
+                    #         TransportClosed,
+                    #     }
+                    # ),
                 )
                 if not entered_debug:
                     # if we prolly should have entered the REPL but
@@ -654,8 +673,7 @@ async def _invoke(
                 # scope ensures unasking of the `await coro` below
                 # *should* never be interfered with!!
                 maybe_raise_from_masking_exc(
-                    tn=tn,
+                    unmask_from=(Cancelled,),
-                    unmask_from=Cancelled,
                 ) as _mbme,  # maybe boxed masked exc
             ):
                 ctx._scope_nursery = tn
@@ -676,6 +694,22 @@ async def _invoke(
                     f'{pretty_struct.pformat(return_msg)}\n'
                 )
                 await chan.send(return_msg)
+                # ?TODO, remove the below since .send() already
+                # doesn't raise on tpt-closed?
+                # try:
+                #     await chan.send(return_msg)
+                # except TransportClosed:
+                #     log.exception(
+                #         f"Failed send final result to 'parent'-side of IPC-ctx!\n"
+                #         f'\n'
+                #         f'{chan}\n'
+                #         f'Channel already disconnected ??\n'
+                #         f'\n'
+                #         f'{pretty_struct.pformat(return_msg)}'
+                #     )
+                #     # ?TODO? will this ever be true though?
+                #     if chan.connected():
+                #         raise
 
             # NOTE: this happens IFF `ctx._scope.cancel()` is
             # called by any of,

tractor/devx/debug/_trace.py

@@ -561,6 +561,9 @@ async def _pause(
             return
 
         elif isinstance(pause_err, trio.Cancelled):
+            __tracebackhide__: bool = False
+            # XXX, unmask to REPL it.
+            # mk_pdb().set_trace(frame=inspect.currentframe())
             _repl_fail_report += (
                 'You called `tractor.pause()` from an already cancelled scope!\n\n'
                 'Consider `await tractor.pause(shield=True)` to make it work B)\n'

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}'
+# TODO, compare with using a "filter" instead?
-# as it did before..
+# - 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 (
-        name
+                pkg_name
-        and
+                # and
-        name != _proj_name
+                # 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 != _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: str = pkg_name
-        rname, _, sub_name = name.partition('.')
+        pkg_path: str = name
-        pkgpath, _, modfilename = sub_name.rpartition('.')
 
-        # NOTE: for tractor itself never include the last level
+        # ex. modden.runtime.progman
-        # module key in the name such that something like: eg.
+        # -> rname='modden', _, pkg_path='runtime.progman'
-        # 'tractor.trionics._broadcast` only includes the first
+        if pkg_name in name:
-        # 2 tokens in the (coloured) name part.
+            rname, _, pkg_path = name.partition('.')
-        if rname == 'tractor':
-            sub_name = pkgpath
 
-        if _root_name in sub_name:
+        # ex. modden.runtime.progman
-            duplicate, _, sub_name = sub_name.partition('.')
+        # -> 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:
+        elif mk_sublog:
-            log = rlog.getChild(sub_name)
+            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
+        # ensure our custom adapter levels exist as methods
-        assert getattr(logger, name.lower()), f'Logger does not define {name}'
+        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/to_asyncio.py

@@ -337,9 +337,12 @@ def _run_asyncio_task(
 
     '''
     __tracebackhide__: bool = hide_tb
-    if not tractor.current_actor().is_infected_aio():
+    if not (actor := tractor.current_actor()).is_infected_aio():
         raise RuntimeError(
-            "`infect_asyncio` mode is not enabled!?"
+            f'`infect_asyncio: bool` mode is not enabled ??\n'
+            f'Ensure you pass `ActorNursery.start_actor(infect_asyncio=True)`\n'
+            f'\n'
+            f'{actor}\n'
         )
 
     # ITC (inter task comms), these channel/queue names are mostly from

tractor/trionics/_mngrs.py

@@ -31,7 +31,6 @@ from typing import (
     AsyncIterator,
     Callable,
     Hashable,
-    Optional,
     Sequence,
     TypeVar,
     TYPE_CHECKING,
@@ -204,7 +203,7 @@ class _Cache:
     a kept-alive-while-in-use async resource.
 
     '''
-    service_tn: Optional[trio.Nursery] = None
+    service_tn: trio.Nursery|None = None
     locks: dict[Hashable, trio.Lock] = {}
     users: int = 0
     values: dict[Any,  Any] = {}
@@ -213,7 +212,7 @@ class _Cache:
         tuple[trio.Nursery, trio.Event]
     ] = {}
     # nurseries: dict[int, trio.Nursery] = {}
-    no_more_users: Optional[trio.Event] = None
+    no_more_users: trio.Event|None = None
 
     @classmethod
     async def run_ctx(
@@ -223,15 +222,17 @@ class _Cache:
         task_status: trio.TaskStatus[T] = trio.TASK_STATUS_IGNORED,
 
     ) -> None:
+        try:
             async with mng as value:
                 _, no_more_users = cls.resources[ctx_key]
+                try:
                     cls.values[ctx_key] = value
                     task_status.started(value)
-            try:
                     await no_more_users.wait()
                 finally:
-                # discard nursery ref so it won't be re-used (an error)?
                     value = cls.values.pop(ctx_key)
+        finally:
+            # discard nursery ref so it won't be re-used (an error)?
             cls.resources.pop(ctx_key)
 
 

tractor/trionics/_taskc.py

@@ -22,7 +22,14 @@ from __future__ import annotations
 from contextlib import (
     asynccontextmanager as acm,
 )
-from typing import TYPE_CHECKING
+import inspect
+from types import (
+    TracebackType,
+)
+from typing import (
+    Type,
+    TYPE_CHECKING,
+)
 
 import trio
 from tractor.log import get_logger
@@ -60,12 +67,71 @@ def find_masked_excs(
     return None
 
 
+_mask_cases: dict[
+    Type[Exception],  # masked exc type
+    dict[
+        int,  # inner-frame index into `inspect.getinnerframes()`
+        # `FrameInfo.function/filename: str`s to match
+        tuple[str, str],
+    ],
+] = {
+    trio.WouldBlock: {
+        # `trio.Lock.acquire()` has a checkpoint inside the
+        # `WouldBlock`-no_wait path's handler..
+        -5: {  # "5th frame up" from checkpoint
+            'filename': 'trio/_sync.py',
+            'function': 'acquire',
+            # 'lineno': 605,  # matters?
+        },
+    }
+}
+
+
+def is_expected_masking_case(
+    cases: dict,
+    exc_ctx: Exception,
+    exc_match: BaseException,
+
+) -> bool|inspect.FrameInfo:
+    '''
+    Determine whether the provided masked exception is from a known
+    bug/special/unintentional-`trio`-impl case which we do not wish
+    to unmask.
+
+    Return any guilty `inspect.FrameInfo` ow `False`.
+
+    '''
+    exc_tb: TracebackType = exc_match.__traceback__
+    if cases := _mask_cases.get(type(exc_ctx)):
+        inner: list[inspect.FrameInfo] = inspect.getinnerframes(exc_tb)
+
+        # from tractor.devx.debug import mk_pdb
+        # mk_pdb().set_trace()
+        for iframe, matchon in cases.items():
+            try:
+                masker_frame: inspect.FrameInfo = inner[iframe]
+            except IndexError:
+                continue
+
+            for field, in_field in matchon.items():
+                val = getattr(
+                    masker_frame,
+                    field,
+                )
+                if in_field not in val:
+                    break
+            else:
+                return masker_frame
+
+    return False
+
+
+
 # XXX, relevant discussion @ `trio`-core,
 # https://github.com/python-trio/trio/issues/455
 #
 @acm
 async def maybe_raise_from_masking_exc(
-    tn: trio.Nursery|None = None,
     unmask_from: (
         BaseException|
         tuple[BaseException]
@@ -74,15 +140,26 @@ async def maybe_raise_from_masking_exc(
     raise_unmasked: bool = True,
     extra_note: str = (
         'This can occurr when,\n'
-        ' - a `trio.Nursery` scope embeds a `finally:`-block '
+        '\n'
-        'which executes a checkpoint!'
+        ' - a `trio.Nursery/CancelScope` embeds a `finally/except:`-block '
+        'which execs an un-shielded checkpoint!'
         #
         # ^TODO? other cases?
     ),
 
-    always_warn_on: tuple[BaseException] = (
+    always_warn_on: tuple[Type[BaseException]] = (
         trio.Cancelled,
     ),
+
+    # don't ever unmask or warn on any masking pair,
+    # {<masked-excT-key> -> <masking-excT-value>}
+    never_warn_on: dict[
+        Type[BaseException],
+        Type[BaseException],
+    ] = {
+        KeyboardInterrupt: trio.Cancelled,
+        trio.Cancelled: trio.Cancelled,
+    },
     # ^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.
@@ -104,81 +181,109 @@ async def maybe_raise_from_masking_exc(
         individual sub-excs but maintain the eg-parent's form right?
 
     '''
+    if not isinstance(unmask_from, tuple):
+        raise ValueError(
+            f'Invalid unmask_from = {unmask_from!r}\n'
+            f'Must be a `tuple[Type[BaseException]]`.\n'
+        )
+
     from tractor.devx.debug import (
         BoxedMaybeException,
-        pause,
     )
     boxed_maybe_exc = BoxedMaybeException(
         raise_on_exit=raise_unmasked,
     )
     matching: list[BaseException]|None = None
-    maybe_eg: ExceptionGroup|None
+    try:
-
-    if tn:
-        try:  # handle egs
         yield boxed_maybe_exc
         return
-        except* unmask_from as _maybe_eg:
+    except BaseException as _bexc:
-            maybe_eg = _maybe_eg
+        bexc = _bexc
+        if isinstance(bexc, BaseExceptionGroup):
             matches: ExceptionGroup
-            matches, _ = maybe_eg.split(
+            matches, _ = bexc.split(unmask_from)
+            if matches:
+                matching = matches.exceptions
+
+        elif (
             unmask_from
-            )
+            and
-            if not matches:
+            type(bexc) in unmask_from
-                raise
+        ):
-
+            matching = [bexc]
-            matching: list[BaseException] = matches.exceptions
-    else:
-        try:  # handle non-egs
-            yield boxed_maybe_exc
-            return
-        except unmask_from as _maybe_exc:
-            maybe_exc = _maybe_exc
-            matching: list[BaseException] = [
-                maybe_exc
-            ]
-
-        # XXX, only unmask-ed for debuggin!
-        # TODO, remove eventually..
-        except BaseException as _berr:
-            berr = _berr
-            await pause(shield=True)
-            raise berr
 
     if matching is None:
         raise
 
     masked: list[tuple[BaseException, BaseException]] = []
     for exc_match in matching:
-
         if exc_ctx := find_masked_excs(
             maybe_masker=exc_match,
-            unmask_from={unmask_from},
+            unmask_from=set(unmask_from),
         ):
-            masked.append((exc_ctx, exc_match))
+            masked.append((
+                exc_ctx,
+                exc_match,
+            ))
             boxed_maybe_exc.value = exc_match
             note: str = (
                 f'\n'
-                f'^^WARNING^^ the above {exc_ctx!r} was masked by a {unmask_from!r}\n'
+                f'^^WARNING^^\n'
+                f'the above {type(exc_ctx)!r} was masked by a {type(exc_match)!r}\n'
             )
             if extra_note:
                 note += (
                     f'\n'
                     f'{extra_note}\n'
                 )
+
+            do_warn: bool = (
+                never_warn_on.get(
+                    type(exc_ctx)  # masking type
+                )
+                is not
+                type(exc_match)  # masked type
+            )
+
+            if do_warn:
                 exc_ctx.add_note(note)
 
-            if type(exc_match) in always_warn_on:
+            if (
+                do_warn
+                and
+                type(exc_match) in always_warn_on
+            ):
                 log.warning(note)
 
-            # await tractor.pause(shield=True)
+            if (
-            if raise_unmasked:
+                do_warn
-
+                and
+                raise_unmasked
+            ):
                 if len(masked) < 2:
+                    # don't unmask already known "special" cases..
+                    if (
+                        (cases := _mask_cases.get(type(exc_ctx)))
+                        and
+                        (masker_frame := is_expected_masking_case(
+                            cases,
+                            exc_ctx,
+                            exc_match,
+                        ))
+                    ):
+                        log.warning(
+                            f'Ignoring already-known/non-ideally-valid masker code @\n'
+                            f'{masker_frame}\n'
+                            f'\n'
+                            f'NOT raising {exc_ctx} from masker {exc_match!r}\n'
+                        )
+                        raise exc_match
+
                     raise exc_ctx from exc_match
-                else:
+
-                    # ?TODO, see above but, possibly unmasking sub-exc
+                # ??TODO, see above but, possibly unmasking sub-exc
                 # entries if there are > 1
-                    await pause(shield=True)
+                # else:
+                #     await pause(shield=True)
     else:
         raise