Full_Name: Daniel Armbrust Version: HEAD OS: Redhat 9 URL: Submission from: (NULL) (129.176.151.126) When I do a search (from java client code) that has a fairly large number results, and set the page size to be quite small (usually less than 100) at some point while iterating over the results, I will get an error when I ask for the next page: [LDAP: error code 53 - paged results cookie is invalid or old]. This seems to happen more frequently when I set the page size to a small number - Making the page size larger usually either changes the point where it fails, or makes it not fail at all. The debug log on the server looks like this when the failure happens: do_search ber_scanf fmt ({miiiib) ber: >>> dnPrettyNormal: <dc=concepts, codingScheme=ICD9,dc=codingSchemes,service=ICD9Service,dc=HL7,dc=org> => ldap_bv2dn(dc=concepts, codingScheme=ICD9,dc=codingSchemes,service=ICD9Service,dc=HL7,dc=org,0) <= ldap_bv2dn(dc=concepts, codingScheme=ICD9,dc=codingSchemes,service=ICD9Service,dc=HL7,dc=org,0)=0 => ldap_dn2bv(272) <= ldap_dn2bv(dc=concepts,codingScheme=ICD9,dc=codingSchemes,service=ICD9Service,dc=HL7,dc=org,272)=0 => ldap_dn2bv(272) <= ldap_dn2bv(dc=concepts,codingScheme=ICD9,dc=codingschemes,service=icd9service,dc=hl7,dc=org,272)=0 <<< dnPrettyNormal: <dc=concepts,codingScheme=ICD9,dc=codingSchemes,service=ICD9Service,dc=HL7,dc=org>, <dc=concepts,codingScheme=ICD9,dc=codingschemes,service=icd9service,dc=hl7,dc=org> ber_scanf fmt ({mm}) ber: ber_scanf fmt ({M}}) ber: => get_ctrls ber_scanf fmt ({m) ber: ber_scanf fmt (b) ber: ber_scanf fmt (m) ber: => get_ctrls: oid="1.2.840.113556.1.4.319" (critical) ber_scanf fmt ({im}) ber: <= get_ctrls: n=1 rc=53 err="paged results cookie is invalid or old" send_ldap_result: conn=0 op=4068 p=3 send_ldap_response: msgid=4069 tag=101 err=53 ber_flush: 53 bytes to sd 9 do_search: get_ctrls failed connection_get(9): got connid=0 connection_read(9): checking for input on id=0 ber_get_next ber_get_next on fd 9 failed errno=104 (Connection reset by peer) connection_read(9): input error=-2 id=0, closing. connection_closing: readying conn=0 sd=9 for close connection_close: conn=0 sd=9 With a given page size, and a given database, the error always happens at the same point. Different databases have different failure points (and for that matter, the same database with the same page size fails at a different point depending on the speed of the hardware it is running on - seems to happen more often on faster hardware) I could consistantly reproduce this behavior with versions older than 2.2.7. I could not reproduce it in 2.2.7 (so I assumed it was fixed), but now I can reproduce it with the code I checked out from HEAD today. Also, with the todays code, once this error occurrs, the database will not allow me to get any paged results, until I restart the database (with versions prior to 2.2.7, it would allow me to get results up to the failure point). If necessary, I should be able to provide a database that consistantly reproduces this error.
> Full_Name: Daniel Armbrust > Version: HEAD > OS: Redhat 9 > URL: > Submission from: (NULL) (129.176.151.126) Quick test: can you reproduce it with ldapsearch -E '!pr=<pagesize>' ? p. -- Pierangelo Masarati mailto:pierangelo.masarati@sys-net.it
Yes, I can: openldapHead/ldap/clients/tools/ldapsearch -b 'dc=concepts,codingScheme=ICD9,dc=codingSchemes,service=ICD9Service,dc=HL7,dc=org' -E '!pr=1' -s sub -h localhost -p 23456 # extended LDIF # # LDAPv3 # base <dc=concepts,codingScheme=ICD9,dc=codingSchemes,service=ICD9Service,dc=HL7,dc=org> with scope subtree # filter: (objectclass=*) # requesting: ALL # with pagedResults critical control: size=1 # # concepts, ICD9, codingSchemes, ICD9Service, HL7.org dn: dc=concepts,codingScheme=ICD9,dc=codingSchemes,service=ICD9Service,dc=HL7, dc=org objectClass: concepts dc: concepts # search result search: 2 result: 0 Success control: 1.2.840.113556.1.4.319 false MAsCAwDu6gQEDAAAAA== Estimate entries: 61162 Press [size] Enter for the next {1|size} entries. ..... ..... ..... # search result search: 220 result: 0 Success control: 1.2.840.113556.1.4.319 false MAsCAwDu6gQEigEAAA== Estimate entries: 61162 Press [size] Enter for the next {1|size} entries. # extended LDIF # # LDAPv3 # base <dc=concepts,codingScheme=ICD9,dc=codingSchemes,service=ICD9Service,dc=HL7,dc=org> with scope subtree # filter: (objectclass=*) # requesting: ALL # with pagedResults critical control: size=1 # # 902.4, concepts, ICD9, codingSchemes, ICD9Service, HL7.org dn: conceptCode=902.4,dc=concepts,codingScheme=ICD9,dc=codingSchemes,service=I CD9Service,dc=HL7,dc=org objectClass: codedEntry conceptCode: 902.4 entityDescription: Injury to renal blood vessels # search result search: 221 result: 0 Success control: 1.2.840.113556.1.4.319 false MAsCAwDu6gQEjwEAAA== Estimate entries: 61162 Press [size] Enter for the next {1|size} entries. # extended LDIF # # LDAPv3 # base <dc=concepts,codingScheme=ICD9,dc=codingSchemes,service=ICD9Service,dc=HL7,dc=org> with scope subtree # filter: (objectclass=*) # requesting: ALL # with pagedResults critical control: size=1 # # search result search: 222 result: 53 Server is unwilling to perform text: paged results cookie is invalid or old Server is unwilling to perform (53) # numResponses: 441 Although it happens at much more random intervals when I do it this way. Dan -----Original Message----- From: Pierangelo Masarati [mailto:ando@sys-net.it] Sent: Thursday, April 15, 2004 12:43 PM To: Armbrust, Daniel C. Cc: openldap-its@OpenLDAP.org Subject: Re: paged results gives invalid cookie (ITS#3089) > Full_Name: Daniel Armbrust > Version: HEAD > OS: Redhat 9 > URL: > Submission from: (NULL) (129.176.151.126) Quick test: can you reproduce it with ldapsearch -E '!pr=<pagesize>' ? p. -- Pierangelo Masarati mailto:pierangelo.masarati@sys-net.it
changed notes changed state Open to Feedback
moved from Incoming to Software Bugs
Paging bug from 2.2.5 still present in 2.2.11 The Paged Results Control bug that I mentioned for OpenLdap 2.2.5 still appears to be present IN 2.2.11. I recently upgraded from 2.2.5 to 2.2.11 and ran an old test I had to see if the paged results control stuff now worked (java code attached). The test failed in the same manner as it had with 2.2.5. I wouldnt have posted to the list, except some time ago I seem to remember someone mentioning that it had been fixed (in 2.2.7 I think). I just thought I'd let you know the bug is still there, lurking in the shadows and waiting to strike ;-) Links that may be relevant: http://www.openldap.org/its/index.cgi/Contrib?id=2189;expression=paging;usea rchives=1;statetype=-1 Looks curiously like what I've been experiencing; beyond getting the first page of results I get errors (LDAP code 2 or 53) stating that the cookie is invalid or old. LDAP error code 2 always seems to be the error I get the first time my test method runs (wrapped by a CommunicationException) and LDAP error code 53 always seems to be generated for all subsequent runs of the method until the calling program exits. This looks similar to the problem I've been having: http://www.openldap.org/its/index.cgi/Incoming?id=3089;selectid=3089;usearch ives=1;statetype=-1
Can you provide the attached file in a more readable manner? e.g. a link to somewhere for download? Thanks. p.
A number of paged results bug fixes have been committed to HEAD and OPENLDAP_REL_ENG_2_2. Please test. Thanks, Kurt At 02:54 AM 6/5/2004, jon@illumining.com wrote: >This is a multi-part message in MIME format. > >------=_NextPart_000_0002_01C44AEB.4CE89F20 >Content-Type: text/plain; > charset="iso-8859-1" >Content-Transfer-Encoding: 7bit > >Paging bug from 2.2.5 still present in 2.2.11 > >The Paged Results Control bug that I mentioned for OpenLdap 2.2.5 still >appears to be present IN 2.2.11. I recently upgraded from 2.2.5 to 2.2.11 >and ran an old test I had to see if the paged results control stuff now >worked (java code attached). The test failed in the same manner as it had >with 2.2.5. > >I wouldnt have posted to the list, except some time ago I seem to remember >someone mentioning that it had been fixed (in 2.2.7 I think). I just thought >I'd let you know the bug is still there, lurking in the shadows and waiting >to strike ;-) > >Links that may be relevant: > >http://www.openldap.org/its/index.cgi/Contrib?id=2189;expression=paging;usea >rchives=1;statetype=-1 >Looks curiously like what I've been experiencing; beyond getting the first >page of results I get errors (LDAP code 2 or 53) stating that the cookie is >invalid or old. LDAP error code 2 always seems to be the error I get the >first time my test method runs (wrapped by a CommunicationException) and >LDAP error code 53 always seems to be generated for all subsequent runs of >the method until the calling program exits. > >This looks similar to the problem I've been having: >http://www.openldap.org/its/index.cgi/Incoming?id=3089;selectid=3089;usearch >ives=1;statetype=-1 > >------=_NextPart_000_0002_01C44AEB.4CE89F20 >Content-Type: text/plain; > name="testmethod.txt" >Content-Transfer-Encoding: quoted-printable >Content-Disposition: attachment; > filename="testmethod.txt" > > /* Do not remove this test method or these comments until we get = >OpenLdap working with paging. > > Currently this method will fail at a random point when retreiving a = >number of pages one after > the other. The failure is reported in the form of an = >OperationNotSupportedException wrapped around > the following Ldap error code: > =20 > [LDAP: error code 53 - paged results cookie is invalid or old] > =20 > A brief search using Google gave me a peice of C source code for = >OpenLdap, which is ultimately > the source of the error: > =20 > = >http://www.opensource.apple.com/darwinsource/10.3/OpenLDAP-37/OpenLDAP/se= >rvers/slapd/controls.c > =20 > A copy of the controls.c is available locally. On occasion the start = >of the error message says=20 > [LDAP: error code 2..] but the remainder of the message is the same. > */ =20 > public void testLdapPaging() throws Exception > { > try { > =09 > //#1 create a naming enumeration to hold the results > NamingEnumeration naming =3D null; > =09 > //#2 set or retreive the size of the page > int pageSize =3D 2; > =09 > //#3 determine what the search base is > String searchBase =3D "ou=3DPeople, dc=3Djon, dc=3Dillumining, = >dc=3Dcom"; > =09 > //#4 get the context object > Hashtable hashtable =3D new Hashtable(); > String initCtxFactory =3D "com.sun.jndi.ldap.LdapCtxFactory"; > String host =3D "ldap://localhost:389"; > String security =3D "simple"; > String dn =3D "cn=3DManager, dc=3Dillumining, dc=3Dcom"; > String pwd =3D "secret"; =09 > hashtable.put(Context.INITIAL_CONTEXT_FACTORY, initCtxFactory); > hashtable.put(Context.PROVIDER_URL, host); > hashtable.put(Context.SECURITY_AUTHENTICATION, security); > hashtable.put(Context.SECURITY_PRINCIPAL, dn); > hashtable.put(Context.SECURITY_CREDENTIALS, pwd); > hashtable.put("java.naming.ldap.version", "3"); > InitialLdapContext ctx =3D new InitialLdapContext(hashtable, null); > =09 > //#5 create the search controls object > SearchControls controls =3D new SearchControls(); > controls.setSearchScope(SearchControls.SUBTREE_SCOPE); > =09 > //#6 create the paged results control object > PagedResultsControl prc =3D new PagedResultsControl(pageSize); > =09 > //#7 create the request controls array > Control reqCtls[] =3D new Control[]{prc}; > =09 > //#8 set the request controls array on the context > ctx.setRequestControls(reqCtls); > =09 > //#9 set what the return attributes will be > String[] returnAttributes =3D {"uid"}; > controls.setReturningAttributes(returnAttributes); > =09 > //#10 create an ldap search filter > String ldapSearchFilter =3D = >"(&(objectClass=3DinetOrgPerson)(cn=3D*hick*))"; > =09 > //#11 create do while loop variables > int count =3D 0; > byte[] b =3D null; > =09 > //#12 enter do while loop > do > { > //#13 perform search using search base- search filter and search > naming =3D ctx.search(searchBase, ldapSearchFilter, controls); > =09 > //#14 test if NamingEnumeration does not equal null > if(naming !=3D null) > { > int subcounter =3D 0; > // You must iterate through the NamingEnumeration, even if its not = >the one you want- > // and you want a subsequent page. For some reason if you dont = >iterate through the=20 > // NamingEnumeration a server-side cookie is NOT created, which = >means you cant access > // the subsequent pages by obtaining a PagedResultsResponseControl = >and getting a cookie > // from it. > while(naming.hasMoreElements()) > { > subcounter++; > SearchResult si =3D (SearchResult)naming.nextElement(); > count++; > System.out.println(si.getName()); > } > System.out.println(ldapSearchFilter + " returned " + subcounter ); > } > else =20 > { > System.out.println(ldapSearchFilter + " did not return any = >entries."); > } > =09 > //#15 check if the response controls are null > Control[] response =3D ctx.getResponseControls(); > if(response !=3D null) > {=09 > b =3D((PagedResultsResponseControl)response[0]).getCookie(); > } > else > { > b =3D null; > } > if(b !=3D null) > { > //print out cookie info > System.out.println("Got cookie: "); > for(int i =3D 0; i < b.length; i++) > { > System.out.println("Byte "+i+" =3D "+ b[i]); > } > =09 > //create new PagedResultsControl > prc =3D new PagedResultsControl(pageSize, b, Control.CRITICAL); > ctx.setRequestControls(new Control[] {prc}); > }=09 > =09 > }while(b !=3D null); > //added this to see if it made any difference > naming.close(); > ctx.close(); > } catch (NamingException e) { > e.printStackTrace(); > throw new Exception(); > } catch (IOException e) { > e.printStackTrace(); > throw new Exception(); > } > } >------=_NextPart_000_0002_01C44AEB.4CE89F20 >Content-Type: text/plain; > name="STACK.txt" >Content-Transfer-Encoding: quoted-printable >Content-Disposition: attachment; > filename="STACK.txt" > >FIRST EXAMPLE STACK TRACE AND STDOUT- FAILURE ON AN ATTEMPT TO GET THE = >SECOND PAGE > >uid=3DAhab12345678 >uid=3DAbraham12345678 >(&(objectClass=3DinetOrgPerson)(cn=3D*hick*)) returned 2 >Got cookie: >Byte 0 =3D 22 >Byte 1 =3D -4 >Byte 2 =3D 0 >Byte 3 =3D 0 >javax.naming.CommunicationException: [LDAP: error code 2 - paged results = >cookie is invalid]; remaining name 'ou=3DPeople, dc=3Djon, = >dc=3Dillumining, dc=3Dcom' > at com.sun.jndi.ldap.LdapCtx.mapErrorCode(LdapCtx.java:3036) > at = >com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2934) > at = >com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2740) > at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1811) > at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1734) > at = >com.sun.jndi.toolkit.ctx.ComponentDirContext.p_search(ComponentDirContext= >.java:368) > at = >com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialComposi= >teDirContext.java:328) > at = >com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialComposi= >teDirContext.java:313) > at = >javax.naming.directory.InitialDirContext.search(InitialDirContext.java:23= >8) > at = >com.illumining.server.persistence.ldap.LdapUserDAO.testLdapPaging(LdapUse= >rDAO.java:1002) > at com.illumining.server.UserService.test(UserService.java:885) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at = >sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java= >:39) > at = >sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorI= >mpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:324) > at = >sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:261) > at sun.rmi.transport.Transport$1.run(Transport.java:148) > at java.security.AccessController.doPrivileged(Native Method) > at sun.rmi.transport.Transport.serviceCall(Transport.java:144) > at = >sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:460) > at = >sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.jav= >a:701) > at java.lang.Thread.run(Thread.java:534) > > > >SECOND EXAMPLE STDOUT AND STACK TRACE BELOW- FAILURE ON AN ATTEMPT TO = >GET THE THIRD PAGE OF RESULTS > >uid=3DAhab12345678 >uid=3DAbraham12345678 >(&(objectClass=3DinetOrgPerson)(cn=3D*hick*)) returned 2 >Got cookie: >Byte 0 =3D 99 >Byte 1 =3D -4 >Byte 2 =3D 0 >Byte 3 =3D 0 >uid=3DAlice12345678 >uid=3DBilly-Bob12345678 >(&(objectClass=3DinetOrgPerson)(cn=3D*hick*)) returned 2 >Got cookie: >Byte 0 =3D 105 >Byte 1 =3D -4 >Byte 2 =3D 0 >Byte 3 =3D 0 >javax.naming.OperationNotSupportedException: [LDAP: error code 53 - = >paged results cookie is invalid or old]; remaining name 'ou=3DPeople, = >dc=3Djon, dc=3Dillumining, dc=3Dcom' > at com.sun.jndi.ldap.LdapCtx.mapErrorCode(LdapCtx.java:3061) > at = >com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2934) > at = >com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2740) > at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1811) > at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1734) > at = >com.sun.jndi.toolkit.ctx.ComponentDirContext.p_search(ComponentDirContext= >.java:368) > at = >com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialComposi= >teDirContext.java:328) > at = >com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialComposi= >teDirContext.java:313) > at = >javax.naming.directory.InitialDirContext.search(InitialDirContext.java:23= >8) > at = >com.illumining.server.persistence.ldap.LdapUserDAO.testLdapPaging(LdapUse= >rDAO.java:1002) > at com.illumining.server.UserService.test(UserService.java:885) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at = >sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java= >:39) > at = >sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorI= >mpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:324) > at = >sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:261) > at sun.rmi.transport.Transport$1.run(Transport.java:148) > at java.security.AccessController.doPrivileged(Native Method) > at sun.rmi.transport.Transport.serviceCall(Transport.java:144) > at = >sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:460) > at = >sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.jav= >a:701) > at java.lang.Thread.run(Thread.java:534) >------=_NextPart_000_0002_01C44AEB.4CE89F20--
A number of paged results bug fixes have been committed to HEAD and OPENLDAP_REL_ENG_2_2. Please test. Thanks, Kurt
changed state Feedback to Test
changed notes
changed notes changed state Test to Release
Sounds great! I just downloaded HEAD, will test either today or tomorrow. I won't introduce any problems if I test it with a database loaded with version 2.2.11 will I? Or should a reload the database with HEAD before I do my testing? Thanks for looking into this, Dan -----Original Message----- From: Kurt Zeilenga [mailto:openldap-its@OpenLDAP.org] Sent: Wednesday, June 16, 2004 5:14 PM To: Armbrust, Daniel C. Subject: Re: paged results gives invalid cookie (ITS#3089) A number of paged results bug fixes have been committed to HEAD and OPENLDAP_REL_ENG_2_2. Please test. Thanks, Kurt
FYI: I just built the HEAD branch, and make test failed with: >>>>> Starting test006-acls ... running defines.sh Running slapadd to build slapd database... ./testrun/slapd.1.conf: line 55: warning: cannot assess the validity of the ACL scope within backend naming context ./testrun/slapd.1.conf: line 60: warning: cannot assess the validity of the ACL scope within backend naming context ./testrun/slapd.1.conf: line 71: warning: cannot assess the validity of the ACL scope within backend naming context ./testrun/slapd.1.conf: line 75: warning: cannot assess the validity of the ACL scope within backend naming context ./testrun/slapd.1.conf: line 81: warning: cannot assess the validity of the ACL scope within backend naming context ./testrun/slapd.1.conf: line 93: warning: cannot assess the validity of the ACL scope within backend naming context Starting slapd on TCP/IP port 9011... Testing slapd access control... Waiting 5 seconds for slapd to start... Using ldapsearch to retrieve all the entries... Filtering ldapsearch results... Filtering original ldif used to create database... Comparing filter output... comparison failed - modify operations did not complete correctly >>>>> ./scripts/test006-acls failed (exit 1) make[2]: *** [bdb-yes] Error 1 make[2]: Leaving directory `/home/armbrust/openldap/ldap/tests' make[1]: *** [test] Error 2 make[1]: Leaving directory `/home/armbrust/openldap/ldap/tests' make: *** [test] Error 2 I'll assume this is a known issue with the HEAD code... If not let me know and I'll go post it in the right place. Dan
changed state Release to Closed
I'm still able to generate the error with (at least) one of my databases. This database was loaded with 2.2.11, not head, however - maybe I should reload the database first?. Debug level 1 from the server, while doing rapid searches with a page size of 1: <= send_search_entry send_ldap_result: conn=0 op=166 p=3 send_ldap_response: msgid=167 tag=101 err=0 ber_flush: 15 bytes to sd 33 connection_get(34): got connid=1 connection_read(34): checking for input on id=1 ber_get_next ber_get_next: tag 0x30 len 219 contents: ber_get_next ber_get_next on fd 34 failed errno=11 (Resource temporarily unavailable) do_search ber_scanf fmt ({miiiib) ber: >>> dnPrettyNormal: <dc=concepts, codingScheme=RXNorm, dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org> => ldap_bv2dn(dc=concepts, codingScheme=RXNorm, dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org,0) <= ldap_bv2dn(dc=concepts, codingScheme=RXNorm, dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org,0)=0 => ldap_dn2bv(272) <= ldap_dn2bv(dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org,272)=0 => ldap_dn2bv(272) <= ldap_dn2bv(dc=concepts,codingScheme=rxnorm,dc=codingschemes,service=rxnorm,dc=lexgrid,dc=org,272)=0 <<< dnPrettyNormal: <dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org>, <dc=concepts,codingScheme=rxnorm,dc=codingschemes,service=rxnorm,dc=lexgrid,dc=org> ber_scanf fmt ({mm}) ber: ber_scanf fmt ({M}}) ber: => get_ctrls ber_scanf fmt ({m) ber: ber_scanf fmt (b) ber: ber_scanf fmt (m) ber: => get_ctrls: oid="1.2.840.113556.1.4.319" (critical) ber_scanf fmt ({im}) ber: <= get_ctrls: n=1 rc=53 err="paged results cookie is invalid or old" send_ldap_result: conn=1 op=55 p=3 send_ldap_response: msgid=56 tag=101 err=53 ber_flush: 52 bytes to sd 34 do_search: get_ctrls failed ************************************ -----Original Message----- From: Kurt Zeilenga [mailto:openldap-its@OpenLDAP.org] Sent: Wednesday, June 16, 2004 5:14 PM To: Armbrust, Daniel C. Subject: Re: paged results gives invalid cookie (ITS#3089) A number of paged results bug fixes have been committed to HEAD and OPENLDAP_REL_ENG_2_2. Please test. Thanks, Kurt
> I'm still able to generate the error with (at least) one of my databases. > This database was loaded with 2.2.11, not head, however - maybe I should > reload the database first?. The current design allows ony one pagedresults request per connection; by chance, are you issuing different requests on the same connection? I mean: on a single connection, starting more than one search with pagedresults control, and performing them simultaneously, randomly intermixed? In this case, it's guaranteed that it won't work, because slapd uses the connection structure to save the state of the last returned search. This is indeed a design limitation, and might require a bit of coding to be overcome. Can you clarify? Thanks, p. -- Pierangelo Masarati mailto:pierangelo.masarati@sys-net.it SysNet - via Dossi,8 27100 Pavia Tel: +390382573859 Fax: +390382476497
Let me add that, according to RFC2696: A client may have any number of outstanding search requests pending, any of which may have used the pagedResultsControl. A server implementation which requires a limit on the number of outstanding paged search requests from a given client MAY either return unwillingToPerform when the client attempts to create a new paged search request, or age out an older result set. If the server implementation ages out an older paged search request, it SHOULD return "unwilling to perform" if the client attempts to resume the paged search that was aged out. currently slapd complies to this when more than one request comes on the same connection; in that case, an alternative solution could be to reject further operations with "unwilling ToPerform" if they come in with an empty cookie and a (valid?) cookie is present in the connection structure; currently, it silently ages out the cookie stored in the connection structure, and starts a new one. -- Pierangelo Masarati mailto:pierangelo.masarati@sys-net.it SysNet - via Dossi,8 27100 Pavia Tel: +390382573859 Fax: +390382476497
changed notes changed state Closed to Feedback
I discovered that through trial and error a while ago... But I solved it by simply maintaining an additional connection when I needed to do that. The current way I'm raising the bug is through java with a single connection, doing a single search, and just trying to get all of the results. No other searches occur in between the times when I ask for more results (and since it's a testing server, I am the only client) I just tried again using only the openldap tools, and I can still recreate it that way as well. armbrust@mir04==> ~/openldap/ldap/clients/tools>ldapsearch -b 'dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org' -E '!pr=1' -s sub -h localhost -p 32900 # extended LDIF # # LDAPv3 # base <dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org> with scope sub # filter: (objectclass=*) # requesting: ALL # with pagedResults critical control: size=1 # # concepts, RXNorm, codingSchemes, RXNorm, LexGrid.org dn: dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid ,dc=org objectClass: concepts dc: concepts earch result search: 2 result: 0 Success control: 1.2.840.113556.1.4.319 false MAsCAwqUMwQEBQAAAA== Estimate entries: 693299 Press [size] Enter for the next {1|size} entries. # extended LDIF # # LDAPv3 # base <dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org> with scope sub # filter: (objectclass=*) # requesting: ALL # with pagedResults critical control: size=1 # # C0000220, concepts, RXNorm, codingSchemes, RXNorm, LexGrid.org dn: conceptCode=C0000220,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,serv ice=RXNorm,dc=LexGrid,dc=org version: 1 objectClass: codedEntry conceptCode: C0000220 entityDescription: 2,4-Dichlorophenoxyacetic Acid # search result search: 3 result: 0 Success control: 1.2.840.113556.1.4.319 false MAsCAwqUMwQEBgAAAA== Estimate entries: 693299 Press [size] Enter for the next {1|size} entries. . . [snip] . . 0002328, concepts, RXNorm, codingSchemes, RXNorm, LexGrid.org dn: conceptCode=C0002328,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,serv ice=RXNorm,dc=LexGrid,dc=org objectClass: codedEntry conceptCode: C0002328 entityDescription: Algestone # search result search: 60 result: 0 Success control: 1.2.840.113556.1.4.319 false MAsCAwqUMwQEPwAAAA== Estimate entries: 693299 Press [size] Enter for the next {1|size} entries. # extended LDIF # # LDAPv3 # base <dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org> with scope sub # filter: (objectclass=*) # requesting: ALL # with pagedResults critical control: size=1 # # search result search: 61 result: 53 Server is unwilling to perform text: paged results cookie is invalid or old Server is unwilling to perform (53) # numResponses: 119 armbrust@mir04== ~/openldap/ldap/clients/tools> Furthermore, the point where it fails changes - If I do this test repeatedly, it seldom fails on the same entry. So I don't think it's a corrupt entry in the database. I'm not much of a c programmer, but if there is any other debug output I can generate that may shed some light, let me know. If it would be helpful, I can publish this database for debugging. But its kind of big (about 1GB) when loaded. The ldif is 255 MB. It also has a custom schema. Dan
I suggest you enable full server-side logging. Of particular interest would be the hexdump of the server's response immediately prior to the client's last request, and the client's last request. Kurt At 11:17 AM 6/18/2004, Armbrust.Daniel@mayo.edu wrote: > I discovered that through trial and error a while ago... But I solved it by simply maintaining an additional connection when I needed to do that. > >The current way I'm raising the bug is through java with a single connection, doing a single search, and just trying to get all of the results. No other searches occur in between the times when I ask for more results (and since it's a testing server, I am the only client) > >I just tried again using only the openldap tools, and I can still recreate it that way as well. > >armbrust@mir04==> ~/openldap/ldap/clients/tools>ldapsearch -b 'dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org' -E '!pr=1' -s sub -h localhost -p 32900 ># extended LDIF ># ># LDAPv3 ># base <dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org> with scope sub ># filter: (objectclass=*) ># requesting: ALL ># with pagedResults critical control: size=1 ># > ># concepts, RXNorm, codingSchemes, RXNorm, LexGrid.org >dn: dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid > ,dc=org >objectClass: concepts >dc: concepts > > >earch result >search: 2 >result: 0 Success >control: 1.2.840.113556.1.4.319 false MAsCAwqUMwQEBQAAAA== >Estimate entries: 693299 >Press [size] Enter for the next {1|size} entries. > ># extended LDIF ># ># LDAPv3 ># base <dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org> with scope sub ># filter: (objectclass=*) ># requesting: ALL ># with pagedResults critical control: size=1 ># > ># C0000220, concepts, RXNorm, codingSchemes, RXNorm, LexGrid.org >dn: conceptCode=C0000220,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,serv > ice=RXNorm,dc=LexGrid,dc=org >version: 1 >objectClass: codedEntry >conceptCode: C0000220 >entityDescription: 2,4-Dichlorophenoxyacetic Acid > ># search result >search: 3 >result: 0 Success >control: 1.2.840.113556.1.4.319 false MAsCAwqUMwQEBgAAAA== >Estimate entries: 693299 >Press [size] Enter for the next {1|size} entries. >. >. >[snip] >. >. >0002328, concepts, RXNorm, codingSchemes, RXNorm, LexGrid.org >dn: conceptCode=C0002328,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,serv > ice=RXNorm,dc=LexGrid,dc=org >objectClass: codedEntry >conceptCode: C0002328 >entityDescription: Algestone > ># search result >search: 60 >result: 0 Success >control: 1.2.840.113556.1.4.319 false MAsCAwqUMwQEPwAAAA== >Estimate entries: 693299 >Press [size] Enter for the next {1|size} entries. ># extended LDIF ># ># LDAPv3 ># base <dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org> with scope sub ># filter: (objectclass=*) ># requesting: ALL ># with pagedResults critical control: size=1 ># > ># search result >search: 61 >result: 53 Server is unwilling to perform >text: paged results cookie is invalid or old >Server is unwilling to perform (53) > ># numResponses: 119 > >armbrust@mir04== ~/openldap/ldap/clients/tools> > > >Furthermore, the point where it fails changes - If I do this test repeatedly, it seldom fails on the same entry. So I don't think it's a corrupt entry in the database. > >I'm not much of a c programmer, but if there is any other debug output I can generate that may shed some light, let me know. > >If it would be helpful, I can publish this database for debugging. But its kind of big (about 1GB) when loaded. The ldif is 255 MB. It also has a custom schema. > >Dan
I'm probably going to error on the side of providing too much information, but here goes. Here are the last 2 entries that were returned (doing the same manual search as the previous post) # search result search: 72 result: 0 Success control: 1.2.840.113556.1.4.319 false MAsCAwqUMwQESwAAAA== Estimate entries: 693299 Press [size] Enter for the next {1|size} entries. # extended LDIF # # LDAPv3 # base <dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org> with scope sub # filter: (objectclass=*) # requesting: ALL # with pagedResults critical control: size=1 # # C0002421, concepts, RXNorm, codingSchemes, RXNorm, LexGrid.org dn: conceptCode=C0002421,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,serv ice=RXNorm,dc=LexGrid,dc=org objectClass: codedEntry conceptCode: C0002421 entityDescription: Ambroxol # search result search: 73 result: 0 Success control: 1.2.840.113556.1.4.319 false MAsCAwqUMwQETAAAAA== Estimate entries: 693299 Press [size] Enter for the next {1|size} entries. # extended LDIF # # LDAPv3 # base <dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org> with scope sub # filter: (objectclass=*) # requesting: ALL # with pagedResults critical control: size=1 # # search result search: 74 result: 53 Server is unwilling to perform text: paged results cookie is invalid or old Server is unwilling to perform (53) # numResponses: 145 Here is the end of the server log for the last couple of results that worked: do_search ber_scanf fmt ({miiiib) ber: ber_dump: buf=0x086dd6c8 ptr=0x086dd6cb end=0x086dd76a len=159 0000: 63 71 04 51 64 63 3d 63 6f 6e 63 65 70 74 73 2c cq.Qdc=concepts, 0010: 63 6f 64 69 6e 67 53 63 68 65 6d 65 3d 52 58 4e codingScheme=RXN 0020: 6f 72 6d 2c 64 63 3d 63 6f 64 69 6e 67 53 63 68 orm,dc=codingSch 0030: 65 6d 65 73 2c 73 65 72 76 69 63 65 3d 52 58 4e emes,service=RXN 0040: 6f 72 6d 2c 64 63 3d 4c 65 78 47 72 69 64 2c 64 orm,dc=LexGrid,d 0050: 63 3d 6f 72 67 0a 01 02 0a 01 00 02 01 00 02 01 c=org........... 0060: 00 01 01 00 87 0b 6f 62 6a 65 63 74 63 6c 61 73 ......objectclas 0070: 73 30 00 a0 2a 30 28 04 16 31 2e 32 2e 38 34 30 s0..*0(..1.2.840 0080: 2e 31 31 33 35 35 36 2e 31 2e 34 2e 33 31 39 01 .113556.1.4.319. 0090: 01 ff 04 0b 30 09 02 01 01 04 04 4b 00 00 00 ....0......K... >>> dnPrettyNormal: <dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org> => ldap_bv2dn(dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org,0) <= ldap_bv2dn(dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org,0)=0 => ldap_dn2bv(272) <= ldap_dn2bv(dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org,272)=0 => ldap_dn2bv(272) <= ldap_dn2bv(dc=concepts,codingScheme=rxnorm,dc=codingschemes,service=rxnorm,dc=lexgrid,dc=org,272)=0 <<< dnPrettyNormal: <dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org>, <dc=concepts,codingScheme=rxnorm,dc=codingschemes,service=rxnorm,dc=lexgrid,dc=org> SRCH "dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org" 2 0 0 0 0 begin get_filter PRESENT ber_scanf fmt (m) ber: ber_dump: buf=0x086dd6c8 ptr=0x086dd72f end=0x086dd76a len=59 0000: 87 0b 6f 62 6a 65 63 74 63 6c 61 73 73 30 00 a0 ..objectclass0.. 0010: 2a 30 28 04 16 31 2e 32 2e 38 34 30 2e 31 31 33 *0(..1.2.840.113 0020: 35 35 36 2e 31 2e 34 2e 33 31 39 01 01 ff 04 0b 556.1.4.319..... 0030: 30 09 02 01 01 04 04 4b 00 00 00 0......K... end get_filter 0 filter: (objectClass=*) ber_scanf fmt ({M}}) ber: ber_dump: buf=0x086dd6c8 ptr=0x086dd73c end=0x086dd76a len=46 0000: 00 00 a0 2a 30 28 04 16 31 2e 32 2e 38 34 30 2e ...*0(..1.2.840. 0010: 31 31 33 35 35 36 2e 31 2e 34 2e 33 31 39 01 01 113556.1.4.319.. 0020: ff 04 0b 30 09 02 01 01 04 04 4b 00 00 00 ...0......K... => get_ctrls ber_scanf fmt ({m) ber: ber_dump: buf=0x086dd6c8 ptr=0x086dd740 end=0x086dd76a len=42 0000: 30 28 04 16 31 2e 32 2e 38 34 30 2e 31 31 33 35 0(..1.2.840.1135 0010: 35 36 2e 31 2e 34 2e 33 31 39 01 01 ff 04 0b 30 56.1.4.319.....0 0020: 09 02 01 01 04 04 4b 00 00 00 ......K... ber_scanf fmt (b) ber: ber_dump: buf=0x086dd6c8 ptr=0x086dd75a end=0x086dd76a len=16 0000: 00 01 ff 04 0b 30 09 02 01 01 04 04 4b 00 00 00 .....0......K... ber_scanf fmt (m) ber: ber_dump: buf=0x086dd6c8 ptr=0x086dd75d end=0x086dd76a len=13 0000: 04 0b 30 09 02 01 01 04 04 4b 00 00 00 ..0......K... => get_ctrls: oid="1.2.840.113556.1.4.319" (critical) ber_scanf fmt ({im}) ber: ber_dump: buf=0x086f2ed0 ptr=0x086f2ed0 end=0x086f2edb len=11 0000: 30 09 02 01 01 04 04 4b 00 00 00 0......K... <= get_ctrls: n=1 rc=0 err="" attrs: conn=0 op=72 SRCH base="dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org" scope=2 deref=0 filter="(objectClass=*)" ==> limits_get: conn=0 op=72 dn="[anonymous]" => bdb_search bdb_dn2entry("dc=concepts,codingScheme=rxnorm,dc=codingschemes,service=rxnorm,dc=lexgrid,dc=org") search_candidates: base="dc=concepts,codingScheme=rxnorm,dc=codingschemes,service=rxnorm,dc=lexgrid,dc=org" (0x00000005) scope=2 => bdb_dn2idl( "dc=concepts,codingScheme=rxnorm,dc=codingschemes,service=rxnorm,dc=lexgrid,dc=org" ) bdb_idl_fetch_key: @dc=concepts,codingScheme=rxnorm,dc=codingschemes,service=rxnorm,dc=lexgrid,dc=org <= bdb_dn2idl: id=-1 first=5 last=693303 => bdb_filter_candidates AND => bdb_list_candidates 0xa0 => bdb_filter_candidates PRESENT => bdb_presence_candidates (objectClass) <= bdb_filter_candidates: id=-1 first=1 last=694184 <= bdb_list_candidates: id=-1 first=5 last=693303 <= bdb_filter_candidates: id=-1 first=5 last=693303 bdb_search_candidates: id=-1 first=5 last=693303 => test_filter PRESENT => access_allowed: search access to "conceptCode=C0002421,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org" "objectClass" requested => dn: [1] dc=users,service=uservalidation,dc=lexgrid,dc=org => dn: [2] dc=org => dn: [3] service=cts,dc=lexgrid,dc=org => dn: [4] service=ietfterminologyservice,dc=lexgrid,dc=org => dn: [5] service=isoterminologyservice,dc=lexgrid,dc=org => dn: [6] service=nci,dc=lexgrid,dc=org => dn: [7] service=rxnorm,dc=lexgrid,dc=org => acl_get: [7] matched => acl_get: [7] attr objectClass => acl_mask: access to entry "conceptCode=C0002421,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org", attr "objectClass" requested => acl_mask: to all values by "", (=n) <= check a_dn_pat: cn=admin,dc=users,service=uservalidation,dc=lexgrid,dc=org <= check a_dn_pat: * <= acl_mask: [2] applying read(=rscx) (stop) <= acl_mask: [2] mask: read(=rscx) => access_allowed: search access granted by read(=rscx) <= test_filter 6 => send_search_entry: dn="conceptCode=C0002421,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org" => access_allowed: read access to "conceptCode=C0002421,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org" "entry" requested => dn: [1] dc=users,service=uservalidation,dc=lexgrid,dc=org => dn: [2] dc=org => dn: [3] service=cts,dc=lexgrid,dc=org => dn: [4] service=ietfterminologyservice,dc=lexgrid,dc=org => dn: [5] service=isoterminologyservice,dc=lexgrid,dc=org => dn: [6] service=nci,dc=lexgrid,dc=org => dn: [7] service=rxnorm,dc=lexgrid,dc=org => acl_get: [7] matched => acl_get: [7] attr entry => acl_mask: access to entry "conceptCode=C0002421,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org", attr "entry" requested => acl_mask: to all values by "", (=n) <= check a_dn_pat: cn=admin,dc=users,service=uservalidation,dc=lexgrid,dc=org <= check a_dn_pat: * <= acl_mask: [2] applying read(=rscx) (stop) <= acl_mask: [2] mask: read(=rscx) => access_allowed: read access granted by read(=rscx) => access_allowed: read access to "conceptCode=C0002421,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org" "objectClass" requested => dn: [1] dc=users,service=uservalidation,dc=lexgrid,dc=org => dn: [2] dc=org => dn: [3] service=cts,dc=lexgrid,dc=org => dn: [4] service=ietfterminologyservice,dc=lexgrid,dc=org => dn: [5] service=isoterminologyservice,dc=lexgrid,dc=org => dn: [6] service=nci,dc=lexgrid,dc=org => dn: [7] service=rxnorm,dc=lexgrid,dc=org => acl_get: [7] matched => acl_get: [7] attr objectClass access_allowed: no res from state (objectClass) => acl_mask: access to entry "conceptCode=C0002421,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org", attr "objectClass" requested => acl_mask: to value by "", (=n) <= check a_dn_pat: cn=admin,dc=users,service=uservalidation,dc=lexgrid,dc=org <= check a_dn_pat: * <= acl_mask: [2] applying read(=rscx) (stop) <= acl_mask: [2] mask: read(=rscx) => access_allowed: read access granted by read(=rscx) => access_allowed: read access to "conceptCode=C0002421,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org" "conceptCode" requested => dn: [1] dc=users,service=uservalidation,dc=lexgrid,dc=org => dn: [2] dc=org => dn: [3] service=cts,dc=lexgrid,dc=org => dn: [4] service=ietfterminologyservice,dc=lexgrid,dc=org => dn: [5] service=isoterminologyservice,dc=lexgrid,dc=org => dn: [6] service=nci,dc=lexgrid,dc=org => dn: [7] service=rxnorm,dc=lexgrid,dc=org => acl_get: [7] matched => acl_get: [7] attr conceptCode access_allowed: no res from state (conceptCode) => acl_mask: access to entry "conceptCode=C0002421,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org", attr "conceptCode" requested => acl_mask: to value by "", (=n) <= check a_dn_pat: cn=admin,dc=users,service=uservalidation,dc=lexgrid,dc=org <= check a_dn_pat: * <= acl_mask: [2] applying read(=rscx) (stop) <= acl_mask: [2] mask: read(=rscx) => access_allowed: read access granted by read(=rscx) => access_allowed: read access to "conceptCode=C0002421,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org" "entityDescription" requested => dn: [1] dc=users,service=uservalidation,dc=lexgrid,dc=org => dn: [2] dc=org => dn: [3] service=cts,dc=lexgrid,dc=org => dn: [4] service=ietfterminologyservice,dc=lexgrid,dc=org => dn: [5] service=isoterminologyservice,dc=lexgrid,dc=org => dn: [6] service=nci,dc=lexgrid,dc=org => dn: [7] service=rxnorm,dc=lexgrid,dc=org => acl_get: [7] matched => acl_get: [7] attr entityDescription access_allowed: no res from state (entityDescription) => acl_mask: access to entry "conceptCode=C0002421,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org", attr "entityDescription" requested => acl_mask: to value by "", (=n) <= check a_dn_pat: cn=admin,dc=users,service=uservalidation,dc=lexgrid,dc=org <= check a_dn_pat: * <= acl_mask: [2] applying read(=rscx) (stop) <= acl_mask: [2] mask: read(=rscx) => access_allowed: read access granted by read(=rscx) ber_flush: 204 bytes to sd 33 0000: 30 81 c9 02 01 49 64 81 c3 04 66 63 6f 6e 63 65 0....Id...fconce 0010: 70 74 43 6f 64 65 3d 43 30 30 30 32 34 32 31 2c ptCode=C0002421, 0020: 64 63 3d 63 6f 6e 63 65 70 74 73 2c 63 6f 64 69 dc=concepts,codi 0030: 6e 67 53 63 68 65 6d 65 3d 52 58 4e 6f 72 6d 2c ngScheme=RXNorm, 0040: 64 63 3d 63 6f 64 69 6e 67 53 63 68 65 6d 65 73 dc=codingSchemes 0050: 2c 73 65 72 76 69 63 65 3d 52 58 4e 6f 72 6d 2c ,service=RXNorm, 0060: 64 63 3d 4c 65 78 47 72 69 64 2c 64 63 3d 6f 72 dc=LexGrid,dc=or 0070: 67 30 59 30 1b 04 0b 6f 62 6a 65 63 74 43 6c 61 g0Y0...objectCla 0080: 73 73 31 0c 04 0a 63 6f 64 65 64 45 6e 74 72 79 ss1...codedEntry 0090: 30 19 04 0b 63 6f 6e 63 65 70 74 43 6f 64 65 31 0...conceptCode1 00a0: 0a 04 08 43 30 30 30 32 34 32 31 30 1f 04 11 65 ...C00024210...e 00b0: 6e 74 69 74 79 44 65 73 63 72 69 70 74 69 6f 6e ntityDescription 00c0: 31 0a 04 08 41 6d 62 72 6f 78 6f 6c 1...Ambroxol ldap_write: want=204, written=204 0000: 30 81 c9 02 01 49 64 81 c3 04 66 63 6f 6e 63 65 0....Id...fconce 0010: 70 74 43 6f 64 65 3d 43 30 30 30 32 34 32 31 2c ptCode=C0002421, 0020: 64 63 3d 63 6f 6e 63 65 70 74 73 2c 63 6f 64 69 dc=concepts,codi 0030: 6e 67 53 63 68 65 6d 65 3d 52 58 4e 6f 72 6d 2c ngScheme=RXNorm, 0040: 64 63 3d 63 6f 64 69 6e 67 53 63 68 65 6d 65 73 dc=codingSchemes 0050: 2c 73 65 72 76 69 63 65 3d 52 58 4e 6f 72 6d 2c ,service=RXNorm, 0060: 64 63 3d 4c 65 78 47 72 69 64 2c 64 63 3d 6f 72 dc=LexGrid,dc=or 0070: 67 30 59 30 1b 04 0b 6f 62 6a 65 63 74 43 6c 61 g0Y0...objectCla 0080: 73 73 31 0c 04 0a 63 6f 64 65 64 45 6e 74 72 79 ss1...codedEntry 0090: 30 19 04 0b 63 6f 6e 63 65 70 74 43 6f 64 65 31 0...conceptCode1 00a0: 0a 04 08 43 30 30 30 32 34 32 31 30 1f 04 11 65 ...C00024210...e 00b0: 6e 74 69 74 79 44 65 73 63 72 69 70 74 69 6f 6e ntityDescription 00c0: 31 0a 04 08 41 6d 62 72 6f 78 6f 6c 1...Ambroxol conn=0 op=72 ENTRY dn="conceptCode=C0002421,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org" <= send_search_entry entry_decode: "conceptCode=C0002435,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org" <= entry_decode(conceptCode=C0002435,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org) => bdb_dn2id( "conceptCode=c0002435,dc=concepts,codingScheme=rxnorm,dc=codingschemes,service=rxnorm,dc=lexgrid,dc=org" ) <= bdb_dn2id: got id=0x0000004d => test_filter PRESENT => access_allowed: search access to "conceptCode=C0002435,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org" "objectClass" requested => dn: [1] dc=users,service=uservalidation,dc=lexgrid,dc=org => dn: [2] dc=org => dn: [3] service=cts,dc=lexgrid,dc=org => dn: [4] service=ietfterminologyservice,dc=lexgrid,dc=org => dn: [5] service=isoterminologyservice,dc=lexgrid,dc=org => dn: [6] service=nci,dc=lexgrid,dc=org => dn: [7] service=rxnorm,dc=lexgrid,dc=org => acl_get: [7] matched => acl_get: [7] attr objectClass => acl_mask: access to entry "conceptCode=C0002435,dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org", attr "objectClass" requested => acl_mask: to all values by "", (=n) <= check a_dn_pat: cn=admin,dc=users,service=uservalidation,dc=lexgrid,dc=org <= check a_dn_pat: * <= acl_mask: [2] applying read(=rscx) (stop) <= acl_mask: [2] mask: read(=rscx) => access_allowed: search access granted by read(=rscx) <= test_filter 6 send_paged_response: lastid: (0x0000004c) nentries: (0x000000000000000000000000000000000000000000000000000000000000000000000000000000001) send_ldap_result: conn=0 op=72 p=3 send_ldap_result: err=0 matched="" text="" send_ldap_response: msgid=73 tag=101 err=0 ber_flush: 57 bytes to sd 33 0000: 30 37 02 01 49 65 07 0a 01 00 04 00 04 00 a0 29 07..Ie.........) 0010: 30 27 04 16 31 2e 32 2e 38 34 30 2e 31 31 33 35 0'..1.2.840.1135 0020: 35 36 2e 31 2e 34 2e 33 31 39 04 0d 30 0b 02 03 56.1.4.319..0... 0030: 0a 94 33 04 04 4c 00 00 00 ..3..L... daemon: activity on 1 descriptors daemon: activity on: 33r daemon: read activity on 33 connection_get(33) ldap_write: want=57, written=57 0000: 30 37 02 01 49 65 07 0a 01 00 04 00 04 00 a0 29 07..Ie.........) 0010: 30 27 04 16 31 2e 32 2e 38 34 30 2e 31 31 33 35 0'..1.2.840.1135 0020: 35 36 2e 31 2e 34 2e 33 31 39 04 0d 30 0b 02 03 56.1.4.319..0... 0030: 0a 94 33 04 04 4c 00 00 00 ..3..L... connection_get(33): got connid=0 connection_read(33): checking for input on id=0 ber_get_next ldap_read: want=8, got=8 0000: 30 81 a2 02 01 4a 63 71 0....Jcq ldap_read: want=157, got=157 0000: 04 51 64 63 3d 63 6f 6e 63 65 70 74 73 2c 63 6f .Qdc=concepts,co 0010: 64 69 6e 67 53 63 68 65 6d 65 3d 52 58 4e 6f 72 dingScheme=RXNor 0020: 6d 2c 64 63 3d 63 6f 64 69 6e 67 53 63 68 65 6d m,dc=codingSchem 0030: 65 73 2c 73 65 72 76 69 63 65 3d 52 58 4e 6f 72 es,service=RXNor 0040: 6d 2c 64 63 3d 4c 65 78 47 72 69 64 2c 64 63 3d m,dc=LexGrid,dc= 0050: 6f 72 67 0a 01 02 0a 01 00 02 01 00 02 01 00 01 org............. 0060: 01 00 87 0b 6f 62 6a 65 63 74 63 6c 61 73 73 30 ....objectclass0 0070: 00 a0 2a 30 28 04 16 31 2e 32 2e 38 34 30 2e 31 ..*0(..1.2.840.1 0080: 31 33 35 35 36 2e 31 2e 34 2e 33 31 39 01 01 ff 13556.1.4.319... 0090: 04 0b 30 09 02 01 01 04 04 4c 00 00 00 ..0......L... ber_get_next: tag 0x30 len 162 contents: ber_dump: buf=0x086f4380 ptr=0x086f4380 end=0x086f4422 len=162 0000: 02 01 4a 63 71 04 51 64 63 3d 63 6f 6e 63 65 70 ..Jcq.Qdc=concep 0010: 74 73 2c 63 6f 64 69 6e 67 53 63 68 65 6d 65 3d ts,codingScheme= 0020: 52 58 4e 6f 72 6d 2c 64 63 3d 63 6f 64 69 6e 67 RXNorm,dc=coding 0030: 53 63 68 65 6d 65 73 2c 73 65 72 76 69 63 65 3d Schemes,service= 0040: 52 58 4e 6f 72 6d 2c 64 63 3d 4c 65 78 47 72 69 RXNorm,dc=LexGri 0050: 64 2c 64 63 3d 6f 72 67 0a 01 02 0a 01 00 02 01 d,dc=org........ 0060: 00 02 01 00 01 01 00 87 0b 6f 62 6a 65 63 74 63 .........objectc 0070: 6c 61 73 73 30 00 a0 2a 30 28 04 16 31 2e 32 2e lass0..*0(..1.2. 0080: 38 34 30 2e 31 31 33 35 35 36 2e 31 2e 34 2e 33 840.113556.1.4.3 0090: 31 39 01 01 ff 04 0b 30 09 02 01 01 04 04 4c 00 19.....0......L. 00a0: 00 00 .. ber_get_next ldap_read: want=8 error=Resource temporarily unavailable ber_get_next on fd 33 failed errno=11 (Resource temporarily unavailable) conn=0 op=72 SEARCH RESULT tag=101 err=0 nentries=1 text= do_search ber_scanf fmt ({miiiib) ber: ber_dump: buf=0x086f4380 ptr=0x086f4383 end=0x086f4422 len=159 0000: 63 71 04 51 64 63 3d 63 6f 6e 63 65 70 74 73 2c cq.Qdc=concepts, 0010: 63 6f 64 69 6e 67 53 63 68 65 6d 65 3d 52 58 4e codingScheme=RXN 0020: 6f 72 6d 2c 64 63 3d 63 6f 64 69 6e 67 53 63 68 orm,dc=codingSch 0030: 65 6d 65 73 2c 73 65 72 76 69 63 65 3d 52 58 4e emes,service=RXN 0040: 6f 72 6d 2c 64 63 3d 4c 65 78 47 72 69 64 2c 64 orm,dc=LexGrid,d 0050: 63 3d 6f 72 67 0a 01 02 0a 01 00 02 01 00 02 01 c=org........... 0060: 00 01 01 00 87 0b 6f 62 6a 65 63 74 63 6c 61 73 ......objectclas 0070: 73 30 00 a0 2a 30 28 04 16 31 2e 32 2e 38 34 30 s0..*0(..1.2.840 0080: 2e 31 31 33 35 35 36 2e 31 2e 34 2e 33 31 39 01 .113556.1.4.319. 0090: 01 ff 04 0b 30 09 02 01 01 04 04 4c 00 00 00 ....0......L... >>> dnPrettyNormal: <dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org> => ldap_bv2dn(dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org,0) <= ldap_bv2dn(dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org,0)=0 => ldap_dn2bv(272) <= ldap_dn2bv(dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org,272)=0 => ldap_dn2bv(272) <= ldap_dn2bv(dc=concepts,codingScheme=rxnorm,dc=codingschemes,service=rxnorm,dc=lexgrid,dc=org,272)=0 <<< dnPrettyNormal: <dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org>, <dc=concepts,codingScheme=rxnorm,dc=codingschemes,service=rxnorm,dc=lexgrid,dc=org> SRCH "dc=concepts,codingScheme=RXNorm,dc=codingSchemes,service=RXNorm,dc=LexGrid,dc=org" 2 0 0 0 0 begin get_filter PRESENT ber_scanf fmt (m) ber: ber_dump: buf=0x086f4380 ptr=0x086f43e7 end=0x086f4422 len=59 0000: 87 0b 6f 62 6a 65 63 74 63 6c 61 73 73 30 00 a0 ..objectclass0.. 0010: 2a 30 28 04 16 31 2e 32 2e 38 34 30 2e 31 31 33 *0(..1.2.840.113 0020: 35 35 36 2e 31 2e 34 2e 33 31 39 01 01 ff 04 0b 556.1.4.319..... 0030: 30 09 02 01 01 04 04 4c 00 00 00 0......L... end get_filter 0 filter: (objectClass=*) ber_scanf fmt ({M}}) ber: ber_dump: buf=0x086f4380 ptr=0x086f43f4 end=0x086f4422 len=46 0000: 00 00 a0 2a 30 28 04 16 31 2e 32 2e 38 34 30 2e ...*0(..1.2.840. 0010: 31 31 33 35 35 36 2e 31 2e 34 2e 33 31 39 01 01 113556.1.4.319.. 0020: ff 04 0b 30 09 02 01 01 04 04 4c 00 00 00 ...0......L... => get_ctrls ber_scanf fmt ({m) ber: ber_dump: buf=0x086f4380 ptr=0x086f43f8 end=0x086f4422 len=42 0000: 30 28 04 16 31 2e 32 2e 38 34 30 2e 31 31 33 35 0(..1.2.840.1135 0010: 35 36 2e 31 2e 34 2e 33 31 39 01 01 ff 04 0b 30 56.1.4.319.....0 0020: 09 02 01 01 04 04 4c 00 00 00 ......L... ber_scanf fmt (b) ber: ber_dump: buf=0x086f4380 ptr=0x086f4412 end=0x086f4422 len=16 0000: 00 01 ff 04 0b 30 09 02 01 01 04 04 4c 00 00 00 .....0......L... ber_scanf fmt (m) ber: ber_dump: buf=0x086f4380 ptr=0x086f4415 end=0x086f4422 len=13 0000: 04 0b 30 09 02 01 01 04 04 4c 00 00 00 ..0......L... => get_ctrls: oid="1.2.840.113556.1.4.319" (critical) ber_scanf fmt ({im}) ber: ber_dump: buf=0x086f3380 ptr=0x086f3380 end=0x086f338b len=11 0000: 30 09 02 01 01 04 04 4c 00 00 00 0......L... <= get_ctrls: n=1 rc=53 err="paged results cookie is invalid or old" send_ldap_result: conn=0 op=73 p=3 send_ldap_result: err=53 matched="" text="paged results cookie is invalid or old" send_ldap_response: msgid=74 tag=101 err=53 ber_flush: 52 bytes to sd 33 0000: 30 32 02 01 4a 65 2d 0a 01 35 04 00 04 26 70 61 02..Je-..5...&pa 0010: 67 65 64 20 72 65 73 75 6c 74 73 20 63 6f 6f 6b ged results cook 0020: 69 65 20 69 73 20 69 6e 76 61 6c 69 64 20 6f 72 ie is invalid or 0030: 20 6f 6c 64 old ldap_write: want=52, written=52 0000: 30 32 02 01 4a 65 2d 0a 01 35 04 00 04 26 70 61 02..Je-..5...&pa 0010: 67 65 64 20 72 65 73 75 6c 74 73 20 63 6f 6f 6b ged results cook 0020: 69 65 20 69 73 20 69 6e 76 61 6c 69 64 20 6f 72 ie is invalid or 0030: 20 6f 6c 64 old conn=0 op=73 SEARCH RESULT tag=101 err=53 nentries=0 text=paged results cookie is invalid or old do_search: get_ctrls failed daemon: select: listen=6 active_threads=1 tvp=zero daemon: activity on 1 descriptors daemon: activity on: 33r daemon: read activity on 33 connection_get(33) connection_get(33): got connid=0 connection_read(33): checking for input on id=0 ber_get_next ldap_read: want=8, got=8 0000: 30 31 02 01 4b 42 00 a0 01..KB.. ldap_read: want=43, got=43 0000: 2a 30 28 04 16 31 2e 32 2e 38 34 30 2e 31 31 33 *0(..1.2.840.113 0010: 35 35 36 2e 31 2e 34 2e 33 31 39 01 01 ff 04 0b 556.1.4.319..... 0020: 30 09 02 01 01 04 04 4c 00 00 00 0......L... ber_get_next: tag 0x30 len 49 contents: ber_dump: buf=0x086dd670 ptr=0x086dd670 end=0x086dd6a1 len=49 0000: 02 01 4b 42 00 a0 2a 30 28 04 16 31 2e 32 2e 38 ..KB..*0(..1.2.8 0010: 34 30 2e 31 31 33 35 35 36 2e 31 2e 34 2e 33 31 40.113556.1.4.31 0020: 39 01 01 ff 04 0b 30 09 02 01 01 04 04 4c 00 00 9.....0......L.. 0030: 00 . ber_get_next ldap_read: want=8, got=0 ber_get_next on fd 33 failed errno=0 (Success) connection_read(33): input error=-2 id=0, closing. connection_closing: readying conn=0 sd=33 for close connection_close: deferring conn=0 sd=33 do_unbind conn=0 op=74 UNBIND connection_resched: attempting closing conn=0 sd=33 connection_close: conn=0 sd=33 daemon: removing 33 conn=0 fd=33 closed daemon: select: listen=6 active_threads=0 tvp=NULL daemon: activity on 1 descriptors daemon: select: listen=6 active_threads=0 tvp=NULL daemon: shutdown requested and initiated.
I think I've spotted the bug; slapd was parsing the cookie value after freeing the memory it was carried on. Now it seems to work fine. Please test, and, in case of positive feedback, I'll propagate it to 2.2. Thanks, p. -- Pierangelo Masarati mailto:pierangelo.masarati@sys-net.it SysNet - via Dossi,8 27100 Pavia Tel: +390382573859 Fax: +390382476497
changed notes changed state Feedback to Test
It looks good in my initial tests. I use to be able to recreate this bug pretty easily, but I haven't seen the bug reappear yet with the code I downloaded this morning. Thanks for all your work in fixing this! I'm going to keep running some additional tests to make sure, but it looks like it is now fully fixed. Thanks again, Dan -----Original Message----- From: Pierangelo Masarati [mailto:ando@sys-net.it] Sent: Monday, June 21, 2004 10:49 AM To: Armbrust, Daniel C. Cc: openldap-its@openldap.org Subject: RE: paged results gives invalid cookie (ITS#3089) I think I've spotted the bug; slapd was parsing the cookie value after freeing the memory it was carried on. Now it seems to work fine. Please test, and, in case of positive feedback, I'll propagate it to 2.2. Thanks, p. -- Pierangelo Masarati mailto:pierangelo.masarati@sys-net.it SysNet - via Dossi,8 27100 Pavia Tel: +390382573859 Fax: +390382476497
> It looks good in my initial tests. I use to be able to recreate this bug > pretty easily, but I haven't seen the bug reappear yet with the code I > downloaded this morning. > > Thanks for all your work in fixing this! > > I'm going to keep running some additional tests to make sure, but it looks > like it is now fully fixed. Well, that was definitely a bug; if it's not enough to fix your problem, it's something worth fixing anyway :) p. -- Pierangelo Masarati mailto:pierangelo.masarati@sys-net.it SysNet - via Dossi,8 27100 Pavia Tel: +390382573859 Fax: +390382476497
changed notes changed state Release to Closed
moved from Software Bugs to Archive.Software Bugs
# fixed in HEAD/re22 # User reports continuing problem re-fixed in HEAD/re22