Add the TTL, grace and keep to Hit log records

For HitMiss and HitPass, only show the remaining TTL. Seeing these
values should help debugging of timing-sensitive transactions. The
grace and keep periods are absolute, but the TTL is the remaining
time relative to the current request. Same as obj.{ttl,grace,keep}
variables in VCL.

bin/varnishd/cache/cache_hash.c

@@ -440,13 +440,13 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp,
 			assert(oc->objhead == oh);
 			if (oc->flags & OC_F_HFP) {
 				wrk->stats->cache_hitpass++;
-				VSLb(req->vsl, SLT_HitPass, "%u",
-				     ObjGetXID(wrk, oc));
+				VSLb(req->vsl, SLT_HitPass, "%u %.6f",
+				    ObjGetXID(wrk, oc), EXP_Dttl(req, oc));
 				oc = NULL;
 			} else if (oc->flags & OC_F_PASS) {
 				wrk->stats->cache_hitmiss++;
-				VSLb(req->vsl, SLT_HitMiss, "%u",
-				     ObjGetXID(wrk, oc));
+				VSLb(req->vsl, SLT_HitMiss, "%u %.6f",
+				    ObjGetXID(wrk, oc), EXP_Dttl(req, oc));
 				oc = NULL;
 				*bocp = hsh_insert_busyobj(wrk, oh);
 			} else {
@@ -470,7 +470,8 @@ HSH_Lookup(struct req *req, struct objcore **ocp, struct objcore **bocp,
 
 	if (exp_oc != NULL && exp_oc->flags & OC_F_PASS) {
 		wrk->stats->cache_hitmiss++;
-		VSLb(req->vsl, SLT_HitMiss, "%u", ObjGetXID(wrk, exp_oc));
+		VSLb(req->vsl, SLT_HitMiss, "%u %.6f", ObjGetXID(wrk, exp_oc),
+		    EXP_Dttl(req, exp_oc));
 		exp_oc = NULL;
 		busy_found = 0;
 	}

bin/varnishd/cache/cache_priv.h

@@ -52,6 +52,8 @@ double EXP_Ttl(const struct req *, const struct objcore *);
 void EXP_Insert(struct worker *wrk, struct objcore *oc);
 void EXP_Remove(struct objcore *);
 
+#define EXP_Dttl(req, oc) (oc->ttl - (req->t_req - oc->t_origin))
+
 /* From cache_main.c */
 void BAN_Init(void);
 void BAN_Compile(void);

bin/varnishd/cache/cache_req_fsm.c

@@ -506,7 +506,11 @@ cnt_lookup(struct worker *wrk, struct req *req)
 	req->objcore = oc;
 	AZ(oc->flags & OC_F_PASS);
 
-	VSLb(req->vsl, SLT_Hit, "%u", ObjGetXID(wrk, req->objcore));
+	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);
 

bin/varnishtest/tests/c00011.vtc

@@ -23,7 +23,7 @@ varnish v1 -vcl+backend {
 } -start
 
 logexpect l1 -v v1 -g vxid {
-	expect 1003 *	HitMiss "^1002$"
+	expect 1003 *	HitMiss "^1002 119.*$"
 } -start
 
 client c1 {

bin/varnishtest/tests/c00081.vtc

@@ -30,7 +30,7 @@ varnish v1 -vcl+backend {
 } -start
 
 logexpect l1 -v v1 -g vxid {
-	expect 1003 *	HitPass "^1002$"
+	expect 1003 *	HitPass "^1002 1.*$"
 } -start
 
 client c1 {

bin/varnishtest/tests/r01858.vtc

@@ -24,7 +24,7 @@ varnish v1 -vcl+backend {
 
 # Tests logging hit-for-miss on an expired object
 logexpect l1 -v v1 -g vxid {
-	expect 1003 *	HitMiss "^1002$"
+	expect 1003 *	HitMiss "^1002 -.*$"
 } -start
 
 client c1 {

include/tbl/vsl_tags.h

@@ -276,12 +276,25 @@ SLTM(ReqStart, 0, "Client request start",
 )
 
 SLTM(Hit, 0, "Hit object in cache",
-	"Object looked up in cache. Shows the VXID of the object.\n\n"
+	"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"
+	"\n"
 )
 
 SLTM(HitPass, 0, "Hit for pass object in cache.",
-	"Hit-for-pass object looked up in cache. Shows the VXID of the"
-	" hit-for-pass object.\n\n"
+	"Hit-for-pass object looked up in cache.\n\n"
+	"The format is::\n\n"
+	"\t%u %f\n"
+	"\t|  |\n"
+	"\t|  +- Remaining TTL\n"
+	"\t+---- VXID of the object\n"
+	"\n"
 )
 
 SLTM(ExpBan, 0, "Object evicted due to ban",
@@ -543,8 +556,13 @@ SLTM(H2TxBody, 0, "Transmitted HTTP2 frame body",
 )
 
 SLTM(HitMiss, 0, "Hit for miss object in cache.",
-	"Hit-for-miss object looked up in cache. Shows the VXID of the"
-	" hit-for-miss object.\n\n"
+	"Hit-for-miss object looked up in cache.\n\n"
+	"The format is::\n\n"
+	"\t%u %f\n"
+	"\t|  |\n"
+	"\t|  +- Remaining TTL\n"
+	"\t+---- VXID of the object\n"
+	"\n"
 )
 
 #undef NODEF_NOTICE