search

aoktox / pwm

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

Successful login, then unable to connect to LDAP, but LDAP is reachable and proxy user is able to read account information #41

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
What steps will reproduce the problem?
1. Install a fresh PWM r111
2. Click any function that requires authentication
3. Log in with a valid, working account and correct password
4. An error message occurs, saying that login failed because the directory is 
unavailable.

What is the expected output? What do you see instead?

Expected: succesful login
Seen: "Directory unavailable. If this error occurs repeatedly please contact 
your helpdesk.

An error has occurred. Please close your browser and try again later. If this 
error occurs repeatedly, please contact your help desk."

What version of the product are you using? On what operating system?

SVN revision 111, on Tomcat 6, both on SLES 11P1 and Mac OS X 10.6.6

Please provide any additional information below.

Logs show a succesful login, but immediately show a failed connection to the 
same LDAP server:

2011-03-02 09:29:05, TRACE, pwm.SessionFilter, {0} POST request for: 
/pwm/private/Login [192.168.1.2/client.example.com]
  password=***removed***
  pwmFormID='9NW65LpMpRqFMOgwOmlQiihhf1K5kgPP7ab76bab12e75af1368'
  processAction='login'
  username='p.puk'
2011-03-02 09:29:05, TRACE, pwm.AuthenticationFilter, {0} permitting 
unauthenticated request of login page [192.168.1.2/client.example.com]
2011-03-02 09:29:05, TRACE, pwm.UserStatusHelper, {0} attempting username 
search for 'p.puk' in context dc=example,dc=com [192.168.1.2/client.example.com]
2011-03-02 09:29:05, TRACE, pwm.UserStatusHelper, {0} search for username: 
(&(objectClass=Person)(cn=p.puk)), searchDN: dc=example,dc=com 
[192.168.1.2/client.example.com]
2011-03-02 09:29:05, TRACE, pwm.ContextManager, opening new ldap proxy 
connection
2011-03-02 09:29:05, TRACE, pwm.Helper, creating new chai provider using config 
of ChaiConfiguration: locked=false settings: 
{chai.bind.URLs=ldaps://127.0.0.1:636,, 
chai.bind.dn=cn=pwmproxy,ou=users,o=data, chai.bind.password=**stripped**, 
chai.cache.enable=false, chai.cache.maximumSize=128, 
chai.cache.maximumAge=1000, chai.statistics.enable=true, 
chai.watchdog.enable=false, chai.watchdog.operationTimeout=60000, 
chai.watchdog.idleTimeout=30000, chai.connection.watchdog.frequency=5000, 
chai.connection.promiscuousSSL=true, 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.provider.implementation=com.novell.ldapchai.provider.JNDIProviderImpl, 
chai.edirectory.enableNMAS=true, 
chai.provider.extendedOperation.failureCache=true, 
chai.provider.readonly=false, 
chai.default.identityAttributes=cn,uid,givenName,initials,sn,mail,telephoneNumbe
r,workforceID, chai.vendor.default=}
2011-03-02 09:29:05, TRACE, provider.JNDIProviderImpl, bind successful as 
cn=pwmproxy,ou=users,o=data (51ms)
2011-03-02 09:29:05, TRACE, provider.ChaiProviderFactory, adding 
StatisticsWrapper to provider instance
2011-03-02 09:29:05, TRACE, pwm.UserStatusHelper, {0} username match found: 
cn=p.puk,ou=Students,ou=Users,dc=example,dc=com [192.168.1.2/client.example.com]
2011-03-02 09:29:05, TRACE, pwm.AuthenticationFilter, {0} attempting 
authentication using ldap BIND [192.168.1.2/client.example.com]
2011-03-02 09:29:05, TRACE, pwm.SessionManager, {0} opened new ldap connection 
for null (0ms) [192.168.1.2/client.example.com]
2011-03-02 09:29:05, TRACE, pwm.Helper, creating new chai provider using config 
of ChaiConfiguration: locked=false settings: 
{chai.bind.URLs=ldaps://127.0.0.1:636,, 
chai.bind.dn=cn=p.puk,ou=Students,ou=Users,dc=example,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=61202, 
chai.connection.watchdog.frequency=60000, chai.connection.promiscuousSSL=true, 
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.provider.implementation=com.novell.ldapchai.provider.JNDIProviderImpl, 
chai.edirectory.enableNMAS=true, 
chai.provider.extendedOperation.failureCache=true, 
chai.provider.readonly=false, 
chai.default.identityAttributes=cn,uid,givenName,initials,sn,mail,telephoneNumbe
r,workforceID, chai.vendor.default=}
2011-03-02 09:29:05, TRACE, provider.JNDIProviderImpl, bind successful as 
cn=p.puk,ou=Students,ou=Users,dc=example,dc=com (44ms)
2011-03-02 09:29:05, TRACE, provider.ChaiProviderFactory, adding 
WatchdogWrapper to provider instance
2011-03-02 09:29:05, DEBUG, provider.WatchdogWrapper, starting up LDAP Chai 
WatchdogWrapper timer thread, 60000ms check frequency
2011-03-02 09:29:05, TRACE, provider.ChaiProviderFactory, adding 
StatisticsWrapper to provider instance
2011-03-02 09:29:05, TRACE, entry.EdirEntries, using active universal password 
policy for user cn=p.puk,ou=Students,ou=Users,dc=example,dc=com at cn=Example 
Password Policy,cn=Password Policies,cn=Security
2011-03-02 09:29:05, DEBUG, pwm.PwmPasswordPolicy, {0} discovered assigned 
password policy for cn=p.puk,ou=Students,ou=Users,dc=example,dc=com at 
cn=Example Password Policy,cn=Password Policies,cn=Security PwmPasswordPolicy: 
{MaximumSpecial=0, PolicyEnabled=true, DisallowedValues=[], MaximumLength=32, 
MinimumNumeric=0, ChangeMessage=, MaximumLowerCase=0, 
AllowFirstCharNumeric=TRUE, MaximumNumeric=0, MaximumSequentialRepeat=0, 
CaseSensitive=TRUE, MinimumUpperCase=0, MinimumUnique=3, 
AllowLastCharSpecial=TRUE, AllowFirstCharSpecial=TRUE, AllowSpecial=TRUE, 
MaximumUpperCase=0, MinimumSpecial=0, AllowLastCharNumeric=TRUE, 
MinimumLength=6, MinimumLifetime=0, UniqueRequired=FALSE, 
DisallowedAttributes=[Full Name, Given Name, Surname, uniqueID, CN, 
displayName], MinimumLowerCase=0, ExpirationInterval=0, AllowNumeric=TRUE} 
[192.168.1.2/client.example.com]
2011-03-02 09:29:05, DEBUG, pwm.PwmPasswordPolicy, {0} merged password policy 
with PWM configured policy: PwmPasswordPolicy: {MaximumSpecial=0, 
PolicyEnabled=true, DisallowedValues=[secret, wachtwoord, password, geheim], 
RegExNoMatch=, MaximumAlpha=null, EnableWordlist=true, ChangeMessage=, 
CaseSensitive=true, MinimumUnique=3, AllowFirstCharSpecial=true, 
AllowSpecial=true, AllowLastCharNumeric=true, MinimumLength=6, 
MinimumNonAlpha=null, MinimumLifetime=0, MinimumLowerCase=0, 
DisallowedAttributes=[givenName, fullName, CN, Surname, sn, cn, uniqueID, Full 
Name, uniqueId, displayName, Given Name], MaximumLength=32, MinimumNumeric=0, 
RegExMatch=, MaximumNonAlpha=null, MaximumLowerCase=0, 
AllowFirstCharNumeric=true, MaximumNumeric=0, MinimumAlpha=null, 
MaximumSequentialRepeat=0, MinimumUpperCase=0, AllowLastCharSpecial=true, 
MinimumStrength=45, ADComplexity=false, MaximumUpperCase=0, MinimumSpecial=0, 
UniqueRequired=false, MaximumRepeat=null, ExpirationInterval=0, 
AllowNumeric=true} [192.168.1.2/client.example.com]
2011-03-02 09:29:05, TRACE, pwm.PwmPasswordPolicy, {0} createPwmPasswordPolicy 
completed in 23ms [192.168.1.2/client.example.com]
2011-03-02 09:29:05, DEBUG, pwm.CrUtility, {0} using nmas c/r policy for user 
cn=p.puk,ou=Students,ou=Users,dc=example,dc=com: ChallengeSet identifier: 
1298648483067, minRandom: 2, locale: en, (Challenge: [undefined], required: 
true, adminDefined: false, minLength: 2, maxLength: 255) (Challenge: "What was 
your childhood nickname?", required: false, adminDefined: true, minLength: 2, 
maxLength: 255) (Challenge: "Where were you when you had your first kiss?", 
required: false, adminDefined: true, minLength: 2, maxLength: 255) (Challenge: 
"Who was your childhood hero? ", required: false, adminDefined: true, 
minLength: 2, maxLength: 255) (Challenge: "What is the street number of the 
house you grew up in?", required: false, adminDefined: true, minLength: 1, 
maxLength: 255) (Challenge: "What was the first concert you attended?", 
required: false, adminDefined: true, minLength: 2, maxLength: 255) (Challenge: 
"What is the last name of your favorite high school teacher?", required: false, 
adminDefined: true, minLength: 2, maxLength: 255)  
[192.168.1.2/client.example.com]
2011-03-02 09:29:05, TRACE, pwm.CrUtility, {0} readUserChallengeSet completed 
in 11ms [192.168.1.2/client.example.com]
2011-03-02 09:29:05, TRACE, pwm.UserStatusHelper, {0,p.puk} beginning password 
status check process for cn=p.puk,ou=Students,ou=Users,dc=example,dc=com 
[192.168.1.2/client.example.com]
2011-03-02 09:29:05, TRACE, pwm.UserStatusHelper, {0,p.puk} password for 
cn=p.puk,ou=Students,ou=Users,dc=example,dc=com does not appear to be expired 
[192.168.1.2/client.example.com]
2011-03-02 09:29:05, DEBUG, pwm.UserStatusHelper, {0,p.puk} completed user 
password status check for cn=p.puk,ou=Students,ou=Users,dc=example,dc=com 
PasswordStatus {expired=false, pre-expired=false, warn=false, 
violatesPolicy=false} (3ms) [192.168.1.2/client.example.com]
2011-03-02 09:29:05, TRACE, pwm.UserStatusHelper, {0,p.puk} beginning check to 
determine if responses need to be configured for user 
[192.168.1.2/client.example.com]
2011-03-02 09:29:05, DEBUG, pwm.UserStatusHelper, {0,p.puk} 
checkIfResponseConfigNeeded: cn=p.puk,ou=Students,ou=Users,dc=example,dc=com is 
not eligible for checkIfResponseConfigNeeded due to query match 
[192.168.1.2/client.example.com]
2011-03-02 09:29:05, TRACE, pwm.UserStatusHelper, {0,p.puk} 
populateUserInfoBean for cn=p.puk,ou=Students,ou=Users,dc=example,dc=com 
completed in 68ms [192.168.1.2/client.example.com]
2011-03-02 09:29:05, INFO , pwm.AuthenticationFilter, {0,p.puk} successful ssl 
authentication for cn=p.puk,ou=Students,ou=Users,dc=example,dc=com (210ms) 
[192.168.1.2/client.example.com]
2011-03-02 09:29:05, TRACE, pwm.Helper, {0,p.puk} assigning new GUID to user 
cn=p.puk,ou=Students,ou=Users,dc=example,dc=com [192.168.1.2/client.example.com]
2011-03-02 09:29:05, WARN , provider.FailOverWrapper, unable to reach ldap 
server ldaps://127.0.0.1:636
2011-03-02 09:29:07, TRACE, provider.JNDIProviderImpl, bind successful as 
cn=pwmproxy,ou=users,o=data (43ms)
2011-03-02 09:29:07, WARN , provider.FailOverWrapper, unable to reach ldap 
server ldaps://127.0.0.1:636
2011-03-02 09:29:08, TRACE, provider.JNDIProviderImpl, bind successful as 
cn=pwmproxy,ou=users,o=data (44ms)
2011-03-02 09:29:08, WARN , provider.FailOverWrapper, unable to reach ldap 
server ldaps://127.0.0.1:636
2011-03-02 09:29:09, TRACE, provider.JNDIProviderImpl, bind successful as 
cn=pwmproxy,ou=users,o=data (50ms)
2011-03-02 09:29:09, WARN , provider.FailOverWrapper, unable to reach ldap 
server ldaps://127.0.0.1:636
2011-03-02 09:29:10, TRACE, provider.JNDIProviderImpl, bind successful as 
cn=pwmproxy,ou=users,o=data (39ms)
2011-03-02 09:29:10, FATAL, servlet.TopServlet, {0,p.puk} unable to contact 
ldap directory: unable to reach any configured server, maximum retries exceeded 
[192.168.1.2/client.example.com]
2011-03-02 09:29:10, DEBUG, pwm.SessionManager, {0} closing user ldap 
connection [192.168.1.2/client.example.com]
2011-03-02 09:29:10, DEBUG, provider.WatchdogWrapper, exiting LDAP Chai 
WatchdogWrapper timer thread, no connections requiring monitoring are in use
2011-03-02 09:29:10, DEBUG, pwm.PwmSession, {0} unauthenticate session from 
192.168.1.2 (cn=p.puk,ou=Students,ou=Users,dc=example,dc=com) 
[192.168.1.2/client.example.com]

[note: hostnames/IPs, DN's changed in above log dump]
[b.t.w. it worked fine in previous versions]

Original issue reported on code.google.com by menno.pi...@gmail.com on 2 Mar 2011 at 8:40

GoogleCodeExporter commented 9 years ago 
The problem seems to exist even in revision 108, which worked before... It may 
be a problem on my side. To be continued...

Original comment by menno.pi...@gmail.com on 2 Mar 2011 at 4:50

GoogleCodeExporter commented 9 years ago 
Just went back to PWM v1.5.3 devbuild b1007. That one works fine.

Original comment by menno.pi...@gmail.com on 2 Mar 2011 at 7:19

GoogleCodeExporter commented 9 years ago 
SOLVED: I hadn't noticed the new pwmGUID attribute... in edirectory-schema.ldif.

After disabling the Chai failover, I got a new error message (LDAP: error code 
17 - Undefined Attribute Type). 

Disabling the setting for automagically adding the GUID made the system work 
again. Now I'll add the attribute to the schema.

Original comment by menno.pi...@gmail.com on 3 Mar 2011 at 11:18

GoogleCodeExporter commented 9 years ago 
SVN version 112 has a fix for ldapChai that resolves this issue.  The ldapChai 
bug caused it to incorrectly think the undefined schema error was a comm error 
or some other re-tryable error.  The updated chai error handler does not try to 
retry the connection on schema errors.   Thus, if the schema for pwmGUID (or 
other schema) is missing, pwm will fail gracefully instead of throwing 
directory unavailable errors.

Original comment by jrivard on 4 Mar 2011 at 11:20