Bug 728502

Summary:	WinSync: DS access log is keep printing Search results for the entry which is already deleted.
Product:	[Fedora] Fedora	Reporter:	Sankar Ramalingam <sramling>
Component:	389-ds-base	Assignee:	Rich Megginson <rmeggins>
Status:	CLOSED NOTABUG	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	14	CC:	ckannan, edewata, nhosoi, nkinder, rmeggins
Target Milestone:	---	Keywords:	screened
Target Release:	---
Hardware:	All
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2011-08-08 21:33:51 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:

Description Sankar Ramalingam 2011-08-05 11:21:38 UTC

Description of problem: DS access log keeps printing the error messages for the entries which were deleted from the AD/DS containers.


Version-Release number of selected component (if applicable):


How reproducible: Consistently.


Steps to Reproduce:
1. Install 389-ds-base latest packages and configure WinSync, bi-directional.
2. Run "Initiate Full-Resynchronization" to sync entries from both sides.
3. Once the users are in sync at both sides, create 100 users at DS.
4. Once the newly created users synced, delete them from DS.
5. Make sure the entries are deleted from AD as well.
6. Create few new users at AD and DS and do some MOD/DEL operations.
7. Keep checking the access logs.

Access logs keep printing the Search Results for the entries which were already deleted and doesn't exist any more.

This keeps coming even after DS restart.
  
Actual results: Access logs keep printing the Search Results for the entries which were already deleted and doesn't exist any more.


Expected results: Access log should suppress these messages, since its not valid.


Additional info: 
 attrs=ALL
[05/Aug/2011:13:33:56 -0400] conn=713 op=311 RESULT err=0 tag=101 nentries=0 etime=0
[05/Aug/2011:13:33:56 -0400] conn=713 op=312 SRCH base="dc=pass_sync,dc=com" scope=2 filter="(ntUserDomainId=fromDSDelCheck4)" attrs=ALL
[05/Aug/2011:13:33:56 -0400] conn=713 op=312 RESULT err=0 tag=101 nentries=0 etime=0
[05/Aug/2011:13:33:56 -0400] conn=713 op=313 SRCH base="dc=pass_sync,dc=com" scope=2 filter="(ntUserDomainId=fromDSDelCheck3)" attrs=ALL
[05/Aug/2011:13:33:56 -0400] conn=713 op=313 RESULT err=0 tag=101 nentries=0 etime=0
[05/Aug/2011:13:33:56 -0400] conn=713 op=314 SRCH base="dc=pass_sync,dc=com" scope=2 filter="(ntUserDomainId=fromDSDelCheck2)" attrs=ALL
[05/Aug/2011:13:33:56 -0400] conn=713 op=314 RESULT err=0 tag=101 nentries=0 etime=0
[05/Aug/2011:13:33:56 -0400] conn=713 op=315 SRCH base="dc=pass_sync,dc=com" scope=2 filter="(ntUserDomainId=fromDSDelCheck1)"


These messages kind of misleads the end-user about the which entry is present and which entry is deleted.

Comment 1 Nathan Kinder 2011-08-05 14:41:17 UTC

(In reply to comment #0)

>  attrs=ALL
> [05/Aug/2011:13:33:56 -0400] conn=713 op=311 RESULT err=0 tag=101 nentries=0
> etime=0
> [05/Aug/2011:13:33:56 -0400] conn=713 op=312 SRCH base="dc=pass_sync,dc=com"
> scope=2 filter="(ntUserDomainId=fromDSDelCheck4)" attrs=ALL
> [05/Aug/2011:13:33:56 -0400] conn=713 op=312 RESULT err=0 tag=101 nentries=0
> etime=0
> [05/Aug/2011:13:33:56 -0400] conn=713 op=313 SRCH base="dc=pass_sync,dc=com"
> scope=2 filter="(ntUserDomainId=fromDSDelCheck3)" attrs=ALL
> [05/Aug/2011:13:33:56 -0400] conn=713 op=313 RESULT err=0 tag=101 nentries=0
> etime=0
> [05/Aug/2011:13:33:56 -0400] conn=713 op=314 SRCH base="dc=pass_sync,dc=com"
> scope=2 filter="(ntUserDomainId=fromDSDelCheck2)" attrs=ALL
> [05/Aug/2011:13:33:56 -0400] conn=713 op=314 RESULT err=0 tag=101 nentries=0
> etime=0
> [05/Aug/2011:13:33:56 -0400] conn=713 op=315 SRCH base="dc=pass_sync,dc=com"
> scope=2 filter="(ntUserDomainId=fromDSDelCheck1)"

These are actual operations that are coming in from an external client (likely the PassSync Service on the AD system).  We should not suppress them, as the access log should log all incoming external operations.  These messages are not really misleading, as the searches are not finding any matches (as shown by nentries=0).

I believe what happened here was that you deleted all of the entries before the PassSync Service was able to process through it's changelog to verify that it was in sync with DS.  The PassSync service will go into incremental backoff mode and should ultimately abandon these changes.  This is by design, and does not look like a bug.

Comment 2 Nathan Kinder 2011-08-08 21:33:41 UTC

Closing as NOTABUG.  This is the expected behavior, as descibed in comment#1.