Acmetool debugging

[mnalis]

I’m using acmetool 0.0.58-1~bpo8+1 package (upsteam homepage: https://hlandau.github.io/acme) on Ubuntu precise with Zimbra. It already sucessfully hosts dozen LE certificates ( https://crt.sh/?id=253320154 ) and I’m trying to add another one (mail.partes.hr), but it fails validating. I’m using webroot method.

I’ve verified that mail.partes.hr point to this same IP as other working certificates (195.190.136.180), and that apache redirection seems to be working ok:

mail# echo blah `date` > /var/run/acme/acme-challenge/blah
someotherhost# wget -q --no-hsts -O-  http://mail.partes.hr/.well-known/acme-challenge/blah                                                                                                                                                                         
blah Wed Jan 3 16:09:05 CET 2018

My domain is: main kontos.tomsoft.hr, trying to add mail.partes.hr

I ran this command: sudo -u acme acmetool

It produced this output: error: Target(kontos.tomsoft.hr, webmail.luceed.hr, mail.luceed.hr, email.bova11.hr, mail.bova11.hr, mail.tridea.hr, webmail.tridea.hr, mail.domsvjosip.hr, mail.nediraj.net, mail.partes.hr, mail.vina-acrobat.hr, mail.links.eu; https://acme-v01.api.letsencrypt.org/directory;0): no certificate satisfies this target

My web server is (include version): 2.2.22-1ubuntu1.11

The operating system my web server runs on is (include version): Ubuntu 12.04

My hosting provider, if applicable, is: N/A

I can login to a root shell on my machine (yes or no, or I don’t know): yes

I’m using a control panel to manage my site (no, or provide the name and version of the control panel): no

[mnalis]

additional debug produces this (full log at https://pastebin.com/2DanAw29 ):

sudo -u acme acmetool --xlog.severity=debug 2>&1 | grep -v acme.storageops:

acme.api: request: https://acme-v01.api.letsencrypt.org/directory
acme.api: response: &{200 OK 200 HTTP/1.1 1 1 map[Content-Type:[application/json] Replay-Nonce:[lTo791rRFGX8PhHmlU7dt_t_Ot5DDPcPNT76JOGzeyU] Strict-Transport-Security:[max-age=604800] Connection:[keep-alive] Date:[Wed, 03 Jan 2018 14:14:05 GMT] Server:[nginx] Content-Length:[562] X-Frame-Options:[DENY] Expires:[Wed, 03 Jan 2018 14:14:05 GMT] Cache-Control:[max-age=0, no-cache, no-store] Pragma:[no-cache]] 0xc820388120 562 false map 0xc8204b5dc0 0xc82046e630}
acme.api: request: https://acme-v01.api.letsencrypt.org/acme/new-reg
acme.api: response: &{409 Conflict 409 HTTP/1.1 1 1 map[Expires:[Wed, 03 Jan 2018 14:14:05 GMT] Cache-Control:[max-age=0, no-cache, no-store] Server:[nginx] Content-Type:[application/problem+json] Content-Length:[107] Boulder-Requester:[10919392] Location:[https://acme-v01.api.letsencrypt.org/acme/reg/10919392] Replay-Nonce:[jROolnC0tdc7N_f2xS-5v7CeqD7566PCAJsBE2q9Zkk] Pragma:[no-cache] Date:[Wed, 03 Jan 2018 14:14:05 GMT]] 0xc82028c1c0 107 true map 0xc8202cad20 0xc82046e630}
acme.api: request: https://acme-v01.api.letsencrypt.org/acme/reg/10919392
acme.api: response: &{202 Accepted 202 HTTP/1.1 1 1 map[Pragma:[no-cache] Date:[Wed, 03 Jan 2018 14:14:06 GMT] Server:[nginx] Boulder-Requester:[10919392] Link:[https://acme-v01.api.letsencrypt.org/acme/new-authz;rel="next" https://letsencrypt.org/documents/LE-SA-v1.2-November-15-2017.pdf;rel="terms-of-service"] Replay-Nonce:[t3HT9E751ihm5TtKyRkfzR_87RVW9Evzk_I5ABx9QT4] Expires:[Wed, 03 Jan 2018 14:14:06 GMT] Cache-Control:[max-age=0, no-cache, no-store] Connection:[keep-alive] Content-Type:[application/json] Content-Length:[664]] 0xc820246980 664 false map 0xc8204b4000 0xc82046e4d0}
acme.api: request: https://acme-v01.api.letsencrypt.org/acme/new-authz
acme.api: response: &{201 Created 201 HTTP/1.1 1 1 map[Server:[nginx] Location:[https://acme-v01.api.letsencrypt.org/acme/authz/gp0slV9A6ncavuLf7GOccHQWTjindN_T82L5NwIvUNE] Replay-Nonce:[uwQmt8bMmy0gJzAZvIHB3bKLqDOvDcJYCLR3JfuILMI] Cache-Control:[max-age=0, no-cache, no-store] Date:[Wed, 03 Jan 2018 14:14:06 GMT] Link:[https://acme-v01.api.letsencrypt.org/acme/new-cert;rel="next"] Pragma:[no-cache] Connection:[keep-alive] Content-Length:[995] X-Frame-Options:[DENY] Expires:[Wed, 03 Jan 2018 14:14:06 GMT] Content-Type:[application/json] Boulder-Requester:[10919392] Strict-Transport-Security:[max-age=604800]] 0xc820453a00 995 false map 0xc82045bea0 0xc82046e4d0}
acme.solver: attempting challenge type tls-sni-01
acme.responder: failed to start TLS-SNI listener: listen tcp :443: bind: permission denied
acme.responder: tls-sni-01 self-test failed: when doing self-test, got 3 certificates, expected 1
acme.solver: challenge start failed: when doing self-test, got 3 certificates, expected 1
acme.solver: attempting challenge type http-01
acme.responder: failed to listen on [::]:80: listen tcp [::]:80: bind: permission denied
acme.responder: failed to listen on :80: listen tcp :80: bind: permission denied
acme.responder: listening on 127.0.0.1:4402
acme.responder: failed to listen on [::1]:402: listen tcp [::1]:402: bind: permission denied
acme.responder: failed to listen on 127.0.0.1:402: listen tcp 127.0.0.1:402: bind: permission denied
acme.responder: listening on [::1]:4402
acme.responder: writing 1 webroot challenge files
acme.responder: writing webroot file /var/run/acme/acme-challenge/GM9JLV14Ew8TDP2NzCRXilaDlGflqoewSjdQEN1QB3k
acme.responder: http-01 self test
acme.responder: http-01 started
acme.api: request: https://acme-v01.api.letsencrypt.org/acme/challenge/gp0slV9A6ncavuLf7GOccHQWTjindN_T82L5NwIvUNE/2968458902
acme.api: response: &{202 Accepted 202 HTTP/1.1 1 1 map[Cache-Control:[max-age=0, no-cache, no-store] Pragma:[no-cache] Server:[nginx] Content-Type:[application/json] Content-Length:[336] Link:[https://acme-v01.api.letsencrypt.org/acme/authz/gp0slV9A6ncavuLf7GOccHQWTjindN_T82L5NwIvUNE;rel="up"] Replay-Nonce:[TjOTenE_OGkE07_YHS_n2HI2dGfyR--QHpZWk8dBYLw] Expires:[Wed, 03 Jan 2018 14:14:06 GMT] Connection:[keep-alive] Boulder-Requester:[10919392] Location:[https://acme-v01.api.letsencrypt.org/acme/challenge/gp0slV9A6ncavuLf7GOccHQWTjindN_T82L5NwIvUNE/2968458902] Date:[Wed, 03 Jan 2018 14:14:06 GMT]] 0xc820452200 336 false map 0xc8203bdb20 0xc82046e4d0}
acme.solver: waiting to poll challenge
acme.solver: querying challenge status
acme.api: request: https://acme-v01.api.letsencrypt.org/acme/challenge/gp0slV9A6ncavuLf7GOccHQWTjindN_T82L5NwIvUNE/2968458902
acme.api: response: &{202 Accepted 202 HTTP/1.1 1 1 map[Content-Length:[336] Link:[https://acme-v01.api.letsencrypt.org/acme/authz/gp0slV9A6ncavuLf7GOccHQWTjindN_T82L5NwIvUNE;rel="up"] Replay-Nonce:[qU-WlSvDA-K_igqWuBo3H4R7Vaw4lliMxzZ1SqmYds8] Cache-Control:[max-age=0, no-cache, no-store] Pragma:[no-cache] Date:[Wed, 03 Jan 2018 14:14:12 GMT] Connection:[keep-alive] Server:[nginx] Location:[https://acme-v01.api.letsencrypt.org/acme/challenge/gp0slV9A6ncavuLf7GOccHQWTjindN_T82L5NwIvUNE/2968458902] Expires:[Wed, 03 Jan 2018 14:14:12 GMT] Content-Type:[application/json]] 0xc820452a00 336 false map 0xc8202d4000 0xc82046e4d0}
acme.solver: waiting to poll challenge
acme.solver: querying challenge status
acme.api: request: https://acme-v01.api.letsencrypt.org/acme/challenge/gp0slV9A6ncavuLf7GOccHQWTjindN_T82L5NwIvUNE/2968458902
acme.api: response: &{202 Accepted 202 HTTP/1.1 1 1 map[Cache-Control:[max-age=0, no-cache, no-store] Date:[Wed, 03 Jan 2018 14:14:22 GMT] Connection:[keep-alive] Server:[nginx] Content-Length:[926] Link:[https://acme-v01.api.letsencrypt.org/acme/authz/gp0slV9A6ncavuLf7GOccHQWTjindN_T82L5NwIvUNE;rel="up"] Location:[https://acme-v01.api.letsencrypt.org/acme/challenge/gp0slV9A6ncavuLf7GOccHQWTjindN_T82L5NwIvUNE/2968458902] Replay-Nonce:[wMJe1NCdLnK1i5mgYvL25iv01eg281qZEfrc-VKL8sQ] Content-Type:[application/json] Expires:[Wed, 03 Jan 2018 14:14:22 GMT] Pragma:[no-cache]] 0xc82045e360 926 false map 0xc82028e700 0xc82046e4d0}
acme.solver: challenge now in final state
acme.responder: removing webroot file /var/run/acme/acme-challenge/GM9JLV14Ew8TDP2NzCRXilaDlGflqoewSjdQEN1QB3k
acme.api: request: https://acme-v01.api.letsencrypt.org/acme/new-authz
acme.api: response: &{201 Created 201 HTTP/1.1 1 1 map[Content-Type:[application/json] Content-Length:[1005] Link:[https://acme-v01.api.letsencrypt.org/acme/new-cert;rel="next"] Replay-Nonce:[Nel6A7fjMkPRsVYPcaI5qbDdNjM67AciNcarOkNHsL8] Location:[https://acme-v01.api.letsencrypt.org/acme/authz/x6WwMy5CTDxTz-VUsAjkmmInaPMYxY1ROZwUPOncark] Strict-Transport-Security:[max-age=604800] Expires:[Wed, 03 Jan 2018 14:14:22 GMT] Date:[Wed, 03 Jan 2018 14:14:22 GMT] Cache-Control:[max-age=0, no-cache, no-store] Pragma:[no-cache] Server:[nginx] Boulder-Requester:[10919392] X-Frame-Options:[DENY] Connection:[keep-alive]] 0xc82023b280 1005 false map 0xc8203a9b20 0xc82046e4d0}
acme.solver: attempting challenge type dns-01
acme.solver: challenge start failed: could not install DNS challenge, no hooks succeeded
error satisfying Target(kontos.tomsoft.hr,webmail.luceed.hr,mail.luceed.hr,email.bova11.hr,mail.bova11.hr,mail.tridea.hr,webmail.tridea.hr,mail.domsvjosip.hr,mail.nediraj.net,mail.partes.hr,mail.vina-acrobat.hr,mail.links.eu;https://acme-v01.api.letsencrypt.org/directory;0): failed all combinations

It's hard to read, but to me it looks like it gets OK (2xx) response codes? But, error is returned and nothing shows on https://crt.sh for mail.partes.hr

Also, in apache logs it looks like I only see acmetool selfcheck, no LE servers trying to contact me:

grep GM9JLV14Ew8TDP2NzCRXilaDlGflqoewSjdQEN1QB3k /var/log/apache2/log /opt/zimbra/log/

/var/log/apache2/kontos.tomsoft.hr-access_log:127.0.0.1 - - [03/Jan/2018:15:14:06 +0100] "GET /.well-known/acme-challenge/GM9JLV14Ew8TDP2NzCRXilaDlGflqoewSjdQEN1QB3k HTTP/1.1" 200 318 "-" "Go-http-client/1.1"

How would I debug this further / fix it? Can someone see at LE server side what is the problem? Or can someone with more experience find out something from the logs provided?

[schoen]

One thing that might be contributing to the problem—that you should at least try to resolve first—is that you have IPv6 AAAA records for kontos.tomsoft.hr, yet that server isn’t actually accepting IPv6 connections.

[mnalis]

Thanks for the pointer, IPv6 was indeed firewalled so only some part of the world could use it. After allowing whole world IPv6 access to port 80, LE validations started working again!

But probably Let’s Encrypt validating servers should do fallback (like every browser etc. does - if it can’t connect to IPv6 address, it should automatically retry with IPv4 address). Just a thought.