chore(asm): improve logs in asm_request_context [backport 2.16] (#11325)

Backport 1141754 from #11307 to 2.16.

Improve logs in asm_request_context

- Use log strings with context::function::info
- Add tool to get the previous frame info to know where the function was
called from (disabled for python 3.7)
- Add unit test
- Upgrade a few logs from debug to warning

## Checklist
- [x] PR author has checked that all the criteria below are met
- The PR description includes an overview of the change
- The PR description articulates the motivation for the change
- The change includes tests OR the PR description describes a testing
strategy
- The PR description notes risks associated with the change, if any
- Newly-added code is easy to change
- The change follows the [library release note
guidelines](https://ddtrace.readthedocs.io/en/stable/releasenotes.html)
- The change includes or references documentation updates if necessary
- Backport labels are set (if
[applicable](https://ddtrace.readthedocs.io/en/latest/contributing.html#backporting))

## Reviewer Checklist
- [x] Reviewer has checked that all the criteria below are met 
- Title is accurate
- All changes are related to the pull request's stated goal
- Avoids breaking
[API](https://ddtrace.readthedocs.io/en/stable/versioning.html#interfaces)
changes
- Testing strategy adequately addresses listed risks
- Newly-added code is easy to change
- Release note makes sense to a user of the library
- If necessary, author has acknowledged and discussed the performance
implications of this PR as reported in the benchmarks PR comment
- Backport labels are set in a manner that is consistent with the
[release branch maintenance
policy](https://ddtrace.readthedocs.io/en/latest/contributing.html#backporting)

Co-authored-by: Christophe Papazian <114495376+christophe-papazian@users.noreply.github.com>

ddtrace/appsec/_asm_request_context.py

@@ -16,6 +16,7 @@
 from ddtrace.appsec._constants import APPSEC
 from ddtrace.appsec._constants import EXPLOIT_PREVENTION
 from ddtrace.appsec._constants import SPAN_DATA_NAMES
+from ddtrace.appsec._utils import add_context_log
 from ddtrace.appsec._utils import get_triggers
 from ddtrace.internal import core
 from ddtrace.internal._exceptions import BlockingException
@@ -66,7 +67,8 @@ def __init__(self, span: Optional[Span] = None):
         # add several layers of fallbacks to get a span, but normal span should be the first or the second one
         context_span = span or core.get_span() or tracer.current_span()
         if context_span is None:
-            log.debug("ASM context created without an available span")
+            info = add_context_log(log, "appsec.asm_context.warning::ASM_Environment::no_span")
+            log.warning(info)
             context_span = tracer.trace("asm.context")
         self.span: Span = context_span
         self.waf_info: Optional[Callable[[], "DDWaf_info"]] = None
@@ -158,7 +160,8 @@ def set_blocked(blocked: Dict[str, Any]) -> None:
     blocked = blocked.copy()
     env = _get_asm_context()
     if env is None:
-        log.debug("setting blocked with no active asm context")
+        info = add_context_log(log, "appsec.asm_context.warning::set_blocked::no_active_context")
+        log.warning(info)
         return
     _ctype_from_headers(blocked, get_headers())
     env.blocked = blocked
@@ -219,20 +222,21 @@ def finalize_asm_env(env: ASM_Environment) -> None:
         try:
             if info.errors:
                 env.span.set_tag_str(APPSEC.EVENT_RULE_ERRORS, info.errors)
-                log.debug("Error in ASM In-App WAF: %s", info.errors)
+                log.debug("appsec.asm_context.debug::finalize_asm_env::waf_errors::%s", info.errors)
             env.span.set_tag_str(APPSEC.EVENT_RULE_VERSION, info.version)
             env.span.set_metric(APPSEC.EVENT_RULE_LOADED, info.loaded)
             env.span.set_metric(APPSEC.EVENT_RULE_ERROR_COUNT, info.failed)
         except Exception:
-            log.debug("Error executing ASM In-App WAF metrics report: %s", exc_info=True)
+            log.debug("appsec.asm_context.debug::finalize_asm_env::exception::%s", exc_info=True)
 
     core.discard_local_item(_ASM_CONTEXT)
 
 
 def set_value(category: str, address: str, value: Any) -> None:
     env = _get_asm_context()
     if env is None:
-        log.debug("setting %s address %s with no active asm context", category, address)
+        info = add_context_log(log, f"appsec.asm_context.debug::set_value::no_active_context::{category}::{address}")
+        log.debug(info)
         return
     asm_context_attr = getattr(env, category, None)
     if asm_context_attr is not None:
@@ -268,7 +272,8 @@ def set_waf_address(address: str, value: Any) -> None:
 def get_value(category: str, address: str, default: Any = None) -> Any:
     env = _get_asm_context()
     if env is None:
-        log.debug("getting %s address %s with no active asm context", category, address)
+        info = add_context_log(log, f"appsec.asm_context.debug::get_value::no_active_context::{category}::{address}")
+        log.debug(info)
         return default
     asm_context_attr = getattr(env, category, None)
     if asm_context_attr is not None:
@@ -280,14 +285,6 @@ def get_waf_address(address: str, default: Any = None) -> Any:
     return get_value(_WAF_ADDRESSES, address, default=default)
 
 
-def get_waf_addresses() -> Dict[str, Any]:
-    env = _get_asm_context()
-    if env is None:
-        log.debug("getting WAF addresses with no active asm context")
-        return {}
-    return env.waf_addresses
-
-
 def add_context_callback(function, global_callback: bool = False) -> None:
     if global_callback:
         callbacks = GLOBAL_CALLBACKS.setdefault(_CONTEXT_CALL, [])
@@ -313,7 +310,8 @@ def set_waf_callback(value) -> None:
 def set_waf_info(info: Callable[[], "DDWaf_info"]) -> None:
     env = _get_asm_context()
     if env is None:
-        log.debug("setting waf info with no active asm context")
+        info_str = add_context_log(log, "appsec.asm_context.warning::set_waf_info::no_active_context")
+        log.warning(info_str)
         return
     env.waf_info = info
 
@@ -325,7 +323,8 @@ def call_waf_callback(custom_data: Optional[Dict[str, Any]] = None, **kwargs) ->
     if callback:
         return callback(custom_data, **kwargs)
     else:
-        log.warning("WAF callback called but not set")
+        info = add_context_log(log, "appsec.asm_context.warning::call_waf_callback::not_set")
+        log.warning(info)
         return None
 
 
@@ -378,13 +377,15 @@ def block_request() -> None:
     if _callable:
         _callable()
     else:
-        log.debug("Block request called but block callable not set by framework")
+        info = add_context_log(log, "appsec.asm_context.debug::block_request::no_callable")
+        log.debug(info)
 
 
 def get_data_sent() -> Set[str]:
     env = _get_asm_context()
     if env is None:
-        log.debug("getting addresses sent with no active asm context")
+        info = add_context_log(log, "appsec.asm_context.debug::get_data_sent::no_asm_context")
+        log.debug(info)
         return set()
     return env.addresses_sent
 
@@ -440,7 +441,8 @@ def store_waf_results_data(data) -> None:
         return
     env = _get_asm_context()
     if env is None:
-        log.debug("storing waf results data with no active asm context")
+        info = add_context_log(log, "appsec.asm_context.warning::store_waf_results_data::no_asm_context")
+        log.warning(info)
         return
     for d in data:
         d["span_id"] = env.span.span_id

ddtrace/appsec/_utils.py

@@ -1,3 +1,5 @@
+import logging
+import sys
 from typing import Any
 import uuid
 
@@ -182,3 +184,10 @@ def get_triggers(span) -> Any:
         except Exception:
             log.debug("Failed to parse triggers", exc_info=True)
     return None
+
+
+def add_context_log(logger: logging.Logger, msg: str, offset: int = 0) -> str:
+    if sys.version_info < (3, 8):
+        return msg
+    filename, line_number, function_name, _stack_info = logger.findCaller(False, 3 + offset)
+    return f"{msg}[{filename}, line {line_number}, in {function_name}]"

tests/appsec/appsec/test_asm_request_context.py

@@ -1,8 +1,10 @@
+import mock
 import pytest
 
 from ddtrace.appsec import _asm_request_context
 from ddtrace.internal._exceptions import BlockingException
 from tests.appsec.utils import asm_context
+from tests.utils import override_global_config
 
 
 _TEST_IP = "1.2.3.4"
@@ -120,3 +122,13 @@ def test_blocking_exception_correctly_propagated():
     # no more exception there
     # ensure that the exception was raised and caught at the end of the last context manager
     assert witness == 1
+
+
+def test_log_waf_callback():
+    with mock.patch("ddtrace.appsec._asm_request_context.log.warning") as mck, override_global_config(
+        {"_asm_enabled": True}
+    ):
+        _asm_request_context.call_waf_callback()
+    log_message = mck.call_args[0][0]
+    assert log_message.startswith("appsec.asm_context.warning::call_waf_callback::not_set")
+    # log message can end with anything here due to tests being instrumented by pytest or other tools