Reverse_proxy requests are sometimes garbled

aravind · October 27, 2021, 2:43am

1. Caddy version (`caddy version`):

2.4.5

2. How I run Caddy:

a. System environment:

docker (compose) on debian buster.

We build a Caddy with the following Dockerfile:

FROM caddy:2.4.5-builder-alpine AS builder

RUN xcaddy build \
    --with github.com/caddy-dns/lego-deprecated \
    --with github.com/kirsch33/realip \
    --with github.com/caddyserver/format-encoder

FROM caddy:2.4.5-alpine

ENV GCE_PROJECT=ctd-sandbox

COPY --from=builder /usr/bin/caddy /usr/bin/caddy

b. Command:

docker-compose up -d caddy

c. Service/unit/compose file:

version: "3"                        
                                                           
services:        
  caddy:     
    image: gcr.io/ctorg/caddy
    ports:      
      - "0.0.0.0:80:80"
      - "0.0.0.0:443:443"
    restart: always                    
    network_mode: bridge
    environment:
      - GCE_PROJECT
      - VGS_IPS                          
    volumes:                       
      - ./Caddyfile:/etc/caddy/Caddyfile                                                                               
      - caddy_data:/data                       
      - caddy_config:/config
      - ./certificates:/data/caddy/pvtcerts                                                                            
    logging:                                
      driver: gcplogs
volumes:
  caddy_data:
    driver: local
    driver_opts:
       o: bind
       type: none
       device: /mnt/vpn_data/caddy/data
  caddy_config:
    driver: local
    driver_opts:
       o: bind
       type: none
       device: /mnt/vpn_data/caddy/config

d. My complete Caddyfile or JSON config:

{
        # acme_ca https://acme-v02.api.letsencrypt.org/directory
        email meh@blah.com
        debug
}
vpn.{$GCE_PROJECT}.com {
        @vpn {
                host vpn.{$GCE_PROJECT}.com
        }
        reverse_proxy @vpn pritunl:9700
}
vgs-in.console.{$GCE_PROJECT}.com {
        tls {
                client_auth {
                        mode require_and_verify
                        trusted_leaf_cert_file /data/caddy/pvtcerts/{$GCE_PROJECT}/vgs-client.crt
                        trusted_ca_cert_file /data/caddy/pvtcerts/{$GCE_PROJECT}/myorg-ca.crt
                }
        }
        @vgs {
                host vgs-in.console.{$GCE_PROJECT}.com
                remote_ip {$VGS_IPS:127.0.0.1}
        }
        #log {
        #       format formatted "{ts} {request>headers}"
        #}
        uri @vgs strip_prefix https://{http.request.hostport}
        reverse_proxy @vgs http://console-lb.{$GCE_PROJECT}.com {
                transport http {
                        versions 1.1
                        compression off
                }
        }
}

3. The problem I’m having:

When I made requests to our site with curl, I see requests reach Caddy and then progress on to our upstream correctly. A tcpdump from the container shows Caddy making the requests correctly setting the proper HOST header, etc etc.

When a request comes in from our partners, these requests get into Caddy just fine (cert verification succeeds, etc). After this point, when Caddy sends these on to the upstream - they just get mangled completely and a tcpdump of this traffic does decode properly to ascii. I don’t even see Caddy setting the proper request headers etc when sending this to our upstream. In fact, only the ip and port make sense in the tcpdump. This request is promptly rejected by the upstream as a bad request.

I didn’t see a way to log the reverse proxy request headers and body to see why Caddy is making requests that don’t make sense.

4. Error messages and/or full log output:

Here are the Caddy log messages showing the bad requests:

{"level":"debug","ts":1635301164.1388586,"logger":"tls.handshake","msg":"choosing certificate","identifier":"vgs-in.console.ctd.com","num_choices":1}
{"level":"debug","ts":1635301164.139989,"logger":"tls.handshake","msg":"default certificate selection results","identifier":"vgs-in.console.ctd.com","subjects":["vgs-in.console.ctd.com"],"managed":true,"issuer_key":"acme-v02.api.letsencrypt.org-directory","hash":"89f51e003367a44460f61370d7a3bea4fb02e949d3f9f4bde318f49b8ff3cfc9"}
{"level":"debug","ts":1635301164.1404738,"logger":"tls.handshake","msg":"matched certificate in cache","subjects":["vgs-in.console.ctd.com"],"managed":true,"expiration":1639104921,"hash":"89f51e003367a44460f61370d7a3bea4fb02e949d3f9f4bde318f49b8ff3cfc9"}
{"level":"debug","ts":1635301164.2852256,"logger":"http.handlers.rewrite","msg":"rewrote request","request":{"remote_addr":"34.14.28.15:38109","proto":"HTTP/1.1","method":"POST","host":"vgs-in.console.ctd.com:443","uri":"https://vgs-in.console.ctd.com:443/api/v1/console/connected-integrations/","headers":{"X-Forwarded-Host":["vgs.console.ctd.com"],"Via":["terminator","1.1 reverse-proxy-01-659d7775fb-jqn9k"],"X-B3-Sampled":["1"],"Accept":["*/*"],"Content-Type":["application/json"],"X-Real-Ip":["76.126.248.198"],"X-Forwarded-For":["76.126.248.198, 52.7.148.215"],"Content-Length":["100"],"B3":["6521731aba110191b89273ed7c53256d-f425f8bf50a47bbd-1"],"Vgs-Request-Id":["6521731aba110191b89273ed7c53256d"],"X-B3-Traceid":["6521731aba110191b89273ed7c53256d"],"X-B3-Spanid":["2bd0fe88b6a040f3"],"User-Agent":["curl/7.79.1"],"Vgs-Tenant":["tntirtsalns"],"X-Forwarded-Port":["443"],"X-Forwarded-Proto":["https"]},"tls":{"resumed":false,"version":771,"cipher_suite":49195,"proto":"","proto_mutual":true,"server_name":"vgs-in.console.ctd.com","client_common_name":"vgs-client","client_serial":"415904724679373504317541964934275127265629157207"}},"method":"POST","uri":"/api/v1/console/connected-integrations/"}
{"level":"debug","ts":1635301164.3453803,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"console-lb.ctd.com:80","request":{"remote_addr":"34.14.28.15:38109","proto":"HTTP/1.1","method":"POST","host":"vgs-in.console.ctd.com:443","uri":"/api/v1/console/connected-integrations/","headers":{"User-Agent":["curl/7.79.1"],"Vgs-Tenant":["tntirtsalns"],"X-Forwarded-Port":["443"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["vgs.console.ctd.com"],"Via":["terminator","1.1 reverse-proxy-01-659d7775fb-jqn9k"],"X-B3-Sampled":["1"],"Content-Length":["100"],"Accept":["*/*"],"Content-Type":["application/json"],"X-Real-Ip":["76.126.248.198"],"X-Forwarded-For":["76.126.248.198, 52.7.148.215, 134.14.28.15"],"X-B3-Spanid":["2bd0fe88b6a040f3"],"B3":["6521731aba110191b89273ed7c53256d-f425f8bf50a47bbd-1"],"Vgs-Request-Id":["6521731aba110191b89273ed7c53256d"],"X-B3-Traceid":["6521731aba110191b89273ed7c53256d"]},"tls":{"resumed":false,"version":771,"cipher_suite":49195,"proto":"","proto_mutual":true,"server_name":"vgs-in.console.ctd.com","client_common_name":"vgs-client","client_serial":"415904724679373504317541964934275127265629157207"}},"duration":0.05931753,"error":"tls: first record does not look like a TLS handshake"}
{"level":"error","ts":1635301164.346308,"logger":"http.log.error","msg":"tls: first record does not look like a TLS handshake","request":{"remote_addr":"134.14.28.15:38109","proto":"HTTP/1.1","method":"POST","host":"vgs-in.console.ctd.com:443","uri":"https://vgs-in.console.ctd.com:443/api/v1/console/connected-integrations/","headers":{"X-Forwarded-Host":["vgs.console.ctd.com"],"Via":["terminator","1.1 reverse-proxy-01-659d7775fb-jqn9k"],"X-B3-Sampled":["1"],"Accept":["*/*"],"Content-Type":["application/json"],"X-Real-Ip":["76.126.248.198"],"X-Forwarded-For":["76.126.248.198, 52.7.148.215"],"Content-Length":["100"],"B3":["6521731aba110191b89273ed7c53256d-f425f8bf50a47bbd-1"],"Vgs-Request-Id":["6521731aba110191b89273ed7c53256d"],"X-B3-Traceid":["6521731aba110191b89273ed7c53256d"],"X-B3-Spanid":["2bd0fe88b6a040f3"],"User-Agent":["curl/7.79.1"],"Vgs-Tenant":["tntirtsalns"],"X-Forwarded-Port":["443"],"X-Forwarded-Proto":["https"]},"tls":{"resumed":false,"version":771,"cipher_suite":49195,"proto":"","proto_mutual":true,"server_name":"vgs-in.console.ctd.com","client_common_name":"vgs-client","client_serial":"415904724679373504317541964934275127265629157207"}},"duration":0.061101323,"status":502,"err_id":"evr97v2eb","err_trace":"reverseproxy.statusError (reverseproxy.go:858)"}

5. What I already tried:

The upstream logs weren’t helpful here - the requests are basically reject as being garbage. I can provide a tcpdump capture file, but that doesn’t show anything - no request headers etc… It just looks like random binary data.

The one message that seems to stand out from Caddy logs is “tls: first record does not look like a TLS handshake” - which doesn’t make sense since both Caddy logs and the remote side seem to think that a https connection was established just fine…

I am at a loss as to how Caddy is making an upstream request without setting any proper request headers etc - and how this garbled upstream request is being generated.

francislavoie · October 27, 2021, 4:02am

So what’s actually going on here is that the client is making a request with a weird/bad/invalid request header line, i.e. it’s including the scheme+host+port. For example, it’s making a request like:

GET https://vgs-in.console.ctd.com:443/api/v1/console/connected-integrations/

But it should look like:

GET /api/v1/console/connected-integrations/

Technically the former is valid HTTP, but it doesn’t really make sense unless trying to connect to a forward proxy, to tell it where to make a request on your behalf.

What ends up happening is that the http.Request from Go’s stdlib holds onto this extra information in the URL in the request, then the request gets reused to dial the upstream, but the assumption is that the scheme/host/port on the URL field should typically be empty. But since it’s not, Caddy ends up trying to set up a TLS connection to your upstream, even though you configured HTTP.

We do have a fix, which has coincidentally just been merged today to the master branch:

github.com/caddyserver/caddy

reverseproxy: Sanitize scheme and host on incoming requests

caddyserver:master ← caddyserver:sanitize-request

opened 08:54PM - 06 Jul 21 UTC

francislavoie

+14 -0

See https://caddy.community/t/caddy-attempts-to-connect-downstream-server-via-ht…tps-although-not-configured-to-do-so/12765 for context, and later another report of the same problem in https://caddy.community/t/reverse-proxying-trying-to-make-a-tls-connection-to-an-http-only-backend/13954 Basically some wacky HTTP clients may sometimes make HTTP requests with request-line like this: ``` GET https://example.com/some/path Host: example.com ``` _Most_ well behaved clients make requests like this: ``` GET /some/path Host: example.com ``` Technically, both are valid as per HTTP RFCs, but the former ends up breaking some assumptions that the code makes, like that the scheme is empty before being passed onto the `reverse_proxy` module. The effect was that these requests would tell `http.Client` to use a different scheme than configured. For example, configured `reverse_proxy` to proxy over HTTP, but the scheme in the original request's request-line had `https://` so it would try to proxy over HTTPS :scream: The docs for [`Request.URL`](https://golang.org/pkg/net/http/#Request.URL) do say: // For server requests, the URL is parsed from the URI // supplied on the Request-Line as stored in RequestURI. For // most requests, fields other than Path and RawQuery will be // empty. (See RFC 7230, Section 5.3) So it's definitely pretty unexpected to receive the scheme and host in the URL. This change should just wipe out the scheme and host in the URL, which are otherwise covered by `Request.Host` and `Request.TLS` (and that's how all of the code in Caddy access the host and whether the request was secured). ~~I realize this is a risky change because it affects _every request_ handled by Caddy. We should definitely tread lightly here. But I think this is the most logical and simplest way to solve this.~~ I've adjusted the implementation to only do the sanitization in the `reverseproxy` package, and to restore it after `reverseproxy` is done.

So for the time being, you can build from the latest commit on master, i.e. xcaddy build f73f55d, to get that fix.

aravind · October 27, 2021, 4:16am

@francislavoie actually I did notice that bit in my debugging and I had added this bit of config line in prior attempts:

uri @vgs strip_prefix https://{http.request.hostport}

With that bit of rewrite, the uri is stripped to the correct one, but I still see a garbage request being made to the upstream. Does this uri re-write on my end not fix the issue?

I extracted the certs and tested this setup against nginx and it seems to pass the request through correctly. I am only mentioning this here to validate my certs/setup and I also wanted to test this setup to verify that something wasn’t totally goofy with the partner requests.

francislavoie · October 27, 2021, 4:30am

That rewrite actually does nothing. uri strip_prefix can only affect the “path” portion of the URI. See the docs: uri (Caddyfile directive) — Caddy Documentation

To be clear, it’s not a “garbage request”, it’s actually an attempt at a TLS handshake that you’re seeing.

Like I said, the bug is fixed, just build from the latest commit on master!

aravind · October 27, 2021, 4:57am

I see, thank you for the explanation. I will build from master and try it tomorrow. I appreciate the prompt responses and the bugfixes.

system · November 26, 2021, 2:43am

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