Bug 1658280

Summary:	[RFE] FreeIPA/Dogtag - Slow host deletion due to certificate pagination
Product:	Red Hat Enterprise Linux 8	Reporter:	JaredL <jaredl>
Component:	pki-core	Assignee:	RHCS Maintainers <rhcs-maint>
Status:	CLOSED WONTFIX	QA Contact:	Asha Akkiangady <aakkiang>
Severity:	medium	Docs Contact:
Priority:	high
Version:	8.3	CC:	cheimes, gparente, jaredl, mharmsen, msauton, pcech, tmihinto
Target Milestone:	rc	Keywords:	FutureFeature, Reopened, Triaged
Target Release:	---	Flags:	pm-rhel: mirror+
Hardware:	x86_64
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2021-10-31 07:26:53 UTC	Type:	Feature Request
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:	1851495
Bug Blocks:

Description JaredL 2018-12-11 16:46:37 UTC

Description of problem:
Related pki-users email thread: https://www.redhat.com/archives/pki-users/2018-December/msg00003.html

Currently, on FreeIPA, if you execute 'ipa host-del FQDN_HERE', FreeIPA searches Dogtag, which then searches 389-ds for all of the certificates. This appears to then be used to figure out which certificate needs to be revoked. 

The problem is, if you have many many certificates stored in 'ou=certificateRepository,ou=ca,o=ipaca', this search request is paginated at 2000 entires per search. This in turn, yields very slow host deletion operations. Currently, it takes ~10 seconds to page through our 133,000 certificates, and this is done for each service added to a host, of which we average ~5 services. That results in ~1 minute where we simply page through results from 389-ds. When terminating our test stacks of 100+ hosts, this results in at least 1 hour of time spent just deleting hosts from FreeIPA. 

389-ds access logs from the search operation during host deletion:
[04/Dec/2018:22:01:22.353689552 +0000] conn=349 op=177328 SRCH base="cn=267229053,ou=certificateRepository,ou=ca,o=ipaca" scope=0 filter="(objectClass=*)" attrs=ALL
[04/Dec/2018:22:01:22.353917051 +0000] conn=349 op=177328 RESULT err=0 tag=101 nentries=1 etime=0.0000345716
[04/Dec/2018:22:01:22.362894108 +0000] conn=349 op=177329 SRCH base="cn=13421710098,ou=certificateRepository,ou=ca,o=ipaca" scope=0 filter="(objectClass=*)" attrs=ALL
[04/Dec/2018:22:01:22.363067550 +0000] conn=349 op=177329 RESULT err=0 tag=101 nentries=1 etime=0.0000233928
[04/Dec/2018:22:01:22.364035899 +0000] conn=349 op=177330 SRCH base="cn=13421710098,ou=certificateRepository,ou=ca,o=ipaca" scope=0 filter="(objectClass=*)" attrs=ALL
[04/Dec/2018:22:01:22.364180832 +0000] conn=349 op=177330 RESULT err=0 tag=101 nentries=1 etime=0.0000196279
[04/Dec/2018:22:01:22.365242679 +0000] conn=349 op=177331 SRCH base="cn=13421710098,ou=certificateRepository,ou=ca,o=ipaca" scope=0 filter="(objectClass=*)" attrs=ALL
[04/Dec/2018:22:01:22.365395395 +0000] conn=349 op=177331 RESULT err=0 tag=101 nentries=1 etime=0.0000203993
[04/Dec/2018:22:01:22.366354393 +0000] conn=349 op=177332 SRCH base="cn=319992896,ou=ca,ou=requests,o=ipaca" scope=0 filter="(objectClass=*)" attrs=ALL
[04/Dec/2018:22:01:22.367638687 +0000] conn=349 op=177332 RESULT err=0 tag=101 nentries=1 etime=0.0001335667
[04/Dec/2018:22:01:22.538161912 +0000] conn=349 op=177333 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(serialno=1113421710098)" attrs=ALL
[04/Dec/2018:22:01:22.538412551 +0000] conn=349 op=177333 RESULT err=0 tag=101 nentries=1 etime=0.0000311176
[04/Dec/2018:22:01:22.539778415 +0000] conn=349 op=177334 SRCH base="cn=13421710098,ou=certificateRepository,ou=ca,o=ipaca" scope=0 filter="(objectClass=*)" attrs=ALL
[04/Dec/2018:22:01:22.539928413 +0000] conn=349 op=177334 RESULT err=0 tag=101 nentries=1 etime=0.0000190421
[04/Dec/2018:22:01:22.540800585 +0000] conn=349 op=177335 MOD dn="cn=13421710098,ou=certificateRepository,ou=ca,o=ipaca"
[04/Dec/2018:22:01:22.543326198 +0000] conn=349 op=177335 RESULT err=0 tag=103 nentries=0 etime=0.0002577198 csn=5c073167000005d70000
[04/Dec/2018:22:01:22.544166829 +0000] conn=349 op=177336 ADD dn="cn=420042843,ou=ca,ou=requests,o=ipaca"
[04/Dec/2018:22:01:22.546276345 +0000] conn=349 op=177336 RESULT err=0 tag=105 nentries=0 etime=0.0002342080 csn=5c073167000105d70000
[04/Dec/2018:22:01:22.547311934 +0000] conn=349 op=177337 SRCH base="cn=420042843,ou=ca,ou=requests,o=ipaca" scope=0 filter="(objectClass=*)" attrs=ALL
[04/Dec/2018:22:01:22.547467434 +0000] conn=349 op=177337 RESULT err=0 tag=101 nentries=1 etime=0.0000208434
[04/Dec/2018:22:01:22.548459069 +0000] conn=349 op=177338 SRCH base="cn=13421710098,ou=certificateRepository,ou=ca,o=ipaca" scope=0 filter="(objectClass=*)" attrs=ALL
[04/Dec/2018:22:01:22.548668390 +0000] conn=349 op=177338 RESULT err=0 tag=101 nentries=1 etime=0.0000269301
[04/Dec/2018:22:01:22.549572124 +0000] conn=349 op=177339 SRCH base="cn=319992896,ou=ca,ou=requests,o=ipaca" scope=0 filter="(objectClass=*)" attrs=ALL
[04/Dec/2018:22:01:22.549856365 +0000] conn=349 op=177339 RESULT err=0 tag=101 nentries=1 etime=0.0000348888
[04/Dec/2018:22:01:22.551641226 +0000] conn=349 op=177340 MOD dn="ou=ca,ou=requests,o=ipaca"
[04/Dec/2018:22:01:22.554637665 +0000] conn=349 op=177340 RESULT err=0 tag=103 nentries=0 etime=0.0003042607 csn=5c073167000205d70000
[04/Dec/2018:22:01:22.569050875 +0000] conn=349 op=177341 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:22.569208733 +0000] conn=349 op=177341 SORT serialno
[04/Dec/2018:22:01:22.569214752 +0000] conn=349 op=177341 VLV 0:2147483647:A 135875:135875 (0)
[04/Dec/2018:22:01:22.569319226 +0000] conn=349 op=177341 RESULT err=0 tag=101 nentries=1 etime=0.0000320009
[04/Dec/2018:22:01:22.570290576 +0000] conn=349 op=177342 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:22.675195769 +0000] conn=349 op=177342 SORT serialno
[04/Dec/2018:22:01:22.675205928 +0000] conn=349 op=177342 VLV 0:2147483647:0:135875 1:135875 (0)
[04/Dec/2018:22:01:22.742856305 +0000] conn=349 op=177342 RESULT err=4 tag=101 nentries=2000 etime=0.0172639590
[04/Dec/2018:22:01:22.845750466 +0000] conn=349 op=177343 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:22.932613795 +0000] conn=349 op=177343 SORT serialno
[04/Dec/2018:22:01:22.932624527 +0000] conn=349 op=177343 VLV 0:2147483647:1999:135875 2000:135875 (0)
[04/Dec/2018:22:01:22.999550411 +0000] conn=349 op=177343 RESULT err=4 tag=101 nentries=2000 etime=0.0153862011
[04/Dec/2018:22:01:23.102999705 +0000] conn=349 op=177344 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:23.188183645 +0000] conn=349 op=177344 SORT serialno
[04/Dec/2018:22:01:23.188194523 +0000] conn=349 op=177344 VLV 0:2147483647:3998:135875 3999:135875 (0)
[04/Dec/2018:22:01:23.254634252 +0000] conn=349 op=177344 RESULT err=4 tag=101 nentries=2000 etime=0.0151710572
[04/Dec/2018:22:01:23.360477493 +0000] conn=349 op=177345 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:23.445642617 +0000] conn=349 op=177345 SORT serialno
[04/Dec/2018:22:01:23.445654409 +0000] conn=349 op=177345 VLV 0:2147483647:5997:135875 5998:135875 (0)
[04/Dec/2018:22:01:23.515206583 +0000] conn=349 op=177345 RESULT err=4 tag=101 nentries=2000 etime=0.0154790512
[04/Dec/2018:22:01:23.615433952 +0000] conn=349 op=177346 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:23.696772041 +0000] conn=349 op=177346 SORT serialno
[04/Dec/2018:22:01:23.696781554 +0000] conn=349 op=177346 VLV 0:2147483647:7996:135875 7997:135875 (0)
[04/Dec/2018:22:01:23.762840149 +0000] conn=349 op=177346 RESULT err=4 tag=101 nentries=2000 etime=0.0147461694
[04/Dec/2018:22:01:23.868742245 +0000] conn=349 op=177347 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:23.951664837 +0000] conn=349 op=177347 SORT serialno
[04/Dec/2018:22:01:23.951674935 +0000] conn=349 op=177347 VLV 0:2147483647:9995:135875 9996:135875 (0)
[04/Dec/2018:22:01:24.017537422 +0000] conn=349 op=177347 RESULT err=4 tag=101 nentries=2000 etime=0.0148853857
[04/Dec/2018:22:01:24.129684044 +0000] conn=349 op=177348 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:24.208696518 +0000] conn=349 op=177348 SORT serialno
[04/Dec/2018:22:01:24.208706913 +0000] conn=349 op=177348 VLV 0:2147483647:11994:135875 11995:135875 (0)
[04/Dec/2018:22:01:24.274740021 +0000] conn=349 op=177348 RESULT err=4 tag=101 nentries=2000 etime=0.0145127322
[04/Dec/2018:22:01:24.378832290 +0000] conn=349 op=177349 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:24.456567599 +0000] conn=349 op=177349 SORT serialno
[04/Dec/2018:22:01:24.456579165 +0000] conn=349 op=177349 VLV 0:2147483647:13993:135875 13994:135875 (0)
[04/Dec/2018:22:01:24.522589100 +0000] conn=349 op=177349 RESULT err=4 tag=101 nentries=2000 etime=0.0143821746
[04/Dec/2018:22:01:24.627481307 +0000] conn=349 op=177350 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:24.705118244 +0000] conn=349 op=177350 SORT serialno
[04/Dec/2018:22:01:24.705128742 +0000] conn=349 op=177350 VLV 0:2147483647:15992:135875 15993:135875 (0)
[04/Dec/2018:22:01:24.770982672 +0000] conn=349 op=177350 RESULT err=4 tag=101 nentries=2000 etime=0.0143559574
[04/Dec/2018:22:01:24.875597116 +0000] conn=349 op=177351 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:24.951756025 +0000] conn=349 op=177351 SORT serialno
[04/Dec/2018:22:01:24.951766111 +0000] conn=349 op=177351 VLV 0:2147483647:17991:135875 17992:135875 (0)
[04/Dec/2018:22:01:25.017000898 +0000] conn=349 op=177351 RESULT err=4 tag=101 nentries=2000 etime=0.0141461012
[04/Dec/2018:22:01:25.118992979 +0000] conn=349 op=177352 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:25.193678841 +0000] conn=349 op=177352 SORT serialno
[04/Dec/2018:22:01:25.193689296 +0000] conn=349 op=177352 VLV 0:2147483647:19990:135875 19991:135875 (0)
[04/Dec/2018:22:01:25.259539854 +0000] conn=349 op=177352 RESULT err=4 tag=101 nentries=2000 etime=0.0140611305
[04/Dec/2018:22:01:25.365196068 +0000] conn=349 op=177353 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:25.438494027 +0000] conn=349 op=177353 SORT serialno
[04/Dec/2018:22:01:25.438505747 +0000] conn=349 op=177353 VLV 0:2147483647:21989:135875 21990:135875 (0)
[04/Dec/2018:22:01:25.503380328 +0000] conn=349 op=177353 RESULT err=4 tag=101 nentries=2000 etime=0.0138253315
[04/Dec/2018:22:01:25.609794856 +0000] conn=349 op=177354 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:25.681053183 +0000] conn=349 op=177354 SORT serialno
[04/Dec/2018:22:01:25.681063741 +0000] conn=349 op=177354 VLV 0:2147483647:23988:135875 23989:135875 (0)
[04/Dec/2018:22:01:25.747151877 +0000] conn=349 op=177354 RESULT err=4 tag=101 nentries=2000 etime=0.0137420338
[04/Dec/2018:22:01:25.900462365 +0000] conn=349 op=177355 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:25.970842549 +0000] conn=349 op=177355 SORT serialno
[04/Dec/2018:22:01:25.970852922 +0000] conn=349 op=177355 VLV 0:2147483647:25987:135875 25988:135875 (0)
[04/Dec/2018:22:01:26.035673669 +0000] conn=349 op=177355 RESULT err=4 tag=101 nentries=2000 etime=0.1864715241
[04/Dec/2018:22:01:26.137368522 +0000] conn=349 op=177356 SRCH base="ou=certificateRepository,ou=ca,o=ipaca" scope=1 filter="(certStatus=*)" attrs=ALL
[04/Dec/2018:22:01:26.207618686 +0000] conn=349 op=177356 SORT serialno
[04/Dec/2018:22:01:26.207630296 +0000] conn=349 op=177356 VLV 0:2147483647:27986:135875 27987:135875 (0)

Working on Freenode, in #dogtag-pki, with cipherboy, we troubleshooted this for a long time. Changing the 389-ds parameter, nsslapd-sizelimit, to 10,000 did not affect this pagination. Looking through the code, we end up here on the FreeIPA side: https://github.com/freeipa/freeipa/blob/master/ipaserver/plugins/dogtag.py#L1867-L1868
and that kicks off the search in dogtag. Then, we are here: https://github.com/dogtagpki/pki/blob/DOGTAG_10_5_1_FEDORA_27/base/server/cmscore/src/com/netscape/cmscore/dbs/DBVirtualList.java#L152 
and then we are https://github.com/dogtagpki/pki/blob/DOGTAG_10_5_1_FEDORA_27/base/ca/src/org/dogtagpki/server/ca/rest/CertService.java#L452 a little later on. Then getEntries is defined here: https://github.com/dogtagpki/pki/blob/DOGTAG_10_5_1_FEDORA_27/base/server/cmscore/src/com/netscape/cmscore/dbs/DBVirtualList.java#L415-L417

I used tcpdump to grab the raw traffic being passed between dogtag and 389-ds during these search operations. It looks like dogtag does not send a specific sizelimit to 389-ds:
Transmission Control Protocol, Src Port: 33990, Dst Port: 389, Seq: 1, Ack: 1, Len: 170
Lightweight Directory Access Protocol
    LDAPMessage searchRequest(48) "ou=certificateRepository, ou=ca, o=ipaca" singleLevel
        messageID: 48
        protocolOp: searchRequest (3)
            searchRequest
                baseObject: ou=certificateRepository, ou=ca, o=ipaca
                scope: singleLevel (1)
                derefAliases: neverDerefAliases (0)
                sizeLimit: 0
                timeLimit: 0
                typesOnly: False
                Filter: (certStatus=*)
                    filter: present (7)
                        present: certStatus
                attributes: 0 items
        [Response In: 19]
        controls: 2 items
            Control
                controlType: 1.2.840.113556.1.4.473 (sortKeyList)
                criticality: True
                SortKeyList: 1 item
                    SortKeyList item
                        attributeType: serialno
            Control
                controlType: 2.16.840.1.113730.3.4.9 (VLV Request LDAPv3 control)
                criticality: True
                controlValue: 300a02010002020bb8810141

As far as I can tell, this means, somewhere on the 389-ds side, these searches are getting paginated by default to 2000 entries. However, I'm not entirely sure I've followed the code path correctly, so it'd be great for someone else to verify this as well. 


Version-Release number of selected component (if applicable):
# rpm -q freeipa-server freeipa-client ipa-server ipa-client 389-ds-base pki-ca krb5-server
package freeipa-server is not installed
package freeipa-client is not installed
ipa-server-4.5.4-10.el7.centos.4.4.x86_64
ipa-client-4.5.4-10.el7.centos.4.4.x86_64
389-ds-base-1.3.7.5-28.el7_5.x86_64
pki-ca-10.5.1-15.el7_5.noarch
krb5-server-1.15.1-19.el7.x86_64

How reproducible:


Steps to Reproduce:
1. Install FreeIPA w/ the integrated CA
2. Issue 4,000 certificates
3. Attempt to deleted a host
4. Verify that in the access log, the VLV search request pages at 2000. 

Actual results:
ipa host-del FQDN_HERE operations take a minimum of 1 minute to complete when you have >130,000 certificates issued from the integrated FreeIPA CA. 

Expected results:
ipa host-del FQDN_HERE should be completed within seconds. 


Additional info:
It's entirely possible I'm not following the logic here correctly, if that's the case, please let me know. This issue drastically impacts our production environments and really slows down our day to day operations. Perhaps VLV indexes/searches get a default pagination setting? I was unable to find anything in my searching online.

Comment 3 Christian Heimes 2019-01-14 10:22:58 UTC

It's more of a design flaw in IPA. IPA's implementation for cert revokation of host and service certs is inefficient. It should not need to build a full list of certificates. I have created https://pagure.io/freeipa/issue/7835 to track the issue.

Comment 4 JaredL 2019-01-16 16:42:02 UTC

Hey Christian!

Thanks for responding. That makes sense, as a workaround, do you know if there's any way for the pagination setting used for these searches to be configured? 

For context as well, I also posted to the freeipa-users list: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahosted.org/thread/ALXF4RPIKXWGNYBI2LJI7S67J3HQ4UAO/ 

Currently, a host-del operation in our production environments takes up to 5 minutes to complete/return. We frequently terminate hosts in the environment and spending 5 minutes per host is causing a lot of pain for our users. I think if I can configure the pagination limit used here to be 10,000 or higher, that'll significantly improve things on our end. 

Thanks,
Jared

Comment 5 Marc Sauton 2019-01-25 22:02:14 UTC

try to set a "user-level" size limit for the entry doing the LDAP BIND of those operations, pkidbuser, for example:

ldapsearch -LLLx -D "cn=directory manager" -W -b ou=people,o=ipaca uid=pkidbuser nssizelimit

cat << EOF > /var/tmp/add.nssizelimit.to.uid.pkidbuser.ldif
dn: uid=pkidbuser,ou=people,o=ipaca
changetype: modify
add: nsSizeLimit
nsSizeLimit: 10000
EOF

ldapmodify -xD "cn=directory manager" -W -f /var/tmp/add.nssizelimit.to.uid.pkidbuser.ldif

I think no LDAP server restart is required:
ldapsearch -LLLx -D "cn=directory manager" -W -b ou=people,o=ipaca uid=pkidbuser nssizelimit

nor a CA restart ( if needed: systemctl start pki-tomcatd )

and try again...

Comment 6 JaredL 2019-01-25 22:16:57 UTC

Hey Marc,

Thanks for the idea! I gave it a try but sadly, after setting nsSizeLimit to 10,000 for the 'pkidbuser', it's still paging at 2,000 entries as seeing with the following in /var/log/pki/pki-tomcat/ca/debug:

[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: SessionContextInterceptor: CertResource.searchCerts()
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: SessionContextInterceptor: Not authenticated.
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: AuthMethodInterceptor: CertResource.searchCerts()
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: AuthMethodInterceptor: mapping: default
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: AuthMethodInterceptor: loading /usr/share/pki/ca/conf/auth-method.properties
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: AuthMethodInterceptor: checking /var/lib/pki/pki-tomcat/ca/conf/auth-method.properties
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: AuthMethodInterceptor: required auth methods: [*]
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: AuthMethodInterceptor: anonymous access allowed
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: ACLInterceptor: CertResource.searchCerts()
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: ACLInterceptor.filter: no authorization required
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: ACLInterceptor: No ACL mapping; authz not required.
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: SignedAuditLogger: event AUTHZ
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: MessageFormatInterceptor: CertResource.searchCerts()
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: MessageFormatInterceptor: content-type: application/xml
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: MessageFormatInterceptor: accept: []
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: MessageFormatInterceptor: request format: application/xml
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: MessageFormatInterceptor: response format: application/xml
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: CertService.searchCerts()
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: CertService: filter: (certstatus=*)
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: CertificateRepository.findCertRecordsInList()
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: In LdapBoundConnFactory::getConn()
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connected: true
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is connected true
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns now 2
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: In DBVirtualList filter attrs sortKey pageSize filter: (certstatus=*) attrs: null pageSize 2147483647
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConns now 3
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList: searching for entry A
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList.getEntries()
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList: entries: 1
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList: top: 9901
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList: size: 9902
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: CertService: total: 9902
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList.getPage(0)
[25/Jan/2019:22:11:30][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList.getEntries()
[25/Jan/2019:22:11:31][ajp-bio-127.0.0.1-8009-exec-1]: getEntries: exception java.lang.ClassCastException: netscape.ldap.LDAPException cannot be cast to netscape.ldap.LDAPEntry
[25/Jan/2019:22:11:31][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList: entries: 2000
[25/Jan/2019:22:11:31][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList.getPage(2000)
[25/Jan/2019:22:11:31][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList.getEntries()
[25/Jan/2019:22:11:31][ajp-bio-127.0.0.1-8009-exec-1]: getEntries: exception java.lang.ClassCastException: netscape.ldap.LDAPException cannot be cast to netscape.ldap.LDAPEntry
[25/Jan/2019:22:11:31][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList: entries: 2000
[25/Jan/2019:22:11:31][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList.getPage(3999)
[25/Jan/2019:22:11:31][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList.getEntries()
[25/Jan/2019:22:11:32][ajp-bio-127.0.0.1-8009-exec-1]: getEntries: exception java.lang.ClassCastException: netscape.ldap.LDAPException cannot be cast to netscape.ldap.LDAPEntry
[25/Jan/2019:22:11:32][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList: entries: 2000
[25/Jan/2019:22:11:32][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList.getPage(5998)
[25/Jan/2019:22:11:32][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList.getEntries()
[25/Jan/2019:22:11:32][ajp-bio-127.0.0.1-8009-exec-1]: getEntries: exception java.lang.ClassCastException: netscape.ldap.LDAPException cannot be cast to netscape.ldap.LDAPEntry
[25/Jan/2019:22:11:32][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList: entries: 2000
[25/Jan/2019:22:11:32][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList.getPage(7997)
[25/Jan/2019:22:11:32][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList.getEntries()
[25/Jan/2019:22:11:32][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList: entries: 1906

# ldapsearch -LLL -o ldif-wrap=no -D 'cn=Directory Manager' -W -s sub -b 'ou=people,o=ipaca' '(uid=pkidbuser)' nsSizeLimit
Enter LDAP Password:
dn: uid=pkidbuser,ou=people,o=ipaca
nsSizeLimit: 10000

Just to make sure, I went ahead and restart FreeIPA with ipactl restart as well. That actually appears to have done the trick, now I'm seeing that it's only paging once getting all 9902 entries!
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: SessionContextInterceptor: CertResource.searchCerts()
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: SessionContextInterceptor: Not authenticated.
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: AuthMethodInterceptor: CertResource.searchCerts()
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: AuthMethodInterceptor: mapping: default
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: AuthMethodInterceptor: required auth methods: [*]
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: AuthMethodInterceptor: anonymous access allowed
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: ACLInterceptor: CertResource.searchCerts()
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: ACLInterceptor.filter: no authorization required
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: ACLInterceptor: No ACL mapping; authz not required.
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: SignedAuditLogger: event AUTHZ
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: MessageFormatInterceptor: CertResource.searchCerts()
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: MessageFormatInterceptor: content-type: application/xml
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: MessageFormatInterceptor: accept: []
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: MessageFormatInterceptor: request format: application/xml
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: MessageFormatInterceptor: response format: application/xml
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: CertService.searchCerts()
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: CertService: filter: (certstatus=*)
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: CertificateRepository.findCertRecordsInList()
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: In LdapBoundConnFactory::getConn()
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: masterConn is connected: true
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: getConn: conn is connected true
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: getConn: mNumConns now 2
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: In DBVirtualList filter attrs sortKey pageSize filter: (certstatus=*) attrs: null pageSize 2147483647
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: returnConn: mNumConns now 3
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: DBVirtualList: searching for entry A
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: DBVirtualList.getEntries()
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: DBVirtualList: entries: 1
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: DBVirtualList: top: 9901
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: DBVirtualList: size: 9902
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: CertService: total: 9902
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: DBVirtualList.getPage(0)
[25/Jan/2019:22:15:29][ajp-bio-127.0.0.1-8009-exec-3]: DBVirtualList.getEntries()
[25/Jan/2019:22:15:30][ajp-bio-127.0.0.1-8009-exec-3]: DBVirtualList: entries: 9902 

Thanks!

Comment 7 Marc Sauton 2019-01-26 02:25:14 UTC

Ah!
The CA probably needed to re-do the LDAP BIND as pkidbuser if that connection was kept opened and used.
thanks for confirming/testing fast!

Comment 8 Christian Heimes 2019-01-29 12:03:31 UTC

I have committed a workaround to IPA that optimizes the search query for host names. There is more room for optimization, but they need additional changes to Dogtag, too.

Fixed upstream
master:
https://pagure.io/freeipa/c/ae74d348c3da580264c56441c136af3fc6ae58df
https://pagure.io/freeipa/c/6cd37542e6c563ddd8595d488712935a4d6b17bf

Comment 9 Christian Heimes 2019-01-30 07:09:34 UTC

Fixed upstream
ipa-4-6:
https://pagure.io/freeipa/c/1e842f0fea290cbf8935eea79ea16e17650b7328
https://pagure.io/freeipa/c/9a0783f5ac8a2c7426b4db3a818fa6583bab16e1
ipa-4-7:
https://pagure.io/freeipa/c/a243bd56a65e47b03ee3ba772413b580aeb35ba9
https://pagure.io/freeipa/c/2ccd4da44b5d66298bf1d4938fa3dc6ce2dbfa84

Comment 11 Dinesh Prasanth 2020-04-28 18:29:13 UTC

As per grooming meeting 20200428, this bug can be fixed by having a upgrade to database framework

Comment 14 RHEL Program Management 2021-02-01 07:31:07 UTC

After evaluating this issue, there are no plans to address it further or fix it in an upcoming release.  Therefore, it is being closed.  If plans change such that this issue will be fixed in an upcoming release, then the bug can be reopened.

Comment 20 RHEL Program Management 2021-10-31 07:26:53 UTC

After evaluating this issue, there are no plans to address it further or fix it in an upcoming release.  Therefore, it is being closed.  If plans change such that this issue will be fixed in an upcoming release, then the bug can be reopened.