Bug #17830

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

Added by Lucas Di Pentima 3 months ago. Updated 2 months ago.

Status:
Resolved
Priority:
Normal
Assigned To:
Category:
API
Target version:
Start date:
07/22/2021
Due date:
% Done:

100%

Estimated time:
(Total: 0.00 h)
Story points:
-

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

Task #17865: Review 17830-reqid-header-propagation-fixResolvedLucas Di Pentima


Related issues

Related to Arvados - Bug #18008: [api] reqid not always being recorded in the api server logNew

Blocks Arvados - Bug #17779: Exceptions thrown by the Python SDK should include the request id if possibleIn Progress

Blocks Arvados - Bug #17492: Exceptions thrown by the Ruby SDK should include the request id if possibleNew

Associated revisions

Revision 2f9bf6a1
Added by Lucas Di Pentima 2 months ago

Merge branch '17830-reqid-header-propagation-fix' into main. Closes #17830

Arvados-DCO-1.1-Signed-off-by: Lucas Di Pentima <>

History

#1 Updated by Lucas Di Pentima 3 months 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

#2 Updated by Peter Amstutz 3 months ago

  • Target version changed from 2021-07-07 sprint to 2021-07-21 sprint

#3 Updated by Lucas Di Pentima 3 months ago

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

#4 Updated by Lucas Di Pentima 3 months ago

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

#5 Updated by Peter Amstutz 3 months ago

  • Assigned To set to Lucas Di Pentima

#6 Updated by Ward Vandewege 3 months ago

  • Description updated (diff)

#7 Updated by Lucas Di Pentima 2 months ago

  • Status changed from New to In Progress

#8 Updated by Lucas Di Pentima 2 months ago

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

#9 Updated by Lucas Di Pentima 2 months ago

Updates at e57008566 - branch 17830-reqid-header-propagation-fix
Test run: https://ci.arvados.org/job/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.

#10 Updated by Tom Clegg 2 months 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.

#11 Updated by Lucas Di Pentima 2 months ago

Updates at 5ae9c613a
Test run: https://ci.arvados.org/job/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.

#12 Updated by Tom Clegg 2 months 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)?

#13 Updated by Lucas Di Pentima 2 months ago

Updates at 91f7e961f
Test run: https://ci.arvados.org/job/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?

#14 Updated by Tom Clegg 2 months 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)

#15 Updated by Lucas Di Pentima 2 months ago

Update at bba516847
Test run: https://ci.arvados.org/job/developer-run-tests/2611/

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

#16 Updated by Tom Clegg 2 months ago

LGTM thanks!

#17 Updated by Lucas Di Pentima 2 months ago

  • Status changed from In Progress to Resolved

#18 Updated by Ward Vandewege about 2 months ago

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

Also available in: Atom PDF