Lambda instrumentation interferes with return value for first invocation after a deploy

[astorm]

We're seeing behavior where our instrumentation interferes with the usual return value after a function's initial deployment.

1. Create a Lambda Function hooked up to API Gateway
2. Configure the env variables ELASTIC_APM_SECRET_TOKEN, ELASTIC_APM_SERVER_URL, and ELASTIC_APM_SERVICE_NAME with legitimate values
3. Ensures the Lambda's node_modules folder contains the elastic-apm-node source and its dependencies
4. Change your lambda source so it looks like the following

    const apm = require('elastic-apm-node').start()
    exports.handler = apm.lambda(function handler (event, context, callback) {
      callback(null, `Hello World`)
    })
   
   

5. Click the Deploy Button
6. Invoke your function via its API gateway URL or the aws cli invoke command two times

Expected Behavior: Function returns value Hello World

Actual Behavior: The first invocation after a deploy returns null -- subsequent invocations return the expected Hello World value

[astorm]

Interesting -- for reasons that aren't 100% clear to me, this seems to be a problem of the Lambda Freezing and "returning" a result before the agent can flush

Using some high tech console.log debugging here

  function captureAndMakeCompleter (trans, payload, context, result, callback) {
    captureContext(trans, payload, context, result)
    console.log('ABOUT TO END TRANSACTION')
    trans.end()
    console.log('ENDING TRANSACTION')
    return () => {
      console.log("CALLING done() in captureAndMakeCompleter")
      console.log("about to flush")
      agent.flush((err) => {
        if (err) agent.logger.error('Flush error: %s', err.message)
        console.log("ABOUT TO CALL bound callback in flush callback")
        callback()
      })
    }
  }

In the first invocation, we reach the "about to flush" message. However, the

console.log("ABOUT TO CALL bound callback in flush callback")

line is not logged, indicating that the flush callback is never invoked.

However -- when the function in invoked for the second time, we end up with two ABOUT TO CALL bound callback in flush callback logs, and the first is followed by a Lambda error message

2021-07-21T22:47:01.348Z	11358a5a-fedb-4d84-964d-c204d9c87e02	INFO	ABOUT TO CALL bound callback in flush callback
[ERROR] [1626907621359] LAMBDA_RUNTIME Failed to post handler success response. Http response code: 400.
//...
2021-07-21T22:47:01.541Z	8f6bba67-a298-4519-bb7e-bb8abdb04759	INFO	ABOUT TO CALL bound callback in flush callback

My best guess as to what's going on is

1. The lambda function invokes its callback
2. The agent intercepts this call
3. The agent attempts to flush
4. The lambda runtime hits some timeout and returns a null response and freezes
5. When the lambda unfreezes the agent finishes whatever it was doing and finally invokes the flush callback from the original invocation
6. The second invocation complets without issue

[astorm]

OK -- this isn't a timeout -- here's my reasoning. I've bumped the Lambda's timeout to 15 seconds and

1. The problem still occurs
2. The API Gateway URL returns a null response on a cold start much faster than 15 seconds

Doing some further experimentation it seems like there's something in the HTTP client that's triggering an early freeze. That is -- if we use the no op transport in the Lambda function

const apm = require('elastic-apm-node').start({
  transport: function() {
    const {NoopTransport} = require('./node_modules/elastic-apm-node/lib/noop-transport')
    return new NoopTransport()
  }  
})
exports.handler = apm.lambda(function handler (event, context, callback) {
  console.log("asbefore")
  callback(null, `Hello Science!`)
  console.log("asafter")
})

Then the Lambda behaves normally -- there's no null response for a cold start.

[astorm]

Tracked down a way to prevent the "cold start returns null" behavior -- in the HTTP Client if we comment the following socket.unref() line

intakeReq.on('socket', function (socket) {
  // Unref the socket for this request so that the Client does not keep
  // the node process running if it otherwise would be done. (This is
  // tested by the "unref-client" test in test/side-effects.js.)
  //
  // The HTTP keep-alive agent will unref sockets when unused, and ref them
  // during a request. Given that the normal makeIntakeRequest behaviour
  // is to keep a request open for up to 10s (`apiRequestTimeout`), we must
  // manually unref the socket.
  log.trace('intakeReq "socket": unref it')
  // socket.unref()
})

the "first request after a cold start" will return normally. It seems that unrefing the socket in this way causes the AWS Lambda to stop everything it's doing and freeze before the handler's callback can be invoked. This freeze doesn't happen immediately though.

It's unclear how unrefing the HTTP Client request could impact the overall behavior of the Lambda function itself. My first naive take is this socket is a shared instance and there's some nuance of the AWS Node.js Runtime that expects this socket to remain ref'd

[trentm]

I was hitting this as well when working on #2485

What was happening:

• When the intakeReq socket was unref'd during the agent's intake request, it puts the agent into a state where there are no Node.js active handles.
• Node then sends the process "beforeExit" event.
• For non-async handlers (https://docs.aws.amazon.com/lambda/latest/dg/nodejs-handler.html#nodejs-handler-sync) the Lambda Node.js Runtime normally starts watching for "beforeExit" after the handler callback() has been called, to know when to freeze (except when context.callbackWaitsForEmptyEventLoop = false). However, at the point when we socket.unref() we haven't yet called that callback.
• Before that callback is called, the Lambda Node.js Runtime has a fallback "beforeExit" handler (in Runtime.js):

  /**
   * Setup the 'beforeExit' listener that is used if the callback is never
   * called and the handler is not async.
   * CallbackContext replaces the listener if a callback is invoked.
   */
  _setDefaultExitListener(invokeId) {
    BeforeExitListener.set(() => {
      this.client.postInvocationResponse(null, invokeId, () =>
        this.scheduleIteration()
      );
    });
  }

• That handler was being called, which sends a null response. (The Runtime interprets this situation as the callback() never having been called.)
• The Runtime has a guard so that the handler response can only be called once, so our callback(...) called with the actual result soon after is a no-op.

The fix is to not socket.unref() in a Lambda environment. This is fixed in elastic/apm-nodejs-http-client#178 here: https://github.com/elastic/apm-nodejs-http-client/pull/178/files#diff-e727e4bdf3657fd1d798edcd6b099d6e092f8573cba266154583a746bba0f346R974-R978