diff --git a/docs/docs/user-guide/controlling-log-output.md b/docs/docs/user-guide/controlling-log-output.md new file mode 100644 index 00000000..0403590a --- /dev/null +++ b/docs/docs/user-guide/controlling-log-output.md @@ -0,0 +1,203 @@ +# Controlling Log Output + +EasyScience uses Python's standard `logging` module for all +informational and warning messages. This gives you full control over +what output the library produces and where it goes. + +## Quick Start + +The most common operation is suppressing all EasyScience messages. You +can do it in one line: + +```python +from easyscience import global_object + +global_object.log.level = 'ERROR' +``` + +Or using the standard library directly: + +```python +import logging + +logging.getLogger('easyscience').setLevel(logging.ERROR) +``` + +Both forms set the package-root logger to `ERROR`, which suppresses all +`WARNING`, `INFO`, and `DEBUG` messages from EasyScience. + +## Logger Hierarchy + +EasyScience loggers are named hierarchically under the root +`easyscience` logger. This lets you suppress the whole package or +individual subsystems: + +``` +easyscience # root — controls everything +├── easyscience.base_classes # EasyList runtime warnings +├── easyscience.legacy # ObjBase / CollectionBase deprecations +├── easyscience.deprecated # @deprecated decorator messages +├── easyscience.fitting # import-availability warnings +│ ├── easyscience.fitting.bumps # Bumps fitting runtime messages +│ ├── easyscience.fitting.lmfit # LMFit fitting runtime messages +│ └── easyscience.fitting.dfo # DFO fitting runtime messages +├── easyscience.variable # parameter warnings +└── easyscience.global_object # undo/redo, debugging diagnostics +``` + +Setting the level on a parent logger affects all its children, because +child loggers inherit the parent's effective level. + +```python +import logging + +# Suppress everything from the fitting subsystem (including bumps/lmfit/dfo) +logging.getLogger('easyscience.fitting').setLevel(logging.ERROR) + +# Suppress only Bumps runtime messages +logging.getLogger('easyscience.fitting.bumps').setLevel(logging.ERROR) + +# Suppress only legacy deprecation notices +logging.getLogger('easyscience.legacy').setLevel(logging.ERROR) +``` + +## Environment Variable + +You can control the log level **before** importing EasyScience by +setting the `EASYSCIENCE_LOG_LEVEL` environment variable. This is useful +when a downstream library cannot configure logging in code before +EasyScience is imported. + +**Accepted values:** `DEBUG`, `INFO`, `WARNING`, `ERROR`, `CRITICAL`, or +a numeric level (e.g. `40`). + +**Example — suppressing all import-time messages:** + +```powershell +# Windows PowerShell +$env:EASYSCIENCE_LOG_LEVEL = 'ERROR' +python -c "import easyscience" # silent +``` + +```bash +# Linux / macOS +EASYSCIENCE_LOG_LEVEL=ERROR python -c "import easyscience" # silent +``` + +Or from Python, set the environment variable before the import: + +```python +import os + +os.environ['EASYSCIENCE_LOG_LEVEL'] = 'ERROR' +import easyscience # now silent +``` + +## Temporary Suppression (Context Manager) + +When you only want to silence messages during a specific operation, use +the `at_level` context manager: + +```python +from easyscience import global_object +import logging + +# Messages during the fit are suppressed, then the previous level is restored +with global_object.log.at_level(logging.ERROR): + results = fitter.fit(x, y, weights) +``` + +This is the recommended pattern for technique-specific libraries that +don't want EasyScience output to leak into their own users' consoles. + +## Convenience API + +The `global_object.log` object exposes a `level` property plus +convenience methods that mirror `logging` module-level functions: + +| Member | Description | +| ------------------ | ------------------------------------------------------------------------ | +| `.level` | Get/set the package-root logger level (`'WARNING'` or `logging.WARNING`) | +| `.debug(msg)` | Log a `DEBUG`-level message | +| `.info(msg)` | Log an `INFO`-level message | +| `.warning(msg)` | Log a `WARNING`-level message | +| `.error(msg)` | Log an `ERROR`-level message | +| `.critical(msg)` | Log a `CRITICAL`-level message | +| `.exception(msg)` | Log an `ERROR`-level message with traceback | +| `.getLogger(name)` | Get a child logger under `easyscience` | +| `.at_level(level)` | Context manager for temporary level change | +| `.suspend()` | Suppress all EasyScience output | +| `.resume()` | Restore the previously set level | + +## Recipes + +### Recipe 1: Keep your test output clean + +When running tests that exercise EasyScience fitting, suppress the +library's messages so they don't clutter your test reports: + +```python +import logging +from easyscience import global_object + +@pytest.fixture(autouse=True) +def _quiet_easyscience(): + # The test body runs *inside* the context manager (yield within `with`) + with global_object.log.at_level(logging.ERROR): + yield +``` + +### Recipe 2: Library author embedding EasyScience + +If you maintain a library that uses EasyScience internally, prevent +EasyScience from writing to your users' consoles: + +```python +# In your library's __init__.py, before any EasyScience import: +import os +os.environ.setdefault('EASYSCIENCE_LOG_LEVEL', 'ERROR') +``` + +### Recipe 3: Debug mode for development + +When developing or debugging, see all EasyScience internal diagnostics: + +```python +from easyscience import global_object + +global_object.log.level = 'DEBUG' + +# Your code here — all EasyScience messages will be visible +``` + +### Recipe 4: See only error messages + +Keep the console clean but still see critical problems: + +```python +from easyscience import global_object + +global_object.log.level = 'ERROR' +``` + +## Library-Safe Behaviour + +EasyScience follows standard library-logging best practices: + +- **No `logging.basicConfig()`** — EasyScience never reconfigures the + global logging setup. +- **No default stream handlers** — EasyScience does not attach handlers + that write to `stdout` or `stderr`. It only creates log records. + Applications and test frameworks decide where those records go. +- **Child loggers inherit** — Child loggers (e.g. + `easyscience.fitting.bumps`) are left at `logging.NOTSET` by default, + so they inherit level and handler configuration from the `easyscience` + package-root logger. Supressing the root suppresses everything. + +This means you are in full control. If you don't configure any handlers, +Python's built-in `logging.lastResort` fallback still prints `WARNING` +and above to `stderr`, so standalone users see important messages out of +the box. `INFO` and `DEBUG` messages remain hidden until you opt in. If +you do configure handlers (as `pytest` does via its logging plugin, or +as an application might via `basicConfig`), you control what is shown +and where. diff --git a/docs/docs/user-guide/index.md b/docs/docs/user-guide/index.md index bff8e315..84fe5c09 100644 --- a/docs/docs/user-guide/index.md +++ b/docs/docs/user-guide/index.md @@ -4,5 +4,7 @@ icon: material/book-open-variant # :material-book-open-variant: User Guide -This section is currently under development. Please check back later for -updates. +- [:material-volume-high: Controlling Log Output](controlling-log-output.md) + – How to suppress, filter, or redirect the messages that EasyScience + produces. Covers the `EASYSCIENCE_LOG_LEVEL` environment variable, the + logger hierarchy, context managers, and common recipes. diff --git a/docs/mkdocs.yml b/docs/mkdocs.yml index 15f15dea..977cbb84 100644 --- a/docs/mkdocs.yml +++ b/docs/mkdocs.yml @@ -174,6 +174,7 @@ nav: - Installation & Setup: installation-and-setup/index.md - User Guide: - User Guide: user-guide/index.md + - Controlling Log Output: user-guide/controlling-log-output.md - Tutorials: - Tutorials: tutorials/index.md - Workshops & Schools: diff --git a/src/easyscience/base_classes/collection_base.py b/src/easyscience/base_classes/collection_base.py index a3b01a53..c62e9382 100644 --- a/src/easyscience/base_classes/collection_base.py +++ b/src/easyscience/base_classes/collection_base.py @@ -7,13 +7,12 @@ Please update your imports. """ -import warnings +from easyscience import global_object from ..legacy.collection_base import CollectionBase # noqa: F401 -warnings.warn( +global_object.log.warning( 'easyscience.base_classes.collection_base is deprecated. ' 'Please import from easyscience.legacy.collection_base instead.', - DeprecationWarning, stacklevel=2, ) diff --git a/src/easyscience/base_classes/easy_list.py b/src/easyscience/base_classes/easy_list.py index 34c0e331..23ac673d 100644 --- a/src/easyscience/base_classes/easy_list.py +++ b/src/easyscience/base_classes/easy_list.py @@ -4,7 +4,6 @@ from __future__ import annotations import copy -import warnings from collections.abc import MutableSequence from typing import Any from typing import Callable @@ -16,6 +15,7 @@ from typing import TypeVar from typing import overload +from easyscience import global_object from easyscience.io.serializer_base import SerializerBase from easyscience.variable.descriptor_base import DescriptorBase @@ -159,7 +159,7 @@ def __setitem__( if not isinstance(value, tuple(self._protected_types)): raise TypeError(f'Items must be one of {self._protected_types}, got {type(value)}') if value is not self._data[idx] and value in self: - warnings.warn( + global_object.log.getLogger('base_classes').warning( f'Item with unique name "{self._get_key(value)}" already in EasyList, it will be ignored' ) return @@ -177,7 +177,7 @@ def __setitem__( if not isinstance(v, tuple(self._protected_types)): raise TypeError(f'Items must be one of {self._protected_types}, got {type(v)}') if v in self and replaced[i] is not v: - warnings.warn( + global_object.log.getLogger('base_classes').warning( f'Item with unique name "{v.unique_name}" already in EasyList, it will be ignored' ) new_values[i] = replaced[ @@ -240,7 +240,7 @@ def insert(self, index: int, value: ProtectedType_) -> None: elif not isinstance(value, tuple(self._protected_types)): raise TypeError(f'Items must be one of {self._protected_types}, got {type(value)}') if value in self: - warnings.warn( + global_object.log.getLogger('base_classes').warning( f'Item with unique name "{self._get_key(value)}" already in EasyList, it will be ignored' ) return diff --git a/src/easyscience/base_classes/obj_base.py b/src/easyscience/base_classes/obj_base.py index bf460eca..8d44b193 100644 --- a/src/easyscience/base_classes/obj_base.py +++ b/src/easyscience/base_classes/obj_base.py @@ -7,13 +7,12 @@ Please update your imports. """ -import warnings +from easyscience import global_object from ..legacy.obj_base import ObjBase # noqa: F401 -warnings.warn( +global_object.log.warning( 'easyscience.base_classes.obj_base is deprecated. ' 'Please import from easyscience.legacy.obj_base instead.', - DeprecationWarning, stacklevel=2, ) diff --git a/src/easyscience/fitting/available_minimizers.py b/src/easyscience/fitting/available_minimizers.py index 0cfd262b..311bf35e 100644 --- a/src/easyscience/fitting/available_minimizers.py +++ b/src/easyscience/fitting/available_minimizers.py @@ -1,10 +1,11 @@ # SPDX-FileCopyrightText: 2024 EasyScience contributors # SPDX-License-Identifier: BSD-3-Clause -import warnings from dataclasses import dataclass from enum import Enum +from easyscience import global_object + # Change to importlib.metadata when Python 3.10 is the minimum version # import importlib.metadata # installed_packages = [x.name for x in importlib.metadata.distributions()] @@ -15,11 +16,8 @@ lmfit_engine_available = True except ImportError: - # TODO make this a proper message (use logging?) - warnings.warn( - 'LMFit minimization is not available. Probably lmfit has not been installed.', - ImportWarning, - stacklevel=2, + global_object.log.getLogger('fitting').warning( + 'LMFit minimization is not available. Probably lmfit has not been installed.' ) bumps_engine_available = False @@ -28,11 +26,8 @@ bumps_engine_available = True except ImportError: - # TODO make this a proper message (use logging?) - warnings.warn( - 'Bumps minimization is not available. Probably bumps has not been installed.', - ImportWarning, - stacklevel=2, + global_object.log.getLogger('fitting').warning( + 'Bumps minimization is not available. Probably bumps has not been installed.' ) dfo_engine_available = False @@ -41,11 +36,8 @@ dfo_engine_available = True except ImportError: - # TODO make this a proper message (use logging?) - warnings.warn( - 'DFO minimization is not available. Probably dfols has not been installed.', - ImportWarning, - stacklevel=2, + global_object.log.getLogger('fitting').warning( + 'DFO minimization is not available. Probably dfols has not been installed.' ) diff --git a/src/easyscience/fitting/calculators/interface_factory.py b/src/easyscience/fitting/calculators/interface_factory.py index 73b79965..ad5fbc24 100644 --- a/src/easyscience/fitting/calculators/interface_factory.py +++ b/src/easyscience/fitting/calculators/interface_factory.py @@ -11,6 +11,8 @@ from typing import Optional from typing import Type +from easyscience import global_object + if TYPE_CHECKING: from abc import ABCMeta @@ -96,12 +98,16 @@ def switch(self, new_interface: str, fitter: Optional[Type[Fitter]] = None) -> N if hasattr(obj, 'update_bindings'): obj.update_bindings() except Exception as e: - print(f'Unable to auto generate bindings.\n{e}') + global_object.log.getLogger('fitting.calculators').warning( + 'Unable to auto generate bindings.\n%s', e + ) elif hasattr(fitter, 'generate_bindings'): try: fitter.generate_bindings() except Exception as e: - print(f'Unable to auto generate bindings.\n{e}') + global_object.log.getLogger('fitting.calculators').warning( + 'Unable to auto generate bindings.\n%s', e + ) @property def available_interfaces(self) -> List[str]: diff --git a/src/easyscience/fitting/fitter.py b/src/easyscience/fitting/fitter.py index 38ef7351..70dcfed0 100644 --- a/src/easyscience/fitting/fitter.py +++ b/src/easyscience/fitting/fitter.py @@ -9,6 +9,8 @@ import numpy as np +from easyscience import global_object + from .available_minimizers import AvailableMinimizers from .available_minimizers import from_string_to_enum from .minimizers import FitResults @@ -72,7 +74,9 @@ def create(self, minimizer_enum: Union[AvailableMinimizers, str] = DEFAULT_MINIM DEFAULT_MINIMIZER. """ if isinstance(minimizer_enum, str): - print(f'minimizer should be set with enum {minimizer_enum}') + global_object.log.getLogger('fitting').warning( + 'minimizer should be set with enum %s', minimizer_enum + ) minimizer_enum = from_string_to_enum(minimizer_enum) self._update_minimizer(minimizer_enum) @@ -86,7 +90,9 @@ def switch_minimizer(self, minimizer_enum: Union[AvailableMinimizers, str]) -> N The enum of the minimizer to create and instantiate. """ if isinstance(minimizer_enum, str): - print(f'minimizer should be set with enum {minimizer_enum}') + global_object.log.getLogger('fitting').warning( + 'minimizer should be set with enum %s', minimizer_enum + ) minimizer_enum = from_string_to_enum(minimizer_enum) self._update_minimizer(minimizer_enum) diff --git a/src/easyscience/fitting/minimizers/minimizer_bumps.py b/src/easyscience/fitting/minimizers/minimizer_bumps.py index 496cbfde..0231ce0d 100644 --- a/src/easyscience/fitting/minimizers/minimizer_bumps.py +++ b/src/easyscience/fitting/minimizers/minimizer_bumps.py @@ -2,7 +2,6 @@ # SPDX-License-Identifier: BSD-3-Clause import copy -import warnings from typing import Any from typing import Callable from typing import List @@ -484,19 +483,19 @@ def _gen_fit_results( f'objective evaluated {n_evaluations} times' ) if stopped_on_budget: + from easyscience import global_object + if tolerance is None: - warnings.warn( + global_object.log.getLogger('fitting.bumps').warning( f'Fit did not converge within the maximum optimizer steps of {max_evaluations} ' f'({n_evaluations} objective evaluations). ' - 'Consider increasing the maximum number of evaluations or adjusting the tolerance.', - UserWarning, + 'Consider increasing the maximum number of evaluations or adjusting the tolerance.' ) else: - warnings.warn( + global_object.log.getLogger('fitting.bumps').warning( f'Fit did not reach the desired tolerance of {tolerance} within the maximum optimizer steps of {max_evaluations} ' f'({n_evaluations} objective evaluations). ' - 'Consider increasing the maximum number of evaluations or adjusting the tolerance.', - UserWarning, + 'Consider increasing the maximum number of evaluations or adjusting the tolerance.' ) # results.residual = results.y_obs - results.y_calc diff --git a/src/easyscience/fitting/minimizers/minimizer_dfo.py b/src/easyscience/fitting/minimizers/minimizer_dfo.py index 63eb7795..319db849 100644 --- a/src/easyscience/fitting/minimizers/minimizer_dfo.py +++ b/src/easyscience/fitting/minimizers/minimizer_dfo.py @@ -1,7 +1,6 @@ # SPDX-FileCopyrightText: 2026 EasyScience contributors # SPDX-License-Identifier: BSD-3-Clause -import warnings from dataclasses import dataclass from typing import Any from typing import Callable @@ -393,6 +392,8 @@ def _gen_fit_results(self, fit_results: Any, weights: np.ndarray, **kwargs: Any) """ results = FitResults() + from easyscience import global_object + for name, value in kwargs.items(): if getattr(results, name, False): setattr(results, name, value) @@ -400,7 +401,7 @@ def _gen_fit_results(self, fit_results: Any, weights: np.ndarray, **kwargs: Any) # EXIT_SUCCESS is 0 and EXIT_MAXFUN_WARNING keeps a different flag value. results.success = fit_results.flag == fit_results.EXIT_SUCCESS if fit_results.flag == fit_results.EXIT_MAXFUN_WARNING: - warnings.warn(str(fit_results.msg), UserWarning) + global_object.log.getLogger('fitting.dfo').warning(str(fit_results.msg)) pars = {} for p_name, par in self._cached_pars.items(): @@ -419,7 +420,7 @@ def _gen_fit_results(self, fit_results: Any, weights: np.ndarray, **kwargs: Any) results.message = str(fit_results.msg) if not results.success: warning_message = results.message or 'DFO fit did not succeed.' - warnings.warn(warning_message, UserWarning, stacklevel=2) + global_object.log.getLogger('fitting.dfo').warning(warning_message) # results.residual = results.y_obs - results.y_calc # results.goodness_of_fit = fit_results.f diff --git a/src/easyscience/fitting/minimizers/minimizer_lmfit.py b/src/easyscience/fitting/minimizers/minimizer_lmfit.py index f5fd1d44..31fb543f 100644 --- a/src/easyscience/fitting/minimizers/minimizer_lmfit.py +++ b/src/easyscience/fitting/minimizers/minimizer_lmfit.py @@ -1,7 +1,6 @@ # SPDX-FileCopyrightText: 2026 EasyScience contributors # SPDX-License-Identifier: BSD-3-Clause -import warnings from typing import Any from typing import Callable from typing import List @@ -413,7 +412,9 @@ def _gen_fit_results(self, fit_results: ModelResult, **kwargs: Any) -> FitResult results.iterations = kwargs.get('iterations') results.message = fit_results.message if fit_results.success is False and fit_results.message: - warnings.warn(str(fit_results.message), UserWarning) + from easyscience import global_object + + global_object.log.getLogger('fitting.lmfit').warning(str(fit_results.message)) results.minimizer_engine = self.__class__ results.fit_args = None diff --git a/src/easyscience/global_object/hugger/property.py b/src/easyscience/global_object/hugger/property.py index e1a2d2e2..e36c52e5 100644 --- a/src/easyscience/global_object/hugger/property.py +++ b/src/easyscience/global_object/hugger/property.py @@ -1,6 +1,7 @@ # SPDX-FileCopyrightText: 2026 EasyScience contributors # SPDX-License-Identifier: BSD-3-Clause +import logging import sys from functools import wraps from typing import Any @@ -73,7 +74,9 @@ def result_item(item_to_be_resulted): result_item(item) Store().append_log(self.makeEntry('get', res)) if global_object.debug: # noqa: S1006 - print(f"I'm {self._my_self} and {self._get_id} has been called from the outside!") + logging.getLogger('easyscience.global_object.hugger').debug( + "I'm %s and %s has been called from the outside!", self._my_self, self._get_id + ) return res def __set__(self, instance, value): @@ -83,8 +86,11 @@ def __set__(self, instance, value): if not test and self._get_id is not None and self._my_self is not None: Store().append_log(self.makeEntry('set', value)) if global_object.debug: # noqa: S1006 - print( - f"I'm {self._my_self} and {self._get_id} has been set to {value} from the outside!" + logging.getLogger('easyscience.global_object.hugger').debug( + "I'm %s and %s has been set to %s from the outside!", + self._my_self, + self._get_id, + value, ) return super().__set__(instance, value) @@ -131,7 +137,9 @@ def makeEntry(self, log_type, returns, *args, **kwargs) -> str: var = '"' + var + '"' temp += f'{var}' else: - print(f'{log_type} is not implemented yet. Sorry') + logging.getLogger('easyscience.global_object.hugger').debug( + '%s is not implemented yet. Sorry', log_type + ) temp += '\n' return temp @@ -163,7 +171,9 @@ def patch(self): func = getattr(self.property, key) if func is not None: if global_object.debug: - print(f'Patching property {self.klass.__name__}.{self.prop_name}') + logging.getLogger('easyscience.global_object.hugger').debug( + 'Patching property %s.%s', self.klass.__name__, self.prop_name + ) patch_function: Callable = item.get('patcher') new_func = patch_function(func) option[key] = new_func @@ -171,7 +181,9 @@ def patch(self): def restore(self): if global_object.debug: - print(f'Restoring property {self.klass.__name__}.{self.prop_name}') + logging.getLogger('easyscience.global_object.hugger').debug( + 'Restoring property %s.%s', self.klass.__name__, self.prop_name + ) setattr(self.klass, self.prop_name, self.property) def patch_get(self, func: Callable) -> Callable: @@ -179,8 +191,12 @@ def patch_get(self, func: Callable) -> Callable: @wraps(func) def inner(*args, **kwargs): if global_object.debug: - print( - f'{self.klass.__name__}.{self.prop_name} has been called with {args[1:]}, {kwargs}' + logging.getLogger('easyscience.global_object.hugger').debug( + '%s.%s has been called with %s, %s', + self.klass.__name__, + self.prop_name, + args[1:], + kwargs, ) res = func(*args, **kwargs) self._append_args(*args, **kwargs) @@ -195,8 +211,12 @@ def patch_set(self, func: Callable) -> Callable: @wraps(func) def inner(*args, **kwargs): if global_object.debug: - print( - f'{self.klass.__name__}.{self.prop_name} has been set with {args[1:]}, {kwargs}' + logging.getLogger('easyscience.global_object.hugger').debug( + '%s.%s has been set with %s, %s', + self.klass.__name__, + self.prop_name, + args[1:], + kwargs, ) self._append_args(*args, **kwargs) self._append_log(self.makeEntry('set', None, *args, **kwargs)) @@ -209,7 +229,9 @@ def patch_del(self, func: Callable) -> Callable: @wraps(func) def inner(*args, **kwargs): if global_object.debug: - print(f'{self.klass.__name__}.{self.prop_name} has been deleted.') + logging.getLogger('easyscience.global_object.hugger').debug( + '%s.%s has been deleted.', self.klass.__name__, self.prop_name + ) self._append_log(self.makeEntry('del', None, *args, **kwargs)) return func(*args, **kwargs) @@ -252,6 +274,8 @@ def makeEntry(self, log_type, returns, *args, **kwargs) -> str: var = '"' + var + '"' temp += f'{var}' else: - print(f'{log_type} is not implemented yet. Sorry') + logging.getLogger('easyscience.global_object.hugger').debug( + '%s is not implemented yet. Sorry', log_type + ) temp += '\n' return temp diff --git a/src/easyscience/global_object/logger.py b/src/easyscience/global_object/logger.py index 4aaed1eb..409e534d 100644 --- a/src/easyscience/global_object/logger.py +++ b/src/easyscience/global_object/logger.py @@ -1,44 +1,189 @@ # SPDX-FileCopyrightText: 2026 EasyScience contributors # SPDX-License-Identifier: BSD-3-Clause +import contextlib import logging +import os +from collections.abc import Iterator + +PACKAGE_LOGGER_NAME = 'easyscience' +_LOG_LEVEL_ENV_VAR = 'EASYSCIENCE_LOG_LEVEL' + +_LEVEL_NAME_MAP = { + 'DEBUG': logging.DEBUG, + 'INFO': logging.INFO, + 'WARNING': logging.WARNING, + 'ERROR': logging.ERROR, + 'CRITICAL': logging.CRITICAL, +} + + +def _parse_log_level(level: int | str) -> int: + """Convert a level number or name into a numeric level, raising on an unknown name.""" + if isinstance(level, int): + return level + stripped = level.strip() + if stripped.isdigit(): + return int(stripped) + upper = stripped.upper() + if upper in _LEVEL_NAME_MAP: + return _LEVEL_NAME_MAP[upper] + valid = ', '.join(sorted(_LEVEL_NAME_MAP)) + raise ValueError(f'Unknown log level {level!r}. Expected an integer or one of: {valid}.') + + +def _env_log_level(raw: str | None, default: int) -> int: + """Parse the EASYSCIENCE_LOG_LEVEL env var, falling back to *default* on an unset/bad value.""" + if raw is None: + return default + try: + return _parse_log_level(raw) + except ValueError: + return default class Logger: - def __init__(self, log_level: int = logging.INFO): - self.logger = logging.getLogger(__name__) - self.level = log_level - self.logger.setLevel(self.level) + """ + Central logging controller for EasyScience. + + Owns the package-root logger ``easyscience`` and provides a + convenience API to set its level. It never calls + ``logging.basicConfig`` nor attaches a handler, so the host + application keeps full control over where output goes. + """ + + def __init__(self, log_level: int = logging.WARNING): + """ + Parameters + ---------- + log_level : int, default=logging.WARNING + Default level for the package-root logger. Overridden by the + ``EASYSCIENCE_LOG_LEVEL`` environment variable when set. + """ + effective_default = _env_log_level(os.environ.get(_LOG_LEVEL_ENV_VAR), default=log_level) + self.logger = logging.getLogger(PACKAGE_LOGGER_NAME) + self.logger.setLevel(effective_default) + self._level_before_suspend = effective_default - def getLogger( - self, logger_name: str, color: str = '32', defaults: bool = True - ) -> logging.Logger: + # -- convenience delegation methods (mirror logging module) ------------ + + def debug(self, msg: str, *args, **kwargs) -> None: + """Log a DEBUG-level message on the package-root logger.""" + self.logger.debug(msg, *args, **kwargs) + + def info(self, msg: str, *args, **kwargs) -> None: + """Log an INFO-level message on the package-root logger.""" + self.logger.info(msg, *args, **kwargs) + + def warning(self, msg: str, *args, **kwargs) -> None: + """Log a WARNING-level message on the package-root logger.""" + self.logger.warning(msg, *args, **kwargs) + + def error(self, msg: str, *args, **kwargs) -> None: + """Log an ERROR-level message on the package-root logger.""" + self.logger.error(msg, *args, **kwargs) + + def critical(self, msg: str, *args, **kwargs) -> None: + """Log a CRITICAL-level message on the package-root logger.""" + self.logger.critical(msg, *args, **kwargs) + + def exception(self, msg: str, *args, **kwargs) -> None: + """Log an ERROR-level message with traceback on the package-root logger.""" + self.logger.exception(msg, *args, **kwargs) + + # -- public API ------------------------------------------------------- + + @property + def level(self) -> int: + """ + Get the effective level of the package-root logger. + + Returns + ------- + int + Numeric logging level currently set on the ``easyscience`` + package-root logger. """ - Create a logger :param color:. + return self.logger.level + + @level.setter + def level(self, value: int | str) -> None: + """ + Set the level of the package-root logger. + + Parameters + ---------- + value : int | str + Logging level — a number (e.g. ``logging.WARNING``) or a + level name (e.g. ``'ERROR'``). A string that is not a + recognised level name or numeric string raises ``ValueError``. + """ + self.logger.setLevel(_parse_log_level(value)) + + def getLogger(self, logger_name: str) -> logging.Logger: + """ + Create or retrieve a child logger under *easyscience*. + + The returned logger is left at ``logging.NOTSET`` so it inherits + level and handler configuration from the package-root logger. Parameters ---------- logger_name : str - Logger name. Usually __name__ on creation. - color : str, default='32' - By default, '32'. - defaults : bool, default=True - Do you want to associate any current file loggers with this - logger. By default, True. + Logger name. Usually ``__name__`` of the calling module. Returns ------- logging.Logger - A logger. - """ - logger = logging.getLogger(logger_name) - logger.setLevel(self.level) - # self.applyLevel(logger) - # for handler_type in self._handlers: - # for handler in self._handlers[handler_type]: - # if handler_type == 'sys' or defaults: - # handler.formatter._fmt = self._makeColorText(color) - # logger.addHandler(handler) - # logger.propagate = False - # self._loggers.append(logger) - return logger + A child logger whose name is ``easyscience.`` + when *logger_name* does not already start with *easyscience* + or a dot. + """ + if not logger_name.startswith(PACKAGE_LOGGER_NAME) and not logger_name.startswith('.'): + logger_name = f'{PACKAGE_LOGGER_NAME}.{logger_name}' + return logging.getLogger(logger_name) + + @contextlib.contextmanager + def at_level(self, level: int | str) -> Iterator[None]: + """ + Context manager that temporarily sets the package-root logger + to *level*, restoring the previous level on exit. + + Parameters + ---------- + level : int | str + Temporary level for the package-root logger — e.g. + ``logging.ERROR`` or ``'ERROR'``. + + Yields + ------ + None + Control is handed back to the ``with`` block with the + temporary level applied. + + Example + ------- + Setting the log-level only within the context: + + ```python + with global_object.log.at_level(logging.ERROR): + fitter.fit(x, y, weights) # no core messages below ERROR + ``` + """ + previous = self.logger.level + self.level = level + try: + yield + finally: + self.logger.setLevel(previous) + + # -- deprecated helpers (compatibility shims) ------------------------- + + def suspend(self): + """Suppress all core log output (set level to CRITICAL+1).""" + self._level_before_suspend = self.logger.level + self.logger.setLevel(logging.CRITICAL + 1) + + def resume(self): + """Restore the level captured by the most recent suspend call.""" + self.level = self._level_before_suspend diff --git a/src/easyscience/global_object/undo_redo.py b/src/easyscience/global_object/undo_redo.py index 276ad6ab..141fc5e7 100644 --- a/src/easyscience/global_object/undo_redo.py +++ b/src/easyscience/global_object/undo_redo.py @@ -3,6 +3,7 @@ import abc import functools +import logging from collections import UserDict from collections import deque from typing import Any @@ -233,7 +234,7 @@ def undo(self) -> NoReturn: self._command_running = True command.undo() except Exception as e: - print(e) + logging.getLogger('easyscience.global_object.undo_redo').warning(str(e)) finally: self._command_running = False @@ -251,7 +252,7 @@ def redo(self) -> NoReturn: self._command_running = True command.redo() except Exception as e: - print(e) + logging.getLogger('easyscience.global_object.undo_redo').warning(str(e)) finally: self._command_running = False @@ -446,7 +447,9 @@ def wrapper(obj, *args) -> NoReturn: return if global_object.debug: - print(f"I'm {obj} and have been set from {old_value} to {new_value}!") + logging.getLogger('easyscience.global_object.undo_redo').debug( + "I'm %s and have been set from %s to %s!", obj, old_value, new_value + ) global_object.stack.push(PropertyStack(obj, func, old_value, new_value, **kwargs)) diff --git a/src/easyscience/legacy/collection_base.py b/src/easyscience/legacy/collection_base.py index 588cb124..5be3386c 100644 --- a/src/easyscience/legacy/collection_base.py +++ b/src/easyscience/legacy/collection_base.py @@ -3,7 +3,6 @@ from __future__ import annotations -import warnings from collections.abc import MutableSequence from numbers import Number from typing import TYPE_CHECKING @@ -14,6 +13,7 @@ from typing import Tuple from typing import Union +from easyscience import global_object from easyscience.base_classes.new_base import NewBase from easyscience.global_object.undo_redo import NotarizedDict @@ -69,10 +69,9 @@ def __init__( If a provided item is not an EasyScience object or if a keyword collides with an internal attribute. """ - warnings.warn( + global_object.log.getLogger('legacy').warning( 'CollectionBase is deprecated and will be removed in a future version. ' 'Please migrate to ModelBase or EasyList.', - DeprecationWarning, stacklevel=2, ) BasedBase.__init__(self, name, unique_name=unique_name) diff --git a/src/easyscience/legacy/obj_base.py b/src/easyscience/legacy/obj_base.py index eac47af7..4a70de25 100644 --- a/src/easyscience/legacy/obj_base.py +++ b/src/easyscience/legacy/obj_base.py @@ -3,11 +3,12 @@ from __future__ import annotations -import warnings from typing import TYPE_CHECKING from typing import Callable from typing import Optional +from easyscience import global_object + from ..base_classes.based_base import BasedBase from ..utils.classTools import addLoggedProp from ..variable.descriptor_base import DescriptorBase @@ -58,10 +59,9 @@ def __init__( If a keyword component name would overwrite an existing class attribute. """ - warnings.warn( + global_object.log.getLogger('legacy').warning( 'ObjBase is deprecated and will be removed in a future version. ' 'Please migrate to ModelBase.', - DeprecationWarning, stacklevel=2, ) super(ObjBase, self).__init__(name=name, unique_name=unique_name) diff --git a/src/easyscience/legacy/xml.py b/src/easyscience/legacy/xml.py index 54ccb0ba..da52ef65 100644 --- a/src/easyscience/legacy/xml.py +++ b/src/easyscience/legacy/xml.py @@ -13,6 +13,8 @@ import numpy as np +from easyscience import global_object + from ..io.dict import DataDictSerializer from ..io.dict import DictSerializer from ..io.template import BaseEncoderDecoder @@ -191,5 +193,5 @@ def _check_class(self, element, key: str, value: Any, skip: Optional[List[str]] elif issubclass(T_, np.ndarray): element.text = str(value.tolist()) else: - print(f'Cannot encode {T_} to XML') + global_object.log.getLogger('legacy.xml').error('Cannot encode %s to XML', T_) raise NotImplementedError diff --git a/src/easyscience/utils/decorators.py b/src/easyscience/utils/decorators.py index 03e80f5a..fec9b0fa 100644 --- a/src/easyscience/utils/decorators.py +++ b/src/easyscience/utils/decorators.py @@ -3,7 +3,6 @@ import collections.abc import functools -import warnings from time import time from typing import Any from typing import Callable @@ -99,11 +98,10 @@ def deprecated(func): @functools.wraps(func) def new_func(*args, **kwargs): - warnings.warn_explicit( - 'Call to deprecated function {}.'.format(func.__name__), - category=DeprecationWarning, - filename=func.__code__.co_filename, - lineno=func.__code__.co_firstlineno + 1, + global_object.log.getLogger('deprecated').warning( + 'Call to deprecated function %s.', + func.__name__, + stacklevel=3, ) return func(*args, **kwargs) diff --git a/src/easyscience/variable/parameter.py b/src/easyscience/variable/parameter.py index c873f8ad..04cbbd66 100644 --- a/src/easyscience/variable/parameter.py +++ b/src/easyscience/variable/parameter.py @@ -6,7 +6,6 @@ import copy import numbers import re -import warnings import weakref from typing import Any from typing import Dict @@ -238,7 +237,9 @@ def _update(self) -> None: self._notify_observers() else: - warnings.warn('This parameter is not dependent. It cannot be updated.') + global_object.log.getLogger('variable').warning( + 'This parameter is not dependent. It cannot be updated.' + ) def make_dependent_on( self, diff --git a/src/easyscience/variable/parameter_dependency_resolver.py b/src/easyscience/variable/parameter_dependency_resolver.py index 20351e22..d231dcd2 100644 --- a/src/easyscience/variable/parameter_dependency_resolver.py +++ b/src/easyscience/variable/parameter_dependency_resolver.py @@ -7,6 +7,8 @@ from typing import Dict from typing import List +from easyscience import global_object + from .parameter import Parameter @@ -56,8 +58,9 @@ def _collect_parameters(item: Any, parameters: List[Parameter]) -> None: attr_value = getattr(item, attr_name) _collect_parameters(attr_value, parameters) except (AttributeError, Exception): - # log the exception - print(f"Error accessing property '{attr_name}' of {item}") + global_object.log.getLogger('variable.dependencies').debug( + "Error accessing property '%s' of %s", attr_name, item + ) # Skip properties that can't be accessed continue @@ -85,7 +88,9 @@ def _collect_parameters(item: Any, parameters: List[Parameter]) -> None: # Report results if resolved_count > 0: - print(f'Successfully resolved dependencies for {resolved_count} parameter(s).') + global_object.log.getLogger('variable.dependencies').debug( + 'Successfully resolved dependencies for %d parameter(s).', resolved_count + ) if error_count > 0: error_message = ( @@ -140,8 +145,9 @@ def _collect_pending_parameters(item: Any) -> None: attr_value = getattr(item, attr_name) _collect_pending_parameters(attr_value) except (AttributeError, Exception): - # log the exception - print(f"Error accessing property '{attr_name}' of {item}") + global_object.log.getLogger('variable.dependencies').debug( + "Error accessing property '%s' of %s", attr_name, item + ) # Skip properties that can't be accessed continue diff --git a/tests/unit/base_classes/test_deprecated_wrappers.py b/tests/unit/base_classes/test_deprecated_wrappers.py index 01388b3f..492fc387 100644 --- a/tests/unit/base_classes/test_deprecated_wrappers.py +++ b/tests/unit/base_classes/test_deprecated_wrappers.py @@ -3,12 +3,13 @@ """Tests for the deprecated wrapper modules in easyscience.base_classes. -These modules now only emit DeprecationWarnings and re-export from -easyscience.legacy. We test that the warnings are raised and that +These modules now only emit log warnings and re-export from +easyscience.legacy. We test that the log messages are raised and that the classes are still usable. """ -import warnings +import importlib +import logging import pytest @@ -28,24 +29,23 @@ def _clear_map(): # --------------------------------------------------------------------------- -def test_import_collection_base_warns(): - """Importing easyscience.base_classes.collection_base emits DeprecationWarning.""" - with warnings.catch_warnings(record=True) as w: - warnings.simplefilter('always') - from easyscience.base_classes.collection_base import CollectionBase # noqa: F811 +def test_import_collection_base_warns(caplog: 'pytest.LogCaptureFixture'): + """Importing easyscience.base_classes.collection_base logs a WARNING.""" + import easyscience.base_classes.collection_base + + with caplog.at_level(logging.WARNING, logger='easyscience'): + importlib.reload(easyscience.base_classes.collection_base) - assert len(w) >= 1, 'Expected at least one DeprecationWarning' - deprecation_warnings = [x for x in w if issubclass(x.category, DeprecationWarning)] - assert len(deprecation_warnings) >= 1, 'Expected a DeprecationWarning' - msg = str(deprecation_warnings[0].message) - assert 'deprecated' in msg.lower() - assert 'legacy.collection_base' in msg + assert len(caplog.records) >= 1, 'Expected at least one log record' + messages = [r.message for r in caplog.records] + combined = ' '.join(messages) + assert 'deprecated' in combined.lower() + assert 'legacy.collection_base' in combined -def test_collection_base_still_works_from_deprecated(): +def test_collection_base_still_works_from_deprecated(caplog: 'pytest.LogCaptureFixture'): """The class imported from the deprecated wrapper still works.""" - with warnings.catch_warnings(): - warnings.simplefilter('ignore', DeprecationWarning) + with caplog.at_level(logging.ERROR, logger='easyscience'): from easyscience.base_classes.collection_base import CollectionBase # noqa: F811 from easyscience import Parameter @@ -61,24 +61,23 @@ def test_collection_base_still_works_from_deprecated(): # --------------------------------------------------------------------------- -def test_import_obj_base_warns(): - """Importing easyscience.base_classes.obj_base emits DeprecationWarning.""" - with warnings.catch_warnings(record=True) as w: - warnings.simplefilter('always') - from easyscience.base_classes.obj_base import ObjBase # noqa: F811 +def test_import_obj_base_warns(caplog: 'pytest.LogCaptureFixture'): + """Importing easyscience.base_classes.obj_base logs a WARNING.""" + import easyscience.base_classes.obj_base + + with caplog.at_level(logging.WARNING, logger='easyscience'): + importlib.reload(easyscience.base_classes.obj_base) - assert len(w) >= 1, 'Expected at least one DeprecationWarning' - deprecation_warnings = [x for x in w if issubclass(x.category, DeprecationWarning)] - assert len(deprecation_warnings) >= 1, 'Expected a DeprecationWarning' - msg = str(deprecation_warnings[0].message) - assert 'deprecated' in msg.lower() - assert 'legacy.obj_base' in msg + assert len(caplog.records) >= 1, 'Expected at least one log record' + messages = [r.message for r in caplog.records] + combined = ' '.join(messages) + assert 'deprecated' in combined.lower() + assert 'legacy.obj_base' in combined -def test_obj_base_still_works_from_deprecated(): +def test_obj_base_still_works_from_deprecated(caplog: 'pytest.LogCaptureFixture'): """The class imported from the deprecated wrapper still works.""" - with warnings.catch_warnings(): - warnings.simplefilter('ignore', DeprecationWarning) + with caplog.at_level(logging.ERROR, logger='easyscience'): from easyscience.base_classes.obj_base import ObjBase # noqa: F811 from easyscience import Parameter diff --git a/tests/unit/base_classes/test_easy_list.py b/tests/unit/base_classes/test_easy_list.py index daee3519..69b9bf6e 100644 --- a/tests/unit/base_classes/test_easy_list.py +++ b/tests/unit/base_classes/test_easy_list.py @@ -1,7 +1,7 @@ # SPDX-FileCopyrightText: 2026 EasyScience contributors # SPDX-License-Identifier: BSD-3-Clause -import warnings +import logging import pytest @@ -219,27 +219,25 @@ def test_setitem_slice(self): assert el[0].unique_name == 'a3' assert el[1].unique_name == 'a4' - def test_setitem_self_replacement_int(self): + def test_setitem_self_replacement_int(self, caplog: 'pytest.LogCaptureFixture'): """e[0] = e[0] should work without warning.""" a1 = Alpha(unique_name='a1') a2 = Alpha(unique_name='a2') el = EasyList(a1, a2, protected_types=Alpha) - with warnings.catch_warnings(record=True) as w: - warnings.simplefilter('always') + with caplog.at_level(logging.WARNING, logger='easyscience.base_classes'): el[0] = el[0] - assert len(w) == 0 + assert len(caplog.records) == 0 assert el[0].unique_name == 'a1' assert len(el) == 2 - def test_setitem_self_replacement_slice(self): + def test_setitem_self_replacement_slice(self, caplog: 'pytest.LogCaptureFixture'): """e[0:2] = e[0:2] should work without warning.""" a1 = Alpha(unique_name='a1') a2 = Alpha(unique_name='a2') el = EasyList(a1, a2, protected_types=Alpha) - with warnings.catch_warnings(record=True) as w: - warnings.simplefilter('always') + with caplog.at_level(logging.WARNING, logger='easyscience.base_classes'): el[0:2] = [el[0], el[1]] - assert len(w) == 0 + assert len(caplog.records) == 0 assert el[0].unique_name == 'a1' assert el[1].unique_name == 'a2' @@ -306,49 +304,45 @@ def test_delitem_invalid_type(self, populated_list): # --- Uniqueness --- - def test_append_duplicate_warns(self): + def test_append_duplicate_warns(self, caplog: 'pytest.LogCaptureFixture'): a1 = Alpha(unique_name='a1') el = EasyList(a1, protected_types=Alpha) - with warnings.catch_warnings(record=True) as w: - warnings.simplefilter('always') + with caplog.at_level(logging.WARNING, logger='easyscience.base_classes'): el.append(a1) - assert len(w) == 1 - assert 'already in EasyList' in str(w[0].message) + assert len(caplog.records) == 1 + assert 'already in EasyList' in caplog.records[0].message assert len(el) == 1 - def test_insert_duplicate_warns(self): + def test_insert_duplicate_warns(self, caplog: 'pytest.LogCaptureFixture'): a1 = Alpha(unique_name='a1') el = EasyList(a1, protected_types=Alpha) - with warnings.catch_warnings(record=True) as w: - warnings.simplefilter('always') + with caplog.at_level(logging.WARNING, logger='easyscience.base_classes'): el.insert(0, a1) - assert len(w) == 1 - assert 'already in EasyList' in str(w[0].message) + assert len(caplog.records) == 1 + assert 'already in EasyList' in caplog.records[0].message assert len(el) == 1 - def test_setitem_duplicate_warns(self): + def test_setitem_duplicate_warns(self, caplog: 'pytest.LogCaptureFixture'): a1 = Alpha(unique_name='a1') a2 = Alpha(unique_name='a2') el = EasyList(a1, a2, protected_types=Alpha) - with warnings.catch_warnings(record=True) as w: - warnings.simplefilter('always') + with caplog.at_level(logging.WARNING, logger='easyscience.base_classes'): el[0] = a2 # a2 already at index 1 - assert len(w) == 1 - assert 'already in EasyList' in str(w[0].message) + assert len(caplog.records) == 1 + assert 'already in EasyList' in caplog.records[0].message # Original value should remain unchanged assert el[0].unique_name == 'a1' - def test_setitem_slice_duplicate_warns(self): + def test_setitem_slice_duplicate_warns(self, caplog: 'pytest.LogCaptureFixture'): a1 = Alpha(unique_name='a1') a2 = Alpha(unique_name='a2') a3 = Alpha(unique_name='a3') a4 = Alpha(unique_name='a4') el = EasyList(a1, a2, a3, protected_types=Alpha) - with warnings.catch_warnings(record=True) as w: - warnings.simplefilter('always') + with caplog.at_level(logging.WARNING, logger='easyscience.base_classes'): el[0:3] = [a1, a3, a4] # a3 already at index 2 - assert len(w) == 1 - assert 'already in EasyList' in str(w[0].message) + assert len(caplog.records) == 1 + assert 'already in EasyList' in caplog.records[0].message assert el[0].unique_name == 'a1' assert el[1].unique_name == 'a2' # a3 should not replace a2 because it's a duplicate assert el[2].unique_name == 'a4' diff --git a/tests/unit/fitting/calculators/test_interface_factory.py b/tests/unit/fitting/calculators/test_interface_factory.py index cab3b30f..ce5bb17a 100644 --- a/tests/unit/fitting/calculators/test_interface_factory.py +++ b/tests/unit/fitting/calculators/test_interface_factory.py @@ -1,6 +1,7 @@ # SPDX-FileCopyrightText: 2026 EasyScience contributors # SPDX-License-Identifier: BSD-3-Clause +import logging from unittest.mock import MagicMock import pytest @@ -204,7 +205,9 @@ def test_switch_with_fitter_having_generate_bindings(self, factory_single_interf # Then mock_fitter.generate_bindings.assert_called_once() - def test_switch_with_fitter_exception_handling(self, factory_single_interface, capsys): + def test_switch_with_fitter_exception_handling( + self, factory_single_interface, caplog: 'pytest.LogCaptureFixture' + ): """Test switch handles exceptions in fitter binding updates gracefully""" # Given mock_fit_object = MagicMock() @@ -213,12 +216,12 @@ def test_switch_with_fitter_exception_handling(self, factory_single_interface, c mock_fitter._fit_object = mock_fit_object # When - factory_single_interface.switch('MockInterface1', fitter=mock_fitter) + with caplog.at_level(logging.WARNING, logger='easyscience.fitting.calculators'): + factory_single_interface.switch('MockInterface1', fitter=mock_fitter) # Then - captured = capsys.readouterr() - assert 'Unable to auto generate bindings' in captured.out - assert 'Test exception' in captured.out + assert 'Unable to auto generate bindings' in caplog.text + assert 'Test exception' in caplog.text def test_fit_func_property_returns_callable(self, factory_single_interface): """Test fit_func property returns a callable""" @@ -363,7 +366,7 @@ def test_return_name_static_method_without_name_attribute(self, mock_interface1) assert name == 'MockInterface1' def test_switch_with_fitter_generate_bindings_exception( - self, factory_single_interface, capsys + self, factory_single_interface, caplog: 'pytest.LogCaptureFixture' ): """Test switch handles exceptions in fitter.generate_bindings gracefully""" # Given @@ -374,12 +377,12 @@ def test_switch_with_fitter_generate_bindings_exception( del mock_fitter._fit_object # When - factory_single_interface.switch('MockInterface1', fitter=mock_fitter) + with caplog.at_level(logging.WARNING, logger='easyscience.fitting.calculators'): + factory_single_interface.switch('MockInterface1', fitter=mock_fitter) # Then - captured = capsys.readouterr() - assert 'Unable to auto generate bindings' in captured.out - assert 'Generate bindings test exception' in captured.out + assert 'Unable to auto generate bindings' in caplog.text + assert 'Generate bindings test exception' in caplog.text def test_generate_bindings_with_property_without_value_no_call_back( self, factory_single_interface diff --git a/tests/unit/fitting/minimizers/test_minimizer_bumps.py b/tests/unit/fitting/minimizers/test_minimizer_bumps.py index 6b587dd7..c889cf01 100644 --- a/tests/unit/fitting/minimizers/test_minimizer_bumps.py +++ b/tests/unit/fitting/minimizers/test_minimizer_bumps.py @@ -1,6 +1,7 @@ # SPDX-FileCopyrightText: 2026 EasyScience contributors # SPDX-License-Identifier: BSD-3-Clause +import logging from unittest.mock import ANY from unittest.mock import MagicMock from unittest.mock import patch @@ -194,7 +195,9 @@ def test_set_parameter_fit_result_no_stack_status(self, minimizer: Bumps): assert minimizer._cached_pars['b'].value == 2.0 assert minimizer._cached_pars['b'].error == 0.2 - def test_gen_fit_results(self, minimizer: Bumps, monkeypatch): + def test_gen_fit_results( + self, minimizer: Bumps, monkeypatch, caplog: 'pytest.LogCaptureFixture' + ): # When mock_domain_fit_results = MagicMock() mock_FitResults = MagicMock(return_value=mock_domain_fit_results) @@ -224,12 +227,13 @@ def test_gen_fit_results(self, minimizer: Bumps, monkeypatch): minimizer.evaluate = MagicMock(return_value='evaluate') # Then - with pytest.warns(UserWarning, match='maximum optimizer steps of 3'): + with caplog.at_level(logging.WARNING, logger='easyscience.fitting.bumps'): domain_fit_results = minimizer._gen_fit_results( mock_fit_result, max_evaluations=3, **{'kwargs_set_key': 'kwargs_set_val'}, ) + assert 'maximum optimizer steps of 3' in caplog.text # Expect assert domain_fit_results == mock_domain_fit_results @@ -636,7 +640,9 @@ def test_fit_exception_restores_values(self, minimizer: Bumps, monkeypatch) -> N assert parameter.value == 1.0 - def test_gen_fit_results_uses_nit_for_budget_check(self, minimizer: Bumps, monkeypatch): + def test_gen_fit_results_uses_nit_for_budget_check( + self, minimizer: Bumps, monkeypatch, caplog: 'pytest.LogCaptureFixture' + ): mock_domain_fit_results = MagicMock() mock_FitResults = MagicMock(return_value=mock_domain_fit_results) monkeypatch.setattr( @@ -662,9 +668,11 @@ def test_gen_fit_results_uses_nit_for_budget_check(self, minimizer: Bumps, monke minimizer._eval_counter = MagicMock(count=2) minimizer.evaluate = MagicMock(return_value='evaluate') - with pytest.warns(UserWarning, match='maximum optimizer steps of 3'): + with caplog.at_level(logging.WARNING, logger='easyscience.fitting.bumps'): domain_fit_results = minimizer._gen_fit_results(mock_fit_result, max_evaluations=3) + assert 'maximum optimizer steps of 3' in caplog.text + assert domain_fit_results.success == False assert domain_fit_results.n_evaluations == 2 assert domain_fit_results.iterations == 100 diff --git a/tests/unit/fitting/minimizers/test_minimizer_dfo.py b/tests/unit/fitting/minimizers/test_minimizer_dfo.py index 37c9b2ef..823dcce5 100644 --- a/tests/unit/fitting/minimizers/test_minimizer_dfo.py +++ b/tests/unit/fitting/minimizers/test_minimizer_dfo.py @@ -1,7 +1,7 @@ # SPDX-FileCopyrightText: 2026 EasyScience contributors # SPDX-License-Identifier: BSD-3-Clause -import warnings +import logging from unittest.mock import MagicMock import numpy as np @@ -386,7 +386,7 @@ def test_gen_fit_results(self, minimizer: DFO, monkeypatch): ) def test_gen_fit_results_maxfun_warning_sets_success_false_and_warns( - self, minimizer: DFO, monkeypatch + self, minimizer: DFO, monkeypatch, caplog: 'pytest.LogCaptureFixture' ): """When DFO returns EXIT_MAXFUN_WARNING, _gen_fit_results must warn and set success=False.""" mock_domain_fit_results = MagicMock() @@ -413,20 +413,18 @@ def test_gen_fit_results_maxfun_warning_sets_success_false_and_warns( minimizer._p_0 = 'p_0' minimizer.evaluate = MagicMock(return_value='evaluate') - with pytest.warns(UserWarning, match='Objective has been called MAXFUN times'): + with caplog.at_level(logging.WARNING, logger='easyscience.fitting.dfo'): domain_fit_results = minimizer._gen_fit_results(mock_fit_result, np.array([1.0])) - assert domain_fit_results.success == False - assert domain_fit_results.n_evaluations == 50 - assert domain_fit_results.message == 'Objective has been called MAXFUN times' - - def test_extract_iterations_from_diagnostic_dict(self) -> None: + assert 'Objective has been called MAXFUN times' in caplog.text fit_results = MagicMock() fit_results.diagnostic_info = {'iters_total': [1, 2, 5]} assert DFO._extract_iterations(fit_results) == 5 - def test_gen_fit_results_success_does_not_warn(self, minimizer: DFO, monkeypatch): + def test_gen_fit_results_success_does_not_warn( + self, minimizer: DFO, monkeypatch, caplog: 'pytest.LogCaptureFixture' + ): mock_domain_fit_results = MagicMock() mock_FitResults = MagicMock(return_value=mock_domain_fit_results) monkeypatch.setattr( @@ -451,9 +449,10 @@ def test_gen_fit_results_success_does_not_warn(self, minimizer: DFO, monkeypatch minimizer._p_0 = 'p_0' minimizer.evaluate = MagicMock(return_value='evaluate') - with pytest.warns(UserWarning, match='Objective has been called MAXFUN times'): + with caplog.at_level(logging.WARNING, logger='easyscience.fitting.dfo'): domain_fit_results = minimizer._gen_fit_results(mock_fit_result, np.array([1.0])) + assert 'Objective has been called MAXFUN times' in caplog.text assert domain_fit_results.success == False assert domain_fit_results.n_evaluations == 50 assert domain_fit_results.message == 'Objective has been called MAXFUN times' @@ -469,7 +468,9 @@ def test_dfo_fit_allows_maxfun_warning(self, minimizer: DFO, monkeypatch) -> Non easyscience.fitting.minimizers.minimizer_dfo.dfols, 'solve', mock_solve ) - def test_gen_fit_results_success_does_not_warn(self, minimizer: DFO, monkeypatch): + def test_gen_fit_results_success_does_not_warn( + self, minimizer: DFO, monkeypatch, caplog: 'pytest.LogCaptureFixture' + ): mock_domain_fit_results = MagicMock() mock_FitResults = MagicMock(return_value=mock_domain_fit_results) monkeypatch.setattr( @@ -494,11 +495,10 @@ def test_gen_fit_results_success_does_not_warn(self, minimizer: DFO, monkeypatch minimizer._p_0 = 'p_0' minimizer.evaluate = MagicMock(return_value='evaluate') - with warnings.catch_warnings(record=True) as record: - warnings.simplefilter('always') + with caplog.at_level(logging.WARNING, logger='easyscience.fitting.dfo'): domain_fit_results = minimizer._gen_fit_results(mock_fit_result, np.array([1.0])) - assert len(record) == 0 + assert len(caplog.records) == 0 assert domain_fit_results.success == True def test_dfo_fit_allows_maxfun_warning(self, minimizer: DFO, monkeypatch) -> None: diff --git a/tests/unit/fitting/minimizers/test_minimizer_lmfit.py b/tests/unit/fitting/minimizers/test_minimizer_lmfit.py index e4ca2627..781893d9 100644 --- a/tests/unit/fitting/minimizers/test_minimizer_lmfit.py +++ b/tests/unit/fitting/minimizers/test_minimizer_lmfit.py @@ -1,7 +1,7 @@ # SPDX-FileCopyrightText: 2026 EasyScience contributors # SPDX-License-Identifier: BSD-3-Clause -import warnings +import logging from unittest.mock import ANY from unittest.mock import MagicMock @@ -340,7 +340,9 @@ def test_fit_exception(self, minimizer: LMFit) -> None: with pytest.raises(FitError): minimizer.fit(x=1.0, y=2.0, weights=1) - def test_gen_fit_results_populates_evaluation_metadata(self, minimizer: LMFit) -> None: + def test_gen_fit_results_populates_evaluation_metadata( + self, minimizer: LMFit, caplog: 'pytest.LogCaptureFixture' + ) -> None: fit_results = MagicMock() fit_results.success = False fit_results.data = 'data' @@ -352,16 +354,20 @@ def test_gen_fit_results_populates_evaluation_metadata(self, minimizer: LMFit) - fit_results.nfev = 9 fit_results.message = 'max evaluations reached' - with pytest.warns(UserWarning, match='max evaluations reached'): + with caplog.at_level(logging.WARNING, logger='easyscience.fitting.lmfit'): result = minimizer._gen_fit_results(fit_results, iterations=4) + assert 'max evaluations reached' in caplog.text + assert result.success is False assert result.n_evaluations == 9 assert result.iterations == 4 assert result.message == 'max evaluations reached' assert result.engine_result == fit_results - def test_gen_fit_results_success_does_not_warn(self, minimizer: LMFit) -> None: + def test_gen_fit_results_success_does_not_warn( + self, minimizer: LMFit, caplog: 'pytest.LogCaptureFixture' + ) -> None: fit_results = MagicMock() fit_results.success = True fit_results.data = 'data' @@ -373,11 +379,10 @@ def test_gen_fit_results_success_does_not_warn(self, minimizer: LMFit) -> None: fit_results.nfev = 3 fit_results.message = 'success' - with warnings.catch_warnings(record=True) as record: - warnings.simplefilter('always') + with caplog.at_level(logging.WARNING, logger='easyscience.fitting.lmfit'): result = minimizer._gen_fit_results(fit_results) - assert len(record) == 0 + assert len(caplog.records) == 0 assert result.success is True def test_convert_to_pars_obj(self, minimizer: LMFit, monkeypatch) -> None: diff --git a/tests/unit/global_object/test_logger.py b/tests/unit/global_object/test_logger.py new file mode 100644 index 00000000..3923ad39 --- /dev/null +++ b/tests/unit/global_object/test_logger.py @@ -0,0 +1,356 @@ +# SPDX-FileCopyrightText: 2026 EasyScience contributors +# SPDX-License-Identifier: BSD-3-Clause + +"""Tests for easyscience.global_object.logger. + +Covers the module-level parsing helpers and the public surface of the +``Logger`` class: the ``level`` property, ``getLogger``, the convenience +delegation methods, the ``at_level`` context manager and the +``suspend``/``resume`` shims. +""" + +import logging + +import pytest + +from easyscience.global_object.logger import _LOG_LEVEL_ENV_VAR +from easyscience.global_object.logger import PACKAGE_LOGGER_NAME +from easyscience.global_object.logger import Logger +from easyscience.global_object.logger import _env_log_level +from easyscience.global_object.logger import _parse_log_level + + +@pytest.fixture(autouse=True) +def _restore_package_logger_level(): + """Snapshot and restore the package-root logger level around each test. + + ``Logger`` operates on the process-wide ``easyscience`` logger, so a + test that changes its level would otherwise leak into other tests. + """ + package_logger = logging.getLogger(PACKAGE_LOGGER_NAME) + previous = package_logger.level + yield + package_logger.setLevel(previous) + + +# --------------------------------------------------------------------------- +# _parse_log_level +# --------------------------------------------------------------------------- + + +class TestParseLogLevel: + def test_int_passthrough(self): + # When Then + assert _parse_log_level(logging.ERROR) == logging.ERROR + assert _parse_log_level(42) == 42 + + @pytest.mark.parametrize( + 'name, expected', + [ + ('DEBUG', logging.DEBUG), + ('INFO', logging.INFO), + ('WARNING', logging.WARNING), + ('ERROR', logging.ERROR), + ('CRITICAL', logging.CRITICAL), + ], + ) + def test_level_names(self, name, expected): + # When Then + assert _parse_log_level(name) == expected + + def test_name_is_case_insensitive_and_stripped(self): + # When Then + assert _parse_log_level(' error ') == logging.ERROR + assert _parse_log_level('Warning') == logging.WARNING + + def test_numeric_string(self): + # When Then + assert _parse_log_level('40') == 40 + assert _parse_log_level(' 10 ') == 10 + + def test_unknown_name_raises_value_error(self): + # When Then + with pytest.raises(ValueError) as exc: + _parse_log_level('VERBOSE') + # Expect the message to name the offending value and list valid options + assert 'VERBOSE' in str(exc.value) + assert 'WARNING' in str(exc.value) + + +# --------------------------------------------------------------------------- +# _env_log_level +# --------------------------------------------------------------------------- + + +class TestEnvLogLevel: + def test_none_returns_default(self): + # When Then + assert _env_log_level(None, default=logging.WARNING) == logging.WARNING + + def test_valid_value_is_parsed(self): + # When Then + assert _env_log_level('ERROR', default=logging.WARNING) == logging.ERROR + assert _env_log_level('10', default=logging.WARNING) == 10 + + def test_bad_value_falls_back_to_default(self): + # When Then — a typo must not raise, it falls back to the default + assert _env_log_level('NOPE', default=logging.INFO) == logging.INFO + + +# --------------------------------------------------------------------------- +# Logger.__init__ +# --------------------------------------------------------------------------- + + +class TestLoggerInit: + def test_default_level_is_warning(self, monkeypatch): + # Given no env var set + monkeypatch.delenv(_LOG_LEVEL_ENV_VAR, raising=False) + + # When + log = Logger() + + # Then + assert log.level == logging.WARNING + assert log.logger.name == PACKAGE_LOGGER_NAME + + def test_custom_default_level(self, monkeypatch): + # Given + monkeypatch.delenv(_LOG_LEVEL_ENV_VAR, raising=False) + + # When + log = Logger(log_level=logging.DEBUG) + + # Then + assert log.level == logging.DEBUG + + def test_env_var_overrides_default(self, monkeypatch): + # Given the env var requests ERROR + monkeypatch.setenv(_LOG_LEVEL_ENV_VAR, 'ERROR') + + # When the default would have been WARNING + log = Logger(log_level=logging.WARNING) + + # Then the env var wins + assert log.level == logging.ERROR + + def test_invalid_env_var_falls_back_to_default(self, monkeypatch): + # Given a typo'd env var + monkeypatch.setenv(_LOG_LEVEL_ENV_VAR, 'NONSENSE') + + # When + log = Logger(log_level=logging.INFO) + + # Then import does not crash and the default is used + assert log.level == logging.INFO + + +# --------------------------------------------------------------------------- +# Logger.level property +# --------------------------------------------------------------------------- + + +class TestLevelProperty: + def test_getter_reflects_underlying_logger(self): + # Given + log = Logger() + log.logger.setLevel(logging.CRITICAL) + + # When Then + assert log.level == logging.CRITICAL + + def test_setter_accepts_int(self): + # Given + log = Logger() + + # When + log.level = logging.DEBUG + + # Then + assert log.logger.level == logging.DEBUG + + def test_setter_accepts_level_name(self): + # Given + log = Logger() + + # When + log.level = 'ERROR' + + # Then + assert log.logger.level == logging.ERROR + + def test_setter_raises_on_unknown_name(self): + # Given + log = Logger() + + # When Then — the public API must be strict + with pytest.raises(ValueError): + log.level = 'LOUD' + + +# --------------------------------------------------------------------------- +# Logger.getLogger +# --------------------------------------------------------------------------- + + +class TestGetLogger: + def test_prefixes_with_package_name(self): + # Given + log = Logger() + + # When + child = log.getLogger('fitting') + + # Then + assert child.name == f'{PACKAGE_LOGGER_NAME}.fitting' + + def test_does_not_double_prefix(self): + # Given a name that already starts with the package name + log = Logger() + + # When + child = log.getLogger(f'{PACKAGE_LOGGER_NAME}.fitting.bumps') + + # Then + assert child.name == f'{PACKAGE_LOGGER_NAME}.fitting.bumps' + + def test_child_is_left_at_notset_to_inherit(self): + # Given + log = Logger() + + # When + child = log.getLogger('some_unique_subsystem') + + # Then it inherits configuration from the package root + assert child.level == logging.NOTSET + + +# --------------------------------------------------------------------------- +# Convenience delegation methods +# --------------------------------------------------------------------------- + + +class TestConvenienceMethods: + @pytest.mark.parametrize( + 'method, level', + [ + ('debug', logging.DEBUG), + ('info', logging.INFO), + ('warning', logging.WARNING), + ('error', logging.ERROR), + ('critical', logging.CRITICAL), + ], + ) + def test_methods_emit_at_expected_level(self, caplog, method, level): + # Given + log = Logger() + log.level = logging.DEBUG + + # When + with caplog.at_level(logging.DEBUG, logger=PACKAGE_LOGGER_NAME): + getattr(log, method)('hello %s', 'world') + + # Then + records = [r for r in caplog.records if r.name == PACKAGE_LOGGER_NAME] + assert len(records) == 1 + assert records[0].levelno == level + assert records[0].getMessage() == 'hello world' + + def test_exception_logs_at_error_with_traceback(self, caplog): + # Given + log = Logger() + log.level = logging.DEBUG + + # When + with caplog.at_level(logging.DEBUG, logger=PACKAGE_LOGGER_NAME): + try: + raise RuntimeError('boom') + except RuntimeError: + log.exception('caught it') + + # Then + records = [r for r in caplog.records if r.name == PACKAGE_LOGGER_NAME] + assert len(records) == 1 + assert records[0].levelno == logging.ERROR + assert records[0].exc_info is not None + + +# --------------------------------------------------------------------------- +# Logger.at_level context manager +# --------------------------------------------------------------------------- + + +class TestAtLevel: + def test_temporarily_sets_and_restores_level(self): + # Given + log = Logger() + log.level = logging.WARNING + + # When + with log.at_level(logging.ERROR): + # Then inside the context the temporary level applies + assert log.level == logging.ERROR + + # Then the previous level is restored on exit + assert log.level == logging.WARNING + + def test_accepts_level_name(self): + # Given + log = Logger() + log.level = logging.INFO + + # When + with log.at_level('CRITICAL'): + assert log.level == logging.CRITICAL + + # Then + assert log.level == logging.INFO + + def test_restores_level_on_exception(self): + # Given + log = Logger() + log.level = logging.WARNING + + # When an exception escapes the context + with pytest.raises(RuntimeError): + with log.at_level(logging.ERROR): + raise RuntimeError('boom') + + # Then the previous level is still restored + assert log.level == logging.WARNING + + +# --------------------------------------------------------------------------- +# suspend / resume shims +# --------------------------------------------------------------------------- + + +class TestSuspendResume: + def test_suspend_silences_then_resume_restores(self): + # Given + log = Logger() + log.level = logging.INFO + + # When + log.suspend() + + # Then nothing below CRITICAL gets through + assert log.level > logging.CRITICAL + + # When + log.resume() + + # Then the pre-suspend level is restored + assert log.level == logging.INFO + + def test_resume_uses_level_captured_at_suspend(self): + # Given a level set before suspending + log = Logger() + log.level = logging.ERROR + log.suspend() + + # When + log.resume() + + # Then + assert log.level == logging.ERROR diff --git a/tests/unit/legacy/test_collection_base.py b/tests/unit/legacy/test_collection_base.py index 1a1115da..152a0a37 100644 --- a/tests/unit/legacy/test_collection_base.py +++ b/tests/unit/legacy/test_collection_base.py @@ -7,7 +7,7 @@ tests/unit/base_classes/test_collection_base.py suite. """ -import warnings +import logging import pytest @@ -40,14 +40,14 @@ def setup_pars(): # Deprecation warning on instantiation # --------------------------------------------------------------------------- -def test_instantiation_emits_deprecation_warning(): - """Instantiating CollectionBase should emit a DeprecationWarning.""" - with warnings.catch_warnings(record=True) as w: - warnings.simplefilter('always') +def test_instantiation_emits_deprecation_warning(caplog: "pytest.LogCaptureFixture"): + """Instantiating CollectionBase should log a deprecation warning.""" + with caplog.at_level(logging.WARNING, logger='easyscience.legacy'): CollectionBase('test') - deprecation_warnings = [x for x in w if issubclass(x.category, DeprecationWarning)] - assert len(deprecation_warnings) >= 1 - assert 'deprecated' in str(deprecation_warnings[0].message).lower() + assert len(caplog.records) >= 1 + messages = [r.message for r in caplog.records] + combined = ' '.join(messages) + assert 'deprecated' in combined.lower() # --------------------------------------------------------------------------- diff --git a/tests/unit/legacy/test_obj_base.py b/tests/unit/legacy/test_obj_base.py index 650f0579..fc33c424 100644 --- a/tests/unit/legacy/test_obj_base.py +++ b/tests/unit/legacy/test_obj_base.py @@ -7,7 +7,7 @@ tests/unit/base_classes/test_obj_base.py suite. """ -import warnings +import logging from typing import ClassVar import pytest @@ -28,14 +28,14 @@ def _clear_map(): # Deprecation warning on instantiation # --------------------------------------------------------------------------- -def test_instantiation_emits_deprecation_warning(): - """Instantiating ObjBase should emit a DeprecationWarning.""" - with warnings.catch_warnings(record=True) as w: - warnings.simplefilter('always') +def test_instantiation_emits_deprecation_warning(caplog: "pytest.LogCaptureFixture"): + """Instantiating ObjBase should log a deprecation warning.""" + with caplog.at_level(logging.WARNING, logger='easyscience.legacy'): ObjBase('test') - deprecation_warnings = [x for x in w if issubclass(x.category, DeprecationWarning)] - assert len(deprecation_warnings) >= 1 - assert 'deprecated' in str(deprecation_warnings[0].message).lower() + assert len(caplog.records) >= 1 + messages = [r.message for r in caplog.records] + combined = ' '.join(messages) + assert 'deprecated' in combined.lower() # ---------------------------------------------------------------------------