chore(iast): improve iast logs [backport 2.21] (#12747)

Backport #12716 to 2.21.

This refactor of IAST log messages includes:
- most of the logs have prefixes but no normalized, such as "IAST: ...",
"[IAST] ...", "IAST ...".
- Create a hierarchy/namespaces of IAST features (instrumentation,
metrics, propagation) and sub-levels:
```
iast::instrumentation::
iast::instrumentation::ast_patching::ast::
iast::instrumentation::ast_patching::compiling::
iast::instrumentation::wrapt::

iast::metrics::error::

iast::propagation::context::
iast::propagation::listener::
iast::propagation::sink_point::
iast::propagation::native::
iast::propagation::native::error::
```
With all these levels, filtering and grouping messages becomes easier,
both for use in dashboards and for testing

A lot of logs have been added to analyze the IAST instrumentation
process in depth

This PR is a cherry-pick of one of the commits of this PR
#12639

(cherry picked from commit bfeef47)

## 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)

Author: avara1986

ddtrace/appsec/_iast/__init__.py

@@ -98,7 +98,7 @@ def enable_iast_propagation():
 
     get_package_distributions()
 
-    log.debug("IAST enabled")
+    log.debug("iast::instrumentation::starting IAST")
     ModuleWatchdog.register_pre_exec_module_hook(_should_iast_patch, _exec_iast_patched_module)
     _iast_propagation_enabled = True
 

ddtrace/appsec/_iast/_ast/ast_patching.py

@@ -20,6 +20,8 @@
 from ddtrace.internal.packages import get_package_distributions
 from ddtrace.internal.utils.formats import asbool
 
+from .._logs import iast_ast_debug_log
+from .._logs import iast_compiling_debug_log
 from .visitor import AstVisitor
 
 
@@ -478,28 +480,32 @@ def _should_iast_patch(module_name: Text) -> bool:
     # diff = max_allow - max_deny
     # return diff > 0 or (diff == 0 and not _in_python_stdlib_or_third_party(module_name))
     if _in_python_stdlib(module_name):
-        log.debug("IAST: denying %s. it's in the _in_python_stdlib", module_name)
+        iast_ast_debug_log(f"denying {module_name}. it's in the python_stdlib")
         return False
 
     if _is_first_party(module_name):
+        iast_ast_debug_log(f"allowing {module_name}. it's a first party module")
         return True
 
     # else: third party. Check that is in the allow list and not in the deny list
     dotted_module_name = module_name.lower() + "."
 
     # User allow or deny list set by env var have priority
     if _trie_has_prefix_for(_TRIE_USER_ALLOWLIST, dotted_module_name):
+        iast_ast_debug_log(f"allowing {module_name}. it's in the USER_ALLOWLIST")
         return True
 
     if _trie_has_prefix_for(_TRIE_USER_DENYLIST, dotted_module_name):
+        iast_ast_debug_log(f"denying {module_name}. it's in the USER_DENYLIST")
         return False
 
     if _trie_has_prefix_for(_TRIE_ALLOWLIST, dotted_module_name):
         if _trie_has_prefix_for(_TRIE_DENYLIST, dotted_module_name):
+            iast_ast_debug_log(f"denying {module_name}. it's in the DENYLIST")
             return False
-        log.debug("IAST: allowing %s. it's in the IAST_ALLOWLIST", module_name)
+        iast_ast_debug_log(f"allowing {module_name}. it's in the ALLOWLIST")
         return True
-    log.debug("IAST: denying %s. it's in the IAST_DENYLIST", module_name)
+    iast_ast_debug_log(f"denying {module_name}. it's NOT in the ALLOWLIST")
     return False
 
 
@@ -557,17 +563,17 @@ def astpatch_module(module: ModuleType) -> Tuple[str, Optional[ast.Module]]:
 
     module_origin = origin(module)
     if module_origin is None:
-        log.debug("astpatch_source couldn't find the module: %s", module_name)
+        iast_compiling_debug_log(f"could not find the module: {module_name}")
         return "", None
 
     module_path = str(module_origin)
     try:
         if module_origin.stat().st_size == 0:
             # Don't patch empty files like __init__.py
-            log.debug("empty file: %s", module_path)
+            iast_compiling_debug_log(f"empty file: {module_path}")
             return "", None
     except OSError:
-        log.debug("astpatch_source couldn't find the file: %s", module_path, exc_info=True)
+        iast_compiling_debug_log(f"could not find the file: {module_path}", exc_info=True)
         return "", None
 
     # Get the file extension, if it's dll, os, pyd, dyn, dynlib: return
@@ -577,19 +583,22 @@ def astpatch_module(module: ModuleType) -> Tuple[str, Optional[ast.Module]]:
 
     if module_ext.lower() not in {".pyo", ".pyc", ".pyw", ".py"}:
         # Probably native or built-in module
-        log.debug("extension not supported: %s for: %s", module_ext, module_path)
+        iast_compiling_debug_log(f"Extension not supported: {module_ext} for: {module_path}")
         return "", None
 
     with open(module_path, "r", encoding=get_encoding(module_path)) as source_file:
         try:
             source_text = source_file.read()
         except UnicodeDecodeError:
-            log.debug("unicode decode error for file: %s", module_path, exc_info=True)
+            iast_compiling_debug_log(f"Encode decode error for file: {module_path}", exc_info=True)
+            return "", None
+        except Exception:
+            iast_compiling_debug_log(f"Unexpected read error: {module_path}", exc_info=True)
             return "", None
 
     if len(source_text.strip()) == 0:
         # Don't patch empty files like __init__.py
-        log.debug("empty file: %s", module_path)
+        iast_compiling_debug_log(f"Empty file: {module_path}")
         return "", None
 
     if not asbool(os.environ.get(IAST.ENV_NO_DIR_PATCH, "false")) and version_info > (3, 7):
@@ -603,7 +612,7 @@ def astpatch_module(module: ModuleType) -> Tuple[str, Optional[ast.Module]]:
         module_name=module_name,
     )
     if new_ast is None:
-        log.debug("file not ast patched: %s", module_path)
+        iast_compiling_debug_log(f"file not ast patched: {module_path}")
         return "", None
 
     return module_path, new_ast

ddtrace/appsec/_iast/_handlers.py

@@ -18,6 +18,8 @@
 from ddtrace.settings.asm import config as asm_config
 
 from ._iast_request_context import is_iast_request_enabled
+from ._logs import iast_instrumentation_wrapt_debug_log
+from ._logs import iast_propagation_listener_log_log
 from ._taint_tracking._taint_objects import taint_pyobject
 
 
@@ -70,68 +72,73 @@ def _on_request_init(wrapped, instance, args, kwargs):
                 source_origin=OriginType.PATH,
             )
         except Exception:
-            log.debug("Unexpected exception while tainting pyobject", exc_info=True)
+            iast_propagation_listener_log_log("Unexpected exception while tainting pyobject", exc_info=True)
 
 
 def _on_flask_patch(flask_version):
     if asm_config._iast_enabled:
-        try_wrap_function_wrapper(
-            "werkzeug.datastructures",
-            "Headers.items",
-            functools.partial(if_iast_taint_yield_tuple_for, (OriginType.HEADER_NAME, OriginType.HEADER)),
-        )
-        _set_metric_iast_instrumented_source(OriginType.HEADER_NAME)
-        _set_metric_iast_instrumented_source(OriginType.HEADER)
+        try:
+            try_wrap_function_wrapper(
+                "werkzeug.datastructures",
+                "Headers.items",
+                functools.partial(if_iast_taint_yield_tuple_for, (OriginType.HEADER_NAME, OriginType.HEADER)),
+            )
+            _set_metric_iast_instrumented_source(OriginType.HEADER_NAME)
+            _set_metric_iast_instrumented_source(OriginType.HEADER)
 
-        try_wrap_function_wrapper(
-            "werkzeug.datastructures",
-            "ImmutableMultiDict.__getitem__",
-            functools.partial(if_iast_taint_returned_object_for, OriginType.PARAMETER),
-        )
-        _set_metric_iast_instrumented_source(OriginType.PARAMETER)
+            try_wrap_function_wrapper(
+                "werkzeug.datastructures",
+                "ImmutableMultiDict.__getitem__",
+                functools.partial(if_iast_taint_returned_object_for, OriginType.PARAMETER),
+            )
+            _set_metric_iast_instrumented_source(OriginType.PARAMETER)
 
-        try_wrap_function_wrapper(
-            "werkzeug.datastructures",
-            "EnvironHeaders.__getitem__",
-            functools.partial(if_iast_taint_returned_object_for, OriginType.HEADER),
-        )
-        _set_metric_iast_instrumented_source(OriginType.HEADER)
+            try_wrap_function_wrapper(
+                "werkzeug.datastructures",
+                "EnvironHeaders.__getitem__",
+                functools.partial(if_iast_taint_returned_object_for, OriginType.HEADER),
+            )
+            _set_metric_iast_instrumented_source(OriginType.HEADER)
 
-        if flask_version >= (2, 0, 0):
-            # instance.query_string: raising an error on werkzeug/_internal.py "AttributeError: read only property"
-            try_wrap_function_wrapper("werkzeug.wrappers.request", "Request.__init__", _on_request_init)
+            if flask_version >= (2, 0, 0):
+                # instance.query_string: raising an error on werkzeug/_internal.py "AttributeError: read only property"
+                try_wrap_function_wrapper("werkzeug.wrappers.request", "Request.__init__", _on_request_init)
+
+            _set_metric_iast_instrumented_source(OriginType.PATH)
+            _set_metric_iast_instrumented_source(OriginType.QUERY)
 
-        _set_metric_iast_instrumented_source(OriginType.PATH)
-        _set_metric_iast_instrumented_source(OriginType.QUERY)
+            # Instrumented on _ddtrace.appsec._asm_request_context._on_wrapped_view
+            _set_metric_iast_instrumented_source(OriginType.PATH_PARAMETER)
 
-        # Instrumented on _ddtrace.appsec._asm_request_context._on_wrapped_view
-        _set_metric_iast_instrumented_source(OriginType.PATH_PARAMETER)
+            try_wrap_function_wrapper(
+                "werkzeug.wrappers.request",
+                "Request.get_data",
+                functools.partial(_patched_dictionary, OriginType.BODY, OriginType.BODY),
+            )
+            try_wrap_function_wrapper(
+                "werkzeug.wrappers.request",
+                "Request.get_json",
+                functools.partial(_patched_dictionary, OriginType.BODY, OriginType.BODY),
+            )
 
-        try_wrap_function_wrapper(
-            "werkzeug.wrappers.request",
-            "Request.get_data",
-            functools.partial(_patched_dictionary, OriginType.BODY, OriginType.BODY),
-        )
-        try_wrap_function_wrapper(
-            "werkzeug.wrappers.request",
-            "Request.get_json",
-            functools.partial(_patched_dictionary, OriginType.BODY, OriginType.BODY),
-        )
+            _set_metric_iast_instrumented_source(OriginType.BODY)
 
-        _set_metric_iast_instrumented_source(OriginType.BODY)
+            if flask_version < (2, 0, 0):
+                _w(
+                    "werkzeug._internal",
+                    "_DictAccessorProperty.__get__",
+                    functools.partial(if_iast_taint_returned_object_for, OriginType.QUERY),
+                )
+                _set_metric_iast_instrumented_source(OriginType.QUERY)
 
-        if flask_version < (2, 0, 0):
-            _w(
-                "werkzeug._internal",
-                "_DictAccessorProperty.__get__",
-                functools.partial(if_iast_taint_returned_object_for, OriginType.QUERY),
-            )
-            _set_metric_iast_instrumented_source(OriginType.QUERY)
+            # Instrumented on _on_set_request_tags_iast
+            _set_metric_iast_instrumented_source(OriginType.COOKIE_NAME)
+            _set_metric_iast_instrumented_source(OriginType.COOKIE)
+            _set_metric_iast_instrumented_source(OriginType.PARAMETER_NAME)
 
-        # Instrumented on _on_set_request_tags_iast
-        _set_metric_iast_instrumented_source(OriginType.COOKIE_NAME)
-        _set_metric_iast_instrumented_source(OriginType.COOKIE)
-        _set_metric_iast_instrumented_source(OriginType.PARAMETER_NAME)
+            iast_instrumentation_wrapt_debug_log("Patching flask correctly")
+        except Exception:
+            iast_instrumentation_wrapt_debug_log("Unexpected exception while patching Flask", exc_info=True)
 
 
 def _iast_on_wrapped_view(kwargs):
@@ -173,9 +180,9 @@ def _on_django_patch():
                     functools.partial(if_iast_taint_returned_object_for, OriginType.PARAMETER),
                 )
             )
-            log.debug("[IAST] Patching Django correctly")
+            iast_instrumentation_wrapt_debug_log("Patching Django correctly")
         except Exception:
-            log.debug("[IAST] Unexpected exception while patch Django", exc_info=True)
+            iast_instrumentation_wrapt_debug_log("Unexpected exception while patching Django", exc_info=True)
 
 
 def _on_django_func_wrapped(fn_args, fn_kwargs, first_arg_expected_type, *_):
@@ -215,7 +222,7 @@ def _on_django_func_wrapped(fn_args, fn_kwargs, first_arg_expected_type, *_):
                     source_origin=OriginType.BODY,
                 )
             except AttributeError:
-                log.debug("IAST can't set attribute http_req.body", exc_info=True)
+                iast_propagation_listener_log_log("IAST can't set attribute http_req.body", exc_info=True)
 
         http_req.GET = taint_structure(http_req.GET, OriginType.PARAMETER_NAME, OriginType.PARAMETER)
         http_req.POST = taint_structure(http_req.POST, OriginType.PARAMETER_NAME, OriginType.BODY)
@@ -243,7 +250,9 @@ def _on_django_func_wrapped(fn_args, fn_kwargs, first_arg_expected_type, *_):
                         v, source_name=k, source_value=v, source_origin=OriginType.PATH_PARAMETER
                     )
             except Exception:
-                log.debug("IAST: Unexpected exception while tainting path parameters", exc_info=True)
+                iast_propagation_listener_log_log(
+                    "IAST: Unexpected exception while tainting path parameters", exc_info=True
+                )
 
 
 def _custom_protobuf_getattribute(self, name):
@@ -304,7 +313,7 @@ def if_iast_taint_yield_tuple_for(origins, wrapped, instance, args, kwargs):
                 )
                 yield new_key, new_value
         except Exception:
-            log.debug("Unexpected exception while tainting pyobject", exc_info=True)
+            iast_propagation_listener_log_log("Unexpected exception while tainting pyobject", exc_info=True)
     else:
         for key, value in wrapped(*args, **kwargs):
             yield key, value
@@ -320,7 +329,7 @@ def if_iast_taint_returned_object_for(origin, wrapped, instance, args, kwargs):
                     origin = OriginType.COOKIE
                 return taint_pyobject(pyobject=value, source_name=name, source_value=value, source_origin=origin)
         except Exception:
-            log.debug("Unexpected exception while tainting pyobject", exc_info=True)
+            iast_propagation_listener_log_log("Unexpected exception while tainting pyobject", exc_info=True)
     return value
 
 
@@ -343,7 +352,7 @@ def if_iast_taint_starlette_datastructures(origin, wrapped, instance, args, kwar
                     res.append(element)
             return res
         except Exception:
-            log.debug("Unexpected exception while tainting pyobject", exc_info=True)
+            iast_propagation_listener_log_log("Unexpected exception while tainting pyobject", exc_info=True)
     return value
 
 

ddtrace/appsec/_iast/_iast_request_context.py

@@ -78,7 +78,7 @@ def set_iast_reporter(iast_reporter: IastSpanReporter) -> None:
     if env:
         env.iast_reporter = iast_reporter
     else:
-        log.debug("[IAST] Trying to set IAST reporter but no context is present")
+        log.debug("iast::propagation::context::Trying to set IAST reporter but no context is present")
 
 
 def get_iast_reporter() -> Optional[IastSpanReporter]:
@@ -101,7 +101,7 @@ def set_iast_request_enabled(request_enabled) -> None:
     if env:
         env.request_enabled = request_enabled
     else:
-        log.debug("[IAST] Trying to set IAST reporter but no context is present")
+        log.debug("iast::propagation::context::Trying to set IAST reporter but no context is present")
 
 
 def is_iast_request_enabled() -> bool:
@@ -149,7 +149,9 @@ def _iast_end_request(ctx=None, span=None, *args, **kwargs):
                 req_span = span
             else:
                 req_span = ctx.get_item("req_span")
-
+        if req_span is None:
+            log.debug("iast::propagation::context::Error finishing IAST context. There isn't a SPAN")
+            return
         if asm_config._iast_enabled:
             existing_data = req_span.get_tag(IAST.JSON)
             if existing_data is None:
@@ -168,7 +170,7 @@ def _iast_end_request(ctx=None, span=None, *args, **kwargs):
                 _create_and_attach_iast_report_to_span(req_span, existing_data, merge=True)
 
     except Exception:
-        log.debug("[IAST] Error finishing IAST context", exc_info=True)
+        log.debug("iast::propagation::context::Error finishing IAST context", exc_info=True)
 
 
 def _iast_start_request(span=None, *args, **kwargs):
@@ -180,4 +182,4 @@ def _iast_start_request(span=None, *args, **kwargs):
                 request_iast_enabled = True
             set_iast_request_enabled(request_iast_enabled)
     except Exception:
-        log.debug("[IAST] Error starting IAST context", exc_info=True)
+        log.debug("iast::propagation::context::Error starting IAST context", exc_info=True)

ddtrace/appsec/_iast/_loader.py

@@ -1,5 +1,6 @@
 #!/usr/bin/env python3
 
+from ddtrace.appsec._iast._logs import iast_compiling_debug_log
 from ddtrace.internal.logger import get_logger
 from ddtrace.settings.asm import config as asm_config
 
@@ -18,24 +19,26 @@ def _exec_iast_patched_module(module_watchdog, module):
         try:
             module_path, patched_ast = astpatch_module(module)
         except Exception:
-            log.debug("Unexpected exception while AST patching", exc_info=True)
+            iast_compiling_debug_log("Unexpected exception while AST patching", exc_info=True)
             patched_ast = None
 
     if patched_ast:
         try:
             # Patched source is compiled in order to execute it
             compiled_code = compile(patched_ast, module_path, "exec")
         except Exception:
-            log.debug("Unexpected exception while compiling patched code", exc_info=True)
+            iast_compiling_debug_log("Unexpected exception while compiling patched code", exc_info=True)
             compiled_code = None
 
     if compiled_code:
+        iast_compiling_debug_log(f"INSTRUMENTED CODE. executing {module_path}")
         # Patched source is executed instead of original module
         exec(compiled_code, module.__dict__)  # nosec B102
     elif module_watchdog.loader is not None:
         try:
+            iast_compiling_debug_log(f"DEFAULT CODE. executing {module}")
             module_watchdog.loader.exec_module(module)
         except ImportError:
-            log.debug("Unexpected exception on import loader fallback", exc_info=True)
+            iast_compiling_debug_log("Unexpected exception on import loader fallback", exc_info=True)
     else:
-        log.debug("Module loader is not available, cannot execute module %s", module)
+        iast_compiling_debug_log(f"Module loader is not available, cannot execute module {module}")