Arvados

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

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.

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.

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.

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)?

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?

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)

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

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

LGTM thanks!

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 .

Tom Clegg wrote:

LGTM. Added a test.

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

Thanks! Merged.