Hello, all. This is a sequel to the last email on this subject now that
we've resolved the shadowLastChange problem. Fixing that problem did
not fix the DS 8.0 / AD password synchronization problem. To reiterate,
the passwords synchronize if the change is made from idm-console or from
AD. But they do not change when our Ubuntu/KDE users change their own
passwords. It fails when changed from both the KDE password change
interface and using passwd at the command line.
Windows Event Viewer is not giving me any useful information. There is
quite a bit of information in the DS logs but I'm not quite sure what
they are telling me. I'll post pertinent snippets below (please pardon
the left truncation but I'm screen scraping):
icationPlugin - ruv_add_csn_inprogress: successfully inserted csn 49f632dd000000010000
into pending list
icationPlugin - Purged state information from entry
uid=mlap,ou=Desks,o=a0000-0010,o=Internal,dc=ssiservices,dc=biz up to CSN
49ecf604000200010000
icationPlugin - ruv_add_csn_inprogress: successfully inserted csn 49f632dd000100010000
into pending list
icationPlugin - Purged state information from entry
uid=mlap,ou=Desks,o=a0000-0010,o=Internal,dc=ssiservices,dc=biz up to CSN
49ecf604000200010000
icationPlugin - ruv_update_ruv: successfully committed csn 49f632dd000100010000
icationPlugin - ruv_add_csn_inprogress: successfully inserted csn 49f632dd000200010000
into pending list
icationPlugin - Purged state information from entry
uid=mlap,ou=Desks,o=a0000-0010,o=Internal,dc=ssiservices,dc=biz up to CSN
49ecf604000200010000
icationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636): State:
wait_for_changes -> wait_for_changes
icationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636): State:
wait_for_changes -> ready_to_acquire_replica
(this seemed to happen immediately upon password change and not in the normal five minute
sync routine)
.
.
.
[27/Apr/2009:18:34:05 -0400] NSMMReplicationPlugin - ruv_update_ruv: successfully
committed csn 49f632dd000200010000
[27/Apr/2009:18:34:05 -0400] - acquire_replica, supplier RUV:
.
.
.
r/2009:18:34:05 -0400] NSMMReplicationPlugin - ruv_update_ruv: successfully committed csn
49f632dd000000010000
r/2009:18:34:05 -0400] NSMMReplicationPlugin - supplier: {replicageneration}
49e5ebb3000000010000
r/2009:18:34:05 -0400] NSMMReplicationPlugin - supplier: {replica 1
ldap://ldap01.ssiservices.biz:389} 49e70122000000010000 49f632dd000200010000 49f632dd
r/2009:18:34:05 -0400] - acquire_replica, consumer RUV:
r/2009:18:34:05 -0400] NSMMReplicationPlugin - consumer: {replicageneration}
49e5ebb3000000010000
r/2009:18:34:05 -0400] NSMMReplicationPlugin - consumer: {replica 1
ldap://ldap01.ssiservices.biz:389} 49e70122000000010000 49f63084000200010000 49f63084
r/2009:18:34:05 -0400] - acquire_replica, supplier RUV is newer
r/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): Trying secure slapi_ldap_init
NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636): binddn =
cn=Synch Manager,cn=Users,dc=mycompany,dc=com, passwd = {DES}tOBO
.
.
.
[27/Apr/2009:18:34:05 -0400] - windows_conn_connect : detected Win2k3 peer
[27/Apr/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): No linger to cancel on the connection
[27/Apr/2009:18:34:05 -0400] NSMMReplicationPlugin - windows_acquire_replica returned
success (101)
[27/Apr/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): State: ready_to_acquire_replica -> sending_updates
[27/Apr/2009:18:34:05 -0400] - _cl5PositionCursorForReplay
(agmt="cn=a0000-0010(EBC)" (timberline:636)): Consumer RUV:
[27/Apr/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): {replicageneration} 49e5ebb3000000010000
tionPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636): {replica 1
ldap://ldap01.ssiservices.biz:389} 49e70122000000010000 49f63084000200010000 49f63084
[27/Apr/2009:18:34:05 -0400] - _cl5PositionCursorForReplay
(agmt="cn=a0000-0010(EBC)" (timberline:636)): Supplier RUV:
[27/Apr/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): {replicageneration} 49e5ebb3000000010000
tionPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636): {replica 1
ldap://ldap01.ssiservices.biz:389} 49e70122000000010000 49f632dd000200010000 49f632dd
05 -0400] agmt="cn=a0000-0010(EBC)" (timberline:636) - session start:
anchorcsn=49f63084000200010000
05 -0400] NSMMReplicationPlugin - changelog program - agmt="cn=a0000-0010(EBC)"
(timberline:636): CSN 49f63084000200010000 found, position set for replay
05 -0400] agmt="cn=a0000-0010(EBC)" (timberline:636) - load=1 rec=1
csn=49f632dd000000010000
8:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): windows_replay_update: Looking at modify operation local
dn="uid=mlap,ou=desks,o=a0000-0010,o=internal,dc=ssiservices,dc=biz"
(ours,user,not group)
8:34:05 -0400] NSMMReplicationPlugin - agmt="cn=ssiservices.biz
ldap01->ldap02" (ldap02:636): No linger to cancel on the connection
8:34:05 -0400] - windows_search_entry: recieved 2 messages, 1 entries, 0 references
8:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): windows_replay_update: Processing modify operation local
dn="uid=mlap,ou=desks,o=a0000-0010,o=internal,dc=ssiservices,dc=biz" remote
dn="<GUID=5b0db1b95d6dca44aaef260be70ee31b>"
8:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): windows_create_remote_entry: Password is already hashed. Not syncing.
**** THIS ENTRY ABOUT NOT SYNCING CERTAINLY JUMPED OUT AT ME BUT I DON'T KNOW WHAT IT
MEANS *****
8:34:05 -0400] agmt="cn=a0000-0010(EBC)" (timberline:636) - load=1 rec=2
csn=49f632dd000100010000
NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636):
windows_replay_update: Looking at modify operation local
dn="uid=mlap,ou=desks,o=a0000-0010,o=internal,dc=ssiservices,dc=biz"
(ours,user,not group)
.
.
.
- windows_search_entry: recieved 2 messages, 1 entries, 0 references
NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636):
windows_replay_update: Processing modify operation local
dn="uid=mlap,ou=desks,,o=a0000-0010,o=internal,dc=ssiservices,dc=biz" remote
dn="<GUID=5b0db1b95d6dca44aaef260be70ee31b>"
agmt="cn=a0000-0010(EBC)" (timberline:636) - load=1 rec=3
csn=49f632dd000200010000
NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636):
windows_replay_update: Looking at modify operation local
dn="uid=mlap,ou=desks,o=a0000-0010,o=internal,dc=ssiservices,dc=biz"
(ours,user,not group)
.
.
.
[27/Apr/2009:18:34:05 -0400] - repl5_inc_result_threadmain starting
[27/Apr/2009:18:34:05 -0400] - windows_search_entry: recieved 2 messages, 1 entries, 0
references
NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636):
windows_replay_update: Processing modify operation local
dn="uid=mlap,ou=desks,,o=a0000-0010,o=internal,dc=ssiservices,dc=biz" remote
dn="<GUID=5b0db1b95d6dca44aaef260be70ee31b>"
- repl5_inc_result_threadmain: read result for message_id 0
[27/Apr/2009:18:34:05 -0400] - repl5_inc_result_threadmain: read result for message_id 0
.
.
.
[27/Apr/2009:18:34:05 -0400] - repl5_inc_result_threadmain: read result for message_id 0
[27/Apr/2009:18:34:05 -0400] agmt="cn=a0000-0010(EBC)" (timberline:636) -
clcache_load_buffer: rc=-30989
[27/Apr/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): No more updates to send (cl5GetNextOperationToReplay)
[27/Apr/2009:18:34:05 -0400] agmt="cn=a0000-0010(EBC)" (timberline:636) -
session end: state=5 load=1 sent=3 skipped=0
[27/Apr/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): Beginning linger on the connection
[27/Apr/2009:18:34:05 -0400] - repl5_inc_result_threadmain: read result for message_id 0
[27/Apr/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): Linger timeout has expired on the connection
[27/Apr/2009:18:34:05 -0400] - repl5_inc_result_threadmain: read result for message_id 6
[27/Apr/2009:18:34:05 -0400] - repl5_inc_result_threadmain: result 3, 0, 0, 6, (null)
[27/Apr/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=ssiservices.biz
ldap01->ldap02" (ldap02:636): replay_update: Consumer successfully sent oper
[27/Apr/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): Disconnected from the consumer
[27/Apr/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): State: sending_updates -> wait_for_changes
[27/Apr/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): State: wait_for_changes -> ready_to_acquire_replica
[27/Apr/2009:18:34:05 -0400] - acquire_replica, supplier RUV:
r/2009:18:34:05 -0400] NSMMReplicationPlugin - supplier: {replicageneration}
49e5ebb3000000010000
r/2009:18:34:05 -0400] NSMMReplicationPlugin - supplier: {replica 1
ldap://ldap01.ssiservices.biz:389} 49e70122000000010000 49f632dd000200010000 49f632dd
r/2009:18:34:05 -0400] - acquire_replica, consumer RUV:
r/2009:18:34:05 -0400] NSMMReplicationPlugin - consumer: {replicageneration}
49e5ebb3000000010000
r/2009:18:34:05 -0400] NSMMReplicationPlugin - consumer: {replica 1
ldap://ldap01.ssiservices.biz:389} 49e70122000000010000 49f632dd000200010000 49f632dd
r/2009:18:34:05 -0400] NSMMReplicationPlugin - windows_acquire_replica returned
consumer_was_uptodate (104)
r/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): State: ready_to_acquire_replica -> wait_for_changes
.
.
.
.
r/2009:18:34:05 -0400] NSMMReplicationPlugin - ruv_update_ruv: successfully committed csn
49f632dd000500010000
r/2009:18:34:05 -0400] - repl5_inc_result_threadmain: read result for message_id 7
r/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): State: wait_for_changes -> wait_for_changes
r/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): State: wait_for_changes -> ready_to_acquire_replica
r/2009:18:34:05 -0400] - acquire_replica, supplier RUV:
r/2009:18:34:05 -0400] NSMMReplicationPlugin - supplier: {replicageneration}
49e5ebb3000000010000
r/2009:18:34:05 -0400] NSMMReplicationPlugin - supplier: {replica 1
ldap://ldap01.ssiservices.biz:389} 49e70122000000010000 49f632dd000500010000 49f632dd
r/2009:18:34:05 -0400] - acquire_replica, consumer RUV:
r/2009:18:34:05 -0400] NSMMReplicationPlugin - consumer: {replicageneration}
49e5ebb3000000010000
r/2009:18:34:05 -0400] NSMMReplicationPlugin - consumer: {replica 1
ldap://ldap01.ssiservices.biz:389} 49e70122000000010000 49f632dd000200010000 49f632dd
r/2009:18:34:05 -0400] - acquire_replica, supplier RUV is newer
r/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): Trying secure slapi_ldap_init
r/2009:18:34:05 -0400] - repl5_inc_result_threadmain: read result for message_id 7
r/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): binddn = cn=SSI Synchronization Manager,cn=Users,dc=ebc-co,dc=c
r/2009:18:34:05 -0400] - repl5_inc_result_threadmain: read result for message_id 8
r/2009:18:34:05 -0400] - repl5_inc_result_threadmain: result 3, 0, 0, 8, (null)
r/2009:18:34:05 -0400] - windows_conn_connect : detected Win2k3 peer
r/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): No linger to cancel on the connection
r/2009:18:34:05 -0400] - repl5_inc_result_threadmain: read result for message_id 8
r/2009:18:34:05 -0400] NSMMReplicationPlugin - windows_acquire_replica returned success
(101)
r/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): State: ready_to_acquire_replica -> sending_updates
r/2009:18:34:05 -0400] - repl5_inc_result_threadmain: read result for message_id 8
r/2009:18:34:05 -0400] - _cl5PositionCursorForReplay (agmt="cn=a0000-0010(EBC)"
(timberline:636)): Consumer RUV:
r/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): {replicageneration} 49e5ebb3000000010000
r/2009:18:34:05 -0400] - repl5_inc_result_threadmain: read result for message_id 8
r/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): {replica 1 ldap://ldap01.ssiservices.biz:389} 49e70122000000010000
49f632dd000200010000 49f632dd
r/2009:18:34:05 -0400] - _cl5PositionCursorForReplay (agmt="cn=a0000-0010(EBC)"
(timberline:636)): Supplier RUV:
r/2009:18:34:05 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)"
(timberline:636): {replicageneration} 49e5ebb3000000010000
tionPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636): {replica 1
ldap://ldap01.ssiservices.biz:389} 49e70122000000010000 49f632dd000500010000 49f632dd
5 -0400] - repl5_inc_result_threadmain: read result for message_id 8
5 -0400] agmt="cn=a0000-0010(EBC)" (timberline:636) - session start:
anchorcsn=49f632dd000200010000
5 -0400] NSMMReplicationPlugin - changelog program - agmt="cn=a0000-0010(EBC)"
(timberline:636): CSN 49f632dd000200010000 found, position set for replay
5 -0400] agmt="cn=a0000-0010(EBC)" (timberline:636) - load=1 rec=1
csn=49f632dd000500010000
5 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636):
windows_replay_update: Looking at modify operation local
dn="uid=mlap,ou=desks,o=a0000-0010,o=internal,dc=ssiservices,dc=biz"
(ours,user,not group)
5 -0400] - windows_search_entry: recieved 2 messages, 1 entries, 0 references
5 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636):
windows_replay_update: Processing modify operation local
dn="uid=mlap,ou=desks,o=a0000-0010,o=internal,dc=ssiservices,dc=biz" remote
dn="<GUID=5b0db1b95d6dca44aaef260be70ee31b>"
5 -0400] agmt="cn=a0000-0010(EBC)" (timberline:636) - clcache_load_buffer:
rc=-30989
5 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636): No
more updates to send (cl5GetNextOperationToReplay)
5 -0400] agmt="cn=a0000-0010(EBC)" (timberline:636) - session end: state=5
load=1 sent=1 skipped=0
5 -0400] - repl5_inc_result_threadmain: read result for message_id 8
5 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636):
Beginning linger on the connection
5 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636):
State: sending_updates -> wait_for_changes
5 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636):
Linger timeout has expired on the connection
5 -0400] NSMMReplicationPlugin - agmt="cn=a0000-0010(EBC)" (timberline:636):
Disconnected from the consumer
5 -0400] - repl5_inc_result_threadmain: read result for message_id 8
5 -0400] - repl5_inc_result_threadmain: read result for message_id 8
5 -0400] - repl5_inc_result_threadmain: read result for message_id 8
5 -0400] - repl5_inc_result_threadmain: read result for message_id 8
6 -0400] - repl5_inc_result_threadmain: read result for message_id 8
6 -0400] - repl5_inc_waitfor_async_results: 8 8
6 -0400] - repl5_inc_result_threadmain: read result for message_id 8
7 -0400] - repl5_inc_result_threadmain exiting
.
.
.
.
27/Apr/2009:18:34:07 -0400] - repl5_inc_waitfor_async_results: 0 12
[27/Apr/2009:18:34:07 -0400] - repl5_inc_result_threadmain: read result for message_id 0
[27/Apr/2009:18:34:07 -0400] - repl5_inc_result_threadmain: read result for message_id 12
[27/Apr/2009:18:34:07 -0400] - repl5_inc_result_threadmain: result 3, 0, 0, 12, (null)
[27/Apr/2009:18:34:07 -0400] - repl5_inc_result_threadmain: read result for message_id 12
[27/Apr/2009:18:34:07 -0400] - repl5_inc_result_threadmain: read result for message_id 12
[27/Apr/2009:18:34:07 -0400] - repl5_inc_result_threadmain: read result for message_id 12
[27/Apr/2009:18:34:07 -0400] - repl5_inc_result_threadmain: read result for message_id 12
[27/Apr/2009:18:34:07 -0400] - repl5_inc_result_threadmain: read result for message_id 12
[27/Apr/2009:18:34:07 -0400] - repl5_inc_result_threadmain: read result for message_id 12
[27/Apr/2009:18:34:07 -0400] - repl5_inc_result_threadmain: read result for message_id 12
[27/Apr/2009:18:34:07 -0400] - repl5_inc_result_threadmain: read result for message_id 12
[27/Apr/2009:18:34:08 -0400] - repl5_inc_result_threadmain: read result for message_id 12
[27/Apr/2009:18:34:08 -0400] - repl5_inc_result_threadmain: read result for message_id 12
[27/Apr/2009:18:34:08 -0400] - repl5_inc_waitfor_async_results: 12 12
[27/Apr/2009:18:34:08 -0400] - repl5_inc_result_threadmain: read result for message_id 12
[27/Apr/2009:18:34:09 -0400] - repl5_inc_result_threadmain exiting
[27/Apr/2009:18:34:09 -0400] agmt="cn=ssiservices.biz ldap01->ldap02"
(ldap02:636) - session end: state=5 load=1 sent=1 skipped=0
Does anyone see the problem? How do I get synchronization working when
the users change their own passwords? Thanks - John
--
John A. Sullivan III
Open Source Development Corporation
+1 207-985-7880
jsullivan(a)opensourcedevel.com
http://www.spiritualoutreach.com
Making Christianity intelligible to secular society