6:01 p.m.
I've been testing the password policy module lately. I updated our
development LDAP infrastructure Monday, basically loading and enabling the
module, adding a default policy:
dn: cn=default,ou=ppolicy,dc=csupomona,dc=edu
cn: default
objectClass: organizationalRole
objectClass: pwdPolicy
pwdAttribute: userPassword
pwdLockout: TRUE
pwdLockoutDuration: 1800
pwdMaxFailure: 100
pwdFailureCountInterval: 300
And a policy specific for service accounts:
dn: cn=serviceaccount,ou=ppolicy,dc=csupomona,dc=edu
cn: serviceaccount
objectClass: organizationalRole
objectClass: pwdPolicy
pwdAttribute: userPassword
After some initial testing and determining that the current implementation
is not suitable for account lockouts, I haven't touched it since Monday.
Yesterday, I started getting alerts that the systems were low on memory, and
upon looking, found extremely bloated slapd processes. Next, I started
getting alerts that the accesslog mdb was running out of space.
Upon investigation, I found that the service account that is used to gather
statistics was generating a considerable amount of churn every time it
authenticated (every 30 seconds). This account was explicitly configured to
use the service account password policy:
dn: cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu
objectClass: person
cn: slapd-monitor
sn: LDAP monitoring account
pwdPolicySubentry: cn=serviceaccount,ou=ppolicy,dc=csupomona,dc=edu
Which should be pretty much "do nothing". (I realize now that this policy
will actually result in pwdFailureTime entries being created for failed
authentications, and accumulating forever until a successful authentication,
but there are no failed authentications for this service account, only
successful ones, in this case).
There were 1662836 entries in the access log for this dn since Monday that
as far as I can tell solely change the CSN:
dn: reqStart=20140502031556.000000Z,cn=accesslog
objectClass: auditModify
structuralObjectClass: auditModify
reqStart: 20140502031556.000000Z
reqEnd: 20140502031558.000000Z
reqType: modify
reqSession: 2
reqAuthzID: cn=ldaproot,dc=csupomona,dc=edu
reqDN: cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu
reqResult: 0
reqMod: entryCSN:= 20140501211559.348458Z#000000#003#000000
reqMod: modifiersName:= cn=ldaproot,dc=csupomona,dc=edu
reqMod: modifyTimestamp:= 20140501211559Z
reqEntryUUID: c16729b0-ce1e-4f9d-9123-e0b8f115133c
entryUUID: 240ec245-0bac-4e20-b387-19243f720674
creatorsName: cn=accesslog
createTimestamp: 20140501211559Z
entryCSN: 20140501211559.348458Z#000000#003#000000
modifiersName: cn=accesslog
modifyTimestamp: 20140501211559Z
This explains why the accesslog was running out of space, it was full of
these. It doesn't explain why the slapd process exploded in memory use,
unless I suppose the steady-state memory usage of a slapd this busy
processing replication is higher than one that's not quite so busy.
But I'm confused as to why loading the password policy module, for an
account with a policy configured to pretty much not do anything, results in
a modification of the CSN for every authentication?
I'm going to go peruse the source code to see if I can determine what's
going on, but any expert opinions would be most welcome.
Thanks much.
7:22 p.m.
--On May 2, 2014 at 6:01:02 PM -0700 "Paul B. Henson" <henson(a)acm.org>
wrote:
I've been testing the password policy module lately. I updated
our
development LDAP infrastructure Monday, basically loading and enabling the
module, adding a default policy:
This explains why the accesslog was running out of space, it was full of
these. It doesn't explain why the slapd process exploded in memory use,
unless I suppose the steady-state memory usage of a slapd this busy
processing replication is higher than one that's not quite so busy.
But I'm confused as to why loading the password policy module, for an
account with a policy configured to pretty much not do anything, results
in a modification of the CSN for every authentication?
I'm going to go peruse the source code to see if I can determine what's
going on, but any expert opinions would be most welcome.
I would suggest (if you haven't) enabling sync replication logging
(loglevel sync) in addition to whatever other loglevels you have. I've
found it is possible to send MMR into an endless loop in some cases
recently. I'm still working on the reproduction case for it, but it
happens 100% of the time for a client of ours eventually.
--Quanah
--
Quanah Gibson-Mount
Server Architect
Zimbra, Inc
--------------------
Zimbra :: the leader in open source messaging and collaboration
7:40 p.m.
From: Quanah Gibson-Mount
Sent: Friday, May 02, 2014 7:22 PM
I would suggest (if you haven't) enabling sync replication logging
(loglevel sync) in addition to whatever other loglevels you have. I've
found it is possible to send MMR into an endless loop in some cases
recently. I'm still working on the reproduction case for it, but it
happens 100% of the time for a client of ours eventually.
Ouch. By any chance, does your client use the password policy module? I've
never had a problem like this until I started testing with it in my
development instance.
I've enabled the additional logging level and reset my testing to the
beginning, and will see if it does it again. When it happens to your client
in production, how do you resolve it?
Thanks.
9:43 p.m.
--On May 5, 2014 at 7:40:31 PM -0700 "Paul B. Henson" <henson(a)acm.org>
wrote:
> From: Quanah Gibson-Mount
> Sent: Friday, May 02, 2014 7:22 PM
>
> I would suggest (if you haven't) enabling sync replication logging
> (loglevel sync) in addition to whatever other loglevels you have. I've
> found it is possible to send MMR into an endless loop in some cases
> recently. I'm still working on the reproduction case for it, but it
> happens 100% of the time for a client of ours eventually.
Ouch. By any chance, does your client use the password policy module? I've
never had a problem like this until I started testing with it in my
development instance.
No, we don't use ppolicy. But the issue for us is arising in a
functionality that is similar to ppolicy that's Zimbra specific.
I've enabled the additional logging level and reset my testing to
the
beginning, and will see if it does it again. When it happens to your
client in production, how do you resolve it?
You can gdb slapd, and manually fix the serverID in the syncinfo structure,
or you can restart all your slapd servers.
--Quanah
--
Quanah Gibson-Mount
Server Architect
Zimbra, Inc
--------------------
Zimbra :: the leader in open source messaging and collaboration
3:07 p.m.
From: Quanah Gibson-Mount
Sent: Tuesday, May 06, 2014 9:43 PM
> beginning, and will see if it does it again. When it happens to your
> client in production, how do you resolve it?
You can gdb slapd, and manually fix the serverID in the syncinfo
structure,
or you can restart all your slapd servers.
How are you detecting when it starts? On my dev system, the first symptom is
massive memory use by the slapd process, followed by an alert that the
accesslog db is over 80% full. Then slapd processes start getting killed off
by the OOM mechanism and my dev environment basically implodes. If it
happened in production, odds are I wouldn't catch it in time to keep things
from going south. How do you trim out the extremely large number of
duplicate entries in the accesslog when you are cleaning up after an
occurrence in one of your production environments?
Hopefully the underlying issue will be sorted out soon. I'm just going to
tell our security guys they are not going to get their account lockouts as
long as the password policy module puts my dev environment into conniptions
:).
Off-topic, is there a secret handshake for the developer list or something
;)? The couple of messages I posted after I subscribed still haven't shown
up, and a couple of inquiries I made on this list about the moderation on
that list were never responded to <sigh>...
Thanks.
3:43 p.m.
--On May 8, 2014 at 3:07:23 PM -0700 "Paul B. Henson" <henson(a)acm.org>
wrote:
> From: Quanah Gibson-Mount
> Sent: Tuesday, May 06, 2014 9:43 PM
>
> > beginning, and will see if it does it again. When it happens to your
> > client in production, how do you resolve it?
>
> You can gdb slapd, and manually fix the serverID in the syncinfo
structure,
> or you can restart all your slapd servers.
How are you detecting when it starts? On my dev system, the first symptom
is massive memory use by the slapd process, followed by an alert that the
accesslog db is over 80% full. Then slapd processes start getting killed
off by the OOM mechanism and my dev environment basically implodes. If it
happened in production, odds are I wouldn't catch it in time to keep
things from going south. How do you trim out the extremely large number of
duplicate entries in the accesslog when you are cleaning up after an
occurrence in one of your production environments?
The massive memory consumption would be due to the switch to refresh mode.
On the environments I've been using, OOM is disabled (horrible concept), so
there's no killing of slapd itself. As for cleaning the accesslog, I stop
all servers, move it aside, and restart (it'll create a new accesslog db).
Hopefully the underlying issue will be sorted out soon. I'm just
going to
tell our security guys they are not going to get their account lockouts as
long as the password policy module puts my dev environment into
conniptions :).
Yeah, it isn't specific to ppolicy because I don't use it. I'm trying to
get this happening in my dev env now.
Off-topic, is there a secret handshake for the developer list or
something
;)? The couple of messages I posted after I subscribed still haven't shown
up, and a couple of inquiries I made on this list about the moderation on
that list were never responded to <sigh>...
Nope... I think I have moderator privs even, but I don't recall where I
have to log into to do it. :/ There's a couple of people I can bug about
it though.
--Quanah
--
Quanah Gibson-Mount
Server Architect
Zimbra, Inc
--------------------
Zimbra :: the leader in open source messaging and collaboration
7 p.m.
--On May 8, 2014 at 3:43:06 PM -0700 Quanah Gibson-Mount
<quanah(a)zimbra.com> wrote:
>>> You can gdb slapd, and manually fix the serverID in the
syncinfo
> structure,
>> or you can restart all your slapd servers.
>
> How are you detecting when it starts? On my dev system, the first symptom
> is massive memory use by the slapd process, followed by an alert that the
> accesslog db is over 80% full. Then slapd processes start getting killed
> off by the OOM mechanism and my dev environment basically implodes. If it
> happened in production, odds are I wouldn't catch it in time to keep
> things from going south. How do you trim out the extremely large number
> of duplicate entries in the accesslog when you are cleaning up after an
> occurrence in one of your production environments?
The massive memory consumption would be due to the switch to refresh
mode. On the environments I've been using, OOM is disabled (horrible
concept), so there's no killing of slapd itself. As for cleaning the
accesslog, I stop all servers, move it aside, and restart (it'll create a
new accesslog db).
> Hopefully the underlying issue will be sorted out soon. I'm just going to
> tell our security guys they are not going to get their account lockouts
> as long as the password policy module puts my dev environment into
> conniptions :).
Yeah, it isn't specific to ppolicy because I don't use it. I'm trying to
get this happening in my dev env now.
Hi Paul,
I haven't had any luck in reproducing it in my lab. I'd be curious to know
if you could share your cn=config setup (minus rootdn passwords), and
describe how you are triggering the ppolicy updates in the lab. I need to
find a way to reliably trigger the problem so it can be debugged under GDB.
If you're up to gdb debugging, then the first step is to gdb slapd, and set
a watchpoint on the serverID, so you can see at which point it gets set to
'0' instead of the the correct sid value.
Thanks,
Quanah
--
Quanah Gibson-Mount
Server Architect
Zimbra, Inc
--------------------
Zimbra :: the leader in open source messaging and collaboration
2:08 p.m.
From: Quanah Gibson-Mount
Sent: Monday, May 12, 2014 7:00 PM
I haven't had any luck in reproducing it in my lab. I'd be curious to
know
if you could share your cn=config setup (minus rootdn passwords),
and
describe how you are triggering the ppolicy updates in the lab.
I'll send you my config off list. The first time this happened, I had
enabled the password policy module and configured two policies, one as
default, and one explicitly configured on about a dozen service accounts. I
played with that for about an hour until I realized the authentication
failure granularity was insufficient to meet our account lockout needs. Then
it just sat basically idle, and maybe 6-8 hours later it started ramping up
memory use and blew up. The second time, I reloaded our dev environment with
a snapshot of production data, and started it up with the password policy
module loaded, but no actual password policies defined. Once again, within a
few hours it started spinning. I'll see if I can get some minimal
configuration that reliably reproduces this failure, I don't think our ISO
would be on board with shipping you a copy of our production data :).
If you're up to gdb debugging, then the first step is to gdb
slapd, and
set
a watchpoint on the serverID, so you can see at which point it gets
set to
'0' instead of the the correct sid value.
My current binaries don't have debugging symbols, but I will build a binary
with debugging enabled and give it a try if I get the time. So you mean the
slap_serverID variable defined in servers/slapd/ctxcsn.c?
2:21 p.m.
--On May 13, 2014 at 2:08:30 PM -0700 "Paul B. Henson" <henson(a)acm.org>
wrote:
> From: Quanah Gibson-Mount
> Sent: Monday, May 12, 2014 7:00 PM
>
> I haven't had any luck in reproducing it in my lab. I'd be curious to
know
> if you could share your cn=config setup (minus rootdn passwords), and
> describe how you are triggering the ppolicy updates in the lab.
I'll send you my config off list. The first time this happened, I had
enabled the password policy module and configured two policies, one as
default, and one explicitly configured on about a dozen service accounts.
I played with that for about an hour until I realized the authentication
failure granularity was insufficient to meet our account lockout needs.
Then it just sat basically idle, and maybe 6-8 hours later it started
ramping up memory use and blew up. The second time, I reloaded our dev
environment with a snapshot of production data, and started it up with
the password policy module loaded, but no actual password policies
defined. Once again, within a few hours it started spinning. I'll see if
I can get some minimal configuration that reliably reproduces this
failure, I don't think our ISO would be on board with shipping you a copy
of our production data :).
That's interesting... it was totally idle (doing nothing at all?).
> If you're up to gdb debugging, then the first step is to gdb
slapd, and
set
> a watchpoint on the serverID, so you can see at which point it gets set
> to '0' instead of the the correct sid value.
My current binaries don't have debugging symbols, but I will build a
binary with debugging enabled and give it a try if I get the time. So you
mean the slap_serverID variable defined in servers/slapd/ctxcsn.c?
No, s_sid in the syncops struct in syncprov.c. That is what was flipping
from [1|2|3] -> 0 on my systems.
--Quanah
--
Quanah Gibson-Mount
Server Architect
Zimbra, Inc
--------------------
Zimbra :: the leader in open source messaging and collaboration
2:30 p.m.
--On May 13, 2014 at 2:21:03 PM -0700 Quanah Gibson-Mount
<quanah(a)zimbra.com> wrote:
> My current binaries don't have debugging symbols, but I will build a
> binary with debugging enabled and give it a try if I get the time. So you
> mean the slap_serverID variable defined in servers/slapd/ctxcsn.c?
No, s_sid in the syncops struct in syncprov.c. That is what was flipping
from [1|2|3] -> 0 on my systems.
For example, here's what I saw on a problematic master:
(gdb) print *so
$1 = {s_next = 0x0, s_base = {bv_len = 12, bv_val = 0xa857d70
"cn=accesslog"}, s_eid = 1, s_op = 0xc13a300, s_rid = 0, s_sid = 0,
s_filterstr = {bv_len = 46, bv_val = 0x42ca1f8 ""}, s_flags = 34, s_inuse =
2, s_res = 0x0, s_restail = 0x0, s_mutex = {__data = {__lock = 0, __count =
0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __list = {__prev =
0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>,
We can see here that s_sid = 0 instead of 2 (The server ID of this master)
The other issue here is that it has also lots the rid (s_rid=0). We use
rids of 100 and up in my configurations. So you can watch on both of those,
and see what triggers first.
--Quanah
--
Quanah Gibson-Mount
Server Architect
Zimbra, Inc
--------------------
Zimbra :: the leader in open source messaging and collaboration
5:46 p.m.
From: Quanah Gibson-Mount
Sent: Tuesday, May 13, 2014 2:21 PM
That's interesting... it was totally idle (doing nothing at all?).
Yes, the absolute only activity after slappadd'ing the data and starting the
server were the automated accesses to the monitoring backend by a service
account.
No, s_sid in the syncops struct in syncprov.c. That is what was
flipping
from [1|2|3] -> 0 on my systems.
Ah, ok.
6:09 p.m.
--On May 13, 2014 at 5:46:38 PM -0700 "Paul B. Henson" <henson(a)acm.org>
wrote:
> From: Quanah Gibson-Mount
> Sent: Tuesday, May 13, 2014 2:21 PM
>
> That's interesting... it was totally idle (doing nothing at all?).
Yes, the absolute only activity after slappadd'ing the data and starting
the server were the automated accesses to the monitoring backend by a
service account.
Ok. Hm, I was wondering if it was related to the accesslog purge, but your
purge only happens once a day for things > 1 week old, so that wouldn't
have hit in such a short term.
--Quanah
--
Quanah Gibson-Mount
Server Architect
Zimbra, Inc
--------------------
Zimbra :: the leader in open source messaging and collaboration
1:51 p.m.
From: Quanah Gibson-Mount
Sent: Thursday, May 08, 2014 3:43 PM
Nope... I think I have moderator privs even, but I don't recall where I
have to log into to do it. :/ There's a couple of people I can bug about
it though.
The list administrative interface is at:
http://www.openldap.org/lists/mm/admin/openldap-devel
But you probably also don't recall the password to get into it ;).
1:58 p.m.
--On May 13, 2014 at 1:51:30 PM -0700 "Paul B. Henson" <henson(a)acm.org>
wrote:
> From: Quanah Gibson-Mount
> Sent: Thursday, May 08, 2014 3:43 PM
>
> Nope... I think I have moderator privs even, but I don't recall where I
> have to log into to do it. :/ There's a couple of people I can bug about
> it though.
The list administrative interface is at:
http://www.openldap.org/lists/mm/admin/openldap-devel
But you probably also don't recall the password to get into it ;).
Very true. ;)
--Quanah
--
Quanah Gibson-Mount
Server Architect
Zimbra, Inc
--------------------
Zimbra :: the leader in open source messaging and collaboration
1:39 p.m.
On Fri, May 02, 2014 at 07:22:10PM -0700, Quanah Gibson-Mount wrote:
I would suggest (if you haven't) enabling sync replication
logging
(loglevel sync) in addition to whatever other loglevels you have.
Ok, so I reloaded my dev environment with a fresh snapshot of production
data, and started it back up. After a couple hours, all of the servers
started producing this entry in the accesslog db:
dn: reqStart=20140506065034.000024Z,cn=accesslog
objectClass: auditModify
structuralObjectClass: auditModify
reqStart: 20140506065034.000024Z
reqEnd: 20140506065034.000028Z
reqType: modify
reqSession: 3
reqAuthzID: cn=ldaproot,dc=csupomona,dc=edu
reqDN: cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu
reqResult: 0
reqMod: entryCSN:= 20140506065034.590711Z#000000#003#000000
reqMod: modifiersName:= cn=ldaproot,dc=csupomona,dc=edu
reqMod: modifyTimestamp:= 20140506065034Z
reqEntryUUID: c16729b0-ce1e-4f9d-9123-e0b8f115133c
entryUUID: f1ff441b-ed2a-4623-a7b6-55931f2f28de
creatorsName: cn=accesslog
createTimestamp: 20140506065034Z
entryCSN: 20140506065034.590711Z#000000#003#000000
modifiersName: cn=accesslog
modifyTimestamp: 20140506065034Z
The reqStart, reqEnd and entryUUID attributes changed, but the reqMod,
entryCSN, and modifyTimestamp are all the same on all entries on all servers.
This continued for hours on end, until the servers ran out of memory and
the slapd process was killed:
dn: reqStart=20140506102707.000012Z,cn=accesslog
objectClass: auditModify
structuralObjectClass: auditModify
reqStart: 20140506102707.000012Z
reqEnd: 20140506102709.000000Z
reqType: modify
reqSession: 2
reqAuthzID: cn=ldaproot,dc=csupomona,dc=edu
reqDN: cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu
reqResult: 0
reqMod: entryCSN:= 20140506065034.590711Z#000000#003#000000
reqMod: modifiersName:= cn=ldaproot,dc=csupomona,dc=edu
reqMod: modifyTimestamp:= 20140506065034Z
reqEntryUUID: c16729b0-ce1e-4f9d-9123-e0b8f115133c
entryUUID: 9c332ed5-f39c-40d1-a8c1-1feb936c1d81
creatorsName: cn=accesslog
createTimestamp: 20140506065034Z
entryCSN: 20140506065034.590711Z#000000#003#000000
modifiersName: cn=accesslog
modifyTimestamp: 20140506065034Z
On the server with id 3, the source of this CSN, logs show:
May 5 23:50:34 pip-dev slapd[31584]: conn=8558 op=0 BIND
dn="cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu" method=128
May 5 23:50:34 pip-dev slapd[31584]: slap_queue_csn: queing
0x7feb09ffbbd0 20140506065034.590711Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: slap_queue_csn: queing
0x7feafc002af0 20140506065034.590711Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: slap_graduate_commit_csn: removing
0x7feafc30dd20 20140506065034.590711Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: slap_graduate_commit_csn: removing
0x7feafc321610 20140506065034.590711Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: conn=8558 op=0 RESULT tag=97
err=49 text=
May 5 23:50:34 pip-dev slapd[31584]: syncprov_sendresp: to=002,
cookie=rid=003,sid=003,csn=20140506065034.590711Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: syncprov_sendresp: to=001,
cookie=rid=003,sid=003,csn=20140506065034.590711Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: syncprov_sendresp:
cookie=rid=000,sid=003,csn=20140506065034.590711Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: conn=1006 op=245464 ABANDON
msg=245464
May 5 23:50:34 pip-dev slapd[31584]: conn=1006 op=245465 SRCH
base="dc=csupomona,dc=edu" scope=2 deref=0 filter="(objectClass=*)"
May 5 23:50:34 pip-dev slapd[31584]: conn=1006 op=245465 SRCH attr=* +
May 5 23:50:34 pip-dev slapd[31584]: srs csn
20140506065033.649766Z#000000#000#000000
May 5 23:50:34 pip-dev slapd[31584]: log csn
20140506044033.088487Z#000000#000#000000
May 5 23:50:34 pip-dev slapd[31584]: cmp -512, too old
May 5 23:50:34 pip-dev slapd[31584]: log csn
20140506044532.528640Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: cmp -512, too old
May 5 23:50:34 pip-dev slapd[31584]: log csn
20140506044532.602250Z#000000#001#000000
[...]
May 5 23:50:34 pip-dev slapd[31584]: log csn
20140506065034.351114Z#000000#001#000000
May 5 23:50:34 pip-dev slapd[31584]: cmp 0, too old
May 5 23:50:34 pip-dev slapd[31584]: log csn
20140506065034.590711Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: syncprov_search_response:
cookie=rid=003,sid=003,csn=20140506065033.649766Z#000000#000#000000;20140506065034.351114Z#000000#001#000000;20140506065033.164941Z#000000#002#000000;20140506065034.590711Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: conn=1006 op=245465 SEARCH RESULT
tag=101 err=0 nentries=1 text=
May 5 23:50:34 pip-dev slapd[31584]: conn=8558 fd=19 closed (connection
lost)
May 5 23:50:34 pip-dev slapd[31584]: do_syncrep2: rid=002
cookie=rid=000,sid=001,csn=20140506065034.590711Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: do_syncrep2: rid=002 CSN too old,
ignoring 20140506065034.590711Z#000000#003#000000
(reqStart=20140506065034.000024Z,cn=accesslog)
[...]
May 5 23:50:34 pip-dev slapd[31584]: slap_queue_csn: queing
0x7feb2011477b 20140506065034.590711Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: slap_queue_csn: queing
0x7feb2010d880 20140506065034.590711Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: do_syncrep2: rid=003
cookie=rid=003,sid=002,csn=20140506065034.675448Z#000000#000#000000
May 5 23:50:34 pip-dev slapd[31584]: do_syncrep2: rid=003 CSN too old,
ignoring 20140506065034.675448Z#000000#000#000000
(reqStart=20140506065034.000026Z,cn=accesslog)
May 5 23:50:34 pip-dev slapd[31584]: slap_graduate_commit_csn: removing
0x7feb201203b0 20140506065034.590711Z#000000#003#000000
May 5 23:50:34 pip-dev slapd[31584]: slap_graduate_commit_csn: removing
0x7feb20126830 20140506065034.590711Z#000000#003#000000
On another server, the first instance of this CSN shows up:
May 5 23:50:34 fosse-dev slapd[7791]: do_syncrep2: rid=003
cookie=rid=000,sid=003,csn=20140506065034.590711Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: slap_queue_csn: queing
0x7fa744104f7d 20140506065034.590711Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: slap_queue_csn: queing
0x7fa74413d590 20140506065034.590711Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: syncprov_matchops: skipping
original sid 003
May 5 23:50:34 fosse-dev slapd[7791]: slap_graduate_commit_csn:
removing 0x7fa7441369d0 20140506065034.590711Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: syncprov_sendresp: to=001,
cookie=rid=001,csn=20140506065034.590711Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: slap_graduate_commit_csn:
removing 0x7fa744136770 20140506065034.590711Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: syncrepl_message_to_op: rid=003
be_modify cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu (0)
May 5 23:50:34 fosse-dev slapd[7791]: slap_queue_csn: queing
0x7fa744134100 20140506065034.590711Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: syncprov_sendresp: to=002,
cookie=rid=001,csn=20140506065034.590711Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: conn=1021 op=2 ABANDON msg=2
May 5 23:50:34 fosse-dev slapd[7791]: conn=1021 op=3 SRCH
base="dc=csupomona,dc=edu" scope=2 deref=0 filter="(objectClass=*)"
May 5 23:50:34 fosse-dev slapd[7791]: conn=1021 op=3 SRCH attr=* +
May 5 23:50:34 fosse-dev slapd[7791]: srs csn
20140506065033.649766Z#000000#000#000000
May 5 23:50:34 fosse-dev slapd[7791]: log csn
20140506044032.985641Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: cmp -512, too old
May 5 23:50:34 fosse-dev slapd[7791]: log csn
20140506044033.088487Z#000000#000#000000
May 5 23:50:34 fosse-dev slapd[7791]: cmp -512, too old
May 5 23:50:34 fosse-dev slapd[7791]: log csn
20140506044532.528640Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: cmp -512, too old
[...]
May 5 23:50:34 fosse-dev slapd[7791]: slap_graduate_commit_csn:
removing 0x7fa744136770 20140506065034.590711
Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: cmp -256, too old
May 5 23:50:34 fosse-dev slapd[7791]: log csn
20140506055533.107369Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: cmp -256, too old
[...]
May 5 23:50:34 fosse-dev slapd[7791]: log csn
20140506062531.905240Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: cmp -3, too old
May 5 23:50:34 fosse-dev slapd[7791]: do_syncrep2: rid=002
cookie=rid=002,sid=002,csn=20140506065034.590711Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: log csn
20140506062532.031640Z#000000#001#000000
May 5 23:50:34 fosse-dev slapd[7791]: cmp -3, too old
[...]
May 5 23:50:34 fosse-dev slapd[7791]: log csn
20140506065034.590711Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: syncprov_search_response:
cookie=rid=001,csn=20140506065033.649766Z#000000#000#000000;20140506065034.351114Z#000000#001#000000;20140506065033.164941Z#000000#002#000000;20140506065034.590711Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: conn=1021 op=3 SEARCH RESULT
tag=101 err=0 nentries=1 text=
May 5 23:50:34 fosse-dev slapd[7791]: do_syncrep2: rid=001
cookie=rid=001,sid=001,csn=20140506065034.590711Z#000000#003#000000
May 5 23:50:34 fosse-dev slapd[7791]: do_syncrep2: rid=001 CSN too old,
ignoring 20140506065034.590711Z#000000#003#000000
(reqStart=20140506065034.000024Z,cn=accesslog)
And then they all just go on forever, queing the CSN and removing it.
Any thoughts on what's blowing up?
Thanks...
9:42 p.m.
--On May 6, 2014 at 1:39:22 PM -0700 "Paul B. Henson" <henson(a)acm.org>
wrote:
On Fri, May 02, 2014 at 07:22:10PM -0700, Quanah Gibson-Mount wrote:
> I would suggest (if you haven't) enabling sync replication logging
> (loglevel sync) in addition to whatever other loglevels you have.
Ok, so I reloaded my dev environment with a fresh snapshot of production
data, and started it back up. After a couple hours, all of the servers
started producing this entry in the accesslog db:
May 5 23:50:34 fosse-dev slapd[7791]: syncprov_search_response:
cookie=rid=001,csn=20140506065033.649766Z#000000#000#000000;
Any thoughts on what's blowing up?
Looks like it lost the serverID, which is exactly what I saw. Note the
#000#
--Quanah
--
Quanah Gibson-Mount
Server Architect
Zimbra, Inc
--------------------
Zimbra :: the leader in open source messaging and collaboration
9:42 a.m.
--On May 6, 2014 at 9:42:13 PM -0700 Quanah Gibson-Mount
<quanah(a)zimbra.com> wrote:
--On May 6, 2014 at 1:39:22 PM -0700 "Paul B. Henson" <henson(a)acm.org>
wrote:
> On Fri, May 02, 2014 at 07:22:10PM -0700, Quanah Gibson-Mount wrote:
>
>> I would suggest (if you haven't) enabling sync replication logging
>> (loglevel sync) in addition to whatever other loglevels you have.
>
> Ok, so I reloaded my dev environment with a fresh snapshot of production
> data, and started it back up. After a couple hours, all of the servers
> started producing this entry in the accesslog db:
> May 5 23:50:34 fosse-dev slapd[7791]: syncprov_search_response:
> cookie=rid=001,csn=20140506065033.649766Z#000000#000#000000;
> Any thoughts on what's blowing up?
Looks like it lost the serverID, which is exactly what I saw. Note the
#000#
One other thing -- Did any of your servers go into refresh mode prior to
this loop starting?
grep REFRESH in the log.
--Quanah
--
Quanah Gibson-Mount
Server Architect
Zimbra, Inc
--------------------
Zimbra :: the leader in open source messaging and collaboration
2:57 p.m.
On Wed, May 07, 2014 at 09:42:12AM -0700, Quanah Gibson-Mount wrote:
One other thing -- Did any of your servers go into refresh mode prior
to
this loop starting?
Yes, it started logging:
May 5 19:00:38 filmore-dev slapd[7665]: do_syncrep2: rid=001
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:01:48 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync, switching to REFRESH
It continued logging the lost sync messages almost continuously until:
May 5 19:06:16 filmore-dev slapd[7665]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
May 5 19:06:19 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:06:26 filmore-dev slapd[7665]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
May 5 19:06:32 filmore-dev slapd[7665]: do_syncrep2: rid=002
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 20:10:32 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506031032.000017Z,cn=accesslog), switching
to REFRESH
May 5 20:10:32 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 21:30:34 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506043034.000008Z,cn=accesslog), switching
to REFRESH
May 5 21:31:26 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 22:10:36 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506051035.000019Z,cn=accesslog), switching
to REFRESH
May 5 22:10:36 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 22:45:33 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506054533.000016Z,cn=accesslog), switching
to REFRESH
May 5 22:45:33 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 23:10:35 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506061035.000008Z,cn=accesslog), switching
to REFRESH
May 5 23:11:27 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 6 02:15:05 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506075534.000068Z,cn=accesslog), switching
to REFRESH
May 6 02:28:40 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
The others had similar logs:
May 5 19:00:40 fosse-dev slapd[7791]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
May 5 19:00:40 fosse-dev slapd[7791]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
[...]
May 5 19:10:33 fosse-dev slapd[7791]: do_syncrep2: rid=001 delta-sync
lost sync, switching to REFRESH
May 5 19:10:36 fosse-dev slapd[7791]: do_syncrep2: rid=001
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506022033.000008Z,cn=accesslog), switching
to REFRESH
May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=001 delta-sync
lost sync on (reqStart=20140506022033.000009Z,cn=accesslog), switching
to REFRESH
May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=002 delta-sync
lost sync on (reqStart=20140506022033.000009Z,cn=accesslog), switching
to REFRESH
May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=001
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=002
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:21:26 fosse-dev slapd[7791]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 21:30:34 fosse-dev slapd[7791]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506043034.000008Z,cn=accesslog), switching
to REFRESH
May 5 19:02:17 shelley-dev slapd[8178]: do_syncrep2: rid=003 delta-sync
lost sync, switching to REFRESH
May 5 19:02:17 shelley-dev slapd[8178]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
May 5 19:02:17 shelley-dev slapd[8178]: do_syncrep2: rid=001
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:02:21 shelley-dev slapd[8178]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
[...]
May 5 19:06:19 shelley-dev slapd[8178]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
May 5 19:06:19 shelley-dev slapd[8178]: do_syncrep2: rid=002
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:06:19 shelley-dev slapd[8178]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 20:10:32 shelley-dev slapd[8178]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506031032.000017Z,cn=accesslog), switching
to REFRESH
May 5 20:10:32 shelley-dev slapd[8178]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 21:30:34 shelley-dev slapd[8178]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506043034.000008Z,cn=accesslog), switching
to REFRESH
May 5 21:30:34 shelley-dev slapd[8178]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 22:45:33 shelley-dev slapd[8178]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506054533.000016Z,cn=accesslog), switching
to REFRESH
I don't know if it's related, but right before the loop it was
replicating pwdFailureTime time changes around:
dn: reqStart=20140506064532.000030Z,cn=accesslog
objectClass: auditModify
structuralObjectClass: auditModify
reqStart: 20140506064532.000030Z
reqEnd: 20140506064532.000033Z
reqType: modify
reqSession: 3
reqAuthzID: cn=ldaproot,dc=csupomona,dc=edu
reqDN: cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu
reqResult: 0
reqMod: pwdFailureTime:+ 20140506064532Z
reqMod: entryCSN:= 20140506064532.612089Z#000000#003#000000
reqMod: modifiersName:= cn=ldaproot,dc=csupomona,dc=edu
reqMod: modifyTimestamp:= 20140506064532Z
reqEntryUUID: c16729b0-ce1e-4f9d-9123-e0b8f115133c
entryUUID: a1e99b9b-64b8-4e79-9451-48cac10ff333
creatorsName: cn=accesslog
createTimestamp: 20140506064532Z
entryCSN: 20140506064532.612089Z#000000#003#000000
modifiersName: cn=accesslog
modifyTimestamp: 20140506064532Z
dn: reqStart=20140506064532.000034Z,cn=accesslog
objectClass: auditModify
structuralObjectClass: auditModify
reqStart: 20140506064532.000034Z
reqEnd: 20140506064532.000035Z
reqType: modify
reqSession: 5048
reqAuthzID: cn=ldaproot,dc=csupomona,dc=edu
reqDN: cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu
reqResult: 0
reqMod: pwdFailureTime:-
reqMod: entryCSN:= 20140506064532.680931Z#000000#002#000000
reqMod: modifiersName:= cn=ldaproot,dc=csupomona,dc=edu
reqMod: modifyTimestamp:= 20140506064532Z
reqEntryUUID: c16729b0-ce1e-4f9d-9123-e0b8f115133c
entryUUID: 557c4163-5170-4dc1-84c4-0159797d5538
creatorsName: cn=accesslog
createTimestamp: 20140506064532Z
entryCSN: 20140506064532.680931Z#000000#002#000000
modifiersName: cn=accesslog
modifyTimestamp: 20140506064532Z
dn: reqStart=20140506064532.000040Z,cn=accesslog
objectClass: auditModify
structuralObjectClass: auditModify
reqStart: 20140506064532.000040Z
reqEnd: 20140506064532.000043Z
reqType: modify
reqSession: 3
reqAuthzID: cn=ldaproot,dc=csupomona,dc=edu
reqDN: cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu
reqResult: 0
reqMod: pwdFailureTime:+ 20140506064532Z
reqMod: entryCSN:= 20140506064532.861668Z#000000#003#000000
reqMod: modifiersName:= cn=ldaproot,dc=csupomona,dc=edu
reqMod: modifyTimestamp:= 20140506064532Z
reqEntryUUID: c16729b0-ce1e-4f9d-9123-e0b8f115133c
entryUUID: c4ba3c02-b67a-4522-8767-8da1fa084916
creatorsName: cn=accesslog
createTimestamp: 20140506064532Z
entryCSN: 20140506064532.861668Z#000000#003#000000
modifiersName: cn=accesslog
modifyTimestamp: 20140506064532Z
5:57 p.m.
I've filed an ITS on the issue and will see if I can replicate it in our lab. This
looks exactly like what I am seeing as well. Howard may be able to provide some gdb
actions he would like to see as well.
--Quanah
On May 7, 2014, at 2:57 PM, "Paul B. Henson"
<henson(a)acm.org> wrote:
> On Wed, May 07, 2014 at 09:42:12AM -0700, Quanah Gibson-Mount wrote:
>
> One other thing -- Did any of your servers go into refresh mode prior to
> this loop starting?
Yes, it started logging:
May 5 19:00:38 filmore-dev slapd[7665]: do_syncrep2: rid=001
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:01:48 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync, switching to REFRESH
It continued logging the lost sync messages almost continuously until:
May 5 19:06:16 filmore-dev slapd[7665]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
May 5 19:06:19 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:06:26 filmore-dev slapd[7665]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
May 5 19:06:32 filmore-dev slapd[7665]: do_syncrep2: rid=002
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 20:10:32 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506031032.000017Z,cn=accesslog), switching
to REFRESH
May 5 20:10:32 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 21:30:34 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506043034.000008Z,cn=accesslog), switching
to REFRESH
May 5 21:31:26 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 22:10:36 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506051035.000019Z,cn=accesslog), switching
to REFRESH
May 5 22:10:36 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 22:45:33 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506054533.000016Z,cn=accesslog), switching
to REFRESH
May 5 22:45:33 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 23:10:35 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506061035.000008Z,cn=accesslog), switching
to REFRESH
May 5 23:11:27 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 6 02:15:05 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506075534.000068Z,cn=accesslog), switching
to REFRESH
May 6 02:28:40 filmore-dev slapd[7665]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
The others had similar logs:
May 5 19:00:40 fosse-dev slapd[7791]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
May 5 19:00:40 fosse-dev slapd[7791]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
[...]
May 5 19:10:33 fosse-dev slapd[7791]: do_syncrep2: rid=001 delta-sync
lost sync, switching to REFRESH
May 5 19:10:36 fosse-dev slapd[7791]: do_syncrep2: rid=001
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506022033.000008Z,cn=accesslog), switching
to REFRESH
May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=001 delta-sync
lost sync on (reqStart=20140506022033.000009Z,cn=accesslog), switching
to REFRESH
May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=002 delta-sync
lost sync on (reqStart=20140506022033.000009Z,cn=accesslog), switching
to REFRESH
May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=001
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=002
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:21:26 fosse-dev slapd[7791]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 21:30:34 fosse-dev slapd[7791]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506043034.000008Z,cn=accesslog), switching
to REFRESH
May 5 19:02:17 shelley-dev slapd[8178]: do_syncrep2: rid=003 delta-sync
lost sync, switching to REFRESH
May 5 19:02:17 shelley-dev slapd[8178]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
May 5 19:02:17 shelley-dev slapd[8178]: do_syncrep2: rid=001
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:02:21 shelley-dev slapd[8178]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
[...]
May 5 19:06:19 shelley-dev slapd[8178]: do_syncrep2: rid=002 delta-sync
lost sync, switching to REFRESH
May 5 19:06:19 shelley-dev slapd[8178]: do_syncrep2: rid=002
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 19:06:19 shelley-dev slapd[8178]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 20:10:32 shelley-dev slapd[8178]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506031032.000017Z,cn=accesslog), switching
to REFRESH
May 5 20:10:32 shelley-dev slapd[8178]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 21:30:34 shelley-dev slapd[8178]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506043034.000008Z,cn=accesslog), switching
to REFRESH
May 5 21:30:34 shelley-dev slapd[8178]: do_syncrep2: rid=003
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 5 22:45:33 shelley-dev slapd[8178]: do_syncrep2: rid=003 delta-sync
lost sync on (reqStart=20140506054533.000016Z,cn=accesslog), switching
to REFRESH
I don't know if it's related, but right before the loop it was
replicating pwdFailureTime time changes around:
dn: reqStart=20140506064532.000030Z,cn=accesslog
objectClass: auditModify
structuralObjectClass: auditModify
reqStart: 20140506064532.000030Z
reqEnd: 20140506064532.000033Z
reqType: modify
reqSession: 3
reqAuthzID: cn=ldaproot,dc=csupomona,dc=edu
reqDN: cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu
reqResult: 0
reqMod: pwdFailureTime:+ 20140506064532Z
reqMod: entryCSN:= 20140506064532.612089Z#000000#003#000000
reqMod: modifiersName:= cn=ldaproot,dc=csupomona,dc=edu
reqMod: modifyTimestamp:= 20140506064532Z
reqEntryUUID: c16729b0-ce1e-4f9d-9123-e0b8f115133c
entryUUID: a1e99b9b-64b8-4e79-9451-48cac10ff333
creatorsName: cn=accesslog
createTimestamp: 20140506064532Z
entryCSN: 20140506064532.612089Z#000000#003#000000
modifiersName: cn=accesslog
modifyTimestamp: 20140506064532Z
dn: reqStart=20140506064532.000034Z,cn=accesslog
objectClass: auditModify
structuralObjectClass: auditModify
reqStart: 20140506064532.000034Z
reqEnd: 20140506064532.000035Z
reqType: modify
reqSession: 5048
reqAuthzID: cn=ldaproot,dc=csupomona,dc=edu
reqDN: cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu
reqResult: 0
reqMod: pwdFailureTime:-
reqMod: entryCSN:= 20140506064532.680931Z#000000#002#000000
reqMod: modifiersName:= cn=ldaproot,dc=csupomona,dc=edu
reqMod: modifyTimestamp:= 20140506064532Z
reqEntryUUID: c16729b0-ce1e-4f9d-9123-e0b8f115133c
entryUUID: 557c4163-5170-4dc1-84c4-0159797d5538
creatorsName: cn=accesslog
createTimestamp: 20140506064532Z
entryCSN: 20140506064532.680931Z#000000#002#000000
modifiersName: cn=accesslog
modifyTimestamp: 20140506064532Z
dn: reqStart=20140506064532.000040Z,cn=accesslog
objectClass: auditModify
structuralObjectClass: auditModify
reqStart: 20140506064532.000040Z
reqEnd: 20140506064532.000043Z
reqType: modify
reqSession: 3
reqAuthzID: cn=ldaproot,dc=csupomona,dc=edu
reqDN: cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu
reqResult: 0
reqMod: pwdFailureTime:+ 20140506064532Z
reqMod: entryCSN:= 20140506064532.861668Z#000000#003#000000
reqMod: modifiersName:= cn=ldaproot,dc=csupomona,dc=edu
reqMod: modifyTimestamp:= 20140506064532Z
reqEntryUUID: c16729b0-ce1e-4f9d-9123-e0b8f115133c
entryUUID: c4ba3c02-b67a-4522-8767-8da1fa084916
creatorsName: cn=accesslog
createTimestamp: 20140506064532Z
entryCSN: 20140506064532.861668Z#000000#003#000000
modifiersName: cn=accesslog
modifyTimestamp: 20140506064532Z
3:10 p.m.
From: Quanah Gibson-Mount
Sent: Wednesday, May 07, 2014 5:58 PM
I've filed an ITS on the issue and will see if I can replicate it in our
lab.
This
looks exactly like what I am seeing as well. Howard may be able to
provide
some gdb actions he would like to see as well.
Cool, I see it is 7849. There's no way with the ITS system to subscribe or
something to track bug updates or changes like with other bug trackers?
I don't know that I could reproduce it on demand, but so far it seems every
time I reload my dev environment with a snapshot of production data and turn
on the password policy module, within a day it starts spinning in that
replication loop. So if there's anything I can do to help track it down let
me know.
Thanks.
3:40 p.m.
--On May 8, 2014 at 3:10:45 PM -0700 "Paul B. Henson" <henson(a)acm.org>
wrote:
> From: Quanah Gibson-Mount
> Sent: Wednesday, May 07, 2014 5:58 PM
>
> I've filed an ITS on the issue and will see if I can replicate it in our
lab. This
> looks exactly like what I am seeing as well. Howard may be able to
> provide some gdb actions he would like to see as well.
Cool, I see it is 7849. There's no way with the ITS system to subscribe or
something to track bug updates or changes like with other bug trackers?
Not yet. I'm working on moving OpenLDAP to using Bugzilla, but there are
some other pieces in front of that.
I don't know that I could reproduce it on demand, but so far it
seems
every time I reload my dev environment with a snapshot of production data
and turn on the password policy module, within a day it starts spinning
in that replication loop. So if there's anything I can do to help track
it down let me know.
Ok. What is triggering it to do updates to the password policy in dev?
--Quanah
--
Quanah Gibson-Mount
Server Architect
Zimbra, Inc
--------------------
Zimbra :: the leader in open source messaging and collaboration
11:25 p.m.
Paul B. Henson wrote:
> From: Quanah Gibson-Mount
> Sent: Wednesday, May 07, 2014 5:58 PM
>
> I've filed an ITS on the issue and will see if I can replicate it in our
lab. This
> looks exactly like what I am seeing as well. Howard may be able to provide
> some gdb actions he would like to see as well.
Cool, I see it is 7849. There's no way with the ITS system to subscribe or
something to track bug updates or changes like with other bug trackers?
I don't know that I could reproduce it on demand, but so far it seems every
time I reload my dev environment with a snapshot of production data and turn
on the password policy module, within a day it starts spinning in that
replication loop. So if there's anything I can do to help track it down let
me know.
I'm using slapo-ppolicy and don't see this issue.
My deployment uses normal syncrepl (not delta-syncrepl) though.
And I'm not using account lockout. However slapo-ppolicy sets pwdFailureTime
in my deployment. All replicas (even read-only consumers) have
slapo-accesslog attached to record failed logins etc.
Ciao, Michael.
3307
days inactive
3318
days old
openldap-technical@openldap.org
21 comments
3 participants
participants (3)
-
Michael Ströder -
Paul B. Henson -
Quanah Gibson-Mount