APM transactions missing SQL statements

airstofather · February 5, 2019, 5:20pm

Kibana version:
6.6.0 (cloud)

Elasticsearch version:
6.6.0 (cloud)

APM Server version:
6.6.0 (self hosted open source docker image)

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

Browser version:
Any browser

Original install method (e.g. download page, yum, deb, from source, etc.) and version:
Elastic and Kibana are cloud hosted. APM server runs from Elastic's open source docker image 6.6.0. The agent was installed with npm install

Description of the problem including expected versus actual behavior.
Transactions do not include any SQL traces. We use sequelize (sequelize v4.39.0 and pg v7.4.3) to connect to a postgres server and none of the SQL statements are included.

In addition we see the following stack trace that I don't know how to interpret when clicking on one of the traces in a transaction

node_modules/follow-redirects/index.js in RedirectableRequest._performRequest at line 186
node_modules/follow-redirects/index.js in RedirectableRequest at line 69
node_modules/follow-redirects/index.js in wrappedProtocol.request at line 363
node_modules/axios/lib/adapters/http.js in dispatchHttpRequest at line 141
in Promise
node_modules/axios/lib/adapters/http.js in httpAdapter at line 18
node_modules/axios/lib/core/dispatchRequest.js in dispatchRequest at line 59
in &lt;anonymous&gt;
internal/process/next_tick.js in _tickCallback at line 189

stephenbelanger · February 6, 2019, 5:22pm

In theory, the queries should be traced by the internal use of the pg module. I'm not sure why that's not happening. I'll need to investigate.

stephenbelanger · February 6, 2019, 5:24pm

Can you share which versions of sequelize and pg you are using so I can try to reproduce with your exact versions?

airstofather · February 6, 2019, 5:41pm

@stephenbelanger I've updated the question to include the versions: sequelize v4.39.0 and pg v7.4.3

stephenbelanger · February 6, 2019, 7:32pm

I've tested those versions locally and I'm getting spans just fine. The next possibility is context loss. If something behaves asynchronously and we don't have code to patch it, the system can lose track of what request transaction a given span belongs to.

Can you share what other modules you are using in your app? I'm especially interested in what is used in the execution path between when the request you are inspecting begins and when the query begins.

airstofather · February 6, 2019, 7:52pm

@stephenbelanger this is the dependency section from package.json:

  "dependencies": {
    "@sendgrid/mail": "^6.2.1",
    "@sera4/essentia": "1.0.9",
    "axios": "^0.18.0",
    "bcrypt": "^3.0.3",
    "bluebird": "^3.5.3",
    "body-parser": "^1.18.3",
    "dotenv-flow": "^0.1.0",
    "elastic-apm-node": "^2.5.1",
    "event-stream": "^4.0.1",
    "express": "^4.16.3",
    "express-list-endpoints": "^4.0.0",
    "express-validator": "^5.3.0",
    "fs-extra": "^7.0.1",
    "google-libphonenumber": "^3.1.14",
    "moment": "^2.23.0",
    "morgan": "^1.9.1",
    "pg": "^7.4.3",
    "pg-hstore": "^2.3.2",
    "redis": "^2.8.0",
    "sequelize": "^4.39.0",
    "sequelize-cli": "^5.2.0",
    "sequelize-transforms": "^2.0.0",
    "uuid": "^3.3.2"
  },

airstofather · February 6, 2019, 7:55pm

And this is a screenshot of a transaction sample with missing SQL spans:

stephenbelanger · February 6, 2019, 7:57pm

Can you get a log from running with ELASTIC_APM_LOG_LEVEL=debug and requesting the route? That will help to identify where in the lifecycle it loses track of the transaction. You can also manually check agent.currentTransaction to see where it becomes null.

airstofather · February 6, 2019, 8:16pm

agent.currentTransaction is undefined when printed right before looking up the user.

The logs from the apm server:

apm_1  | 2019-02-06T20:10:50.160Z	DEBUG	[publish]	pipeline/processor.go:308	Publish event: {
apm_1  |   "@timestamp": "2019-02-06T20:10:40.101Z",
apm_1  |   "@metadata": {
apm_1  |     "beat": "apm-server",
apm_1  |     "type": "doc",
apm_1  |     "version": "6.6.0"
apm_1  |   },
apm_1  |   "system": {
apm_1  |     "cpu": {
apm_1  |       "total": {
apm_1  |         "norm": {
apm_1  |           "pct": 0.4144736842105263
apm_1  |         }
apm_1  |       }
apm_1  |     },
apm_1  |     "memory": {
apm_1  |       "actual": {
apm_1  |         "free": 6.0665856e+07
apm_1  |       },
apm_1  |       "total": 1.7179869184e+10
apm_1  |     },
apm_1  |     "process": {
apm_1  |       "cpu": {
apm_1  |         "total": {
apm_1  |           "norm": {
apm_1  |             "pct": 0.2816320242230635
apm_1  |           }
apm_1  |         }
apm_1  |       },
apm_1  |       "memory": {
apm_1  |         "rss": {
apm_1  |           "bytes": 1.11423488e+08
apm_1  |         }
apm_1  |       }
apm_1  |     }
apm_1  |   },
apm_1  |   "context": {
apm_1  |     "tags": {
apm_1  |       "env": "development",
apm_1  |       "hostname": "Deniss-MacBook-Pro.local"
apm_1  |     },
apm_1  |     "system": {
apm_1  |       "hostname": "Deniss-MacBook-Pro.local",
apm_1  |       "architecture": "x64",
apm_1  |       "platform": "darwin",
apm_1  |       "ip": "172.27.0.1"
apm_1  |     },
apm_1  |     "process": {
apm_1  |       "pid": 13470,
apm_1  |       "ppid": 13463,
apm_1  |       "title": "node",
apm_1  |       "argv": [
apm_1  |         "/usr/local/Cellar/node/9.8.0/bin/node",
apm_1  |         "/Users/denis/Development/project/server.js"
apm_1  |       ]
apm_1  |     },
apm_1  |     "service": {
apm_1  |       "name": "test-apm-local-3",
apm_1  |       "agent": {
apm_1  |         "name": "nodejs",
apm_1  |         "version": "2.5.1"
apm_1  |       },
apm_1  |       "language": {
apm_1  |         "name": "javascript"
apm_1  |       },
apm_1  |       "runtime": {
apm_1  |         "name": "node",
apm_1  |         "version": "9.8.0"
apm_1  |       }
apm_1  |     }
apm_1  |   },
apm_1  |   "processor": {
apm_1  |     "name": "metric",
apm_1  |     "event": "metric"
apm_1  |   },
apm_1  |   "beat": {
apm_1  |     "name": "66901330dd93",
apm_1  |     "hostname": "66901330dd93",
apm_1  |     "version": "6.6.0"
apm_1  |   },
apm_1  |   "host": {
apm_1  |     "name": "66901330dd93"
apm_1  |   }
apm_1  | }
apm_1  | 2019-02-06T20:10:50.162Z	DEBUG	[publish]	pipeline/processor.go:308	Publish event: {
apm_1  |   "@timestamp": "2019-02-06T20:10:44.256Z",
apm_1  |   "@metadata": {
apm_1  |     "beat": "apm-server",
apm_1  |     "type": "doc",
apm_1  |     "version": "6.6.0"
apm_1  |   },
apm_1  |   "context": {
apm_1  |     "system": {
apm_1  |       "hostname": "Deniss-MacBook-Pro.local",
apm_1  |       "architecture": "x64",
apm_1  |       "platform": "darwin",
apm_1  |       "ip": "172.27.0.1"
apm_1  |     },
apm_1  |     "process": {
apm_1  |       "pid": 13470,
apm_1  |       "ppid": 13463,
apm_1  |       "title": "node",
apm_1  |       "argv": [
apm_1  |         "/usr/local/Cellar/node/9.8.0/bin/node",
apm_1  |         "/Users/denis/Development/project/server.js"
apm_1  |       ]
apm_1  |     },
apm_1  |     "service": {
apm_1  |       "name": "test-apm-local-3",
apm_1  |       "agent": {
apm_1  |         "name": "nodejs",
apm_1  |         "version": "2.5.1"
apm_1  |       },
apm_1  |       "language": {
apm_1  |         "name": "javascript"
apm_1  |       },
apm_1  |       "runtime": {
apm_1  |         "name": "node",
apm_1  |         "version": "9.8.0"
apm_1  |       }
apm_1  |     },
apm_1  |     "request": {
apm_1  |       "body": "[REDACTED]",
apm_1  |       "http_version": "1.1",
apm_1  |       "method": "POST",
apm_1  |       "url": {
apm_1  |         "port": "20020",
apm_1  |         "pathname": "/api/v0/auth",
apm_1  |         "full": "http://localhost:20020/api/v0/auth",
apm_1  |         "raw": "/api/v0/auth",
apm_1  |         "protocol": "http:",
apm_1  |         "hostname": "localhost"
apm_1  |       },
apm_1  |       "socket": {
apm_1  |         "encrypted": false,
apm_1  |         "remote_address": "127.0.0.1"
apm_1  |       },
apm_1  |       "headers": {
apm_1  |         "connection": "keep-alive",
apm_1  |         "postman-token": "46880aaa-03e6-453e-9071-9b6e74ba49c3",
apm_1  |         "host": "localhost:20020",
apm_1  |         "accept": "*/*",
apm_1  |         "user-agent": "PostmanRuntime/7.6.0",
apm_1  |         "accept-encoding": "gzip, deflate",
apm_1  |         "content-length": "56",
apm_1  |         "content-type": "application/json",
apm_1  |         "cache-control": "no-cache"
apm_1  |       }
apm_1  |     },
apm_1  |     "response": {
apm_1  |       "headers": {
apm_1  |         "date": "Wed, 06 Feb 2019 20:10:44 GMT",
apm_1  |         "connection": "keep-alive",
apm_1  |         "x-powered-by": "Express",
apm_1  |         "content-type": "application/json; charset=utf-8",
apm_1  |         "content-length": "446",
apm_1  |         "etag": "W/\"1be-Zi8lgVrP3U09s2/24vh0MSe6zDA\""
apm_1  |       },
apm_1  |       "status_code": 200
apm_1  |     }
apm_1  |   },
apm_1  |   "trace": {
apm_1  |     "id": "95fca978e71ba9e6e592e9f8d08aa35e"
apm_1  |   },
apm_1  |   "timestamp": {
apm_1  |     "us": 1549483844256067
apm_1  |   },
apm_1  |   "beat": {
apm_1  |     "version": "6.6.0",
apm_1  |     "name": "66901330dd93",
apm_1  |     "hostname": "66901330dd93"
apm_1  |   },
apm_1  |   "host": {
apm_1  |     "name": "66901330dd93"
apm_1  |   },
apm_1  |   "processor": {
apm_1  |     "name": "transaction",
apm_1  |     "event": "transaction"
apm_1  |   },
apm_1  |   "transaction": {
apm_1  |     "id": "9c0d151bb517d701",
apm_1  |     "name": "POST /api/v0/auth",
apm_1  |     "duration": {
apm_1  |       "us": 228181
apm_1  |     },
apm_1  |     "type": "request",
apm_1  |     "result": "HTTP 2xx",
apm_1  |     "sampled": true,
apm_1  |     "span_count": {
apm_1  |       "started": 0
apm_1  |     }
apm_1  |   }
apm_1  | }

stephenbelanger · February 6, 2019, 8:21pm

Sorry, I meant logs from the agent.

airstofather · February 6, 2019, 8:24pm

@stephenbelanger np. Here's are the agent logs from one call:

adding hook to Node.js module loader
shimming express@4.16.3 module
shimming express.Router.process_params function
shimming express.Router.use function
shimming express.static function
copying property mime from express.static
shimming layer.handle_request function (layer: router)
shimming http@9.8.0 module
shimming http.Server.prototype.emit function
shimming http.request function
shimming http.ServerResponse.prototype.writeHead function
shimming https@9.8.0 module
shimming https.Server.prototype.emit function
shimming https.request function
shimming redis@2.8.0 module
shimming redis.RedisClient.prototype.internal_send_command
shimming bluebird@3.5.3 module
shimming bluebird.prototype functions: [ '_then', '_addCallbacks' ]
shimming bluebird.config
no active transaction found - cannot build new span
intercepted call to RedisClient.prototype.internal_send_command { id: null, command: 'auth' }
no active transaction found - cannot build new span
intercepted call to RedisClient.prototype.internal_send_command { id: null, command: 'hgetall' }
shimming layer.handle_request function (layer: router)
shimming layer.handle_request function (layer: router)
shimming layer.handle_request function (layer: router)
shimming layer.handle_request function (layer: router)
shimming layer.handle_request function (layer: router)
shimming layer.handle_request function (layer: router)
shimming layer.handle_request function (layer: router)
shimming layer.handle_request function (layer: router)
skip shimming layer.handle_request (layer: <anonymous>, path: /)
no active transaction found - cannot build new span
intercepted call to RedisClient.prototype.internal_send_command { id: null, command: 'info' }
no active transaction found - cannot build new span
intercepted call to RedisClient.prototype.internal_send_command { id: null, command: 'hgetall' }
no active transaction found - cannot build new span
intercepted call to http.request { id: null }
intercepted request event call to http.Server.prototype.emit
start trace { trans: '77d1a0927cff85e8',
  parent: undefined,
  trace: '297e96c572c8af376ef75f91ff5e760f',
  name: null,
  type: null }
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
setting transaction result { trans: '77d1a0927cff85e8',
  parent: undefined,
  trace: '297e96c572c8af376ef75f91ff5e760f',
  result: 'HTTP 2xx' }
setting default transaction name: POST /api/v0/auth { trans: '77d1a0927cff85e8',
  parent: undefined,
  trace: '297e96c572c8af376ef75f91ff5e760f' }
sending transaction { trans: '77d1a0927cff85e8',
  trace: '297e96c572c8af376ef75f91ff5e760f' }
ended transaction { trans: '77d1a0927cff85e8',
  parent: undefined,
  trace: '297e96c572c8af376ef75f91ff5e760f',
  type: 'request',
  result: 'HTTP 2xx',
  name: 'POST /api/v0/auth' }
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 }

stephenbelanger · February 6, 2019, 8:33pm

It looks like the pg module is never even loaded.

airstofather · February 6, 2019, 8:57pm

@stephenbelanger first, let me apologize for wasting your time, it was a user error. The problem was a configuration on my side, but hinting on how to look at the agent logs really helped to find the issue. The problem was that even we required the module at the beginning, we weren't starting it right away and pg module wasn't instrumented for this reason.

I can now see the span for pg, but I'm not sure how to read the unaccounted for time in this sample:
06%20PM

Is there a way to find out what happened between the last SELECT and the INSERT?

These are the span details from the last select:
Screen_Shot_2019-02-06_at_3_54_21_PM

stephenbelanger · February 6, 2019, 9:01pm

My guess would be that time is spent in bcrypt, given that it's an auth route and you listed bcrypt in your dependencies. You could try the custom span API to wrap a span around that code and verify yourself. https://www.elastic.co/guide/en/apm/agent/nodejs/current/custom-spans.html

It's probably worthwhile for us to add bcrypt instrumentation too.

airstofather · February 6, 2019, 9:34pm

Excellent, thank you.

system · February 27, 2019, 5:34pm

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