Flush seems to complete before request is sent

[elastic]

Flush seems to complete before request is sent

[astorm]

Thanks for reporting @tylersmalley and for the program reproducing the problem. Debugging and talking about async programming is always tricky, but my first though it you may be running into the same bit of async/await behavior that's described in this issue in the main Node.js repository. When you await in your main function, the execution of your program continues outside of main. Then, node reaches the end of your program and it will exit before the work inside one of the promises promise can complete.

Here's a few questions/comments that will help us debug this further

1. What version of Node.js are you using?
2. When you said "fails to persist the transaction", do you mean the transaction isn't logged to repro-apm-nodejs-http-client.log, or the transaction is logged, but doesn't make it up to your elastic instance?
3. What version of the elastic-apm-http-client are you using?
4. How short can the timeout be and have this still work? Does it need to be 2000ms, or does the transaction still make it through with a short 10ms or even 0ms timeout value?
5. Is this timeout a workable solution for your program, or does it create an additional problem we're not seeing here?

[tylersmalley]

Thanks for reporting @tylersmalley and for the program reproducing the problem. Debugging and talking about async programming is always tricky, but my first though it you may be running into the same bit of async/await behavior that's described in this issue in the main Node.js repository. When you await in your main function, the execution of your program continues outside of main. Then, node reaches the end of your program and it will exit before the work inside one of the promises promise can complete.

It does look like that might be why the example is failing, but I don't believe that would explain why I am seeing this in my actual implementation. For context on what we are wanting to achieve; we are instrumenting the Kibana CLI with APM to log development metrics. A draft PR is available here. In here, I am awaiting the flush, which is completing but the request doesn't make it to the APM server.

What version of Node.js are you using?

v14.15.4

When you said "fails to persist the transaction", do you mean the transaction isn't logged to repro-apm-nodejs-http-client.log, or the transaction is logged, but doesn't make it up to your elastic instance?

I am seeing it in the payload log file, but it's not in the ES instance.

What version of the elastic-apm-http-client are you using?

v9.4.2

How short can the timeout be and have this still work? Does it need to be 2000ms, or does the transaction still make it through with a short 10ms or even 0ms timeout value?

I haven't tested to see how low it could be, as I assume that's based on one's internet speeds.

Is this timeout a workable solution for your program, or does it create an additional problem we're not seeing here?

It is not, I want to await the flush and knew that the data has been persisted.

[tylersmalley]

Thanks so much for your time and response.

Actually, the more I dig into this I think you're correct in your assessment. :shakes fist at v8:

For some reason, during flush, there doesn't seem to be anything on the event loop that would cause the script to prevent from returning. I am going to setTimeout and clear it once the flush returns.

[tylersmalley]

I was able to await the completion of the flush, however, that doesn't appear to have been enough.

  let timeoutInterval;
  const flush = () => new Promise((resolve) => client.flush(resolve))
  const wait = () => new Promise((resolve) => { timeoutInterval = setTimeout(resolve, 5000); })

  const results = await Promise.race([
    flush().then(() => 'completed flush'),
    wait().then(() => 'hit timeout'),
  ])
  clearTimeout(timeoutInterval)
  console.log(results)

  await flush();

With this, I am now seeing a 499 response code in the Cloud proxy logs - indicating the client prematurely closed the connection.

[tylersmalley]

I am going to reopen this as the workaround I tried didn't end up working. Ideally, we would like to find a workaround that would work in the reproduction example.