Bug 728502 - WinSync: DS access log is keep printing Search results for the entry which is already deleted.
WinSync: DS access log is keep printing Search results for the entry which is...
Status: CLOSED NOTABUG
Product: Fedora
Classification: Fedora
Component: 389-ds-base (Show other bugs)
14
All Linux
unspecified Severity medium
: ---
: ---
Assigned To: Rich Megginson
Fedora Extras Quality Assurance
: screened
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2011-08-05 07:21 EDT by Sankar Ramalingam
Modified: 2011-08-15 16:53 EDT (History)
5 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2011-08-08 17:33:51 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Sankar Ramalingam 2011-08-05 07:21:38 EDT
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 10:41:17 EDT
(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 17:33:41 EDT
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.