fix: SDK will report warning for unclosed spans (#635)

Author: Danwakeem

node/packages/aws-lambda-sdk/package.json

@@ -4,7 +4,7 @@
   "version": "0.14.11",
   "author": "Serverless, Inc.",
   "dependencies": {
-    "@serverless/sdk": "^0.5.5",
+    "@serverless/sdk": "^0.5.6",
     "@serverless/sdk-schema": "^0.15.3",
     "d": "^1.0.1",
     "ext": "^1.7.0",

node/packages/aws-lambda-sdk/test/fixtures/lambdas/esm-sdk/index.js

@@ -23,6 +23,9 @@ export const handler = async () => {
   sdk.setTag('user.tag', `example:${invocationId}`);
 
   console.warn('Consoled warning', 12, true);
+
+  sdk._createTraceSpan('custom.not.closed');
+
   return {
     name: sdk.name,
     version: sdk.version,

node/packages/aws-lambda-sdk/test/fixtures/lambdas/sdk.js

@@ -27,6 +27,9 @@ module.exports.handler = async (event) => {
   sdk.setTag('user.tag', `example:${invocationId}`);
 
   console.warn('Consoled warning', 12, true);
+
+  sdk._createTraceSpan('custom.not.closed');
+
   return {
     name: sdk.name,
     version: sdk.version,

node/packages/aws-lambda-sdk/test/integration/index.test.js

@@ -413,25 +413,29 @@ describe('integration', function () {
       { name: 'telemetry.error.generated.v1', type: 'ERROR_TYPE_CAUGHT_USER' },
       { name: 'telemetry.warning.generated.v1', type: 'WARNING_TYPE_USER' },
       { name: 'telemetry.warning.generated.v1', type: 'WARNING_TYPE_USER' },
+      { name: 'telemetry.warning.generated.v1', type: 'WARNING_TYPE_SDK_INTERNAL' },
     ],
     test: ({ invocationsData }) => {
       for (const [index, { trace, responsePayload }] of invocationsData.entries()) {
         const { spans, events, customTags } = trace;
         let awsLambdaInvocationSpan;
+        const rootSpan = spans[0];
         if (index === 0) {
           awsLambdaInvocationSpan = spans[2];
           expect(spans.map(({ name }) => name)).to.deep.equal([
             'aws.lambda',
             'aws.lambda.initialization',
             'aws.lambda.invocation',
             'user.span',
+            'custom.not.closed',
           ]);
         } else {
           awsLambdaInvocationSpan = spans[1];
           expect(spans.map(({ name }) => name)).to.deep.equal([
             'aws.lambda',
             'aws.lambda.invocation',
             'user.span',
+            'custom.not.closed',
           ]);
         }
         const payload = JSON.parse(responsePayload.raw);
@@ -508,6 +512,20 @@ describe('integration', function () {
               },
             },
           },
+          {
+            traceId: rootSpan.traceId,
+            spanId: rootSpan.id,
+            eventName: 'telemetry.warning.generated.v1',
+            customTags: JSON.stringify({}),
+            customFingerprint: 'SDK_SPAN_NOT_CLOSED',
+            tags: {
+              warning: {
+                message:
+                  "Serverless SDK Warning: Following trace spans didn't end before end of lambda invocation: custom.not.closed\n",
+                type: 3,
+              },
+            },
+          },
         ]);
       }
     },
@@ -1778,7 +1796,15 @@ describe('integration', function () {
               'aws.lambda.invocation',
             ]);
           },
+          // The internal captured events may not actually get published until a following
+          // invocation. So we will leverage the hasOrphanedSpans flag to indicate
+          // that an acceptable event list for this test should be an empty array _or_
+          // the capturedEvents listed below.
           hasOrphanedSpans: true,
+          capturedEvents: [
+            // Warning generated by the SDK when the span fails to close
+            { name: 'telemetry.warning.generated.v1', type: 'WARNING_TYPE_SDK_INTERNAL' },
+          ],
         },
       },
     ],
@@ -1842,7 +1868,7 @@ describe('integration', function () {
       if (testResult.error) throw testResult.error;
       log.debug('%s test result: %o', testConfig.name, testResult);
       const afterTimestamp = resolveNanosecondsTimestamp() + 2000000000; // 2 seconds after
-      const { expectedOutcome, capturedEvents } = testConfig;
+      const { expectedOutcome, capturedEvents, hasOrphanedSpans } = testConfig;
       const { invocationsData } = testResult;
       if (
         expectedOutcome === 'success' ||
@@ -1951,7 +1977,12 @@ describe('integration', function () {
               ]);
             }
           }
-          if (capturedEvents) expect(normalizedEvents).deep.equal(capturedEvents);
+          if (
+            (capturedEvents && !hasOrphanedSpans) ||
+            (capturedEvents && hasOrphanedSpans && normalizedEvents.length > 0)
+          ) {
+            expect(normalizedEvents).deep.equal(capturedEvents);
+          }
         }
       }
       if (testConfig.test) {

node/packages/aws-lambda-sdk/test/unit/internal-extension/index.test.js

@@ -818,6 +818,7 @@ describe('internal-extension/index.test.js', () => {
       'aws.lambda.initialization',
       'aws.lambda.invocation',
       'user.span',
+      'custom.not.closed',
     ]);
     expect(result.name).to.equal(pkgJson.name);
     expect(result.version).to.equal(pkgJson.version);
@@ -841,6 +842,7 @@ describe('internal-extension/index.test.js', () => {
       delete event.timestampUnixNano;
       return event;
     };
+    const { id: SDK_ERROR_SPAN_ID } = spans[0];
     const { traceId, spanId } = events[0];
     expect(events.map(normalizeEvent)).to.deep.equal([
       {
@@ -893,6 +895,20 @@ describe('internal-extension/index.test.js', () => {
           },
         },
       },
+      {
+        traceId,
+        spanId: SDK_ERROR_SPAN_ID,
+        eventName: 'telemetry.warning.generated.v1',
+        customFingerprint: 'SDK_SPAN_NOT_CLOSED',
+        customTags: JSON.stringify({}),
+        tags: {
+          warning: {
+            message:
+              "Serverless SDK Warning: Following trace spans didn't end before end of lambda invocation: custom.not.closed\n",
+            type: 3,
+          },
+        },
+      },
     ]);
   });
 
@@ -1017,13 +1033,15 @@ describe('internal-extension/index.test.js', () => {
           { name: 'aws.lambda.initialization', input: undefined, output: undefined },
           { name: 'user.span', input: undefined, output: undefined },
           { name: 'aws.lambda.invocation', input: undefined, output: undefined },
+          { name: 'custom.not.closed', input: undefined, output: undefined },
           { name: 'aws.lambda', input: undefined, output: undefined },
         ],
         traceEvents: [
           { eventName: 'telemetry.error.generated.v1' },
           { eventName: 'telemetry.error.generated.v1' },
           { eventName: 'telemetry.warning.generated.v1' },
           { eventName: 'telemetry.warning.generated.v1' },
+          { eventName: 'telemetry.warning.generated.v1' },
         ],
       });
     });

node/packages/aws-lambda-sdk/trace-spans/aws-lambda.js

@@ -1,6 +1,7 @@
 'use strict';
 
 const TraceSpan = require('@serverless/sdk/lib/trace-span');
+const reportWarning = require('@serverless/sdk/lib/report-warning');
 
 const immutableTags = {
   'aws.lambda.name': process.env.AWS_LAMBDA_FUNCTION_NAME,
@@ -28,6 +29,7 @@ const awsLambdaSpan = new TraceSpan('aws.lambda', {
   startTime: EvalError.$serverlessAwsLambdaInitializationStartTime,
   immediateDescendants: ['aws.lambda.initialization'],
   tags: immutableTags,
+  _reportWarning: reportWarning,
 });
 
 if (process.env.AWS_LAMBDA_INITIALIZATION_TYPE === 'on-demand') {