Nodejs APM not working due to /intake/v2/events timeout in version 7.14

Elastic Observability APM
, ,
1

Hi,

I am trying to set up APM for a nodejs app. however data is not coming to Elasticsearch and I can see the below error in the console.
I'm using the docker-compose from this link

{
   "log.level":"error",
   "@timestamp":"2021-09-22T18:15:06.953Z",
   "log.logger":"request",
   "log.origin":{
      "file.name":"middleware/log_middleware.go",
      "file.line":60
   },
   "message":"request timed out",
   "service.name":"apm-server",
   "event.dataset":"apm-server",
   "url.original":"/intake/v2/events",
   "http.request.method":"POST",
   "user_agent.original":"elasticapm-node/3.21.1 elastic-apm-http-client/10.0.0 node/14.17.1",
   "source.address":"172.20.0.1",
   "http.request.id":"e4bb0bb6-e6ab-4d2e-b845-d2ce1880bd70",
   "event.duration":3071607400,
   "http.response.status_code":503,
   "error.message":"request timed out",
   "ecs.version":"1.6.0"
}
2

Are there any other errors in the apm-server log? e.g. failures to communicate with Elasticsearch?

3

Hi Andrew,

I didn't notice any errors other than this.
this is the entire log from the docker-compose

kibana_1         | {"type":"response","@timestamp":"2021-09-23T05:57:07+00:00","tags":["api"],"pid":1217,"method":"get","statusCode":200,"req":{"url":"/api/status","method":"get","headers":{"host":"localhost:5601","user-agent":"curl/7.61.1","accept":"*/*"},"remoteAddress":"127.0.0.1","userAgent":"curl/7.61.1"},"res":{"statusCode":200,"responseTime":60,"contentLength":22657},"message":"GET /api/status 200 60ms - 22.1KB"}
apm-server_1     | {"log.level":"info","@timestamp":"2021-09-23T05:57:08.609Z","log.logger":"request","log.origin":{"file.name":"middleware/log_middleware.go","file.line":63},"message":"request ok","service.name":"apm-server","event.dataset":"apm-server","url.original":"/","http.request.method":"GET","user_agent.original":"curl/7.29.0","source.address":"127.0.0.1","http.request.body.bytes":0,"http.request.id":"146e1bf6-b43a-45a7-a707-ab6064932f5f","event.duration":9973800,"http.response.status_code":200,"ecs.version":"1.6.0"}
kibana_1         | {"type":"response","@timestamp":"2021-09-23T05:57:10+00:00","tags":[],"pid":1217,"method":"post","statusCode":200,"req":{"url":"/api/ui_counters/_report","method":"post","headers":{"host":"localhost:5601","connection":"keep-alive","content-length":"142","sec-ch-ua":"\"Google Chrome\";v=\"93\", \" Not;A Brand\";v=\"99\", \"Chromium\";v=\"93\"","content-type":"application/json","sec-ch-ua-mobile":"?0","user-agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36","kbn-version":"7.14.2","kbn-system-request":"true","sec-ch-ua-platform":"\"Windows\"","accept":"*/*","origin":"http://localhost:5601","sec-fetch-site":"same-origin","sec-fetch-mode":"cors","sec-fetch-dest":"empty","referer":"http://localhost:5601/app/home","accept-encoding":"gzip, deflate, br","accept-language":"en-GB,en;q=0.9,si-LK;q=0.8,si;q=0.7,en-US;q=0.6"},"remoteAddress":"172.19.0.1","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36","referer":"http://localhost:5601/app/home"},"res":{"statusCode":200,"responseTime":371,"contentLength":15},"message":"POST /api/ui_counters/_report 200 371ms - 15.0B"}
kibana_1         | {"type":"response","@timestamp":"2021-09-23T05:57:23+00:00","tags":[],"pid":1217,"method":"post","statusCode":200,"req":{"url":"/api/ui_counters/_report","method":"post","headers":{"host":"localhost:5601","connection":"keep-alive","content-length":"155","sec-ch-ua":"\"Google Chrome\";v=\"93\", \" Not;A Brand\";v=\"99\", \"Chromium\";v=\"93\"","content-type":"application/json","sec-ch-ua-mobile":"?0","user-agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36","kbn-version":"7.14.2","kbn-system-request":"true","sec-ch-ua-platform":"\"Windows\"","accept":"*/*","origin":"http://localhost:5601","sec-fetch-site":"same-origin","sec-fetch-mode":"cors","sec-fetch-dest":"empty","referer":"http://localhost:5601/app/home","accept-encoding":"gzip, deflate, br","accept-language":"en-GB,en;q=0.9,si-LK;q=0.8,si;q=0.7,en-US;q=0.6"},"remoteAddress":"172.19.0.1","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36","referer":"http://localhost:5601/app/home"},"res":{"statusCode":200,"responseTime":293,"contentLength":15},"message":"POST /api/ui_counters/_report 200 293ms - 15.0B"}
kibana_1         | {"type":"response","@timestamp":"2021-09-23T05:57:37+00:00","tags":[],"pid":1217,"method":"post","statusCode":200,"req":{"url":"/api/ui_counters/_report","method":"post","headers":{"host":"localhost:5601","connection":"keep-alive","content-length":"141","sec-ch-ua":"\"Google Chrome\";v=\"93\", \" Not;A Brand\";v=\"99\", \"Chromium\";v=\"93\"","content-type":"application/json","sec-ch-ua-mobile":"?0","user-agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36","kbn-version":"7.14.2","kbn-system-request":"true","sec-ch-ua-platform":"\"Windows\"","accept":"*/*","origin":"http://localhost:5601","sec-fetch-site":"same-origin","sec-fetch-mode":"cors","sec-fetch-dest":"empty","referer":"http://localhost:5601/app/home","accept-encoding":"gzip, deflate, br","accept-language":"en-GB,en;q=0.9,si-LK;q=0.8,si;q=0.7,en-US;q=0.6"},"remoteAddress":"172.19.0.1","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36","referer":"http://localhost:5601/app/home"},"res":{"statusCode":200,"responseTime":953,"contentLength":15},"message":"POST /api/ui_counters/_report 200 953ms - 15.0B"}
apm-server_1     | {"log.level":"info","@timestamp":"2021-09-23T05:57:40.184Z","log.logger":"request","log.origin":{"file.name":"middleware/log_middleware.go","file.line":63},"message":"request ok","service.name":"apm-server","event.dataset":"apm-server","url.original":"/config/v1/agents?service.name=property-search&service.environment=production","http.request.method":"GET","user_agent.original":"elasticapm-node/3.21.1 elastic-apm-http-client/10.0.0 node/14.17.1","source.address":"172.19.0.1","http.request.body.bytes":0,"http.request.id":"9927c936-a035-436e-b29e-653c1c608635","event.duration":134927900,"http.response.status_code":200,"ecs.version":"1.6.0"}
kibana_1         | {"type":"response","@timestamp":"2021-09-23T05:57:40+00:00","tags":["access:apm"],"pid":1217,"method":"post","statusCode":200,"req":{"url":"/api/apm/settings/agent-configuration/search","method":"post","headers":{"host":"kibana:5601","user-agent":"Go-http-client/1.1","content-length":"75","accept":"application/json","content-type":"application/json","kbn-xsrf":"1","accept-encoding":"gzip"},"remoteAddress":"172.19.0.4","userAgent":"Go-http-client/1.1"},"res":{"statusCode":200,"responseTime":126,"contentLength":262},"message":"POST /api/apm/settings/agent-configuration/search 200 126ms - 262.0B"}
apm-server_1     | {"log.level":"error","@timestamp":"2021-09-23T05:57:44.588Z","log.logger":"request","log.origin":{"file.name":"middleware/log_middleware.go","file.line":60},"message":"request timed out","service.name":"apm-server","event.dataset":"apm-server","url.original":"/intake/v2/events","http.request.method":"POST","user_agent.original":"elasticapm-node/3.21.1 elastic-apm-http-client/10.0.0 node/14.17.1","source.address":"172.19.0.1","http.request.id":"122fd2d5-d177-41ee-80d6-ad3fa396d292","event.duration":4223208400,"http.response.status_code":503,"error.message":"request timed out","ecs.version":"1.6.0"}
kibana_1         | {"type":"response","@timestamp":"2021-09-23T05:57:45+00:00","tags":[],"pid":1217,"method":"post","statusCode":200,"req":{"url":"/api/ui_counters/_report","method":"post","headers":{"host":"localhost:5601","connection":"keep-alive","content-length":"154","sec-ch-ua":"\"Google Chrome\";v=\"93\", \" Not;A Brand\";v=\"99\", \"Chromium\";v=\"93\"","content-type":"application/json","sec-ch-ua-mobile":"?0","user-agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36","kbn-version":"7.14.2","kbn-system-request":"true","sec-ch-ua-platform":"\"Windows\"","accept":"*/*","origin":"http://localhost:5601","sec-fetch-site":"same-origin","sec-fetch-mode":"cors","sec-fetch-dest":"empty","referer":"http://localhost:5601/app/home","accept-encoding":"gzip, deflate, br","accept-language":"en-GB,en;q=0.9,si-LK;q=0.8,si;q=0.7,en-US;q=0.6"},"remoteAddress":"172.19.0.1","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36","referer":"http://localhost:5601/app/home"},"res":{"statusCode":200,"responseTime":298,"contentLength":15},"message":"POST /api/ui_counters/_report 200 298ms - 15.0B"}
kibana_1         | {"type":"response","@timestamp":"2021-09-23T05:58:14+00:00","tags":[],"pid":1217,"method":"post","statusCode":200,"req":{"url":"/api/ui_counters/_report","method":"post","headers":{"host":"localhost:5601","connection":"keep-alive","content-length":"155","sec-ch-ua":"\"Google Chrome\";v=\"93\", \" Not;A Brand\";v=\"99\", \"Chromium\";v=\"93\"","content-type":"application/json","sec-ch-ua-mobile":"?0","user-agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36","kbn-version":"7.14.2","kbn-system-request":"true","sec-ch-ua-platform":"\"Windows\"","accept":"*/*","origin":"http://localhost:5601","sec-fetch-site":"same-origin","sec-fetch-mode":"cors","sec-fetch-dest":"empty","referer":"http://localhost:5601/app/home","accept-encoding":"gzip, deflate, br","accept-language":"en-GB,en;q=0.9,si-LK;q=0.8,si;q=0.7,en-US;q=0.6"},"remoteAddress":"172.19.0.1","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36","referer":"http://localhost:5601/app/home"},"res":{"statusCode":200,"responseTime":201,"contentLength":15},"message":"POST /api/ui_counters/_report 200 201ms - 15.0B"}
kibana_1         | {"type":"response","@timestamp":"2021-09-23T05:58:47+00:00","tags":["api"],"pid":1217,"method":"get","statusCode":200,"req":{"url":"/api/status","method":"get","headers":{"host":"localhost:5601","user-agent":"curl/7.61.1","accept":"*/*"},"remoteAddress":"127.0.0.1","userAgent":"curl/7.61.1"},"res":{"statusCode":200,"responseTime":51,"contentLength":22638},"message":"GET /api/status 200 51ms - 22.1KB"}
apm-server_1     | {"log.level":"info","@timestamp":"2021-09-23T05:58:49.408Z","log.logger":"request","log.origin":{"file.name":"middleware/log_middleware.go","file.line":63},"message":"request ok","service.name":"apm-server","event.dataset":"apm-server","url.original":"/","http.request.method":"GET","user_agent.original":"curl/7.29.0","source.address":"127.0.0.1","http.request.body.bytes":0,"http.request.id":"e661f9d5-0d2c-4dc5-8268-e79e6373adf6","event.duration":191500,"http.response.status_code":200,"ecs.version":"1.6.0"}
elasticsearch_1  | {"type": "deprecation.elasticsearch", "timestamp": "2021-09-23T06:00:01,634Z", "level": "DEPRECATION", "component": "o.e.d.c.m.IndexNameExpressionResolver", "cluster.name": "docker-cluster", "node.name": "ef1ce784e2f4", "message": "this request accesses system indices: [.tasks], but in a future major version, direct access to system indices will be prevented by default", "cluster.uuid": "_S68xD2GRiGwzl_oZgOWCw", "node.id": "KPqPcHnfSpi1qv04H97idw"  }
kibana_1         | {"type":"response","@timestamp":"2021-09-23T05:59:45+00:00","tags":[],"pid":1217,"method":"post","statusCode":200,"req":{"url":"/api/ui_counters/_report","method":"post","headers":{"host":"localhost:5601","connection":"keep-alive","content-length":"154","sec-ch-ua":"\"Google Chrome\";v=\"93\", \" Not;A Brand\";v=\"99\", \"Chromium\";v=\"93\"","content-type":"application/json","sec-ch-ua-mobile":"?0","user-agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36","kbn-version":"7.14.2","kbn-system-request":"true","sec-ch-ua-platform":"\"Windows\"","accept":"*/*","origin":"http://localhost:5601","sec-fetch-site":"same-origin","sec-fetch-mode":"cors","sec-fetch-dest":"empty","referer":"http://localhost:5601/app/home","accept-encoding":"gzip, deflate, br","accept-language":"en-GB,en;q=0.9,si-LK;q=0.8,si;q=0.7,en-US;q=0.6"},"remoteAddress":"172.19.0.1","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36","referer":"http://localhost:5601/app/home"},"res":{"statusCode":200,"responseTime":212,"contentLength":15},"message":"POST /api/ui_counters/_report 200 212ms - 15.0B"}
apm-server_1     | {"log.level":"info","@timestamp":"2021-09-23T06:00:29.948Z","log.logger":"request","log.origin":{"file.name":"middleware/log_middleware.go","file.line":63},"message":"request ok","service.name":"apm-server","event.dataset":"apm-server","url.original":"/","http.request.method":"GET","user_agent.original":"curl/7.29.0","source.address":"127.0.0.1","http.request.body.bytes":0,"http.request.id":"79e02f49-0464-4e92-ba4a-98ce284b4a7f","event.duration":293700,"http.response.status_code":200,"ecs.version":"1.6.0"}
4

nodejs APM agent trace for one request

START RequestId: dc1162b5-71be-4bcf-b9a3-f16ca09da288 Version: $LATEST
{"log.level":"trace","@timestamp":"2021-09-23T05:57:11.497Z","log":{"logger":"elastic-apm-node"},"pid":14,"ppid":1,"arch":"x64","platform":"linux","node":"v14.17.1","agent":"3.21.1","startTrace":["at Agent.start (/var/task/node_modules/elastic-apm-node/lib/agent.js:228:11)","at Object.<anonymous> (/var/task/app.js:3:39)","at Module._compile (internal/modules/cjs/loader.js:1085:14)","at Object.Module._extensions..js (internal/modules/cjs/loader.js:1114:10)","at Module.load (internal/modules/cjs/loader.js:950:32)","at Function.Module._load (internal/modules/cjs/loader.js:790:14)","at Module.require (internal/modules/cjs/loader.js:974:19)","at require (internal/modules/cjs/helpers.js:92:18)","at _tryRequire (/var/runtime/UserFunction.js:75:12)","at _loadUserApp (/var/runtime/UserFunction.js:95:12)"],"main":"<could not determine>","dependencies":"<could not determine>","conf":{"ignoreUrlStr":[],"ignoreUrlRegExp":[],"ignoreUserAgentStr":[],"ignoreUserAgentRegExp":[],"transactionIgnoreUrlRegExp":[],"sanitizeFieldNamesRegExp":["/^password$/i","/^passwd$/i","/^pwd$/i","/^secret$/i","/^.*key$/i","/^.*token.*$/i","/^.*session.*$/i","/^.*credit.*$/i","/^.*card.*$/i","/^authorization$/i","/^set\\x2dcookie$/i","/^pw$/i","/^pass$/i","/^connect\\.sid$/i"],"ignoreMessageQueuesRegExp":[],"abortedErrorThreshold":25,"active":true,"apiRequestSize":786432,"apiRequestTime":10,"asyncHooks":true,"breakdownMetrics":true,"captureBody":"off","captureErrorLogStackTraces":"messages","captureExceptions":true,"captureHeaders":true,"captureSpanStackTraces":true,"centralConfig":true,"cloudProvider":"auto","disableInstrumentations":[],"disableSend":false,"environment":"production","errorOnAbortedRequests":false,"filterHttpHeaders":true,"ignoreMessageQueues":[],"instrument":true,"instrumentIncomingHTTPRequests":true,"logLevel":"trace","logUncaughtExceptions":false,"longFieldMaxLength":10000,"maxQueueSize":1024,"metricsInterval":30,"metricsLimit":1000,"sanitizeFieldNames":["password","passwd","pwd","secret","*key","*token*","*session*","*credit*","*card*","authorization","set-cookie","pw","pass","connect.sid"],"serverTimeout":30,"sourceLinesErrorAppFrames":5,"sourceLinesErrorLibraryFrames":5,"sourceLinesSpanAppFrames":0,"sourceLinesSpanLibraryFrames":0,"spanFramesMinDuration":0.01,"stackTraceLimit":50,"transactionIgnoreUrls":[],"transactionMaxSpans":500,"transactionSampleRate":0.1,"useElasticTraceparentHeader":true,"usePathAsTransactionName":false,"verifyServerCert":true,"serviceName":"property-search","serverUrl":"http://172.21.32.1:8200","serviceVersion":"1.0.0","serverHost":"172.21.32.1:8200","serverPort":8200},"ecs":{"version":"1.6.0"},"message":"agent configured correctly"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:11.617Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"adding hook to Node.js module loader"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:13.053Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming https@14.17.1 module"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:13.496Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming https.Server.prototype.emit function"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:13.502Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming https.request function"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:13.504Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming https.get function"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:13.506Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http@14.17.1 module"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:13.617Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http.Server.prototype.emit function"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:13.617Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http.ServerResponse.prototype.writeHead function"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:13.618Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http.request function"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:13.618Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http.get function"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:39.709Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming @elastic/elasticsearch@7.14.1 module"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:39.937Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"subclassing @elastic/elasticsearch.Client"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:40.209Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start trace {\"trans\":\"8f9cf254675f185d\",\"trace\":\"e53d883dd3e33605bd368d937c99308f\",\"name\":\"unnamed\",\"type\":null,\"subtype\":null,\"action\":null}"}
2021-09-23T05:57:40.215Z        dc1162b5-71be-4bcf-b9a3-f16ca09da288    INFO    [trace.id=e53d883dd3e33605bd368d937c99308f transaction.id=8f9cf254675f185d property-search] my message
} ssc_code: '11344',description',c1162b5-71be-4bcf-b9a3-f16ca09da288    INFO    [trace.id=e53d883dd3e33605bd368d937c99308f transaction.id=8f9cf254675f185d property-search] {
{"log.level":"debug","@timestamp":"2021-09-23T05:57:40.239Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to @elastic/elasticsearch \"request\" event {\"id\":2,\"method\":\"GET\",\"path\":\"/\"}"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:40.244Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to http.request {\"id\":null}"}
{"log.level":"info","@timestamp":"2021-09-23T05:57:40.283Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"Remote config success. Updated transactionMaxSpans: 100"}
{"log.level":"trace","@timestamp":"2021-09-23T05:57:40.321Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"777c5522540eba01556c3e5267d218cb","ecs":{"version":"1.6.0"},"message":"intake request start"}
{"log.level":"trace","@timestamp":"2021-09-23T05:57:40.325Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","fullTimeMs":11.0699,"numEvents":1,"numBytes":886,"ecs":{"version":"1.6.0"},"message":"_write: encode object"}
{"log.level":"trace","@timestamp":"2021-09-23T05:57:40.327Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"777c5522540eba01556c3e5267d218cb","ecs":{"version":"1.6.0"},"message":"intakeReq \"socket\": unref it"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:41.626Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to @elastic/elasticsearch \"request\" event {\"id\":1,\"method\":\"POST\",\"path\":\"/suburbs*/_search\"}"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:41.627Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to http.request {\"id\":null}"}
{"log.level":"trace","@timestamp":"2021-09-23T05:57:41.703Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","fullTimeMs":1.6817,"numEvents":1,"numBytes":899,"ecs":{"version":"1.6.0"},"message":"_write: encode object"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:42.844Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to @elastic/elasticsearch \"request\" event {\"id\":3,\"method\":\"POST\",\"path\":\"/suburbs*/_search\"}"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:42.845Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to http.request {\"id\":null}"}
2021-09-23T05:57:43.357Z        dc1162b5-71be-4bcf-b9a3-f16ca09da288    INFO    ["11344","12287","11678","10027","12977","13610","14239","13622","13856","13573","11842","12249","11446","22804","21339","20278","20128","20963"]
2021-09-23T05:57:43.358Z        dc1162b5-71be-4bcf-b9a3-f16ca09da288    INFO    [trace.id=e53d883dd3e33605bd368d937c99308f transaction.id=8f9cf254675f185d property-search] [{"terms":{"suburb.ssc_code":["11344","12287","11678","10027","12977","13610","14239","13622","13856","13573","11842","12249","11446","22804","21339","20278","20128","20963"],"boost":1}},{"terms":{"num_of_carport_spaces":["2","3"],"boost":1}},{"terms":{"num_of_bathrooms":["2","3"],"boost":1}},{"terms":{"num_of_bedrooms":["2","3"],"boost":1}},{"range":{"house_size":{"gte":"100","lte":"1000"}}},{"range":{"land_size":{"gte":"100","lte":"1000"}}}]
{"log.level":"debug","@timestamp":"2021-09-23T05:57:43.359Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to @elastic/elasticsearch \"request\" event {\"id\":4,\"method\":\"POST\",\"path\":\"/properties*/_search\"}"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:43.359Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to http.request {\"id\":null}"}
END RequestId: dc1162b5-71be-4bcf-b9a3-f16ca09da288
REPORT RequestId: dc1162b5-71be-4bcf-b9a3-f16ca09da288  Init Duration: 1.04 ms  Duration: 75573.46 ms   Billed Duration: 75600 ms       Memory Size: 128 MB     Max Memory Used: 128 MB
2021-09-23 11:27:46 127.0.0.1 - - [23/Sep/2021 11:27:46] "←[37mGET /api/property-search/suburb?ssc_code=11344&radius=10&from=0&size=21&source=id,title,description&num_of_carport_spaces=2,3&num_of_bathrooms=2,3&num_of_bedrooms=2,3&house_size_gte=100&house_size_lte=1000&land_size_gte=100&land_size_lte=1000 HTTP/1.1←[0m" 200 -
2021-09-23 11:27:47 127.0.0.1 - - [23/Sep/2021 11:27:47] "←[31m←[1mGET /favicon.ico HTTP/1.1←[0m" 403 -

Note that this is a aws lambda function and its giving the output as expecting

package.json

{
    "@elastic/elasticsearch": "^7.13.0",
    "axios": "^0.21.1",
    "elastic-apm-node": "^3.20.0"
  }

app.js

var apm = require('elastic-apm-node').start({

// Override the service name from package.json
// Allowed characters: a-z, A-Z, 0-9, -, _, and space
serviceName: 'xxxxx-search',
logLevel: 'trace',
// Use if APM Server requires a secret token
//secretToken: '',

// Set the custom APM Server URL (default: http://localhost:8200)
serverUrl: 'http://xxx.xx.xx.1:8200',
transactionSampleRate: 0.1,

// Set the service environment
environment: 'production'
});

start transaction with traceparent

if (event.headers['Elk-Trace-Parent'] != undefined) {
		apm.startTransaction(serviceName, { childOf: event.headers['Elk-Trace-Parent'] })
	} else { 
		apm.startTransaction(serviceName) //starts apm transaction
	}
5

image
image790×570 24.6 KB

image

6

Note that this is a aws lambda function and its giving the output as expecting

Lambda is not currently supported, so I'd guess it's related to this. When the Lambda freezes, I believe it will not be ending the HTTP request to APM Server gracefully, leading to the server timing out. I'm guessing though.

Are you able to instrument a non-Lambda application and send some traces to APM Server to check the general health of your setup?

7

Ok got your point,
what if I write the trace to cloudwatch and read it from a filebeat or logstash for ex

{"log.level":"trace","@timestamp":"2021-09-23T05:57:11.497Z","log":{"logger":"elastic-apm-node"},"pid":14,"ppid":1,"arch":"x64","platform":"linux","node":"v14.17.1","agent":"3.21.1","startTrace":["at Agent.start (/var/task/node_modules/elastic-apm-node/lib/agent.js:228:11)","at Object.<anonymous> (/var/task/app.js:3:39)","at Module._compile (internal/modules/cjs/loader.js:1085:14)","at Object.Module._extensions..js (internal/modules/cjs/loader.js:1114:10)","at Module.load (internal/modules/cjs/loader.js:950:32)","at Function.Module._load (internal/modules/cjs/loader.js:790:14)","at Module.require (internal/modules/cjs/loader.js:974:19)","at require (internal/modules/cjs/helpers.js:92:18)","at _tryRequire (/var/runtime/UserFunction.js:75:12)","at _loadUserApp (/var/runtime/UserFunction.js:95:12)"],"main":"<could not determine>","dependencies":"<could not determine>","conf":{"ignoreUrlStr":[],"ignoreUrlRegExp":[],"ignoreUserAgentStr":[],"ignoreUserAgentRegExp":[],"transactionIgnoreUrlRegExp":[],"sanitizeFieldNamesRegExp":["/^password$/i","/^passwd$/i","/^pwd$/i","/^secret$/i","/^.*key$/i","/^.*token.*$/i","/^.*session.*$/i","/^.*credit.*$/i","/^.*card.*$/i","/^authorization$/i","/^set\\x2dcookie$/i","/^pw$/i","/^pass$/i","/^connect\\.sid$/i"],"ignoreMessageQueuesRegExp":[],"abortedErrorThreshold":25,"active":true,"apiRequestSize":786432,"apiRequestTime":10,"asyncHooks":true,"breakdownMetrics":true,"captureBody":"off","captureErrorLogStackTraces":"messages","captureExceptions":true,"captureHeaders":true,"captureSpanStackTraces":true,"centralConfig":true,"cloudProvider":"auto","disableInstrumentations":[],"disableSend":false,"environment":"production","errorOnAbortedRequests":false,"filterHttpHeaders":true,"ignoreMessageQueues":[],"instrument":true,"instrumentIncomingHTTPRequests":true,"logLevel":"trace","logUncaughtExceptions":false,"longFieldMaxLength":10000,"maxQueueSize":1024,"metricsInterval":30,"metricsLimit":1000,"sanitizeFieldNames":["password","passwd","pwd","secret","*key","*token*","*session*","*credit*","*card*","authorization","set-cookie","pw","pass","connect.sid"],"serverTimeout":30,"sourceLinesErrorAppFrames":5,"sourceLinesErrorLibraryFrames":5,"sourceLinesSpanAppFrames":0,"sourceLinesSpanLibraryFrames":0,"spanFramesMinDuration":0.01,"stackTraceLimit":50,"transactionIgnoreUrls":[],"transactionMaxSpans":500,"transactionSampleRate":0.1,"useElasticTraceparentHeader":true,"usePathAsTransactionName":false,"verifyServerCert":true,"serviceName":"property-search","serverUrl":"http://172.21.32.1:8200","serviceVersion":"1.0.0","serverHost":"172.21.32.1:8200","serverPort":8200},"ecs":{"version":"1.6.0"},"message":"agent configured correctly"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:11.617Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"adding hook to Node.js module loader"}
{"log.level":"debug","@timestamp":"2021-09-23T05:57:13.053Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming https@14.17.1 module"}

and push them to APM index?
is the original request body is same as the trace?

or else ill try to keep the function warm and see if it is working.

8

I will try this one

1 Like
9

what if I write the trace to cloudwatch and read it from a filebeat or logstash for ex
and push them to APM index?
is the original request body is same as the trace?

No, I'm afraid not - that won't work. The events sent by the agent are transformed by APM Server, and the server also aggregates metrics from transactions and spans.

If you haven't already seen it, we are currently working on adding Lambda support: [META 352] AWS Lambda support · Issue #2156 · elastic/apm-agent-nodejs · GitHub.

1 Like
10

Ok great!
Thanks for the support Andrew

11

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