Timeout waiting for DNS record propagation

[ieure]

Lego stopped renewing my certs, and I'm not sure what's wrong. This has been working fine for a year or more, but something broke around the Dec-Jan-Feb timeframe, and I'm not sure what's wrong or how to fix it. I'm using the current Docker image, ID 21b860c9de86, digest sha256:0f971c76b1a5b7857bf8a0a24e63ee2ff17f73c6c96df5d2ba16d1627c75e984. Weirdly, this does not match what Docker Hub shows for the latest tag, and searching Docker Hub for either the digest or SHA turns up nothing. Pulling doesn't seem to match what's on DH, either:

$ docker pull goacme/lego:latest
latest: Pulling from goacme/lego
Digest: sha256:0f971c76b1a5b7857bf8a0a24e63ee2ff17f73c6c96df5d2ba16d1627c75e984
Status: Image is up to date for goacme/lego:latest
docker.io/goacme/lego:latest

Anyway. This is the command I'm running:

lego --path /lego --accept-tos --email [email protected] --dns joker --domains 'lab.pins.atomized.org' --domains '*.lab.pins.atomized.org' renew

And my environment:

      - JOKER_DEBUG=true
      - JOKER_API_MODE=SVC
      - JOKER_USERNAME_FILE=/run/secrets/joker-username
      - JOKER_PASSWORD_FILE=/run/secrets/joker-password
      - DESIGNATE_POLLING_INTERVAL=60

This is its output:

2023/02/25 18:11:36 [INFO] [lab.pins.atomized.org] acme: Trying renewal with 3 hours remaining
2023/02/25 18:11:36 [INFO] renewal: random delay of 2m16.819556098s
2023/02/25 18:13:53 [INFO] [lab.pins.atomized.org, *.lab.pins.atomized.org, beta.tubular.atomized.org] acme: Obtaining bundled SAN certificate
2023/02/25 18:13:54 [INFO] [*.lab.pins.atomized.org] AuthURL: https://acme-v02.api.letsencrypt.org/acme/authz-v3/198980437317
2023/02/25 18:13:54 [INFO] [beta.tubular.atomized.org] AuthURL: https://acme-v02.api.letsencrypt.org/acme/authz-v3/206356649366
2023/02/25 18:13:54 [INFO] [lab.pins.atomized.org] AuthURL: https://acme-v02.api.letsencrypt.org/acme/authz-v3/206356649376
2023/02/25 18:13:54 [INFO] [beta.tubular.atomized.org] acme: authorization already valid; skipping challenge
2023/02/25 18:13:54 [INFO] [lab.pins.atomized.org] acme: Could not find solver for: tls-alpn-01
2023/02/25 18:13:54 [INFO] [lab.pins.atomized.org] acme: Could not find solver for: http-01
2023/02/25 18:13:54 [INFO] [lab.pins.atomized.org] acme: use dns-01 solver
2023/02/25 18:13:54 [INFO] [*.lab.pins.atomized.org] acme: use dns-01 solver
2023/02/25 18:13:54 [INFO] [lab.pins.atomized.org] acme: Preparing to solve DNS-01
2023/02/25 18:13:55 [INFO] [lab.pins.atomized.org] acme: Trying to solve DNS-01
2023/02/25 18:13:55 [INFO] [lab.pins.atomized.org] acme: Checking DNS record propagation using [127.0.0.11:53]
2023/02/25 18:13:57 [INFO] Wait for propagation [timeout: 2m0s, interval: 2s]
2023/02/25 18:13:57 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:13:59 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:02 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:04 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:06 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:08 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:10 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:12 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:15 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:17 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:19 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:21 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:23 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:25 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:27 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:30 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:32 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:34 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:36 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:38 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:41 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:43 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:45 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:47 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:49 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:51 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:53 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:56 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:14:58 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:00 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:02 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:04 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:06 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:08 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:11 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:13 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:15 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:17 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:19 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:21 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:23 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:26 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:28 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:30 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:32 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:34 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:36 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:39 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:41 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:43 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:45 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:47 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:49 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:51 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:54 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:56 [INFO] [lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:15:58 [INFO] [lab.pins.atomized.org] acme: Cleaning DNS-01 challenge
2023/02/25 18:15:59 [INFO] [*.lab.pins.atomized.org] acme: Preparing to solve DNS-01
2023/02/25 18:15:59 [INFO] [*.lab.pins.atomized.org] acme: Trying to solve DNS-01
2023/02/25 18:15:59 [INFO] [*.lab.pins.atomized.org] acme: Checking DNS record propagation using [127.0.0.11:53]
2023/02/25 18:16:01 [INFO] Wait for propagation [timeout: 2m0s, interval: 2s]
2023/02/25 18:16:01 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:03 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:05 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:07 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:09 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:12 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:14 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:16 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:18 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:20 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:22 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:24 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:27 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:29 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:31 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:33 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:35 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:38 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:40 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:42 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:44 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:46 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:48 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:51 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:53 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:55 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:57 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:16:59 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:01 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:03 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:06 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:08 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:10 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:12 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:14 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:17 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:19 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:21 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:23 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:25 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:27 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:30 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:32 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:34 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:36 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:38 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:40 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:42 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:45 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:47 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:49 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:51 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:53 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:56 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:17:58 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:18:00 [INFO] [*.lab.pins.atomized.org] acme: Waiting for DNS record propagation.
2023/02/25 18:18:02 [INFO] [*.lab.pins.atomized.org] acme: Cleaning DNS-01 challenge
2023/02/25 18:18:03 [INFO] retry due to: acme: error: 400 :: POST :: https://acme-v02.api.letsencrypt.org/acme/authz-v3/198980437317 :: urn:ietf:params:acme:error:badNonce :: JWS has an invalid anti-replay nonce: "15C9f3Pa5hbxAVXs0K_uMz6FKYxeewvpv4OUdR330-3iQmk"
2023/02/25 18:18:03 [INFO] Skipping deactivating of valid auth: https://acme-v02.api.letsencrypt.org/acme/authz-v3/198980437317
2023/02/25 18:18:03 [INFO] Deactivating auth: https://acme-v02.api.letsencrypt.org/acme/authz-v3/206356649366
2023/02/25 18:18:03 [INFO] Deactivating auth: https://acme-v02.api.letsencrypt.org/acme/authz-v3/206356649376
2023/02/25 18:18:03 error: one or more domains had a problem:
[*.lab.pins.atomized.org] time limit exceeded: last error: NS a.ns.joker.com. did not return the expected TXT record [fqdn: _acme-challenge.lab.pins.atomized.org., value: (redacted)]: 
[lab.pins.atomized.org] time limit exceeded: last error: NS a.ns.joker.com. did not return the expected TXT record [fqdn: _acme-challenge.lab.pins.atomized.org., value: (redacted)]: 
dox-frontend-letsencrypt-renew-1 exited with code 1

I can't switch to another challenge type, because DNS-01 is required to issue a wildcard cert.

I found some similar issues, but nothing quite like what I'm experiencing. One suggestion was to change the DNS resolvers, so I tried that:

lego --path /lego --accept-tos --email [email protected] --dns joker --domains 'lab.pins.atomized.org' --domains '*.lab.pins.atomized.org' --dns.resolvers=8.8.8.8 renew

This gives different output, but still fails:

2023/02/25 18:28:31 [INFO] [lab.pins.atomized.org] acme: Trying renewal with 2 hours remaining
2023/02/25 18:28:31 [INFO] renewal: random delay of 3m19.622320291s
2023/02/25 18:31:51 [INFO] [lab.pins.atomized.org, *.lab.pins.atomized.org, beta.tubular.atomized.org] acme: Obtaining bundled SAN certificate
2023/02/25 18:31:52 [INFO] [*.lab.pins.atomized.org] AuthURL: https://acme-v02.api.letsencrypt.org/acme/authz-v3/198980437317
2023/02/25 18:31:52 [INFO] [beta.tubular.atomized.org] AuthURL: https://acme-v02.api.letsencrypt.org/acme/authz-v3/206359588536
2023/02/25 18:31:52 [INFO] [lab.pins.atomized.org] AuthURL: https://acme-v02.api.letsencrypt.org/acme/authz-v3/206359588546
2023/02/25 18:31:52 [INFO] [beta.tubular.atomized.org] acme: authorization already valid; skipping challenge
2023/02/25 18:31:52 [INFO] [lab.pins.atomized.org] acme: Could not find solver for: tls-alpn-01
2023/02/25 18:31:52 [INFO] [lab.pins.atomized.org] acme: Could not find solver for: http-01
2023/02/25 18:31:52 [INFO] [lab.pins.atomized.org] acme: use dns-01 solver
2023/02/25 18:31:52 [INFO] [*.lab.pins.atomized.org] acme: use dns-01 solver
2023/02/25 18:31:52 [INFO] [lab.pins.atomized.org] acme: Preparing to solve DNS-01
2023/02/25 18:31:52 [INFO] [lab.pins.atomized.org] acme: Cleaning DNS-01 challenge
2023/02/25 18:31:52 [WARN] [lab.pins.atomized.org] acme: cleaning up failed: joker: unexpected response code 'REFUSED' for _acme-challenge.lab.pins.atomized.org. 
2023/02/25 18:31:52 [INFO] [*.lab.pins.atomized.org] acme: Preparing to solve DNS-01
2023/02/25 18:31:53 [INFO] [*.lab.pins.atomized.org] acme: Cleaning DNS-01 challenge
2023/02/25 18:31:53 [WARN] [*.lab.pins.atomized.org] acme: cleaning up failed: joker: unexpected response code 'REFUSED' for _acme-challenge.lab.pins.atomized.org. 
2023/02/25 18:31:53 [INFO] Skipping deactivating of valid auth: https://acme-v02.api.letsencrypt.org/acme/authz-v3/198980437317
2023/02/25 18:31:53 [INFO] Deactivating auth: https://acme-v02.api.letsencrypt.org/acme/authz-v3/206359588536
2023/02/25 18:31:53 [INFO] Deactivating auth: https://acme-v02.api.letsencrypt.org/acme/authz-v3/206359588546
2023/02/25 18:31:53 error: one or more domains had a problem:
[*.lab.pins.atomized.org] [*.lab.pins.atomized.org] acme: error presenting token: joker: unexpected response code 'REFUSED' for _acme-challenge.lab.pins.atomized.org.
[lab.pins.atomized.org] [lab.pins.atomized.org] acme: error presenting token: joker: unexpected response code 'REFUSED' for _acme-challenge.lab.pins.atomized.org.
dox-frontend-letsencrypt-renew-1 exited with code 1

I get the same issue using 1.1.1.1. I consistently get this when specifying --dns.resolvers; it never happens if I don't provide that option (but it doesn't work, either).

What can I do to troubleshoot this issue and get new certs?

[ieure]

I dug a bit more, it's very hard to figure out what Lego is doing, since it doesn't have any kind of debug logging facility.

Here's where Joker describes using Let's Encrypt.

I was able to successfully update my zone with curl:

curl -X POST https://svc.joker.com/nic/replace -d 'username=me&password=secret&zone=atomized.org&label=_test&type=TXT&value=the-TXT-content-to-insert'

Running dig immediately afterwards shows that it's working with minimal propagation delay:

$ dig -t TXT _test.atomized.org @a.ns.joker.com

; <<>> DiG 9.16.37-Debian <<>> -t TXT _test.atomized.org @a.ns.joker.com
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 52791
;; flags: qr aa rd; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; WARNING: recursion requested but not available

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;_test.atomized.org.		IN	TXT

;; ANSWER SECTION:
_test.atomized.org.	300	IN	TXT	"the-TXT-content-to-insert"

;; Query time: 204 msec
;; SERVER: 2a01:4f8:c0c:165b::1#53(2a01:4f8:c0c:165b::1)
;; WHEN: Sat Feb 25 13:50:04 PST 2023
;; MSG SIZE  rcvd: 85

So I know the underlying stuff is working. And it's immediately visible, so I don't think it's a timing issue. I'm at a loss to understand a) what exactly lego is doing and b) why it broke c) why specifying different dns.resolvers causes the Joker update to fail — they seem like orthogonal concerns.

[ieure]

Okay, I was able to figure this out.

I was asking for certs for lab.pins.atomized.org (and a wildcard of that). But pins.atomized.org was delegated to a nameserver that's only reachable on my LAN, so when LE tried to validate the challenge, it couldn't reach it and reported SERVFAIL.

And also, the DDNS update put the challenge response into a place where LE would never look, again, because of the delegation of the subdomain.

I removed the NS record which delegated it, ran lego again, and it worked fine.