Repository: serverless/dashboard (language: python)

Issue:
Cannot intialize span: Trace is closed
Just installed the console observability layer into our aws platform which has a large deployment of lambda apis. Initial impression is great as it gives us a fantastic view across the whole platform. I can see errors in there which I hadn't seen before and will provide me the ability to see when the system hits periods of high usage.

But I keep seeing this error in there which I think is related to the serverless layer rather than our codebase, as everything appears to be working correctly. 

Stack trace below
Unhandled Promise Rejection 	{"errorType":"Runtime.UnhandledPromiseRejection","errorMessage":"Error: Cannot intialize span: Trace is closed","reason":{"errorType":"Error","errorMessage":"Cannot intialize span: Trace is closed","code":"UNREACHABLE_TRACE","stack":["Error: Cannot intialize span: Trace is closed","

   at new TraceSpan (/opt/sls-sdk-node/index.js:2156:33)","
   at Object.serverlessSdk.createTraceSpan (/opt/sls-sdk-node/index.js:3242:61)","
   at request2 (/opt/sls-sdk-node/index.js:2525:41)","
   at /var/task/node_modules/node-fetch/lib/index.js:1438:15","
   at new Promise (<anonymous>)","
   at fetch (/var/task/node_modules/node-fetch/lib/index.js:1407:9)","
   at fetch (/var/task/node_modules/cross-fetch/dist/node-ponyfill.js:10:20)","
   at GraphQLClient.<anonymous> (/var/task/node_modules/graphql-request/src/index.ts:87:28)","
   at step (/var/task/node_modules/graphql-request/dist/index.js:63:23)","
   at Object.next (/var/task/node_modules/graphql-request/dist/index.js:44:53)","
   at /var/task/node_modules/graphql-request/dist/index.js:38:71","
   at new Promise (<anonymous>)","
   at __awaiter (/var/task/node_modules/graphql-request/dist/index.js:34:12)","
   at GraphQLClient.request (/var/task/node_modules/graphql-request/dist/index.js:151:16)","
   at h (/var/task/src/controllers/mypath/mycode.ts:600:31)","
   at Timeout._onTimeout (/var/task/src/controllers/mypath/mycode.ts:249:17)"]},"promise":{},"stack":["Runtime.UnhandledPromiseRejection: Error: Cannot intialize span: Trace is closed","
   at process.<anonymous> (/var/runtime/index.js:35:15)","
   at process.emit (events.js:400:28)","
   at process.emit (/var/task/node_modules/source-map-support/source-map-support.js:495:21)","
   at processPromiseRejections (internal/process/promises.js:245:33)","
   at processTicksAndRejections (internal/process/task_queues.js:96:32)"]}

Any thoughts on what is causing this, or how to resolve. Thanks. 
Cannot intialize span: Trace is closed
Just installed the console observability layer into our aws platform which has a large deployment of lambda apis. Initial impression is great as it gives us a fantastic view across the whole platform. I can see errors in there which I hadn't seen before and will provide me the ability to see when the system hits periods of high usage.

But I keep seeing this error in there which I think is related to the serverless layer rather than our codebase, as everything appears to be working correctly. 

Stack trace below
Unhandled Promise Rejection 	{"errorType":"Runtime.UnhandledPromiseRejection","errorMessage":"Error: Cannot intialize span: Trace is closed","reason":{"errorType":"Error","errorMessage":"Cannot intialize span: Trace is closed","code":"UNREACHABLE_TRACE","stack":["Error: Cannot intialize span: Trace is closed","

   at new TraceSpan (/opt/sls-sdk-node/index.js:2156:33)","
   at Object.serverlessSdk.createTraceSpan (/opt/sls-sdk-node/index.js:3242:61)","
   at request2 (/opt/sls-sdk-node/index.js:2525:41)","
   at /var/task/node_modules/node-fetch/lib/index.js:1438:15","
   at new Promise (<anonymous>)","
   at fetch (/var/task/node_modules/node-fetch/lib/index.js:1407:9)","
   at fetch (/var/task/node_modules/cross-fetch/dist/node-ponyfill.js:10:20)","
   at GraphQLClient.<anonymous> (/var/task/node_modules/graphql-request/src/index.ts:87:28)","
   at step (/var/task/node_modules/graphql-request/dist/index.js:63:23)","
   at Object.next (/var/task/node_modules/graphql-request/dist/index.js:44:53)","
   at /var/task/node_modules/graphql-request/dist/index.js:38:71","
   at new Promise (<anonymous>)","
   at __awaiter (/var/task/node_modules/graphql-request/dist/index.js:34:12)","
   at GraphQLClient.request (/var/task/node_modules/graphql-request/dist/index.js:151:16)","
   at h (/var/task/src/controllers/mypath/mycode.ts:600:31)","
   at Timeout._onTimeout (/var/task/src/controllers/mypath/mycode.ts:249:17)"]},"promise":{},"stack":["Runtime.UnhandledPromiseRejection: Error: Cannot intialize span: Trace is closed","
   at process.<anonymous> (/var/runtime/index.js:35:15)","
   at process.emit (events.js:400:28)","
   at process.emit (/var/task/node_modules/source-map-support/source-map-support.js:495:21)","
   at processPromiseRejections (internal/process/promises.js:245:33)","
   at processTicksAndRejections (internal/process/task_queues.js:96:32)"]}

Any thoughts on what is causing this, or how to resolve. Thanks. 


Discussion / hints:
Sometimes also see the following which could be related. 

Serverless SDK Warning: Following trace spans didn't end before end of lambda invocation: node.https.request, node.https.request, node.https.request, node.https.request, node.https.request, node.https.request, node.https.request, node.https.request, node.https.request

@simonphughes Great thanks for reporting that.

Can you share a bit more about a scenario in which you get this error? Is this possible for you to prepare a reproduction case we can test on our side?
I will have a think about it and see what I can do, although its very sporadic. Its only happening in 2 functions out of about 20. And in the last hour we have had 1500 invocations and its happened in 40.
@simonphughes additional questions:
- How do you close invocation in Lambda? Is this normal async handler that simply resolves? Or do you resove via `callback`?
- Are those functions running close to timeout (do you also observe occasional timeout errors?)

Generally, this error signals that the previous invocation ended in some not natural manner, yet the same ongoing instance was used to handle the following invocation.
We do have the occasional timeout on functions, but these erroring as per screenshot below are well within the time available.
![image](https://user-images.githubusercontent.com/19175683/206748184-67448100-44e8-4671-b8f4-dc2a6ae1951e.png)

Functions are all normal async handlers defined as below
export const handleupdatemessage: ValidatedEventAPIGatewayProxyEvent<typeof schema> = async (event): Promise<APIGatewayProxyResult> => {

which then end with a 
return OKReponse();

where OKResponse is defined thus. 
export const OKResponse = () => {
  return {
    statusCode: 200,
    body: null,
    headers: null
  }
}
@simonphughes thanks for more details.

I believe I know what’s going on. It’s a corner case, when invocation starts with some work (that was scheduled in previous invocation) before having handler run by the AWS. This signals likely processing flow error in lambda, still our extension should not break it. I'll work out a fix for it next week.
Great, thanks, please let me know when you have resolved. appreciate the quick replies on this thread.
Sometimes also see the following which could be related. 

Serverless SDK Warning: Following trace spans didn't end before end of lambda invocation: node.https.request, node.https.request, node.https.request, node.https.request, node.https.request, node.https.request, node.https.request, node.https.request, node.https.request

@simonphughes Great thanks for reporting that.

Can you share a bit more about a scenario in which you get this error? Is this possible for you to prepare a reproduction case we can test on our side?
I will have a think about it and see what I can do, although its very sporadic. Its only happening in 2 functions out of about 20. And in the last hour we have had 1500 invocations and its happened in 40.
@simonphughes additional questions:
- How do you close invocation in Lambda? Is this normal async handler that simply resolves? Or do you resove via `callback`?
- Are those functions running close to timeout (do you also observe occasional timeout errors?)

Generally, this error signals that the previous invocation ended in some not natural manner, yet the same ongoing instance was used to handle the following invocation.
We do have the occasional timeout on functions, but these erroring as per screenshot below are well within the time available.
![image](https://user-images.githubusercontent.com/19175683/206748184-67448100-44e8-4671-b8f4-dc2a6ae1951e.png)

Functions are all normal async handlers defined as below
export const handleupdatemessage: ValidatedEventAPIGatewayProxyEvent<typeof schema> = async (event): Promise<APIGatewayProxyResult> => {

which then end with a 
return OKReponse();

where OKResponse is defined thus. 
export const OKResponse = () => {
  return {
    statusCode: 200,
    body: null,
    headers: null
  }
}
@simonphughes thanks for more details.

I believe I know what’s going on. It’s a corner case, when invocation starts with some work (that was scheduled in previous invocation) before having handler run by the AWS. This signals likely processing flow error in lambda, still our extension should not break it. I'll work out a fix for it next week.
Great, thanks, please let me know when you have resolved. appreciate the quick replies on this thread.

Fix patch:
diff --git a/node/packages/aws-lambda-sdk/instrument/index.js b/node/packages/aws-lambda-sdk/instrument/index.js
index e677ada6b..510a9ebd0 100644
--- a/node/packages/aws-lambda-sdk/instrument/index.js
+++ b/node/packages/aws-lambda-sdk/instrument/index.js
@@ -127,15 +127,7 @@ module.exports = (originalHandler, options = {}) => {
       let isResolved = false;
       let responseStartTime;
       const invocationId = ++currentInvocationId;
-      if (invocationId > 1) {
-        // Reset root span ids and startTime with every next invocation
-        delete awsLambdaSpan.traceId;
-        delete awsLambdaSpan.id;
-        delete awsLambdaSpan.endTime;
-        awsLambdaSpan.startTime = requestStartTime;
-        awsLambdaSpan.tags.reset();
-        awsLambdaSpan.subSpans.clear();
-      }
+      if (invocationId > 1) awsLambdaSpan.startTime = requestStartTime;
       awsLambdaSpan.tags.set('aws.lambda.request_id', context.awsRequestId);
       const awsLambdaInvocationSpan = (traceSpans.awsLambdaInvocation =
         serverlessSdk.createTraceSpan('aws.lambda.invocation', { startTime: requestStartTime }));
@@ -184,6 +176,14 @@ module.exports = (originalHandler, options = {}) => {
           awsLambdaSpan.close({ endTime });
           reportTrace();
           flushSpans();
+
+          // Clear root span
+          delete awsLambdaSpan.traceId;
+          delete awsLambdaSpan.id;
+          delete awsLambdaSpan.endTime;
+          awsLambdaSpan.tags.reset();
+          awsLambdaSpan.subSpans.clear();
+
           await Promise.all(serverlessSdk._deferredTelemetryRequests);
           serverlessSdk._deferredTelemetryRequests.length = 0;
           serverlessSdk._debugLog(
diff --git a/node/packages/aws-lambda-sdk/lib/trace-span/index.js b/node/packages/aws-lambda-sdk/lib/trace-span/index.js
index 683de66d1..d4bb33623 100644
--- a/node/packages/aws-lambda-sdk/lib/trace-span/index.js
+++ b/node/packages/aws-lambda-sdk/lib/trace-span/index.js
@@ -214,14 +214,6 @@ class TraceSpan {
           { code: 'FUTURE_SPAN_START_TIME' }
         );
       }
-      if (this.parentSpan && startTime < this.parentSpan.startTime) {
-        throw Object.assign(
-          new Error(
-            'Cannot intialize span: Start time cannot be older than start time of parent span'
-          ),
-          { code: 'PAST_PARENT_SPAN_START_TIME' }
-        );
-      }
     }
     this.startTime = startTime || defaultStartTime;
     this.name = ensureSpanName(name);


Test patch:
diff --git a/node/packages/aws-lambda-sdk/test/fixtures/lambdas/delayed-http-request.js b/node/packages/aws-lambda-sdk/test/fixtures/lambdas/delayed-http-request.js
new file mode 100644
index 000000000..23270a209
--- /dev/null
+++ b/node/packages/aws-lambda-sdk/test/fixtures/lambdas/delayed-http-request.js
@@ -0,0 +1,34 @@
+'use strict';
+
+const http = require('http');
+
+const TEST_SERVER_PORT = 3177;
+
+http
+  .createServer((request, response) => {
+    request.on('data', () => {});
+    request.on('end', () => {
+      response.writeHead(200, {});
+      response.end('"ok"');
+    });
+  })
+  .listen(TEST_SERVER_PORT);
+
+const url = `http://localhost:${TEST_SERVER_PORT}/?foo=bar`;
+
+module.exports.handler = async () => {
+  setTimeout(() => {
+    http
+      .request(url, { headers: { someHeader: 'bar' } }, (response) => {
+        let body = '';
+        response.on('data', (data) => {
+          body += data;
+        });
+        response.on('end', () => {
+          console.log('Body', body);
+        });
+      })
+      .end();
+  }, 50).unref();
+  return 'ok';
+};
diff --git a/node/packages/aws-lambda-sdk/test/integration/index.test.js b/node/packages/aws-lambda-sdk/test/integration/index.test.js
index a6a6ac54f..2ca6af21b 100644
--- a/node/packages/aws-lambda-sdk/test/integration/index.test.js
+++ b/node/packages/aws-lambda-sdk/test/integration/index.test.js
@@ -1261,6 +1261,27 @@ describe('integration', function () {
         }),
       },
     ],
+    [
+      'delayed-http-request',
+      {
+        variants: new Map([
+          ['v12', { config: { configuration: { Runtime: 'nodejs12.x' } } }],
+          ['v14', { config: { configuration: { Runtime: 'nodejs14.x' } } }],
+          ['v16', { config: { configuration: { Runtime: 'nodejs16.x' } } }],
+          ['v18', { config: { configuration: { Runtime: 'nodejs18.x' } } }],
+        ]),
+        config: {
+          test: ({ invocationsData }) => {
+            expect(invocationsData[1].trace.spans.map(({ name }) => name)).to.deep.equal([
+              'aws.lambda',
+              'node.http.request',
+              'aws.lambda.invocation',
+            ]);
+          },
+          hasOrphanedSpans: true,
+        },
+      },
+    ],
   ]);
 
   const testVariantsConfig = resolveTestVariantsConfig(useCasesConfig);
@@ -1313,10 +1334,12 @@ describe('integration', function () {
             expect(String(initializationSpan.parentSpanId)).to.equal(String(lambdaSpan.id));
             expect(String(invocationSpan.parentSpanId)).to.equal(String(lambdaSpan.id));
           } else {
-            expect(spans.map(({ name }) => name).slice(0, 2)).to.deep.equal([
-              'aws.lambda',
-              'aws.lambda.invocation',
-            ]);
+            if (!testConfig.hasOrphanedSpans) {
+              expect(spans.map(({ name }) => name).slice(0, 2)).to.deep.equal([
+                'aws.lambda',
+                'aws.lambda.invocation',
+              ]);
+            }
             expect(lambdaSpan.tags.aws.lambda.isColdstart).to.be.false;
             const [, invocationSpan] = spans;
             expect(String(invocationSpan.parentSpanId)).to.equal(String(lambdaSpan.id));