1. The problem I’m having:
We register our servers to Caddy via the API (not using Caddyfile). For the most part this works well, but when fetching the certificates for new servers we’re getting the logs as shown below. The main concerns being:
Aug 29 04:52:50 ns5012842 caddy[3361552]: {"level":"error","ts":1724907170.810878,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"redacted.example.com","issuer":"acme-v02.api.letsencrypt.org-directory","error":"HTTP 400 urn:ietf:params:acme:error:malformed - JWS verification error"}
Aug 29 04:52:50 ns5012842 caddy[3361552]: {"level":"error","ts":1724907170.8110101,"logger":"tls","msg":"job failed","error":"redacted.example.com: obtaining certificate: [redacted.example.com] Obtain: [redacted.example.com] creating new order: attempt 1: https://acme-v02.api.letsencrypt.org/acme/new-order: HTTP 400 urn:ietf:params:acme:error:malformed - JWS verification error (ca=https://acme-v02.api.letsencrypt.org/directory)"}
We run caddy with the --resume
flag (see below) and have up to 30 servers running on the same machine, all registering themselves automatically. In this case the issue happened after updating caddy
to latest.
We first tried
sudo apt remove caddy
sudo apt install caddy
and rebooted our web servers/systems so that they would re-register with caddy from scratch however they still had the same JWS error above.
So, we then did the same thing again but manually removed the existing /var/lib/caddy
folder:
sudo apt remove caddy
- didn’t automatically remove/var/lib/caddy
- so we removed it manually afterwards.sudo apt install caddy
- this then didn’t seem to recreate/var/lib/caddy
sudo mkdir /var/lib/caddy
- recreate the HomeDir manuallysudo chown caddy:caddy /var/lib/caddy
- make surecaddy
user has ownership of the HomeDirsudo systemctl restart caddy
- then we restarted our services to re-register to caddy, and it all worked perfectly
and things worked again, and we can restart caddy and the servers with no issues.
We want to understand what is going on here to give us confidence that when we add new servers or update caddy in the future that we won’t see these errors! We left caddy running for at least an hour and were still getting the errors shown above.
I have seen this in the past with our set up. After a period of time (maybe a few hours) it has figured it out but I can’t say that was going to happen here.
If you need any more context or have any further issues please let me know! We do have the original HomeDir folder which we assume got corrupted in some way.
2. Error messages and/or full log output:
Aug 29 04:51:11 ns5012842 caddy[3361499]: caddy.HomeDir=/var/lib/caddy
Aug 29 04:51:11 ns5012842 caddy[3361499]: caddy.AppDataDir=/var/lib/caddy/.local/share/caddy
Aug 29 04:51:11 ns5012842 caddy[3361499]: caddy.AppConfigDir=/var/lib/caddy/.config/caddy
Aug 29 04:51:11 ns5012842 caddy[3361499]: caddy.ConfigAutosavePath=/var/lib/caddy/.config/caddy/autosave.json
Aug 29 04:51:11 ns5012842 caddy[3361499]: caddy.Version=v2.8.4 h1:q3pe0wpBj1OcHFZ3n/1nl4V4bxBrYoSoab7rL9BMYNk=
Aug 29 04:51:11 ns5012842 caddy[3361499]: runtime.GOOS=linux
Aug 29 04:51:11 ns5012842 caddy[3361499]: runtime.GOARCH=amd64
Aug 29 04:51:11 ns5012842 caddy[3361499]: runtime.Compiler=gc
Aug 29 04:51:11 ns5012842 caddy[3361499]: runtime.NumCPU=16
Aug 29 04:51:11 ns5012842 caddy[3361499]: runtime.GOMAXPROCS=16
Aug 29 04:51:11 ns5012842 caddy[3361499]: runtime.Version=go1.22.3
Aug 29 04:51:11 ns5012842 caddy[3361499]: os.Getwd=/
Aug 29 04:51:11 ns5012842 caddy[3361499]: LANG=C.UTF-8
Aug 29 04:51:11 ns5012842 caddy[3361499]: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin
Aug 29 04:51:11 ns5012842 caddy[3361499]: NOTIFY_SOCKET=/run/systemd/notify
Aug 29 04:51:11 ns5012842 caddy[3361499]: HOME=/var/lib/caddy
Aug 29 04:51:11 ns5012842 caddy[3361499]: LOGNAME=caddy
Aug 29 04:51:11 ns5012842 caddy[3361499]: USER=caddy
Aug 29 04:51:11 ns5012842 caddy[3361499]: INVOCATION_ID=4bbb42c27a804c33a5939db563fa5a51
Aug 29 04:51:11 ns5012842 caddy[3361499]: JOURNAL_STREAM=8:394665449
Aug 29 04:51:11 ns5012842 caddy[3361499]: SYSTEMD_EXEC_PID=3361499
Aug 29 04:51:11 ns5012842 caddy[3361499]: {"level":"info","ts":1724907071.1120114,"msg":"using config from file","file":"/etc/caddy/Caddyfile"}
Aug 29 04:51:11 ns5012842 caddy[3361499]: {"level":"info","ts":1724907071.1121652,"msg":"adapted config to JSON","adapter":"caddyfile"}
Aug 29 04:51:11 ns5012842 caddy[3361499]: {"level":"info","ts":1724907071.1124501,"logger":"admin","msg":"admin endpoint started","address":"localhost:2019","enforce_origin":false,"origins":["//127.0.0.1:2019","//localhost:2019","//[::1]:2019"]}
Aug 29 04:51:11 ns5012842 caddy[3361499]: {"level":"info","ts":1724907071.1125567,"msg":"autosaved config (load with --resume flag)","file":"/var/lib/caddy/.config/caddy/autosave.json"}
Aug 29 04:51:11 ns5012842 caddy[3361499]: {"level":"info","ts":1724907071.1125836,"msg":"serving initial configuration"}
Aug 29 04:51:11 ns5012842 systemd[1]: Started Caddy.
Aug 29 04:51:11 ns5012842 caddy[3361499]: {"level":"info","ts":1724907071.3249125,"msg":"shutting down apps, then terminating","signal":"SIGTERM"}
Aug 29 04:51:11 ns5012842 caddy[3361499]: {"level":"warn","ts":1724907071.3250031,"msg":"exiting; byeee!! 👋","signal":"SIGTERM"}
Aug 29 04:51:11 ns5012842 caddy[3361499]: {"level":"info","ts":1724907071.3250895,"logger":"admin","msg":"stopped previous server","address":"localhost:2019"}
Aug 29 04:51:11 ns5012842 caddy[3361499]: {"level":"info","ts":1724907071.325096,"msg":"shutdown complete","signal":"SIGTERM","exit_code":0}
Aug 29 04:51:11 ns5012842 systemd[1]: Stopping Caddy...
Aug 29 04:51:11 ns5012842 systemd[1]: caddy.service: Deactivated successfully.
Aug 29 04:51:11 ns5012842 systemd[1]: Stopped Caddy.
Aug 29 04:51:11 ns5012842 systemd[1]: Starting Caddy...
Aug 29 04:51:11 ns5012842 caddy[3361552]: caddy.HomeDir=/var/lib/caddy
Aug 29 04:51:11 ns5012842 caddy[3361552]: caddy.AppDataDir=/var/lib/caddy/.local/share/caddy
Aug 29 04:51:11 ns5012842 caddy[3361552]: caddy.AppConfigDir=/var/lib/caddy/.config/caddy
Aug 29 04:51:11 ns5012842 caddy[3361552]: caddy.ConfigAutosavePath=/var/lib/caddy/.config/caddy/autosave.json
Aug 29 04:51:11 ns5012842 caddy[3361552]: caddy.Version=v2.8.4 h1:q3pe0wpBj1OcHFZ3n/1nl4V4bxBrYoSoab7rL9BMYNk=
Aug 29 04:51:11 ns5012842 caddy[3361552]: runtime.GOOS=linux
Aug 29 04:51:11 ns5012842 caddy[3361552]: runtime.GOARCH=amd64
Aug 29 04:51:11 ns5012842 caddy[3361552]: runtime.Compiler=gc
Aug 29 04:51:11 ns5012842 caddy[3361552]: runtime.NumCPU=16
Aug 29 04:51:11 ns5012842 caddy[3361552]: runtime.GOMAXPROCS=16
Aug 29 04:51:11 ns5012842 caddy[3361552]: runtime.Version=go1.22.3
Aug 29 04:51:11 ns5012842 caddy[3361552]: os.Getwd=/
Aug 29 04:51:11 ns5012842 caddy[3361552]: LANG=C.UTF-8
Aug 29 04:51:11 ns5012842 caddy[3361552]: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin
Aug 29 04:51:11 ns5012842 caddy[3361552]: NOTIFY_SOCKET=/run/systemd/notify
Aug 29 04:51:11 ns5012842 caddy[3361552]: HOME=/var/lib/caddy
Aug 29 04:51:11 ns5012842 caddy[3361552]: LOGNAME=caddy
Aug 29 04:51:11 ns5012842 caddy[3361552]: USER=caddy
Aug 29 04:51:11 ns5012842 caddy[3361552]: INVOCATION_ID=40cc40c7412e42cb88daa2c76ce3b8a5
Aug 29 04:51:11 ns5012842 caddy[3361552]: JOURNAL_STREAM=8:394667604
Aug 29 04:51:11 ns5012842 caddy[3361552]: SYSTEMD_EXEC_PID=3361552
Aug 29 04:51:11 ns5012842 caddy[3361552]: {"level":"info","ts":1724907071.3524294,"msg":"using config from file","file":"/etc/caddy/Caddyfile"}
Aug 29 04:51:11 ns5012842 caddy[3361552]: {"level":"info","ts":1724907071.3530636,"msg":"adapted config to JSON","adapter":"caddyfile"}
Aug 29 04:51:11 ns5012842 caddy[3361552]: {"level":"info","ts":1724907071.353524,"logger":"admin","msg":"admin endpoint started","address":"localhost:2019","enforce_origin":false,"origins":["//localhost:2019","//[::1]:2019","//127.0.0.1:2019"]}
Aug 29 04:51:11 ns5012842 caddy[3361552]: {"level":"info","ts":1724907071.3536794,"msg":"autosaved config (load with --resume flag)","file":"/var/lib/caddy/.config/caddy/autosave.json"}
Aug 29 04:51:11 ns5012842 caddy[3361552]: {"level":"info","ts":1724907071.3537183,"msg":"serving initial configuration"}
Aug 29 04:51:11 ns5012842 systemd[1]: Started Caddy.
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3095067,"logger":"admin.api","msg":"received request","method":"GET","host":"localhost:2019","uri":"/config/","remote_ip":"127.0.0.1","remote_port":"42538","headers":{"Accept-Encoding":["gzip"],"User-Agent":["Go-http-client/1.1"]}}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3098624,"logger":"admin.api","msg":"received request","method":"POST","host":"localhost:2019","uri":"/config/","remote_ip":"127.0.0.1","remote_port":"42538","headers":{"Accept-Encoding":["gzip"],"Content-Length":["265"],"Content-Type":["application/json"],"User-Agent":["Go-http-client/1.1"]}}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3103292,"logger":"admin","msg":"admin endpoint started","address":"localhost:2019","enforce_origin":false,"origins":["//localhost:2019","//[::1]:2019","//127.0.0.1:2019"]}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3107433,"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":"helical_https","https_port":443}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.310758,"logger":"http.auto_https","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"helical_https"}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.310813,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc000643080"}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.311267,"logger":"http","msg":"enabling HTTP/3 listener","addr":":443"}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3114116,"logger":"http.log","msg":"server running","name":"helical_https","protocols":["h1","h2","h3"]}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3114514,"logger":"http.log","msg":"server running","name":"remaining_auto_https_redirects","protocols":["h1","h2","h3"]}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.311457,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["redacted.example.com"]}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3116813,"msg":"autosaved config (load with --resume flag)","file":"/var/lib/caddy/.config/caddy/autosave.json"}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3117087,"logger":"tls","msg":"storage cleaning happened too recently; skipping for now","storage":"FileStorage:/var/lib/caddy/.local/share/caddy","instance":"741a10e5-eb1d-4442-ba2a-08775355b1a6","try_again":1724993504.3117075,"try_again_in":86399.99999973}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.311746,"logger":"tls","msg":"finished cleaning storage units"}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3120904,"logger":"tls.obtain","msg":"acquiring lock","identifier":"redacted.example.com"}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3123178,"logger":"tls.obtain","msg":"lock acquired","identifier":"redacted.example.com"}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.312377,"logger":"tls.obtain","msg":"obtaining certificate","identifier":"redacted.example.com"}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3130088,"logger":"http","msg":"waiting on internal rate limiter","identifiers":["redacted.example.com"],"ca":"https://acme-v02.api.letsencrypt.org/directory","account":"caddy@zerossl.com"}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3130221,"logger":"http","msg":"done waiting on internal rate limiter","identifiers":["redacted.example.com"],"ca":"https://acme-v02.api.letsencrypt.org/directory","account":"caddy@zerossl.com"}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3130383,"logger":"http","msg":"using ACME account","account_id":"https://acme-v02.api.letsencrypt.org/acme/acct/1087063237","account_contact":["mailto:caddy@zerossl.com"]}
Aug 29 04:51:44 ns5012842 caddy[3361552]: {"level":"info","ts":1724907104.3142889,"logger":"admin","msg":"stopped previous server","address":"localhost:2019"}
Aug 29 04:51:45 ns5012842 caddy[3361552]: {"level":"error","ts":1724907105.2395036,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"redacted.example.com","issuer":"acme-v02.api.letsencrypt.org-directory","error":"HTTP 400 urn:ietf:params:acme:error:malformed - JWS verification error"}
Aug 29 04:51:45 ns5012842 caddy[3361552]: {"level":"error","ts":1724907105.2395725,"logger":"tls.obtain","msg":"will retry","error":"[redacted.example.com] Obtain: [redacted.example.com] creating new order: attempt 1: https://acme-v02.api.letsencrypt.org/acme/new-order: HTTP 400 urn:ietf:params:acme:error:malformed - JWS verification error (ca=https://acme-v02.api.letsencrypt.org/directory)","attempt":1,"retrying_in":60,"elapsed":0.927246757,"max_duration":2592000}
Aug 29 04:52:45 ns5012842 caddy[3361552]: {"level":"info","ts":1724907165.2397695,"logger":"tls.obtain","msg":"obtaining certificate","identifier":"redacted.example.com"}
Aug 29 04:52:45 ns5012842 caddy[3361552]: {"level":"info","ts":1724907165.2401927,"logger":"http","msg":"using ACME account","account_id":"https://acme-staging-v02.api.letsencrypt.org/acme/acct/100225144","account_contact":["mailto:caddy@zerossl.com"]}
Aug 29 04:52:46 ns5012842 caddy[3361552]: {"level":"info","ts":1724907166.3699415,"logger":"http.acme_client","msg":"authorization finalized","identifier":"redacted.example.com","authz_status":"valid"}
Aug 29 04:52:46 ns5012842 caddy[3361552]: {"level":"info","ts":1724907166.3699725,"logger":"http.acme_client","msg":"validations succeeded; finalizing order","order":"https://acme-staging-v02.api.letsencrypt.org/acme/order/100225144/18718182193"}
Aug 29 04:52:50 ns5012842 caddy[3361552]: {"level":"info","ts":1724907170.1061745,"logger":"http.acme_client","msg":"got renewal info","names":["redacted.example.com"],"window_start":1730002425.3333333,"window_end":1730175225.3333333,"selected_time":1730107955,"recheck_after":1724928770.1061714,"explanation_url":""}
Aug 29 04:52:50 ns5012842 caddy[3361552]: {"level":"info","ts":1724907170.4655457,"logger":"http.acme_client","msg":"got renewal info","names":["redacted.example.com"],"window_start":1730002425.3333333,"window_end":1730175225.3333333,"selected_time":1730122542,"recheck_after":1724928770.4655428,"explanation_url":""}
Aug 29 04:52:50 ns5012842 caddy[3361552]: {"level":"info","ts":1724907170.4655805,"logger":"http.acme_client","msg":"successfully downloaded available certificate chains","count":2,"first_url":"https://acme-staging-v02.api.letsencrypt.org/acme/cert/2b88caa374277ec0884032c79c6a84605488"}
Aug 29 04:52:50 ns5012842 caddy[3361552]: {"level":"info","ts":1724907170.4657645,"logger":"http","msg":"waiting on internal rate limiter","identifiers":["redacted.example.com"],"ca":"https://acme-v02.api.letsencrypt.org/directory","account":"caddy@zerossl.com"}
Aug 29 04:52:50 ns5012842 caddy[3361552]: {"level":"info","ts":1724907170.4657743,"logger":"http","msg":"done waiting on internal rate limiter","identifiers":["redacted.example.com"],"ca":"https://acme-v02.api.letsencrypt.org/directory","account":"caddy@zerossl.com"}
Aug 29 04:52:50 ns5012842 caddy[3361552]: {"level":"info","ts":1724907170.465785,"logger":"http","msg":"using ACME account","account_id":"https://acme-v02.api.letsencrypt.org/acme/acct/1087063237","account_contact":["mailto:caddy@zerossl.com"]}
Aug 29 04:52:50 ns5012842 caddy[3361552]: {"level":"error","ts":1724907170.810878,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"redacted.example.com","issuer":"acme-v02.api.letsencrypt.org-directory","error":"HTTP 400 urn:ietf:params:acme:error:malformed - JWS verification error"}
Aug 29 04:52:50 ns5012842 caddy[3361552]: {"level":"info","ts":1724907170.8109257,"logger":"tls.obtain","msg":"releasing lock","identifier":"redacted.example.com"}
Aug 29 04:52:50 ns5012842 caddy[3361552]: {"level":"error","ts":1724907170.8110101,"logger":"tls","msg":"job failed","error":"redacted.example.com: obtaining certificate: [redacted.example.com] Obtain: [redacted.example.com] creating new order: attempt 1: https://acme-v02.api.letsencrypt.org/acme/new-order: HTTP 400 urn:ietf:params:acme:error:malformed - JWS verification error (ca=https://acme-v02.api.letsencrypt.org/directory)"}
3. Caddy version:
v2.8.4 h1:q3pe0wpBj1OcHFZ3n/1nl4V4bxBrYoSoab7rL9BMYNk=
4. How I installed and ran Caddy:
We installed caddy using apt (sudo apt install caddy
, as shown here)
a. System environment:
uname -a
Linux ns5012842 5.15.0-70-generic #77-Ubuntu SMP Tue Mar 21 14:02:37 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux
b. Command:
/usr/bin/caddy run --environ --resume
c. systemd service
This is the same as the pre-installed one, except we add the --resume
flag
[Unit]
Description=Caddy
Documentation=https://caddyserver.com/docs/
After=network.target network-online.target
Requires=network-online.target
[Service]
Type=notify
User=caddy
Group=caddy
ExecStart=/usr/bin/caddy run --environ --resume
ExecReload=/usr/bin/caddy reload --force
TimeoutStopSec=5s
LimitNOFILE=1048576
PrivateTmp=true
ProtectSystem=full
AmbientCapabilities=CAP_NET_ADMIN CAP_NET_BIND_SERVICE
[Install]
WantedBy=multi-user.target
d. My complete Caddy config:
In this case we add it directly to the API, but the caddy JSON (gotten via curl http://localhost:2019/config/
)
{
"apps": {
"http": {
"servers": {
"srv0": {
"listen": [
":443"
],
"routes": [
{
"handle": [
{
"handler": "subroute",
"routes": [
{
"handle": [
{
"handler": "reverse_proxy",
"upstreams": [
{
"dial": "localhost:3037"
}
]
}
]
}
]
}
],
"match": [
{
"host": [
"redacted.example.com"
]
}
],
"terminal": true
}
]
}
}
}
}
}