# Mongoose spans are missing(When i add custom spans i can see also the mongo spans)

**URL:** <https://discuss.elastic.co/t/mongoose-spans-are-missing-when-i-add-custom-spans-i-can-see-also-the-mongo-spans/205744>\
**Category:** APM\
**Tags:** nodejs\
**Created:** [October 29, 2019, 6:57pm UTC](https://discuss.elastic.co/t/mongoose-spans-are-missing-when-i-add-custom-spans-i-can-see-also-the-mongo-spans/205744 "2019-10-29T18:57:00Z")\
**Posts on this page:** 9\
**Page:** 1

<div class="post-metadata">

**Author:** ![Aviad\_Hadida](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/aviad_hadida/32/46821_2.png) [@Aviad\_Hadida](https://discuss.elastic.co/u/Aviad_Hadida)\
**Post date:** [October 29, 2019, 6:57pm UTC](https://discuss.elastic.co/t/mongoose-spans-are-missing-when-i-add-custom-spans-i-can-see-also-the-mongo-spans/205744/1 "2019-10-29T18:57:01Z")

</div>

**Kibana version** :  
7.4.0 On Elastic cloud

**Elasticsearch version** :  
7.4.0 On Elastic cloud

**APM Server version** :  
7.4.0 On Elastic cloud

**APM Agent language and version** :  
Node.js - Elatic apm node 3.1.0

**Description of the problem including expected versus actual behavior. Please include screenshots (if relevant)**:

**Steps to reproduce** :

1. Started elastic apm without special config on index(on start before all). NOTE: We are using HapiJS
2. Downgraded mongoose version to 5.6.13(The prev version to 5.7.0 that is not supported)
3. Run simple transaction - Able to see only redis span with no mongoose span at all
4. If i use custom spans.. I can see insert from the mongodb.. Very weird

Dependencies:

> ```
> "agenda": "^2.1.0",
> "amqplib": "^0.5.5",
> "aws-sdk": "^2.537.0",
> "axios": "0.16.2",
> "bcryptjs": "^2.4.3",
> "big.js": "^5.2.2",
> "bitgo": "^4.49.2",
> "blipp": "^3.1.3",
> "boom": "^5.2.0",
> "config": "^2.0.2",
> "elastic-apm-node": "^3.1.0",
> "fast-tcp": "3.3.2",
> "geoip-lite": "^1.3.8",
> "glob": "7.1.2",
> "hapi": "^17.8.5",
> "hapi-auth-jwt2": "^8.6.2",
> "hapi-swagger": "^9.4.2",
> "http-status": "1.0.1",
> "inert": "^5.1.3",
> "ioredis": "^4.14.1",
> "joi": "14.3.1",
> "json2csv": "^4.5.3",
> "jsonwebtoken": "^8.5.1",
> "lodash": "4.17.4",
> "mailgun-js": "^0.22.0",
> "moment": "^2.24.0",
> "moment-timezone": "^0.5.26",
> "mongoose": "^5.6.13",
> "mongoose-bcrypt": "1.4.2",
> "mongoose-lean-virtuals": "^0.4.4",
> "qrcode": "^1.4.2",
> "redis": "^2.8.0",
> "socket.io": "2.1.1",
> "socket.io-redis": "5.2.0",
> "speakeasy": "^2.0.0",
> "string-template": "^1.0.0",
> "useragent": "^2.3.0",
> "uuid": "3.3.2",
> "vision": "^5.4.4",
> "winston": "^3.2.1",
> "winston-daily-rotate-file": "^3.10.0"
> 
> ```

I tried everything.. Tried to find maybe conflict in dependencies but with no success.. Any way to figure oute what this is not showing at all?

---

<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:** [October 30, 2019, 6:59pm UTC](https://discuss.elastic.co/t/mongoose-spans-are-missing-when-i-add-custom-spans-i-can-see-also-the-mongo-spans/205744/2 "2019-10-30T18:59:03Z")

</div>

Can you try setting the [log level](https://www.elastic.co/guide/en/apm/agent/nodejs/current/configuration.html#log-level) to `debug` and sharing the output here? It would also help greatly if you could provide a simple example app which reproduces the issue.

---

<div class="post-metadata">

**Author:** ![Aviad\_Hadida](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/aviad_hadida/32/46821_2.png) [@Aviad\_Hadida](https://discuss.elastic.co/u/Aviad_Hadida)\
**Post date:** [October 30, 2019, 9:04pm UTC](https://discuss.elastic.co/t/mongoose-spans-are-missing-when-i-add-custom-spans-i-can-see-also-the-mongo-spans/205744/3 "2019-10-30T21:04:08Z")

</div>

Actaully i had built sample app as you asked.. But for some reason it works fine on this app.  
The example app package.json:

> **package.json**
>
> > {  
> > "name": "mongooseApm",  
> > "version": "1.0.0",  
> > "description": "",  
> > "main": "index.js",  
> > "scripts": {  
> > "test": "echo "Error: no test specified" && exit 1"  
> > },  
> > "keywords": ,  
> > "author": "",  
> > "license": "ISC",  
> > "dependencies": {  
> > "mongoose": "^5.6.13",  
> > "elastic-apm-node": "^3.1.0",  
> > "hapi": "^17.8.5"  
> > }  
> > }

> **index.js**
>
> ```
> 'use strict';
> 
> const secretToken = ''
> const serverUrl = ''
> const mongodbUri = ''
> 
> require('elastic-apm-node').start({
> secretToken,
> serverUrl
> });
> 
> const Hapi = require('hapi');
> const mongoose = require('mongoose');
> const { Schema } = mongoose;
> const schema = new Schema({
> testField: String
> })
> const TestModel = mongoose.model('TestModel', schema)
> 
> mongoose.set('useUnifiedTopology', true )
> mongoose.connect(mongodbUri, { useNewUrlParser: true})
> 
> const init = async () => {
> 
> const server = Hapi.server({
> port: 3000,
> host: 'localhost'
> });
> 
> server.route({
> method: 'GET',
> path: '/',
> handler: async (request, h) => {
> const test = new TestModel({testField: '1234'})
> await test.save()
> return 'Hello World!';
> }
> });
> 
> await server.start();
> console.log('Server running on %s', server.info.uri);
> };
> 
> mongoose.connection.on('connected', () => {
> console.log('connected')
> init()
> });
> 
> ```

Another thing that i did is to set debug as you asked.

> **Without custom span**
>
> 2019-10-30 22:33:06.236 debug [index.js]: no active transaction found - cannot build new span  
> 2019-10-30 22:33:06.237 debug [undefined]: intercepted call to %s.%s %o  
> 2019-10-30 22:33:11.110 debug [undefined]: intercepted request event call to %s.Server.prototype.emit for %s  
> 2019-10-30 22:33:11.110 debug [undefined]: %s trace %o  
> 2019-10-30 22:33:11.110 debug [undefined]: no original function %s to wrap  
> 2019-10-30 22:33:11.110 debug [undefined]: no original function %s to wrap  
> // start  
> 2019-10-30 22:33:11.113 debug [index.js]: received hapi onPreAuth event  
> 2019-10-30 22:33:11.113 debug [undefined]: setting default transaction name: %s %o  
> 2019-10-30 22:33:11.115 debug [index.js]: start span %o  
> 2019-10-30 22:33:11.117 debug [index.js]: intercepted call to ioredis.prototype.sendCommand %o  
> 2019-10-30 22:33:11.117 debug [index.js]: ended span %o  
> 2019-10-30 22:33:11.118 debug [index.js]: encoding span %o  
> 2019-10-30 22:33:11.150 debug [index.js]: sending span %o  
> 2019-10-30 22:33:11.170 debug [index.js]: start span %o  
> 2019-10-30 22:33:11.171 debug [index.js]: intercepted call to RedisClient.prototype.internal\_send\_command %o  
> 2019-10-30 22:33:11.174 debug [index.js]: start span %o  
> 2019-10-30 22:33:11.174 debug [index.js]: intercepted call to ws.prototype.send %o  
> 2019-10-30 22:33:11.177 debug [index.js]: ended span %o  
> 2019-10-30 22:33:11.177 debug [index.js]: encoding span %o  
> 2019-10-30 22:33:11.185 debug [index.js]: start span %o  
> 2019-10-30 22:33:11.186 debug [undefined]: intercepted call to %s.%s %o  
> 2019-10-30 22:33:11.187 debug [undefined]: ignore %s request to intake API %o  
> 2019-10-30 22:33:11.204 debug [index.js]: ended span %o  
> 2019-10-30 22:33:11.204 debug [index.js]: encoding span %o  
> 2019-10-30 22:33:11.211 debug [index.js]: start span %o  
> 2019-10-30 22:33:11.211 debug [index.js]: intercepted call to RedisClient.prototype.internal\_send\_command %o  
> 2019-10-30 22:33:11.212 debug [index.js]: start span %o  
> 2019-10-30 22:33:11.213 debug [index.js]: intercepted call to ws.prototype.send %o  
> 2019-10-30 22:33:11.215 debug [index.js]: received hapi onPreResponse event  
> // end  
> 2019-10-30 22:33:11.219 debug [index.js]: setting transaction result %o  
> 2019-10-30 22:33:11.221 debug [index.js]: ended span %o  
> 2019-10-30 22:33:11.221 debug [index.js]: encoding span %o  
> 2019-10-30 22:33:11.227 debug [index.js]: sending transaction %o  
> 2019-10-30 22:33:11.228 debug [index.js]: ended transaction %o  
> 2019-10-30 22:33:11.231 debug [index.js]: ended span %o  
> 2019-10-30 22:33:11.232 debug [index.js]: encoding span %o  
> 2019-10-30 22:33:11.247 debug [index.js]: sending span %o  
> 2019-10-30 22:33:11.247 debug [index.js]: sending span %o  
> 2019-10-30 22:33:11.252 debug [index.js]: sending span %o  
> 2019-10-30 22:33:11.253 debug [index.js]: sending span %o

I tried again with custom span but for some reason it is not showing.. I worked with that all day and it worked consistently as i described.. Suddenly something happened.

What is the reason that this shouldn't work for mongoose? It is on my index.js at the first line and i downgraded mongoose to use supported version

Thanks

---

<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:** [October 30, 2019, 10:35pm UTC](https://discuss.elastic.co/t/mongoose-spans-are-missing-when-i-add-custom-spans-i-can-see-also-the-mongo-spans/205744/4 "2019-10-30T22:35:02Z")

</div>

Are you using a custom logger? All the interpolation data is missing. That's what all the %s and %o bits are supposed to be. 🤔

---

<div class="post-metadata">

**Author:** ![Aviad\_Hadida](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/aviad_hadida/32/46821_2.png) [@Aviad\_Hadida](https://discuss.elastic.co/u/Aviad_Hadida)\
**Post date:** [October 31, 2019, 7:08am UTC](https://discuss.elastic.co/t/mongoose-spans-are-missing-when-i-add-custom-spans-i-can-see-also-the-mongo-spans/205744/5 "2019-10-31T07:08:25Z")

</div>

And i thought to myself how can someone understand something from this logs 🙂

> **Without custom span**
>
> intercepted call to mongodb-core.Server.prototype.command { id: null, ns: 'admin.$cmd' }  
> no active transaction found - cannot build new span  
> intercepted call to http.request { id: null }  
> intercepted call to mongodb-core.Server.prototype.command { id: null, ns: 'admin.$cmd' }  
> no active transaction found - cannot build new span  
> intercepted call to http.request { id: null }  
> intercepted request event call to http.Server.prototype.emit for /inx/api/1.0/order/addLimitOrder  
> start trace { trans: '71d6d9a61bb60a3a',  
> parent: undefined,  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'unnamed',  
> type: null,  
> subtype: null,  
> action: null }  
> no original function off to wrap  
> no original function off to wrap  
> received hapi onPreAuth event  
> setting default transaction name: POST /inx/api/1.0/order/addLimitOrder { trans: '71d6d9a61bb60a3a',  
> parent: undefined,  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec' }  
> start span { span: '4b9bb459e271f5b7',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'unnamed',  
> type: 'cache',  
> subtype: 'redis',  
> action: null }  
> intercepted call to ioredis.prototype.sendCommand { id: '71d6d9a61bb60a3a', command: 'evalsha' }  
> ended span { span: '4b9bb459e271f5b7',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'EVALSHA',  
> type: 'cache',  
> subtype: 'redis',  
> action: null }  
> encoding span { span: '4b9bb459e271f5b7',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'EVALSHA',  
> type: 'cache' }  
> sending span { span: '4b9bb459e271f5b7',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'EVALSHA',  
> type: 'cache' }  
> start span { span: 'dc08de43250a9539',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'unnamed',  
> type: 'cache',  
> subtype: 'redis',  
> action: null }  
> intercepted call to RedisClient.prototype.internal\_send\_command { id: '71d6d9a61bb60a3a', command: 'publish' }  
> start span { span: '1d4fff513d49ceb2',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'Send WebSocket Message',  
> type: 'websocket',  
> subtype: 'send',  
> action: null }  
> intercepted call to ws.prototype.send { id: '71d6d9a61bb60a3a' }  
> ended span { span: '1d4fff513d49ceb2',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'Send WebSocket Message',  
> type: 'websocket',  
> subtype: 'send',  
> action: null }  
> encoding span { span: '1d4fff513d49ceb2',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'Send WebSocket Message',  
> type: 'websocket' }  
> ended span { span: 'dc08de43250a9539',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'PUBLISH',  
> type: 'cache',  
> subtype: 'redis',  
> action: null }  
> encoding span { span: 'dc08de43250a9539',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'PUBLISH',  
> type: 'cache' }  
> start span { span: '8e8cad6a0f773d93',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'unnamed',  
> type: 'cache',  
> subtype: 'redis',  
> action: null }  
> intercepted call to RedisClient.prototype.internal\_send\_command { id: '71d6d9a61bb60a3a', command: 'publish' }  
> start span { span: '795b1581d1e0dfba',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'Send WebSocket Message',  
> type: 'websocket',  
> subtype: 'send',  
> action: null }  
> intercepted call to ws.prototype.send { id: '71d6d9a61bb60a3a' }  
> received hapi onPreResponse event  
> setting transaction result { trans: '71d6d9a61bb60a3a',  
> parent: undefined,  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> result: 'HTTP 2xx' }  
> ended span { span: '795b1581d1e0dfba',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'Send WebSocket Message',  
> type: 'websocket',  
> subtype: 'send',  
> action: null }  
> encoding span { span: '795b1581d1e0dfba',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'Send WebSocket Message',  
> type: 'websocket' }  
> sending transaction { trans: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec' }  
> ended transaction { trans: '71d6d9a61bb60a3a',  
> parent: undefined,  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> type: 'request',  
> result: 'HTTP 2xx',  
> name: 'POST /inx/api/1.0/order/addLimitOrder' }  
> ended span { span: '8e8cad6a0f773d93',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'PUBLISH',  
> type: 'cache',  
> subtype: 'redis',  
> action: null }  
> encoding span { span: '8e8cad6a0f773d93',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'PUBLISH',  
> type: 'cache' }  
> sending span { span: 'dc08de43250a9539',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'PUBLISH',  
> type: 'cache' }  
> sending span { span: '1d4fff513d49ceb2',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'Send WebSocket Message',  
> type: 'websocket' }  
> sending span { span: '8e8cad6a0f773d93',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'PUBLISH',  
> type: 'cache' }  
> sending span { span: '795b1581d1e0dfba',  
> parent: '71d6d9a61bb60a3a',  
> trace: '16c5dc8dccc86e67a0b05bfb803680ec',  
> name: 'Send WebSocket Message',  
> type: 'websocket' }

I can see increpeted call from mongod DB, but not on my route that i tested(I tried a few more routes.. Nothing work so this is not specific to 1 route

---

<div class="post-metadata">

**Author:** ![Aviad\_Hadida](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/aviad_hadida/32/46821_2.png) [@Aviad\_Hadida](https://discuss.elastic.co/u/Aviad_Hadida)\
**Post date:** [November 14, 2019, 9:59am UTC](https://discuss.elastic.co/t/mongoose-spans-are-missing-when-i-add-custom-spans-i-can-see-also-the-mongo-spans/205744/6 "2019-11-14T09:59:28Z")

</div>

@stephenbelanger Any news?

---

<div class="post-metadata">

**Author:** ![axw](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/axw/32/28197_2.png) [@axw](https://discuss.elastic.co/u/axw)\
**Post date:** [November 14, 2019, 11:07am UTC](https://discuss.elastic.co/t/mongoose-spans-are-missing-when-i-add-custom-spans-i-can-see-also-the-mongo-spans/205744/7 "2019-11-14T11:07:19Z")

</div>

@Aviad_Hadida sorry this got left hanging. Can you please also provide the logs for _with_ the custom span? It sounds a bit like context loss, and ending the custom span is recovering the context; but it would be helpful to see the differences in the logs to (when it works and when it doesn't) to confirm.

---

<div class="post-metadata">

**Author:** ![Aviad\_Hadida](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/aviad_hadida/32/46821_2.png) [@Aviad\_Hadida](https://discuss.elastic.co/u/Aviad_Hadida)\
**Post date:** [November 16, 2019, 8:07pm UTC](https://discuss.elastic.co/t/mongoose-spans-are-missing-when-i-add-custom-spans-i-can-see-also-the-mongo-spans/205744/8 "2019-11-16T20:07:44Z")

</div>

@axw Thanks for responding.. I have tried to make it happen again but with no success.  
Unfortunately i couldn't get the mongo instrumentation to work and i probably changed something in the project because this is not happening anymore(No instrumentation at all).

How can i get mongo instrumentation to work? Do you have a clue here?

---

<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:** [December 7, 2019, 4:07pm UTC](https://discuss.elastic.co/t/mongoose-spans-are-missing-when-i-add-custom-spans-i-can-see-also-the-mongo-spans/205744/9 "2019-12-07T16:07:52Z")

</div>

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