Can't get the NodeJS transactions in Kibana

Elastic Observability APM
1

If you are asking about a problem you are experiencing, please use the following template, as it will help us help you. If you have a different problem, please delete all of this text :slight_smile:

Kibana version: 7.6.0

Elasticsearch version: 7.6.0

APM Server version: 7.6.0

APM Agent language and version: NodeJS, 10.16.3

Browser version: Chrome v71

Original install method (e.g. download page, yum, deb, from source, etc.) and version: Download page (zip file)

Fresh install or upgraded from other version? Fresh Install

Is there anything special in your setup? For example, are you using the Logstash or Kafka outputs? Are you using a load balancer in front of the APM Servers? Have you changed index pattern, generated custom templates, changed agent configuration etc.
NONE

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):

Steps to reproduce:

  1. install npm elastic-apm-node (v3.5.0, was v3.4.0 but updated yesterday to see it fixes but not :-1: )
  2. Add elastic-apm-node to the nodejs app.js
  3. Restart NodeJS

Errors in browser console (if relevant): Don't see anything under Transactions, however I see the errors and Metrics

Provide logs and/or server output (if relevant):

APM Server transport error (400): Unexpected APM Server response       
APM Server accepted 0 events in the last request 
Error: error validating JSON document against schema: I[#] S[#] doesn't validate with "transaction#"  
  I[#] S[#/allOf/3] allOf failed  
     I[#/duration] S[#/allOf/3/properties/duration/type] expected number, but got null                                   
  Document: {"transaction":{"name":"GET unknown route","type":"request","result":"HTTP 2xx","id":"4d0193
2

Hi, and welcome to the forum :slight_smile:

From the APM Server error you posted, it looks like that the agent sends up a transaction duration property with the value null. This is not supposed to happen.

Are you in any way manipulating the data before it's being sent to the APM Server? For instance by using a filter in the agent, either via agent.addFilter or agent.addTransactionFilter?

3

Hi, wa7son -

I really appreciate what you guys have been doing and especially your help to the community.

Regarding the issue, I'm very new to the Elastic Search so i'm not even capable of altering anything atleast at the moment. It's just simple plain and fresh install. I've downloaded apm server (Zip file) and add the node entries in my app.js file as per the documentation.

What's surprising is I can see the errors and metrics from NodeJS but not the Transacton. I can see Transactions for APM server itself though.

Thanks again,
Pandu.

4

Thought I would add more details - After downloading APM server I edited the apm-server.yml file with these below

#-------------------------- Elasticsearch output --------------------------
output.elasticsearch:
hosts: ["xx.xx.xx.xx:9200"]
enabled: true
username: "elastic"
password: "xxxxxxx"

On the NodeJS side, app.js I have this

const apm = require('elastic-apm-node').start({
serviceName: 'NodeJS',

// Use if APM Server requires a token
//secretToken: '',

serverUrl: 'http://xx.xx.xx.xx:8300',

//Log Level
logLevel: 'trace',
});

5

APM_Issue
APM_Issue1278×266 17.4 KB

6

Thanks for following up. This is a really weird error that I've never seen before and as far as I read the code it shouldn't happen. However, it does, so I'll need your help in order to track down what's going on.

I can see that you've set the logLevel to trace - this is good :+1:

Can you see if you, in your Node.js logs, have a log line that starts with the following:

tried to call duration() on un-ended transaction/span

This would be the only situation where duration becomes null as far as I can see, but it shouldn't be possible for the code to get in this state, so I'm really curious if it does.

7

Hi Watson,

I'm sorry but don't see that line in the log. All I can see is as below

0|app    | APM Server transport error (400): Unexpected APM Server response
0|app    | APM Server accepted 1 events in the last request
0|app    | Error: error validating JSON document against schema: I[#] S[#] doesn't validate with "transaction#"
0|app    |   I[#] S[#/allOf/3] allOf failed
0|app    |     I[#/duration] S[#/allOf/3/properties/duration/type] expected number, but got null
0|app    |   Document: {"transaction":{"name":"GET unknown route","type":"request","result":"HTTP 3xx","id":"9df4a69d6510057e","trace_id":"20edc5652a0f1f58fd55067735b51f13","subtype":null,"action":null,"duration":null,"timestamp":null,"sampled":true,"context":{"user":{},"tags":{},"custom":{},"request":{"http_version":"1.1","method":"GET","url":{"raw":"/","protocol":"http:","hostname":"nodejs-intra-intra.propelapps.com","port":"8808","pathname":"/","full":"http://nodejs-intra-intra.propelapps.com:8808/"},"socket":{"remote_address":"::ffff:xx.xx.xx.79","encrypted":false},"headers":{"host":"nodejs-intra-intra.propelapps.com:8808","connection":"keep-alive","upgrade-insecure-requests":"1","user-agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/71.0.3578.98 Safari/537.36","accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8","accept-encoding":"gzip, deflate","accept-language":"en-US,en;q=0.9","cookie":"_ga=GA1.2.2003565780.1583956732; sbjs_migrations=1418474375998=1; sbjs_current_add=fd=2020-03-11 15:58:51||ep=https://www.propelapps.com/||rf=(none); sbjs_first_add=fd=2020-03-11 15:58:51||ep=https://www.propelapps.com/||rf=(none); sbjs_current=typ=typein||src=(direct)||mdm=(none)||cmp=(none)||cnt=(none)||trm=(none); sbjs_first=typ=typein||src=(direct)||mdm=(none)||cmp=(none)||cnt=(none)||trm=(none); sbjs_udata=vst=1||uip=(none)||uag=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/71.0.3578.98 Safari/537.36; _engagebay_visitor_id=[REDACTED]; _hjid=3a4d93b4-6dbe-4b7c-a8f1-65da4bcbf212; messagesUtk=f60f7af9f3a14be59597d43773a2ac6b; __hstc=35436606.a962f29c096528809e9f8af802de3dbd.1583956738792.1583956738792.1583956738793.1; hubspotutk=a962f29c096528809e9f8af802de3dbd; __hs_opt_out=no","if-none-match":"W/\"1e-8sOLorzGd52hYFS7WXjOHEQnwXY\""}},"response":{"status_code":304,"headers":{"x-powered-by":"Express","access-control-allow-origin":"*","access-control-allow-headers":"Origin,X-Requested-With,Accept,Content-Type,Authorization","etag":"W/\"1e-8sOLorzGd52hYFS7WXjOHEQnwXY\"","date":"Thu, 02 Apr 2020 12:41:32 GMT","connection":"keep-alive"}}},"sync":false,"span_count":{"started":0}}}
0|app    | Error: error validating JSON document against schema: I[#] S[#] doesn't validate with "metricset#"
0|app    |   I[#] S[#/allOf/5] allOf failed
0|app    |     I[#/samples/transaction.duration.sum.us/value] S[#/allOf/5/properties/samples/patternProperties/%5E%5B%5E%2A%22%5D%2A$/properties/value/type] expected number, but got null
0|app    |   Document: {"metricset":{"samples":{"transaction.duration.count":{"value":1},"transaction.duration.sum.us":{"value":null},"transaction.breakdown.count":{"value":1}},"timestamp":null,"tags":{"hostname":"nodejs-intra.propelapps.com","env":"development"},"transaction":{"name":"GET unknown route","type":"request"}}}
0|app    | Error: error validating JSON document against schema: I[#] S[#] doesn't validate with "metricset#"
0|app    |   I[#] S[#/allOf/5] allOf failed
0|app    |     I[#/samples/span.self_time.sum.us/value] S[#/allOf/5/properties/samples/patternProperties/%5E%5B%5E%2A%22%5D%2A$/properties/value/type] expected number, but got null
0|app    |   Document: {"metricset":{"samples":{"span.self_time.count":{"value":1},"span.self_time.sum.us":{"value":null}},"timestamp":null,"tags":{"hostname":"nodejs-intra.propelapps.com","env":"development"},"transaction":{"name":"GET unknown route","type":"request"},"span":{"type":"app"}}}
1|app    | no active transaction found - cannot build new span
1|app    | intercepted call to http.request { id: null }
0|app    | no active transaction found - cannot build new span
0|app    | intercepted call to http.request { id: null }
1|app    | no active transaction found - cannot build new span
1|app    | intercepted call to http.request { id: null }
0|app    | no active transaction found - cannot build new span
0|app    | intercepted call to http.request { id: null }
1|app    | no active transaction found - cannot build new span
1|app    | intercepted call to http.request { id: null }
8

Thanks for the detailed logs.

I can see that timestamp is also null which seems to indicate something is completely off regarding the internal timer. I just remembered that JSON.stringify({foo: NaN}) will produce {"foo":null}, so maybe that's what's going on - maybe the timer somehow calculates something that results in a NaN value which then gets converted to null by JSON.stringify.

I've pushed a debug version of the agent that will throw an error in case the timer produces a NaN value. You can install it into your application by changing the dependency from ^3.5.0 to elastic/apm-agent-nodejs#debug-timer which will instruct npm to fetch the module from the debug-timer branch on GitHub instead of from npm.

You can see what I changed compared to the npm version here: https://github.com/elastic/apm-agent-nodejs/compare/3.x...debug-timer

Be aware that this will crash the application when/if a timer produces a NaN value. So you shouldn't run this in production.

Let me know if this can work for you and what result you get.

/thomas

9

Talking about timestamp, I just noticed a 15 secs time difference between the APM server and the NodeJS. You think this is causing the issues?

I'll try the debug agent in a bit and send you the trace.

10

It’s important that the agent is started before you require any other modules in your Node.js application - i.e. before http and before your router official site etc.

11

It’s important that the agent is started before you require any other modules in your Node.js application - i.e. before http and before your router official site etc.

@Enright I don't think that's the issue in this particular case. The agent does send up transactions to the APM Server, just with null for some of the important values, which is strange.

Talking about timestamp, I just noticed a 15 secs time difference between the APM server and the NodeJS. You think this is causing the issues?

@propelelk No that shouldn't be an issue in this case.

12

Hi Watson,

I tried this approach and below is what I see in the log (Didn't notice much difference though!)

My dependency looks like this

"dependencies": {
    "cors": "^2.8.5",
    "elastic-apm-node": "elastic/apm-agent-nodejs#debug-timer",

Log has this

1|app  | APM Server transport error (400): Unexpected APM Server response
1|app  | APM Server accepted 1 events in the last request
1|app  | Error: error validating JSON document against schema: I[#] S[#] doesn't validate with "metricset#"
1|app  |   I[#] S[#/allOf/5] allOf failed
1|app  |     I[#/samples/transaction.duration.sum.us/value] S[#/allOf/5/properties/samples/patternProperties/%5E%5B%5E%2A%22%5D%2A$/properties/value/type] expected number, but got null
1|app  |   Document: {"metricset":{"samples":{"transaction.duration.count":{"value":3},"transaction.duration.sum.us":{"value":null},"transaction.breakdown.count":{"value":3}},"timestamp":null,"tags":{"hostname":"xxxxxxxx.com","env":"development"},"transaction":{"name":"GET unknown route","type":"request"}}}
1|app  | Error: error validating JSON document against schema: I[#] S[#] doesn't validate with "metricset#"
1|app  |   I[#] S[#/allOf/5] allOf failed
1|app  |     I[#/samples/span.self_time.sum.us/value] S[#/allOf/5/properties/samples/patternProperties/%5E%5B%5E%2A%22%5D%2A$/properties/value/type] expected number, but got null
1|app  |   Document: {"metricset":{"samples":{"span.self_time.count":{"value":3},"span.self_time.sum.us":{"value":null}},"timestamp":null,"tags":{"hostname":"xxxxxxxx.com","env":"development"},"transaction":{"name":"GET unknown route","type":"request"},"span":{"type":"app"}}}
0|app  | no active transaction found - cannot build new span
0|app  | intercepted call to http.request { id: null }
1|app  | no active transaction found - cannot build new span
1|app  | intercepted call to http.request { id: null }
13

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