Project

General

Profile

Actions

Bug #17830

closed

Controller doesn't propagate back X-Request-Id headers on "new code path" endpoints

Added by Lucas Di Pentima almost 3 years ago. Updated over 2 years ago.

Status:
Resolved
Priority:
Normal
Assigned To:
Category:
API
Target version:
Story points:
-
Release relationship:
Auto

Description

Examples:

Request to arvbox's controller

$ curl -v -H "Authorization: OAuth2 xxxtokenxxx" http://localhost:8003/arvados/v1/container_requests/invalid
*   Trying 127.0.0.1...
* TCP_NODELAY set
...
< HTTP/1.1 404 Not Found
< Access-Control-Allow-Headers: Authorization, Content-Type, X-Http-Method-Override
< Access-Control-Allow-Methods: GET, HEAD, PUT, POST, PATCH, DELETE
< Access-Control-Allow-Origin: *
< Access-Control-Max-Age: 86486400
< Content-Type: application/json
< X-Content-Type-Options: nosniff
< Date: Tue, 22 Jun 2021 20:30:53 GMT
< Content-Length: 128
<
{"errors":["//railsapi.internal/arvados/v1/container_requests/invalid: 404 Not Found: Path not found (req-nmeiu3bkuepn10km5uv4)"]}
* Connection #0 to host localhost left intact

Request to arvbox's railsAPI

$ curl -v -H "Authorization: OAuth2 xxxtokenxxx" http://localhost:8004/arvados/v1/container_requests/invalid
*   Trying 127.0.0.1...
...
< HTTP/1.1 404 Not Found
< Content-Type: application/json; charset=utf-8
< Transfer-Encoding: chunked
< Connection: keep-alive
< Status: 404 Not Found
< Cache-Control: no-cache
< Access-Control-Allow-Origin: *
< Referrer-Policy: strict-origin-when-cross-origin
< X-Permitted-Cross-Domain-Policies: none
< Access-Control-Max-Age: 86486400
< X-XSS-Protection: 1; mode=block
< X-Request-Id: e04d4235-ffc4-4df2-ac78-3bd1031fa302
< Access-Control-Allow-Headers: Authorization, Content-Type
< Access-Control-Allow-Methods: GET, HEAD, PUT, POST, DELETE
< X-Download-Options: noopen
< X-Runtime: 0.014451
< X-Frame-Options: SAMEORIGIN
< X-Content-Type-Options: nosniff
< Date: Tue, 22 Jun 2021 20:33:19 GMT
< X-Powered-By: Phusion Passenger 6.0.2
< Server: nginx/1.15.8 + Phusion Passenger 6.0.2
<
* Connection #0 to host localhost left intact
{"errors":["Path not found (req-84gl5jhcyy7oqfkxp19r)"],"error_token":"1624393999+99d17f5f"}

Not sure why I'm getting a uuid-like X-Request-Id header when making requests directly to railsAPI, but if I send a custom one with the curl call, I get it back correctly.

https://api.rubyonrails.org/classes/ActionDispatch/RequestId.html


Subtasks 1 (0 open1 closed)

Task #17865: Review 17830-reqid-header-propagation-fixResolvedLucas Di Pentima07/22/2021Actions

Related issues

Related to Arvados - Bug #18008: [api] reqid not always being recorded in the api server logNewActions
Blocks Arvados - Bug #17779: Exceptions thrown by the Python SDK should include the request id if possibleResolvedTom Clegg09/29/2021Actions
Blocks Arvados - Bug #17492: Exceptions thrown by the Ruby SDK should include the request id if possibleResolvedLucas Di Pentima02/08/2022Actions
Actions #1

Updated by Lucas Di Pentima almost 3 years ago

The /arvados/v1/collections endpoint doesn't even include the req-xxxxx ID on the response message:

$ curl -v -H "Authorization: OAuth2 xxxtokenxxx" http://localhost:8003/arvados/v1/collections/invalid
*   Trying 127.0.0.1...
...
< HTTP/1.1 404 Not Found
< Access-Control-Allow-Headers: Authorization, Content-Type, X-Http-Method-Override
< Access-Control-Allow-Methods: GET, HEAD, PUT, POST, PATCH, DELETE
< Access-Control-Allow-Origin: *
< Access-Control-Max-Age: 86486400
< Content-Type: application/json
< X-Content-Type-Options: nosniff
< Date: Tue, 22 Jun 2021 20:51:43 GMT
< Content-Length: 25
<
{"errors":["not found"]}
* Connection #0 to host localhost left intact
Actions #2

Updated by Peter Amstutz almost 3 years ago

  • Target version changed from 2021-07-07 sprint to 2021-07-21 sprint
Actions #3

Updated by Lucas Di Pentima almost 3 years ago

  • Blocks Bug #17779: Exceptions thrown by the Python SDK should include the request id if possible added
Actions #4

Updated by Lucas Di Pentima almost 3 years ago

  • Blocks Bug #17492: Exceptions thrown by the Ruby SDK should include the request id if possible added
Actions #5

Updated by Peter Amstutz over 2 years ago

  • Assigned To set to Lucas Di Pentima
Actions #6

Updated by Ward Vandewege over 2 years ago

  • Description updated (diff)
Actions #7

Updated by Lucas Di Pentima over 2 years ago

  • Status changed from New to In Progress
Actions #8

Updated by Lucas Di Pentima over 2 years ago

  • Target version changed from 2021-07-21 sprint to 2021-08-04 sprint
Actions #9

Updated by Lucas Di Pentima over 2 years ago

Updates at e57008566 - branch 17830-reqid-header-propagation-fix
Test run: developer-run-tests: #2600

  • Fixes an issue in RailsAPI related to the RequestId middleware introduced in rails 5.0; left both df2ba5f & 705bb88 just in case my reviewer prefers the former rather than the latter.
  • Fixes an issue in controller where the RailsAPI's response X-Request-Id header was not added to the final response.
  • Adds tests.
Actions #10

Updated by Tom Clegg over 2 years ago

I think there's a mismatch in expectations between controller and router. Controller's http server comes from service.Command(), which should ensure every request has an X-Request-Id header by the time it gets to a lib/controller/router. So the new TestRequestIDHeader() (ensure request ID is added if not present) in lib/controller/router tests checks something we never actually use. I suspect if we tested this somewhere that uses the whole stack (perhaps lib/controller/integration_test.go?) we wouldn't need the change to addRoute(), the fix would be much simpler -- just add w.Header().Set("X-Request-Id", req.Header.Get("X-Request-Id")) in sendResponse().

The fix for the "request ID not propagated to error messages / logs" problem on the RailsAPI side LGTM.

Actions #11

Updated by Lucas Di Pentima over 2 years ago

Updates at 5ae9c613a
Test run: developer-run-tests: #2603

  • Rebased & dropped the commit that disabled the middleware in RailsAPI to clean up the history.
  • Following the above suggestions, copies X-Request-Id header from the request to the response.
  • Moves tests to integration_test.go.
Actions #12

Updated by Tom Clegg over 2 years ago

LGTM, thanks.

Either I'm missing it, or we don't quite have a test that confirms the request IDs are propagated through controller to Rails. Perhaps we could do this by adding some cases to TestRequestIDHeader that check that the request ID quoted in the "not found" error message text (from Rails) matches the response header (from controller)? Worth checking one path that uses the "new" code path (collections/zzzzz-4zz18-notfound) and one that uses the old code path (specimens/zzzzz-nonexistent)?

Actions #13

Updated by Lucas Di Pentima over 2 years ago

Updates at 91f7e961f
Test run: developer-run-tests: #2610

Thanks Tom for the suggestion on adding more test cases! They exposed one more issue where the header wasn't added to the response when asking for "new code path" (nonexistent) resources. I've moved the response's header setting to router.go just after setting the request id context, I think that place is the one where which we care about request id propagation, although it could be set before any potential sendError() call too. WDYT?

Actions #14

Updated by Tom Clegg over 2 years ago

Come to think of it, I suppose that line could even go in source:sdk/go/httpserver/id_generator.go as soon as we decide it's worth having a request ID -- that would cover old+new code paths, and keep-web, keepproxy, etc.

                if req.Header.Get(HeaderRequestID) == "" {
                        if req.Header == nil {
                                req.Header = http.Header{}
                        }
                        req.Header.Set(HeaderRequestID, gen.Next())
                }
+               w.Header().Set("X-Request-Id", req.Header.Get("X-Request-Id"))
                h.ServeHTTP(w, req)
Actions #15

Updated by Lucas Di Pentima over 2 years ago

Update at bba516847
Test run: developer-run-tests: #2611

Moved the header setting call to id_generator.go as suggested.

Actions #16

Updated by Tom Clegg over 2 years ago

LGTM thanks!

Actions #17

Updated by Lucas Di Pentima over 2 years ago

  • Status changed from In Progress to Resolved
Actions #18

Updated by Ward Vandewege over 2 years ago

  • Related to Bug #18008: [api] reqid not always being recorded in the api server log added
Actions #19

Updated by Ward Vandewege over 2 years ago

Ready for review: fix the rails request_id logging in dcd77dd78f89a225cc9bcefc1930f8a54bc62791 on branch 17830-fix-rails-request_id-logging. Tests passed at developer-run-tests: #2711 .

Actions #20

Updated by Tom Clegg over 2 years ago

  • Target version changed from 2021-08-04 sprint to 2021-10-13 sprint
  • Assigned To changed from Lucas Di Pentima to Ward Vandewege
  • Status changed from Resolved to In Progress

LGTM. Added a test.

17830-fix-rails-request_id-logging @ 290695c429ea536bd4e4ee01ff76e0d770bc8021 -- developer-run-tests: #2716

Actions #21

Updated by Ward Vandewege over 2 years ago

Tom Clegg wrote:

LGTM. Added a test.

17830-fix-rails-request_id-logging @ 290695c429ea536bd4e4ee01ff76e0d770bc8021 -- developer-run-tests: #2716

Thanks! Merged.

Actions #22

Updated by Ward Vandewege over 2 years ago

  • Status changed from In Progress to Resolved
Actions #23

Updated by Ward Vandewege over 2 years ago

  • Release set to 42
Actions

Also available in: Atom PDF