Understanding how caddy.storage.redis works, caddy re-request certificate after migration

renodesper · April 2, 2024, 2:52am

1. The problem I’m having:

My company ran into a problem and we had to create a new server instance for our caddy. We had difficulty moving all the certificates we had and ended up planning to store the certificates in Redis.

We tested exporting with the old config and importing with the new config and succeeded in seeing the certificate enter Redis. But when we try to call the domain that we have directed to caddy, caddy tries to create a new certificate. We have tried using 3 domains and all of them requested new certificates. Apart from that, we also see that the /var/lib/caddy folder has a size of around 210MB even though Caddy already uses Redis as storage.

P.S. We have deleted all folders related to caddy before trying the export and import process. Also, we use github.com/pberkel/caddy-storage-redis.

Can you explain how to use external storage in a caddy? Is it normal for the contents of the /var/lib/caddy folder to be quite large because the certificate is downloaded locally before being added to Redis? Is it common for caddy to re-request a certificate even though the certificate is already exist in Redis? Or did we make a mistake in our caddy config?

We appreciate your help, thank you.

2. Error messages and/or full log output:

PASTE OVER THIS, BETWEEN THE ``` LINES.
Please use the preview pane to ensure it looks nice.

3. Caddy version:

2.7.6

4. How I installed and ran Caddy:

a. System environment:

b. Command:

PASTE OVER THIS, BETWEEN THE ``` LINES.
Please use the preview pane to ensure it looks nice.

c. Service/unit/compose file:

● caddy.service - Caddy
     Loaded: loaded (/etc/systemd/system/caddy.service; enabled; vendor preset: enabled)
     Active: active (running) since Mon 2024-04-01 09:53:25 UTC; 17h ago
       Docs: https://caddyserver.com/docs/
   Main PID: 5479 (caddy)
      Tasks: 13 (limit: 18944)
     Memory: 21.4M
     CGroup: /system.slice/caddy.service
             └─5479 /usr/bin/caddy run --environ --config /etc/caddy/Caddyfile

d. My complete Caddy config:

{
	on_demand_tls {
		ask https://domain.com/domain-checker
	}

	storage redis {
		host HOST
		port 6379
		password PASSWORD
		db 0
		timeout 5
		key_prefix "caddy"
		tls_enabled false
		tls_insecure true
	}
}

*.domain.com {
	tls email@gmail.com {
		on_demand
	}

	respond /notfound 404

	encode gzip

	reverse_proxy /storefront/* https://domain.com {
		header_up oo-api-key our_api_key
	}

	reverse_proxy /page/* for-specific-page.ap-southeast-1.elasticbeanstalk.com {
		header_down Access-Control-Allow-Origin "*"
	}

	reverse_proxy /* {
        to our_server:8000
        to our_server:8000
        to our_server:8000

		lb_policy least_conn
		fail_duration 30s

		header_down Access-Control-Allow-Origin *
		header_down Access-Control-Allow-Methods "GET, POST, PUT, PATCH, OPTIONS, DELETE"
	}

	@assets path /js* /css* /favicon.ico
	header @assets Cache-Control "public, max-age=31536000;"

	log {
		output stdout
		format json
	}
}

:80 {
	respond /notfound 404

	encode gzip

	reverse_proxy /storefront/* https://domain.com {
		header_up oo-api-key our_api_key
	}

	reverse_proxy /page/* for-specific-page.ap-southeast-1.elasticbeanstalk.com {
		header_down Access-Control-Allow-Origin "*"
	}

	reverse_proxy /* {
        to our_server:8000
        to our_server:8000
        to our_server:8000

		lb_policy least_conn
		fail_duration 30s

		header_up Host {host}
	}

	@assets path /js* /css* /favicon.ico
	header @assets Cache-Control "public, max-age=31536000;"

	log {
		output stdout
		format json
	}
}

:443 {
	tls email@gmail.com {
		on_demand
	}

	respond /notfound 404

	encode gzip

	reverse_proxy /storefront/* https://domain.com {
		header_up oo-api-key our_api_key
	}

	reverse_proxy /page/* for-specific-page.ap-southeast-1.elasticbeanstalk.com {
		header_down Access-Control-Allow-Origin "*"
	}

	reverse_proxy /* {
        to our_server:8000
        to our_server:8000
        to our_server:8000

		lb_policy least_conn
		fail_duration 30s

		header_up Host {host}
	}

	@assets path /js* /css* /favicon.ico
	header @assets Cache-Control "public, max-age=31536000;"

	log {
		output stdout
		format json
	}
}

5. Links to relevant resources:

matt · April 2, 2024, 4:22am

How did you transfer your certificates in storage? Did you use the caddy storage export/import commands?

renodesper · April 2, 2024, 4:30am

Yes.
I use this command:

sudo -u caddy caddy storage export -c /etc/caddy/Caddyfile -o- | sudo -u caddy caddy storage import -c ./Caddyfile -i-

francislavoie · April 2, 2024, 6:59am

That assumes /etc/caddy/Caddyfile is your old config (without redis storage config) and your new config is ./Caddyfile, with your redis config. Is that correct? Does your caddy binary (i.e. which caddy) have the redis plugin installed at this point?

Export + import will not delete the existing data from /var/lib/caddy, it’ll still leave it around. export + import just copies the data over to the new storage.

You’ve confirmed the data is in Redis? What does an example key look like in Redis?

Show your Caddy logs with the debug global option enabled. Show the logs for Caddy process startup + the TLS handshake for a request.

renodesper · April 5, 2024, 6:51am

Yes, you’re correct. The Caddy binary has been compiled with the Redis plugin as well.

That makes sense. So, it is not an issue when we can still find the lingering files and folders, right?

I did. I can see the data in the Redis. Is it correct that Caddy will store 5 keys per certificate? I saw 5 new rows when I tried calling a domain that pointed to the Caddy instance.

Currently, Caddy has been deployed to AWS ECS using the configuration below. I tested it using a subdomain and a domain, for example:

But somehow, the SSL version of personal.com returns personal.company.com certificate. It even returns the same thing after I delete all keys that exist in Redis (Redis is empty).

This is the Caddy log with debug enabled:

{"level":"info","ts":1712291357.145801,"msg":"using provided configuration","config_file":"/etc/caddy/Caddyfile","config_adapter":""}
{"level":"warn","ts":1712291357.1536682,"logger":"admin","msg":"admin endpoint on open interface; host checking disabled","address":"0.0.0.0:2020"}
{"level":"info","ts":1712291357.1534324,"logger":"admin","msg":"admin endpoint started","address":"0.0.0.0:2020","enforce_origin":false,"origins":["//0.0.0.0:2020"]}
{"level":"info","ts":1712291357.2488458,"logger":"caddy.storage.redis","msg":"Provision Redis simple storage using address [redis.domain.com:6379]"}
{"level":"debug","ts":1712291357.2496994,"logger":"http.auto_https","msg":"adjusted config","tls":{"automation":{"policies":[{"on_demand":true}],"on_demand":{"ask":"https://api.domain.com/domain-checker"}}},"http":{"servers":{"srv0":{"listen":[":443"],"routes":[{"handle":[{"handler":"headers","response":{"set":{"Cache-Control":["public, max-age=31536000;"]}}}]},{"handle":[{"encodings":{"br":{},"gzip":{},"zstd":{}},"handler":"encode","prefer":["br","zstd","gzip"]}]},{"handle":[{"handler":"reverse_proxy","headers":{"request":{"set":{"Oo-Api-Key":["some-api-key"]}}},"transport":{"protocol":"http","tls":{}},"upstreams":[{"dial":"api.domain.com:443"}]}]},{"handle":[{"handler":"reverse_proxy","headers":{"request":{"set":{"X-Real-Ip":["{http.request.header.X-Forwarded-For}"]}},"response":{"set":{"Access-Control-Allow-Origin":["*"]}}},"upstreams":[{"dial":"specific-page.ap-southeast-1.elasticbeanstalk.com:80"}]}]},{"handle":[{"handler":"reverse_proxy","headers":{"request":{"set":{"Host":["{http.request.host}"],"X-Real-Ip":["{http.request.header.X-Forwarded-For}"]}}},"health_checks":{"passive":{"fail_duration":30000000000}},"load_balancing":{"selection_policy":{"policy":"least_conn"}},"upstreams":[{"dial":"y.y.y.y:2015"},{"dial":"z.z.z.z:2015"},{"dial":"x.x.x.x:2015"}]}]}],"tls_connection_policies":[{}],"automatic_https":{},"logs":{"default_logger_name":"log1"}},"srv1":{"listen":[":80"],"routes":[{"handle":[{"handler":"headers","response":{"set":{"Cache-Control":["public, max-age=31536000;"]}}}]},{"handle":[{"handler":"reverse_proxy","headers":{"request":{"set":{"Oo-Api-Key":["some-api-key"]}}},"transport":{"protocol":"http","tls":{}},"upstreams":[{"dial":"api.domain.com:443"}]}]},{"handle":[{"handler":"reverse_proxy","headers":{"request":{"set":{"X-Real-Ip":["{http.request.header.X-Forwarded-For}"]}},"response":{"set":{"Access-Control-Allow-Origin":["*"]}}},"upstreams":[{"dial":"specific-page.ap-southeast-1.elasticbeanstalk.com:80"}]}]},{"handle":[{"handler":"reverse_proxy","headers":{"request":{"set":{"Host":["{http.request.host}"],"X-Real-Ip":["{http.request.header.X-Forwarded-For}"]}}},"health_checks":{"passive":{"fail_duration":30000000000}},"load_balancing":{"selection_policy":{"policy":"least_conn"}},"upstreams":[{"dial":"y.y.y.y:2015"},{"dial":"z.z.z.z:2015"},{"dial":"x.x.x.x:2015"}]}]},{}],"automatic_https":{"disable":true},"logs":{"default_logger_name":"log0"}},"srv2":{"listen":[":8000"],"routes":[{"handle":[{"handler":"static_response","status_code":200}]}],"automatic_https":{}}}}}
{"level":"warn","ts":1712291357.2495816,"logger":"http.auto_https","msg":"server is listening only on the HTTP port, so no automatic HTTPS will be applied to this server","server_name":"srv1","http_port":80}
{"level":"info","ts":1712291357.2495146,"logger":"http.auto_https","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
{"level":"info","ts":1712291357.249424,"logger":"http.auto_https","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":1712291357.2493804,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc0001d2800"}
{"level":"info","ts":1712291357.2507858,"msg":"failed to sufficiently increase receive buffer size (was: 208 kiB, wanted: 2048 kiB, got: 416 kiB). See https://github.com/quic-go/quic-go/wiki/UDP-Buffer-Sizes for details."}
{"level":"info","ts":1712291357.250617,"logger":"http","msg":"enabling HTTP/3 listener","addr":":443"}
{"level":"info","ts":1712291357.2515662,"msg":"serving initial configuration"}
{"level":"info","ts":1712291357.2515216,"msg":"autosaved config (load with --resume flag)","file":"/config/caddy/autosave.json"}
{"level":"info","ts":1712291357.2512903,"logger":"http.log","msg":"server running","name":"srv2","protocols":["h1","h2","h3"]}
{"level":"debug","ts":1712291357.2512481,"logger":"http","msg":"starting server loop","address":"[::]:8000","tls":false,"http3":false}
{"level":"info","ts":1712291357.2511718,"logger":"http.log","msg":"server running","name":"srv1","protocols":["h1","h2","h3"]}
{"level":"debug","ts":1712291357.2511399,"logger":"http","msg":"starting server loop","address":"[::]:80","tls":false,"http3":false}
{"level":"info","ts":1712291357.2510514,"logger":"http.log","msg":"server running","name":"srv0","protocols":["h1","h2","h3"]}
{"level":"debug","ts":1712291357.2509983,"logger":"http","msg":"starting server loop","address":"[::]:443","tls":true,"http3":true}
{"level":"warn","ts":1712291357.286291,"logger":"tls","msg":"storage cleaning happened too recently; skipping for now","storage":"{\"client_type\":\"simple\",\"address\":[\"redis.domain.com:6379\"],\"host\":[],\"port\":[],\"db\":0,\"timeout\":\"5\",\"username\":\"\",\"password\":\"REDACTED\",\"master_name\":\"\",\"key_prefix\":\"caddy\",\"encryption_key\":\"\",\"compression\":false,\"tls_enabled\":false,\"tls_insecure\":true,\"tls_server_certs_pem\":\"\",\"tls_server_certs_path\":\"\",\"route_by_latency\":false,\"route_randomly\":false}","instance":"2a958f7c-dea9-44f8-8138-a83fd2d28413","try_again":1712377757.2862842,"try_again_in":86399.999999406}
{"level":"info","ts":1712291357.3069818,"logger":"tls","msg":"finished cleaning storage units"}
{"level":"debug","ts":1712291373.6612523,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x:2015","total_upstreams":3}
{"level":"debug","ts":1712291373.6847224,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"y.y.y.y:2015","total_upstreams":3}
{"level":"debug","ts":1712291373.6847224,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"z.z.z.z:2015","total_upstreams":3}

This is the newest Caddy config that we use:

{
	on_demand_tls {
		ask https://domain.com/domain-checker
	}

	storage redis {
		host HOST
		port 6379
		password PASSWORD
		db 0
		timeout 5
		key_prefix "caddy"
		tls_enabled false
		tls_insecure true
	}
}

:80 {
	respond /notfound 404

	encode gzip

	reverse_proxy /storefront/* https://domain.com {
		header_up oo-api-key our_api_key
	}

	reverse_proxy /page/* for-specific-page.ap-southeast-1.elasticbeanstalk.com {
		header_down Access-Control-Allow-Origin "*"
	}

	reverse_proxy /* {
        to our_server:8000
        to our_server:8000
        to our_server:8000

		lb_policy least_conn
		fail_duration 30s

		header_up Host {host}
	}

	@assets path /js* /css* /favicon.ico
	header @assets Cache-Control "public, max-age=31536000;"

	log {
		output stdout
		format json
	}
}

:443 {
	tls email@gmail.com {
		on_demand
	}

	respond /notfound 404

	encode gzip

	reverse_proxy /storefront/* https://domain.com {
		header_up oo-api-key our_api_key
	}

	reverse_proxy /page/* for-specific-page.ap-southeast-1.elasticbeanstalk.com {
		header_down Access-Control-Allow-Origin "*"
	}

	reverse_proxy /* {
        to our_server:8000
        to our_server:8000
        to our_server:8000

		lb_policy least_conn
		fail_duration 30s

		header_up Host {host}
	}

	@assets path /js* /css* /favicon.ico
	header @assets Cache-Control "public, max-age=31536000;"

	log {
		output stdout
		format json
	}
}

P.S. I think the issue is not about re-requesting certificate anymore. But more about how it works because it didn’t behave as expected (returning the wrong certificate). Should I create a new post for this?

francislavoie · April 5, 2024, 2:39pm

Yeah, you can clean it up yourself if you know you’re done with it. Exporting does no deleting. Importing does no deleting. So you need to do that yourself.

By “keys” do you mean like private keys, or Redis keys? I think there should be 3 if I remember correctly (private key, cert chain, JSON metadata file). Can you show the keys you’re talking about? Probably as expected though.

Did you restart Caddy after deleting the data in storage? Caddy doesn’t fetch from storage on every request, it has an in-memory cache of certificates (IIRC up to 50,000 entries) and it persists this cache on config reload as well. Typically if a certificate is still valid, there’s no reason to get rid of it unless it’s expired or revoked – and Caddy will detect either of those cases on its own (revocation via OCSP).

renodesper · April 8, 2024, 2:35am

Actually, since ECS is container-based. When I deploy a new instance, there will be no data in the new instance. So it should fetch again from the Redis. At least, that is how it should be.

But, what about the case where it returns certificate of different domain/subdomain? It should not be possible, right?

francislavoie · April 10, 2024, 6:49pm

I don’t understand what you mean here. What’s your evidence of that? Show your logs, an example curl -v command that exhibits that behaviour.

renodesper · April 11, 2024, 9:15am

This is the example when using curl:

curl -v https://personal.my.id
* Trying x.x.x.x:443...
* Connected to personal.my.id (x.x.x.x) port 443
* ALPN: curl offers h2,http/1.1
* (304) (OUT), TLS handshake, Client hello (1):
* CAfile: /etc/ssl/cert.pem
* CApath: none
* (304) (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN: server accepted h2
* Server certificate:
* subject: CN=*.orderonline.id
* start date: Apr 7 00:00:00 2024 GMT
* expire date: May 7 23:59:59 2025 GMT
* subjectAltName does not match personal.my.id
* SSL: no alternative certificate subject name matches target host name 'personal.my.id'
* Closing connection
* TLSv1.2 (OUT), TLS alert, close notify (256):
curl: (60) SSL: no alternative certificate subject name matches target host name 'personal.my.id'
More details here: https://curl.se/docs/sslcerts.html

curl failed to verify the legitimacy of the server and therefore could not
establish a secure connection to it. To learn more about this situation and
how to fix it, please visit the web page mentioned above.

matt · April 11, 2024, 5:15pm

To debug this one and potentially make a fix, if necessary, I’ll need your help with unredacted domains.

Can you please show the curl command without redactions/edits, as well as the server logs in debug mode?

I’d also be curious as to the contents (can be abbreviated if long) of your storage in the certificates folder for each CA.

francislavoie · April 11, 2024, 7:37pm

Caddy debug logs would help too.

renodesper · April 12, 2024, 7:54am

Okay.
So the company provides a service to serve some kind of landing page and automatically gives the user a subdomain .orderonline.id. But, it also gives the user the capability to use their own domain. Both are being served by the same caddy service. This is an example (my personal domain and subdomain for testing):

curl -v https://tokobudu.my.id
*   Trying 18.139.47.158:443...
* Connected to tokobudu.my.id (18.139.47.158) port 443
* ALPN: curl offers h2,http/1.1
* (304) (OUT), TLS handshake, Client hello (1):
*  CAfile: /etc/ssl/cert.pem
*  CApath: none
* (304) (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=*.orderonline.id
*  start date: Apr  7 00:00:00 2024 GMT
*  expire date: May  7 23:59:59 2025 GMT
*  subjectAltName does not match tokobudu.my.id
* SSL: no alternative certificate subject name matches target host name 'tokobudu.my.id'
* Closing connection
* TLSv1.2 (OUT), TLS alert, close notify (256):
curl: (60) SSL: no alternative certificate subject name matches target host name 'tokobudu.my.id'
More details here: https://curl.se/docs/sslcerts.html

curl failed to verify the legitimacy of the server and therefore could not
establish a secure connection to it. To learn more about this situation and
how to fix it, please visit the web page mentioned above.

My subdomain is boysandy.orderonline.id. And my custom domain is tokobudu.my.id. Both pointed to the same caddy.

It is enabled already.

Anyway, the log is too big, so I will send it as a separate comment.

renodesper · April 12, 2024, 7:56am

April 12, 2024 at 14:39 (UTC+7:00)	{"level":"info","ts":1712907585.6180544,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"172.31.16.159","remote_port":"40186","client_ip":"172.31.16.159","proto":"HTTP/1.1","method":"GET","host":"tokobudu.my.id","uri":"/sw.js","headers":{"X-Amzn-Trace-Id":["Root=1-6618e541-6c9231bf4d4a04786c882960"],"Sec-Fetch-Mode":["same-origin"],"Accept":["*/*"],"Service-Worker":["script"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36"],"Accept-Language":["en-US,en;q=0.9"],"Cookie":[],"X-Forwarded-For":["114.122.108.242"],"X-Forwarded-Proto":["https"],"Dnt":["1"],"Sec-Fetch-Site":["same-origin"],"Sec-Fetch-Dest":["serviceworker"],"Referer":["https://tokobudu.my.id/"],"X-Forwarded-Port":["443"],"Cache-Control":["max-age=0"],"Accept-Encoding":["gzip, deflate, br, zstd"]}},"bytes_read":0,"user_id":"","duration":0.001238643,"size":388,"status":200,"resp_headers":{"Server":["Caddy","Caddy"],"Content-Type":["application/javascript"],"Last-Modified":["Wed, 27 May 2020 12:20:28 GMT"],"Content-Encoding":["gzip"],"Date":["Fri, 12 Apr 2024 07:39:45 GMT"],"Accept-Ranges":["bytes"],"Access-Control-Allow-Methods":["GET, POST, PUT, DELETE, OPTIONS"],"Vary":["Accept-Encoding"],"Content-Length":["388"],"Access-Control-Allow-Headers":["Content-Type"],"Etag":["W/\"qazoy4pf\""]}}	
April 12, 2024 at 14:39 (UTC+7:00)	{"level":"debug","ts":1712907585.6179254,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"x.x.x.x","duration":0.001014452,"request":{"remote_ip":"172.31.16.159","remote_port":"40186","client_ip":"172.31.16.159","proto":"HTTP/1.1","method":"GET","host":"tokobudu.my.id","uri":"/sw.js","headers":{"Sec-Fetch-Site":["same-origin"],"Cache-Control":["max-age=0"],"Accept":["*/*"],"Referer":["https://tokobudu.my.id/"],"X-Real-Ip":["114.122.108.242"],"Accept-Encoding":["gzip, deflate, br, zstd"],"Cookie":[],"X-Forwarded-Proto":["http"],"Dnt":["1"],"X-Forwarded-For":["172.31.16.159"],"Service-Worker":["script"],"Sec-Fetch-Mode":["same-origin"],"Accept-Language":["en-US,en;q=0.9"],"X-Forwarded-Host":["tokobudu.my.id"],"X-Amzn-Trace-Id":["Root=1-6618e541-6c9231bf4d4a04786c882960"],"X-Forwarded-Port":["443"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36"],"Sec-Fetch-Dest":["serviceworker"]}},"headers":{"Access-Control-Allow-Methods":["GET, POST, PUT, DELETE, OPTIONS"],"Content-Type":["application/javascript"],"Last-Modified":["Wed, 27 May 2020 12:20:28 GMT"],"Vary":["Accept-Encoding"],"Content-Length":["388"],"Accept-Ranges":["bytes"],"Content-Encoding":["gzip"],"Etag":["W/\"qazoy4pf\""],"Server":["Caddy"],"Date":["Fri, 12 Apr 2024 07:39:45 GMT"],"Access-Control-Allow-Headers":["Content-Type"]},"status":200}	
April 12, 2024 at 14:35 (UTC+7:00)	{"level":"debug","ts":1712907344.0080087,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"x.x.x.x","duration":0.000998797,"request":{"remote_ip":"172.31.36.245","remote_port":"44084","client_ip":"172.31.36.245","proto":"HTTP/1.1","method":"GET","host":"boysandy.orderonline.id","uri":"/sw.js","headers":{"X-Forwarded-For":["172.31.36.245"],"Cache-Control":["max-age=0"],"Accept-Encoding":["gzip, deflate, br, zstd"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36"],"Service-Worker":["script"],"Dnt":["1"],"Sec-Fetch-Dest":["serviceworker"],"Sec-Fetch-Site":["same-origin"],"Accept-Language":["en-US,en;q=0.9"],"Accept":["*/*"],"If-Modified-Since":["Wed, 27 May 2020 12:20:28 GMT"],"X-Forwarded-Port":["443"],"X-Forwarded-Host":["boysandy.orderonline.id"],"X-Real-Ip":["114.122.108.242"],"X-Amzn-Trace-Id":["Root=1-6618e450-1557f28a2b24922f2601442f"],"Sec-Fetch-Mode":["same-origin"],"If-None-Match":["W/\"qazoy4pf\""],"X-Forwarded-Proto":["http"],"Cookie":[],"Referer":["https://boysandy.orderonline.id/"]}},"headers":{"Accept-Ranges":["bytes"],"Access-Control-Allow-Methods":["GET, POST, PUT, DELETE, OPTIONS"],"Date":["Fri, 12 Apr 2024 07:35:43 GMT"],"Access-Control-Allow-Headers":["Content-Type"],"Content-Encoding":["gzip"],"Content-Type":["application/javascript"],"Etag":["W/\"q48x9dpf\""],"Last-Modified":["Fri, 17 Jan 2020 10:03:13 GMT"],"Server":["Caddy"],"Vary":["Accept-Encoding"],"Content-Length":["388"]},"status":200}	
April 12, 2024 at 14:35 (UTC+7:00)	{"level":"info","ts":1712907344.0081902,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"172.31.36.245","remote_port":"44084","client_ip":"172.31.36.245","proto":"HTTP/1.1","method":"GET","host":"boysandy.orderonline.id","uri":"/sw.js","headers":{"X-Amzn-Trace-Id":["Root=1-6618e450-1557f28a2b24922f2601442f"],"Dnt":["1"],"Accept-Encoding":["gzip, deflate, br, zstd"],"If-None-Match":["W/\"qazoy4pf\""],"X-Forwarded-Proto":["https"],"Cache-Control":["max-age=0"],"Sec-Fetch-Dest":["serviceworker"],"X-Forwarded-For":["114.122.108.242"],"Sec-Fetch-Site":["same-origin"],"Referer":["https://boysandy.orderonline.id/"],"If-Modified-Since":["Wed, 27 May 2020 12:20:28 GMT"],"Cookie":[],"X-Forwarded-Port":["443"],"Accept":["*/*"],"Service-Worker":["script"],"Sec-Fetch-Mode":["same-origin"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36"],"Accept-Language":["en-US,en;q=0.9"]}},"bytes_read":0,"user_id":"","duration":0.001278576,"size":388,"status":200,"resp_headers":{"Content-Encoding":["gzip"],"Etag":["W/\"q48x9dpf\""],"Server":["Caddy","Caddy"],"Vary":["Accept-Encoding"],"Access-Control-Allow-Headers":["Content-Type"],"Accept-Ranges":["bytes"],"Access-Control-Allow-Methods":["GET, POST, PUT, DELETE, OPTIONS"],"Date":["Fri, 12 Apr 2024 07:35:43 GMT"],"Last-Modified":["Fri, 17 Jan 2020 10:03:13 GMT"],"Content-Length":["388"],"Content-Type":["application/javascript"]}}	
April 12, 2024 at 14:35 (UTC+7:00)	{"level":"debug","ts":1712907317.1765401,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:35 (UTC+7:00)	{"level":"debug","ts":1712907317.173378,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:35 (UTC+7:00)	{"level":"debug","ts":1712907317.1606536,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:35 (UTC+7:00)	{"level":"debug","ts":1712907314.9377925,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:35 (UTC+7:00)	{"level":"debug","ts":1712907312.8656828,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:35 (UTC+7:00)	{"level":"debug","ts":1712907307.1720178,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:35 (UTC+7:00)	{"level":"debug","ts":1712907307.162087,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:35 (UTC+7:00)	{"level":"debug","ts":1712907307.1529644,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"debug","ts":1712907297.1614304,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"debug","ts":1712907297.1514833,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"debug","ts":1712907297.1517632,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"debug","ts":1712907294.9392648,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"debug","ts":1712907292.8666508,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"debug","ts":1712907287.159653,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"debug","ts":1712907287.1506119,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"debug","ts":1712907287.1465404,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"x.x.x.x","total_upstreams":3}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.553188,"logger":"tls","msg":"finished cleaning storage units"}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"warn","ts":1712907263.5353405,"logger":"tls","msg":"storage cleaning happened too recently; skipping for now","storage":"{\"client_type\":\"simple\",\"address\":[\"x.x.x.x:6379\"],\"host\":[],\"port\":[],\"db\":0,\"timeout\":\"5\",\"username\":\"\",\"password\":\"REDACTED\",\"master_name\":\"\",\"key_prefix\":\"caddy\",\"encryption_key\":\"\",\"compression\":false,\"tls_enabled\":false,\"tls_insecure\":true,\"tls_server_certs_pem\":\"\",\"tls_server_certs_path\":\"\",\"route_by_latency\":false,\"route_randomly\":false}","instance":"bdf37a6f-fa6e-4ee5-a9e2-0f82b93cff11","try_again":1712993663.5353374,"try_again_in":86399.99999955}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.499121,"msg":"autosaved config (load with --resume flag)","file":"/config/caddy/autosave.json"}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.499262,"msg":"serving initial configuration"}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"debug","ts":1712907263.49839,"logger":"http","msg":"starting server loop","address":"[::]:8000","tls":false,"http3":false}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.4984252,"logger":"http.log","msg":"server running","name":"srv2","protocols":["h1","h2","h3"]}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.4984665,"logger":"http","msg":"enabling HTTP/3 listener","addr":":443"}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.4985497,"msg":"failed to sufficiently increase receive buffer size (was: 208 kiB, wanted: 2048 kiB, got: 416 kiB). See https://github.com/quic-go/quic-go/wiki/UDP-Buffer-Sizes for details."}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"debug","ts":1712907263.4987874,"logger":"http","msg":"starting server loop","address":"[::]:443","tls":true,"http3":true}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.4988012,"logger":"http.log","msg":"server running","name":"srv0","protocols":["h1","h2","h3"]}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"debug","ts":1712907263.4988477,"logger":"http","msg":"starting server loop","address":"[::]:80","tls":false,"http3":false}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.4988592,"logger":"http.log","msg":"server running","name":"srv1","protocols":["h1","h2","h3"]}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.4971232,"logger":"http.auto_https","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}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.4971402,"logger":"http.auto_https","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"warn","ts":1712907263.4971893,"logger":"http.auto_https","msg":"server is listening only on the HTTP port, so no automatic HTTPS will be applied to this server","server_name":"srv1","http_port":80}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"debug","ts":1712907263.4972527,"logger":"http.auto_https","msg":"adjusted config","tls":{"automation":{"policies":[{"on_demand":true}],"on_demand":{"ask":"https://api.orderonline.id/domain-checker"}}},"http":{"servers":{"srv0":{"listen":[":443"],"routes":[{"handle":[{"encodings":{"br":{},"gzip":{},"zstd":{}},"handler":"encode","prefer":["br","zstd","gzip"]}]},{"handle":[{"handler":"subroute","routes":[{"handle":[{"handler":"file_server","hide":["/etc/caddy/Caddyfile"]}]}]}]},{"handle":[{"handler":"reverse_proxy","headers":{"request":{"set":{"Oo-Api-Key":["some-api-key"]}}},"transport":{"protocol":"http","tls":{}},"upstreams":[{"dial":"api.orderonline.id:443"}]}]},{"handle":[{"handler":"reverse_proxy","headers":{"request":{"set":{"X-Real-Ip":["{http.request.header.X-Forwarded-For}"]}},"response":{"set":{"Access-Control-Allow-Origin":["*"]}}},"upstreams":[{"dial":"some-page.ap-southeast-1.elasticbeanstalk.com:80"}]}]},{"handle":[{"handler":"reverse_proxy","headers":{"request":{"set":{"Host":["{http.request.host}"],"X-Real-Ip":["{http.request.header.X-Forwarded-For}"]}}},"health_checks":{"passive":{"fail_duration":30000000000}},"load_balancing":{"selection_policy":{"policy":"least_conn"}},"upstreams":[{"dial":"x.x.x.x"},{"dial":"x.x.x.x"},{"dial":"x.x.x.x"}]}]}],"tls_connection_policies":[{}],"automatic_https":{},"logs":{"default_logger_name":"log1"}},"srv1":{"listen":[":80"],"routes":[{"handle":[{"handler":"subroute","routes":[{"handle":[{"handler":"file_server","hide":["/etc/caddy/Caddyfile"]}]}]}]},{"handle":[{"handler":"reverse_proxy","headers":{"request":{"set":{"Oo-Api-Key":["some-api-key"]}}},"transport":{"protocol":"http","tls":{}},"upstreams":[{"dial":"api.orderonline.id:443"}]}]},{"handle":[{"handler":"reverse_proxy","headers":{"request":{"set":{"X-Real-Ip":["{http.request.header.X-Forwarded-For}"]}},"response":{"set":{"Access-Control-Allow-Origin":["*"]}}},"upstreams":[{"dial":"some-page.ap-southeast-1.elasticbeanstalk.com:80"}]}]},{"handle":[{"handler":"reverse_proxy","headers":{"request":{"set":{"Host":["{http.request.host}"],"X-Real-Ip":["{http.request.header.X-Forwarded-For}"]}}},"health_checks":{"passive":{"fail_duration":30000000000}},"load_balancing":{"selection_policy":{"policy":"least_conn"}},"upstreams":[{"dial":"x.x.x.x"},{"dial":"x.x.x.x"},{"dial":"x.x.x.x"}]}]},{}],"automatic_https":{"disable":true},"logs":{"default_logger_name":"log0"}},"srv2":{"listen":[":8000"],"routes":[{"handle":[{"handler":"static_response","status_code":200}]}],"automatic_https":{}}}}}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.4964054,"logger":"caddy.storage.redis","msg":"Provision Redis simple storage using address [x.x.x.x:6379]"}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.4968865,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc000885700"}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.3966274,"logger":"admin","msg":"admin endpoint started","address":"0.0.0.0:2020","enforce_origin":false,"origins":["//0.0.0.0:2020"]}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"warn","ts":1712907263.3968015,"logger":"admin","msg":"admin endpoint on open interface; host checking disabled","address":"0.0.0.0:2020"}	
April 12, 2024 at 14:34 (UTC+7:00)	{"level":"info","ts":1712907263.316107,"msg":"using provided configuration","config_file":"/etc/caddy/Caddyfile","config_adapter":""}

P.S. I remove some lines (automatic health check from AWS) because the line is too big

renodesper · April 12, 2024, 8:23am

Values in Redis:

caddy
caddy/acme
caddy/acme/acme-v02.api.letsencrypt.org-directory
caddy/acme/acme-v02.api.letsencrypt.org-directory/users
caddy/acme/acme-v02.api.letsencrypt.org-directory/users/company@gmail.com
caddy/acme/acme-v02.api.letsencrypt.org-directory/users/company@gmail.com/company.json
caddy/acme/acme-v02.api.letsencrypt.org-directory/users/company@gmail.com/company.key
caddy/certificates
caddy/certificates/acme-v02.api.letsencrypt.org-directory
caddy/certificates/acme-v02.api.letsencrypt.org-directory/tokobudu.my.id
caddy/certificates/acme-v02.api.letsencrypt.org-directory/tokobudu.my.id/tokobudu.my.id.crt
caddy/certificates/acme-v02.api.letsencrypt.org-directory/tokobudu.my.id/tokobudu.my.id.json
caddy/certificates/acme-v02.api.letsencrypt.org-directory/tokobudu.my.id/tokobudu.my.id.key
caddy/certificates/acme-v02.api.letsencrypt.org-directory/tokobudu.orderonline.id
caddy/certificates/acme-v02.api.letsencrypt.org-directory/tokobudu.orderonline.id/tokobudu.orderonline.id.crt
caddy/certificates/acme-v02.api.letsencrypt.org-directory/tokobudu.orderonline.id/tokobudu.orderonline.id.json
caddy/certificates/acme-v02.api.letsencrypt.org-directory/tokobudu.orderonline.id/tokobudu.orderonline.id.key
caddy/last_clean.json
caddy/ocsp
caddy/ocsp/tokobudu.my.id-184fe028
caddy/ocsp/tokobudu.my.id-1ce44820
caddy/ocsp/tokobudu.orderonline.id-18cd8182
caddy/ocsp/tokobudu.orderonline.id-43a4e8ba
caddy/ocsp/tokobudu.orderonline.id-9aa87b79

francislavoie · April 13, 2024, 8:42pm

That’s just the startup logs. That’s not useful here.

What we’re looking to see is the debug logs from a single request which is exhibiting the behaviour you’re seeing. It’ll show the TLS cert selection logging.

matt · April 14, 2024, 1:45pm

I’m confused; this looks like Caddy served a wildcard cert (*.orderonline.id)

So, to clarify, are you saying that with your config above, a request comes in for tokobudu.my.id but then Caddy is serving a certificate for *.orderonline.id instead?