Issue #2028 Still Occurring - TCP Connection Not Closed, Previous Request Payload Interpreted as Headers

[aagit]

Description

I'm experiencing what appears to be a recurrence of issue #2028 in llama.cpp with httplib 0.27. I've added retry logic to gracefully handle server restarts in synthmerge. The client code can be found here: https://gitlab.com/aarcange/synthmerge/-/blob/main/src/api_client.rs?ref_type=heads#L275

Reproduction Details

After a llama.cpp server restart, the first request is processed correctly as a POST and handled with httplib::Server::HandlerResponse::Handled in the pre-routing handler with error 503 (model still loading).

At the TCP stack level, by the time the server sends the error 503 to the client, the entire payload of the previous request has already been fully received on the server side (verified via packet capture).

The TCP connection is not closed by either server or client, so the llama.cpp server after sending the firsst error, processes the payload of the request as if it were the headers (and payload) of a new request.

This causes the server to send another error 404, creating an infinite loop where the client keeps receiving 404 errors because headers are always taken from the previous payload.

I'm not certain what the HTTP protocol specification requires, but this appears to be a server-side bug. I can imagine one of two approaches would fix it:

1. The server should close the connection by closing the socket to discard the entire TCP receive queue
2. If the server is really allowed by some spec not to close the connection, it must then read the complete content length of the request before processing further request for that stream, after the request is "Handled" in the pre-routing handler

Reproduction Steps

The following curl command seem to reproduces the issue with llama.cpp. It doesn't reproduce the infinite loop, because unlike the reqwest client lib used by synthmerge, curl actually closes the connection.

The theory is there's just one bug so if curl stops triggering two requests instead of one, then synthmerge should not fail and timeout anymore if llama.cpp restarts.

curl -X POST \
  -H "Content-Type: application/json" \
  -H "Connection: keep-alive" \
  -H "Keep-Alive: timeout=60, max=1000" \
  http://localhost:8811/v1/chat/completions -d '''
{
  "model": "",
  "messages": [
    {
      "role": "system",
      "content": "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
    }
  ]
}
'''

Expected vs Actual Behavior

Expected:

$ ./build/bin/llama-server  --port 8811 -m somemodel.gguf 2>&1 |grep log_server_r
srv  log_server_r: request: POST /v1/chat/completions 127.0.0.1 503

Actual:

$ ./build/bin/llama-server  --port 8811 -m somemodel.gguf 2>&1 |grep log_server_r
srv  log_server_r: request: POST /v1/chat/completions 127.0.0.1 503
srv  log_server_r: request:    400

Additional Information

The expected result can be obtained by adding the --http1.0 parameter to curl.

[yhirose]

@aagit thanks for the report. If you suspect this is a recent regression, could you test with version 0.26.0 or earlier to identify which version introduced the issue? Thanks!

[aagit]

I don't think it's a recent regression, I first attempted to bisect it and I believe it was reproducible since the very first version llama.cpp server switched to httplib.h,so I did debug it, and my finding was identical to what was described in Issue #2028: the leftover payload of the previous request never read by httplib when the app returns Handled in the pre routing handler, is erroneously parsed as a new request. It first looked like plain memory corruption (as also supposed in issue #2028) but it's not, it's just the data in the tcp recv queue that wasn't flushed either by closing the socket or by reading it and getting it out of the way. I put a pause() before the new getline is issued the second time by the suprious second request, and netstat showed the data waiting to be read in the kernel recv buffer of the llama.cpp server. Right before getline the line reader ptr is empty, it gets filled with the data in the rcev queue immediately after getline is issued.

[yhirose]

Thanks for the additional comment. You mean that the fix in #2028 (released in v0.18.7) doesn't work, right? Could you please test with this version in your environment, since I'm not familiar with llama.cpp and how to reproduce the issue? Just in case, could you please try #2260 as well? It might be related to this issue. If you confirm the fix works, I'll bump up the cpp-httplib version to 0.27.1 as soon as possible.

If you can provide the smallest possible reproducible code using only cpp-httplib (without llama.cpp), I'll take a look at it soon. I can then add the code to test/test.cc to see if the issue also occurs in the GitHub Actions workflow. Otherwise, it's quite difficult for me to investigate this issue any further...

Thanks for your patience and understanding. (Since this is just my 'after work' project, my time for it is limited. 😅)

[ngxson]

IIRC the error has something to do with keep-alive, could you try disabling it to see if it resolves the problem? @aagit

I haven't seen this error for quite a while, but could be because it requires some machine-specific conditions. As mentioned by @yhirose you can also compile a very basic program to test it, code in this issue

We can also disable the keep-alive support in llama.cpp if needed, though I'm not sure it's currently possible to customize this behavior in httplib

[aagit]

Passing --http1.0 to curl avoids the problem and the llama.cpp server then sends a RST closing the connection, so it's most certainly related to keep-alive, that prevents the close_connection.

[yhirose]

@aagit could you please try with this version (4b2b851)? Thanks!
CC: @chansikpark

[chansikpark]

@aagit, the latest commit based on PR #2260 (comment) may (or may not) be relevant. I've neither stepped through the changes with a debugger nor inspected the TCP stack.

IIRC, there are two flags in Server::process_request, connection_closed and close_connection. I suspect that the former closes the connection right away, and the latter communicates the intent to the client ("Connection: close"). The given commit only does the latter. I've yet to validate this assumption.. It may be that communicating the intent to the client and the client then closing the connection is allowing the tests I set up to pass, in which case I'd want to dig into whether this is correct behaviour. Unclear whether this is sufficient to resolve the issue here.

I've opened another PR #2262 to try to chip away at this.