Failed ACME challenge

Ray_Johnson · March 30, 2021, 4:01pm

1. Caddy version (`caddy version`):

I’m now on a custom build of Caddy since the update of CertMagic broke the route53 DNS provider. So I’m using a commit just before the update of CertMagic. Plus a cherry-pick of the commit that adds support for regsub of the request path.

2. How I run Caddy:

In docker containers with docker-compose.

a. System environment:

Linux, AWS.

b. Command:

paste command here

c. Service/unit/compose file:

paste full file contents here

d. My complete Caddyfile or JSON config:

<sorry - have to redact or I'm told I'm above limit and can not post.  Just showing the tls config part as that is what is most relevant.>

  tls:
    certificates:
      automate:
        - '*.buster2.dev.tilia-inc.com'
        - accounts-customer.secondlife.buster2.dev.tilia-inc.com
    automation:
      policies:
        - subjects:
            - '*.buster2.dev.tilia-inc.com'
            - accounts-customer.secondlife.buster2.dev.tilia-inc.com
          issuers:
            - module: acme
              # When testing is this test CA
              # ca: https://acme-staging-v02.api.letsencrypt.org/directory
              challenges:
                dns:
                  provider:
                    name: route53
        # - subjects:
        #     - 'login.sansar.com'
        #   issuers:
        #     - module: internal

3. The problem I’m having:

No certs are generated.

4. Error messages and/or full log output:

{"level":"info","ts":1617061046.1941125,"msg":"using provided configuration","config_file":"/config.yml","config_adapter":"yaml"}
{"level":"info","ts":1617061047.5776064,"logger":"admin","msg":"admin endpoint started","address":"tcp/0.0.0.0:2019","enforce_origin":false,"origins":["0.0.0.0:2019"]}
{"level":"warn","ts":1617061047.5799992,"logger":"admin","msg":"admin endpoint on open interface; host checking disabled","address":"tcp/0.0.0.0:2019"}
{"level":"info","ts":1617061047.7188063,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc000a3a690"}
{"level":"info","ts":1617061048.1508665,"logger":"http.handlers.s3proxy","msg":"S3 proxy initialized for bucket: buster2.dev.tilia-inc.com"}
{"level":"info","ts":1617061048.2719026,"logger":"tls.obtain","msg":"acquiring lock","identifier":"accounts-customer.secondlife.buster2.dev.tilia-inc.com"}
{"level":"info","ts":1617061048.3138146,"logger":"tls","msg":"cleaned up storage units"}
{"level":"info","ts":1617061048.3161294,"msg":"autosaved config","file":"/config/caddy/autosave.json"}
{"level":"info","ts":1617061048.3213265,"msg":"serving initial configuration"}
{"level":"info","ts":1617061048.3162355,"logger":"tls.obtain","msg":"acquiring lock","identifier":"*.buster2.dev.tilia-inc.com"}
2021/03/29 23:37:28 [INFO][FileStorage:/data/caddy] Lock for 'issue_cert_accounts-customer.secondlife.buster2.dev.tilia-inc.com' is stale (created: 2021-03-29 21:34:05.438277242 +0000 UTC, last update: 2021-03-29 23:34:41.370002598 +0000 UTC); removing then retrying: /data/caddy/locks/issue_cert_accounts-customer.secondlife.buster2.dev.tilia-inc.com.lock
2021/03/29 23:37:28 [INFO][FileStorage:/data/caddy] Lock for 'issue_cert_*.buster2.dev.tilia-inc.com' is stale (created: 2021-03-29 21:34:05.438917161 +0000 UTC, last update: 2021-03-29 23:34:41.372075167 +0000 UTC); removing then retrying: /data/caddy/locks/issue_cert_wildcard_.buster2.dev.tilia-inc.com.lock
{"level":"info","ts":1617061048.3732955,"logger":"tls.obtain","msg":"lock acquired","identifier":"accounts-customer.secondlife.buster2.dev.tilia-inc.com"}
{"level":"info","ts":1617061048.448075,"logger":"tls.obtain","msg":"lock acquired","identifier":"*.buster2.dev.tilia-inc.com"}
{"level":"info","ts":1617061048.7034988,"logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["accounts-customer.secondlife.buster2.dev.tilia-inc.com"]}
{"level":"info","ts":1617061048.7035446,"logger":"tls.issuance.acme","msg":"done waiting on internal rate limiter","identifiers":["accounts-customer.secondlife.buster2.dev.tilia-inc.com"]}
{"level":"info","ts":1617061048.7470336,"logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["*.buster2.dev.tilia-inc.com"]}
{"level":"info","ts":1617061048.7631578,"logger":"tls.issuance.acme","msg":"done waiting on internal rate limiter","identifiers":["*.buster2.dev.tilia-inc.com"]}
{"level":"info","ts":1617061053.2578948,"logger":"tls.issuance.acme.acme_client","msg":"trying to solve challenge","identifier":"accounts-customer.secondlife.buster2.dev.tilia-inc.com","challenge_type":"dns-01","ca":"https://acme-v02.api.letsencrypt.org/directory"}
{"level":"info","ts":1617061053.2692575,"logger":"tls.issuance.acme.acme_client","msg":"trying to solve challenge","identifier":"*.buster2.dev.tilia-inc.com","challenge_type":"dns-01","ca":"https://acme-v02.api.letsencrypt.org/directory"}
{"level":"error","ts":1617061057.1700072,"logger":"tls.issuance.acme.acme_client","msg":"cleaning up solver","identifier":"accounts-customer.secondlife.buster2.dev.tilia-inc.com","challenge_type":"dns-01","error":"no memory of presenting a DNS record for accounts-customer.secondlife.buster2.dev.tilia-inc.com (probably OK if presenting failed)"}
{"level":"error","ts":1617061057.2524803,"logger":"tls.issuance.acme.acme_client","msg":"cleaning up solver","identifier":"*.buster2.dev.tilia-inc.com","challenge_type":"dns-01","error":"no memory of presenting a DNS record for buster2.dev.tilia-inc.com (probably OK if presenting failed)"}
{"level":"error","ts":1617061057.2639065,"logger":"tls.obtain","msg":"will retry","error":"[accounts-customer.secondlife.buster2.dev.tilia-inc.com] Obtain: [accounts-customer.secondlife.buster2.dev.tilia-inc.com] solving challenges: presenting for challenge: adding temporary record for zone dev.tilia-inc.com.: InvalidChangeBatch: InvalidChangeBatch: [Tried to create resource record set [name='_acme-challenge.accounts-customer.secondlife.buster2.dev.tilia-inc.com.', type='TXT'] but it already exists]\n\tstatus code: 400, request id: 042e67a7-bcbd-46ac-8891-62da84aa91e8 (order=https://acme-v02.api.letsencrypt.org/acme/order/117392991/8748942711) (ca=https://acme-v02.api.letsencrypt.org/directory)","attempt":1,"retrying_in":60,"elapsed":8.877229548,"max_duration":2592000}
{"level":"error","ts":1617061057.3103502,"logger":"tls.obtain","msg":"will retry","error":"[*.buster2.dev.tilia-inc.com] Obtain: [*.buster2.dev.tilia-inc.com] solving challenges: presenting for challenge: adding temporary record for zone dev.tilia-inc.com.: InvalidChangeBatch: InvalidChangeBatch: [Tried to create resource record set [name='_acme-challenge.buster2.dev.tilia-inc.com.', type='TXT'] but it already exists]\n\tstatus code: 400, request id: d976fdae-0621-42b1-a92b-e37a503a4057 (order=https://acme-v02.api.letsencrypt.org/acme/order/117392991/8748942717) (ca=https://acme-v02.api.letsencrypt.org/directory)","attempt":1,"retrying_in":60,"elapsed":8.858834661,"max_duration":2592000}
{"level":"info","ts":1617061117.6856034,"logger":"tls.issuance.acme.acme_client","msg":"trying to solve challenge","identifier":"accounts-customer.secondlife.buster2.dev.tilia-inc.com","challenge_type":"dns-01","ca":"https://acme-staging-v02.api.letsencrypt.org/directory"}
{"level":"info","ts":1617061118.3386168,"logger":"tls.issuance.acme.acme_client","msg":"trying to solve challenge","identifier":"*.buster2.dev.tilia-inc.com","challenge_type":"dns-01","ca":"https://acme-staging-v02.api.letsencrypt.org/directory"}
{"level":"error","ts":1617061118.4399567,"logger":"tls.issuance.acme.acme_client","msg":"cleaning up solver","identifier":"accounts-customer.secondlife.buster2.dev.tilia-inc.com","challenge_type":"dns-01","error":"no memory of presenting a DNS record for accounts-customer.secondlife.buster2.dev.tilia-inc.com (probably OK if presenting failed)"}
{"level":"error","ts":1617061119.1218812,"logger":"tls.obtain","msg":"will retry","error":"[accounts-customer.secondlife.buster2.dev.tilia-inc.com] Obtain: [accounts-customer.secondlife.buster2.dev.tilia-inc.com] solving challenges: presenting for challenge: adding temporary record for zone dev.tilia-inc.com.: InvalidChangeBatch: InvalidChangeBatch: [Tried to create resource record set [name='_acme-challenge.accounts-customer.secondlife.buster2.dev.tilia-inc.com.', type='TXT'] but it already exists]\n\tstatus code: 400, request id: 72ac4800-c875-4715-844f-f694f6909d04 (order=https://acme-staging-v02.api.letsencrypt.org/acme/order/18830866/21061762) (ca=https://acme-staging-v02.api.letsencrypt.org/directory)","attempt":2,"retrying_in":120,"elapsed":70.735204333,"max_duration":2592000}
{"level":"error","ts":1617061119.1976955,"logger":"tls.issuance.acme.acme_client","msg":"cleaning up solver","identifier":"*.buster2.dev.tilia-inc.com","challenge_type":"dns-01","error":"no memory of presenting a DNS record for buster2.dev.tilia-inc.com (probably OK if presenting failed)"}
{"level":"error","ts":1617061119.2597537,"logger":"tls.obtain","msg":"will retry","error":"[*.buster2.dev.tilia-inc.com] Obtain: [*.buster2.dev.tilia-inc.com] solving challenges: presenting for challenge: adding temporary record for zone dev.tilia-inc.com.: InvalidChangeBatch: InvalidChangeBatch: [Tried to create resource record set [name='_acme-challenge.buster2.dev.tilia-inc.com.', type='TXT'] but it already exists]\n\tstatus code: 400, request id: 2edaf1f7-0f64-41fb-b893-941aa344c110 (order=https://acme-staging-v02.api.letsencrypt.org/acme/order/18830866/21061765) (ca=https://acme-staging-v02.api.letsencrypt.org/directory)","attempt":2,"retrying_in":120,"elapsed":70.808238291,"max_duration":2592000}

5. What I already tried:

So we had a problem that a CertMagic update broke route53 DNS provider. I reverted to an older version of caddy. This largely worked and certs were obtained for most developers. However, we are still getting an error on one developers machine. (The logs above are for that machine.)

3 things are really confusing to me:

The set up for other developer machines is pretty much exactly the same. It is very weird it is consistently not working for just this machine.
The error messages are are saying the DNS entry is already there. But we went and deleted the DNS entries to see if that is the issue. Caddy is certainly writing to route53.
I’m seeing in the logs that it is sometimes referencing the normal letsencrypt CA and sometimes referencing the staging CA!!! As you can see in the config - The line turning on the staging CA is commented out. The staging CA should not be getting referenced or used. Why is caddy logging that it is using it?

6. Links to relevant resources:

francislavoie · March 30, 2021, 4:28pm

I don’t know enough about route53 to help here unfortunately.

Caddy automatically switches to the staging environment as a fallback on errors to avoid running over rate limits. Once a successful issuance happens, it flips back to the non-staging to try again. It’s explained here:

system · April 29, 2021, 4:01pm

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