`._entry`: use same msg info in start/terminate log

Since this was changed as part of overall project wide logging format
updates, and i ended up changing the both the crash and pause `.pdb()`
msgs to include some multi-line-ascii-"stuff", might as well make the
pre-prompt checks in the test suite more flexible to match.

As such, this exposes 2 new constants inside the `.devx._debug` mod:
- `._pause_msg: str` for the pre `tractor.pause()` header emitted via
  `log.pdb()` and,
- `._crash_msg: str` for the pre `._post_mortem()` equiv when handling
  errors in debug mode.

Adjust the test suite to use these values and thus make us more capable
to absorb changes in the future as well:
- add a new `in_prompt_msg()` predicate, very similar to `assert_before()`
  but minus `assert`s which takes in a `parts: list[str]` to match
  in the pre-prompt stdout.
- delegate to `in_prompt_msg()` in `assert_before()` since it was mostly
  duplicate minus `assert`.
- adjust all previous `<patt> in before` asserts to instead use
  `in_prompt_msg()` with separated pre-prompt-header vs. actor-name
  `parts`.
- use new `._pause/crash_msg` values in all such calls including any
  `assert_before()` cases.

tests/test_advanced_streaming.py

@@ -329,7 +329,7 @@ async def inf_streamer(
 
             # close out the stream gracefully
             except trio.ClosedResourceError:
-                print('msgstream closed on streamer side!')
+                print('transport closed on streamer side!')
                 assert stream.closed
                 break
         else:

tests/test_child_manages_service_nursery.py

@@ -10,7 +10,6 @@ from contextlib import asynccontextmanager as acm
 
 import pytest
 import trio
-from trio_typing import TaskStatus
 import tractor
 from tractor import RemoteActorError
 from async_generator import aclosing

tests/test_debugger.py

@@ -10,12 +10,13 @@ TODO:
     - wonder if any of it'll work on OS X?
 
 """
+from functools import partial
 import itertools
-from os import path
+# from os import path
 from typing import Optional
 import platform
 import pathlib
-import sys
+# import sys
 import time
 
 import pytest
@@ -25,6 +26,10 @@ from pexpect.exceptions import (
     EOF,
 )
 
+from tractor.devx._debug import (
+    _pause_msg,
+    _crash_msg,
+)
 from conftest import (
     examples_dir,
     _ci_env,
@@ -123,20 +128,52 @@ def expect(
         raise
 
 
+def in_prompt_msg(
+    prompt: str,
+    parts: list[str],
+
+    pause_on_false: bool = False,
+    print_prompt_on_false: bool = True,
+
+) -> bool:
+    '''
+    Predicate check if (the prompt's) std-streams output has all
+    `str`-parts in it.
+
+    Can be used in test asserts for bulk matching expected
+    log/REPL output for a given `pdb` interact point.
+
+    '''
+    for part in parts:
+        if part not in prompt:
+
+            if pause_on_false:
+                import pdbp
+                pdbp.set_trace()
+
+            if print_prompt_on_false:
+                print(prompt)
+
+            return False
+
+    return True
+
 def assert_before(
     child,
     patts: list[str],
 
+    **kwargs,
+
 ) -> None:
 
-    before = str(child.before.decode())
+    # as in before the prompt end
+    before: str = str(child.before.decode())
+    assert in_prompt_msg(
+        prompt=before,
+        parts=patts,
 
-    for patt in patts:
-        try:
-            assert patt in before
-        except AssertionError:
-            print(before)
-            raise
+        **kwargs
+    )
 
 
 @pytest.fixture(
@@ -195,7 +232,10 @@ def test_root_actor_error(spawn, user_in_out):
     before = str(child.before.decode())
 
     # make sure expected logging and error arrives
-    assert "Attaching to pdb in crashed actor: ('root'" in before
+    assert in_prompt_msg(
+        before,
+        [_crash_msg, "('root'"]
+    )
     assert 'AssertionError' in before
 
     # send user command
@@ -332,7 +372,10 @@ def test_subactor_error(
     child.expect(PROMPT)
 
     before = str(child.before.decode())
-    assert "Attaching to pdb in crashed actor: ('name_error'" in before
+    assert in_prompt_msg(
+        before,
+        [_crash_msg, "('name_error'"]
+    )
 
     if do_next:
         child.sendline('n')
@@ -353,9 +396,15 @@ def test_subactor_error(
     before = str(child.before.decode())
 
     # root actor gets debugger engaged
-    assert "Attaching to pdb in crashed actor: ('root'" in before
+    assert in_prompt_msg(
+        before,
+        [_crash_msg, "('root'"]
+    )
     # error is a remote error propagated from the subactor
-    assert "RemoteActorError: ('name_error'" in before
+    assert in_prompt_msg(
+        before,
+        [_crash_msg, "('name_error'"]
+    )
 
     # another round
     if ctlc:
@@ -380,7 +429,10 @@ def test_subactor_breakpoint(
     child.expect(PROMPT)
 
     before = str(child.before.decode())
-    assert "Attaching pdb to actor: ('breakpoint_forever'" in before
+    assert in_prompt_msg(
+        before,
+        [_pause_msg, "('breakpoint_forever'"]
+    )
 
     # do some "next" commands to demonstrate recurrent breakpoint
     # entries
@@ -396,7 +448,10 @@ def test_subactor_breakpoint(
         child.sendline('continue')
         child.expect(PROMPT)
         before = str(child.before.decode())
-        assert "Attaching pdb to actor: ('breakpoint_forever'" in before
+        assert in_prompt_msg(
+            before,
+            [_pause_msg, "('breakpoint_forever'"]
+        )
 
         if ctlc:
             do_ctlc(child)
@@ -441,7 +496,10 @@ def test_multi_subactors(
     child.expect(PROMPT)
 
     before = str(child.before.decode())
-    assert "Attaching pdb to actor: ('breakpoint_forever'" in before
+    assert in_prompt_msg(
+        before,
+        [_pause_msg, "('breakpoint_forever'"]
+    )
 
     if ctlc:
         do_ctlc(child)
@@ -461,7 +519,10 @@ def test_multi_subactors(
     # first name_error failure
     child.expect(PROMPT)
     before = str(child.before.decode())
-    assert "Attaching to pdb in crashed actor: ('name_error'" in before
+    assert in_prompt_msg(
+        before,
+        [_crash_msg, "('name_error'"]
+    )
     assert "NameError" in before
 
     if ctlc:
@@ -487,7 +548,10 @@ def test_multi_subactors(
     child.sendline('c')
     child.expect(PROMPT)
     before = str(child.before.decode())
-    assert "Attaching pdb to actor: ('breakpoint_forever'" in before
+    assert in_prompt_msg(
+        before,
+        [_pause_msg, "('breakpoint_forever'"]
+    )
 
     if ctlc:
         do_ctlc(child)
@@ -527,17 +591,21 @@ def test_multi_subactors(
     child.expect(PROMPT)
     before = str(child.before.decode())
 
-    assert_before(child, [
-        # debugger attaches to root
-        "Attaching to pdb in crashed actor: ('root'",
+    assert_before(
+        child, [
+            # debugger attaches to root
+            # "Attaching to pdb in crashed actor: ('root'",
+            _crash_msg,
+            "('root'",
 
-        # expect a multierror with exceptions for each sub-actor
-        "RemoteActorError: ('breakpoint_forever'",
-        "RemoteActorError: ('name_error'",
-        "RemoteActorError: ('spawn_error'",
-        "RemoteActorError: ('name_error_1'",
-        'bdb.BdbQuit',
-    ])
+            # expect a multierror with exceptions for each sub-actor
+            "RemoteActorError: ('breakpoint_forever'",
+            "RemoteActorError: ('name_error'",
+            "RemoteActorError: ('spawn_error'",
+            "RemoteActorError: ('name_error_1'",
+            'bdb.BdbQuit',
+        ]
+    )
 
     if ctlc:
         do_ctlc(child)
@@ -574,15 +642,22 @@ def test_multi_daemon_subactors(
     # the root's tty lock first so anticipate either crash
     # message on the first entry.
 
-    bp_forever_msg = "Attaching pdb to actor: ('bp_forever'"
+    bp_forev_parts = [_pause_msg, "('bp_forever'"]
+    bp_forev_in_msg = partial(
+        in_prompt_msg,
+        parts=bp_forev_parts,
+    )
+
     name_error_msg = "NameError: name 'doggypants' is not defined"
+    name_error_parts = [name_error_msg]
 
     before = str(child.before.decode())
-    if bp_forever_msg in before:
-        next_msg = name_error_msg
+
+    if bp_forev_in_msg(prompt=before):
+        next_parts = name_error_parts
 
     elif name_error_msg in before:
-        next_msg = bp_forever_msg
+        next_parts = bp_forev_parts
 
     else:
         raise ValueError("Neither log msg was found !?")
@@ -599,7 +674,10 @@ def test_multi_daemon_subactors(
 
     child.sendline('c')
     child.expect(PROMPT)
-    assert_before(child, [next_msg])
+    assert_before(
+        child,
+        next_parts,
+    )
 
     # XXX: hooray the root clobbering the child here was fixed!
     # IMO, this demonstrates the true power of SC system design.
@@ -623,9 +701,15 @@ def test_multi_daemon_subactors(
     child.expect(PROMPT)
 
     try:
-        assert_before(child, [bp_forever_msg])
+        assert_before(
+            child,
+            bp_forev_parts,
+        )
     except AssertionError:
-        assert_before(child, [name_error_msg])
+        assert_before(
+            child,
+            name_error_parts,
+        )
 
     else:
         if ctlc:
@@ -637,7 +721,10 @@ def test_multi_daemon_subactors(
 
         child.sendline('c')
         child.expect(PROMPT)
-        assert_before(child, [name_error_msg])
+        assert_before(
+            child,
+            name_error_parts,
+        )
 
     # wait for final error in root
     # where it crashs with boxed error
@@ -647,7 +734,7 @@ def test_multi_daemon_subactors(
             child.expect(PROMPT)
             assert_before(
                 child,
-                [bp_forever_msg]
+                bp_forev_parts
             )
         except AssertionError:
             break
@@ -656,7 +743,9 @@ def test_multi_daemon_subactors(
         child,
         [
             # boxed error raised in root task
-            "Attaching to pdb in crashed actor: ('root'",
+            # "Attaching to pdb in crashed actor: ('root'",
+            _crash_msg,
+            "('root'",
             "_exceptions.RemoteActorError: ('name_error'",
         ]
     )
@@ -770,7 +859,7 @@ def test_multi_nested_subactors_error_through_nurseries(
 
     child = spawn('multi_nested_subactors_error_up_through_nurseries')
 
-    timed_out_early: bool = False
+    # timed_out_early: bool = False
 
     for send_char in itertools.cycle(['c', 'q']):
         try:
@@ -871,11 +960,14 @@ def test_root_nursery_cancels_before_child_releases_tty_lock(
 
     if not timed_out_early:
         before = str(child.before.decode())
-        assert_before(child, [
-            "tractor._exceptions.RemoteActorError: ('spawner0'",
-            "tractor._exceptions.RemoteActorError: ('name_error'",
-            "NameError: name 'doggypants' is not defined",
-        ])
+        assert_before(
+            child,
+            [
+                "tractor._exceptions.RemoteActorError: ('spawner0'",
+                "tractor._exceptions.RemoteActorError: ('name_error'",
+                "NameError: name 'doggypants' is not defined",
+            ],
+        )
 
 
 def test_root_cancels_child_context_during_startup(
@@ -909,8 +1001,10 @@ def test_different_debug_mode_per_actor(
 
     # only one actor should enter the debugger
     before = str(child.before.decode())
-    assert "Attaching to pdb in crashed actor: ('debugged_boi'" in before
-    assert "RuntimeError" in before
+    assert in_prompt_msg(
+        before,
+        [_crash_msg, "('debugged_boi'", "RuntimeError"],
+    )
 
     if ctlc:
         do_ctlc(child)

tests/test_rpc.py

@@ -134,7 +134,7 @@ def test_rpc_errors(
         value = err.value
 
         # might get multiple `trio.Cancelled`s as well inside an inception
-        if isinstance(value, trio.MultiError):
+        if isinstance(value, ExceptionGroup):
             value = next(itertools.dropwhile(
                 lambda exc: not isinstance(exc, tractor.RemoteActorError),
                 value.exceptions

tractor/_entry.py

@@ -116,14 +116,18 @@ def _trio_main(
     if actor.loglevel is not None:
         get_console_log(actor.loglevel)
         import os
-        log.info(
-            'Started new trio process:\n'
+        actor_info: str = (
             f'|_{actor}\n'
             f'  uid: {actor.uid}\n'
             f'  pid: {os.getpid()}\n'
             f'  parent_addr: {parent_addr}\n'
             f'  loglevel: {actor.loglevel}\n'
         )
+        log.info(
+            'Started new trio process:\n'
+            +
+            actor_info
+        )
 
     try:
         if infect_asyncio:
@@ -133,8 +137,14 @@ def _trio_main(
             trio.run(trio_main)
     except KeyboardInterrupt:
         log.cancel(
-            f'@{actor.uid} received KBI'
+            'Actor received KBI\n'
+            +
+            actor_info
         )
 
     finally:
-        log.info(f"Actor {actor.uid} terminated")
+        log.info(
+            'Actor terminated\n'
+            +
+            actor_info
+        )

tractor/_portal.py

@@ -257,7 +257,7 @@ class Portal:
             return False
 
         reminfo: str = (
-            f'{self.channel.uid}\n'
+            f'`Portal.cancel_actor()` => {self.channel.uid}\n'
             f' |_{chan}\n'
         )
         log.cancel(
@@ -949,9 +949,13 @@ class Portal:
 
                 # CASE 1
                 else:
+                    outcome_str: str = ctx.repr_outcome(
+                        show_error_fields=True,
+                        # type_only=True,
+                    )
                     log.cancel(
-                        f'Context terminated due to local scope error:\n'
-                        f'{etype.__name__}\n'
+                        f'Context terminated due to local scope error:\n\n'
+                        f'{ctx.chan.uid} => {outcome_str}\n'
                     )
 
             # FINALLY, remove the context from runtime tracking and

tractor/_root.py

@@ -342,7 +342,9 @@ async def open_root_actor(
                 #     for an in nurseries:
                 #         tempn.start_soon(an.exited.wait)
 
-                logger.cancel("Shutting down root actor")
+                logger.info(
+                    'Closing down root actor'
+                )
                 await actor.cancel(None)  # self cancel
     finally:
         _state._current_actor = None

tractor/devx/__init__.py

@@ -21,30 +21,17 @@ and working with/on the actor runtime.
 
 """
 from ._debug import (
-    maybe_wait_for_debugger,
-    acquire_debug_lock,
-    breakpoint,
-    pause,
-    pause_from_sync,
-    shield_sigint_handler,
-    MultiActorPdb,
-    open_crash_handler,
-    maybe_open_crash_handler,
-    post_mortem,
+    maybe_wait_for_debugger as maybe_wait_for_debugger,
+    acquire_debug_lock as acquire_debug_lock,
+    breakpoint as breakpoint,
+    pause as pause,
+    pause_from_sync as pause_from_sync,
+    shield_sigint_handler as shield_sigint_handler,
+    MultiActorPdb as MultiActorPdb,
+    open_crash_handler as open_crash_handler,
+    maybe_open_crash_handler as maybe_open_crash_handler,
+    post_mortem as post_mortem,
 )
 from ._stackscope import (
     enable_stack_on_sig as enable_stack_on_sig,
 )
-
-__all__ = [
-    'maybe_wait_for_debugger',
-    'acquire_debug_lock',
-    'breakpoint',
-    'pause',
-    'pause_from_sync',
-    'shield_sigint_handler',
-    'MultiActorPdb',
-    'open_crash_handler',
-    'maybe_open_crash_handler',
-    'post_mortem',
-]

tractor/devx/_debug.py

@@ -21,18 +21,19 @@ Multi-core debugging for da peeps!
 """
 from __future__ import annotations
 import bdb
-import os
-import sys
-import signal
-from functools import (
-    partial,
-    cached_property,
-)
 from contextlib import (
     asynccontextmanager as acm,
     contextmanager as cm,
     nullcontext,
 )
+from functools import (
+    partial,
+    cached_property,
+)
+import os
+import signal
+import sys
+import traceback
 from typing import (
     Any,
     Callable,
@@ -611,6 +612,9 @@ def shield_sigint_handler(
         # https://github.com/prompt-toolkit/python-prompt-toolkit/blob/c2c6af8a0308f9e5d7c0e28cb8a02963fe0ce07a/prompt_toolkit/patch_stdout.py
 
 
+_pause_msg: str = 'Attaching to pdb REPL in actor'
+
+
 def _set_trace(
     actor: tractor.Actor | None = None,
     pdb: MultiActorPdb | None = None,
@@ -632,7 +636,13 @@ def _set_trace(
         ) or shield
     ):
         # pdbp.set_trace()
-        log.pdb(f"\nAttaching pdb to actor: {actor.uid}\n")
+        # TODO: maybe print the actor supervion tree up to the
+        # root here? Bo
+        log.pdb(
+            f'{_pause_msg}\n'
+            '|\n'
+            f'|_ {actor.uid}\n'
+        )
         # no f!#$&* idea, but when we're in async land
         # we need 2x frames up?
         frame = frame.f_back
@@ -911,6 +921,11 @@ async def breakpoint(**kwargs):
     await pause(**kwargs)
 
 
+_crash_msg: str = (
+    'Attaching to pdb REPL in crashed actor'
+)
+
+
 def _post_mortem(
     actor: tractor.Actor,
     pdb: MultiActorPdb,
@@ -921,15 +936,23 @@ def _post_mortem(
     debugger instance.
 
     '''
-    log.pdb(f"\nAttaching to pdb in crashed actor: {actor.uid}\n")
+    # TODO: print the actor supervion tree up to the root
+    # here! Bo
+    log.pdb(
+        f'{_crash_msg}\n'
+        '|\n'
+        f'|_ {actor.uid}\n'
+    )
 
-    # TODO: you need ``pdbpp`` master (at least this commit
-    # https://github.com/pdbpp/pdbpp/commit/b757794857f98d53e3ebbe70879663d7d843a6c2)
-    # to fix this and avoid the hang it causes. See issue:
-    # https://github.com/pdbpp/pdbpp/issues/480
-    # TODO: help with a 3.10+ major release if/when it arrives.
-
-    pdbp.xpm(Pdb=lambda: pdb)
+    # TODO: only replacing this to add the
+    # `end=''` to the print XD
+    # pdbp.xpm(Pdb=lambda: pdb)
+    info = sys.exc_info()
+    print(traceback.format_exc(), end='')
+    pdbp.post_mortem(
+        t=info[2],
+        Pdb=lambda: pdb,
+    )
 
 
 post_mortem = partial(
@@ -1001,13 +1024,13 @@ async def maybe_wait_for_debugger(
 
     header_msg: str = '',
 
-) -> None:
+) -> bool:  # was locked and we polled?
 
     if (
         not debug_mode()
         and not child_in_debug
     ):
-        return
+        return False
 
 
     msg: str = header_msg
@@ -1025,8 +1048,7 @@ async def maybe_wait_for_debugger(
 
         if sub_in_debug := Lock.global_actor_in_debug:
             msg += (
-                'Debug `Lock` in use by subactor\n'
-                f'|_{sub_in_debug}\n'
+                f'Debug `Lock` in use by subactor: {sub_in_debug}\n'
             )
             # TODO: could this make things more deterministic?
             # wait to see if a sub-actor task will be
@@ -1035,12 +1057,12 @@ async def maybe_wait_for_debugger(
             # XXX => but it doesn't seem to work..
             # await trio.testing.wait_all_tasks_blocked(cushion=0)
         else:
-            log.pdb(
+            log.debug(
                 msg
                 +
                 'Root immediately acquired debug TTY LOCK'
             )
-            return
+            return False
 
         for istep in range(poll_steps):
 
@@ -1090,12 +1112,13 @@ async def maybe_wait_for_debugger(
                     continue
 
         # fallthrough on failure to acquire..
-        else:
-            raise RuntimeError(
-                msg
-                +
-                'Root actor failed to acquire debug lock?'
-            )
+        # else:
+        #     raise RuntimeError(
+        #         msg
+        #         +
+        #         'Root actor failed to acquire debug lock?'
+        #     )
+        return True
 
     # else:
     #     # TODO: non-root call for #320?
@@ -1104,6 +1127,7 @@ async def maybe_wait_for_debugger(
     #         subactor_uid=this_uid,
     #     ):
     #         pass
+    return False
 
 # TODO: better naming and what additionals?
 # - [ ] optional runtime plugging?

tractor/devx/cli.py

@@ -23,10 +23,6 @@ Currently popular frameworks supported are:
 
 """
 from __future__ import annotations
-from contextlib import (
-    # asynccontextmanager as acm,
-    contextmanager as cm,
-)
 from typing import (
     Any,
     Callable,
@@ -36,9 +32,6 @@ from typing_extensions import Annotated
 import typer
 
 
-from ._debug import open_crash_handler
-
-
 _runtime_vars: dict[str, Any] = {}