Bug 2164348

When a user is doing ipa cert-find, the operation triggers a search in PKI (through an HTTP POST ca/rest/certs/search?size=2147483647). PKI performs a LDAP search with VLV that can return err=4 (sizelimit exceeded) but does not properly handle this case.

When LDAP returns err=4, PKI tries to decode the result as a LDAPEntry even though it received a netscape.ldap.LDAPException. This triggers the following error in ca/debug logs:
2023-02-02 11:34:30 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-7] SEVERE: Operation Error - netscape.ldap.LDAPException cannot be cast to netscape.ldap.LDAPEntry
java.lang.ClassCastException: netscape.ldap.LDAPException cannot be cast to netscape.ldap.LDAPEntry
        at com.netscape.cmscore.dbs.DBVirtualList.getEntries(DBVirtualList.java:482)
        at com.netscape.cmscore.dbs.DBVirtualList.getPage(DBVirtualList.java:617)
        at com.netscape.cmscore.dbs.DBVirtualList.getPage(DBVirtualList.java:609)
        at com.netscape.cmscore.dbs.DBVirtualList.getElementAt(DBVirtualList.java:763)
        at com.netscape.cmscore.dbs.CertRecordList.getCertRecord(CertRecordList.java:142)
        at org.dogtagpki.server.ca.rest.CertService.searchCerts(CertService.java:503)

The data returned to the POST operation (=received by IPA) is then the following:
status, _, data = dogtag.https_request(...)

status = 500
data = b'<?xml version="1.0" encoding="UTF-8" standalone="yes"?><PKIException><Attributes/><ClassName>com.netscape.certsrv.base.PKIException</ClassName><Code>500</Code><Message>Unable to search for certificates: java.lang.ClassCastException: netscape.ldap.LDAPException cannot be cast to netscape.ldap.LDAPEntry</Message></PKIException>'

IPA checks the status and if != 200 raises an Exception with the information from the status only:
        if status != 200:
            self.raise_certificate_operation_error('find',
                                                   detail=status)

IPA could parse the output from the data field and include this information in the exception, and call instead self.raise_certificate_operation_error('find',err_msg=<to be filled>, detail=status).
The err_msg would then be logged instead of "Unable to communicate with CMS" which is not specific enough.

But IMO PKI should fix the Exception on its side and return a clean error message, that could be easily understood by the user.

flo do you remember how you reproduced this?

(In reply to Rob Crittenden from comment #3)
> flo do you remember how you reproduced this?

Yes, I defined a sizelimit for uid=pkidbuser. The trick is to pick something big enough that allows pki to start (pkidbuser is performing searches for the certificate profiles for instance, and there are ~90 entries, so I picked nsSizeLimit= 100).

# ldapmodify -D cn=directory\ manager -w Secret123 
dn: uid=pkidbuser,ou=people,o=ipaca
changetype: modify
add: nssizelimit                    
nssizelimit: 100

# ipactl restart
(restart pki is needed to re-establish a new connection between pki and 389ds and take into account the new sizelimit for uid=pkidbuser)

# ipa cert-find
(if there are < 100 certificates, should succeed)

Create enough certificates to reach the limit

# ipa cert-find
ipa: ERROR: Certificate operation cannot be completed: Unable to communicate with CMS (500)

The logs in /var/log/pki/pki-tomcat/ca/debug.$DATE.log show all the certs returned up to 100 and then the failure:
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] INFO: Searching for certificates
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] INFO: PKIService: Request class: CertSearchRequest
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] INFO: PKIService: Request format: application/xml
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] INFO: PKIService: XML request:
<?xml version='1.0' encoding='UTF-8'?>
<CertSearchRequest><serialNumberRangeInUse>true</serialNumberRangeInUse><subjectInUse>false</subjectInUse><matchExactly>false</matchExactly><revokedByInUse>false</revokedByInUse><revokedOnInUse>false</revokedOnInUse><revocationReasonInUse>false</revocationReasonInUse><issuedByInUse>false</issuedByInUse><issuedOnInUse>false</issuedOnInUse><validNotBeforeInUse>false</validNotBeforeInUse><validNotAfterInUse>false</validNotAfterInUse><validityLengthInUse>false</validityLengthInUse><certTypeInUse>false</certTypeInUse></CertSearchRequest>
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] INFO: Search filter: (certstatus=*)
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] INFO: DBVirtualList: Searching ou=certificateRepository, ou=ca,o=ipaca
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] INFO: DBVirtualList: filter: (certStatus=*)
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] INFO: DBVirtualList: dn: cn=101,ou=certificateRepository,ou=ca,o=ipaca
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] INFO: Search results: 101
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] INFO: DBVirtualList: Searching ou=certificateRepository, ou=ca,o=ipaca
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] INFO: DBVirtualList: filter: (certStatus=*)
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] INFO: DBVirtualList: dn: cn=1,ou=certificateRepository,ou=ca,o=ipaca
...
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] INFO: DBVirtualList: dn: cn=100,ou=certificateRepository,ou=ca,o=ipaca
2023-04-25 06:51:31 [ajp-nio-0:0:0:0:0:0:0:1-8009-exec-1] SEVERE: Operation Error - class netscape.ldap.LDAPException cannot be cast to class netscape.ldap.LDAPEntry (netscape.ldap.LDAPException and netscape.ldap.LDAPEntry are in unnamed module of loader java.net.URLClassLoader @5e8c92f4)
java.lang.ClassCastException: class netscape.ldap.LDAPException cannot be cast to class netscape.ldap.LDAPEntry (netscape.ldap.LDAPException and netscape.ldap.LDAPEntry are in unnamed module of loader java.net.URLClassLoader @5e8c92f4)

The new message will be (proposed): ipa: ERROR: Certificate operation cannot be completed: Unable to search for certificates (500)

We get no indication of the reason for the search failure. I suppose this is message is better in that it doesn't imply that the CA is not available at all.

Fixed upstream
master:
https://pagure.io/freeipa/c/9e80616401fe878f4db9dcd5b6188c0b2039db53

Fixed upstream
ipa-4-9:
https://pagure.io/freeipa/c/b9b268e5ed497400b3525b0eec95e2ae4f039526

Fixed upstream
ipa-4-10:
https://pagure.io/freeipa/c/81a6b9ad2d42fecdd94e17fa7c888bbdea2daf3c

version:
ipa-server-4.9.12-2.module+el8.9.0+18921+013c0de2.x86_64

Steps:
https://bugzilla.redhat.com/show_bug.cgi?id=2164348#c4

Actual result:
when number of cert > nssizelimit

[root@master ~]# ldapmodify -D cn=Directory\ Manager -w Secret123
dn: uid=pkidbuser,ou=people,o=ipaca
changetype: modify
add: nssizelimit
nssizelimit: 100

modifying entry "uid=pkidbuser,ou=people,o=ipaca"

^C
[root@master ~]# ipactl restart
Restarting Directory Service
Restarting krb5kdc Service
Restarting kadmin Service
Restarting named Service
Restarting httpd Service
Restarting ipa-custodia Service
Restarting pki-tomcatd Service
Restarting ipa-otpd Service
Restarting ipa-dnskeysyncd Service
ipa: INFO: The ipactl command was successful
[root@master ~]# ipa cert-find
ipa: ERROR: Certificate operation cannot be completed: Unable to search for certificates (500)
[root@master ~]# 
[root@master ~]# 


when number of cert < nssizelimit:

[root@master ~]# ldapmodify -D cn=Directory\ Manager -w Secret123
dn: uid=pkidbuser,ou=people,o=ipaca
changetype: modify
replace: nssizelimit
nssizelimit: 200

modifying entry "uid=pkidbuser,ou=people,o=ipaca"

^C
[root@master ~]# 
[root@master ~]# ipactl restart
Restarting Directory Service
Restarting krb5kdc Service
Restarting kadmin Service
Restarting named Service
Restarting httpd Service
Restarting ipa-custodia Service
Restarting pki-tomcatd Service
Restarting ipa-otpd Service
Restarting ipa-dnskeysyncd Service
ipa: INFO: The ipactl command was successful
[root@master ~]# 
[root@master ~]# 
[root@master ~]# ipa cert-find
------------------------
100 certificates matched
------------------------

[..]

  Issuing CA: ipa
  Subject: CN=tuser90,O=TESTRELM.TEST
  Issuer: CN=Certificate Authority,O=TESTRELM.TEST
  Not Before: Thu Jun 08 07:13:13 2023 UTC
  Not After: Sun Jun 08 07:13:13 2025 UTC
  Serial number: 100
  Serial number (hex): 0x64
  Status: VALID
  Revoked: False
------------------------------
Number of entries returned 100
------------------------------
[root@master ~]#

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (idm:client and idm:DL1 bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2023:6977