Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Not working with apollo-server-lambda (Apollo GraphQL) #2832

Closed
wjensen-godaddy opened this issue Jul 18, 2022 · 13 comments · Fixed by #2865
Closed

Not working with apollo-server-lambda (Apollo GraphQL) #2832

wjensen-godaddy opened this issue Jul 18, 2022 · 13 comments · Fixed by #2865
Assignees
Labels
agent-nodejs Make available for APM Agents project planning. aws-λ-extension community
Milestone

Comments

@wjensen-godaddy
Copy link

wjensen-godaddy commented Jul 18, 2022

The agent seems to think this is a regular HTTP server. All of the requests are being grouped under POST /staging/{proxy+}.

From reading the documentation, I think our setup is supported, but clearly something isn't working. Thanks for the help!

Lambda extensions:

arn:aws:lambda:us-west-2:267093732750:layer:elastic-apm-extension-ver-1-0-2-x86_64:1
arn:aws:lambda:us-west-2:267093732750:layer:elastic-apm-node-ver-3-36-0:1

Apollo packages:

"node_modules/apollo-server-lambda": {
  "version": "3.8.2",
  "resolved": "https://registry.npmjs.org/apollo-server-lambda/-/apollo-server-lambda-3.8.2.tgz",
  "integrity": "sha512-8KWp/YYM9yctWwAv0oMERKHM91MQmpJCOnS1TykWC4p1JwrSgt1vln9TJK5FRCD4rFGgSlPvhc3TItXjdDVVAw==",
  "dependencies": {
    "@types/aws-lambda": "^8.10.76",
    "@vendia/serverless-express": "^4.3.9",
    "apollo-server-core": "^3.8.2",
    "apollo-server-express": "^3.8.2",
    "express": "^4.17.1"
  },
  "engines": {
    "node": ">=12.0"
  },
  "peerDependencies": {
    "graphql": "^15.3.0 || ^16.0.0"
  }
}
@trentm
Copy link
Member

trentm commented Jul 18, 2022

If there is an issue here, it will be with the Node.js APM agent, and not with the Lambda ext. I'll move it over to the Node.js APM agent repo.

@trentm trentm transferred this issue from elastic/apm-aws-lambda Jul 18, 2022
@github-actions github-actions bot added the agent-nodejs Make available for APM Agents project planning. label Jul 18, 2022
@trentm
Copy link
Member

trentm commented Jul 22, 2022

@wjensen-godaddy A couple details might help with this:

  1. Do you get a "GraphQL: ..." spans in your traces?
  2. If you are able, a trace log (set ELASTIC_APM_LOG_LEVEL=trace on the Lambda function) of an execution of your Lambda function would likely help.

@wjensen-godaddy
Copy link
Author

wjensen-godaddy commented Jul 25, 2022

@trentm

  1. Not that I see
  2. I noticed it doesn't have a log entry for shimming Apollo:
START RequestId: c5ab3c3e-45e1-49b2-8502-f2599bca0c14 Version: $LATEST
--
{"log.level":"warn","@timestamp":"2022-07-25T20:52:47.010Z","log.origin":{"file.name":"extension/process_env.go","file.line":70},"message":"Could not read ELASTIC_APM_DATA_RECEIVER_TIMEOUT_SECONDS, defaulting to 15: strconv.Atoi: parsing \"\": invalid syntax","ecs.version":"1.6.0"}
{"log.level":"warn","@timestamp":"2022-07-25T20:52:47.010Z","log.origin":{"file.name":"extension/process_env.go","file.line":76},"message":"Could not read ELASTIC_APM_DATA_FORWARDER_TIMEOUT_SECONDS, defaulting to 3: strconv.Atoi: parsing \"\": invalid syntax","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:47.012Z","log.origin":{"file.name":"extension/client.go","file.line":116},"message":"ExtensionID : 9d0ed8f6-15b8-47e2-9301-4712b0a12e82","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:47.013Z","log.origin":{"file.name":"apm-lambda-extension/main.go","file.line":70},"message":"Register response: {\t\"functionName\": \"platy-1156-graph-staging-graphql\",\t\"functionVersion\": \"$LATEST\",\t\"handler\": \"src/index.graphqlHandler\"}","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-07-25T20:52:47.013Z","log.origin":{"file.name":"extension/http_server.go","file.line":47},"message":"Extension listening for apm data on :8200","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-07-25T20:52:47.047Z","log.origin":{"file.name":"logsapi/subscribe.go","file.line":122},"message":"Extension listening for Lambda Logs API events on 169.254.79.130:46793","ecs.version":"1.6.0"}
LOGS�Name: apm-lambda-extension�State: Subscribed�Types: [platform]
{"log.level":"info","@timestamp":"2022-07-25T20:52:47.049Z","log.origin":{"file.name":"apm-lambda-extension/main.go","file.line":112},"message":"Waiting for next event...","ecs.version":"1.6.0"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:47.517Z","log":{"logger":"elastic-apm-node"},"pid":17,"ppid":1,"arch":"x64","platform":"linux","node":"v14.19.3","agent":"3.37.0","startTrace":["at Agent.start (/opt/nodejs/node_modules/elastic-apm-node/lib/agent.js:241:11)","at Object.<anonymous> (/opt/nodejs/node_modules/elastic-apm-node/start.js:9:32)","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:12)","at Module.require (internal/modules/cjs/loader.js:974:19)","at Module._preloadModules (internal/modules/cjs/loader.js:1244:12)","at loadPreloadModules (internal/bootstrap/pre_execution.js:475:5)","at prepareMainThreadExecution (internal/bootstrap/pre_execution.js:72:3)"],"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","/^.*auth.*$/i","/^set\\x2dcookie$/i","/^pw$/i","/^pass$/i","/^connect\\.sid$/i"],"ignoreMessageQueuesRegExp":[],"abortedErrorThreshold":25,"active":true,"apiRequestSize":786432,"apiRequestTime":10,"breakdownMetrics":false,"captureBody":"off","captureErrorLogStackTraces":"messages","captureExceptions":true,"captureHeaders":true,"centralConfig":false,"cloudProvider":"none","contextPropagationOnly":false,"disableInstrumentations":[],"disableSend":false,"environment":"development","errorOnAbortedRequests":false,"filterHttpHeaders":true,"ignoreMessageQueues":[],"instrument":true,"instrumentIncomingHTTPRequests":true,"logLevel":"trace","logUncaughtExceptions":false,"longFieldMaxLength":10000,"maxQueueSize":1024,"metricsInterval":0,"metricsLimit":1000,"opentelemetryBridgeEnabled":false,"sanitizeFieldNames":["password","passwd","pwd","secret","*key","*token*","*session*","*credit*","*card*","*auth*","set-cookie","pw","pass","connect.sid"],"serverTimeout":30,"sourceLinesErrorAppFrames":5,"sourceLinesErrorLibraryFrames":5,"sourceLinesSpanAppFrames":0,"sourceLinesSpanLibraryFrames":0,"spanCompressionEnabled":true,"spanCompressionExactMatchMaxDuration":0.05,"spanCompressionSameKindMaxDuration":0,"stackTraceLimit":50,"traceContinuationStrategy":"continue","transactionIgnoreUrls":[],"transactionMaxSpans":500,"transactionSampleRate":1,"useElasticTraceparentHeader":true,"usePathAsTransactionName":false,"verifyServerCert":true,"secretToken":"[REDACTED]","serviceName":"platy-1156-graph-staging-graphql","serviceVersion":"$LATEST","spanStackTraceMinDuration":-1,"serverHost":"[REDACTED]","serverPort":8200},"ecs":{"version":"1.6.0"},"message":"agent configured correctly"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:47.521Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","ecs":{"version":"1.6.0"},"message":"corking (expectExtraMetadata)"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:47.528Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"adding hook to Node.js module loader"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:47.543Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http@14.19.3 module"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:47.546Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http.Server.prototype.emit function"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:47.546Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http.ServerResponse.prototype.writeHead function"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:47.547Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http.request function"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:47.547Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http.get function"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:47.688Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming https@14.19.3 module"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:47.689Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming https.Server.prototype.emit function"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:47.689Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming https.request function"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:47.689Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming https.get function"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.457Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming aws-sdk@2.1055.0 module"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.556Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming index@14.19.3 module"}
EXTENSION�Name: apm-lambda-extension�State: Ready�Events: [INVOKE,SHUTDOWN]
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.669Z","log":{"logger":"elastic-apm-node"},"awsRequestId":"c5ab3c3e-45e1-49b2-8502-f2599bca0c14","ecs":{"version":"1.6.0"},"message":"lambda: fn start"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.669Z","log":{"logger":"elastic-apm-node"},"awsRequestId":"c5ab3c3e-45e1-49b2-8502-f2599bca0c14","ecs":{"version":"1.6.0"},"message":"lambda: setExtraMetadata"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.654Z","log.origin":{"file.name":"extension/route_handlers.go","file.line":38},"message":"Handling APM server Info Request","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.671Z","log.origin":{"file.name":"apm-lambda-extension/main.go","file.line":125},"message":"Received event.","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.671Z","log.origin":{"file.name":"apm-lambda-extension/main.go","file.line":126},"message":"{\t\"eventType\": \"INVOKE\",\t\"deadlineMs\": 1658782398653,\t\"requestId\": \"c5ab3c3e-45e1-49b2-8502-f2599bca0c14\",\t\"invokedFunctionArn\": \"arn:aws:lambda:us-west-2:565513978173:function:platy-1156-graph-staging-graphql\",\t\"tracing\": {\t\t\"type\": \"X-Amzn-Trace-Id\",\t\t\"value\": \"Root=1-62df029e-3441f62023c5edb911689bee;Parent=1b499c47507d745b;Sampled=0\"\t}}","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.672Z","log.origin":{"file.name":"logsapi/subscribe.go","file.line":165},"message":"Received log event platform.logsSubscription","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.672Z","log.origin":{"file.name":"logsapi/subscribe.go","file.line":165},"message":"Received log event platform.start","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.672Z","log.origin":{"file.name":"logsapi/subscribe.go","file.line":165},"message":"Received log event platform.extension","ecs.version":"1.6.0"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.673Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","_encodedMetadata":"{\"metadata\":{\"service\":{\"name\":\"platy-1156-graph-staging-graphql\",\"environment\":\"development\",\"runtime\":{\"name\":\"AWS_Lambda_nodejs14.x\",\"version\":\"14.19.3\"},\"language\":{\"name\":\"javascript\"},\"agent\":{\"name\":\"nodejs\",\"version\":\"3.37.0\"},\"version\":\"$LATEST\",\"framework\":{\"name\":\"AWS Lambda\"},\"node\":{\"configured_name\":\"2022/07/25/[$LATEST]5344006a870f45dea08b93fe11bd1121\"}},\"process\":{\"pid\":17,\"ppid\":1,\"title\":\"/var/lang/bin/node\",\"argv\":[\"/var/lang/bin/node\",\"/var/runtime/index.js\"]},\"system\":{\"hostname\":\"169.254.81.97\",\"architecture\":\"x64\",\"platform\":\"linux\"},\"cloud\":{\"provider\":\"aws\",\"region\":\"us-west-2\",\"service\":{\"name\":\"lambda\"},\"account\":{\"id\":\"565513978173\"}}}}","ecs":{"version":"1.6.0"},"message":"_resetEncodedMetadata"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.673Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","ecs":{"version":"1.6.0"},"message":"maybe uncork (expectExtraMetadata)"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.675Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start trace {\"trans\":\"8011fbd21ad2b98c\",\"trace\":\"7ff3b3d792a127f3fdbc437efb42ab3e\",\"name\":\"unnamed\",\"type\":\"lambda\",\"subtype\":null,\"action\":null}"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.676Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<Transaction(8011fb, 'platy-1156-graph-staging-graphql')> )","ecs":{"version":"1.6.0"},"message":"supersedeWithTransRunContext(<Trans 8011fbd21ad2b98c>)"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.676Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction name {\"trans\":\"8011fbd21ad2b98c\",\"trace\":\"7ff3b3d792a127f3fdbc437efb42ab3e\",\"name\":\"OPTIONS /staging/{proxy+}\"}"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.695Z","log":{"logger":"elastic-apm-node"},"awsRequestId":"c5ab3c3e-45e1-49b2-8502-f2599bca0c14","ecs":{"version":"1.6.0"},"message":"lambda: fn end"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.695Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction result {\"trans\":\"8011fbd21ad2b98c\",\"trace\":\"7ff3b3d792a127f3fdbc437efb42ab3e\",\"result\":\"HTTP 2xx\"}"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.696Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext<> )","ecs":{"version":"1.6.0"},"message":"addEndedTransaction(OPTIONS /staging/{proxy+})"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.697Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending transaction {\"trans\":\"8011fbd21ad2b98c\",\"trace\":\"7ff3b3d792a127f3fdbc437efb42ab3e\"}"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.697Z","log":{"logger":"elastic-apm-node"},"trans":"8011fbd21ad2b98c","name":"OPTIONS /staging/{proxy+}","trace":"7ff3b3d792a127f3fdbc437efb42ab3e","type":"request","result":"HTTP 2xx","duration":21.878,"ecs":{"version":"1.6.0"},"message":"ended transaction"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.713Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"51e08a2ff86788a7fba6e9ab90364580","ecs":{"version":"1.6.0"},"message":"intake request start"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.715Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","encodeTimeMs":0.560163,"fullTimeMs":16.308783,"numEvents":1,"numBytes":862,"ecs":{"version":"1.6.0"},"message":"_writeBatch"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.715Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","activeIntakeReq":true,"lambdaEnd":true,"ecs":{"version":"1.6.0"},"message":"_writeFlush"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.755Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"51e08a2ff86788a7fba6e9ab90364580","ecs":{"version":"1.6.0"},"message":"gzipStream \"finish\""}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.755Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"51e08a2ff86788a7fba6e9ab90364580","timeout":10000,"ecs":{"version":"1.6.0"},"message":"start intakeResTimer"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.756Z","log.origin":{"file.name":"extension/route_handlers.go","file.line":78},"message":"Handling APM Data Intake","ecs.version":"1.6.0"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.773Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"51e08a2ff86788a7fba6e9ab90364580","ecs":{"version":"1.6.0"},"message":"gzipStream \"end\""}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.773Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"51e08a2ff86788a7fba6e9ab90364580","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart gzipStream"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.774Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"51e08a2ff86788a7fba6e9ab90364580","ecs":{"version":"1.6.0"},"message":"intakeReq \"finish\""}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.774Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"51e08a2ff86788a7fba6e9ab90364580","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeReq"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.775Z","log.origin":{"file.name":"extension/apm_server_transport.go","file.line":238},"message":"Adding agent data to buffer to be sent to apm server","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.775Z","log.origin":{"file.name":"extension/apm_server_transport.go","file.line":166},"message":"Sending data chunk to APM server","ecs.version":"1.6.0"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.777Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"51e08a2ff86788a7fba6e9ab90364580","statusCode":202,"reqFinished":true,"ecs":{"version":"1.6.0"},"message":"intakeReq \"response\""}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.778Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"51e08a2ff86788a7fba6e9ab90364580","ecs":{"version":"1.6.0"},"message":"intakeRes \"end\""}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.778Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"51e08a2ff86788a7fba6e9ab90364580","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeRes"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.778Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"51e08a2ff86788a7fba6e9ab90364580","timeline":[[73.463793,"completePart gzipStream",null],[74.058807,"completePart intakeReq",null],[77.888503,"completePart intakeRes",null]],"bytesWritten":828,"backoffDelayMs":0,"ecs":{"version":"1.6.0"},"message":"conclude intake request: success"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.778Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","ecs":{"version":"1.6.0"},"message":"_signalLambdaEnd start"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.780Z","log.origin":{"file.name":"extension/route_handlers.go","file.line":78},"message":"Handling APM Data Intake","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.780Z","log.origin":{"file.name":"apm-lambda-extension/main.go","file.line":176},"message":"Received agent done signal","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.780Z","log.origin":{"file.name":"apm-lambda-extension/main.go","file.line":95},"message":"Waiting for background data send to end","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.780Z","log.origin":{"file.name":"logsapi/subscribe.go","file.line":178},"message":"Current invocation over. Interrupting logs processing goroutine","ecs.version":"1.6.0"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.780Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","durationMs":2.111845000181347,"ecs":{"version":"1.6.0"},"message":"signaled lambda invocation done"}
{"log.level":"trace","@timestamp":"2022-07-25T20:52:48.781Z","log":{"logger":"elastic-apm-node"},"awsRequestId":"c5ab3c3e-45e1-49b2-8502-f2599bca0c14","ecs":{"version":"1.6.0"},"message":"lambda: wrapper end"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.794Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","apmServerVersion":"7.15.2","ecs":{"version":"1.6.0"},"message":"fetched APM Server version"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.806Z","log.origin":{"file.name":"extension/apm_server_transport.go","file.line":200},"message":"APM server Transport status set to Healthy","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.806Z","log.origin":{"file.name":"extension/apm_server_transport.go","file.line":182},"message":"Transport status set to healthy","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.806Z","log.origin":{"file.name":"extension/apm_server_transport.go","file.line":183},"message":"APM server response body: ","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.806Z","log.origin":{"file.name":"extension/apm_server_transport.go","file.line":184},"message":"APM server response status code: 202","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.806Z","log.origin":{"file.name":"extension/apm_server_transport.go","file.line":85},"message":"Invocation context cancelled, not processing any more agent data","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.806Z","log.origin":{"file.name":"extension/apm_server_transport.go","file.line":101},"message":"Flush started - Checking for agent data","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-07-25T20:52:48.806Z","log.origin":{"file.name":"extension/apm_server_transport.go","file.line":110},"message":"Flush ended - No agent data on buffer","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-07-25T20:52:48.806Z","log.origin":{"file.name":"apm-lambda-extension/main.go","file.line":112},"message":"Waiting for next event...","ecs.version":"1.6.0"}
END RequestId: c5ab3c3e-45e1-49b2-8502-f2599bca0c14
REPORT RequestId: c5ab3c3e-45e1-49b2-8502-f2599bca0c14�Duration: 153.66 ms�Billed Duration: 154 ms�Memory Size: 1024 MB�Max Memory Used: 144 MB�Init Duration: 1683.36 ms�

@trentm
Copy link
Member

trentm commented Jul 25, 2022

The log above shows me that there is no graphql.graphql(...) or graphql.execute(...) call made -- at least not that the APM agent noticed.

We'll have to dig in. If you have a small code repro showing how this is being used that would help immensely.

@trentm trentm added this to the 8.5 milestone Jul 28, 2022
@wjensen-godaddy
Copy link
Author

I think you should be able to reproduce the issue with this (I was able to using an almost identical setup):

serverless.yml

service: graph

frameworkVersion: "3"

plugins:
  - serverless-esbuild
  - serverless-offline

provider:
  name: aws
  runtime: nodejs14.x
  region: us-west-2
  environment:
    NODE_OPTIONS: "-r elastic-apm-node/start"
    ELASTIC_APM_LAMBDA_APM_SERVER: ${env:ELASTIC_APM_LAMBDA_APM_SERVER, ''}
    ELASTIC_APM_SECRET_TOKEN: ${env:ELASTIC_APM_SECRET_TOKEN, ''}
    ELASTIC_APM_LOG_LEVEL: trace

functions:
  graphql:
    # this is formatted as <FILENAME>.<HANDLER>
    handler: src/index.graphqlHandler
    layers:
      - arn:aws:lambda:us-west-2:267093732750:layer:elastic-apm-extension-ver-1-0-2-x86_64:1
      - arn:aws:lambda:us-west-2:267093732750:layer:elastic-apm-node-ver-3-37-0:1
    events:
    - http:
        path: /graphql
        method: post
        cors: true
    - http:
        path: /graphql
        method: get
        cors: true

src/index.ts

const { ApolloServer, gql } = require('apollo-server-lambda');
const { ApolloServerPluginLandingPageGraphQLPlayground } = require('apollo-server-core');

// Construct a schema, using GraphQL schema language
const typeDefs = gql`
  type Query {
    hello: String
  }
`;

// Provide resolver functions for your schema fields
const resolvers = {
  Query: {
    hello: () => 'Hello world!'
  }
};

const server = new ApolloServer({
  typeDefs,
  resolvers,

  // By default, the GraphQL Playground interface and GraphQL introspection
  // is disabled in "production" (i.e. when `process.env.NODE_ENV` is `production`).
  //
  // If you'd like to have GraphQL Playground and introspection enabled in production,
  // install the Playground plugin and set the `introspection` option explicitly to `true`.
  introspection: true,
  plugins: [ApolloServerPluginLandingPageGraphQLPlayground()]
});

exports.graphqlHandler = server.createHandler();

@trentm
Copy link
Member

trentm commented Jul 29, 2022

@wjensen-godaddy Thanks! I will hopefully be able to dig into this soon.

However, before then, a thing from your serverless.yml jumps out at me:

plugins:
  - serverless-esbuild

It is likely that esbuild's bundling is breaking the APM agent's attempt to instrument modules. The bundling necessarily replaces use of node's core require(...) with just inlining the bundled module, so that it looks something like:

...
var __commonJS = (cb, mod) => function __require() {
  return mod || (0, cb[__getOwnPropNames(cb)[0]])((mod = { exports: {} }).exports, mod), mod.exports;
};
...
// node_modules/somemodule/index.js
var require_somemodule = __commonJS({
  "node_modules/somemodule/index.js"(exports, module2) {
    "use strict";
...
// src/functions/hello/handler.ts
var hello = async (event, context) => {
  var _a;
...

In this case (assuming the APM agent is even function when bundled itself -- which I don't think it is), the APM agent never "sees" that somemodule is loaded, so it cannot instrument it.

I just merged this update to the APM agent docs that (among some other things) tries to improve the documentation around using bundlers with the APM agent: #2837
Here is where bundlers (including a second on esbuild) are discussed: https://www.elastic.co/guide/en/apm/agent/nodejs/master/starting-the-agent.html#start-bundlers

tl;dr: For the APM agent to work, it has to be excluded from the bundle. Plus any modules that you want the APM agent to instrument need to be excluded as well. Esbuild and webpack call this "externals" in their configuration.

It looks like the serverless-esbuild plugin has a config option for externals: https://www.serverless.com/plugins/serverless-esbuild#external-dependencies

Would you be able to try your example with the following added to the "serverless.yml"?

custom:
  esbuild:
    external:
      - 'elastic-apm-node'
      - 'graphql'
      - 'apollo-server-core'
      - 'express'

If not, I'll give this a go when I can get back to this ticket.

@wjensen-godaddy
Copy link
Author

🤦‍♂️ That was it!

Thanks for the help!

Since we're using the lambda layers, this config worked (also had to add apollo-server-lambda):

external:
  - 'graphql'
  - 'apollo-server-core'
  - 'apollo-server-lambda'
  - 'express'

@wjensen-godaddy
Copy link
Author

I might have spoke too soon. The graphql option is now in the request dropdown, but we're still seeing all transactions grouped under POST /staging/{proxy+}.

image

@trentm trentm self-assigned this Aug 8, 2022
@trentm trentm moved this from Planned to In Progress in APM-Agents (OLD) Aug 8, 2022
@trentm
Copy link
Member

trentm commented Aug 8, 2022

Thanks for the repro information. I was able to start looking today. Here is my working repo at "v1.0.0": https://github.com/trentm/example-apollo-lambda/tree/v1.0.0
This is using vanilla JS (no TypeScript, no esbuild). I get working tracing with (a) a "GraphQL: ..." span and (b) a transaction name that is the name of the Lambda function ... which is what I expect for a plain Lambda function.

Screen Shot 2022-08-08 at 2 40 14 PM

Next I'll try to work closer to what you have and see if I can answer:

  1. Why my transaction.name is the Lambda function name and yours POST /staging/{proxy+}.
  2. Whether both of those are wrong and what needs to change to have transaction.name be GraphQL: ... (per our spec)

@trentm
Copy link
Member

trentm commented Aug 8, 2022

  1. Why my transaction.name is the Lambda function name and yours POST /staging/{proxy+}.

This was because I was using serverless invoke ... to invoke my Lambda function. That invokes the function directly, rather than making an HTTP request to the API Gateway trigger for the function. When I do this:

POST https://[REDACTED].execute-api.us-east-1.amazonaws.com/dev
content-type: application/json

{"operationName": null, "variables": null, "query": "{ hello }"}

I get the $method $path transaction naming that you see.

Screen Shot 2022-08-08 at 3 27 27 PM

@trentm
Copy link
Member

trentm commented Aug 8, 2022

2. ... what needs to change to have transaction.name be [a GraphQL-y name]

Found the problem here. The APM agent's Lambda instrumentation was setting transaction.name in such a way that the graphql instrumentation's setting of transaction.name was effectively ignored. The fix is straightforward.

After deploying a dev layer of the APM agent with the fix, switching my serverless function to it, and invoking via:

POST https://[REDACTED].execute-api.us-east-1.amazonaws.com/dev
content-type: application/json

{"query": "query Fuzzy { hello }"}

I get transactions with the name Fuzzy hello:

Screen Shot 2022-08-08 at 3 55 04 PM

(Side note: This isn't using the "GraphQL: " prefix that is discussed in our GraphQL tracing spec... but that is a separate issue.)

@wjensen-godaddy
Copy link
Author

@trentm Awesome! Thank you for such a quick response and fix!

APM-Agents (OLD) automation moved this from In Progress to Done Aug 10, 2022
@trentm
Copy link
Member

trentm commented Aug 11, 2022

FYI: elastic-apm-node@3.38.0 is now published with the fix for this (#2872).

n-e pushed a commit to keplr-team/apm-agent-nodejs that referenced this issue Aug 12, 2022
…low subsequent override by graphql instrumentation (elastic#2865)

Before this the Lambda instrumentation was setting `trans.name = ...`,
which (via the Transaction.name setter) would set `trans._customName`,
which has higher prio than the `trans._defaultName`. Setting
`_customName` is intended for the *user* to override. If a Lambda
function is using GraphQL, the graphql instrumentation should be able to
override the transaction name.

Fixes: elastic#2832
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
agent-nodejs Make available for APM Agents project planning. aws-λ-extension community
Projects
2 participants