[OPENAM-14825] OAuth2 Dynamic Registration with Software Statement triggers objectClass=* search Created: 26/Apr/19  Updated: 28/Jun/19  Resolved: 02/May/19

Status: Resolved
Project: OpenAM
Component/s: oauth2
Affects Version/s: 6.5.0.1, 6.5.1
Fix Version/s: 6.5.2, 6.0.1, 5.5.2, 7.0.0

Type: Bug Priority: Major
Reporter: Aaron Haskins Assignee: Lawrence Yarham
Resolution: Fixed Votes: 0
Labels: EDISON
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Relates
is related to OPENAM-11944 REST OAuth2 creation triggers objectC... Resolved
Sprint: AM Sustaining Sprint 62
Story Points: 5
Needs backport:
No
Support Ticket IDs:
Needs QA verification:
No
Functional tests:
No
Are the reproduction steps defined?:
Yes and I used the same an in the description

 Description   

Bug description

When dynamically creating OAuth2 clients using a software statement, it triggers objectClass=* searches. When lots of clients are registered/registering, the search causes performance issues.

How to reproduce the issue

  1. Create a profile for the Software Statement (Applications > Agents > Software Publisher) using the same values as mentioned in https://backstage.forgerock.com/docs/am/6.5/oauth2-guide/#register-oauth2-client-dynamic-software-statement-example
  2. Enable Allow Open Dynamic Client Registration (no need for Master Client access token then) in Services > OAuth2 Provider > Client Dynamic Registration
  3. curl -X POST \
      http://openam.example.com:8088/openam/oauth2/connect/register \
      -H 'Content-Type: application/json' \
      -H 'cache-control: no-cache' \
      -d '{
     "redirect_uris": ["https://client.example.com:8443/callback"],
     "client_name": "SoftStateTest",
     "client_uri": "https://client.example.com/",
     "software_statement": "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJpc3MiOiJodHRwczovL2NsaWVudC5leGFtcGxlLmNvbSIsImlhdCI6MTU1NjI4Nzc5MiwiZXhwIjoxNTg3ODIzNzkyLCJhdWQiOiJodHRwOi8vb3BlbmFtLmV4YW1wbGUuY29tOjgwODgvb3BlbmFtL29hdXRoMiIsInN1YiI6IjROUkIxLTBYWkFCWkk5RTYtNVNNM1IiLCJyZWRpcmVjdF91cmlzIjpbImh0dHBzOi8vY2xpZW50LmV4YW1wbGUuY29tL2NhbGxiYWNrIl19.pq9UqSSU2DJkIidp3ZJS1oQ-BE0DuTwJ5nKjBCG4ves"
     }'
  1. Search client_id (not client name) generated in DS LDAP access log files
Expected behaviour
A less impacting, quicker search
Current behaviour
objectClass=*

Work around

None



 Comments   
Comment by Lawrence Yarham [ 21/May/19 ]

Note that if using OpenDJ as an external config store here and attempting to create more than 4000 clients (without first having created an indexed search), the following response will be seen on attempting to create the 4001'st client:

{"error_description":"Unknown software publisher","error":"invalid_software_statement"}

And the following logs in IdRepo debug log:

amAgentsRepo:05/21/2019 02:46:23:678 PM PDT: Thread[http-bio-8443-exec-10,5,main]: TransactionId[0927e293-2b2c-42cc-b381-6a3da08eb64c-32649]
ERROR: AgentsRepo.getAgentPattern(): Error occurred while checking AgentName sent for pattern *
SMSException Exception Code:5
Message:Unexpected LDAP exception occurred.
--------------------------------------------------
The lower level exception message
Unavailable Critical Extension: The search results cannot be sorted because the given search request is not indexed
The lower level exception:
Unavailable Critical Extension: The search results cannot be sorted because the given search request is not indexed
        at org.forgerock.opendj.ldap.LdapException.newLdapException(LdapException.java:253)
...
        at com.sun.identity.idm.plugins.internal.AgentsRepo.search(AgentsRepo.java:755)
        at org.forgerock.openam.idm.IdRepoAuditor.search(IdRepoAuditor.java:256)
        at com.sun.identity.idm.server.IdServicesImpl.search(IdServicesImpl.java:1444)
        at com.sun.identity.idm.server.IdCachedServicesImpl.search(IdCachedServicesImpl.java:616)
        at com.sun.identity.idm.AMIdentityRepository.searchIdentities(AMIdentityRepository.java:380)
        at com.sun.identity.idm.AMIdentityRepository.searchIdentities(AMIdentityRepository.java:312)
        at org.forgerock.oauth2.registration.SoftwarePublisherStore.searchIdentity(SoftwarePublisherStore.java:109)
        at org.forgerock.oauth2.registration.SoftwarePublisherStore.getIdentity(SoftwarePublisherStore.java:97)
        at org.forgerock.oauth2.registration.SoftwarePublisherStore.get(SoftwarePublisherStore.java:83)

The error is because the limit for the number of entries that need to be processed for the unindexed search (4000) has been reached on the server.

The ldap search that is triggering this is:

SearchRequest(name=ou=default,ou=OrganizationConfig,ou=1.0,ou=AgentService,ou=services,dc=examplecfg1,dc=com, scope=one, dereferenceAliasesPolicy=never, typesOnly=false, filter=(&(&(objectclass=top)(ou=*))(&(objectclass=top)(sunserviceID=SoftwarePublisher))), attributes=[o], controls=[TransactionIdControl(oid=1.3.6.1.4.1.36733.2.1.5.1, transactionId=0927e293-2b2c-42cc-b381-6a3da08eb64c-32649/0), ServerSideSortRequestControl(oid=1.2.840.113556.1.4.473, criticality=true, sortKeys=[ou])])

which can be seen in the ldap server access logs:

{"eventName":"DJ-LDAP","client":{"ip":"127.0.0.1","port":51678},"server":{"ip":"127.0.0.1","port":2389},"request":{"protocol":"LDAP","operation":"SEARCH","connId":45,"msgId":11136,"dn":"ou=default,ou=OrganizationConfig,ou=1.0,ou=AgentService,ou=services,dc=examplecfg1,dc=com","scope":"one","filter":"(&(&(objectclass=top)(ou=*))(&(objectclass=top)(sunserviceID=SoftwarePublisher)))","attrs":["o"]},"transactionId":"7f7fb881-9bf6-4052-b60c-6b7126f8815c-135718","response":{"status":"FAILED","statusCode":"12","elapsedTime":53,"elapsedTimeUnits":"MILLISECONDS","detail":"The search results cannot be sorted because the given search request is not indexed","additionalItems":"unindexed","nentries":0},"timestamp":"2019-05-21T21:46:23.677Z","_id":"7f7fb881-9bf6-4052-b60c-6b7126f8815c-135724"}

One solution is to use the steps described in https://backstage.forgerock.com/docs/ds/6.5/admin-guide/#configure-vlv to create a VLV index to enable the search to be performed successfully.  In my tests I was able to do this by using the following:

/opt/opendj3/opendj_6_5_2_14825/bin/dsconfig create-backend-vlv-index --hostname opendj.amtest2.com --port 2444 --bindDn "cn=Directory Manager" --bindPassword <password> --backend-name userRoot --index-name software-publishers --set base-dn:ou=default,ou=OrganizationConfig,ou=1.0,ou=AgentService,ou=services,dc=examplecfg1,dc=com --set filter:"(&(&(objectclass=top)(ou=*))(&(objectclass=top)(sunserviceID=SoftwarePublisher)))" --set scope:single-level --set sort-order:"+ou" --trustAll --no-prompt

and then rebuilding the index...

/opt/opendj3/opendj_6_5_2_14825/bin/rebuild-index --hostname opendj.amtest2.com --port 2444 --bindDn "cn=Directory Manager" --bindPassword <password> --baseDn dc=examplecfg1,dc=com --index vlv.software-publishers --trustAll

which ends with the following output:

21/May/2019:14:50:04 -0700] severity="NOTICE" msgCount=32 msgID=org.opends.messages.backend-414 message="Rebuild Index task 20190521144944853 finished execution in the state Completed successfully"
Rebuild Index task 20190521144944853 has been successfully completed

 

Then creating additional clients succeed.

Comment by Lawrence Yarham [ 22/May/19 ]

Further note.  After restarting AM, I was unable to login in as amadmin.  Ldap logs reported similar issues with the following search:

{"eventName":"DJ-LDAP","client":{"ip":"127.0.0.1","port":59956},"server":{"ip":"127.0.0.1","port":2389},"request":{"protocol":"LDAP","operation":"SEARCH","connId":19,"msgId":299,"dn":"ou=services,dc=examplecfg1,dc=com","scope":"sub","filter":"(|(sunxmlKeyValue=sunidentityrepositoryservice-sunOrganizationAliases=openam.amtest2.com)(sunxmlKeyValue=sunOrganizationAliases=openam.amtest2.com))","attrs":["o"]},"transactionId":"8e62a88b-2b0d-41e4-b21e-012c987381f7-6656","response":{"status":"FAILED","statusCode":"12","elapsedTime":3,"elapsedTimeUnits":"MILLISECONDS","detail":"The search results cannot be sorted because the given search request is not indexed","additionalItems":"unindexed","nentries":0},"timestamp":"2019-05-22T15:22:19.686Z","_id":"8e62a88b-2b0d-41e4-b21e-012c987381f7-6658"}

I added the following vlv index:

/opt/opendj3/opendj_6_5_2_14825/bin/dsconfig create-backend-vlv-index --hostname opendj.amtest2.com --port 2444 --bindDn "cn=Directory Manager" --bindPassword <password> --backend-name userRoot --index-name services1 --set base-dn:ou=services,dc=examplecfg1,dc=com --set filter:"(|(sunxmlKeyValue=sunidentityrepositoryservice-sunOrganizationAliases=openam.amtest2.com)(sunxmlKeyValue=sunOrganizationAliases=openam.amtest2.com))" --set scope:subordinate-subtree --set sort-order:"+o" --trustAll --no-prompt
/opt/opendj3/opendj_6_5_2_14825/bin/rebuild-index --hostname opendj.amtest2.com --port 2444 --bindDn "cn=Directory Manager" --bindPassword <password> --baseDn dc=examplecfg1,dc=com --index vlv.services1 --trustAll

I still saw an internal server error on trying to login as amadmin, so stopped AM, stopped DJ, restarted and it reported degraded indexes.

/opt/opendj3/opendj_6_5_2_14825/bin/rebuild-index --hostname opendj.amtest2.com --port 2444 --bindDn "cn=Directory Manager" --bindPassword <password> --baseDn dc=examplecfg1,dc=com --rebuildDegraded --trustAll

Then restarted AM and operation was as expected (could login, navigate admin UI, view agents, create a new agent), login as an end user (e.g. test1).

Generated at Tue Sep 22 12:00:16 UTC 2020 using Jira 7.13.12#713012-sha1:6e07c38070d5191bbf7353952ed38f111754533a.