diff --git a/README.md b/README.md index 401b1c0..5462e94 100644 --- a/README.md +++ b/README.md @@ -142,7 +142,7 @@ pip install azure-functions-logging ```python import azure.functions as func -from azure_functions_logging import get_logger, inject_context, setup_logging +from azure_functions_logging import get_logger, logging_context, setup_logging setup_logging() logger = get_logger(__name__) @@ -151,12 +151,23 @@ app = func.FunctionApp() @app.route(route="hello") def hello(req: func.HttpRequest, context: func.Context) -> func.HttpResponse: - inject_context(context) # binds invocation_id, function_name, cold_start + with logging_context(context): # binds invocation_id, function_name, cold_start; resets on exit + logger.info("Request received") + # {"level": "INFO", "invocation_id": "abc-123", "cold_start": true, ...} - logger.info("Request received") - # {"level": "INFO", "invocation_id": "abc-123", "cold_start": true, ...} + return func.HttpResponse("OK") +``` - return func.HttpResponse("OK") +`logging_context` is the recommended primary pattern: it injects context on enter and **always** resets on exit (even when the handler raises), which prevents stale context from leaking into the next invocation on a reused worker. + +For lower-level control or when integrating with custom middleware, `inject_context(context)` and `reset_context()` are exposed individually: + +```python +inject_context(context) +try: + logger.info("Request received") +finally: + reset_context() ``` Start the Functions host locally (using the [e2e example app](examples/e2e_app)): diff --git a/src/azure_functions_logging/__init__.py b/src/azure_functions_logging/__init__.py index 996f8f0..5533f7a 100644 --- a/src/azure_functions_logging/__init__.py +++ b/src/azure_functions_logging/__init__.py @@ -2,7 +2,7 @@ from __future__ import annotations -from ._context import inject_context +from ._context import inject_context, logging_context, reset_context from ._decorator import get_logging_metadata, with_context from ._filters import RedactionFilter, SamplingFilter from ._json_formatter import JsonFormatter @@ -18,6 +18,8 @@ "get_logging_metadata", "get_logger", "inject_context", + "logging_context", + "reset_context", "setup_logging", "with_context", ] diff --git a/src/azure_functions_logging/_context.py b/src/azure_functions_logging/_context.py index 0045438..7923e9b 100644 --- a/src/azure_functions_logging/_context.py +++ b/src/azure_functions_logging/_context.py @@ -2,6 +2,8 @@ from __future__ import annotations +from collections.abc import Iterator +from contextlib import contextmanager import contextvars import logging from typing import Any @@ -104,3 +106,43 @@ def inject_context(context: Any) -> None: cold_start_var.set(_check_cold_start()) except Exception: # nosec B110 — Principle 3: context failures are silent pass + + +def reset_context() -> None: + """Clear every invocation context variable. + + Call this after an invocation completes when you used ``inject_context()`` + manually. Without resetting, contextvar values can leak across reused + Azure Functions worker invocations and across async/thread boundaries — + a subsequent log line may carry a stale ``invocation_id`` belonging to an + earlier request. + + Safe to call repeatedly. Setting to ``None`` is the documented "absent" + state for every context field (matches ``ContextVar`` defaults). + """ + invocation_id_var.set(None) + function_name_var.set(None) + trace_id_var.set(None) + cold_start_var.set(None) + + +@contextmanager +def logging_context(context: Any) -> Iterator[None]: + """Context manager wrapping ``inject_context`` + ``reset_context``. + + Recommended pattern when handlers don't use the ``with_context`` decorator:: + + def handler(req, context): + with logging_context(context): + logger.info("processing") + ... + + Guarantees ``reset_context()`` runs even if the body raises, preventing + invocation context from leaking into subsequent invocations on the same + worker. + """ + inject_context(context) + try: + yield + finally: + reset_context() diff --git a/src/azure_functions_logging/_decorator.py b/src/azure_functions_logging/_decorator.py index 9c7dd62..8db739e 100644 --- a/src/azure_functions_logging/_decorator.py +++ b/src/azure_functions_logging/_decorator.py @@ -13,13 +13,7 @@ import inspect from typing import Any, Callable, TypeVar, overload -from ._context import ( - cold_start_var, - function_name_var, - inject_context, - invocation_id_var, - trace_id_var, -) +from ._context import inject_context, reset_context _F = TypeVar("_F", bound=Callable[..., Any]) @@ -29,7 +23,9 @@ def _merge_toolkit_metadata( - fn: Callable[..., Any], namespace: str, payload: dict[str, Any], + fn: Callable[..., Any], + namespace: str, + payload: dict[str, Any], ) -> None: """Merge toolkit metadata into the convention attribute, preserving other namespaces.""" existing: dict[str, Any] = getattr(fn, _TOOLKIT_META_ATTR, {}) @@ -39,14 +35,6 @@ def _merge_toolkit_metadata( setattr(fn, _TOOLKIT_META_ATTR, existing) -def _reset_context_vars() -> None: - """Reset all invocation context variables to None.""" - invocation_id_var.set(None) - function_name_var.set(None) - trace_id_var.set(None) - cold_start_var.set(None) - - def _find_context_arg( func: Callable[..., Any], param: str, @@ -82,7 +70,7 @@ def wrapper(*args: Any, **kwargs: Any) -> Any: try: return func(*args, **kwargs) finally: - _reset_context_vars() + reset_context() _merge_toolkit_metadata(wrapper, "logging", {"version": 1, "context_param": param}) return wrapper # type: ignore[return-value] @@ -99,7 +87,7 @@ async def wrapper(*args: Any, **kwargs: Any) -> Any: try: return await func(*args, **kwargs) finally: - _reset_context_vars() + reset_context() _merge_toolkit_metadata(wrapper, "logging", {"version": 1, "context_param": param}) return wrapper # type: ignore[return-value] @@ -157,7 +145,6 @@ def decorator(fn: _F) -> _F: return decorator - def get_logging_metadata(func: Any) -> dict[str, Any] | None: """Return logging metadata if the function was decorated with ``with_context``. @@ -168,4 +155,4 @@ def get_logging_metadata(func: Any) -> dict[str, Any] | None: meta = toolkit_meta.get("logging") if isinstance(meta, dict): return meta - return None \ No newline at end of file + return None diff --git a/src/azure_functions_logging/_host_config.py b/src/azure_functions_logging/_host_config.py index 6544a4b..6c40f88 100644 --- a/src/azure_functions_logging/_host_config.py +++ b/src/azure_functions_logging/_host_config.py @@ -18,8 +18,24 @@ } +def _resolve_host_level(value: object) -> int | None: + if not isinstance(value, str): + return None + return _HOST_LEVEL_TO_LOGGING.get(value.lower()) + + def warn_host_json_level_conflict(configured_level: int) -> None: - """Warn when host.json suppresses logs below setup_logging level.""" + """Warn when any ``host.json`` ``logLevel`` entry suppresses logs below ``configured_level``. + + Azure Functions honors category-specific keys under ``logging.logLevel`` + (e.g. ``Function``, ``Function.``, ``Host.Results``, + ``Host.Aggregator``) in addition to ``default``. Inspecting only ``default`` + misses the common case where ``default = Information`` while a specific + function category is set to ``Warning`` or ``None`` and silently drops the + user's logs. + + This helper iterates every category and warns once per offending entry. + """ host_path = Path.cwd() / "host.json" if not host_path.exists(): return @@ -30,24 +46,30 @@ def warn_host_json_level_conflict(configured_level: int) -> None: return try: - host_level = host_config["logging"]["logLevel"]["default"] + log_levels = host_config["logging"]["logLevel"] except Exception: return - if not isinstance(host_level, str): + if not isinstance(log_levels, dict): return - resolved_level = _HOST_LEVEL_TO_LOGGING.get(host_level.lower()) - if resolved_level is None: - return + configured_level_name = logging.getLevelName(configured_level) + + for category, raw_level in log_levels.items(): + if not isinstance(category, str): + continue + resolved_level = _resolve_host_level(raw_level) + if resolved_level is None: + continue + if resolved_level <= configured_level: + continue - if resolved_level > configured_level: - configured_level_name = logging.getLevelName(configured_level) + scope = "default" if category == "default" else f"category '{category}'" warnings.warn( ( - f"host.json logLevel.default is set to '{host_level}' which is more restrictive " - f"than the configured level '{configured_level_name}'. Logs below '{host_level}' " - "will be suppressed by the Azure Functions host." + f"host.json logLevel for {scope} is set to '{raw_level}' which is more " + f"restrictive than the configured level '{configured_level_name}'. Logs " + f"below '{raw_level}' will be suppressed by the Azure Functions host." ), stacklevel=3, ) diff --git a/tests/test_context.py b/tests/test_context.py index 834fa44..dae790d 100644 --- a/tests/test_context.py +++ b/tests/test_context.py @@ -14,6 +14,8 @@ function_name_var, inject_context, invocation_id_var, + logging_context, + reset_context, trace_id_var, ) @@ -170,3 +172,60 @@ def trace_context(self) -> object: assert invocation_id_var.get() is None assert function_name_var.get() is None assert trace_id_var.get() is None + + +def test_reset_context_clears_all_contextvars() -> None: + invocation_id_var.set("inv-x") + function_name_var.set("fn-x") + trace_id_var.set("trace-x") + cold_start_var.set(True) + + reset_context() + + assert invocation_id_var.get() is None + assert function_name_var.get() is None + assert trace_id_var.get() is None + assert cold_start_var.get() is None + + +def test_reset_context_is_idempotent() -> None: + reset_context() + reset_context() + + assert invocation_id_var.get() is None + assert cold_start_var.get() is None + + +def test_logging_context_sets_then_resets() -> None: + context = SimpleNamespace( + invocation_id="inv-cm", + function_name="fn-cm", + trace_context=SimpleNamespace( + trace_parent="00-cccccccccccccccccccccccccccccccc-2222222222222222-01" + ), + ) + + with logging_context(context): + assert invocation_id_var.get() == "inv-cm" + assert function_name_var.get() == "fn-cm" + assert trace_id_var.get() == "cccccccccccccccccccccccccccccccc" + assert cold_start_var.get() is True + + assert invocation_id_var.get() is None + assert function_name_var.get() is None + assert trace_id_var.get() is None + assert cold_start_var.get() is None + + +def test_logging_context_resets_even_when_body_raises() -> None: + context = SimpleNamespace(invocation_id="inv-raise", function_name="fn-raise") + + with pytest.raises(RuntimeError, match="boom"): + with logging_context(context): + assert invocation_id_var.get() == "inv-raise" + raise RuntimeError("boom") + + assert invocation_id_var.get() is None + assert function_name_var.get() is None + assert trace_id_var.get() is None + assert cold_start_var.get() is None diff --git a/tests/test_host_config.py b/tests/test_host_config.py index 318490d..c07e1ef 100644 --- a/tests/test_host_config.py +++ b/tests/test_host_config.py @@ -143,3 +143,73 @@ def test_no_warning_when_host_level_is_unrecognized_string( warn_host_json_level_conflict(logging.DEBUG) assert len(warning_list) == 0 + + +def test_warns_per_category_when_specific_category_is_more_restrictive( + tmp_path: Path, + monkeypatch: pytest.MonkeyPatch, +) -> None: + _write_host_json( + tmp_path / "host.json", + { + "logging": { + "logLevel": { + "default": "Information", + "Function.MyFunction": "Warning", + "Host.Results": "Error", + } + } + }, + ) + monkeypatch.chdir(tmp_path) + + with warnings.catch_warnings(record=True) as warning_list: + warnings.simplefilter("always") + warn_host_json_level_conflict(logging.INFO) + + messages = [str(w.message) for w in warning_list] + assert any("Function.MyFunction" in m and "'Warning'" in m for m in messages) + assert any("Host.Results" in m and "'Error'" in m for m in messages) + assert not any("default" in m for m in messages) + + +def test_no_warning_when_all_categories_permissive( + tmp_path: Path, + monkeypatch: pytest.MonkeyPatch, +) -> None: + _write_host_json( + tmp_path / "host.json", + { + "logging": { + "logLevel": { + "default": "Information", + "Function": "Debug", + "Host.Aggregator": "Trace", + } + } + }, + ) + monkeypatch.chdir(tmp_path) + + with warnings.catch_warnings(record=True) as warning_list: + warnings.simplefilter("always") + warn_host_json_level_conflict(logging.INFO) + + assert len(warning_list) == 0 + + +def test_no_warning_when_log_level_block_is_not_a_dict( + tmp_path: Path, + monkeypatch: pytest.MonkeyPatch, +) -> None: + _write_host_json( + tmp_path / "host.json", + {"logging": {"logLevel": "Warning"}}, + ) + monkeypatch.chdir(tmp_path) + + with warnings.catch_warnings(record=True) as warning_list: + warnings.simplefilter("always") + warn_host_json_level_conflict(logging.INFO) + + assert len(warning_list) == 0 diff --git a/tests/test_integration.py b/tests/test_integration.py index 54f2962..bccf795 100644 --- a/tests/test_integration.py +++ b/tests/test_integration.py @@ -88,6 +88,8 @@ def test_public_api_exports() -> None: "get_logging_metadata", "get_logger", "inject_context", + "logging_context", + "reset_context", "setup_logging", "with_context", } diff --git a/tests/test_public_api.py b/tests/test_public_api.py index 81c61d3..fc5a475 100644 --- a/tests/test_public_api.py +++ b/tests/test_public_api.py @@ -16,6 +16,8 @@ def test_all_exports(self) -> None: "get_logging_metadata", "get_logger", "inject_context", + "logging_context", + "reset_context", "setup_logging", "with_context", } @@ -35,6 +37,8 @@ def test_public_names_are_importable(self) -> None: get_logger, get_logging_metadata, inject_context, + logging_context, + reset_context, ) def test_get_logger_is_callable(self) -> None: diff --git a/tests/test_setup.py b/tests/test_setup.py index 2e5a4dc..8d09004 100644 --- a/tests/test_setup.py +++ b/tests/test_setup.py @@ -94,6 +94,7 @@ def test_setup_logging_is_idempotent_per_logger_name() -> None: second.handlers.clear() second.filters.clear() + def test_is_functions_environment() -> None: with patch.dict(os.environ, {}, clear=True): assert _is_functions_environment() is False @@ -122,3 +123,33 @@ def test_setup_logging_functions_formatter_applied_in_azure_env() -> None: root.handlers = [] root.filters.clear() + + +def test_setup_logging_in_azure_env_does_not_install_duplicate_context_filters() -> None: + root = logging.getLogger() + root.handlers = [logging.StreamHandler()] + root.filters.clear() + + import azure_functions_logging._setup as setup_mod + + setup_mod._configured_loggers.clear() + + with patch.dict(os.environ, {"FUNCTIONS_WORKER_RUNTIME": "python"}, clear=True): + setup_logging() + setup_logging() + + handler = root.handlers[0] + context_filters_on_handler = [f for f in handler.filters if isinstance(f, ContextFilter)] + context_filters_on_root = [f for f in root.filters if isinstance(f, ContextFilter)] + + assert len(context_filters_on_handler) == 1 + assert len(context_filters_on_root) == 1 + + root.handlers = [] + root.filters.clear() + + +def test_is_functions_environment_with_only_website_instance_id_is_false() -> None: + with patch.dict(os.environ, {"WEBSITE_INSTANCE_ID": "abc123"}, clear=True): + assert _is_functions_environment() is False + assert _is_azure_hosted() is True