Closed fgilio closed 2 years ago
mholt
commented
3 years ago Thanks for the report. When you enable debug logs, what do they show?
Edit: Also, it's weird that it happens with both ZeroSSL and Let's Encrypt, very different providers. How many operations are taking place at the time? How are we sure that it's not a hiccup in your network? Just trying to narrow down possibilities.
fgilio
commented
3 years ago Hi @mholt!
When you enable debug logs, what do they show?
Never did it. According to the docs it's just a matter of adding debug to the caddyfile at the same level as the on_demand_tls or storage directives. I'm going to try this and let you know.
UPDATE: I tested the debug flag and can now see a ton more info. But the issue is no longer happening right now, I'll keep this in mind for the next time something weird happens with our Caddy instances.
I'm leaving the issue open in case the questions below can point us in any direction.
Edit: Also, it's weird that it happens with both ZeroSSL and Let's Encrypt, very different providers.
Yes, it's very strange.
How many operations are taking place at the time?
What do you mean by "operations"? If it's only certificates generation, then it's usually about 1 to 4 per hour.
How are we sure that it's not a hiccup in your network? Just trying to narrow down possibilities.
Good question, I'd love to give you a solid answer but I've no idea. These servers are 100% dedicated to Caddy, nothing else is running on them. And both servers usually stay below 10% CPU usage.
francislavoie
commented
3 years ago Any update on this @fgilio?
fgilio
commented
3 years ago Hi @francislavoie! No updates, this has not happened again. We'll reopen and update in case it does happen again, and we'll use the debug flag straight away.
fgilio
commented
3 years ago Hi guys!
This is happening again and now we have the logs 💪
We're running v2.4.2 h1:chB106RlsIaY4mVEyq9OQM5g/9lHYVputo/LAX2ndFg=, and this is our Caddy config:
{
# This enables `debug` log
debug
on_demand_tls {
ask https://ourapp-https-guard.com/caddy-check-blablablabla
}
storage dynamodb caddy_ssl_certificates
storage_clean_interval 32d
}
:80 {
respond /health "Im healthy!" 200
}
:443 {
tls {
issuer zerossl blablablabla {
email my@email.com
dir https://acme.zerossl.com/v2/DV90
eab blablablabla blablablablablablablablablablablablablablablabla
}
issuer acme {
email my@email.com
}
on_demand
}
reverse_proxy * https://ourapp.com {
header_up Host ourapp.com
header_up X-Forwarded-Host {host}
header_up X-Forwarded-For {remote_host}
header_up X-Forwarded-Port {server_port}
header_up X-Forwarded-Proto {scheme}
health_timeout 5s
}
}And these are the logs with the debug level enabled:
Oct 25 19:50:45 custom-domains-staging-br-01 systemd[1]: Reloading Caddy.
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[1088051]: {"level":"info","ts":1635191445.7659783,"msg":"using provided configuration","config_file":"/etc/caddy/Caddyfile","config_adapter":""}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[1088051]: 2021/10/25 19:50:45 [WARNING] Unnecessary header_up ('X-Forwarded-Proto' field): the reverse proxy's default behavior is to pass headers to the upstream
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[1088051]: 2021/10/25 19:50:45 [WARNING] Unnecessary header_up ('X-Forwarded-Proto' field): the reverse proxy's default behavior is to pass headers to the upstream
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[1088051]: {"level":"warn","ts":1635191445.7697878,"msg":"input is not formatted with 'caddy fmt'","adapter":"caddyfile","file":"/etc/caddy/Caddyfile","line":2}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191445.772287,"logger":"admin.api","msg":"received request","method":"POST","host":"localhost:2019","uri":"/load","remote_addr":"127.0.0.1:51494","headers":{"Accept-Encoding":["gzip"],"Content-Length":["1824"],"Content-Type":["application/json"],"Origin":["localhost:2019"],"User-Agent":["Go-http-client/1.1"]}}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191445.7734485,"logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["localhost:2019","[::1]:2019","127.0.0.1:2019"]}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191445.7746146,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc00011ac40"}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191445.774674,"logger":"http","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}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191445.774871,"logger":"http","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}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191445.7748866,"logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191445.776187,"logger":"http","msg":"starting server loop","address":"[::]:443","http3":false,"tls":true}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191445.7762077,"logger":"http","msg":"starting server loop","address":"[::]:80","http3":false,"tls":false}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191445.7763228,"logger":"tls","msg":"cleaning storage unit","description":"&{caddy_ssl_certificates <nil> false 0 0}"}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191445.845681,"logger":"tls.cache.maintenance","msg":"stopped background certificate maintenance","cache":"0xc000120770"}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191445.8468363,"msg":"autosaved config (load with --resume flag)","file":"/var/lib/caddy/.config/caddy/autosave.json"}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191445.8468578,"logger":"admin.api","msg":"load complete"}
Oct 25 19:50:45 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191445.8489323,"logger":"admin","msg":"stopped previous server","address":"tcp/localhost:2019"}
Oct 25 19:50:45 custom-domains-staging-br-01 systemd[1]: Reloaded Caddy.
Oct 25 19:50:50 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191450.55012,"logger":"tls","msg":"loading managed certificate","domain":"staging-farfalla.publica.la","expiration":1641599999,"issuer_key":"acme.zerossl.com-v2-DV90","storage":{"table":"caddy_ssl_certificates","lock_timeout":300000000000,"lock_polling_interval":5000000000}}
Oct 25 19:50:59 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191459.7764788,"logger":"tls.on_demand","msg":"obtaining new certificate","server_name":"demofgiliotest20211025.publicala.me"}
Oct 25 19:51:00 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191460.7144182,"logger":"tls.obtain","msg":"acquiring lock","identifier":"demofgiliotest20211025.publicala.me"}
Oct 25 19:51:00 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191460.95853,"logger":"tls.obtain","msg":"lock acquired","identifier":"demofgiliotest20211025.publicala.me"}
Oct 25 19:51:01 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191461.434814,"logger":"tls.obtain","msg":"trying issuer 1/2","issuer":"acme.zerossl.com-v2-DV90"}
Oct 25 19:51:01 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191461.6692853,"logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["demofgiliotest20211025.publicala.me"],"ca":"https://acme.zerossl.com/v2/DV90","account":"fgilio@publica.la"}
Oct 25 19:51:01 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191461.669537,"logger":"tls.issuance.acme","msg":"done waiting on internal rate limiter","identifiers":["demofgiliotest20211025.publicala.me"],"ca":"https://acme.zerossl.com/v2/DV90","account":"fgilio@publica.la"}
Oct 25 19:51:02 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191462.573778,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"HEAD","url":"https://acme.zerossl.com/v2/DV90/newNonce","headers":{"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Type":["application/octet-stream"],"Date":["Mon, 25 Oct 2021 19:51:02 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["YDoTPRlh1-qHnmy21iTQfw2JtAHE71cZH4XHehfPk7Y"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:02 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191462.8212652,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/newOrder","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":201,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=0, no-cache, no-store","max-age=-1"],"Content-Length":["297"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:02 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/Nc8u6X2dsf4i12EFZxO7zQ"],"Replay-Nonce":["qdBDJ32c92XMn4iVk3y2VPHLTCLgwXN4UdXzBGufa60"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:03 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191463.024055,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/11CxCt3R_tFKswKXaK_VWg","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["465"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:02 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["PigsaXE4kBUg-kaB6_NF5Ny7WoAXCVRIlT3QZAkxPJw"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:03 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191463.0242057,"logger":"tls.issuance.acme.acme_client","msg":"no solver configured","challenge_type":"dns-01"}
Oct 25 19:51:03 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191463.0242183,"logger":"tls.issuance.acme.acme_client","msg":"trying to solve challenge","identifier":"demofgiliotest20211025.publicala.me","challenge_type":"http-01","ca":"https://acme.zerossl.com/v2/DV90"}
Oct 25 19:51:03 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191463.3946435,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/chall/z3Cw6JJZYHbrKiTBXEOjmA","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["164"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:03 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\"","<https://acme.zerossl.com/v2/DV90/authz/11CxCt3R_tFKswKXaK_VWg>;rel=\"up\""],"Replay-Nonce":["xaOOee_pwzgE3JT1USy2RvJirn_YfoAPnL2I4LrCO5E"],"Retry-After":["10"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:03 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191463.394733,"logger":"tls.issuance.acme.acme_client","msg":"challenge accepted","identifier":"demofgiliotest20211025.publicala.me","challenge_type":"http-01"}
Oct 25 19:51:03 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191463.9322329,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/11CxCt3R_tFKswKXaK_VWg","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["468"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:03 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["UCpkKlUG8uEy-ZMz-oLaLp1GK3Xf8_cW44NOTDlFaG0"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:09 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191469.1185324,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/11CxCt3R_tFKswKXaK_VWg","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["468"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:09 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["N3zMKUBCwDK-3ssj-9kVbr88JVDx8UzIPIxomqw_uZ8"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:14 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191474.3100483,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/11CxCt3R_tFKswKXaK_VWg","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["468"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:14 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["iW_r_ZTntJXw50Z3JFGjjTCD00v3HVHGtSVEZh5jNFI"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:19 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191479.5178995,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/11CxCt3R_tFKswKXaK_VWg","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["468"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:19 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["EIwWXh3JTlgqK8Gn2gcYS5bApJVo0DdJeILerZkEKOY"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:24 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191484.6796386,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/11CxCt3R_tFKswKXaK_VWg","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["468"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:24 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["AwrHbfeB_kVkB8BzaGojzcIxQLh-vYno_ggAVNGXt8M"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:29 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191489.852036,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/11CxCt3R_tFKswKXaK_VWg","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["468"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:29 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["VfEeBU8t0aOqQBHXrb0-3XmYupAO6_mGFxCc2oNu-T4"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:35 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191495.0641243,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/11CxCt3R_tFKswKXaK_VWg","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["468"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:34 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["kEfmDi9PxaNLjvMXdX_WpAFfA2jPHAnuo19FPAdWDIY"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:40 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191500.244451,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/11CxCt3R_tFKswKXaK_VWg","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["468"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:40 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["TX2H8SKfcOjkYl02_8jknWlGHO9JbXSFp84MXqVfLiE"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:45 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191505.4565187,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/11CxCt3R_tFKswKXaK_VWg","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["468"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:45 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["u30DLaMqPG0E8oTx5_mPWWuVVc3c-VBaRwgT-QBkHME"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:50 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191510.6674209,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/11CxCt3R_tFKswKXaK_VWg","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["335"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:50 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["gnGzVGQ7SBQJxXtVfW4vCusBsvAxbwfrOR7lpwSQ4C0"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:51:50 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191510.7889047,"logger":"tls.issuance.acme.acme_client","msg":"validations succeeded; finalizing order","order":"https://acme.zerossl.com/v2/DV90/order/Nc8u6X2dsf4i12EFZxO7zQ"}
Oct 25 19:51:51 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191511.1681097,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/order/Nc8u6X2dsf4i12EFZxO7zQ/finalize","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["300"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:51:51 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/Nc8u6X2dsf4i12EFZxO7zQ"],"Replay-Nonce":["ibglOVN7I9VI-4SgQo0MkXky56_ccsJ02QqbQ0ZdW9g"],"Retry-After":["15"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:52:06 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191526.4611456,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/order/Nc8u6X2dsf4i12EFZxO7zQ","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["300"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:52:06 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/Nc8u6X2dsf4i12EFZxO7zQ"],"Replay-Nonce":["V_7jyio-vb3FVdV4z2wlYzB2IoNIEc_cN810OtbvgdY"],"Retry-After":["15"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:52:21 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191541.714607,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/order/Nc8u6X2dsf4i12EFZxO7zQ","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["300"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:52:21 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/Nc8u6X2dsf4i12EFZxO7zQ"],"Replay-Nonce":["sUozd0B4QXXAtVuC0A5ehwBZfcK6ExteVZhL46iDGvk"],"Retry-After":["15"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:52:29 custom-domains-staging-br-01 caddy[326595]: {"level":"error","ts":1635191549.7770689,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"demofgiliotest20211025.publicala.me","issuer":"acme.zerossl.com-v2-DV90","error":"[demofgiliotest20211025.publicala.me] finalizing order https://acme.zerossl.com/v2/DV90/order/Nc8u6X2dsf4i12EFZxO7zQ: context deadline exceeded (ca=https://acme.zerossl.com/v2/DV90)"}
Oct 25 19:52:29 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191549.7771528,"logger":"tls.obtain","msg":"trying issuer 2/2","issuer":"acme-v02.api.letsencrypt.org-directory"}
Oct 25 19:52:30 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191550.014238,"logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["demofgiliotest20211025.publicala.me"],"ca":"https://acme-v02.api.letsencrypt.org/directory","account":"fgilio@publica.la"}
Oct 25 19:52:30 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191550.0142884,"logger":"tls.issuance.acme","msg":"done waiting on internal rate limiter","identifiers":["demofgiliotest20211025.publicala.me"],"ca":"https://acme-v02.api.letsencrypt.org/directory","account":"fgilio@publica.la"}
Oct 25 19:52:30 custom-domains-staging-br-01 caddy[326595]: {"level":"warn","ts":1635191550.0143466,"logger":"tls.issuance.acme.acme_client","msg":"HTTP request failed; retrying","url":"https://acme-v02.api.letsencrypt.org/directory","error":"performing request: Get \"https://acme-v02.api.letsencrypt.org/directory\": context deadline exceeded"}
Oct 25 19:52:30 custom-domains-staging-br-01 caddy[326595]: {"level":"error","ts":1635191550.0143867,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"demofgiliotest20211025.publicala.me","issuer":"acme-v02.api.letsencrypt.org-directory","error":"[demofgiliotest20211025.publicala.me] creating new order: provisioning client: context deadline exceeded (ca=https://acme-v02.api.letsencrypt.org/directory)"}
Oct 25 19:52:30 custom-domains-staging-br-01 caddy[326595]: {"level":"error","ts":1635191550.0144014,"logger":"tls.obtain","msg":"will retry","error":"[demofgiliotest20211025.publicala.me] Obtain: [demofgiliotest20211025.publicala.me] creating new order: provisioning client: context deadline exceeded (ca=https://acme-v02.api.letsencrypt.org/directory)","attempt":1,"retrying_in":60,"elapsed":89.055843708,"max_duration":2592000}
Oct 25 19:52:30 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191550.014412,"logger":"tls.obtain","msg":"releasing lock","identifier":"demofgiliotest20211025.publicala.me"}
Oct 25 19:52:30 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191550.1329362,"logger":"http.stdlib","msg":"http: TLS handshake error from 190.245.59.70:55122: context canceled"}
Oct 25 19:53:06 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191586.7669406,"logger":"tls.on_demand","msg":"obtaining new certificate","server_name":"demofgiliotest20211025.publicala.me"}
Oct 25 19:53:07 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191587.6330338,"logger":"tls.obtain","msg":"acquiring lock","identifier":"demofgiliotest20211025.publicala.me"}
Oct 25 19:53:07 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191587.871315,"logger":"tls.obtain","msg":"lock acquired","identifier":"demofgiliotest20211025.publicala.me"}
Oct 25 19:53:08 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191588.3419158,"logger":"tls.obtain","msg":"trying issuer 1/2","issuer":"acme.zerossl.com-v2-DV90"}
Oct 25 19:53:08 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191588.5800972,"logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["demofgiliotest20211025.publicala.me"],"ca":"https://acme.zerossl.com/v2/DV90","account":"fgilio@publica.la"}
Oct 25 19:53:08 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191588.5812044,"logger":"tls.issuance.acme","msg":"done waiting on internal rate limiter","identifiers":["demofgiliotest20211025.publicala.me"],"ca":"https://acme.zerossl.com/v2/DV90","account":"fgilio@publica.la"}
Oct 25 19:53:09 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191589.1687744,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"HEAD","url":"https://acme.zerossl.com/v2/DV90/newNonce","headers":{"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Type":["application/octet-stream"],"Date":["Mon, 25 Oct 2021 19:53:09 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["0dh8iykLRJEgdsog2XLslsiYq9drCPoJMiSsrYQ5kus"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:53:09 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191589.4605386,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/newOrder","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":201,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=0, no-cache, no-store","max-age=-1"],"Content-Length":["297"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:53:09 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA"],"Replay-Nonce":["4OIO4OAZKeTYOVgNJ3iSr6k1V9cygtbghKA51AFEMDY"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:53:09 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191589.689198,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/sC26awn34WxJOT0K8KH0cQ","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["465"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:53:09 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["chu11uxUzb3hc23EtDu8cK1brtOuoCQlfTAurdW2B2g"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:53:09 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191589.6893125,"logger":"tls.issuance.acme.acme_client","msg":"no solver configured","challenge_type":"dns-01"}
Oct 25 19:53:09 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191589.6893222,"logger":"tls.issuance.acme.acme_client","msg":"trying to solve challenge","identifier":"demofgiliotest20211025.publicala.me","challenge_type":"http-01","ca":"https://acme.zerossl.com/v2/DV90"}
Oct 25 19:53:10 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191590.0838847,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/chall/4ThSVn5l_RTsZehqxbIFtA","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["164"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:53:10 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\"","<https://acme.zerossl.com/v2/DV90/authz/sC26awn34WxJOT0K8KH0cQ>;rel=\"up\""],"Replay-Nonce":["SOMosWVXlBlfaliviulBbQDDcWUhqXvktLK3SKxFqKg"],"Retry-After":["10"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:53:10 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191590.0842097,"logger":"tls.issuance.acme.acme_client","msg":"challenge accepted","identifier":"demofgiliotest20211025.publicala.me","challenge_type":"http-01"}
Oct 25 19:53:10 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191590.6076076,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/sC26awn34WxJOT0K8KH0cQ","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["335"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:53:10 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["Qjl5WjHBK1nRfekMs74U1XMfmG3NRtXS0DTGZnn7cKA"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:53:10 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191590.72736,"logger":"tls.issuance.acme.acme_client","msg":"validations succeeded; finalizing order","order":"https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA"}
Oct 25 19:53:11 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191591.1284513,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA/finalize","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["300"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:53:11 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA"],"Replay-Nonce":["vWl4qMBEOyq_WD6QQmwESuaep6PBO-WMj75erB6rAlE"],"Retry-After":["15"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:53:26 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191606.3751113,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["300"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:53:26 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA"],"Replay-Nonce":["ff17Uyd9N4mLvKCP_weztBWv6NgsrCNBUjVvtf9aSm4"],"Retry-After":["15"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:53:41 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191621.5647938,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["300"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:53:41 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA"],"Replay-Nonce":["VbYdCdeqSQlyJ1Hv_v54mh5DaFU16bVP_r4D6FEfLNE"],"Retry-After":["15"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:53:56 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191636.89529,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["300"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:53:56 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA"],"Replay-Nonce":["yFP7uOa_II2AP_bKIL4rjQUiCOOEObCmPCDWDIzAas0"],"Retry-After":["15"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:54:12 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191652.0751743,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["300"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:54:12 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA"],"Replay-Nonce":["zA9RLK9H4Zds2K_a4rWJTu7EgdGwssDJmD6ZaUpcKWM"],"Retry-After":["15"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:54:27 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191667.2728748,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["300"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:54:27 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA"],"Replay-Nonce":["m8iQffKLQR0V3xr9QapqBqwThpZ0IiHXgqoT2GK9oOg"],"Retry-After":["15"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:54:36 custom-domains-staging-br-01 caddy[326595]: {"level":"error","ts":1635191676.7675414,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"demofgiliotest20211025.publicala.me","issuer":"acme.zerossl.com-v2-DV90","error":"[demofgiliotest20211025.publicala.me] finalizing order https://acme.zerossl.com/v2/DV90/order/q1DjDnv8t0SndgnF9XbLJA: context deadline exceeded (ca=https://acme.zerossl.com/v2/DV90)"}
Oct 25 19:54:36 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191676.7681208,"logger":"tls.obtain","msg":"trying issuer 2/2","issuer":"acme-v02.api.letsencrypt.org-directory"}
Oct 25 19:54:37 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191677.0064538,"logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["demofgiliotest20211025.publicala.me"],"ca":"https://acme-v02.api.letsencrypt.org/directory","account":"fgilio@publica.la"}
Oct 25 19:54:37 custom-domains-staging-br-01 caddy[326595]: {"level":"error","ts":1635191677.006508,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"demofgiliotest20211025.publicala.me","issuer":"acme-v02.api.letsencrypt.org-directory","error":"context canceled"}
Oct 25 19:54:37 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191677.006521,"logger":"tls.obtain","msg":"releasing lock","identifier":"demofgiliotest20211025.publicala.me"}
Oct 25 19:54:37 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191677.1253417,"logger":"http.stdlib","msg":"http: TLS handshake error from 190.245.59.70:55130: [demofgiliotest20211025.publicala.me] Obtain: context canceled"}
Oct 25 19:54:37 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191677.5960405,"logger":"http.stdlib","msg":"http: TLS handshake error from 190.245.59.70:55137: no certificate available for 'demofgiliotest20211025.publicala.me'"}
Oct 25 19:55:05 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191705.225738,"logger":"tls.on_demand","msg":"obtaining new certificate","server_name":"demofgiliotest20211025.publicala.me"}
Oct 25 19:55:06 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191706.053277,"logger":"tls.obtain","msg":"acquiring lock","identifier":"demofgiliotest20211025.publicala.me"}
Oct 25 19:56:07 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191767.717552,"logger":"tls.obtain","msg":"lock acquired","identifier":"demofgiliotest20211025.publicala.me"}
Oct 25 19:56:08 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191768.187909,"logger":"tls.obtain","msg":"trying issuer 1/2","issuer":"acme.zerossl.com-v2-DV90"}
Oct 25 19:56:08 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191768.4232187,"logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["demofgiliotest20211025.publicala.me"],"ca":"https://acme.zerossl.com/v2/DV90","account":"fgilio@publica.la"}
Oct 25 19:56:08 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191768.423264,"logger":"tls.issuance.acme","msg":"done waiting on internal rate limiter","identifiers":["demofgiliotest20211025.publicala.me"],"ca":"https://acme.zerossl.com/v2/DV90","account":"fgilio@publica.la"}
Oct 25 19:56:09 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191769.081165,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"HEAD","url":"https://acme.zerossl.com/v2/DV90/newNonce","headers":{"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Type":["application/octet-stream"],"Date":["Mon, 25 Oct 2021 19:56:09 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["aUBEL5uDebF2_j8V7OWauOgISt025bl8xiknaomxmzk"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:56:09 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191769.2536356,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/newOrder","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":201,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=0, no-cache, no-store","max-age=-1"],"Content-Length":["297"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:56:09 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/HR0WouyxpXxQa5CmqaqllQ"],"Replay-Nonce":["x3XpWbLQ7HVpUjhIe4uAAqY2QPdDGZCw9qXCuovoJAY"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:56:09 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191769.3988042,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/m-cOpAQ_GEtU7gfFHJq1Hw","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["465"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:56:09 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["qeKkPlh2Gt5sMok6so3Ik4S_j1Fcob6zPvCSuIB6xfE"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:56:09 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191769.3989742,"logger":"tls.issuance.acme.acme_client","msg":"no solver configured","challenge_type":"dns-01"}
Oct 25 19:56:09 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191769.398987,"logger":"tls.issuance.acme.acme_client","msg":"trying to solve challenge","identifier":"demofgiliotest20211025.publicala.me","challenge_type":"http-01","ca":"https://acme.zerossl.com/v2/DV90"}
Oct 25 19:56:09 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191769.7203524,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/chall/0a-lCl-MMqXOXoZLmYcRgA","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["164"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:56:09 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\"","<https://acme.zerossl.com/v2/DV90/authz/m-cOpAQ_GEtU7gfFHJq1Hw>;rel=\"up\""],"Replay-Nonce":["nWiya1skWh5cU3ErXOHv_FSEx-oFq19mc8KnNBXpRUo"],"Retry-After":["10"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:56:09 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191769.7204297,"logger":"tls.issuance.acme.acme_client","msg":"challenge accepted","identifier":"demofgiliotest20211025.publicala.me","challenge_type":"http-01"}
Oct 25 19:56:10 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191770.1756642,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/authz/m-cOpAQ_GEtU7gfFHJq1Hw","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["335"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:56:10 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["vc83s2uVDcb6OYR1I_ZuPK-iorN9uRQ7QoDqPukgwqo"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:56:10 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191770.2961998,"logger":"tls.issuance.acme.acme_client","msg":"validations succeeded; finalizing order","order":"https://acme.zerossl.com/v2/DV90/order/HR0WouyxpXxQa5CmqaqllQ"}
Oct 25 19:56:10 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191770.5669835,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/order/HR0WouyxpXxQa5CmqaqllQ/finalize","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["300"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:56:10 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/HR0WouyxpXxQa5CmqaqllQ"],"Replay-Nonce":["iQybeRTqNuUGcLD_YyYlEklJ9aVDXUaa0wXlSkK_Ys4"],"Retry-After":["15"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
^[Oct 25 19:56:25 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191785.7490797,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme.zerossl.com/v2/DV90/order/HR0WouyxpXxQa5CmqaqllQ","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.2 CertMagic acmez (linux; amd64)"]},"status_code":200,"response_headers":{"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=-1"],"Content-Length":["300"],"Content-Type":["application/json"],"Date":["Mon, 25 Oct 2021 19:56:25 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/HR0WouyxpXxQa5CmqaqllQ"],"Replay-Nonce":["iSFMy-lDgwM3rH-lExumF6azYevHrzst8tfvzWvIBcI"],"Retry-After":["15"],"Server":["nginx"],"Status":[""],"Strict-Transport-Security":["max-age=15552000"]}}
Oct 25 19:56:35 custom-domains-staging-br-01 caddy[326595]: {"level":"error","ts":1635191795.2265968,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"demofgiliotest20211025.publicala.me","issuer":"acme.zerossl.com-v2-DV90","error":"[demofgiliotest20211025.publicala.me] finalizing order https://acme.zerossl.com/v2/DV90/order/HR0WouyxpXxQa5CmqaqllQ: context deadline exceeded (ca=https://acme.zerossl.com/v2/DV90)"}
Oct 25 19:56:35 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191795.227279,"logger":"tls.obtain","msg":"trying issuer 2/2","issuer":"acme-v02.api.letsencrypt.org-directory"}
Oct 25 19:56:35 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191795.4636214,"logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["demofgiliotest20211025.publicala.me"],"ca":"https://acme-v02.api.letsencrypt.org/directory","account":"fgilio@publica.la"}
Oct 25 19:56:35 custom-domains-staging-br-01 caddy[326595]: {"level":"error","ts":1635191795.4636722,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"demofgiliotest20211025.publicala.me","issuer":"acme-v02.api.letsencrypt.org-directory","error":"context canceled"}
Oct 25 19:56:35 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1635191795.4636865,"logger":"tls.obtain","msg":"releasing lock","identifier":"demofgiliotest20211025.publicala.me"}
Oct 25 19:56:35 custom-domains-staging-br-01 caddy[326595]: {"level":"debug","ts":1635191795.583506,"logger":"http.stdlib","msg":"http: TLS handshake error from 190.245.59.70:55143: [demofgiliotest20211025.publicala.me] Obtain: context canceled"}I hope this helps, please let me know if you need more information.
francislavoie
commented
3 years ago I think that happens in this case because it took longer than 90 seconds, i.e. the maximum amount of time on-demand waits for the handshake.
There was some related discussion in this topic on the forums https://caddy.community/t/zerossl-dns-challenge-failing-often-route53-plugin/13822/9
Matt did recently increase it to 180 seconds, to be in the next release: https://github.com/caddyserver/certmagic/commit/c17cc712281496569bca81c8bb21dae81789b63e
fgilio
commented
3 years ago Hi Francis, and thanks for the info! 180 seconds feels like an eternity. Is this caused by issues in the ACME providers? I find it weird that it happens with both ZeroSSL and Let's Encrypt (which we use as a fallback). Also, is there anything I can do to collect more information? Anything you need
mholt
commented
3 years ago Thanks for the additional info, I'll look at this as soon as I can. We're not sure why some cert requests take longer. This was always a concern when On-Demand was initially implemented back in 2015-2016, but Let's Encrypt (the only ACME CA at the time) was always speedy with issuance (less than 5 seconds) so it wasn't a concern, but our docs still said that if CAs became slow at issuing then on-demand would lose its appeal/validity. We removed that caveat recently because that seems like it won't be a problem (especially as Let's Encrypt has significantly beefed up their hardware). But apparently some CAs are still slow sometimes, or maybe it's related to DNS. We're not sure yet.
fgilio
commented
3 years ago Thanks for the extra info Matt. We stand available in case there's something we can do to gather more info.
mholt
commented
3 years ago It looks like ZeroSSL's endpoint sometimes just takes a long time to finalize an order (I've experienced this before too), and those times can be too slow for the timeout I configured; from start to finish it can't take more than 180 seconds (although you're probably still running the release that has it at 90s).
francislavoie
commented
3 years ago @mholt is there a way at all to cancel the TLS handshake after a certain point, but let the ACME job keep going async? Like move it from sync to async on timeout?
mholt
commented
3 years ago Ehhhh, if 3 minutes isn't long enough, I think a bigger problem needs to be fixed, rather than introducing more complexity into our code base first. @fgilio maybe ask ZeroSSL and see how long to expect FinalizeOrder to take?
fgilio
commented
3 years ago (although you're probably still running the release that has it at 90s).
Yes, we're running v2.4.2.
@fgilio maybe ask ZeroSSL and see how long to expect FinalizeOrder to take?
Will let you know what they say. Hadn't have much success with their support team so far.
We do have Let's Encrypt as a fallback (can't use it as primary because of rate limits), are these slow requests in ZeroSSL making the Let's Encrypt fallback fail?
mholt
commented
3 years ago We do have Let's Encrypt as a fallback (can't use it as primary because of rate limits), are these slow requests in ZeroSSL making the Let's Encrypt fallback fail?
Yes, it looks like it. From your recent logs, an issuance task that started at 1635191461 was canceled at 1635191549, which is about 90 seconds later. That's already an absurdly long amount of time to hold a TLS handshake open, and I've even doubled it to 180 on tip. I don't know a better solution than to request the CAs to speed up their issuance times.
fgilio
commented
3 years ago That's already an absurdly long amount of time to hold a TLS handshake open, and I've even doubled it to 180 on tip
100% agree. Also the issue here is the huge amplitud of issuance time.
*I've already contacted ZeroSSL support, let's see what they have to say 🤞
EDIT: I'm still waiting for their reply, hope it arrives soon EDIT 2: They are now actively looking into this issue 🙌 🤞
fgilio
commented
2 years ago Hello! This is ZeroSSL's official response:
our backend team said that as per logs we had some issues at our end for DCV backlog which causes slow issuances of certs.
I guess it's not really helpful, but confirm that it was indeed an issue on their side. Maybe (I've no idea actually) Caddy can do something to better handle those cases use fallback earlier, idk.
Is there anything else that would be useful to know and I could ask them?
mholt
commented
2 years ago Nothing I can think of. Thanks for reporting it to them. I'm not sure we can really do anything/much about it... open to ideas though.
carterbryden
commented
2 years ago Not looking to revive this, just confirming that this is also happening for me when I had a bulk import of a few thousand domains over a couple of days.
I think ZeroSSL just has some performance issues (maybe only from time to time, unsure as of yet).
nsouto
commented
1 month ago Hello everyone,
I'm sorry to reopen this thread, but it's the only one I can find about the exact problem I'm having "context deadline exceeded"
I'm trying to get certificates for a couple thousand domains, and everything seems to go well, until around 3:40m it starts spewing the error into the logs and snowballs from there until I restart the caddy container... it makes no sense at all, and once that happens if I have fallbacks defined it will try to use those and fail as well, this happens no matter the provider.
here is a quick log sample using grep for "certificate obtained successfully and context deadline exceeded":
{"level":"info","ts":1727717302.5693352,"logger":"tls.obtain","msg":"certificate obtained successfully","identifier":"93614.com","issuer":"acme-v02.api.letsencrypt.org-directory"}
{"level":"error","ts":1727717304.5485673,"logger":"http.acme_client","msg":"cleaning up solver","identifier":"www.29142.com","challenge_type":"http-01","error":"Unable to delete directory for key acme/acme-staging-v02.api.letsencrypt.org-directory/challenge_tokens/www.29142.com.json: Unable to remove www.29142.com.json from Set caddy/acme/acme-staging-v02.api.letsencrypt.org-directory/challenge_tokens: context deadline exceeded"}
{"level":"warn","ts":1727717304.5487227,"logger":"http.acme_client","msg":"HTTP request failed; retrying","url":"https://acme-staging-v02.api.letsencrypt.org/acme/authz-v3/14216807603","error":"performing request: Post \"https://acme-staging-v02.api.letsencrypt.org/acme/authz-v3/14216807603\": context deadline exceeded"}
{"level":"error","ts":1727717304.5487387,"logger":"http.acme_client","msg":"deactivating authorization","identifier":"www.29142.com","authz":"https://acme-staging-v02.api.letsencrypt.org/acme/authz-v3/14216807603","error":"attempt 1: https://acme-staging-v02.api.letsencrypt.org/acme/authz-v3/14216807603: context deadline exceeded"}
{"level":"error","ts":1727717304.5487556,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"www.29142.com","issuer":"acme-v02.api.letsencrypt.org-directory","error":"[www.29142.com] solving challenges: [www.29142.com] context deadline exceeded (order=https://acme-staging-v02.api.letsencrypt.org/acme/order/165289333/19472659243) (ca=https://acme-staging-v02.api.letsencrypt.org/directory)"}
{"level":"warn","ts":1727717789.1796052,"logger":"http.acme_client","msg":"HTTP request failed; retrying","url":"https://acme-v02.api.letsencrypt.org/acme/finalize/1951916056/309551433737","error":"performing request: Post \"https://acme-v02.api.letsencrypt.org/acme/finalize/1951916056/309551433737\": context deadline exceeded"}
{"level":"error","ts":1727717789.1796513,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"faerman.com","issuer":"acme-v02.api.letsencrypt.org-directory","error":"[faerman.com] finalizing order https://acme-v02.api.letsencrypt.org/acme/order/1951916056/309551433737: attempt 1: https://acme-v02.api.letsencrypt.org/acme/finalize/1951916056/309551433737: context deadline exceeded (ca=https://acme-v02.api.letsencrypt.org/directory)"}unsure also why acme-staging is showing up in there, I don't have staging set anywhere in the configs:
{
# debug
on_demand_tls {
ask {$DOMAIN_CHECK_URL}
}
cert_issuer acme https://acme-v02.api.letsencrypt.org/directory
# cert_issuer acme https://acme.zerossl.com/v2/DV90
# cert_issuer acme https://api.buypass.com/acme/directory
# cert_issuer acme https://dv.acme-v02.api.pki.goog/directory {
# eab {$ACME_GOOGLE_EAB_KEY_ID} {$ACME_GOOGLE_EAB_HMAC_KEY}
# }
email {$LETS_ENCRYPT_EMAIL}
storage redis {
host "{$REDIS_HOST:redis}"
port "{$REDIS_PORT:6379}"
password "{$REDIS_PASSWORD:}"
compression true
}
}
: {
tls {
on_demand
}
handle {
reverse_proxy {$ORIGIN_URL}
}
log {
output stderr
}
}I'm at a complete loss as I can't figure out what the issue is here, I would appreciate any pointers, or things to look out for, test, etc...
The only way I had to get through most of the certificates was to run this:
watch -n300 docker restart caddy
So the container would restart automatically every 5m in an attempt to get through all the domains.
Thank You
mholt
commented
1 month ago unsure also why acme-staging is showing up in there, I don't have staging set anywhere in the configs
Caddy (CertMagic) reverts to LE's staging endpoint after LE production fails once, to avoid rate limits, while the issues that prevented success are addressed. If it then succeeds in staging, it will likely succeed in prod. See https://caddyserver.com/docs/automatic-https#errors
On-demand TLS sets a timeout of 3 minutes to avoid keeping TLS handshake connections open forever. If a cert can't be obtained in 3 minutes, it's likely not going to happen, so it exceeds the context deadline.
How many certs are you getting all at once?
I'm trying to get certificates for a couple thousand domains
All at once?
nsouto
commented
1 month ago Caddy (CertMagic) reverts to LE's staging endpoint after LE production fails once, to avoid rate limits, while the issues that prevented success are addressed. If it then succeeds in staging, it will likely succeed in prod. See https://caddyserver.com/docs/automatic-https#errors
I see, I will look more into that.
On-demand TLS sets a timeout of 3 minutes to avoid keeping TLS handshake connections open forever. If a cert can't be obtained in 3 minutes, it's likely not going to happen, so it exceeds the context deadline.
Yeah I saw that, and it makes perfect sense, I just don't get why certs are issued fine and all of a sudden they go into a context deadline exceed snowball, as per the logs, ocasionally a cert or two make it, but it essentially comes to a full stop.
How many certs are you getting all at once?
I'm trying to get certificates for a couple thousand domains
All at once?
It's a very busy instance and I'm using the on demand so I don't really have control over how many accesses to different domains happen all at once, basically if someone adds 50k domains to the system and they all have a lot of traffic I would have to deal with issuing 50k certs as fast as possible, LE already upped the rate limit to 100k on their end (unsure if per day or per week, need to clarify that)
Do you have any suggestion to mitigate this, maybe present http until the https is available?
The only thing I can think of is to offload the cert generation from caddy to an external process, which would then populate the caddy redis/mysql/file storage with the correct data but the ideal solution would be to have caddy deal with the certs as traffic comes in, some domains will hardly have any traffic at all.
Thank you so much for the quick reply
mholt
commented
1 month ago Hm, yeah if you're getting a stampede that could cause a timeout since we don't want to overwhelm CAs. This is very rare though and I haven't heard about this from other large integrators 🤔
Do you have any suggestion to mitigate this, maybe present http until the https is available?
Browsers will (should) reject HTTP if they are requesting HTTPS.
Best course of action would probably be to pin down what is causing the delays. Full logs, a profile could be helpful, an idea of the traffic it's currently getting, etc. (Probably in the forum since I'm not sure if it's a bug.)
nsouto
commented
1 month ago Sounds good, I'll continue in the forum, I don't think it's a bug also, but at the same time it feels like one.
I'll update the issue here with a link to the forum so if anyone else finds this there's some reference.
Will have to parse some of the logs though as the instance does get a lot of traffic, I'm working on gathering the stats for it, but last I did a quick check it was about 130k every hour if I'm not mistaken, most of them of course are bots which I'll be blocking from accessing the application behind caddy but will need caddy to deal with it.
mholt
commented
1 month ago most of them of course are bots which I'll be blocking from accessing the application behind caddy
Are the domains they're getting certs for even supposed to be served by you? What is your ask endpoint doing?
nsouto
commented
1 month ago Are the domains they're getting certs for even supposed to be served by you? What is your
askendpoint doing?
Yes the domains are supposed to be served by caddy, the ask endpoint is making sure that the domain is valid and added to the system so the application can respond, if someone points the domain at it but doesn't register it in the system, the ask endpoint will not validate it for caddy to get a cert for it.
Eventually I also want to get wildcard domains supported, as at the moment it's getting both the www. and the root domain separately but I didn't find a way to actually do that unless I work on a custom module to support it, when I tried the DNS module it would get the *. but not include the root domain on it as well, so it wouldn't work (this could be something I did wrong though)
mholt
commented
1 month ago I guess I don't understand why you have bots able to initiate certificate requests, which you end up blocking... like how do they know what domains your ask endpoint is approving? Are they enumerating them?
nsouto
commented
1 month ago What I mean by bots is things like http://domain.com/wp-content/unsecuredfile.php scans for example, we get a ton of those, and when faced with that caddy will reply with a 308 to https://domain.com/wp-content/unsecuredfile.php if domain.com is a valid domain as checked by the ask endpoint.
As I write this I haven't checked if the ask endpoint passes anything other than the domain itself if it does it could serve as a basic WAF as well, at the moment I'm using the forward_auth to implement a sort of firewall and block all those requests from ever reaching the application based on specific rules, but this happens after caddy sends the 308, doing it before would actually be much better and avoid cert generation until an actual person loads the domain.
Off the top of your head do you think I can achieve this?
francislavoie
commented
1 month ago The HTTP path is not known at the time of the TLS handshake so it's not possible to pass that info in ask.
You could prevent the redirects from happening using an http:// site block but I don't know if that would truly solve anything.
nsouto
commented
1 month ago You could prevent the redirects from happening using an
http://site block but I don't know if that would truly solve anything.
I'm thinking maybe instead of the automatic https redirect, I could do it manually and in the http request, firewall at least some of the traffic, and then issue an https redirect, but again if some bot just decides to hit https directly then it changes nothing.
So I guess the main point of solving the context deadline exceeded is what I need to figure out, first on why they are happening, maybe due to the overwhelming number of requests, and how to mitigate that and still have the fastest ssl cert generation possible.
mholt
commented
1 month ago I'm still unclear as to what bots have to do with it. Whether it's a bot or a person in a web browser shouldn't matter. 🤔
nsouto
commented
1 month ago I'm still unclear as to what bots have to do with it. Whether it's a bot or a person in a web browser shouldn't matter. 🤔
Sorry, the mention of the bots is that we get a LOT of traffic from them, since there are so many domains, we get a lot of "scans" for possible vulnerable installed software such as Wordpress for example.
The mention of the bots was in regards to the question about how many certs is caddy trying to issue at once, and since it's on-demand it depends on the traffic coming in, which in this case is loading a bunch of domains all at once, from my rough calc at the time about 130k accesses per hour, I was not able to gather proper stats yet, but should have that hopefully by today.
All this seems to contribute to the context deadline exceeded issue and how to go about solving it, the server is fine in terms of load and I must say caddy is very much optimized, as it can handle all that without a sweat.
LE can handle it and we never ran into any rate limits with them based on them upping it to 100k
Now that all domains have had their certs issued, I still see some context deadline errors but more sporadically, so this seems to indicate that it's something related to volume, just unsure how to solve it, but one idea was to try to block as many bots as possible so we focus only on actual traffic, but that doesn't seem to be a proper solution, just a patch for this specific case right now.
mholt
commented
1 month ago Ah okay, so you're getting bot traffic for legitimate domain names that you service, so it's just a flood of requests all at once that isn't at all natural.
So yeah, in that case, you will perhaps need to do some sort of filtering/blocking of bot traffic to improve performance. (That's probably true regardless of on-demand TLS though tbh). Also, this should be a one-time thing. Did you recently turn on on-demand TLS for thousands of sites all at once? Once you have certificates, management happens in the background so it won't block like that.
I would recommend your company invest in an appropriate sponsorship if you're serving that many domains. We'll be able to help you better.
nsouto
commented
1 month ago Did you recently turn on on-demand TLS for thousands of sites all at once?
Only ever used on-demand, I did build a separate application to register the certs and add them to caddy's storage so that I can start getting the cert as soon as the domains are added and resolving in the system, but with LE's rate limit increase it became less of an issue until I ran into this context deadline exceeded. Along with this application I was thinking of setting a caddy instance that would only load on http and once the cert is out move the domain to the normal one that auto-redirects to https and serves it with the cert (might be overcomplicating it but it seemed logical to me to get things "working" while the certs are issued), unsure yet if it's possible to do it all in one caddy instance though with an unknown number of domains.
Once you have certificates, management happens in the background so it won't block like that.
Yes after the fact things work proper (just moved from postgres to redis as the db was having regular spikes and it was a waste to up the instance size just to account for the spikes looking for renewals), however we never know how many domains might be added at any one time, so it's important to come up with the solution to speed things up as fast as possible.
I would recommend your company invest in an appropriate sponsorship if you're serving that many domains. We'll be able to help you better.
And yeah was looking at the sponsorship, to support even, just trying to clear it and making sure the budget is there, if not sooner at least later in the year, it's a startup so things are pretty tight with all the development and no money coming in yet (soon hopefully).
mholt
commented
1 month ago Gotcha, well thanks for filling me in!
And yeah was looking at the sponsorship, to support even, just trying to clear it and making sure the budget is there, if not sooner at least later in the year, it's a startup so things are pretty tight with all the development and no money coming in yet (soon hopefully).
Yeah sounds good -- I know how it goes! Happy to dive into your needs and infra more at that point.
Hello!
We're getting this error when trying to generate new certificates. We're using Caddy 2.4.2 and running in 2 servers behind a load balancer, we use DynamoDB to store the certificates.
Up until minutes ago we only used ZeroSSL as the issuer, but after seeing the error we thought it may be something on their side and decided to try with the new fallback functionality using Let's Encrypt. But we're getting the same error as with ZeroSSL, and we thought
context deadline exceededsounded like something from inside Caddy and not an error in the issuer.TLS config
tls { issuer zerossl blablablabla { email my@mail.com dir https://acme.zerossl.com/v2/DV90 eab blabla blablablablablablablablablablablablablablablabla } issuer acme { email my@mail.com } on_demand }All these logs are from our staging environment, which is identical to production and we could replicate the error there.
Full log, with the error
Aug 02 15:22:22 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627917742.2827234,"msg":"using provided configuration","config_file":"/etc/caddy/Caddyfile","config_adapter":""} Aug 02 15:22:22 custom-domains-staging-br-01 caddy[326595]: 2021/08/02 15:22:22 [WARNING] Unnecessary header_up ('X-Forwarded-Proto' field): the reverse proxy's default behavior is to pass headers to the upstream Aug 02 15:22:22 custom-domains-staging-br-01 caddy[326595]: 2021/08/02 15:22:22 [WARNING] Unnecessary header_up ('X-Forwarded-Proto' field): the reverse proxy's default behavior is to pass headers to the upstream Aug 02 15:22:22 custom-domains-staging-br-01 caddy[326595]: {"level":"warn","ts":1627917742.2882245,"msg":"input is not formatted with 'caddy fmt'","adapter":"caddyfile","file":"/etc/caddy/Caddyfile","line":2} Aug 02 15:22:22 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627917742.289781,"logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["127.0.0.1:2019","localhost:2019","[::1]:2019"]} Aug 02 15:22:22 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627917742.290084,"logger":"http","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} Aug 02 15:22:22 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627917742.2901125,"logger":"http","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} Aug 02 15:22:22 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627917742.290119,"logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"} Aug 02 15:22:22 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627917742.2903583,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc0002fe540"} Aug 02 15:22:22 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627917742.2908654,"logger":"tls","msg":"cleaning storage unit","description":"&{caddy_ssl_certificatesUPDATE: We started to be able to generate certificates while I was writing this issue. All the new certificates are being generated with Let's Encrypt after ZeroSSL fails.
We're not sure if this is indeed an error on ZeroSSL or if something else was also happening with Let's Encrypt, as this log suggests
Aug 02 15:30:15 custom-domains-staging-br-01 caddy[326595]: {"level":"error","ts":1627918215.7663093,"logger":"tls.obtain","msg":"will retry","error":"[catorce.publicala.me] Obtain: [catorce.publicala.me] creating new order: provisioning client: context deadline exceeded (ca=https://acme-v02.api.letsencrypt.org/directory)","attempt":1,"retrying_in":60,"elapsed":89.538869619,"max_duration":2592000}.Full log after error solved "itself"
Aug 02 15:36:24 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627918584.6788352,"logger":"tls.on_demand","msg":"obtaining new certificate","server_name":"catorce.publicala.me"} Aug 02 15:36:25 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627918585.4860163,"logger":"tls.obtain","msg":"acquiring lock","identifier":"catorce.publicala.me"} Aug 02 15:36:25 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627918585.7181144,"logger":"tls.obtain","msg":"lock acquired","identifier":"catorce.publicala.me"} Aug 02 15:36:26 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627918586.4122481,"logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["catorce.publicala.me"],"ca":"https://acme.zerossl.com/v2/DV90","account":"fgilio@publica.la"} Aug 02 15:36:26 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627918586.4122853,"logger":"tls.issuance.acme","msg":"done waiting on internal rate limiter","identifiers":["catorce.publicala.me"],"ca":"https://acme.zerossl.com/v2/DV90","account":"fgilio@publica.la"} Aug 02 15:36:27 custom-domains-staging-br-01 caddy[326595]: {"level":"error","ts":1627918587.2315016,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"catorce.publicala.me","issuer":"acme.zerossl.com-v2-DV90","error":"[catorce.publicala.me] creating new order: fetching new nonce from server: HTTP 504: (ca=https://acme.zerossl.com/v2/DV90)"} Aug 02 15:36:27 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627918587.4627676,"logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["catorce.publicala.me"],"ca":"https://acme-v02.api.letsencrypt.org/directory","account":"fgilio@publica.la"} Aug 02 15:36:27 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627918587.4628348,"logger":"tls.issuance.acme","msg":"done waiting on internal rate limiter","identifiers":["catorce.publicala.me"],"ca":"https://acme-v02.api.letsencrypt.org/directory","account":"fgilio@publica.la"} Aug 02 15:36:28 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627918588.7454534,"logger":"tls.issuance.acme.acme_client","msg":"trying to solve challenge","identifier":"catorce.publicala.me","challenge_type":"http-01","ca":"https://acme-v02.api.letsencrypt.org/directory"} Aug 02 15:36:32 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627918592.7008424,"logger":"tls.issuance.acme.acme_client","msg":"validations succeeded; finalizing order","order":"https://acme-v02.api.letsencrypt.org/acme/order/113805931/14027200930"} Aug 02 15:36:33 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627918593.4735258,"logger":"tls.issuance.acme.acme_client","msg":"successfully downloaded available certificate chains","count":2,"first_url":"https://acme-v02.api.letsencrypt.org/acme/cert/03e24093caca1e12dae2699a7ccc5578a9d7"} Aug 02 15:36:33 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627918593.8252475,"logger":"tls.obtain","msg":"certificate obtained successfully","identifier":"catorce.publicala.me"} Aug 02 15:36:33 custom-domains-staging-br-01 caddy[326595]: {"level":"info","ts":1627918593.8252823,"logger":"tls.obtain","msg":"releasing lock","identifier":"catorce.publicala.me"}EDIT
We're getting a similar error again, these logs are from our production environment: