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

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?

Can you try setting the 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.

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

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. :thinking:

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

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

@stephenbelanger Any news?

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

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