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

feat: add 'captureBody' support for Hapi #2618

Merged
merged 5 commits into from
Mar 23, 2022

Conversation

trentm
Copy link
Member

@trentm trentm commented Mar 22, 2022

The body of incoming requests to an HTTP server using the Hapi
framework will be recorded in relevant APM transaction and error
objects depending on the captureBody config var setting.

Closes: #1905

Checklist

  • Implement code
  • Add tests
  • Add CHANGELOG.asciidoc entry
  • Commit message follows commit guidelines

The body of incoming requests to an HTTP server using the Hapi
framework will be recorded in relevant APM transaction and error
objects depending on the `captureBody` config var setting.

Closes: #1905
@trentm trentm requested a review from astorm March 22, 2022 20:52
@trentm trentm self-assigned this Mar 22, 2022
@github-actions github-actions bot added the agent-nodejs Make available for APM Agents project planning. label Mar 22, 2022
@trentm
Copy link
Member Author

trentm commented Mar 22, 2022

@mshustov You know Hapi much better than I. Is onPostAuth the best place in the Hapi Request lifecycle (https://hapi.dev/api/?v=20.2.1#request-lifecycle) to capture the parsed request.payload? It is the first lifecyle event after "Payload processing" that is always run.

@trentm trentm removed the request for review from astorm March 22, 2022 22:08
@trentm
Copy link
Member Author

trentm commented Mar 22, 2022

removed the request for review ...

I have a test hang with node v16 and v17 to solve first.

@apmmachine
Copy link
Contributor

apmmachine commented Mar 22, 2022

💚 Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS
Pipeline View Test View Changes Artifacts preview preview

Expand to view the summary

Build stats

  • Start Time: 2022-03-23T16:39:57.835+0000

  • Duration: 46 min 4 sec

Test stats 🧪

Test Results
Failed 0
Passed 242815
Skipped 0
Total 242815

🤖 GitHub comments

To re-run your PR in the CI, just comment with:

  • /test : Re-trigger the build.

  • run module tests for <modules> : Run TAV tests for one or more modules, where <modules> can be either a comma separated list of modules (e.g. memcached,redis) or the string literal ALL to test all modules

  • run benchmark tests : Run the benchmark test only.

  • run elasticsearch-ci/docs : Re-trigger the docs validation. (use unformatted text in the comment!)

…ated legacy hapi) and node >=16 *hangs*. No need to support this.
@trentm
Copy link
Member Author

trentm commented Mar 23, 2022

run module tests for hapi,@hapi/hapi

@trentm
Copy link
Member Author

trentm commented Mar 23, 2022

@@ -60,13 +61,16 @@ module.exports = function (hapi, agent, { version, enabled }) {
if (typeof server.ext === 'function') {
server.ext('onPreAuth', onPreAuth)
server.ext('onPreResponse', onPreResponse)
if (agent._conf.captureBody !== 'off') {
server.ext('onPostAuth', onPostAuth)

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is onPostAuth the best place in the Hapi Request lifecycle (https://hapi.dev/api/?v=20.2.1#request-lifecycle) to capture the parsed request.payload?

Yeah, it seems that payload parsing is called before https://github.com/hapijs/hapi/blob/master/lib/route.js#L252-L270
Also, according to Hapi.js in action book, 6. Read/Parse payload step happens before onPostAuth callback.

05fig05_alt

@mshustov
Copy link

mshustov commented Mar 23, 2022

@trentm LGTM. Tested with Kibana, it works fine. 👌
2022-03-23_16-25-19

@trentm
Copy link
Member Author

trentm commented Mar 23, 2022

LGTM. Tested with Kibana, it works fine. 👌

@mshustov Good to hear.
I still have a failure in our "TAV" (test all versions) tests with node v16 and v17 when testing with @hapi/hapi@20.1.1 that I need to understand. @hapi/hapi@20.1.2 and newer passed the tests.

@trentm
Copy link
Member Author

trentm commented Mar 23, 2022

The TAV run failed https://apm-ci.elastic.co/blue/organizations/jenkins/apm-agent-nodejs%2Fapm-agent-nodejs-mbp/detail/PR-2618/3/pipeline
The failures were with testing @hapi/hapi with node 16 and 17, starting
with @hapi/hapi@20.1.1.

[2022-03-23T00:55:38.851Z] node_tests_1  | -- required packages ["@hapi/hapi@20.1.2"]
[2022-03-23T00:55:38.851Z] node_tests_1  | -- installing ["@hapi/hapi@20.1.2"]
[2022-03-23T00:55:43.059Z] node_tests_1  | -- running test "node test/instrumentation/modules/hapi/basic.test.js" with @hapi/hapi
[2022-03-23T00:55:43.319Z] node_tests_1  | -- running test "node test/instrumentation/modules/hapi/set-framework-hapihapi.test.js" with @hapi/hapi
[2022-03-23T00:55:43.889Z] node_tests_1  | -- required packages ["@hapi/hapi@20.1.1"]
[2022-03-23T00:55:43.889Z] node_tests_1  | -- installing ["@hapi/hapi@20.1.1"]
[2022-03-23T00:55:48.145Z] node_tests_1  | -- running test "node test/instrumentation/modules/hapi/basic.test.js" with @hapi/hapi
[2022-03-23T00:55:48.145Z] node_tests_1  | /app/node_modules/@hapi/hapi/lib/request.js:499
[2022-03-23T00:55:48.145Z] node_tests_1  |             if (this.response.statusCode === 500 &&
[2022-03-23T00:55:48.145Z] node_tests_1  |                               ^
[2022-03-23T00:55:48.145Z] node_tests_1  |
[2022-03-23T00:55:48.145Z] node_tests_1  | TypeError: Cannot read properties of null (reading 'statusCode')
[2022-03-23T00:55:48.145Z] node_tests_1  |     at Request._finalize (/app/node_modules/@hapi/hapi/lib/request.js:499:31)
[2022-03-23T00:55:48.145Z] node_tests_1  |     at Request._reply (/app/node_modules/@hapi/hapi/lib/request.js:436:18)
[2022-03-23T00:55:48.145Z] node_tests_1  |     at Request._execute (/app/node_modules/@hapi/hapi/lib/request.js:281:14)
[2022-03-23T00:55:48.145Z] node_tests_1  |     at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2022-03-23T00:55:48.145Z] node_tests_1  | -- detected failing command, flushing stdout...
[2022-03-23T00:55:48.145Z] node_tests_1  | TAP version 13
[2022-03-23T00:55:48.145Z] node_tests_1  | # extract URL from request
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 1 no error from startServer
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 2 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 3 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 4 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 5 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 6 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 7 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 8 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 9 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | # route naming
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 10 null
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 11 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 12 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 13 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 14 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 15 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 16 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 17 should be strictly equal
[2022-03-23T00:55:48.146Z] node_tests_1  | # captureBody
[2022-03-23T00:55:48.146Z] node_tests_1  | ok 18 null
[2022-03-23T00:55:48.146Z] node_tests_1  |
[2022-03-23T00:55:48.146Z] node_tests_1  | -- fatal: Test exited with code 1

This failure happens even if I disable the added captureBody processing,
and also when disabling the agent. The issue occurs for a Hapi server handling
a POST (rather than just a GET, which is all our tests were testing before
this). @hapi/hapi@20.1.2 fixes the issue hapijs/hapi#4225
Any earlier happy version (at least back to 18.x), hits the same issue.

I.e. to use @hapi/hapi with node v16 or later requires at least 20.1.2.

Handled in 3a787b4

@trentm
Copy link
Member Author

trentm commented Mar 23, 2022

run module tests for hapi,@hapi/hapi

@trentm trentm requested a review from astorm March 23, 2022 16:06
@trentm
Copy link
Member Author

trentm commented Mar 23, 2022

Copy link
Contributor

@astorm astorm left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code looks like it does the thing. I also spun up a quick HAPI test app with the following route

    server.route({
      method: 'POST',
      path: '/test-post',
      handler: (request, h) => {
          console.log(request.payload)
          return 'Hello World!' + "\n" + JSON.stringify(request.payload);
      }
    });

and posted via curl localhost:3000/test-post -d 'foo=bar', and the request body made it through to the http.request.body.original field in the UI

thereitis

Approving

lib/instrumentation/modules/hapi.js Show resolved Hide resolved
function onPostAuth (request, reply) {
if (request.payload && request.raw && request.raw.req) {
// Save the parsed req body to be picked up by getContextFromRequest().
request.raw.req.payload = request.payload
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks like our parse treats .payload, .json, and .body the same so .payload is an appropriate place for this

var body = req.json || req.body || req.payload
👍

@@ -15,10 +15,11 @@ module.exports = function (hapi, agent, { version, enabled }) {
agent.logger.debug('hapi version %s not supported - aborting...', version)
return hapi
}
const isHapiGte17 = semver.satisfies(version, '>=17')
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 for caching/memoizing/whateveritscalledthesedays the value of the call to semver.satisfies

@trentm
Copy link
Member Author

trentm commented Mar 23, 2022

the request body made it through to the http.request.body.original field in the UI

@astorm Whoa what is going on with the http.request.body.original value in your screenshot. It looks like there is an extra single-quote on the "foo": {"'foo": "bar"}. Am I misreading that?

Oh there is a trailing single-quote on the "bar" as well. So I'm guessing that curl call included the literal single-quotes for the form-encoded POST body?

@astorm
Copy link
Contributor

astorm commented Mar 23, 2022

Oh there is a trailing single-quote on the "bar" as well. So I'm guessing that curl call included the literal single-quotes for the form-encoded POST body?

@trentm trentm merged commit 37d7d2e into main Mar 23, 2022
@trentm trentm deleted the trentm/issue1905-hapi-capture-body branch March 23, 2022 20:04
@astorm
Copy link
Contributor

astorm commented Mar 23, 2022

Oh there is a trailing single-quote on the "bar" as well. So I'm guessing that curl call included the literal single-quotes for the form-encoded POST body?

Good question. This looks like a weird side effect of shell escaping in a bash script I used for testing and a type 1 thinking copy-pasta. I call the script like this

curl-sleep.bash "localhost:3000/test-post -d 'foo=bar'"

and curl-sleep uses that like curl $1, so those single quotes ended up included as literals. FWIW a regular invocation of curl

curl localhost:3000/test-post -d 'foo=bar'

does not produce those extra quotes.

TL;DR; -- all clear :)

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.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Hapi Instrumentation does not Capture Request Body
4 participants