Not all transactions/spans are sent from agent / stored in elastic and worse when using addLabels

[sammaxwell]

Kibana version: 6.7.1

Elasticsearch version: 6.7.1

APM Server version: 6.6.1

APM Agent language and version: nodejs 2.11.0

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant): not all transactions/spans are being sent from agent and/or stored in elastic apm server

**Steps to reproduce (not all TRANSACTIONS sent/stored) **:

1. git clone https://github.com/SamMaxwell/elastic-apm-test.git
2. run it for 1000 iterations
3. open kibana Discover, filter to context.server.name is elastic-apm-test
4. notice how the number of document hits is less than 1000

**Steps to reproduce (even fewer TRANSACTIONS sent/stored when addLabels called) **:

1. un-comment line index.js line 8
2. run it for 1000 iterations
3. open kibana Discover, filter to context.server.name is elastic-apm-test and relative time (to be short enough to not include hits from previous run)
4. notice how the number of document hits is even less than previous run

**Steps to reproduce (not all SPANS sent/stored) **:

1. set ELASTIC_APM_LOG_LEVEL to "Trace"
2. run it for 10 iterations
3. inspect the trace output in the console
4. notice how the the span is not sent for each transaction. many times, if not every time, it only sends a span for the first iteration. (I included the trace output below)

Provide logs and/or server output (if relevant):
example of how SPAN is only sent on 1st iteration (out of 10)

adding hook to Node.js module loader
shimming bluebird@3.5.4 module
shimming bluebird.prototype functions: [ '_then', '_addCallbacks' ]
shimming bluebird.config
shimming knex@0.16.5 module
shimming Knex.Client.prototype.runner
shimming Knex.Client.prototype functions: [ 'queryBuilder', 'raw' ]
shimming http@10.15.3 module
shimming http.Server.prototype.emit function
shimming http.request function
shimming http.get function
shimming http.ServerResponse.prototype.writeHead function
shimming https@10.15.3 module
shimming https.Server.prototype.emit function
shimming https.request function
shimming https.get function
shimming tedious@4.2.0 module
shimming tedious.Connection
shimming generic-pool@3.7.1 module
shimming generic-pool.PriorityQueue.prototype.enqueue
capturing custom stack trace for knex
start trace { trans: '6be1c2fc5614412f',
  parent: undefined,
  trace: '1bfd9a97cd55574d0a9ba37a1d159d9a',
  name: 'test',
  type: undefined }
capturing custom stack trace for knex
shimming knex runner.query
no active transaction found - cannot build new span
intercepted call to https.request { id: null }
intercepted call to knex runner.query
intercepted call to generic-pool.PriorityQueue.prototype.enqueue { id: '6be1c2fc5614412f' }
start span { span: '96262fc66173c3b6',
  parent: '6be1c2fc5614412f',
  trace: '1bfd9a97cd55574d0a9ba37a1d159d9a',
  name: null,
  type: 'db.mssql.query' }
ended span { span: '96262fc66173c3b6',
  parent: '6be1c2fc5614412f',
  trace: '1bfd9a97cd55574d0a9ba37a1d159d9a',
  name: 'SELECT FROM Tickets',
  type: 'db.mssql.query' }
encoding span { span: '96262fc66173c3b6',
  parent: '6be1c2fc5614412f',
  trace: '1bfd9a97cd55574d0a9ba37a1d159d9a',
  name: 'SELECT FROM Tickets',
  type: 'db.mssql.query' }
sending transaction { trans: '6be1c2fc5614412f',
  trace: '1bfd9a97cd55574d0a9ba37a1d159d9a' }
ended transaction { trans: '6be1c2fc5614412f',
  parent: undefined,
  trace: '1bfd9a97cd55574d0a9ba37a1d159d9a',
  type: 'custom',
  result: 'success',
  name: 'test' }
start trace { trans: 'a0c3b9175e0aa467',
  parent: undefined,
  trace: 'e305bec16641b5145a947a995bf94f9e',
  name: 'test',
  type: undefined }
capturing custom stack trace for knex
shimming knex runner.query
intercepted call to knex runner.query
intercepted call to generic-pool.PriorityQueue.prototype.enqueue { id: null }
no active transaction found - cannot build new span
sending transaction { trans: 'a0c3b9175e0aa467',
  trace: 'e305bec16641b5145a947a995bf94f9e' }
ended transaction { trans: 'a0c3b9175e0aa467',
  parent: undefined,
  trace: 'e305bec16641b5145a947a995bf94f9e',
  type: 'custom',
  result: 'success',
  name: 'test' }
start trace { trans: 'c3ecb04f02b456a1',
  parent: undefined,
  trace: 'fcba443d63442a5d949c59027033b5dc',
  name: 'test',
  type: undefined }
capturing custom stack trace for knex
shimming knex runner.query
intercepted call to knex runner.query
intercepted call to generic-pool.PriorityQueue.prototype.enqueue { id: null }
sending span { span: '96262fc66173c3b6',
  parent: '6be1c2fc5614412f',
  trace: '1bfd9a97cd55574d0a9ba37a1d159d9a',
  name: 'SELECT FROM Tickets',
  type: 'db.mssql.query' }
no active transaction found - cannot build new span
sending transaction { trans: 'c3ecb04f02b456a1',
  trace: 'fcba443d63442a5d949c59027033b5dc' }
ended transaction { trans: 'c3ecb04f02b456a1',
  parent: undefined,
  trace: 'fcba443d63442a5d949c59027033b5dc',
  type: 'custom',
  result: 'success',
  name: 'test' }
start trace { trans: 'c817047a49262ed1',
  parent: undefined,
  trace: '4b6af26dde9a62c6b26a47de59087dc2',
  name: 'test',
  type: undefined }
capturing custom stack trace for knex
shimming knex runner.query
intercepted call to knex runner.query
intercepted call to generic-pool.PriorityQueue.prototype.enqueue { id: null }
no active transaction found - cannot build new span
sending transaction { trans: 'c817047a49262ed1',
  trace: '4b6af26dde9a62c6b26a47de59087dc2' }
ended transaction { trans: 'c817047a49262ed1',
  parent: undefined,
  trace: '4b6af26dde9a62c6b26a47de59087dc2',
  type: 'custom',
  result: 'success',
  name: 'test' }
start trace { trans: '606e207254f8794f',
  parent: undefined,
  trace: '3f9423454a8cd4de0a17005d4aab83a4',
  name: 'test',
  type: undefined }
capturing custom stack trace for knex
shimming knex runner.query
intercepted call to knex runner.query
intercepted call to generic-pool.PriorityQueue.prototype.enqueue { id: null }
no active transaction found - cannot build new span
sending transaction { trans: '606e207254f8794f',
  trace: '3f9423454a8cd4de0a17005d4aab83a4' }
ended transaction { trans: '606e207254f8794f',
  parent: undefined,
  trace: '3f9423454a8cd4de0a17005d4aab83a4',
  type: 'custom',
  result: 'success',
  name: 'test' }
start trace { trans: '957a1e89225b7990',
  parent: undefined,
  trace: '46b73177c0437aca163a00a7e3e5f41e',
  name: 'test',
  type: undefined }
...

[wa7son (Thomas Watson)]

While you might lose a spans/transaction if you exit the process right after the transaction or span ends (as it will not have enough time to send it up to the APM Server), you have also encountered what we call a "context propagation bug". Here the agent loses track of which transaction is the active transaction due to the async nature of Node.js.

My guess is that it's something related to knex or tedious. We should support the versions you're using, so I'm not sure why it doesn't work. I'll have to investigate a little deeper to figure out what happens in your case. Thanks for providing an example app. This will make the process a lot easier

Btw, I couldn't get your 2nd example to work:

1. un-comment line index.js line 8

I'm not seeing the addLabels call in the index.js file.

[sammaxwell]

Sorry, I forgot to push my change into GitHub. Now line 8 is there.

[sammaxwell]

Should I perform a flush before exiting? Is flush awaitable?

[wa7son (Thomas Watson)]

Yes, you can use agent.flush([callback])

[sammaxwell]

Adding flush doesn't seem to help much, if at all. New version of repo commited/pushed to GitHub

[wa7son (Thomas Watson)]

Yes, I still suspect that that is a context propagation bug that we need to look into. I'll update this topic as I know more

[sammaxwell]

Stephen Belanger thinks it might be that tedious is using a non-promise-like then-able Elastic-apm-node memory leak . After he fixed the memory leak I thought he had moved on from the topic since it was really more than one issue. I don't intend for more than one person to be chasing the same thing.

[stephenbelanger]

No worries. I'm working on figuring out what we can do about it. For now, the wrapper promise I suggested in the other issue should fix things for you. I'll see about making a pull request to Knex to wrap its thenables in AsyncResource so it works properly without the manual wrap. It would be good if we could get it supported properly at the V8 level in PromiseHook though. I've added a note to the agenda for the next Node.js diagnostics working group meeting to discuss it.