opencloud icon indicating copy to clipboard operation
opencloud copied to clipboard

Request hangs when less bytes are send than advertised by `Content-Length` header

Open individual-it opened this issue 2 months ago • 4 comments

Describe the bug

When the TUS upload request contains less bytes than given in the Content-Length header, the request hangs or comes back with 502 depending on the deployment

Steps to reproduce

  1. create a TUS resource e.g. curl -vk -XPOST 'https://localhost:9200/remote.php/dav/spaces/6ee4ff97-5185-4a54-8df7-447299e75dfa$cb651e9f-eebb-4827-95eb-f3cea34bb6d4' -uadmin:admin -H"Tus-Resumable: 1.0.0" -H"Upload-Length: 10" -H"Upload-Metadata: filename ZmlsZS50eHQ=" -H"Content-Type: application/offset+octet-stream"
  2. send a PATCH request to the location given by the server, but set the Content-Lenght header to 10 but only send 9 bytes: curl -vk -XPATCH "$LOCATION" -H'Content-Type: application/offset+octet-stream' -H'Content-Length: 10' -H'Upload-Offset: 0' -H'Tus-Resumable: 1.0.0' -d"012345678"

Expected behavior

4xx error

Actual behavior

on bare metal installation the request just hangs in the docker compose full example a 502 error comes back

log in the server:

{"level":"error","service":"storage-users","host.name":"deepthought3","pkg":"rhttp","datatx":"tus","method":"PATCH","path":"/8e04450a-3455-4738-96cb-c3d7cfcf6087","requestId":"","id":"8e04450a-3455-4738-96cb-c3d7cfcf6087","error":"ERR_READ_TIMEOUT: timeout while reading request body","time":"2025-10-10T12:49:39+05:45","message":"BodyReadError"}
{"level":"error","service":"storage-users","host.name":"deepthought3","pkg":"rhttp","traceid":"8cefab162ea7ca27b1fdfb68aae32f2f","host":"127.0.0.1","method":"PATCH","uri":"/data/tus/8e04450a-3455-4738-96cb-c3d7cfcf6087","url":"/8e04450a-3455-4738-96cb-c3d7cfcf6087","proto":"HTTP/1.1","status":500,"size":53,"start":"10/Oct/2025:12:48:39 +0545","end":"10/Oct/2025:12:49:39 +0545","time_ns":60001145254,"time":"2025-10-10T12:49:39+05:45","message":"http"}
{"level":"error","service":"frontend","host.name":"deepthought3","pkg":"rhttp","traceid":"d3f138e6646dd3d94632c0356ce40d90","host":"127.0.0.1","method":"PATCH","uri":"/data/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOlsicmV2YSJdLCJleHAiOjE3NjAxNjYxODksImlhdCI6MTc2MDA3OTc4OSwidGFyZ2V0IjoiaHR0cDovL2xvY2FsaG9zdDo5MTU4L2RhdGEvdHVzLzhlMDQ0NTBhLTM0NTUtNDczOC05NmNiLWMzZDdjZmNmNjA4NyJ9.e5hCrwx3eLKeT7V5WpAEm6koc7WHZKksS4zShUOPASo","url":"/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOlsicmV2YSJdLCJleHAiOjE3NjAxNjYxODksImlhdCI6MTc2MDA3OTc4OSwidGFyZ2V0IjoiaHR0cDovL2xvY2FsaG9zdDo5MTU4L2RhdGEvdHVzLzhlMDQ0NTBhLTM0NTUtNDczOC05NmNiLWMzZDdjZmNmNjA4NyJ9.e5hCrwx3eLKeT7V5WpAEm6koc7WHZKksS4zShUOPASo","proto":"HTTP/1.1","status":500,"size":0,"start":"10/Oct/2025:12:48:39 +0545","end":"10/Oct/2025:12:49:39 +0545","time_ns":60001606539,"time":"2025-10-10T12:49:39+05:45","message":"http"}

When canceling the request the upload can be actually finished by sending -H'Content-Length: 1' -H'Upload-Offset: 9' and one byte of data

individual-it avatar Oct 10 '25 07:10 individual-it

hm when you send a malformed request like this the server should return a bad request status code. to simulate that the connection was canceled we may have to leave the connection open and kill curl ... I mean if the connection is interrupted you will not receive a response at all...

butonic avatar Oct 30 '25 09:10 butonic

Ok, AFAICT this is expected behavior. In the case of docker traefik will return the 502. Bare metal we currently do not set a timeout IIRC:

	config := tusd.Config{
		StoreComposer:         composer,
		NotifyCompleteUploads: true,
		Logger:                slog.New(tusdLogger{log: m.log}),
	}

The default is 60s:

    // NetworkTimeout is the timeout for individual read operations on the request body. If the
    // read operation succeeds in this time window, the handler will continue consuming the body.
    // If a read operation times out, the handler will stop reading and close the request.
    // This ensures that an upload is consumed while data is being transmitted, while also closing
    // dead connections.
    // Under the hood, this is passed to ResponseController.SetReadDeadline
    // Defaults to 60s
    NetworkTimeout time.Duration

butonic avatar Oct 30 '25 13:10 butonic

so after 60sec you should see a 500:

func (r *bodyReader) Read(b []byte) (int, error) {
    // [...]
		// For timeouts, we also send a nicer response to the clients.
		if netErr, ok := err.(net.Error); ok && netErr.Timeout() {
			err = ErrReadTimeout
		}

and

	// These two responses are 500 for backwards compatability. Clients might receive a timeout response
	// when the upload got interrupted. Most clients will not retry 4XX but only 5XX, so we responsd with 500 here.
	ErrReadTimeout     = NewError("ERR_READ_TIMEOUT", "timeout while reading request body", http.StatusInternalServerError)

butonic avatar Oct 30 '25 13:10 butonic

First of all, the response from an installation with a proxy depends on the proxy used, but 5xx looks good to me!

Now, regarding the issue without an external proxy: the internal httputil.ReverseProxy hangs if the body is smaller than the given content-length body.

It happens here: https://github.com/golang/go/blob/34fec512ce34fb5926aa38e0ccd0083feed94733/src/net/http/transfer.go#L372

at that point io.CopyBuffer is used to copy the data which gets stuck because it thinks more bytes have to follow.

A simple timeout wont work because the timer needs a refresh every now and then, a http.ResponseController and a custom transport Roundtripper looks like a better solution to me!

We also have to consider that some requests could take longer, such as sse.

After discussing it with @rhafer & @butonic weve decided its not a blocker, i downvote it to prio 3 and we can work on it as soon as we have the next release done.

for reference this branch solves the problem but introduces problems when the sse endpoint is in use.

https://github.com/opencloud-eu/opencloud/tree/readtimeout

reproducible via:

#!/usr/bin/env bash

echo 1
LOCATION=$(curl -k -I -s -o /dev/null -w '%header{location}' -XPOST 'https://localhost:9200/remote.php/dav/spaces/281457a5-5279-47d7-b55e-9f514c2df42b%24f8f96f82-34fb-4fb8-90bc-4f38b7f8366e' -uadmin:admin -H"Tus-Resumable: 1.0.0" -H"Upload-Length: 10" -H"Upload-Metadata: filename ZmlsZS50eHQ=" -H"Content-Type: application/offset+octet-stream")
echo 2
echo "$LOCATION"
echo "========================="
curl -vk -XPATCH "$LOCATION" -H"Connection: close" -H'Content-Type: application/offset+octet-stream' -H'Content-Length: 10' -H'Upload-Offset: 0' -H'Tus-Resumable: 1.0.0' -d"012345678"
echo "========================="
echo 3

fschade avatar Nov 04 '25 16:11 fschade