[Freeipa-users] FreeIPA password sync one direction only (Windows DC -> IPA)

Fri May 17 18:03:44 UTC 2013

Thanks for getting me on the right track.

Yes to the Windows sync agreement.

I'm not sure if this is related to password sync'ing, but it looks like a
sync operation is triggering (and failing) every 4 seconds on one of my
users:

[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): State: start_backoff -> backoff
[17/May/2013:13:28:42 -0400] - acquire_replica, supplier RUV:
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin - supplier:
{replicageneration} 50802036000000030000
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin - supplier: {replica 3
ldap://ipa1.miovision.linux:389} 50802036000100030000 51966776000100030000
51966776
[17/May/2013:13:28:42 -0400] - acquire_replica, consumer RUV:
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin - consumer:
{replicageneration} 50802036000000030000
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin - consumer: {replica 3
ldap://ipa1.miovision.linux:389} 50802036000100030000 515ad91f000000030000
00000000
[17/May/2013:13:28:42 -0400] - acquire_replica, supplier RUV is newer
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): Cancelling linger on the
connection
[17/May/2013:13:28:42 -0400] - _csngen_adjust_local_time: gen state before
519668c60001:1368811718:0:0
[17/May/2013:13:28:42 -0400] - _csngen_adjust_local_time: gen state after
519668ca0000:1368811722:0:0
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): State: backoff ->
sending_updates
[17/May/2013:13:28:42 -0400] - csngen_adjust_time: gen state before
519668ca0001:1368811722:0:0
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin - changelog program -
_cl5GetDBFile: found DB object f6d910 for database
/var/lib/dirsrv/slapd-MIOVISION-LINUX/cldb/854fd282-193811e2-9177aa0d-17c9983f_50802036000000030000.db4
[17/May/2013:13:28:42 -0400] - _cl5PositionCursorForReplay
(agmt="cn=meTodc1.miovision.corp" (dc1:389)): Consumer RUV:
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): {replicageneration}
50802036000000030000
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): {replica 3
ldap://ipa1.miovision.linux:389} 50802036000100030000 515ad91f000000030000
00000000
[17/May/2013:13:28:42 -0400] - _cl5PositionCursorForReplay
(agmt="cn=meTodc1.miovision.corp" (dc1:389)): Supplier RUV:
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): {replicageneration}
50802036000000030000
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): {replica 3
ldap://ipa1.miovision.linux:389} 50802036000100030000 51966776000100030000
51966776
[17/May/2013:13:28:42 -0400] agmt="cn=meTodc1.miovision.corp" (dc1:389) -
clcache_get_buffer: found thread private buffer cache 7f30bc061d00
[17/May/2013:13:28:42 -0400] agmt="cn=meTodc1.miovision.corp" (dc1:389) -
clcache_get_buffer: _pool is 2e7cc10 _pool->pl_busy_lists is 7f30bc050790
_pool->pl_busy_lists->bl_buffers is 7f30bc061d00
[17/May/2013:13:28:42 -0400] agmt="cn=meTodc1.miovision.corp" (dc1:389) -
session start: anchorcsn=515ad91f000000030000
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin - changelog program -
agmt="cn=meTodc1.miovision.corp" (dc1:389): CSN 515ad91f000000030000 found,
position set for replay
[17/May/2013:13:28:42 -0400] agmt="cn=meTodc1.miovision.corp" (dc1:389) -
load=1 rec=1 csn=515ae3f4000000030000
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): windows_replay_update: Looking
at modify operation local
dn="uid=jkeller,cn=users,cn=accounts,dc=miovision,dc=linux" (ours,user,not
group)
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): map_entry_dn_outbound: looking
for AD entry for DS
dn="uid=jkeller,cn=users,cn=accounts,dc=miovision,dc=linux"
guid="ba17f9770e0c814cb9eea9df2d4df61a"
[17/May/2013:13:28:42 -0400] - Calling windows entry search request plugin
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin - Could not retrieve
entry from Windows using search base
[<GUID=ba17f9770e0c814cb9eea9df2d4df61a>] scope [0] filter
[(objectclass=*)]: error 1:Operations error
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): map_entry_dn_outbound: return
code -1 from search for AD entry
dn="<GUID=ba17f9770e0c814cb9eea9df2d4df61a>" or dn="(null)"
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): map_entry_dn_outbound: entry
not found - rc -1
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): windows_replay_update:
Processing modify operation local
dn="uid=jkeller,cn=users,cn=accounts,dc=miovision,dc=linux" remote
dn="<GUID=ba17f9770e0c814cb9eea9df2d4df61a>"
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): map_entry_dn_outbound: looking
for AD entry for DS
dn="uid=jkeller,cn=users,cn=accounts,dc=miovision,dc=linux"
guid="ba17f9770e0c814cb9eea9df2d4df61a"
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): map_entry_dn_outbound: looking
for AD entry for DS
dn="uid=jkeller,cn=users,cn=accounts,dc=miovision,dc=linux"
username="jkeller"
[17/May/2013:13:28:42 -0400] - Calling windows entry search request plugin
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin - Could not retrieve
entry from Windows using search base [dc=miovision,dc=corp] scope [2]
filter [(samAccountName=jkeller)]: error 1:Operations error
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): map_entry_dn_outbound: entry
not found - rc -1
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): map_entry_dn_outbound: failed
to fetch entry from AD:
dn="uid=jkeller,cn=users,cn=accounts,dc=miovision,dc=linux", err=-1
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): windows_replay_update: update
password returned 1
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): Consumer failed to replay
change (uniqueid cd3be819-21c711e2-96aaaa0d-17c9983f, CSN
515ae3f4000000030000): Operations error. Will retry later.
[17/May/2013:13:28:42 -0400] agmt="cn=meTodc1.miovision.corp" (dc1:389) -
session end: state=0 load=1 sent=1 skipped=0
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): Beginning linger on the
connection
[17/May/2013:13:28:42 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): State: sending_updates ->
start_backoff

Here's the output of an ldapsearch for the user jkeller:

#/usr/bin/ldapsearch -h dc1.miovision.corp -D "ldap-auth at miovision.corp" -W
-b "dc=miovision,dc=corp" '(samAccountName=jkeller)' cn samAccountName

# Joel Keller, 01Engineering, miovision.corp
dn: CN=Joel Keller,OU=01Engineering,DC=miovision,DC=corp
cn: Joel Keller
sAMAccountName: jkeller

When I change my password on the IPA server, it looks like the change is
queued:

[17/May/2013:13:53:48 -0400] - _csngen_adjust_local_time: gen state before
51966eab0001:1368813227:0:0
[17/May/2013:13:53:48 -0400] - _csngen_adjust_local_time: gen state after
51966eac0000:1368813228:0:0
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin -
ruv_add_csn_inprogress: successfully inserted csn 51966eac000000030000 into
pending list
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin - Purged state
information from entry
uid=sdainard,cn=users,cn=accounts,dc=miovision,dc=linux up to CSN
518d33f90007000300
00
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin - changelog program -
_cl5GetDBFileByReplicaName: found DB object f6d910 for database
/var/lib/dirsrv/slapd-MIOVISION-LINU
X/cldb/854fd282-193811e2-9177aa0d-17c9983f_50802036000000030000.db4
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin - changelog program -
_cl5GetDBFileByReplicaName: found DB object f6d910 for database
/var/lib/dirsrv/slapd-MIOVISION-LINU
X/cldb/854fd282-193811e2-9177aa0d-17c9983f_50802036000000030000.db4
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin - ruv_update_ruv:
successfully committed csn 51966eac000000030000
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin -
ruv_add_csn_inprogress: successfully inserted csn 51966eac000100030000 into
pending list
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin - Purged state
information from entry
uid=sdainard,cn=users,cn=accounts,dc=miovision,dc=linux up to CSN
518d342c0000000300
00
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin - changelog program -
_cl5GetDBFileByReplicaName: found DB object f6d910 for database
/var/lib/dirsrv/slapd-MIOVISION-LINUX/cldb/854fd282-193811e2-9177aa0d-17c9983f_50802036000000030000.db4
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin - changelog program -
_cl5GetDBFileByReplicaName: found DB object f6d910 for database
/var/lib/dirsrv/slapd-MIOVISION-LINUX/cldb/854fd282-193811e2-9177aa0d-17c9983f_50802036000000030000.db4
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin - ruv_update_ruv:
successfully committed csn 51966eac000100030000
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): State: start_backoff -> backoff
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin -
ruv_add_csn_inprogress: successfully inserted csn 51966eac000200030000 into
pending list
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin - Purged state
information from entry
uid=sdainard,cn=users,cn=accounts,dc=miovision,dc=linux up to CSN
518d342c000100030000
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin - changelog program -
_cl5GetDBFileByReplicaName: found DB object f6d910 for database
/var/lib/dirsrv/slapd-MIOVISION-LINUX/cldb/854fd282-193811e2-9177aa0d-17c9983f_50802036000000030000.db4
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin - changelog program -
_cl5GetDBFileByReplicaName: found DB object f6d910 for database
/var/lib/dirsrv/slapd-MIOVISION-LINUX/cldb/854fd282-193811e2-9177aa0d-17c9983f_50802036000000030000.db4
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin - ruv_update_ruv:
successfully committed csn 51966eac000200030000
[17/May/2013:13:53:48 -0400] NSMMReplicationPlugin -
agmt="cn=meTodc1.miovision.corp" (dc1:389): State: backoff -> backoff

Perhaps whatever is causing the sync error with user jkeller is holding up
the queued transactions?

Steve Dainard
Infrastructure Manager
Miovision Technologies Inc.

On Fri, May 17, 2013 at 11:39 AM, Rich Megginson <rmeggins at redhat.com>wrote:

>  On 05/17/2013 09:26 AM, Steve Dainard wrote:
>
> Hello,
>
>  We're running a single IPA server (CentOS 6) on our network as a side
> project for some testing before we implement.
>
>  It had been a significant period of time since I had last logged into
> the web interface, so I had to kinit from a client machine (of which I had
> logged into successfully with my domain password), at which point I was
> requested to change my password. After the password change I RDP'd into a
> Windows machine on our domain and realized the password had not been
> updated on the domain controller.
>
>  Is the password sync feature with an external source such as Active
> Directory supposed to be two-way? If so where can I start troubleshooting
> this issue?
>
>
> Are you talking about a windows sync agreement you set up with
> ipa-replica-manage?
> If so, yes, the password sync is supposed to be two-way.
> Try this:
> turn on the replication log level
> http://port389.org/wiki/FAQ#Troubleshooting
> change your IPA password
> turn off the replication log level
> http://port389.org/wiki/FAQ#Troubleshooting
> see if you can use your new password in AD
>
> The 389 errors log in /var/log/dirsrv/slapd-YOUR-DOMAIN/errors may contain
> a clue.
>
>
>  Thanks,
>
>
>
> Steve Dainard
> Infrastructure Manager
> Miovision Technologies Inc.
>
>
> _______________________________________________
> Freeipa-users mailing listFreeipa-users at redhat.comhttps://www.redhat.com/mailman/listinfo/freeipa-users
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20130517/9a7cafba/attachment.htm>