On Nov 10, 2009, at 3:25 PM, Rich Megginson wrote:
No. Check the access log to see what operations were submitted to
the directory server at or around [10/Nov/2009:08:56:27 -0500]
Are your servers in time sync? Is cn=people rewbell gertrude the
agreement that sends updates to the master that is having the
spontaneous import problem?
Yes, "cn=people rewbell gertrude" is that agreement. We name our
agreements with the name of the database ("people") followed by the
name of the source server ("rewbell") followed by the name of the
destination server ("gertrude"). Gertrude is the master that had the
spontaneous import problem.
We have ntpd running on all our machines, so all times should be in
sync.
We have a lot going on, but I found the following in the access log on
the problem server:
[10/Nov/2009:08:55:19 -0500] conn=158624 op=71 RESULT err=0 tag=103
nentries=0 etime=0 csn=4af96f38000000370000
[10/Nov/2009:08:55:19 -0500] conn=158624 op=72 MOD
dn
=
"gtdirguid
=54e468fd7520dbdb1da52263fb4a6576,ou=people,dc=gted,dc=gatech,dc=edu"
[10/Nov/2009:08:55:19 -0500] conn=158624 op=72 RESULT err=0 tag=103
nentries=0 etime=0 csn=4af96f38000100370000
[10/Nov/2009:08:55:19 -0500] conn=158624 op=73 MOD
dn
=
"gtdirguid
=af56dc17bc397b8371b9eed7d91b2af2,ou=people,dc=gted,dc=gatech,dc=edu"
[10/Nov/2009:08:55:19 -0500] conn=158624 op=73 RESULT err=0 tag=103
nentries=0 etime=0 csn=4af96f38000500370000
[10/Nov/2009:08:55:19 -0500] conn=158624 op=74 MOD
dn
=
"gtdirguid
=5261a6e61f97bca3f2741b428255daf4,ou=people,dc=gted,dc=gatech,dc=edu"
[10/Nov/2009:08:55:19 -0500] conn=158624 op=74 RESULT err=0 tag=103
nentries=0 etime=0 csn=4af96f39000000370000
[10/Nov/2009:08:55:19 -0500] conn=158624 op=75 MOD
dn
=
"gtdirguid
=ad5dddfb9ec4fe230644dc060ce641c7,ou=people,dc=gted,dc=gatech,dc=edu"
[10/Nov/2009:08:55:19 -0500] conn=158624 op=75 RESULT err=0 tag=103
nentries=0 etime=0 csn=4af96f39000100370000
[10/Nov/2009:08:55:19 -0500] conn=158624 op=76 MOD
dn
=
"gtdirguid
=0a87d4434e42edf9df3019b922fe2b63,ou=people,dc=gted,dc=gatech,dc=edu"
[10/Nov/2009:08:55:19 -0500] conn=158624 op=76 RESULT err=0 tag=103
nentries=0 etime=0 csn=4af96f39000200370000
[10/Nov/2009:08:55:20 -0500] conn=158624 op=77 MOD
dn
=
"gtdirguid
=8be9c47e00957f900b69af162cba8adf,ou=people,dc=gted,dc=gatech,dc=edu"
[10/Nov/2009:08:55:20 -0500] conn=158624 op=77 RESULT err=0 tag=103
nentries=0 etime=0 csn=4af96f7b000000370000
[10/Nov/2009:08:55:20 -0500] conn=158624 op=78 MOD
dn
=
"gtdirguid
=beef247b54a6e1289f3e392865e08e17,ou=people,dc=gted,dc=gatech,dc=edu"
[10/Nov/2009:08:55:20 -0500] conn=158624 op=78 RESULT err=0 tag=103
nentries=0 etime=0 csn=4af96f7b000400370000
[10/Nov/2009:08:55:20 -0500] conn=158624 op=79 MOD
dn
=
"gtdirguid
=db2aa7040d3b982cf1a32aad503d7e6f,ou=people,dc=gted,dc=gatech,dc=edu"
[10/Nov/2009:08:55:20 -0500] conn=158624 op=79 RESULT err=0 tag=103
nentries=0 etime=0 csn=4af96f7b000500370000
[10/Nov/2009:08:55:20 -0500] conn=158624 op=80 MOD
dn
=
"gtdirguid
=c9390deb6018475b4d5d5267ba70fb99,ou=people,dc=gted,dc=gatech,dc=edu"
[10/Nov/2009:08:55:20 -0500] conn=158624 op=80 RESULT err=0 tag=103
nentries=0 etime=0 csn=4af96f7b000600370000
[10/Nov/2009:08:55:20 -0500] conn=158624 op=81 EXT
oid="2.16.840.1.113730.3.5.5" name="Netscape Replication End Session"
[10/Nov/2009:08:55:20 -0500] conn=158624 op=81 RESULT err=0 tag=120
nentries=0 etime=0
[10/Nov/2009:08:55:24 -0500] conn=158624 op=83 EXT
oid="2.16.840.1.113730.3.5.3" name="Netscape Replication Start Session"
[10/Nov/2009:08:55:24 -0500] conn=158624 op=83 RESULT err=0 tag=120
nentries=0 etime=0
[10/Nov/2009:08:55:28 -0500] conn=158624 op=84 EXT
oid="2.16.840.1.113730.3.5.3" name="Netscape Replication Start Session"
[10/Nov/2009:08:55:28 -0500] conn=158624 op=84 RESULT err=0 tag=120
nentries=0 etime=0
[10/Nov/2009:08:56:06 -0500] conn=158624 op=86 EXT
oid="2.16.840.1.113730.3.5.3" name="Netscape Replication Start Session"
[10/Nov/2009:08:56:06 -0500] conn=158624 op=87 EXT
oid="2.16.840.1.113730.3.5.3" name="Netscape Replication Start Session"
[10/Nov/2009:08:56:07 -0500] conn=158624 op=87 RESULT err=0 tag=120
nentries=0 etime=1
[10/Nov/2009:08:56:10 -0500] conn=158624 op=88 EXT
oid="2.16.840.1.113730.3.5.3" name="Netscape Replication Start Session"
[10/Nov/2009:08:56:27 -0500] conn=158624 op=88 RESULT err=0 tag=120
nentries=0 etime=17
[10/Nov/2009:08:56:59 -0500] conn=158624 op=89 EXT
oid="2.16.840.1.113730.3.5.3" name="Netscape Replication Start Session"
[10/Nov/2009:08:56:59 -0500] conn=158624 op=89 RESULT err=0 tag=120
nentries=0 etime=0
[10/Nov/2009:08:57:59 -0500] conn=158624 op=91 UNBIND
[10/Nov/2009:08:57:59 -0500] conn=158624 op=91 fd=64 closed - U1
You can see that replication was working until around 8:55:20 and then
there's a series of "Replication Start Session" operations with no
corresponding "End Session". The log messages from the supplier
server (which I sent in the previous mail) seem to indicate that some
communication problems may have occurred (all those "Unable to receive
response" logs).
Digging through the audit-log, I found the following:
time: 20091110085608
dn: cn="ou=people,dc=gted,dc=gatech,dc=edu",cn=mapping tree,cn=config
changetype: modify
replace: nsslapd-referral
nsslapd-referral: ldap://rewbell.iam.gatech.edu:389/ou%3Dpeople%2Cdc
%3Dgted%2C
dc%3Dgatech%2Cdc%3Dedu
-
replace: modifiersname
modifiersname: cn=server,cn=plugins,cn=config
-
replace: modifytimestamp
modifytimestamp: 20091110135607Z
-
time: 20091110085610
dn: cn="ou=people,dc=gted,dc=gatech,dc=edu",cn=mapping tree,cn=config
changetype: modify
replace: nsslapd-referral
nsslapd-referral: ldaps://rw.gted.gatech.edu:636/
ou=people,dc=gted,dc=gatech,d
c=edu
-
replace: modifiersname
modifiersname: cn=server,cn=plugins,cn=config
-
replace: modifytimestamp
modifytimestamp: 20091110135610Z
-
time: 20091110085625
dn: cn="ou=people,dc=gted,dc=gatech,dc=edu",cn=mapping tree,cn=config
changetype: modify
replace: nsslapd-state
nsslapd-state: referral
-
replace: modifiersname
modifiersname: cn=server,cn=plugins,cn=config
-
replace: modifytimestamp
modifytimestamp: 20091110135625Z
-
time: 20091110085626
dn: cn="ou=people,dc=gted,dc=gatech,dc=edu",cn=mapping tree,cn=config
changetype: modify
replace: nsslapd-state
nsslapd-state: backend
-
replace: modifiersname
modifiersname: cn=server,cn=plugins,cn=config
-
replace: modifytimestamp
modifytimestamp: 20091110135626Z
-
The referral for that suffix first gets changed "ldap://
rewbell.iam.gatech.edu:389/...", which isn't right.
Then it get changed to "ldaps://rw.gted.gatech.edu:636/..." which is
correct (and what we have configured in the nsDS5ReplicaReferral
attribute).
Then the state gets changed a couple of times too. Not sure if this
is a cause or effect of the problem we're seeing, but I'm inclined to
think it's an effect of the server thinking it's been told to do an
import, not a cause. IMHO, of course.
--
389 users mailing list
389-users@xxxxxxxxxx
https://www.redhat.com/mailman/listinfo/fedora-directory-users
