Activate User Not Working First Time

454 views

Skip to first unread message

Lee Wiscovitch

unread,

Apr 5, 2021, 3:46:57 PM4/5/21

to pwm-general

Seeing something similar to this thread:

https://groups.google.com/g/pwm-general/c/0rVOg8feYbU/m/k-VbNe_XBAAJ

I create a new AD user, set a random password and valid email, and then attempt to activate the user using PWM.

The first time I attempt it, it skips the set password screen and goes back to the default login page.

If I retry, it works!

So my questions are this:

1 - If this indeed addressed already, how do get that? I'm trying to avoid building the WAR, so I've been using https://www.pwm-project.org/artifacts/pwm/release/v1.9.1/pwm-1.9.1.war so far. But obviously since it's 1.5 years old, it's missing new code. Should I just bite the bullet and plan on building the WAR as part of my deployment tasks?

2 - How can I prevent a user from going through the activation process more than one successful time? We have OTP enabled and required if that makes any difference. I saw another thread that mentioned using the following activation filter:

(&(objectclass=person)(!(userAccountControl:1.2.840.113556.1.4.803:=2))(|(lastLogon=0)(!(lastLogonTimestamp=*))))

Is that a valid solution?

Here are the TRACE logs for the two attempts (I replaced any sensitive data):

###FAIL###

2021-04-05T19:38:17Z, TRACE, http.PwmRequest, {fTNKU} GET request for: /pwm/public/activate (no params) requestID=1563 [x.x.x.x]

2021-04-05T19:38:17Z, TRACE, http.SessionManager, {fTNKU} incremented request counter to 2 [x.x.x.x]

2021-04-05T19:38:17Z, TRACE, state.CryptoCookieLoginImpl, {fTNKU} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:38:17Z","g":"kn4zt7u8GT6CdMhIxSd2Y6yK6ls10ThxXY1dbsq5EPPHRJRMhqw1r3zClC4G3xQgWDaUULay","c":2,"lf":[]} [x.x.x.x]

2021-04-05T19:38:17Z, TRACE, http.PwmResponse, {fTNKU} forwarding to /WEB-INF/jsp/activateuser.jsp [x.x.x.x]

2021-04-05T19:38:17Z, TRACE, http.PwmRequest, {fTNKU} GET request for: /pwm/public/activate (no params) completed requestID=1563 in 3ms [x.x.x.x]

2021-04-05T19:38:17Z, TRACE, http.PwmRequest, {fTNKU} GET request for: /pwm/public/api requestID=1564 [x.x.x.x]

processAction='clientData'

etag='bd73b93ea2a223979b304a8fdb1a26cc0e9cd242'

pageUrl='https://pwm.com/pwm/public/activate'

2021-04-05T19:38:17Z, TRACE, http.PwmRequest, {fTNKU} GET request for: /pwm/public/api completed requestID=1564 in 6ms [x.x.x.x]

processAction='clientData'

etag='bd73b93ea2a223979b304a8fdb1a26cc0e9cd242'

pageUrl='https://pwm.com/pwm/public/activate'

2021-04-05T19:38:22Z, TRACE, http.PwmRequest, {fTNKU} POST request for: /pwm/public/activate requestID=1565 [x.x.x.x]

processAction='activate'

sAMAccountName='test.user'

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakHWab7t0HJUYCddsZAbzg1yePO2yFADn8DML16yf7qzcmukQl49371SLpWAhdJSBH7w2kFnpyl-YI1R6HEIJiLGq9EKbg92Rpk84OblNo09jS644L-yZcuzY4ZfHutunx3VUOR9KZWFb4fnAhdZnGlvRobdWt8dKoFkFlNFcSeu36JEkietkWaAAAA'

2021-04-05T19:38:22Z, TRACE, activation.ActivateUserUtils, {fTNKU} auto generated search filter based on activation form: (&(objectclass=User)(sAMAccountName=%sAMAccountName%)) [x.x.x.x]

2021-04-05T19:38:22Z, TRACE, cache.CacheService, memCache={"storeCount":6,"readCount":20,"hitCount":13,"missCount":7}, histogram={"LdapOperationsHelper":3,"LdapProfile":2}

2021-04-05T19:38:22Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:38:22Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (66ms)

2021-04-05T19:38:22Z, TRACE, profile.LdapProfile, read and cached canonical ldap DN value for input 'OU=domain,DC=domain,DC=com' as 'OU=domain,DC=domain,DC=com'

2021-04-05T19:38:22Z, DEBUG, search.UserSearchEngine, {fTNKU} searchID=2 beginning user search process with 1 search jobs, filter: (&(objectclass=User)(sAMAccountName=test.user)) [x.x.x.x]

2021-04-05T19:38:22Z, DEBUG, search.UserSearchEngine, periodic debug status: background-enabled=false,backgroundJobCounter=0,foregroundJobCounter=2,jvmThreadCount=52,searchCount=3

2021-04-05T19:38:22Z, TRACE, search.UserSearchEngine, {fTNKU} searchID=2-0 performing ldap search for user; [profile=default,base=OU=domain,DC=domain,DC=com,maxCount=2] [x.x.x.x]

2021-04-05T19:38:22Z, TRACE, search.UserSearchEngine, {fTNKU} searchID=2-0 found 1 results in 1ms; [profile=default,base=OU=domain,DC=domain,DC=com,maxCount=2] [x.x.x.x]

2021-04-05T19:38:22Z, DEBUG, search.UserSearchEngine, {fTNKU} searchID=2 completed user search process in 1ms, intermediate result size=1 [x.x.x.x]

2021-04-05T19:38:22Z, DEBUG, search.UserSearchEngine, {fTNKU} found userDN: CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (70ms) [x.x.x.x]

2021-04-05T19:38:22Z, TRACE, activation.ActivateUserUtils, {fTNKU} auto generated search filter based on activation form: (&(objectclass=User)(sAMAccountName=%sAMAccountName%)) [x.x.x.x]

2021-04-05T19:38:22Z, TRACE, activation.ActivateUserUtils, {fTNKU} skipping validation of ldap value for 'sAMAccountName' because it is in search filter [x.x.x.x]

2021-04-05T19:38:22Z, TRACE, ldap.LdapPermissionTester, {fTNKU} begin check for ldapQuery match for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) using queryMatch: (&(objectclass=person)(!(userAccountControl:1.2.840.113556.1.4.803:=2))(|(lastLogon=0)(!(lastLogonTimestamp=*)))) [x.x.x.x]

2021-04-05T19:38:22Z, TRACE, ldap.LdapPermissionTester, {fTNKU} checking ldap to see if CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) matches '(&(objectclass=person)(!(userAccountControl:1.2.840.113556.1.4.803:=2))(|(lastLogon=0)(!(lastLogonTimestamp=*))))' [x.x.x.x]

2021-04-05T19:38:22Z, DEBUG, ldap.LdapPermissionTester, {fTNKU} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(&(objectclass=person)(!(userAccountControl:1.2.840.113556.1.4.803:=2))(|(lastLogon=0)(!(lastLogonTimestamp=*))))' (1ms) [x.x.x.x]

2021-04-05T19:38:22Z, DEBUG, servlet.AbstractPwmServlet, {fTNKU} this request is not idempotent, redirecting to self with no action [x.x.x.x]

2021-04-05T19:38:22Z, TRACE, state.CryptoCookieLoginImpl, {fTNKU} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:38:22Z","g":"kn4zt7u8GT6CdMhIxSd2Y6yK6ls10ThxXY1dbsq5EPPHRJRMhqw1r3zClC4G3xQgWDaUULay","c":2,"lf":[]} [x.x.x.x]

2021-04-05T19:38:22Z, TRACE, http.PwmResponse, {fTNKU} sending 303 redirect to /pwm/public/activate [x.x.x.x]

2021-04-05T19:38:22Z, TRACE, http.PwmRequest, {fTNKU} POST request for: /pwm/public/activate completed requestID=1565 in 73ms [x.x.x.x]

processAction='activate'

sAMAccountName='test.user'

2021-04-05T19:38:22Z, TRACE, http.PwmRequest, {fTNKU} GET request for: /pwm/public/activate (no params) requestID=1566 [x.x.x.x]

2021-04-05T19:38:22Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:38:22Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (55ms)

2021-04-05T19:38:22Z, TRACE, token.TokenUtil, {fTNKU} calculated available token send destinations: [{"id":"B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867","display":"u*************@d*************.com","value":"user...@domain.com","type":"email"}] [x.x.x.x]

2021-04-05T19:38:22Z, TRACE, http.SessionManager, {fTNKU} incremented request counter to 3 [x.x.x.x]

2021-04-05T19:38:22Z, TRACE, http.PwmResponse, {fTNKU} forwarding to /WEB-INF/jsp/activateuser-tokenchoice.jsp [x.x.x.x]

2021-04-05T19:38:22Z, TRACE, http.PwmRequest, {fTNKU} GET request for: /pwm/public/activate (no params) completed requestID=1566 in 61ms [x.x.x.x]

2021-04-05T19:38:24Z, TRACE, http.PwmRequest, {fTNKU} POST request for: /pwm/public/activate requestID=1567 [x.x.x.x]

processAction='tokenChoice'

choice='B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867'

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakHXicESAnX45LluGZH9mKHbqR9zo4P3rccV-y2nwE8YBSieyAtqaMXaNfxjWUmLBs9TJ2Zf_UNQQgk-6qfQHy_FZNrBxHm43KLlle6Q21_4mz9drOu42dfdhOG-lHATHhxjHQp3s7vny--B3imAR1mSh6IqKE8vZHht5KK4Stw7ZoMvm9loteaAAAA'

2021-04-05T19:38:24Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:38:24Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (69ms)

2021-04-05T19:38:24Z, TRACE, token.TokenUtil, {fTNKU} calculated available token send destinations: [{"id":"B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867","display":"u*************@d*************.com","value":"user...@domain.com","type":"email"}] [x.x.x.x]

2021-04-05T19:38:24Z, DEBUG, servlet.AbstractPwmServlet, {fTNKU} this request is not idempotent, redirecting to self with no action [x.x.x.x]

2021-04-05T19:38:24Z, TRACE, state.CryptoCookieLoginImpl, {fTNKU} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:38:24Z","g":"kn4zt7u8GT6CdMhIxSd2Y6yK6ls10ThxXY1dbsq5EPPHRJRMhqw1r3zClC4G3xQgWDaUULay","c":3,"lf":[]} [x.x.x.x]

2021-04-05T19:38:24Z, TRACE, http.PwmResponse, {fTNKU} sending 303 redirect to /pwm/public/activate [x.x.x.x]

2021-04-05T19:38:24Z, TRACE, http.PwmRequest, {fTNKU} POST request for: /pwm/public/activate completed requestID=1567 in 77ms [x.x.x.x]

processAction='tokenChoice'

choice='B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867'

2021-04-05T19:38:24Z, TRACE, http.PwmRequest, {fTNKU} GET request for: /pwm/public/activate (no params) requestID=1568 [x.x.x.x]

2021-04-05T19:38:24Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:38:25Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (59ms)

2021-04-05T19:38:25Z, TRACE, token.TokenUtil, {fTNKU} calculated available token send destinations: [{"id":"B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867","display":"u*************@d*************.com","value":"user...@domain.com","type":"email"}] [x.x.x.x]

2021-04-05T19:38:25Z, TRACE, operations.PasswordUtility, {fTNKU} read last user password change timestamp (via chai) as: 2021-04-05T19:29:24Z [x.x.x.x]

2021-04-05T19:38:25Z, TRACE, token.TokenService, {fTNKU} generated new token random code, checking for uniqueness [x.x.x.x]

2021-04-05T19:38:25Z, TRACE, token.TokenService, {fTNKU} created new unique random token value after 1 attempts [x.x.x.x]

2021-04-05T19:38:25Z, TRACE, token.TokenService, {fTNKU} generated token with payload: {"issueTime":"2021-04-05T19:38:25Z","name":"ACTIVATION","guid":"f3dd5013-ae22-4b2e-8ffc-bcab0bf2c7fd","expiration":"2021-04-05T20:38:25Z","user":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default)"} [x.x.x.x]

2021-04-05T19:38:25Z, INFO , event.AuditService, audit event: {"perpetratorID":"test.user","perpetratorDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","perpetratorLdapProfile":"default","sourceAddress":"x.x.x.x","sourceHost":"x.x.x.x","type":"USER","eventCode":"TOKEN_ISSUED","guid":"8f822033-9c8d-49e9-9cb7-be2df7ceff21","timestamp":"2021-04-05T19:38:25Z","message":"{\"t\":\"2021-04-05T19:38:25Z\",\"e\":\"2021-04-05T20:38:25Z\",\"n\":\"ACTIVATION\",\"p\":{\"_lastPwdChange\":\"2021-04-05T19:29:24Z\"},\"user\":{\"userDN\":\"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com\",\"ldapProfile\":\"default\"},\"d\":{\"id\":\"B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867\",\"display\":\"u*************@d*************.com\",\"value\":\"user...@domain.com\",\"type\":\"email\"},\"g\":\"f3dd5013-ae22-4b2e-8ffc-bcab0bf2c7fd\"}","narrative":"A token has been issued","xdasTaxonomy":"XDAS_AE_SET_CRED_ACCOUNT","xdasOutcome":"XDAS_OUT_PRIV_GRANTED"}

2021-04-05T19:38:25Z, DEBUG, intruder.RecordManagerImpl, re-setting existing outdated record={"type":"TOKEN_DEST","subject":"user...@domain.com","timeStamp":"2021-04-05T19:19:15Z","attemptCount":0,"alerted":false} (19m)

2021-04-05T19:38:25Z, DEBUG, event.AuditService, discarding event, INTRUDER_ATTEMPT are being ignored; event={"instance":"E1EA799F459B7986","type":"SYSTEM","eventCode":"INTRUDER_ATTEMPT","guid":"8690eff4-3521-4c72-8b3d-4f112bc3f351","timestamp":"2021-04-05T19:38:25Z","message":"{\"type\":\"TOKEN_DEST\",\"subject\":\"user...@domain.com\"}","narrative":"Non user-specific intruder attempt (Details: {\"type\":\"TOKEN_DEST\",\"subject\":\"user...@domain.com\"})","xdasTaxonomy":"XDAS_AE_IDS_SUSPICIOUS","xdasOutcome":"XDAS_OUT_SUCCESS"}

2021-04-05T19:38:25Z, TRACE, intruder.IntruderManager, delaying response 697ms due to intruder record: {"type":"TOKEN_DEST","subject":"user...@domain.com","timeStamp":"2021-04-05T19:38:25Z","attemptCount":1,"alerted":false}

2021-04-05T19:38:25Z, TRACE, macro.MacroMachine, {fTNKU} replaced macro @User:Email@ with value: user...@domain.com [x.x.x.x]

2021-04-05T19:38:25Z, TRACE, macro.MacroMachine, {fTNKU} replaced macro @DefaultEmailFromAddress@ with value: p...@domain.com [x.x.x.x]

2021-04-05T19:38:25Z, TRACE, macro.MacroMachine, {fTNKU} replaced macro @SiteURL@ with value: https://pwm.com/pwm [x.x.x.x]

2021-04-05T19:38:25Z, TRACE, email.EmailService, initializing new threadLocal transport, stats: newConnectionCounter=0,useExistingConnection=2,useExistingTransport=0,newThreadLocalTransport=2

2021-04-05T19:38:25Z, DEBUG, email.EmailServerUtil, connected to id=default,host=10.40.1.198,port=337 (unauthenticated)

2021-04-05T19:38:25Z, TRACE, email.EmailService, using existing threadLocal: stats: newConnectionCounter=0,useExistingConnection=3,useExistingTransport=0,newThreadLocalTransport=3

2021-04-05T19:38:25Z, DEBUG, email.EmailService, sent email: from: Activation Verification <p...@domain.com>, to: user...@domain.com, subject: Account Verification

2021-04-05T19:38:25Z, TRACE, email.EmailService_WorkQueueProcessor, successfully processed item=[date=2021-04-05T19:38:25.729Z,id=2,item=from: Activation Verification <p...@domain.com>, to: user...@domain.com, subject: Account Verification]; lagTime=45ms; sendRate=0.00/s,preQueueFallback=0,preQueueSubmit=0,preQueueBypass=0,avgLagTime=45ms,queueProcessItems=1

2021-04-05T19:38:25Z, DEBUG, token.TokenService, token email added to send queue for user...@domain.com

2021-04-05T19:38:25Z, TRACE, http.SessionManager, {fTNKU} incremented request counter to 4 [x.x.x.x]

2021-04-05T19:38:25Z, TRACE, state.CryptoCookieLoginImpl, {fTNKU} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:38:25Z","g":"kn4zt7u8GT6CdMhIxSd2Y6yK6ls10ThxXY1dbsq5EPPHRJRMhqw1r3zClC4G3xQgWDaUULay","c":4,"lf":[]} [x.x.x.x]

2021-04-05T19:38:25Z, TRACE, http.PwmResponse, {fTNKU} forwarding to /WEB-INF/jsp/activateuser-entercode.jsp [x.x.x.x]

2021-04-05T19:38:25Z, TRACE, http.PwmRequest, {fTNKU} GET request for: /pwm/public/activate (no params) completed requestID=1568 in 826ms [x.x.x.x]

2021-04-05T19:38:51Z, TRACE, http.PwmRequest, {fTNKU} POST request for: /pwm/public/activate requestID=1569 [x.x.x.x]

processAction='enterCode'

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakHZAaaWGFML2WtVL1pJSpu8CFas639vXccxEjGh1IfhaVZA4AAb65zkosAc9nyQyN9c8vCxGi9yfSEeGzZFTvl4Lfp7hw_gpaL9K3PN9flRtFglRkEk0sX4x-rR2SIpUN4B_CKKT8V-25HAKao1348mzhD4IX-i2gk1peq6oLEIVX4FEvj1_qaAAAA'

token=*hidden*

2021-04-05T19:38:51Z, TRACE, token.TokenService, {fTNKU} retrieved tokenPayload: {"issueTime":"2021-04-05T19:38:25Z","name":"ACTIVATION","guid":"f3dd5013-ae22-4b2e-8ffc-bcab0bf2c7fd","expiration":"2021-04-05T20:38:25Z","user":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default)"} [x.x.x.x]

2021-04-05T19:38:51Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:38:51Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (68ms)

2021-04-05T19:38:51Z, TRACE, operations.PasswordUtility, {fTNKU} read last user password change timestamp (via chai) as: 2021-04-05T19:29:24Z [x.x.x.x]

2021-04-05T19:38:51Z, TRACE, token.TokenService, {fTNKU} tokenPayload={"issueTime":"2021-04-05T19:38:25Z","name":"ACTIVATION","guid":"f3dd5013-ae22-4b2e-8ffc-bcab0bf2c7fd","expiration":"2021-04-05T20:38:25Z","user":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default)"}, sessionUser=CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default), payloadUserIdentity=CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default), userLastPasswordChange=2021-04-05T19:29:24Z, dateStringInToken=2021-04-05T19:29:24Z [x.x.x.x]

2021-04-05T19:38:51Z, DEBUG, token.TokenService, {fTNKU} token validation has been passed [x.x.x.x]

2021-04-05T19:38:51Z, TRACE, token.TokenService, {fTNKU} removing claimed token: {"issueTime":"2021-04-05T19:38:25Z","name":"ACTIVATION","guid":"f3dd5013-ae22-4b2e-8ffc-bcab0bf2c7fd","expiration":"2021-04-05T20:38:25Z","user":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default)"} [x.x.x.x]

2021-04-05T19:38:51Z, INFO , event.AuditService, audit event: {"perpetratorID":"test.user","perpetratorDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","perpetratorLdapProfile":"default","sourceAddress":"x.x.x.x","sourceHost":"x.x.x.x","type":"USER","eventCode":"TOKEN_CLAIMED","guid":"37c27c0f-d9f9-49f9-975d-fd8187aef6aa","timestamp":"2021-04-05T19:38:51Z","message":"{\"t\":\"2021-04-05T19:38:25Z\",\"e\":\"2021-04-05T20:38:25Z\",\"n\":\"ACTIVATION\",\"p\":{\"_lastPwdChange\":\"2021-04-05T19:29:24Z\"},\"user\":{\"userDN\":\"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com\",\"ldapProfile\":\"default\"},\"d\":{\"id\":\"B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867\",\"display\":\"u*************@d*************.com\",\"value\":\"user...@domain.com\",\"type\":\"email\"},\"g\":\"f3dd5013-ae22-4b2e-8ffc-bcab0bf2c7fd\"}","narrative":"A token has been claimed","xdasTaxonomy":"XDAS_AE_GRANT_ACCOUNT_ACCESS","xdasOutcome":"XDAS_OUT_PRIV_USED"}

2021-04-05T19:38:51Z, TRACE, http.SessionManager, {fTNKU} incremented request counter to 5 [x.x.x.x]

2021-04-05T19:38:51Z, TRACE, state.CryptoCookieLoginImpl, {fTNKU} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:38:51Z","g":"kn4zt7u8GT6CdMhIxSd2Y6yK6ls10ThxXY1dbsq5EPPHRJRMhqw1r3zClC4G3xQgWDaUULay","c":5,"lf":[]} [x.x.x.x]

2021-04-05T19:38:51Z, TRACE, http.PwmResponse, {fTNKU} forwarding to /WEB-INF/jsp/activateuser-tokensuccess.jsp [x.x.x.x]

2021-04-05T19:38:51Z, TRACE, http.PwmRequest, {fTNKU} POST request for: /pwm/public/activate completed requestID=1569 in 89ms [x.x.x.x]

processAction='enterCode'

token=*hidden*

2021-04-05T19:38:52Z, DEBUG, provider.WatchdogProviderHolder, disconnecting underlying connection: ldap idle timeout detected (PT30.256S), closing connection id=w292-757

2021-04-05T19:38:52Z, DEBUG, provider.WatchdogProviderHolder, disconnecting underlying connection: ldap idle timeout detected (PT30.365S), closing connection id=w281-755

2021-04-05T19:38:53Z, TRACE, http.PwmRequest, {fTNKU} GET request for: /pwm/public/activate requestID=1570 [x.x.x.x]

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakHah1aCJvlohU9H4XQr1ZgsNxBWxC54DrhzF9eeFoNnZpOe93jcOSojGyjqrkNHuawGs1Mip1Y0h8lWouDPfqqs5Bn9U8D7RhC7m2uG4jOrsvus-dG7SFozV_yfB9SMvdKpRXQ9C1U0PfsKHKpesM-PHAnFHPpzTF1jiGyB-bfVkIjIxBRc7OaAAAA'

2021-04-05T19:38:53Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:38:53Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (76ms)

2021-04-05T19:38:53Z, TRACE, token.TokenUtil, {fTNKU} calculated available token send destinations: [{"id":"B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867","display":"u*************@d*************.com","value":"user...@domain.com","type":"email"}] [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, activation.ActivateUserUtils, {fTNKU} executing configured pre-actions to user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, auth.LDAPAuthenticationRequest, {fTNKU} authID=32, beginning authentication using unknown password procedure [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, auth.LDAPAuthenticationRequest, {fTNKU} authID=32, preparing to authenticate user using authenticationType=AUTH_FROM_PUBLIC_MODULE using strategy ADMIN_PROXY [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.LdapOperationsHelper, {fTNKU} creating new ldap connection using config: ChaiConfiguration: settings: {chai.bind.URLs=ldaps://win-prfm7lapha7.domain.com:636,ldaps://WIN-TO8QHSDK40B.domain.com:636,, chai.bind.dn=CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com, chai.bind.password=**stripped**, chai.cache.enable=false, chai.cache.maximumSize=128, chai.cache.maximumAge=1000, chai.statistics.enable=true, chai.watchdog.enable=true, chai.watchdog.operationTimeout=60000, chai.watchdog.idleTimeout=30000, chai.watchdog.maxConnectionLifetime=3300000, chai.watchdog.disableIfPwExpired=true, chai.connection.promiscuousSSL=false, chai.wireDebug.enable=false, chai.failover.enable=true, chai.failover.useLastKnownGoodHint=true, chai.failover.failBackTime=90000, chai.failover.connectRetries=4, chai.ldap.dereferenceAliases=never, chai.ldap.ldapTimeout=30000, chai.ldap.ldapReadTimeout=0, chai.ldap.followReferrals=true, chai.provider.implementation=com.novell.ldapchai.provider.JNDIProviderImpl, chai.edirectory.enableNMAS=true, chai.provider.extendedOperation.failureCache=true, chai.provider.readonly=false, chai.vendor.default=, chai.provider.jndi.enablePool=false, chai.crsetting.caseInsensitive=true, chai.crsetting.allowDuplicateResponses=false, chai.crsetting.defaultFormatType=PBKDF2_SHA512, chai.cr.chai.attributeName=pwmResponseSet, chai.cr.chai.recordId=0002, chai.cr.chai.saltCount=100000, chai.ad.setPolicyHintsOnPwSet=false, chai.ldap.paging.enable=auto, chai.ldap.paging.size=500, chai.openldap.passwordPolicyDn=, chai.openldap.passwordPolicy.url=file:/etc/openldap/check_password.conf, chai.jndi.resolveInNamespace=true, chai.ldap.characterEncoding=UTF8} [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (75ms)

2021-04-05T19:38:53Z, TRACE, provider.ChaiProviderFactory, adding WatchdogWrapper to provider instance

2021-04-05T19:38:53Z, TRACE, provider.WatchdogWrapper, checking for user password expiration to adjust watchdog timeout id=w303

2021-04-05T19:38:53Z, TRACE, provider.ChaiProviderFactory, adding StatisticsWrapper to provider instance

2021-04-05T19:38:53Z, DEBUG, auth.LDAPAuthenticationRequest, {fTNKU} authID=32, successful ldap authentication for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) (78ms) type: AUTH_BIND_INHIBIT, using strategy ADMIN_PROXY, using proxy connection: true, returning bind dn: CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:38:53Z, INFO , event.AuditService, audit event: {"perpetratorID":"test.user","perpetratorDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","perpetratorLdapProfile":"default","sourceAddress":"x.x.x.x","sourceHost":"x.x.x.x","type":"USER","eventCode":"AUTHENTICATE","guid":"3548bce3-e587-49fc-971c-8e8d74ed620c","timestamp":"2021-04-05T19:38:53Z","message":"type=AUTH_BIND_INHIBIT, source=USER_ACTIVATION","narrative":"test.user (CN=Test User,OU=Users,OU=domain,DC=domain,DC=com) has authenticated","xdasTaxonomy":"XDAS_AE_AUTHENTICATE_ACCOUNT","xdasOutcome":"XDAS_OUT_SUCCESS"}

2021-04-05T19:38:53Z, DEBUG, operations.PasswordUtility, {fTNKU} testing password policy profile 'default' [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.LdapPermissionTester, {fTNKU} begin check for ldapQuery match for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) using queryMatch: (objectClass=*) [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.LdapPermissionTester, {fTNKU} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.LdapPermissionTester, {fTNKU} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (0ms) [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, operations.PasswordUtility, {fTNKU} read user policy for 'CN=Test User,OU=Users,OU=domain,DC=domain,DC=com', policy: PwmPasswordPolicy: {"policyMap":{"chai.pwrule.repeat.max":"0","chai.pwrule.changeMessage":"","chai.pwrule.upper.min":"0","chai.pwrule.numeric.allow":"true","chai.pwrule.allowUserChange":"true","chai.pwrule.disallowedValues":"","chai.pwrule.challengeResponseEnabled":"false","chai.pwrule.length.max":"0","chai.pwrule.nonalpha.allow":"true","chai.pwrule.nonalpha.max":"0","chai.pwrule.allowAdminChange":"true","chai.pwrule.disallowedAttributes":"","chai.pwrule.uniqueRequired":"false","chai.pwrule.ADComplexity2008":"false","chai.pwrule.sequentialRepeat.max":"0","chai.pwrule.lower.min":"0","chai.pwrule.ADComplexity":"false","chai.pwrule.unique.max":"0","chai.pwrule.special.max":"0","chai.pwrule.enforceAtLogin":"false","chai.pwrule.nonalpha.min":"0","chai.pwrule.numeric.allowLast":"true","chai.pwrule.policyEnabled":"true","chai.pwrule.numeric.allowFirst":"true","chai.pwrule.special.allow":"true","chai.pwrule.expirationInterval":"0","chai.pwrule.special.min":"0","chai.pwrule.lower.max":"0","chai.pwrule.numeric.max":"0","chai.pwrule.novellComplexity":"","chai.pwrule.ADComplexityMaxViolation":"false","chai.pwrule.upper.max":"0","chai.pwrule.numeric.min":"0","chai.pwrule.unique.min":"0","chai.pwrule.special.allowFirst":"true","chai.pwrule.length.min":"7","chai.pwrule.special.allowLast":"true","chai.pwrule.caseSensitive":"true","chai.pwrule.lifetime.minimimum":"0"}} [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, operations.PasswordUtility, {fTNKU} merged user password policy of 'CN=Test User,OU=Users,OU=domain,DC=domain,DC=com' with PWM configured policy: PwmPasswordPolicy: {"policyMap":{"chai.pwrule.repeat.max":"0","chai.pwrule.changeMessage":"","chai.pwrule.upper.min":"0","chai.pwrule.allowUserChange":"true","chai.pwrule.disallowedValues":"password\ntest","password.policy.disallowCurrent":"true","chai.pwrule.nonalpha.allow":"true","chai.pwrule.nonalpha.max":"0","chai.pwrule.allowAdminChange":"true","chai.pwrule.uniqueRequired":"false","chai.pwrule.unique.max":"0","chai.pwrule.special.max":"0","chai.pwrule.enforceAtLogin":"false","password.policy.charGroup.regExValues":".*[0-9]\n.*[^A-Za-z0-9]\n.*[A-Z]\n.*[a-z]","chai.pwrule.policyEnabled":"true","chai.pwrule.lower.max":"0","password.policy.checkWordlist":"true","chai.pwrule.upper.max":"0","chai.pwrule.unique.min":"0","chai.pwrule.length.min":"7","password.policy.maximumAlpha":"0","chai.pwrule.numeric.allow":"true","chai.pwrule.challengeResponseEnabled":"false","password.policy.regExMatch":"","chai.pwrule.length.max":"64","password.policy.ADComplexityLevel":"AD2008","password.policy.minimumStrength":"0","chai.pwrule.disallowedAttributes":"givenName\ncn\nsn","password.policy.charGroup.minimumMatch":"0","chai.pwrule.sequentialRepeat.max":"0","password.policy.minimumAlpha":"0","chai.pwrule.lower.min":"0","password.policy.allowMacroInRegexSetting":"true","chai.pwrule.numeric.allowLast":"true","chai.pwrule.nonalpha.min":"0","chai.pwrule.numeric.allowFirst":"true","chai.pwrule.special.allow":"true","chai.pwrule.expirationInterval":"0","chai.pwrule.special.min":"0","chai.pwrule.numeric.max":"0","chai.pwrule.ADComplexityMaxViolation":"2","chai.pwrule.numeric.min":"0","chai.pwrule.special.allowFirst":"true","chai.pwrule.special.allowLast":"true","password.policy.maximumConsecutive":"0","chai.pwrule.caseSensitive":"true","chai.pwrule.lifetime.minimimum":"0","password.policy.regExNoMatch":""}} [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, operations.PasswordUtility, {fTNKU} readPasswordPolicyForUser completed in 4ms [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.UserInfoReader, {fTNKU} beginning password status check process for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.UserInfoReader, {fTNKU} password for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com does not appear to be expired [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.UserInfoReader, {fTNKU} completed user password status check for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com PasswordStatus.PasswordStatusBuilder(expired=false, preExpired=false, violatesPolicy=false, warnPeriod=false) (2ms) [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, auth.SessionAuthenticator, {fTNKU,test.user} clearing permission cache [x.x.x.x]

2021-04-05T19:38:53Z, INFO , event.AuditService, audit event: {"perpetratorID":"test.user","perpetratorDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","perpetratorLdapProfile":"default","sourceAddress":"x.x.x.x","sourceHost":"","type":"USER","eventCode":"ACTIVATE_USER","guid":"77e74398-dec1-458c-9e14-f09a05c36cda","timestamp":"2021-04-05T19:38:53Z","narrative":"test.user (CN=Test User,OU=Users,OU=domain,DC=domain,DC=com) has activated their account","xdasTaxonomy":"XDAS_AE_CREATE_SESSION","xdasOutcome":"XDAS_OUT_SUCCESS"}

2021-04-05T19:38:53Z, TRACE, macro.MacroMachine, {fTNKU,test.user} replaced macro @User:Email@ with value: user...@domain.com [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, macro.MacroMachine, {fTNKU,test.user} replaced macro @DefaultEmailFromAddress@ with value: p...@domain.com [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, macro.MacroMachine, {fTNKU,test.user} replaced macro @LDAP:givenName@ with value: Test [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, email.EmailService_WorkQueueProcessor, item submitted: [date=2021-04-05T19:38:53.273Z,id=3,item=from: Activation Notification <p...@domain.com>, to: user...@domain.com, subject: Account Activated], 1 items in queue

2021-04-05T19:38:53Z, TRACE, http.SessionManager, {fTNKU,test.user} incremented request counter to 6 [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, state.CryptoCookieLoginImpl, {fTNKU,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTH_FROM_PUBLIC_MODULE","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:38:53Z","rq":"2021-04-05T19:38:53Z","g":"kn4zt7u8GT6CdMhIxSd2Y6yK6ls10ThxXY1dbsq5EPPHRJRMhqw1r3zClC4G3xQgWDaUULay","c":6,"lf":["forcePwChange"]} [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, http.PwmResponse, {fTNKU,test.user} forwarding to /WEB-INF/jsp/success.jsp [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, macro.MacroMachine, {fTNKU,test.user} replaced macro @User:ID@ with value: test.user [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.LdapPermissionTester, {fTNKU} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.LdapPermissionTester, {fTNKU} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (0ms) [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, profile.ChallengeProfile, discarding configured helpdesk challengeSet for profile 'default' issue: 5203 CONFIG_FORMAT_ERROR (invalid challenge set configuration: too few challenges are required)

2021-04-05T19:38:53Z, DEBUG, operations.CrService, {fTNKU} testing challenge profiles 'default' [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.LdapPermissionTester, {fTNKU} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.LdapPermissionTester, {fTNKU} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (0ms) [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, email.EmailService, using existing threadLocal transport, stats: newConnectionCounter=0,useExistingConnection=3,useExistingTransport=0,newThreadLocalTransport=3

2021-04-05T19:38:53Z, TRACE, email.EmailService, connecting threadLocal transport, stats: newConnectionCounter=0,useExistingConnection=3,useExistingTransport=1,newThreadLocalTransport=3

2021-04-05T19:38:53Z, TRACE, operations.CrService, {fTNKU} readUserChallengeProfile completed in 20ms returned profile: default [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, operations.CrService, {fTNKU} beginning read of user response sequence [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, operations.CrService, {fTNKU} will attempt to read the following storage methods: ["DB"] for response info for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, operations.CrService, {fTNKU} attempting read of response info via storage method: DB [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, cr.DbCrOperator, user guid for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com not found in remote database (key=d6b2eaeacca6384a9fe6e542d13a817c)

2021-04-05T19:38:53Z, TRACE, operations.CrService, {fTNKU} no responses info read using method DB [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, operations.CrService, {fTNKU} no response info found for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, operations.CrService, {fTNKU} beginning check to determine if responses need to be configured for user [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, operations.CrService, {fTNKU} checkIfResponseConfigNeeded: response setup is disabled, so user is not required to setup responses [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.UserInfoReader, {fTNKU} checkOtp: beginning process to check if user OTP setup is required [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.LdapPermissionTester, {fTNKU} begin check for ldapGroup match for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) using queryMatch: CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.LdapPermissionTester, {fTNKU} checking ldap to see if CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) matches group 'CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com' using filter '(memberOf=CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com)' [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.LdapPermissionTester, {fTNKU} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is not a match for group 'CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com' (1ms) [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.UserInfoReader, {fTNKU} Helpdesk has no matching profiles for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.LdapPermissionTester, {fTNKU} checking ldap to see if CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) matches '(objectClass=person)' [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.LdapPermissionTester, {fTNKU} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=person)' (1ms) [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.UserInfoReader, {fTNKU} assigned UpdateAttributes profileID "default" to CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.UserInfoReader, {fTNKU} DeleteAccount has no matching profiles for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.LdapPermissionTester, {fTNKU} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.LdapPermissionTester, {fTNKU} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (0ms) [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.UserInfoReader, {fTNKU} assigned SetupOTPProfile profileID "default" to CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.UserInfoReader, {fTNKU} EmailServers has no matching profiles for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, otp.DbOtpOperator, Enter: readOtpUserConfiguration(CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default), d6b2eaeacca6384a9fe6e542d13a817c)

2021-04-05T19:38:53Z, TRACE, operations.OtpService, {fTNKU} readOTPUserConfiguration completed in 1ms, no otp record found [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.UserInfoReader, {fTNKU} checkOtp: user does not have existing valid otp record, user OTP setup is required [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, ldap.UserInfoReader, {fTNKU} checkProfiles: CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) profile force setup is not enabled [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.LdapPermissionTester, {fTNKU,test.user} begin check for ldapGroup match for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) using queryMatch: CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, ldap.LdapPermissionTester, {fTNKU,test.user} checking ldap to see if CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) matches group 'CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com' using filter '(memberOf=CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com)' [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, email.EmailServerUtil, connected to id=default,host=10.40.1.198,port=337 (unauthenticated)

2021-04-05T19:38:53Z, DEBUG, ldap.LdapPermissionTester, {fTNKU,test.user} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is not a match for group 'CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com' (2ms) [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, http.SessionManager, {fTNKU,test.user} permission PWMADMIN for user default|CN=Test User,OU=Users,OU=domain,DC=domain,DC=com is DENIED [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, macro.MacroMachine, {fTNKU,test.user} replaced macro @User:ID@ with value: test.user [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, http.PwmRequest, {fTNKU,test.user} GET request for: /pwm/public/activate completed requestID=1570 in 212ms [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, email.EmailService, sent email: from: Activation Notification <p...@domain.com>, to: user...@domain.com, subject: Account Activated

2021-04-05T19:38:53Z, TRACE, email.EmailService_WorkQueueProcessor, successfully processed item=[date=2021-04-05T19:38:53Z,id=3,item=from: Activation Notification <p...@domain.com>, to: user...@domain.com, subject: Account Activated]; lagTime=328ms; sendRate=0.00/s,preQueueFallback=0,preQueueSubmit=0,preQueueBypass=0,avgLagTime=47ms,queueProcessItems=2

2021-04-05T19:38:53Z, TRACE, http.PwmRequest, {fTNKU,test.user} GET request for: /pwm/public/api requestID=1571 [x.x.x.x]

processAction='clientData'

etag='562a2ddc5a2d33cafb4c543ae66b3f6732269f67'

pageUrl='https://pwm.com/pwm/public/activate?pwmFormID=H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakHah1aCJvlohU9H4XQr1ZgsNxBWxC54DrhzF9eeFoNnZpOe93jcOSojGyjqrkNHuawGs1Mip1Y0h8lWouDPfqqs5Bn9U8D7RhC7m2uG4jOrsvus-dG7SFozV_yfB9SMvdKpRXQ9C1U0PfsKHKpesM-PHAnFHPpzTF1jiGyB-bfVkIjIxBRc7OaAAAA'

2021-04-05T19:38:53Z, TRACE, http.PwmRequest, {fTNKU,test.user} GET request for: /pwm/public/api completed requestID=1571 in 2ms [x.x.x.x]

processAction='clientData'

etag='562a2ddc5a2d33cafb4c543ae66b3f6732269f67'

2021-04-05T19:38:53Z, TRACE, http.HttpEventManager, new http session created

2021-04-05T19:38:53Z, TRACE, http.PwmSession, {N1ZJM} created new session

2021-04-05T19:38:53Z, TRACE, filter.RequestInitializationFilter, {N1ZJM} user locale set to 'en' [x.x.x.x]

2021-04-05T19:38:53Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/api requestID=1572 [x.x.x.x]

processAction='strings'

etag='562a2ddc5a2d33cafb4c543ae66b3f6732269f67'

bundle='Display'

2021-04-05T19:38:53Z, TRACE, filter.SessionFilter, {N1ZJM} https secure request headers: [x.x.x.x]

host='pwm.com'

connection='keep-alive'

sec-ch-ua='"Google Chrome";v="89", "Chromium";v="89", ";Not A Brand";v="99"'

accept='application/json'

x-requested-with='XMLHttpRequest'

sec-ch-ua-mobile='?0'

user-agent='Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.114 Safari/537.36'

sec-fetch-site='same-origin'

sec-fetch-mode='cors'

sec-fetch-dest='empty'

referer='https://pwm.com/pwm/public/activate?pwmFormID=H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakHah1aCJvlohU9H4XQr1ZgsNxBWxC54DrhzF9eeFoNnZpOe93jcOSojGyjqrkNHuawGs1Mip1Y0h8lWouDPfqqs5Bn9U8D7RhC7m2uG4jOrsvus-dG7SFozV_yfB9SMvdKpRXQ9C1U0PfsKHKpesM-PHAnFHPpzTF1jiGyB-bfVkIjIxBRc7OaAAAA'

accept-encoding='gzip, deflate, br'

accept-language='en-US,en;q=0.9'

cookie='authRecord=H4sIAAAAAAAAAAFyAI3_UFdNLkdDTTEQywvAEkiwhu0reZOnlakGfu9dSqFsLBVwnaBaZonhyFM7YgUO9M5su-S_tGXu59LJYC5hMEk_zb2HVfx2MsT7mR2gkVhvKaGCzFiHjiIZbkV5vZaU8mT3WowVc8U43CshGBVRAZackFHTPG8083IAAAA%3D; ID=YrtVP8cohG14jkF8qSjFYafUQiyUkh3Ckn4zt7u9; SESSION=H4sIAAAAAAAAAAGNAXL-UFdNLkdDTTEQywvAEkiwhu0reZOnlakHbHk-zxNiUM-shSO51wR7adB78jlyNhoXXp_g4mqBNcmhw6dbEiyR1EGI7s5gNCp3n2pbyCOHBn1U-Xb5ZcFTpsgavbwrVDnohc0gKFHm_tkYZ6gEq2kxTmZqsSVpMtyZ7DSA9N6-ksdTwwtFyOYy_pJm3WVCqYDbbsTVsX9jSTRGAqwiCgtzKpdF725-WGXOpHBHSB1Q4UjWs0WP4toNcpwHny-U3iGoru8uMMq2vQgVGH9f7lgLkukiLUU4sOlkyKCVEVhylagUdgFiTuzLqF0Ay4N61k9XnbxVy7nfcmlMhv4Gnu_j7HBlcSrbrtozw2JeMbVdV-oh8Wu1OGVsmqLwt6D8MCMmrWrJu4t5YdxYj3rhl_2KjYDqubUMgqTi_QKd7DuTeGGh6lsmiz-SNxAReEhg8czQNxAv4pCe13xEG5N-BehefZmfDDcH1G6AALbwar4gI_qZDOLFPA-PuWecHfkz28BbG6UiMYOSzhewSS5BOUJe8PCNAQAA; JSESSIONID=ACA7D4E6A464A996E6725A6D0CCAF856'

2021-04-05T19:38:53Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM} login cookie session was generated by a foreign instance, seen login cookie value = {"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTH_FROM_PUBLIC_MODULE","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:38:53Z","rq":"2021-04-05T19:38:53Z","g":"kn4zt7u8GT6CdMhIxSd2Y6yK6ls10ThxXY1dbsq5EPPHRJRMhqw1r3zClC4G3xQgWDaUULay","c":6,"lf":["forcePwChange"]} [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, state.CryptoCookieLoginImpl, {N1ZJM} triggering authentication because request contains an authenticated session but local session is unauthenticated [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, auth.LDAPAuthenticationRequest, {N1ZJM} authID=33, preparing to authenticate user using authenticationType=AUTHENTICATED using strategy BIND [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:38:53Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (65ms)

2021-04-05T19:38:53Z, TRACE, auth.LDAPAuthenticationRequest, {N1ZJM} authID=33, beginning testCredentials process [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, auth.LDAPAuthenticationRequest, {N1ZJM} authID=33, attempt to authenticate with null password [x.x.x.x]

2021-04-05T19:38:53Z, ERROR, auth.SessionAuthenticator, {N1ZJM} ldap error during search: 5001 ERROR_WRONGPASSWORD (attempt to authenticate with null password) [x.x.x.x]

2021-04-05T19:38:53Z, DEBUG, intruder.RecordManagerImpl, re-setting existing outdated record={"type":"ADDRESS","subject":"x.x.x.x","timeStamp":"2021-04-05T19:19:35Z","attemptCount":0,"alerted":false} (19m)

2021-04-05T19:38:53Z, DEBUG, event.AuditService, discarding event, INTRUDER_ATTEMPT are being ignored; event={"instance":"E1EA799F459B7986","type":"SYSTEM","eventCode":"INTRUDER_ATTEMPT","guid":"f03af9f8-5e18-4c5d-a65b-8c9e3284a8ee","timestamp":"2021-04-05T19:38:53Z","message":"{\"type\":\"ADDRESS\",\"subject\":\"x.x.x.x\"}","narrative":"Non user-specific intruder attempt (Details: {\"type\":\"ADDRESS\",\"subject\":\"x.x.x.x\"})","xdasTaxonomy":"XDAS_AE_IDS_SUSPICIOUS","xdasOutcome":"XDAS_OUT_SUCCESS"}

2021-04-05T19:38:53Z, TRACE, intruder.IntruderManager, {N1ZJM} delaying response 1199ms due to intruder record: {"type":"ADDRESS","subject":"x.x.x.x","timeStamp":"2021-04-05T19:38:53Z","attemptCount":1,"alerted":false} [x.x.x.x]

2021-04-05T19:38:54Z, DEBUG, intruder.RecordManagerImpl, re-setting existing outdated record={"type":"USER_ID","subject":"default|CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","timeStamp":"2021-04-05T19:19:36Z","attemptCount":0,"alerted":false} (19m)

2021-04-05T19:38:54Z, DEBUG, event.AuditService, discarding event, INTRUDER_USER_ATTEMPT are being ignored; event={"perpetratorID":"test.user","perpetratorDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","perpetratorLdapProfile":"default","sourceAddress":"x.x.x.x","sourceHost":"x.x.x.x","type":"USER","eventCode":"INTRUDER_USER_ATTEMPT","guid":"249fc939-339d-4af0-9b9d-9b08784d3827","timestamp":"2021-04-05T19:38:54Z","narrative":"test.user (CN=Test User,OU=Users,OU=domain,DC=domain,DC=com) account has had an invalid login attempt (intruder attempt)","xdasTaxonomy":"XDAS_AE_IDS_SUSPICIOUS","xdasOutcome":"XDAS_OUT_SUCCESS"}

2021-04-05T19:38:54Z, TRACE, intruder.IntruderManager, {N1ZJM} delaying response 670ms due to intruder record: {"type":"USER_ID","subject":"default|CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","timeStamp":"2021-04-05T19:38:54Z","attemptCount":1,"alerted":false} [x.x.x.x]

2021-04-05T19:38:55Z, ERROR, state.CryptoCookieLoginImpl, {N1ZJM} 5015 ERROR_INTERNAL (unexpected error reading session cookie: 5001 ERROR_WRONGPASSWORD (attempt to authenticate with null password)) [x.x.x.x]

2021-04-05T19:38:55Z, ERROR, state.CryptoCookieLoginImpl, {N1ZJM} 5015 ERROR_INTERNAL (unexpected error authenticating using crypto session cookie: 5015 ERROR_INTERNAL (unexpected error reading session cookie: 5001 ERROR_WRONGPASSWORD (attempt to authenticate with null password))) [x.x.x.x]

2021-04-05T19:38:55Z, WARN , filter.SessionFilter, {N1ZJM} error while reading login session state: 5015 ERROR_INTERNAL (unexpected error authenticating using crypto session cookie: 5015 ERROR_INTERNAL (unexpected error reading session cookie: 5001 ERROR_WRONGPASSWORD (attempt to authenticate with null password))) [x.x.x.x]

2021-04-05T19:38:55Z, DEBUG, filter.SessionFilter, {N1ZJM} session is unvalidated but can not be validated during a json request, will allow [x.x.x.x]

2021-04-05T19:38:55Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:38:55Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":0,"lf":[]} [x.x.x.x]

2021-04-05T19:38:55Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/api completed requestID=1572 in 1946ms [x.x.x.x]

processAction='strings'

etag='562a2ddc5a2d33cafb4c543ae66b3f6732269f67'

bundle='Display'

2021-04-05T19:38:55Z, DEBUG, provider.WatchdogProviderHolder, disconnecting underlying connection: ldap idle timeout detected (PT30.774S), closing connection id=w293-759

2021-04-05T19:38:56Z, DEBUG, provider.WatchdogProviderHolder, disconnecting underlying connection: ldap idle timeout detected (PT30.955S), closing connection id=w294-761

2021-04-05T19:38:56Z, TRACE, http.PwmRequest, {N1ZJM} POST request for: /pwm/public/command requestID=1573 [x.x.x.x]

processAction='next'

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakHbv73up4h0dMQOsPmasDQtBIPcitCI2H1QMNEaA18XDa9On2-V1FICFGpK356tj8zYgf8wuL0vwtTWo5q-s6_HEea2B4wchYFh4MJtxjyJspe8BQ3czWRkQcHnuREnsF2TCqOAVOkr047ruEH05Ui09802zAzDpBO1AgrQp5dZo48ES3Zym-aAAAA'

2021-04-05T19:38:56Z, DEBUG, filter.SessionFilter, {N1ZJM} session is unvalidated but can not be validated during a POST request, will allow [x.x.x.x]

2021-04-05T19:38:56Z, TRACE, command.CommandServlet, {N1ZJM} redirecting user to forward url: /pwm [x.x.x.x]

2021-04-05T19:38:56Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:38:56Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":0,"lf":[]} [x.x.x.x]

2021-04-05T19:38:56Z, TRACE, http.PwmResponse, {N1ZJM} sending 302 redirect to /pwm [x.x.x.x]

2021-04-05T19:38:56Z, TRACE, http.PwmRequest, {N1ZJM} POST request for: /pwm/public/command completed requestID=1573 in 1ms [x.x.x.x]

processAction='next'

2021-04-05T19:38:56Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/ (no params) requestID=1574 [x.x.x.x]

2021-04-05T19:38:56Z, TRACE, filter.SessionFilter, {N1ZJM} session has not been validated, redirecting with verification key to /pwm/?stickyRedirectTest=key [x.x.x.x]

2021-04-05T19:38:56Z, TRACE, http.PwmResponse, {N1ZJM} sending 302 redirect to /pwm/?stickyRedirectTest=key [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/ requestID=1575 [x.x.x.x]

stickyRedirectTest='key'

2021-04-05T19:38:57Z, TRACE, filter.SessionFilter, {N1ZJM} session validated, redirecting to original request url: /pwm/ [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:38:57Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":0,"lf":[]} [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.PwmResponse, {N1ZJM} sending 302 redirect to /pwm/ [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/ (no params) requestID=1576 [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/ (no params) completed requestID=1576 in 2ms [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/private/ (no params) requestID=1577 [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, filter.AuthenticationFilter, {N1ZJM} user requested resource requiring authentication (/pwm/private/), but is not authenticated; redirecting to LoginServlet [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, servlet.LoginServlet, {N1ZJM} redirecting to self to set nextUrl to: /pwm/private/ [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.PwmResponse, {N1ZJM} sending 302 redirect to /pwm/private/login?posturl=H4sIAAAAAAAAAAE2AMn_UFdNLkdDTTEQywvAEkiwhu0reZOnlakHdVcfSduH6_iWvfkG0ieKsq2Z1jsg1rSol2tWsh_CSBl4NzYAAAA%3D&processAction=receiveUrl [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/private/ (no params) completed requestID=1577 in 2ms [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/private/login requestID=1578 [x.x.x.x]

posturl='H4sIAAAAAAAAAAE2AMn_UFdNLkdDTTEQywvAEkiwhu0reZOnlakHdVcfSduH6_iWvfkG0ieKsq2Z1jsg1rSol2tWsh_CSBl4NzYAAAA='

processAction='receiveUrl'

2021-04-05T19:38:57Z, DEBUG, state.CryptoCookieBeanImpl, {N1ZJM} ignoring existing existing b-C4778132 cookie bean due to error: 5076 ERROR_CRYPT_ERROR (unexpected error performing simple decrypt operation: 5076 ERROR_CRYPT_ERROR (unexpected error performing simple decrypt operation: Tag mismatch!)) [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, servlet.LoginServlet, {N1ZJM} received nextUrl and storing in module bean, value: /pwm/private/ [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.PwmResponse, {N1ZJM} sending 302 redirect to /pwm/private/login [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/private/login completed requestID=1578 in 2ms [x.x.x.x]

posturl='H4sIAAAAAAAAAAE2AMn_UFdNLkdDTTEQywvAEkiwhu0reZOnlakHdVcfSduH6_iWvfkG0ieKsq2Z1jsg1rSol2tWsh_CSBl4NzYAAAA='

processAction='receiveUrl'

2021-04-05T19:38:57Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/private/login (no params) requestID=1579 [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.SessionManager, {N1ZJM} incremented request counter to 1 [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.PwmResponse, {N1ZJM} forwarding to /WEB-INF/jsp/login.jsp [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/private/login (no params) completed requestID=1579 in 6ms [x.x.x.x]

2021-04-05T19:38:57Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/api requestID=1580 [x.x.x.x]

processAction='clientData'

etag='8d9aff0da137e022e08aa4f8762bc4c2784a262c'

pageUrl='https://pwm.com/pwm/private/login'

2021-04-05T19:38:57Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/api completed requestID=1580 in 2ms [x.x.x.x]

processAction='clientData'

etag='8d9aff0da137e022e08aa4f8762bc4c2784a262c'

pageUrl='https://pwm.com/pwm/private/login'

2021-04-05T19:38:57Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/api requestID=1581 [x.x.x.x]

processAction='strings'

etag='8d9aff0da137e022e08aa4f8762bc4c2784a262c'

bundle='Display'

2021-04-05T19:38:57Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/api completed requestID=1581 in 6ms [x.x.x.x]

processAction='strings'

etag='8d9aff0da137e022e08aa4f8762bc4c2784a262c'

bundle='Display'

###PASS###

2021-04-05T19:40:04Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/activate (no params) requestID=1582 [x.x.x.x]

2021-04-05T19:40:04Z, TRACE, http.SessionManager, {N1ZJM} incremented request counter to 2 [x.x.x.x]

2021-04-05T19:40:04Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:40:04Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":2,"lf":[]} [x.x.x.x]

2021-04-05T19:40:04Z, TRACE, http.PwmResponse, {N1ZJM} forwarding to /WEB-INF/jsp/activateuser.jsp [x.x.x.x]

2021-04-05T19:40:04Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/activate (no params) completed requestID=1582 in 2ms [x.x.x.x]

2021-04-05T19:40:04Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/api requestID=1583 [x.x.x.x]

processAction='clientData'

etag='8d9aff0da137e022e08aa4f8762bc4c2784a262c'

pageUrl='https://pwm.com/pwm/public/activate'

2021-04-05T19:40:04Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/api completed requestID=1583 in 3ms [x.x.x.x]

processAction='clientData'

etag='8d9aff0da137e022e08aa4f8762bc4c2784a262c'

pageUrl='https://pwm.com/pwm/public/activate'

2021-04-05T19:40:07Z, TRACE, http.PwmRequest, {N1ZJM} POST request for: /pwm/public/activate requestID=1584 [x.x.x.x]

processAction='activate'

sAMAccountName='test.user'

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakIASgy-GzWD2XuME8xiscs5z6wWVsQY22oHwA4NFGikUOKpvblthU1RwyeGbst3IzFqdMElcUIFN5L5ohQWeCrwlhBfKSYqu8W8z5IbJbIsvgG4AEkbgKDQQ-54de9LLimGW59ftJ4nHG-AU6R8ntIevWNifqsd_PCKoE7lYCG2Dszvn6-fxWaAAAA'

2021-04-05T19:40:07Z, TRACE, activation.ActivateUserUtils, {N1ZJM} auto generated search filter based on activation form: (&(objectclass=User)(sAMAccountName=%sAMAccountName%)) [x.x.x.x]

2021-04-05T19:40:07Z, TRACE, cache.CacheService, memCache={"storeCount":7,"readCount":25,"hitCount":18,"missCount":7}, histogram={"LdapOperationsHelper":3,"LdapProfile":3}

2021-04-05T19:40:07Z, DEBUG, search.UserSearchEngine, {N1ZJM} searchID=3 beginning user search process with 1 search jobs, filter: (&(objectclass=User)(sAMAccountName=test.user)) [x.x.x.x]

2021-04-05T19:40:07Z, DEBUG, search.UserSearchEngine, periodic debug status: background-enabled=false,backgroundJobCounter=0,foregroundJobCounter=3,jvmThreadCount=53,searchCount=4

2021-04-05T19:40:07Z, TRACE, search.UserSearchEngine, {N1ZJM} searchID=3-0 performing ldap search for user; [profile=default,base=OU=domain,DC=domain,DC=com,maxCount=2] [x.x.x.x]

2021-04-05T19:40:07Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:40:07Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (75ms)

2021-04-05T19:40:07Z, TRACE, search.UserSearchEngine, {N1ZJM} searchID=3-0 found 1 results in 76ms; [profile=default,base=OU=domain,DC=domain,DC=com,maxCount=2] [x.x.x.x]

2021-04-05T19:40:07Z, DEBUG, search.UserSearchEngine, {N1ZJM} searchID=3 completed user search process in 76ms, intermediate result size=1 [x.x.x.x]

2021-04-05T19:40:07Z, DEBUG, search.UserSearchEngine, {N1ZJM} found userDN: CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (76ms) [x.x.x.x]

2021-04-05T19:40:07Z, TRACE, activation.ActivateUserUtils, {N1ZJM} auto generated search filter based on activation form: (&(objectclass=User)(sAMAccountName=%sAMAccountName%)) [x.x.x.x]

2021-04-05T19:40:07Z, TRACE, activation.ActivateUserUtils, {N1ZJM} skipping validation of ldap value for 'sAMAccountName' because it is in search filter [x.x.x.x]

2021-04-05T19:40:07Z, TRACE, ldap.LdapPermissionTester, {N1ZJM} begin check for ldapQuery match for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) using queryMatch: (&(objectclass=person)(!(userAccountControl:1.2.840.113556.1.4.803:=2))(|(lastLogon=0)(!(lastLogonTimestamp=*)))) [x.x.x.x]

2021-04-05T19:40:07Z, TRACE, ldap.LdapPermissionTester, {N1ZJM} checking ldap to see if CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) matches '(&(objectclass=person)(!(userAccountControl:1.2.840.113556.1.4.803:=2))(|(lastLogon=0)(!(lastLogonTimestamp=*))))' [x.x.x.x]

2021-04-05T19:40:07Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(&(objectclass=person)(!(userAccountControl:1.2.840.113556.1.4.803:=2))(|(lastLogon=0)(!(lastLogonTimestamp=*))))' (1ms) [x.x.x.x]

2021-04-05T19:40:07Z, DEBUG, servlet.AbstractPwmServlet, {N1ZJM} this request is not idempotent, redirecting to self with no action [x.x.x.x]

2021-04-05T19:40:07Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:40:07Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":2,"lf":[]} [x.x.x.x]

2021-04-05T19:40:07Z, TRACE, http.PwmResponse, {N1ZJM} sending 303 redirect to /pwm/public/activate [x.x.x.x]

2021-04-05T19:40:07Z, TRACE, http.PwmRequest, {N1ZJM} POST request for: /pwm/public/activate completed requestID=1584 in 80ms [x.x.x.x]

processAction='activate'

sAMAccountName='test.user'

2021-04-05T19:40:07Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/activate (no params) requestID=1585 [x.x.x.x]

2021-04-05T19:40:07Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:40:07Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (59ms)

2021-04-05T19:40:07Z, TRACE, token.TokenUtil, {N1ZJM} calculated available token send destinations: [{"id":"B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867","display":"u*************@d*************.com","value":"user...@domain.com","type":"email"}] [x.x.x.x]

2021-04-05T19:40:07Z, TRACE, http.SessionManager, {N1ZJM} incremented request counter to 3 [x.x.x.x]

2021-04-05T19:40:07Z, TRACE, http.PwmResponse, {N1ZJM} forwarding to /WEB-INF/jsp/activateuser-tokenchoice.jsp [x.x.x.x]

2021-04-05T19:40:07Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/activate (no params) completed requestID=1585 in 65ms [x.x.x.x]

2021-04-05T19:40:09Z, TRACE, http.PwmRequest, {N1ZJM} POST request for: /pwm/public/activate requestID=1586 [x.x.x.x]

processAction='tokenChoice'

choice='B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867'

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakIBsO7mszjJ_U2OvE_7_9KWa8X4_xUmpN3yatizlvKxKrYCQL_syLvjXWA3FtghayCyYOcSEmikrgPHD9igj6Mu4e-76YF7yaRyMdThcF2C-bvzyf8RqC8SkDLVueS4Jr9VR9Mpkp6Esj1FnN9uUbOHRa9dXpX--t7oYdlhUHjVPpu_7EWpuiaAAAA'

2021-04-05T19:40:09Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:40:09Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (68ms)

2021-04-05T19:40:09Z, TRACE, token.TokenUtil, {N1ZJM} calculated available token send destinations: [{"id":"B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867","display":"u*************@d*************.com","value":"user...@domain.com","type":"email"}] [x.x.x.x]

2021-04-05T19:40:09Z, DEBUG, servlet.AbstractPwmServlet, {N1ZJM} this request is not idempotent, redirecting to self with no action [x.x.x.x]

2021-04-05T19:40:09Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:40:09Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":3,"lf":[]} [x.x.x.x]

2021-04-05T19:40:09Z, TRACE, http.PwmResponse, {N1ZJM} sending 303 redirect to /pwm/public/activate [x.x.x.x]

2021-04-05T19:40:09Z, TRACE, http.PwmRequest, {N1ZJM} POST request for: /pwm/public/activate completed requestID=1586 in 77ms [x.x.x.x]

processAction='tokenChoice'

choice='B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867'

2021-04-05T19:40:09Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/activate (no params) requestID=1587 [x.x.x.x]

2021-04-05T19:40:09Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:40:10Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (71ms)

2021-04-05T19:40:10Z, TRACE, token.TokenUtil, {N1ZJM} calculated available token send destinations: [{"id":"B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867","display":"u*************@d*************.com","value":"user...@domain.com","type":"email"}] [x.x.x.x]

2021-04-05T19:40:10Z, TRACE, operations.PasswordUtility, {N1ZJM} read last user password change timestamp (via chai) as: 2021-04-05T19:29:24Z [x.x.x.x]

2021-04-05T19:40:10Z, TRACE, token.TokenService, {N1ZJM} generated new token random code, checking for uniqueness [x.x.x.x]

2021-04-05T19:40:10Z, TRACE, token.TokenService, {N1ZJM} created new unique random token value after 1 attempts [x.x.x.x]

2021-04-05T19:40:10Z, TRACE, token.TokenService, {N1ZJM} generated token with payload: {"issueTime":"2021-04-05T19:40:10Z","name":"ACTIVATION","guid":"d1ec3163-5df6-4793-a5fa-aa1019b290e2","expiration":"2021-04-05T20:40:10Z","user":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default)"} [x.x.x.x]

2021-04-05T19:40:10Z, INFO , event.AuditService, audit event: {"perpetratorID":"test.user","perpetratorDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","perpetratorLdapProfile":"default","sourceAddress":"x.x.x.x","sourceHost":"x.x.x.x","type":"USER","eventCode":"TOKEN_ISSUED","guid":"30705821-d144-46f8-9c03-b41c89623e9d","timestamp":"2021-04-05T19:40:10Z","message":"{\"t\":\"2021-04-05T19:40:10Z\",\"e\":\"2021-04-05T20:40:10Z\",\"n\":\"ACTIVATION\",\"p\":{\"_lastPwdChange\":\"2021-04-05T19:29:24Z\"},\"user\":{\"userDN\":\"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com\",\"ldapProfile\":\"default\"},\"d\":{\"id\":\"B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867\",\"display\":\"u*************@d*************.com\",\"value\":\"user...@domain.com\",\"type\":\"email\"},\"g\":\"d1ec3163-5df6-4793-a5fa-aa1019b290e2\"}","narrative":"A token has been issued","xdasTaxonomy":"XDAS_AE_SET_CRED_ACCOUNT","xdasOutcome":"XDAS_OUT_PRIV_GRANTED"}

2021-04-05T19:40:10Z, DEBUG, event.AuditService, discarding event, INTRUDER_ATTEMPT are being ignored; event={"instance":"E1EA799F459B7986","type":"SYSTEM","eventCode":"INTRUDER_ATTEMPT","guid":"c4070ff2-cfd0-4a66-9c55-d3dca2a5eec0","timestamp":"2021-04-05T19:40:10Z","message":"{\"type\":\"TOKEN_DEST\",\"subject\":\"user...@domain.com\"}","narrative":"Non user-specific intruder attempt (Details: {\"type\":\"TOKEN_DEST\",\"subject\":\"user...@domain.com\"})","xdasTaxonomy":"XDAS_AE_IDS_SUSPICIOUS","xdasOutcome":"XDAS_OUT_SUCCESS"}

2021-04-05T19:40:10Z, TRACE, intruder.IntruderManager, delaying response 1341ms due to intruder record: {"type":"TOKEN_DEST","subject":"user...@domain.com","timeStamp":"2021-04-05T19:40:10Z","attemptCount":1,"alerted":false}

2021-04-05T19:40:11Z, TRACE, macro.MacroMachine, {N1ZJM} replaced macro @User:Email@ with value: user...@domain.com [x.x.x.x]

2021-04-05T19:40:11Z, TRACE, macro.MacroMachine, {N1ZJM} replaced macro @DefaultEmailFromAddress@ with value: p...@domain.com [x.x.x.x]

2021-04-05T19:40:11Z, TRACE, macro.MacroMachine, {N1ZJM} replaced macro @SiteURL@ with value: https://pwm.com/pwm [x.x.x.x]

2021-04-05T19:40:11Z, TRACE, email.EmailService, initializing new threadLocal transport, stats: newConnectionCounter=1,useExistingConnection=3,useExistingTransport=1,newThreadLocalTransport=3

2021-04-05T19:40:11Z, DEBUG, email.EmailServerUtil, connected to id=default,host=10.40.1.198,port=337 (unauthenticated)

2021-04-05T19:40:11Z, TRACE, email.EmailService, using existing threadLocal: stats: newConnectionCounter=1,useExistingConnection=4,useExistingTransport=1,newThreadLocalTransport=4

2021-04-05T19:40:11Z, DEBUG, email.EmailService, sent email: from: Activation Verification <p...@domain.com>, to: user...@domain.com, subject: Account Verification

2021-04-05T19:40:11Z, TRACE, email.EmailService_WorkQueueProcessor, successfully processed item=[date=2021-04-05T19:40:11.416Z,id=4,item=from: Activation Verification <p...@domain.com>, to: user...@domain.com, subject: Account Verification]; lagTime=28ms; sendRate=0.00/s,preQueueFallback=0,preQueueSubmit=0,preQueueBypass=0,avgLagTime=47ms,queueProcessItems=2

2021-04-05T19:40:11Z, DEBUG, token.TokenService, token email added to send queue for user...@domain.com

2021-04-05T19:40:11Z, TRACE, http.SessionManager, {N1ZJM} incremented request counter to 4 [x.x.x.x]

2021-04-05T19:40:11Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:40:11Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":4,"lf":[]} [x.x.x.x]

2021-04-05T19:40:11Z, TRACE, http.PwmResponse, {N1ZJM} forwarding to /WEB-INF/jsp/activateuser-entercode.jsp [x.x.x.x]

2021-04-05T19:40:11Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/activate (no params) completed requestID=1587 in 1460ms [x.x.x.x]

2021-04-05T19:40:27Z, TRACE, http.PwmRequest, {N1ZJM} POST request for: /pwm/public/activate requestID=1588 [x.x.x.x]

processAction='enterCode'

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakIDPBnohKSN2Wupu-mXdXHV7uxI6ts7Qh6OpgucXOGh-ysAI99ok25UW1f0QXCPPdF9-wL2kqorthxPIIo5f06TK1Zl2Hn_Ydrppjs1yGAJjaoS9wvNvy4OvOFn-OIXDC8PoIzw_PbASqMt-L81Bq3xKjRjdvPfWBQw9aswFch3CGb2cmkHG2aAAAA'

token=*hidden*

2021-04-05T19:40:27Z, TRACE, token.TokenService, {N1ZJM} retrieved tokenPayload: {"issueTime":"2021-04-05T19:40:10Z","name":"ACTIVATION","guid":"d1ec3163-5df6-4793-a5fa-aa1019b290e2","expiration":"2021-04-05T20:40:10Z","user":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default)"} [x.x.x.x]

2021-04-05T19:40:27Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:40:27Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (74ms)

2021-04-05T19:40:27Z, TRACE, operations.PasswordUtility, {N1ZJM} read last user password change timestamp (via chai) as: 2021-04-05T19:29:24Z [x.x.x.x]

2021-04-05T19:40:27Z, TRACE, token.TokenService, {N1ZJM} tokenPayload={"issueTime":"2021-04-05T19:40:10Z","name":"ACTIVATION","guid":"d1ec3163-5df6-4793-a5fa-aa1019b290e2","expiration":"2021-04-05T20:40:10Z","user":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default)"}, sessionUser=CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default), payloadUserIdentity=CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default), userLastPasswordChange=2021-04-05T19:29:24Z, dateStringInToken=2021-04-05T19:29:24Z [x.x.x.x]

2021-04-05T19:40:27Z, DEBUG, token.TokenService, {N1ZJM} token validation has been passed [x.x.x.x]

2021-04-05T19:40:27Z, TRACE, token.TokenService, {N1ZJM} removing claimed token: {"issueTime":"2021-04-05T19:40:10Z","name":"ACTIVATION","guid":"d1ec3163-5df6-4793-a5fa-aa1019b290e2","expiration":"2021-04-05T20:40:10Z","user":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default)"} [x.x.x.x]

2021-04-05T19:40:27Z, INFO , event.AuditService, audit event: {"perpetratorID":"test.user","perpetratorDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","perpetratorLdapProfile":"default","sourceAddress":"x.x.x.x","sourceHost":"x.x.x.x","type":"USER","eventCode":"TOKEN_CLAIMED","guid":"0adcae58-4fc0-4fac-866a-9e0e3f2a3736","timestamp":"2021-04-05T19:40:27Z","message":"{\"t\":\"2021-04-05T19:40:10Z\",\"e\":\"2021-04-05T20:40:10Z\",\"n\":\"ACTIVATION\",\"p\":{\"_lastPwdChange\":\"2021-04-05T19:29:24Z\"},\"user\":{\"userDN\":\"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com\",\"ldapProfile\":\"default\"},\"d\":{\"id\":\"B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867\",\"display\":\"u*************@d*************.com\",\"value\":\"user...@domain.com\",\"type\":\"email\"},\"g\":\"d1ec3163-5df6-4793-a5fa-aa1019b290e2\"}","narrative":"A token has been claimed","xdasTaxonomy":"XDAS_AE_GRANT_ACCOUNT_ACCESS","xdasOutcome":"XDAS_OUT_PRIV_USED"}

2021-04-05T19:40:27Z, TRACE, http.SessionManager, {N1ZJM} incremented request counter to 5 [x.x.x.x]

2021-04-05T19:40:27Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:40:27Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":5,"lf":[]} [x.x.x.x]

2021-04-05T19:40:27Z, TRACE, http.PwmResponse, {N1ZJM} forwarding to /WEB-INF/jsp/activateuser-tokensuccess.jsp [x.x.x.x]

2021-04-05T19:40:27Z, TRACE, http.PwmRequest, {N1ZJM} POST request for: /pwm/public/activate completed requestID=1588 in 96ms [x.x.x.x]

processAction='enterCode'

token=*hidden*

2021-04-05T19:40:29Z, TRACE, http.PwmRequest, {N1ZJM} GET request for: /pwm/public/activate requestID=1589 [x.x.x.x]

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakIEgGLaPqCTHRjD57Ij_fuhtVvZsiPSxdHm25dOqKXAede_pA7c21nKGnyf1jwjU66ccca1p_lACdvDU67vP0fUJPeydOslizovqj6F-MvES2xRQucBkUEWuUlkuAdA7BT_6eN2XaPL0jXJsEweYKgZqtlH3KMbml3DKMz_B8KM39iLbBVdGiaAAAA'

2021-04-05T19:40:29Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:40:29Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (71ms)

2021-04-05T19:40:29Z, TRACE, token.TokenUtil, {N1ZJM} calculated available token send destinations: [{"id":"B1E08DC21A8C0CC8E4756FE91C122517D71A32BBDE26E639B3E82D1D4C007F13DF93C673D593A2E14028CC5A4198773370384D019D361D51D6E474141B8BD867","display":"u*************@d*************.com","value":"user...@domain.com","type":"email"}] [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, activation.ActivateUserUtils, {N1ZJM} executing configured pre-actions to user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, auth.LDAPAuthenticationRequest, {N1ZJM} authID=34, beginning authentication using unknown password procedure [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, auth.LDAPAuthenticationRequest, {N1ZJM} authID=34, preparing to authenticate user using authenticationType=AUTH_FROM_PUBLIC_MODULE using strategy ADMIN_PROXY [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.LdapOperationsHelper, {N1ZJM} creating new ldap connection using config: ChaiConfiguration: settings: {chai.bind.URLs=ldaps://win-prfm7lapha7.domain.com:636,ldaps://WIN-TO8QHSDK40B.domain.com:636,, chai.bind.dn=CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com, chai.bind.password=**stripped**, chai.cache.enable=false, chai.cache.maximumSize=128, chai.cache.maximumAge=1000, chai.statistics.enable=true, chai.watchdog.enable=true, chai.watchdog.operationTimeout=60000, chai.watchdog.idleTimeout=30000, chai.watchdog.maxConnectionLifetime=3300000, chai.watchdog.disableIfPwExpired=true, chai.connection.promiscuousSSL=false, chai.wireDebug.enable=false, chai.failover.enable=true, chai.failover.useLastKnownGoodHint=true, chai.failover.failBackTime=90000, chai.failover.connectRetries=4, chai.ldap.dereferenceAliases=never, chai.ldap.ldapTimeout=30000, chai.ldap.ldapReadTimeout=0, chai.ldap.followReferrals=true, chai.provider.implementation=com.novell.ldapchai.provider.JNDIProviderImpl, chai.edirectory.enableNMAS=true, chai.provider.extendedOperation.failureCache=true, chai.provider.readonly=false, chai.vendor.default=, chai.provider.jndi.enablePool=false, chai.crsetting.caseInsensitive=true, chai.crsetting.allowDuplicateResponses=false, chai.crsetting.defaultFormatType=PBKDF2_SHA512, chai.cr.chai.attributeName=pwmResponseSet, chai.cr.chai.recordId=0002, chai.cr.chai.saltCount=100000, chai.ad.setPolicyHintsOnPwSet=false, chai.ldap.paging.enable=auto, chai.ldap.paging.size=500, chai.openldap.passwordPolicyDn=, chai.openldap.passwordPolicy.url=file:/etc/openldap/check_password.conf, chai.jndi.resolveInNamespace=true, chai.ldap.characterEncoding=UTF8} [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (58ms)

2021-04-05T19:40:29Z, TRACE, provider.ChaiProviderFactory, adding WatchdogWrapper to provider instance

2021-04-05T19:40:29Z, TRACE, provider.WatchdogWrapper, checking for user password expiration to adjust watchdog timeout id=w304

2021-04-05T19:40:29Z, TRACE, provider.ChaiProviderFactory, adding StatisticsWrapper to provider instance

2021-04-05T19:40:29Z, DEBUG, auth.LDAPAuthenticationRequest, {N1ZJM} authID=34, successful ldap authentication for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) (62ms) type: AUTH_BIND_INHIBIT, using strategy ADMIN_PROXY, using proxy connection: true, returning bind dn: CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:29Z, INFO , event.AuditService, audit event: {"perpetratorID":"test.user","perpetratorDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","perpetratorLdapProfile":"default","sourceAddress":"x.x.x.x","sourceHost":"x.x.x.x","type":"USER","eventCode":"AUTHENTICATE","guid":"2a6f1dc2-d79c-4952-9099-6d47cb2d17e6","timestamp":"2021-04-05T19:40:29Z","message":"type=AUTH_BIND_INHIBIT, source=USER_ACTIVATION","narrative":"test.user (CN=Test User,OU=Users,OU=domain,DC=domain,DC=com) has authenticated","xdasTaxonomy":"XDAS_AE_AUTHENTICATE_ACCOUNT","xdasOutcome":"XDAS_OUT_SUCCESS"}

2021-04-05T19:40:29Z, DEBUG, operations.PasswordUtility, {N1ZJM} testing password policy profile 'default' [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.LdapPermissionTester, {N1ZJM} begin check for ldapQuery match for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) using queryMatch: (objectClass=*) [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.LdapPermissionTester, {N1ZJM} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (1ms) [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, operations.PasswordUtility, {N1ZJM} read user policy for 'CN=Test User,OU=Users,OU=domain,DC=domain,DC=com', policy: PwmPasswordPolicy: {"policyMap":{"chai.pwrule.repeat.max":"0","chai.pwrule.changeMessage":"","chai.pwrule.upper.min":"0","chai.pwrule.numeric.allow":"true","chai.pwrule.allowUserChange":"true","chai.pwrule.disallowedValues":"","chai.pwrule.challengeResponseEnabled":"false","chai.pwrule.length.max":"0","chai.pwrule.nonalpha.allow":"true","chai.pwrule.nonalpha.max":"0","chai.pwrule.allowAdminChange":"true","chai.pwrule.disallowedAttributes":"","chai.pwrule.uniqueRequired":"false","chai.pwrule.ADComplexity2008":"false","chai.pwrule.sequentialRepeat.max":"0","chai.pwrule.lower.min":"0","chai.pwrule.ADComplexity":"false","chai.pwrule.unique.max":"0","chai.pwrule.special.max":"0","chai.pwrule.enforceAtLogin":"false","chai.pwrule.nonalpha.min":"0","chai.pwrule.numeric.allowLast":"true","chai.pwrule.policyEnabled":"true","chai.pwrule.numeric.allowFirst":"true","chai.pwrule.special.allow":"true","chai.pwrule.expirationInterval":"0","chai.pwrule.special.min":"0","chai.pwrule.lower.max":"0","chai.pwrule.numeric.max":"0","chai.pwrule.novellComplexity":"","chai.pwrule.ADComplexityMaxViolation":"false","chai.pwrule.upper.max":"0","chai.pwrule.numeric.min":"0","chai.pwrule.unique.min":"0","chai.pwrule.special.allowFirst":"true","chai.pwrule.length.min":"7","chai.pwrule.special.allowLast":"true","chai.pwrule.caseSensitive":"true","chai.pwrule.lifetime.minimimum":"0"}} [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, operations.PasswordUtility, {N1ZJM} merged user password policy of 'CN=Test User,OU=Users,OU=domain,DC=domain,DC=com' with PWM configured policy: PwmPasswordPolicy: {"policyMap":{"chai.pwrule.repeat.max":"0","chai.pwrule.changeMessage":"","chai.pwrule.upper.min":"0","chai.pwrule.allowUserChange":"true","chai.pwrule.disallowedValues":"password\ntest","password.policy.disallowCurrent":"true","chai.pwrule.nonalpha.allow":"true","chai.pwrule.nonalpha.max":"0","chai.pwrule.allowAdminChange":"true","chai.pwrule.uniqueRequired":"false","chai.pwrule.unique.max":"0","chai.pwrule.special.max":"0","chai.pwrule.enforceAtLogin":"false","password.policy.charGroup.regExValues":".*[0-9]\n.*[^A-Za-z0-9]\n.*[A-Z]\n.*[a-z]","chai.pwrule.policyEnabled":"true","chai.pwrule.lower.max":"0","password.policy.checkWordlist":"true","chai.pwrule.upper.max":"0","chai.pwrule.unique.min":"0","chai.pwrule.length.min":"7","password.policy.maximumAlpha":"0","chai.pwrule.numeric.allow":"true","chai.pwrule.challengeResponseEnabled":"false","password.policy.regExMatch":"","chai.pwrule.length.max":"64","password.policy.ADComplexityLevel":"AD2008","password.policy.minimumStrength":"0","chai.pwrule.disallowedAttributes":"givenName\ncn\nsn","password.policy.charGroup.minimumMatch":"0","chai.pwrule.sequentialRepeat.max":"0","password.policy.minimumAlpha":"0","chai.pwrule.lower.min":"0","password.policy.allowMacroInRegexSetting":"true","chai.pwrule.numeric.allowLast":"true","chai.pwrule.nonalpha.min":"0","chai.pwrule.numeric.allowFirst":"true","chai.pwrule.special.allow":"true","chai.pwrule.expirationInterval":"0","chai.pwrule.special.min":"0","chai.pwrule.numeric.max":"0","chai.pwrule.ADComplexityMaxViolation":"2","chai.pwrule.numeric.min":"0","chai.pwrule.special.allowFirst":"true","chai.pwrule.special.allowLast":"true","password.policy.maximumConsecutive":"0","chai.pwrule.caseSensitive":"true","chai.pwrule.lifetime.minimimum":"0","password.policy.regExNoMatch":""}} [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, operations.PasswordUtility, {N1ZJM} readPasswordPolicyForUser completed in 3ms [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.UserInfoReader, {N1ZJM} beginning password status check process for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.UserInfoReader, {N1ZJM} password for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com does not appear to be expired [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.UserInfoReader, {N1ZJM} completed user password status check for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com PasswordStatus.PasswordStatusBuilder(expired=false, preExpired=false, violatesPolicy=false, warnPeriod=false) (2ms) [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, auth.SessionAuthenticator, {N1ZJM,test.user} clearing permission cache [x.x.x.x]

2021-04-05T19:40:29Z, INFO , event.AuditService, audit event: {"perpetratorID":"test.user","perpetratorDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","perpetratorLdapProfile":"default","sourceAddress":"x.x.x.x","sourceHost":"","type":"USER","eventCode":"ACTIVATE_USER","guid":"da090f09-c74f-49c0-b030-abc63e1c7c67","timestamp":"2021-04-05T19:40:29Z","narrative":"test.user (CN=Test User,OU=Users,OU=domain,DC=domain,DC=com) has activated their account","xdasTaxonomy":"XDAS_AE_CREATE_SESSION","xdasOutcome":"XDAS_OUT_SUCCESS"}

2021-04-05T19:40:29Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @User:Email@ with value: user...@domain.com [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @DefaultEmailFromAddress@ with value: p...@domain.com [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @LDAP:givenName@ with value: Test [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, email.EmailService_WorkQueueProcessor, item submitted: [date=2021-04-05T19:40:29.811Z,id=5,item=from: Activation Notification <p...@domain.com>, to: user...@domain.com, subject: Account Activated], 1 items in queue

2021-04-05T19:40:29Z, TRACE, http.SessionManager, {N1ZJM,test.user} incremented request counter to 6 [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTH_FROM_PUBLIC_MODULE","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:29Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":6,"lf":["forcePwChange"]} [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, http.PwmResponse, {N1ZJM,test.user} forwarding to /WEB-INF/jsp/success.jsp [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @User:ID@ with value: test.user [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.LdapPermissionTester, {N1ZJM} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (1ms) [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, profile.ChallengeProfile, discarding configured helpdesk challengeSet for profile 'default' issue: 5203 CONFIG_FORMAT_ERROR (invalid challenge set configuration: too few challenges are required)

2021-04-05T19:40:29Z, DEBUG, operations.CrService, {N1ZJM} testing challenge profiles 'default' [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.LdapPermissionTester, {N1ZJM} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (0ms) [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, email.EmailService, using existing threadLocal transport, stats: newConnectionCounter=1,useExistingConnection=4,useExistingTransport=1,newThreadLocalTransport=4

2021-04-05T19:40:29Z, TRACE, email.EmailService, using existing threadLocal: stats: newConnectionCounter=1,useExistingConnection=4,useExistingTransport=2,newThreadLocalTransport=4

2021-04-05T19:40:29Z, TRACE, operations.CrService, {N1ZJM} readUserChallengeProfile completed in 19ms returned profile: default [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, operations.CrService, {N1ZJM} beginning read of user response sequence [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, operations.CrService, {N1ZJM} will attempt to read the following storage methods: ["DB"] for response info for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, operations.CrService, {N1ZJM} attempting read of response info via storage method: DB [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, cr.DbCrOperator, user guid for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com not found in remote database (key=d6b2eaeacca6384a9fe6e542d13a817c)

2021-04-05T19:40:29Z, TRACE, operations.CrService, {N1ZJM} no responses info read using method DB [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, operations.CrService, {N1ZJM} no response info found for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, operations.CrService, {N1ZJM} beginning check to determine if responses need to be configured for user [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, operations.CrService, {N1ZJM} checkIfResponseConfigNeeded: response setup is disabled, so user is not required to setup responses [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.UserInfoReader, {N1ZJM} checkOtp: beginning process to check if user OTP setup is required [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.LdapPermissionTester, {N1ZJM} begin check for ldapGroup match for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) using queryMatch: CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.LdapPermissionTester, {N1ZJM} checking ldap to see if CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) matches group 'CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com' using filter '(memberOf=CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com)' [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is not a match for group 'CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com' (1ms) [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.UserInfoReader, {N1ZJM} Helpdesk has no matching profiles for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.LdapPermissionTester, {N1ZJM} checking ldap to see if CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) matches '(objectClass=person)' [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, email.EmailService, sent email: from: Activation Notification <p...@domain.com>, to: user...@domain.com, subject: Account Activated

2021-04-05T19:40:29Z, TRACE, email.EmailService_WorkQueueProcessor, successfully processed item=[date=2021-04-05T19:40:29Z,id=5,item=from: Activation Notification <p...@domain.com>, to: user...@domain.com, subject: Account Activated]; lagTime=837ms; sendRate=0.00/s,preQueueFallback=0,preQueueSubmit=0,preQueueBypass=0,avgLagTime=51ms,queueProcessItems=3

2021-04-05T19:40:29Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=person)' (1ms) [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.UserInfoReader, {N1ZJM} assigned UpdateAttributes profileID "default" to CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.UserInfoReader, {N1ZJM} DeleteAccount has no matching profiles for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.LdapPermissionTester, {N1ZJM} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (0ms) [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.UserInfoReader, {N1ZJM} assigned SetupOTPProfile profileID "default" to CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.UserInfoReader, {N1ZJM} EmailServers has no matching profiles for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, otp.DbOtpOperator, Enter: readOtpUserConfiguration(CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default), d6b2eaeacca6384a9fe6e542d13a817c)

2021-04-05T19:40:29Z, TRACE, operations.OtpService, {N1ZJM} readOTPUserConfiguration completed in 2ms, no otp record found [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.UserInfoReader, {N1ZJM} checkOtp: user does not have existing valid otp record, user OTP setup is required [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.UserInfoReader, {N1ZJM} checkProfiles: CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) profile force setup is not enabled [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.LdapPermissionTester, {N1ZJM,test.user} begin check for ldapGroup match for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) using queryMatch: CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, ldap.LdapPermissionTester, {N1ZJM,test.user} checking ldap to see if CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) matches group 'CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com' using filter '(memberOf=CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com)' [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM,test.user} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is not a match for group 'CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com' (1ms) [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, http.SessionManager, {N1ZJM,test.user} permission PWMADMIN for user default|CN=Test User,OU=Users,OU=domain,DC=domain,DC=com is DENIED [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @User:ID@ with value: test.user [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/activate completed requestID=1589 in 183ms [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/api requestID=1590 [x.x.x.x]

processAction='clientData'

etag='09695db9004cb1e6db308cd9d1b0425b4b1bcff5'

pageUrl='https://pwm.com/pwm/public/activate?pwmFormID=H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakIEgGLaPqCTHRjD57Ij_fuhtVvZsiPSxdHm25dOqKXAede_pA7c21nKGnyf1jwjU66ccca1p_lACdvDU67vP0fUJPeydOslizovqj6F-MvES2xRQucBkUEWuUlkuAdA7BT_6eN2XaPL0jXJsEweYKgZqtlH3KMbml3DKMz_B8KM39iLbBVdGiaAAAA'

2021-04-05T19:40:29Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/api completed requestID=1590 in 2ms [x.x.x.x]

processAction='clientData'

etag='09695db9004cb1e6db308cd9d1b0425b4b1bcff5'

2021-04-05T19:40:29Z, TRACE, http.HttpEventManager, new http session created

2021-04-05T19:40:29Z, TRACE, http.PwmSession, {3ORUX} created new session

2021-04-05T19:40:29Z, TRACE, filter.RequestInitializationFilter, {3ORUX} user locale set to 'en' [x.x.x.x]

2021-04-05T19:40:29Z, TRACE, http.PwmRequest, {3ORUX} GET request for: /pwm/public/api requestID=1591 [x.x.x.x]

processAction='strings'

etag='09695db9004cb1e6db308cd9d1b0425b4b1bcff5'

bundle='Display'

2021-04-05T19:40:29Z, TRACE, filter.SessionFilter, {3ORUX} https secure request headers: [x.x.x.x]

host='pwm.com'

connection='keep-alive'

sec-ch-ua='"Google Chrome";v="89", "Chromium";v="89", ";Not A Brand";v="99"'

accept='application/json'

x-requested-with='XMLHttpRequest'

sec-ch-ua-mobile='?0'

user-agent='Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.114 Safari/537.36'

sec-fetch-site='same-origin'

sec-fetch-mode='cors'

sec-fetch-dest='empty'

referer='https://pwm.com/pwm/public/activate?pwmFormID=H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakIEgGLaPqCTHRjD57Ij_fuhtVvZsiPSxdHm25dOqKXAede_pA7c21nKGnyf1jwjU66ccca1p_lACdvDU67vP0fUJPeydOslizovqj6F-MvES2xRQucBkUEWuUlkuAdA7BT_6eN2XaPL0jXJsEweYKgZqtlH3KMbml3DKMz_B8KM39iLbBVdGiaAAAA'

accept-encoding='gzip, deflate, br'

accept-language='en-US,en;q=0.9'

cookie='authRecord=H4sIAAAAAAAAAAFyAI3_UFdNLkdDTTEQywvAEkiwhu0reZOnlakGfu9dSqFsLBVwnaBaZonhyFM7YgUO9M5su-S_tGXu59LJYC5hMEk_zb2HVfx2MsT7mR2gkVhvKaGCzFiHjiIZbkV5vZaU8mT3WowVc8U43CshGBVRAZackFHTPG8083IAAAA%3D; ID=YrtVP8cohG14jkF8qSjFYafUQiyUkh3Ckn4zt7u9; SESSION=H4sIAAAAAAAAAAGNAXL-UFdNLkdDTTEQywvAEkiwhu0reZOnlakIFMG94Pm5Y7AhvYTTAQ2M6FT1gQg18N7JMvMRo_hb5dzklKs8Rr1Wx1IpsYcmlUQnNrk6UmkzYOk-G05FNvKBjGQ7Da6ajNBlc9Dygwb8eE-AIROR6ndUUp_RSr41JE3mn6s2_Q6VJxoHYqhAQNrm4FeqMM6xwiTN_OP9YHlvh1Vop4n4xkiPDnLawrvU8ucmnclVty3doqbMVfftrOILrN6UTsBrobyiI1RdjAsFjErQJtiY4GoFYNIPpSmxcd9pcDw5teKfMTpeVlFTuVnvwZ89LT-wgBXRyW6PaCYM3PsFBWXey-OoQKNqhCAXW-zMBkuZoy1ZcLFkkFpCI7gQ5cmz5bnUnULnYoGu5pd_upfnXyFDKY2N5z9jrzhRGqBhz1t7eHojHhyjCqVKQok0ZBsEiPqifjrZkAJ74T1qJDJTDtb0zTya7hEeg8JDGSLBVKy4BgoAcsZK_6K6zlVOQWFg7z8o4VFaiuqg6fBUT57uvMXc75l84WiNAQAA; JSESSIONID=4206B127E6E5B385E82AF907F580ADD9'

2021-04-05T19:40:29Z, TRACE, state.CryptoCookieLoginImpl, {3ORUX} login cookie session was generated by a foreign instance, seen login cookie value = {"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTH_FROM_PUBLIC_MODULE","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:29Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":6,"lf":["forcePwChange"]} [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, state.CryptoCookieLoginImpl, {3ORUX} triggering authentication because request contains an authenticated session but local session is unauthenticated [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, auth.LDAPAuthenticationRequest, {3ORUX} authID=35, preparing to authenticate user using authenticationType=AUTHENTICATED using strategy BIND [x.x.x.x]

2021-04-05T19:40:29Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:40:30Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (68ms)

2021-04-05T19:40:30Z, TRACE, auth.LDAPAuthenticationRequest, {3ORUX} authID=35, beginning testCredentials process [x.x.x.x]

2021-04-05T19:40:30Z, DEBUG, auth.LDAPAuthenticationRequest, {3ORUX} authID=35, attempt to authenticate with null password [x.x.x.x]

2021-04-05T19:40:30Z, ERROR, auth.SessionAuthenticator, {3ORUX} ldap error during search: 5001 ERROR_WRONGPASSWORD (attempt to authenticate with null password) [x.x.x.x]

2021-04-05T19:40:30Z, DEBUG, event.AuditService, discarding event, INTRUDER_ATTEMPT are being ignored; event={"instance":"E1EA799F459B7986","type":"SYSTEM","eventCode":"INTRUDER_ATTEMPT","guid":"b11ac615-b04a-48e7-98a1-89913a227559","timestamp":"2021-04-05T19:40:30Z","message":"{\"type\":\"ADDRESS\",\"subject\":\"x.x.x.x\"}","narrative":"Non user-specific intruder attempt (Details: {\"type\":\"ADDRESS\",\"subject\":\"x.x.x.x\"})","xdasTaxonomy":"XDAS_AE_IDS_SUSPICIOUS","xdasOutcome":"XDAS_OUT_SUCCESS"}

2021-04-05T19:40:30Z, TRACE, intruder.IntruderManager, {3ORUX} delaying response 1502ms due to intruder record: {"type":"ADDRESS","subject":"x.x.x.x","timeStamp":"2021-04-05T19:40:30Z","attemptCount":1,"alerted":false} [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/command requestID=1592 [x.x.x.x]

processAction='next'

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakIFu9eWAtiCbKK0Y8mnGrgsEtmUp_2KWRhSGEQK-WMlgWBwI6Nf79dvKVZaFzOT1_i59eQwlwMwM2pq1FrB4qCdK1fv_efnA_3HaVvCGerlgupPNNHALMkoMIxbpJwsyvOunrRfs6WrObAxQuz4dhKU_pMqkxBPKZlv_Mypqm79cJ9E07hih6aAAAA'

2021-04-05T19:40:31Z, DEBUG, filter.AuthenticationFilter, {N1ZJM,test.user} user is authenticated via forgotten password mechanism, redirecting to change password servlet [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTH_FROM_PUBLIC_MODULE","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:31Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":6,"lf":["forcePwChange"]} [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, http.PwmResponse, {N1ZJM,test.user} sending 302 redirect to /pwm/public/changepassword [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/command completed requestID=1592 in 1ms [x.x.x.x]

processAction='next'

2021-04-05T19:40:31Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/changepassword (no params) requestID=1593 [x.x.x.x]

2021-04-05T19:40:31Z, DEBUG, changepw.ChangePasswordServletUtil, {N1ZJM,test.user} skipping user current password requirement, authentication type is AUTH_FROM_PUBLIC_MODULE [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, ldap.LdapPermissionTester, {N1ZJM,test.user} begin check for ldapQuery match for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) using queryMatch: (objectClass=*) [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, ldap.LdapPermissionTester, {N1ZJM,test.user} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:40:31Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM,test.user} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (0ms) [x.x.x.x]

2021-04-05T19:40:31Z, DEBUG, http.SessionManager, {N1ZJM,test.user} permission CHANGE_PASSWORD for user default|CN=Test User,OU=Users,OU=domain,DC=domain,DC=com is GRANTED [x.x.x.x]

2021-04-05T19:40:31Z, DEBUG, operations.PasswordUtility, {N1ZJM} testing password policy profile 'default' [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, ldap.LdapPermissionTester, {N1ZJM} begin check for ldapQuery match for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) using queryMatch: (objectClass=*) [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, ldap.LdapPermissionTester, {N1ZJM} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:40:31Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (0ms) [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, operations.PasswordUtility, {N1ZJM} read user policy for 'CN=Test User,OU=Users,OU=domain,DC=domain,DC=com', policy: PwmPasswordPolicy: {"policyMap":{"chai.pwrule.repeat.max":"0","chai.pwrule.changeMessage":"","chai.pwrule.upper.min":"0","chai.pwrule.numeric.allow":"true","chai.pwrule.allowUserChange":"true","chai.pwrule.disallowedValues":"","chai.pwrule.challengeResponseEnabled":"false","chai.pwrule.length.max":"0","chai.pwrule.nonalpha.allow":"true","chai.pwrule.nonalpha.max":"0","chai.pwrule.allowAdminChange":"true","chai.pwrule.disallowedAttributes":"","chai.pwrule.uniqueRequired":"false","chai.pwrule.ADComplexity2008":"false","chai.pwrule.sequentialRepeat.max":"0","chai.pwrule.lower.min":"0","chai.pwrule.ADComplexity":"false","chai.pwrule.unique.max":"0","chai.pwrule.special.max":"0","chai.pwrule.enforceAtLogin":"false","chai.pwrule.nonalpha.min":"0","chai.pwrule.numeric.allowLast":"true","chai.pwrule.policyEnabled":"true","chai.pwrule.numeric.allowFirst":"true","chai.pwrule.special.allow":"true","chai.pwrule.expirationInterval":"0","chai.pwrule.special.min":"0","chai.pwrule.lower.max":"0","chai.pwrule.numeric.max":"0","chai.pwrule.novellComplexity":"","chai.pwrule.ADComplexityMaxViolation":"false","chai.pwrule.upper.max":"0","chai.pwrule.numeric.min":"0","chai.pwrule.unique.min":"0","chai.pwrule.special.allowFirst":"true","chai.pwrule.length.min":"7","chai.pwrule.special.allowLast":"true","chai.pwrule.caseSensitive":"true","chai.pwrule.lifetime.minimimum":"0"}} [x.x.x.x]

2021-04-05T19:40:31Z, DEBUG, operations.PasswordUtility, {N1ZJM} merged user password policy of 'CN=Test User,OU=Users,OU=domain,DC=domain,DC=com' with PWM configured policy: PwmPasswordPolicy: {"policyMap":{"chai.pwrule.repeat.max":"0","chai.pwrule.changeMessage":"","chai.pwrule.upper.min":"0","chai.pwrule.allowUserChange":"true","chai.pwrule.disallowedValues":"password\ntest","password.policy.disallowCurrent":"true","chai.pwrule.nonalpha.allow":"true","chai.pwrule.nonalpha.max":"0","chai.pwrule.allowAdminChange":"true","chai.pwrule.uniqueRequired":"false","chai.pwrule.unique.max":"0","chai.pwrule.special.max":"0","chai.pwrule.enforceAtLogin":"false","password.policy.charGroup.regExValues":".*[0-9]\n.*[^A-Za-z0-9]\n.*[A-Z]\n.*[a-z]","chai.pwrule.policyEnabled":"true","chai.pwrule.lower.max":"0","password.policy.checkWordlist":"true","chai.pwrule.upper.max":"0","chai.pwrule.unique.min":"0","chai.pwrule.length.min":"7","password.policy.maximumAlpha":"0","chai.pwrule.numeric.allow":"true","chai.pwrule.challengeResponseEnabled":"false","password.policy.regExMatch":"","chai.pwrule.length.max":"64","password.policy.ADComplexityLevel":"AD2008","password.policy.minimumStrength":"0","chai.pwrule.disallowedAttributes":"givenName\ncn\nsn","password.policy.charGroup.minimumMatch":"0","chai.pwrule.sequentialRepeat.max":"0","password.policy.minimumAlpha":"0","chai.pwrule.lower.min":"0","password.policy.allowMacroInRegexSetting":"true","chai.pwrule.numeric.allowLast":"true","chai.pwrule.nonalpha.min":"0","chai.pwrule.numeric.allowFirst":"true","chai.pwrule.special.allow":"true","chai.pwrule.expirationInterval":"0","chai.pwrule.special.min":"0","chai.pwrule.numeric.max":"0","chai.pwrule.ADComplexityMaxViolation":"2","chai.pwrule.numeric.min":"0","chai.pwrule.special.allowFirst":"true","chai.pwrule.special.allowLast":"true","password.policy.maximumConsecutive":"0","chai.pwrule.caseSensitive":"true","chai.pwrule.lifetime.minimimum":"0","password.policy.regExNoMatch":""}} [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, operations.PasswordUtility, {N1ZJM} readPasswordPolicyForUser completed in 4ms [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, operations.PasswordUtility, {N1ZJM} read last user password change timestamp (via chai) as: 2021-04-05T19:29:24Z [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, ldap.UserInfoReader, {N1ZJM} beginning password status check process for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, ldap.UserInfoReader, {N1ZJM} password for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com does not appear to be expired [x.x.x.x]

2021-04-05T19:40:31Z, DEBUG, ldap.UserInfoReader, {N1ZJM} completed user password status check for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com PasswordStatus.PasswordStatusBuilder(expired=false, preExpired=false, violatesPolicy=false, warnPeriod=false) (1ms) [x.x.x.x]

2021-04-05T19:40:31Z, DEBUG, changepw.ChangePasswordServletUtil, {N1ZJM,test.user} skipping user current password requirement, authentication type is AUTH_FROM_PUBLIC_MODULE [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, http.SessionManager, {N1ZJM,test.user} incremented request counter to 7 [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, http.PwmResponse, {N1ZJM,test.user} forwarding to /WEB-INF/jsp/changepassword.jsp [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @User:ID@ with value: test.user [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/changepassword (no params) completed requestID=1593 in 10ms [x.x.x.x]

2021-04-05T19:40:31Z, DEBUG, event.AuditService, discarding event, INTRUDER_USER_ATTEMPT are being ignored; event={"perpetratorID":"test.user","perpetratorDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","perpetratorLdapProfile":"default","sourceAddress":"x.x.x.x","sourceHost":"x.x.x.x","type":"USER","eventCode":"INTRUDER_USER_ATTEMPT","guid":"989dd832-89a5-4d9b-8079-462e8dc77556","timestamp":"2021-04-05T19:40:31Z","narrative":"test.user (CN=Test User,OU=Users,OU=domain,DC=domain,DC=com) account has had an invalid login attempt (intruder attempt)","xdasTaxonomy":"XDAS_AE_IDS_SUSPICIOUS","xdasOutcome":"XDAS_OUT_SUCCESS"}

2021-04-05T19:40:31Z, TRACE, intruder.IntruderManager, {3ORUX} delaying response 1466ms due to intruder record: {"type":"USER_ID","subject":"default|CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","timeStamp":"2021-04-05T19:40:31Z","attemptCount":1,"alerted":false} [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/api requestID=1594 [x.x.x.x]

processAction='clientData'

etag='60334171ec7c136c1980f42423b195736875e0ed'

pageUrl='https://pwm.com/pwm/public/changepassword'

2021-04-05T19:40:31Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/api completed requestID=1594 in 2ms [x.x.x.x]

processAction='clientData'

etag='60334171ec7c136c1980f42423b195736875e0ed'

pageUrl='https://pwm.com/pwm/public/changepassword'

2021-04-05T19:40:31Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/api requestID=1595 [x.x.x.x]

processAction='strings'

etag='60334171ec7c136c1980f42423b195736875e0ed'

bundle='Display'

2021-04-05T19:40:31Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @User:ID@ with value: test.user [x.x.x.x]

2021-04-05T19:40:31Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/api completed requestID=1595 in 7ms [x.x.x.x]

processAction='strings'

etag='60334171ec7c136c1980f42423b195736875e0ed'

bundle='Display'

2021-04-05T19:40:33Z, ERROR, state.CryptoCookieLoginImpl, {3ORUX} 5015 ERROR_INTERNAL (unexpected error reading session cookie: 5001 ERROR_WRONGPASSWORD (attempt to authenticate with null password)) [x.x.x.x]

2021-04-05T19:40:33Z, ERROR, state.CryptoCookieLoginImpl, {3ORUX} 5015 ERROR_INTERNAL (unexpected error authenticating using crypto session cookie: 5015 ERROR_INTERNAL (unexpected error reading session cookie: 5001 ERROR_WRONGPASSWORD (attempt to authenticate with null password))) [x.x.x.x]

2021-04-05T19:40:33Z, WARN , filter.SessionFilter, {3ORUX} error while reading login session state: 5015 ERROR_INTERNAL (unexpected error authenticating using crypto session cookie: 5015 ERROR_INTERNAL (unexpected error reading session cookie: 5001 ERROR_WRONGPASSWORD (attempt to authenticate with null password))) [x.x.x.x]

2021-04-05T19:40:33Z, DEBUG, filter.SessionFilter, {3ORUX} session is unvalidated but can not be validated during a json request, will allow [x.x.x.x]

2021-04-05T19:40:33Z, TRACE, state.CryptoCookieLoginImpl, {3ORUX} wrote LoginInfoBean={"a":false,"p":"*hidden*","t":"UNAUTHENTICATED","af":[],"rq":"2021-04-05T19:40:33Z","g":"kn500i2tYdKMM0EFOZoiyQFIQoLTYpOUhZe9twRM12PZMw9Kp7RUWkPlqtYy49Ah8vAXX33z","c":0,"lf":[]} [x.x.x.x]

2021-04-05T19:40:33Z, TRACE, http.PwmRequest, {3ORUX} GET request for: /pwm/public/api completed requestID=1591 in 3s [x.x.x.x]

processAction='strings'

etag='09695db9004cb1e6db308cd9d1b0425b4b1bcff5'

bundle='Display'

2021-04-05T19:40:36Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword requestID=1596 [x.x.x.x]

preventCache='1617651636621'

processAction='checkPassword'

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakIG0wOLl8ntp2Oyd4xQabgQ15skDRDlBAjihStIf8IOgwYtwJIzoXZWSUdqagqLzhsoR3R5paK7YhX14lriG7upjhQWQqkbjDyqi0puHmzWgypB4St1kZ1yxnaUYTeXviXyyYF5hDCfYTNeSjfiigEabxdK8j1H7lcevMwWwW4xBdZYwqVUQaaAAAA'

2021-04-05T19:40:36Z, DEBUG, changepw.ChangePasswordServletUtil, {N1ZJM,test.user} skipping user current password requirement, authentication type is AUTH_FROM_PUBLIC_MODULE [x.x.x.x]

2021-04-05T19:40:36Z, TRACE, password.PwmPasswordRuleValidator, calling chai directory password validation checker

2021-04-05T19:40:36Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTH_FROM_PUBLIC_MODULE","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:36Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":7,"lf":["forcePwChange"]} [x.x.x.x]

2021-04-05T19:40:36Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword completed requestID=1596 in 5ms [x.x.x.x]

preventCache='1617651636621'

processAction='checkPassword'

2021-04-05T19:40:36Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword requestID=1597 [x.x.x.x]

preventCache='1617651636761'

processAction='checkPassword'

2021-04-05T19:40:36Z, DEBUG, changepw.ChangePasswordServletUtil, {N1ZJM,test.user} skipping user current password requirement, authentication type is AUTH_FROM_PUBLIC_MODULE [x.x.x.x]

2021-04-05T19:40:36Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword completed requestID=1597 in 2ms [x.x.x.x]

preventCache='1617651636761'

processAction='checkPassword'

2021-04-05T19:40:37Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword requestID=1598 [x.x.x.x]

preventCache='1617651637140'

processAction='checkPassword'

2021-04-05T19:40:37Z, DEBUG, changepw.ChangePasswordServletUtil, {N1ZJM,test.user} skipping user current password requirement, authentication type is AUTH_FROM_PUBLIC_MODULE [x.x.x.x]

2021-04-05T19:40:37Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTH_FROM_PUBLIC_MODULE","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:37Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":7,"lf":["forcePwChange"]} [x.x.x.x]

2021-04-05T19:40:37Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword completed requestID=1598 in 2ms [x.x.x.x]

preventCache='1617651637140'

processAction='checkPassword'

2021-04-05T19:40:37Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword requestID=1599 [x.x.x.x]

preventCache='1617651637281'

processAction='checkPassword'

2021-04-05T19:40:37Z, DEBUG, changepw.ChangePasswordServletUtil, {N1ZJM,test.user} skipping user current password requirement, authentication type is AUTH_FROM_PUBLIC_MODULE [x.x.x.x]

2021-04-05T19:40:37Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword completed requestID=1599 in 2ms [x.x.x.x]

preventCache='1617651637281'

processAction='checkPassword'

2021-04-05T19:40:38Z, DEBUG, provider.WatchdogProviderHolder, disconnecting underlying connection: ldap idle timeout detected (PT30.936S), closing connection id=w281-773

2021-04-05T19:40:39Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword requestID=1600 [x.x.x.x]

preventCache='1617651639689'

processAction='checkPassword'

2021-04-05T19:40:39Z, DEBUG, changepw.ChangePasswordServletUtil, {N1ZJM,test.user} skipping user current password requirement, authentication type is AUTH_FROM_PUBLIC_MODULE [x.x.x.x]

2021-04-05T19:40:39Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTH_FROM_PUBLIC_MODULE","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:39Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":7,"lf":["forcePwChange"]} [x.x.x.x]

2021-04-05T19:40:39Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword completed requestID=1600 in 3ms [x.x.x.x]

preventCache='1617651639689'

processAction='checkPassword'

2021-04-05T19:40:40Z, DEBUG, provider.WatchdogProviderHolder, disconnecting underlying connection: ldap idle timeout detected (PT30.797S), closing connection id=w292-775

2021-04-05T19:40:41Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword requestID=1601 [x.x.x.x]

processAction='change'

password2=*hidden*

password1=*hidden*

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakIHBJnVfh8Tx6uHaV7m70oadUptfR-I4eRney_STn9zvdpB0SIym0HjEQrWJHVEy_LSpy8GbL7fL7um19qk5Dr77BsXmQDabyMF4NYwFnL1zpYOJ5rrf0-qAlK-ZRcA6EnoyTKvxjuR4wjdVv65DhOsXFdUNkRC-3MKS-gwmtO51N8GgIRqK2aAAAA'

2021-04-05T19:40:41Z, DEBUG, changepw.ChangePasswordServletUtil, {N1ZJM,test.user} skipping user current password requirement, authentication type is AUTH_FROM_PUBLIC_MODULE [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:40:41Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (78ms)

2021-04-05T19:40:41Z, TRACE, password.PwmPasswordRuleValidator, calling chai directory password validation checker

2021-04-05T19:40:41Z, DEBUG, operations.PasswordUtility, {N1ZJM,test.user} testing password policy profile 'default' [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, ldap.LdapPermissionTester, {N1ZJM,test.user} begin check for ldapQuery match for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) using queryMatch: (objectClass=*) [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, ldap.LdapPermissionTester, {N1ZJM,test.user} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM,test.user} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (0ms) [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, operations.PasswordUtility, {N1ZJM,test.user} read user policy for 'CN=Test User,OU=Users,OU=domain,DC=domain,DC=com', policy: PwmPasswordPolicy: {"policyMap":{"chai.pwrule.repeat.max":"0","chai.pwrule.changeMessage":"","chai.pwrule.upper.min":"0","chai.pwrule.numeric.allow":"true","chai.pwrule.allowUserChange":"true","chai.pwrule.disallowedValues":"","chai.pwrule.challengeResponseEnabled":"false","chai.pwrule.length.max":"0","chai.pwrule.nonalpha.allow":"true","chai.pwrule.nonalpha.max":"0","chai.pwrule.allowAdminChange":"true","chai.pwrule.disallowedAttributes":"","chai.pwrule.uniqueRequired":"false","chai.pwrule.ADComplexity2008":"false","chai.pwrule.sequentialRepeat.max":"0","chai.pwrule.lower.min":"0","chai.pwrule.ADComplexity":"false","chai.pwrule.unique.max":"0","chai.pwrule.special.max":"0","chai.pwrule.enforceAtLogin":"false","chai.pwrule.nonalpha.min":"0","chai.pwrule.numeric.allowLast":"true","chai.pwrule.policyEnabled":"true","chai.pwrule.numeric.allowFirst":"true","chai.pwrule.special.allow":"true","chai.pwrule.expirationInterval":"0","chai.pwrule.special.min":"0","chai.pwrule.lower.max":"0","chai.pwrule.numeric.max":"0","chai.pwrule.novellComplexity":"","chai.pwrule.ADComplexityMaxViolation":"false","chai.pwrule.upper.max":"0","chai.pwrule.numeric.min":"0","chai.pwrule.unique.min":"0","chai.pwrule.special.allowFirst":"true","chai.pwrule.length.min":"7","chai.pwrule.special.allowLast":"true","chai.pwrule.caseSensitive":"true","chai.pwrule.lifetime.minimimum":"0"}} [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, operations.PasswordUtility, {N1ZJM,test.user} merged user password policy of 'CN=Test User,OU=Users,OU=domain,DC=domain,DC=com' with PWM configured policy: PwmPasswordPolicy: {"policyMap":{"chai.pwrule.repeat.max":"0","chai.pwrule.changeMessage":"","chai.pwrule.upper.min":"0","chai.pwrule.allowUserChange":"true","chai.pwrule.disallowedValues":"password\ntest","password.policy.disallowCurrent":"true","chai.pwrule.nonalpha.allow":"true","chai.pwrule.nonalpha.max":"0","chai.pwrule.allowAdminChange":"true","chai.pwrule.uniqueRequired":"false","chai.pwrule.unique.max":"0","chai.pwrule.special.max":"0","chai.pwrule.enforceAtLogin":"false","password.policy.charGroup.regExValues":".*[0-9]\n.*[^A-Za-z0-9]\n.*[A-Z]\n.*[a-z]","chai.pwrule.policyEnabled":"true","chai.pwrule.lower.max":"0","password.policy.checkWordlist":"true","chai.pwrule.upper.max":"0","chai.pwrule.unique.min":"0","chai.pwrule.length.min":"7","password.policy.maximumAlpha":"0","chai.pwrule.numeric.allow":"true","chai.pwrule.challengeResponseEnabled":"false","password.policy.regExMatch":"","chai.pwrule.length.max":"64","password.policy.ADComplexityLevel":"AD2008","password.policy.minimumStrength":"0","chai.pwrule.disallowedAttributes":"givenName\ncn\nsn","password.policy.charGroup.minimumMatch":"0","chai.pwrule.sequentialRepeat.max":"0","password.policy.minimumAlpha":"0","chai.pwrule.lower.min":"0","password.policy.allowMacroInRegexSetting":"true","chai.pwrule.numeric.allowLast":"true","chai.pwrule.nonalpha.min":"0","chai.pwrule.numeric.allowFirst":"true","chai.pwrule.special.allow":"true","chai.pwrule.expirationInterval":"0","chai.pwrule.special.min":"0","chai.pwrule.numeric.max":"0","chai.pwrule.ADComplexityMaxViolation":"2","chai.pwrule.numeric.min":"0","chai.pwrule.special.allowFirst":"true","chai.pwrule.special.allowLast":"true","password.policy.maximumConsecutive":"0","chai.pwrule.caseSensitive":"true","chai.pwrule.lifetime.minimimum":"0","password.policy.regExNoMatch":""}} [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, operations.PasswordUtility, {N1ZJM,test.user} readPasswordPolicyForUser completed in 4ms [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, operations.PasswordUtility, {N1ZJM,test.user} preparing to setActorPassword for 'CN=Test User,OU=Users,OU=domain,DC=domain,DC=com', using bind DN: CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, provider.WatchdogProviderHolder, disconnecting underlying connection: ldap idle timeout detected (PT30.318S), closing connection id=w293-777

2021-04-05T19:40:41Z, INFO , operations.PasswordUtility, {N1ZJM,test.user} password for user 'CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default)' has been changed by CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (29ms) [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, http.SessionManager, {N1ZJM,test.user} closing user ldap connection [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, ldap.LdapOperationsHelper, {N1ZJM,test.user} creating new ldap connection using config: ChaiConfiguration: settings: {chai.bind.URLs=ldaps://win-prfm7lapha7.domain.com:636,ldaps://WIN-TO8QHSDK40B.domain.com:636,, chai.bind.dn=CN=Test User,OU=Users,OU=domain,DC=domain,DC=com, chai.bind.password=**stripped**, chai.cache.enable=false, chai.cache.maximumSize=128, chai.cache.maximumAge=1000, chai.statistics.enable=true, chai.watchdog.enable=true, chai.watchdog.operationTimeout=60000, chai.watchdog.idleTimeout=30000, chai.watchdog.maxConnectionLifetime=3300000, chai.watchdog.disableIfPwExpired=true, chai.connection.promiscuousSSL=false, chai.wireDebug.enable=false, chai.failover.enable=true, chai.failover.useLastKnownGoodHint=true, chai.failover.failBackTime=90000, chai.failover.connectRetries=4, chai.ldap.dereferenceAliases=never, chai.ldap.ldapTimeout=30000, chai.ldap.ldapReadTimeout=0, chai.ldap.followReferrals=true, chai.provider.implementation=com.novell.ldapchai.provider.JNDIProviderImpl, chai.edirectory.enableNMAS=true, chai.provider.extendedOperation.failureCache=true, chai.provider.readonly=false, chai.vendor.default=, chai.provider.jndi.enablePool=false, chai.crsetting.caseInsensitive=true, chai.crsetting.allowDuplicateResponses=false, chai.crsetting.defaultFormatType=PBKDF2_SHA512, chai.cr.chai.attributeName=pwmResponseSet, chai.cr.chai.recordId=0002, chai.cr.chai.saltCount=100000, chai.ad.setPolicyHintsOnPwSet=false, chai.ldap.paging.enable=auto, chai.ldap.paging.size=500, chai.openldap.passwordPolicyDn=, chai.openldap.passwordPolicy.url=file:/etc/openldap/check_password.conf, chai.jndi.resolveInNamespace=true, chai.ldap.characterEncoding=UTF8} [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (63ms)

2021-04-05T19:40:41Z, TRACE, provider.ChaiProviderFactory, adding WatchdogWrapper to provider instance

2021-04-05T19:40:41Z, TRACE, provider.WatchdogWrapper, checking for user password expiration to adjust watchdog timeout id=w305

2021-04-05T19:40:41Z, TRACE, provider.ChaiProviderFactory, adding StatisticsWrapper to provider instance

2021-04-05T19:40:41Z, TRACE, http.PwmSession, {N1ZJM,test.user} performing reloadUserInfoBean [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, activation.ActivateUserUtils, {N1ZJM,test.user} executing post-activate configured actions to user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, operations.PasswordUtility, {N1ZJM,test.user} executing configured actions to user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, provider.JNDIProviderImpl, error during write of attribute 'pwdLastSet', error: [LDAP: error code 50 - 00002098: SecErr: DSID-03150E49, problem 4003 (INSUFF_ACCESS_RIGHTS), data 0

]

2021-04-05T19:40:41Z, DEBUG, ldap.LdapOperationsHelper, {N1ZJM,test.user} error writing update attribute for user 'CN=Test User,OU=Users,OU=domain,DC=domain,DC=com' javax.naming.NoPermissionException: [LDAP: error code 50 - 00002098: SecErr: DSID-03150E49, problem 4003 (INSUFF_ACCESS_RIGHTS), data 0 [x.x.x.x]

]

2021-04-05T19:40:41Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @User:Email@ with value: user...@domain.com [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @DefaultEmailFromAddress@ with value: p...@domain.com [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, email.EmailService_WorkQueueProcessor, item submitted: [date=2021-04-05T19:40:41.815Z,id=6,item=from: Change Password Notice <p...@domain.com>, to: user...@domain.com, subject: Password Change Notification], 1 items in queue

2021-04-05T19:40:41Z, TRACE, email.EmailService, using existing threadLocal transport, stats: newConnectionCounter=1,useExistingConnection=4,useExistingTransport=2,newThreadLocalTransport=4

2021-04-05T19:40:41Z, INFO , event.AuditService, audit event: {"perpetratorID":"test.user","perpetratorDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","perpetratorLdapProfile":"default","sourceAddress":"x.x.x.x","sourceHost":"","type":"USER","eventCode":"CHANGE_PASSWORD","guid":"f2871731-e1a7-4022-94e4-1552be02cc8a","timestamp":"2021-04-05T19:40:41Z","narrative":"test.user (CN=Test User,OU=Users,OU=domain,DC=domain,DC=com) has changed their password","xdasTaxonomy":"XDAS_AE_SET_CRED_ACCOUNT","xdasOutcome":"XDAS_OUT_SUCCESS"}

2021-04-05T19:40:41Z, TRACE, email.EmailService, using existing threadLocal: stats: newConnectionCounter=1,useExistingConnection=4,useExistingTransport=3,newThreadLocalTransport=4

2021-04-05T19:40:41Z, DEBUG, email.EmailService, sent email: from: Change Password Notice <p...@domain.com>, to: user...@domain.com, subject: Password Change Notification

2021-04-05T19:40:41Z, TRACE, email.EmailService_WorkQueueProcessor, successfully processed item=[date=2021-04-05T19:40:41Z,id=6,item=from: Change Password Notice <p...@domain.com>, to: user...@domain.com, subject: Password Change Notification]; lagTime=825ms; sendRate=0.00/s,preQueueFallback=0,preQueueSubmit=0,preQueueBypass=0,avgLagTime=53ms,queueProcessItems=4

2021-04-05T19:40:41Z, DEBUG, servlet.AbstractPwmServlet, {N1ZJM,test.user} this request is not idempotent, redirecting to self with no action [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTHENTICATED","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:41Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":7,"lf":[]} [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, http.PwmResponse, {N1ZJM,test.user} sending 303 redirect to /pwm/public/changepassword [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword completed requestID=1601 in 198ms [x.x.x.x]

processAction='change'

password2=*hidden*

password1=*hidden*

2021-04-05T19:40:41Z, TRACE, ldap.LdapPermissionTester, {N1ZJM,test.user} begin check for ldapGroup match for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) using queryMatch: CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, ldap.LdapPermissionTester, {N1ZJM,test.user} checking ldap to see if CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) matches group 'CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com' using filter '(memberOf=CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com)' [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM,test.user} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is not a match for group 'CN=pwm-admins,OU=Groups,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com' (3ms) [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.UserInfoReader, {N1ZJM,test.user} Helpdesk has no matching profiles for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, ldap.LdapPermissionTester, {N1ZJM,test.user} checking ldap to see if CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) matches '(objectClass=person)' [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM,test.user} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=person)' (1ms) [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.UserInfoReader, {N1ZJM,test.user} assigned UpdateAttributes profileID "default" to CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.UserInfoReader, {N1ZJM,test.user} DeleteAccount has no matching profiles for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, ldap.LdapPermissionTester, {N1ZJM,test.user} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM,test.user} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (0ms) [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.UserInfoReader, {N1ZJM,test.user} assigned SetupOTPProfile profileID "default" to CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.UserInfoReader, {N1ZJM,test.user} EmailServers has no matching profiles for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/changepassword (no params) requestID=1602 [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, http.SessionManager, {N1ZJM,test.user} incremented request counter to 8 [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, http.PwmResponse, {N1ZJM,test.user} forwarding to /WEB-INF/jsp/changepassword-wait.jsp [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @User:ID@ with value: test.user [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, operations.PasswordUtility, {N1ZJM,test.user} testing password policy profile 'default' [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, ldap.LdapPermissionTester, {N1ZJM,test.user} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM,test.user} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (0ms) [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, operations.PasswordUtility, {N1ZJM,test.user} readPasswordPolicyForUser completed in 7ms [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, ldap.UserInfoReader, {N1ZJM,test.user} beginning password status check process for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, ldap.UserInfoReader, {N1ZJM,test.user} password for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com does not appear to be expired [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.UserInfoReader, {N1ZJM,test.user} completed user password status check for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com PasswordStatus.PasswordStatusBuilder(expired=false, preExpired=false, violatesPolicy=false, warnPeriod=false) (3ms) [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, ldap.LdapPermissionTester, {N1ZJM,test.user} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM,test.user} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (0ms) [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, profile.ChallengeProfile, discarding configured helpdesk challengeSet for profile 'default' issue: 5203 CONFIG_FORMAT_ERROR (invalid challenge set configuration: too few challenges are required)

2021-04-05T19:40:41Z, DEBUG, operations.CrService, {N1ZJM,test.user} testing challenge profiles 'default' [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, ldap.LdapPermissionTester, {N1ZJM,test.user} queryMatch check is guaranteed to be true, skipping ldap query [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.LdapPermissionTester, {N1ZJM,test.user} user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) is a match for filter '(objectClass=*)' (0ms) [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, operations.CrService, {N1ZJM,test.user} readUserChallengeProfile completed in 12ms returned profile: default [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, operations.CrService, {N1ZJM,test.user} beginning read of user response sequence [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, operations.CrService, {N1ZJM,test.user} will attempt to read the following storage methods: ["DB"] for response info for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, operations.CrService, {N1ZJM,test.user} attempting read of response info via storage method: DB [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, cr.DbCrOperator, user guid for CN=Test User,OU=Users,OU=domain,DC=domain,DC=com not found in remote database (key=d6b2eaeacca6384a9fe6e542d13a817c)

2021-04-05T19:40:41Z, TRACE, operations.CrService, {N1ZJM,test.user} no responses info read using method DB [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, operations.CrService, {N1ZJM,test.user} no response info found for user CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, operations.CrService, {N1ZJM,test.user} beginning check to determine if responses need to be configured for user [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, operations.CrService, {N1ZJM,test.user} checkIfResponseConfigNeeded: response setup is disabled, so user is not required to setup responses [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, ldap.UserInfoReader, {N1ZJM,test.user} checkOtp: beginning process to check if user OTP setup is required [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, otp.DbOtpOperator, Enter: readOtpUserConfiguration(CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default), d6b2eaeacca6384a9fe6e542d13a817c)

2021-04-05T19:40:41Z, TRACE, operations.OtpService, {N1ZJM,test.user} readOTPUserConfiguration completed in 2ms, no otp record found [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.UserInfoReader, {N1ZJM,test.user} checkOtp: user does not have existing valid otp record, user OTP setup is required [x.x.x.x]

2021-04-05T19:40:41Z, DEBUG, ldap.UserInfoReader, {N1ZJM,test.user} checkProfiles: CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default) profile force setup is not enabled [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @User:ID@ with value: test.user [x.x.x.x]

2021-04-05T19:40:41Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/changepassword (no params) completed requestID=1602 in 30ms [x.x.x.x]

2021-04-05T19:40:42Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword requestID=1603 [x.x.x.x]

preventCache='1617651642145'

processAction='checkProgress'

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakIL_XO14v2eJoOwH5Aat-L4mehM_TniLQ1sy72DGwV77Nxmof27JFJrc9vL3F6UdANdIeBg3tX4Xvi8fCYUNJ_XqURI9-X1mLl54yiWiABWzKDc0lhoRs8ICMYcI7MTVjpYgmWKDdNg2qTujHrf5ddFE-jQNXb3-SifKweNn62A-_W8hCOGYaaAAAA'

2021-04-05T19:40:42Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} beginning password replication time check for default|CN=Test User,OU=Users,OU=domain,DC=domain,DC=com [x.x.x.x]

2021-04-05T19:40:42Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (65ms)

2021-04-05T19:40:42Z, TRACE, provider.ChaiProviderFactory, adding WatchdogWrapper to provider instance

2021-04-05T19:40:42Z, TRACE, provider.WatchdogWrapper, checking for user password expiration to adjust watchdog timeout id=w306

2021-04-05T19:40:42Z, TRACE, provider.ChaiProviderFactory, adding StatisticsWrapper to provider instance

2021-04-05T19:40:42Z, DEBUG, provider.WatchdogProviderHolder, reopening ldap connection for method=, id=, after PT0S

2021-04-05T19:40:42Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (76ms)

2021-04-05T19:40:42Z, TRACE, operations.PasswordUtility, {N1ZJM,test.user} read last user password change timestamp (via chai) as: 2021-04-05T19:40:41Z [x.x.x.x]

2021-04-05T19:40:42Z, TRACE, provider.JNDIProviderImpl, bind successful as CN=Service PWM,OU=Users,OU=PWM,OU=INC,OU=Customers,OU=domain,DC=domain,DC=com (67ms)

2021-04-05T19:40:42Z, TRACE, provider.ChaiProviderFactory, adding WatchdogWrapper to provider instance

2021-04-05T19:40:42Z, TRACE, provider.WatchdogWrapper, checking for user password expiration to adjust watchdog timeout id=w307

2021-04-05T19:40:42Z, TRACE, provider.ChaiProviderFactory, adding StatisticsWrapper to provider instance

2021-04-05T19:40:42Z, TRACE, operations.PasswordUtility, {N1ZJM,test.user} read last user password change timestamp (via chai) as: 2021-04-05T19:40:41Z [x.x.x.x]

2021-04-05T19:40:42Z, TRACE, ldap.PasswordChangeProgressChecker, only one replica returned data, marking as complete

2021-04-05T19:40:42Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} percent complete: 100.00 [x.x.x.x]

2021-04-05T19:40:42Z, TRACE, changepw.ChangePasswordServlet, {N1ZJM,test.user} returning result for restCheckProgress: {"error":false,"errorCode":0,"data":{"complete":false,"percentComplete":9.22,"messages":[{"key":"replication","label":"Password replication (progress 100%)","percentComplete":100,"complete":true,"show":false}],"elapsedSeconds":"1.38 seconds","estimatedRemainingSeconds":"13 seconds"}} [x.x.x.x]

2021-04-05T19:40:42Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTHENTICATED","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:42Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":8,"lf":[]} [x.x.x.x]

2021-04-05T19:40:42Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword completed requestID=1603 in 220ms [x.x.x.x]

preventCache='1617651642145'

processAction='checkProgress'

2021-04-05T19:40:45Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword requestID=1604 [x.x.x.x]

preventCache='1617651645408'

processAction='checkProgress'

2021-04-05T19:40:45Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} skipping replica sync check, replica sync completed previously [x.x.x.x]

2021-04-05T19:40:45Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} percent complete: 100.00 [x.x.x.x]

2021-04-05T19:40:45Z, TRACE, changepw.ChangePasswordServlet, {N1ZJM,test.user} returning result for restCheckProgress: {"error":false,"errorCode":0,"data":{"complete":false,"percentComplete":29.54,"messages":[{"key":"replication","label":"Password replication (progress 100%)","percentComplete":100,"complete":true,"show":false}],"elapsedSeconds":"4.4 seconds","estimatedRemainingSeconds":"10 seconds"}} [x.x.x.x]

2021-04-05T19:40:45Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTHENTICATED","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:45Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":8,"lf":[]} [x.x.x.x]

2021-04-05T19:40:45Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword completed requestID=1604 in 3ms [x.x.x.x]

preventCache='1617651645408'

processAction='checkProgress'

2021-04-05T19:40:48Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword requestID=1605 [x.x.x.x]

preventCache='1617651648459'

processAction='checkProgress'

2021-04-05T19:40:48Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} skipping replica sync check, replica sync completed previously [x.x.x.x]

2021-04-05T19:40:48Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} percent complete: 100.00 [x.x.x.x]

2021-04-05T19:40:48Z, TRACE, changepw.ChangePasswordServlet, {N1ZJM,test.user} returning result for restCheckProgress: {"error":false,"errorCode":0,"data":{"complete":false,"percentComplete":49.90,"messages":[{"key":"replication","label":"Password replication (progress 100%)","percentComplete":100,"complete":true,"show":false}],"elapsedSeconds":"7 seconds","estimatedRemainingSeconds":"7 seconds"}} [x.x.x.x]

2021-04-05T19:40:48Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTHENTICATED","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:48Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":8,"lf":[]} [x.x.x.x]

2021-04-05T19:40:48Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword completed requestID=1605 in 2ms [x.x.x.x]

preventCache='1617651648459'

processAction='checkProgress'

2021-04-05T19:40:51Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword requestID=1606 [x.x.x.x]

preventCache='1617651651514'

processAction='checkProgress'

2021-04-05T19:40:51Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} skipping replica sync check, replica sync completed previously [x.x.x.x]

2021-04-05T19:40:51Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} percent complete: 100.00 [x.x.x.x]

2021-04-05T19:40:51Z, TRACE, changepw.ChangePasswordServlet, {N1ZJM,test.user} returning result for restCheckProgress: {"error":false,"errorCode":0,"data":{"complete":false,"percentComplete":70.25,"messages":[{"key":"replication","label":"Password replication (progress 100%)","percentComplete":100,"complete":true,"show":false}],"elapsedSeconds":"10 seconds","estimatedRemainingSeconds":"4.5 seconds"}} [x.x.x.x]

2021-04-05T19:40:51Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTHENTICATED","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:51Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":8,"lf":[]} [x.x.x.x]

2021-04-05T19:40:51Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword completed requestID=1606 in 2ms [x.x.x.x]

preventCache='1617651651514'

processAction='checkProgress'

2021-04-05T19:40:54Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword requestID=1607 [x.x.x.x]

preventCache='1617651654566'

processAction='checkProgress'

2021-04-05T19:40:54Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} skipping replica sync check, replica sync completed previously [x.x.x.x]

2021-04-05T19:40:54Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} percent complete: 100.00 [x.x.x.x]

2021-04-05T19:40:54Z, TRACE, changepw.ChangePasswordServlet, {N1ZJM,test.user} returning result for restCheckProgress: {"error":false,"errorCode":0,"data":{"complete":false,"percentComplete":90.59,"messages":[{"key":"replication","label":"Password replication (progress 100%)","percentComplete":100,"complete":true,"show":false}],"elapsedSeconds":"13 seconds","estimatedRemainingSeconds":"1.41 seconds"}} [x.x.x.x]

2021-04-05T19:40:54Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTHENTICATED","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:54Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":8,"lf":[]} [x.x.x.x]

2021-04-05T19:40:54Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword completed requestID=1607 in 2ms [x.x.x.x]

preventCache='1617651654566'

processAction='checkProgress'

2021-04-05T19:40:57Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword requestID=1608 [x.x.x.x]

preventCache='1617651657617'

processAction='checkProgress'

2021-04-05T19:40:57Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} skipping replica sync check, replica sync completed previously [x.x.x.x]

2021-04-05T19:40:57Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} percent complete: 100.00 [x.x.x.x]

2021-04-05T19:40:57Z, TRACE, changepw.ChangePasswordServlet, {N1ZJM,test.user} returning result for restCheckProgress: {"error":false,"errorCode":0,"data":{"complete":true,"percentComplete":100.00,"messages":[{"key":"replication","label":"Password replication (progress 100%)","percentComplete":100,"complete":true,"show":false}],"elapsedSeconds":"16 seconds","estimatedRemainingSeconds":"0 seconds"}} [x.x.x.x]

2021-04-05T19:40:57Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTHENTICATED","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:57Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":8,"lf":[]} [x.x.x.x]

2021-04-05T19:40:57Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/changepassword completed requestID=1608 in 2ms [x.x.x.x]

preventCache='1617651657617'

processAction='checkProgress'

2021-04-05T19:40:58Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/changepassword requestID=1609 [x.x.x.x]

processAction='complete'

2021-04-05T19:40:58Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} skipping replica sync check, replica sync completed previously [x.x.x.x]

2021-04-05T19:40:58Z, TRACE, ldap.PasswordChangeProgressChecker, {N1ZJM,test.user} percent complete: 100.00 [x.x.x.x]

2021-04-05T19:40:58Z, TRACE, changepw.ChangePasswordServlet, {N1ZJM,test.user} password sync process marked completed (17s) [x.x.x.x]

2021-04-05T19:40:58Z, TRACE, http.SessionManager, {N1ZJM,test.user} incremented request counter to 9 [x.x.x.x]

2021-04-05T19:40:58Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTHENTICATED","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:40:58Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":9,"lf":[]} [x.x.x.x]

2021-04-05T19:40:58Z, TRACE, http.PwmResponse, {N1ZJM,test.user} forwarding to /WEB-INF/jsp/success.jsp [x.x.x.x]

2021-04-05T19:40:58Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @User:ID@ with value: test.user [x.x.x.x]

2021-04-05T19:40:58Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/changepassword completed requestID=1609 in 4ms [x.x.x.x]

processAction='complete'

2021-04-05T19:40:58Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/api requestID=1610 [x.x.x.x]

processAction='clientData'

etag='60334171ec7c136c1980f42423b195736875e0ed'

pageUrl='https://pwm.com/pwm/public/changepassword?processAction=complete&pwmFormID=H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakIL_XO14v2eJoOwH5Aat-L4mehM_TniLQ1sy72DGwV77Nxmof27JFJrc9vL3F6UdANdIeBg3tX4Xvi8fCYUNJ_XqURI9-X1mLl54yiWiABWzKDc0lhoRs8ICMYcI7MTVjpYgmWKDdNg2qTujHrf5ddFE-jQNXb3-SifKweNn62A-_W8hCOGYaaAAAA'

2021-04-05T19:40:58Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/api completed requestID=1610 in 3ms [x.x.x.x]

processAction='clientData'

etag='60334171ec7c136c1980f42423b195736875e0ed'

2021-04-05T19:41:00Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/command requestID=1611 [x.x.x.x]

processAction='next'

pwmFormID='H4sIAAAAAAAAAAGaAGX_UFdNLkdDTTEQywvAEkiwhu0reZOnlakIQE7EBB7BnWRRDwJnPe3dVt3jBe3dlaUnT6R6twgJRFTqlE3AGeqcf22KLigWz6bll1GeKerWnDg6s_ZWUi7ZmgiMcUzBrsFHGo0cN-DCxbipyShUh5hJy-P2cY294hEEolLkkt2LQVqimRJtxbzWXrhzujlPu_olYd-RuVGG0_eNYdynpBOaAAAA'

2021-04-05T19:41:00Z, DEBUG, filter.AuthenticationFilter, {N1ZJM,test.user} user is required to setup OTP configuration, redirecting to OTP setup page [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTHENTICATED","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:41:00Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":9,"lf":[]} [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, http.PwmResponse, {N1ZJM,test.user} sending 302 redirect to /pwm/private/setup-otp [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, http.PwmRequest, {N1ZJM,test.user} POST request for: /pwm/public/command completed requestID=1611 in 1ms [x.x.x.x]

processAction='next'

2021-04-05T19:41:00Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/private/setup-otp (no params) requestID=1612 [x.x.x.x]

2021-04-05T19:41:00Z, DEBUG, auth.HttpAuthenticationUtilities, {N1ZJM,test.user} wrote auth record cookie to user browser for use during forgotten password [x.x.x.x]

2021-04-05T19:41:00Z, DEBUG, state.CryptoCookieBeanImpl, {N1ZJM,test.user} ignoring existing existing b-3B0AB4CD cookie bean due to error: 5076 ERROR_CRYPT_ERROR (unexpected error performing simple decrypt operation: 5076 ERROR_CRYPT_ERROR (unexpected error performing simple decrypt operation: Tag mismatch!)) [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, otp.DbOtpOperator, Enter: readOtpUserConfiguration(CN=Test User,OU=Users,OU=domain,DC=domain,DC=com (default), d6b2eaeacca6384a9fe6e542d13a817c)

2021-04-05T19:41:00Z, TRACE, operations.OtpService, {N1ZJM,test.user} readOTPUserConfiguration completed in 4ms, no otp record found [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @User:Email@ with value: user...@domain.com [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @RandomChar:8:0123456789@ with value: 88040461 [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @RandomChar:8:0123456789@ with value: 02838559 [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @RandomChar:8:0123456789@ with value: 92423668 [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @RandomChar:8:0123456789@ with value: 92405256 [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @RandomChar:8:0123456789@ with value: 88524280 [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, operations.OtpService, {N1ZJM,test.user} hashing the recovery codes [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, servlet.SetupOtpServlet, {N1ZJM,test.user} generated new otp record [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, http.SessionManager, {N1ZJM,test.user} incremented request counter to 10 [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, http.PwmResponse, {N1ZJM,test.user} forwarding to /WEB-INF/jsp/setupotpsecret.jsp [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, macro.MacroMachine, {N1ZJM,test.user} replaced macro @User:ID@ with value: test.user [x.x.x.x]

2021-04-05T19:41:00Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/private/setup-otp (no params) completed requestID=1612 in 35ms [x.x.x.x]

2021-04-05T19:41:01Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/api requestID=1613 [x.x.x.x]

processAction='clientData'

etag='60334171ec7c136c1980f42423b195736875e0ed'

pageUrl='https://pwm.com/pwm/private/setup-otp'

2021-04-05T19:41:01Z, TRACE, state.CryptoCookieLoginImpl, {N1ZJM,test.user} wrote LoginInfoBean={"u":{"userDN":"CN=Test User,OU=Users,OU=domain,DC=domain,DC=com","ldapProfile":"default"},"a":true,"p":"*hidden*","t":"AUTHENTICATED","af":["AUTH_FROM_PUBLIC_MODULE"],"as":"USER_ACTIVATION","at":"2021-04-05T19:40:29Z","rq":"2021-04-05T19:41:01Z","g":"kn4zyflkbV2xT8ck3iEwPV9oTITssS6upagu9z6I7KNvYUUUUSuD6x040WQFfbelBganuov0","c":10,"lf":["authRecordSet"]} [x.x.x.x]

2021-04-05T19:41:01Z, TRACE, http.PwmRequest, {N1ZJM,test.user} GET request for: /pwm/public/api completed requestID=1613 in 3ms [x.x.x.x]

processAction='clientData'

etag='60334171ec7c136c1980f42423b195736875e0ed'

pageUrl='https://pwm.com/pwm/private/setup-otp'

2021-04-05T19:41:01Z, DEBUG, provider.WatchdogProviderHolder, disconnecting underlying connection: ldap idle timeout detected (PT30.206S), closing connection id=w283-785

2021-04-05T19:41:01Z, DEBUG, provider.WatchdogProviderHolder, disconnecting underlying connection: ldap idle timeout detected (PT30.424S), closing connection id=w284-771

Lee Wiscovitch

unread,

Apr 5, 2021, 3:51:02 PM4/5/21

to pwm-general

Also, if we do need to build the WAR from latest code on github.com, that will be drop-in compatible with the 1.9.1 that we're currently using?

Lee Wiscovitch

unread,

Apr 7, 2021, 2:10:26 PM4/7/21

to pwm-general

Been trying/testing the latest build from a WAR that I generated from the latest code on github repo. The WAR builds fine, but when I deploy it using the same method as 1.9.1 it doesn't start, nor does it give much useful information:

07-Apr-2021 18:03:51.615 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name: Apache Tomcat/9.0.43

07-Apr-2021 18:03:51.623 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built: Jan 28 2021 20:25:45 UTC

07-Apr-2021 18:03:51.623 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 9.0.43.0

07-Apr-2021 18:03:51.623 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name: Linux

07-Apr-2021 18:03:51.623 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version: 3.10.0-1160.21.1.el7.x86_64

07-Apr-2021 18:03:51.623 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture: amd64

07-Apr-2021 18:03:51.623 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home: /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.282.b08-1.el7_9.x86_64/jre

07-Apr-2021 18:03:51.624 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version: 1.8.0_282-b08

07-Apr-2021 18:03:51.624 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor: Red Hat, Inc.

07-Apr-2021 18:03:51.624 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE: /opt/apache-tomcat-9.0.43

07-Apr-2021 18:03:51.624 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME: /opt/apache-tomcat-9.0.43

07-Apr-2021 18:03:51.626 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/opt/tomcat/conf/logging.properties

07-Apr-2021 18:03:51.626 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager

07-Apr-2021 18:03:51.626 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.awt.headless=true

07-Apr-2021 18:03:51.626 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.library.path=/usr/local/apr/lib

07-Apr-2021 18:03:51.626 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048

07-Apr-2021 18:03:51.626 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources

07-Apr-2021 18:03:51.626 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027

07-Apr-2021 18:03:51.627 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xms512M

07-Apr-2021 18:03:51.627 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xmx1G

07-Apr-2021 18:03:51.627 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.net.preferIPv4Stack=true

07-Apr-2021 18:03:51.627 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dhttp.proxyHost=10.40.1.198

07-Apr-2021 18:03:51.627 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dhttp.proxyPort=3128

07-Apr-2021 18:03:51.627 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dhttps.proxyHost=10.40.1.198

07-Apr-2021 18:03:51.627 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dhttps.proxyPort=3128

07-Apr-2021 18:03:51.627 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=

07-Apr-2021 18:03:51.627 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/opt/tomcat

07-Apr-2021 18:03:51.627 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/opt/tomcat

07-Apr-2021 18:03:51.627 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/opt/tomcat/temp

07-Apr-2021 18:03:51.637 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded Apache Tomcat Native library [1.2.26] using APR version [1.4.8].

07-Apr-2021 18:03:51.637 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].

07-Apr-2021 18:03:51.638 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true]

07-Apr-2021 18:03:51.641 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized [OpenSSL 1.0.2k-fips 26 Jan 2017]

07-Apr-2021 18:03:52.366 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["https-openssl-nio-8443"]

07-Apr-2021 18:03:52.976 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [1768] milliseconds

07-Apr-2021 18:03:53.054 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]

07-Apr-2021 18:03:53.054 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.43]

07-Apr-2021 18:03:53.077 INFO [main] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying deployment descriptor [/opt/apache-tomcat-9.0.43/conf/Catalina/localhost/pwm.xml]

07-Apr-2021 18:03:58.201 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.

07-Apr-2021 18:03:58.246 SEVERE [main] org.apache.catalina.core.StandardContext.startInternal One or more listeners failed to start. Full details will be found in the appropriate container log file

07-Apr-2021 18:03:58.250 SEVERE [main] org.apache.catalina.core.StandardContext.startInternal Context [/pwm] startup failed due to previous errors

I then figured I would try the hosted WAR's, in case my build process was somehow at fault. I found that the latest two had the same behavior, but the one from 2020-11-07T03_09_58Z starts up. I'm not savvy enough to know what the differences are from that build to the latest, but it does start at least. Will try connecting it to our remote SQL database after some further investigation.

Jason Rivard

unread,

Apr 12, 2021, 4:34:31 PM4/12/21

to pwm-general

The latest code requires Java 11, looks like your using a 1.8 JVM. If you update the Java version the newest WARs should work.

Lee Wiscovitch

unread,

Apr 12, 2021, 5:21:31 PM4/12/21

to pwm-general

Oh nice, didn't realize wasn't pulling in the latest JVM...Will try that tomorrow and update this thread with results.

Reply all

Reply to author

Forward

0 new messages