fix(_app): a logger bound at module scope no longer discards every record

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

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", ""

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