search

gandres / pwm

Automatically exported from code.google.com/p/pwm
0 stars 0 forks source link

Change Password Wait screen shows error #440

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
What steps will reproduce the problem?
1. Login to PWM
2. Change your password
3. Notice the error on the wait screen:

Unable to read app-data from server, please reload page (RequestError: Unable 
to load 
/account/public/rest/app-data?pwmFormID=stBmrZwXLmI2mjWylA8ccerg25ow9F711405d362
2cf4o6nrp status: 0)

This issue has been introduced in Revision 582 (probably changes in 
RestAppDataServer.java)

Original issue reported on code.google.com by sebastia...@gmail.com on 8 Aug 2013 at 12:24

GoogleCodeExporter commented 9 years ago 
Unable to reproduce, what browser are you seeing this on?  Have you cleared 
caches, tomcat work directory, etc?  Can you share logs?

Original comment by jrivard on 8 Aug 2013 at 6:43

GoogleCodeExporter commented 9 years ago 
How I tested:

- Using both Browser Firefox 23.0 on Mac OSX and Firefox 22.0 on Linux Mint
- clean build of pwm trunk
- cleared Tomcat Cache and working directory
- cleared browser cache

I think this is a Javascript issue, because server side everything seems fine 
(catalina.out, anonymized):

2013-08-09 08:22:14, DEBUG, servlet.ChangePasswordServlet, {0,testaccount} 
current password is too young, but skipping enforcement of minimum lifetime 
check because current password is expired [123.456.789.123]
2013-08-09 08:22:14, TRACE, util.CustomPasswordRuleValidator, Processing 
samAccountName: testaccount
2013-08-09 08:22:14, TRACE, util.CustomPasswordRuleValidator, Processing 
displayName: T. Tester
2013-08-09 08:22:14, TRACE, util.CustomPasswordRuleValidator, Comparing token 
veldhuisen with password
2013-08-09 08:22:14, DEBUG, util.PwmPasswordRuleValidator, externalRuleMethod 
'password.pwm.util.CustomPasswordRuleValidator' returned no values
2013-08-09 08:22:14, TRACE, util.PwmPasswordRuleValidator, calling chai 
directory password validation checker
2013-08-09 08:22:14, TRACE, servlet.ChangePasswordServlet, {0,testaccount} 
wrote password to changePasswordBean [123.456.789.123]
2013-08-09 08:22:14, TRACE, util.MacroMachine, replaced Macro @User:ID@ with 
value: testaccount
2013-08-09 08:22:14, DEBUG, servlet.ChangePasswordServlet, {0,testaccount} 
current password is too young, but skipping enforcement of minimum lifetime 
check because current password is expired [123.456.789.123]
2013-08-09 08:22:14, TRACE, servlet.ChangePasswordServlet, {0,testaccount} 
retrieved password from server session [123.456.789.123]
2013-08-09 08:22:14, TRACE, util.CustomPasswordRuleValidator, Processing 
samAccountName: testaccount
2013-08-09 08:22:14, TRACE, util.CustomPasswordRuleValidator, Processing 
displayName: T. Tester
2013-08-09 08:22:14, TRACE, util.CustomPasswordRuleValidator, Comparing token 
veldhuisen with password
2013-08-09 08:22:14, DEBUG, util.PwmPasswordRuleValidator, externalRuleMethod 
'password.pwm.util.CustomPasswordRuleValidator' returned no values
2013-08-09 08:22:14, TRACE, util.PwmPasswordRuleValidator, calling chai 
directory password validation checker
2013-08-09 08:22:14, INFO , operations.PasswordUtility, {0,testaccount} user 
'cn=test123,ou=users,o=meta' successfully changed password [123.456.789.123]
2013-08-09 08:22:14, DEBUG, pwm.SessionManager, {0,testaccount} closing user 
ldap connection [123.456.789.123]
2013-08-09 08:22:14, TRACE, pwm.SessionManager, {0,testaccount} attempting to 
open new ldap connection for cn=test123,ou=users,o=meta [123.456.789.123]
2013-08-09 08:22:14, TRACE, util.Helper, creating new chai provider using 
config of ChaiConfiguration: locked=false settings: 
{chai.bind.URLs=ldaps://ldap1.example.com:636,ldaps://ldap2.example.com:636,, 
chai.bind.dn=cn=test123,ou=users,o=meta, 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.disableIfPwExpired=true, 
chai.connection.watchdog.frequency=60000, chai.connection.promiscuousSSL=false, 
chai.wireDebug.enable=false, chai.failover.enable=true, 
chai.failover.failBackTime=90000, chai.failover.connectRetries=4, 
chai.ldap.dereferenceAliases=never, chai.ldap.ldapTimeout=5000, 
chai.ldap.followReferrals=false, 
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=true, chai.crsetting.caseInsensitive=true, 
chai.crsetting.allowDuplicateResponses=false, 
chai.crsetting.defaultFormatType=SHA1_SALT, 
chai.cr.chai.attributeName=AuxaccountResponseSet, chai.cr.chai.recordId=0002, 
chai.cr.chai.saltCount=100000}
2013-08-09 08:22:14, TRACE, provider.JNDIProviderImpl, bind successful as 
cn=test123,ou=users,o=meta (115ms)
2013-08-09 08:22:14, TRACE, provider.ChaiProviderFactory, adding 
WatchdogWrapper to provider instance
2013-08-09 08:22:14, TRACE, provider.WatchdogWrapper, checking for user 
password expiration to adjust watchdog timeout
2013-08-09 08:22:14, TRACE, provider.ChaiProviderFactory, adding 
StatisticsWrapper to provider instance
2013-08-09 08:22:14, TRACE, operations.UserStatusHelper, {0,testaccount} 
beginning password status check process for cn=test123,ou=users,o=meta 
[123.456.789.123]
2013-08-09 08:22:14, TRACE, operations.UserStatusHelper, {0,testaccount} 
password for cn=test123,ou=users,o=meta does not appear to be expired 
[123.456.789.123]
2013-08-09 08:22:14, TRACE, operations.UserStatusHelper, 
ldapPasswordExpirationTime (cn=test123,ou=users,o=meta): Fri Feb 07 07:22:14 
CET 2014 (1391754134726 ms)
2013-08-09 08:22:14, DEBUG, operations.UserStatusHelper, {0,testaccount} 
completed user password status check for cn=test123,ou=users,o=meta 
PasswordStatus {expired=false, pre-expired=false, warn=false, 
violatesPolicy=false} (8ms) [123.456.789.123]
2013-08-09 08:22:14, TRACE, util.Helper, externalJudgeMethod 
'password.pwm.PwmPasswordJudge' returned a value of 72
2013-08-09 08:22:14, DEBUG, servlet.ActivateUserServlet, {0,testaccount} 
executing post-activate configured actions to user cn=test123,ou=users,o=meta 
[123.456.789.123]
2013-08-09 08:22:14, TRACE, util.MacroMachine, replaced Macro @User:ID@ with 
value: testaccount
2013-08-09 08:22:14, INFO , util.Helper, set attribute on user 
cn=test123,ou=users,o=meta (AuxaccountState=pwm-activated)
2013-08-09 08:22:14, INFO , operations.ActionExecutor, {0,testaccount} action 
AuxaccountState completed successfully upon user testaccount [123.456.789.123]
2013-08-09 08:22:14, DEBUG, operations.PasswordUtility, {0,testaccount} 
executing configured actions to user cn=test123,ou=users,o=meta 
[123.456.789.123]
2013-08-09 08:22:14, TRACE, util.MacroMachine, replaced Macro @User:ID@ with 
value: testaccount
2013-08-09 08:22:14, TRACE, util.MacroMachine, replaced Macro @User:ID@ with 
value: testaccount
2013-08-09 08:22:14, TRACE, util.MacroMachine, replaced Macro @User:ID@ with 
value: testaccount
2013-08-09 08:22:14, TRACE, util.MacroMachine, replaced Macro @User:ID@ with 
value: testaccount
2013-08-09 08:22:14, INFO , util.Helper, set attribute on user 
cn=test123,ou=users,o=meta (AuxaccountState=pwm-completed)
2013-08-09 08:22:14, INFO , operations.ActionExecutor, {0,testaccount} action 
AuxaccountState completed successfully upon user testaccount [123.456.789.123]
2013-08-09 08:22:14, TRACE, util.MacroMachine, replaced Macro @User:Password@ 
with value: cknol2edge6ZU
2013-08-09 08:22:14, INFO , util.Helper, set attribute on user 
cn=test123,ou=users,o=meta (AuxuserPassword=test1234)
2013-08-09 08:22:14, INFO , operations.ActionExecutor, {0,testaccount} action 
AuxuserPassword completed successfully upon user testaccount [123.456.789.123]
2013-08-09 08:22:14, TRACE, util.MacroMachine, replaced Macro @LDAP:Auxuser@ 
with value: testaccount
2013-08-09 08:22:14, DEBUG, operations.ActionExecutor, sending HTTP request: 
https://logger.example.com/xmlrpc/server.php
2013-08-09 08:22:15, DEBUG, operations.ActionExecutor, response from http rest 
request: HTTP/1.1 200 OK
2013-08-09 08:22:15, TRACE, operations.ActionExecutor, response body from http 
rest request: <?xml version="1.0"?>
<methodResponse>
<params>
<param>
<value><struct>
<member><name>text</name>
<value><string>log record toegevoegd</string></value>
</member>
</struct></value>
</param>
</params>
</methodResponse>
2013-08-09 08:22:15, INFO , operations.ActionExecutor, {0,testaccount} action 
XMLrpc to Logger completed successfully upon user testaccount [123.456.789.123]
2013-08-09 08:22:15, DEBUG, operations.UserStatusHelper, {0,testaccount} wrote 
pwdLastModified update attribute for cn=test123,ou=users,o=meta 
[123.456.789.123]
2013-08-09 08:22:15, TRACE, operations.PasswordUtility, {0,testaccount} 
beginning password replication checking [123.456.789.123]
2013-08-09 08:22:16, TRACE, util.ChaiUtility, testAttributeReplication, will 
test the following ldap urls: [ldaps://ldap1.example.com:636]
2013-08-09 08:22:16, TRACE, provider.JNDIProviderImpl, bind successful as 
cn=pwm_proxy,ou=acl,o=meta (57ms)
2013-08-09 08:22:16, TRACE, provider.ChaiProviderFactory, adding 
WatchdogWrapper to provider instance
2013-08-09 08:22:16, TRACE, provider.WatchdogWrapper, checking for user 
password expiration to adjust watchdog timeout
2013-08-09 08:22:16, TRACE, provider.ChaiProviderFactory, adding 
StatisticsWrapper to provider instance
2013-08-09 08:22:16, DEBUG, util.ChaiUtility, testAttributeReplication for 
EntryDN: cn=test123,ou=users,o=meta:AuxaccountLastPwdUpdate 1 up, 0 down, 1 in 
sync
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @SiteHost@ with 
value: nam.example.com
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro 
@LDAP:AuxdisplayName@ with value: Dhr Drs. T. Tester
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @LDAP:Auxuser@ 
with value: testaccount
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @LDAP:Auxmail@ 
with value: test@example.com
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @LDAP:Auxmail4@ 
with value: test@gmail.com
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro 
@LDAP:AuxsmsNumber@ with value: +31612345678
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @SiteURL@ with 
value: https://nam.example.com/account
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro 
@LDAP:AuxdisplayName@ with value: Dhr Drs. T. Tester
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @LDAP:Auxuser@ 
with value: testaccount
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @LDAP:Auxmail@ 
with value: test@example.com
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @LDAP:Auxmail4@ 
with value: test@gmail.com
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro 
@LDAP:AuxsmsNumber@ with value: +31612345678
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @SiteURL@ with 
value: https://nam.example.com/account
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @SiteURL@ with 
value: https://nam.example.com/account
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @SiteURL@ with 
value: https://nam.example.com/account
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @SiteURL@ with 
value: https://nam.example.com/account
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @SiteURL@ with 
value: https://nam.example.com/account
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @SiteURL@ with 
value: https://nam.example.com/account
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @SiteURL@ with 
value: https://nam.example.com/account
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @SiteURL@ with 
value: https://nam.example.com/account
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @SiteURL@ with 
value: https://nam.example.com/account
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @SiteURL@ with 
value: https://nam.example.com/account
2013-08-09 08:22:18, INFO , event.AuditManager, audit event: 
{"eventCode":"CHANGE_PASSWORD","perpetratorID":"testaccount","perpetratorDN":"cn
\u003dtest123,ou\u003dusers,o\u003dmeta","timestamp":"Aug 9, 2013 8:22:18 
AM","targetID":"testaccount","targetDN":"cn\u003dtest123,ou\u003dusers,o\u003dme
ta","sourceAddress":"123.456.789.123","sourceHost":"123.456.789.123"}
2013-08-09 08:22:18, TRACE, util.MacroMachine, replaced Macro @User:ID@ with 
value: testaccount
2013-08-09 08:22:18, DEBUG, server.RestServerHelper, {0,testaccount} REST 
WebService Request: GET request for: /account/public/rest/app-data  
[123.456.789.123]
  pwmFormID='piwXHMDN1G28HYlg6VUGQA9bmzeqvHP014061bb66abxy6ddk'
2013-08-09 08:22:18, DEBUG, queue.EmailQueueManager, successfully sent 
authenticated email: from: Test Company <noreply@nam.example.com>, to: 
test@gmail.com, subject: [TEST] Your password has been changed
2013-08-09 08:22:21, TRACE, pwm.SessionFilter, {0,testaccount} POST request 
for: /account/public/CommandServlet  [123.456.789.123]
  processAction='continue'
2013-08-09 08:22:21, TRACE, servlet.CommandServlet, {0,testaccount} received 
request for action continue [123.456.789.123]
2013-08-09 08:22:21, TRACE, servlet.CommandServlet, {0,testaccount} logging out 
user; password has been modified [123.456.789.123]
2013-08-09 08:22:21, TRACE, pwm.SessionFilter, {0,testaccount} GET request for: 
/account/public/Logout (no params)  [123.456.789.123]
2013-08-09 08:22:21, DEBUG, servlet.LogoutServlet, {0,testaccount} processing 
logout request from user [123.456.789.123]
2013-08-09 08:22:21, DEBUG, pwm.SessionManager, {0} closing user ldap 
connection [123.456.789.123]
2013-08-09 08:22:21, DEBUG, pwm.PwmSession, {0} unauthenticate session from 
123.456.789.123 (cn=test123,ou=users,o=meta) [123.456.789.123]
2013-08-09 08:22:21, TRACE, servlet.LogoutServlet, {0} redirecting user to 
configured logout url:https://nam.example.com/nesp/jsp/logout.jsp 
[123.456.789.123]
2013-08-09 08:22:21, DEBUG, pwm.PwmSession, {0} invalidating PwmSession 
[123.456.789.123]
2013-08-09 08:22:21, TRACE, pwm.HttpEventManager, {0} http session destroyed 
[123.456.789.123]

On the client-side (Firebug) I see that the XHR request to the Rest App Data 
Server has no remote IP while the password is being changed *and therefore no 
response is availablem which probaby results in the error). After the password 
change the XHR request has a remote IP. I suspect some kind of timing issue.

Original comment by sebastia...@gmail.com on 9 Aug 2013 at 8:01

GoogleCodeExporter commented 9 years ago 
Did some further testing with Google Chrome 28.0.1500.95 and could not 
reproduce it. With Chrome I only see one XHR request to RestAppData with a 
remote IP. So it looks like a specific brwoser issue (at least Firefox).

Original comment by sebastia...@gmail.com on 9 Aug 2013 at 8:13

GoogleCodeExporter commented 9 years ago 
So this must be some type of timing issue, I can't reproduce it at all.  I'm 
just going to get rid of the error message to screen (it's still written to 
browser console log) as it's not useful anyway.  

The change-wait screen meta-redirect is probably the root cause.  

Error message output removed in revision 585.

Original comment by jrivard on 10 Aug 2013 at 3:19