Account activation, user is not eligible

[matthe...@selu.edu]

I'm attempting to activate users; however, I'm getting a 5021 error. Trace below...

ctober 16, 2015 at 4:08:46 AM CDT, TRACE, http.PwmResponse, {yc} forwarding to /WEB-INF/jsp/error.jsp [70.196.131.73]
October 16, 2015 at 4:08:46 AM CDT, ERROR, http.PwmRequest, {yc} 5021 ERROR_ACTIVATE_USER_NO_QUERY_MATCH (user UserIdentity{"userDN":"CN=Bearguest,OU=Guests,ou=User Base,dc=not,dc=real","ldapProfile":"default"} attempted activation, but does not match query string) [70.196.131.73]
October 16, 2015 at 4:08:46 AM CDT, FATAL, servlet.AbstractPwmServlet, 5021 ERROR_ACTIVATE_USER_NO_QUERY_MATCH (user UserIdentity{"userDN":"CN=Bearguest,OU=Guests,ou=User Base,dc=not,dc=real","ldapProfile":"default"} attempted activation, but does not match query string)
October 16, 2015 at 4:08:44 AM CDT, TRACE, intruder.IntruderManager, {yc} delaying response 1563ms due to intruder record: {"type":"ADDRESS","subject":"70.196.131.73","timeStamp":"2015-10-16T09:08:44Z","attemptCount":1,"alerted":false} [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, DEBUG, event.AuditManager, discarding event, INTRUDER_ATTEMPT are being ignored; event={"instance":"9BA9FB7F7B829E76","type":"SYSTEM","eventCode":"INTRUDER_ATTEMPT","guid":"ae87635e-8178-4a30-a272-c8e58bdfbd21","timestamp":"2015-10-16T09:08:44Z","message":"{\"type\":\"ADDRESS\",\"subject\":\"70.196.131.73\"}"}
October 16, 2015 at 4:08:44 AM CDT, TRACE, intruder.IntruderManager, {yc} delaying response 609ms due to intruder record: {"type":"USER_ID","subject":"default|CN=Bearguest,OU=Guests,ou=User Base,dc=not,dc=real","timeStamp":"2015-10-16T09:08:44Z","attemptCount":1,"alerted":false} [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, DEBUG, event.AuditManager, discarding event, INTRUDER_ATTEMPT are being ignored; event={"instance":"9BA9FB7F7B829E76","type":"SYSTEM","eventCode":"INTRUDER_ATTEMPT","guid":"a3b45bfe-648b-407c-83b7-0c18cae4ebce","timestamp":"2015-10-16T09:08:44Z","message":"{\"type\":\"USER_ID\",\"subject\":\"default|CN=Bearguest,OU=Guests,ou=User Base,dc=not,dc=real\"}"}
October 16, 2015 at 4:08:44 AM CDT, DEBUG, intruder.RecordManagerImpl, re-setting existing outdated record={"type":"USER_ID","subject":"default|CN=Bearguest,OU=Guests,ou=User Base,dc=not,dc=real","timeStamp":"2015-10-16T08:44:34Z","attemptCount":1,"alerted":false} (24m)
October 16, 2015 at 4:08:44 AM CDT, TRACE, cache.CacheService, , memCache={"storeCount":22,"readCount":34,"hitCount":11,"missCount":23,"itemCount":1}, localDbCache={"storeCount":22,"readCount":23,"hitCount":0,"missCount":23,"itemCount":0}
October 16, 2015 at 4:08:44 AM CDT, TRACE, servlet.ActivateUserServlet, {yc} skipping validation of ldap value for 'cn' because it is in search filter [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, TRACE, servlet.ActivateUserServlet, {yc} auto generated search filter based on activation form: (&(objectclass=User)(cn=%cn%)) [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, DEBUG, ldap.UserSearchEngine, {yc} found userDN: CN=Bearguest,OU=Guests,ou=User Base,dc=not,dc=real (72ms) [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, DEBUG, ldap.UserSearchEngine, {yc} completed user search process in 72ms, resultSize=1 [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, TRACE, ldap.UserSearchEngine, {yc} no matches from search (1ms); searchID=85 profile=default base=CN=Users,dc=not,dc=real filter=SearchHelper: filter: (&(objectclass=User)(cn=Bearguest)), scope: SUBTREE, attributes: [] maxCount=1 [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, DEBUG, ldap.UserSearchEngine, {yc} performing ldap search for user; searchID=85 profile=default base=CN=Users,dc=not,dc=real filter=SearchHelper: filter: (&(objectclass=User)(cn=Bearguest)), scope: SUBTREE, attributes: [] maxCount=1 [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, TRACE, ldap.UserSearchEngine, {yc} no matches from search (0ms); searchID=84 profile=default base=ou=Service Accounts,dc=not,dc=real filter=SearchHelper: filter: (&(objectclass=User)(cn=Bearguest)), scope: SUBTREE, attributes: [] maxCount=1 [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, DEBUG, ldap.UserSearchEngine, {yc} performing ldap search for user; searchID=84 profile=default base=ou=Service Accounts,dc=not,dc=real filter=SearchHelper: filter: (&(objectclass=User)(cn=Bearguest)), scope: SUBTREE, attributes: [] maxCount=1 [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, TRACE, ldap.UserSearchEngine, {yc} found 1 results in 70ms; searchID=83 profile=default base=ou=User Base,dc=not,dc=real filter=SearchHelper: filter: (&(objectclass=User)(cn=Bearguest)), scope: SUBTREE, attributes: [] maxCount=2 [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, TRACE, provider.ChaiProviderFactory, adding StatisticsWrapper to provider instance
October 16, 2015 at 4:08:44 AM CDT, TRACE, provider.WatchdogWrapper, checking for user password expiration to adjust watchdog timeout
October 16, 2015 at 4:08:44 AM CDT, DEBUG, provider.WatchdogWrapper, starting up LDAP Chai WatchdogWrapper timer thread, 5000ms check frequency
October 16, 2015 at 4:08:44 AM CDT, TRACE, provider.ChaiProviderFactory, adding WatchdogWrapper to provider instance
October 16, 2015 at 4:08:44 AM CDT, TRACE, provider.JNDIProviderImpl, bind successful as cn=AD Admin,ou=Service Accounts,dc=not,dc=real (66ms)
October 16, 2015 at 4:08:44 AM CDT, DEBUG, provider.WatchdogWrapper, reopening ldap connection for cn=AD Admin,ou=Service Accounts,dc=not,dc=real
October 16, 2015 at 4:08:44 AM CDT, DEBUG, ldap.UserSearchEngine, {yc} performing ldap search for user; searchID=83 profile=default base=ou=User Base,dc=not,dc=real filter=SearchHelper: filter: (&(objectclass=User)(cn=Bearguest)), scope: SUBTREE, attributes: [] maxCount=2 [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, DEBUG, ldap.UserSearchEngine, {yc} beginning user search process [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, TRACE, servlet.ActivateUserServlet, {yc} auto generated search filter based on activation form: (&(objectclass=User)(cn=%cn%)) [70.196.131.73]
October 16, 2015 at 4:08:44 AM CDT, TRACE, http.PwmRequest, {yc} POST request for: /pwm/public/activate [70.196.131.73]
processAction='activate'
cn='Bearguest'
pwmFormID='0hIRvFGhx6NUfErv5A38fPGGYqL7Tp721506fe821d1LAfBu'

[matthe...@selu.edu]

Thanks in advance :)

[matthe...@selu.edu]

Running the nightly build from a few days ago

[Jason Rivard]

I'm not sure what isn't clear about the logs?  The user doesn't match the activation filter...

[matthe...@selu.edu]

On Tuesday, October 20, 2015 at 6:48:21 PM UTC-5, Jason Rivard wrote:
> I'm not sure what isn't clear about the logs?  The user doesn't match the activation filter...

I figured out what the issue was.

When left blank the Activation filter will be constructed based on the attributes supplied to the Activation Module.

In my case, the constructed query was cn=%cn% . But, even though that user existed, and PWM found it, it didn't match. After some trial and error, I included the explicit filter (&(objectclass=person)(cn=%cn%)) , which was later changed to use 'user' instead of 'person'. It worked after that.