DNS challenge TXT record not being removed

[BDaddyG]

Hello

Just started working with Caddy, and with the Cloudflare plugin.

I was able to get the setup correct in that: the _acme-challenge TXT record is created, and a SSL cert is obtained.

But the plugin is not able to remove the _acme-challenge TXT record.

The log reports:

{"level":"error","ts":1635957602.852264,"logger":"tls.issuance.acme.acme_client","msg":"cleaning up solver","identifier":"*.mysite.org","challenge_type":"dns-01","error":"deleting temporary record for zone mysite.org.: Delete \"https://api.cloudflare.com/client/v4/zones/<long number>/dns_records/<different long number>": context canceled"}

I've verified that the API Token used is set to:

• Zone:Zone:Read
• Zone:DNS:Edit

which should be OK, since the challenge record was created, right?

Any pointer as to where to look?

Specs: custom build of Caddy v2.4.5 with the Cloudflare DNS plugin downloaded from the Caddy site. Ubuntu 20.04 Server Caddy installed from the PPA, then the caddy executable overwritten with the custom build Caddy running as a service

Thanks!

[mholt]

How can we reproduce this behavior?

[BDaddyG]

Is there a way to capture debug info from the plugin? (I already have DEBUG in the global section of my Caddyfile)

If I delete the currently downloaded certificate and restart Caddy, will it download a new certificate so we can then look over the logs?

[mholt]

Is there a way to capture debug info from the plugin? (I already have DEBUG in the global section of my Caddyfile)

Hm, I don't think we emit debug logs in this plugin currently (because of how simple the code is and the fact that most info that is needed comes back as errors). But the most helpful logs would be the ones that come before the 1 log line you posted here.

If I delete the currently downloaded certificate and restart Caddy, will it download a new certificate so we can then look over the logs?

Yes, but make sure to switch to your CA's staging endpoint (if there is one) first, otherwise you'll get rate limited quickly.

Logs are good, but even better is how can we reproduce the problem?

[Sailboat265]

+1 agree to

How can we reproduce this behavior?

@BDaddyG I tried to replicate your issue. Everything seems to work fine.

Also, by looking closely at the Cloudflare audit log, I can see that the "acme-challenge TXT record" is created and then deleted as expected.

Not sure how yours didn't

[BDaddyG]

@Sailboat265

Here is the complete log with the error (I had stopped Caddy after I saw it had obtained a cert):

Nov  3 16:39:45 caddy-rp systemd[1]: Starting Caddy...
Nov  3 16:39:45 caddy-rp caddy[17248]: caddy.HomeDir=/var/lib/caddy
Nov  3 16:39:45 caddy-rp caddy[17248]: caddy.AppDataDir=/var/lib/caddy/.local/share/caddy
Nov  3 16:39:45 caddy-rp caddy[17248]: caddy.AppConfigDir=/var/lib/caddy/.config/caddy
Nov  3 16:39:45 caddy-rp caddy[17248]: caddy.ConfigAutosavePath=/var/lib/caddy/.config/caddy/autosave.json
Nov  3 16:39:45 caddy-rp caddy[17248]: caddy.Version=v2.4.5 h1:P1mRs6V2cMcagSPn+NWpD+OEYUYLIf6ecOa48cFGeUg=
Nov  3 16:39:45 caddy-rp caddy[17248]: runtime.GOOS=linux
Nov  3 16:39:45 caddy-rp caddy[17248]: runtime.GOARCH=amd64
Nov  3 16:39:45 caddy-rp caddy[17248]: runtime.Compiler=gc
Nov  3 16:39:45 caddy-rp caddy[17248]: runtime.NumCPU=2
Nov  3 16:39:45 caddy-rp caddy[17248]: runtime.GOMAXPROCS=2
Nov  3 16:39:45 caddy-rp caddy[17248]: runtime.Version=go1.17
Nov  3 16:39:45 caddy-rp caddy[17248]: os.Getwd=/
Nov  3 16:39:45 caddy-rp caddy[17248]: LANG=en_US.UTF-8
Nov  3 16:39:45 caddy-rp caddy[17248]: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin
Nov  3 16:39:45 caddy-rp caddy[17248]: NOTIFY_SOCKET=/run/systemd/notify
Nov  3 16:39:45 caddy-rp caddy[17248]: HOME=/var/lib/caddy
Nov  3 16:39:45 caddy-rp caddy[17248]: LOGNAME=caddy
Nov  3 16:39:45 caddy-rp caddy[17248]: USER=caddy
Nov  3 16:39:45 caddy-rp caddy[17248]: INVOCATION_ID=a2b69adaddda4cf2ac9b3d496108d767
Nov  3 16:39:45 caddy-rp caddy[17248]: JOURNAL_STREAM=9:206621
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.6389291,"msg":"using provided configuration","config_file":"/etc/caddy/Caddyfile","config_adapter":""}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"warn","ts":1635957585.6403484,"msg":"input is not formatted with 'caddy fmt'","adapter":"caddyfile","file":"/etc/caddy/Caddyfile","line":52}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.6418576,"logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["[::1]:2019","127.0.0.1:2019","localhost:2019"]}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.6421099,"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}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.642129,"logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.6421146,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc0002b8b60"}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.642514,"logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/var/lib/caddy/.local/share/caddy"}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.6426191,"logger":"tls","msg":"finished cleaning storage units"}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"debug","ts":1635957585.6431668,"logger":"http","msg":"starting server loop","address":"[::]:443","http3":false,"tls":true}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"debug","ts":1635957585.64321,"logger":"http","msg":"starting server loop","address":"[::]:80","http3":false,"tls":false}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.6432168,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["*.mysite.org"]}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.64379,"logger":"tls.obtain","msg":"acquiring lock","identifier":"*.mysite.org"}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.6465728,"logger":"tls.obtain","msg":"lock acquired","identifier":"*.mysite.org"}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.647043,"msg":"autosaved config (load with --resume flag)","file":"/var/lib/caddy/.config/caddy/autosave.json"}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.6470866,"msg":"serving initial configuration"}
Nov  3 16:39:45 caddy-rp systemd[1]: Started Caddy.
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"debug","ts":1635957585.6482928,"logger":"tls.obtain","msg":"trying issuer 1/2","issuer":"acme-staging-v02.api.letsencrypt.org-directory"}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.6486478,"logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["*.mysite.org"],"ca":"https://acme-staging-v02.api.letsencrypt.org/directory","account":"myemail@mysite.org"}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"info","ts":1635957585.648782,"logger":"tls.issuance.acme","msg":"done waiting on internal rate limiter","identifiers":["*.mysite.org"],"ca":"https://acme-staging-v02.api.letsencrypt.org/directory","account":"myemail@mysite.org"}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"debug","ts":1635957585.8576636,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"GET","url":"https://acme-staging-v02.api.letsencrypt.org/directory","headers":{"User-Agent":["Caddy/2.4.5 CertMagic acmez (linux; amd64)"]},"response_headers":{"Cache-Control":["public, max-age=0, no-cache"],"Content-Length":["822"],"Content-Type":["application/json"],"Date":["Wed, 03 Nov 2021 16:39:45 GMT"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]},"status_code":200}
Nov  3 16:39:45 caddy-rp caddy[17248]: {"level":"debug","ts":1635957585.9121146,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"HEAD","url":"https://acme-staging-v02.api.letsencrypt.org/acme/new-nonce","headers":{"User-Agent":["Caddy/2.4.5 CertMagic acmez (linux; amd64)"]},"response_headers":{"Cache-Control":["public, max-age=0, no-cache"],"Date":["Wed, 03 Nov 2021 16:39:45 GMT"],"Link":["<https://acme-staging-v02.api.letsencrypt.org/directory>;rel=\"index\""],"Replay-Nonce":["0001fGLxsQAE4e7AplJikV5ZnzxTv3v49NGjjyM7WOjF8ss"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]},"status_code":200}
Nov  3 16:39:46 caddy-rp caddy[17248]: {"level":"debug","ts":1635957586.4510608,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme-staging-v02.api.letsencrypt.org/acme/new-order","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.5 CertMagic acmez (linux; amd64)"]},"response_headers":{"Boulder-Requester":["32147148"],"Cache-Control":["public, max-age=0, no-cache"],"Content-Length":["345"],"Content-Type":["application/json"],"Date":["Wed, 03 Nov 2021 16:39:46 GMT"],"Link":["<https://acme-staging-v02.api.letsencrypt.org/directory>;rel=\"index\""],"Location":["https://acme-staging-v02.api.letsencrypt.org/acme/order/32147148/923754638"],"Replay-Nonce":["0002LXjnECO4WQIPKhigZe1w0sbxP2mUJ2NNxHNtSBVv-vE"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]},"status_code":201}
Nov  3 16:39:46 caddy-rp caddy[17248]: {"level":"debug","ts":1635957586.5084858,"logger":"tls.issuance.acme.acme_client","msg":"http request","method":"POST","url":"https://acme-staging-v02.api.letsencrypt.org/acme/authz-v3/849857268","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.4.5 CertMagic acmez (linux; amd64)"]},"response_headers":{"Boulder-Requester":["32147148"],"Cache-Control":["public, max-age=0, no-cache"],"Content-Length":["388"],"Content-Type":["application/json"],"Date":["Wed, 03 Nov 2021 16:39:46 GMT"],"Link":["<https://acme-staging-v02.api.letsencrypt.org/directory>;rel=\"index\""],"Replay-Nonce":["0002z6eiAed6WnnSMq9h1iCvluoWFZyBlMKRg51eyjXO2Sc"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]},"status_code":200}
Nov  3 16:39:46 caddy-rp caddy[17248]: {"level":"info","ts":1635957586.5086987,"logger":"tls.issuance.acme.acme_client","msg":"trying to solve challenge","identifier":"*.mysite.org","challenge_type":"dns-01","ca":"https://acme-staging-v02.api.letsencrypt.org/directory"}
Nov  3 16:40:02 caddy-rp systemd[1]: Stopping Caddy...
Nov  3 16:40:02 caddy-rp caddy[17248]: {"level":"info","ts":1635957602.8479714,"msg":"shutting down apps, then terminating","signal":"SIGTERM"}
Nov  3 16:40:02 caddy-rp caddy[17248]: {"level":"warn","ts":1635957602.8483791,"msg":"exiting; byeee!! 👋","signal":"SIGTERM"}
Nov  3 16:40:02 caddy-rp caddy[17248]: {"level":"info","ts":1635957602.851774,"logger":"tls.cache.maintenance","msg":"stopped background certificate maintenance","cache":"0xc0002b8b60"}
Nov  3 16:40:02 caddy-rp caddy[17248]: {"level":"error","ts":1635957602.852264,"logger":"tls.issuance.acme.acme_client","msg":"cleaning up solver","identifier":"*.mysite.org","challenge_type":"dns-01","error":"deleting temporary record for zone mysite.org.: Delete \"https://api.cloudflare.com/client/v4/zones/<long number>/dns_records/<different long number>": context canceled"}
Nov  3 16:40:02 caddy-rp caddy[17248]: {"level":"warn","ts":1635957602.852986,"logger":"tls.issuance.acme.acme_client","msg":"HTTP request failed; retrying","url":"https://acme-staging-v02.api.letsencrypt.org/acme/authz-v3/849857268","error":"performing request: Post \"https://acme-staging-v02.api.letsencrypt.org/acme/authz-v3/849857268\": context canceled"}
Nov  3 16:40:02 caddy-rp caddy[17248]: {"level":"error","ts":1635957602.8531506,"logger":"tls.issuance.acme.acme_client","msg":"deactivating authorization","identifier":"*.mysite.org","authz":"https://acme-staging-v02.api.letsencrypt.org/acme/authz-v3/849857268","error":"attempt 1: https://acme-staging-v02.api.letsencrypt.org/acme/authz-v3/849857268: context canceled"}
Nov  3 16:40:02 caddy-rp caddy[17248]: {"level":"error","ts":1635957602.853291,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"*.mysite.org","issuer":"acme-staging-v02.api.letsencrypt.org-directory","error":"[*.mysite.org] solving challenges: waiting for solver certmagic.solverWrapper to be ready: context canceled (order=https://acme-staging-v02.api.letsencrypt.org/acme/order/32147148/923754638) (ca=https://acme-staging-v02.api.letsencrypt.org/directory)"}
Nov  3 16:40:02 caddy-rp caddy[17248]: {"level":"debug","ts":1635957602.853408,"logger":"tls.obtain","msg":"trying issuer 2/2","issuer":"acme-staging-v02.api.letsencrypt.org-directory"}
Nov  3 16:40:02 caddy-rp caddy[17248]: {"level":"info","ts":1635957602.853764,"logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["*.mysite.org"],"ca":"https://acme-staging-v02.api.letsencrypt.org/directory","account":"myemail@mysite.org"}
Nov  3 16:40:02 caddy-rp caddy[17248]: {"level":"error","ts":1635957602.8539233,"logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"*.mysite.org","issuer":"acme-staging-v02.api.letsencrypt.org-directory","error":"context canceled"}
Nov  3 16:40:02 caddy-rp caddy[17248]: {"level":"info","ts":1635957602.8540788,"logger":"tls.obtain","msg":"releasing lock","identifier":"*.mysite.org"}
Nov  3 16:40:02 caddy-rp caddy[17248]: {"level":"info","ts":1635957602.8538988,"logger":"admin","msg":"stopped previous server","address":"tcp/localhost:2019"}
Nov  3 16:40:02 caddy-rp caddy[17248]: {"level":"info","ts":1635957602.8543653,"msg":"shutdown complete","signal":"SIGTERM","exit_code":0}
Nov  3 16:40:02 caddy-rp systemd[1]: caddy.service: Succeeded.
Nov  3 16:40:02 caddy-rp systemd[1]: Stopped Caddy.

And here is my Caddyfile (just to be sure I've not messed something up there)

# The Caddyfile is an easy way to configure your Caddy web server.
#
# Unless the file starts with a global options block, the first
# uncommented line is always the address of your site.
#
# To use your own domain name (with automatic HTTPS), first make
# sure your domain's A/AAAA DNS records are properly pointed to
# this machine's public IP, then replace ":80" below with your
# domain name.
{
    debug
    email myemail@mysite.org
    acme_ca https://acme-staging-v02.api.letsencrypt.org/directory
}

(dnsauth) {
    tls {
        dns cloudflare myAPIToken
                resolvers 1.1.1.1
    }
    log {
        output file /var/log/caddy/access.log
    }
}

*.mysite.org {
    import dnsauth

    @jellyfin host jellyfin.mysite.org
    handle @jellyfin {
        reverse_proxy jellyfin.mysite.org:8096
    }

    #@limesurvey host limesurvey.mysite.local
    @limesurvey host limesurvey.mysite.org
    handle @limesurvey {
        reverse_proxy 172.16.0.11:80
    }

    # Set this path to your site's directory.
    ##root * /usr/share/caddy

    # Enable the static file server.
    ##file_server

    # Another common task is to set up a reverse proxy:
    # reverse_proxy localhost:8080

    # Or serve a PHP site through php-fpm:
    # php_fastcgi localhost:9000

# Refer to the Caddy docs for more information:
# https://caddyserver.com/docs/caddyfile
}

I'll delete the current certificate and have Caddy get a new one today and see what happens. Maybe it was a glitch at Cloudflare's end?

Thanks for looking at the issue!

[BDaddyG]

I was able to delete the current certificate and have Caddy get a new one... and the TXT record at Cloudflare was removed.

I tried a couple of times and things worked correctly each time.

So, it appears it was a glitch on Cloudflare's end.

Thanks for your time and thoughts about what could be going on.

[mholt]

Context canceled usually means something took too long, so if the network or the remote service was delayed signifcantly, that could cause the problem, and those are usually intermittent.

Although, looking at your logs, it looks like Caddy was stopped right then, which is another thing that can cancel the context prematurely.

(I had stopped Caddy after I saw it had obtained a cert)

Aye, that would do it, since it was still cleaning up. Just leave Caddy running, it will keep the cert renewed.

[radokristof]

Hi! It seems that for me is the same. TXT records are not being removed (I can't confirm more than I see multiple TXT records for the same domain). I just switched from systemd to docker, but anyway how it should detect if a TXT record should be removed? Does it remove all TXT records for a given domain when renewing certificate? What happens with domains which are removed from caddy? Does caddy keep a track of deleted domains?

[mholt]

It's provider-dependent, but in the case of Cloudflare's API, DNS records have an associated ID, and we use IDs to remove the specific record that was created. In order to retrieve the ID, though, we first "get" the records from the API that match the type and name.