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

[nilsmechtel]

An app that writes logger = bioengine.logger at the top of its module gets a logger that silently discards everything it is given. The same line inside a method works. Nothing in the API distinguishes the two, and nothing warns — the records simply never appear in the replica log.

Tracked as #0022 in the session backlog.

Why the placement decides whether logging works

bioengine.logger resolves through _get_logger(), which picks ray.serve inside a replica and bioengine.app everywhere else. The branch is decided by BIOENGINE_REPLICA, and the only thing that ever set it was mixin.py:40, inside _setup_replica — which runs from the user's wrapped __init__.

By then the module has long been imported. Ray Serve reconstructs the deployment class in cloudpickle.loads, which imports the user module, which evaluates module-scope statements. BIOENGINE_REPLICA is unset at that instant, so the fallback branch is taken — and the result was cached in _logger_singleton for the life of the process, so the later in-process os.environ write could never repair it.

The fallback is not a quieter logger, it is a mute one. bioengine.app is never configured anywhere: no level, so it inherits the root's WARNING and isEnabledFor(INFO) is false; no handler, so anything that did pass the level check would fall to logging.lastResort and print unformatted to stderr rather than into the replica log file.

Confirmed on two live replicas — BIOENGINE_REPLICA was absent from /proc/<pid>/environ in both.

Three changes, in order of what they fix

Set the env var where exec can see it. build_and_run_application now adds BIOENGINE_REPLICA=1 to replica_env_vars, which is merged into every deployment's runtime_env.env_vars — the normal branch, the container branch, and the proxy. Being in the runtime_env means it is true from the replica process's first line, before any import.

It is added after the loop that re-applies replica_env_vars to the build task's own os.environ, deliberately: the build task calls serve.run, it is not itself a replica, and claiming otherwise would be a lie the accessor believes.

It is also not added in AppBuilder._build_env_vars, which looks like the natural home. That dict is passed both to the replicas and to the introspection Ray task (builder.py:673), which imports the user's package outside any replica and must keep taking the fallback branch.

Stop caching the branch. _get_logger re-reads the env var on every call. logging.getLogger is itself a cached dict lookup, so there is nothing to memoise; the singleton only ever preserved a stale answer. This is what makes _setup_replica's in-process write meaningful as a backstop rather than dead code.

Note this does not rescue a module-scope binding on its own: logger = bioengine.logger captures the object, so re-evaluating the branch afterwards changes nothing for that name. The env var has to be right at import time, which is what the first change does. Removing the cache matters for every later access in a process where the var flipped.

Make the fallback degraded, not silent. The bioengine.app branch now runs it through create_logger on first use, so it has INFO and a formatted stream handler. If some path still lands there — the introspection task does, by design — the output is visible rather than swallowed.

Verification

tests/_app/test_replica_logger.py, 6 tests. Both behavioural halves have a positive control; the fix was neutered one edit at a time and the failure was checked to be the production symptom, not just a red test:

• dropping the create_logger call failed test_the_fallback_logger_actually_emits_info with assert False where False = <Logger bioengine.app (WARNING)>.isEnabledFor(20) — the mute logger itself, named in the assertion
• restoring the _logger_singleton cache failed test_the_branch_is_re_evaluated_not_cached with assert 'bioengine.app' == 'ray.serve' after the env var was set — the exact stale-branch mechanism

The runtime_env injection has no unit test. build_and_run_application cannot be driven without a live Ray and Serve, and the existing tests/_app/test_env_vars_propagation.py gets around that by re-implementing the merge in the test file, which would pass whether or not the source changed. I would rather say it is unverified than add a test that mirrors the code. It is verified by inspection, and the live check below is the real one.

102 tests in tests/_app pass; 183 across tests/_app, tests/apps and tests/worker.

Not yet run on a live cluster

The check the issue asks for is a deploy of an app whose module scope, __init__ and one method each emit a distinct probe at INFO, confirming all three reach the replica log — with the module-scope one being the probe that fails today. That needs a dev image on a real worker and has not been done.