diff --git a/bioengine/_app/accessors.py b/bioengine/_app/accessors.py index 2106f4c..72e1cbb 100644 --- a/bioengine/_app/accessors.py +++ b/bioengine/_app/accessors.py @@ -24,7 +24,6 @@ _datasets_singleton: Optional["BioEngineDatasets"] = None -_logger_singleton: Optional[logging.Logger] = None def _get_datasets() -> "BioEngineDatasets": @@ -65,25 +64,30 @@ def _get_datasets() -> "BioEngineDatasets": def _get_logger() -> logging.Logger: - """Return the process-local logger. + """Return the logger for the current process. Inside a Ray Serve replica the appropriate logger is ``ray.serve`` — Ray installs handlers that route logs into the replica log files. - Elsewhere we fall back to a plain ``bioengine.app`` logger. - """ - global _logger_singleton - if _logger_singleton is not None: - return _logger_singleton + Elsewhere (notably the worker's introspection Ray task) we fall back to + ``bioengine.app``, configured on first use so the fallback is merely + degraded rather than silent: unconfigured, it inherits the root level of + ``WARNING`` and has no handler, so ``INFO`` records are dropped outright. + Deliberately not cached. ``BIOENGINE_REPLICA`` is only true once the + replica's environment is in place, and a cached fallback would outlive it. + """ if os.environ.get("BIOENGINE_REPLICA") == "1": - _logger_singleton = logging.getLogger("ray.serve") - else: - _logger_singleton = logging.getLogger("bioengine.app") - return _logger_singleton + return logging.getLogger("ray.serve") + + logger = logging.getLogger("bioengine.app") + if not logger.handlers: + from bioengine.utils import create_logger + + logger = create_logger("bioengine.app") + return logger def _reset_for_tests() -> None: - """Drop cached singletons so tests can re-init under different env vars.""" - global _datasets_singleton, _logger_singleton + """Drop the cached datasets so tests can re-init under different env vars.""" + global _datasets_singleton _datasets_singleton = None - _logger_singleton = None diff --git a/bioengine/_app/bootstrap.py b/bioengine/_app/bootstrap.py index 8dc6932..cde969f 100644 --- a/bioengine/_app/bootstrap.py +++ b/bioengine/_app/bootstrap.py @@ -493,6 +493,14 @@ def build_and_run_application( for key, value in replica_env_vars.items(): os.environ[key] = value + # ``_setup_replica`` also sets this, but only once the user's ``__init__`` + # is already running — far too late for a module-scope ``bioengine.logger``, + # which is evaluated during the import inside ``cloudpickle.loads``. Putting + # it in the replica's runtime_env makes it true from the replica's first + # line. Deliberately added after the loop above: this build task is not + # itself a replica. + replica_env_vars = {**replica_env_vars, "BIOENGINE_REPLICA": "1"} + head_app_dir = Path(replica_env_vars["BIOENGINE_APP_DIR"]) head_version = replica_env_vars.get("BIOENGINE_ARTIFACT_VERSION") or spec.get( "version", "" diff --git a/tests/_app/test_replica_logger.py b/tests/_app/test_replica_logger.py new file mode 100644 index 0000000..cf27b64 --- /dev/null +++ b/tests/_app/test_replica_logger.py @@ -0,0 +1,81 @@ +"""A logger bound at module scope must still reach the replica log. + +``bioengine.logger`` resolves to ``ray.serve`` inside a replica and to +``bioengine.app`` everywhere else. The branch is decided by +``BIOENGINE_REPLICA``, which ``_setup_replica`` sets in-process — after the +user module has already been imported. A module-scope +``logger = bioengine.logger`` therefore took the fallback branch, and that +logger had neither a level nor a handler, so every ``INFO`` record it was +given was dropped before it could reach the replica log. +""" + +from __future__ import annotations + +import logging + +import pytest + +import bioengine +from bioengine._app import accessors + + +@pytest.fixture(autouse=True) +def _restore_app_logger(): + """Undo the process-global configuration the fallback branch installs.""" + logger = logging.getLogger("bioengine.app") + handlers = list(logger.handlers) + level, propagate = logger.level, logger.propagate + yield + logger.handlers = handlers + logger.setLevel(level) + logger.propagate = propagate + + +def test_replica_env_var_selects_the_ray_serve_logger(monkeypatch) -> None: + monkeypatch.setenv("BIOENGINE_REPLICA", "1") + assert accessors._get_logger() is logging.getLogger("ray.serve") + + +def test_falls_back_outside_a_replica(monkeypatch) -> None: + monkeypatch.delenv("BIOENGINE_REPLICA", raising=False) + assert accessors._get_logger() is logging.getLogger("bioengine.app") + + +def test_the_branch_is_re_evaluated_not_cached(monkeypatch) -> None: + """``_setup_replica`` sets the env var late; a cached fallback outlives it.""" + monkeypatch.delenv("BIOENGINE_REPLICA", raising=False) + assert accessors._get_logger().name == "bioengine.app" + + monkeypatch.setenv("BIOENGINE_REPLICA", "1") + assert accessors._get_logger().name == "ray.serve" + + +def test_module_scope_access_in_a_replica_reaches_ray_serve(monkeypatch) -> None: + """The failing case: the env var comes from the replica's runtime_env, so + it is already true when the user module is imported.""" + monkeypatch.setenv("BIOENGINE_REPLICA", "1") + assert bioengine.logger is logging.getLogger("ray.serve") + + +def test_the_fallback_logger_actually_emits_info(monkeypatch) -> None: + """Unconfigured, ``bioengine.app`` inherits the root level of WARNING and + has no handler — an ``INFO`` call is discarded outright.""" + monkeypatch.delenv("BIOENGINE_REPLICA", raising=False) + logger = logging.getLogger("bioengine.app") + logger.handlers = [] + logger.setLevel(logging.NOTSET) + + logger = accessors._get_logger() + + assert logger.isEnabledFor(logging.INFO) + assert logger.handlers + + +def test_the_fallback_logger_is_configured_once(monkeypatch) -> None: + monkeypatch.delenv("BIOENGINE_REPLICA", raising=False) + logging.getLogger("bioengine.app").handlers = [] + + first = accessors._get_logger() + accessors._get_logger() + + assert len(first.handlers) == 1