HTTP/3 stopps sending data after a bit

Forza · September 19, 2021, 2:05pm

1. Caddy version (`caddy version`):

2.4.5 from github

2. How I run Caddy:

a. System environment:

Gentoo Linux 5.13.12, OpenRC, golang 1.17.1

b. Command:

Caddy run

c. Service/unit/compose file:

N/A

d. My complete Caddyfile or JSON config:

{
	debug
	#	http_port 60001
	auto_https off
	servers :60000 {
		protocol {
			experimental_http3
		}
	}

	servers [2001:470:28:704::100]:443 {
		protocol {
			experimental_http3
		}
	}
	servers [2001:470:28:704::100]:80 {
		protocol {
		}
	}
}

wikidev.tnonline.net:443 {
	tls /etc/letsencrypt/live/wikidev.tnonline.net/fullchain.pem /etc/letsencrypt/live/wikidev.tnonline.net/privkey.pem {
	}
	bind 2001:470:28:704::100
	encode zstd gzip

	@title {
		not file {
			try_files {path} {path}/
			split_path .php
		}
		path_regexp title ^/(.*)$
	}
	rewrite @title /mediawiki/index.php?title={re.title.1}&{query}
	redir / /w/Main_Page

	root * /var/www/domains/wikidev.tnonline.net/htdocs
	php_fastcgi unix//var/run/php-fpm/fpm-wiki.socket
	file_server
}

wikidev.tnonline.net:80 {
	bind 2001:470:28:704::100
	root * /var/www/domains/wikidev.tnonline.net/
	file_server
}

# RewriteRule ^/?w(/.*)?$ %{DOCUMENT_ROOT}/mediawiki/index.php [L]
# RewriteRule ^/?$ %{DOCUMENT_ROOT}/mediawiki/index.php [L]


mirrors.tnonline.net:60000 {
	tls /etc/letsencrypt/live/mirrors.tnonline.net/fullchain.pem /etc/letsencrypt/live/mirrors.tnonline.net/privkey.pem {
	}
	root * /var/www/domains/mirrors.tnonline.net/
	php_fastcgi unix//var/run/php-fpm/fpm-www.socket
	file_server
	encode zstd gzip
}

3. The problem I’m having:

When serving large files over HTTP/3 the transfers stop after a few MiB. I’m using https://mirrors.tnonline.net:60000 for these tests.

4. Error messages and/or full log output:

I’m not seing any errors logged. Looks like transfers simply stall.

{"level":"info","ts":1632059639.2035172,"msg":"using adjacent Caddyfile"}
{"level":"warn","ts":1632059639.2068872,"msg":"input is not formatted with 'caddy fmt'","adapter":"caddyfile","file":"Caddyfile","line":37}
{"level":"info","ts":1632059639.2079818,"logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["localhost:2019","[::1]:2019","127.0.0.1:2019"]}
{"level":"info","ts":1632059639.2082248,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc00039a770"}
{"level":"debug","ts":1632059639.2085938,"logger":"tls.cache","msg":"added certificate to cache","subjects":["mirrors.tnonline.net"],"expiration":1635988016,"managed":false,"issuer_key":"","hash":"d2fae7bf784cc33ee99dce0296a578eb6b4bf417c292d1823282c883d21bd853"}
{"level":"debug","ts":1632059639.208711,"logger":"tls.cache","msg":"added certificate to cache","subjects":["wikidev.tnonline.net"],"expiration":1639465781,"managed":false,"issuer_key":"","hash":"4e4e8fb27855a3b0a7bb95baf98e5b7492ba0ff7de38da5ae259fc6684532c33"}
{"level":"info","ts":1632059639.209651,"logger":"http","msg":"enabling experimental HTTP/3 listener","addr":":60000"}
{"level":"debug","ts":1632059639.2096736,"logger":"http","msg":"starting server loop","address":"[::]:60000","http3":true,"tls":true}
{"level":"info","ts":1632059639.209697,"logger":"http","msg":"enabling experimental HTTP/3 listener","addr":"[2001:470:28:704::100]:443"}
{"level":"debug","ts":1632059639.2097185,"logger":"http","msg":"starting server loop","address":"[2001:470:28:704::100]:443","http3":true,"tls":true}
{"level":"debug","ts":1632059639.209739,"logger":"http","msg":"starting server loop","address":"[2001:470:28:704::100]:80","http3":false,"tls":false}
{"level":"info","ts":1632059639.2098117,"logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/root/.local/share/caddy"}
{"level":"info","ts":1632059639.2098575,"msg":"autosaved config (load with --resume flag)","file":"/root/.config/caddy/autosave.json"}
{"level":"info","ts":1632059639.2098644,"msg":"serving initial configuration"}
{"level":"info","ts":1632059639.2102633,"logger":"tls","msg":"finished cleaning storage units"}
{"level":"debug","ts":1632059643.0511892,"logger":"tls.handshake","msg":"choosing certificate","identifier":"mirrors.tnonline.net","num_choices":1}
{"level":"debug","ts":1632059643.0512443,"logger":"tls.handshake","msg":"custom certificate selection results","identifier":"mirrors.tnonline.net","subjects":["mirrors.tnonline.net"],"managed":false,"issuer_key":"","hash":"d2fae7bf784cc33ee99dce0296a578eb6b4bf417c292d1823282c883d21bd853"}
{"level":"debug","ts":1632059643.051261,"logger":"tls.handshake","msg":"matched certificate in cache","subjects":["mirrors.tnonline.net"],"managed":false,"expiration":1635988016,"hash":"d2fae7bf784cc33ee99dce0296a578eb6b4bf417c292d1823282c883d21bd853"}
{"level":"debug","ts":1632059643.0862348,"logger":"http.handlers.file_server","msg":"sanitized path join","site_root":"/var/www/domains/mirrors.tnonline.net/","request_path":"/haiku/release/r1beta3/haiku-r1beta3-x86_gcc2h-anyboot.iso","result":"/var/www/domains/mirrors.tnonline.net/haiku/release/r1beta3/haiku-r1beta3-x86_gcc2h-anyboot.iso"}
{"level":"debug","ts":1632059643.0862901,"logger":"http.handlers.file_server","msg":"opening file","filename":"/var/www/domains/mirrors.tnonline.net/haiku/release/r1beta3/haiku-r1beta3-x86_gcc2h-anyboot.iso"}
{"level":"info","ts":1632059651.4466825,"msg":"shutting down","signal":"SIGINT"}
{"level":"warn","ts":1632059651.4467635,"msg":"exiting; byeee!!

5. What I already tried:

This fails. Curl receives some data and then sits waiting with no more bytes arriving. No error is logged.

curl --http3 https://mirrors.tnonline.net:60000/haiku/release/r1beta3/haiku-r1beta3-x86_gcc2h-anyboot.iso > /dev/null

This works (and very fast!):

curl --http2 https://mirrors.tnonline.net:60000/haiku/release/r1beta3/haiku-r1beta3-x86_gcc2h-anyboot.iso > /dev/null

6. Links to relevant resources:

Curl-7.78.0 is built with quiche-0.9.0 for HTTP/3 support.

francislavoie · September 19, 2021, 2:46pm

It’s possible you’re running into this:

github.com/caddyserver/caddy

http/3 seems to stop working after any kind of reload

opened 05:31PM - 12 Sep 21 UTC

Zierhut-IT

bug

http/3 seems to stop working after any kind of reload. - http/3 works as expe…cted before reloading - I went as far as v2.0.0 back (thus the two Caddyfiles, see further down) and encountered this issue every time - Caddy seems to still listen on `udp/443` when it's happening: ```bash $ ss --listening --udp --processes # -lup UNCONN 0 0 *:https *:* users:(("caddy",pid=872477,fd=8)) ``` - Verbose `curl -vvv` logs: ```bash $ curl -vvv --http3 https://localhost * Trying ::1:443... * Connect socket 5 over QUIC to ::1:443 * Sent QUIC client Initial, ALPN: h3-29,h3-28,h3-27 * Trying 127.0.0.1:443... * Connect socket 6 over QUIC to 127.0.0.1:443 * Sent QUIC client Initial, ALPN: h3-29,h3-28,h3-27 * After 150000ms connect time, move on! * connect to ::1 port 443 failed: Connection timed out * After 150000ms connect time, move on! * connect to 127.0.0.1 port 443 failed: Connection timed out * Failed to connect to localhost port 443: Connection timed out * Closing connection 0 curl: (28) Failed to connect to localhost port 443: Connection timed out ``` - <details><summary>Verbose caddy logs from console with annotations (// 📌):</summary> ```json // 📌 start caddy {"level":"info","ts":1631424276.233273,"msg":"using adjacent Caddyfile"} {"level":"warn","ts":1631424276.233972,"msg":"input is not formatted with 'caddy fmt'","adapter":"caddyfile","file":"Caddyfile","line":2} {"level":"info","ts":1631424276.2348974,"logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["[::1]:2019","127.0.0.1:2019","localhost:2019"]} {"level":"info","ts":1631424276.2352147,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc00045f030"} {"level":"info","ts":1631424276.235942,"logger":"http","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"srv0","https_port":443} {"level":"info","ts":1631424276.2359629,"logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"} {"level":"info","ts":1631424276.2525249,"logger":"pki.ca.local","msg":"root certificate is already trusted by system","path":"storage:pki/authorities/local/root.crt"} {"level":"info","ts":1631424276.2526367,"logger":"http","msg":"enabling experimental HTTP/3 listener","addr":":443"} {"level":"info","ts":1631424276.2526562,"logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/root/.local/share/caddy"} {"level":"debug","ts":1631424276.252672,"logger":"http","msg":"starting server loop","address":"[::]:443","http3":true,"tls":true} {"level":"debug","ts":1631424276.25269,"logger":"http","msg":"starting server loop","address":"[::]:80","http3":false,"tls":false} {"level":"info","ts":1631424276.252697,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["localhost"]} {"level":"warn","ts":1631424276.2530873,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [localhost]: no OCSP server specified in certificate"} {"level":"debug","ts":1631424276.2531059,"logger":"tls.cache","msg":"added certificate to cache","subjects":["localhost"],"expiration":1631461064,"managed":true,"issuer_key":"local","hash":"a186539e15337b0547621156c842d1502a09780d05eb5d36684496f530c1fb84"} {"level":"info","ts":1631424276.2532187,"msg":"autosaved config (load with --resume flag)","file":"/root/.local/share/caddy/autosave.json"} {"level":"info","ts":1631424276.2532284,"msg":"serving initial configuration"} {"level":"info","ts":1631424276.2536077,"logger":"tls","msg":"finished cleaning storage units"} // 📌 test http/3 connection via curl {"level":"debug","ts":1631424286.478527,"logger":"tls.handshake","msg":"choosing certificate","identifier":"localhost","num_choices":1} {"level":"debug","ts":1631424286.4785457,"logger":"tls.handshake","msg":"default certificate selection results","identifier":"localhost","subjects":["localhost"],"managed":true,"issuer_key":"local","hash":"a186539e15337b0547621156c842d1502a09780d05eb5d36684496f530c1fb84"} {"level":"debug","ts":1631424286.4785507,"logger":"tls.handshake","msg":"matched certificate in cache","subjects":["localhost"],"managed":true,"expiration":1631461064,"hash":"a186539e15337b0547621156c842d1502a09780d05eb5d36684496f530c1fb84"} // 📌 forcefully reload caddy config via curl {"level":"info","ts":1631424303.4187894,"logger":"admin.api","msg":"received request","method":"GET","host":"127.0.0.1:2019","uri":"/config/","remote_addr":"127.0.0.1:48794","headers":{"Accept":["*/*"],"User-Agent":["curl/7.78.0"]}} {"level":"info","ts":1631424303.4197412,"logger":"admin.api","msg":"received request","method":"POST","host":"127.0.0.1:2019","uri":"/load","remote_addr":"127.0.0.1:48796","headers":{"Accept":["*/*"],"Cache-Control":["must-revalidate"],"Content-Length":["399"],"Content-Type":["application/json"],"User-Agent":["curl/7.78.0"]}} {"level":"info","ts":1631424303.4200108,"logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["localhost:2019","[::1]:2019","127.0.0.1:2019"]} {"level":"info","ts":1631424303.4201722,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc000276700"} {"level":"info","ts":1631424303.4203856,"logger":"http","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"srv0","https_port":443} {"level":"info","ts":1631424303.4204006,"logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"} {"level":"debug","ts":1631424303.4204953,"logger":"http","msg":"starting server loop","address":"[::]:80","http3":false,"tls":false} {"level":"info","ts":1631424303.4205036,"logger":"http","msg":"enabling experimental HTTP/3 listener","addr":":443"} 2021/09/12 07:25:03 [DEBUG] udp/:443: Usage counter should not go above 2 or maybe 3, is now: 2 {"level":"debug","ts":1631424303.420539,"logger":"http","msg":"starting server loop","address":"[::]:443","http3":true,"tls":true} {"level":"info","ts":1631424303.420544,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["localhost"]} {"level":"warn","ts":1631424303.4207737,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [localhost]: no OCSP server specified in certificate"} {"level":"debug","ts":1631424303.4207897,"logger":"tls.cache","msg":"added certificate to cache","subjects":["localhost"],"expiration":1631461064,"managed":true,"issuer_key":"local","hash":"a186539e15337b0547621156c842d1502a09780d05eb5d36684496f530c1fb84"} {"level":"info","ts":1631424303.4208012,"logger":"pki.ca.local","msg":"root certificate is already trusted by system","path":"storage:pki/authorities/local/root.crt"} 2021/09/12 07:25:03 [DEBUG] Fake-closing underlying packet conn {"level":"info","ts":1631424303.4235258,"logger":"tls.cache.maintenance","msg":"stopped background certificate maintenance","cache":"0xc00045f030"} {"level":"info","ts":1631424303.423664,"msg":"autosaved config (load with --resume flag)","file":"/root/.local/share/caddy/autosave.json"} {"level":"info","ts":1631424303.4236767,"logger":"admin.api","msg":"load complete"} {"level":"info","ts":1631424303.427598,"logger":"admin","msg":"stopped previous server","address":"tcp/localhost:2019"} // 📌 test http/3 connection via curl (no result) ``` </details> --- <details open><summary>Caddyfile (v2.3.0+):</summary> ```Caddyfile { debug servers :443 { protocol { experimental_http3 } } } localhost { tls internal respond localhost } ``` </details> <details><summary>Caddyfile (v2.3.0+) as JSON:</summary> ```json { "logging": { "logs": { "default": { "level": "DEBUG" } } }, "apps": { "http": { "servers": { "srv0": { "listen": [ ":443" ], "routes": [ { "match": [ { "host": [ "localhost" ] } ], "handle": [ { "handler": "subroute", "routes": [ { "handle": [ { "body": "localhost", "handler": "static_response" } ] } ] } ], "terminal": true } ], "experimental_http3": true } } }, "tls": { "automation": { "policies": [ { "subjects": [ "localhost" ], "issuers": [ { "module": "internal" } ] } ] } } } } ``` </details> <details><summary>Caddyfile (pre v2.3.0):</summary> ```Caddyfile { debug experimental_http3 } localhost { tls internal respond localhost } ``` </details> --- Below are 3 different way to reproduce this issue: 1. <details open><summary>Case (collapse)</summary> - Copy example Caddyfile - ```bash $ caddy run ``` - Test http/3 connection via ```bash $ curl --http3 https://localhost # localhost ``` - Force reload same (json) config via API ```bash $ curl --silent 127.1:2019/config/ | curl -X POST 127.1:2019/load -H "Content-Type: application/json" -d @- -H "Cache-Control: must-revalidate" ``` - Test http/3 connection again via ```bash $ curl --http3 https://localhost # curl: (28) Failed to connect to localhost port 443: Connection timed out ``` </details> 1. <details><summary>Case (expand)</summary> - Copy example Caddyfile - ```bash $ caddy run ``` - Test http/3 connection via ```bash $ curl --http3 https://localhost # localhost ``` - Force reload same config via CLI ```bash $ caddy reload --force ``` - Test http/3 connection again via ```bash $ curl --http3 https://localhost # curl: (28) Failed to connect to localhost port 443: Connection timed out ``` </details> 1. <details><summary>Case (expand)</summary> - Copy example Caddyfile - ```bash $ caddy run --watch ``` - Test http/3 connection via ```bash $ curl --http3 https://localhost # localhost ``` - Edit config (e.g. `respond`) and save - Test http/3 connection again via ```bash $ curl --http3 https://localhost # curl: (28) Failed to connect to localhost port 443: Connection timed out ``` </details> Hope this is has not yet been reported. Otherwise feel free to close this issue. \ And despite this bug, Caddy is awesome! :) ~ @IndeedNotJames

Forza · September 19, 2021, 3:00pm

It does not look like the same. I’m starting Caddy fresh and doing one file transfer without any configuration changes during the transfer. Small files load ok. I can also ctrl-c curl and try again without restarting Caddy.

Different amounts get transferred on different attempts. I was thinking it might be due to some dropped packets, but this is on localhost so it shouldn’t happen, should it?

Forza · September 20, 2021, 1:58pm

Is there any more data I can provide for this issue, or should I perhaps make a GitHub issue for it?

Thanks.

matt · September 20, 2021, 6:28pm

If you do open an issue, I would probably open it here: GitHub - lucas-clemente/quic-go: A QUIC implementation in pure go

Forza · September 21, 2021, 4:35am

github.com/lucas-clemente/quic-go

Serving large files with Caddy stall after a few MB

opened 08:46PM - 20 Sep 21 UTC

closed 04:46PM - 06 Oct 21 UTC

Forza-tng

Hi, I'm testing the http3 capability of the Caddy webserver. It normally work…s OK, but for large static files (like an iso image). I do not get any errors with debug logging. It just simply looks like the connection stalls. Curl drops to receiving 0 bytes/a but didn't throw an error. I made a post on the Caddy forum and got the suggestion to come here instead. I hope its OK. https://caddy.community/t/http-3-stopps-sending-data-after-a-bit/13694/3 ![Screenshot_20210919-165840_Termius](https://user-images.githubusercontent.com/68693597/134072986-6ea6cd70-1e4e-4a63-8114-24e637c399aa.png)

system · October 19, 2021, 2:05pm

This topic was automatically closed after 30 days. New replies are no longer allowed.