vsl: Log the progress of streaming hits

The larger the response we hit, the more likely we are to hit an ongoing
fetch and since we buffer transaction logs it can become really tedious
to infer whether the backend transaction may have already been overrun
or not flushed yet. At least, such a heuristic was impossible with a VSL
query until now.

bin/varnishd/cache/cache_hash.c

@@ -369,6 +369,7 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp)
 	vtim_real exp_t_origin;
 	int busy_found;
 	const uint8_t *vary;
+	intmax_t boc_progress;
 	unsigned xid = 0;
 	float dttl = 0.0;
 
@@ -519,7 +520,9 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp)
 			return (HSH_HITMISS);
 		}
 		oc->hits++;
+		boc_progress = oc->boc == NULL ? -1 : oc->boc->len_so_far;
 		AN(hsh_deref_objhead_unlock(wrk, &oh, HSH_RUSH_POLICY));
+		Req_LogHit(wrk, req, oc, boc_progress);
 		return (HSH_HIT);
 	}
 
@@ -539,6 +542,11 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp)
 		return (HSH_HITMISS);
 	}
 
+	if (exp_oc != NULL && exp_oc->boc != NULL)
+		boc_progress = exp_oc->boc->len_so_far;
+	else
+		boc_progress = -1;
+
 	if (!busy_found) {
 		*bocp = hsh_insert_busyobj(wrk, oh);
 
@@ -548,6 +556,7 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp)
 			if (EXP_Ttl_grace(req, exp_oc) >= req->t_req) {
 				exp_oc->hits++;
 				Lck_Unlock(&oh->mtx);
+				Req_LogHit(wrk, req, exp_oc, boc_progress);
 				return (HSH_GRACE);
 			}
 		}
@@ -562,6 +571,7 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp)
 		*ocp = exp_oc;
 		exp_oc->hits++;
 		AN(hsh_deref_objhead_unlock(wrk, &oh, 0));
+		Req_LogHit(wrk, req, exp_oc, boc_progress);
 		return (HSH_GRACE);
 	}
 

bin/varnishd/cache/cache_req.c

@@ -72,6 +72,33 @@ Req_AcctLogCharge(struct VSC_main_wrk *ds, struct req *req)
 	memset(a, 0, sizeof *a);
 }
 
+void
+Req_LogHit(struct worker *wrk, struct req *req, struct objcore *oc,
+    intmax_t fetch_progress)
+{
+	const char *clen, *sep;
+
+	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
+	CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
+	CHECK_OBJ_NOTNULL(oc, OBJCORE_MAGIC);
+
+	if (fetch_progress >= 0) {
+		clen = HTTP_GetHdrPack(wrk, oc, H_Content_Length);
+		if (clen == NULL)
+			clen = sep = "";
+		else
+			sep = " ";
+		VSLb(req->vsl, SLT_Hit, "%u %.6f %.6f %.6f %jd%s%s",
+		    ObjGetXID(wrk, oc), EXP_Dttl(req, oc),
+		    oc->grace, oc->keep,
+		    fetch_progress, sep, clen);
+	} else {
+		VSLb(req->vsl, SLT_Hit, "%u %.6f %.6f %.6f",
+		    ObjGetXID(wrk, oc), EXP_Dttl(req, oc),
+		    oc->grace, oc->keep);
+	}
+}
+
 /*--------------------------------------------------------------------
  * Alloc/Free a request
  */

bin/varnishd/cache/cache_req_fsm.c

@@ -602,12 +602,6 @@ cnt_lookup(struct worker *wrk, struct req *req)
 	req->objcore = oc;
 	AZ(oc->flags & OC_F_HFM);
 
-	VSLb(req->vsl, SLT_Hit, "%u %.6f %.6f %.6f",
-	    ObjGetXID(wrk, req->objcore),
-	    EXP_Dttl(req, req->objcore),
-	    req->objcore->grace,
-	    req->objcore->keep);
-
 	VCL_hit_method(req->vcl, wrk, req, NULL, NULL);
 
 	switch (wrk->handling) {

bin/varnishd/cache/cache_varnishd.h

@@ -403,6 +403,7 @@ void Req_Rollback(VRT_CTX);
 void Req_Cleanup(struct sess *sp, struct worker *wrk, struct req *req);
 void Req_Fail(struct req *req, enum sess_close reason);
 void Req_AcctLogCharge(struct VSC_main_wrk *, struct req *);
+void Req_LogHit(struct worker *, struct req *, struct objcore *, intmax_t);
 
 /* cache_req_body.c */
 int VRB_Ignore(struct req *);

bin/varnishtest/tests/b00077.vtc

+varnishtest "SLT_Hit ongoing fetch"
+
+barrier b1 cond 2 -cyclic
+barrier b2 cond 2 -cyclic
+
+server s1 {
+	rxreq
+	txresp -nolen -hdr "Content-Length: 10"
+	send hello
+	barrier b1 sync
+	barrier b2 sync
+	send world
+
+	rxreq
+	txresp -nolen -hdr "Transfer-Encoding: chunked"
+	chunked hello
+	barrier b1 sync
+	barrier b2 sync
+	chunked world
+	chunked ""
+} -start
+
+varnish v1 -cliok "param.set debug +syncvsl"
+varnish v1 -cliok "param.set thread_pools 1"
+varnish v1 -vcl+backend "" -start
+
+client c1 {
+	txreq
+	rxresp
+	expect resp.body == helloworld
+} -start
+
+barrier b1 sync
+
+logexpect l1 -v v1 -g raw {
+	#                   vxid TTL     grace     keep     fetch length
+	expect * 1004 Hit "^1002 [0-9.]+ 10.000000 0.000000 [0-5] 10$"
+} -start
+
+client c2 {
+	txreq
+	rxresp
+	expect resp.body == helloworld
+} -start
+
+logexpect l1 -wait
+
+barrier b2 sync
+
+client c1 -wait
+client c2 -wait
+
+# Recycle almost everything for the chunked variant
+
+varnish v1 -cliok "ban obj.status != 0"
+
+client c1 -start
+
+barrier b1 sync
+
+logexpect l2 -v v1 -g raw {
+	#                   vxid TTL     grace     keep     fetch
+	expect * 1009 Hit "^1007 [0-9.]+ 10.000000 0.000000 [0-5]$"
+} -start
+
+client c2 -start
+
+logexpect l2 -wait
+
+barrier b2 sync
+
+client c1 -wait
+client c2 -wait

include/tbl/vsl_tags.h

@@ -338,12 +338,14 @@ SLTM(ReqStart, 0, "Client request start",
 SLTM(Hit, 0, "Hit object in cache",
 	"Object looked up in cache.\n\n"
 	"The format is::\n\n"
-	"\t%u %f %f %f\n"
-	"\t|  |  |  |\n"
-	"\t|  |  |  +- Keep period\n"
-	"\t|  |  +---- Grace period\n"
-	"\t|  +------- Remaining TTL\n"
-	"\t+---------- VXID of the object\n"
+	"\t%u %f %f %f [%u [%u]]\n"
+	"\t|  |  |  |   |   |\n"
+	"\t|  |  |  |   |   +- Content length\n"
+	"\t|  |  |  |   +----- Fetched so far\n"
+	"\t|  |  |  +--------- Keep period\n"
+	"\t|  |  +------------ Grace period\n"
+	"\t|  +--------------- Remaining TTL\n"
+	"\t+------------------ VXID of the object\n"
 	"\n"
 )