[389-users] Ldap and Active Directory -- Data Sync not Happening

Sun Mar 1 21:17:51 UTC 2015

Hi

I am having issues related to a oneWay SYNC from AD to LDAP.

I got everything running the password sync part I have kept disable for 
a bit as I want to JUST sync users for start.
This is an Ubuntu --- Windows2012 setup (only 2 boxes)
The Unidirectional setup "fromWindows" defined in the replication object.

The authentication gets through to the AD box, I can initialise the 
replica and that is all, it never gets any data into the DS.
I have follow all the steps certificate related...etc.. which they seem 
all right, but I cannot understand what happens.

Error log below:

-----
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): State: 
wait_for_changes -> wait_for_changes
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): State: 
wait_for_changes -> start
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): No linger to 
cancel on the connection
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): Disconnected from 
the consumer
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): State: start -> 
ready_to_acquire_replica
[01/Mar/2015:09:08:53 +0000] - acquire_replica, supplier RUV:
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - supplier: 
{replicageneration} 54f0c078000000010000
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - supplier: {replica 
1 ldap://ldapserver.com:389} 54f23832000000010000 54f2d5e1000000010000 
54f2d5e1
[01/Mar/2015:09:08:53 +0000] - acquire_replica, consumer RUV:
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - consumer: 
{replicageneration} 54f0c078000000010000
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - consumer: {replica 
1 ldap://ldapserver.com:389} 54f23832000000010000 54f2d5e1000000010000 
54f2d5e1
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): Trying secure 
slapi_ldap_init_ext

[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): binddn = cn=user 
Sync,cn=Users,dc=windows,dc=activedirectory,dc=com,  passwd = 
{DES}s/tdsdsdsd
[01/Mar/2015:09:08:53 +0000] - windows_conn_connect : detected Win2k3 or 
later peer
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): No linger to 
cancel on the connection
[01/Mar/2015:09:08:53 +0000] - _csngen_adjust_local_time: gen state 
before 54f2d6e10002:1425200865:0:0
[01/Mar/2015:09:08:53 +0000] - _csngen_adjust_local_time: gen state 
after 54f2d7250000:1425200933:0:0
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - windows sync - 
windows_acquire_replica returned success (101)
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): State: 
ready_to_acquire_replica -> sending_updates
[01/Mar/2015:09:08:53 +0000] - csngen_adjust_time: gen state before 
54f2d7250001:1425200933:0:0
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - changelog program - 
_cl5GetDBFile: found DB object 7f462249add0 for database 
/var/lib/dirsrv/slapd-instance/changelogdb/c3b80d03-beb311e4-8df9a16f-b0f06c9b_54f0c078000000010000.db
[01/Mar/2015:09:08:53 +0000] - _cl5PositionCursorForReplay 
(agmt="cn=windows.activedirectory.com" (adserver:636)): Consumer RUV:
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - 
agmt="cn=windows.activedirectory.com" (adserver:636): 
{replicageneration} 54f0c078000000010000
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - 
agmt="cn=windows.activedirectory.com" (adserver:636): {replica 1 
ldap://ldapserver.com:389} 54f23832000000010000 54f2d5e1000000010000 
54f2d5e1
[01/Mar/2015:09:08:53 +0000] - _cl5PositionCursorForReplay 
(agmt="cn=windows.activedirectory.com" (adserver:636)): Supplier RUV:
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - 
agmt="cn=windows.activedirectory.com" (adserver:636): 
{replicageneration} 54f0c078000000010000
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - 
agmt="cn=windows.activedirectory.com" (adserver:636): {replica 1 
ldap://ldapserver.com:389} 54f23832000000010000 54f2d5e1000000010000 
54f2d5e1
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): No changes to send
[01/Mar/2015:09:08:53 +0000] - Calling dirsync search request plugin
[01/Mar/2015:09:08:53 +0000] - Sending dirsync search request
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): Beginning linger 
on the connection
[01/Mar/2015:09:08:53 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): State: 
sending_updates -> wait_for_changes
[01/Mar/2015:09:09:24 +0000] - _csngen_adjust_local_time: gen state 
before 54f2d7250001:1425200933:0:0
[01/Mar/2015:09:09:24 +0000] - _csngen_adjust_local_time: gen state 
after 54f2d7440000:1425200964:0:0
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - 
ruv_add_csn_inprogress: successfully inserted csn 54f2d744000000010000 
into pending list
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - Purged state 
information from entry ou=People,dc=windows,dc=activedirectory,dc=com up 
to CSN 54e99b61000000010000
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - changelog program - 
_cl5GetDBFileByReplicaName: found DB object 7f462249add0 for database 
/var/lib/dirsrv/slapd-instance/changelogdb/c3b80d03-beb311e4-8df9a16f-b0f06c9b_54f0c078000000010000.db
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - changelog program - 
_cl5GetDBFileByReplicaName: found DB object 7f462249add0 for database 
/var/lib/dirsrv/slapd-instance/changelogdb/c3b80d03-beb311e4-8df9a16f-b0f06c9b_54f0c078000000010000.db
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - ruv_update_ruv: 
successfully committed csn 54f2d744000000010000
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): State: 
wait_for_changes -> wait_for_changes
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): State: 
wait_for_changes -> ready_to_acquire_replica
[01/Mar/2015:09:09:24 +0000] - acquire_replica, supplier RUV:
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - supplier: 
{replicageneration} 54f0c078000000010000
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - supplier: {replica 
1 ldap://ldapserver.com:389} 54f23832000000010000 54f2d744000000010000 
54f2d744
[01/Mar/2015:09:09:24 +0000] - acquire_replica, consumer RUV:
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - consumer: 
{replicageneration} 54f0c078000000010000
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - consumer: {replica 
1 ldap://ldapserver.com:389} 54f23832000000010000 54f2d5e1000000010000 
54f2d5e1
[01/Mar/2015:09:09:24 +0000] - acquire_replica, supplier RUV is newer
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): Cancelling linger 
on the connection
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - windows sync - 
windows_acquire_replica returned success (101)
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): State: 
ready_to_acquire_replica -> sending_updates
[01/Mar/2015:09:09:24 +0000] - csngen_adjust_time: gen state before 
54f2d7440002:1425200964:0:0
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - changelog program - 
_cl5GetDBFile: found DB object 7f462249add0 for database 
/var/lib/dirsrv/slapd-instance/changelogdb/c3b80d03-beb311e4-8df9a16f-b0f06c9b_54f0c078000000010000.db
[01/Mar/2015:09:09:24 +0000] - _cl5PositionCursorForReplay 
(agmt="cn=windows.activedirectory.com" (adserver:636)): Consumer RUV:
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - 
agmt="cn=windows.activedirectory.com" (adserver:636): 
{replicageneration} 54f0c078000000010000
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - 
agmt="cn=windows.activedirectory.com" (adserver:636): {replica 1 
ldap://ldapserver.com:389} 54f23832000000010000 54f2d5e1000000010000 
54f2d5e1
[01/Mar/2015:09:09:24 +0000] - _cl5PositionCursorForReplay 
(agmt="cn=windows.activedirectory.com" (adserver:636)): Supplier RUV:
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - 
agmt="cn=windows.activedirectory.com" (adserver:636): 
{replicageneration} 54f0c078000000010000
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - 
agmt="cn=windows.activedirectory.com" (adserver:636): {replica 1 
ldap://ldapserver.com:389} 54f23832000000010000 54f2d744000000010000 
54f2d744
[01/Mar/2015:09:09:24 +0000] agmt="cn=windows.activedirectory.com" 
(adserver:636) - clcache_get_buffer: found thread private buffer cache 
7f4604021ef0
[01/Mar/2015:09:09:24 +0000] agmt="cn=windows.activedirectory.com" 
(adserver:636) - clcache_get_buffer: _pool is 7f462248e080 
_pool->pl_busy_lists is 7f4604001010 _pool->pl_busy_lists->bl_buffers is 
7f4604021ef0
[01/Mar/2015:09:09:24 +0000] agmt="cn=windows.activedirectory.com" 
(adserver:636) - session start: anchorcsn=54f2d5e1000000010000
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - changelog program - 
agmt="cn=windows.activedirectory.com" (adserver:636): CSN 
54f2d5e1000000010000 found, position set for replay
[01/Mar/2015:09:09:24 +0000] agmt="cn=windows.activedirectory.com" 
(adserver:636) - load=1 rec=1 csn=54f2d744000000010000
[01/Mar/2015:09:09:24 +0000] agmt="cn=windows.activedirectory.com" 
(adserver:636) - clcache_load_buffer: rc=-30988
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): No more updates to 
send (cl5GetNextOperationToReplay)
[01/Mar/2015:09:09:24 +0000] agmt="cn=windows.activedirectory.com" 
(adserver:636) - session end: state=5 load=1 sent=1 skipped=0 
skipped_new_rid=0 skipped_csn_gt_cons_maxcsn=0 skipped_up_to_date=0 
skipped_csn_gt_ruv=0 skipped_csn_covered=0
[01/Mar/2015:09:09:24 +0000] - Calling dirsync search request plugin
[01/Mar/2015:09:09:24 +0000] - Sending dirsync search request
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): Beginning linger 
on the connection
[01/Mar/2015:09:09:24 +0000] NSMMReplicationPlugin - windows sync - 
agmt="cn=windows.activedirectory.com" (adserver:636): State: 
sending_updates -> wait_for_changes
[01/Mar/2015:09:09:28 +0000] NSMMReplicationPlugin - changelog program - 
_cl5GetDBFile: found DB object 7f462249add0 for database 
/var/lib/dirsrv/slapd-instance/changelogdb/c3b80d03-beb311e4-8df9a16f-b0f06c9b_54f0c078000000010000.db
[01/Mar/2015:09:09:28 +0000] NSMMReplicationPlugin - changelog program - 
cl5GetOperationCount: found DB object 7f462249add0
------

I have played with this for 2 weeks setting up every single possible 
change in DS related to Users, Groups, but I cannot understand why 
389-DS does not feel able of getting the data out of AD?
I do not have a good error log showing a successful data import which I 
can compare with, so I do not know how to expect that.
To me looks like Windows is simply dropping the connection, but from a 
Windows perspective it seems ok as the User validates all right . At 
this stage I do not know what else to look at?

Any tips please?

Many thanks!