Hi, everyone. I've been doing my best to dig into the bug I opened:
http://varnish.projects.linpro.no/ticket/240
Basically, every object is inserted, but the second and subsiquent
objects always miss. The object goes to the MISS step in cache_center
cnt_lookup() where there is a check on sp->obj->busy. This seems to be
an indication that there was no object on the session.
cnt_lookup is called with a session that does not have an >obj
cnt_lookup is called from the 'STEP' system, from cnt_recv - which
itself doen't touch the obj, except to call 'AZ' on it, which I think is
a check.
RECV is called from fetch/RESTART, and cnt_start. And cache_vrt_esi. So
obviously ESI is expected to do something to the object that it isn't.
RESTART is calling Unbusy.
ESI_Deliver is setting RECV. The object is fiddled with but seems to
already exist.
Tried calling Unbusy in ESI_Deliver. No success. Can't modify the object
until after RECV.
ESI_Deliver is setting the document's object aside, and calling RECV
with a NULL'ed object.
Yes, the object to RECV is null.
Then it passes on to LOOKUP, still with NULL.
LOOKUP checks for null, allocates, and calls VCL_hash_method. I.e., the
manpage lies. vcl_hash manipulates req.hash.
Back in cnt_lookup. HSH_Lookup is called and assigned to local o.
HSH_Lookup locates objhead (?) then loops through the objects of
objhead(?). It looks to see if the object was busy, if it is
uncacheable, vary condition, banning, and grace period. Okay, I guess
objhead is a hash of objects. It's looking for one that it can work
with. If it finds one it likes, it returns it.
In our case, it is finding the object for one include, and not for the
other.
So how is the object getting into objhead?
There is a call to HSH_Prealloc. It pre-builds the objhead and object if
needed. Hmmm....
the objhead has some kind of queue functionality.
So if there is no objhead yet as of HSH_Lookup, then the empty one is
used, and a call to hash->lookup fills it, I guess. It only places
objhead into the session if there are busy items, otherwise into the
object. hash is a hash_slinger. I guess this is mapping the different
hash types.
So lookup seems to be accessing the store and looking for the object. I
guess it walks the hash looking for a match by comparing various values.
It calls HSH_Compare as the final check, then returns the matching objhead.
HSH_Compare is passed a session and an objhead. First it checks the hash
lenghts. Then it checks if the hash itself matches.
In our case, compare is returning 0 on both requests.
Back to hash->lookup. This falls to the second have of the loop. It
increases the header element's refcnt. Places the objhead in roh.
Unlockes mtx. Then returns roh.
So head back to HSH_Lookup. Now we've got the newly-retrieved objhead.
Which we are looping through. What is oh->objects exactly? It's a
VTAILQ_HEAD(,object) if that helps.
TTL value is broken! NaN! Staring me in the face!
So I think the date is funny. RFC2616_cache_policy is being called from
cnt_fetch. Afterwards TTL is correct.
http://varnish.projects.linpro.no/ticket/240
Basically, every object is inserted, but the second and subsiquent
objects always miss. The object goes to the MISS step in cache_center
cnt_lookup() where there is a check on sp->obj->busy. This seems to be
an indication that there was no object on the session.
cnt_lookup is called with a session that does not have an >obj
cnt_lookup is called from the 'STEP' system, from cnt_recv - which
itself doen't touch the obj, except to call 'AZ' on it, which I think is
a check.
RECV is called from fetch/RESTART, and cnt_start. And cache_vrt_esi. So
obviously ESI is expected to do something to the object that it isn't.
RESTART is calling Unbusy.
ESI_Deliver is setting RECV. The object is fiddled with but seems to
already exist.
Tried calling Unbusy in ESI_Deliver. No success. Can't modify the object
until after RECV.
ESI_Deliver is setting the document's object aside, and calling RECV
with a NULL'ed object.
Yes, the object to RECV is null.
Then it passes on to LOOKUP, still with NULL.
LOOKUP checks for null, allocates, and calls VCL_hash_method. I.e., the
manpage lies. vcl_hash manipulates req.hash.
Back in cnt_lookup. HSH_Lookup is called and assigned to local o.
HSH_Lookup locates objhead (?) then loops through the objects of
objhead(?). It looks to see if the object was busy, if it is
uncacheable, vary condition, banning, and grace period. Okay, I guess
objhead is a hash of objects. It's looking for one that it can work
with. If it finds one it likes, it returns it.
In our case, it is finding the object for one include, and not for the
other.
So how is the object getting into objhead?
There is a call to HSH_Prealloc. It pre-builds the objhead and object if
needed. Hmmm....
the objhead has some kind of queue functionality.
So if there is no objhead yet as of HSH_Lookup, then the empty one is
used, and a call to hash->lookup fills it, I guess. It only places
objhead into the session if there are busy items, otherwise into the
object. hash is a hash_slinger. I guess this is mapping the different
hash types.
So lookup seems to be accessing the store and looking for the object. I
guess it walks the hash looking for a match by comparing various values.
It calls HSH_Compare as the final check, then returns the matching objhead.
HSH_Compare is passed a session and an objhead. First it checks the hash
lenghts. Then it checks if the hash itself matches.
In our case, compare is returning 0 on both requests.
Back to hash->lookup. This falls to the second have of the loop. It
increases the header element's refcnt. Places the objhead in roh.
Unlockes mtx. Then returns roh.
So head back to HSH_Lookup. Now we've got the newly-retrieved objhead.
Which we are looping through. What is oh->objects exactly? It's a
VTAILQ_HEAD(,object) if that helps.
TTL value is broken! NaN! Staring me in the face!
So I think the date is funny. RFC2616_cache_policy is being called from
cnt_fetch. Afterwards TTL is correct.