search

polhenarejos / acme_email

ACME Email Client for EmailReply-00 Challenge
https://acme.castle.cloud
GNU General Public License v3.0
46 stars 7 forks source link

Cert generation just fails #16

Closed DDvO closed 9 months ago

DDvO commented 2 years ago

In manual mode (using one -e option, to avoid bug #15), the process seems to work until:

Requesting a certificate for 1@y

- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
A challenge request for S/MIME certificate has been sent. In few minutes, ACME
server will send a challenge e-mail to requested recipient. Please, copy the
ENTIRE subject and paste it below. The subject starts with the label ACME:
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
Subject:  (Enter 'c' to cancel): ACME: jpgHkpwS7AaZVlsOOTrh4A

- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
A challenge response has been generated. Please, copy the following text, reply
the e-mail you have received from ACME server and paste this text in the TOP of
the message's body:
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -

-----BEGIN ACME RESPONSE-----
jlmy3Y1CiOMYL29HTgQ6-TbQcTGvm2_E7zaYXRNaKyA
-----END ACME RESPONSE-----

All authorizations were not finalized by the CA.
DDvO commented 2 years ago

Tried multiple times, but always failed after about one minute with the rather unclear message:

All authorizations were not finalized by the CA.

Looks like a timeout occurred?

LecrisUT commented 2 years ago

On that note, I know that sending untrusted/badly signed emails will break the process. Could the error be more descriptive on those parts? E.g. if a DMARC test fails and so on.

DDvO commented 2 years ago

Same disappointment with automatic mode. After

Requesting a certificate for ...(blinded)

- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
A challenge request for S/MIME certificate has been sent. In few minutes, ACME
server will send a challenge e-mail to requested recipient. You do not need to
take ANY action, as it will be replied automatically.
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -

and waiting for a couple of minutes, got again the rather non-telling

All authorizations were not finalized by the CA.
polhenarejos commented 2 years ago

It is very strange. I've tested it right now and it works. I saw your last attempt was on 30th Oct @ 10:52 pm (UTC+2). Is that correct? Furthermore, could you upload a redacted version of your log file?

DDvO commented 2 years ago

Right, my last manual attempt was at that time. And two days later I tried with --imap, as mentioned in my third comment above.

I just tried again in automatic mode, and this time for sure go a timeout error:

An unexpected error occurred:
requests.exceptions.ReadTimeout: HTTPSConnectionPool(host='acme.castle.cloud', port=443): Read timed out. (read timeout=45)

This is the tail of the log (replacing any personal information by ...):

2021-11-03 11:16:31,156:DEBUG:acme.client:Sending POST request to https://acme.castle.cloud/acme/new-order:
{
  "protected": "...",
  "signature": "...>
  "payload": "..."
}
2021-11-03 11:17:16,205:DEBUG:certbot._internal.log:Exiting abnormally:
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 445, in _make_request
    six.raise_from(e, None)
  File "<string>", line 3, in raise_from
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 440, in _make_request
    httplib_response = conn.getresponse()
  File "/usr/lib/python3.9/http/client.py", line 1347, in getresponse
    response.begin()
  File "/usr/lib/python3.9/http/client.py", line 307, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python3.9/http/client.py", line 268, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/lib/python3.9/socket.py", line 704, in readinto
    return self._sock.recv_into(b)
  File "/usr/lib/python3.9/ssl.py", line 1241, in recv_into
    return self.read(nbytes, buffer)
  File "/usr/lib/python3.9/ssl.py", line 1099, in read
    return self._sslobj.read(len, buffer)
socket.timeout: The read operation timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/requests/adapters.py", line 439, in send
    resp = conn.urlopen(
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 755, in urlopen
    retries = retries.increment(
  File "/usr/lib/python3/dist-packages/urllib3/util/retry.py", line 532, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/lib/python3/dist-packages/six.py", line 719, in reraise
    raise value
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 699, in urlopen
    httplib_response = self._make_request(
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 447, in _make_request
    self._raise_timeout(err=e, url=url, timeout_value=read_timeout)
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 336, in _raise_timeout
    raise ReadTimeoutError(
urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host='acme.castle.cloud', port=443): Read timed out. (read timeout=45)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/david/sys/software/acme_email/cli.py", line 166, in <module>
    main(args)
  File "/home/david/sys/software/acme_email/cli.py", line 119, in main
    request_cert(args, config)
  File "/home/david/sys/software/acme_email/cli.py", line 91, in request_cert
    cert_path, chain_path, fullchain_path = certbot_main._csr_get_and_save_cert(config, le_client)
  File "/home/david/.local/lib/python3.9/site-packages/certbot/_internal/main.py", line 1353, in _csr_get_and_save_cert
    cert, chain = le_client.obtain_certificate_from_csr(csr)
  File "/home/david/.local/lib/python3.9/site-packages/certbot/_internal/client.py", line 295, in obtain_certificate_from_csr
    orderr = self._get_order_and_authorizations(csr.data, best_effort=False)
  File "/home/david/.local/lib/python3.9/site-packages/certbot/_internal/client.py", line 416, in _get_order_and_authorizations
    orderr = self.acme.new_order(csr_pem)
  File "/home/david/.local/lib/python3.9/site-packages/acme/client.py", line 899, in new_order
    return cast(ClientV2, self.client).new_order(csr_pem)
  File "/home/david/.local/lib/python3.9/site-packages/acme/client.py", line 671, in new_order
    response = self._post(self.directory['newOrder'], order)
  File "/home/david/.local/lib/python3.9/site-packages/acme/client.py", line 92, in _post
    return self.net.post(*args, **kwargs)
  File "/home/david/.local/lib/python3.9/site-packages/acme/client.py", line 1227, in post
    return self._post_once(*args, **kwargs)
  File "/home/david/.local/lib/python3.9/site-packages/acme/client.py", line 1239, in _post_once
    response = self._send_request('POST', url, data=data, **kwargs)
  File "/home/david/.local/lib/python3.9/site-packages/acme/client.py", line 1133, in _send_request
    response = self.session.request(method, url, *args, **kwargs)
  File "/usr/lib/python3/dist-packages/requests/sessions.py", line 542, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/lib/python3/dist-packages/requests/sessions.py", line 655, in send
    r = adapter.send(request, **kwargs)
  File "/usr/lib/python3/dist-packages/requests/adapters.py", line 529, in send
    raise ReadTimeout(e, request=request)
requests.exceptions.ReadTimeout: HTTPSConnectionPool(host='acme.castle.cloud', port=443): Read timed out. (read timeout=45)
2021-11-03 11:17:16,213:ERROR:certbot._internal.log:An unexpected error occurred:
2021-11-03 11:17:16,214:ERROR:certbot._internal.log:requests.exceptions.ReadTimeout: HTTPSConnectionPool(host='acme.castle.cloud', port=443): Read timed out. (read timeout=45)
DDvO commented 2 years ago

A further try failed for some other reason:

2021-11-03 11:32:12,824:DEBUG:acme.client:Sending POST request to https://acme.castle.cloud/acme/authz/PtTVT4dT7kT:
{
  "protected": "...>
  "signature": "...>
  "payload": ""
}
2021-11-03 11:32:12,946:DEBUG:urllib3.connectionpool:https://acme.castle.cloud:443 "POST /acme/authz/PtTVT4dT7kT HTTP/1.1" 200 None
2021-11-03 11:32:12,947:DEBUG:acme.client:Received response:
HTTP 200
Date: Wed, 03 Nov 2021 10:32:12 GMT
Content-Type: application/json
Transfer-Encoding: chunked
Connection: keep-alive
location: https://acme.castle.cloud/acme/authz/PtTVT4dT7kT
replay-nonce: 5XP8IQv_9DjcBfI_qUP4PQ
x-frame-options: DENY
x-content-type-options: nosniff
referrer-policy: same-origin
strict-transport-security: max-age=15768000
CF-Cache-Status: DYNAMIC
Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
Report-To: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=6QfgXAMjuswUzcvzfVtwNzvgFALtjneuwYza0H%2FBkcUchCs4JYB2jDG3uI46njDO8%2FUuUrfpIjQsLdTbgDNWypZQdbNdwYiDM3PeDL2RYTMtyaRizz>
NEL: {"success_fraction":0,"report_to":"cf-nel","max_age":604800}
Server: cloudflare
CF-RAY: 6a84eff86e9e5c38-FRA
Content-Encoding: gzip
alt-svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400, h3-28=":443"; ma=86400, h3-27=":443"; ma=86400

{"status": "pending", "expires": "2021-11-04T10:25:46.817Z", "identifier": {"type": "dns", "value": "..."}, "challenges": [{"url": "https://acme.castle.cloud/acme/chall/3P2yQ9vY8Kk>
2021-11-03 11:32:12,947:DEBUG:acme.client:Storing nonce: 5XP8IQv_9DjcBfI_qUP4PQ
2021-11-03 11:32:15,949:DEBUG:acme.client:JWS payload:
b''
2021-11-03 11:32:15,956:DEBUG:acme.client:Sending POST request to https://acme.castle.cloud/acme/authz/PtTVT4dT7kT:
{
  "protected": "...>
  "signature": "...>
  "payload": ""
}
2021-11-03 11:32:16,082:DEBUG:urllib3.connectionpool:https://acme.castle.cloud:443 "POST /acme/authz/PtTVT4dT7kT HTTP/1.1" 200 None
2021-11-03 11:32:16,084:DEBUG:acme.client:Received response:
HTTP 200
Date: Wed, 03 Nov 2021 10:32:16 GMT
Content-Type: application/json
Transfer-Encoding: chunked
Connection: keep-alive
location: https://acme.castle.cloud/acme/authz/PtTVT4dT7kT
replay-nonce: 5s-qaKSAKwPWvsHoY9tluA
x-frame-options: DENY
x-content-type-options: nosniff
referrer-policy: same-origin
strict-transport-security: max-age=15768000
CF-Cache-Status: DYNAMIC
Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
Report-To: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=J11JNHReoiWa%2BLyxJLWHjawiIwfNWJ7Bn1LdjO%2BocdagR83vdgXKse6QnDjxvnMj1YNOekUoarNKF9JosSKNjO8Y8M9ezq6vmVLNbwLGCIvY9nGEmW>
NEL: {"success_fraction":0,"report_to":"cf-nel","max_age":604800}
Server: cloudflare
CF-RAY: 6a84f00bfb4e5c38-FRA
Content-Encoding: gzip
alt-svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400, h3-28=":443"; ma=86400, h3-27=":443"; ma=86400

{"status": "pending", "expires": "2021-11-04T10:25:46.817Z", "identifier": {"type": "dns", "value": "..."}, "challenges": [{"url": "https://acme.castle.cloud/acme/chall/3P2yQ9vY8Kk>
2021-11-03 11:32:16,084:DEBUG:acme.client:Storing nonce: 5s-qaKSAKwPWvsHoY9tluA
2021-11-03 11:32:16,086:DEBUG:certbot._internal.error_handler:Encountered exception:
Traceback (most recent call last):
  File "/home/david/.local/lib/python3.9/site-packages/certbot/_internal/auth_handler.py", line 90, in handle_authorizations
    self._poll_authorizations(authzrs, max_retries, best_effort)
  File "/home/david/.local/lib/python3.9/site-packages/certbot/_internal/auth_handler.py", line 182, in _poll_authorizations
    raise errors.AuthorizationError('All authorizations were not finalized by the CA.')
certbot.errors.AuthorizationError: All authorizations were not finalized by the CA.

2021-11-03 11:32:16,086:DEBUG:certbot._internal.error_handler:Calling registered functions
2021-11-03 11:32:16,087:INFO:certbot._internal.auth_handler:Cleaning up challenges
2021-11-03 11:32:16,087:DEBUG:imapclient.imaplib:> b'PCAM6 LOGOUT'
2021-11-03 11:32:16,112:DEBUG:imapclient.imaplib:< b'* BYE Logging out'
2021-11-03 11:32:16,112:DEBUG:imapclient.imaplib:       matched b'\\* (?P<type>[A-Z-]+)( (?P<data>.*))?' => (b'BYE', b' Logging out', b'Logging out')
2021-11-03 11:32:16,113:DEBUG:imapclient.imaplib:untagged_responses[BYE] 0 += ["b'Logging out'"]
2021-11-03 11:32:16,113:DEBUG:imapclient.imaplib:BYE response: b'Logging out'
2021-11-03 11:32:16,113:DEBUG:imapclient.imapclient:Logged out, connection closed
2021-11-03 11:32:16,115:DEBUG:certbot._internal.log:Exiting abnormally:
Traceback (most recent call last):
  File "/home/david/sys/software/acme_email/cli.py", line 166, in <module>
    main(args)
  File "/home/david/sys/software/acme_email/cli.py", line 119, in main
    request_cert(args, config)
  File "/home/david/sys/software/acme_email/cli.py", line 91, in request_cert
    cert_path, chain_path, fullchain_path = certbot_main._csr_get_and_save_cert(config, le_client)
  File "/home/david/.local/lib/python3.9/site-packages/certbot/_internal/main.py", line 1353, in _csr_get_and_save_cert
    cert, chain = le_client.obtain_certificate_from_csr(csr)
  File "/home/david/.local/lib/python3.9/site-packages/certbot/_internal/client.py", line 295, in obtain_certificate_from_csr
    orderr = self._get_order_and_authorizations(csr.data, best_effort=False)
  File "/home/david/.local/lib/python3.9/site-packages/certbot/_internal/client.py", line 434, in _get_order_and_authorizations
    authzr = self.auth_handler.handle_authorizations(orderr, self.config, best_effort)
  File "/home/david/.local/lib/python3.9/site-packages/certbot/_internal/auth_handler.py", line 90, in handle_authorizations
    self._poll_authorizations(authzrs, max_retries, best_effort)
  File "/home/david/.local/lib/python3.9/site-packages/certbot/_internal/auth_handler.py", line 182, in _poll_authorizations
    raise errors.AuthorizationError('All authorizations were not finalized by the CA.')
certbot.errors.AuthorizationError: All authorizations were not finalized by the CA.
2021-11-03 11:32:16,117:ERROR:certbot._internal.log:All authorizations were not finalized by the CA.
DDvO commented 2 years ago

A further attempt started at 2021-11-03 11:56:56,693 and ended after many message exchanges at 2021-11-03 12:03:28,244 with the same ERROR:certbot._internal.log:All authorizations were not finalized by the CA.

polhenarejos commented 2 years ago

I made lots of changes and added more logging stuff to the server to track your issue. Your emailed challenge is received (and processed) by the server but for unknown reason it does not respond. I enabled a full debug log, so I you can try again I would have more information. Thanks!