Compare commits

..

4 Commits

Author SHA1 Message Date
Tyler Goodlet 369fca6cc1 Use new `pkg_name` in log-sys test suites 2025-09-05 15:08:09 -04:00
Tyler Goodlet 3af55d9d64 Implicitly name sub-logs by caller's mod
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`.
2025-09-05 15:08:09 -04:00
Tyler Goodlet 093ad02beb Add an implicit-pkg-path-as-logger-name test
A bit of test driven dev to anticipate support  of `.log.get_logger()`
usage such that it can be called from arbitrary sub-modules, themselves
embedded in arbitrary sub-pkgs, of some project; the when not provided,
the `sub_name` passed to the `Logger.getChild(<sub_name>)` will be set
as the sub-pkg path "down to" the calling module.

IOW if you call something like,

`log = tractor.log.get_logger(pkg_name='mypylib')`

from some `submod.py` in a project-dir that looks like,

mypylib/
  mod.py
  subpkg/
    submod.py  <- calling module

the `log: StackLevelAdapter` child-`Logger` instance will have a
`.name: str = 'mypylib.subpkg'`, discluding the `submod` part since this
already rendered as the `{filename}` header in `log.LOG_FORMAT`.

Previously similar behaviour would be obtained by passing
`get_logger(name=__name__)` in the calling module and so much so it
motivated me to make this the default, presuming we can introspect for
the info.

Impl deats,
- duplicated a `load_module_from_path()` from `modden` to load the
  `testdir` rendered py project dir from its path.
 |_should prolly factor it down to this lib anyway bc we're going to
   need it for hot code reload? (well that and `watchfiles` Bp)
- in each of `mod.py` and `submod.py` render the `get_logger()` code
  sin `name`, expecting the (coming shortly) implicit introspection
  feat to do this.
- do `.name` and `.parent` checks against expected sub-logger values
  from `StackLevelAdapter.logger.getChildren()`.
2025-09-05 15:08:09 -04:00
Tyler Goodlet b4bacbc766 Start a logging-sys unit-test module
To start ensuring that when `name=__name__` is passed we try to
de-duplicate the `_root_name` and any `leaf_mod: str` since it's already
included in the headers as `{filename}`.

Deats,
- heavily document the de-duplication `str.partition()`s in
  `.log.get_logger()` and provide the end fix by changing the predicate,
  `if rname == 'tractor':` -> `if rname == _root_name`.
  * also toss in some warnings for when we still detect duplicates.
- add todo comments around logging "filters" (vs. our "adapter").
- create the new `test_log_sys.test_root_pkg_not_duplicated()` which
  runs green with the fixes from ^.
- add a ton of test-suite todos both for existing and anticipated
  logging sys feats in the new mod.
2025-09-05 15:08:09 -04:00
5 changed files with 18 additions and 247 deletions

View File

@ -1,85 +0,0 @@
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',
))

View File

@ -9,10 +9,8 @@ import tractor
import trio import trio
log = tractor.log.get_logger( log = tractor.log.get_logger(__name__)
name=__name__ tractor.log.get_console_log('info')
)
@cm @cm
def teardown_on_exc( def teardown_on_exc(
@ -56,7 +54,6 @@ def teardown_on_exc(
async def finite_stream_to_rent( async def finite_stream_to_rent(
tx: trio.abc.SendChannel, tx: trio.abc.SendChannel,
child_errors_mid_stream: bool, child_errors_mid_stream: bool,
raise_unmasked: bool,
task_status: trio.TaskStatus[ task_status: trio.TaskStatus[
trio.CancelScope, trio.CancelScope,
@ -71,41 +68,20 @@ async def finite_stream_to_rent(
# inside the child task! # inside the child task!
# #
# TODO, uncomment next LoC to see the supprsessed beg[RTE]! # 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! 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\ # pass our scope back to parent for supervision\
# control. # control.
cs: trio.CancelScope|None = ( task_status.started(_tn.cancel_scope)
None
if _tn is True
else _tn.cancel_scope
)
task_status.started(cs)
with teardown_on_exc( with teardown_on_exc(
raise_from_handler=not child_errors_mid_stream, raise_from_handler=not child_errors_mid_stream,
): ):
for i in range(100): for i in range(100):
log.debug( log.info(
f'Child tx {i!r}\n' f'Child tx {i!r}\n'
) )
if ( if (
@ -131,31 +107,23 @@ async def main(
# bug and raises. # bug and raises.
# #
child_errors_mid_stream: bool, 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) tx, rx = trio.open_memory_channel(1)
async with ( async with (
tractor.trionics.collapse_eg(),
trio.open_nursery() as tn, trio.open_nursery() as tn,
rx as rx, rx as rx,
): ):
_child_cs = await tn.start( _child_cs = await tn.start(
partial( partial(
finite_stream_to_rent, finite_stream_to_rent,
child_errors_mid_stream=child_errors_mid_stream, child_errors_mid_stream=child_errors_mid_stream,
raise_unmasked=raise_unmasked,
tx=tx, tx=tx,
) )
) )
async for msg in rx: async for msg in rx:
log.debug( log.info(
f'Rent rx {msg!r}\n' f'Rent rx {msg!r}\n'
) )
@ -171,25 +139,7 @@ async def main(
tn.cancel_scope.cancel() tn.cancel_scope.cancel()
# XXX, manual test as script
if __name__ == '__main__': if __name__ == '__main__':
tractor.log.get_console_log(level='info')
for case in [True, False]: for case in [True, False]:
log.info( trio.run(main, case)
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()

View File

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

View File

@ -6,18 +6,11 @@ want to see changed.
from contextlib import ( from contextlib import (
asynccontextmanager as acm, asynccontextmanager as acm,
) )
from types import ModuleType
from functools import partial
import pytest import pytest
from _pytest import pathlib
from tractor.trionics import collapse_eg from tractor.trionics import collapse_eg
import trio import trio
from trio import TaskStatus from trio import TaskStatus
from tractor._testing import (
examples_dir,
)
@pytest.mark.parametrize( @pytest.mark.parametrize(
@ -113,9 +106,8 @@ def test_acm_embedded_nursery_propagates_enter_err(
debug_mode: bool, debug_mode: bool,
): ):
''' '''
Demo how a masking `trio.Cancelled` could be handled by unmasking Demo how a masking `trio.Cancelled` could be handled by unmasking from the
from the `.__context__` field when a user (by accident) re-raises `.__context__` field when a user (by accident) re-raises from a `finally:`.
from a `finally:`.
''' '''
import tractor import tractor
@ -166,13 +158,13 @@ def test_acm_embedded_nursery_propagates_enter_err(
assert len(assert_eg.exceptions) == 1 assert len(assert_eg.exceptions) == 1
def test_gatherctxs_with_memchan_breaks_multicancelled( def test_gatherctxs_with_memchan_breaks_multicancelled(
debug_mode: bool, debug_mode: bool,
): ):
''' '''
Demo how a using an `async with sndchan` inside Demo how a using an `async with sndchan` inside a `.trionics.gather_contexts()` task
a `.trionics.gather_contexts()` task will break a strict-eg-tn's will break a strict-eg-tn's multi-cancelled absorption..
multi-cancelled absorption..
''' '''
from tractor import ( from tractor import (
@ -198,6 +190,7 @@ def test_gatherctxs_with_memchan_breaks_multicancelled(
f'Closed {task!r}\n' f'Closed {task!r}\n'
) )
async def main(): async def main():
async with ( async with (
# XXX should ensure ONLY the KBI # XXX should ensure ONLY the KBI
@ -218,85 +211,3 @@ def test_gatherctxs_with_memchan_breaks_multicancelled(
with pytest.raises(KeyboardInterrupt): with pytest.raises(KeyboardInterrupt):
trio.run(main) 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)

View File

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