APM is not getting spans for https requests

Elastic Observability APM
1

Hello,

I'm ind of new with Elastic APM, Starting working with it this week. I'm working with elastic-apm-node package, nodejs and express.

Package-version:"elastic-apm-node": "^1.12.0"

Code:
const apm = require('elastic-apm-node');
apm.start({
serverUrl: 'http://apm_server_hostname:apm_server_port',
logLevel: 'debug',
});

The main issue I'm having is that APM is not being able to create the span in the current transaction.

APM Log example:
adding hook to Node.js module loader
shimming express@4.16.3 module
shimming express.Router.process_params function
shimming express.Router.use function
shimming express.static function
copying property mime from express.static
shimming http@9.11.2 module
shimming http.Server.prototype.emit function
shimming http.request function
shimming http.ServerResponse.prototype.writeHead function
shimming https@9.11.2 module
shimming https.Server.prototype.emit function
shimming https.request function
shimming layer.handle_request function (layer: router)
skip shimming layer.handle_request (layer: jsonParser, path: /)
skip shimming layer.handle_request (layer: , path: /)
skip shimming layer.handle_request (layer: router, path: /)
skip shimming layer.handle_request (layer: errorMiddleware, path: /)
intercepted request event call to http.Server.prototype.emit
setting transaction result { id: 'a60cf357-64fb-412e-a4b3-fbadb9516525',
result: 'success' }
start transaction { id: 'a60cf357-64fb-412e-a4b3-fbadb9516525',
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
no active transaction found - cannot build new span
intercepted call to https.request { id: null }
[2018-09-11 13:13:56.482] [INFO] Service call to settings profiler // call to another service
type: http_service_profiler
service: endpoint
durationMs: 8025
duration: 8025ms
setting transaction result { id: 'a60cf357-64fb-412e-a4b3-fbadb9516525',
result: 'HTTP 2xx' }
[2018-09-11 13:13:56.492] [INFO] GET /endpoint/general 200 8035ms
res:
statusCode: 200
req:
url: /endpoint/general
headers:
host: localhost:3000
user-agent: curl/7.47.0
accept: /
method: GET
httpVersion: 1.1
originalUrl: /endpoint/general
query: {}
responseTime: 8035
message_id: 89ccadb0-b5c4-11e8-9594-5f11febf4442
setting default transaction name: GET /endpoint/general { id: 'a60cf357-64fb-412e-a4b3-fbadb9516525' }
adding transaction to queue { id: 'a60cf357-64fb-412e-a4b3-fbadb9516525' }
setting timer to flush queue: 5208ms
ended transaction { id: 'a60cf357-64fb-412e-a4b3-fbadb9516525',
type: 'request',
result: 'HTTP 2xx',
name: 'GET /endpoint/general' }
flushing queue
sending transactions payload
no active transaction found - cannot build new span
intercepted call to http.request { id: null }

I'll be glad if somebody already implemented this with node and solved this issue.

Thanks
Gerardo

2

What modules are you using within that route? In particular, I want to know of anything that does async things.

It looks to me like the context is being lost, which could happen if something uses async code which we haven't specifically instrumented. The most common cause is callback queues like connection pooling.

3

May superagent be causing this issue?
Here's some probably related piece: https://github.com/visionmedia/superagent/blob/13ff9b3a1bec34020c7d5dfcf88bbb26d67b9ee1/lib/node/index.js#L150
I mention this cause I'm working with Gerardo on the same project, and know for a fact that library is being used, plus ran some tests that indicate the problem might be there...

4

I don't see any immediate issues, in a quick glance through the code, by I can try and find some time for some in-depth testing tomorrow. Can you share your package.json so I can see what specific versions of modules you are using?

5

Stephen, Finally found the issue, we are overriding the http context to add some configuration :frowning: !!!! Thanks to much for your help! I really appreciate it!

6

Oh, good. I'm glad you got it figured out. :+1:

Is there anything you think we could do on our end to guard against something like that breaking the context?

7

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