# APM transactions missing SQL statements

**URL:** <https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164>\
**Category:** APM\
**Created:** [February 5, 2019, 5:20pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164 "2019-02-05T17:20:25Z")\
**Posts on this page:** 16\
**Page:** 1

<div class="post-metadata">

**Author:** ![airstofather](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/airstofather/32/49623_2.png) [@airstofather](https://discuss.elastic.co/u/airstofather)\
**Post date:** [February 5, 2019, 5:20pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/1 "2019-02-05T17:20:25Z")

</div>

**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
```

---

<div class="post-metadata">

**Author:** ![stephenbelanger](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/stephenbelanger/32/34880_2.png) [@stephenbelanger](https://discuss.elastic.co/u/stephenbelanger)\
**Post date:** [February 6, 2019, 5:22pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/2 "2019-02-06T17:22:54Z")

</div>

_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.

---

<div class="post-metadata">

**Author:** ![stephenbelanger](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/stephenbelanger/32/34880_2.png) [@stephenbelanger](https://discuss.elastic.co/u/stephenbelanger)\
**Post date:** [February 6, 2019, 5:24pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/3 "2019-02-06T17:24:50Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![airstofather](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/airstofather/32/49623_2.png) [@airstofather](https://discuss.elastic.co/u/airstofather)\
**Post date:** [February 6, 2019, 5:41pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/4 "2019-02-06T17:41:43Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![stephenbelanger](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/stephenbelanger/32/34880_2.png) [@stephenbelanger](https://discuss.elastic.co/u/stephenbelanger)\
**Post date:** [February 6, 2019, 7:32pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/5 "2019-02-06T19:32:50Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![airstofather](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/airstofather/32/49623_2.png) [@airstofather](https://discuss.elastic.co/u/airstofather)\
**Post date:** [February 6, 2019, 7:52pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/6 "2019-02-06T19:52:08Z")

</div>

@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"
  },
```

---

<div class="post-metadata">

**Author:** ![airstofather](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/airstofather/32/49623_2.png) [@airstofather](https://discuss.elastic.co/u/airstofather)\
**Post date:** [February 6, 2019, 7:55pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/7 "2019-02-06T19:55:04Z")

</div>

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

 ![26%20PM](https://us1.discourse-cdn.com/elastic/original/3X/9/a/9ae1491599a602876959beb5a5d6a56dbdfaccb6.png)

---

<div class="post-metadata">

**Author:** ![stephenbelanger](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/stephenbelanger/32/34880_2.png) [@stephenbelanger](https://discuss.elastic.co/u/stephenbelanger)\
**Post date:** [February 6, 2019, 7:57pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/8 "2019-02-06T19:57:33Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![airstofather](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/airstofather/32/49623_2.png) [@airstofather](https://discuss.elastic.co/u/airstofather)\
**Post date:** [February 6, 2019, 8:16pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/9 "2019-02-06T20:16:24Z")

</div>

`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 | }
```

---

<div class="post-metadata">

**Author:** ![stephenbelanger](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/stephenbelanger/32/34880_2.png) [@stephenbelanger](https://discuss.elastic.co/u/stephenbelanger)\
**Post date:** [February 6, 2019, 8:21pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/10 "2019-02-06T20:21:42Z")

</div>

Sorry, I meant logs from the agent. 😅

---

<div class="post-metadata">

**Author:** ![airstofather](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/airstofather/32/49623_2.png) [@airstofather](https://discuss.elastic.co/u/airstofather)\
**Post date:** [February 6, 2019, 8:24pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/11 "2019-02-06T20:24:56Z")

</div>

@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 }
```

---

<div class="post-metadata">

**Author:** ![stephenbelanger](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/stephenbelanger/32/34880_2.png) [@stephenbelanger](https://discuss.elastic.co/u/stephenbelanger)\
**Post date:** [February 6, 2019, 8:33pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/12 "2019-02-06T20:33:34Z")

</div>

It looks like the `pg` module is never even loaded. 🤔

---

<div class="post-metadata">

**Author:** ![airstofather](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/airstofather/32/49623_2.png) [@airstofather](https://discuss.elastic.co/u/airstofather)\
**Post date:** [February 6, 2019, 8:57pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/13 "2019-02-06T20:57:57Z")

</div>

@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](https://us1.discourse-cdn.com/elastic/original/3X/0/1/01a5a10b57cb15120710e1f2852bd54e0f32e96b.png)

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](https://us1.discourse-cdn.com/elastic/original/3X/7/4/74c36e99763c26a7b34682ad0ccaeedfad083313.png)

---

<div class="post-metadata">

**Author:** ![stephenbelanger](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/stephenbelanger/32/34880_2.png) [@stephenbelanger](https://discuss.elastic.co/u/stephenbelanger)\
**Post date:** [February 6, 2019, 9:01pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/14 "2019-02-06T21:01:49Z")

</div>

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](https://www.elastic.co/guide/en/apm/agent/nodejs/current/custom-spans.html)

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

---

<div class="post-metadata">

**Author:** ![airstofather](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/airstofather/32/49623_2.png) [@airstofather](https://discuss.elastic.co/u/airstofather)\
**Post date:** [February 6, 2019, 9:34pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/15 "2019-02-06T21:34:33Z")

</div>

Excellent, thank you.

---

<div class="post-metadata">

**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\
**Post date:** [February 27, 2019, 5:34pm UTC](https://discuss.elastic.co/t/apm-transactions-missing-sql-statements/167164/16 "2019-02-27T17:34:35Z")

</div>

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