APM Not Correlating Trace

cuxoni · March 18, 2019, 11:42am

Kibana version: 6.6.2

Elasticsearch version:6.6.2

APM Server version:6.6.2

APM Agent language and version:6.6.2

Browser version: Curl request?

Original install method (e.g. download page, yum, deb, from source, etc.) and version: docker images

Fresh install or upgraded from other version? fresh

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):
The basic node / express script I wrote should follow this path
curl -> service_one -> service_two
The request appear as separate entities in the APM area of kibana. After reading the documentation I was expecting that the calls would be correlated as a single trace.

I have tried to use as basic config as possible but cannot seem to get it to match up/
Steps to reproduce:
1.Run default docker images in elaticsearch, apm and kibana
2. Run 'npm start 8000' in one window
3. Run 'npm start 8001 in another window
4. Run 'curl http://localhost:8000/one' in a third window

Errors in browser console (if relevant):
NA
Provide logs and/or server output (if relevant):
SERVICE ONE OUTPUT

adding hook to Node.js module loader
shimming http@10.13.0 module
shimming http.Server.prototype.emit function
shimming http.request function
shimming http.ServerResponse.prototype.writeHead function
shimming finalhandler@1.1.1 module
shimming express@4.16.4 module
shimming express.Router.use function
shimming express.static function
copying property mime from express.static
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
8000
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: 'fd38b472359048e2',
  parent: undefined,
  trace: 'c2d20168cff87ef22217a1931eeb6579',
  name: null,
  type: null }
200
setting transaction result { trans: 'fd38b472359048e2',
  parent: undefined,
  trace: 'c2d20168cff87ef22217a1931eeb6579',
  result: 'HTTP 2xx' }
setting default transaction name: GET /one { trans: 'fd38b472359048e2',
  parent: undefined,
  trace: 'c2d20168cff87ef22217a1931eeb6579' }
sending transaction { trans: 'fd38b472359048e2',
  trace: 'c2d20168cff87ef22217a1931eeb6579' }
ended transaction { trans: 'fd38b472359048e2',
  parent: undefined,
  trace: 'c2d20168cff87ef22217a1931eeb6579',
  type: 'request',
  result: 'HTTP 2xx',
  name: 'GET /one' }

SERVICE TWO OUTPUT

$ npm start 8001

> tmp@1.0.0 start C:\tmp
> node server.js "8001"

adding hook to Node.js module loader
shimming http@10.13.0 module
shimming http.Server.prototype.emit function
shimming http.request function
shimming http.ServerResponse.prototype.writeHead function
shimming finalhandler@1.1.1 module
shimming express@4.16.4 module
shimming express.Router.use function
shimming express.static function
copying property mime from express.static
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
8001
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: '064933f61b6dc2bb',
  parent: undefined,
  trace: 'da04d720eb64993fdea244657eaf612b',
  name: null,
  type: null }
setting transaction result { trans: '064933f61b6dc2bb',
  parent: undefined,
  trace: 'da04d720eb64993fdea244657eaf612b',
  result: 'HTTP 2xx' }
setting default transaction name: GET /two { trans: '064933f61b6dc2bb',
  parent: undefined,
  trace: 'da04d720eb64993fdea244657eaf612b' }
sending transaction { trans: '064933f61b6dc2bb',
  trace: 'da04d720eb64993fdea244657eaf612b' }
ended transaction { trans: '064933f61b6dc2bb',
  parent: undefined,
  trace: 'da04d720eb64993fdea244657eaf612b',
  type: 'request',
  result: 'HTTP 2xx',
  name: 'GET /two' }

cuxoni · March 18, 2019, 11:43am

my node script...

var apm = require('elastic-apm-node').start({
    serviceName: 'xxx',
  
    filterHttpHeaders: false,
    captureBody: 'all',
    logLevel: 'debug',
    serverUrl: 'http://dockerhost:8200/',
    payloadLogFile: '.\log.txt',
    distributedTracingOrigins: ['*']
  })

const http = require('http');
const express        = require('express');
const app            = express();
const port = process.argv.slice(2)[0];

app.get('/one', (req, res) => {
  http.get('http://localhost:8001/two', (result) => {
    console.log(result.statusCode);
    res.send('One')
  });
});

app.get('/two', (req, res) => {
  res.send('Two')
});

app.listen(port, () => {
    console.log(port);
});

wa7son · March 18, 2019, 2:09pm

The agents use a different version scheme than the rest of the Elastic Stack. The current latest version of the Node.js agent is v2.6.0. Is that the one you're using?

cuxoni · March 18, 2019, 2:24pm

Thanks for the response. My mistake, it's using the latest version, 2.6.0

wa7son · March 18, 2019, 8:11pm

Hm yeah it should work with your setup. Thanks for providing the detailed logs and example code btw - that's super helpful

I can see in the logs that the agent is correctly attaching it self to the http.request
function on service one. So any http request made from that service to any other service should be picked up. And according to the logs it's like it's not performing the request at all.

I'll just try to see if I can reproduce it and let you know what happens...

wa7son · March 27, 2019, 5:47pm

I found the culprit and opened a PR to fix it: https://github.com/elastic/apm-agent-nodejs/pull/954

Thanks for making us aware of this issue. I'll make sure the fix gets released ASAP.

wa7son · March 28, 2019, 10:12pm

The fix have just been released in version 2.7.1.

Thanks again for letting us know about this issue

cuxoni · March 29, 2019, 6:47am

That's excellent. Thanks for your help, I'll give it a try.

cuxoni · April 1, 2019, 11:19am

I gave this a try and still seem to be having problems, though maybe this is something else wrong in my setup somewhere as the traces seem to now correlate in the console output. However, when I look in Kibana, the trace doesn't show the call to /two, only to /one.

/one output:

$ npm start 8000

> tmp2@1.0.0 start C:\tmp2
> node server.js "8000"

adding hook to Node.js module loader
shimming http@10.13.0 module
shimming http.Server.prototype.emit function
shimming http.request function
shimming http.get function
shimming http.ServerResponse.prototype.writeHead function
shimming finalhandler@1.1.1 module
shimming express@4.16.4 module
shimming express.Router.use function
shimming express.static function
copying property mime from express.static
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
8000
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: '46699f4878f9e8b9',
  parent: undefined,
  trace: 'bcb46b9ece0675786ce155af9ee1a3ad',
  name: null,
  type: null }
start span { span: 'ba4db289d2d7ece4',
  parent: '46699f4878f9e8b9',
  trace: 'bcb46b9ece0675786ce155af9ee1a3ad',
  name: null,
  type: 'ext.http.http' }
intercepted call to http.get { id: '46699f4878f9e8b9' }
request details: { protocol: 'http:',
  host: 'localhost:8001',
  id: '46699f4878f9e8b9' }
200
setting transaction result { trans: '46699f4878f9e8b9',
  parent: undefined,
  trace: 'bcb46b9ece0675786ce155af9ee1a3ad',
  result: 'HTTP 2xx' }
intercepted http.ClientRequest response event { id: '46699f4878f9e8b9' }
setting default transaction name: GET /one { trans: '46699f4878f9e8b9',
  parent: undefined,
  trace: 'bcb46b9ece0675786ce155af9ee1a3ad' }
sending transaction { trans: '46699f4878f9e8b9',
  trace: 'bcb46b9ece0675786ce155af9ee1a3ad' }
ended transaction { trans: '46699f4878f9e8b9',
  parent: undefined,
  trace: 'bcb46b9ece0675786ce155af9ee1a3ad',
  type: 'request',
  result: 'HTTP 2xx',
  name: 'GET /one' }

/two output:

$ npm start 8001

> tmp2@1.0.0 start C:\tmp2
> node server.js "8001"

adding hook to Node.js module loader
shimming http@10.13.0 module
shimming http.Server.prototype.emit function
shimming http.request function
shimming http.get function
shimming http.ServerResponse.prototype.writeHead function
shimming finalhandler@1.1.1 module
shimming express@4.16.4 module
shimming express.Router.use function
shimming express.static function
copying property mime from express.static
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
shimming express.Router.Layer.handle function
8001
no active transaction found - cannot build new span
intercepted call to http.request { id: null }
intercepted request event call to http.Server.prototype.emit
continue trace { trans: '0c532d76af5c7a40',
  parent: 'ba4db289d2d7ece4',
  trace: 'bcb46b9ece0675786ce155af9ee1a3ad',
  name: null,
  type: null }
setting transaction result { trans: '0c532d76af5c7a40',
  parent: 'ba4db289d2d7ece4',
  trace: 'bcb46b9ece0675786ce155af9ee1a3ad',
  result: 'HTTP 2xx' }
setting default transaction name: GET /two { trans: '0c532d76af5c7a40',
  parent: 'ba4db289d2d7ece4',
  trace: 'bcb46b9ece0675786ce155af9ee1a3ad' }
sending transaction { trans: '0c532d76af5c7a40',
  trace: 'bcb46b9ece0675786ce155af9ee1a3ad' }
ended transaction { trans: '0c532d76af5c7a40',
  parent: 'ba4db289d2d7ece4',
  trace: 'bcb46b9ece0675786ce155af9ee1a3ad',
  type: 'request',
  result: 'HTTP 2xx',
  name: 'GET /two' }

wa7son · April 1, 2019, 7:50pm

You are not consuming the response in the test app you posted above. You need to either add a data listener or call result.resume(), eg:

  http.get('http://localhost:8001/two', (result) => {
    console.log(result.statusCode);
    result.resume();
    res.send('One')
  });

When you add a response listener to an outgoing request, you must also consume the response as mentioned in the Node.js docs:

[...] If a 'response' event handler is added, then the data from the response object must be consumed, either by calling response.read() whenever there is a 'readable' event, or by adding a 'data' handler, or by calling the .resume() method. Until the data is consumed, the 'end' event will not fire. Also, until the data is read it will consume memory that can eventually lead to a 'process out of memory' error.

As long as the response has not been fully consumed, the Node.js agent will not end the outgoing span and therefore not send it to the APM Server either. I'm looking into if we can somehow end it when the request ends in case the response isn't consumed as that will circumvent this gotcha. But in any case, you should consume the response to avoid memory leaks.

I think that will solve this issue.

cuxoni · April 2, 2019, 7:50am

I've tried that and everything works now. Thanks for your help. I'll try this out in our actual microservices architecture now and let you know if I have any problems.

system · April 23, 2019, 3:50am

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