caddy 2.5.1 + experimental_http3 + fastcgi reverse_proxy always returns 500 #4819

aaronriekenberg · 2022-05-29T15:34:31Z

caddy version
v2.5.1 h1:bAWwslD1jNeCzDa+jDCNwb8M3UJ2tPa8UZFFzPVmGKs=

Running caddy on a 64-bit install of raspberry pi os lite.

Have a small go app acting as a fastcgi server listening on a unix socket. This app is using the standard "net/http/fcgi" package in go 1.18.2: https://github.com/aaronriekenberg/go-fastcgi

caddy is acting as a file server and reverse proxy to the go fastcgi app.

Things work perfectly with the default HTTP/2 in caddy.

But as soon as I enable experimental_http3 in my Caddyfile I observe:

All requests going over the fastcgi reverse_proxy return 500
Putting logging into my go-fastcgi server app - I see the fastcgi handler is never invoked when caddy is using experimental_http3
Turned on debug logging in caddy and have logs as below.
All requests that do not use fastcgi reverse_proxy (e.g. file_server) work normally with experimental_http3 and I see in chrome dev tools the requests are using http3. So the issue seems isolated to experimental_http3 + fastcgi reverse_proxy.

My Caddyfile:

{
        email aaron.riekenberg@gmail.com
        debug
        servers :443 {
                protocol {
                        experimental_http3
                }
        }
}

www.aaronr.digital, aaronr.digital {
        log {
                output file /var/log/caddy/access.log {
                        roll_size 10mb
                        roll_keep 5
                }
        }

        root * /var/www/html/aaronr.digital

        header {
                Cache-Control "no-cache"
                Strict-Transport-Security "max-age=63072000; includeSubDomains; preload"
        }

        handle /cgi-bin/* {
                reverse_proxy unix//var/www/run/go-fastcgi/socket {
                        transport fastcgi
                }
        }

        handle {
                header Cache-Control "public, max-age=150"

                file_server {
                        hide /var/www/html/aaronr.digital/.git/*
                        precompressed br
                }
        }

        handle_errors {
                rewrite * /error.html
                templates
                file_server
                header Cache-Control "no-cache"
        }
}

Debug errors in caddy log when making a request using http3:

May 29 10:29:16 raspberrypi caddy[1633]: {"level":"debug","ts":1653838156.6797538,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"/var/www/run/go-fastcgi/socket","total_upstreams":1}
May 29 10:29:16 raspberrypi caddy[1633]: {"level":"debug","ts":1653838156.6806445,"logger":"http.reverse_proxy.transport.fastcgi","msg":"roundtrip","request":{"remote_ip":"2600:6c46:7c00:e89f:e5a0:f1cf:54d:2e04","remote_port":"55767","proto":"HTTP/3","method":"GET","host":"aaronr.digital","uri":"/cgi-bin/debug/request_info","headers":{"Sec-Ch-Ua-Mobile":["?0"],"Accept-Language":["en-US,en;q=0.9"],"X-Forwarded-For":["2600:6c46:7c00:e89f:e5a0:f1cf:54d:2e04"],"Sec-Ch-Ua":["\" Not A;Brand\";v=\"99\", \"Chromium\";v=\"101\", \"Google Chrome\";v=\"101\""],"Axios-Version":["0.27.2"],"Sec-Ch-Ua-Platform":["\"macOS\""],"Sec-Fetch-Dest":["empty"],"X-Forwarded-Host":["aaronr.digital"],"Sec-Fetch-Site":["same-origin"],"Sec-Fetch-Mode":["cors"],"Accept-Encoding":["gzip, deflate, br"],"Accept":["application/json, text/plain, */*"],"X-Forwarded-Proto":["https"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/101.0.4951.64 Safari/537.36"],"Referer":["https://aaronr.digital/debug/request_info.html"]},"tls":{"resumed":false,"version":0,"cipher_suite":0,"proto":"","server_name":""}},"dial":"/var/www/run/go-fastcgi/socket","env":{"HTTP_ACCEPT":"application/json, text/plain, */*","HTTP_X_FORWARDED_PROTO":"https","HTTP_SEC_FETCH_SITE":"same-origin","HTTP_SEC_CH_UA_MOBILE":"?0","CONTENT_TYPE":"","SERVER_PROTOCOL":"HTTP/3","SERVER_SOFTWARE":"Caddy/v2.5.1","DOCUMENT_ROOT":"/var/www/html/aaronr.digital","HTTP_X_FORWARDED_FOR":"2600:6c46:7c00:e89f:e5a0:f1cf:54d:2e04","HTTP_SEC_CH_UA_PLATFORM":"\"macOS\"","QUERY_STRING":"","SCRIPT_NAME":"","HTTP_REFERER":"https://aaronr.digital/debug/request_info.html","HTTP_HOST":"aaronr.digital","PATH_TRANSLATED":"/var/www/html/aaronr.digital/cgi-bin/debug/request_info","SERVER_PORT":"443","HTTP_ACCEPT_LANGUAGE":"en-US,en;q=0.9","GATEWAY_INTERFACE":"CGI/1.1","REMOTE_USER":"","REQUEST_SCHEME":"https","DOCUMENT_URI":"","HTTP_X_FORWARDED_HOST":"aaronr.digital","SCRIPT_FILENAME":"/var/www/html/aaronr.digital","HTTP_AXIOS_VERSION":"0.27.2","CONTENT_LENGTH":"","PATH_INFO":"/cgi-bin/debug/request_info","REMOTE_HOST":"2600:6c46:7c00:e89f:e5a0:f1cf:54d:2e04","REQUEST_METHOD":"GET","REMOTE_ADDR":"2600:6c46:7c00:e89f:e5a0:f1cf:54d:2e04","SERVER_NAME":"aaronr.digital","HTTP_SEC_CH_UA":"\" Not A;Brand\";v=\"99\", \"Chromium\";v=\"101\", \"Google Chrome\";v=\"101\"","HTTP_SEC_FETCH_DEST":"empty","AUTH_TYPE":"","REMOTE_PORT":"55767","HTTPS":"on","HTTP_SEC_FETCH_MODE":"cors","REMOTE_IDENT":"","REQUEST_URI":"/cgi-bin/debug/request_info","HTTP_ACCEPT_ENCODING":"gzip, deflate, br","HTTP_USER_AGENT":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/101.0.4951.64 Safari/537.36"}}
May 29 10:29:16 raspberrypi caddy[1633]: {"level":"debug","ts":1653838156.6995711,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"unix//var/www/run/go-fastcgi/socket","duration":0.01931079,"request":{"remote_ip":"2600:6c46:7c00:e89f:e5a0:f1cf:54d:2e04","remote_port":"55767","proto":"HTTP/3","method":"GET","host":"aaronr.digital","uri":"/cgi-bin/debug/request_info","headers":{"Referer":["https://aaronr.digital/debug/request_info.html"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/101.0.4951.64 Safari/537.36"],"Accept-Language":["en-US,en;q=0.9"],"X-Forwarded-For":["2600:6c46:7c00:e89f:e5a0:f1cf:54d:2e04"],"Sec-Ch-Ua-Mobile":["?0"],"Axios-Version":["0.27.2"],"Sec-Ch-Ua-Platform":["\"macOS\""],"Sec-Fetch-Dest":["empty"],"X-Forwarded-Host":["aaronr.digital"],"Sec-Ch-Ua":["\" Not A;Brand\";v=\"99\", \"Chromium\";v=\"101\", \"Google Chrome\";v=\"101\""],"Sec-Fetch-Mode":["cors"],"Accept-Encoding":["gzip, deflate, br"],"Accept":["application/json, text/plain, */*"],"X-Forwarded-Proto":["https"],"Sec-Fetch-Site":["same-origin"]},"tls":{"resumed":false,"version":0,"cipher_suite":0,"proto":"","server_name":""}},"headers":{"Status":["500 Internal Server Error"],"Content-Type":["text/plain; charset=utf-8"],"Date":["Sun, 29 May 2022 15:29:16 GMT"]},"status":500}

The text was updated successfully, but these errors were encountered:

francislavoie · 2022-05-29T16:17:45Z

Are you able to use wireshark or similar to watch the traffic? I think the 500 status message must be coming from the upstream, it might not be happy with something in the request before it reaches your handler.

aaronriekenberg · 2022-05-29T16:54:48Z

@francislavoie thanks will try this and post the results.

aaronriekenberg · 2022-05-29T23:04:52Z

@francislavoie -

I was not able to find a way to sniff packets for the unix socket. So I changed the go-fastcgi app to listen on tcp port 9000, and I changed my Caddyfile to:

       handle /cgi-bin/* {
                reverse_proxy 127.0.0.1:9000 {
                        transport fastcgi
                }
        }

With this I was able to recreate the http3 500 errors, and http2 worked as expected.

Here is some data from Wireshark showing responses from go-fastcgi to caddy when using http/3:

So it looks like my go-fastcgi app is hitting this: https://github.com/golang/go/blob/master/src/net/http/cgi/child.go#L62

cgi: invalid SERVER_PROTOCOL version

From caddy debug logs - I have seen in outgoing fastcgi requests when using http3 in caddy:

"SERVER_PROTOCOL":"HTTP/3"

and when using http2 in caddy I see this in outgoing fastcgi requests:

"SERVER_PROTOCOL":"HTTP/2.0"

So finally I think the issue is go's http. ParseHTTPVersion here does not accept HTTP/3 but does accept HTTP/2.0: https://github.com/golang/go/blob/master/src/net/http/request.go#L787-L790

See this go playground for a small demo: https://go.dev/play/p/HgK2fi1r8Bb

I think this is probably a bug in caddy in that SERVER_PROTOCOL should be HTTP/3.0 when using reverse_proxy + fastcgi with incoming http3 requests?

aaronriekenberg · 2022-05-30T21:55:33Z

Further observations:

I think caddy is setting SERVER_PROTOCOL to r.Proto here: https://github.com/caddyserver/caddy/blob/master/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go#L286

Then after this configured env key/values from the fastcgi transport are set: https://github.com/caddyserver/caddy/blob/master/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go#L335-L338

So I tried changing my Caddyfile to set SERVER_PROTOCOL to HTTP/3.0 in the fastcgi transport env:
```
    handle /cgi-bin/* {
            reverse_proxy unix//var/www/run/go-fastcgi/socket {
                    transport fastcgi {
                            env SERVER_PROTOCOL HTTP/3.0
                    }
            }
    }
```
This worked completely end-to-end with an HTTP/3 request making it all the way to my go-fastcgi app 😃
I suspect the HTTP/3 value for r.Proto may be coming from quic-go here: https://github.com/lucas-clemente/quic-go/blob/master/http3/request.go#L77

But I may be missing something on how HTTP/3 is being used in quic-go and caddy. Does this make sense? Thanks!

francislavoie · 2022-05-30T22:08:28Z

Interesting. Thanks for investigating!

FYI @marten-seemann, I think quic-go should report HTTP/3.0 instead of HTTP/3, supposedly the minor version is required

mholt · 2022-05-31T05:20:19Z

Thanks for the deep investigation! Sounds like a likely easy fix.

marten-seemann · 2022-05-31T09:16:27Z

What makes you think that it should be HTTP/3.0? The name of the protocol is HTTP/3 (compare to HTTP/2, which specifies HTTP/2.0 preface here: https://datatracker.ietf.org/doc/html/rfc7540#section-3.5).

aaronriekenberg · 2022-05-31T12:24:18Z

@marten-seemann -

My use case is:

I have caddy running as a fastcgi reverse proxy
A small go app is my fastcgi server (https://github.com/aaronriekenberg/go-fastcgi). This is using the standard "net/http/fcgi" package in go 1.18.2
caddy is connecting to go-fastcgi app via a unix socket

With out-of-the-box HTTP/2 in caddy everything works as expected.

I tried turning on experimental_http3 in caddy and noticed all fastcgi requests to go-fastcgi were returning 500 in caddy. With http3 enabled in caddy my http.Handler in go-fastcgi is never called.

After some debugging above - I am finding:

caddy is setting the fastcgi SERVER_PROTOCOL to r.Proto here: https://github.com/caddyserver/caddy/blob/master/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go#L286
a. When using HTTP/2 r.Proto is HTTP/2.0
b. When using HTTP/3 r.Proto is HTTP/3 It looks like this comes from quic-go here: https://github.com/lucas-clemente/quic-go/blob/master/http3/request.go#L77
From some packet sniffing between caddy and go-fastcgi - the error returned with from go-fastcgi when using http3 is cgi: invalid SERVER_PROTOCOL version here: https://github.com/golang/go/blob/master/src/net/http/cgi/child.go#L62

This happens on the way into go-fastcgi as part of the net/http/fcgi package parsing the request, before any user handler is invoked.
Looks like the reason for this error in net/http/fcgi is the SERVER_PROTOCOL value is passed to http.ParseHTTPVersion: https://github.com/golang/go/blob/master/src/net/http/cgi/child.go#L58-L60

http.ParseHTTPVersion seems to require a very specific HTTP/X.Y string format - HTTP/3 is not considered valid. See this go playground: https://go.dev/play/p/9t13-xYkyxl

The comments in http.ParseHTTPVersion also state this requirement: https://github.com/golang/go/blob/master/src/net/http/request.go#L787-L790

A couple of thoughts on how to fix this:

quic-go could set the request protocol field to HTTP/3.0 to make http.ParseHTTPVersion work if the request is sent to a fastcgi server using go's net/http/fcgi
If HTTP/3 is correct perhaps go should update http.ParseHTTPVersion to accept this ?

Thanks!

marten-seemann · 2022-05-31T13:14:48Z

The :protocol pseudo-header is only sent when using Extended CONNECT: https://github.com/lucas-clemente/quic-go/blob/b5ef99a32c250fc63f89cc686c13a008c5419d01/http3/request_writer.go#L178-L180.

HTTP/3 doesn't specify a serialization of the HTTP version, as far as I can see: https://datatracker.ietf.org/doc/html/draft-ietf-quic-http-34#section-4.1.1.1. So it seems like the value we set on the http.Request is entire implementation- / Go-specific.

@aaronriekenberg Do you agree with that reading? If so, do you want to send a PR in quic-go?

aaronriekenberg · 2022-05-31T21:08:14Z

Created a PR for quic-go: quic-go/quic-go#3439

Thank you!

mindon · 2022-06-30T19:33:28Z

facing the same problem with reverse_proxy, here's the clue

v2.5.1 h1:bAWwslD1jNeCzDa+jDCNwb8M3UJ2tPa8UZFFzPVmGKs=

	route /hello/* {
		header X-Real-IP {http.request.remote}
		reverse_proxy http://127.0.01:3000
	}

(http://127.0.01:3000 is also serving with caddy2 as encode zstd gzip.)

when got 500 failed, it reports following error

{
  "error": "{id=yeq4edcjs} fileserver.(*FileServer).notFound (staticfiles.go:511): HTTP 404",
  "first_error": {
    "msg": "template: /hello/:3: unrecognized character in action: U+FFFD '�'",
    "status": 500,
    "err_id": "swt6pk6tb",
    "err_trace": "templates.(*Templates).executeTemplate (templates.go:372)"
  }
}

updated:
curl -v works fine. the issue pattern is encode zstd gzip → reverse_proxy → templates
remove encode zstd gzip from target server or the templates from current server deliminates the 500 error

francislavoie · 2022-07-06T04:14:23Z

@mindon I'm pretty sure that's not the same problem as was described in this issue either. This issue was specific to HTTP/3, and did not involve templates.

That said, we can close this soon, once we bump the quic-go dependency to v0.28.0 (FYI @mholt if you want to do that just before our next release https://github.com/lucas-clemente/quic-go/releases/tag/v0.28.0)

aaronriekenberg · 2022-07-23T12:50:40Z

Validated my original use case works in caddy 2.5.2

Thanks all! 😄

francislavoie added bug 🐞 Something isn't working upstream ⬆️ Relates to some dependency of this project labels May 30, 2022

aaronriekenberg mentioned this issue May 31, 2022

Change "HTTP/3" to "HTTP/3.0". quic-go/quic-go#3439

Merged

mindon mentioned this issue Jul 4, 2022

Can we make reverse proxy response available in templates #4420

Open

francislavoie mentioned this issue Jul 6, 2022

go.mod: Bump up quic-go to v0.28.0, fixes for BC breaks #4867

Merged

mholt closed this as completed in #4867 Jul 6, 2022

otbutz mentioned this issue Jul 13, 2022

consider enabling QUIC by default #3833

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

caddy 2.5.1 + experimental_http3 + fastcgi reverse_proxy always returns 500 #4819

caddy 2.5.1 + experimental_http3 + fastcgi reverse_proxy always returns 500 #4819

aaronriekenberg commented May 29, 2022 •

edited

Loading

francislavoie commented May 29, 2022

aaronriekenberg commented May 29, 2022

aaronriekenberg commented May 29, 2022 •

edited

Loading

aaronriekenberg commented May 30, 2022 •

edited

Loading

francislavoie commented May 30, 2022 •

edited

Loading

mholt commented May 31, 2022

marten-seemann commented May 31, 2022

aaronriekenberg commented May 31, 2022 •

edited

Loading

marten-seemann commented May 31, 2022

aaronriekenberg commented May 31, 2022

mindon commented Jun 30, 2022 •

edited

Loading

francislavoie commented Jul 6, 2022 •

edited

Loading

aaronriekenberg commented Jul 23, 2022

caddy 2.5.1 + experimental_http3 + fastcgi reverse_proxy always returns 500 #4819

caddy 2.5.1 + experimental_http3 + fastcgi reverse_proxy always returns 500 #4819

Comments

aaronriekenberg commented May 29, 2022 • edited Loading

francislavoie commented May 29, 2022

aaronriekenberg commented May 29, 2022

aaronriekenberg commented May 29, 2022 • edited Loading

aaronriekenberg commented May 30, 2022 • edited Loading

francislavoie commented May 30, 2022 • edited Loading

mholt commented May 31, 2022

marten-seemann commented May 31, 2022

aaronriekenberg commented May 31, 2022 • edited Loading

marten-seemann commented May 31, 2022

aaronriekenberg commented May 31, 2022

mindon commented Jun 30, 2022 • edited Loading

francislavoie commented Jul 6, 2022 • edited Loading

aaronriekenberg commented Jul 23, 2022

aaronriekenberg commented May 29, 2022 •

edited

Loading

aaronriekenberg commented May 29, 2022 •

edited

Loading

aaronriekenberg commented May 30, 2022 •

edited

Loading

francislavoie commented May 30, 2022 •

edited

Loading

aaronriekenberg commented May 31, 2022 •

edited

Loading

mindon commented Jun 30, 2022 •

edited

Loading

francislavoie commented Jul 6, 2022 •

edited

Loading