Different behavior on Node.js 12.x and Node.js 14.x using knex 0.21.6 #1882

qfdk · 2020-11-19T11:18:15Z

Describe the bug

Different behavior on Node.js 12.x and Node.js 14.x using knex 0.21.6

It is stated in your documentation that APM supports a minimal version of NodeJS 10.

Nevertheless, when using Node.js (v12.16.2) on our environment, we noticed that we had no more span returned for our SQL queries created via the knex driver (v0.21.6).

After some investigations, we decided to upgrade Node.js from v12.16.2 to 14.16.1 and the problem strangely disappeared.

We were indeed able to see the spans back.

We have tested serval combinations by activating debug mode:

Node.js v12.16.2 + knex (0.21.6) : no span sql

Node.js v14.15.1 + knex (0.21.6) : span sql

Expected behavior

Environment (please complete the following information)

OS: Linux ubuntu 16.04 / macOS
Node.js version: 12.16.2 / 14.15.1
APM Server version: 7.9.3
Agent version: 3.7.0

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

Agent config options

Click to expand

serviceName: process.env.APM_SERVICE_NAME,
containerId: containerId,
secretToken: process.env.APM_SECRET_TOKEN,
serverUrl: process.env.APM_SERVER_URL,
active: true,
captureSpanStackTraces: false,
breakdownMetrics: false,

package.json dependencies:

Click to expand

"dependencies": {
   "elastic-apm-node": "3.7.0",
    "axios": "^0.20.0",
    "body-parser": "^1.19.0",
    "compression": "^1.7.4",
    "express": "^4.17.1",
    "helmet": "^4.1.1",
    "knex": "^0.21.1",
    "lodash": "^4.17.15",
    "moment": "^2.24.0",
    "mongoose": "^5.8.10",
    "mssql": "^6.2.0"
},
"devDependencies": {
    "@types/compression": "^1.0.1",
    "@types/express": "^4.17.2",
    "@types/helmet": "0.0.48",
    "@types/lodash": "^4.14.161",
    "nodemon": "^2.0.2"
}    ```
</details>

The text was updated successfully, but these errors were encountered:

qfdk · 2020-11-19T11:31:08Z

Node.js v14.15.1 + knex (0.21.6) : span sql

agent configured correctly {
  pid: 75014,
  ppid: 74478,
  arch: 'x64',
  platform: 'darwin',
  node: 'v14.15.1',
  agent: '3.7.0',
}
adding hook to Node.js module loader
shimming [email protected] module
shimming [email protected] module
shimming http.Server.prototype.emit function
shimming http.ServerResponse.prototype.writeHead function
shimming http.request function
shimming http.get function
shimming [email protected] module
shimming express.Router.use function
shimming express.static function
copying property mime from express.static
shimming [email protected] module
shimming [email protected] module
shimming bluebird.prototype functions: [ '_then', '_addCallbacks' ]
shimming bluebird.config
shimming [email protected] module
shimming Knex.Client.prototype.runner
shimming Knex.Client.prototype functions: [ 'queryBuilder', 'raw' ]
shimming [email protected] module
shimming https.Server.prototype.emit function
shimming https.request function
shimming https.get function
shimming [email protected] module
capturing custom stack trace for knex
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: query
shimming express.Router.Layer.handle function: expressInit
shimming express.Router.Layer.handle function: logger
shimming express.Router.Layer.handle function: helmetMiddleware
shimming express.Router.Layer.handle function: compression
shimming express.Router.Layer.handle function: jsonParser
shimming express.Router.Layer.handle function: <anonymous>
shimming express.Router.Layer.handle function: router
shimming express.Router.Layer.handle function: <anonymous>
shimming express.Router.Layer.handle function: router
shimming express.Router.Layer.handle function: router
shimming express.Router.Layer.handle function: <anonymous>
shimming express.Router.Layer.handle function: <anonymous>
intercepted request event call to http.Server.prototype.emit for /test-query
start trace {
  trans: 'ba2cb800af2822f6',
  parent: undefined,
  trace: '3051b95a7191cc315782902863d99c18',
  name: 'unnamed',
  type: null,
  subtype: null,
  action: null
}
capturing custom stack trace for knex
shimming knex runner.query
intercepted call to knex runner.query
start span {
  span: 'b827b4b4cf4301b7',
  parent: 'ba2cb800af2822f6',
  trace: '3051b95a7191cc315782902863d99c18',
  name: 'unnamed',
  type: 'db',
  subtype: 'mssql',
  action: 'query'
}
ended span {
  span: 'b827b4b4cf4301b7',
  parent: 'ba2cb800af2822f6',
  trace: '3051b95a7191cc315782902863d99c18',
  name: 'SELECT FROM student',
  type: 'db',
  subtype: 'mssql',
  action: 'query'
}
encoding span {
  span: 'b827b4b4cf4301b7',
  parent: 'ba2cb800af2822f6',
  trace: '3051b95a7191cc315782902863d99c18',
  name: 'SELECT FROM student',
  type: 'db'
}
sending span {
  span: 'b827b4b4cf4301b7',
  parent: 'ba2cb800af2822f6',
  trace: '3051b95a7191cc315782902863d99c18',
  name: 'SELECT FROM student',
  type: 'db'
}
setting transaction result {
  trans: 'ba2cb800af2822f6',
  parent: undefined,
  trace: '3051b95a7191cc315782902863d99c18',
  result: 'HTTP 2xx'
}
setting default transaction name: GET /test-query {
  trans: 'ba2cb800af2822f6',
  parent: undefined,
  trace: '3051b95a7191cc315782902863d99c18'
}
sending transaction {
  trans: 'ba2cb800af2822f6',
  trace: '3051b95a7191cc315782902863d99c18'
}
ended transaction {
  trans: 'ba2cb800af2822f6',
  parent: undefined,
  trace: '3051b95a7191cc315782902863d99c18',
  type: 'request',
  result: 'HTTP 2xx',
  name: 'GET /test-query'
}
no active transaction found - cannot build new span
intercepted call to https.request { id: null }
no active transaction found - cannot build new span
intercepted call to https.get { id: null }

Node.js v12.16.2 + knex (0.21.6) : no span SQL

agent configured correctly {
  pid: 76421,
  ppid: 74478,
  arch: 'x64',
  platform: 'darwin',
  node: 'v12.16.2',
  agent: '3.7.0'
}
intercepted call to https.get { id: null }
intercepted request event call to http.Server.prototype.emit for /test-query
start trace {
  trans: '1458e17402247db2',
  parent: undefined,
  trace: '4fbe11863172eb0a9c2018e44c690651',
  name: 'unnamed',
  type: null,
  subtype: null,
  action: null
}
capturing custom stack trace for knex
shimming knex runner.query
intercepted call to knex runner.query
no active transaction found - cannot build new span
setting transaction result {
  trans: '1458e17402247db2',
  parent: undefined,
  trace: '4fbe11863172eb0a9c2018e44c690651',
  result: 'HTTP 2xx'
}
setting default transaction name: GET /test-query {
  trans: '1458e17402247db2',
  parent: undefined,
  trace: '4fbe11863172eb0a9c2018e44c690651'
}
sending transaction {
  trans: '1458e17402247db2',
  trace: '4fbe11863172eb0a9c2018e44c690651'
}
ended transaction {
  trans: '1458e17402247db2',
  parent: undefined,
  trace: '4fbe11863172eb0a9c2018e44c690651',
  type: 'request',
  result: 'HTTP 2xx',
  name: 'GET /test-query'
}
no active transaction found - cannot build new span

astorm · 2020-11-19T16:06:30Z

Thanks for the bug report @qfdk -- that's certainly strange and something we'll want to investigate. Do you happen to

Have code sample for one of the queries that doesn't show up?
Know what type of database you're talking to with knex (MySQL, PostgreSQL, etc?)

If you could share the information we've requested above it'll go a long way towards us being able to track this issue down.

qfdk · 2020-11-19T21:13:54Z

@astorm

I created a sample repo for you (the real project is private).

https://github.com/qfdk/apm-node-agnet-1882

You can reproduce the issue by doing the following steps:

yarn install
using docker or using your database with MS-SQL (we are using 2016, I just take a docker image for this sample)
APM is in debug mode
using n to change node version to 14.x or 12.x
call endpoint /test-query

I mention it in APM 3.7.0, well my sample project agent 3.8.0 still has this problem.

If you require additional information, please, let me know.

I put logs as follows.

node: 'v14.15.1', agent: '3.8.0',

intercepted request event call to http.Server.prototype.emit for /test-query
start trace {
  trans: '062eb9c119ab63c5',
  parent: undefined,
  trace: '38f15fc9713efcd0f7b65d75bdaf1224',
  name: 'unnamed',
  type: null,
  subtype: null,
  action: null
}
capturing custom stack trace for knex
shimming knex runner.query
{
  method: 'raw',
  sql: '\n      SELECT 1+1\n    ',
  bindings: [],
  options: {},
  __knexQueryUid: '6aRpVBa4QG-XzMMqOv07o'
}
intercepted call to knex runner.query
start span {
  span: '67706d4d0858c574',
  parent: '062eb9c119ab63c5',
  trace: '38f15fc9713efcd0f7b65d75bdaf1224',
  name: 'unnamed',
  type: 'db',
  subtype: 'mssql',
  action: 'query'
}
ended span {
  span: '67706d4d0858c574',
  parent: '062eb9c119ab63c5',
  trace: '38f15fc9713efcd0f7b65d75bdaf1224',
  name: 'SELECT',
  type: 'db',
  subtype: 'mssql',
  action: 'query'
}
encoding span {
  span: '67706d4d0858c574',
  parent: '062eb9c119ab63c5',
  trace: '38f15fc9713efcd0f7b65d75bdaf1224',
  name: 'SELECT',
  type: 'db'
}
sending span {
  span: '67706d4d0858c574',
  parent: '062eb9c119ab63c5',
  trace: '38f15fc9713efcd0f7b65d75bdaf1224',
  name: 'SELECT',
  type: 'db'
}
setting transaction result {
  trans: '062eb9c119ab63c5',
  parent: undefined,
  trace: '38f15fc9713efcd0f7b65d75bdaf1224',
  result: 'HTTP 3xx'
}
setting default transaction name: GET /test-query {
  trans: '062eb9c119ab63c5',
  parent: undefined,
  trace: '38f15fc9713efcd0f7b65d75bdaf1224'
}
sending transaction {
  trans: '062eb9c119ab63c5',
  trace: '38f15fc9713efcd0f7b65d75bdaf1224'
}
ended transaction {
  trans: '062eb9c119ab63c5',
  parent: undefined,
  trace: '38f15fc9713efcd0f7b65d75bdaf1224',
  type: 'request',
  result: 'HTTP 3xx',
  name: 'GET /test-query'
}
GET /test-query 304 107.904 ms - -
no active transaction found - cannot build new span
intercepted call to http.request { id: null }

node: 'v12.16.2', agent: '3.8.0',

intercepted request event call to http.Server.prototype.emit for /test-query
start trace {
  trans: '5e888f8af3ec5d64',
  parent: undefined,
  trace: '6b3e4150c758a76ee9c08ae6abf1d09c',
  name: 'unnamed',
  type: null,
  subtype: null,
  action: null
}
capturing custom stack trace for knex
shimming knex runner.query
{
  method: 'raw',
  sql: '\n      SELECT 1+1\n    ',
  bindings: [],
  options: {},
  __knexQueryUid: 'bQS21t9EpRonbisCiOU1F'
}
intercepted call to knex runner.query
no active transaction found - cannot build new span
setting transaction result {
  trans: '5e888f8af3ec5d64',
  parent: undefined,
  trace: '6b3e4150c758a76ee9c08ae6abf1d09c',
  result: 'HTTP 3xx'
}
setting default transaction name: GET /test-query {
  trans: '5e888f8af3ec5d64',
  parent: undefined,
  trace: '6b3e4150c758a76ee9c08ae6abf1d09c'
}
sending transaction {
  trans: '5e888f8af3ec5d64',
  trace: '6b3e4150c758a76ee9c08ae6abf1d09c'
}
ended transaction {
  trans: '5e888f8af3ec5d64',
  parent: undefined,
  trace: '6b3e4150c758a76ee9c08ae6abf1d09c',
  type: 'request',
  result: 'HTTP 3xx',
  name: 'GET /test-query'
}
GET /test-query 304 77.830 ms - -

qfdk · 2020-12-08T08:32:22Z

@astorm Hello Something new ?

astorm · 2020-12-09T00:02:09Z

@qfdk Thanks for the reproduction, despite the silence is is appreciated. We have not had a chance to investigate deeply yet.

Giving things a quick look over, given the

no active transaction found - cannot build new span

message I suspect this may the agent hitting a different knex (or perhaps internal) codepath in node 14 -- one that includes calling some asyncronous code (setImmediate and its ilk, a promise, etc) in an unintrumented function. This leads to the execution happening outside a transaction.

Our next steps on this would to validate that theroy, attempt to identify where that code path is and either wrap the async function or further diagnose the issue.

We do intend to investigate but have high priority items right now. The perils of open source and a small team :| If anyone else reading has thoughts or wanted to figure this out we'd be appreciative. Otherwise all be can do is ask for your patience, and thank you again for the reproduction.

rattkin · 2020-12-15T08:22:35Z

my logs are filling with messages like:

intercepted call to https.request { id: null }
no active transaction found - cannot build new span

just posting here so I get notified if there are any changes.
I'm using node 14 as well

astorm · 2021-01-04T21:23:57Z

@qfdk We had a chance to look into this a bit today. Using your reproduction

We saw the span-less behavior you described in Node 12.16.2
We saw the span-less behavior you described in Node 12.18.4
We did NOT see the behavior you described in Node 12.19.0 or Node 12.20.1

It seems like a chance that landed in Node 12.19.0 has cleared this issue up. (we're currently unsure which issue -- if folks reading had a reckon about that we're all ears)

@qfdk Would you be able to switch to a more recent version of Node and let us know if you're still seeing the behavior?

@qfdk Presuming the answer to the above is "no, a recent version of 12.x fixed this" -- is moving to a more recent version of Node 12 an acceptable fix for you, or is there something compelling keeping you at 12.16.2?

astorm · 2021-01-04T21:33:01Z

@rattkin Is your interest here in the Node 12/Node 14 behavior difference that qfdk noticed -- or are you concerned about the "no active transaction found - cannot build new span" errors found in your logs more generally? If the later -- is this a problem of your logs filling up, or just curiosity about what these messages mean?

rattkin · 2021-01-05T07:34:55Z

@astorm I am concerned that the "no active transaction found - cannot build new span" errors mean that I have configured something badly, or there is a bug in apm agent or another package.

We are in development, if it scaled up with number of users for example, it could cause a real problem

qfdk · 2021-01-05T08:41:06Z

Hello @astorm,

We migrated Node.js to 14.15.1 for env prod, the problem has resolved. In Decembre we deloyed our solution in elastic cloud.
I didn't test all version of Node.js 12.x.

Then we upgraded apm-agent-nodejs to the lastest version(3.9.0) witch fixed mongodb logo missing problem in Service Map.
#1892

Thank you and Happy New Year 2021

astorm · 2021-01-05T17:42:14Z

Thanks for the update @qfdk -- it sounds like you're all set here so we're going to close this issue out. @rattkin -- it wasn't 100% clear if you had the same, or just a similar problem, so let us know if you're still seeing problems.

Also -- swiping some things @trentm shared with me, it looks like this cherry pick commit is what fixed things in more recent versions of node: nodejs/node#33778 the (possibly inaccurate) TL;DR; on that is the async_hooks modules can now see when non-native promises/thenables run.

trentm · 2021-01-05T18:01:29Z

Some more background on that: This backport of the patch to v8 landed on node versions v14.6.0, v12.19.0, and v10.23.0.
Here is the v8 CR discussion: https://chromium-review.googlesource.com/c/v8/v8/+/2215624 and a long technical dive of some of the issues (including mention if Knex's ".then()" implementation) here: https://gist.github.com/Qard/faad53ba2368db54c95828365751d7bc

qfdk changed the title ~~Different behaviour on NodeJS 12 and NodeJS 14 using knex 0.21.6~~ Different behavior on Node.js 12.x and Node.js 14.x using knex 0.21.6 Nov 19, 2020

astorm added the agent-nodejs Make available for APM Agents project planning. label Nov 19, 2020

astorm closed this as completed Jan 5, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Different behavior on Node.js 12.x and Node.js 14.x using knex 0.21.6 #1882

Different behavior on Node.js 12.x and Node.js 14.x using knex 0.21.6 #1882

qfdk commented Nov 19, 2020 •

edited

Loading

qfdk commented Nov 19, 2020

astorm commented Nov 19, 2020 •

edited

Loading

qfdk commented Nov 19, 2020 •

edited

Loading

qfdk commented Dec 8, 2020

astorm commented Dec 9, 2020

rattkin commented Dec 15, 2020

astorm commented Jan 4, 2021

astorm commented Jan 4, 2021

rattkin commented Jan 5, 2021

qfdk commented Jan 5, 2021 •

edited

Loading

astorm commented Jan 5, 2021

trentm commented Jan 5, 2021

Different behavior on Node.js 12.x and Node.js 14.x using knex 0.21.6 #1882

Different behavior on Node.js 12.x and Node.js 14.x using knex 0.21.6 #1882

Comments

qfdk commented Nov 19, 2020 • edited Loading

qfdk commented Nov 19, 2020

astorm commented Nov 19, 2020 • edited Loading

qfdk commented Nov 19, 2020 • edited Loading

node: 'v14.15.1', agent: '3.8.0',

node: 'v12.16.2', agent: '3.8.0',

qfdk commented Dec 8, 2020

astorm commented Dec 9, 2020

rattkin commented Dec 15, 2020

astorm commented Jan 4, 2021

astorm commented Jan 4, 2021

rattkin commented Jan 5, 2021

qfdk commented Jan 5, 2021 • edited Loading

astorm commented Jan 5, 2021

trentm commented Jan 5, 2021

qfdk commented Nov 19, 2020 •

edited

Loading

astorm commented Nov 19, 2020 •

edited

Loading

qfdk commented Nov 19, 2020 •

edited

Loading

qfdk commented Jan 5, 2021 •

edited

Loading