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

Aviad_Hadida · October 29, 2019, 6:57pm

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:

Started elastic apm without special config on index(on start before all). NOTE: We are using HapiJS
Downgraded mongoose version to 5.6.13(The prev version to 5.7.0 that is not supported)
Run simple transaction - Able to see only redis span with no mongoose span at all
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?

stephenbelanger · October 30, 2019, 6:59pm

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.

Aviad_Hadida · October 30, 2019, 9:04pm

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

stephenbelanger · October 30, 2019, 10:35pm

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.

Aviad_Hadida · October 31, 2019, 7:08am

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

Aviad_Hadida · November 14, 2019, 9:59am

@stephenbelanger Any news?

axw · November 14, 2019, 11:07am

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

Aviad_Hadida · November 16, 2019, 8:07pm

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

system · December 7, 2019, 4:07pm

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