Index: dassldapsync/dassldapsync.py
===================================================================
--- dassldapsync/dassldapsync.py	(revision 1218)
+++ dassldapsync/dassldapsync.py	(revision 1219)
@@ -2,14 +2,24 @@
 # vim: tabstop=4 expandtab shiftwidth=4 softtabstop=4
 
+import argparse
+import ConfigParser
+import datetime
+import dateutil.parser
+import dateutil.tz
 import ldap
+import ldap.modlist
 import ldif
-import ldap.modlist
-import ConfigParser
+import logging
 import os
 import sys
 
-import dateutil.parser
-import dateutil.tz
-import datetime
+def getArguments():
+    configfile = '/etc/dassldapsync.conf'
+    parser = argparse.ArgumentParser(description='Synchronize the content of two LDAP servers.' )
+    parser.add_argument('-d', '--debug', action='store_true', help="enable debug output")
+    parser.add_argument('configfile', default=configfile, help="Configuration file [default: {}]".format(configfile))
+    args = parser.parse_args()
+    return args
+
 
 class Options:
@@ -18,24 +28,42 @@
         self.starttls=False
         self.updateonly=False
+        self.filter=None
         self.attrfilter=None
         self.exclude=None
         self.renameattr=None
         self.renamecommand=None
-        self.verbose=False
-
-def notify_created(dn):
-    print "notify_created",dn
-
-def notify_modified(dn):
-    print "notify_modified",dn
-
-def notify_deleted(dn):
-    print "notify_deleted",dn
-
-def notify_renamed(dn,newdn,uid,newuid,options):
-    print "notify_renamed",dn,newdn
-    subprocess.check_call("%s %s %s %s %s" % (options.renamecommand,dn,newdn,uid,newuid),shell=True)
+        self.pwd_max_days=0
+        
+class ConfigParserDefaults(ConfigParser.ConfigParser, object):
+    def get(self, section, option, default = None):
+        try:
+            result = super(self.__class__, self).get(section, option)
+        except ConfigParser.NoOptionError:
+            if default is None:
+                raise
+            else:
+                result = default
+        return result
+
+    def get0(self, section, option, default = None):
+        try:
+            result = super(self.__class__, self).get(section, option)
+        except ConfigParser.NoOptionError:
+            result = default
+        return result
+
+    def getboolean(self, section, option, default = None):
+        try:
+            result = super(self.__class__, self).getboolean(section, option)
+        except ConfigParser.NoOptionError:
+            if default is None:
+                raise
+            else:
+                result = default
+        return result
 
 def readLDIFSource(path):
+    logger = logging.getLogger()
+    logger.info("reading LDAP objects from file {}".format(path))
     with open(path,'r') as f:
         parser = ldif.LDIFRecordList(f)
@@ -44,164 +72,220 @@
     return result
 
-def readLdapSource(server,binddn,bindpw,basedn,filter,starttls=False):
+def readLdapSource(server,binddn,bindpw,basedn,filter,attrs=None,starttls=False):
+    logger = logging.getLogger()
+    logger.info("reading LDAP objects from server {}".format(server))
     con = ldap.open(server,port=389)
     if starttls:
     	con.start_tls_s()
     con.simple_bind_s(binddn,bindpw)
-    results=con.search_s(basedn,ldap.SCOPE_SUBTREE,filter,None)
+    results=con.search_s(basedn,ldap.SCOPE_SUBTREE,filter,attrs)
     return results
 
-def syncLdapDestination(searchresult,destserver,destbinddn,destbindpw,srcbasedn,destbasedn,destrdn,options=Options()):
-
-    attrmap=ldap.cidict.cidict({
+class LdapSync:
+    def __init__(self, destserver,destbinddn,destbindpw,srcbasedn,destbasedn,options=Options()):
+        self.logger = logging.getLogger()
+        
+        self.destserver = destserver
+        self.destbasedn = destbasedn
+        self.destbinddn = destbinddn
+        self.destbindpw = destbindpw
+        self.options = options
+        
+        self.srcbasedn = srcbasedn
+
+        self.con = None
+        
+        self.attrmap=ldap.cidict.cidict({
         })
-    classmap={ 
+        self.classmap={ 
         }
 
-    junk_attrs = [ "memberof", "modifiersname", "modifytimestamp", "entryuuid", "entrycsn", "contextcsn", "creatorsname", "createtimestamp", "structuralobjectclass", "pwdchangedtime", "pwdfailuretime" ]
-    update_objects=[]
-
-    if len(searchresult)==0:
-	print "empty source, aborting"
-	return
-
-    for r in searchresult:
-        dn=r[0]
-
-        d=ldap.cidict.cidict(r[1])
-        objectclasses=d["objectclass"]
-
-        newObjectclasses=[]
-        for o in objectclasses:
-            if o.lower() in classmap:
-                    new_oc = classmap[o.lower()]
-                    if not new_oc in newObjectclasses:
-                        newObjectclasses.append(new_oc)
+        self.junk_attrs = [ "memberof", "modifiersname", "modifytimestamp", "entryuuid", "entrycsn", "contextcsn", "creatorsname", "createtimestamp", "structuralobjectclass", "pwdchangedtime", "pwdfailuretime" ]
+
+    def __ldap_connect(self):
+        if self.con is None:
+            self.logger.info("connect to destination LDAP server {}".format(self.destserver))
+            self.con = ldap.open(self.destserver,port=389)
+            if self.options.starttls:
+                self.con.start_tls_s()
+            self.con.simple_bind_s(self.destbinddn,self.destbindpw)
+
+    def __adapt_dn(self, dn):
+        # move LDAP object to dest base
+        if self.srcbasedn != self.destbasedn:
+            dn_old = dn
+            rpath = dn[:-len(srcbasedn)]
+            dn=rpath+self.destbasedn
+            self.logger.debug("moved {} to {}".format(dn_old, dn))
+            # print "dn:",dn,"src:",srcbasedn,"rpath:",rpath,"dest:",destbasedn
+        return dn
+
+    def __is_dn_included(self, dn):
+        if self.options.exclude is None:
+            return True
+        if dn.lower().endswith(self.options.exclude):
+            return False
+        return True
+
+    def __adapt_source_ldap_objects(self, searchresult):
+        """
+        Do configured modification to the source LDAP objects.
+        """
+        self.logger.debug("modifying LDAP objects retrieved from source LDAP")
+
+        update_objects=[]
+        
+        for r in searchresult:
+            dn = self.__adapt_dn(r[0])
+            d=ldap.cidict.cidict(r[1])
+
+            if self.__is_dn_included(dn):
+                objectclasses=d["objectclass"]
+
+                newObjectclasses=[]
+                for o in objectclasses:
+                    if o.lower() in self.classmap:
+                            new_oc = self.classmap[o.lower()]
+                            if not new_oc in newObjectclasses:
+                                newObjectclasses.append(new_oc)
+                    else:
+                        #pass
+                        if not o in newObjectclasses:
+                            newObjectclasses.append(o)
+
+                d["objectclass"]=newObjectclasses
+
+                for a in d.keys():
+                    attr=a
+                    if self.attrmap.has_key(a.lower()):
+                        attr=self.attrmap[attr].lower()
+                        if attr.lower()!=a.lower():
+                            # print "# ",a," -> ",attr
+                            values=d[a]
+                            del d[a]
+                            d[attr]=values
+
+                update_objects.append((dn,d))
+        return update_objects
+
+
+    def __get_dest_entry(self, dn, entry):
+        """
+        In the destination LDAP, the objects should be named
+        according to options.renameattr.
+        """
+        existingDestDn = None
+        existingDestEntry = None
+        if self.options.renameattr and entry.has_key(self.options.renameattr):
+            searchresult = self.con.search_s(self.destbasedn,ldap.SCOPE_SUB,"%s=%s" % (self.options.renameattr,entry[self.options.renameattr][0]))
+            if searchresult != None and len(searchresult)>0:
+                existingDestDn, existingDestEntry = searchresult[0]
+                if existingDestDn.lower() != dn.lower():
+                    self.con.modrdn_s(existingDestDn,dn)
+                    notify_renamed(existingDestDn, dn, existingDestEntry[self.options.renameattr][0],entry[self.options.renameattr][0],options)
+        if existingDestDn is None:
+            searchresult=self.con.search_s(dn,ldap.SCOPE_BASE,"objectclass=*")
+            existingDestDn, existingDestEntry = searchresult[0]
+        return (existingDestDn, existingDestEntry)
+
+
+    def __handle_pwdAccountLockedTime(self, dn, entry, now, max_age):
+        # hack for syncing accounts locked by password policy
+        do_unlock = False
+        if self.options.pwd_max_days>0 and entry.has_key('pwdChangedTime'):
+            # print "pwdChangedTime set for",dn
+            pwdChange = entry['pwdChangedTime'][0]
+            d = dateutil.parser.parse(pwdChange)
+            if (now-d)>max_age:
+                entry['pwdAccountLockedTime']=['000001010000Z']
+                self.logger.info( "locking {} {}".format(dn, pwdChange))
             else:
-                #pass
-                if not o in newObjectclasses:
-                    newObjectclasses.append(o)
-
-        d["objectclass"]=newObjectclasses
-
-      	rpath = dn[:-len(srcbasedn)]
-	# print "dn:",dn,"src:",srcbasedn,"rpath:",rpath,"dest:",destbasedn
-
-        for a in d.keys():
-            attr=a
-            if attrmap.has_key(a.lower()):
-                attr=attrmap[attr].lower()
-                if attr.lower()!=a.lower():
-                    # print "# ",a," -> ",attr
-                    values=d[a]
-                    del d[a]
-                    d[attr]=values
-            else:
-                # del d[a]
-                continue
-
-        dn=rpath+destbasedn
-
-        update_objects.append((dn,d))
-
-    con = ldap.open(destserver,port=389)
-    if options.starttls:
-    	con.start_tls_s()
-    con.simple_bind_s(destbinddn,destbindpw)
-
-    exist=0
-    failed=0
-    good=0
-    deleted=0
-    existing=[]
-    tzutc = dateutil.tz.gettz('UTC')
-    now = datetime.datetime.now(tzutc)
-    max_age = datetime.timedelta(days=pwd_max_days)
-
-    for o in update_objects:
-        dn,entry=o
-        try:
-            result = None
-            if options.renameattr and entry.has_key(options.renameattr):
-                result = con.search_s(destbasedn,ldap.SCOPE_SUB,"%s=%s" % (options.renameattr,entry[options.renameattr][0]))
-                if result != None and len(result)>0:
-                    existingDn, existingEntry = result[0]
-                    if existingDn.lower() != dn.lower():
-                        con.modrdn_s(existingDn,dn)
-                        notify_renamed(existingDn,dn,existingEntry[options.renameattr][0],entry[options.renameattr][0],options)
-                        continue
-
-            result=con.search_s(dn,ldap.SCOPE_BASE,"objectclass=*")
-            destDn,destEntry=result[0]
-
-            if options.exclude!=None and destDn.lower().endswith(options.exclude):
-                continue
-
-            # hack for syncing accounts locked by password policy
-            do_unlock = False
-            if pwd_max_days>0 and entry.has_key('pwdChangedTime'):
-                # print "pwdChangedTime set for",dn
-                pwdChange = entry['pwdChangedTime'][0]
-               	d = dateutil.parser.parse(pwdChange)
-                if (now-d)>max_age:
-                    if dn.startswith('cn=haydar aldetest'):
-        	        entry['pwdAccountLockedTime']=[ '000001010000Z' ]
-                        print "locking",dn,pwdChange
-                else:
-                    result = con.search_s(dn,ldap.SCOPE_BASE,"objectclass=*", \
-                       attrlist = [ 'pwdAccountLockedTime' ])
-                    tmp_dn, tmp_entry = result[0]
-                    if tmp_entry.has_key('pwdAccountLockedTime'):
-                        print "unlocking",dn,pwdChange
-                        do_unlock = True	
- 
-            mod_attrs=ldap.modlist.modifyModlist(destEntry,entry)
-
-            # hack for unlocking, see above
-            if do_unlock:
-                mod_attrs.append( (ldap.MOD_DELETE,'pwdAccountLockedTime',None) )
-
-            if options.attrfilter!=None:
-                mod_attrs=[ a for a in mod_attrs if a[1] in options.attrfilter]
-
-            if junk_attrs!=None:
-                mod_attrs=[ a for a in mod_attrs if a[1].lower() not in junk_attrs]
-
-	    if mod_attrs!=[]:
-            	exist=exist+1
-            	#if options.verbose:
-                #	print dn, "already exists"
-		try:
-			# print dn,destEntry['objectClass'],entry['objectClass']
-	    		con.modify_s(dn,mod_attrs)
-		except:
-			print "error",dn,mod_attrs
-		notify_modified(dn)
-            else:
-                pass
-                # print "no changes, not modified"
-
-        except ldap.NO_SUCH_OBJECT:
-            if options.updateonly==True:
-                continue
-
+                # pwdAccountLockedTime is a operational attribute,
+                # and therefore not part of entry.
+                # Do extra search to retrieve attribute.
+                searchresult = self.con.search_s(dn,ldap.SCOPE_BASE,"objectclass=*", \
+                attrlist = ['pwdAccountLockedTime'])
+                tmp_dn, tmp_entry = searchresult[0]
+                if tmp_entry.has_key('pwdAccountLockedTime'):
+                    do_unlock = True
+        return do_unlock
+
+
+
+    def __syncLdapDestination(self, update_objects):
+        
+        result = {
+            'add': { 'ok': [], 'failed': [] },
+            'update': { 'ok': [], 'failed': [] },
+        }
+
+        tzutc = dateutil.tz.gettz('UTC')
+        now = datetime.datetime.now(tzutc)
+        max_age = datetime.timedelta(days=self.options.pwd_max_days)
+
+        logger.debug("writing data to destination LDAP")
+        for o in update_objects:
+            dn,entry=o
+            #logger.debug(dn)
             try:
-                con.add_s(dn,ldap.modlist.addModlist(entry,junk_attrs))
-                notify_created(dn)
-                if options.verbose:
-                    print dn,"created"
-                good=good+1
-            except (ldap.OBJECT_CLASS_VIOLATION,ldap.NO_SUCH_OBJECT):
-                print dn, "failed"
-                failed=failed+1
-
-    if options.delete==True and options.updateonly==False:
-        result=con.search_s(destbasedn,ldap.SCOPE_SUBTREE,filter)
-        existing=[ x[0].lower() for x in result ]
+                destDn,destEntry=self.__get_dest_entry(dn, entry)
+
+                # hack for syncing accounts locked by password policy
+                do_unlock = self.__handle_pwdAccountLockedTime(dn, entry, now, max_age)
+    
+                mod_attrs=ldap.modlist.modifyModlist(destEntry,entry)
+
+                # hack for unlocking, see above
+                if do_unlock:
+                    self.logger.info( "unlocking {} {}".format(dn,pwdChange))
+                    mod_attrs.append( (ldap.MOD_DELETE,'pwdAccountLockedTime',None) )
+
+                if self.options.attrfilter is not None:
+                    mod_attrs=[ a for a in mod_attrs if a[1].lower() in options.attrfilter]
+
+                if self.junk_attrs is not None:
+                    mod_attrs=[ a for a in mod_attrs if a[1].lower() not in self.junk_attrs]
+
+                if mod_attrs:
+                    try:
+                            self.con.modify_s(dn,mod_attrs)
+                            result['update']['ok'].append(dn)
+                            self.notify_modified(dn)
+                    except:
+                            self.logger.error("failed to modify {} ({})".format(dn,mod_attrs))
+                            result['update']['failed'].append(dn)
+
+            except ldap.NO_SUCH_OBJECT:
+                if options.updateonly==True:
+                    continue
+
+                try:
+                    self.con.add_s(dn,ldap.modlist.addModlist(entry,self.junk_attrs))
+                    self.notify_created(dn)
+                    result['add']['ok'].append(dn)
+                except (ldap.OBJECT_CLASS_VIOLATION,ldap.NO_SUCH_OBJECT):
+                    self.logger.warning("failed to add {}".format(dn))
+                    result['add']['failed'].append(dn)
+        return result
+
+                    
+    def __deleteDestLdapObjects(self, update_objects):
+        """
+        Remove all LDAP objects in destination LDAP server
+        that did not come from the source LDAP objects
+        and are not excluded.
+        """
+
+        result = {
+            'delete': { 'ok': [], 'failed': [] },
+        }
+
+        searchresult=self.con.search_s(self.destbasedn,ldap.SCOPE_SUBTREE,self.options.filter)
+        existing=[ x[0].lower() for x in searchresult ]
 
         morituri=existing
 
-        if destbasedn.lower() in existing:
-            morituri.remove(destbasedn.lower())
+        if self.destbasedn.lower() in existing:
+            morituri.remove(self.destbasedn.lower())
 
         for o in update_objects:
@@ -210,30 +294,84 @@
                 morituri.remove(dn.lower())
         for dn in morituri:
-            if options.exclude != None and dn.lower().endswith(options.exclude):
-                # print "ignoring",dn
-                continue
-
-            try:
-                con.delete_s(dn)
-            except:
-                print "failed to delete",dn
-
-            notify_deleted(dn) 
-            if options.verbose:
-                print dn,"deleted"
-            deleted=deleted+1
+            if self.__is_dn_included(dn):
+                try:
+                    self.con.delete_s(dn)
+                    self.notify_deleted(dn) 
+                    result['delete']['ok'].append(dn)
+                except:
+                    self.logger.error("failed to delete {}".format(dn))
+                    result['delete']['failed'].append(dn)
+        return result
+                    
+
+    def sync(self, searchresult):
+        """
+        Synchronize entries from searchresult to destination LDAP server.
+        """
+        result = {
+            'add': { 'ok': [], 'failed': [] },
+            'update': { 'ok': [], 'failed': [] },
+            'delete': { 'ok': [], 'failed': [] },
+        }
+
+        if len(searchresult)==0:
+            self.logger.error("empty source, aborting")
+            return
+
+        self.__ldap_connect()
+
+        update_objects = self.__adapt_source_ldap_objects(searchresult)
+        result = self.__syncLdapDestination(update_objects)
+        if self.options.delete==True and self.options.updateonly==False:
+            result.update(self.__deleteDestLdapObjects(update_objects))
+        self.con.unbind()
  
-    con.unbind()
-    print good,"entries created,",exist,"updated,",deleted,"deleted,",failed,"failed."
+        self.__log_summary(result, True)
+
+
+
+    def __log_summary(self, result, show_failed = True, show_ok = False):
+        for action in result.keys():
+            ok = len(result[action]['ok'])
+            failed = len(result[action]['failed'])
+            print "{} (ok: {}, failed: {}):".format(action, ok, failed)
+
+            if show_ok and ok > 0:
+                print "succeeded:"
+                print "\n".join(result[action]['ok'])
+
+            if show_failed and failed > 0:
+                print "failed:"
+                print "\n".join(result[action]['failed'])
+
+
+    def notify_created(self, dn):
+        print "created",dn
+
+    def notify_modified(self, dn):
+        print "modified",dn
+
+    def notify_deleted(self, dn):
+        print "deleted",dn
+
+    def notify_renamed(self, dn, newdn, uid, newuid, options):
+        print "renamed",dn,newdn
+        subprocess.check_call("%s %s %s %s %s" % (options.renamecommand,dn,newdn,uid,newuid),shell=True)
+
+
 
 
 if __name__ == "__main__":
-    conffile="ldapsync.conf"
-    filter = None
+    logging.basicConfig(format='%(levelname)s %(module)s.%(funcName)s: %(message)s', level=logging.INFO)
+    logger = logging.getLogger()
+
+    args=getArguments()
+    if args.debug:
+        logger.setLevel(logging.DEBUG)
+    conffile=args.configfile
+
     exclude = None
-    if len(sys.argv)>1:
-        conffile=sys.argv[1]
-
-    config=ConfigParser.ConfigParser()
+
+    config=ConfigParserDefaults()
     config.read(conffile)
 
@@ -245,4 +383,6 @@
 
     basedn = config.get("source","baseDn")
+    filter = config.get0("source","filter", None)
+    attrs = config.get0("source", "attributes", None)
 
     if srcfile==None:
@@ -250,16 +390,5 @@
         admindn = config.get("source","bindDn") 
         adminpw = config.get("source","bindPassword")
-        filter = config.get("source","filter")
         starttls = config.getboolean("source","starttls")
-
-    if filter==None:
-        filter = '(objectClass=*)'
-
-    options = Options()
-
-    try:
-        options.exclude = config.get("destination","excludesubtree").lower()
-    except:
-        pass
 
     destsrv = config.get("destination","server") 
@@ -268,11 +397,24 @@
     destbasedn = config.get("destination","baseDn")
     destdelete = config.getboolean("destination","delete")
-    rdn = config.get("destination","rdn")
-
     try:
-        options.updateonly = not config.getboolean("destination","create")
+        rdn = config.get("destination","rdn")
+        logger.warning("setting rdn is currently ignored")
     except:
-        options.updateonly = False
-    options.starttls = config.getboolean("destination","starttls")
+        pass
+
+    options = Options()
+    try:
+        options.exclude = config.get("destination","excludesubtree").lower()
+    except:
+        pass
+
+    options.updateonly = not config.getboolean("destination","create", False)
+    options.starttls = config.getboolean("destination","starttls", False)
+    options.renameattr = config.get0("destination","detectRename", None)
+    options.renamecommand = config.get0("destination","detectRename", None)
+    options.pwd_max_days = int(config.get("source","pwd_max_days",0))
+    options.filter = filter
+
+    
     try:
         options.attrfilter = config.get("destination","attributes").split(",")
@@ -280,23 +422,9 @@
         options.attrfilter = None
 
-    try:
-        options.renameattr = config.get("destination","detectRename")
-    except:
-        options.renameattr = None
-
-    try:
-        options.renamecommand = config.get("destination","detectRename")
-    except:
-        options.renamecommand = None
-
     if srcfile:
-        result = readLDIFSource(srcfile)
+        objects = readLDIFSource(srcfile)
     else:
-        result = readLdapSource(srv,admindn,adminpw,basedn,filter,starttls)
-
-    try:
-        pwd_max_days = int(config.get("source","pwd_max_days"))
-    except:
-        pwd_max_days = 0
-
-    syncLdapDestination(result,destsrv,destadmindn,destadminpw,basedn,destbasedn,rdn,options)
+        objects = readLdapSource(srv,admindn,adminpw,basedn,filter,attrs,starttls)
+
+    ldapsync = LdapSync(destsrv,destadmindn,destadminpw,basedn,destbasedn,options)
+    ldapsync.sync(objects)
