Reverse_proxy difference when building with "xcaddy" vs "go build"

Help
1

1. Output of caddy version:

When using xcaddy: v2.6.1 h1:EDqo59TyYWhXQnfde93Mmv4FJfYe00dO60zMiEt+pzo=
when using “go build” of 2.6.1: 9206e8a7381d62a5f8362f541ab9c052f06a9d50 (21 Sep 22 18:59 UTC)

2. How I run Caddy:

a. System environment:

macOS 12.6

b. Command:

ROOT=`pwd` caddy start

c. Service/unit/compose file:

N/A

Paste full file contents here.
Make sure backticks stay on their own lines,
and the post looks nice in the preview pane. -->

d. My complete Caddy config:

Sorry, I cannot leave domain names or paths intact due to confidentiality requirements

{
  log {
    output file {$ROOT}/caddy/caddy.log {
      roll_size 1MiB
      roll_keep 1
    }
  }
}

(use_server) {
  log {
    output file {$ROOT}/caddy/access.log {
      roll_size 1MiB
      roll_keep 1
    }
  }
 
	tls internal

  root * {$ROOT}/dist

	handle /foo/v1/api/bar.js {
		try_files /bar.js =404
		file_server
	}

	@matchproxied {
		path /path1/*
		path /path2/*
		path /endpoint
		path /path3/*
		path /path4/*
	}
	handle @matchproxied {
    reverse_proxy https://{args.0} {
      health_timeout 10m
      transport http {
        dial_timeout 10m
        versions 1.1
      }

      header_up Host {upstream_hostport}
      header_up Set-Cookie {host} {args.0}
      header_up -X-Forwarded-For
      header_up -X-Forwarded-Proto
      header_up -X-Forwarded-Host

      header_down Access-Control-Allow-Origin *
      header_down Set-Cookie {args.0} {host}
    }
  }

	handle {
		header +Access-Control-Allow-Origin *;
		try_files {path} /index.html =404;
		file_server
	}
}

local.testdomain.com:8443 {
  import use_server www.testdomain.com
}

staging.testdomain.com:8443 {
  import use_server staging.testdomain.com
}

prod.testdomain.com:8443 {
  import use_server www.testdomain.com
}

3. The problem I’m having:

I’m seeing a difference in behaviour when using caddy built with xcaddy vs built from the repo using go build (following the instructions in GitHub - caddyserver/caddy: Fast and extensible multi-platform HTTP/3 web server with automatic HTTPS)

When using the xcaddy version making requests to local.testdomain.com and staging.testdomain.com works as expected, but all requests to prod.testdomain.com time out.

However, when using the go build version requests to all 3 domains are successful.

Why would the different build processes cause this difference in behaviour?

4. Error messages and/or full log output:

Example of a request that timed out:

2022/09/27 18:00:20.060 error   http.log.access.log0    handled request {"request": {"remote_ip": "127.0.0.1", "remote_port": "56120", "proto": "HTTP/1.1", "method": "GET", "host": "www.testdomain.com:8443", "uri": "/path1/endpoint?", "headers": {"Cookie": [], "Referer": ["https://www.testdomain.com:8443/"], "Cache-Control": ["no-cache"], "X-Csrf-Token": ["***"], "Pragma": ["no-cache"], "Accept-Encoding": ["gzip, deflate, br"], "Connection": ["keep-alive"], "Accept": ["*/*"], "User-Agent": ["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.0 Safari/605.1.15"], "Accept-Language": ["en-CA,en-US;q=0.9,en;q=0.8"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "", "server_name": "www.testdomain.com"}}, "user_id": "", "duration": 79.748940769, "size": 0, "status": 502, "resp_headers": {"Server": ["Caddy"], "Alt-Svc": ["h3=\":8443\"; ma=2592000"]}}

Paste logs/commands/output here.
USE THE PREVIEW PANE TO MAKE SURE IT LOOKS NICELY FORMATTED.

5. What I already tried:

I was trying to debug the timeout issue, that’s how I discovered a manual build did not have the same problem. So here I am…

2

What is your xcaddy command?

How can we reproduce the results?

3

I downloaded the latest binary from the xcaddy repo and ran
xcaddy build
The same issue is present in the binary installed by Homebrew (homebrew-core/caddy.rb at 7e38db19852e0ea5ef3735b0121959f0f9ce5d01 · Homebrew/homebrew-core · GitHub)

Unfortunately I don’t have a way of reproducing this with a server you would be able to access, this is a very locked down environment.

I know this is not ideal, but I am happy to try things to debug this if pointed in the right direction.

4

First port of call is probably to go for debug: Global options (Caddyfile) — Caddy Documentation

Start it up, run a request, then bring it down with each Caddy binary - both working (go build) and non-working (xcaddy) built variants - and post both full sets of logs for us to compare. Unredacted, if at all possible.

Try to avoid redacting your domain name with other, real domain names - somebody else owns testdomain.com. The IANA reserves example.com and example.net for this purpose. Your actual domain will likely make things simpler, though, and certificate transparency renders security through domain name obscurity moot anyway.

1 Like
5

Apologies for using real domain names, I’ll use the ones reserved for this purpose from now on. Sorry, I can’t reveal the real domain name, not up to me to decide.

Here are the logs for one request after turning on the debug setting:

xcaddy


2022/09/28 16:04:52.973	debug	events	event	{"name": "tls_get_certificate", "id": "1fb4cc86-48c4-4614-acfb-6a85454ed74b", "origin": "tls", "data": {"client_hello":{"CipherSuites":[4866,4867,4865,49200,49196,49192,49188,49172,49162,159,107,57,52393,52392,52394,65413,196,136,129,157,61,53,192,132,49199,49195,49191,49187,49171,49161,158,103,51,190,69,156,60,47,186,65,49169,49159,5,4,49170,49160,22,10,255],"ServerName":"prod.local","SupportedCurves":[29,23,24,25],"SupportedPoints":"AA==","SignatureSchemes":[2054,1537,1539,2053,1281,1283,2052,1025,1027,513,515],"SupportedProtos":["h2","http/1.1"],"SupportedVersions":[772,771,770,769],"Conn":{}}}}
2022/09/28 16:04:52.974	debug	tls.handshake	choosing certificate	{"identifier": "prod.local", "num_choices": 1}
2022/09/28 16:04:52.974	debug	tls.handshake	default certificate selection results	{"identifier": "prod.local", "subjects": ["prod.local"], "managed": true, "issuer_key": "local", "hash": "8cb49e0160a2c8330ae492ab1cfe745d1000b8ea90c94e46ed2c0905e5ef227b"}
2022/09/28 16:04:52.974	debug	tls.handshake	matched certificate in cache	{"remote_ip": "127.0.0.1", "remote_port": "62953", "subjects": ["prod.local"], "managed": true, "expiration": "2022/09/28 20:56:53.000", "hash": "8cb49e0160a2c8330ae492ab1cfe745d1000b8ea90c94e46ed2c0905e5ef227b"}
2022/09/28 16:04:52.995	debug	http.handlers.reverse_proxy	selected upstream	{"dial": "prod.example.com:443", "total_upstreams": 1}
2022/09/28 16:06:13.002	debug	http.handlers.reverse_proxy	upstream roundtrip	{"upstream": "prod.example.com:443", "duration": 80.004422467, "request": {"remote_ip": "127.0.0.1", "remote_port": "62953", "proto": "HTTP/2.0", "method": "GET", "host": "prod.example.com:443", "uri": "/api/endpoint", "headers": {"Cache-Control": ["no-cache"], "X-Csrf-Token": ["***"], "Accept": ["*/*"], "User-Agent": ["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.0 Safari/605.1.15"], "Referer": ["https://prod.local:8443"], "Pragma": ["no-cache"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h2", "server_name": "prod.local"}}, "error": "dial tcp ***.***.***.***:443: connect: operation timed out"}
2022/09/28 16:06:13.005	error	http.log.error.log2	dial tcp ***.***.***.***:443: connect: operation timed out	{"request": {"remote_ip": "127.0.0.1", "remote_port": "62953", "proto": "HTTP/2.0", "method": "GET", "host": "prod.local:8443", "uri": "/api/endpoint", "headers": {"Referer": ["https://prod.local:8443"], "Accept": ["*/*"], "User-Agent": ["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.0 Safari/605.1.15"], "Pragma": ["no-cache"], "Cache-Control": ["no-cache"], "X-Csrf-Token": ["***"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h2", "server_name": "prod.local"}}, "duration": 80.007844101, "status": 502, "err_id": "70qaxgeq4", "err_trace": "reverseproxy.statusError (reverseproxy.go:1271)"}
2022/09/28 16:06:13.005	error	http.log.access.log2	handled request	{"request": {"remote_ip": "127.0.0.1", "remote_port": "62953", "proto": "HTTP/2.0", "method": "GET", "host": "prod.local:8443", "uri": "/api/endpoint", "headers": {"Accept": ["*/*"], "User-Agent": ["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.0 Safari/605.1.15"], "Pragma": ["no-cache"], "Cache-Control": ["no-cache"], "X-Csrf-Token": ["***"], "Referer": ["https://prod.local:8443"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h2", "server_name": "prod.local"}}, "user_id": "", "duration": 80.007844101, "size": 0, "status": 502, "resp_headers": {"Server": ["Caddy"], "Alt-Svc": ["h3=\":8443\"; ma=2592000"]}}

go build

2022/09/28 16:08:52.934	debug	events	event	{"name": "tls_get_certificate", "id": "7c60846c-9bdd-441b-872b-ce9ec5dd79fb", "origin": "tls", "data": {"client_hello":{"CipherSuites":[4866,4867,4865,49200,49196,49192,49188,49172,49162,159,107,57,52393,52392,52394,65413,196,136,129,157,61,53,192,132,49199,49195,49191,49187,49171,49161,158,103,51,190,69,156,60,47,186,65,49169,49159,5,4,49170,49160,22,10,255],"ServerName":"prod.local","SupportedCurves":[29,23,24,25],"SupportedPoints":"AA==","SignatureSchemes":[2054,1537,1539,2053,1281,1283,2052,1025,1027,513,515],"SupportedProtos":["h2","http/1.1"],"SupportedVersions":[772,771,770,769],"Conn":{}}}}
2022/09/28 16:08:52.934	debug	tls.handshake	choosing certificate	{"identifier": "prod.local", "num_choices": 1}
2022/09/28 16:08:52.934	debug	tls.handshake	default certificate selection results	{"identifier": "prod.local", "subjects": ["prod.local"], "managed": true, "issuer_key": "local", "hash": "8cb49e0160a2c8330ae492ab1cfe745d1000b8ea90c94e46ed2c0905e5ef227b"}
2022/09/28 16:08:52.934	debug	tls.handshake	matched certificate in cache	{"remote_ip": "127.0.0.1", "remote_port": "62972", "subjects": ["prod.local"], "managed": true, "expiration": "2022/09/28 20:56:53.000", "hash": "8cb49e0160a2c8330ae492ab1cfe745d1000b8ea90c94e46ed2c0905e5ef227b"}
2022/09/28 16:08:52.949	debug	http.handlers.reverse_proxy	selected upstream	{"dial": "prod.example.com:443", "total_upstreams": 1}
2022/09/28 16:08:53.024	debug	http.handlers.reverse_proxy	upstream roundtrip	{"upstream": "prod.example.com:443", "duration": 0.074966453, "request": {"remote_ip": "127.0.0.1", "remote_port": "62972", "proto": "HTTP/2.0", "method": "GET", "host": "prod.example.com:443", "uri": "/api/endpoint", "headers": {"X-Csrf-Token": ["***"], "Referer": ["https://prod.local:8443"], "Accept": ["*/*"], "User-Agent": ["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.0 Safari/605.1.15"], "Pragma": ["no-cache"], "Cache-Control": ["no-cache"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h2", "server_name": "prod.local"}}, "headers": {"Content-Type": ["application/json"], "Content-Length": ["127"], "Connection": ["keep-alive"], "Vary": ["Accept-Encoding"], "Access-Control-Allow-Origin": ["https://prod.example.com"], "Server": ["nginx"], "Date": ["Wed, 28 Sep 2022 16:08:52 GMT"]}, "status": 401}
2022/09/28 16:08:53.025	error	http.log.access.log2	handled request	{"request": {"remote_ip": "127.0.0.1", "remote_port": "62972", "proto": "HTTP/2.0", "method": "GET", "host": "prod.local:8443", "uri": "/api/endpoint", "headers": {"Cache-Control": ["no-cache"], "X-Csrf-Token": ["***"], "Referer": ["https://prod.local:8443"], "Accept": ["*/*"], "User-Agent": ["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.0 Safari/605.1.15"], "Pragma": ["no-cache"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h2", "server_name": "prod.local"}}, "user_id": "", "duration": 0.075553573, "size": 127, "status": 401, "resp_headers": {"Access-Control-Allow-Origin": ["*"], "Server": ["Caddy", "nginx"], "Alt-Svc": ["h3=\":8443\"; ma=2592000"], "Date": ["Wed, 28 Sep 2022 16:08:52 GMT"], "Content-Type": ["application/json"], "Content-Length": ["127"], "Vary": ["Accept-Encoding"]}}
6

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