Response timing out with HTTP2 on get_headers()

[neilp9]

Thank you @daurnimator for an excellent package and just as much, your responsive support.

We have observed an issue on Debian 9 with (latest) lua packages installed. The script we are running makes a request to our app, and responds with simple JSON response:

local https = require "http.compat.socket"
local ltn12 = require "ltn12"

local Main = {
    callflow = nil
}

function Main:run()

    local reqbody = "foo=bar&baz=boo&auth_token=xxx'
    local result, respcode = https.request {
              url="https://api.myurl.com/integrations/freeswitch/inbound/",
              method="POST",
              source=ltn12.source.string(reqbody),
        headers = {
                        ["content-type"] = "application/x-www-form-urlencoded",
                        ["content-length"] = tostring(#reqbody)
                        },
              sink = ltn12.sink.table(response)
    }
    print(result);
    print(respcode);
    print(response);
end


Main:run()

The issue we are observing is that this script times out (on the response) when using HTTP2. When we force the system to use HTTP1 by setting has_alpn variable to nil in http/tls.lua, the response comes back and the https.request function returns right away with result=1 and respcode=200.

Here's the stack trace when we force exit the script while the response is in process of timing out:

lua: /usr/local/share/lua/5.2/cqueues.lua:77: interrupted!
stack traceback:
    [C]: in function 'step'
    /usr/local/share/lua/5.2/cqueues.lua:77: in function 'step'
    /usr/local/share/lua/5.2/cqueues.lua:50: in function 'poll'
    /usr/local/share/lua/5.2/http/h2_stream.lua:1219: in function 'get_headers'
    /usr/local/share/lua/5.2/http/request.lua:597: in function 'go'
    /usr/local/share/lua/5.2/http/compat/socket.lua:153: in function 'request'
    local.lua:25: in function 'run'
    local.lua:43: in main chunk
    [C]: in ?

It appears it's stuck polling while fetching (processing?) response headers, but I can't quite understand what's happening here.

I'm hoping (assuming) we are doing something silly with this script and a simple tweak will fix. Thanks in advance.

Lua packages installed:

basexx
   0.4.1-1 (installed) - /usr/local/lib/luarocks/rocks
binaryheap
   0.4-1 (installed) - /usr/local/lib/luarocks/rocks
compat53
   0.7-1 (installed) - /usr/local/lib/luarocks/rocks
cqueues
   20171014.52-0 (installed) - /usr/local/lib/luarocks/rocks
fifo
   0.2-0 (installed) - /usr/local/lib/luarocks/rocks
http
   0.3-0 (installed) - /usr/local/lib/luarocks/rocks
inspect
   3.1.1-0 (installed) - /usr/local/lib/luarocks/rocks
lpeg
   1.0.2-1 (installed) - /usr/local/lib/luarocks/rocks
lpeg_patterns
   0.5-0 (installed) - /usr/local/lib/luarocks/rocks
lualogging
   1.3.0-1 (installed) - /usr/local/lib/luarocks/rocks
luaossl
   20190612-0 (installed) - /usr/local/lib/luarocks/rocks
luasec
   0.8-1 (installed) - /usr/local/lib/luarocks/rocks
luasocket
   3.0rc1-2 (installed) - /usr/local/lib/luarocks/rocks

[daurnimator]

Could you try translating your snippet to use the http.request api? When doing so, you can set myrequest.version = 1.1 to disallow http 2.

Otherwise try running with the environment variable SOCKET_DEBUG=1 so we can see what's going on.

[kapilrupavatiya]

Hi @daurnimator,

Thank you for quick response. We changed our implementation to use "http.request" api as per your example file here. Once we followed this approach to set request, our script worked fine with both HTTP1 and HTTP2.

Please note that we spent a lot of time on this issue because we assumed the right way to setup the request was how you described it here. This doesn't seem to work with Debian 9 (we only discovered our issue once we upgraded from Debian 8). Is it possible that your suggested solution above is outdated?

Thanks again for quick help.

[daurnimator]

Thank you for quick response. We changed our implementation to use "http.request" api as per your example file here. Once we followed this approach to set request, our script worked fine with both HTTP1 and HTTP2.

Okay that indicates that there may be an issue in the compat module.

Please note that we spent a lot of time on this issue because we assumed the right way to setup the request was how you described it here. This doesn't seem to work with Debian 9 (we only discovered our issue once we upgraded from Debian 8). Is it possible that your suggested solution above is outdated?

Swapping in the http.compat.socket should work, that has not changed.

You still haven't shared much context: how did you compile lua-http's dependencies (especially luaossl and cqueues)? Unless you provide a reproducible test case I'm not going to be able to replicate your issue and hence fix it: the best I can do is take educated guesses to narrow things down.

[neilp9]

You still haven't shared much context: how did you compile lua-http's dependencies (especially luaossl and cqueues)? Unless you provide a reproducible test case I'm not going to be able to replicate your issue and hence fix it: the best I can do is take educated guesses to narrow things down.

We installed lua-http via luarocks and other dependencies from Debian (stretch) package. So all standard setup. We didn't compile anything ourselves

[daurnimator]

We installed lua-http via luarocks and other dependencies from Debian (stretch) package. So all standard setup. We didn't compile anything ourselves

If you installed lua-http from luarocks then luarocks probably installed/compiled luaossl and cqueues itself. You may have then additionally installed luaossl and cqueues from Debian, which would result in multiple (different) versions present on your system.

[neilp9]

I can confirm that we have not additionally installed any packages on Debian. Just what's there from luarocks. I can confirm the script we shared is demonstrating the issue on vanilla Debian 9 after installing lua-http from luarocks and nothing else. And the same script works as expected on Debian 8

[cejkato2]

Dear all, I had a related issue with timeout in :go() function - the timeout had no effect and go() was blocking forever. My setup is Fedora32, lua5.3, http0.3 (both from official packages from Fedora repository). Investigation led to strange behavior of cqueues.poll(), which was called with negative (<0) timeout parameter in the function stream_methods:get_headers(timeout) in http/h2_stream.lua (similar cqueues.poll() calls are elsewhere). A hotfix is to add:

                if timeout < 0 then 
                        return nil, ce.strerror(ce.ETIMEDOUT), ce.ETIMEDOUT
                end

before local which = cqueues.poll(self.recv_headers_cond, self.connection, timeout). I'm not a lua expert so it's probably not the best way how to deal with it. Please, consider if some additional check of timeout variable could help to deal with such unexpected states...