http.get only return after timeout

[carlosqsilva]

Describe the bug

http.get only returns after read_timeout, this is happening only on localhost (tested with 127.0.0.1 as well)

Reproduction Steps

start any api locally, ex:

google-chrome --headless --remote-debugging-port=4000

module main

import net.http

fn main() {
   response := http.get('http://127.0.0.1:4000/json/version')!
   eprintln(response.body)
}

response.body will be printed after 30 seconds (default read_timeout value)

changing read_timeout:

module main

import net.http
import time

fn main() {
  req := http.Request{
    url: "http://127.0.0.1:4000/json/version"
    method: .get
    read_timeout: 5 * time.second 
  }
  response := req.do()!
  eprintln(response.body)
}

response.body will be printed after 5 seconds

curl http://120.0.0.1:4000/json/version

returns immediately, with no additional delay

Expected Behavior

http.get returns immediately when request has finished

Current Behavior

http.get returns when reach timeout

Possible Solution

No response

Additional Information/Context

can't reproduce to external apis (ex: https://api.github.com/users/...) only localhost

V version

0.4.3 b944927

Environment details (OS name and version, etc.)

V full version: V 0.4.3 8f76a06.b944927
OS: macos, macOS, 14.3, 23D5033f
Processor: 8 cpus, 64bit, little endian, Apple M1

getwd: /Users/carlossilva/Code/v_issues
vexe: /Users/carlossilva/Code/v/v
vexe mtime: 2023-12-27 21:50:04

vroot: OK, value: /Users/carlossilva/Code/v
VMODULES: OK, value: /Users/carlossilva/.vmodules
VTMP: OK, value: /tmp/v_501

Git version: git version 2.43.0
Git vroot status: weekly.2023.37-756-gb944927f
.git/config present: true

CC version: Apple clang version 15.0.0 (clang-1500.1.0.2.5)
thirdparty/tcc status: thirdparty-macos-arm64 a668e5a0

Note

You can use the 👍 reaction to increase the issue's priority for developers.

Please note that only the 👍 reaction to the issue itself counts as a vote.
Other reactions and those to comments will not be taken into account.

[hholst80]

Jikes! I need to rollback my health service checker then, that extensively use http://127.0.0.1:$port to check for Pod service healths. Thanks for reporting the issue!

Edit: Luckily for me, I could not repro this in my K8s environment. Only locally with the chromium endpoint suggested.

[JalonSolov]

Seems like the problem is chrome, then, not V. If chrome has implemented some weird side-effect, there's nothing much V can do about it, unless someone can hunt down the details.

[hholst80]

The Python built-in server works just fine. It uses a HTTP/1.0 response and that mandates that the TCP/IP connection is closed after the body payload. Could this be related to a end-of-payload issue? I find it hard to believe that this is related to localhost but rather that the read stalls for some reason.

python3 -m http.server
Serving HTTP on 0.0.0.0 port 8000 (http://0.0.0.0:8000/) ...
127.0.0.1 - - [28/Dec/2023 11:50:11] "GET / HTTP/1.1" 200 -
127.0.0.1 - - [28/Dec/2023 11:51:15] "GET / HTTP/1.1" 200 -

The Content-Length is correct in the response, but perhaps this is worth looking into in details in the source.

~ # curl -s http://127.0.0.1:4000/json/version |wc
        8        24       426
~ # curl http://127.0.0.1:4000/json/version -I
HTTP/1.1 200 OK
Content-Security-Policy:frame-ancestors 'none'
Content-Length:426
Content-Type:application/json; charset=UTF-8

[hholst80]

I also tried this with lighttpd with a proper HTTP/1.1 response and it also works there.

The only thing that kinds of "pops out" in the difference is the lack of spaces between ":" in the headers. Could it be that the Content-Length is not properly parsed due to this? EDIT: Not likely. The header is properly read into the header. I think once has to debug this in V source code. and see what is going on in the request.

~ # curl 127.0.0.1:4000/json/version -v
*   Trying 127.0.0.1:4000...
* Connected to 127.0.0.1 (127.0.0.1) port 4000
> GET /json/version HTTP/1.1
> Host: 127.0.0.1:4000
> User-Agent: curl/8.5.0
> Accept: */*
> 
< HTTP/1.1 200 OK
< Content-Security-Policy:frame-ancestors 'none'
< Content-Length:426
< Content-Type:application/json; charset=UTF-8
< 
{
   "Browser": "HeadlessChrome/120.0.6099.129",
   "Protocol-Version": "1.3",
   "User-Agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/120.0.6099.129 Safari/537.36",
   "V8-Version": "12.0.267.10",
   "WebKit-Version": "537.36 (@204016af461e03117aa3858b51ba4534c7cfda81)",
   "webSocketDebuggerUrl": "ws://127.0.0.1:4000/devtools/browser/74f95521-bfa4-401a-885f-03c7845bd137"
}
* Connection #0 to host 127.0.0.1 left intact
~ # 

~ # curl 127.0.0.1:80 -v
*   Trying 127.0.0.1:80...
* Connected to 127.0.0.1 (127.0.0.1) port 80
> GET / HTTP/1.1
> Host: 127.0.0.1
> User-Agent: curl/8.5.0
> Accept: */*
> 
< HTTP/1.1 200 OK
< Content-Type: text/html
< ETag: "2737971526"
< Last-Modified: Thu, 28 Dec 2023 11:04:38 GMT
< Content-Length: 25
< Accept-Ranges: bytes
< Date: Thu, 28 Dec 2023 11:08:57 GMT
< Server: lighttpd/1.4.73
< 
<html>Hello world</html>
* Connection #0 to host 127.0.0.1 left intact
~ # 

~ # ./qqq
http.Response{
    body: '{
   "Browser": "HeadlessChrome/120.0.6099.129",
   "Protocol-Version": "1.3",
   "User-Agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/120.0.6099.129 Safari/537.36",
   "V8-Version": "12.0.267.10",
   "WebKit-Version": "537.36 (@204016af461e03117aa3858b51ba4534c7cfda81)",
   "webSocketDebuggerUrl": "ws://127.0.0.1/devtools/browser/74f95521-bfa4-401a-885f-03c7845bd137"
}
'
    header: Content-Security-Policy: frame-ancestors 'none'
Content-Length: 421
Content-Type: application/json; charset=UTF-8

    status_code: 200
    status_msg: 'OK'
    http_version: '1.1'
}
{
   "Browser": "HeadlessChrome/120.0.6099.129",
   "Protocol-Version": "1.3",
   "User-Agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/120.0.6099.129 Safari/537.36",
   "V8-Version": "12.0.267.10",
   "WebKit-Version": "537.36 (@204016af461e03117aa3858b51ba4534c7cfda81)",
   "webSocketDebuggerUrl": "ws://127.0.0.1/devtools/browser/74f95521-bfa4-401a-885f-03c7845bd137"
}

[hholst80]

I think the problem is here in the req.http_do method there is a call to req.read_all_from_client_connection. This not correct, it should read Content-Length bytes if it is specified, not read until connection is closed.

[JalonSolov]

It's a lot more complex than just making it pay attention to Content-Length. For one thing, that header wasn't introduced until HTTP/1.1, so it may not be passed at all for an HTTP/1.0 connection. Etc., etc. Lots of MUST and MUST NOT things about Content-Length:

https://www.rfc-editor.org/rfc/rfc9110.html#section-8.6

[hholst80]

We have no option here as supporting only HTTP/1.0 is not an option in 2023^W2024. Was HTTP/1.1 a good idea? No. It made the protocol too complex and brittle. But here we are.

I am looking into making a PR to fix this. I am quite new to V so it might take me a couple of days before I have a solution we are happy with.

[jorgeluismireles]

I think I am getting the same this issue talks about right now. I have a very old service that sends a minimal response but big html file (Only header is Content-Length):

< HTTP/1.1 200 OK
Content-Length: 65352

<!DOCTYPE html><html><head profile='http://www.w3.org/2005/10/profile'><META http-equiv='Content-Type' content='text/html; charset=utf-16'><meta name='viewport' content='width=device-width, initial
...

with -d debug_http I see all parts arrive (last text is </html>) to say under 1.5 seconds. But fn (req &Request) receive_all_data_from_cb_in_builder returns after 30 seconds (the default timeout).

A Golang client and curl return the page within the 2 seconds.

I add a dump in vlib/net/http/request.v:

fn (req &Request) receive_all_data_from_cb_in_builder(mut content strings.Builder, con voidptr, receive_chunk_cb FnReceiveChunk) ! {
	mut buff := [bufsize]u8{}
	bp := unsafe { &buff[0] }
	mut readcounter := 0
	mut body_pos := u64(0)
	mut old_len := u64(0)
	mut new_len := u64(0)
	mut expected_size := u64(0)
	mut status_code := -1
	for {
		readcounter++
		len := receive_chunk_cb(con, bp, bufsize) or { dump('break'); break }

Last line is printed after the 30 seconds and returns silently (break without error) because timeout but was not needed since all page's parte arrived and think an extra TCP call will return nothing. Maybe counting bytes problem for servicing "old" responses in the function?