Don't replace an existing request id header

[sycured]

Fix #6

[vbrandl]

Sorry for the late answer. This looks good but I want to properly review the changes. This might take a few days.

[vbrandl]

Ok I had a look at the changes and it seems fine.

I just think there should be a way to disable the behavior of using the supplied request id from the request. Something like a boolean flag use_incoming_request_id in the middleware, that when set to false, ignores the incoming value and mirrors the current behavior of the library.

[sycured]

Is the boolean to replace the map that I did to take the value from the request otherwise take the one generated by the middleware?

I don't see the usage of having one request id comming from the load balancer that we need to replace by the new one… it will break the entire tracking/observability

[vbrandl]

Some apps might not be running behind a load balancer. In this case any request coming from a user might include the request id header. In this case it might not be acceptable to use the supplied id value.
Also I'd like to fall back on the current mode of operation as to not break the library for projects that already use it as is.

And I found a bug in your PR: the RequestId extractor that can be used to access the request id in a route handler, is not properly set, when the incoming request id is used instead of a generated one.

Add the following lines to your testcase to reproduce:

let body: Bytes = test::read_body(resp).await;
let body = String::from_utf8_lossy(&body);
assert_eq!(body, uuid4);

[sycured]

Strange, I ran 50k call (with and without request id in request header) on an API and 0 error between request header and response header and no missing or malformed request id in the response header.

I'll try with your snippet

[vbrandl]

The bug happens here: https://github.com/vbrandl/actix-request-identifier/blob/master/src/lib.rs#L174

This line makes RequestId extractable in actix handlers, but it always uses the generated value, not the value extracted from the request headers.

I also think, calling the id generator should happen in the Service trait implementation, instead of the Transfer block. That way it can be called only when the request does not already supply a request id and the generated value is actually used.

[vbrandl]

I pushed code for both points:

• The RequestId extractor now contains the correct id, when the incoming id is reused
• It is now possible to configure the id reuse behavior

I'm still not sure, which one should be the default. Using IdReuse::UseIncoming might break the library for existing users. On the other hand, it might be time for a 1.0.0 release and I can document this as a breaking change for consumers...

[sycured]

Maybe I broke something but implementing this version without .use_incoming_id(IdReuse::IgnoreIncoming) and running multiple times the same request, it's looping across the same request id generated by the middleware

To reproduce:

• Source code: https://github.com/sycured/streaming_calc_actixweb
• Docker image: https://hub.docker.com/r/sycured/scaw

1. pull the container: docker pull sycured/scaw
2. run the container: docker run --rm -it -p 8080:8080 sycured/scaw
3. execute the same request few times (at least the same number of workers) and find the same result in the log: curl http://127.0.0.1:8080/
4. look at the log:

[2022-12-28T04:59:29Z INFO  actix_server::builder] Starting 2 workers
[2022-12-28T04:59:29Z INFO  actix_server::server] Actix runtime found; starting in Actix runtime
[2022-12-28T04:59:31Z INFO  actix_web::middleware::logger]  172.17.0.1 2022-12-28T04:59:31.354974383Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "10935814-84e0-49c8-8823-8965547ea362" 0.000751
[2022-12-28T04:59:32Z INFO  actix_web::middleware::logger]  172.17.0.1 2022-12-28T04:59:32.469874447Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "d3daefd0-755a-4a48-bf2c-3529938bda11" 0.000122
[2022-12-28T04:59:33Z INFO  actix_web::middleware::logger]  172.17.0.1 2022-12-28T04:59:33.15326365Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "10935814-84e0-49c8-8823-8965547ea362" 0.000112
[2022-12-28T04:59:33Z INFO  actix_web::middleware::logger]  172.17.0.1 2022-12-28T04:59:33.667521365Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "d3daefd0-755a-4a48-bf2c-3529938bda11" 0.000054
[2022-12-28T04:59:35Z INFO  actix_web::middleware::logger]  172.17.0.1 2022-12-28T04:59:35.156373314Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "10935814-84e0-49c8-8823-8965547ea362" 0.000062
[2022-12-28T04:59:35Z INFO  actix_web::middleware::logger]  172.17.0.1 2022-12-28T04:59:35.598717559Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "d3daefd0-755a-4a48-bf2c-3529938bda11" 0.000052

Only 2 different request id on 6 requests:

• 10935814-84e0-49c8-8823-8965547ea362
• d3daefd0-755a-4a48-bf2c-3529938bda11
  It's equal to the number of workers so something is keeping it in memory also if nothing is coming from the request header.

You can try it on other endpoints (just look at the readme to have curl requests), it's the same thing when the middleware generates the value

If I put .use_incoming_id(IdReuse::IgnoreIncoming), the generation is working as expected: each request has a different id

[sycured]

I ran 26 requests and the request id is different each time as expected (commit 51fd7dc)

[vbrandl]

I cannot reproduce the issue you described. I just pulled and ran the docker image and I get random ids:

[2023-01-05T14:07:30Z INFO  actix_web::middleware::logger]  10.0.2.100 2023-01-05T14:07:30.308258672Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "b484c6b5-6507-459e-ae8b-8bd4aff2d678" 0.000073
[2023-01-05T14:07:31Z INFO  actix_web::middleware::logger]  10.0.2.100 2023-01-05T14:07:31.332238917Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "57ca71d1-2666-4339-8897-5e364b83062c" 0.000079
[2023-01-05T14:07:31Z INFO  actix_web::middleware::logger]  10.0.2.100 2023-01-05T14:07:31.867976823Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "dd96bafe-17f6-42a6-bd6d-7a809260262c" 0.000076
[2023-01-05T14:07:37Z INFO  actix_web::middleware::logger]  10.0.2.100 2023-01-05T14:07:37.753107644Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "44dc76b6-8cff-4426-8481-8e54b9558915" 0.000090
[2023-01-05T14:07:38Z INFO  actix_web::middleware::logger]  10.0.2.100 2023-01-05T14:07:38.212431011Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "cbd45845-bd94-4af1-b8c2-1e826d60dd0b" 0.000061
[2023-01-05T14:07:38Z INFO  actix_web::middleware::logger]  10.0.2.100 2023-01-05T14:07:38.639412765Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "f2ede482-41aa-4803-b0b2-44e7789f4970" 0.000072
[2023-01-05T14:07:39Z INFO  actix_web::middleware::logger]  10.0.2.100 2023-01-05T14:07:39.070253809Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "faf942e9-398e-43b3-9e10-03d95e0e5817" 0.000081
[2023-01-05T14:07:39Z INFO  actix_web::middleware::logger]  10.0.2.100 2023-01-05T14:07:39.499249367Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "54f20b59-88e3-4453-b102-0910828baab5" 0.000087
[2023-01-05T14:07:39Z INFO  actix_web::middleware::logger]  10.0.2.100 2023-01-05T14:07:39.930286734Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "dd0a9502-04a3-44c1-a8a9-4c0be1f80a38" 0.000067
[2023-01-05T14:07:40Z INFO  actix_web::middleware::logger]  10.0.2.100 2023-01-05T14:07:40.384608628Z "GET / HTTP/1.1" 200 23 "-" "curl/7.87.0" "ea8c3bfd-c62c-40f1-a225-844c7b2979b3" 0.000052

Removing/keeping the const modifier does not change this behavior (I tested this using the example code: cargo run --example actix-web). So I don't see any reason for removing the const modifier again but we should investigate what causes the error for you. Could it be a weak PRNG inside your docker container or something like that?

Edit: I saw you pushed to the latest tag a few days ago. I cloned your repository, changed the actix-request-identifier dependency to actix-request-identifier = { path = "../actix-request-identifier/" } and changed both header_value and header to be const again and still cannot reproduce... Can you provide another testcase for the problem? Otherwise I'd like to keep the functions const.

[vbrandl]

I just built sycured/streaming_calc_actixweb@fdc7bff0 with the const modifier for header_value and header_value and still can't reproduce.

Edit: It seems like you deleted your answer. Could you investigate and provide a minimal testcase to reproduce (best case would be in the form of a unit test) and if you are not able to reproduce, revert the commit 51fd7dc

[sycured]

On it, I'm running some hyperfine and k6 with services running on docker and bare-metal to verify without the last commit

[sycured]

Everything is fine on my tests with the commit removed

edit: the issue was when using Docker Desktop 4.15.0 on my workstation, now I'm using another engine, and no issue. Nothing changed at OS level

[vbrandl]

Weird and probably worth opening a bug report against docker desktop.
I'll do a final review, merge later and publish a new release of the crate.

I just realized, this crate is already on a stable version. I plan to match the crate version to actix, so creating a 5.0.0 release will break this. Would you also be ok with keeping the current default behavior but being able to configure IdReuse::UseIncoming when needed?

I can introduce the breaking change with the new actix release, when I bump this crate to 5.0.0.

[sycured]

Would you also be ok with keeping the current default behavior but being able to configure IdReuse::UseIncoming when needed?

No problem for me

[vbrandl]

Thanks for your help and sorry, it took so long to finish and for being so picky but I merged your changes and just published the new release to crates.io: https://crates.io/crates/actix-request-identifier/4.1.0

[sycured]

No problem, thank you