Bug 729717

Summary: Windows sync logs errors when a delete is synced from AD
Product: [Retired] 389 Reporter: Nathan Kinder <nkinder>
Component: Replication - GeneralAssignee: Nathan Kinder <nkinder>
Status: CLOSED CURRENTRELEASE QA Contact: Ben Levenson <benl>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 1.2.9CC: nhosoi, rmeggins
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-12-10 18:40:59 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 690318, 708096, 729838    
Attachments:
Description Flags
Patch nkinder: review?, rmeggins: review+

Description Nathan Kinder 2011-08-10 15:59:24 UTC 
When a user delete operation is synced from AD->DS, the following messages are logged in the DS error log at the fatal log level:

------------------------------------------------------------------------------
[10/Aug/2011:08:22:06 -0700] NSMMReplicationPlugin - Could not retrieve entry from Windows using search base [<GUID=c20e55507a39ee4aa53a8024687466e2>] scope [0] filter [(objectclass=*)]: error 32:No such object
[10/Aug/2011:08:22:06 -0700] NSMMReplicationPlugin - Could not retrieve entry from Windows using search base [<GUID=c20e55507a39ee4aa53a8024687466e2>] scope [0] filter [(objectclass=*)]: error 32:No such object
------------------------------------------------------------------------------

Replication level logging shows that at least one of these errors are related to enabling the account, which we shouldn't be trying to do for a delete:

------------------------------------------------------------------------------
[09/Aug/2011:15:18:32 -0700] NSMMReplicationPlugin - changelog program - agmt="cn=meTo10.14.54.184389" (10:389): CSN 4e41b0fb000000010000 found, position set for replay
[09/Aug/2011:15:18:32 -0700] agmt="cn=meTo10.14.54.184389" (10:389) - load=1 rec=1 csn=4e41b236000100010000
[09/Aug/2011:15:18:32 -0700] NSMMReplicationPlugin - agmt="cn=meTo10.14.54.184389" (10:389): windows_replay_update: Looking at delete operation local dn="uid=deleteme,ou=people,dc=example,dc=com" (ours,user,not group)
[09/Aug/2011:15:18:32 -0700] NSMMReplicationPlugin - agmt="cn=meTo10.14.54.184389" (10:389): map_entry_dn_outbound: looking for AD entry for DS dn="nsuniqueid=ab112e01-c2d411e0-9734812a-3e1fdb92,uid=deleteme,ou=People,dc=example,dc=com" guid="29d3c7efd7d5c94b9994f0ce0717c13b"
[09/Aug/2011:15:18:32 -0700] - Calling windows entry search request plugin
[09/Aug/2011:15:18:32 -0700] NSMMReplicationPlugin - Could not retrieve entry from Windows using search base [<GUID=29d3c7efd7d5c94b9994f0ce0717c13b>] scope [0] filter [(objectclass=*)]: error 32:No such object
[09/Aug/2011:15:18:32 -0700] NSMMReplicationPlugin - agmt="cn=meTo10.14.54.184389" (10:389): map_entry_dn_outbound: return code -1 from search for AD entry dn="<GUID=29d3c7efd7d5c94b9994f0ce0717c13b>" or dn="(null)"
[09/Aug/2011:15:18:32 -0700] NSMMReplicationPlugin - agmt="cn=meTo10.14.54.184389" (10:389): map_entry_dn_outbound: entry not found - rc -1
[09/Aug/2011:15:18:32 -0700] NSMMReplicationPlugin - agmt="cn=meTo10.14.54.184389" (10:389): windows_replay_update: Processing delete operation local dn="uid=deleteme,ou=people,dc=example,dc=com" remote dn="<GUID=29d3c7efd7d5c94b9994f0ce0717c13b>"
[09/Aug/2011:15:18:32 -0700] NSMMReplicationPlugin - agmt="cn=meTo10.14.54.184389" (10:389): Received result code 0 (0000208D: NameErr: DSID-031001A8, problem 2001 (NO_OBJECT), data 0, best match of: 	'' ) for delete operation 
[09/Aug/2011:15:18:32 -0700] NSMMReplicationPlugin - agmt="cn=meTo10.14.54.184389" (10:389): windows_replay_update: deleted remote entry, dn="<GUID=29d3c7efd7d5c94b9994f0ce0717c13b>", result=0
[09/Aug/2011:15:18:32 -0700] - Calling windows entry search request plugin
[09/Aug/2011:15:18:32 -0700] NSMMReplicationPlugin - Could not retrieve entry from Windows using search base [<GUID=29d3c7efd7d5c94b9994f0ce0717c13b>] scope [0] filter [(objectclass=*)]: error 32:No such object
[09/Aug/2011:15:18:32 -0700] NSMMReplicationPlugin - agmt="cn=meTo10.14.54.184389" (10:389): New Windows entry <GUID=29d3c7efd7d5c94b9994f0ce0717c13b> will be enabled.
[09/Aug/2011:15:18:32 -0700] NSMMReplicationPlugin - agmt="cn=meTo10.14.54.184389" (10:389): Received result code 32 (0000208D: NameErr: DSID-031001A8, problem 2001 (NO_OBJECT), data 0, best match of: 	'' ) for modify operation 
[09/Aug/2011:15:18:32 -0700] NSMMReplicationPlugin - agmt="cn=meTo10.14.54.184389" (10:389): Consumer failed to replay change (uniqueid ab112e01-c2d411e0-9734812a-3e1fdb92, CSN 4e41b236000100010000): No such object. Skipping.
------------------------------------------------------------------------------

These errors do not block syncing future changes, but we should not have errors like this at the fatal log level for normal sync operations.  We also should not be trying to enable an account for a delete operation.
Comment 1 Nathan Kinder 2011-08-10 21:21:28 UTC 
Created attachment 517697 [details]
Patch
Comment 2 Nathan Kinder 2011-08-10 22:15:35 UTC 
Pushed to master.  Thanks to Rich for his review!

Counting objects: 25, done.
Delta compression using up to 2 threads.
Compressing objects: 100% (16/16), done.
Writing objects: 100% (16/16), 2.44 KiB, done.
Total 16 (delta 12), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/ds.git
   d7d0b2a..a150e8e  master -> master