3:53 p.m.
--On Wednesday, February 15, 2017 6:36 PM -0800 "Paul B. Henson"
<henson(a)acm.org> wrote:
On Wed, Feb 15, 2017 at 12:22:29PM -0800, Quanah Gibson-Mount wrote:
> I would suggest filing an ITS with the full backtrace info, so I can
> track it.
Ok, will do.
> It could be useful to have the entry data from the accesslog as
> well for the failed replication op, as we can see the failed entry DN in
> the output of your backtrace.
That would be in the accesslog on the server that crashed? Hmm, the
server that crashed is the master, and all updates were going to it. Am
I confused, or did the update that caused the crash come in via syncrepl
though, and hence originate from a different server? So the accesslog
entry you want would be from that server, not the server that crashed?
But given no other servers should have been receiving updates, how would
an update have been received via replication? Or is this another issue
like the memberOf problem where updates are being improperly replicated?
It appears to be crashing while writing the change to the accesslog
database. It's odd that the value for the attribute is NULL. Do we know
for sure what the client doing the write op to the server is sending?
Hmm, looking at the logs that correspond with one of the crashes:
This operation appears to succeed? Then there's this:
Feb 14 04:00:13 fosse slapd[12524]: conn=37859 op=806 MOD
dn="uid=vntruong,ou=user,dc=csupomona,dc=edu" Feb 14 04:00:13 fosse
slapd[12524]: conn=37859 op=806 MOD attr=csupomonaEduPersonExpiration
Yeah, so this is the operation that actually failed... It'd be interesting
to know if it succeeded in the primary DB, but failed when writing to the
accesslog DB (I.e., the master and its consumers are now out of sync for
that entry), or if the entire write op failed (master and consumers are in
sync for the entry)
when I restarted the server. I guess I am confused; the entryCSN has
serverID 0, the ID of this server, so this isn't a replicated op, it's
an op from this server. So why does the backtrace show the change coming
in via syncrepl? It seems like it's getting applied twice. The change is
deleting the attribute, so the second time it's getting applied you
would get a no such attribute error...
Hm, so I guess my question would be is it doing the op like this:
dn: ...
changetype: modify
replace: csupomonaEduPersonExpiration
csupomonaEduPersonExpiration:
Or is it doing it like this:
dn: ...
changetype: modify
delete: csupomonaEduPersonExpiration
Because the NULL value seems to imply the former.
--Quanah
--
Quanah Gibson-Mount
Product Architect
Symas Corporation
Packaged, certified, and supported LDAP solutions powered by OpenLDAP:
<http://www.symas.com>
2:44 p.m.
New subject: 2.4.44 + ITS 8432 patch segfault in modify_add_values
On Thu, Feb 16, 2017 at 03:53:40PM -0800, Quanah Gibson-Mount wrote:
It appears to be crashing while writing the change to the accesslog
database. It's odd that the value for the attribute is NULL. Do we know
for sure what the client doing the write op to the server is sending?
The code is in perl, and looks like this:
$entry->replace(eduPersonAffiliation => \@eduPersonAffiliation);
In this case, the array @eduPersonAffiliation is empty, effectively
deleting the attribute. I'm not 100% sure what this generates on the
wire, I'd have to debug it. I can say it's the same code that's been
running for a decade or so with no issues.
Yeah, so this is the operation that actually failed... It'd be
interesting
to know if it succeeded in the primary DB, but failed when writing to the
accesslog DB
I already reran that operation to fix the expiration, but the next time
it crashes I'll take a look at the primary and secondaries first to see
if they're out of sync.
Hm, so I guess my question would be is it doing the op like this:
Hmm, the expiration code when removing an expiration looks like:
$entry->delete('cppEduPersonExpiration');
So it should be a delete on the wire for removing the attribute. You
think it crashed on the expiration operating, even though the backtrace
shows the segfault having the eduPersonAffiliation accesslog reqStart
id?
dn: ...
changetype: modify
replace: csupomonaEduPersonExpiration
csupomonaEduPersonExpiration:
Or is it doing it like this:
dn: ...
changetype: modify
delete: csupomonaEduPersonExpiration
Because the NULL value seems to imply the former.
5:04 a.m.
New subject: 2.4.44 + ITS 8432 patch segfault in modify_add_values
Years ago, I had code that did that and then I got a version of Net::LDAP that sent null
attributes across the wire. Even back then OpenLDAP was upset by such behavior. I
quickly updated my code to check if (in your case) @eduPersonAffiliation had zero entries
and issue a proper $entry->delete('eduPersonAffiliation') call in that case.
I've not had any issues since. Perhaps, your Net::LDAP module version has changed and
it is sending what is being logged across the wire instead of the delete you are
expecting.
On 2/17/17, 17:44, "openldap-technical on behalf of Paul B. Henson"
<openldap-technical-bounces(a)openldap.org on behalf of henson(a)acm.org> wrote:
The code is in perl, and looks like this:
$entry->replace(eduPersonAffiliation => \@eduPersonAffiliation);
7:32 p.m.
New subject: 2.4.44 + ITS 8432 patch segfault in modify_add_values
On Tue, Feb 21, 2017 at 01:04:33PM +0000, Frank Swasey wrote:
case. I've not had any issues since. Perhaps, your Net::LDAP
module
version has changed and it is sending what is being logged across the
wire instead of the delete you are expecting.
Hmm, I don't believe we've updated Net::LDAP recently, the only change
since the crashes started was the openldap update. It probably would be
cleaner to do an explicit delete rather than a replace with an empty
array, but it's always done the right thing in the past so it's never
come up. I'll add that to my todo list :), thanks...
6:39 p.m.
New subject: 2.4.44 + ITS 8432 patch segfault in modify_add_values
On Thu, Feb 16, 2017 at 03:53:40PM -0800, Quanah Gibson-Mount wrote:
Yeah, so this is the operation that actually failed... It'd be
interesting
to know if it succeeded in the primary DB, but failed when writing to the
accesslog DB (I.e., the master and its consumers are now out of sync for
that entry), or if the entire write op failed (master and consumers are in
sync for the entry)
I had another crash today :(. The logs leading up to the crash were:
Mar 4 03:53:52 themis slapd[27421]: conn=1668323 op=145931 MOD
dn="uid=mlmungia,ou=user,dc=cpp,dc=edu"
Mar 4 03:53:52 themis slapd[27421]: conn=1668323 op=145931 MOD attr=eduPersonAffiliation
eduPersonPrimaryAffi
liation cppEduPersonAffiliation
Mar 4 03:53:52 themis slapd[27421]: conn=1668323 op=145931 RESULT tag=103 err=0 text=
Mar 4 03:53:52 themis slapd[27421]: conn=1668323 op=145932 MOD
dn="uid=mlmungia,ou=user,dc=cpp,dc=edu"
Mar 4 03:53:52 themis slapd[27421]: conn=1668323 op=145932 MOD
attr=cppEduPersonExpiration
Mar 4 03:53:52 themis slapd[27421]: conn=1668323 op=145932 RESULT tag=103 err=0 text=
Mar 4 03:53:52 themis slapd[27421]: conn=1668323 op=145933 MOD
dn="uid=mlmungia,ou=user,dc=cpp,dc=edu"
Mar 4 03:53:52 themis slapd[27421]: conn=1668323 op=145933 MOD
attr=cppEduPersonStatusFlag
Mar 4 03:53:52 themis slapd[27421]: conn=1668323 op=145933 RESULT tag=103 err=0 text=
Interesting, this time there was no failed operation on the client side.
All three of these opereration succeeded, then the server died and the
load balancer cut over to the secondary. The client got some errors
while it was trying to initiate the next operation it wanted to do, but
it retried a couple of times and successfully performed it on the
secondary once the load balancer cut over.
When I brought the primary back online, all three of these operations
were reflected in its local database and had been replicated to the
other servers.
The backtrace was the same:
Program terminated with signal SIGSEGV, Segmentation fault.
#0 0x0000000000485c61 in modify_add_values (e=e@entry=0x7f417d5b8480,
mod=mod@entry=0x7f4170000980,
permissive=0, text=text@entry=0x7f417d5b89a0,
textbuf=textbuf@entry=0x7f417d5b84d0 "modify/delete: eduPersonAffiliation: no
such attribute",
textlen=textlen@entry=256)
at
/var/lib/portage/tmp/portage/net-nds/openldap-2.4.44-r1/work/openldap-2.4.44/servers/slapd/mods.c:61
61 if ( !BER_BVISNULL( &mod->sm_values[mod->sm_numvals] )) {
It seems like this has something to do with duplicated operations? The
first time this operation was applied, the eduPersonAffiliation
attribute did exist, with a single value that was removed. Then for some
reason it's like it tried to remove it again and went boom? But there
was no operation that *actually* failed. Everything that the client
tried to do was done.
BTW, I opened the ITS for tracking, it's #8609. Thanks...
2470
days inactive
2487
days old
openldap-technical@openldap.org
4 comments
3 participants
participants (3)
-
Frank Swasey -
Paul B. Henson -
Quanah Gibson-Mount