Error cleaning up DNS challenge solver (with certmagic fix)

1. Output of caddy version:

v2.5.3-0.20220831011552-687a4b9e81c7 h1:by5h5TFif7dxcBLb+p76ktY88+Zxo4V/EOWYXK+elpQ=
(./xcaddy build master --with GitHub - caddy-dns/route53: Caddy module: dns.providers.route53)

2. How I run Caddy:

brew

a. System environment:

Mac, Brew

b. Command:

sudo caddy run

d. My complete Caddy config:

{
  "admin": { "listen": ":2020" },
  "apps": {
    "http": {
      "servers": {
        "srv0": {
          "listen": [":443"],
          "routes": [
            {
              "handle": [
                {
                  "handler": "subroute",
                  "routes": [
                    {
                      "handle": [
                        {
                          "handler": "vars",
                          "root": "/opt/homebrew/var/www/localhost"
                        },
                        { "handler": "file_server", "hide": ["./Caddyfile"] }
                      ]
                    }
                  ]
                }
              ],
              "match": [{ "host": ["*.localfounder.me"] }],
              "terminal": true
            },
            {
              "handle": [
                {
                  "handler": "subroute",
                  "routes": [
                    {
                      "handle": [
                        {
                          "handler": "reverse_proxy",
                          "upstreams": [{ "dial": "127.0.0.1:8090" }]
                        }
                      ]
                    }
                  ]
                }
              ],
              "match": [{ "host": ["*.localkinde.me"] }],
              "terminal": true
            },
            {
              "handle": [
                {
                  "handler": "subroute",
                  "routes": [
                    {
                      "handle": [
                        {
                          "handler": "reverse_proxy",
                          "upstreams": [{ "dial": "127.0.0.1:8090" }]
                        }
                      ]
                    }
                  ]
                }
              ],
              "match": [{ "host": ["beta-three.davebain.me"] }],
              "terminal": true
            }
          ],
          "tls_connection_policies": [
            {
              "certificate_selection": { "any_tag": ["cert0"] },
              "match": { "sni": ["*.localfounder.me"] }
            },
            {
              "certificate_selection": { "any_tag": ["cert1"] },
              "match": { "sni": ["*.localkinde.me"] }
            },
            {}
          ]
        }
      }
    },
    "tls": {
      "automation": {
        "policies": [
          {
            "issuers": [
              {
                "ca": "https://acme-v02.api.letsencrypt.org/directory",
                "module": "acme"
              }
            ],
            "subjects": ["*.localfounder.me", "*.localkinde.me"]
          },
          {
            "issuers": [
              {
                "ca": "https://acme-staging-v02.api.letsencrypt.org/directory",
                "challenges": {
                  "dns": {
                    "override_domain": "_acme-challenge.e8dfc814512412f151441790919c2b3e.au_1.localkinde.me",
                    "provider": {
                      "aws_profile": "default",
                      "max_retries": 10,
                      "name": "route53"
                    }
                  }
                },
                "module": "acme"
              }
            ],
            "subjects": ["beta-three.davebain.me"]
          }
        ]
      },
      "certificates": {
        "load_files": [
          {
            "certificate": "/etc/letsencrypt/live/localfounder.me/fullchain.pem",
            "key": "/etc/letsencrypt/live/localfounder.me/privkey.pem",
            "tags": ["cert0"]
          },
          {
            "certificate": "/etc/letsencrypt/live/localkinde.me/fullchain.pem",
            "key": "/etc/letsencrypt/live/localkinde.me/privkey.pem",
            "tags": ["cert1"]
          }
        ]
      }
    }
  }
}

Isolated config

In the above Iā€™m locally serving some two other domains (which already have local certs), these arenā€™t relevant to this issue, so hereā€™s a slimmed down version of the config, to the bits for the specific domain using the challenge:

{
  "admin": { "listen": ":2020" },
  "apps": {
    "http": {
      "servers": {
        "srv0": {
          "listen": [":443"],
          "routes": [
            {
              "handle": [
                {
                  "handler": "subroute",
                  "routes": [
                    {
                      "handle": [
                        {
                          "handler": "reverse_proxy",
                          "upstreams": [{ "dial": "127.0.0.1:8090" }]
                        }
                      ]
                    }
                  ]
                }
              ],
              "match": [{ "host": ["beta-four.davebain.me"] }],
              "terminal": true
            }
          ]
        }
      }
    },
    "tls": {
      "automation": {
        "policies": [
          {
            "issuers": [
              {
                "ca": "https://acme-staging-v02.api.letsencrypt.org/directory",
                "challenges": {
                  "dns": {
                    "override_domain": "_acme-challenge.1bd1831e999dc6409ea4820252d545e2.au_1.localkinde.me",
                    "provider": {
                      "aws_profile": "default",
                      "max_retries": 10,
                      "name": "route53"
                    }
                  }
                },
                "module": "acme"
              }
            ],
            "subjects": ["beta-four.davebain.me"]
          }
        ]
      }
    }
  }
}

3. The problem Iā€™m having:

The DNS challenge is being used, which does work and certs are issued however the DNS challenge is not being cleaned up. There was a fix for this on Use OverrideDomain when cleaning up DNS solver (#193) Ā· caddyserver/certmagic@23ca487 Ā· GitHub
So I used xcaddy to build a custom binary from the master branch, on build I can see itā€™s using certmagic version v0.16.3 so the fix is included.

4. Error messages and/or full log output:

2022/08/31 17:18:31.705 ERROR   tls.issuance.acme.acme_client   cleaning up solver      {"identifier": "beta-four.davebain.me", "challenge_type": "dns-01", "error": "no memory of presenting a DNS record for \"_acme-challenge.1bd1831e999dc6409ea4820252d545e2.au_1.localkinde.me\" (usually OK if presenting also failed)"}

5. What I already tried:

Building a custom binary with the fix.

6. Links to relevant resources:

Original discussion related to this:

The fix: Use OverrideDomain when cleaning up DNS solver (#193) Ā· caddyserver/certmagic@23ca487 Ā· GitHub

What are the full logs though? (Not just one line in isolation please)

Hi @matt, thanks for taking a look - hereā€™s the full log block that gets generated when I update the config via the api (I do a full config reload). Note itā€™s now ā€˜beta-threeā€™ as the lets encrypt doesnā€™t retry the dns challenge if itā€™s already succeeded previously. The two localx.me domains shouldnā€™t be relevant to this issue (I have local certs of these, all included in the full caddy config above).

2022/09/01 07:20:03.086 INFO    admin.api       received request        {"method": "POST", "host": "localhost:2020", "uri": "/load", "remote_ip": "::1", "remote_port": "50518", "headers": {"Accept-Encoding":["gzip"],"Cache-Control":["must-revalidate"],"Content-Length":["1818"],"Content-Type":["application/json; charset=UTF-8"],"User-Agent":["Go-http-client/1.1"]}}
2022/09/01 07:20:03.087 INFO    admin   admin endpoint started  {"address": ":2020", "enforce_origin": false, "origins": ["//:2020"]}
2022/09/01 07:20:03.087 WARN    admin   admin endpoint on open interface; host checking disabled        {"address": ":2020"}
2022/09/01 07:20:03.090 INFO    tls.cache.maintenance   started background certificate maintenance      {"cache": "0xc0004a4ee0"}
2022/09/01 07:20:03.092 INFO    http    skipping automatic certificate management because one or more matching certificates are already loaded  {"domain": "*.localfounder.me", "server_name": "srv0"}
2022/09/01 07:20:03.092 INFO    http    skipping automatic certificate management because one or more matching certificates are already loaded  {"domain": "*.localkinde.me", "server_name": "srv0"}
2022/09/01 07:20:03.092 INFO    http    enabling automatic HTTP->HTTPS redirects        {"server_name": "srv0"}
2022/09/01 07:20:03.094 INFO    http.log        server running  {"name": "remaining_auto_https_redirects", "protocols": ["h1", "h2", "h3"]}
2022/09/01 07:20:03.095 INFO    http    enabling HTTP/3 listener        {"addr": ":443"}
2022/09/01 07:20:03.095 INFO    http.log        server running  {"name": "srv0", "protocols": ["h1", "h2", "h3"]}
2022/09/01 07:20:03.095 INFO    http    enabling automatic TLS certificate management   {"domains": ["beta-three.davebain.me"]}
2022/09/01 07:20:03.098 INFO    tls.obtain      acquiring lock  {"identifier": "beta-three.davebain.me"}
2022/09/01 07:20:03.100 INFO    tls.cache.maintenance   stopped background certificate maintenance      {"cache": "0xc00044f8f0"}
2022/09/01 07:20:03.119 INFO    tls.obtain      lock acquired   {"identifier": "beta-three.davebain.me"}
2022/09/01 07:20:03.120 INFO    autosaved config (load with --resume flag)      {"file": "/Users/david/Library/Application Support/Caddy/autosave.json"}
2022/09/01 07:20:03.120 INFO    admin.api       load complete
2022/09/01 07:20:03.120 INFO    tls.issuance.acme       waiting on internal rate limiter        {"identifiers": ["beta-three.davebain.me"], "ca": "https://acme-staging-v02.api.letsencrypt.org/directory", "account": "caddy@zerossl.com"}
2022/09/01 07:20:03.121 INFO    tls.issuance.acme       done waiting on internal rate limiter   {"identifiers": ["beta-three.davebain.me"], "ca": "https://acme-staging-v02.api.letsencrypt.org/directory", "account": "caddy@zerossl.com"}
2022/09/01 07:20:03.131 INFO    admin   stopped previous server {"address": ":2020"}
2022/09/01 07:20:03.938 INFO    tls.issuance.acme.acme_client   trying to solve challenge       {"identifier": "beta-three.davebain.me", "challenge_type": "dns-01", "ca": "https://acme-staging-v02.api.letsencrypt.org/directory"}
2022/09/01 07:20:20.703 ERROR   tls.issuance.acme.acme_client   cleaning up solver      {"identifier": "beta-three.davebain.me", "challenge_type": "dns-01", "error": "no memory of presenting a DNS record for \"_acme-challenge.e8dfc814512412f151441790919c2b3e.au_1.localkinde.me\" (usually OK if presenting also failed)"}
2022/09/01 07:20:20.703 INFO    tls.issuance.acme.acme_client   authorization finalized {"identifier": "beta-three.davebain.me", "authz_status": "valid"}
2022/09/01 07:20:20.703 INFO    tls.issuance.acme.acme_client   validations succeeded; finalizing order {"order": "https://acme-staging-v02.api.letsencrypt.org/acme/order/63075564/3878390043"}
2022/09/01 07:20:21.110 INFO    tls.issuance.acme.acme_client   successfully downloaded available certificate chains    {"count": 1, "first_url": "https://acme-staging-v02.api.letsencrypt.org/acme/cert/fa0d406efc208c66d95025704e29ca78f6fd"}
2022/09/01 07:20:21.112 INFO    tls.obtain      certificate obtained successfully       {"identifier": "beta-three.davebain.me"}
2022/09/01 07:20:21.113 INFO    tls.obtain      releasing lock  {"identifier": "beta-three.davebain.me"}

Thanks, thatā€™s interesting. Are you doing a config reload at about this time? It looks like itā€™s finishing up a config reload, but I want to verify

Yes I generate the full config server side, then post that to the api load end point.

Ok. And did you confirm that the DNS TXT record still exists after the challenge completes successfully? Because I donā€™t see the TXT records anywhere:

$ dig beta-three.davebain.me

; <<>> DiG 9.18.1-1ubuntu1.1-Ubuntu <<>> beta-three.davebain.me
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 30253
;; flags: qr rd ra; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 65494
;; QUESTION SECTION:
;beta-three.davebain.me.		IN	A

;; ANSWER SECTION:
beta-three.davebain.me.	8600	IN	CNAME	davebain.localkinde.me.
davebain.localkinde.me.	300	IN	A	127.0.0.1

;; Query time: 28 msec
;; SERVER: 127.0.0.53#53(127.0.0.53) (UDP)
;; WHEN: Thu Sep 01 11:34:15 MDT 2022
;; MSG SIZE  rcvd: 101


$ dig davebain.localkinde.me

; <<>> DiG 9.18.1-1ubuntu1.1-Ubuntu <<>> davebain.localkinde.me
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 12391
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 65494
;; QUESTION SECTION:
;davebain.localkinde.me.		IN	A

;; ANSWER SECTION:
davebain.localkinde.me.	287	IN	A	127.0.0.1

;; Query time: 0 msec
;; SERVER: 127.0.0.53#53(127.0.0.53) (UDP)
;; WHEN: Thu Sep 01 11:34:28 MDT 2022
;; MSG SIZE  rcvd: 67

So in this case the error might be a red herring.

@matt your command is incorrect:

$ dig TXT _acme-challenge.beta-three.davebain.me

; <<>> DiG 9.16.8-Ubuntu <<>> TXT _acme-challenge.beta-three.davebain.me
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 46221
;; flags: qr rd ra; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 65494
;; QUESTION SECTION:
;_acme-challenge.beta-three.davebain.me.	IN TXT

;; ANSWER SECTION:
_acme-challenge.beta-three.davebain.me.	8600 IN	CNAME _acme-challenge.e8dfc814512412f151441790919c2b3e.au_1.localkinde.me.
_acme-challenge.e8dfc814512412f151441790919c2b3e.au_1.localkinde.me. 0 IN TXT "5xwzjQiR9Co3XdWfybgukcT8H0BNpnwUIuKNbzBlwM8"

;; Query time: 48 msec
;; SERVER: 127.0.0.53#53(127.0.0.53)
;; WHEN: Thu Sep 01 13:49:17 EDT 2022
;; MSG SIZE  rcvd: 202
1 Like

Thanks @francislavoie
Yes and the txt record still exists in route53 for localkinde.me where the challenge is delegated to:
_acme-challenge.e8dfc814512412f151441790919c2b3e.au_1.localkinde.me

1 Like

Wow, thanks.

@davebain What are in the logs for that domain name before the config reload?

Hi Matt, this the initial load logs:

2022/09/02 18:03:19.729 INFO    using adjacent Caddyfile
2022/09/02 18:03:19.733 INFO    admin   admin endpoint started  {"address": ":2020", "enforce_origin": false, "origins": ["//:2020"]}
2022/09/02 18:03:19.733 WARN    admin   admin endpoint on open interface; host checking disabled        {"address": ":2020"}
2022/09/02 18:03:19.734 INFO    tls.cache.maintenance   started background certificate maintenance      {"cache": "0xc0001f1260"}
2022/09/02 18:03:19.737 INFO    http    skipping automatic certificate management because one or more matching certificates are already loaded  {"domain": "*.localfounder.me", "server_name": "srv0"}
2022/09/02 18:03:19.737 INFO    http    skipping automatic certificate management because one or more matching certificates are already loaded  {"domain": "*.localkinde.me", "server_name": "srv0"}
2022/09/02 18:03:19.737 INFO    http    enabling automatic HTTP->HTTPS redirects        {"server_name": "srv0"}
2022/09/02 18:03:19.740 INFO    http    enabling HTTP/3 listener        {"addr": ":443"}
2022/09/02 18:03:19.740 INFO    tls     cleaning storage unit   {"description": "FileStorage:/Users/david/Library/Application Support/Caddy"}
2022/09/02 18:03:19.741 INFO    http.log        server running  {"name": "srv0", "protocols": ["h1", "h2", "h3"]}
2022/09/02 18:03:19.741 INFO    http.log        server running  {"name": "remaining_auto_https_redirects", "protocols": ["h1", "h2", "h3"]}
2022/09/02 18:03:19.741 INFO    autosaved config (load with --resume flag)      {"file": "/Users/david/Library/Application Support/Caddy/autosave.json"}
2022/09/02 18:03:19.741 INFO    serving initial configuration
2022/09/02 18:03:19.750 INFO    tls     finished cleaning storage units

At that stage, the config is based on the following caddyfile:

{
	acme_ca https://acme-staging-v02.api.letsencrypt.org/directory
	admin :2020
}

*.localfounder.me {
	root * /path/to/founder
	file_server
	tls /etc/letsencrypt/live/localfounder.me/fullchain.pem /etc/letsencrypt/live/localfounder.me/privkey.pem
}

*.localkinde.me {
	reverse_proxy 127.0.0.1:8090
	tls /etc/letsencrypt/live/localkinde.me/fullchain.pem /etc/letsencrypt/live/localkinde.me/privkey.pem
}

Within my application, a custom domain is added, at which point I rebuild the config with the new domain (example above), and push this to caddy via the api. At which point the logs I attached earlier are triggered.

Thank you! Is it reproducible? i.e. does this happen every time you do something like this, or did it just happen once?

I am trying to determine the characteristics of the bug so I can diagnose it.

Hi @matt this happens every time, Iā€™ve always had to manually delete the dns record

@matt I think Iā€™ve found the issue.

I downloaded certmagic and created a custom build with the following:

sudo ./xcaddy build master --with github.com/caddyserver/certmagic@v0.17.0=../certmagic --with github.com/caddy-dns/route53 --output ./caddy

I then added some error logging to step through the process, including adding the following in the solvers.go file getDNSPresentMemory function:

	for _, mem := range s.txtRecords[dnsName] {
		log.Printf("[CHALLENGE] GETDNSPRESENTMEMORY: %v = %v", mem.rec.Value, keyAuth)
		if mem.rec.Value == keyAuth {
			log.Printf("[CHALLENGE] MATCH SET MEMORY")
			memory = mem
			break
		} else {
			log.Printf("[CHALLENGE] NO MATCH")
		}
	}

In the logs I see the following:

2022/09/05 11:06:38.713 INFO    [CHALLENGE] GETDNSPRESENTMEMORY: "wCb6R-yh31DXyD-GR6lgOWahWmUrckWf_2UG4GIt-oo" = wCb6R-yh31DXyD-GR6lgOWahWmUrckWf_2UG4GIt-oo
2022/09/05 11:06:38.713 INFO    [CHALLENGE] NO MATCH

So it seems that the mem.rec.Value is wrapped with inverted commas and failing to match.

If I update it to the following:

if strings.Trim(mem.rec.Value, "\"") == keyAuth {

ā€¦it matches and then works as expected with the DNS challenge being removed. I suspect there is a more elegant solution with the type / data handling further up the chain but that seems to be the fundamental issue.

As a side note, Iā€™d like to highlight a related issue. I simplified my requirements in this thread, my full requirement is to request two certificates for the domain, one for x.davebain.me, and another wildcard certificate for *.x.davebain.me (this is for environments, e.g. staging.x.davebain.me).

So in my caddy json the hosts and subjects are as follows (charlie-three as an example):

"match": [
                {
                  "host": [
                    "charlie-three.davebain.me",
                    "*.charlie-three.davebain.me"
                  ]
                }
              ],

This results in the following output logs (with my custom error logging). To summarise, it appears to be doing the challenge for both certs at the same time, but these rely on the same acme dns challenge record, so one of them fails to match in the same getDNSPresentMemory function. As you can see this self-resolves on the second attempt, but this could be handled better.

2022/09/05 10:58:37.483 INFO    http    enabling automatic TLS certificate management   {"domains": ["charlie-three.davebain.me", "*.charlie-three.davebain.me"]}
2022/09/05 10:58:37.485 INFO    tls.obtain      acquiring lock  {"identifier": "*.charlie-three.davebain.me"}
2022/09/05 10:58:37.485 INFO    tls.obtain      acquiring lock  {"identifier": "charlie-three.davebain.me"}
2022/09/05 10:58:37.486 INFO    tls.cache.maintenance   stopped background certificate maintenance      {"cache": "0xc0004156c0"}
2022/09/05 10:58:37.504 INFO    tls.obtain      lock acquired   {"identifier": "*.charlie-three.davebain.me"}
2022/09/05 10:58:37.504 INFO    tls.obtain      obtaining certificate   {"identifier": "*.charlie-three.davebain.me"}
2022/09/05 10:58:37.505 INFO    tls.issuance.acme       waiting on internal rate limiter        {"identifiers": ["*.charlie-three.davebain.me"], "ca": "https://acme-staging-v02.api.letsencrypt.org/directory", "account": "caddy@zerossl.com"}
2022/09/05 10:58:37.505 INFO    tls.issuance.acme       done waiting on internal rate limiter   {"identifiers": ["*.charlie-three.davebain.me"], "ca": "https://acme-staging-v02.api.letsencrypt.org/directory", "account": "caddy@zerossl.com"}
2022/09/05 10:58:37.524 INFO    autosaved config (load with --resume flag)      {"file": "/Users/david/Library/Application Support/Caddy/autosave.json"}
2022/09/05 10:58:37.524 INFO    admin.api       load complete
2022/09/05 10:58:37.523 INFO    tls.obtain      lock acquired   {"identifier": "charlie-three.davebain.me"}
2022/09/05 10:58:37.525 INFO    tls.obtain      obtaining certificate   {"identifier": "charlie-three.davebain.me"}
2022/09/05 10:58:37.525 INFO    tls.issuance.acme       waiting on internal rate limiter        {"identifiers": ["charlie-three.davebain.me"], "ca": "https://acme-staging-v02.api.letsencrypt.org/directory", "account": "caddy@zerossl.com"}
2022/09/05 10:58:37.525 INFO    tls.issuance.acme       done waiting on internal rate limiter   {"identifiers": ["charlie-three.davebain.me"], "ca": "https://acme-staging-v02.api.letsencrypt.org/directory", "account": "caddy@zerossl.com"}
2022/09/05 10:58:37.552 INFO    admin   stopped previous server {"address": ":2020"}
2022/09/05 10:58:38.334 INFO    tls.issuance.acme.acme_client   trying to solve challenge       {"identifier": "*.charlie-three.davebain.me", "challenge_type": "dns-01", "ca": "https://acme-staging-v02.api.letsencrypt.org/directory"}
2022/09/05 10:58:38.334 INFO    [CHALLENGE] PRESENT ORIGINAL: _acme-challenge.charlie-three.davebain.me
2022/09/05 10:58:38.334 INFO    [CHALLENGE] PRESENT OVERRIDDEN: _acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain.localkinde.me
2022/09/05 10:58:38.395 INFO    tls.issuance.acme.acme_client   trying to solve challenge       {"identifier": "charlie-three.davebain.me", "challenge_type": "dns-01", "ca": "https://acme-staging-v02.api.letsencrypt.org/directory"}
2022/09/05 10:58:38.395 INFO    [CHALLENGE] PRESENT ORIGINAL: _acme-challenge.charlie-three.davebain.me
2022/09/05 10:58:38.395 INFO    [CHALLENGE] PRESENT OVERRIDDEN: _acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain.localkinde.me
2022/09/05 10:58:40.868 INFO    [CHALLENGE] WAIT ORIGINAL: _acme-challenge.charlie-three.davebain.me
2022/09/05 10:58:40.868 INFO    [CHALLENGE] WAIT OVERRIDEN: _acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain.localkinde.me
2022/09/05 10:58:41.175 INFO    [CHALLENGE] CLEANUP ORIGINAL: _acme-challenge.charlie-three.davebain.me
2022/09/05 10:58:41.175 INFO    [CHALLENGE] CLEANUP OVERRIDEN: _acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain.localkinde.me
2022/09/05 10:58:41.175 INFO    [CHALLENGE] GETDNSPRESENTMEMORY: hds5OhEZzwmOuD-Z0Gf2LTraAPITUhh1K3D5nnVNw3A = tn023N8CVMdXe6gOYqVXGiomeAwTmCYIetdIfN8h9Cw
2022/09/05 10:58:41.175 INFO    [CHALLENGE] NO MATCH
2022/09/05 10:58:41.175 INFO    [CHALLENGE] MEMORY.REC = {    0s 0}
2022/09/05 10:58:41.175 ERROR   tls.issuance.acme.acme_client   cleaning up solver      {"identifier": "charlie-three.davebain.me", "challenge_type": "dns-01", "error": "no memory of presenting a DNS record for \"_acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain.localkinde.me\" (usually OK if presenting also failed)"}
2022/09/05 10:58:41.328 ERROR   tls.obtain      could not get certificate from issuer   {"identifier": "charlie-three.davebain.me", "issuer": "acme-staging-v02.api.letsencrypt.org-directory", "error": "[charlie-three.davebain.me] solving challenges: presenting for challenge: adding temporary record for zone \"localkinde.me.\": InvalidChangeBatch: operation error Route 53: ChangeResourceRecordSets, https response error StatusCode: 400, RequestID: 6765f251-c654-4b20-8b51-2e198842675f, InvalidChangeBatch: [Tried to create resource record set [name='_acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain.localkinde.me.', type='TXT'] but it already exists] (order=https://acme-staging-v02.api.letsencrypt.org/acme/order/63075564/3934673133) (ca=https://acme-staging-v02.api.letsencrypt.org/directory)"}
2022/09/05 10:58:41.328 ERROR   tls.obtain      will retry      {"error": "[charlie-three.davebain.me] Obtain: [charlie-three.davebain.me] solving challenges: presenting for challenge: adding temporary record for zone \"localkinde.me.\": InvalidChangeBatch: operation error Route 53: ChangeResourceRecordSets, https response error StatusCode: 400, RequestID: 6765f251-c654-4b20-8b51-2e198842675f, InvalidChangeBatch: [Tried to create resource record set [name='_acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain.localkinde.me.', type='TXT'] but it already exists] (order=https://acme-staging-v02.api.letsencrypt.org/acme/order/63075564/3934673133) (ca=https://acme-staging-v02.api.letsencrypt.org/directory)", "attempt": 1, "retrying_in": 60, "elapsed": 3.803503083, "max_duration": 2592000}
2022/09/05 10:58:56.823 INFO    [CHALLENGE] CLEANUP ORIGINAL: _acme-challenge.charlie-three.davebain.me
2022/09/05 10:58:56.823 INFO    [CHALLENGE] CLEANUP OVERRIDEN: _acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain.localkinde.me
2022/09/05 10:58:56.823 INFO    [CHALLENGE] GETDNSPRESENTMEMORY: hds5OhEZzwmOuD-Z0Gf2LTraAPITUhh1K3D5nnVNw3A = hds5OhEZzwmOuD-Z0Gf2LTraAPITUhh1K3D5nnVNw3A
2022/09/05 10:58:56.823 INFO    [CHALLENGE] MATCH SET MEMORY
2022/09/05 10:58:56.823 INFO    [CHALLENGE] MEMORY.REC = { TXT _acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain "hds5OhEZzwmOuD-Z0Gf2LTraAPITUhh1K3D5nnVNw3A" 0s 0}
2022/09/05 10:58:57.585 INFO    tls.issuance.acme.acme_client   authorization finalized {"identifier": "*.charlie-three.davebain.me", "authz_status": "valid"}
2022/09/05 10:58:57.585 INFO    tls.issuance.acme.acme_client   validations succeeded; finalizing order {"order": "https://acme-staging-v02.api.letsencrypt.org/acme/order/63075564/3934673123"}
2022/09/05 10:58:58.029 INFO    tls.issuance.acme.acme_client   successfully downloaded available certificate chains    {"count": 1, "first_url": "https://acme-staging-v02.api.letsencrypt.org/acme/cert/fa11e34f0a23aa475d2a15f0619a2e5397e1"}
2022/09/05 10:58:58.032 INFO    tls.obtain      certificate obtained successfully       {"identifier": "*.charlie-three.davebain.me"}
2022/09/05 10:58:58.032 INFO    tls.obtain      releasing lock  {"identifier": "*.charlie-three.davebain.me"}
2022/09/05 10:59:41.330 INFO    tls.obtain      obtaining certificate   {"identifier": "charlie-three.davebain.me"}
2022/09/05 10:59:41.800 INFO    tls.issuance.acme.acme_client   trying to solve challenge       {"identifier": "charlie-three.davebain.me", "challenge_type": "dns-01", "ca": "https://acme-staging-v02.api.letsencrypt.org/directory"}
2022/09/05 10:59:41.800 INFO    [CHALLENGE] PRESENT ORIGINAL: _acme-challenge.charlie-three.davebain.me
2022/09/05 10:59:41.800 INFO    [CHALLENGE] PRESENT OVERRIDDEN: _acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain.localkinde.me
2022/09/05 10:59:42.786 INFO    [CHALLENGE] WAIT ORIGINAL: _acme-challenge.charlie-three.davebain.me
2022/09/05 10:59:42.786 INFO    [CHALLENGE] WAIT OVERRIDEN: _acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain.localkinde.me
2022/09/05 10:59:56.117 INFO    [CHALLENGE] CLEANUP ORIGINAL: _acme-challenge.charlie-three.davebain.me
2022/09/05 10:59:56.117 INFO    [CHALLENGE] CLEANUP OVERRIDEN: _acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain.localkinde.me
2022/09/05 10:59:56.117 INFO    [CHALLENGE] GETDNSPRESENTMEMORY: hds5OhEZzwmOuD-Z0Gf2LTraAPITUhh1K3D5nnVNw3A = MDs3mW3BkyPpoc75jcGD8m1vFQAaF_gJrZvi2C2s5Z8
2022/09/05 10:59:56.117 INFO    [CHALLENGE] NO MATCH
2022/09/05 10:59:56.117 INFO    [CHALLENGE] GETDNSPRESENTMEMORY: MDs3mW3BkyPpoc75jcGD8m1vFQAaF_gJrZvi2C2s5Z8 = MDs3mW3BkyPpoc75jcGD8m1vFQAaF_gJrZvi2C2s5Z8
2022/09/05 10:59:56.117 INFO    [CHALLENGE] MATCH SET MEMORY
2022/09/05 10:59:56.117 INFO    [CHALLENGE] MEMORY.REC = { TXT _acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain "MDs3mW3BkyPpoc75jcGD8m1vFQAaF_gJrZvi2C2s5Z8" 0s 0}
2022/09/05 10:59:56.922 INFO    tls.issuance.acme.acme_client   authorization finalized {"identifier": "charlie-three.davebain.me", "authz_status": "valid"}
2022/09/05 10:59:56.923 INFO    tls.issuance.acme.acme_client   validations succeeded; finalizing order {"order": "https://acme-staging-v02.api.letsencrypt.org/acme/order/63075564/3934682333"}
2022/09/05 10:59:57.487 INFO    tls.issuance.acme.acme_client   successfully downloaded available certificate chains    {"count": 1, "first_url": "https://acme-staging-v02.api.letsencrypt.org/acme/cert/fa00a4080e2803886cd834879aa3191e25bd"}
2022/09/05 10:59:57.491 INFO    tls.obtain      certificate obtained successfully       {"identifier": "charlie-three.davebain.me"}
2022/09/05 10:59:57.492 INFO    tls.obtain      releasing lock  {"identifier": "charlie-three.davebain.me"}
2 Likes

:sweat_smile: those are called ā€œdouble quotesā€. A single quote is ' and a double quote is "

Thatā€™s interesting though. Maybe the route53 plugin is adding the double quotes somehow?

That might be a bug with the route53 plugin. Itā€™s okay to have two DNS TXT records at the same time. CertMagic asks the plugin to append the record, so it should only add one, not replace existing ones. Maybe Route53ā€™s API doesnā€™t allow for that though. I dunno.

Ah! Excellent debugging work @davebain ā€“ you are right!

So yes, as Francis suggests, that value with the extra quotes around it comes from the route53 plugin. DNS zone files require quotes around TXT values with spaces, and it seems like the route53 API and/or the plugin is not removing those quotes. The quotes are just syntax for parsing zone files; not part of the actual TXT record value. From a quick google search:

The content of a DNS TXT type record is always displayed with double quotes, but those quotes are not part of the record content.

I opened an issue:

Seconding what Francis said, itā€™s valid for there to be multiple TXT records with the same name. This error:

Tried to create resource record set [name=ā€˜_acme-challenge.3eb03e95e4dadd3b7e50d19fd2456c85.davebain.localkinde.me.ā€™, type=ā€˜TXTā€™] but it already exists

comes from Route53, and should be reported to Amazon instead.

CertMagic is properly expecting multiple TXT records with the same name:

And Iā€™ve tested it as such and it does work.

Seems that Route53 could use some conformance to spec.

Thank you for the investigation! I hope this is helpful.

Edit: Also opened an issue to route53 plugin to support multiple TXT records, this is a Route53 limitation though so donā€™t get your hopes up: Hack to support multiple TXT records Ā· Issue #17 Ā· libdns/route53 Ā· GitHub

Brilliant, Iā€™ll keep an eye out for those fixes and run with a custom build for the short term. Thanks for all your help @matt

1 Like

Hey @davebain, Iā€™ve created a PR to fix these issues here. I would appreciate it if you could give it a try and confirm it solves the problem before merging and making a new release. Thank you!

2 Likes

This topic was automatically closed after 30 days. New replies are no longer allowed.