search

caddy-dns / desec

deSEC module for Caddy
MIT License
14 stars 3 forks source link

"could not get certificate from issuer" #1

Closed fabricionaweb closed 1 year ago

fabricionaweb commented 1 year ago

I was using deprecated-lego with same settings. Trying to migrate now.

My Caddyfile is:

{
    debug
}

*.fabricio.dev {
    tls {
        dns desec {
            token {$DESEC_TOKEN}
        }
    }

    @vaultwarden host vaultwarden.fabricio.dev
    reverse_proxy @vaultwarden 127.0.0.1:8000
}

Im running with envfile, but I tried just strings, its not related. The _acme-challenge TXT is being update, something seems to block the read. I guess is something related to the wildcard...

Without wildcard I could generate cert during the 2rd attempt when Caddy tries using zerossl. But I hope I need the wildcard for my subdomains...

The full logs with debug enable:

2023/05/11 14:21:15.246 INFO    using provided configuration    {"config_file": "/var/lib/caddy/Caddyfile", "config_adapter": ""}
2023/05/11 14:21:15.248 INFO    admin   admin endpoint started  {"address": "localhost:2019", "enforce_origin": false, "origins": ["//localhost:2019", "//[::1]:2019", "//127.0.0.1:2019"]}
2023/05/11 14:21:15.248 INFO    http    server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS {"server_name": "srv0", "https_port": 443}
2023/05/11 14:21:15.248 INFO    http    enabling automatic HTTP->HTTPS redirects    {"server_name": "srv0"}
2023/05/11 14:21:15.248 INFO    tls.cache.maintenance   started background certificate maintenance  {"cache": "0xc000470cb0"}
2023/05/11 14:21:15.249 INFO    http    enabling HTTP/3 listener    {"addr": ":443"}
2023/05/11 14:21:15.249 INFO    tls cleaning storage unit   {"description": "FileStorage:/root/.local/share/caddy"}
2023/05/11 14:21:15.249 INFO    tls finished cleaning storage units
2023/05/11 14:21:15.249 DEBUG   http    starting server loop    {"address": "[::]:443", "tls": true, "http3": true}
2023/05/11 14:21:15.249 INFO    http.log    server running  {"name": "srv0", "protocols": ["h1", "h2", "h3"]}
2023/05/11 14:21:15.249 DEBUG   http    starting server loop    {"address": "[::]:80", "tls": false, "http3": false}
2023/05/11 14:21:15.249 INFO    http.log    server running  {"name": "remaining_auto_https_redirects", "protocols": ["h1", "h2", "h3"]}
2023/05/11 14:21:15.249 INFO    http    enabling automatic TLS certificate management   {"domains": ["*.fabricio.dev"]}
2023/05/11 14:21:15.249 INFO    autosaved config (load with --resume flag)  {"file": "/root/.config/caddy/autosave.json"}
2023/05/11 14:21:15.249 INFO    serving initial configuration
2023/05/11 14:21:15.249 INFO    tls.obtain  acquiring lock  {"identifier": "*.fabricio.dev"}
2023/05/11 14:21:15.249 INFO    tls.obtain  lock acquired   {"identifier": "*.fabricio.dev"}
2023/05/11 14:21:15.249 INFO    tls.obtain  obtaining certificate   {"identifier": "*.fabricio.dev"}
2023/05/11 14:21:15.249 DEBUG   events  event   {"name": "cert_obtaining", "id": "24e6afca-5d0b-41a8-83a2-ddc2347c0ef8", "origin": "tls", "data": {"identifier":"*.fabricio.dev"}}
2023/05/11 14:21:15.250 DEBUG   tls.obtain  trying issuer 1/2   {"issuer": "acme-v02.api.letsencrypt.org-directory"}
2023/05/11 14:21:15.250 INFO    http    waiting on internal rate limiter    {"identifiers": ["*.fabricio.dev"], "ca": "https://acme-v02.api.letsencrypt.org/directory", "account": "hi@fabricio.dev"}
2023/05/11 14:21:15.250 INFO    http    done waiting on internal rate limiter   {"identifiers": ["*.fabricio.dev"], "ca": "https://acme-v02.api.letsencrypt.org/directory", "account": "hi@fabricio.dev"}
2023/05/11 14:21:15.772 DEBUG   http.acme_client    http request    {"method": "GET", "url": "https://acme-v02.api.letsencrypt.org/directory", "headers": {"User-Agent":["Caddy/2.6.4 CertMagic acmez (linux; amd64)"]}, "response_headers": {"Cache-Control":["public, max-age=0, no-cache"],"Content-Length":["756"],"Content-Type":["application/json"],"Date":["Thu, 11 May 2023 14:21:15 GMT"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]}, "status_code": 200}
2023/05/11 14:21:15.938 DEBUG   http.acme_client    http request    {"method": "HEAD", "url": "https://acme-v02.api.letsencrypt.org/acme/new-nonce", "headers": {"User-Agent":["Caddy/2.6.4 CertMagic acmez (linux; amd64)"]}, "response_headers": {"Cache-Control":["public, max-age=0, no-cache"],"Date":["Thu, 11 May 2023 14:21:15 GMT"],"Link":["<https://acme-v02.api.letsencrypt.org/directory>;rel=\"index\""],"Replay-Nonce":["5CA2AvS-mx2abPoLi9nTo0tIS1EUZ8i988mwwaqYru5-fZQ"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]}, "status_code": 200}
2023/05/11 14:21:16.230 DEBUG   http.acme_client    http request    {"method": "POST", "url": "https://acme-v02.api.letsencrypt.org/acme/new-order", "headers": {"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.6.4 CertMagic acmez (linux; amd64)"]}, "response_headers": {"Boulder-Requester":["1104608907"],"Cache-Control":["public, max-age=0, no-cache"],"Content-Length":["340"],"Content-Type":["application/json"],"Date":["Thu, 11 May 2023 14:21:16 GMT"],"Link":["<https://acme-v02.api.letsencrypt.org/directory>;rel=\"index\""],"Location":["https://acme-v02.api.letsencrypt.org/acme/order/1104608907/181527821707"],"Replay-Nonce":["371CU-WAYQyVH3V8Js5Jo0zFAEyWOcIrJf2sDtO67zPJNCg"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]}, "status_code": 201}
2023/05/11 14:21:16.397 DEBUG   http.acme_client    http request    {"method": "POST", "url": "https://acme-v02.api.letsencrypt.org/acme/authz-v3/226879846697", "headers": {"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.6.4 CertMagic acmez (linux; amd64)"]}, "response_headers": {"Boulder-Requester":["1104608907"],"Cache-Control":["public, max-age=0, no-cache"],"Content-Length":["386"],"Content-Type":["application/json"],"Date":["Thu, 11 May 2023 14:21:16 GMT"],"Link":["<https://acme-v02.api.letsencrypt.org/directory>;rel=\"index\""],"Replay-Nonce":["371CBoX_Cqllt9maF-d9tZST7Z5DpSD4grW7fB30bVBf0Gg"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]}, "status_code": 200}
2023/05/11 14:21:16.397 INFO    http.acme_client    trying to solve challenge   {"identifier": "*.fabricio.dev", "challenge_type": "dns-01", "ca": "https://acme-v02.api.letsencrypt.org/directory"}
2023/05/11 14:21:16.883 DEBUG   http.acme_client    waiting for solver before continuing    {"identifier": "*.fabricio.dev", "challenge_type": "dns-01"}
2023/05/11 14:22:46.719 DEBUG   events  event   {"name": "tls_get_certificate", "id": "072a07d3-80d8-4224-a104-916269988a39", "origin": "tls", "data": {"client_hello":{"CipherSuites":[4865,4866,4867],"ServerName":"vaultwarden.fabricio.dev","SupportedCurves":[29,23,24],"SupportedPoints":null,"SignatureSchemes":[1027,2052,1025,1283,2053,1281,2054,1537,513],"SupportedProtos":["h3"],"SupportedVersions":[772],"Conn":{}}}}
2023/05/11 14:22:46.727 DEBUG   events  event   {"name": "tls_get_certificate", "id": "e3bd013b-b2d3-458b-9a5a-61d12bee7ec9", "origin": "tls", "data": {"client_hello":{"CipherSuites":[2570,4865,4866,4867,49195,49199,49196,49200,52393,52392,49171,49172,156,157,47,53],"ServerName":"vaultwarden.fabricio.dev","SupportedCurves":[47802,29,23,24],"SupportedPoints":"AA==","SignatureSchemes":[1027,2052,1025,1283,2053,1281,2054,1537],"SupportedProtos":["h2","http/1.1"],"SupportedVersions":[35466,772,771],"Conn":{}}}}
2023/05/11 14:22:46.727 DEBUG   http.stdlib http: TLS handshake error from 10.0.5.5:62714: no certificate available for 'vaultwarden.fabricio.dev'
2023/05/11 14:22:46.731 DEBUG   events  event   {"name": "tls_get_certificate", "id": "a37171d2-a184-4083-897c-ed3cb5c761b4", "origin": "tls", "data": {"client_hello":{"CipherSuites":[31354,4865,4866,4867,49195,49199,49196,49200,52393,52392,49171,49172,156,157,47,53],"ServerName":"vaultwarden.fabricio.dev","SupportedCurves":[27242,29,23,24],"SupportedPoints":"AA==","SignatureSchemes":[1027,2052,1025,1283,2053,1281,2054,1537,513],"SupportedProtos":["h2","http/1.1"],"SupportedVersions":[35466,772,771],"Conn":{}}}}
2023/05/11 14:22:46.731 DEBUG   http.stdlib http: TLS handshake error from 10.0.5.5:62715: no certificate available for 'vaultwarden.fabricio.dev'
2023/05/11 14:23:17.564 DEBUG   http.acme_client    done waiting for solver {"identifier": "*.fabricio.dev", "challenge_type": "dns-01"}
2023/05/11 14:23:18.152 DEBUG   http.acme_client    http request    {"method": "POST", "url": "https://acme-v02.api.letsencrypt.org/acme/authz-v3/226879846697", "headers": {"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.6.4 CertMagic acmez (linux; amd64)"]}, "response_headers": {"Boulder-Requester":["1104608907"],"Cache-Control":["public, max-age=0, no-cache"],"Content-Length":["390"],"Content-Type":["application/json"],"Date":["Thu, 11 May 2023 14:23:18 GMT"],"Link":["<https://acme-v02.api.letsencrypt.org/directory>;rel=\"index\""],"Replay-Nonce":["371CkOZU43l5qYk6LNLXf4HfBlu4XiVjoq1qbaLLs_PiEZM"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]}, "status_code": 200}
2023/05/11 14:23:18.152 ERROR   tls.obtain  could not get certificate from issuer   {"identifier": "*.fabricio.dev", "issuer": "acme-v02.api.letsencrypt.org-directory", "error": "[*.fabricio.dev] solving challenges: waiting for solver certmagic.solverWrapper to be ready: timed out waiting for record to fully propagate; verify DNS provider configuration is correct - last error: <nil> (order=https://acme-v02.api.letsencrypt.org/acme/order/1104608907/181527821707) (ca=https://acme-v02.api.letsencrypt.org/directory)"}
2023/05/11 14:23:18.152 DEBUG   tls.obtain  trying issuer 2/2   {"issuer": "acme.zerossl.com-v2-DV90"}
2023/05/11 14:23:18.152 INFO    http    waiting on internal rate limiter    {"identifiers": ["*.fabricio.dev"], "ca": "https://acme.zerossl.com/v2/DV90", "account": "hi@fabricio.dev"}
2023/05/11 14:23:18.152 INFO    http    done waiting on internal rate limiter   {"identifiers": ["*.fabricio.dev"], "ca": "https://acme.zerossl.com/v2/DV90", "account": "hi@fabricio.dev"}
2023/05/11 14:23:18.592 DEBUG   http.acme_client    http request    {"method": "GET", "url": "https://acme.zerossl.com/v2/DV90", "headers": {"User-Agent":["Caddy/2.6.4 CertMagic acmez (linux; amd64)"]}, "response_headers": {"Access-Control-Allow-Origin":["*"],"Content-Length":["645"],"Content-Type":["application/json"],"Date":["Thu, 11 May 2023 14:23:18 GMT"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15724800; includeSubDomains"]}, "status_code": 200}
2023/05/11 14:23:18.718 DEBUG   http.acme_client    http request    {"method": "HEAD", "url": "https://acme.zerossl.com/v2/DV90/newNonce", "headers": {"User-Agent":["Caddy/2.6.4 CertMagic acmez (linux; amd64)"]}, "response_headers": {"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=0, no-cache, no-store"],"Content-Type":["application/octet-stream"],"Date":["Thu, 11 May 2023 14:23:18 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["5M5Ad90yOYD6toTQAh61M0yWTwfYF0vAR9Iu0Tl7ypA"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15724800; includeSubDomains"]}, "status_code": 200}
2023/05/11 14:23:18.887 DEBUG   http.acme_client    http request    {"method": "POST", "url": "https://acme.zerossl.com/v2/DV90/newOrder", "headers": {"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.6.4 CertMagic acmez (linux; amd64)"]}, "response_headers": {"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=0, no-cache, no-store"],"Content-Length":["276"],"Content-Type":["application/json"],"Date":["Thu, 11 May 2023 14:23:18 GMT"],"Location":["https://acme.zerossl.com/v2/DV90/order/-Xb5eMXj8UHNMwa81YLqfw"],"Replay-Nonce":["BrxTP_H4rOOySHCHqHmyzbDsigMXGuN0gW2ODV-sai0"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15724800; includeSubDomains"]}, "status_code": 201}
2023/05/11 14:23:19.024 DEBUG   http.acme_client    http request    {"method": "POST", "url": "https://acme.zerossl.com/v2/DV90/authz/G3GfUXp_LYpBPGEUIa3RFQ", "headers": {"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.6.4 CertMagic acmez (linux; amd64)"]}, "response_headers": {"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=0, no-cache, no-store"],"Content-Length":["296"],"Content-Type":["application/json"],"Date":["Thu, 11 May 2023 14:23:19 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["F3TvsJGNurs4gDgCh0tzlnLcQndifUB4xm0LV3n_-do"],"Retry-After":["5"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15724800; includeSubDomains"]}, "status_code": 200}
2023/05/11 14:23:19.024 INFO    http.acme_client    trying to solve challenge   {"identifier": "*.fabricio.dev", "challenge_type": "dns-01", "ca": "https://acme.zerossl.com/v2/DV90"}
2023/05/11 14:23:19.332 DEBUG   http.acme_client    waiting for solver before continuing    {"identifier": "*.fabricio.dev", "challenge_type": "dns-01"}
2023/05/11 14:25:16.338 DEBUG   events  event   {"name": "tls_get_certificate", "id": "2def196f-f590-42df-858f-937184a023f4", "origin": "tls", "data": {"client_hello":{"CipherSuites":[4865,4866,4867],"ServerName":"vaultwarden.fabricio.dev","SupportedCurves":[29,23,24],"SupportedPoints":null,"SignatureSchemes":[1027,2052,1025,1283,2053,1281,2054,1537,513],"SupportedProtos":["h3"],"SupportedVersions":[772],"Conn":{}}}}
2023/05/11 14:25:16.348 DEBUG   events  event   {"name": "tls_get_certificate", "id": "aa6dee77-5963-4f40-9e11-ee95b1d62540", "origin": "tls", "data": {"client_hello":{"CipherSuites":[2570,4865,4866,4867,49195,49199,49196,49200,52393,52392,49171,49172,156,157,47,53],"ServerName":"vaultwarden.fabricio.dev","SupportedCurves":[31354,29,23,24],"SupportedPoints":"AA==","SignatureSchemes":[1027,2052,1025,1283,2053,1281,2054,1537],"SupportedProtos":["h2","http/1.1"],"SupportedVersions":[43690,772,771],"Conn":{}}}}
2023/05/11 14:25:16.348 DEBUG   http.stdlib http: TLS handshake error from 10.0.5.5:63333: no certificate available for 'vaultwarden.fabricio.dev'
2023/05/11 14:25:16.354 DEBUG   events  event   {"name": "tls_get_certificate", "id": "c4b977b3-aeab-40e6-b012-0219482ff4fd", "origin": "tls", "data": {"client_hello":{"CipherSuites":[31354,4865,4866,4867,49195,49199,49196,49200,52393,52392,49171,49172,156,157,47,53],"ServerName":"vaultwarden.fabricio.dev","SupportedCurves":[51914,29,23,24],"SupportedPoints":"AA==","SignatureSchemes":[1027,2052,1025,1283,2053,1281,2054,1537,513],"SupportedProtos":["h2","http/1.1"],"SupportedVersions":[60138,772,771],"Conn":{}}}}
2023/05/11 14:25:16.354 DEBUG   http.stdlib http: TLS handshake error from 10.0.5.5:63334: no certificate available for 'vaultwarden.fabricio.dev'
2023/05/11 14:25:20.013 DEBUG   http.acme_client    done waiting for solver {"identifier": "*.fabricio.dev", "challenge_type": "dns-01"}
2023/05/11 14:25:20.713 DEBUG   http.acme_client    http request    {"method": "POST", "url": "https://acme.zerossl.com/v2/DV90/authz/G3GfUXp_LYpBPGEUIa3RFQ", "headers": {"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.6.4 CertMagic acmez (linux; amd64)"]}, "response_headers": {"Access-Control-Allow-Origin":["*"],"Cache-Control":["max-age=0, no-cache, no-store"],"Content-Length":["140"],"Content-Type":["application/json"],"Date":["Thu, 11 May 2023 14:25:20 GMT"],"Link":["<https://acme.zerossl.com/v2/DV90>;rel=\"index\""],"Replay-Nonce":["JcbvcbNGMhGC3GdJev5j9PKYk-cCYdxGXWYR2744Piw"],"Retry-After":["86400"],"Server":["nginx"],"Strict-Transport-Security":["max-age=15724800; includeSubDomains"]}, "status_code": 200}
2023/05/11 14:25:20.713 ERROR   tls.obtain  could not get certificate from issuer   {"identifier": "*.fabricio.dev", "issuer": "acme.zerossl.com-v2-DV90", "error": "[*.fabricio.dev] solving challenges: waiting for solver certmagic.solverWrapper to be ready: timed out waiting for record to fully propagate; verify DNS provider configuration is correct - last error: <nil> (order=https://acme.zerossl.com/v2/DV90/order/-Xb5eMXj8UHNMwa81YLqfw) (ca=https://acme.zerossl.com/v2/DV90)"}
2023/05/11 14:25:20.713 DEBUG   events  event   {"name": "cert_failed", "id": "b80fd27a-3469-49b6-bc27-702434f2fdf9", "origin": "tls", "data": {"error":{},"identifier":"*.fabricio.dev","issuers":["acme-v02.api.letsencrypt.org-directory","acme.zerossl.com-v2-DV90"],"renewal":false}}
2023/05/11 14:25:20.713 ERROR   tls.obtain  will retry  {"error": "[*.fabricio.dev] Obtain: [*.fabricio.dev] solving challenges: waiting for solver certmagic.solverWrapper to be ready: timed out waiting for record to fully propagate; verify DNS provider configuration is correct - last error: <nil> (order=https://acme.zerossl.com/v2/DV90/order/-Xb5eMXj8UHNMwa81YLqfw) (ca=https://acme.zerossl.com/v2/DV90)", "attempt": 1, "retrying_in": 60, "elapsed": 245.464081822, "max_duration": 2592000}
znkr commented 1 year ago

I tried reproducing this and at first I thought I could reproduce it, but the problem resolved itself while I was looking into it. I don't know exactly what is going on here, but my hypothesis is that it's due to negative DNS caching. Every DNS resolver may cache NXDOMAIN (DNS equivalent to 404 - not found) for a time and will answer sucessive queries with NXDOMAIN. IIUC, the time negative queries are cached is defined by the authority section in an NXDOMAIN response.

dig +all +multiline _acme.challenge.fabricio.dev TXT @ns1.desec.io

; <<>> DiG 9.10.6 <<>> +all +multiline _acme.challenge.fabricio.dev TXT @ns1.desec.io
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 6794
;; flags: qr aa rd; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1
;; WARNING: recursion requested but not available

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;_acme.challenge.fabricio.dev. IN TXT

;; AUTHORITY SECTION:
fabricio.dev.       300 IN SOA get.desec.io. get.desec.io. (
                2023053981 ; serial
                86400      ; refresh (1 day)
                3600       ; retry (1 hour)
                2419200    ; expire (4 weeks)
                3600       ; minimum (1 hour)
                )

;; Query time: 47 msec
;; SERVER: 2607:f740:e633:deec::2#53(2607:f740:e633:deec::2)
;; WHEN: Thu May 11 21:22:24 CEST 2023
;; MSG SIZE  rcvd: 105

There are two numbers here that are of interest. 300 is the TTL and 3600 is the minimum TTL. The minimum of both is the negative caching time. That is, NXDOMAIN responses are cached for 5 minutes.

If it happens that the update via the deSEC API takes longer to propagate to DNS and validation starts before it has propagated, it's possible that a NXDOMAIN response is generated that delays everything by 5 minutes due to negative DNS caching.

That's all just speculation though. I suggest to let it keep running for a bit longer and see if it resolves itself after a couple of minutes. Maybe that works for you too.

fabricionaweb commented 1 year ago

I need to say, really sorry but I could not understand much! hahahahah 🙈

But ok yes, I get that I need to let it running for longer, lets see.

Many thanks!

znkr commented 1 year ago

Sorry for not explaining this well. What I wanted to say is that this is probably a problem somewhere in the interaction between the various systems involved in the ACME protocol. The part that I implemented and that caddy-dns/desec is responsible for is creating the record for desec.io. IIUC, that part works.

Problems in the interaction between systems are notoriously difficult to debug. Let me know if letting it run for longer helps. If it does help, a caching issue is the likely reason you are experiencing this issue. If it does not help, I can't really help until I can reproduce the issue.

There are two more things that may help. You can specify a propagation_delay and a propagation timeout in the Caddyfile. I suggest to try the following:

    tls {
        dns desec {
            token {$DESEC_TOKEN}
        }
                propagation_delay 1m
                propagation_timeout 5m
    }

This will make is less likely to run into the timeout you were seeing before.

fabricionaweb commented 1 year ago

I have applied the propagation value as suggested and I left it there running for hours, and it was not working, but yet I was thinking it could be cache - there or here.

And... It is working now! 🎉 I think it took 3h or so, maybe I've done many requests or something...

I really appreciate the work and the time you have spent with this little issue. Really thank you very much! It is working.

znkr commented 1 year ago

I am glad it's finally working. It definitely should not take this long though. If you are running into the issue again, I would probably try increasing the propagation timeout to 15 minutes. Maybe also increase the propagation delay.