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

get_headers does not return when using http2 #202

Open
Mehgugs opened this issue Jul 3, 2022 · 1 comment
Open

get_headers does not return when using http2 #202

Mehgugs opened this issue Jul 3, 2022 · 1 comment

Comments

@Mehgugs
Copy link
Contributor

Mehgugs commented Jul 3, 2022

I've ran into an issue where sending requests with request.version = 2 leads to an ETIMEDOUT even though the server receives the request properly. After inspecting the state of the coroutine which was running my request I can see that execution is held up at the poll in the get_headers function.

Data pulled from an active request (request:go called with a timeout of 1000):

stack traceback:
        [C]: in function 'coroutine.yield'
        /usr/local/share/lua/5.4/cqueues.lua:45: in function '_cqueues.poll'
        /usr/local/share/lua/5.4/http/h2_stream.lua:1222: in method 'get_headers'
        /usr/local/share/lua/5.4/http/request.lua:598: in method 'go'
        ....

locals at the get_headers stack frame:

self            http.h2_stream{connection=http.h2_connection{type="client"};id=1;state="half closed (local)";parent=0;dependees={}}
timeout         998.9164443
deadline        7024.448864047
(temporary)     function: 0x5653d5ba8e20
(temporary)     CQS Condition: 0x5653d5aaf218
(temporary)     http.h2_connection{type="client"}
(temporary)     998.9164443

Line 1222 is the following:

local which = cqueues.poll(self.recv_headers_cond, self.connection, timeout)
@Mehgugs
Copy link
Contributor Author

Mehgugs commented Jul 9, 2022

Okay so I think I've found part of the issue:

In get_headers the connection polls but the self.connection:step(0) times out. Due to how step works this timeout is simply returned as true which means the get_headers loop goes into a blocking call again; which never seems to terminate unless timed out.

When I catch the offending thread and inspect the locals I can grab the stream object. If I manually step the attached connection the poll returns and the deadlock is fixed.

Here is an example which seems to reproduce the problem, it is not always reproduced which suggests to me it's some kind of race condition in the code.

local request = require"http.request"
local errno   = require"cqueues.errno"
local loop    = require"cqueues".new()

local DATA = [[{"hi" : "]] .. ("there"):rep(1000)..[["}]]

local TIMEOUT = 10
local VERSION = 2

loop:wrap(function()
    local r = request.new_from_uri("https://postman-echo.com/post")
    r.headers:upsert(":method", "POST")
    r.headers:upsert("content-type", "application/json")

    r.version = VERSION
    r.expect_100_timeout = TIMEOUT 

    r:set_body(DATA)

    for hname, value, never_index in r.headers:each() do
        print(string.format("%s = %s", hname, never_index and "<never_index>" or value))
    end

    local headers , stream , eno = r:go(TIMEOUT)

    if not headers then
        print(string.format("%q (%s, %q)",
            tostring(stream), eno and errno[eno] or "?", eno and errno.strerror(eno) or "??"))
        return
    end

    print(headers:get":status")


end)

assert(loop:loop())

If you set version to 1.1 the request completes.
If you make body smaller the request completes.
The request will often timeout with a small timeout; if you make the timeout large enough you receive the following:

"PROTOCOL_ERROR(0x1): Protocol error detected: 'RST_STREAM' on stream #1 (code=0x1)" (?, "??")

The request will also sometimes complete successfully.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant