tricky spec failure

[James Bowes]

Hey all:

For the past few days I've been trying to track down the spec test
failure in " Entitlements should bypasses rules for "candlepin"
consumers"

I've been able to reliably reproduce this failure, but only on a full
run of 'buildr spec' (not limiting just to that test or that spec file),
and only right after a full deploy with GENDB=1 and TESTDATA=1. When I
run a second time, it passes.

The direct cause of the failure is an ISE when attempting to bind by
product, from not finding an entitlement that grants the provided
product id.

Now, there should be an entitlement that grants the requested product,
but it never appears because refresh pools is failing. I haven't yet
tracked the original cause of this failure, but it never gets reported
to the client (who just assumes the refresh passed, and continues
along). Even more interestingly, it seems as if the job keeps getting
run by pinsetter.

I've tracked down the commit where this first starts happening,
1ce24a780... which is just an addition of more test data. I've got no
idea why it would cause this.

My suspicion is that this is some really nasty bug in refresh pools, so
I'm going to keep digging. If anyone has any ideas, let me know :)

In addition, it would be good to fix the ISE from bind by product, and
to communicate the refresh pools failure in the job status.

-James

[James Bowes]

On Tue, Jun 21, 2011 at 10:37:07AM -0300, James Bowes wrote:
>  Hey all:
>  
>  For the past few days I've been trying to track down the spec test
>  failure in " Entitlements should bypasses rules for "candlepin"
>  consumers"
>  
>  I've been able to reliably reproduce this failure, but only on a full
>  run of 'buildr spec' (not limiting just to that test or that spec file),
>  and only right after a full deploy with GENDB=1 and TESTDATA=1. When I
>  run a second time, it passes.
>  
>  The direct cause of the failure is an ISE when attempting to bind by
>  product, from not finding an entitlement that grants the provided
>  product id.
>  
>  Now, there should be an entitlement that grants the requested product,
>  but it never appears because refresh pools is failing. I haven't yet
>  tracked the original cause of this failure, but it never gets reported
>  to the client (who just assumes the refresh passed, and continues
>  along). Even more interestingly, it seems as if the job keeps getting
>  run by pinsetter.
>  
>  I've tracked down the commit where this first starts happening,
>  1ce24a780... which is just an addition of more test data. I've got no
>  idea why it would cause this.
>  
>  My suspicion is that this is some really nasty bug in refresh pools, so
>  I'm going to keep digging. If anyone has any ideas, let me know :)
>  
>  In addition, it would be good to fix the ISE from bind by product, and
>  to communicate the refresh pools failure in the job status.
>  
>  -James 
I've figured it out, now. 
This happens for me because entitlements runs directly after job_status.
job status queues up a whole bunch of refresh pools jobs during its
testing. At the end of a spec, created owners are cleaned up, but
pending jobs are not.

When the entitlement test begins, candlepin is working through ~14
refresh pools jobs. entitlement creates an owner and gives that owner
some subscriptions, then adds another refresh pools job.

It's not clear to me if at this point the job queue is run in random
order, or if failed jobs are readded to the queue, but we get into a
state where the entitlement spec test refresh pools is run (and does
what it should), then one of the stale jobs from the job_status spec is
run.

The stale jobs now refrence owners that don't exist, so when the refresh
pools job runs, it gets a null owner object. Here's where the fun
happens: refresh pools looks up subscriptions by owner, and pools by
owner. An api call for subs by owner with a null owner returns 0
subscriptions. A call for pools with a null owner returns _all_ pools.
refresh pools then checks for any pool that does not have a backing sub,
and deletes it. So now we have no pools or entitlements for anybody. Fun
times!

I'm going to fix this up just by adding a check to see if the returned
owner is null, and if so, just quit out. This exposes failures in some
other tests, that I expect depended on this behaviour as a way to clean
up old pools before their owner got deleted. I'll fix those up too.

Why is this happening now, and only with test data? I suspect that on my
machine it's just enough data loaded into the db to slow things down to
the point where this race condition begins to happen.

Does anyone have any good suggestions for testing race conditions? Let
me know if so, as otherwise I'm not sure how to unit/spec test this.

-James

[Devan Goodwin]

On Tue, Jun 21, 2011 at 11:00 AM, James Bowes <jbowes(a)redhat.com&gt; wrote:
>  On Tue, Jun 21, 2011 at 10:37:07AM -0300, James Bowes wrote:
> > Hey all:
> >
> > For the past few days I've been trying to track down the spec test
> > failure in " Entitlements should bypasses rules for "candlepin"
> > consumers"
> >
> > I've been able to reliably reproduce this failure, but only on a full
> > run of 'buildr spec' (not limiting just to that test or that spec file),
> > and only right after a full deploy with GENDB=1 and TESTDATA=1. When I
> > run a second time, it passes.
> >
> > The direct cause of the failure is an ISE when attempting to bind by
> > product, from not finding an entitlement that grants the provided
> > product id.
> >
> > Now, there should be an entitlement that grants the requested product,
> > but it never appears because refresh pools is failing. I haven't yet
> > tracked the original cause of this failure, but it never gets reported
> > to the client (who just assumes the refresh passed, and continues
> > along). Even more interestingly, it seems as if the job keeps getting
> > run by pinsetter.
> >
> > I've tracked down the commit where this first starts happening,
> > 1ce24a780... which is just an addition of more test data. I've got no
> > idea why it would cause this.
> >
> > My suspicion is that this is some really nasty bug in refresh pools, so
> > I'm going to keep digging. If anyone has any ideas, let me know :)
> >
> > In addition, it would be good to fix the ISE from bind by product, and
> > to communicate the refresh pools failure in the job status.
> >
> > -James
>
>  I've figured it out, now.
>  This happens for me because entitlements runs directly after job_status.
>  job status queues up a whole bunch of refresh pools jobs during its
>  testing. At the end of a spec, created owners are cleaned up, but
>  pending jobs are not.
>
>  When the entitlement test begins, candlepin is working through ~14
>  refresh pools jobs. entitlement creates an owner and gives that owner
>  some subscriptions, then adds another refresh pools job.
>
>  It's not clear to me if at this point the job queue is run in random
>  order, or if failed jobs are readded to the queue, but we get into a
>  state where the entitlement spec test refresh pools is run (and does
>  what it should), then one of the stale jobs from the job_status spec is
>  run.
>
>  The stale jobs now refrence owners that don't exist, so when the refresh
>  pools job runs, it gets a null owner object. Here's where the fun
>  happens: refresh pools looks up subscriptions by owner, and pools by
>  owner. An api call for subs by owner with a null owner returns 0
>  subscriptions. A call for pools with a null owner returns _all_ pools.
>  refresh pools then checks for any pool that does not have a backing sub,
>  and deletes it. So now we have no pools or entitlements for anybody. Fun
>  times!
>
>  I'm going to fix this up just by adding a check to see if the returned
>  owner is null, and if so, just quit out. This exposes failures in some
>  other tests, that I expect depended on this behaviour as a way to clean
>  up old pools before their owner got deleted. I'll fix those up too.
>
>  Why is this happening now, and only with test data? I suspect that on my
>  machine it's just enough data loaded into the db to slow things down to
>  the point where this race condition begins to happen.
>
>  Does anyone have any good suggestions for testing race conditions? Let
>  me know if so, as otherwise I'm not sure how to unit/spec test this.
>
>  -James
>  
Not sure how to test the race condition, but we could perhaps cleanup
the jobs during owner deletion (I think that's a cleanup method in
OwnerResource) and test that, combined with the fix you spoke of and a
test on that, that's a decent level of confidence IMO.


-- 
Devan Goodwin <dgoodwin(a)rm-rf.ca&gt;
http://rm-rf.ca

[James Bowes]

On Tue, Jun 21, 2011 at 11:21:13AM -0300, Devan Goodwin wrote:
>  On Tue, Jun 21, 2011 at 11:00 AM, James Bowes
> <jbowes(a)redhat.com&gt; wrote:
>  > On Tue, Jun 21, 2011 at 10:37:07AM -0300, James Bowes wrote:
>  >> Hey all:
>  >>
>  >> For the past few days I've been trying to track down the spec test
>  >> failure in " Entitlements should bypasses rules for "candlepin"
>  >> consumers"
>  >>
>  >> I've been able to reliably reproduce this failure, but only on a full
>  >> run of 'buildr spec' (not limiting just to that test or that spec
> file),
>  >> and only right after a full deploy with GENDB=1 and TESTDATA=1. When I
>  >> run a second time, it passes.
>  >>
>  >> The direct cause of the failure is an ISE when attempting to bind by
>  >> product, from not finding an entitlement that grants the provided
>  >> product id.
>  >>
>  >> Now, there should be an entitlement that grants the requested product,
>  >> but it never appears because refresh pools is failing. I haven't yet
>  >> tracked the original cause of this failure, but it never gets reported
>  >> to the client (who just assumes the refresh passed, and continues
>  >> along). Even more interestingly, it seems as if the job keeps getting
>  >> run by pinsetter.
>  >>
>  >> I've tracked down the commit where this first starts happening,
>  >> 1ce24a780... which is just an addition of more test data. I've got no
>  >> idea why it would cause this.
>  >>
>  >> My suspicion is that this is some really nasty bug in refresh pools, so
>  >> I'm going to keep digging. If anyone has any ideas, let me know :)
>  >>
>  >> In addition, it would be good to fix the ISE from bind by product, and
>  >> to communicate the refresh pools failure in the job status.
>  >>
>  >> -James
>  >
>  > I've figured it out, now.
>  > This happens for me because entitlements runs directly after job_status.
>  > job status queues up a whole bunch of refresh pools jobs during its
>  > testing. At the end of a spec, created owners are cleaned up, but
>  > pending jobs are not.
>  >
>  > When the entitlement test begins, candlepin is working through ~14
>  > refresh pools jobs. entitlement creates an owner and gives that owner
>  > some subscriptions, then adds another refresh pools job.
>  >
>  > It's not clear to me if at this point the job queue is run in random
>  > order, or if failed jobs are readded to the queue, but we get into a
>  > state where the entitlement spec test refresh pools is run (and does
>  > what it should), then one of the stale jobs from the job_status spec is
>  > run.
>  >
>  > The stale jobs now refrence owners that don't exist, so when the refresh
>  > pools job runs, it gets a null owner object. Here's where the fun
>  > happens: refresh pools looks up subscriptions by owner, and pools by
>  > owner. An api call for subs by owner with a null owner returns 0
>  > subscriptions. A call for pools with a null owner returns _all_ pools.
>  > refresh pools then checks for any pool that does not have a backing sub,
>  > and deletes it. So now we have no pools or entitlements for anybody. Fun
>  > times!
>  >
>  > I'm going to fix this up just by adding a check to see if the returned
>  > owner is null, and if so, just quit out. This exposes failures in some
>  > other tests, that I expect depended on this behaviour as a way to clean
>  > up old pools before their owner got deleted. I'll fix those up too.
>  >
>  > Why is this happening now, and only with test data? I suspect that on my
>  > machine it's just enough data loaded into the db to slow things down to
>  > the point where this race condition begins to happen.
>  >
>  > Does anyone have any good suggestions for testing race conditions? Let
>  > me know if so, as otherwise I'm not sure how to unit/spec test this.
>  >
>  > -James
>  >
>  
>  Not sure how to test the race condition, but we could perhaps cleanup
>  the jobs during owner deletion (I think that's a cleanup method in
>  OwnerResource) and test that, combined with the fix you spoke of and a
>  test on that, that's a decent level of confidence IMO.
>   
What about pools? If an owner is deleted, should their pools be cleaned
up too? or should we prevent the owner from being deleted?

>  
>  -- 
>  Devan Goodwin <dgoodwin(a)rm-rf.ca&gt;
>  http://rm-rf.ca
>  _______________________________________________
>  candlepin mailing list
>  candlepin(a)lists.fedorahosted.org
>  https://fedorahosted.org/mailman/listinfo/candlepin 
-James

[Devan Goodwin]

On Tue, Jun 21, 2011 at 12:34 PM, James Bowes <jbowes(a)redhat.com&gt; wrote:
>  On Tue, Jun 21, 2011 at 11:21:13AM -0300, Devan Goodwin wrote:
> > On Tue, Jun 21, 2011 at 11:00 AM, James Bowes <jbowes(a)redhat.com&gt; wrote:
> > > On Tue, Jun 21, 2011 at 10:37:07AM -0300, James Bowes wrote:
> > >> Hey all:
> > >>
> > >> For the past few days I've been trying to track down the spec test
> > >> failure in " Entitlements should bypasses rules for
> "candlepin"
> > >> consumers"
> > >>
> > >> I've been able to reliably reproduce this failure, but only on a full
> > >> run of 'buildr spec' (not limiting just to that test or that spec
> file),
> > >> and only right after a full deploy with GENDB=1 and TESTDATA=1. When I
> > >> run a second time, it passes.
> > >>
> > >> The direct cause of the failure is an ISE when attempting to bind by
> > >> product, from not finding an entitlement that grants the provided
> > >> product id.
> > >>
> > >> Now, there should be an entitlement that grants the requested product,
> > >> but it never appears because refresh pools is failing. I haven't yet
> > >> tracked the original cause of this failure, but it never gets reported
> > >> to the client (who just assumes the refresh passed, and continues
> > >> along). Even more interestingly, it seems as if the job keeps getting
> > >> run by pinsetter.
> > >>
> > >> I've tracked down the commit where this first starts happening,
> > >> 1ce24a780... which is just an addition of more test data. I've got no
> > >> idea why it would cause this.
> > >>
> > >> My suspicion is that this is some really nasty bug in refresh pools, so
> > >> I'm going to keep digging. If anyone has any ideas, let me know :)
> > >>
> > >> In addition, it would be good to fix the ISE from bind by product, and
> > >> to communicate the refresh pools failure in the job status.
> > >>
> > >> -James
> > >
> > > I've figured it out, now.
> > > This happens for me because entitlements runs directly after job_status.
> > > job status queues up a whole bunch of refresh pools jobs during its
> > > testing. At the end of a spec, created owners are cleaned up, but
> > > pending jobs are not.
> > >
> > > When the entitlement test begins, candlepin is working through ~14
> > > refresh pools jobs. entitlement creates an owner and gives that owner
> > > some subscriptions, then adds another refresh pools job.
> > >
> > > It's not clear to me if at this point the job queue is run in random
> > > order, or if failed jobs are readded to the queue, but we get into a
> > > state where the entitlement spec test refresh pools is run (and does
> > > what it should), then one of the stale jobs from the job_status spec is
> > > run.
> > >
> > > The stale jobs now refrence owners that don't exist, so when the refresh
> > > pools job runs, it gets a null owner object. Here's where the fun
> > > happens: refresh pools looks up subscriptions by owner, and pools by
> > > owner. An api call for subs by owner with a null owner returns 0
> > > subscriptions. A call for pools with a null owner returns _all_ pools.
> > > refresh pools then checks for any pool that does not have a backing sub,
> > > and deletes it. So now we have no pools or entitlements for anybody. Fun
> > > times!
> > >
> > > I'm going to fix this up just by adding a check to see if the returned
> > > owner is null, and if so, just quit out. This exposes failures in some
> > > other tests, that I expect depended on this behaviour as a way to clean
> > > up old pools before their owner got deleted. I'll fix those up too.
> > >
> > > Why is this happening now, and only with test data? I suspect that on my
> > > machine it's just enough data loaded into the db to slow things down to
> > > the point where this race condition begins to happen.
> > >
> > > Does anyone have any good suggestions for testing race conditions? Let
> > > me know if so, as otherwise I'm not sure how to unit/spec test this.
> > >
> > > -James
> > >
> >
> > Not sure how to test the race condition, but we could perhaps cleanup
> > the jobs during owner deletion (I think that's a cleanup method in
> > OwnerResource) and test that, combined with the fix you spoke of and a
> > test on that, that's a decent level of confidence IMO.
> >
>
>  What about pools? If an owner is deleted, should their pools be cleaned
>  up too? or should we prevent the owner from being deleted? 
Pools and subscriptions both are supposedly getting cleaned up in that
delete owner routine.

> >
> > --
> > Devan Goodwin <dgoodwin(a)rm-rf.ca&gt;
> > http://rm-rf.ca
> > _______________________________________________
> > candlepin mailing list
> > candlepin(a)lists.fedorahosted.org
> > https://fedorahosted.org/mailman/listinfo/candlepin
>
>  -James
>
>  _______________________________________________
>  candlepin mailing list
>  candlepin(a)lists.fedorahosted.org
>  https://fedorahosted.org/mailman/listinfo/candlepin
>
>  


-- 
Devan Goodwin <dgoodwin(a)rm-rf.ca&gt;
http://rm-rf.ca