Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

PUT timeout after a OPTIONS/HEAD request #401

Closed
jeanbiber opened this issue Apr 11, 2022 · 18 comments
Closed

PUT timeout after a OPTIONS/HEAD request #401

jeanbiber opened this issue Apr 11, 2022 · 18 comments
Labels
bug Something isn't working further information required existing information is lacking, or feedback is required

Comments

@jeanbiber
Copy link

If i immediatly send a PUT request after an OPTIONS or HEAD request, the answer from the PUT only comes back after 5 seconds (default timeout).

@The-EDev
Copy link
Member

Could you please provide more details? What does you PUT route do? does it happen with other routes or just that specific one? What OS are you on? etc...

@The-EDev The-EDev added the further information required existing information is lacking, or feedback is required label Apr 11, 2022
@jeanbiber
Copy link
Author

Sorry, not reproducible. I need more time to investigate it.

@The-EDev
Copy link
Member

No worries, let me know if anything comes up.

@The-EDev
Copy link
Member

The-EDev commented Apr 27, 2022

@samichoulo911 wrote

I am getting huge latency on PUT requests (around 5seconds running on the same machine).
This issue does not happen when running the request from a client (postman, isomnia, curl) but happens when running on browser (tested on firefox and chrome). I believe the issue is caused by the preflight request as it is the only difference between the client and the browser I could find.

I am using the CORS middleware.
I tested using a node server (quick setup using NESTJs) and the put request had no peculiar latency.

This is a simple setup for the server to get the endpoint setup
crow::App<crow::CORSHandler> app;
CROW_ROUTE(app, "/").methods("GET"_method)([]() { return "Test"; });

To run the PUT command in the browser with no previous setup simply run this code in the browser console.The response should be printed to the console right when it resolves and for details check the network tab of the browser.
fetch("http://localhost:18765/", {method: "PUT", headers: { 'Content-Type': 'application/json' },}).then((r) => console.log(r))

After changing the timeout to 0 based on the linked issue, I am no longer getting the latency. I tried looking in the lib's code but was unable to find an obvious issue.

@The-EDev The-EDev added the bug Something isn't working label Apr 27, 2022
@samichoulo911
Copy link

samichoulo911 commented Apr 27, 2022

I was able to reproduce on my side using watefox is there a way to check my version of crow? That being said I downloaded the latest version about a week ago.
This is the complete code I was using as I noticed a typo in my last post where the method was GET and not PUT

#include <crow.h>
int main()
{
    crow::App<crow::CORSHandler> app;
    constexpr std::uint16_t port = 18765;
    CROW_ROUTE(app, "/").methods("PUT"_method)([]() { return "Test"; });
    app.port(port).run();
}

For the moment setting the app timeout at 0 (app.timeout(0)) seems to patch the issue. Is there a possible side effect to setting the timeout this low?

@The-EDev
Copy link
Member

That being said I downloaded the latest version about a week ago.

You're most likely using v1.0+1, Crow's source code only contains the major and minor versions unfortunately.

Is there a possible side effect to setting the timeout this low?

Yes, any request that takes Crow more than 0 seconds to process will timeout, which is generally quite bad.

I'll try to reproduce the bug on my side using your exact code and see what comes up

@samichoulo911
Copy link

I reproduced it using log level debug and got the following:
image

The yellow logs were printed on server start.
The green was printed as soon as the request was sent.
The red part was printed later (~5 sec) and after those logs the response came through.

I also debugged my code to try and pin down at what step the response come through and got this
image

After line 578 (http_connection.h) is called, the response comes through.
Ill keep trying to find other ways to trigger it.

@The-EDev
Copy link
Member

I suspect something related to the CORS middleware is blocking the thread until the deadline is triggered

@The-EDev
Copy link
Member

I still can't get the issue to appear, are you using MSVC @samichoulo911 @jeanbiber ? it could be a compiler quirk

@samichoulo911
Copy link

I tried using g++ and clang++ compiling in c++2a and got the delay with both. I am running on Kubuntu 21.10

@The-EDev
Copy link
Member

Still can't reproduce the bug whatsoever :/

@The-EDev
Copy link
Member

The-EDev commented Apr 28, 2022

Here's my log, interestingly enough it seems you're missing some debug logs (specifically those created when a new connection is created), this could be a cause of the CROW_ENABLE_DEBUG macro being missing. Other than that the logs seem to be identical..

The colors are the same with the exception that the red part is run after the keep-alive time runs out, the responses are made immediately.

image

@jeanbiber jeanbiber reopened this Apr 29, 2022
@jeanbiber
Copy link
Author

jeanbiber commented Apr 29, 2022

Hi, after I fixed locally for me the issue with the missing content-length in OPTIONS, the timeout problem with a PUT request was gone.

@The-EDev
Copy link
Member

@samichoulo911 can you confirm whether the fix for #402 fixes this issue as well for you too?

@samichoulo911
Copy link

Not sure where I should be adding the content-length header since the OPTIONS requests get processed automaticly.

@samichoulo911
Copy link

samichoulo911 commented Apr 29, 2022

I added this line to the cors middleware following the fix and was able to fix the issue.
image

I'm not sure if this is the best place to put it tho. I think the best place to put it would be where the OPTIONS requests get processed automaticly. Alternatively I could make a custom middleware that adds it to the OPTIONS requests (would be a little weird to have a full middleware for this specific header). Not sure what the best fix would be. Any suggestion?

I would be happy to work on a PR to merge a fix.

@The-EDev
Copy link
Member

@samichoulo911 If you haven't updated Crow to where #424 is applied, what you did has the same effect, though @424 does it without using any middleware.

@The-EDev
Copy link
Member

I'm guessing that's why I wasn't able to reproduce the issue (I was using a version that had content-length as 0). the most likely occurrence is that the browser was waiting for more data due to the lack of content-length and would display what it got when Crow eventually closed the connection after Keep-Alive was timed out.

I'll close this issue as fixed in #424.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working further information required existing information is lacking, or feedback is required
Projects
None yet
Development

No branches or pull requests

3 participants