Bug 728502 - WinSync: DS access log is keep printing Search results for the entry which is already deleted.
Summary: WinSync: DS access log is keep printing Search results for the entry which is...
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora
Classification: Fedora
Component: 389-ds-base
Version: 14
Hardware: All
OS: Linux
unspecified
medium
Target Milestone: ---
Assignee: Rich Megginson
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2011-08-05 11:21 UTC by Sankar Ramalingam
Modified: 2011-08-15 20:53 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2011-08-08 21:33:51 UTC


Attachments (Terms of Use)

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.


Note You need to log in before you can comment on or make changes to this bug.