Most of the spans can't find current transaction

Elastic Observability APM
1

Kibana version: 7.6.1

Elasticsearch version: 7.6.1

APM Server version: 7.6.1

APM Agent language and version: elastic-apm-node: 3.5.0

Original install method and version: docker

Fresh install or upgraded from other version?: fresh

Is there anything special in your setup? I can't think of anything special

Description of the problem:

Hi guys,
I find the ELK stack tools very, very useful. Thank you!
I have recently added APM support to my app and can see that most of the spans are missing on the trace samples in Kibana.
My code is not using any of the supported http stack apps, like express or so.
However I did my best to follow the setup instructions for elastic-apm-node
I use connect and swagger to handle http requests
I use knex to handle postgreSQL queries
Please take a look at the provided logs. I suspect that the context of the transaction is lost, but let me know where to find the problem.
In the GET request sample below all the spans are missing
In the POST request sample below I can see three of them:

  • external http call
  • BEGIN sql transaction
  • COMMIT sql transaction

All others are missing

Provide logs and/or server output (if relevant):

samples from index.js:

// starting method at the top of the file
const apm = require('elastic-apm-node').start({
  active: false // override with ELASTIC_APM_ACTIVE
})

const http = require('http')
const app = require('connect')()
const swaggerTools = require('swagger-tools')

...

const setApmTransactionName = (req, res, next) => {
    apm.setTransactionName(`${req.method} ${req.swagger.apiPath}`)
}

...

swaggerTools.initializeMiddleware(swaggerDoc, middleware => {
  app.use(middleware.swaggerMetadata())
  app.use(setApmTransactionName)
  app.use(middleware.swaggerSecurity(securityHandler))
  app.use(middleware.swaggerValidator())
  app.use(middleware.swaggerRouter(options))
  app.use(apm.middleware.connect())
  app.use(appErrorHandler)
})

elastic env variables set for the app:

  ELASTIC_APM_ACTIVE=true
  ELASTIC_APM_SERVER_URL=http://apm-server:8200
  ELASTIC_APM_SERVICE_NAME=${imageName}
  ELASTIC_APM_LOG_LEVEL=debug
  ELASTIC_APM_USE_PATH_AS_TRANSACTION_NAME=true

extract from package.json:

  "main": "index.js",
  "dependencies": {
    "bunyan": "^1.8.12",
    "connect": "^3.2.0",
    "cors": "^2.8.4",
    "elastic-apm-node": "^3.5.0",
    "jaeger-client": "^3.13.0",
    "jsonwebtoken": "^8.2.2",
    "jwks-rsa": "^1.2.1",
    "knex": "^0.20.8",
    "mongodb": "^3.3.3",
    "opentracing": "^0.14.3",
    "pg": "^7.17.1",
    "superagent": "^5.1.0",
    "swagger-tools": "^0.10.4"
  },

startup logs:

adding hook to Node.js module loader
shimming http@12.14.1 module
shimming http.Server.prototype.emit function
shimming http.ServerResponse.prototype.writeHead function
shimming http.request function
shimming http.get function
shimming finalhandler@1.1.2 module
shimming https@12.14.1 module
shimming https.Server.prototype.emit function
shimming https.request function
shimming https.get function
shimming knex@0.20.11 module
shimming Knex.Client.prototype.runner
shimming Knex.Client.prototype functions: [ 'queryBuilder', 'raw' ]
shimming pg@7.18.2 module
shimming pg.Client.prototype.query
capturing custom stack trace for knex
capturing custom stack trace for knex
shimming knex runner.query
no active transaction found - cannot build new span
intercepted call to http.request { id: null }
APM Server transport error (EAI_AGAIN): getaddrinfo EAI_AGAIN apm-server
capturing custom stack trace for knex
capturing custom stack trace for knex
shimming knex runner.query
no active transaction found - cannot build new span
intercepted call to pg.Client.prototype.query { id: null, sql: 'select version();' }
intercepted call to knex runner.query
no active transaction found - cannot build new span
intercepted call to pg.Client.prototype.query { id: null, sql: 'SELECT 1+1 AS result' }
shimming http2@12.14.1 module
shimming http2.createServer function
shimming http2.connect function
no active transaction found - cannot build new span
intercepted call to http.request { id: null }
no active transaction found - cannot build new span
intercepted call to http.request { id: null }
no active transaction found - cannot build new span
intercepted call to http.request { id: null }
no active transaction found - cannot build new span
intercepted call to http.request { id: null }

GET request logs:

intercepted request event call to http.Server.prototype.emit for /restapi/v1/product/1
start trace {
  trans: 'd5401eed8016f170',
  parent: undefined,
  trace: '5b0d5206255f78fcfdd36a71ddf28a35',
  name: 'unnamed',
  type: null,
  subtype: null,
  action: null
}
setting transaction name {
  trans: 'd5401eed8016f170',
  parent: undefined,
  trace: '5b0d5206255f78fcfdd36a71ddf28a35',
  name: 'GET /product/{productId}'
}
capturing custom stack trace for knex
shimming knex runner.query
intercepted call to knex runner.query
no active transaction found - cannot build new span
intercepted call to pg.Client.prototype.query {
  id: null,
  sql: 'select "data", "product_id" from "public"."product" where "product_id" = $1'
}
no active transaction found - cannot build new span
intercepted call to http.request { id: null }
setting transaction result {
  trans: 'd5401eed8016f170',
  parent: undefined,
  trace: '5b0d5206255f78fcfdd36a71ddf28a35',
  result: 'HTTP 2xx'
}
setting default transaction name: GET /restapi/v1/product/1 {
  trans: 'd5401eed8016f170',
  parent: undefined,
  trace: '5b0d5206255f78fcfdd36a71ddf28a35'
}
sending transaction {
  trans: 'd5401eed8016f170',
  trace: '5b0d5206255f78fcfdd36a71ddf28a35'
}
ended transaction {
  trans: 'd5401eed8016f170',
  parent: undefined,
  trace: '5b0d5206255f78fcfdd36a71ddf28a35',
  type: 'request',
  result: 'HTTP 2xx',
  name: 'GET /product/{productId}'
}
no active transaction found - cannot build new span
intercepted call to http.request { id: null }

POST request logs:

intercepted request event call to http.Server.prototype.emit for /restapi/v1/product/1
start trace {
  trans: 'a9c15ae6fb9b076a',
  parent: undefined,
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'unnamed',
  type: null,
  subtype: null,
  action: null
}
setting transaction name {
  trans: 'a9c15ae6fb9b076a',
  parent: undefined,
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'POST /product/{productId}'
}
start span {
  span: 'e3f02e6ca275778d',
  parent: 'a9c15ae6fb9b076a',
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'unnamed',
  type: 'external',
  subtype: 'https',
  action: 'http'
}
intercepted call to https.request { id: 'a9c15ae6fb9b076a' }
request details: {
  protocol: 'https:',
  host: '000001-dummy.auth0.com',
  id: 'a9c15ae6fb9b076a'
}
intercepted http.ClientRequest response event { id: 'a9c15ae6fb9b076a' }
intercepted http.IncomingMessage end event { id: 'a9c15ae6fb9b076a' }
ended span {
  span: 'e3f02e6ca275778d',
  parent: 'a9c15ae6fb9b076a',
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'GET 000001-dummy.auth0.com/.well-known/jwks.json',
  type: 'external',
  subtype: 'https',
  action: 'http'
}
encoding span {
  span: 'e3f02e6ca275778d',
  parent: 'a9c15ae6fb9b076a',
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'GET 000001-dummy.auth0.com/.well-known/jwks.json',
  type: 'external'
}
sending span {
  span: 'e3f02e6ca275778d',
  parent: 'a9c15ae6fb9b076a',
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'GET 000001-dummy.auth0.com/.well-known/jwks.json',
  type: 'external'
}
capturing custom stack trace for knex
shimming knex runner.query
intercepted call to knex runner.query
no active transaction found - cannot build new span
intercepted call to pg.Client.prototype.query {
  id: null,
  sql: 'select "data", "product_id" from "public"."product" where "product_id" = $1'
}
start span {
  span: '47b66011020b5147',
  parent: 'e3f02e6ca275778d',
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'unnamed',
  type: 'external',
  subtype: 'http',
  action: 'http'
}
intercepted call to http.request { id: 'a9c15ae6fb9b076a' }
ignore http request to intake API { id: 'a9c15ae6fb9b076a' }
start span {
  span: '05987eea2247c6bb',
  parent: 'a9c15ae6fb9b076a',
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'SQL',
  type: 'db',
  subtype: 'postgresql',
  action: 'query'
}
intercepted call to pg.Client.prototype.query { id: 'a9c15ae6fb9b076a', sql: 'BEGIN;' }
applying custom stack trace to span {
  span: '05987eea2247c6bb',
  parent: 'a9c15ae6fb9b076a',
  trace: '9f35a2d7322529f536a4e87169c1ea9a'
}
intercepted end of pg.Client.prototype.query { id: 'a9c15ae6fb9b076a' }
ended span {
  span: '05987eea2247c6bb',
  parent: 'a9c15ae6fb9b076a',
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'BEGIN',
  type: 'db',
  subtype: 'postgresql',
  action: 'query'
}
encoding span {
  span: '05987eea2247c6bb',
  parent: 'a9c15ae6fb9b076a',
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'BEGIN',
  type: 'db'
}
capturing custom stack trace for knex
shimming knex runner.query
intercepted call to knex runner.query
no active transaction found - cannot build new span
intercepted call to pg.Client.prototype.query {
  id: null,
  sql: 'insert into "public"."product" ("data", "product_id") values ($1, $2)'
}
shimming knex runner.query
intercepted call to knex runner.query
no active transaction found - cannot build new span
intercepted call to pg.Client.prototype.query { id: null, sql: 'create schema "000001"' }
sending span {
  span: '05987eea2247c6bb',
  parent: 'a9c15ae6fb9b076a',
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'BEGIN',
  type: 'db'
}
shimming knex runner.query
intercepted call to knex runner.query
no active transaction found - cannot build new span
intercepted call to pg.Client.prototype.query {
  id: null,
  sql: 'create table "000001"."hardware" ("hardware_id" varchar(255), "data" jsonb)'
}
intercepted call to knex runner.query
no active transaction found - cannot build new span
start span {
  span: '9e2d888d282e2ab0',
  parent: '05987eea2247c6bb',
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'SQL',
  type: 'db',
  subtype: 'postgresql',
  action: 'query'
}
intercepted call to pg.Client.prototype.query { id: 'a9c15ae6fb9b076a', sql: 'COMMIT;' }
intercepted end of pg.Client.prototype.query { id: 'a9c15ae6fb9b076a' }
ended span {
  span: '9e2d888d282e2ab0',
  parent: '05987eea2247c6bb',
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'COMMIT',
  type: 'db',
  subtype: 'postgresql',
  action: 'query'
}
encoding span {
  span: '9e2d888d282e2ab0',
  parent: '05987eea2247c6bb',
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'COMMIT',
  type: 'db'
}
no active transaction found - cannot build new span
intercepted call to http.request { id: null }
sending span {
  span: '9e2d888d282e2ab0',
  parent: '05987eea2247c6bb',
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  name: 'COMMIT',
  type: 'db'
}
setting transaction result {
  trans: 'a9c15ae6fb9b076a',
  parent: undefined,
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  result: 'HTTP 2xx'
}
setting default transaction name: POST /restapi/v1/product/1 {
  trans: 'a9c15ae6fb9b076a',
  parent: undefined,
  trace: '9f35a2d7322529f536a4e87169c1ea9a'
}
sending transaction {
  trans: 'a9c15ae6fb9b076a',
  trace: '9f35a2d7322529f536a4e87169c1ea9a'
}
ended transaction {
  trans: 'a9c15ae6fb9b076a',
  parent: undefined,
  trace: '9f35a2d7322529f536a4e87169c1ea9a',
  type: 'request',
  result: 'HTTP 2xx',
  name: 'POST /product/{productId}'
}
2

I kept digging it further and it seems I was using knex calls improperly. The db object below is a knex instance.

This code looses transaction tracking

app.use(async function (req, res, next) {
  await db.schema.createSchemaIfNotExists('public')
  res.end()
})

This code keeps transaction tracking

app.use(function (req, res, next) {
  db.schema.createSchemaIfNotExists('public').then(() => {
    res.end()
  })
})
3

Setting ELASTIC_APM_ASYNC_HOOKS to false fixed the issue

Thanks to this thread:

4

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.