Questions & Suggestions

[oren0e]

Thanks for creating this repo, it is quite helpful!
Continuing the discussion from rwf2/Rocket#982 :

Questions

1. Why the need to pass Option::None to .local_cache() in the response methods? As I understood, you can pass a new value and if there is, e.g., a request_id already that is there, it won't be created. Or I got this wrong?
2. Can you use the #[instrument] macro with this instead of the explicit enter and drop? (maybe I am wrong but I thought that the span is dropped automatically when the scope ends)
3. Where is the documentation regarding the kind of things you do in filter_layer()? (Rocket options like rocket::support=info or hyper=off), I didn't know you can do that.

Suggestions

• It might be helpful to add a screenshot(s) of a "demo" of how the logs look like etc.
• What if I want to add a name to the span to identify it's function? In your examples it's always "request". Can TracingSpan include a name field in it?
• Isn't it better to make a new or generate method for RequestId instead of calling it default? Seems more intuitive to me.
• What if I want a debug log level but not trace? As I understand, your debug level includes both.

I had more questions, once I remember them I'll post it here.

Thank you very much!

[somehowchris]

Lovely, let me answer some things but keep in mind, the only reason I created the repo is to not to have to explain it every time and so I'm not that much into tracing

#1: Yes, well on request we create these things and on response we pull them out of local_cache. As I wouldn't have any value to give it the None value is used to get something out.
#2: #[instrument] works, but it wouldn't log the details of the created span. The created span would just be dropped. In addition all your function arguments would need to implement Debug and would be printed out. This also includes all user inputted data which isn't really good (talking from a security point of view). As the actix implementation of tracing can await all the request/response tree from the service infrastructure it can instrument on that future but that comes with it's own downsides
#3: Since rwf2/Rocket#1579 had a lot of progress but was stale I got "inspired" by it, so a lot of it originated from it

About the suggestions:

• Sure, will ad some screenshots
• Over here Tracing on handlers rwf2/Rocket#2053 we had something like this, again I don't have like any experience with using the output of tracing but giving it the otel.name did it for datadog, you got an example of an integration?
• Well clippy screamed I should use default instead of new but let's change that to generate
• That's the part where I'm 100% unsure, a lot of the logging part originated from stale draft PR you commented on

[somehowchris]

And I have added an example for json with the disabled colors

[oren0e]

Regarding #[instrument] - why the span will be dropped? tracing allows you to:
a. use the Display impl with % in the beginning of a name
b. you can skip fields you don't want in the span by skip()

I might have missed it, but I didn't see any request_id in the example screenshots..

[oren0e]

I'm updating that I have tried most of the code in the example and it gives me pretty much the same results that I got when using #[instrument]. I didn't get any status_code in the response, and did not have any request_id in the response either. Don't know why that happens.
I guess Ideally I would want the request_id attached in every message related to the request, including the messages coming from hyper.
I do like the extra info in the span so maybe I'll use it over the #[instrument] way, although the benefit of #[instrument] is that it is not polluting the code in the function (of the route).
For the response, the following could be possibly added, attaching the request_id to the response headers, but it will show only there and it is a single log line in a multiple-lines response so that does not change things much.

response.set_raw_header("request_id", request_id.0.to_string());

[somehowchris]

About the #[instrument] thing, I got to know the rule „If one can‘t acknowledge by reading, don‘t do it“ meaning if one developer jumps over that code and doesn‘t know what the instrument macro does, just don‘t do it. It‘s too easy to follow the compilers errors and implement debug everywhere rather than understanding what the macro means and does. If you as a developer or engineer know what it is, just it I have nothing against that but many developers do not second-guess the code they see.

About the request_id. Just though about how cloudfoundry and some networking things in k8s handle this. My conclusion was. Use the X-Request-Id header if one exists, if not create an id and append it to the headers. This means either your application takes over the request-id from the context of your platform for end2end debugging and usage or your app creates one

Edit: Just added it to the file

[oren0e]

Thanks for the reply.
re 1st point: so basically you're saying that if potential code readers (which are mostly developers) won't know what the #[instrument] is for, then it's wrong to use it? Everyone can and should read documentation - that's how they'll learn about it. The other approach of polluting the function's code with things that are meant only for logging is much worse in my opinion.

re 2nd point: I didn't really understand what are you trying to say. Is it a good thing to add X-Request-Id to the headers? If so, how does that help you? You'll only see one line in the logs of the response with the request id - the headers one. It's hard to connect this to other log lines of the response (like e.g. hyper responses). This is even worse in async code because then you don't necessarily have a "consecutive timeline".

[somehowchris]

ok, so for the first point. I'm not saying that #[instrument] in general is wrong to use. If you are aware of the data being fed into the function which will be either printed out or handed over to some other service feel free to use it. Yes indeed everyone should read docs but that doesn't mean a lot of people are doing it and neither does that mean people understand things from multiple perspectives like tracing, quality measures, performance and security. But yes the other solution with entering and leaving the scope isn't well suited,....until rocket itself will implement it.

numeros 2: X-Request-Id is a widely used standard, many load balancers or platforms append this header to all requests. Using this as a request id means you have an id from end to end. It's still used internally as the RequestId as you suggested and if the header doesn't exist, it will just create a uuid. Now I do not get the part about "other log lines of the response" and the "consecurtive timeline". Yes this is why tracing has been invented but what does it have to do with reusing and optional header?

[oren0e]

When I send e.g. a GET request to the server I get a response. This activity is being logged by multiple entries (each with its own timestamp etc. like usually) because the log level is set to DEBUG. When I follow these messages and get to the section of the response (which is logged as number of sub-activities, each with its own timestamp etc.) - I see only one line, specifically with message="headers ..." that has the X-Request-Id appended. Example:

{"timestamp":"2022-01-12T08:46:31.837111Z","level":"DEBUG","fields":{"message":"headers [\nHeaders { Content-Type: application/json\r\n, Server: Rocket\r\n, X-Frame-Options: SAMEORIGIN\r\n, X-XSS-Protection: 1\r\n, X-Content-Type-Options: nosniff\r\n, X-Request-Id: b631ec4d-b98f-44bd-92fc-66f6fca96e55\r\n, Content-Length: 126\r\n, Date: Wed, 12 Jan 2022 08:46:31 GMT\r\n, }]","log.target":"hyper::server::response","log.module_path":"hyper::server::response","log.file":"/Users/me/.cargo/registry/src/github.zerozr99.workers.dev-1ecc6299db9ec823/hyper-0.10.16/src/server/response.rs","log.line":119},"target":"hyper::server::response"}

But I don't see it appended in other log lines also related to the response such as those with:

"message":"\u001b[32mResponse succeeded.\u001b[0m

or

"message":"\u001b[1;49;39mOutcome:\u001b[0m \u001b[49;32mSuccess\u001b[0m"

[somehowchris]

The latter two are from within rocket, which doesn't support tracing

[dawid-nowak]

hey; this is super interesting as I started looking into it two weeks ago and adopted a similar approach.
Two issues I have run into:

1. Finding all endpoints and adding tracingcontext from request and was painful.
2. For all "FromRequest" methods, I have to repeat the same process
   so there was lots of copy and paste boilerplate code to retrieve span/tracing context... and I always missed a method. So having it automated, hidden would be a big bonus.

Minor stuff, but W3C says that tracing header should be "traceparent" https://www.w3.org/TR/trace-context/#header-name. I suppose it would be neat if we could suggest name of the header to use for span id.

I am trying to make "Use 'tracing' library instead of 'log'" up to date with the master and see how that behaves.

[somehowchris]

hey @dawid-nowak

I'm currently busy studing some things, so I might have missed something out.

1. Would you mind explaining what specifically painful was? Rocket has methods to list all endpoints and uses fairings as kinda middleware
2. What do you consider as "all" FromRequest Guards/methods?

Are you talking about X-Request-Id or would you mind pointing me to what you mean?

If you are trying to use tracing inside rocket instead of log, there's already a PR for that and we are working on a fork and will add that

[dawid-nowak]

sure,

1. for example in your example you have
   #[get("/abc")] pub async fn abc<'a>( span: TracingSpan,
   so really for every method/path you will need to change the function signature and add span: TracingSpan

2. with respect to FromRequest, let's change the method below and add AuthenticationData which implements FromRequest and DbConnection which also implements FromRequsest
   #[get("/abc")] pub async fn abc<'a>( span: TracingSpan, authData: AuthenticationData, dbConn: DbConnection
   my understanding is that in AutenticationData you will need to either retrieve the request id from headers or retrieve the span from cache local,

Both these points are relatively trivial, but as the project grows and more endpoints are added you will need to ensure that everybody follows the same convention.

X-Requst-Id is commonly used, but with adoption of OpenTelemetry applications should really switch to "traceparent" HTTP header as per W3C. Not too mention that Zipkin headers are still very popular for tracing.

[somehowchris]

Ok yeah, isn't really neat to have that TracingSpan thing everywhere, as soon as rocket will implement tracing itself it's not needed to have that.

I'm not really getting the point the point of correlating auth data with the request id within your route, but your point on implementation is right, so yes

If you try to shrae conventions, maybe put up a crate on crates.io or via a git repository (if you are using it on on-prem systsems), that way you need to implement it once and use the code via a usual crate everwhere in your projects.

I'm kinda new to that tracing thing, X-Request-Id doesn't really have to do with tracing per-se but is just a header set by loadbalancer like f5 to identify and track requests, just took it as an example to take that id as your application is probably hosted on some platform which provides one anyway, If you mind, do you have some lectures about that on your mind?

[dawid-nowak]

no worries, these are mere suggestions
with respect to tracing; exactly to your point, different solution would use a different tracing header to achieve the same. w3c https://www.w3.org/TR/trace-context/ is just trying to ensure that this is consistent. also check here
https://dev.to/luizhlelis/using-w3c-trace-context-standard-in-distributed-tracing-3743

[kyrias]

In addition all your function arguments would need to implement Debug and would be printed out. This also includes all user inputted data which isn't really good (talking from a security point of view)

That's not true, you can tell it to either skip some or all of the arguments using #[instrument(skip(foo))] and #[instrument(skip_all)].

It's quite unfortunate that Rocket still doesn't have tracing support as this method isn't really tenable for anything other than small examples. For the small example in this repo it doesn't look that bad since it's 'just' three additional function calls in the function body, but that's only because the example isn't actually doing anything async.

For real handlers where you have await points it gets very hairy because it is incorrect to hold a span entered across await points. Doing that will result in broken traces if the runtime switches to another task while the span is entered. That's why things like the #[instrument] macro and the tracing::Instrument combinator are important, they automatically enter and exit the span when the wrapped future is polled. But due to the design of Rocket's fairings there seems to be no way to do something reasonable there.