Skip to content

feat(logging): replace print statements with the logging module - #160

Open
LukasGold wants to merge 14 commits into
mainfrom
feat/logging
Open

feat(logging): replace print statements with the logging module#160
LukasGold wants to merge 14 commits into
mainfrom
feat/logging

Conversation

@LukasGold

@LukasGold LukasGold commented Sep 2, 2026

Copy link
Copy Markdown
Contributor

Closes #130.

Scope and decisions were agreed in #130 (comment).

Changes

  • src/osw/__init__.py: the osw logger gets a StreamHandler at INFO on sys.stdout, plus set_log_level(), disable_logging(), enable_logging() and the OSW_LOG_LEVEL environment variable, which takes a level name, a level number, or OFF.
  • That handler stands down as soon as the calling application configures logging of its own, so osw's records stay aggregatable. See "Handing over to the application" below.
  • A one-time notice on import states the level and how to change it: osw logs at INFO on the 'osw' logger. Use osw.set_log_level('WARNING') to see less, osw.disable_logging() to switch it off, or set OSW_LOG_LEVEL=OFF before import. Configuring logging yourself, e.g. with logging.basicConfig(), takes the output over automatically.
  • 113 of the 123 print() calls in src/osw become _logger calls on a per-module logger: 18 error, 12 warning, 23 info, 60 debug. Levels were chosen per call site from the message content.
  • src/osw/utils/util.py: ThreadRoutedLogHandler, the log counterpart of the ThreadRoutedStdout added in fix(util): honour flush_at_end and progress_bar in parallelize #154. parallelize buffers each worker thread's LogRecords and replays them in the order of iterable when flush_at_end is set.
  • 22 messages lose a leading Error: , Warning: or Info: label, which the formatter now emits as the level.
  • src/osw/utils/workflow.py gets a module-level logger, replacing the import logging calls that sat inside function bodies at lines 195 and 654.
  • tests/test_logging_setup.py: 29 offline tests.
  • README documents the new controls and the hand-over.

Rationale

Only two modules used logging before, and neither consistently: core.py had a proper _logger used for five error calls while the same file still had 29 prints.

Logging is on by default because a library that goes silent would break every existing notebook and script at once.

Handing over to the application

The osw logger propagates at all times. osw never sets propagate = False, so its records always reach whatever handlers the calling application configured, on the osw logger or on the root logger above it. Aggregating osw into an application's logging therefore needs no osw-specific call, and works the same whether logging is configured before or after import osw.

Not writing the messages twice is the handler's job rather than propagation's:

  • _DefaultHandler.emit first asks whether any handler exists above the osw logger. If one does, it detaches itself and writes nothing, so the application's handler is the only one reporting.
  • The check runs at emit rather than at import, because a script normally imports osw before it calls logging.basicConfig().
  • The hand-over also resets the level osw picked back to NOTSET, so the application's level governs from then on. Without that, basicConfig(level=WARNING) would still see osw's INFO records, since ancestor logger levels are not consulted once a record exists.
  • A level the caller asked for, through set_log_level(), enable_logging(level=...) or OSW_LOG_LEVEL, is kept across the hand-over. That is how one pulls osw's DEBUG records into an aggregated setup while the rest of the application stays quieter.
  • When logging was already configured at import time, osw attaches nothing at all.

disable_logging() remains the explicit form of the same thing, and is needed for the one case osw cannot detect: a handler added to the osw logger itself, which is indistinguishable from one of osw's own.

Interaction with #154

#154 had just rebuilt output capture in parallelize around replacing sys.stdout, which works because print() resolves sys.stdout at call time. Converting the workers to logging would have bypassed it and silently undone that fix, since a StreamHandler writes to a stream captured at construction and defaults to stderr.

The routing is installed as a handler on the osw logger rather than a filter. A logger's filters run only for records logged on that logger itself, so a filter on osw would never see records from osw.wtsite and the other child loggers, which is exactly the traffic that needs capturing. handler_chain() walks to the root, so a batch's records are replayed into the application's handlers like any other.

parallelize does set propagate = False for the duration of a batch, which is what stops buffered records escaping to the root logger before the replay, and restores it in a finally.

The stdout router stays in place, so an external caller passing its own printing function to parallelize keeps working.

Kept as prints

10 of the 123, deliberately:

  • 8 in src/osw/utils/util.py: the replay machinery itself, in MessageBuffer.flush, redirect_print, redirect_print_explicitly and the flush_at_end replay. These write captured output to a caller-supplied file or buffer, they are not status messages.
  • src/osw/auth.py: the "No credentials found, please use the prompt to login" message, which directly precedes the input() and getpass() calls it refers to.
  • src/osw/controller/entity.py: Entity.explain(), a user-facing method whose whole purpose is to print.

The 22 prints in the if __name__ == "__main__": demo block of util.py and the 47 commented-out ones are untouched.

Behaviour change

Output now carries a level and a module name, [INFO] osw.wtsite: ... instead of bare text, and goes through the osw logger, so it can be filtered, redirected or switched off. Anything previously printed at a debug-ish verbosity is now at DEBUG and therefore hidden at the default level. Callers that need the old volume can call osw.set_log_level("DEBUG").

Verification

Offline suite passes: 147 passed, 1 skipped, up from 118 passed, 1 skipped. ruff check and ruff format --check are clean over src and tests.

The hand-over was additionally checked in real interpreters rather than only under pytest, which holds handlers on the root logger throughout and so masks the default path. Seven cases, each producing exactly one copy of every message and losing none: plain import, basicConfig() after import, basicConfig() before import, an application asking for WARNING while osw defaults to INFO, OSW_LOG_LEVEL=DEBUG against an application at WARNING, OSW_LOG_LEVEL=OFF, and set_log_level("DEBUG") against an application at WARNING.

Notes

  • Two calls in src/osw/ontology.py passed a tuple as the message because of a stray pair of parentheses, so they logged ('remove value with unsupported language: ', 'de'). Since stripping their redundant prefix touched those exact lines, the tuple was collapsed into a single string, matching the correct sibling call a few lines below.
  • src/osw/wtsite.py get_page_ has one call site whose message is either "Page loaded." or a retry failure. It is logged at INFO, since the level applies per call site and the failure is also recorded in exceptions and re-raised when appropriate.
  • Unrelated, but it keeps tripping the large-file pre-commit hook: graphify-out/ is not in .gitignore, so a 1.6 MB generated graph.json is offered on every git add -A.
  • This touches 15 modules and will conflict with most of the open PR queue, so it is held until the rest has landed, then rebased onto main.

- osw logs at INFO by default, with a one-time notice on import
- set_log_level, disable_logging, enable_logging and OSW_LOG_LEVEL
- ThreadRoutedLogHandler, the log counterpart of ThreadRoutedStdout
- parallelize buffers worker records and replays them in input order
- 113 of 123 print calls become _logger calls on a per-module logger
- levels chosen per call site: 18 error, 12 warning, 23 info, 60 debug
- kept: the output-replay machinery in util.py, the auth login prompt
  and Entity.explain, which are interactive or are the replay itself
- workflow.py gets a module-level logger, replacing function-local ones
- README documents set_log_level, disable_logging and OSW_LOG_LEVEL
- 22 messages lose a leading 'Error: ', 'Warning: ' or 'Info: ' that the
  formatter now emits as the level
- ontology.py: two calls passed a tuple as the message, a stray pair of
  parens that logged "('remove value...', 'de')"; collapsed to one string
- left where the level word is sentence text, e.g. 'Error creating entity'
- 23 offline tests over enable/disable, level parsing and OSW_LOG_LEVEL
- handler_chain walking past a non-propagating logger
- worker records buffered, replayed in input order, dropped without
  flush_at_end, and the logger restored even when the batch raises
@LukasGold LukasGold self-assigned this Sep 2, 2026
@LukasGold

Copy link
Copy Markdown
Contributor Author

(As of 2026-09-02) This PR is designed to land after other open PRs are merged and might need a rework before that

- osw never sets propagate=False, so its records always reach the
  handlers the calling application configured
- the default handler detaches itself once anything above the osw
  logger is listening, so nothing is written twice
- the hand-over gives back the level osw picked, keeping one the
  caller asked for via set_log_level or OSW_LOG_LEVEL
- osw attaches nothing when logging was configured before the import
@LukasGold LukasGold added the enhancement New feature or request label Sep 2, 2026
- keep both imports in wiki_tools: logging and warnings
- semantic_search debug output logs at DEBUG, over main's prints,
  while keeping main's result count n and the truncation warning
@github-actions

github-actions Bot commented Sep 2, 2026

Copy link
Copy Markdown
Contributor

Release preview

Merging this PR would release v2.4.0 (current: v2.3.2).

Changelog preview (truncated)
## v2.4.0 (2026-09-07)

### Bug Fixes

- **logging**: Restore two changes lost in the merge resolution
  ([`b097b10`](https://github.com/OpenSemanticLab/osw-python/commit/b097b1030aaa1ad8fc9a1fee9a4b559cd06e7780))

- **util**: Replay worker warnings from a quiet parallel batch
  ([`48b9537`](https://github.com/OpenSemanticLab/osw-python/commit/48b95372627a3bd288d6c3cfbdb8ea8c0749375f))

### Features

- **logging**: Report library warnings as log records
  ([`8d24914`](https://github.com/OpenSemanticLab/osw-python/commit/8d2491462cd5f99de5163f312c76bbb18bb485fe))

Preview via python-semantic-release and conventional commits.

@LukasGold

Copy link
Copy Markdown
Contributor Author

enable_logging() in src/osw/__init__.py defaults to sys.stdout. That
conflicts with the MCP stdio server added in
#133. Full details and a
standalone reproduction are in
#170.

The short version:

  • The MCP server serves JSON-RPC over stdout. Its guard redirects sys.stdout
    to stderr around each osw call
    (src/osw/service/context.py:113-125, enabled at src/osw/mcp/server.py:134).
  • A logging.StreamHandler stores its stream at construction time, so
    redirect_stdout does not affect it. Records emitted during a tool call reach
    the real stdout, past the guard.

Two ways to resolve it:

  1. Keep the stdout default. The MCP server then calls
    osw.enable_logging(stream=sys.stderr) in main(). This PR stays unchanged.
  2. Change the enable_logging() default to sys.stderr. This removes the
    conflict for every stdio consumer, not only this one, and matches the usual
    convention for library diagnostics. It does move existing output for anyone
    who reads osw progress messages from stdout, which is what the current
    docstring gives as the reason for choosing stdout.

I lean towards option 2, because it fixes the class of problem rather than one
instance, and because the compatibility argument for stdout is weaker once the
output is a log record with a level and a logger name rather than a bare print.
Option 1 is fine too and is the smaller change. Only option 2 has to be decided
in this PR.

Whichever of #133 and #160 merges second should carry the fix, plus a test
asserting that an MCP tool call writes nothing to stdout.

Comment thread README.md
[Basics tutorial](docs/tutorials/basics.ipynb) walks through the
OpenSemanticLab data model.

## Logging

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

would make more sense to move this description into the docs in order to keep github landing page of repo clean.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Moved in 4b341f2. The description now lives in docs/get-started.md under a ## Logging section, between "First steps" and "Examples and tutorials".

The README keeps a two-line pointer to it, matching how the Installation section links to the same guide for the optional extras. Say if you would rather have the section gone from the README entirely.

@raederan raederan left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great to change this to logging also for usage in containerized setups :)
I suggest just to keep README.md as clean as possible and move the description for logging usage feature into docs.

- stdout is the JSON-RPC channel of an MCP stdio server
- redirect_stdout does not reach a StreamHandler bound at construction
- refs #170
@LukasGold

Copy link
Copy Markdown
Contributor Author

Resolved as option 2 in 329bff4: enable_logging() now defaults to
sys.stderr. Correcting one badly built sentence in my comment above, and
adding evidence I had not checked when I wrote it.

What the sentence should have said. The docstring argues for stdout, and
its reason is backward compatibility: osw used print() before this PR, and
print() writes to stdout. Option 2 breaks exactly that compatibility. Someone
running python script.py > out.txt captures stdout but not stderr, so osw
messages stop appearing in out.txt.

Why that argument is weaker than it looks.

  • The only place in osw that captures stdout is parallelize in
    src/osw/utils/util.py. This PR already added ThreadRoutedLogHandler
    (src/osw/utils/util.py:315) as the counterpart of ThreadRoutedStdout for
    the modules that log rather than print. It collects records through
    handler_chain(osw_logger), not through the stream, so it does not depend on
    the handler writing to stdout.
  • The compatibility is partial in any case. The output format changed from a
    bare printed line to [INFO] osw.core: message, so anything that parsed
    those lines is affected whichever stream they arrive on.

What changed

  • src/osw/__init__.py: the stream default is sys.stderr, and the docstring
    gives the reason.
  • tests/test_logging_setup.py: test_the_default_handler_writes_to_stderr
    asserts it, so the default cannot revert unnoticed.

The full offline suite passes (166 passed, 1 skipped).

This also closes #170 from
the library side. #133 needs
no change: with the default on stderr, the MCP server no longer has to call
enable_logging(stream=sys.stderr) itself.

- semantic_search: test the query limit again, not SearchParam.limit
- modify_search_results: restore the modify_single_result definition
- wtsite: log the slot content via pformat instead of printing it
- refs #130
- parallelize discarded every buffered record when flush_at_end was off
- records at WARNING and above are now replayed either way
- printed output and records below WARNING still obey flush_at_end
- also recovers the _logger.error calls in OSW.delete_entity's workers
- 17 warnings.warn calls across 6 modules become _logger.warning
- auth.py keeps its DeprecationWarning, the one correct use left
- page_package.py gains the module logger it lacked
- tests assert on caplog instead of pytest.warns
- get-started.md notes that a warnings filter no longer applies
- what a task printed now arrives as INFO records on a dedicated
  osw.parallel.output logger, one record per line
- keeps the library off the process's real stdout, which an MCP stdio
  server needs clear for its JSON-RPC channel
- BEHAVIOUR CHANGE: a direct parallelize caller who read a task's
  printed output from captured stdout now gets nothing there
- the ordering guarantee is unchanged: items follow the iterable
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

enhancement New feature or request

Projects

None yet

Development

Successfully merging this pull request may close these issues.

replace all print statements with proper logging

2 participants