feat(logging): replace print statements with the logging module

README.md

@@ -39,6 +39,13 @@ More runnable scripts live in [examples/](examples/), and the
 [Basics tutorial](docs/tutorials/basics.ipynb) walks through the
 OpenSemanticLab data model.
 
+## Logging
+
+osw reports what it is doing on the `osw` logger at INFO by default. Levels,
+the `OSW_LOG_LEVEL` environment variable and how to collect the records in your
+own logging setup are described in the
+[Get Started guide](https://opensemanticlab.github.io/osw-python/get-started/#logging).
+
 ## Contributing
 
 Contributions are welcome, see [CONTRIBUTING.md](CONTRIBUTING.md).

docs/get-started.md

@@ -64,6 +64,69 @@ Credentials are resolved from the environment variables `OSW_USERNAME` /
 credentials file, or via an interactive prompt - and are held in memory
 only, never written to disk; see [Authentication](api/auth.md).
 
+## Logging
+
+osw reports what it is doing through the standard `logging` module, on the
+`osw` logger, at INFO by default:
+
+```python
+import osw
+
+osw.set_log_level("WARNING")  # see less
+osw.set_log_level("DEBUG")    # see more
+osw.disable_logging()         # detach the handler osw attached
+```
+
+Problems that osw can work around are WARNING records on the same logger, not
+Python `warnings`. A truncated query result and a page that does not exist are
+examples. A `warnings` filter or the `-W` option therefore has no effect on
+them. A message that repeats is also written out every time, where the warnings
+machinery would have shown it once. Use `set_log_level` to control them.
+
+The records go to `stderr`, which leaves `stdout` free for your program's own
+output. That matters for anything speaking a protocol over `stdout`, such as an
+MCP stdio server. Pass `osw.enable_logging(stream=...)` to send them elsewhere.
+
+Set `OSW_LOG_LEVEL` to a level name, a level number, or `OFF` to choose the
+level before the package is imported. `OFF` silences osw everywhere, including
+in your own handlers.
+
+### Collecting osw's records in your application
+
+Configure logging the way you normally would and osw's records arrive there,
+once:
+
+```python
+import logging
+import osw
+
+logging.basicConfig(level=logging.INFO, filename="app.log")
+```
+
+The `osw` logger propagates at all times, so the records reach your handlers
+whatever else happens. osw's own handler notices that something above it is
+listening, detaches itself so nothing is written twice, and gives back the
+level it had picked, so your level applies from then on. It makes no difference
+whether you configure logging before or after importing osw.
+
+A level you asked for is kept across that hand-over, so `set_log_level("DEBUG")`
+or `OSW_LOG_LEVEL=DEBUG` is how you pull osw's debug records into an aggregated
+setup while the rest of your application stays quieter.
+
+One case osw cannot detect is a handler added to the `osw` logger itself, since
+that is indistinguishable from one of its own. Call `disable_logging()` first if
+you do that.
+
+### Output from parallel batches
+
+Several osw calls process their input in parallel. What such a task prints, as
+opposed to logs, is collected while the batch runs and replayed afterwards, so
+that concurrent writing cannot garble the progress bar. That text arrives on the
+`osw.parallel.output` logger, one record per line, at INFO. Give that logger its
+own level or handler to keep the output of third-party code apart from osw's own
+records. Most osw calls replay it only when you pass `debug=True`; `copy_pages`
+always replays.
+
 ## Examples and tutorials
 
 - Runnable scripts in

src/osw/__init__.py

@@ -1,3 +1,6 @@
+import logging
+import os
+import sys
 from importlib.metadata import PackageNotFoundError, version  # pragma: no cover
 
 try:
@@ -8,3 +11,209 @@
     __version__ = "unknown"
 finally:
     del version, PackageNotFoundError
+
+LOG_LEVEL_ENV_VAR = "OSW_LOG_LEVEL"
+"""Name of the environment variable read for the initial log level. Accepts a
+level name, a level number, or 'OFF' to start silent."""
+DEFAULT_LOG_LEVEL = logging.INFO
+"""Level the osw logger starts at when the environment variable is unset"""
+LOG_FORMAT = "[%(levelname)s] %(name)s: %(message)s"
+OFF = logging.CRITICAL + 1
+"""Level above every real record, so setting it silences the logger"""
+
+_DEFAULT_HANDLER_NAME = "osw-default"
+_logger = logging.getLogger(__name__)
+_level_is_ours = False
+"""Whether the level on the osw logger is the one osw picked for itself. A
+level the calling code asked for is left alone when osw hands over."""
+
+
+def _parse_level(value: str) -> int:
+    """Turns the environment variable into a level, tolerating junk
+
+    Parameters
+    ----------
+    value
+        a level name such as 'DEBUG', a level number such as '10', or 'OFF'
+
+    Returns
+    -------
+        the level, or DEFAULT_LOG_LEVEL if the value names none
+    """
+    cleaned = value.strip().upper()
+    if cleaned in ("OFF", "NONE", "SILENT"):
+        return OFF
+    if cleaned.isdigit():
+        return int(cleaned)
+    # getLevelName maps an unknown name to the string 'Level %s', not to a number
+    level = logging.getLevelName(cleaned)
+    if isinstance(level, int):
+        return level
+    return DEFAULT_LOG_LEVEL
+
+
+def _application_handles_records() -> bool:
+    """Whether the calling code already has somewhere for osw's records to go
+
+    Walks what logging.Logger.callHandlers walks above the osw logger. Any
+    handler found up there belongs to the calling application, so osw writing
+    its own copy would only duplicate what that handler already reports.
+    """
+    if not _logger.propagate:
+        # something is deliberately holding the records at the osw logger,
+        # parallelize while it captures a batch among them
+        return False
+    current = _logger.parent
+    while current:
+        if current.handlers:
+            return True
+        if not current.propagate:
+            return False
+        current = current.parent
+    return False
+
+
+class _DefaultHandler(logging.StreamHandler):
+    """The handler osw attaches while nothing else is listening
+
+    Steps aside the first time it finds that the calling application has
+    configured logging of its own. The check belongs here rather than at import
+    time because a script normally imports osw before it calls basicConfig().
+    """
+
+    def emit(self, record: logging.LogRecord):
+        if _application_handles_records():
+            _hand_over()
+            return
+        super().emit(record)
+
+
+def _detach():
+    """Removes the handler osw attached, leaving any other one in place
+
+    Rebinds the list instead of calling removeHandler, because this also runs
+    from inside the handler's own emit, where callHandlers is iterating that
+    very list.
+    """
+    detached = [h for h in _logger.handlers if h.get_name() == _DEFAULT_HANDLER_NAME]
+    _logger.handlers = [h for h in _logger.handlers if h not in detached]
+    for handler in detached:
+        handler.close()
+
+
+def _hand_over():
+    """Gives the application's own logging setup sole charge of osw's records
+
+    Drops osw's handler so nothing is written twice, and drops the level osw
+    picked so the application's level applies. A level the calling code asked
+    for, through set_log_level, enable_logging or the environment variable, is
+    kept, since that is how one asks for osw's DEBUG records in an aggregated
+    setup.
+    """
+    global _level_is_ours
+    _detach()
+    if _level_is_ours:
+        _logger.setLevel(logging.NOTSET)
+        _level_is_ours = False
+
+
+def enable_logging(level=None, stream=None) -> logging.Handler:
+    """Attaches osw's own handler to the osw logger
+
+    Called on import when nothing else handles the records, so osw reports what
+    it is doing without the calling code configuring anything. Call it again to
+    take the output back after disable_logging(), or to send it elsewhere.
+
+    The handler detaches itself as soon as the calling application configures
+    logging, so records are never written twice.
+
+    Parameters
+    ----------
+    level
+        a level name or number. Defaults to the environment variable, then to
+        DEFAULT_LOG_LEVEL.
+    stream
+        where to write. Defaults to sys.stderr, so stdout stays free for a
+        program's own output. Anything speaking a protocol over stdout, such as
+        an MCP stdio server, depends on that.
+
+    Returns
+    -------
+        the attached handler
+    """
+    global _level_is_ours
+    asked_for = level is not None or LOG_LEVEL_ENV_VAR in os.environ
+    if level is None:
+        level = _parse_level(os.environ.get(LOG_LEVEL_ENV_VAR, ""))
+    _detach()
+    handler = _DefaultHandler(sys.stderr if stream is None else stream)
+    handler.setFormatter(logging.Formatter(LOG_FORMAT))
+    handler.set_name(_DEFAULT_HANDLER_NAME)
+    _logger.addHandler(handler)
+    _logger.setLevel(level)
+    _level_is_ours = not asked_for
+    return handler
+
+
+def disable_logging():
+    """Hands the osw logger over to the calling application
+
+    Removes the handler osw attached and the level it picked, so the records
+    follow whatever the application configured, on the 'osw' logger or on the
+    root logger above it. A handler the calling code added to the 'osw' logger
+    is left in place.
+
+    Not needed in order to aggregate osw's records. They propagate to the root
+    logger at all times, and osw's own handler steps aside by itself once
+    anything else is listening. Call this to be explicit about it, or when a
+    handler was added to the 'osw' logger directly, which osw cannot tell apart
+    from one of its own callers.
+    """
+    global _level_is_ours
+    _detach()
+    _logger.setLevel(logging.NOTSET)
+    _level_is_ours = False
+
+
+def set_log_level(level):
+    """Sets how much osw reports
+
+    The level survives a hand-over to the application's own logging setup, so
+    this is also how to ask for osw's DEBUG records in an aggregated setup.
+
+    Parameters
+    ----------
+    level
+        a level name or number, e.g. 'DEBUG', 'WARNING', or logging.WARNING.
+        Pass osw.OFF to silence osw everywhere, its own handler and the
+        application's alike.
+    """
+    global _level_is_ours
+    _logger.setLevel(level)
+    _level_is_ours = False
+
+
+def _configure_on_import():
+    """Sets logging up the way an interpreter that configured none needs it"""
+    if _application_handles_records():
+        # logging was configured before osw was imported, so the records
+        # already have somewhere to go and only the level is osw's to set
+        if LOG_LEVEL_ENV_VAR in os.environ:
+            set_log_level(_parse_level(os.environ[LOG_LEVEL_ENV_VAR]))
+        return
+    enable_logging()
+    if LOG_LEVEL_ENV_VAR not in os.environ:
+        # once per interpreter, since this module is imported once. Sent
+        # through the logger itself, so it disappears with everything else as
+        # soon as the level is raised or the environment variable is set.
+        _logger.info(
+            "osw logs at %s on the 'osw' logger. Use osw.set_log_level"
+            "('WARNING') to see less, osw.disable_logging() to switch it off, "
+            "or set %s=OFF before import. Configuring logging yourself, e.g. "
+            "with logging.basicConfig(), takes the output over automatically.",
+            logging.getLevelName(_logger.level),
+            LOG_LEVEL_ENV_VAR,
+        )
+
+
+_configure_on_import()

src/osw/auth.py

@@ -1,6 +1,7 @@
 from __future__ import annotations
 
 import getpass
+import logging
 import os
 import warnings
 from enum import Enum
@@ -16,6 +17,8 @@
 
 from osw.defaults import paths as default_paths
 
+_logger = logging.getLogger(__name__)
+
 
 def _secret_to_str(v):
     """Unwrap SecretStr to plain str, pass through otherwise."""
@@ -131,7 +134,7 @@ def _load_file_credentials(self):
                     loaded = _load_credentials(fp, into_store=False)
                     all_creds.update(loaded)
                 except Exception as exc:
-                    print(exc)
+                    _logger.error(f"{exc}")
         return all_creds
 
     def get_credential(self, config: CredentialConfig) -> BaseCredential:
@@ -243,7 +246,7 @@ def iri_in_file(self, iri: str) -> bool:
                                     if iri_ == iri:
                                         return True
                             except yaml.YAMLError as exc:
-                                print(exc)
+                                _logger.error(f"{exc}")
         return False
 
     def save_credentials_to_file(
@@ -292,9 +295,9 @@ def save_credentials_to_file(
             with open(fp, "w", encoding="utf-8") as stream:
                 yaml.dump(data, stream)
             if file_already_exists:
-                print(f"Credentials file updated at '{fp.resolve()}'.")
+                _logger.info(f"Credentials file updated at '{fp.resolve()}'.")
             else:
-                print(f"Credentials file created at '{fp.resolve()}'.")
+                _logger.info(f"Credentials file created at '{fp.resolve()}'.")
 
 
 CredentialManager.CredentialConfig.update_forward_refs()

src/osw/controller/database.py

@@ -1,3 +1,4 @@
+import logging
 from typing import Optional, Union
 
 from opensemantic.v1 import OswBaseModel
@@ -9,6 +10,8 @@
 from osw.auth import CredentialManager
 from osw.core import OSW
 
+_logger = logging.getLogger(__name__)
+
 
 class DatabaseController(model.Database):
     """
@@ -130,4 +133,4 @@ def execute(self, sql: str):
         with self.engine.connect() as conn:
             result_set = conn.execute(sql_text(sql))
             for r in result_set:
-                print(r)
+                _logger.debug(f"{r}")

src/osw/controller/file/wiki.py

@@ -1,4 +1,5 @@
 import functools
+import logging
 import os
 from typing import IO, Any, Dict, List, Optional
 
@@ -8,6 +9,8 @@
 from osw.utils.wiki import get_namespace, get_title
 from osw.wtsite import WtSite
 
+_logger = logging.getLogger(__name__)
+
 
 class WikiFileController(model.WikiFile, RemoteFileController):
     """File controller for wiki files"""
@@ -70,10 +73,9 @@ def get(self) -> IO:
         if web_api_failed:
             # fallback: use direct download
             url = file.imageinfo["url"]
-            print(
-                "Extension FileApi not installed on the server. Fallback: use direct "
-                "download from ",
-                url,
+            _logger.warning(
+                f"Extension FileApi not installed on the server. Fallback: use "
+                f"direct download from {url}"
             )
             response = self.osw.mw_site.connection.get(url, stream=True)