Experiencing excessively-long challenge times

Ersatz · August 20, 2016, 10:27am

Both running certbot and acme-tiny, I have been experiencing quite lengthy wait times for domain verification.

Here’s a verbose log running letsencrypt certonly --webroot -t -v -w /var/www/acme/ -d x.nks.io:

2016-08-19 08:42:22,169:DEBUG:letsencrypt.cli:Root logging level set at 20
2016-08-19 08:42:22,172:INFO:letsencrypt.cli:Saving debug log to /var/log/letsencrypt/letsencrypt.log
2016-08-19 08:42:22,180:DEBUG:letsencrypt.cli:letsencrypt version: 0.4.1
2016-08-19 08:42:22,180:DEBUG:letsencrypt.cli:Arguments: ['--webroot', '-t', '-v', '-w', '/var/www/acme', '-d', 'x.nks.io']
2016-08-19 08:42:22,181:DEBUG:letsencrypt.cli:Discovered plugins: PluginsRegistry(PluginEntryPoint#webroot,PluginEntryPoint#null,PluginEntryPoint#manual,PluginEntryPoint#standalone)
2016-08-19 08:42:22,182:DEBUG:letsencrypt.cli:Requested authenticator webroot and installer None
2016-08-19 08:42:22,183:DEBUG:letsencrypt.plugins.webroot:Creating root challenges validation dir at /var/www/acme/.well-known/acme-challenge
2016-08-19 08:42:22,184:DEBUG:letsencrypt.display.ops:Single candidate plugin: * webroot
Description: Webroot Authenticator
Interfaces: IAuthenticator, IPlugin
Entry point: webroot = letsencrypt.plugins.webroot:Authenticator
Initialized: <letsencrypt.plugins.webroot.Authenticator object at <<I AM PARANOID>>>
Prep: True
2016-08-19 08:42:22,203:DEBUG:letsencrypt.cli:Selected authenticator <letsencrypt.plugins.webroot.Authenticator object at 0x7f3ca0cdf250> and installer None
2016-08-19 08:42:22,339:DEBUG:letsencrypt.cli:Picked account: <Account(<<I AM PARANOID>>)>
2016-08-19 08:42:22,394:DEBUG:root:Sending GET request to https://acme-v01.api.letsencrypt.org/directory. args: (), kwargs: {}
2016-08-19 08:42:22,419:INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): acme-v01.api.letsencrypt.org
2016-08-19 08:46:37,951:DEBUG:requests.packages.urllib3.connectionpool:"GET /directory HTTP/1.1" 200 280
2016-08-19 08:46:37,961:DEBUG:root:Received <Response [200]>.<<I AM PARANOID>>
2016-08-19 08:46:37,962:DEBUG:acme.client:Received response <Response [200]> 
2016-08-19 08:46:38,274:INFO:letsencrypt.crypto_util:Generating key (2048 bits): /etc/letsencrypt/keys/0003_key-letsencrypt.pem
2016-08-19 08:46:38,292:INFO:letsencrypt.crypto_util:Creating CSR: /etc/letsencrypt/csr/0003_csr-letsencrypt.pem
2016-08-19 08:46:38,296:DEBUG:letsencrypt.client:CSR: <<I AM PARANOID>>
2016-08-19 08:46:38,297:DEBUG:root:Requesting fresh nonce
2016-08-19 08:46:38,297:DEBUG:root:Sending HEAD request to https://acme-v01.api.letsencrypt.org/acme/new-authz. args: (), kwargs: {}
2016-08-19 08:46:38,300:INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): acme-v01.api.letsencrypt.org
2016-08-19 08:50:53,425:DEBUG:requests.packages.urllib3.connectionpool:"HEAD /acme/new-authz HTTP/1.1" 405 0
2016-08-19 08:50:53,438:DEBUG:root:Received <Response [405]>.
2016-08-19 08:50:53,439:DEBUG:acme.client:Storing nonce: <<I AM PARANOID>>
2016-08-19 08:50:53,440:DEBUG:acme.jose.json_util:Omitted empty fields: challenges=None, combinations=None, status=None, expires=None
2016-08-19 08:50:53,440:DEBUG:acme.client:Serialized JSON: {"identifier": {"type": "dns", "value": "x.nks.io"}, "resource": "new-authz"}
2016-08-19 08:50:53,443:DEBUG:acme.jose.json_util:Omitted empty fields: x5c=(), x5tS256=None, cty=None, jku=None, x5u=None, x5t=None, crit=(), kid=None, alg=None, jwk=None, typ=None
2016-08-19 08:50:53,451:DEBUG:acme.jose.json_util:Omitted empty fields: jku=None, x5tS256=None, cty=None, x5c=(), x5u=None, x5t=None, crit=(), nonce=None, kid=None, typ=None
2016-08-19 08:50:53,452:DEBUG:root:Sending POST request to https://acme-v01.api.letsencrypt.org/acme/new-authz. <<I AM PARANOID>>
2016-08-19 08:50:53,455:INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): acme-v01.api.letsencrypt.org
2016-08-19 08:55:08,475:DEBUG:requests.packages.urllib3.connectionpool:"POST /acme/new-authz HTTP/1.1" 201 993
2016-08-19 08:55:08,480:DEBUG:root:Received <Response [201]>. 
2016-08-19 08:55:08,481:DEBUG:acme.client:Storing nonce: <<I AM PARANOID>>
2016-08-19 08:55:08,481:DEBUG:acme.client:Received response <Response [201]> 
2016-08-19 08:55:08,486:DEBUG:acme.challenges:dns-01 was not recognized, full message: {u'status': u'pending', u'token': u'<<I AM PARANOID>>', u'type': u'dns-01', u'uri': u'https://acme-v01.api.letsencrypt.org/acme/challenge/<<I AM PARANOID>>'}
2016-08-19 08:55:08,490:INFO:letsencrypt.auth_handler:Performing the following challenges:
2016-08-19 08:55:08,491:INFO:letsencrypt.auth_handler:http-01 challenge for x.nks.io
2016-08-19 08:55:08,503:DEBUG:letsencrypt.plugins.webroot:Attempting to save validation to /var/www/acme/.well-known/acme-challenge/vLtT26ZUJhAxcJrbuTCOA8pJPw1bf5iIInMwYlqwFzY
2016-08-19 08:55:08,505:INFO:letsencrypt.auth_handler:Waiting for verification...
2016-08-19 08:55:08,505:DEBUG:acme.client:Serialized JSON: {"keyAuthorization": "vLtT26ZUJhAxcJrbuTCOA8pJPw1bf5iIInMwYlqwFzY.<<I AM PARANOID>>", "type": "http-01", "resource": "challenge"}
2016-08-19 08:55:08,509:DEBUG:acme.jose.json_util:Omitted empty fields: x5c=(), x5tS256=None, cty=None, jku=None, x5u=None, x5t=None, crit=(), kid=None, alg=None, jwk=None, typ=None
2016-08-19 08:55:08,515:DEBUG:acme.jose.json_util:Omitted empty fields: jku=None, x5tS256=None, cty=None, x5c=(), x5u=None, x5t=None, crit=(), nonce=None, kid=None, typ=None
2016-08-19 08:55:08,515:DEBUG:root:Sending POST request to https://acme-v01.api.letsencrypt.org/acme/challenge/<<I AM PARANOID>>
2016-08-19 08:55:08,518:INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): acme-v01.api.letsencrypt.org
2016-08-19 08:59:23,410:DEBUG:requests.packages.urllib3.connectionpool:"POST /acme/challenge/<<I AM PARANOID>> HTTP/1.1" 202 335
2016-08-19 08:59:23,419:DEBUG:root:Received <Response [202]>. <<I AM PARANOID>>
2016-08-19 08:59:23,424:DEBUG:acme.client:Storing nonce: <<I AM PARANOID>>
2016-08-19 08:59:23,424:DEBUG:acme.client:Received response <Response [202]> <<I AM PARANOID>>
2016-08-19 08:59:26,433:DEBUG:root:Sending GET request to https://acme-v01.api.letsencrypt.org/acme/authz/<<I AM PARANOID>>
2016-08-19 08:59:26,438:INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): acme-v01.api.letsencrypt.org
2016-08-19 09:03:41,322:DEBUG:requests.packages.urllib3.connectionpool:"GET /acme/authz/<<I AM PARANOID>> HTTP/1.1" 200 1431
2016-08-19 09:03:41,329:DEBUG:root:Received <Response [200]>.<<I AM PARANOID>>
2016-08-19 09:03:41,331:DEBUG:acme.client:Received response <Response [200]> <<I AM PARANOID>>
2016-08-19 09:03:41,333:DEBUG:acme.challenges:dns-01 was not recognized, full message: {u'status': u'pending', u'token': u'<<I AM PARANOID>>', u'type': u'dns-01', u'uri': u'https://acme-v01.api.letsencrypt.org/acme/challenge/<<I AM PARANOID>>'}
2016-08-19 09:03:41,334:INFO:letsencrypt.auth_handler:Cleaning up challenges
2016-08-19 09:03:41,335:DEBUG:letsencrypt.plugins.webroot:Removing /var/www/acme/.well-known/acme-challenge/<<I AM PARANOID>>
2016-08-19 09:03:41,337:DEBUG:letsencrypt.plugins.webroot:All challenges cleaned up, removing /var/www/acme/.well-known/acme-challenge
2016-08-19 09:03:41,339:DEBUG:acme.client:Requesting issuance...
2016-08-19 09:03:41,340:DEBUG:acme.client:Serialized JSON: <<I AM PARANOID>>
2016-08-19 09:03:41,342:DEBUG:acme.jose.json_util:Omitted empty fields: x5c=(), x5tS256=None, cty=None, jku=None, x5u=None, x5t=None, crit=(), kid=None, alg=None, jwk=None, typ=None
2016-08-19 09:03:41,347:DEBUG:acme.jose.json_util:Omitted empty fields: jku=None, x5tS256=None, cty=None, x5c=(), x5u=None, x5t=None, crit=(), nonce=None, kid=None, typ=None
2016-08-19 09:03:41,348:DEBUG:root:Sending POST request to https://acme-v01.api.letsencrypt.org/acme/new-cert. <<I AM PARANOID>>
2016-08-19 09:03:41,351:INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): acme-v01.api.letsencrypt.org
2016-08-19 09:07:56,617:DEBUG:requests.packages.urllib3.connectionpool:"POST /acme/new-cert HTTP/1.1" 201 1272
2016-08-19 09:07:56,634:DEBUG:root:Received <Response [201]>. <<I AM PARANOID>>
2016-08-19 09:07:56,637:DEBUG:acme.client:Storing nonce: <<I AM PARANOID>>
2016-08-19 09:07:56,637:DEBUG:acme.client:Received response <Response [201]> <<I AM PARANOID>>
2016-08-19 09:07:56,701:DEBUG:root:Sending GET request to https://acme-v01.api.letsencrypt.org/acme/issuer-cert. <<I AM PARANOID>>
2016-08-19 09:07:56,704:INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): acme-v01.api.letsencrypt.org
2016-08-19 09:12:11,622:DEBUG:requests.packages.urllib3.connectionpool:"GET /acme/issuer-cert HTTP/1.1" 200 1174
2016-08-19 09:12:11,629:DEBUG:root:Received <Response [200]>. <<I AM PARANOID>>
2016-08-19 09:12:11,631:DEBUG:acme.client:Received response <Response [200]> <<I AM PARANOID>>
2016-08-19 09:12:11,667:DEBUG:letsencrypt.storage:Creating directory /etc/letsencrypt/archive.
2016-08-19 09:12:11,667:DEBUG:letsencrypt.storage:Creating directory /etc/letsencrypt/live.
2016-08-19 09:12:11,668:DEBUG:letsencrypt.storage:Archive directory /etc/letsencrypt/archive/x.nks.io and live directory /etc/letsencrypt/live/x.nks.io created.
2016-08-19 09:12:11,668:DEBUG:letsencrypt.storage:Writing certificate to /etc/letsencrypt/live/x.nks.io/cert.pem.
2016-08-19 09:12:11,668:DEBUG:letsencrypt.storage:Writing private key to /etc/letsencrypt/live/x.nks.io/privkey.pem.
2016-08-19 09:12:11,669:DEBUG:letsencrypt.storage:Writing chain to /etc/letsencrypt/live/x.nks.io/chain.pem.
2016-08-19 09:12:11,669:DEBUG:letsencrypt.storage:Writing full chain to /etc/letsencrypt/live/x.nks.io/fullchain.pem.
2016-08-19 09:12:11,671:DEBUG:letsencrypt.storage:Writing new config /etc/letsencrypt/renewal/x.nks.io.conf.
2016-08-19 09:12:11,679:INFO:letsencrypt.reporter:Reporting to user: Congratulations! Your certificate and chain have been saved at /etc/letsencrypt/live/x.nks.io/fullchain.pem. Your cert will expire on 2016-11-17. To obtain a new version of the certificate in the future, simply run Let's Encrypt again.
2016-08-19 09:12:11,680:INFO:letsencrypt.reporter:Reporting to user: If you like Let's Encrypt, please consider supporting our work by:

Similarly, acme-tiny took 59 minutes (estimated with $ time python acme_tiny.py --account-key ./testaccount.key --csr ./csr/bag.csr --acme-dir /var/www/acme/ > ./certs/bag.crt to verify 2 SAN (out of 8) domains before I CTRL+Ced it.

Previously, I have used letsencrypt-nosudo to obtain LE certificates, which suited me quite well until I had to perform about 20 manual verifications. Even manually signing files and serving challenges, the process took no mroe than 2 min, and I’m curious — why are straight requests through proper clients taking so long?

The DigitalOcean video, although dated, shows the processs is quite fast for them.

I have a VPS running Ubuntu 16.04, newst nginx version, and everything is as updated as can be. VPS has 2 GB ram and is sitting in Australia. pings to the LE api address take about 400ms at worst.

I will greatly appreciate assistance in understanding what’s going and and perhaps resolving the matter,
Thank you,
Ersatz.

pfg · August 20, 2016, 11:14am

Sounds like this issue, which is due to a misconfigured IPv6 interface. Essentially what is happening is that the client attempts to connect to the ACME server via IPv6, then times out and retries via IPv4 (which works).

Check the IPv6 configuration on your server or disable it completely. You can use something like ping6 acme-v01.api.letsencrypt.org to test connectivity.

Ersatz · August 20, 2016, 12:22pm

Thank you very much for your response. On the surface of it, this would appear to be the issue, as ping6 to the api times out. Interestingly, I can ping6 ipv6.google.com without issue.

For the moment I'll disable IPv6 entirely (am too sleepy), but I would very much like to dig into this issue at a later date.

Cheers,
Ersatz

Osiris · August 20, 2016, 1:06pm

Such problems are, I think, mostely because of path MTU problems between the client and server.

system · September 19, 2016, 1:06pm

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