Options displayed as 'undefined' in debug log #1

New Issue

Ghost · 2019-06-03T03:03:30Z

Ghost commented

2019-06-03 03:03:30 +00:00

I had troubled recently with the automated SSL certificate renewal. I ended having to do it manually with docker and a certbot-dns-cloudflare image. I am trying to figure out what went wrong. In the debug log messages, I see that the options usually displayed are now 'undefined':

[gl/index.js] gl.getCertificates called for checkin.wednesdaynighthop.com with certs for NONE
[gl/index.js] gl.approveDomains called with certs for NONE and options:
[gl/index.js] undefined
[gl/index.js] gl getting from disk or registering new

Any idea what could be wrong?

I had troubled recently with the automated SSL certificate renewal. I ended having to do it manually with docker and a certbot-dns-cloudflare image. I am trying to figure out what went wrong. In the debug log messages, I see that the options usually displayed are now 'undefined': ``` [gl/index.js] gl.getCertificates called for checkin.wednesdaynighthop.com with certs for NONE [gl/index.js] gl.approveDomains called with certs for NONE and options: [gl/index.js] undefined [gl/index.js] gl getting from disk or registering new ``` Any idea what could be wrong?

Ghost commented

2019-06-03 03:08:25 +00:00

I am using the le-challenge-cloudflare plugin with a delay of 10 seconds to get the DNS TXT data to update. Though it worked before, during the renewal, I could not see the 10-second delay being honored and the renewal was failing right away. I am going to add a log below.

Ghost commented

2019-06-03 03:12:45 +00:00

Here is the full log of the failed renewal attempt:

[gl/index.js] gl.getCertificates called for checkin.wednesdaynighthop.com with certs for NONE
[gl/index.js] gl.approveDomains called with certs for NONE and options:
[gl/index.js] undefined
[gl/index.js] gl getting from disk or registering new
[greenlock/lib/core.js] checkAsync found existing certificates
[greenlock/lib/core.js] Check Expires At 2019-05-24T17:06:57.000Z
[greenlock/lib/core.js] Check Renewable At 2019-05-10T17:06:57.000Z
[greenlock/lib/core.js] certificates are renewable
[greenlock/lib/core.js] (Renew) Expires At 2019-05-24T17:06:57.000Z
[greenlock/lib/core.js] (Renew) Renewable At 2019-05-10T17:06:57.000Z
[greenlock/lib/core.js] Renewing!
[le-store-certbot] success reading arg.accountsDir
[le-store-certbot] regrs.length 1
[le-store-certbot] accountId: --HIDDEN--ACCOUNT-ID--
[greenlock/lib/core.js] calling greenlock.acme.getCertificateAsync checkin.wednesdaynighthop.com [ 'checkin.wednesdaynighthop.com' ]
[acme-v2] DEBUG get cert 1
[greenlock/lib/core.js] setChallenge called for 'checkin.wednesdaynighthop.com'
[gl/index.js] gl.getCertificates called for checkin.wednesdaynighthop.com with certs for [ 'checkin.wednesdaynighthop.com' ]
[gl/index.js] gl.approveDomains called with certs for [ 'checkin.wednesdaynighthop.com' ] and options:
[gl/index.js] undefined
[gl/index.js] gl renewing
[DEBUG] waitChallengeDelay 500
[acme-v2] handled(?) rejection as errback:
Error: queryTxt ENODATA _greenlock-dryrun-7280.checkin.wednesdaynighthop.com
  at QueryReqWrap.onresolve [as oncomplete] (dns.js:199:19)
Error renewing certificate for 'checkin.wednesdaynighthop.com':
{ Error: queryTxt ENODATA _greenlock-dryrun-7280.checkin.wednesdaynighthop.com
   at QueryReqWrap.onresolve [as oncomplete] (dns.js:199:19)
 cause:
{ Error: queryTxt ENODATA _greenlock-dryrun-7280.checkin.wednesdaynighthop.com
   at QueryReqWrap.onresolve [as oncomplete] (dns.js:199:19)
   errno: 'ENODATA',
   code: 'ENODATA',
  syscall: 'queryTxt',
  hostname: '_greenlock-dryrun-7280.checkin.wednesdaynighthop.com' },
  isOperational: true,
  errno: 'ENODATA',
  code: 'ENODATA',
  syscall: 'queryTxt',
  hostname: '_greenlock-dryrun-7280.checkin.wednesdaynighthop.com' }

Here is the full log of the failed renewal attempt: ``` [gl/index.js] gl.getCertificates called for checkin.wednesdaynighthop.com with certs for NONE [gl/index.js] gl.approveDomains called with certs for NONE and options: [gl/index.js] undefined [gl/index.js] gl getting from disk or registering new [greenlock/lib/core.js] checkAsync found existing certificates [greenlock/lib/core.js] Check Expires At 2019-05-24T17:06:57.000Z [greenlock/lib/core.js] Check Renewable At 2019-05-10T17:06:57.000Z [greenlock/lib/core.js] certificates are renewable [greenlock/lib/core.js] (Renew) Expires At 2019-05-24T17:06:57.000Z [greenlock/lib/core.js] (Renew) Renewable At 2019-05-10T17:06:57.000Z [greenlock/lib/core.js] Renewing! [le-store-certbot] success reading arg.accountsDir [le-store-certbot] regrs.length 1 [le-store-certbot] accountId: --HIDDEN--ACCOUNT-ID-- [greenlock/lib/core.js] calling greenlock.acme.getCertificateAsync checkin.wednesdaynighthop.com [ 'checkin.wednesdaynighthop.com' ] [acme-v2] DEBUG get cert 1 [greenlock/lib/core.js] setChallenge called for 'checkin.wednesdaynighthop.com' [gl/index.js] gl.getCertificates called for checkin.wednesdaynighthop.com with certs for [ 'checkin.wednesdaynighthop.com' ] [gl/index.js] gl.approveDomains called with certs for [ 'checkin.wednesdaynighthop.com' ] and options: [gl/index.js] undefined [gl/index.js] gl renewing [DEBUG] waitChallengeDelay 500 [acme-v2] handled(?) rejection as errback: Error: queryTxt ENODATA _greenlock-dryrun-7280.checkin.wednesdaynighthop.com at QueryReqWrap.onresolve [as oncomplete] (dns.js:199:19) Error renewing certificate for 'checkin.wednesdaynighthop.com': { Error: queryTxt ENODATA _greenlock-dryrun-7280.checkin.wednesdaynighthop.com at QueryReqWrap.onresolve [as oncomplete] (dns.js:199:19) cause: { Error: queryTxt ENODATA _greenlock-dryrun-7280.checkin.wednesdaynighthop.com at QueryReqWrap.onresolve [as oncomplete] (dns.js:199:19) errno: 'ENODATA', code: 'ENODATA', syscall: 'queryTxt', hostname: '_greenlock-dryrun-7280.checkin.wednesdaynighthop.com' }, isOperational: true, errno: 'ENODATA', code: 'ENODATA', syscall: 'queryTxt', hostname: '_greenlock-dryrun-7280.checkin.wednesdaynighthop.com' } ```

coolaj86 commented

2019-06-03 03:17:39 +00:00

What are the installed versions of these?

greenlock
greenlock-express
le-challenge-cloudflare

And what does your approveDomains function look like?

What are the installed versions of these? * greenlock * greenlock-express * le-challenge-cloudflare And what does your `approveDomains` function look like?

Ghost commented

2019-06-03 03:20:27 +00:00

I am using greenlock-express 2.7.8 with greenlock 2.7.22.

I am using approvedDomains and have not specified an approveDomains function, just like in the quick start example.

I am using greenlock-express 2.7.8 with greenlock 2.7.22. I am using approvedDomains and have not specified an approveDomains function, just like in the quick start example.

Ghost commented

2019-06-03 03:22:23 +00:00

My code looks like this:

      const store = LEStoreCertbot.create({
        liveDir: sslPath,
      })

      const acmePrefix = '_acme-challenge'
      const DNSChallenge = new LEChallengeCloudflare({
        email: config.cloudflare_email,
        key: config.cloudflare_api_key,
        acmePrefix,
        delay: 1000 * 10, // 10-second delay for TXT record update
      })

      // https/http servers
      const greenlock = greenlockExpress.create({
        version: 'draft-11', // Let's Encrypt v2 is ACME draft 11
        server: config.letsencrypt_server, // Let's Encrypt server
        email: config.ssl_email, // Emailed when certificates expire
        agreeTos: true, // Required for letsencrypt
        approvedDomains: [config.domain], // List of accepted domain names
        configDir: path.dirname(path.dirname(sslPath)), // Directory path where certificates go
        // app: expressServer, // Express server
        debug: config.https_server_debug, // Add console messages and uses staging LetsEncrypt server (disable in production)
        communityMember: true,
        telemetry: true,
        //
        store,
        challenges: { 'dns-01': DNSChallenge },
        challengeType: 'dns-01',
        acmePrefix, // LEChallengeCloudflare uses acmePrefix but Greenlock provides acmeChallengePrefix
      })

My code looks like this: ``` const store = LEStoreCertbot.create({ liveDir: sslPath, }) const acmePrefix = '_acme-challenge' const DNSChallenge = new LEChallengeCloudflare({ email: config.cloudflare_email, key: config.cloudflare_api_key, acmePrefix, delay: 1000 * 10, // 10-second delay for TXT record update }) // https/http servers const greenlock = greenlockExpress.create({ version: 'draft-11', // Let's Encrypt v2 is ACME draft 11 server: config.letsencrypt_server, // Let's Encrypt server email: config.ssl_email, // Emailed when certificates expire agreeTos: true, // Required for letsencrypt approvedDomains: [config.domain], // List of accepted domain names configDir: path.dirname(path.dirname(sslPath)), // Directory path where certificates go // app: expressServer, // Express server debug: config.https_server_debug, // Add console messages and uses staging LetsEncrypt server (disable in production) communityMember: true, telemetry: true, // store, challenges: { 'dns-01': DNSChallenge }, challengeType: 'dns-01', acmePrefix, // LEChallengeCloudflare uses acmePrefix but Greenlock provides acmeChallengePrefix }) ```

coolaj86 commented

2019-06-03 03:25:13 +00:00

Must be a regression. I'm looking into it.

Ghost commented

2019-06-03 03:25:54 +00:00

Thank you.

The log used to look like this:

[gl/index.js] gl.getCertificates called for checkin.wednesdaynighthop.com with certs for [ 'checkin.wednesdaynighthop.com' ]
[gl/index.js] gl.approveDomains called with certs for [ 'checkin.wednesdaynighthop.com' ] and options:
[gl/index.js] { domain: 'checkin.wednesdaynighthop.com',
  domains: [ 'checkin.wednesdaynighthop.com' ],
  email: 'ssl@wednesdaynighthop.com',
  agreeTos: true,
  communityMember: true,
  telemetry: true }
[gl/index.js] gl renewing
[le-store-certbot] success reading arg.accountsDir
[le-store-certbot] regrs.length 1

Thank you. The log used to look like this: ``` [gl/index.js] gl.getCertificates called for checkin.wednesdaynighthop.com with certs for [ 'checkin.wednesdaynighthop.com' ] [gl/index.js] gl.approveDomains called with certs for [ 'checkin.wednesdaynighthop.com' ] and options: [gl/index.js] { domain: 'checkin.wednesdaynighthop.com', domains: [ 'checkin.wednesdaynighthop.com' ], email: 'ssl@wednesdaynighthop.com', agreeTos: true, communityMember: true, telemetry: true } [gl/index.js] gl renewing [le-store-certbot] success reading arg.accountsDir [le-store-certbot] regrs.length 1 ```

Ghost commented

2019-06-03 03:31:04 +00:00

This line in greenlock/index.js looks a little suspicious:

            PromiseA.resolve(gl.approveDomains(opts)).then(cb2).catch(eb2);

as no arguments are getting passed to cb2. Shouldn't a callback function be passed to gl.approveDomains after the opts argument?

This line in greenlock/index.js looks a little suspicious: ``` PromiseA.resolve(gl.approveDomains(opts)).then(cb2).catch(eb2); ``` as no arguments are getting passed to cb2. Shouldn't a callback function be passed to gl.approveDomains after the opts argument?

coolaj86 commented

2019-06-03 03:44:18 +00:00

First:

This is just a red herring that needs a better log message. It's normal to get this message on startup because no certs have been loaded yet at all. It's just a cache miss.

[gl/index.js] gl.getCertificates called for checkin.wednesdaynighthop.com with certs for NONE
[gl/index.js] gl.approveDomains called with certs for NONE and options:
[gl/index.js] undefined

The second time it shows the certs, but the options aren't showing because the assignment was moved to after the logging (line 560 of lib/core.js).

This looks important:

Error: queryTxt ENODATA _greenlock-dryrun-7280.checkin.wednesdaynighthop.com
  at QueryReqWrap.onresolve [as oncomplete] (dns.js:199:19)
Error renewing certificate for 'checkin.wednesdaynighthop.com':

I can indeed confirm that there is no TXT record _greenlock-dryrun-7280.checkin.wednesdaynighthop.com.

I think this is an issue of fixing one bug caused another. I'm moving on to looking at le-challenge-cloudflare. I think it may be relying on _acme-challenge as a hard-coded value, or I may have accidentally broken the contract and passed in the wrong value.

I believe that if you set skipChallengeTest: true and skipDryRun: true in the main options it will get around that issue.

First: This is just a red herring that needs a better log message. It's normal to get this message on startup because no certs have been loaded yet at all. It's just a cache miss. ``` [gl/index.js] gl.getCertificates called for checkin.wednesdaynighthop.com with certs for NONE [gl/index.js] gl.approveDomains called with certs for NONE and options: [gl/index.js] undefined ``` The second time it shows the certs, but the options aren't showing because the assignment was moved to after the logging (line 560 of lib/core.js). This looks important: ``` Error: queryTxt ENODATA _greenlock-dryrun-7280.checkin.wednesdaynighthop.com at QueryReqWrap.onresolve [as oncomplete] (dns.js:199:19) Error renewing certificate for 'checkin.wednesdaynighthop.com': ``` I can indeed confirm that there is no TXT record `_greenlock-dryrun-7280.checkin.wednesdaynighthop.com`. I think this is an issue of fixing one bug caused another. I'm moving on to looking at `le-challenge-cloudflare`. I think it may be relying on `_acme-challenge` as a hard-coded value, or I may have accidentally broken the contract and passed in the wrong value. I believe that if you set `skipChallengeTest: true` and `skipDryRun: true` in the main options it will get around that issue.

Ghost commented

2019-06-03 03:46:50 +00:00

The TXT record is gone as I have renewed the certificate manually.

By the way, I am using this plugin: https://github.com/llun/le-challenge-cloudflare

The TXT record is gone as I have renewed the certificate manually. By the way, I am using this plugin: https://github.com/llun/le-challenge-cloudflare

coolaj86 commented

2019-06-03 03:47:46 +00:00

P.S. The code is really nasty because I've attempted to maintain backwards compatibility while adding new features, sometimes with different API signatures. I'll have v3 out before November (the next mandatory Let's Encrypt API update) and I'll be deleting all backwards compatibility to drastically simplify the code.

There's already nice test harnesses acme-challenge-test and greenlock-store-test for the v3 API (available in greenlock v2.7+).

P.S. The code is really nasty because I've attempted to maintain backwards compatibility while adding new features, sometimes with different API signatures. I'll have v3 out before November (the next mandatory Let's Encrypt API update) and I'll be deleting all backwards compatibility to drastically simplify the code. There's already nice test harnesses `acme-challenge-test` and `greenlock-store-test` for the v3 API (available in greenlock v2.7+).

Ghost commented

2019-06-03 03:56:48 +00:00

Hmm I have log from my app from 3/2/19 and the options displayed correctly at launch. I had greenlock-express 2.6.7 at the time.

coolaj86 commented

2019-06-03 04:26:09 +00:00

Would you mind putting some custom logging into le-challenge-cloudflare showing what's being passed into the arguments and sending that log to me? I'd do it myself, but I don't have cloudflare set up for my domains.

Right around here:
https://github.com/llun/le-challenge-cloudflare/blob/master/lib/index.js#L32

Would you mind putting some custom logging into le-challenge-cloudflare showing what's being passed into the arguments and sending that log to me? I'd do it myself, but I don't have cloudflare set up for my domains. Right around here: https://github.com/llun/le-challenge-cloudflare/blob/master/lib/index.js#L32

Ghost commented

2019-06-03 05:22:59 +00:00

Here is what I get:

  set({ acmePrefix, delay }, domain, challengePath, keyAuthorization, done) {
    console.log('HERE:', acmePrefix, delay, domain, challengePath, keyAuthorization, done);

HERE: _acme-challenge
10000
checkin.wednesdaynighthop.com
test-60899f990608abcdd35cc308d2d0c531-1
test-60899f990608abcdd35cc308d2d0c531-1.v6cuToeQwa15uRy0yx03rnHXYrGNM4H6HOh8ZHRUfQE
function (err) { if(err) { reject(err); } else { resolve(); } }

Here is what I get: ``` set({ acmePrefix, delay }, domain, challengePath, keyAuthorization, done) { console.log('HERE:', acmePrefix, delay, domain, challengePath, keyAuthorization, done); ``` ``` HERE: _acme-challenge 10000 checkin.wednesdaynighthop.com test-60899f990608abcdd35cc308d2d0c531-1 test-60899f990608abcdd35cc308d2d0c531-1.v6cuToeQwa15uRy0yx03rnHXYrGNM4H6HOh8ZHRUfQE function (err) { if(err) { reject(err); } else { resolve(); } } ```

Ghost commented

2019-06-03 05:26:11 +00:00

Hmm I see the expected hostname is wrong.

Greenlock expects this:

hostname: '_greenlock-dryrun-5562.checkin.wednesdaynighthop.com'

but the plugin is using:

_acme-challenge.checkin.wednesdaynighthop.com

Hmm I see the expected hostname is wrong. Greenlock expects this: ``` hostname: '_greenlock-dryrun-5562.checkin.wednesdaynighthop.com' ``` but the plugin is using: ``` _acme-challenge.checkin.wednesdaynighthop.com ```

Ghost commented

2019-06-03 05:44:57 +00:00

By the way, the skipDryRun option does not seem to exist. I see this in acme-v2/node.js:

      var dryrun = true;
      var auth = ACME._challengeToAuth(me, options, results, challenge, dryrun);

By the way, the skipDryRun option does not seem to exist. I see this in acme-v2/node.js: ``` var dryrun = true; var auth = ACME._challengeToAuth(me, options, results, challenge, dryrun); ```

coolaj86 commented

2019-06-03 05:56:43 +00:00

var dryrun = true;
var auth = ACME._challengeToAuth(me, options, results, challenge, dryrun);

That's from within the dry run function, hence it calls with the dryrun option set. When it doesn't do the dry run, that code never executes.

You only see the one option because it's the next acme-v2.js version in the queue (which is already implemented for https://greenlock.domains) that has the option skipDryRun separate from skipChallengeTest.

``` var dryrun = true; var auth = ACME._challengeToAuth(me, options, results, challenge, dryrun); ``` That's from within the dry run function, hence it calls with the `dryrun` option set. When it doesn't do the dry run, that code never executes. You only see the one option because it's the next acme-v2.js version in the queue (which is already implemented for https://greenlock.domains) that has the option `skipDryRun` separate from `skipChallengeTest`.

Ghost commented

2019-06-03 06:02:59 +00:00

If I set skipChallengeTest to true, the hostname is still different from ${acmePrefix}.${domain}:

  hostname: '_greenlock-dryrun-5603.checkin.wednesdaynighthop.com'

If I set skipChallengeTest to true, the hostname is still different from `${acmePrefix}.${domain}`: hostname: '_greenlock-dryrun-5603.checkin.wednesdaynighthop.com'

coolaj86 commented

2019-06-03 06:19:21 +00:00

I'm going to just remove the dry run so that I don't have to come up with a convoluted fix.

If I change it back to _acme-challenge then there's a DNS cache self-poisoning issue.

In v3 I'll get it all cleanup up.

I'm going to just remove the dry run so that I don't have to come up with a convoluted fix. If I change it back to `_acme-challenge` then there's a DNS cache self-poisoning issue. In v3 I'll get it all cleanup up.

Ghost commented

2019-06-03 06:21:00 +00:00

Alternatively, the plugin could be updated to make use of done.dnsHost to replace ${acmePrefix}.${domain}.

Alternatively, the plugin could be updated to make use of done.dnsHost to replace `${acmePrefix}.${domain}`.

coolaj86 commented

2019-06-03 08:27:45 +00:00

Or rather, the plugin should be updated to pass acme-challenge-test.

Or rather, the plugin should be updated to pass [`acme-challenge-test`](https://www.npmjs.com/package/acme-challenge-test).

coolaj86 commented

2019-06-03 09:55:03 +00:00

I published a new patch version of greenlock that should unbreak le-challenge-cloudflare.

I also manually tested it with node v6.8 to try to make sure there were no other regressions.

I published a new patch version of greenlock that should unbreak le-challenge-cloudflare. I also manually tested it with node v6.8 to try to make sure there were no other regressions.

coolaj86 commented

2019-06-04 01:41:54 +00:00

Is it working for you now? Can I close out the issue?

Ghost commented

2019-06-05 01:35:33 +00:00

I will test it out this Thursday, sorry for the delay.

Ghost commented

2019-06-12 05:49:43 +00:00

I tested it out today and a new certificate was fetched without issue, so I think your fix worked. Thank you!

coolaj86 closed this issue

2019-06-12 07:13:00 +00:00

coolaj86 commented