ci(debugging): add exploration testing (#3991)

This change adds the so-called exploration tests which we use to ensure that the dynamic instrumentation does not affect the expected behaviour of the instrumented code. We select a few popular Python frameworks and inject probes on each single line and wrap every single function. We then run the full test suite for the actual validation.

At the end of the test run, line coverage and function call counts are reported as a "proof-of-work"

Author: P403n1x87

.github/workflows/test_frameworks.yml

@@ -48,15 +48,17 @@ jobs:
         run: pip install ../ddtrace
         # Allows tests to continue through deprecation warnings for jinja2 and mako
       - name: Run tests
-        # Disable TestServerAdapter_gunicorn.test_simple because it checks for
-        # log output and it contains the profiler failing to upload
-        run: ddtrace-run pytest test --continue-on-collection-errors -v -k 'not TestServerAdapter_gunicorn'
+        # Disable all test_simple tests because they check for
+        # log output and it contains phony error messages.
+        run: PYTHONPATH=../ddtrace/tests/debugging/exploration/ ddtrace-run pytest test --continue-on-collection-errors -v -k 'not test_simple'
 
   django-testsuite-3_1:
     runs-on: ubuntu-latest
     env:
       DD_PROFILING_ENABLED: true
       DD_TESTING_RAISE: true
+      DD_DEBUGGER_EXPL_ENCODE: 0  # Disabled to speed up
+      PYTHONPATH: ../ddtrace/tests/debugging/exploration/:.
     defaults:
       run:
         working-directory: django
@@ -81,15 +83,21 @@ jobs:
       - name: Install ddtrace
         run: pip install ../ddtrace
       - name: Install django
-        run: pip install ../django
-      - name: Set Pythonpath
-        run: echo "PYTHONPATH=." >> $GITHUB_ENV
+        run: pip install -e .
       - name: Disable unsupported tests
         run: |
           # Note: test_supports_json_field_operational_error will fail with the tracer
           # DEV: Insert @skipUnless before the test definition
           # DEV: We need to escape the space indenting
           sed -i'' '/def test_supports_json_field_operational_error/i \ \ \ \ @skipUnless(False, "test not supported by dd-trace-py")' tests/backends/sqlite/test_features.py
+          sed -i'' 's/if not filename.startswith(os.path.dirname(django.__file__))/if False/' django/conf/__init__.py
+          sed -i'' 's/test_paginating_unordered_queryset_raises_warning/paginating_unordered_queryset_raises_warning/' tests/pagination/tests.py
+          sed -i'' 's/test_access_warning/access_warning/' tests/auth_tests/test_password_reset_timeout_days.py
+          sed -i'' 's/test_get_or_set_version/get_or_set_version/' tests/cache/tests.py
+          sed -i'' 's/test_avoid_infinite_loop_on_too_many_subqueries/avoid_infinite_loop_on_too_many_subqueries/' tests/queries/tests.py
+          sed -i'' 's/test_multivalue_dict_key_error/multivalue_dict_key_error/' tests/view_tests/tests/test_debug.py  # Sensitive data leak
+          sed -i'' 's/test_db_table/db_table/' tests/schema/tests.py
+
       - name: Run tests
         # django.tests.requests module interferes with requests library patching in the tracer -> disable requests patch
         run: DD_TRACE_REQUESTS_ENABLED=0 ddtrace-run tests/runtests.py
@@ -99,6 +107,7 @@ jobs:
     env:
       DD_PROFILING_ENABLED: true
       DD_TESTING_RAISE: true
+      PYTHONPATH: ../ddtrace/tests/debugging/exploration/:.
     defaults:
       run:
         working-directory: graphene
@@ -124,8 +133,6 @@ jobs:
         run: pip install "pytest-asyncio>0.17,<2"
       - name: Install ddtrace
         run: pip install ../ddtrace
-      - name: Set Pythonpath
-        run: echo "PYTHONPATH=." >> $GITHUB_ENV
       - name: Run tests
         run: ddtrace-run pytest graphene
 
@@ -165,14 +172,15 @@ jobs:
       - name: Inject ddtrace
         run: pip install ../ddtrace
       - name: Test
-        run: ddtrace-run pytest -p no:warnings tests
+        run: PYTHONPATH=../ddtrace/tests/debugging/exploration/ ddtrace-run pytest -p no:warnings tests
 
   flask-testsuite-1_1_4:
     runs-on: ubuntu-latest
     env:
       TOX_TESTENV_PASSENV: DD_TESTING_RAISE DD_PROFILING_ENABLED
       DD_TESTING_RAISE: true
       DD_PROFILING_ENABLED: true
+      PYTHONPATH: ../ddtrace/tests/debugging/exploration/
     defaults:
       run:
         working-directory: flask
@@ -230,6 +238,8 @@ jobs:
         env:
           # Disabled distributed tracing since there are a lot of tests that assert on headers
           DD_HTTPX_DISTRIBUTED_TRACING: "false"
+          # Debugger exploration testing does not work in CI
+          # PYTHONPATH: ../ddtrace/tests/debugging/exploration/
         # test_pool_timeout raises RuntimeError: The connection pool was closed while 1 HTTP requests/responses were still in-flight
         run: pytest -k 'not test_pool_timeout'
 
@@ -239,6 +249,7 @@ jobs:
       TOX_TESTENV_PASSENV: DD_TESTING_RAISE DD_PROFILING_ENABLED
       DD_TESTING_RAISE: true
       DD_PROFILING_ENABLED: true
+      PYTHONPATH: ../ddtrace/tests/debugging/exploration/
     defaults:
       run:
         working-directory: mako
@@ -260,18 +271,21 @@ jobs:
         run: sed -i 's/pygments/pygments~=2.11.0/' tox.ini
       - name: Create tox env
         run: tox -e py --notest
-      - name: Inject ddtrace
-        run: .tox/py/bin/pip install ../ddtrace
       - name: Add pytest configuration for ddtrace
         run: echo -e "[pytest]\nddtrace-patch-all = 1" > pytest.ini
       - name: Run tests
-        run: tox -e py
+        run: |
+          source .tox/py/bin/activate
+          pip install ../ddtrace
+          pip install -e .
+          pytest -p no:warnings
 
   starlette-testsuite-0_17_1:
     runs-on: "ubuntu-latest"
     env:
       DD_TESTING_RAISE: true
       DD_PROFILING_ENABLED: true
+      PYTHONPATH: ../ddtrace/tests/debugging/exploration/
     defaults:
       run:
         working-directory: starlette
@@ -294,7 +308,7 @@ jobs:
       #Parameters for keyword expression skip 3 failing tests that are expected due to asserting on headers. The errors are because our context propagation headers are being added
       #test_staticfiles_with_invalid_dir_permissions_returns_401 fails with and without ddtrace enabled
       - name: Run tests
-        run: pytest --ddtrace-patch-all tests -k 'not test_request_headers and not test_subdomain_route and not test_websocket_headers and not test_staticfiles_with_invalid_dir_permissions_returns_401'
+        run: pytest -W ignore --ddtrace-patch-all tests -k 'not test_request_headers and not test_subdomain_route and not test_websocket_headers and not test_staticfiles_with_invalid_dir_permissions_returns_401'
 
   requests-testsuite-2_26_0:
     runs-on: "ubuntu-latest"
@@ -323,7 +337,7 @@ jobs:
       - name: MarkupSafe fix
         run: pip install --upgrade MarkupSafe==2.0.1
       - name: Run tests
-        run: ddtrace-run pytest -p no:warnings tests
+        run: PYTHONPATH=../ddtrace/tests/debugging/exploration/ ddtrace-run pytest -p no:warnings tests
 
   asyncpg-testsuite-0_25_0:
     # https://github.com/MagicStack/asyncpg/blob/v0.25.0/.github/workflows/tests.yml#L125
@@ -356,3 +370,37 @@ jobs:
           python -m pip install -e .[test]
       - name: Run tests
         run: ddtrace-run python setup.py test
+
+  pylons-testsuite-1_0_3:
+    name: Pylons 1.0.3
+    runs-on: "ubuntu-latest"
+    env:
+      DD_TESTING_RAISE: true
+      PYTHONPATH: ../ddtrace/tests/debugging/exploration/
+    defaults:
+      run:
+        working-directory: pylons
+    steps:
+      - uses: actions/setup-python@v2
+        with:
+          python-version: '2.7'
+      - uses: actions/checkout@v2
+        with:
+          path: ddtrace
+      - uses: actions/checkout@v2
+        with:
+          repository: pylons/pylons
+          ref: master
+          path: pylons
+      - name: Install ddtrace
+        run: pip install ../ddtrace
+      - name: Install test dependencies
+        run: pip install -e .[test]
+      - name: MarkupSafe fix
+        run: pip install --upgrade MarkupSafe==0.18 pip setuptools --force
+      - name: Disable failing tests
+        run: |
+          sed -i'' "s/test_detect_lang/detect_lang/g" tests/test_units/test_basic_app.py
+          sed -i'' "s/test_langs/langs/g" tests/test_units/test_basic_app.py
+      - name: Run tests
+        run: nosetests

tests/debugging/exploration/__init__.py

@@ -0,0 +1,20 @@
+"""
+The exploration debugger is a special case of the debugger that is used to
+instrument all the lines and functions within a codebase during the test runs.
+This is to ensure that the tests still pass with the instrumentation on.
+
+To run an exploration test, set the environment variable
+
+    PYTHONPATH=/path/to/tests/debugging/exploration/
+
+Line and function instrumentation can be turned off independently by setting
+the environment variables ``DD_DEBUGGER_EXPL_COVERAGE_ENABLED`` and
+``DD_DEBUGGER_EXPL_PROFILER_ENABLED`` to ``0``. As a proof of work for the
+instrumentation, we use line probes to measure line coverage during tests.
+For function probes, we count the number of times a function is called, like
+a deterministic profiler. Aa the end of the test runs, we report the function
+calls and the line coverage.
+
+Encoding can be turned off for very large test suites by setting the environment
+variable ``DD_DEBUGGER_EXPL_ENCODE`` to ``0``.
+"""

tests/debugging/exploration/_coverage.py

@@ -0,0 +1,100 @@
+from collections import defaultdict
+import os
+import sys
+from types import ModuleType
+import typing as t
+
+from debugger import COLS
+from debugger import CWD
+from debugger import ExplorationDebugger
+from debugger import ModuleCollector
+from debugger import status
+
+from ddtrace.debugging._function.discovery import FunctionDiscovery
+from ddtrace.debugging._probe.model import LineProbe
+from ddtrace.debugging._snapshot.model import Snapshot
+from ddtrace.internal.module import origin
+from ddtrace.internal.utils.formats import asbool
+
+
+# Track all the covered modules and its lines. Indexed by module origin.
+_tracked_modules = {}  # type: t.Dict[str, t.Tuple[ModuleType, t.Set[int]]]
+
+ENABLED = asbool(os.getenv("DD_DEBUGGER_EXPL_COVERAGE_ENABLED", True))
+DELETE_LINE_PROBE = asbool(os.getenv("DD_DEBUGGER_EXPL_DELETE_LINE_PROBE", False))
+
+
+class LineCollector(ModuleCollector):
+    def on_collect(self, discovery):
+        # type: (FunctionDiscovery) -> None
+        o = origin(discovery._module)
+        status("[coverage] collecting lines from %s" % o)
+        _tracked_modules[o] = (discovery._module, {_ for _ in discovery.keys()})
+        LineCoverage.add_probes(
+            [
+                LineProbe(
+                    probe_id="@".join([str(hash(f)), str(line)]),
+                    source_file=origin(sys.modules[f.__module__]),
+                    line=line,
+                    rate=0.0,
+                )
+                for line, functions in discovery.items()
+                for f in functions
+            ]
+        )
+
+
+class LineCoverage(ExplorationDebugger):
+    __watchdog__ = LineCollector
+
+    @classmethod
+    def report_coverage(cls):
+        # type: () -> None
+        seen_lines_map = defaultdict(set)
+        for probe in (_ for _ in cls.get_triggered_probes() if isinstance(_, LineProbe)):
+            seen_lines_map[probe.source_file].add(probe.line)
+
+        try:
+            w = max(len(os.path.relpath(o, CWD)) for o in _tracked_modules)
+        except ValueError:
+            w = int(COLS * 0.75)
+        print(("{:=^%ds}" % COLS).format(" Line coverage "))
+        print("")
+        head = ("{:<%d} {:>5} {:>6}" % w).format("Source", "Lines", "Covered")
+        print(head)
+        print("=" * len(head))
+
+        total_lines = 0
+        total_covered = 0
+        for o, (_, lines) in sorted(_tracked_modules.items(), key=lambda x: x[0]):
+            total_lines += len(lines)
+            seen_lines = seen_lines_map[o]
+            total_covered += len(seen_lines)
+            print(
+                ("{:<%d} {:>5} {: 6.0f}%%" % w).format(
+                    os.path.relpath(o, CWD),
+                    len(lines),
+                    len(seen_lines) * 100.0 / len(lines) if lines else 0,
+                )
+            )
+        if not total_lines:
+            print("No lines found")
+            return
+        print("-" * len(head))
+        print(("{:<%d} {:>5} {: 6.0f}%%" % w).format("TOTAL", total_lines, total_covered * 100.0 / total_lines))
+        print("")
+
+    @classmethod
+    def on_disable(cls):
+        # type: () -> None
+        cls.report_coverage()
+
+    @classmethod
+    def on_snapshot(cls, snapshot):
+        # type: (Snapshot) -> None
+        if DELETE_LINE_PROBE:
+            cls.delete_probe(snapshot.probe)
+
+
+if ENABLED:
+    LineCoverage.enable()

tests/debugging/exploration/_profiler.py

@@ -0,0 +1,69 @@
+import os
+import typing as t
+
+from debugger import COLS
+from debugger import ExplorationDebugger
+from debugger import ModuleCollector
+from debugger import status
+
+from ddtrace.debugging._function.discovery import FunctionDiscovery
+from ddtrace.debugging._probe.model import FunctionProbe
+from ddtrace.internal.utils.formats import asbool
+
+
+# Track all instrumented functions and their call count.
+_tracked_funcs = {}  # type: t.Dict[str, int]
+
+
+ENABLED = asbool(os.getenv("DD_DEBUGGER_EXPL_PROFILER_ENABLED", True))
+
+
+class FunctionCollector(ModuleCollector):
+    def on_collect(self, discovery):
+        # type: (FunctionDiscovery) -> None
+        module = discovery._module
+        status("[profiler] Collecting functions from %s" % module.__name__)
+        for fname, f in discovery._fullname_index.items():
+            _tracked_funcs[fname] = 0
+            DeterministicProfiler.add_probe(
+                FunctionProbe(
+                    probe_id=str(hash(f)),
+                    module=module.__name__,
+                    func_qname=fname.replace(module.__name__, "").lstrip("."),
+                    rate=float("inf"),
+                )
+            )
+
+
+class DeterministicProfiler(ExplorationDebugger):
+    __watchdog__ = FunctionCollector
+
+    @classmethod
+    def report_func_calls(cls):
+        # type: () -> None
+        for probe in (_ for _ in cls.get_triggered_probes() if isinstance(_, FunctionProbe)):
+            _tracked_funcs[".".join([probe.module, probe.func_qname])] += 1
+        print(("{:=^%ds}" % COLS).format(" Function coverage "))
+        print("")
+        calls = sorted([(v, k) for k, v in _tracked_funcs.items()], reverse=True)
+        if not calls:
+            print("No functions called")
+            return
+        w = max(len(f) for _, f in calls)
+        called = sum(v > 0 for v in _tracked_funcs.values())
+        print("Functions called: %d/%d" % (called, len(_tracked_funcs)))
+        print("")
+        print(("{:<%d} {:>5}" % w).format("Function", "Calls"))
+        print("=" * (w + 6))
+        for calls, func in calls:
+            print(("{:<%d} {:>5}" % w).format(func, calls))
+        print("")
+
+    @classmethod
+    def on_disable(cls):
+        # type: () -> None
+        cls.report_func_calls()
+
+
+if ENABLED:
+    DeterministicProfiler.enable()