Elasticsearch, apm with node.js, kibana and docker - No services found


#1

I am trying to monitor my express API with apm-agent-nodejs (version 1.12.0)

Everything seems to works fine (no errors) but going to http://localhost:5601/app/apm show No services were found, I don't have any search filter and the date range is Last 24 hours.

If I click on the Setup instructions then click on Check apm server status button I have : You have correctly setup APM-Server and Check agent status button return Data successfully received from one or more agents but I can't figure out how to have data about the HTTP calls made to the API.

My docker-compose.yml :

version: "3.3"
services:

  api:
    build: .
    env_file:
      - .env
    volumes:
      - .:/app
      - /app/node_modules
    ports:
      - "9000:9000"
    command: sh -c "mkdir -p dist && touch ./dist/app.js && yarn run start"

  transpiler:
    build: .
    volumes:
      - .:/app
      - /app/node_modules
    command: yarn run transpile -w

  mongo:
    image: mongo:4.0
    ports:
      - "27017"
    command: mongod
    volumes:
      - ./data:/data/db

  elasticsearch:
    image: docker.elastic.co/elasticsearch/elasticsearch:6.4.1
    volumes:
      - ./esdata:/usr/share/elasticsearch/data
    environment:
      - bootstrap.memory_lock=true
      - "ES_JAVA_OPTS=-Xms512m -Xmx512m"
      - discovery.type=single-node
    ports:
      - "9300:9300"
      - "9200:9200"

  kibana:
    image: docker.elastic.co/kibana/kibana:6.4.1
    ports:
      - "5601:5601"

  apm-server:
    image: docker.elastic.co/apm/apm-server:6.4.1
    ports:
      - 8200:8200
    volumes:
      - ./apm-server.yml:/usr/share/apm-server/apm-server.yml

volumes:
  esdata:

The ./apm-server.yml file :

apm-server:
  host: "0.0.0.0:8200"
output.elasticsearch:
  hosts: ["elasticsearch:9200"]
setup.kibana:
  host: "kibana:5601"
logging.level: debug

The entrypoint file of the app with the agent :

import * as apm from 'elastic-apm-node/start'
import * as express from 'express'
import * as http from 'http'
import * as mongoose from 'mongoose'
import config from './config/environment'
import expressConfig from './config/express'
import routesConfig from './routes'

// Connect to database
(mongoose.Promise as any) = global.Promise
mongoose.connect(config.mongo.uri, { useNewUrlParser: true })

// Setup server
const app: express.Application = express()
const server: http.Server = http.createServer(app)

expressConfig(app)
routesConfig(app)

server.listen(config.port, config.ip, () => {
    console.log('Express server listening on %d, in %s mode', config.port, app.get('env'))
})

export default app 

If I add :

app.use(apm.middleware.connect())

after routesConfig(app)

Then I have the following log :

intercepted request event call to http.Server.prototype.emit
setting transaction result { id: '34b65a8f-cc50-4e48-aaed-46406ab70f22',
  result: 'success' }
start transaction { id: '34b65a8f-cc50-4e48-aaed-46406ab70f22',
  name: undefined,
  type: undefined }
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 { id: '34b65a8f-cc50-4e48-aaed-46406ab70f22',
  result: 'HTTP 3xx' }
setting default transaction name: GET /api/v1/ping { id: '34b65a8f-cc50-4e48-aaed-46406ab70f22' }
adding transaction to queue { id: '34b65a8f-cc50-4e48-aaed-46406ab70f22' }
setting timer to flush queue: 5051ms
ended transaction { id: '34b65a8f-cc50-4e48-aaed-46406ab70f22',
  type: 'request',
  result: 'HTTP 3xx',
  name: 'GET /api/v1/ping' }
flushing queue
sending transactions payload
transaction already ended - cannot build new span { id: '34b65a8f-cc50-4e48-aaed-46406ab70f22' }
intercepted call to http.request { id: null }
Error: connect EINVAL 0.0.32.8:80 - Local (0.0.0.0:0)
    at internalConnect (net.js:884:16)
    at defaultTriggerAsyncIdScope (internal/async_hooks.js:294:19)
    at GetAddrInfoReqWrap.emitLookup (net.js:1031:9)
    at GetAddrInfoReqWrap.elasticAPMCallbackWrapper [as callback] (/app/node_modules/elastic-apm-node/lib/instrumentation/index.js:189:27)
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:62:10)

The elastic-apm-node.js file (used to configure the agent) :

module.exports = {
    // Overwrite service name from package.json
    // Allowed characters: a-z, A-Z, 0-9, -, _, and space
    serviceName: 'test',
    // Use if APM Server requires a token
    secretToken: '',
    // Set custom APM Server URL (default: http://localhost:8200)
    serverUrl: '0.0.0.0:8200',
    logLevel: 'debug'
}

After running docker-compose up I do a few requests to http://localhost:9000/api/v1/ping/ basic GET url which return :

{
    "ping": "pong"
} 

with the HTTP code 200. But after waiting few minutes there is still no data.

In the kibana dev console

GET apm*/_search
{
  "query": {
    "term": {
      "processor.name": "transaction"
    }
  }
}

produces

{
  "took": 1,
  "timed_out": false,
  "_shards": {
    "total": 3,
    "successful": 3,
    "skipped": 0,
    "failed": 0
  },
  "hits": {
    "total": 0,
    "max_score": null,
    "hits": []
  }
}

And curl localhost:8200 outputs 404 page not found


#2

My package.json is :

{
    "name": "node api",
    "version": "0.0.0",
    "description": "",
    "main": "app.js",
    "apidoc": {
        "name": "Apidoc",
        "title": "Apidoc",
        "forceLanguage": "en",
        "url": "http://localhost:9000/api/v1",
        "sampleUrl": "http://localhost:9000/api/v1"
    },
    "nyc": {
        "exclude": [
            "**/*.spec.js",
            "*/config/*"
        ]
    },
    "dependencies": {
        "bcrypt": "^3.0.1",
        "body-parser": "^1.15.2",
        "compression": "^1.6.2",
        "cors": "^2.8.4",
        "elastic-apm-node": "^1.12.0",
        "elasticsearch": "^15.1.1",
        "email-validator": "^2.0.3",
        "express": "^4.14.0",
        "helmet": "^3.12.0",
        "image-size": "^0.6.2",
        "jsonwebtoken": "^8.2.1",
        "lodash": "^4.17.11",
        "method-override": "^3.0.0",
        "moment": "^2.22.1",
        "mongoose": "^5.2.15",
        "mongoose-beautiful-unique-validation": "^7.1.1",
        "mongoose-validation-error-transform": "0.0.2",
        "morgan": "^1.9.0",
        "multer": "^1.3.0",
        "passport-jwt": "^4.0.0",
        "socket.io": "^2.1.0"
    },
    "devDependencies": {
        "@types/bcrypt": "^2.0.0",
        "@types/body-parser": "^1.17.0",
        "@types/chai": "^4.1.3",
        "@types/compression": "^0.0.36",
        "@types/cors": "^2.8.4",
        "@types/elastic-apm-node": "^1.0.0",
        "@types/elasticsearch": "^5.0.26",
        "@types/express": "^4.11.0",
        "@types/helmet": "^0.0.42",
        "@types/image-size": "^0.0.29",
        "@types/jsonwebtoken": "^7.2.7",
        "@types/lodash": "^4.14.108",
        "@types/method-override": "^0.0.31",
        "@types/mocha": "^5.2.0",
        "@types/mongodb": "^3.1.7",
        "@types/mongoose": "^5.2.15",
        "@types/morgan": "^1.7.35",
        "@types/multer": "^1.3.6",
        "@types/node": "~10.10.0",
        "@types/passport-jwt": "^3.0.1",
        "@types/socket.io": "^1.4.33",
        "@types/supertest": "^2.0.4",
        "apidoc": "^0.17.6",
        "chai": "^4.1.2",
        "debug": "^4.0.1",
        "mocha": "^5.1.1",
        "nyc": "^13.0.1",
        "supertest": "^3.0.0",
        "tslint": "^5.10.0",
        "typescript": "^3.0.3"
    },
    "scripts": {
        "start": "nodemon --delay 500ms ./dist/app.js",
        "lint": "./node_modules/tslint/bin/tslint -p .",
        "transpile": "./node_modules/typescript/bin/tsc",
        "test": "./node_modules/mocha/bin/mocha --recursive --bail --colors --exit ./dist",
        "doc": "apidoc -e \"(node_modules|doc)\" -i api -o doc"
    }
}

#3

Turns out the correct configuration was :

elastic-apm-node.js

module.exports = {
    // Overwrite service name from package.json
    // Allowed characters: a-z, A-Z, 0-9, -, _, and space
    serviceName: 'node',
    // Use if APM Server requires a token
    secretToken: '',
    // Set custom APM Server URL (default: http://localhost:8200)
    serverUrl: 'http://apm-server:8200',
    logLevel: 'info',
    asyncHooks: false
}

apm-server.yml

apm-server:
  host: "apm-server:8200"
output.elasticsearch:
  hosts: ["elasticsearch:9200"]
setup.kibana:
  host: "kibana:5601"
logging.level: info

app.ts

import * as apm from 'elastic-apm-node/start' // tslint:disable-line
import * as express from 'express'
import * as http from 'http'
import * as mongoose from 'mongoose'
import config from './config/environment'
import expressConfig from './config/express'
import routesConfig from './routes'

// Connect to database
(mongoose.Promise as any) = global.Promise
mongoose.connect(config.mongo.uri, { useNewUrlParser: true })

// Setup server
const app: express.Application = express()
const server: http.Server = http.createServer(app)

expressConfig(app)
app.use(apm.middleware.connect())
routesConfig(app)

// Start server
server.listen(config.port, config.ip, () => {
console.log('Express server listening on %d, in %s mode', config.port, app.get('env')) // tslint:disable-line
})

// Expose app
export default app

I was in part mislead by Particularly, if you are using Docker, ensure to bind to the right interface (for example, set apm-server.host = 0.0.0.0:8200 to match any IP) and set the SERVER_URL setting in the agent accordingly and I forgot to use the app.use(apm.middleware.connect()) from https://www.elastic.co/guide/en/apm/server/master/common-problems.html

By the way having "elastic-apm-node": "^1.12.0", and "@types/elastic-apm-node": "^1.0.0", gives the following typescript error :
[ts] Property 'middleware' does not exist on type 'Agent'.


(Thomas Watson) #4

Hi Faros

I'm glad you found a solution. I'll see if there's anything we can do to improve the Docker instructions.

Just a few follow up questions:

The Connect middleware provided by the agent doesn't influence the agents ability to send data instrumentation data to the APM Server. It's only used for collecting errors. Are you sure that does any difference?

Actually, since you're using Express, you shouldn't add the Connect middleware manually. The Node.js agent will automatically detect that you're using Express and add the middleware for you. So you should just remove the app.use(apm.middleware.connect()) line.

Finally, I'm curious why you configured the agent with asyncHooks: false?

Cheers,
Thomas


#5

Hello wa7son,

Just removed the elasticsearch volume and then did the usual docker-compose down && docker-compose up with app.use(apm.middleware.connect()) commented out.
The kibana apm shows

No services were found

Try another time range or reset the search filter.

If I uncomment app.use(apm.middleware.connect()) then all HTTP calls are correctly logged, so using the connect middleware does make a difference for me. (Wouldn't have thought about it if I didn't saw this github issue https://github.com/elastic/apm-agent-nodejs/issues/84 so thanks a lot ^^)
I would be glad to share more of my config if that could help tho.

About the asyncHooks: false; I was just trying a lot of stuff out, and forgot to remove it before copying my code.


(Thomas Watson) #6

Interesting - that's very odd. If you don't mind, it would help me understand what's going wrong if you could enable debug mode and have your Express app process a few HTTP requests for about 20 seconds and then send us the resulting log (be sure to scrub any potentially sensitive or personally identifiable information from the logs before sending).


#7

With app.use(apm.middleware.connect()) :

intercepted request event call to http.Server.prototype.emit
setting transaction result { id: '16c39299-c277-4b60-b994-7369b056e62c',
  result: 'success' }
start transaction { id: '16c39299-c277-4b60-b994-7369b056e62c',
  name: undefined,
  type: undefined }
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
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 { id: '16c39299-c277-4b60-b994-7369b056e62c',
  result: 'HTTP 3xx' }
setting default transaction name: GET /api/v1/ping { id: '16c39299-c277-4b60-b994-7369b056e62c' }
adding transaction to queue { id: '16c39299-c277-4b60-b994-7369b056e62c' }
setting timer to flush queue: 4965ms
ended transaction { id: '16c39299-c277-4b60-b994-7369b056e62c',
  type: 'request',
  result: 'HTTP 3xx',
  name: 'GET /api/v1/ping' }
::ffff:172.21.0.1 - - [03/Oct/2018:08:08:52 +0000] "GET /api/v1/ping HTTP/1.1" 304 - "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/69.0.3497.100 Safari/537.36"
flushing queue
sending transactions payload
transaction already ended - cannot build new span { id: '16c39299-c277-4b60-b994-7369b056e62c' }
intercepted call to http.request { id: null }
apm-server_1     | 2018-10-03T08:08:57.929Z     INFO    [request]       beater/handlers.go:282  handled request {"request_id": "03599216-4a92-4aff-bc45-a8b39615e67a", "method": "POST", "URL": "/v1/transactions", "content_length": 1061, "remote_address": "172.21.0.8", "user-agent": "elastic-apm-node/1.12.0 elastic-apm-http-client/5.2.1", "response_code": 202}
transactions payload successfully sent

Without app.use(apm.middleware.connect()) there is just no output


(Thomas Watson) #8

The plot thickens :thinking: Even if the agent is disabled or doesn't correctly discover the incoming HTTP requests, it should still output debug info.

I assume you use Babel? Do you have some sort of tree shaking transpilation step that removes imports that it thinks are not in use? I.e. if it sees that you're not using apm for anything maybe it's simply removing the import statement?

Can you try to run node with the -r elastic-apm-node/start argument instead of importing it inside you app? As long as you don't need the apm variable, that should be equivalent to importing it at the very top.


#9

I am using typescript and compile with ./node_modules/typescript/bin/tsc.
Good call about

I.e. if it sees that you're not using apm for anything maybe it's simply removing the import statement

This is what happens (checked in my app.js file).

nodemon -r elastic-apm-node/start --delay 500ms ./dist/app.js works just fine, tyvm for your time


(Thomas Watson) #10

Thanks for investigating this. I'll make sure to update our documentation to mention this gotcha.


(system) #11

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