mrc-5048: Add request ID into logs

[r-ash]

@plietar has added request_id into Rust API in this mrc-ide/outpack_server#58, if a request is received with header x-request-id it will be included in log messages, if one not sent a request ID will be generated and included in the logs.

This PR adds the same pattern so we can use it across all our R APIs. Hopefully with this, if we send a request from Kotlin backend to any of our services we can trace it through with this ID.

This PR will

• Update github actions workflows (these were a fair bit out of date)
• If request includes a header x-request-id it will return it in the response header. If one not sent, it will generate a uuid.
• If logger is being used, it will add add request ID into all log messages
• If API author uses the logger which porcelain configures (i.e. the logger with name equal to the package name), it will also add the request ID into all logs from this

[r-ash]

These req, res args were not being used

[r-ash]

Note how users will have to get the logger if they want to use the request ID (and all other things configured by porcelain). They could also pass this through from when the logger is created in the api. We could add a function to make this easier.

[r-ash]

Think this has changed due to porcelain update

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 100.00%. Comparing base (18511c4) to head (6c35bd6).

Additional details and impacted files

@@            Coverage Diff            @@
##            master       #38   +/-   ##
=========================================
  Coverage   100.00%   100.00%           
=========================================
  Files           19        19           
  Lines          975       992   +17     
=========================================
+ Hits           975       992   +17     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[plietar]

Very nice. Just some minor points

[M-Kusumgar]

LGTM, tiny optional comment

[richfitz]

The advantage of this constant seem reduced by (I'm guessing) it needing to match the name used in FilterInject. You could use the .list argument there and do

FilterInject$new(.list = set_names(request_id, LOG_FILTER_REQUEST_ID_NAME))

which would reuse this constant at least

[richfitz]

This interaction with lgr feels like it's going to have performance issues each time (based on my previous experience with the package). Each request we'll be doing

• add_filter
• FilterInject creation
• remove_filter

I presume this means that when the request comes through we're checking to see "do we have the appropriate header" then if so adding additional data to the log output? Any reason this can't be done directly in porcelain_log_postserialize where we have req already? It's possible I'm missing something here though.

OTOH, it might be worth looking to see how bad this is performance wise - see if it's actually an issue with a quick benchmark with and without the header being present and see how long a roundtrip takes?

[r-ash]

We chatted about this in person but just putting this down here for future reference.

We can't just use porcelain_log_postserialize as we want to add the request ID into the logger so if a user writes a log call in their API impl it will pick up the request ID.

With plumber we have 4 hooks we can use preroute, postroute, preserialize and posterialize. In preroute we don't have a handle on the "HTTP_X_REQUEST_ID" so we need to do this after the preroute, but by actual code endpoint is run before we get to postroute. So we have to handle this in a filter.

I did some benchmarking on this, by running up the API in a background process with the add.chatty package I added in this PR. There isn't a huge amount of variation in timings

With no filter

rashton@wpia-dide270:~/projects/porcelain$ ./timeit curl -w "@curl_format.txt" -o /dev/null -s  "http://localhost:8552/?a=3&b=3"
Average: 0.00569371 N:  1000

With the filter which creates and removes the object every time

rashton@wpia-dide270:~/projects/porcelain$ ./timeit curl -w "@curl_format.txt" -o /dev/null -s  "http://localhost:9120/?a=3&b=3"
Average: 0.0055903 N:  1000

With updated filter which just changes the request ID on an the filter object which exists in cache

rashton@wpia-dide270:~/projects/porcelain$ ./timeit curl -w "@curl_format.txt" -o /dev/null -s  "http://localhost:9343/?a=3&b=3"
Average: 0.00546013 N:  1000

So very similar average times, less different than I was expecting. Feels nice to not have to create the object every time so have gone with that but previous impl I think read a little more simply so we can always revert back.