Bug 2015102

Summary: ipa-getcert request fails with JSON-RPC error: 903: an internal error has occurred
Product: [Fedora] Fedora Reporter: Martin Pitt <mpitt>
Component: certmongerAssignee: Rob Crittenden <rcritten>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: rawhideCC: abokovoy, cheimes, ftrivino, ipa-maint, jcholast, jeremy, jhrozek, mharmsen, mhjacks, nalin, nick, npmccallum, pvoborni, rcritten, ssorce, terrycwk1994, twoerner
Target Milestone: ---Keywords: Regression, Reopened
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: certmonger-0.79.14-2.fc34 certmonger-0.79.14-2.fc33 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-10-27 02:08:28 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
/var/log none

Description Martin Pitt 2021-10-18 12:06:40 UTC
Description of problem: Our Cockpit CI uses freeipa through the quay.io/freeipa/freeipa-server:fedora-rawhide [1] container on Fedora CoreOS. A recent version broke ipa-getcert [2]: The .key is still written, but not the .cert file.


Version-Release number of selected component (if applicable):

freeipa-server-4.9.7-2.fc36.1.x86_64

How reproducible: Always


Steps to Reproduce:
1. Join a domain

2. Request a certificate:
   ipa-getcert request -f /etc/pki/tls/ipa.cert -k /etc/pki/tls/private/ipa.key -K HTTP/$(hostname -f) -w -v

3. Check certificate:
   # ls -l /etc/pki/tls/ipa.cert /etc/pki/tls/private/ipa.key

Actual results:

2.

New signing request "20211018120057" added.
State NEWLY_ADDED_READING_KEYINFO, stuck: no.
State SUBMITTING, stuck: no.
State CA_UNREACHABLE, stuck: no.

3.
ls: cannot access '/etc/pki/tls/ipa.cert': No such file or directory
-rw-------. 1 root root 1704 Oct 18 12:00 /etc/pki/tls/private/ipa.key

Journal output:

2021-10-18 12:00:57 [3807] Setting "CERTMONGER_REQ_SUBJECT" to "CN=x0.cockpit.lan" for child.
2021-10-18 12:00:57 [3807] Setting "CERTMONGER_REQ_PRINCIPAL" to "HTTP/x0.cockpit.lan" for child.
2021-10-18 12:00:57 [3807] Setting "CERTMONGER_OPERATION" to "SUBMIT" for child.
2021-10-18 12:00:57 [3807] Setting "CERTMONGER_CSR" to "-----BEGIN NEW CERTIFICATE REQUEST-----
MIIDTzCCAjcCAQAwGTEXMBUGA1UEAxMOeDAuY29ja3BpdC5sYW4wggEiMA0GCSqG
SIb3DQEBAQUAA4IBDwAwggEKAoIBAQDYuuKn2SMMObuqhHYCgqzBh2Vg2+lmWCYR
XGdSYRkXe3j4206mOmQE1aqFP4C3QlOcVUPgdFLRQ3qe/aPpF2YIiSBJZ6Fuh6r+
nE8yInmK2nECwV1d5kfHSEKZTjbDsSRQ5kPQoDy7LoFL1LbHhRmDgt9xaZ7eG3tr
t5r8YSZqj7VcOsJNANVKg8cAKjm0Homl/5yyXs6L7yMj1KJRafCpaFsArLXcexIu
uMs6ooZ2YRBCNqCubovtPW117Rd8Ds42ZfdDehSyXNdLes7DWVwSQ/HFnAsx1C5+
7V2pFFOFEko7qUNw52OaG/veaVnTwOnttL2gV+qVP5z9EeiWeEaJAgMBAAGggfAw
KwYJKoZIhvcNAQkUMR4eHAAyADAAMgAxADEAMAAxADgAMQAyADAAMAA1ADcwgcAG
CSqGSIb3DQEJDjGBsjCBrzB9BgNVHREBAQAEczBxoC8GCisGAQQBgjcUAgOgIQwf
SFRUUC94MC5jb2NrcGl0LmxhbkBDT0NLUElULkxBTqA+BgYrBgEFAgKgNDAyoA0b
C0NPQ0tQSVQuTEFOoSEwH6ADAgEBoRgwFhsESFRUUBsOeDAuY29ja3BpdC5sYW4w
DAYDVR0TAQH/BAIwADAgBgNVHQ4BAQAEFgQUYwaIkSd0b0bTS/XTmc7NEBb0rUUw
DQYJKoZIhvcNAQELBQADggEBAEip/DMLVJbnVwq4EgwHM2dtpTYxFtHRrj1lw0Jc
b45j7Wbcxu/ItMWc8lh0vtGnuOaQ/CrWozLy6xEzv5KDiybzMGT9ZxyTXBZnFHqy
tgHFosAXLkIChbige6xpmbXAlemZuOUKgtCjsOwuVhK3g0F21svBxJbNIVi/bs1q
4aL1P21odeU7KCtgL0RGzGVipKTshfI5kabH/k5WJEd7nlBkFBcVyRWuNQvOO0Wi
cZaBFK1eR9hpl1r25IMrYlfU6Ayj8l4gVrRAZ2vGfg6SZZWVk4o8zljHUIFf+NxH
okvNVe9cC3ESfQWsVQODFJdnKUlp+4gSdRJcexH9DG1ZIGI=
-----END NEW CERTIFICATE REQUEST-----
" for child.
2021-10-18 12:00:57 [3807] Setting "CERTMONGER_SPKAC" to "MIICQDCCASgwggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQDYuuKn2SMMObuqhHYCgqzBh2Vg2+lmWCYRXGdSYRkXe3j4206mOmQE1aqFP4C3QlOcVUPgdFLRQ3qe/aPpF2YIiSBJZ6Fuh6r+nE8yInmK2nECwV1d5kfHSEKZTjbDsSRQ5kPQoDy7LoFL1LbHhRmDgt9xaZ7eG3trt5r8YSZqj7VcOsJNANVKg8cAKjm0Homl/5yyXs6L7yMj1KJRafCpaFsArLXcexIuuMs6ooZ2YRBCNqCubovtPW117Rd8Ds42ZfdDehSyXNdLes7DWVwSQ/HFnAsx1C5+7V2pFFOFEko7qUNw52OaG/veaVnTwOnttL2gV+qVP5z9EeiWeEaJAgMBAAEWADANBgkqhkiG9w0BAQsFAAOCAQEAtTHujP83EFBwaI7SR4FDB+KGwRRXwWmIHNIvZguZ+oj68RnxzqACNSFRHrWlKordcPQ0ITA8dSHv9W8KG7pBotvjS3Us51f5EBpahA7NlUIERSu52Kjw/5m4qEO2GbG388LCyFimJYcF8Mpv2XakxLKigxEP8NN7oLr39G5XaDhfqTDo+pa4cyZQIMwvsy0/Ud4pBPPMS65NUhOmUTbRspitkQ7jisJDDruuEjL2uvjYXqGZ5dppKbNkDJIhdwE1eL68MGG8ditIsCQ2WD/TuG5LDxoE/C+kP83ZqbcJU8ZtDfDbx9gNaTsAnLkee7bSxkQrW5ljI8D/XiZR/TepCQ==" for child.
2021-10-18 12:00:57 [3807] Setting "CERTMONGER_SPKI" to "MIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEA2Lrip9kjDDm7qoR2AoKswYdlYNvpZlgmEVxnUmEZF3t4+NtOpjpkBNWqhT+At0JTnFVD4HRS0UN6nv2j6RdmCIkgSWehboeq/pxPMiJ5itpxAsFdXeZHx0hCmU42w7EkUOZD0KA8uy6BS9S2x4UZg4LfcWme3ht7a7ea/GEmao+1XDrCTQDVSoPHACo5tB6Jpf+csl7Oi+8jI9SiUWnwqWhbAKy13HsSLrjLOqKGdmEQQjagrm6L7T1tde0XfA7ONmX3Q3oUslzXS3rOw1lcEkPxxZwLMdQufu1dqRRThRJKO6lDcOdjmhv73mlZ08Dp7bS9oFfqlT+c/RHolnhGiQIDAQAB" for child.
2021-10-18 12:00:57 [3807] Setting "CERTMONGER_LOCAL_CA_DIR" to "/var/lib/certmonger/local" for child.
2021-10-18 12:00:57 [3807] Setting "CERTMONGER_KEY_TYPE" to "RSA" for child.
2021-10-18 12:00:57 [3807] Setting "CERTMONGER_CA_NICKNAME" to "IPA" for child.
2021-10-18 12:00:57 [3807] Redirecting stdin to /dev/null, leaving stdout and stderr open for child "/usr/libexec/certmonger/ipa-submit".
2021-10-18 12:00:57 [3807] Running enrollment helper "/usr/libexec/certmonger/ipa-submit".
Submitting request to "https://f0.cockpit.lan/ipa/json".
JSON-RPC error: 903: an internal error has occurred
GSSAPI client step 1
GSSAPI client step 1
GSSAPI client step 1
GSSAPI client step 1
GSSAPI client step 2
2021-10-18 12:00:58 [2636] Certificate submission still ongoing.
2021-10-18 12:00:58 [2636] Certificate submission attempt complete.
2021-10-18 12:00:58 [2636] Child status = 3.
2021-10-18 12:00:58 [2636] Child output:
"Server at https://f0.cockpit.lan/ipa/json failed request, will retry: 903 (an internal error has occurred).
"
2021-10-18 12:00:58 [2636] Server at https://f0.cockpit.lan/ipa/json failed request, will retry: 903 (an internal error has occurred).
2021-10-18 12:00:58 [2636] Certificate not (yet?) issued.



Expected results: Certificate gets created


Additional info:

Last known version to work was freeipa-server-4.9.6-3.fc35 (sorry, we don't refresh that image very often). Our currently pending image refresh actually has a slightly older version 4.9.7-1, so at first sight this *could* have been bug 2014658. But I updated to the latest container (version -2) with the fix, and same issue.


[1] https://quay.io/repository/freeipa/freeipa-server?tab=tags
[2] https://github.com/cockpit-project/bots/pull/2524

Comment 1 Alexander Bokovoy 2021-10-18 12:10:42 UTC
You need to wait until https://koji.fedoraproject.org/koji/buildinfo?buildID=1845811 is in Rawhide compose and freeipa-container is rebuilt.
I'll mark this as a duplicate of bug #2014658

*** This bug has been marked as a duplicate of bug 2014658 ***

Comment 2 Martin Pitt 2021-10-18 12:16:54 UTC
Hello Alexander,

as I wrote in the description, I already did that:

> at first sight this *could* have been bug 2014658. But I updated to the latest container (version -2) with the fix, and same issue.

. -2 is in Rawhide: https://bodhi.fedoraproject.org/updates/FEDORA-2021-7dac22d63a , and quay.io has an up to date container. This is *not* a duplicate.

Comment 3 Alexander Bokovoy 2021-10-18 12:27:03 UTC
Do you have httpd's error_log and PKI logs?

I cannot find them in your PR's logs. Without server's logs it is hard to see what else is broken in recent PKI's removal of XML-RPC support.

Comment 4 Martin Pitt 2021-10-18 12:41:42 UTC
Created attachment 1834215 [details]
/var/log

Indeed error_log has something that looks very relevant:

ipa: ERROR: non-public: ValueError: error parsing asn1 value: ParseError { kind: EncodedDefault, location: ["0", "Extension::critical"] }
Traceback (most recent call last):
  File "/usr/lib/python3.10/site-packages/ipaserver/rpcserver.py", line 405, in wsgi_execute
    result = command(*args, **options)
  File "/usr/lib/python3.10/site-packages/ipalib/frontend.py", line 471, in __call__
    return self.__do_call(*args, **options)
  File "/usr/lib/python3.10/site-packages/ipalib/frontend.py", line 499, in __do_call
    ret = self.run(*args, **options)
  File "/usr/lib/python3.10/site-packages/ipalib/frontend.py", line 821, in run
    return self.execute(*args, **options)
  File "/usr/lib/python3.10/site-packages/ipaserver/plugins/cert.py", line 719, in execute
    ext_san = csr.extensions.get_extension_for_oid(
ValueError: error parsing asn1 value: ParseError { kind: EncodedDefault, location: ["0", "Extension::critical"] }
ipa: INFO: [jsonserver_kerb] host/x0.cockpit.lan: cert_request('MIIDTzCCAjcCAQAwGTEXMBUGA1UEAxMOeDAuY29ja3BpdC5sYW4wggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQC9L2/NsS/B6qMywcUeqpgd9DtGRT7WjCRLGZSOt50+pfDYjP9NLLZAlHGFEqivlYrXhfP/rrOYmznZBwmAin7+f2SLIzcpKs1HEc8UoPtr9Tuf6gjYdFofGo94fjGjeZsax9pMFKAPc6Icm1YOqgzX1EZQ0OR2okvVV9p4lW14hy1xMZcDBmMvLovH+nABSeDwe4ucpdG/cE+yfwKEvirW7zx8Glc2hrzPaqBNBgIUcfZkfD8Nn+QAzx3JelI1u6D2qOaYDk9KQm0Z8MN5nXDYa4AbpjTnGRB2IOykFFSMA4OSwKxl3duH0P0vJ/ab8VjIAk3lRGvp3Baq7lgEgTnjAgMBAAGggfAwKwYJKoZIhvcNAQkUMR4eHAAyADAAMgAxADEAMAAxADgAMQAyADMANwAzADcwgcAGCSqGSIb3DQEJDjGBsjCBrzB9BgNVHREBAQAEczBxoC8GCisGAQQBgjcUAgOgIQwfSFRUUC94MC5jb2NrcGl0LmxhbkBDT0NLUElULkxBTqA+BgYrBgEFAgKgNDAyoA0bC0NPQ0tQSVQuTEFOoSEwH6ADAgEBoRgwFhsESFRUUBsOeDAuY29ja3BpdC5sYW4wDAYDVR0TAQH/BAIwADAgBgNVHQ4BAQAEFgQUglxkOudA1OQlVy0HBnAk23DoN9IwDQYJKoZIhvcNAQELBQADggEBAAyvaMeDs0MZ4b7TUIDr9HPVeulIQs6vs7lUVvZnnoCui2jEt8ydZiCIh/98LdlB5D6iLkQOlaM7AHnuSXwyKjNQMRz5nRMVCwg48atXeT/eDBYuONYn0+oBd3q7vDrsKEl+M3UabGaiPE1hqf1kkIj5k7s7t9t1qQl5hxGYQKU3z1h1s3mP+4xBt4M8hneXibP4kuB/zDVbXiZB5ViSTmHENfVPLNZ5w18BZv6BoQzpkOM5r+E8YiVDKfNajR7q02P24urI8eFbWgAvE+gmQvUS3nUHOqO6OCG09JZ+DEvdXh8tnKSow/CF61RpgyDaazOFDoV16D8huDeyndnV+R4=', principal='HTTP/x0.cockpit.lan', add=True): InternalError

I'll attach the complete /var/log from the container, in case it has something else that is interesting.

Comment 5 Alexander Bokovoy 2021-10-18 12:47:09 UTC
Ah, this is python-cryptography 35.0 issue: https://github.com/pyca/cryptography/issues/6340

We saw that in Rawhide just this weekend in IPA CI runs: http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/1ae3e78e-2eab-11ec-8838-fa163ef390f3/report.html

----
A few tests failed because of python cryptography issue #6340: CSR with 'BEGIN NEW CERTIFICATE REQUEST' no longer accepted (external_ca_TestExternalCAInvalidCert, external_ca_TestMultipleExternalCA, external_ca_TestExternalCAdirsrvStop, external_ca_templates, test_acme, test_caless_TestServerCALessToExternalCA, test_external_ca_TestExternalCA, test_ipahealthcheck_nodns_extca_file). There is already an upstream fix but no rawhide build yet.
----

python-cryptography update is not yet in Rawhide.

Comment 6 Alexander Bokovoy 2021-10-18 12:58:59 UTC
I will move this to python-cryptography for awareness.

Comment 7 Rob Crittenden 2021-10-18 13:04:15 UTC
What version of certmonger is this?

Comment 8 Christian Heimes 2021-10-18 13:08:19 UTC
This is actually a certmonger bug that was revealed by a new ASN.1 parser in python-cryptography. The new parser does not accept invalid ASN.1 DER. The problem should be fixed by certmonger-0.79.14-6.fc36. The update https://bodhi.fedoraproject.org/updates/FEDORA-2021-1881de28ed is in Rawhide.

Upstream python-cryptography has agreed to accept a temporary workaround for backwards compatibility. The workaround is still work in progress.

Comment 9 Martin Pitt 2021-10-18 13:15:03 UTC
Rob: certmonger-0.79.14-6.fc36.x86_64 on the server side (in the container), certmonger-0.79.14-2.fc35.x86_64 on the client side; I'm not sure which one is relevant.

Comment 10 Christian Heimes 2021-10-18 13:18:56 UTC
The relevant side is side that generates the CSR. In your case it's the client. 

https://bodhi.fedoraproject.org/updates/FEDORA-2021-08cd0d66af is not available in F35 yet. Could you please verify the update?

Comment 11 Martin Pitt 2021-10-18 14:13:53 UTC
On the client side I ran

    dnf update --enablerepo=updates-testing certmonger

which pulled in certmonger-0.79.14-3.fc35 from that bodhi update. I confirm that this works.

There is no corresponding fix for Fedora 34, so I can't test it there. Is this still planned? As that seems to break "over the wire" compatibility, all supported Fedora/RHEL versions ought to get that fix?

Thanks for tracking this down!

Comment 12 Rob Crittenden 2021-10-18 15:04:36 UTC
I'm working on builds for 33 and 34.

Comment 13 Fedora Update System 2021-10-18 15:33:08 UTC
FEDORA-2021-bf70829200 has been submitted as an update to Fedora 33. https://bodhi.fedoraproject.org/updates/FEDORA-2021-bf70829200

Comment 14 Fedora Update System 2021-10-19 00:48:15 UTC
FEDORA-2021-df9eee3325 has been pushed to the Fedora 34 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2021-df9eee3325`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2021-df9eee3325

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 15 Fedora Update System 2021-10-19 01:29:11 UTC
FEDORA-2021-bf70829200 has been pushed to the Fedora 33 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2021-bf70829200`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2021-bf70829200

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 16 Martin Pitt 2021-10-19 04:54:50 UTC
I tested the F34 update [1] and this works again. (Still a bit sad that e.g. stable Debian or CentOS 7/8 clients will be broken with 4.9.7)

Thanks!

[1] https://bodhi.fedoraproject.org/updates/FEDORA-2021-df9eee3325

Comment 17 Rob Crittenden 2021-10-19 11:40:42 UTC
I believe that python-cryptography is going to add an option to relax this validation which will help with unpatched certmonger releases.

Comment 18 Fedora Update System 2021-10-27 02:08:28 UTC
FEDORA-2021-df9eee3325 has been pushed to the Fedora 34 stable repository.
If problem still persists, please make note of it in this bug report.

Comment 19 Fedora Update System 2021-10-27 03:04:19 UTC
FEDORA-2021-bf70829200 has been pushed to the Fedora 33 stable repository.
If problem still persists, please make note of it in this bug report.