1 (edited by tedcox 2013-01-31 06:53:24)

Topic: [Solved] Changing LDAP Passwords

==== Required information ====
- iRedMail version: 0.8.3
- Store mail accounts in  backend (LDAP):
- Linux/BSD distribution name and version: CentOS 6.3
====

Hello Zhang,

Thanks again for the wonderful product.  I'm trying to setup a backup mail server, but am running into problems with the LDAP piece.  I have imported my LDIF backup as described in the wiki (http://www.iredmail.org/wiki/index.php? … _LDIF_file), but when I try to update the passwords for vmail and vmail admin in phpldapadmin, I get:

Could not perform ldap_modify operation.
LDAP said: Server is unwilling to perform
Error number: 0x35 (LDAP_UNWILLING_TO_PERFORM)
Description: The LDAP server refused to perform the operation.

Not wanting to throw in the towel, I tried changing the password at the command line:

ldappasswd -s <vmailPasswd> -D "cn=Manager,dc=mydomain,dc=com" \
-w <ManagerPasswd> -x cn=vmail,dc=mydomain,dc=com

This returns:

Result: Server is unwilling to perform (53)
Additional info: shadow context; no update referral

I have tried looking in /var/log/openldap.log for additional information, but it is empty, even after changing log level to -1 in slapd.conf and restarting the service.

However, the service is running:

# service slapd status
slapd (pid  14275) is running...

And there are no issues with connecting to phpldapadmin and viewing the imported data.  I simply can't login to any user accounts.  (Presumably because the vmail password is incorrect)

Here's a snippet of the /var/log/maillog file during a connection attempt:

Jan 30 11:12:44 ruthie postfix/proxymap[13349]: warning: dict_ldap_lookup: Search error 50: Insufficient access 
Jan 30 11:12:44 ruthie postfix/proxymap[13349]: warning: dict_ldap_lookup: Search error 50: Insufficient access 
Jan 30 11:12:44 ruthie postfix/proxymap[13349]: warning: dict_ldap_lookup: Search error 50: Insufficient access 
Jan 30 11:12:44 ruthie postfix/trivial-rewrite[14606]: fatal: proxy:ldap:/etc/postfix/ldap/virtual_mailbox_domains.cf(0,lock|fold_fix): table lookup problem
Jan 30 11:12:45 ruthie postfix/qmgr[14469]: warning: problem talking to service rewrite: Success
Jan 30 11:12:45 ruthie postfix/master[13307]: warning: process /usr/libexec/postfix/trivial-rewrite pid 14606 exit status 1
Jan 30 11:12:45 ruthie postfix/master[13307]: warning: /usr/libexec/postfix/trivial-rewrite: bad command startup -- throttling
Jan 30 11:13:25 ruthie roundcube: IMAP Error: Login failed for ted@heroesinc.us from 75.70.227.211. LOGIN: Temporary authentication failure. in /var/www/roundcubemail-0.8.2/program/include/rcube_imap.php on line 191 (POST /mail/?_task=login&_action=login)

Obviously nothing works so long as I can't update these passwords.  Any idea what I'm doing wrong?

Thanks!
Ted

2

Re: [Solved] Changing LDAP Passwords

Okay, I figured out the logging problem.  So LDAP is showing logs now.  Here is the logs when I try to commit the password change:

Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on 1 descriptor
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on:
Jan 30 13:04:51 myserver slapd[16377]: 
Jan 30 13:04:51 myserver slapd[16377]: slap_listener_activate(7): 
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=7 busy
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: >>> slap_listener(ldap:///)
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: listen=7, new connection on 15
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on 1 descriptor
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on:
Jan 30 13:04:51 myserver slapd[16377]: 
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=7 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on 1 descriptor
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on:
Jan 30 13:04:51 myserver slapd[16377]:  15r
Jan 30 13:04:51 myserver slapd[16377]: 
Jan 30 13:04:51 myserver slapd[16377]: daemon: read active on 15
Jan 30 13:04:51 myserver slapd[16377]: daemon: added 15r (active) listener=(nil)
Jan 30 13:04:51 myserver slapd[16377]: conn=1019 fd=15 ACCEPT from IP=127.0.0.1:37221 (IP=0.0.0.0:389)
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=7 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on 1 descriptor
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on:
Jan 30 13:04:51 myserver slapd[16377]: 
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=7 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: connection_get(15)
Jan 30 13:04:51 myserver slapd[16377]: connection_get(15): got connid=1019
Jan 30 13:04:51 myserver slapd[16377]: connection_read(15): checking for input on id=1019
Jan 30 13:04:51 myserver slapd[16377]: op tag 0x60, time 1359576291
Jan 30 13:04:51 myserver slapd[16377]: conn=1019 op=0 do_bind
Jan 30 13:04:51 myserver slapd[16377]: >>> dnPrettyNormal: <cn=Manager,dc=mydomain,dc=com>
Jan 30 13:04:51 myserver slapd[16377]: <<< dnPrettyNormal: <cn=Manager,dc=mydomain,dc=com>, <cn=manager,dc=mydomain,dc=com>
Jan 30 13:04:51 myserver slapd[16377]: conn=1019 op=0 BIND dn="cn=Manager,dc=mydomain,dc=com" method=128
Jan 30 13:04:51 myserver slapd[16377]: do_bind: version=3 dn="cn=Manager,dc=mydomain,dc=com" method=128
Jan 30 13:04:51 myserver slapd[16377]: ==> bdb_bind: dn: cn=Manager,dc=mydomain,dc=com
Jan 30 13:04:51 myserver slapd[16377]: conn=1019 op=0 BIND dn="cn=Manager,dc=mydomain,dc=com" mech=SIMPLE ssf=0
Jan 30 13:04:51 myserver slapd[16377]: do_bind: v3 bind: "cn=Manager,dc=mydomain,dc=com" to "cn=Manager,dc=mydomain,dc=com"
Jan 30 13:04:51 myserver slapd[16377]: send_ldap_result: conn=1019 op=0 p=3
Jan 30 13:04:51 myserver slapd[16377]: send_ldap_result: err=0 matched="" text=""
Jan 30 13:04:51 myserver slapd[16377]: send_ldap_response: msgid=1 tag=97 err=0
Jan 30 13:04:51 myserver slapd[16377]: conn=1019 op=0 RESULT tag=97 err=0 text=
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on 1 descriptor
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on:
Jan 30 13:04:51 myserver slapd[16377]: 
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=7 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on 1 descriptor
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on:
Jan 30 13:04:51 myserver slapd[16377]:  15r
Jan 30 13:04:51 myserver slapd[16377]: 
Jan 30 13:04:51 myserver slapd[16377]: daemon: read active on 15
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=7 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: connection_get(15)
Jan 30 13:04:51 myserver slapd[16377]: connection_get(15): got connid=1019
Jan 30 13:04:51 myserver slapd[16377]: connection_read(15): checking for input on id=1019
Jan 30 13:04:51 myserver slapd[16377]: op tag 0x63, time 1359576291
Jan 30 13:04:51 myserver slapd[16377]: conn=1019 op=1 do_search
Jan 30 13:04:51 myserver slapd[16377]: >>> dnPrettyNormal: <cn=vmailadmin,dc=mydomain,dc=com>
Jan 30 13:04:51 myserver slapd[16377]: <<< dnPrettyNormal: <cn=vmailadmin,dc=mydomain,dc=com>, <cn=vmailadmin,dc=mydomain,dc=com>
Jan 30 13:04:51 myserver slapd[16377]: SRCH "cn=vmailadmin,dc=mydomain,dc=com" 0 0
Jan 30 13:04:51 myserver slapd[16377]:     0 0 0
Jan 30 13:04:51 myserver slapd[16377]: begin get_filter
Jan 30 13:04:51 myserver slapd[16377]: AND
Jan 30 13:04:51 myserver slapd[16377]: begin get_filter_list
Jan 30 13:04:51 myserver slapd[16377]: begin get_filter
Jan 30 13:04:51 myserver slapd[16377]: PRESENT
Jan 30 13:04:51 myserver slapd[16377]: end get_filter 0
Jan 30 13:04:51 myserver slapd[16377]: end get_filter_list
Jan 30 13:04:51 myserver slapd[16377]: end get_filter 0
Jan 30 13:04:51 myserver slapd[16377]:     filter: (&(objectClass=*))
Jan 30 13:04:51 myserver slapd[16377]:     attrs:
Jan 30 13:04:51 myserver slapd[16377]:  *
Jan 30 13:04:51 myserver slapd[16377]:  +
Jan 30 13:04:51 myserver slapd[16377]: 
Jan 30 13:04:51 myserver slapd[16377]: conn=1019 op=1 SRCH base="cn=vmailadmin,dc=mydomain,dc=com" scope=0 deref=0 filter="(&(objectClass=*))"
Jan 30 13:04:51 myserver slapd[16377]: conn=1019 op=1 SRCH attr=* +
Jan 30 13:04:51 myserver slapd[16377]: => bdb_search
Jan 30 13:04:51 myserver slapd[16377]: bdb_dn2entry("cn=vmailadmin,dc=mydomain,dc=com")
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: search access to "cn=vmailadmin,dc=mydomain,dc=com" "entry" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: search access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: base_candidates: base: "cn=vmailadmin,dc=mydomain,dc=com" (0x00000003)
Jan 30 13:04:51 myserver slapd[16377]: => test_filter
Jan 30 13:04:51 myserver slapd[16377]:     AND
Jan 30 13:04:51 myserver slapd[16377]: => test_filter_and
Jan 30 13:04:51 myserver slapd[16377]: => test_filter
Jan 30 13:04:51 myserver slapd[16377]:     PRESENT
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: search access to "cn=vmailadmin,dc=mydomain,dc=com" "objectClass" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: search access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: <= test_filter 6
Jan 30 13:04:51 myserver slapd[16377]: <= test_filter_and 6
Jan 30 13:04:51 myserver slapd[16377]: <= test_filter 6
Jan 30 13:04:51 myserver slapd[16377]: => send_search_entry: conn 1019 dn="cn=vmailadmin,dc=mydomain,dc=com"
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "entry" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (objectClass)
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on 1 descriptor
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on:
Jan 30 13:04:51 myserver slapd[16377]: 
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "objectClass" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=7 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result was in cache (objectClass)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result was in cache (objectClass)
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (cn)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "cn" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (sn)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "sn" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (uid)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "uid" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (userPassword)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "userPassword" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (structuralObjectClass)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "structuralObjectClass" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (entryUUID)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "entryUUID" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (creatorsName)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "creatorsName" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (createTimestamp)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "createTimestamp" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (entryCSN)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "entryCSN" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (modifiersName)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "modifiersName" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (modifyTimestamp)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "modifyTimestamp" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (entryDN)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "entryDN" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result was in cache (entryDN)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (subschemaSubentry)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "subschemaSubentry" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result was in cache (subschemaSubentry)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result not in cache (hasSubordinates)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access to "cn=vmailadmin,dc=mydomain,dc=com" "hasSubordinates" requested
Jan 30 13:04:51 myserver slapd[16377]: <= root access granted
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: read access granted by manage(=mwrscxd)
Jan 30 13:04:51 myserver slapd[16377]: => access_allowed: result was in cache (hasSubordinates)
Jan 30 13:04:51 myserver slapd[16377]: conn=1019 op=1 ENTRY dn="cn=vmailadmin,dc=mydomain,dc=com"
Jan 30 13:04:51 myserver slapd[16377]: <= send_search_entry: conn 1019 exit.
Jan 30 13:04:51 myserver slapd[16377]: send_ldap_result: conn=1019 op=1 p=3
Jan 30 13:04:51 myserver slapd[16377]: send_ldap_result: err=0 matched="" text=""
Jan 30 13:04:51 myserver slapd[16377]: send_ldap_response: msgid=2 tag=101 err=0
Jan 30 13:04:51 myserver slapd[16377]: conn=1019 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text=
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on 1 descriptor
Jan 30 13:04:51 myserver slapd[16377]: daemon: activity on:
Jan 30 13:04:51 myserver slapd[16377]:  15r

3

Re: [Solved] Changing LDAP Passwords

Okay!  I figured it out.  I had tried to setup replication earlier, but hadn't been able to make it work due to issues with the TLS certs.  I had to remove the sync directive.