Fix go tests to maintain order of the log output (#38)

* fix go tests

* add no ddlambda log test

* testing snapshot mismatches

* testing discrepancies

* increase log wait time

* fix scrubbing of integers

* fix timeout tests

* improve error test

* update snapshots

* continue testing

* scrub hex characters

* pls work

* fix run script

* add some time expectations to tests

* doh!

* build extension

* fix datadog layer tag

* version issue

* trying again

* strip trailing whitespace

Author: jcstorms1

.gitignore

@@ -4,7 +4,6 @@ integration_tests/node_modules
 integration_tests/recorder-extension/node_modules/
 integration_tests/recorder-extension/ext.zip
 integration_tests/.DS_Store
-integration_tests/bootstrap
 integration_tests/src/bin
 integration_tests/src/csharp-tests/bin
 integration_tests/src/csharp-tests/obj

integration_tests/bootstrap

@@ -0,0 +1,3 @@
+#!/bin/sh
+cd $LAMBDA_TASK_ROOT
+./${_HANDLER}

integration_tests/run.sh

@@ -6,7 +6,7 @@
 # To regenerate snapshots:
 #   UPDATE_SNAPSHOTS=true aws-vault exec sandbox-account-admin -- ./integration_tests/run.sh
 
-LOGS_WAIT_SECONDS=45
+LOGS_WAIT_SECONDS=600
 
 DEFAULT_NODE_LAYER_VERSION=66
 DEFAULT_PYTHON_LAYER_VERSION=49
@@ -40,15 +40,15 @@ GOOS=linux GOARCH=amd64 go build -o extensions/recorder-extension main.go
 zip -rq ext.zip extensions/* -x ".*" -x "__MACOSX" -x "extensions/.*"
 cd ..
 
-go_test_dirs=("with-ddlambda" "without-ddlambda" "timeout" "trace")
+go_test_dirs=("with-ddlambda" "without-ddlambda" "log-with-ddlambda" "log-without-ddlambda" "timeout" "trace")
 
-# build Go Lambda function
+# build Go Lambda functions
 cd src
 for go_dir in "${go_test_dirs[@]}"; do
     env GOOS=linux go build -ldflags="-s -w" -o bin/"$go_dir" go-tests/"$go_dir"/main.go
 done
 
-#build .NET function
+#build .NET functions
 cd csharp-tests
 dotnet restore
 set +e #set this so we don't exit if the tools are already installed
@@ -87,24 +87,25 @@ NODE_LAYER_VERSION=${NODE_LAYER_VERSION} \
     serverless deploy --stage ${stage}
 
 # invoke functions
-metric_function_names=("enhanced-metric-node" "enhanced-metric-python" "metric-csharp" "no-enhanced-metric-node" "no-enhanced-metric-python" "timeout-python" "timeout-node")
-log_function_names=("log-node" "log-python" "log-csharp")
 
-go_function_names=("with-ddlambda-go" "without-ddlambda-go" "timeout-go")
+metric_function_names=("enhanced-metric-node" "enhanced-metric-python" "metric-csharp" "no-enhanced-metric-node" "no-enhanced-metric-python" "with-ddlambda-go" "without-ddlambda-go" "timeout-python" "timeout-node" "timeout-go" "error-python" "error-node")
+log_function_names=("log-node" "log-python" "log-csharp" "log-go-with-ddlambda" "log-go-without-ddlambda")
 trace_function_names=("simple-trace-node" "simple-trace-python" "simple-trace-go")
 
-all_functions=("${metric_function_names[@]}" "${log_function_names[@]}" "${go_function_names[@]}" "${trace_function_names[@]}")
+all_functions=("${metric_function_names[@]}" "${log_function_names[@]}" "${trace_function_names[@]}")
 
 set +e # Don't exit this script if an invocation fails or there's a diff
-
 for function_name in "${all_functions[@]}"; do
     serverless invoke --stage ${stage} -f ${function_name}
+done
+#wait 30 seconds to make sure metrics aren't merged into a single metric
+sleep 30
+for function_name in "${all_functions[@]}"; do
     # two invocations are needed since enhanced metrics are computed with the REPORT log line (which is created at the end of the first invocation)
     return_value=$(serverless invoke --stage ${stage} -f ${function_name})
-
     # Compare new return value to snapshot
     diff_output=$(echo "$return_value" | diff - "./snapshots/expectedInvocationResult")
-    if [ "$?" -eq 1 ] && [ [ "${function_name:0:7}" != timeout ] || [ "${function_name:0:5}" != error ] ]; then
+    if [ "$?" -eq 1 ] && { [ "${function_name:0:7}" != timeout ] && [ "${function_name:0:5}" != error ]; }; then
         echo "Failed: Return value for $function_name does not match snapshot:"
         echo "$diff_output"
         mismatch_found=true
@@ -113,7 +114,10 @@ for function_name in "${all_functions[@]}"; do
     fi
 done
 
+now=$(date +"%r")
 echo "Sleeping $LOGS_WAIT_SECONDS seconds to wait for logs to appear in CloudWatch..."
+echo "This should be done in 10 minutes from $now"
+
 sleep $LOGS_WAIT_SECONDS
 
 for function_name in "${all_functions[@]}"; do
@@ -136,19 +140,23 @@ for function_name in "${all_functions[@]}"; do
         # Normalize metrics
         logs=$(
             echo "$raw_logs" |
-                grep "\[sketch\]" |
+                perl -p -e "s/raise Exception/\n/g" |
+                grep -v "\[log\]" |
+                grep "\[sketch\].*" |
                 perl -p -e "s/(ts\":)[0-9]{10}/\1XXX/g" |
-                perl -p -e "s/(min\":)[0-9\.e\-]{2,30}/\1XXX/g" |
-                perl -p -e "s/(max\":)[0-9\.e\-]{2,30}/\1XXX/g" |
-                perl -p -e "s/(cnt\":)[0-9\.e\-]{2,30}/\1XXX/g" |
-                perl -p -e "s/(avg\":)[0-9\.e\-]{2,30}/\1XXX/g" |
-                perl -p -e "s/(sum\":)[0-9\.e\-]{2,30}/\1XXX/g" |
+                perl -p -e "s/(min\":)[0-9\.e\-]{1,30}/\1XXX/g" |
+                perl -p -e "s/(max\":)[0-9\.e\-]{1,30}/\1XXX/g" |
+                perl -p -e "s/(cnt\":)[0-9\.e\-]{1,30}/\1XXX/g" |
+                perl -p -e "s/(avg\":)[0-9\.e\-]{1,30}/\1XXX/g" |
+                perl -p -e "s/(sum\":)[0-9\.e\-]{1,30}/\1XXX/g" |
                 perl -p -e "s/(k\":\[)[0-9\.e\-]{1,30}/\1XXX/g" |
                 perl -p -e "s/(datadog-nodev)[0-9]+\.[0-9]+\.[0-9]+/\1X\.X\.X/g" |
                 perl -p -e "s/(datadog_lambda:v)[0-9]+\.[0-9]+\.[0-9]+/\1X\.X\.X/g" |
+                perl -p -e "s/dd_lambda_layer:datadog-go[0-9.]{1,}/dd_lambda_layer:datadog-gox.x.x/g" |
                 perl -p -e "s/(dd_lambda_layer:datadog-python)[0-9_]+\.[0-9]+\.[0-9]+/\1X\.X\.X/g" |
                 perl -p -e "s/(serverless.lambda-extension.integration-test.count)[0-9\.]+/\1/g" |
                 perl -p -e "s/$stage/XXXXXX/g" |
+                perl -p -e "s/[ ]$//g" |
                 sort
         )
     elif [[ " ${log_function_names[*]} " =~ " ${function_name} " ]]; then
@@ -162,33 +170,9 @@ for function_name in "${all_functions[@]}"; do
                 perl -p -e "s/(,\"request_id\":\")[a-zA-Z0-9\-,]+\"//g" |
                 perl -p -e "s/$stage/STAGE/g" |
                 perl -p -e "s/(\"message\":\").*(XXX LOG)/\1\2\3/g" |
+                perl -p -e "s/[ ]$//g" |
                 grep XXX
         )
-    elif [[ " ${go_function_names[*]} " =~ " ${function_name} " ]]; then
-        logs=$(
-            echo "$raw_logs" |
-                grep -E "\[sketch\]|\[log\]" |
-                perl -p -e "s/(ts\":)[0-9]{10}/\1XXX/g" |
-                perl -p -e "s/(min\":)[0-9\.e\-]{2,30}/\1XXX/g" |
-                perl -p -e "s/(max\":)[0-9\.e\-]{2,30}/\1XXX/g" |
-                perl -p -e "s/(cnt\":)[0-9\.e\-]{2,30}/\1XXX/g" |
-                perl -p -e "s/(avg\":)[0-9\.e\-]{2,30}/\1XXX/g" |
-                perl -p -e "s/(sum\":)[0-9\.e\-]{2,30}/\1XXX/g" |
-                perl -p -e "s/(k\":\[)[0-9\.e\-]{1,30}/\1XXX/g" |
-                perl -p -e "s/(datadog-nodev)[0-9]+\.[0-9]+\.[0-9]+/\1X\.X\.X/g" |
-                perl -p -e "s/(datadog_lambda:v)[0-9]+\.[0-9]+\.[0-9]+/\1X\.X\.X/g" |
-                perl -p -e "s/(dd_lambda_layer:datadog-python)[0-9_]+\.[0-9]+\.[0-9]+/\1X\.X\.X/g" |
-                perl -p -e "s/(serverless.lambda-extension.integration-test.count)[0-9\.]+/\1/g" |
-                perl -p -e "s/$stage/XXXXXX/g" |
-                perl -p -e "s/(timestamp\":)[0-9]{13}/\1TIMESTAMP/g" |
-                perl -p -e "s/(\"REPORT |START |END ).*/\1XXX\"}}/g" |
-                perl -p -e "s/(\"HTTP ).*/\1\"}}/g" |
-                perl -p -e "s/(,\"request_id\":\")[a-zA-Z0-9\-,]+\"//g" |
-                perl -p -e "s/$stage/STAGE/g" |
-                perl -p -e "s/(\"message\":\").*(XXX LOG)/\1\2\3/g" |
-                grep XXX
-
-        )
     else
         # Normalize traces
         logs=$(
@@ -202,6 +186,7 @@ for function_name in "${all_functions[@]}"; do
                 perl -p -e "s/(,\"runtime-id\":\")[a-zA-Z0-9\-,]+\"/\1XXX\"/g" |
                 perl -p -e "s/(,\"system.pid\":\")[a-zA-Z0-9\-,]+\"/\1XXX\"/g" |
                 perl -p -e "s/$stage/XXXXXX/g" |
+                perl -p -e "s/[ ]$//g" |
                 sort
         )
     fi

integration_tests/serverless.yml

@@ -199,6 +199,36 @@ functions:
       DD_EXTRA_TAGS: tagC:valueC tagD:valueD
       DD_LAMBDA_HANDLER: src/logPython.log
 
+  log-go-with-ddlambda:
+    runtime: provided.al2
+    handler: src/bin/log-with-ddlambda
+    layers:
+      - { Ref: RecorderExtensionLambdaLayer }
+      - { Ref: DatadogExtensionIntegrationTestLambdaLayer }
+    environment:
+      DD_ENHANCED_METRICS: false
+      DD_LOG_LEVEL: ERROR
+      DD_LOGS_ENABLED: true
+      DD_SERVERLESS_LOGS_ENABLED: true
+      DD_LOGS_INJECTION: true
+      DD_TAGS: tagA:valueA tagB:valueB
+      DD_EXTRA_TAGS: tagC:valueC tagD:valueD
+
+  log-go-without-ddlambda:
+    runtime: provided.al2
+    handler: src/bin/log-without-ddlambda
+    layers:
+      - { Ref: RecorderExtensionLambdaLayer }
+      - { Ref: DatadogExtensionIntegrationTestLambdaLayer }
+    environment:
+      DD_ENHANCED_METRICS: false
+      DD_LOG_LEVEL: ERROR
+      DD_LOGS_ENABLED: true
+      DD_SERVERLESS_LOGS_ENABLED: true
+      DD_LOGS_INJECTION: true
+      DD_TAGS: tagA:valueA tagB:valueB
+      DD_EXTRA_TAGS: tagC:valueC tagD:valueD
+
   simple-trace-node:
     runtime: nodejs14.x
     handler: /opt/nodejs/node_modules/datadog-lambda-js/handler.handler