fix(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
 
 
@@ -171,13 +171,14 @@ def join_aspect(orig_function: Optional[Callable], flag_added_args: int, *args:
 
     joiner = args[0]
     args = args[flag_added_args:]
+
     if not isinstance(joiner, IAST.TEXT_TYPES):
         return joiner.join(*args, **kwargs)
     try:
         return _join_aspect(joiner, *args, **kwargs)
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. join_aspect. {}".format(e))
-        return joiner.join(*args, **kwargs)
+        iast_taint_log_error("join_aspect. {}".format(e))
+    return joiner.join(*args, **kwargs)
 
 
 def bytearray_extend_aspect(orig_function: Optional[Callable], flag_added_args: int, *args: Any, **kwargs: Any) -> Any:
@@ -199,7 +200,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)
 
 
@@ -220,25 +221,26 @@ def ljust_aspect(
     candidate_text = args[0]
     args = args[flag_added_args:]
 
+    result = candidate_text.ljust(*args, **kwargs)
+
     if isinstance(candidate_text, IAST.TEXT_TYPES):
         try:
             ranges_new = get_ranges(candidate_text)
             fillchar = parse_params(1, "fillchar", " ", *args, **kwargs)
             fillchar_ranges = get_ranges(fillchar)
             if ranges_new is None or (not ranges_new and not fillchar_ranges):
-                return candidate_text.ljust(*args, **kwargs)
+                return result
 
             if fillchar_ranges:
                 # Can only be one char, so we create one range to cover from the start to the end
                 ranges_new = ranges_new + [shift_taint_range(fillchar_ranges[0], len(candidate_text))]
 
-            result = candidate_text.ljust(parse_params(0, "width", None, *args, **kwargs), fillchar)
             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)
+    return result
 
 
 def zfill_aspect(
@@ -280,7 +282,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 +314,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)
 
@@ -330,8 +332,11 @@ def format_map_aspect(
 
     candidate_text: Text = args[0]
     args = args[flag_added_args:]
+
+    result = candidate_text.format_map(*args, **kwargs)
+
     if not isinstance(candidate_text, IAST.TEXT_TYPES):
-        return candidate_text.format_map(*args, **kwargs)
+        return result
 
     try:
         mapping = parse_params(0, "mapping", None, *args, **kwargs)
@@ -341,7 +346,7 @@ def format_map_aspect(
             args + mapping_tuple,
         )
         if not ranges_orig:
-            return candidate_text.format_map(*args, **kwargs)
+            return result
 
         return _convert_escaped_text_to_tainted_text(
             as_formatted_evidence(
@@ -359,8 +364,9 @@ def format_map_aspect(
             ranges_orig=ranges_orig,
         )
     except Exception as e:
-        iast_taint_log_error("IAST propagation error. format_map_aspect. {}".format(e))
-        return candidate_text.format_map(*args, **kwargs)
+        iast_taint_log_error("format_map_aspect. {}".format(e))
+
+    return result
 
 
 def repr_aspect(orig_function: Optional[Callable], flag_added_args: int, *args: Any, **kwargs: Any) -> Any:
@@ -389,7 +395,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 +437,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
 
 
@@ -505,8 +511,8 @@ def decode_aspect(
             codec = args[0] if args else "utf-8"
             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))
+        except Exception:
+            pass
     return self.decode(*args, **kwargs)
 
 
@@ -526,10 +532,9 @@ def encode_aspect(
             codec = args[0] if args else "utf-8"
             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))
-    result = self.encode(*args, **kwargs)
-    return result
+        except Exception:
+            pass
+    return self.encode(*args, **kwargs)
 
 
 def upper_aspect(
@@ -548,7 +553,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 +573,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 +794,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 +813,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 +832,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 +852,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 +885,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 +904,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/aspects/test_encode_decode_aspect.py

@@ -142,9 +142,7 @@ def test_encode_error_with_tainted_gives_one_log_metric(telemetry_writer):
         mod.do_encode(string_input, "encoding-not-exists")
 
     list_metrics_logs = list(telemetry_writer._logs)
-    assert len(list_metrics_logs) == 1
-    assert "message" in list_metrics_logs[0]
-    assert "IAST propagation error. encode_aspect. " in list_metrics_logs[0]["message"]
+    assert len(list_metrics_logs) == 0
 
 
 def test_encode_error_with_not_tainted_gives_no_log_metric(telemetry_writer):
@@ -167,9 +165,7 @@ def test_dencode_error_with_tainted_gives_one_log_metric(telemetry_writer):
         mod.do_decode(string_input, "decoding-not-exists")
 
     list_metrics_logs = list(telemetry_writer._logs)
-    assert len(list_metrics_logs) == 1
-    assert "message" in list_metrics_logs[0]
-    assert "IAST propagation error. decode_aspect. " in list_metrics_logs[0]["message"]
+    assert len(list_metrics_logs) == 0
 
 
 def test_dencode_error_with_not_tainted_gives_no_log_metric(telemetry_writer):

tests/appsec/iast/aspects/test_index_aspect_fixtures.py

@@ -97,7 +97,9 @@ def test_index_error_with_tainted_gives_one_log_metric(telemetry_writer):
 
     list_metrics_logs = list(telemetry_writer._logs)
     assert len(list_metrics_logs) == 1
-    assert list_metrics_logs[0]["message"].startswith("IAST propagation error. string index out of range")
+    assert list_metrics_logs[0]["message"].startswith(
+        "[IAST] Propagation error. string index out of range"
+    )
 
 
 @pytest.mark.skip_iast_check_logs

tests/appsec/iast/aspects/test_str_aspect.py

@@ -533,7 +533,7 @@ def test_aspect_ljust_error_with_tainted_gives_one_log_metric(self, telemetry_wr
             mod.do_ljust(string_input, "aaaaa")
 
         list_metrics_logs = list(telemetry_writer._logs)
-        assert len(list_metrics_logs) == 1
+        assert len(list_metrics_logs) == 0
 
     def test_zfill(self):
         # Not tainted