Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
11 changes: 11 additions & 0 deletions DESIGN.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
32 changes: 30 additions & 2 deletions docs/configuration.md
Original file line number Diff line number Diff line change
Expand Up @@ -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`

Expand Down
72 changes: 43 additions & 29 deletions src/azure_functions_logging/_setup.py
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@

from __future__ import annotations

from collections.abc import Callable
import contextvars
import logging
import os
Expand All @@ -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,
Expand All @@ -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:
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -180,33 +190,37 @@ 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
# previously-configured default — that would break idempotency.
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:
Expand Down
12 changes: 12 additions & 0 deletions tests/conftest.py
Original file line number Diff line number Diff line change
Expand Up @@ -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] = []


Expand Down
8 changes: 2 additions & 6 deletions tests/test_setup.py
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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(
Expand Down
142 changes: 142 additions & 0 deletions tests/test_strategy_lifetime.py
Original file line number Diff line number Diff line change
@@ -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)
Loading