feat(iast): report telemetry log error

ddtrace/appsec/_iast/_metrics.py

@@ -7,6 +7,7 @@
 from ddtrace.appsec._constants import IAST
 from ddtrace.appsec._constants import IAST_SPAN_TAGS
 from ddtrace.appsec._deduplications import deduplication
+from ddtrace.appsec._iast._utils import _is_iast_debug_enabled
 from ddtrace.internal import telemetry
 from ddtrace.internal.logger import get_logger
 from ddtrace.internal.telemetry.constants import TELEMETRY_LOG_LEVEL
@@ -61,22 +62,25 @@ def wrapper(f):
 def _set_iast_error_metric(msg: Text) -> None:
     # Due to format_exc and format_exception returns the error and the last frame
     try:
-        exception_type, exception_instance, _traceback_list = sys.exc_info()
-        res = []
-        # first 10 frames are this function, the exception in aspects and the error line
-        res.extend(traceback.format_stack(limit=10))
+        stack_trace = ""
+        if _is_iast_debug_enabled():
+            exception_type, exception_instance, _traceback_list = sys.exc_info()
+            res = []
+            # first 10 frames are this function, the exception in aspects and the error line
+            res.extend(traceback.format_stack(limit=10))
 
-        # get the frame with the error and the error message
-        result = traceback.format_exception(exception_type, exception_instance, _traceback_list)
-        res.extend(result[1:])
+            # get the frame with the error and the error message
+            result = traceback.format_exception(exception_type, exception_instance, _traceback_list)
+            res.extend(result[1:])
+
+            stack_trace = "".join(res)
 
-        stack_trace = "".join(res)
         tags = {
             "lib_language": "python",
         }
         telemetry.telemetry_writer.add_log(TELEMETRY_LOG_LEVEL.ERROR, msg, stack_trace=stack_trace, tags=tags)
     except Exception:
-        log.warning("Error reporting ASM WAF logs metrics", exc_info=True)
+        log.warning("Error reporting ASM logs metrics", exc_info=True)
 
 
 @metric_verbosity(TELEMETRY_MANDATORY_VERBOSITY)

ddtrace/appsec/_iast/_taint_tracking/__init__.py

@@ -1,14 +1,13 @@
-import os
 from typing import Any
 from typing import Tuple
 
 from ddtrace.internal._unpatched import _threading as threading
 from ddtrace.internal.logger import get_logger
-from ddtrace.internal.utils.formats import asbool
 
 from ..._constants import IAST
 from .._metrics import _set_iast_error_metric
 from .._metrics import _set_metric_iast_executed_source
+from .._utils import _is_iast_debug_enabled
 from .._utils import _is_python_version_supported
 
 
@@ -112,18 +111,14 @@
 ]
 
 
-def _is_iast_debug_enabled():
-    return asbool(os.environ.get(IAST.ENV_DEBUG, "false"))
-
-
 def iast_taint_log_error(msg):
     if _is_iast_debug_enabled():
         import inspect
 
         stack = inspect.stack()
         frame_info = "\n".join("%s %s" % (frame_info.filename, frame_info.lineno) for frame_info in stack[:7])
-        log.debug("%s:\n%s", msg, frame_info)
-        _set_iast_error_metric("IAST propagation error. %s" % msg)
+        log.debug("[IAST] Propagation error. %s:\n%s", msg, frame_info)
+    _set_iast_error_metric("[IAST] Propagation error. %s" % msg)
 
 
 def is_pyobject_tainted(pyobject: Any) -> bool:

ddtrace/appsec/_iast/_taint_tracking/aspects.py

@@ -118,7 +118,7 @@ def str_aspect(orig_function: Optional[Callable], flag_added_args: int, *args: A
             offset = result.index(check_offset)
             copy_and_shift_ranges_from_strings(args[0], result, offset)
         except Exception as e:
-            iast_taint_log_error("IAST propagation error. str_aspect. {}".format(e))
+            iast_taint_log_error("str_aspect. {}".format(e))
     return result
 
 
@@ -136,7 +136,7 @@ def bytes_aspect(orig_function: Optional[Callable], flag_added_args: int, *args:
         try:
             copy_ranges_from_strings(args[0], result)
         except Exception as e:
-            iast_taint_log_error("IAST propagation error. bytes_aspect. {}".format(e))
+            iast_taint_log_error("bytes_aspect. {}".format(e))
     return result
 
 
@@ -154,7 +154,7 @@ def bytearray_aspect(orig_function: Optional[Callable], flag_added_args: int, *a
         try:
             copy_ranges_from_strings(args[0], result)
         except Exception as e:
-            iast_taint_log_error("IAST propagation error. bytearray_aspect. {}".format(e))
+            iast_taint_log_error("bytearray_aspect. {}".format(e))
     return result
 
 
@@ -176,7 +176,7 @@ def join_aspect(orig_function: Optional[Callable], flag_added_args: int, *args:
     try:
         return _join_aspect(joiner, *args, **kwargs)
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. join_aspect. {}".format(e))
+        iast_taint_log_error("join_aspect. {}".format(e))
         return joiner.join(*args, **kwargs)
 
 
@@ -199,7 +199,7 @@ def bytearray_extend_aspect(orig_function: Optional[Callable], flag_added_args:
     try:
         return _extend_aspect(op1, op2)
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. extend_aspect. {}".format(e))
+        iast_taint_log_error("extend_aspect. {}".format(e))
         return op1.extend(op2)
 
 
@@ -236,7 +236,7 @@ def ljust_aspect(
             taint_pyobject_with_ranges(result, ranges_new)
             return result
         except Exception as e:
-            iast_taint_log_error("IAST propagation error. ljust_aspect. {}".format(e))
+            iast_taint_log_error("ljust_aspect. {}".format(e))
 
     return candidate_text.ljust(*args, **kwargs)
 
@@ -280,7 +280,7 @@ def zfill_aspect(
                 )
         taint_pyobject_with_ranges(result, tuple(ranges_new))
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. format_aspect. {}".format(e))
+        iast_taint_log_error("format_aspect. {}".format(e))
 
     return result
 
@@ -312,7 +312,7 @@ def format_aspect(
             params = tuple(args) + tuple(kwargs.values())
             return _format_aspect(candidate_text, params, *args, **kwargs)
         except Exception as e:
-            iast_taint_log_error("IAST propagation error. format_aspect. {}".format(e))
+            iast_taint_log_error("format_aspect. {}".format(e))
 
     return candidate_text.format(*args, **kwargs)
 
@@ -359,7 +359,7 @@ def format_map_aspect(
             ranges_orig=ranges_orig,
         )
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. format_map_aspect. {}".format(e))
+        iast_taint_log_error("format_map_aspect. {}".format(e))
         return candidate_text.format_map(*args, **kwargs)
 
 
@@ -389,7 +389,7 @@ def repr_aspect(orig_function: Optional[Callable], flag_added_args: int, *args:
 
             copy_and_shift_ranges_from_strings(args[0], result, offset, len(check_offset))
         except Exception as e:
-            iast_taint_log_error("IAST propagation error. repr_aspect. {}".format(e))
+            iast_taint_log_error("repr_aspect. {}".format(e))
     return result
 
 
@@ -431,7 +431,7 @@ def format_value_aspect(
         else:
             return format(new_text)
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. format_value_aspect. {}".format(e))
+        iast_taint_log_error("format_value_aspect. {}".format(e))
         return new_text
 
 
@@ -506,7 +506,7 @@ def decode_aspect(
             inc_dec = codecs.getincrementaldecoder(codec)(**kwargs)
             return incremental_translation(self, inc_dec, inc_dec.decode, "")
         except Exception as e:
-            iast_taint_log_error("IAST propagation error. decode_aspect. {}".format(e))
+            iast_taint_log_error("decode_aspect. {}".format(e))
     return self.decode(*args, **kwargs)
 
 
@@ -527,7 +527,7 @@ def encode_aspect(
             inc_enc = codecs.getincrementalencoder(codec)(**kwargs)
             return incremental_translation(self, inc_enc, inc_enc.encode, b"")
         except Exception as e:
-            iast_taint_log_error("IAST propagation error. encode_aspect. {}".format(e))
+            iast_taint_log_error("encode_aspect. {}".format(e))
     result = self.encode(*args, **kwargs)
     return result
 
@@ -548,7 +548,7 @@ def upper_aspect(
     try:
         return common_replace("upper", candidate_text, *args, **kwargs)
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. upper_aspect. {}".format(e))
+        iast_taint_log_error("upper_aspect. {}".format(e))
         return candidate_text.upper(*args, **kwargs)
 
 
@@ -568,7 +568,7 @@ def lower_aspect(
     try:
         return common_replace("lower", candidate_text, *args, **kwargs)
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. lower_aspect. {}".format(e))
+        iast_taint_log_error("lower_aspect. {}".format(e))
         return candidate_text.lower(*args, **kwargs)
 
 
@@ -789,7 +789,7 @@ def replace_aspect(
 
         return aspect_result
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. replace_aspect. {}".format(e))
+        iast_taint_log_error("replace_aspect. {}".format(e))
         return orig_result
 
 
@@ -808,7 +808,7 @@ def swapcase_aspect(
     try:
         return common_replace("swapcase", candidate_text, *args, **kwargs)
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. swapcase_aspect. {}".format(e))
+        iast_taint_log_error("swapcase_aspect. {}".format(e))
         return candidate_text.swapcase(*args, **kwargs)
 
 
@@ -827,7 +827,7 @@ def title_aspect(
     try:
         return common_replace("title", candidate_text, *args, **kwargs)
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. title_aspect. {}".format(e))
+        iast_taint_log_error("title_aspect. {}".format(e))
         return candidate_text.title(*args, **kwargs)
 
 
@@ -847,7 +847,7 @@ def capitalize_aspect(
     try:
         return common_replace("capitalize", candidate_text, *args, **kwargs)
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. capitalize_aspect. {}".format(e))
+        iast_taint_log_error("capitalize_aspect. {}".format(e))
         return candidate_text.capitalize(*args, **kwargs)
 
 
@@ -880,7 +880,7 @@ def casefold_aspect(
     try:
         return common_replace("casefold", candidate_text, *args, **kwargs)
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. casefold_aspect. {}".format(e))
+        iast_taint_log_error("casefold_aspect. {}".format(e))
         return candidate_text.casefold(*args, **kwargs)  # type: ignore[union-attr]
 
 
@@ -899,7 +899,7 @@ def translate_aspect(
     try:
         return common_replace("translate", candidate_text, *args, **kwargs)
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. translate_aspect. {}".format(e))
+        iast_taint_log_error("translate_aspect. {}".format(e))
         return candidate_text.translate(*args, **kwargs)
 
 

ddtrace/appsec/_iast/_utils.py

@@ -1,8 +1,11 @@
+import os
 import sys
 from typing import List
 from typing import Text
 
+from ddtrace.appsec._constants import IAST
 from ddtrace.internal.logger import get_logger
+from ddtrace.internal.utils.formats import asbool
 from ddtrace.settings.asm import config as asm_config
 
 
@@ -63,3 +66,7 @@ def _get_patched_code(module_path: Text, module_name: Text) -> str:
     MODULE_PATH = sys.argv[1]
     MODULE_NAME = sys.argv[2]
     print(_get_patched_code(MODULE_PATH, MODULE_NAME))
+
+
+def _is_iast_debug_enabled():
+    return asbool(os.environ.get(IAST.ENV_DEBUG, "false"))

releasenotes/notes/iast-feat-iast-telemetry-error-f6ba4a6aadf96ec9.yaml

@@ -0,0 +1,5 @@
+---
+features:
+  - |
+    Code Security (IAST): Always report a telemetry log error when an IAST propagation error raises, 
+    regardless of whether the _DD_IAST_DEBUG environment variable is enabled or not.

tests/appsec/iast/test_telemetry.py

@@ -3,6 +3,7 @@
 from ddtrace.appsec import _asm_request_context
 from ddtrace.appsec._common_module_patches import patch_common_modules
 from ddtrace.appsec._common_module_patches import unpatch_common_modules
+from ddtrace.appsec._constants import IAST
 from ddtrace.appsec._constants import IAST_SPAN_TAGS
 from ddtrace.appsec._handlers import _on_django_patch
 from ddtrace.appsec._iast._metrics import TELEMETRY_DEBUG_VERBOSITY
@@ -193,6 +194,38 @@ def test_log_metric(telemetry_writer):
     assert str(list_metrics_logs[0]["stack_trace"]).startswith('  File "/')
 
 
+def test_log_metric_debug_disabled(telemetry_writer):
+    with override_env({IAST.ENV_DEBUG: "false"}):
+        _set_iast_error_metric("test_format_key_error_and_no_log_metric raises")
+
+        list_metrics_logs = list(telemetry_writer._logs)
+        assert len(list_metrics_logs) == 1
+        assert list_metrics_logs[0]["message"] == "test_format_key_error_and_no_log_metric raises"
+        assert "stack_trace" not in list_metrics_logs[0].keys()
+
+
+def test_log_metric_debug_disabled_deduplication(telemetry_writer):
+    with override_env({IAST.ENV_DEBUG: "false"}):
+        for i in range(10):
+            _set_iast_error_metric("test_format_key_error_and_no_log_metric raises")
+
+        list_metrics_logs = list(telemetry_writer._logs)
+        assert len(list_metrics_logs) == 1
+        assert list_metrics_logs[0]["message"] == "test_format_key_error_and_no_log_metric raises"
+        assert "stack_trace" not in list_metrics_logs[0].keys()
+
+
+def test_log_metric_debug_disabled_deduplication_different_messages(telemetry_writer):
+    with override_env({IAST.ENV_DEBUG: "false"}):
+        for i in range(10):
+            _set_iast_error_metric(f"test_format_key_error_and_no_log_metric raises {i}")
+
+        list_metrics_logs = list(telemetry_writer._logs)
+        assert len(list_metrics_logs) == 10
+        assert list_metrics_logs[0]["message"].startswith("test_format_key_error_and_no_log_metric raises")
+        assert "stack_trace" not in list_metrics_logs[0].keys()
+
+
 def test_django_instrumented_metrics(telemetry_writer):
     with override_global_config(dict(_iast_enabled=True)):
         _on_django_patch()