Closed GoogleCodeExporter closed 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
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
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
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
Original issue reported on code.google.com by
sebastia...@gmail.com
on 8 Aug 2013 at 12:24