[DEV] allow configuration of context logging level

CHANGELOG

@@ -7,6 +7,13 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+## [v0.13.1] X February, 2024
+- Adds environment variable `WOODCHIPPER_CONTEXT_LOG_LEVEL` to allow configuration of entrance and exit logging for logging contexts.
+
+## [v0.13.0] 2 February, 2024
+- Adds entrance logging for LoggingContext
+- Changes log level for exit logging to DEBUG
+
 ## [v0.12.1] 23 May, 2023
 - Corrects bug in FastAPI integration, so that http.path outputs full URL, bringing it to parity with Flask integration
 

demo/context_demo/demo.py

@@ -9,7 +9,7 @@
 
 os.environ["WOODCHIPPER_KEY_PREFIX"] = "tkl"
 
-woodchipper.configure(config=DevLogToStdout, facilities={"": "INFO"})
+woodchipper.configure(config=DevLogToStdout, facilities={"": "DEBUG"})
 
 logger = woodchipper.get_logger(__name__)
 
@@ -22,8 +22,20 @@ def decorated_func(product: dict):
 def ctx_func(product: dict):
     with LoggingContext(vendor=product["vendor"]):
         logger.info("Context one.")
-        with LoggingContext(product=product["id"]):
-            logger.info("Context two.")
+        nested_ctx_func(product)
+        logger.info("Context three.")
+    logger.info("Context four.")
+
+
+def nested_ctx_func(product: dict):
+    with LoggingContext(product=product["id"]):
+        logger.info("Context two.")
+
+
+def ctx_func_with_log_level(product: dict):
+    with LoggingContext(vendor=product["vendor"], _log_level="DEBUG"):
+        logger.info("Context one.")
+        nested_ctx_func(product)
         logger.info("Context three.")
     logger.info("Context four.")
 
@@ -32,6 +44,7 @@ def demo():
     product = dict(vendor="DEMOVENDOR", id="DEMOPRODUCT")
     decorated_func(product)
     ctx_func(product)
+    ctx_func_with_log_level(product)
 
 
 if __name__ == "__main__":

docs/advanced.md

@@ -41,6 +41,31 @@ with LoggingContext(user=request.user.id, _prefix="demo"):
 In the above message, the `user` contextual key would be outputted as `demo.user`, regardless of the value of the
 `WOODCHIPPER_KEY_PREFIX` environment variable.
 
+## Changing context logging levels
+
+Woodchipper supports changing the log level of entrance and exit logging for contexts, with the default log level of `"INFO"`.
+
+You can set the default log level for all context logs by setting the environment variable `WOODCHIPPER_CONTEXT_LOG_LEVEL` to
+the desired log level name. For example, if you set `WOODCHIPPER_CONTEXT_LOG_LEVEL` to `"DEBUG"` all logs created when entering or
+exiting a LoggingContext would be debug by default.
+
+You can also set the log level on a `LoggingContext`, overriding the default log level, with the `_log_level` kwarg. For
+example:
+
+```python
+with LoggingContext(user=request.user.id, _log_level="ERROR"):
+    logger.info("Demo beginning.")
+```
+
+In the above message, the entrance and exit logs would be outputted as level `"ERROR"`, regardless of the value of the
+`WOODCHIPPER_CONTEXT_LOG_LEVEL` environment variable. Examples of the output logs can be seen here:
+
+```
+2024-02-02T15:44:48.488489 [error    ] Entering context: __main__:<module> [__main__] func_name=<module> lineno=1 module=demo tkl.context_name=__main__:<module> tkl.user=user-123
+2024-02-02T15:44:48.488805 [info     ] Demo beginning.      [__main__] func_name=<module> lineno=2 module=demo tkl.user=user-123
+2024-02-02T15:44:48.489311 [error    ] Exiting context: __main__:<module> [__main__] context.time_to_run_musec=859 func_name=<module> lineno=1 module=demo tkl.context_name=__main__:<module> tkl.user=user-123
+```
+
 ## Using Woodchipper with Flask
 
 Woodchipper ships with a built-in Flask integration, which wraps the entire request/response cycle in a

docs/environment.md

@@ -15,6 +15,10 @@ For example, if you set this environment variable to `tackle`, then a key `user`
 
 If you want to override this, call the clear_prefix() function on the logger once initialized.
 
+### `WOODCHIPPER_CONTEXT_LOG_LEVEL`
+
+If set, all entrance and exit logging for contexts will be logged at the level specified. Default is `"INFO"`.
+
 ### `WOODCHIPPER_DISABLE_SENTRY`
 
 If set to a non-empty value, the built-in Sentry integration will be disabled.

tests/test_context.py

@@ -39,7 +39,21 @@ def test_logging_context_prefix():
     with ctx_obj:
         assert context.logging_ctx.as_dict() == {"test.a": 1}
 
-    with patch("woodchipper.context.os.getenv", return_value="env"):
+    with patch.dict("woodchipper.context.os.environ", WOODCHIPPER_KEY_PREFIX="env"):
+        with context.LoggingContext(a=1):
+            assert context.logging_ctx.as_dict() == {"env.a": 1}
+
+    with context.LoggingContext(a=1, _prefix=None):
+        assert context.logging_ctx.as_dict() == {"a": 1}
+
+
+def test_logging_context_log_level():
+    assert context.logging_ctx.as_dict() == {}
+    ctx_obj = context.LoggingContext("test-name", a=1, _prefix="test")
+    with ctx_obj:
+        assert context.logging_ctx.as_dict() == {"test.a": 1}
+
+    with patch.dict("woodchipper.context.os.environ", WOODCHIPPER_KEY_PREFIX="env"):
         with context.LoggingContext(a=1):
             assert context.logging_ctx.as_dict() == {"env.a": 1}
 

tests/test_fastapi.py

@@ -38,7 +38,7 @@ def client(app):
 
 def test_fastapi_with_woodchipper(client, caplog):
     caplog.set_level(logging.DEBUG)
-    with patch("woodchipper.context.os.getenv", return_value="woodchip"):
+    with patch.dict("woodchipper.context.os.environ", WOODCHIPPER_KEY_PREFIX="woodchip"):
         response = client.get("/foo")
 
     assert response.status_code == 200
@@ -158,7 +158,7 @@ def hello_world():
 
     client = TestClient(app)
 
-    with patch("woodchipper.context.os.getenv", return_value="woodchip"):
+    with patch.dict("woodchipper.context.os.environ", WOODCHIPPER_KEY_PREFIX="woodchip"):
         response = client.get("/foo")
 
     assert response.status_code == 200

tests/test_flask.py

@@ -21,7 +21,7 @@ def hello_world():
 
 def test_flask_with_woodchipper(caplog):
     caplog.set_level(logging.DEBUG)
-    with patch("woodchipper.context.os.getenv", return_value="woodchip"):
+    with patch.dict("woodchipper.context.os.environ", WOODCHIPPER_KEY_PREFIX="woodchip"):
         with app.test_client() as client:
             response = client.get("/")
     assert response.status_code == 200
@@ -98,7 +98,7 @@ def test_flask_with_woodchipper_adds_query_params():
     }
     encoded = urlencode(query_dict, doseq=True)
 
-    with patch("woodchipper.context.os.getenv", return_value="woodchip"):
+    with patch.dict("woodchipper.context.os.environ", WOODCHIPPER_KEY_PREFIX="woodchip"):
         with app.test_client() as client:
             response = client.get("/", query_string=encoded)
 

woodchipper/context.py

@@ -1,5 +1,6 @@
 import contextvars
 import inspect
+import logging
 import os
 import time
 from collections.abc import MutableMapping
@@ -12,6 +13,8 @@
 LoggableValue = Optional[Union[str, int, bool, Decimal, float]]
 LoggingContextType = Mapping[str, LoggableValue]
 
+DEFAULT_LOG_LEVEL = logging.INFO
+
 
 class Missing:
     """A sentinel value to be raised if something is missing."""
@@ -138,12 +141,25 @@ def _convert_to_loggable_value(value: Any) -> LoggableValue:
             )
 
 
+def _convert_to_valid_log_level(log_level: Union[str, int, Missing]) -> int:
+    if isinstance(log_level, Missing):
+        return DEFAULT_LOG_LEVEL
+
+    if isinstance(log_level, str):
+        log_level = logging.getLevelName(log_level)
+
+    if log_level not in logging._levelToName:
+        return DEFAULT_LOG_LEVEL
+
+    return log_level
+
+
 class LoggingContext:
     """A context manager for logging context. Can also be used as a decorator.
 
     Usage:
     ```python
-    with LoggingContext(data_to_inject_to_logging_context):
+    with LoggingContext(**data_to_inject_to_logging_context):
         some_function()
     ```
     """
@@ -157,11 +173,15 @@ def __init__(
         _prefix: Union[str, Missing] = missing,
         _missing_default=missing,
         _path_delimiter=".",
+        _log_level: Union[str, int, Missing] = missing,
         **kwargs: LoggableValue,
     ):
         self.name = name
         self.injected_context = kwargs
         self.prefix = os.getenv("WOODCHIPPER_KEY_PREFIX") if _prefix is missing else _prefix
+        self._log_level = _convert_to_valid_log_level(
+            os.getenv("WOODCHIPPER_CONTEXT_LOG_LEVEL", DEFAULT_LOG_LEVEL) if _log_level is missing else _log_level
+        )
         self._token = None
         self._monitors = [cls() for cls in woodchipper._monitors]
         self.missing_default = _missing_default
@@ -183,8 +203,9 @@ def __enter__(self):
         for monitor in self._monitors:
             monitor.setup()
         self.start_time = time.time()
-
-        woodchipper.get_logger(module_name).debug(f"Entering context: {self.name}", context_name=self.name)
+        woodchipper.get_logger(module_name).log(
+            self._log_level, f"Entering context: {self.name}", context_name=self.name
+        )
 
     def __exit__(self, exc_type, exc_val, exc_tb):
         current_frame = inspect.currentframe()
@@ -200,8 +221,8 @@ def __exit__(self, exc_type, exc_val, exc_tb):
         monitored_data.update({"context.time_to_run_musec": int((time.time() - self.start_time) * 1e6)})
         for monitor in self._monitors:
             monitored_data.update(monitor.finish())
-        woodchipper.get_logger(module_name).debug(
-            f"Exiting context: {self.name}", context_name=self.name, **monitored_data
+        woodchipper.get_logger(module_name).log(
+            self._log_level, f"Exiting context: {self.name}", context_name=self.name, **monitored_data
         )
         assert self._token
         logging_ctx.reset(self._token)