From 88ab87746a580f477b3f3724c1a839855ceb951d Mon Sep 17 00:00:00 2001 From: Tyler Goodlet Date: Tue, 2 Sep 2025 21:02:37 -0400 Subject: [PATCH] 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. --- tests/test_log_sys.py | 62 ++++++++++++++++++++++++++++++++++++++ tractor/log.py | 70 +++++++++++++++++++++++++++++++++++-------- 2 files changed, 120 insertions(+), 12 deletions(-) create mode 100644 tests/test_log_sys.py diff --git a/tests/test_log_sys.py b/tests/test_log_sys.py new file mode 100644 index 00000000..7f47413b --- /dev/null +++ b/tests/test_log_sys.py @@ -0,0 +1,62 @@ +''' +`tractor.log`-wrapping unit tests. + +''' +import tractor + + +def test_root_pkg_not_duplicated(): + + project_name: str = 'pylib' + pkg_path: str = 'pylib.subpkg.mod' + + log = tractor.log.get_logger( + _root_name=project_name, + ) + + sublog = tractor.log.get_logger( + _root_name=project_name, + name=pkg_path, + ) + + assert log is not sublog + assert sublog.name.count(log.name) == 1 + assert 'mod' not in sublog.name + + +# TODO, moar tests against existing feats: +# ------ - ------ +# - [ ] color settings? +# - [ ] header contents like, +# - actor + thread + task names from various conc-primitives, +# - [ ] `StackLevelAdapter` extensions, +# - our custom levels/methods: `transport|runtime|cance|pdb|devx` +# - [ ] custom-headers support? +# + +# TODO, test driven dev of new-ideas/long-wanted feats, +# ------ - ------ +# - [ ] https://github.com/goodboy/tractor/issues/244 +# - [ ] @catern mentioned using a sync / deterministic sys +# and in particular `svlogd`? +# |_ https://smarden.org/runit/svlogd.8 + +# - [ ] using adapter vs. filters? +# - https://stackoverflow.com/questions/60691759/add-information-to-every-log-message-in-python-logging/61830838#61830838 + +# - [ ] `.at_least_level()` optimization which short circuits wtv +# `logging` is doing behind the scenes when the level filters +# the emission..? + +# - [ ] use of `.log.get_console_log()` in subactors and the +# subtleties of ensuring it actually emits from a subproc. + +# - [ ] this idea of activating per-subsys emissions with some +# kind of `.name` filter passed to the runtime or maybe configured +# via the root `StackLevelAdapter`? + +# - [ ] use of `logging.dict.dictConfig()` to simplify the impl +# of any of ^^ ?? +# - https://stackoverflow.com/questions/7507825/where-is-a-complete-example-of-logging-config-dictconfig +# - https://docs.python.org/3/library/logging.config.html#configuration-dictionary-schema +# - https://docs.python.org/3/library/logging.config.html#logging.config.dictConfig diff --git a/tractor/log.py b/tractor/log.py index 329562b1..d127ea71 100644 --- a/tractor/log.py +++ b/tractor/log.py @@ -97,10 +97,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, @@ -283,6 +290,9 @@ class ActorContextInfo(Mapping): def get_logger( + # ?TODO, could we just grab the caller's `mod.__name__`? + # -[ ] do it with `inspect` says SO, + # |_https://stackoverflow.com/a/1095621 name: str|None = None, _root_name: str = _proj_name, @@ -304,9 +314,10 @@ def get_logger( log = rlog = logger or logging.getLogger(_root_name) if ( - name - and name != _proj_name + and + name + # ^TODO? see caller_mod.__name__ as default above? ): # NOTE: for handling for modules that use `get_logger(__name__)` @@ -319,18 +330,53 @@ def get_logger( # module-file. sub_name: None|str = None + + # ex. modden.runtime.progman + # -> rname='modden', _, sub_name='runtime.progman' rname, _, sub_name = name.partition('.') - pkgpath, _, modfilename = sub_name.rpartition('.') - # 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 + # -> pkgpath='runtime', _, leaf_mod='progman' + subpkg_path, _, leaf_mod = sub_name.rpartition('.') + # NOTE: special usage for passing `name=__name__`, + # + # - remove duplication of any root-pkg-name in the + # (sub/child-)logger name; i.e. never include the + # `_root_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 == _root_name: + sub_name = 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 _root_name in sub_name: - duplicate, _, sub_name = sub_name.partition('.') + _duplicate, _, sub_name = sub_name.partition('.') + if _duplicate: + assert _duplicate == rname + log.warning( + f'Duplicate pkg-name in sub-logger key?\n' + f'_root_name = {_root_name!r}\n' + f'sub_name = {sub_name!r}\n' + ) + + if leaf_mod in sub_name: + # XXX, for debuggin.. + # import pdbp; pdbp.set_trace() + log.warning( + f'Duplicate leaf-module-name in sub-logger key?\n' + f'leaf_mod = {leaf_mod!r}\n' + f'sub_name = {sub_name!r}\n' + ) if not sub_name: log = rlog