Moving from thread-local storage / logging to tokio task-level, with 0.5

[mgumbley-resilient]

Hi,
Thank you for all the work that's gone into 0.5! I wonder if there's already a solution to this problem we've encountered after upgrading from 0.4 to 0.5?

On each incoming request, our microservice receives a request id (and other data). We extract this id in a request fairing, and use log-mdc and log4rs to add this to the mapped diagnostic context, so that all our processing, and logging from 3rd party libraries is logged with this request id - this allows us to easily isolate everything that happened during processing each request. log-mdc uses thread_local! storage to record the id; we remove the id in a response fairing.

This worked fine in 0.4, but with the change to tokio and async in 0.5, the task handling each incoming request can migrate between threads, and so will be logged with the wrong id (that of the thread's first incoming request).

If there's no existing solution to this, I'm considering enhancing log-mdc and log4rs to use tokio task_local! storage - does anyone have any thoughts on this? Is there a better way?

Kind regards,
Matt Gumbley

[SergioBenitez]

The correct solution for this in Rocket is to use request-local cache. This is the same across 0.4 and 0.5.

https://rocket.rs/v0.4/guide/state/#request-local-state

https://rocket.rs/v0.5-rc/guide/state/#request-local-state

[SergioBenitez]

Ah, I assumed you were generating the request IDs on the server, not the client. Answering your question depends a lot on what you're trying to do and why you're trying to do it that way. Are there constraints? Why is the ID being generated client-side? Can it be generated server-side? Can you change how the ID is supplied, for instance, to being supplied via a header instead?

Nevertheless, I'll take a stab at the questions.

If I understand the request local state cache documentation correctly, the cache is available if you are implementing a request guard, i.e. a FromRequest. However our RequestData struct is decoded inside Rocket's Json data guard, with the decoded RequestData struct being made available to our route handlers - where we do not have access to the Request: this is only available to fairings, request guards and responders. (I've seen the FAQ on 'How do I get an &Request in a handler?')

This isn't quite right. "request-local state cache" is available anywhere an &Request is available. This includes data guards: the first argument to FromData::from_data is an &Request.

The only way I see of solving this is to re-implement the Json data guard as a request guard; from here I could store the request_id in the request local cache. This could then be passed into route handlers as usual. Is there a better way?

Based on the above, this could trivially be a data guard. If you really want to go down that path, see the last bit in https://rocket.rs/v0.5-rc/guide/faq/#response-headers for how to re-use the existing Json data guard.

A completely different approach would be to implement a fairing that reads the request ID from the request and stores it in request-local cache; a request guard can retrieve it later, and you could make that guard a Sentinel to ensure you don't forget to attach the fairing. In the fairing, you could use Data::peek() if you can guarantee that the ID is in the first part of the request body. Or if you can make the ID available via a header, then you can read it directly without shenanigans.

However, even if the above worked, how could the request_id be extracted from the request local cache for use in log-mdc/log4rs?

I suppose that depends entirely on where you're logging. For the general idea to make sense, you'll need to be inside of a request context when logging, and if you're inside of a request context then you have (potentially indirect) access to &Request which means you have access to request-local state. This could mean implementing a request guard to retrieve the ID from request-local cache (stored earlier by something, say a fairing or data guard).

[mgumbley-resilient]

Thank you Sergio, I'll look at the 'existing Json data guard re-use' you suggest; but some background to explain what we're trying to achieve, and the problems we're having:

The request ID that our Rocket microservice receives is used to assist in observability of the flow of a single request through many different microservices. It's generated by a single upstream service and is passed to us; we make further calls out to other services, and we pass it on to them. All services include it in their logs which are collected by a central log analysis system.

We're using log4rs as our logging framework, and log-mdc to attach the request ID to thread-local storage, so that every log statement generated by our route handlers, utility code, or third-party library code in the service of a single request will cause log4rs to emit the request ID. We have a response fairing that removes the request ID from thread-local storage at the end of processing a request.

Thread-local storage of the request ID is the wrong mechanism to use now that Rocket is using Tokio tasks; upon a task yielding, it can be assigned to a different thread when it continues executing - and so may cause logs to be emitted with the wrong request ID.

If I can extract the request ID in a request guard, such that it's stored in request-local cache, how can that request context be accessed implicitly by anything that logs (our route handler, utility & third party code that's using log)? Using thread-local storage and log-mdc works since the current thread ID can always be obtained, and is used to look up the thread's copy of the request ID in the log-mdc map. Could a similar tokio-task ID, or Request ID or address be obtained?

Many thanks,
Matt

[killpack]

@mgumbley-resilient - any chance you came up with a workaround or solution for this? I'm running into a similar problem where I need to pass around implicit context derived from the request and I'm not sure how to approach it.

[mgumbley-resilient]

Hi @killpack no, sorry, we haven't found a solution yet.

[mgumbley-resilient]

We found a solution for this (cc @killpack )...

After extracting the request ID from the incoming data, we store it in tokio's task_local! storage - using its sync_scope fn, so that it's only stored there for the duration of servicing the request.

We then use a custom Encode impl from log4rs that encodes each log request according to our needs (date/time, level, thread id, message) - and the value of the request ID retrieved from the tokio task_local! storage. It might not be present, if we're serving calls that don't provide the request ID (eg. healthcheck, from our monitoring system) so we default the logged ID to an empty string if not present on retrieval. This custom Encode impl is added to the set of 'deserialisers' that we initialise log4rs with, along with its .yaml configuration file, which sets this encoder against the appender we configure.

One thing to be aware of is that this only works if all your code is async - we have a mix of async and sync code (from the pre-Rocket-0.5 days; we're gradually making it all async). Our async request handlers use tokio's spawn_blocking around these sync parts. However this causes our request ID logging to fail - as inside spawn_blocking, you're in a different task. Thanks to a suggestion from the tokio maintainers, we have created a wrapper around spawn_blocking that takes a FnOnce (as spawn_blocking does) and also a reference to the LocalKey object used inside the task_local! variable. The wrapper gets the current value of the LocalKey, if present, then runs a new closure inside a call to spawn_blocking that re-stores the value in the LocalKey (using sync_scope), then runs the passed FnOnce. The request ID is then set inside the new task. If the LocalKey isn't present, we just spawn_blocking the FnOnce directly.