Unexpected connection loss when cloning via https with slow bandwidth

[ashimokawa]

• Gitea version (or commit ref): lastest 1.14 and latest main
• Git version: 2.29
• Operating system: Debian 10
• Database (use [x]):
  • PostgreSQL
  • MySQL
  • MSSQL
  • SQLite
• Can you reproduce the bug at https://try.gitea.io:
  • Yes (provide example URL)
  • No

Description

When cloning a repository with slow bandwidth over https, gitea seems to timeout.
We noticed that because F-Droid fails to checkout repositories from codeberg.org, there is also a issue on Codeberg here: https://codeberg.org/Codeberg/Community/issues/461.

This seems to affect try.gitea.io also. Timeouts seem to happen after a few minutes, but not always after the same time. We tried to increase git.timeout values on our test instance also, also accessed port 3000 directly without reverse proxy, without any effect.

$ sudo wondershaper enp0s31f6 4000 4000 # somehow values do not really matter, anything between 500-4000 had the same effect
$ time git clone https://try.gitea.io/ashi/Gadgetbridge
Klone nach 'Gadgetbridge' ...
remote: Enumerating objects: 92096, done.
remote: Counting objects: 100% (92096/92096), done.
remote: Compressing objects: 100% (22562/22562), done.
error: 5767 Bytes des Bodys werden noch erwartet | 12.00 KiB/s
fetch-pack: unexpected disconnect while reading sideband packet
fatal: zu frühes Dateiende
fatal: fetch-pack: ungültige index-pack Ausgabe

real    1m31,925s
user    0m0,005s
sys     0m0,025s

[fnetX]

Because the description is not clear on this: We reproduced with serving assets from Gitea public folder, too. https://codeberg.org/Codeberg/Community/issues/460 is most likely related, too.

[zeripath]

We really need to see some logs from the gitea side of things.

[fnetX]

Oh sure, sorry, we only shared them in our internal infrastructure groups ... 🙈

root@codeberg:~# grep -E '2021/06/02 06.*RPC\(upload-pack\)' /data/git/log/gitea.log
2021/06/02 06:07:40 routers/repo/http.go:556:serviceRPC() [E] Fail to serve RPC(upload-pack) in /data/git/gitea-repositories/kollo/x11-basic.git: signal: broken pipe - 
2021/06/02 06:09:53 routers/repo/http.go:556:serviceRPC() [E] Fail to serve RPC(upload-pack) in /data/git/gitea-repositories/kollo/x11-basic.git: signal: broken pipe - 
2021/06/02 06:10:05 routers/repo/http.go:556:serviceRPC() [E] Fail to serve RPC(upload-pack) in /data/git/gitea-repositories/gitnex/gitnex.git: signal: broken pipe - 
2021/06/02 06:10:35 routers/repo/http.go:556:serviceRPC() [E] Fail to serve RPC(upload-pack) in /data/git/gitea-repositories/gitnex/gitnex.git: signal: broken pipe - 
2021/06/02 06:12:09 routers/repo/http.go:556:serviceRPC() [E] Fail to serve RPC(upload-pack) in /data/git/gitea-repositories/hjacobs/kube-resource-report.git: exit status 128 - fatal: the remote end hung up unexpectedly
2021/06/02 06:17:27 routers/repo/http.go:556:serviceRPC() [E] Fail to serve RPC(upload-pack) in /data/git/gitea-repositories/nexttracks/android.git: signal: broken pipe - 
2021/06/02 06:18:53 routers/repo/http.go:556:serviceRPC() [E] Fail to serve RPC(upload-pack) in /data/git/gitea-repositories/nexttracks/android.git: signal: broken pipe - 
2021/06/02 06:21:01 routers/repo/http.go:556:serviceRPC() [E] Fail to serve RPC(upload-pack) in /data/git/gitea-repositories/freeyourgadget/gadgetbridge.git: signal: broken pipe - 
2021/06/02 06:22:46 routers/repo/http.go:556:serviceRPC() [E] Fail to serve RPC(upload-pack) in /data/git/gitea-repositories/freeyourgadget/gadgetbridge.git: signal: broken pipe - 
2021/06/02 06:33:16 routers/repo/http.go:556:serviceRPC() [E] Fail to serve RPC(upload-pack) in /data/git/gitea-repositories/oppenlab/ariane.git: signal: broken pipe - 
2021/06/02 06:39:18 routers/repo/http.go:556:serviceRPC() [E] Fail to serve RPC(upload-pack) in /data/git/gitea-repositories/corona-contact-tracing-germany/cwa-android.git: signal: broken pipe - 
2021/06/02 06:42:56 routers/repo/http.go:556:serviceRPC() [E] Fail to serve RPC(upload-pack) in /data/git/gitea-repositories/stoptheccp/ccp-database-leak.git: signal: broken pipe - 
root@codeberg:~# 

This was the final thing we grepped because of the reports related to FDroid repos. We saw more broken pipes, but expected them to being unrelated, we noticed later that also normal file transfers fail. I'll check the logs again with this information.

Note: 2021/06/02 06:12:09 routers/repo/http.go:556:serviceRPC() [E] Fail to serve RPC(upload-pack) in /data/git/gitea-repositories/hjacobs/kube-resource-report.git: exit status 128 - fatal: the remote end hung up unexpectedly - this log line is most likely unrelated and means the client side hung up (we also suspected the reverse proxy or something). We tried looking for correlations between those messages and the actual issues, but found none.

[fnetX]

Hmm, the canceling file downloads don't seem to appear in the logs, will play with the loglevels once more.

But basically, we're seeing this broken pipe issue, on slow throughput or when halting the download (I'm using ctrl+z and fg from time to time when reproducing locally when I don't want to throttle my full machine)

We were already looking for some timeout, but found none left to configure.
Using haproxy for connections to other backends (e.g. file serving from nginx) works fine. Direct access to Gitea via the local port results in the same issue.

Oh and I just noticed the error log from OP is translated, the English version would look like

error: 7158 bytes of body are still expected29 MiB | 487.00 KiB/s
fetch-pack: unexpected disconnect while reading sideband packet
fatal: early EOF
fatal: index-pack failed

[zeripath]

Ok your logs imply to me that the response writer is being closed independently of the upload pack.

So ... If we're sure it's not coming from a proxy it must be being closed further down within gitea.

Now, we know that long running connections are allowed because the event stream doesn't have this problem. So there's maybe something that the event stream is setting on the response that is preventing this early close?

I guess it would be helpful to know if you're running with the inbuilt gzip handler or other config?

[zeripath]

In particular we set:

gitea/routers/events/events.go

Line 29 in c1ff59c

ctx.Resp.Header().Set("Connection", "keep-alive")

Which we don't set in http.

So a good guess might be to set that after this line here:

gitea/routers/repo/http.go

Line 439 in c1ff59c

h.w.Header().Set("Content-Type", fmt.Sprintf("application/x-git-%s-result", service))

[fnetX]

We didn't change the GZIP config. In case you have questions about the codeberg config and don't want to wait for a reply, you can usually look at https://codeberg.org/Codeberg/build-deploy-gitea/src/branch/master/etc/gitea/conf/app.ini - in case this is easier for you.

Please keep in mind that normal file transfer seemed to show this very same issue (e.g. downloading a big file from gitea/public). Maybe a similiarity between repo and other connections (public serving + most likely file attachments) gives you a hint?

[zeripath]

I think it's all similar as I don't think we set the keep alive header on those either so it's worth checking if the above suggestion solves things.

If it does then we can add in the keep alive command elsewhere or everywhere.

If it doesn't then at least we know it's not that.

[ashimokawa]

@zeripath
added the keepalive header as suggested. Didn't help.

Since this affects try.gitea.io also we should not distract ourselves by digging into codeberg specific configs.

[6543]

just an idear of mine: could it be an regression of the macaron -> chi migration ?

[zeripath]

@6543 that's my suspicion too and why I was asking specifically about things like HTTP keep alive etc.

[fnetX]

@6543 I already started searching for the regression commit, but as I told you on Matrix I won't find time looking into more details until tonight, but I wanted to share some first results early, maybe you can already make use of them:

Good news - Release 1.14.2 seems not to be affected, so the bug wasn't delivered to end users (but Codeberg, shame on us for living on the edge). The release branch is. So maybe you have an idea what changed in between?

Also from the log:

2021/06/04 19:53:34 ...les/public/public.go:165:handle() [I] [Static] Serving /many-zeroes
2021/06/04 19:53:39 Completed GET /many-zeroes 200 OK in 5.01920503s

As you can see, this returned early (after five seconds apparently) while the actual transfer timed out after 51 seconds with

2021-06-04 19:54:25 (50.1 KB/s) - Connection closed at byte 2621440. Giving up.

Before this timeout was shown AFTER the transfer stopped (e.g. Completed GET /many-zeroes 200 OK in 11m56.011945691s).

The file is 100MB in size.

[fnetX]

Well, nevermind, I just finished the bisect, have a look at this commit: 41422f0

Add timeout to writing to responses (#15831) (#15872)

Backport #15831

In #15826 it has become apparent that there are a few occasions when a response can
hang during writing, and because there is no timeout go will happily just block
interminably. This PR adds a fixed 5 second timeout to all writes to a connection.

Fix #15826

Signed-off-by: Andrew Thornton art27@cantab.net

Sounds obvious ...