`client.flush(cb)` callback may not be called in v9.7.0

[trentm]

`client.flush(cb)` callback may not be called in v9.7.0

[trentm]

Here is a repro script just using the client (instead of via the apm-agent-nodejs). "call-me-back-maybe.js"

// A script, used by test/side-effects.js, to test that the client.flush
// callback is called.
//
// We expect both `console.log`s to write their output.
//
// Two important things are required to reproduce the issue:
// 1. There cannot be other activities going on that involve active libuv
//    handles. For this Client that means:
//    - ensure no `_pollConfig` requests via `centralConfig: false`
//    - do not provide a `cloudMetadataFetcher`
// 2. There must be a listening APM server to which to send data.

const Client = require('../../') // elastic-apm-http-client

const serverUrl = process.argv[2]

const client = new Client({
  logger: require('pino')({ level: 'trace', ...require('@elastic/ecs-pino-format')() }, process.stderr), // uncomment for debugging
  serverUrl: serverUrl,
  serviceName: 'call-me-back-maybe',
  agentName: 'my-nodejs-agent',
  agentVersion: '1.2.3',
  userAgent: 'my-nodejs-agent/1.2.3',
  centralConfig: false // important for repro, see above
})

const e = { exception: { message: 'boom', type: 'Error' } }

client.sendError(e, function sendCb () {
  console.log('sendCb called')
  client.flush(function flushCb () {
    console.log('flushCb called')
  })
})

With that logger enabled for debugging, here is a run without a fix:

% node test/lib/call-me-back-maybe.js 2> >(ecslog -x process.pid,reqId)
[2021-04-06T21:21:10.655Z] TRACE (on pink.local): intake request start
[2021-04-06T21:21:10.658Z] TRACE (on pink.local): _write: encode object
    fullTimeMs: 8.877795
    numEvents: 1
    numBytes: 58
[2021-04-06T21:21:10.658Z] TRACE (on pink.local): intakeReq "socket": unref it
sendCb called
[2021-04-06T21:21:10.660Z] TRACE (on pink.local): _writeFlush
    active: true
[2021-04-06T21:21:10.662Z] TRACE (on pink.local): gzipStream "finish"
[2021-04-06T21:21:10.662Z] TRACE (on pink.local): start intakeResTimer
    timeout: 10000
[2021-04-06T21:21:10.665Z] TRACE (on pink.local): gzipStream "end"
[2021-04-06T21:21:10.665Z] TRACE (on pink.local): completePart gzipStream
    concluded: false
[2021-04-06T21:21:10.666Z] TRACE (on pink.local): intakeReq "finish"
[2021-04-06T21:21:10.666Z] TRACE (on pink.local): completePart intakeReq
    concluded: false
[2021-04-06T21:21:10.666Z] TRACE (on pink.local): auto-end client beforeExit

and with the fix:

% node test/lib/call-me-back-maybe.js 2> >(ecslog -x process.pid,reqId)
[2021-04-06T21:22:40.147Z] TRACE (on pink.local): intake request start
[2021-04-06T21:22:40.149Z] TRACE (on pink.local): _write: encode object
    fullTimeMs: 9.602986
    numEvents: 1
    numBytes: 58
[2021-04-06T21:22:40.150Z] TRACE (on pink.local): intakeReq "socket": unref it
sendCb called
[2021-04-06T21:22:40.151Z] TRACE (on pink.local): _writeFlush
    active: true
[2021-04-06T21:22:40.154Z] TRACE (on pink.local): gzipStream "finish"
[2021-04-06T21:22:40.154Z] TRACE (on pink.local): start intakeResTimer
    timeout: 10000
[2021-04-06T21:22:40.155Z] TRACE (on pink.local): gzipStream "end"
[2021-04-06T21:22:40.155Z] TRACE (on pink.local): completePart gzipStream
    concluded: false
[2021-04-06T21:22:40.156Z] TRACE (on pink.local): intakeReq "finish"
[2021-04-06T21:22:40.156Z] TRACE (on pink.local): completePart intakeReq
    concluded: false
[2021-04-06T21:22:40.157Z] TRACE (on pink.local): _gracefulExit
[2021-04-06T21:22:40.158Z] TRACE (on pink.local): intakeReq "response"
    statusCode: 202
    reqFinished: true
[2021-04-06T21:22:40.159Z] TRACE (on pink.local): intakeRes "end"
[2021-04-06T21:22:40.159Z] TRACE (on pink.local): completePart intakeRes
    concluded: false
flushCb called
[2021-04-06T21:22:40.159Z] TRACE (on pink.local): conclude intake request: success
    timeline: [
        [
            13.591589,
            "completePart gzipStream",
            null
        ],
        [
            14.249018,
            "completePart intakeReq",
            null
        ],
        [
            17.151894,
            "completePart intakeRes",
            null
        ]
    ]
    bytesWritten: 326
    backoffDelayMs: 0
[2021-04-06T21:22:40.160Z] TRACE (on pink.local): _final

The difference is what happens when the "beforeExit" event is sent when node is about to terminate. Before the fix, the expectation was that the "beforeExit" handler would call client.end(), which would call client._ref() (via Client._final) to add a libuv reference to the socket being used to flush data to APM server. However, the bug was the expectation that client.end() would call Client.prototype._final. That is async and doesn't happen when node is exiting. The solution is to ensure client._ref() gets called synchronously.