caddy
caddy copied to clipboard
caddyserver
caddy removes expired cert resource and breaks auto renewal
I used Caddy a few weeks back, and at the time the certs works properly. And on the most recent usage, I see the below logs and error.
What the recommended steps to restore this setup in working order?
2022/05/09 12:10:04.504 INFO admin admin endpoint started {"address": "tcp/localhost:3019", "enforce_origin": false, "origins": ["//localhost:3019", "//[::1]:3019", "//127.0.0.1:3019"]}
2022/05/09 12:10:04.505 INFO tls.cache.maintenance started background certificate maintenance {"cache": "0xc000024cb0"}
2022/05/09 12:10:04.506 INFO http 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}
2022/05/09 12:10:04.506 INFO http enabling automatic HTTP->HTTPS redirects {"server_name": "srv0"}
2022/05/09 12:10:04.562 INFO pki.ca.local root certificate is already trusted by system {"path": "storage:pki/authorities/local/root.crt"}
2022/05/09 12:10:04.562 INFO pki intermediate expires soon; renewing {"ca": "local", "time_remaining": -888682.5628871}
2022/05/09 12:10:04.568 INFO pki renewed intermediate {"ca": "local", "new_expiration": "2022/05/16 12:10:04.000"}
2022/05/09 12:10:04.570 INFO http enabling automatic TLS certificate management {"domains": ["localhost"]}
2022/05/09 12:10:04.595 WARN tls stapling OCSP {"error": "no OCSP stapling for [localhost]: no OCSP server specified in certificate", "identifiers": ["localhost"]}
2022/05/09 12:10:04.596 INFO tls cleaning storage unit {"description": "FileStorage:C:\\Users\\XXXXXX\\AppData\\Roaming\\Caddy"}
2022/05/09 12:10:04.597 INFO autosaved config (load with --resume flag) {"file": "C:\\Users\\XXXXXX\\AppData\\Roaming\\Caddy\\autosave.json"}
2022/05/09 12:10:04.598 INFO admin.api load complete
2022/05/09 08:10:04 [INFO] Certificate certificates/local/localhost/localhost.crt expired 370h41m40.6010362s ago; cleaning up
2022/05/09 08:10:04 [INFO] Deleting certificates/local/localhost/localhost.crt because resource expired
2022/05/09 08:10:04 [INFO] Deleting certificates/local/localhost/localhost.key because resource expired
2022/05/09 08:10:04 [INFO] Deleting certificates/local/localhost/localhost.json because resource expired
2022/05/09 08:10:04 [INFO] Deleting certificates/local/localhost because key is empty
Here the localhost key resources are being removed.
2022/05/09 12:10:04.603 INFO tls finished cleaning storage units
2022/05/09 12:10:04.605 INFO admin stopped previous server {"address": "tcp/localhost:2019"}
2022/05/09 12:10:04.608 INFO tls.renew acquiring lock {"identifier": "localhost"}
2022/05/09 12:10:04.609 INFO tls.renew lock acquired {"identifier": "localhost"}
2022/05/09 12:10:04.609 ERROR tls.renew will retry {"error": "open C:\\Users\\XXXXXX\\AppData\\Roaming\\Caddy\\certificates\\local\\localhost\\localhost.key: The system cannot find the path specified.", "attempt": 1, "retrying_in": 60, "elapsed": 0, "max_duration": 2592000}
2022/05/09 12:11:04.622 ERROR tls.renew will retry {"error": "open C:\\Users\\XXXXXX\\AppData\\Roaming\\Caddy\\certificates\\local\\localhost\\localhost.key: The system cannot find the path specified.", "attempt": 2, "retrying_in": 120, "elapsed": 60.0119546, "max_duration": 2592000}
Here is the error when it's used in renewal.
Hi! Thanks for trying Caddy!
Please ask your usage questions on the Caddy community forums. We prefer to keep the GitHub issue board for bugs and feature requests. Don't forget to fill out the thread template so we can help you!
It's unclear what's going on, so we need you to open a topic and fill out the help template so we can better understand.
Copying my response in the forum to here, since it is likely a bug, but a very extremely rare one (I suspect):
I think it was just a rare race condition, never seen it before. Basically storage cleanup happened at approximately the same time as trying to renew the resource that was getting cleaned up. Usually, very very expired resources are no longer used, so it's safe to just clean them up. It's very unlikely that an extremely-expired resource is being renewed at the exact same time as it's being cleaned up, so I don't think I bothered to implement locking there.
Re-running Caddy should definitely work around the problem. Not ideal, I know, but it's a very simple workaround for a problem that is extremely rare. It might be a simple fix, but unless there's another report, I'm inclined to think it's an edge case that won't impact many people, so it's not a high priority.
Will mark this as deferred, since I am not sure how urgent it is and I have not assessed whether the fix is complex or easy. If it is simple, I definitely welcome a pull request.
@mholt hello, I'm encountering this. The workflow I've seen is:
- set up Caddy to run to test something locally with HTTPS
- test something locally with HTTPS
- stop Caddy
- wait long enough for the leaf cert to expire (12h)
- wait long enough for the expired cert grace period to elapse (14 days)
- start Caddy again to test a new thing with HTTPS
- see in the logs that the site folder is deleted as Caddy starts, about the same time as TLS renewal is attempted
logs snippet
{"level":"info","ts":1743089980.7655025,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["mycooldomain.com","*.mycooldomain.com"]}
{"level":"info","ts":1743089980.766621,"logger":"tls","msg":"cleaning storage unit","storage":"FileStorage:/data/caddy"}
{"level":"info","ts":1743089980.766727,"logger":"tls","msg":"certificate expired beyond grace period; cleaning up","storage":"FileStorage:/data/caddy","asset_key":"certificates/local/mycooldomain.com/mycooldomain.com.crt","expired_for":1954523.766726645,"grace_period":1209600}
{"level":"info","ts":1743089980.7667356,"logger":"tls","msg":"deleting asset because resource expired","storage":"FileStorage:/data/caddy","asset_key":"certificates/local/mycooldomain.com/mycooldomain.com.crt"}
{"level":"info","ts":1743089980.7667544,"logger":"tls","msg":"deleting asset because resource expired","storage":"FileStorage:/data/caddy","asset_key":"certificates/local/mycooldomain.com/mycooldomain.com.key"}
{"level":"info","ts":1743089980.7667632,"logger":"tls","msg":"deleting asset because resource expired","storage":"FileStorage:/data/caddy","asset_key":"certificates/local/mycooldomain.com/mycooldomain.com.json"}
{"level":"info","ts":1743089980.7667859,"logger":"tls","msg":"deleting site folder because key is empty","storage":"FileStorage:/data/caddy","site_key":"certificates/local/mycooldomain.com"}
{"level":"info","ts":1743089980.7668896,"logger":"tls","msg":"certificate is in configured renewal window based on expiration date","subjects":["mycooldomain.com"],"expiration":1741135457,"ari_cert_id":"","next_ari_update":null,"renew_check_interval":600,"window_start":-6795364578.8713455,"window_end":-6795364578.8713455,"remaining":-1954523.766888812}
{"level":"info","ts":1743089980.7670577,"logger":"tls","msg":"certificate expired beyond grace period; cleaning up","storage":"FileStorage:/data/caddy","asset_key":"certificates/local/wildcard_.mycooldomain.com/wildcard_.mycooldomain.com.crt","expired_for":1954523.767057145,"grace_period":1209600}
{"level":"info","ts":1743089980.767067,"logger":"tls","msg":"deleting asset because resource expired","storage":"FileStorage:/data/caddy","asset_key":"certificates/local/wildcard_.mycooldomain.com/wildcard_.mycooldomain.com.crt"}
{"level":"info","ts":1743089980.7670858,"logger":"tls","msg":"deleting asset because resource expired","storage":"FileStorage:/data/caddy","asset_key":"certificates/local/wildcard_.mycooldomain.com/wildcard_.mycooldomain.com.key"}
{"level":"info","ts":1743089980.7670949,"logger":"tls","msg":"deleting asset because resource expired","storage":"FileStorage:/data/caddy","asset_key":"certificates/local/wildcard_.mycooldomain.com/wildcard_.mycooldomain.com.json"}
{"level":"info","ts":1743089980.7671132,"logger":"tls","msg":"deleting site folder because key is empty","storage":"FileStorage:/data/caddy","site_key":"certificates/local/wildcard_.mycooldomain.com"}
{"level":"info","ts":1743089980.7673316,"logger":"tls","msg":"certificate is in configured renewal window based on expiration date","subjects":["*.mycooldomain.com"],"expiration":1741135457,"ari_cert_id":"","next_ari_update":null,"renew_check_interval":600,"window_start":-6795364578.8713455,"window_end":-6795364578.8713455,"remaining":-1954523.767331353}
{"level":"info","ts":1743089980.767586,"msg":"autosaved config (load with --resume flag)","file":"/config/caddy/autosave.json"}
{"level":"info","ts":1743089980.7675989,"msg":"serving initial configuration"}
{"level":"info","ts":1743089980.7680223,"logger":"tls","msg":"finished cleaning storage units"}
{"level":"info","ts":1743089980.7680538,"logger":"tls.renew","msg":"acquiring lock","identifier":"mycooldomain.com"}
{"level":"info","ts":1743089980.7682269,"logger":"tls.renew","msg":"acquiring lock","identifier":"*.mycooldomain.com"}
{"level":"info","ts":1743089980.7687461,"logger":"tls.renew","msg":"lock acquired","identifier":"mycooldomain.com"}
{"level":"error","ts":1743089980.768773,"logger":"tls.renew","msg":"will retry","error":"open /data/caddy/certificates/local/mycooldomain.com/mycooldomain.com.key: no such file or directory","attempt":1,"retrying_in":60,"elapsed":0.000018917,"max_duration":2592000}
{"level":"info","ts":1743089980.7690713,"logger":"tls.renew","msg":"lock acquired","identifier":"*.mycooldomain.com"}
[... above error 'no such file or directory' repeated 4 times per domain]
{"level":"info","ts":1743090580.740017,"logger":"tls","msg":"certificate is in configured renewal window based on expiration date","subjects":["mycooldomain.com"],"expiration":1741135457,"ari_cert_id":"","next_ari_update":null,"renew_check_interval":600,"window_start":-6795364578.8713455,"window_end":-6795364578.8713455,"remaining":-1955123.740011181}
{"level":"warn","ts":1743090580.7404199,"logger":"tls.cache.maintenance","msg":"error while checking if stored certificate is also expiring soon","identifiers":["mycooldomain.com"],"error":"open /data/caddy/certificates/local/mycooldomain.com/mycooldomain.com.key: no such file or directory"}
If I stop and restart Caddy, it works fine. But it's difficult to automate a fix or explain to other devs how to recognise & resolve it.
@francislavoie @mholt Could this issue please be reopened?
I ran into the same bug today when restarting an old service. I'm using the latest version of Caddy if that's relevant.
caddy-1 | 2025-09-19T08:38:11.976949938Z {"level":"info","ts":1758271091.9760208,"msg":"maxprocs: Leaving GOMAXPROCS=1: CPU quota undefined"}
caddy-1 | 2025-09-19T08:38:11.976984338Z {"level":"info","ts":1758271091.9767137,"msg":"GOMEMLIMIT is updated","package":"github.com/KimMachineGun/automemlimit/memlimit","GOMEMLIMIT":1797717196,"previous":9223372036854775807}
caddy-1 | 2025-09-19T08:38:11.980691667Z {"level":"info","ts":1758271091.9787066,"msg":"using config from file","file":"/etc/caddy/Caddyfile"}
caddy-1 | 2025-09-19T08:38:11.983335887Z {"level":"info","ts":1758271091.9832559,"msg":"adapted config to JSON","adapter":"caddyfile"}
caddy-1 | 2025-09-19T08:38:11.983748990Z {"level":"warn","ts":1758271091.9836807,"msg":"Caddyfile input is not formatted; run 'caddy fmt --overwrite' to fix inconsistencies","adapter":"caddyfile","file":"/etc/caddy/Caddyfile","line":2}
caddy-1 | 2025-09-19T08:38:11.991711651Z {"level":"info","ts":1758271091.9889207,"logger":"admin","msg":"admin endpoint started","address":"localhost:2019","enforce_origin":false,"origins":["//localhost:2019","//[::1]:2019","//127.0.0.1:2019"]}
caddy-1 | 2025-09-19T08:38:11.991729751Z {"level":"info","ts":1758271091.989072,"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}
caddy-1 | 2025-09-19T08:38:11.991734351Z {"level":"info","ts":1758271091.9890885,"logger":"http.auto_https","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
caddy-1 | 2025-09-19T08:38:11.991738051Z {"level":"info","ts":1758271091.9893074,"logger":"http","msg":"enabling HTTP/3 listener","addr":":443"}
caddy-1 | 2025-09-19T08:38:11.991741651Z {"level":"info","ts":1758271091.9894505,"msg":"failed to sufficiently increase receive buffer size (was: 1024 kiB, wanted: 7168 kiB, got: 2048 kiB). See https://github.com/quic-go/quic-go/wiki/UDP-Buffer-Sizes for details."}
caddy-1 | 2025-09-19T08:38:11.991745151Z {"level":"info","ts":1758271091.9895394,"logger":"http.log","msg":"server running","name":"srv0","protocols":["h1","h2","h3"]}
caddy-1 | 2025-09-19T08:38:11.991748451Z {"level":"warn","ts":1758271091.9895937,"logger":"http","msg":"HTTP/2 skipped because it requires TLS","network":"tcp","addr":":80"}
caddy-1 | 2025-09-19T08:38:11.991751451Z {"level":"warn","ts":1758271091.989599,"logger":"http","msg":"HTTP/3 skipped because it requires TLS","network":"tcp","addr":":80"}
caddy-1 | 2025-09-19T08:38:11.991754451Z {"level":"info","ts":1758271091.9896016,"logger":"http.log","msg":"server running","name":"remaining_auto_https_redirects","protocols":["h1","h2","h3"]}
caddy-1 | 2025-09-19T08:38:11.991757751Z {"level":"info","ts":1758271091.989606,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["demo.demo.dev"]}
caddy-1 | 2025-09-19T08:38:11.999142208Z {"level":"info","ts":1758271091.9975986,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc0005b8f80"}
caddy-1 | 2025-09-19T08:38:12.006025261Z {"level":"info","ts":1758271092.0058389,"msg":"autosaved config (load with --resume flag)","file":"/config/caddy/autosave.json"}
caddy-1 | 2025-09-19T08:38:12.006043061Z {"level":"info","ts":1758271092.005856,"msg":"serving initial configuration"}
caddy-1 | 2025-09-19T08:38:12.020956975Z {"level":"info","ts":1758271092.020868,"logger":"tls","msg":"cleaning storage unit","storage":"FileStorage:/data/caddy"}
caddy-1 | 2025-09-19T08:38:12.024833405Z {"level":"info","ts":1758271092.0246305,"logger":"tls","msg":"certificate expired beyond grace period; cleaning up","storage":"FileStorage:/data/caddy","asset_key":"certificates/acme-v02.api.letsencrypt.org-directory/demo.demo.dev/demo.demo.dev.crt","expired_for":2458133.024629204,"grace_period":1209600}
caddy-1 | 2025-09-19T08:38:12.024957606Z {"level":"info","ts":1758271092.024673,"logger":"tls","msg":"deleting asset because resource expired","storage":"FileStorage:/data/caddy","asset_key":"certificates/acme-v02.api.letsencrypt.org-directory/demo.demo.dev/demo.demo.dev.crt"}
caddy-1 | 2025-09-19T08:38:12.030224747Z {"level":"info","ts":1758271092.0298023,"logger":"tls","msg":"deleting asset because resource expired","storage":"FileStorage:/data/caddy","asset_key":"certificates/acme-v02.api.letsencrypt.org-directory/demo.demo.dev/demo.demo.dev.key"}
caddy-1 | 2025-09-19T08:38:12.030256247Z {"level":"info","ts":1758271092.029991,"logger":"tls","msg":"deleting asset because resource expired","storage":"FileStorage:/data/caddy","asset_key":"certificates/acme-v02.api.letsencrypt.org-directory/demo.demo.dev/demo.demo.dev.json"}
caddy-1 | 2025-09-19T08:38:12.030598249Z {"level":"info","ts":1758271092.0301619,"logger":"tls","msg":"deleting site folder because key is empty","storage":"FileStorage:/data/caddy","site_key":"certificates/acme-v02.api.letsencrypt.org-directory/demo.demo.dev"}
caddy-1 | 2025-09-19T08:38:12.048031583Z {"level":"info","ts":1758271092.047859,"logger":"tls","msg":"finished cleaning storage units"}
caddy-1 | 2025-09-19T08:38:12.752091483Z {"level":"info","ts":1758271092.7518742,"msg":"got renewal info","names":["demo.demo.dev"],"window_start":1753144403,"window_end":1753299852,"selected_time":1753233568,"recheck_after":1758292692.75186,"explanation_url":""}
caddy-1 | 2025-09-19T08:38:12.754172199Z {"level":"error","ts":1758271092.7537937,"logger":"tls","msg":"updating ARI upon managing","error":"got new ARI from acme-v02.api.letsencrypt.org-directory, but failed loading stored certificate metadata: loading cert metadata: open /data/caddy/certificates/acme-v02.api.letsencrypt.org-directory/demo.demo.dev/demo.demo.dev.json: no such file or directory"}
caddy-1 | 2025-09-19T08:38:12.754186499Z {"level":"info","ts":1758271092.7538192,"logger":"tls","msg":"certificate needs renewal based on ARI window","subjects":["demo.demo.dev"],"expiration":1755812959,"ari_cert_id":"nytfzzwhT50Et-0rLMTGcIvS1w0.BiAWzdHG8_iVHP_VFl7VBGe_","next_ari_update":1758292692.75186,"renew_check_interval":600,"window_start":1753144403,"window_end":1753299852,"selected_time":1753237240,"renewal_cutoff":1753236640}
caddy-1 | 2025-09-19T08:38:12.840713563Z {"level":"info","ts":1758271092.840537,"logger":"tls.renew","msg":"acquiring lock","identifier":"demo.demo.dev"}
caddy-1 | 2025-09-19T08:38:12.889036634Z {"level":"info","ts":1758271092.8886168,"logger":"tls.renew","msg":"lock acquired","identifier":"demo.demo.dev"}
caddy-1 | 2025-09-19T08:38:12.889078734Z {"level":"error","ts":1758271092.8887498,"logger":"tls.renew","msg":"will retry","error":"open /data/caddy/certificates/acme-v02.api.letsencrypt.org-directory/demo.demo.dev/demo.demo.dev.key: no such file or directory","attempt":1,"retrying_in":60,"elapsed":0.0000857,"max_duration":2592000}caddy-1 | 2025-09-19T08:39:12.889233244Z {"level":"error","ts":1758271152.889021,"logger":"tls.renew","msg":"will retry","error":"open /data/caddy/certificates/acme-v02.api.letsencrypt.org-directory/demo.demo.dev/demo.demo.dev.key: no such file or directory","attempt":2,"retrying_in":120,"elapsed":60.000354911,"max_duration":2592000}
caddy-1 | 2025-09-19T08:41:12.889554710Z {"level":"error","ts":1758271272.8893492,"logger":"tls.renew","msg":"will retry","error":"open /data/caddy/certificates/acme-v02.api.letsencrypt.org-directory/demo.demo.dev/demo.demo.dev.key: no such file or directory","attempt":3,"retrying_in":120,"elapsed":180.000683178,"max_duration":2592000}
caddy-1 | 2025-09-19T08:43:12.889829457Z {"level":"error","ts":1758271392.8896391,"logger":"tls.renew","msg":"will retry","error":"open /data/caddy/certificates/acme-v02.api.letsencrypt.org-directory/demo.demo.dev/demo.demo.dev.key: no such file or directory","attempt":4,"retrying_in":300,"elapsed":300.000971825,"max_duration":2592000}
caddy-1 | 2025-09-19T08:48:11.998215309Z {"level":"info","ts":1758271691.9979057,"logger":"tls","msg":"certificate needs renewal based on ARI window","subjects":["demo.demo.dev"],"expiration":1755812959,"ari_cert_id":"nytfzzwhT50Et-0rLMTGcIvS1w0.BiAWzdHG8_iVHP_VFl7VBGe_","next_ari_update":1758292692.75186,"renew_check_interval":600,"window_start":1753144403,"window_end":1753299852,"selected_time":1753237240,"renewal_cutoff":1753236640}
caddy-1 | 2025-09-19T08:48:11.998263409Z {"level":"warn","ts":1758271691.9980133,"logger":"tls.cache.maintenance","msg":"error while checking if stored certificate is also expiring soon","identifiers":["demo.demo.dev"],"error":"open /data/caddy/certificates/acme-v02.api.letsencrypt.org-directory/demo.demo.dev/demo.demo.dev.key: no such file or directory"}
caddy-1 | 2025-09-19T08:48:11.998270609Z {"level":"info","ts":1758271691.998028,"logger":"tls.cache.maintenance","msg":"certificate expires soon; queuing for renewal","identifiers":["demo.demo.dev"],"remaining":-2458732.998027307}
caddy-1 | 2025-09-19T08:48:12.890173046Z {"level":"error","ts":1758271692.889983,"logger":"tls.renew","msg":"will retry","error":"open /data/caddy/certificates/acme-v02.api.letsencrypt.org-directory/demo.demo.dev/demo.demo.dev.key: no such file or directory","attempt":5,"retrying_in":600,"elapsed":600.001314514,"max_duration":2592000}
