Knex database spans not recorded when using async/await

[thrcorrea]

Describe the bug
When a define a route wich uses knex to connect do the database, and use async await at the function definition, the apm agent does not send the sql span, not showing the sql info at the request timeline at kibana. The apm agent does not support async/await

To Reproduce
Steps to reproduce the behavior:

1. Use this config '...'
2. Then call '....'
3. Then do '....'
4. See error

Expected behavior
To show the sql span at the request timeline.

Environment (please complete the following information)

• OS: Linux
• Node.js version: v11.10.0
• APM Server version: 6.6.1
• Agent version: 2.5.1

How are you starting the agent? (please tick one of the boxes)

• Calling agent.start() directly (e.g. require('elastic-apm-node').start(...))
• Requiring elastic-apm-node/start from within the source code
• Starting node with -r elastic-apm-node/start

Additional context
Add any other context about the problem here.

• Agent config options

  Click to expand

  serviceName: 'service',
  

• package.json dependencies:

  Click to expand

  "elastic-apm-node": "^2.5.1",
  "express": "^4.16.4",
  "knex": "^0.16.3",
  "mysql2": "^1.6.5"
  

[watson]

Does the database span it self show up - just without the SQL query - or is the entire database span missing from the transaction?

Would you mind sharing a code snippet of how you're making the query?

[thrcorrea]

The entire database span is missing. I created a project with an example:

https://github.com/thrcorrea/apm-test

[watson]

Thanks for sharing the test app. I've been able to reproduce the problem now. I don't think it's directly async/await related, but you're right that this is what triggers it in this case. Other apps with async/await do work though. So I guess it's something with the combination of how knex operates. I'll investigate further...

[watson]

Update: It's somehow related to a combination of async/await and async hooks. A temporary workaround is to set asyncHooks: false in the agent config.

I'll continue to investigate to find a more permanent solution...

[watson]

This issue might be the same as discussed in #897

[MartinKolarik]

Same problem here, knex + async/await + asyncHooks (+ something else? not sure) = no active transaction for mysql spans. I'm on node 12. Turning off asyncHooks solves this issue but as I understand, it might break context propagation for some other cases?

[jsumners]

We are seeing this problem. Screenshot 1 here is with ELASTIC_APM_ASYNC_HOOKS=true:

Screenshot 2 is the same transaction path with ELASTIC_APM_ASYNC_HOOKS=false:

This is just a series of SQL statements being executed in order via await db.query. They are not executed within a database transaction.

Note: in the first screenshot there is a SET statement happening from the mysql2 module's onConnect hook to set the timezone for the session.

ping: @Qard

[PaulMougel]

FWI, we have the same issue when we use Objection.js (an SQL ORM): queries are not properly associated with the current transaction.

The trace logs show that no transaction is found, even though in our case we are processing a route response from hapi. If we manually create a span it is attached to the correct transaction, and knex requests are properly instrumented and associated with the transaction.

What is the recommended course of action?

[tgriesser]

I've been subscribed to this issue because I was curious if there was a solution (proper tracing in node is a difficult thing to do). So this is mostly just a complete guess here, but I wonder if this is because knex now uses a module called "tarn" as its pooling library:

https://github.com/vincit/tarn.js/

It looks like there's a instrumentation for generic-pool, which knex previously used:

https://github.com/elastic/apm-agent-nodejs/blob/master/lib/instrumentation/modules/generic-pool.js

Perhaps adding a similar shim for tarn would help associate the trace?

[Qard]

It's because the promise hooks feature in V8, which Node.js relies on for async_hooks, does not work with Thenables, which both Knex and Objection.js are using. This is unfixable without investing some time in fixing the issue in V8. See: nodejs/node#22360

[brandoncollins7]

Having this issue as well now, which led me to this thread. Are there any workarounds?

[JCMais]

The issue mentioned above by @Qard seems to be fixed on this PR nodejs/node#33778 (by @Qard). Looks like the fix will be released with Node.js v14.6.0 nodejs/node#34371

[Qard]

Yep, it's fixed in 14.6.x+. It hasn't been backported to 12.x yet, but shouldn't be too hard to backport.

[JCMais]

Can confirm that this issue is fixed when running the apm agent on Node.js >= 14.6