Objects for ESI includes incorrectly miss

[JT Justman]

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.