pg instrumentation doesn't send spans when used with knex and asnyc/await

[pvatterott]

Summary

When using the Knex query builder and await, no span is created for Postgres queries which means we don't get useful traces

I've reproduced this issue in https://github.com/pvatterott/pg-trace-example/tree/knex-await-repro

There are four endpoints in that repo:

• /callback/text-only-knex-await demonstrates the issue - when using the knex query builder with an async request handler, no span is created for the postgresql query
• /callback/text-only-knex-promise correctly creates the span when using knex but with promise chaining
• /callback/text-only-pg-await shows that using an async request handler with just pg correctly creates a span
• /callback/text-only-pg-promise is the original text-only API which correctly creates a span when using pg + promise chaining

Possible Related Issues

#127 #164 #89

Environment

• node 10.17.0
• express 4.17.1
• honeycomb-beeline 1.8.2
• pg 7.11.0
• knex 0.20.0

[allyjweir]

Got time on Saturday so 🤞 will be able to look then.

[allyjweir]

Spent a couple hours on this today. Really weird that it sends when used as a promise but not in async/await given that async/await is syntactical sugar on top of promises.

It seems that there isn't an active trace when using the async/await syntax. We can confidently say this is wrong as the trace does exist, having been created by express when the request was made to the server.

Reproduction

Using @pvatterott's supplied reproduction...

Configure npm link with beeline-nodejs,

cd beeline-nodejs
npm link

cd pg-trace-example
npm link honeycomb-beeline

Then add a console.log in this conditional in the pg instrumentation: https://github.com/honeycombio/beeline-nodejs/blob/master/lib/instrumentation/pg.js#L30

Then run pg-trace-example and ping the endpoint under test:

# Running in debug mode is super helpful for seeing the spans being sent.
DEBUG=honeycomb-beeline:* yarn start

curl localhost:8080/example/callback/text-only-knex-await

It will print the console.log showing it can't find an active trace but the request will complete and beelines will send the express trace to Honeycomb. So the trace does exist but the pg instrumentation cannot find it under these specific conditions.

Next Steps

@toshok Could you possibly take a look at trying this reproduction? I don't know enough about the way AsyncTracker works and how async/await might behave differently to promises enough to cause this weirdness.

[giulianob]

Is it related to this issue that I found on the cloud-trace-nodejs project?

The async_hooks API has issues tracking context around await-ed "thenables" (rather than real promises). Requests originating from the body of a then implementation in such a user-space "thenable" may not get traced. This is largely an unconventional case but is present in the knex module, which monkeypatches the Bluebird Promise's prototype to make database calls. If you are using knex (esp. the raw function), see #946 for more details on whether you are affected, as well as a suggested workaround.

[allyjweir]

@giulianob Thanks for the context. beeline-nodejs also monkeypatches Bluebird if that instrumentation is enabled as well which could potentially add to the weirdness.

I will 💯 dig into that issue. For anyone looking for the link in the future, googleapis/cloud-trace-nodejs#946

[vpontis]

I removed the Bluebird monkeypatching and I'm still running into this issue.

I added some console.logs and it looks like the instrumentation thinks that the trace isn't active. I'm hitting this line:

beeline-nodejs/lib/instrumentation/pg.js

Line 30 in 03de7e3

return query.apply(this, args);

I logged beeline.traceActive() and I'm getting true in my route.

Maybe related: I'm using Koa so I'm starting the startTrace in an async function since Koa doesn't use sync functions for Middleware.

[kousun12]

@allyjweir any updates on this by chance? spent a few hours today debugging here

[allyjweir]

Hey Rob, Unfortunately not. I’ve not been working in Node recently so haven’t had the time to work on this fix. If you make any progress I’d love to see the results!

…

On Tue, 3 Mar 2020 at 23:07, Rob Cheung ***@***.***> wrote: @allyjweir <https://github.com/allyjweir> any updates on this by chance? spent a few hours today debugging here — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#171?email_source=notifications&email_token=AA3YWBPDSRW2DDLD3TGXCG3RFWEUJA5CNFSM4JGJDMR2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOENVQYNQ#issuecomment-594218038>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AA3YWBKVF43G7IDZL4TUDWDRFWEUJANCNFSM4JGJDMRQ> .

[kousun12]

yeah, we'd love to get this working. in the meantime our solution is to use knex hooks to make our own instrumentation rather than the pg instrumentation. maybe worth contributing back if you think it makes sense / worth supporting

…

On Tue, Mar 3, 2020 at 3:21 PM Ally Weir ***@***.***> wrote: Hey Rob, Unfortunately not. I’ve not been working in Node recently so haven’t had the time to work on this fix. If you make any progress I’d love to see the results! On Tue, 3 Mar 2020 at 23:07, Rob Cheung ***@***.***> wrote: > @allyjweir <https://github.com/allyjweir> any updates on this by chance? > spent a few hours today debugging here > > — > You are receiving this because you were mentioned. > > > Reply to this email directly, view it on GitHub > < #171?email_source=notifications&email_token=AA3YWBPDSRW2DDLD3TGXCG3RFWEUJA5CNFSM4JGJDMR2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOENVQYNQ#issuecomment-594218038 >, > or unsubscribe > < https://github.com/notifications/unsubscribe-auth/AA3YWBKVF43G7IDZL4TUDWDRFWEUJANCNFSM4JGJDMRQ > > . > — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#171?email_source=notifications&email_token=AAOS6XJN7GVWPLKOHQJIKC3RFWGGFA5CNFSM4JGJDMR2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOENVRZJA#issuecomment-594222244>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAOS6XPHRWKYRVA2YIMH6H3RFWGGFANCNFSM4JGJDMRQ> .

-- Robert

[giuliano-barberi-tf]

@kousun12 I'm using knex hooks but even then the tracing gets lost. Did you find a way to maintain the trace properly?

[s5no5t]

@kousun12 would you be willing to explain how to use knex hooks to add knex instrumentation?

[pvatterott]

This appears to have been fixed by #272! Would be interested to hear confirmation from others who have encountered this issue, then will close this one out

[JamieDanielson]

Looks like this was fixed in a PR and has had no recent activity. Closing for now but feel free to reopen if the issue is still relevant.