diff --git a/DESIGN.md b/DESIGN.md index 290a813..d55d7fe 100644 --- a/DESIGN.md +++ b/DESIGN.md @@ -97,6 +97,17 @@ Four exports plus a logger class: ## Key Design Decisions +### Process-wide context strategy + +Filter mode remains the default. The opt-in record factory is reversible during +quiescent setup: enabling removes package context filters across registered +loggers; disabling restores its predecessor only while the exact owned factory +is active. A third-party replacement/wrapper causes a clear error, never an +automatic uninstall. Reconfiguration invalidates setup caches, not host handlers +or formatters. Invocation context remains in contextvars, not setup registries. +See [strategy lifetime and migration](docs/configuration.md#strategy-lifetime-and-migration) +for the changed True-to-False contract and queue-draining requirements. + ### Opt-in secure redaction `configure_secure_redaction()` installs handler-level fail-closed redaction diff --git a/docs/configuration.md b/docs/configuration.md index c07ecc2..3198a1f 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -261,13 +261,41 @@ Behavior details: - Input validation (e.g. `format`) runs **before** the factory is installed, so invalid arguments raise `ValueError` without any global side effects. +### Strategy lifetime and migration + +The strategy is process-wide because a record factory affects every logger. +Select it during startup; switch only while logging is quiescent, never during +concurrent invocations. Enabling factory mode removes exact package-owned context +filters across registered loggers and handlers; user subclasses are preserved. +Calling `setup_logging(use_record_factory=False)` (including a bare call) now +restores the preceding factory instead of leaving a mixed factory/filter mode. +Keep passing `use_record_factory=True` on repeated setup if snapshots are needed. + +Restoration only occurs when the exact factory installed by this package remains +active. If another library replaces or wraps it, setup raises `RuntimeError` +without removing that library's factory. Tear down that integration in reverse +installation order so our factory is active again, then switch modes. Do not +assign the standard factory blindly: that would discard third-party behavior. + +Switching back invalidates package setup bookkeeping, not handlers or formatters. +The next call configures the selected target; rerun setup for other standalone +targets as needed. Azure repeats still discover late host handlers without +adding handlers or changing host levels. Existing records retain fields already +injected; drain queues before switching. Factory mode reserves context keys in +stdlib `extra`; restoring filter mode ends those creation-time reservations. + +The local logger-name registry retains first-call handler/level configuration; +the Azure weak-handler registry retains late-handler recovery and formatter +idempotency. Factory ownership is one identity reference, used only to prevent +uninstalling someone else's factory. None stores invocation context. + ## Parameter: `extra_context_vars` `extra_context_vars` is an optional mapping of `field_name -> contextvars.ContextVar` whose current values `ContextFilter` copies onto each `LogRecord`, alongside the built-in context fields. Field names must not collide with the built-in fields. -This only applies to the `ContextFilter` strategy and is ignored when -`use_record_factory=True`. +This applies to both `ContextFilter` and factory strategies. Repeated setup with +the same strategy retains its initial mapping; choose fields at startup. ## Parameter: `activate_trace_context` diff --git a/src/azure_functions_logging/_setup.py b/src/azure_functions_logging/_setup.py index 6711442..435bdfd 100644 --- a/src/azure_functions_logging/_setup.py +++ b/src/azure_functions_logging/_setup.py @@ -2,6 +2,7 @@ from __future__ import annotations +from collections.abc import Callable import contextvars import logging import os @@ -11,7 +12,13 @@ import warnings import weakref -from ._context import ContextFilter, _install_context_factory, set_default_trace_context_activation +from ._context import ( + ContextFilter, + _install_context_factory, + _uninstall_context_factory, + _validate_extra_context_vars, + set_default_trace_context_activation, +) from ._formatter import ColorFormatter from ._host_config import ( _is_otel_logging_handler, @@ -33,6 +40,7 @@ _AzureStateKey = tuple[str | None, bool] _AzureStateValue = tuple[ContextFilter | None, weakref.WeakSet[logging.Handler]] _azure_state: dict[_AzureStateKey, _AzureStateValue] = {} +_owned_factory: Callable[..., logging.LogRecord] | None = None def _remove_context_filters(logger: logging.Logger) -> None: @@ -110,15 +118,17 @@ def setup_logging( call, without duplicating filters. The root logger's level and handler list are never modified (``host.json`` owns the level). - **Switching ``use_record_factory`` between calls.** Enabling it - (``False`` -> ``True``) installs the global ``LogRecordFactory`` and strips - any ``ContextFilter`` this package previously installed on the target and - root loggers, so context is injected by exactly one mechanism. The two - modes keep isolated per-signature state, so a later ``ContextFilter`` call - never reuses a factory-mode instance (or vice versa). Switching back - (``True`` -> ``False``) installs a fresh ``ContextFilter`` but does **not** - uninstall the already-installed global factory; prefer a single, consistent - ``use_record_factory`` value per process. + **Strategy lifetime.** ``use_record_factory`` selects a process-wide strategy. + Reconfigure only while application logging is quiescent, not per invocation. + Enabling the factory removes exact package-owned ``ContextFilter`` instances + from all registered loggers/handlers, preserving user subclasses. Switching + back restores the preceding factory only if our factory is still the active + global factory, then configures filters on the selected target. Configure + other standalone targets again after switching back. If another library + replaces or wraps our factory, reconfiguration raises ``RuntimeError`` before + changing anything; restore our factory through that library's teardown first. + A bare call selects filter mode too. Keep passing ``use_record_factory=True`` + on repeated setup calls if creation-time snapshots are required. **Switching ``activate_trace_context``.** A bare ``setup_logging()`` (the default ``activate_trace_context=None``) leaves the previously configured @@ -180,14 +190,30 @@ def setup_logging( msg = "format must be 'color' or 'json'" raise ValueError(msg) - # Install the global LogRecordFactory only after argument validation, so an - # invalid call (e.g. an extra_context_vars collision) does not leave - # persistent global side effects. In record-factory mode the factory now - # carries extra_context_vars too, so both modes honor user fields. - if use_record_factory: - _install_context_factory(extra_context_vars) - + global _owned_factory + _validate_extra_context_vars(extra_context_vars) with _configured_lock: + current = logging.getLogRecordFactory() + if _owned_factory is not None and current is not _owned_factory: + raise RuntimeError( + "LogRecordFactory changed after setup; restore the package-owned factory " + "before reconfiguring context injection" + ) + if use_record_factory: + enabling = _owned_factory is None + _install_context_factory(extra_context_vars) + _owned_factory = logging.getLogRecordFactory() + for logger in (logging.getLogger(), *tuple(logging.Logger.manager.loggerDict.values())): + if isinstance(logger, logging.Logger): + _remove_context_filters(logger) + if enabling: + _azure_state.clear() + elif _owned_factory is not None: + _uninstall_context_factory() + _owned_factory = None + _azure_state.clear() + _configured_loggers.clear() + # Only override the process-wide activation default when the caller # explicitly opts in or out. A bare ``setup_logging()`` (where # ``activate_trace_context`` is ``None``) must not silently revert a @@ -195,18 +221,6 @@ def setup_logging( if activate_trace_context is not None: set_default_trace_context_activation(activate_trace_context) - # When switching to record-factory mode, strip any previously-installed - # ContextFilter from the target logger and root logger. Must run BEFORE - # the idempotency guards (so re-entry for the same logger_name still - # removes stale filters), and UNDER _configured_lock (so concurrent - # setup_logging() calls cannot race on the filter lists). - if use_record_factory: - _target = logging.getLogger(logger_name) - _root = logging.getLogger() - _remove_context_filters(_target) - if _root is not _target: - _remove_context_filters(_root) - is_functions_env = _is_functions_environment() if is_functions_env: diff --git a/tests/conftest.py b/tests/conftest.py index f480399..bc1ce49 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -11,10 +11,22 @@ from __future__ import annotations +from collections.abc import Iterator import os import pytest +import azure_functions_logging._setup as setup_mod + + +@pytest.fixture(autouse=True) +def restore_strategy_owner() -> Iterator[None]: + previous = setup_mod._owned_factory + setup_mod._owned_factory = None + yield + setup_mod._owned_factory = previous + + _skipped: list[str] = [] diff --git a/tests/test_setup.py b/tests/test_setup.py index 64cb7b4..81257dc 100644 --- a/tests/test_setup.py +++ b/tests/test_setup.py @@ -940,9 +940,7 @@ def test_azure_repeat_calls_do_not_modify_root_level_or_handlers() -> None: root.setLevel(original_level) -def test_switch_back_to_filter_mode_leaves_global_factory_installed() -> None: - """Documented caveat: True -> False installs a fresh ContextFilter but does - NOT uninstall the already-installed global LogRecordFactory.""" +def test_switch_back_to_filter_mode_restores_global_factory() -> None: from azure_functions_logging._context import _CONTEXT_FACTORY_MARKER name_true = "afl.test.reconfig.factory" @@ -955,11 +953,9 @@ def test_switch_back_to_filter_mode_leaves_global_factory_installed() -> None: with patch.dict(os.environ, {}, clear=True): setup_logging(logger_name=name_true, use_record_factory=True) assert getattr(logging.getLogRecordFactory(), _CONTEXT_FACTORY_MARKER, False) is True - # A subsequent filter-mode call for a different logger does not tear the - # global factory back down. setup_logging(logger_name=name_false, use_record_factory=False) - assert getattr(logging.getLogRecordFactory(), _CONTEXT_FACTORY_MARKER, False) is True + assert getattr(logging.getLogRecordFactory(), _CONTEXT_FACTORY_MARKER, False) is False filter_installed = any( type(f) is ContextFilter for f in logging.getLogger(name_false).filters ) or any( diff --git a/tests/test_strategy_lifetime.py b/tests/test_strategy_lifetime.py new file mode 100644 index 0000000..7d7779b --- /dev/null +++ b/tests/test_strategy_lifetime.py @@ -0,0 +1,142 @@ +from collections.abc import Iterator +from concurrent.futures import ThreadPoolExecutor +import io +import json +import logging +from types import SimpleNamespace + +import pytest + +from azure_functions_logging import JsonFormatter, logging_context, setup_logging +from azure_functions_logging._context import ContextFilter +import azure_functions_logging._setup as setup_mod + + +@pytest.fixture(autouse=True) +def isolated_setup(monkeypatch: pytest.MonkeyPatch) -> Iterator[None]: + factory = logging.getLogRecordFactory() + root = logging.getLogger() + handlers, filters = root.handlers[:], root.filters[:] + root.handlers = [logging.NullHandler()] + root.filters = [] + setup_mod._configured_loggers.clear() + setup_mod._azure_state.clear() + setup_mod._owned_factory = None + monkeypatch.setenv("FUNCTIONS_WORKER_RUNTIME", "python") + yield + root.handlers, root.filters = handlers, filters + logging.setLogRecordFactory(factory) + setup_mod._configured_loggers.clear() + setup_mod._azure_state.clear() + + +def test_repeated_filter_setup_recovers_late_host_handler() -> None: + setup_logging() + late = logging.NullHandler() + logging.getLogger().addHandler(late) + setup_logging() + setup_logging() + assert sum(type(f) is ContextFilter for f in late.filters) == 1 + + +def test_factory_setup_preserves_previous_factory_and_removes_root_filters() -> None: + previous = logging.getLogRecordFactory() + setup_logging() + setup_logging(use_record_factory=True) + active = logging.getLogRecordFactory() + setup_logging(use_record_factory=True) + assert logging.getLogRecordFactory() is active + assert active is not previous + assert not any(type(f) is ContextFilter for f in logging.getLogger().filters) + + +def test_switch_back_restores_previous_factory_and_filter_mode() -> None: + previous = logging.getLogRecordFactory() + setup_logging(use_record_factory=True) + setup_logging(use_record_factory=False) + assert logging.getLogRecordFactory() is previous + assert sum(type(f) is ContextFilter for f in logging.getLogger().handlers[0].filters) == 1 + + +def test_factory_upgrade_removes_filters_from_other_configured_loggers() -> None: + named = logging.getLogger("strategy.other") + handler = logging.NullHandler() + named.addHandler(handler) + handler.addFilter(ContextFilter()) + try: + setup_logging(use_record_factory=True) + assert not any(type(f) is ContextFilter for f in handler.filters) + finally: + named.removeHandler(handler) + + +def test_switch_rejects_third_party_wrapper_without_uninstalling_it() -> None: + setup_logging(use_record_factory=True) + owned = logging.getLogRecordFactory() + + def foreign(*args: object, **kwargs: object) -> logging.LogRecord: + return owned(*args, **kwargs) + + logging.setLogRecordFactory(foreign) + with pytest.raises(RuntimeError, match="restore the package-owned factory"): + setup_logging(use_record_factory=False) + assert logging.getLogRecordFactory() is foreign + + +def test_switch_back_restores_foreign_predecessor_with_custom_fields() -> None: + baseline = logging.getLogRecordFactory() + + def predecessor(*args: object, **kwargs: object) -> logging.LogRecord: + record = baseline(*args, **kwargs) + record.__dict__["foreign"] = "preserved" + return record + + logging.setLogRecordFactory(predecessor) + setup_logging(use_record_factory=True) + setup_logging() + assert logging.getLogRecordFactory() is predecessor + assert logging.makeLogRecord({}).__dict__["foreign"] == "preserved" + + +@pytest.mark.parametrize("factory_mode", [False, True]) +def test_concurrent_invocations_and_outside_records_are_isolated(factory_mode: bool) -> None: + stream = io.StringIO() + handler = logging.StreamHandler(stream) + handler.setFormatter(JsonFormatter()) + root = logging.getLogger() + root.handlers = [handler] + setup_logging(use_record_factory=factory_mode) + logger = logging.getLogger("strategy.concurrent.thirdparty") + + def emit(index: int) -> None: + context = SimpleNamespace(invocation_id=f"inv-{index}", function_name="parallel") + with logging_context(context): + logger.warning("inside", extra={"index": index}) + logger.warning("outside") + + with ThreadPoolExecutor(max_workers=4) as pool: + list(pool.map(emit, range(16))) + + records = [json.loads(line) for line in stream.getvalue().splitlines()] + assert len(records) == 32 + for record in records: + if record["message"] == "inside": + assert record["invocation_id"] == f"inv-{record['extra']['index']}" + else: + assert record["invocation_id"] is None + + +def test_local_strategy_roundtrip_recovers_same_logger(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.delenv("FUNCTIONS_WORKER_RUNTIME") + logger = logging.getLogger("strategy.local") + handler = logging.StreamHandler(io.StringIO()) + logger.addHandler(handler) + try: + setup_logging(logger_name=logger.name) + setup_logging(logger_name=logger.name, use_record_factory=True) + assert not any(type(f) is ContextFilter for f in handler.filters) + setup_logging(logger_name=logger.name) + assert sum(type(f) is ContextFilter for f in handler.filters) == 1 + assert logger.handlers == [handler] + finally: + logger.removeHandler(handler)