Skip to content

Commit 1b23b0f

Browse files
authored
feat(logging): replace print statements with the logging module
Merge pull request #160 from OpenSemanticLab/feat/logging
2 parents f361065 + a10790e commit 1b23b0f

24 files changed

Lines changed: 1166 additions & 293 deletions

‎README.md‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,13 @@ More runnable scripts live in [examples/](examples/), and the
3939
[Basics tutorial](docs/tutorials/basics.ipynb) walks through the
4040
OpenSemanticLab data model.
4141

42+
## Logging
43+
44+
osw reports what it is doing on the `osw` logger at INFO by default. Levels,
45+
the `OSW_LOG_LEVEL` environment variable and how to collect the records in your
46+
own logging setup are described in the
47+
[Get Started guide](https://opensemanticlab.github.io/osw-python/get-started/#logging).
48+
4249
## Contributing
4350

4451
Contributions are welcome, see [CONTRIBUTING.md](CONTRIBUTING.md).

‎docs/get-started.md‎

Lines changed: 63 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -64,6 +64,69 @@ Credentials are resolved from the environment variables `OSW_USERNAME` /
6464
credentials file, or via an interactive prompt - and are held in memory
6565
only, never written to disk; see [Authentication](api/auth.md).
6666

67+
## Logging
68+
69+
osw reports what it is doing through the standard `logging` module, on the
70+
`osw` logger, at INFO by default:
71+
72+
```python
73+
import osw
74+
75+
osw.set_log_level("WARNING") # see less
76+
osw.set_log_level("DEBUG") # see more
77+
osw.disable_logging() # detach the handler osw attached
78+
```
79+
80+
Problems that osw can work around are WARNING records on the same logger, not
81+
Python `warnings`. A truncated query result and a page that does not exist are
82+
examples. A `warnings` filter or the `-W` option therefore has no effect on
83+
them. A message that repeats is also written out every time, where the warnings
84+
machinery would have shown it once. Use `set_log_level` to control them.
85+
86+
The records go to `stderr`, which leaves `stdout` free for your program's own
87+
output. That matters for anything speaking a protocol over `stdout`, such as an
88+
MCP stdio server. Pass `osw.enable_logging(stream=...)` to send them elsewhere.
89+
90+
Set `OSW_LOG_LEVEL` to a level name, a level number, or `OFF` to choose the
91+
level before the package is imported. `OFF` silences osw everywhere, including
92+
in your own handlers.
93+
94+
### Collecting osw's records in your application
95+
96+
Configure logging the way you normally would and osw's records arrive there,
97+
once:
98+
99+
```python
100+
import logging
101+
import osw
102+
103+
logging.basicConfig(level=logging.INFO, filename="app.log")
104+
```
105+
106+
The `osw` logger propagates at all times, so the records reach your handlers
107+
whatever else happens. osw's own handler notices that something above it is
108+
listening, detaches itself so nothing is written twice, and gives back the
109+
level it had picked, so your level applies from then on. It makes no difference
110+
whether you configure logging before or after importing osw.
111+
112+
A level you asked for is kept across that hand-over, so `set_log_level("DEBUG")`
113+
or `OSW_LOG_LEVEL=DEBUG` is how you pull osw's debug records into an aggregated
114+
setup while the rest of your application stays quieter.
115+
116+
One case osw cannot detect is a handler added to the `osw` logger itself, since
117+
that is indistinguishable from one of its own. Call `disable_logging()` first if
118+
you do that.
119+
120+
### Output from parallel batches
121+
122+
Several osw calls process their input in parallel. What such a task prints, as
123+
opposed to logs, is collected while the batch runs and replayed afterwards, so
124+
that concurrent writing cannot garble the progress bar. That text arrives on the
125+
`osw.parallel.output` logger, one record per line, at INFO. Give that logger its
126+
own level or handler to keep the output of third-party code apart from osw's own
127+
records. Most osw calls replay it only when you pass `debug=True`; `copy_pages`
128+
always replays.
129+
67130
## Examples and tutorials
68131

69132
- Runnable scripts in

‎src/osw/__init__.py‎

Lines changed: 209 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,6 @@
1+
import logging
2+
import os
3+
import sys
14
from importlib.metadata import PackageNotFoundError, version # pragma: no cover
25

36
try:
@@ -8,3 +11,209 @@
811
__version__ = "unknown"
912
finally:
1013
del version, PackageNotFoundError
14+
15+
LOG_LEVEL_ENV_VAR = "OSW_LOG_LEVEL"
16+
"""Name of the environment variable read for the initial log level. Accepts a
17+
level name, a level number, or 'OFF' to start silent."""
18+
DEFAULT_LOG_LEVEL = logging.INFO
19+
"""Level the osw logger starts at when the environment variable is unset"""
20+
LOG_FORMAT = "[%(levelname)s] %(name)s: %(message)s"
21+
OFF = logging.CRITICAL + 1
22+
"""Level above every real record, so setting it silences the logger"""
23+
24+
_DEFAULT_HANDLER_NAME = "osw-default"
25+
_logger = logging.getLogger(__name__)
26+
_level_is_ours = False
27+
"""Whether the level on the osw logger is the one osw picked for itself. A
28+
level the calling code asked for is left alone when osw hands over."""
29+
30+
31+
def _parse_level(value: str) -> int:
32+
"""Turns the environment variable into a level, tolerating junk
33+
34+
Parameters
35+
----------
36+
value
37+
a level name such as 'DEBUG', a level number such as '10', or 'OFF'
38+
39+
Returns
40+
-------
41+
the level, or DEFAULT_LOG_LEVEL if the value names none
42+
"""
43+
cleaned = value.strip().upper()
44+
if cleaned in ("OFF", "NONE", "SILENT"):
45+
return OFF
46+
if cleaned.isdigit():
47+
return int(cleaned)
48+
# getLevelName maps an unknown name to the string 'Level %s', not to a number
49+
level = logging.getLevelName(cleaned)
50+
if isinstance(level, int):
51+
return level
52+
return DEFAULT_LOG_LEVEL
53+
54+
55+
def _application_handles_records() -> bool:
56+
"""Whether the calling code already has somewhere for osw's records to go
57+
58+
Walks what logging.Logger.callHandlers walks above the osw logger. Any
59+
handler found up there belongs to the calling application, so osw writing
60+
its own copy would only duplicate what that handler already reports.
61+
"""
62+
if not _logger.propagate:
63+
# something is deliberately holding the records at the osw logger,
64+
# parallelize while it captures a batch among them
65+
return False
66+
current = _logger.parent
67+
while current:
68+
if current.handlers:
69+
return True
70+
if not current.propagate:
71+
return False
72+
current = current.parent
73+
return False
74+
75+
76+
class _DefaultHandler(logging.StreamHandler):
77+
"""The handler osw attaches while nothing else is listening
78+
79+
Steps aside the first time it finds that the calling application has
80+
configured logging of its own. The check belongs here rather than at import
81+
time because a script normally imports osw before it calls basicConfig().
82+
"""
83+
84+
def emit(self, record: logging.LogRecord):
85+
if _application_handles_records():
86+
_hand_over()
87+
return
88+
super().emit(record)
89+
90+
91+
def _detach():
92+
"""Removes the handler osw attached, leaving any other one in place
93+
94+
Rebinds the list instead of calling removeHandler, because this also runs
95+
from inside the handler's own emit, where callHandlers is iterating that
96+
very list.
97+
"""
98+
detached = [h for h in _logger.handlers if h.get_name() == _DEFAULT_HANDLER_NAME]
99+
_logger.handlers = [h for h in _logger.handlers if h not in detached]
100+
for handler in detached:
101+
handler.close()
102+
103+
104+
def _hand_over():
105+
"""Gives the application's own logging setup sole charge of osw's records
106+
107+
Drops osw's handler so nothing is written twice, and drops the level osw
108+
picked so the application's level applies. A level the calling code asked
109+
for, through set_log_level, enable_logging or the environment variable, is
110+
kept, since that is how one asks for osw's DEBUG records in an aggregated
111+
setup.
112+
"""
113+
global _level_is_ours
114+
_detach()
115+
if _level_is_ours:
116+
_logger.setLevel(logging.NOTSET)
117+
_level_is_ours = False
118+
119+
120+
def enable_logging(level=None, stream=None) -> logging.Handler:
121+
"""Attaches osw's own handler to the osw logger
122+
123+
Called on import when nothing else handles the records, so osw reports what
124+
it is doing without the calling code configuring anything. Call it again to
125+
take the output back after disable_logging(), or to send it elsewhere.
126+
127+
The handler detaches itself as soon as the calling application configures
128+
logging, so records are never written twice.
129+
130+
Parameters
131+
----------
132+
level
133+
a level name or number. Defaults to the environment variable, then to
134+
DEFAULT_LOG_LEVEL.
135+
stream
136+
where to write. Defaults to sys.stderr, so stdout stays free for a
137+
program's own output. Anything speaking a protocol over stdout, such as
138+
an MCP stdio server, depends on that.
139+
140+
Returns
141+
-------
142+
the attached handler
143+
"""
144+
global _level_is_ours
145+
asked_for = level is not None or LOG_LEVEL_ENV_VAR in os.environ
146+
if level is None:
147+
level = _parse_level(os.environ.get(LOG_LEVEL_ENV_VAR, ""))
148+
_detach()
149+
handler = _DefaultHandler(sys.stderr if stream is None else stream)
150+
handler.setFormatter(logging.Formatter(LOG_FORMAT))
151+
handler.set_name(_DEFAULT_HANDLER_NAME)
152+
_logger.addHandler(handler)
153+
_logger.setLevel(level)
154+
_level_is_ours = not asked_for
155+
return handler
156+
157+
158+
def disable_logging():
159+
"""Hands the osw logger over to the calling application
160+
161+
Removes the handler osw attached and the level it picked, so the records
162+
follow whatever the application configured, on the 'osw' logger or on the
163+
root logger above it. A handler the calling code added to the 'osw' logger
164+
is left in place.
165+
166+
Not needed in order to aggregate osw's records. They propagate to the root
167+
logger at all times, and osw's own handler steps aside by itself once
168+
anything else is listening. Call this to be explicit about it, or when a
169+
handler was added to the 'osw' logger directly, which osw cannot tell apart
170+
from one of its own callers.
171+
"""
172+
global _level_is_ours
173+
_detach()
174+
_logger.setLevel(logging.NOTSET)
175+
_level_is_ours = False
176+
177+
178+
def set_log_level(level):
179+
"""Sets how much osw reports
180+
181+
The level survives a hand-over to the application's own logging setup, so
182+
this is also how to ask for osw's DEBUG records in an aggregated setup.
183+
184+
Parameters
185+
----------
186+
level
187+
a level name or number, e.g. 'DEBUG', 'WARNING', or logging.WARNING.
188+
Pass osw.OFF to silence osw everywhere, its own handler and the
189+
application's alike.
190+
"""
191+
global _level_is_ours
192+
_logger.setLevel(level)
193+
_level_is_ours = False
194+
195+
196+
def _configure_on_import():
197+
"""Sets logging up the way an interpreter that configured none needs it"""
198+
if _application_handles_records():
199+
# logging was configured before osw was imported, so the records
200+
# already have somewhere to go and only the level is osw's to set
201+
if LOG_LEVEL_ENV_VAR in os.environ:
202+
set_log_level(_parse_level(os.environ[LOG_LEVEL_ENV_VAR]))
203+
return
204+
enable_logging()
205+
if LOG_LEVEL_ENV_VAR not in os.environ:
206+
# once per interpreter, since this module is imported once. Sent
207+
# through the logger itself, so it disappears with everything else as
208+
# soon as the level is raised or the environment variable is set.
209+
_logger.info(
210+
"osw logs at %s on the 'osw' logger. Use osw.set_log_level"
211+
"('WARNING') to see less, osw.disable_logging() to switch it off, "
212+
"or set %s=OFF before import. Configuring logging yourself, e.g. "
213+
"with logging.basicConfig(), takes the output over automatically.",
214+
logging.getLevelName(_logger.level),
215+
LOG_LEVEL_ENV_VAR,
216+
)
217+
218+
219+
_configure_on_import()

‎src/osw/auth.py‎

Lines changed: 7 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
from __future__ import annotations
22

33
import getpass
4+
import logging
45
import os
56
import warnings
67
from enum import Enum
@@ -16,6 +17,8 @@
1617

1718
from osw.defaults import paths as default_paths
1819

20+
_logger = logging.getLogger(__name__)
21+
1922

2023
def _secret_to_str(v):
2124
"""Unwrap SecretStr to plain str, pass through otherwise."""
@@ -131,7 +134,7 @@ def _load_file_credentials(self):
131134
loaded = _load_credentials(fp, into_store=False)
132135
all_creds.update(loaded)
133136
except Exception as exc:
134-
print(exc)
137+
_logger.error(f"{exc}")
135138
return all_creds
136139

137140
def get_credential(self, config: CredentialConfig) -> BaseCredential:
@@ -243,7 +246,7 @@ def iri_in_file(self, iri: str) -> bool:
243246
if iri_ == iri:
244247
return True
245248
except yaml.YAMLError as exc:
246-
print(exc)
249+
_logger.error(f"{exc}")
247250
return False
248251

249252
def save_credentials_to_file(
@@ -292,9 +295,9 @@ def save_credentials_to_file(
292295
with open(fp, "w", encoding="utf-8") as stream:
293296
yaml.dump(data, stream)
294297
if file_already_exists:
295-
print(f"Credentials file updated at '{fp.resolve()}'.")
298+
_logger.info(f"Credentials file updated at '{fp.resolve()}'.")
296299
else:
297-
print(f"Credentials file created at '{fp.resolve()}'.")
300+
_logger.info(f"Credentials file created at '{fp.resolve()}'.")
298301

299302

300303
CredentialManager.CredentialConfig.update_forward_refs()

‎src/osw/controller/database.py‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,4 @@
1+
import logging
12
from typing import Optional, Union
23

34
from opensemantic.v1 import OswBaseModel
@@ -9,6 +10,8 @@
910
from osw.auth import CredentialManager
1011
from osw.core import OSW
1112

13+
_logger = logging.getLogger(__name__)
14+
1215

1316
class DatabaseController(model.Database):
1417
"""
@@ -130,4 +133,4 @@ def execute(self, sql: str):
130133
with self.engine.connect() as conn:
131134
result_set = conn.execute(sql_text(sql))
132135
for r in result_set:
133-
print(r)
136+
_logger.debug(f"{r}")

‎src/osw/controller/file/wiki.py‎

Lines changed: 6 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
import functools
2+
import logging
23
import os
34
from typing import IO, Any, Dict, List, Optional
45

@@ -8,6 +9,8 @@
89
from osw.utils.wiki import get_namespace, get_title
910
from osw.wtsite import WtSite
1011

12+
_logger = logging.getLogger(__name__)
13+
1114

1215
class WikiFileController(model.WikiFile, RemoteFileController):
1316
"""File controller for wiki files"""
@@ -70,10 +73,9 @@ def get(self) -> IO:
7073
if web_api_failed:
7174
# fallback: use direct download
7275
url = file.imageinfo["url"]
73-
print(
74-
"Extension FileApi not installed on the server. Fallback: use direct "
75-
"download from ",
76-
url,
76+
_logger.warning(
77+
f"Extension FileApi not installed on the server. Fallback: use "
78+
f"direct download from {url}"
7779
)
7880
response = self.osw.mw_site.connection.get(url, stream=True)
7981

0 commit comments

Comments
 (0)