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

[qfdk]

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.

supported-technologies.

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>
  

[qfdk]

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 finalhandler@1.1.2 module
shimming http@14.13.0 module
shimming http.Server.prototype.emit function
shimming http.ServerResponse.prototype.writeHead function
shimming http.request function
shimming http.get function
shimming express@4.17.1 module
shimming express.Router.use function
shimming express.static function
copying property mime from express.static
shimming mongodb@3.6.2 module
shimming bluebird@3.5.1 module
shimming bluebird.prototype functions: [ '_then', '_addCallbacks' ]
shimming bluebird.config
shimming knex@0.21.6 module
shimming Knex.Client.prototype.runner
shimming Knex.Client.prototype functions: [ 'queryBuilder', 'raw' ]
shimming https@14.13.0 module
shimming https.Server.prototype.emit function
shimming https.request function
shimming https.get function
shimming tedious@6.7.0 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]

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

1. Have code sample for one of the queries that doesn't show up?
2. 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]

@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]

@astorm Hello Something new ?

[astorm]

@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]

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]

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

1. We saw the span-less behavior you described in Node 12.16.2
2. We saw the span-less behavior you described in Node 12.18.4
3. 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]

@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]

@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]

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]

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]

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