fix(lambda): fixed heartbeat error (#1351)

- The heartbeat error was thrown although the request succeeded.
instana · Oct 1, 2024 · 0c001c8 · 0c001c8
1 parent cd4bb25
commit 0c001c8
Show file tree

Hide file tree

Showing 2 changed files with 42 additions and 14 deletions.
diff --git a/packages/serverless/src/backend_connector.js b/packages/serverless/src/backend_connector.js
@@ -135,13 +135,15 @@ let heartbeatInterval;
 function scheduleLambdaExtensionHeartbeatRequest() {
   const executeHeartbeat = () => {
     logger.debug('Executing Heartbeat request to Lambda extension.');
+    const startTime = Date.now();
 
     const req = uninstrumented.http.request(
       {
         hostname: layerExtensionHostname,
         port: layerExtensionPort,
         path: '/heartbeat',
         method: 'POST',
+        Connection: 'close',
         // This sets a timeout for establishing the socket connection, see setTimeout below for a timeout for an
         // idle connection after the socket has been opened.
         timeout: layerExtensionTimeout
@@ -156,9 +158,25 @@ function scheduleLambdaExtensionHeartbeatRequest() {
             )
           );
         }
+
+        res.once('data', () => {
+          // we need to register the handlers to avoid running into a timeout
+        });
+
+        res.once('end', () => {
+          const endTime = Date.now();
+          const duration = endTime - startTime;
+          logger.debug(`Took ${duration}ms to receive response from extension`);
+        });
       }
     );
 
+    req.once('finish', () => {
+      const endTime = Date.now();
+      const duration = endTime - startTime;
+      logger.debug(`Took ${duration}ms to send data to extension`);
+    });
+
     function handleHeartbeatError(e) {
       // Make sure we do not try to talk to the Lambda extension again.
       useLambdaExtension = false;
@@ -171,7 +189,7 @@ function scheduleLambdaExtensionHeartbeatRequest() {
       );
     }
 
-    req.on('error', e => {
+    req.once('error', e => {
       // req.destroyed indicates that we have run into a timeout and have already handled the timeout error.
       if (req.destroyed) {
         return;

diff --git a/packages/serverless/test/backend_connector_test.js b/packages/serverless/test/backend_connector_test.js
@@ -32,18 +32,23 @@ describe('[UNIT] backend connector', () => {
     this.timeout(config.getTestTimeout());
 
     let onStub;
+    let onceStub;
     let destroyStub;
+    let setTimeoutStub;
 
     beforeEach(() => {
       sinon.spy(global, 'setInterval');
       sinon.spy(global, 'clearInterval');
 
       onStub = sinon.stub();
+      onceStub = sinon.stub();
       destroyStub = sinon.stub();
+      setTimeoutStub = sinon.stub();
 
       sinon.stub(uninstrumentedHttp.http, 'request').returns({
         on: onStub,
-        setTimeout: sinon.stub(),
+        once: onceStub,
+        setTimeout: setTimeoutStub,
         end: sinon.stub(),
         removeAllListeners: sinon.stub(),
         destroy: destroyStub
@@ -72,7 +77,7 @@ describe('[UNIT] backend connector', () => {
       expect(uninstrumentedHttp.http.request.called).to.be.true;
       expect(uninstrumentedHttp.http.request.callCount).to.eql(1);
 
-      const onError = onStub.getCalls().find(call => call.firstArg === 'error').callback;
+      const onError = onceStub.getCalls().find(call => call.firstArg === 'error').callback;
       onError();
 
       expect(global.clearInterval.called).to.be.true;
@@ -86,19 +91,21 @@ describe('[UNIT] backend connector', () => {
       expect(uninstrumentedHttp.http.request.called).to.be.true;
       expect(uninstrumentedHttp.http.request.callCount).to.eql(1);
 
-      return retry(async () => {
-        const prom = sendBundle();
-        await delay(200);
+      expect(setTimeoutStub.called).to.be.true;
+      expect(destroyStub.called).to.be.false;
 
-        const onTimeout = onStub.getCalls().find(call => call.firstArg === 'timeout').callback;
-        const onEnd = uninstrumentedHttp.http.request
-          .getCalls()
-          .find(call => call.firstArg.path === '/bundle').callback;
+      const firstCallArgs = setTimeoutStub.getCall(0).args;
 
-        onTimeout();
-        expect(global.clearInterval.called).to.be.true;
+      await delay(200);
 
-        setTimeout(onEnd, 200);
+      // simulate timeout of extension
+      firstCallArgs[1]();
+
+      return retry(async () => {
+        expect(destroyStub.called).to.be.true;
+
+        const prom = sendBundle();
+        await delay(200);
         await prom;
 
         expect(destroyStub.called).to.be.true;
@@ -117,7 +124,7 @@ describe('[UNIT] backend connector', () => {
         const prom = sendBundle();
         await delay(200);
 
-        const onError = onStub.getCalls().find(call => call.firstArg === 'error').callback;
+        const onError = onceStub.getCalls().find(call => call.firstArg === 'error').callback;
         const onEnd = uninstrumentedHttp.http.request
           .getCalls()
           .find(call => call.firstArg.path === '/bundle').callback;
@@ -150,11 +157,14 @@ describe('[UNIT] backend connector', () => {
         const prom = sendBundle();
         await delay(200);
 
+        const onceFinish = onceStub.getCalls().find(call => call.firstArg === 'finish').callback;
         const onFinish = onStub.getCalls().find(call => call.firstArg === 'finish').callback;
         const onEnd = uninstrumentedHttp.http.request
           .getCalls()
           .find(call => call.firstArg.path === '/bundle').callback;
 
+        onceFinish();
+
         setTimeout(onEnd, 250);
         setTimeout(onFinish, 200);