After HSH_Lookup() returns NULL indicating a busy object, we diddled

the session a bit to transfer the per-request stats to the session
counters with SES_Charge().

Not only was it inconsistent to charge accounting data in the middle
of a request, it was also illegal because after the hash lock was
released we no longer owned the session.

Once a system is under sufficient load that there is a queue for the
CPU, a race could happen where upon hitting a busy object, the hash lock
was released, another thread would schedule, finish the busy object,
start the sessions on the waiting list, finish off the request we had
and then when we get the cpu again and access it, it's gone.

The previous commit (r3512) eliminated the need to call SES_Charge,
this commit removes the (option) shmlog message inside the hash lock
thus, hopefully, eliminating the race that caused #418.

Fixes: #418


git-svn-id: http://www.varnish-cache.org/svn/trunk/varnish-cache@3513 d4fa192b-c00b-0410-8231-f00ffab90ce4

bin/varnishd/cache_center.c

@@ -584,13 +584,10 @@ cnt_lookup(struct sess *sp)
 
 	if (o == NULL) {
 		/*
-		 * We hit a busy object, disembark worker thread and expect
-		 * hash code to restart us, still in STP_LOOKUP, later.
+		 * We lost the session to a busy object, disembark the
+		 * worker thread.   The hash code to restart the session,
+		 * still in STP_LOOKUP, later when the busy object isn't.
 		 */
-		assert(sp->objhead != NULL);
-		if (params->diag_bitmap & 0x20)
-			WSP(sp, SLT_Debug,
-			    "on waiting list <%s>", sp->objhead->hash);
 		return (1);
 	}
 

bin/varnishd/cache_hash.c

@@ -298,6 +298,9 @@ HSH_Lookup(struct sess *sp)
 		/* There are one or more busy objects, wait for them */
 		if (sp->esis == 0)
 			VTAILQ_INSERT_TAIL(&oh->waitinglist, sp, list);
+		if (params->diag_bitmap & 0x20)
+			WSP(sp, SLT_Debug,
+				"on waiting list <%s>", oh->hash);
 		sp->objhead = oh;
 		Lck_Unlock(&oh->mtx);
 		return (NULL);