Log HTTP requests if DD_INTEGRATION_TEST=true; normalize snapshots more

Author: swfunc

datadog_lambda/patch.py

@@ -3,6 +3,8 @@
 # This product includes software developed at Datadog (https://www.datadoghq.com/).
 # Copyright 2019 Datadog, Inc.
 
+import json
+import os
 import sys
 import logging
 
@@ -13,9 +15,9 @@
 logger = logging.getLogger(__name__)
 
 if sys.version_info >= (3, 0, 0):
-    httplib_module = 'http.client'
+    httplib_module = "http.client"
 else:
-    httplib_module = 'httplib'
+    httplib_module = "httplib"
 
 _httplib_patched = False
 _requests_patched = False
@@ -38,12 +40,9 @@ def _patch_httplib():
     global _httplib_patched
     if not _httplib_patched:
         _httplib_patched = True
-        wrap(
-            httplib_module,
-            'HTTPConnection.request',
-            _wrap_httplib_request
-        )
-    logger.debug('Patched %s', httplib_module)
+        wrap(httplib_module, "HTTPConnection.request", _wrap_httplib_request)
+
+    logger.debug("Patched %s", httplib_module)
 
 
 def _patch_requests():
@@ -55,14 +54,10 @@ def _patch_requests():
     if not _requests_patched:
         _requests_patched = True
         try:
-            wrap(
-                'requests',
-                'Session.request',
-                _wrap_requests_request
-            )
-            logger.debug('Patched requests')
+            wrap("requests", "Session.request", _wrap_requests_request)
+            logger.debug("Patched requests")
         except Exception:
-            logger.debug('Failed to patch requests', exc_info=True)
+            logger.debug("Failed to patch requests", exc_info=True)
 
 
 def _wrap_requests_request(func, instance, args, kwargs):
@@ -71,12 +66,18 @@ def _wrap_requests_request(func, instance, args, kwargs):
     into the outgoing requests.
     """
     context = get_dd_trace_context()
-    if 'headers' in kwargs:
-        kwargs['headers'].update(context)
+    if "headers" in kwargs:
+        kwargs["headers"].update(context)
     elif len(args) >= 5:
         args[4].update(context)
     else:
-        kwargs['headers'] = context
+        kwargs["headers"] = context
+
+    # If we're in an integration test, log the HTTP requests made
+    if os.environ.get("DD_INTEGRATION_TEST", "false").lower() == "true":
+        request_string = "HTTP {} Kwargs: {}".format(" ".join(args), kwargs)
+        print(request_string)
+
     return func(*args, **kwargs)
 
 
@@ -86,10 +87,16 @@ def _wrap_httplib_request(func, instance, args, kwargs):
     the Datadog trace headers into the outgoing requests.
     """
     context = get_dd_trace_context()
-    if 'headers' in kwargs:
-        kwargs['headers'].update(context)
+    if "headers" in kwargs:
+        kwargs["headers"].update(context)
     elif len(args) >= 4:
         args[3].update(context)
     else:
-        kwargs['headers'] = context
+        kwargs["headers"] = context
+
+    if os.environ.get("DD_INTEGRATION_TEST", "false").lower() == "true":
+        request_string = "HTTP {} Kwargs: {}".format(" ".join(args), kwargs)
+        print(request_string)
+
     return func(*args, **kwargs)
+

scripts/run_integration_tests.sh

@@ -5,7 +5,7 @@ set -e
 
 # These values need to be in sync with serverless.yml, where there needs to be a function
 # defined for every handler-runtime combination
-LAMBDA_HANDLERS=("async-metrics")
+LAMBDA_HANDLERS=("async-metrics" "sync-metrics")
 RUNTIMES=("python27" "python36" "python37" "python38")
 
 LOGS_WAIT_SECONDS=20
@@ -21,45 +21,53 @@ mismatch_found=false
 
 echo "Start time is $script_start_time"
 
-echo "Building layers that will be deployed with our test functions"
-# source $scripts_dir/build_layers.sh
-
-if [ -n "$OVERWRITE" ]; then
+if [ -n "$UPDATE_SNAPSHOTS" ]; then
     echo "Overwriting snapshots in this execution"
 fi
 
+if [ -z "$DD_API_KEY" ]; then
+    echo "No DD_API_KEY env var set, exiting"
+    exit 1
+else
+    echo "The API key is $DD_API_KEY"
+fi
+
+echo "Building layers that will be deployed with our test functions"
+# source $scripts_dir/build_layers.sh
+
 echo "Deploying functions"
 cd $integration_tests_dir
 serverless deploy
 
 echo "Invoking functions"
+set +e # Don't exit this script if an invocation fails
 for handler_name in "${LAMBDA_HANDLERS[@]}"; do
     for runtime in "${RUNTIMES[@]}"; do
         function_name="$handler_name-$runtime"
         function_snapshot_path="./snapshots/$function_name.return_value"
 
         return_value=$(serverless invoke -f $function_name)
 
-        if [ -n "$OVERWRITE" ]; then
-            # If $OVERWRITE is set to true, write the new logs over the current snapshot
+        if [ -n "$UPDATE_SNAPSHOTS" ]; then
+            # If $UPDATE_SNAPSHOTS is set to true, write the new logs over the current snapshot
             echo "Overwriting return value snapshot for $function_name"
             echo "$return_value" >$function_snapshot_path
         else
             # Compare new return value to snapshot
-            set +e # Don't exit this script if there is a diff
             diff_output=$(echo "$return_value" | diff - $function_snapshot_path)
             if [ $? -eq 1 ]; then
-                echo "FAILURE: Return value for $function_name does not match snapshot:"
+                echo "Failed: Return value for $function_name does not match snapshot:"
                 echo "$diff_output"
                 mismatch_found=true
             else
-                echo "SUCCESS: Return value for $function_name matches snapshot"
+                echo "Ok: Return value for $function_name matches snapshot"
             fi
-            set -e
         fi
     done
 done
 
+set -e
+
 echo "Sleeping $LOGS_WAIT_SECONDS seconds to wait for logs to appear in CloudWatch..."
 sleep $LOGS_WAIT_SECONDS
 
@@ -75,32 +83,46 @@ for handler_name in "${LAMBDA_HANDLERS[@]}"; do
         # Filter serverless cli errors
         logs=$(echo "$logs" | sed '/Serverless: Recoverable error occurred/d')
 
-        # Replace invocation-specific data with XXXX to normalize between executions
+        # Replace invocation-specific data like timestamps and IDs with XXXX to normalize logs across executions
+        # Normalize Lambda runtime report logs
         logs=$(echo "$logs" | sed -E 's/(RequestId|TraceId|SegmentId|Duration|Memory Used|"e"): [a-z0-9\.\-]+/\1: XXXX/g')
-
-        if [ -n "$OVERWRITE" ]; then
-            # If $OVERWRITE is set to true, write the new logs over the current snapshot
-            echo "Overwriting snapshot for $function_name"
+        # Normalize DD APM headers
+        logs=$(echo "$logs" | sed -E "s/('x-datadog-parent-id': '|'x-datadog-trace-id': ')[0-9]+/\1XXXX/g")
+        # Normalize timestamps logged requests
+        logs=$(echo "$logs" | sed -E 's/"points": \[\[[0-9\.]+,/"points": \[\[XXXX,/g')
+        # Normalize the invocation IDs used in requests to the Lambda runtime
+        logs=$(echo "$logs" | sed -E 's/\/2018-06-01\/runtime\/invocation\/[a-z0-9-]+/\/2018-06-01\/runtime\/invocation\/XXXX/g')
+        # Strip API key from logged requests
+        logs=$(echo "$logs" | sed -E "s/(api_key=|'api_key': ')[a-z0-9\.\-]+/\1XXXX/g")
+
+        if [ -n "$UPDATE_SNAPSHOTS" ]; then
+            # If $UPDATE_SNAPSHOTS is set to true, write the new logs over the current snapshot
+            echo "Overwriting log snapshot for $function_name"
             echo "$logs" >$function_snapshot_path
         else
             # Compare new logs to snapshots
             set +e # Don't exit this script if there is a diff
             diff_output=$(echo "$logs" | diff - $function_snapshot_path)
             if [ $? -eq 1 ]; then
-                echo "FAILURE: Mismatch found between new $function_name logs and snapshot:"
+                echo "Failed: Mismatch found between new $function_name logs and snapshot:"
                 echo "$diff_output"
                 mismatch_found=true
             else
-                echo "SUCCESS: New logs for $function_name match snapshot"
+                echo "Ok: New logs for $function_name match snapshot"
             fi
             set -e
         fi
     done
 done
 
 if [ "$mismatch_found" = true ]; then
-    echo "TEST FAILED: A mismatch between newly generated logs and a snapshot was found above. If this is expected, re-run this script with OVERWRITE=true to generate new snapshots"
+    echo "FAILURE: A mismatch between new data and a snapshot was found and printed above. If the change is expected, generate new snapshots by running 'UPDATE_SNAPSHOTS=true ./scripts/run_integration_tests.sh'"
     exit 1
 fi
 
-echo "TEST SUCCEEDED: No difference found between new logs and snapshots"
+if [ -n "$UPDATE_SNAPSHOTS" ]; then
+    echo "SUCCESS: Wrote new snapshots for all functions"
+    exit 0
+fi
+
+echo "SUCCESS: No difference found between new logs and snapshots"

tests/integration/date

@@ -0,0 +1,16 @@
+import json
+import requests
+
+from datadog_lambda.metric import lambda_metric
+from datadog_lambda.wrapper import datadog_lambda_wrapper
+
+
+@datadog_lambda_wrapper
+def handle(event, context):
+    lambda_metric("hello.dog", 1, tags=["team:serverless", "role:hello"])
+    lambda_metric(
+        "tests.integration.count", 21, tags=["test:integration", "role:hello"]
+    )
+    response = requests.get("https://datadoghq.com")
+
+    return {"statusCode": 200, "body": "hello, dog!"}

tests/integration/submit_metrics.py tests/integration/handle.pytests/integration/submit_metrics.py renamed to tests/integration/handle.py

@@ -5,6 +5,9 @@ provider:
   tracing:
     lambda: true
     apiGateway: true
+  environment:
+    DD_INTEGRATION_TEST: true
+    DD_API_KEY: ${env:DD_API_KEY}
 
 layers:
   python27:
@@ -21,66 +24,60 @@ layers:
       artifact: ../../.layers/datadog_lambda_py3.8.zip
 
 functions:
+  # async-metrics
   async-metrics-python27:
-    handler: submit_metrics.handle
+    handler: handle.handle
     runtime: python2.7
     layers:
       - { Ref: Python27LambdaLayer }
     environment:
       DD_FLUSH_TO_LOG: true
 
   async-metrics-python36:
-    handler: submit_metrics.handle
+    handler: handle.handle
     runtime: python3.6
     layers:
       - { Ref: Python36LambdaLayer }
     environment:
       DD_FLUSH_TO_LOG: true
 
   async-metrics-python37:
-    handler: submit_metrics.handle
+    handler: handle.handle
     runtime: python3.7
     layers:
       - { Ref: Python37LambdaLayer }
     environment:
       DD_FLUSH_TO_LOG: true
 
   async-metrics-python38:
-    handler: submit_metrics.handle
+    handler: handle.handle
     runtime: python3.8
     layers:
       - { Ref: Python38LambdaLayer }
     environment:
       DD_FLUSH_TO_LOG: true
 
+  # sync-metrics
   sync-metrics-python27:
-    handler: submit_metrics.handle
+    handler: handle.handle
     runtime: python2.7
     layers:
       - { Ref: Python27LambdaLayer }
-    environment:
-      DD_API_KEY: "abcdefghijk"
 
   sync-metrics-python36:
-    handler: submit_metrics.handle
+    handler: handle.handle
     runtime: python3.6
     layers:
       - { Ref: Python36LambdaLayer }
-    environment:
-      DD_API_KEY: "abcdefghijk"
 
   sync-metrics-python37:
-    handler: submit_metrics.handle
+    handler: handle.handle
     runtime: python3.7
     layers:
       - { Ref: Python37LambdaLayer }
-    environment:
-      DD_API_KEY: "abcdefghijk"
 
   sync-metrics-python38:
-    handler: submit_metrics.handle
+    handler: handle.handle
     runtime: python3.8
     layers:
       - { Ref: Python38LambdaLayer }
-    environment:
-      DD_API_KEY: "abcdefghijk"

tests/integration/http_requests.py

@@ -1,7 +1,10 @@
+HTTP GET /2018-06-01/runtime/invocation/XXXX Kwargs: {'headers': {'x-datadog-trace-id': 'XXXX', 'x-datadog-parent-id': 'XXXX', 'x-datadog-sampling-priority': '-1'}}
 START RequestId: XXXX Version: $LATEST
 {"m": "aws.lambda.enhanced.invocations", "v": 1, "e": XXXX, "t": ["region:us-east-1", "account_id:601427279990", "functionname:integration-tester-dev-async-metrics-python37", "cold_start:true", "memorysize:1024", "runtime:python3.7", "dd_lambda_layer:datadog-python37_2.13.0"]}
 {"m": "hello.dog", "v": 1, "e": XXXX, "t": ["team:serverless", "role:hello", "dd_lambda_layer:datadog-python37_2.13.0"]}
 {"m": "tests.integration.count", "v": 21, "e": XXXX, "t": ["test:integration", "role:hello", "dd_lambda_layer:datadog-python37_2.13.0"]}
+HTTP POST /2018-06-01/runtime/invocation/XXXX/response {"statusCode": 200, "body": "hello, dog!"} Kwargs: {'headers': {'Content-Type': 'application/json', 'x-datadog-trace-id': 'XXXX', 'x-datadog-parent-id': 'XXXX', 'x-datadog-sampling-priority': '2'}}
+HTTP GET /2018-06-01/runtime/invocation/XXXX Kwargs: {'headers': {'x-datadog-trace-id': 'XXXX', 'x-datadog-parent-id': 'XXXX', 'x-datadog-sampling-priority': '2'}}
 END RequestId: XXXX
 REPORT RequestId: XXXX	Duration: XXXX ms	Billed Duration: XXXX ms	Memory Size: 1024 MB	Max Memory Used: XXXX MB	Init Duration: XXXX ms	
 XRAY TraceId: XXXX	SegmentId: XXXX	Sampled: true	

tests/integration/serverless.yml

@@ -1,13 +1,3 @@
-/opt/python/lib/python3.8/site-packages/jmespath/visitor.py:32: SyntaxWarning: "is" with a literal. Did you mean "=="?
-  if x is 0 or x is 1:
-/opt/python/lib/python3.8/site-packages/jmespath/visitor.py:32: SyntaxWarning: "is" with a literal. Did you mean "=="?
-  if x is 0 or x is 1:
-/opt/python/lib/python3.8/site-packages/jmespath/visitor.py:34: SyntaxWarning: "is" with a literal. Did you mean "=="?
-  elif y is 0 or y is 1:
-/opt/python/lib/python3.8/site-packages/jmespath/visitor.py:34: SyntaxWarning: "is" with a literal. Did you mean "=="?
-  elif y is 0 or y is 1:
-/opt/python/lib/python3.8/site-packages/jmespath/visitor.py:260: SyntaxWarning: "is" with a literal. Did you mean "=="?
-  if original_result is 0:
 START RequestId: XXXX Version: $LATEST
 {"m": "aws.lambda.enhanced.invocations", "v": 1, "e": XXXX, "t": ["region:us-east-1", "account_id:601427279990", "functionname:integration-tester-dev-async-metrics-python38", "cold_start:true", "memorysize:1024", "runtime:python3.8", "dd_lambda_layer:datadog-python38_2.13.0"]}
 {"m": "hello.dog", "v": 1, "e": XXXX, "t": ["team:serverless", "role:hello", "dd_lambda_layer:datadog-python38_2.13.0"]}

tests/integration/snapshots/async-metrics-python37.logs

@@ -0,0 +1,7 @@
+START RequestId: XXXX Version: $LATEST
+{"e": XXXX, "m": "aws.lambda.enhanced.invocations", "t": ["region:us-east-1", "account_id:601427279990", "functionname:integration-tester-dev-sync-metrics-python27", "cold_start:true", "memorysize:1024", "runtime:python2.7", "dd_lambda_layer:datadog-python27_2.13.0"], "v": 1}
+HTTP POST https://api.datadoghq.com/api/v1/distribution_points Kwargs: {'verify': True, 'headers': {'x-datadog-trace-id': 'XXXX', 'Content-Type': 'application/json', 'x-datadog-sampling-priority': '2', 'x-datadog-parent-id': 'XXXX'}, 'params': {'api_key': 'XXXX'}, 'timeout': 60, 'proxies': None, 'data': '{"series": [{"tags": ["team:serverless", "role:hello", "dd_lambda_layer:datadog-python27_2.13.0"], "metric": "hello.dog", "interval": 10, "host": null, "points": [[XXXX, [1.0]]], "device": null, "type": "distribution"}, {"tags": ["test:integration", "role:hello", "dd_lambda_layer:datadog-python27_2.13.0"], "metric": "tests.integration.count", "interval": 10, "host": null, "points": [[XXXX, [21.0]]], "device": null, "type": "distribution"}]}'}
+HTTP POST /api/v1/distribution_points?api_key=XXXX Kwargs: {'body': '{"series": [{"tags": ["team:serverless", "role:hello", "dd_lambda_layer:datadog-python27_2.13.0"], "metric": "hello.dog", "interval": 10, "host": null, "points": [[XXXX, [1.0]]], "device": null, "type": "distribution"}, {"tags": ["test:integration", "role:hello", "dd_lambda_layer:datadog-python27_2.13.0"], "metric": "tests.integration.count", "interval": 10, "host": null, "points": [[XXXX, [21.0]]], "device": null, "type": "distribution"}]}', 'headers': {'Content-Length': '460', 'Accept-Encoding': 'gzip, deflate', 'x-datadog-sampling-priority': '2', 'Accept': '*/*', 'User-Agent': 'python-requests/2.23.0', 'Connection': 'keep-alive', 'x-datadog-trace-id': 'XXXX', 'x-datadog-parent-id': 'XXXX', 'Content-Type': 'application/json'}}
+END RequestId: XXXX
+REPORT RequestId: XXXX	Duration: XXXX ms	Billed Duration: XXXX ms	Memory Size: 1024 MB	Max Memory Used: XXXX MB	Init Duration: XXXX ms	
+XRAY TraceId: XXXX	SegmentId: XXXX	Sampled: true	

tests/integration/snapshots/async-metrics-python38.logs

@@ -0,0 +1,4 @@
+{
+    "body": "hello, dog!",
+    "statusCode": 200
+}