Add {req,req_top,resp,bereq,beresp,obj}.time

{req,bereq}.time remain constant across restarts/retries
req_top.time remains constant across esi includes

The other values represent the time when the respective object
was created.

bin/varnishd/cache/cache.h

@@ -393,6 +393,7 @@ struct busyobj {
 
 	/* Timers */
 	vtim_real		t_first;	/* First timestamp logged */
+	vtim_real		t_resp;		/* response received */
 	vtim_real		t_prev;		/* Previous timestamp logged */
 
 	/* Acct */
@@ -484,6 +485,7 @@ struct req {
 	vtim_real		t_first;	/* First timestamp logged */
 	vtim_real		t_prev;		/* Previous timestamp logged */
 	vtim_real		t_req;		/* Headers complete */
+	vtim_real		t_resp;		/* Entry to last deliver/synth */
 
 	struct http_conn	*htc;
 	struct vfp_ctx		*vfc;

bin/varnishd/cache/cache_fetch.c

@@ -427,7 +427,7 @@ vbf_stp_startfetch(struct worker *wrk, struct busyobj *bo)
 	VSLb_ts_busyobj(bo, "Fetch", W_TIM_real(wrk));
 	i = VDI_GetHdr(bo);
 
-	now = W_TIM_real(wrk);
+	bo->t_resp = now = W_TIM_real(wrk);
 	VSLb_ts_busyobj(bo, "Beresp", now);
 
 	if (i) {

bin/varnishd/cache/cache_req_fsm.c

@@ -231,7 +231,9 @@ cnt_deliver(struct worker *wrk, struct req *req)
 	    !(req->objcore->flags & OC_F_PRIVATE))
 		http_ForceHeader(req->resp, H_Accept_Ranges, "bytes");
 
+	req->t_resp = W_TIM_real(wrk);
 	VCL_deliver_method(req->vcl, wrk, req, NULL, NULL);
+
 	VSLb_ts_req(req, "Process", W_TIM_real(wrk));
 
 	assert(req->restarts <= cache_param->max_restarts);
@@ -324,6 +326,7 @@ cnt_synth(struct worker *wrk, struct req *req)
 	synth_body = VSB_new_auto();
 	AN(synth_body);
 
+	req->t_resp = W_TIM_real(wrk);
 	VCL_synth_method(req->vcl, wrk, req, NULL, synth_body);
 
 	AZ(VSB_finish(synth_body));

bin/varnishd/cache/cache_vrt_var.c

@@ -707,6 +707,25 @@ VRT_DO_EXP_R(beresp, ctx->bo->fetch_objcore, keep, 0)
 
 /*lint -restore */
 
+// XXX more assertions?
+#define VRT_DO_TIME_R(which, where, field)				\
+									\
+VCL_TIME								\
+VRT_r_##which##_time(VRT_CTX)						\
+{									\
+	CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);				\
+	AN((ctx)->where);						\
+									\
+	return ((ctx)->where->field);					\
+}
+
+VRT_DO_TIME_R(req, req, t_req)
+VRT_DO_TIME_R(req_top, req->top->topreq, t_req)
+VRT_DO_TIME_R(resp, req, t_resp)
+VRT_DO_TIME_R(bereq, bo, t_first)
+VRT_DO_TIME_R(beresp, bo, t_resp)
+VRT_DO_TIME_R(obj, req->objcore, t_origin)
+
 /*--------------------------------------------------------------------
  */
 

bin/varnishtest/tests/b00030.vtc

@@ -7,68 +7,107 @@ varnishtest "Test timestamps"
 server s1 {
 	rxreq
 	txresp
+	rxreq
+	txresp
 } -start
 
 varnish v1 -vcl+backend {
 	import vtc;
+	import std;
 
 	sub recv_sub {
-		set req.http.recv_sub = now;
+		set req.http.now-recv_sub = now;
 	}
 	sub vcl_recv {
-		set req.http.recv = now;
+		if (req.restarts == 0) {
+			set req.http.req-time = req.time;
+		} else if (req.http.req-time != "" + req.time) {
+			return (fail);
+		}
+		set req.http.now-recv = now;
 		vtc.sleep(1s);
 		call recv_sub;
-		if (req.http.recv != req.http.recv_sub) {
+		if (req.http.now-recv != req.http.now-recv_sub) {
 			return (fail);
 		}
 	}
 	sub vcl_synth {
-		set resp.http.synth = now;
+		set resp.http.now-synth = now;
+		if (req.http.req-time != "" + req.time) {
+			return (fail);
+		}
+		set req.http.req-time = req.time;
+		set resp.http.resp-time = resp.time;
 	}
 
 	sub vcl_deliver {
-		set resp.http.deliver = now;
-		if (req.http.recv == req.http.deliver) {
+		if (req.http.req-time != "" + req.time) {
+			return (fail);
+		}
+		set resp.http.resp-time = resp.time;
+		set resp.http.obj-time = obj.time;
+		set resp.http.now-deliver = now;
+		if (req.http.now-recv == req.http.now-deliver) {
 			return (fail);
 		}
 
 		vtc.sleep(1s);
+		if (req.restarts == 0) {
+			return (restart);
+		}
 		return (synth(200));
 	}
 
 	sub bf_sub {
-		set bereq.http.bf_sub = now;
+		set bereq.http.now-bf_sub = now;
 	}
 	sub vcl_backend_fetch {
-		set bereq.http.bf = now;
+		if (bereq.retries == 0) {
+			set bereq.http.bereq-time = bereq.time;
+		} else if (bereq.http.bereq-time != "" + bereq.time) {
+			# bereq.time is identical for all retries
+			return (fail);
+		}
+		if (bereq.time <= std.time(bereq.http.req-time)) {
+			return (fail);
+		}
+		set bereq.http.now-bf = now;
 		vtc.sleep(1s);
 		call bf_sub;
-		if (bereq.http.bf != bereq.http.bf_sub) {
+		# now remains constant during built-in vcl sub
+		if (bereq.http.now-bf != bereq.http.now-bf_sub) {
 			return (fail);
 		}
 	}
 	sub br_sub {
-		set beresp.http.br_sub = now;
+		set beresp.http.now-br_sub = now;
 	}
 	sub vcl_backend_response {
-		set beresp.http.br = now;
+		if (bereq.http.bereq-time != "" + bereq.time) {
+			return (fail);
+		}
+		set beresp.http.beresp-time = beresp.time;
+		set beresp.http.now-br = now;
 		vtc.sleep(1s);
 		call br_sub;
-		if (beresp.http.br != beresp.http.br_sub) {
+		if (beresp.http.now-br != beresp.http.now-br_sub) {
 			return (fail);
 		}
-		if (bereq.http.bf == beresp.http.br) {
+		if (bereq.http.now-bf == beresp.http.now-br) {
 			return (fail);
 		}
+		if (bereq.retries == 0) {
+			return (retry);
+		}
+	}
+	sub vcl_backend_error {
+		call vcl_backend_response;
 	}
-
-
 } -start
 
 client c1 {
 	txreq
 	rxresp
 	expect resp.status == 200
-	expect resp.http.synth ~ "^..., .. ... .... ..:..:.. GMT"
+	expect resp.http.now-synth ~ "^..., .. ... .... ..:..:.. GMT"
 } -run

bin/varnishtest/tests/e00030.vtc

@@ -56,7 +56,11 @@ varnish v1 -vcl+backend {
 	sub vcl_recv {
 		if (req.esi_level > 0) {
 			set req.url = req.url + req.esi_level;
+			if (req_top.http.top-time != "" + req_top.time) {
+				return (fail);
+			}
 		} else {
+			set req.http.top-time = req_top.time;
 			set req.http.foo = "bar";
 		}
 

doc/sphinx/reference/vcl_var.rst

@@ -409,6 +409,15 @@ req.is_hitpass
 
 	If this request resulted in a hitpass
 
+req.time
+
+	Type: TIME
+
+	Readable from: client
+
+	The time when the request was fully received, remains constant
+	across restarts.
+
 req_top.method
 
 	Type: STRING
@@ -453,6 +462,14 @@ req_top.proto
 	ESI requests.
 	Identical to req.proto in non-ESI requests.
 
+req_top.time
+
+	Type: TIME
+
+	Readable from: client
+
+	The time when the top-level request was fully received,
+	remains constant across restarts.
 
 bereq
 ~~~~~
@@ -671,6 +688,15 @@ bereq.is_hitpass
 
 	If this backend request was caused by a hitpass.
 
+bereq.time
+
+	Type: TIME
+
+	Readable from: backend
+
+	The time when we started preparing the first backend request,
+	remains constant across retries.
+
 beresp
 ~~~~~~
 
@@ -1025,6 +1051,17 @@ beresp.filters
 	After beresp.filters is set, using any of the beforementioned
 	``beresp.do_*`` switches is a VCL error.
 
+beresp.time
+
+	Type: TIME
+
+	Readable from: vcl_backend_response, vcl_backend_error
+
+	When the backend headers were fully received just before
+	``vcl_backend_response {}`` was entered, or when
+	``vcl_backend_error {}`` was entered.
+
+
 obj
 ~~~
 
@@ -1149,6 +1186,15 @@ obj.can_esi
 	``vcl_deliver {}`` would cause the response body to be ESI
 	processed.
 
+obj.time
+
+	Type: TIME
+
+	Readable from: vcl_hit, vcl_deliver
+
+	The time the object was created from the perspective of the
+	server which generated it. This will roughly be equivalent to
+	``now`` - ``obj.age``.
 
 resp
 ~~~~
@@ -1292,6 +1338,15 @@ resp.filters
 	effiect. Using resp.do_esi is an error once resp.filters is
 	set.
 
+resp.time
+
+	Type: TIME
+
+	Readable from: vcl_deliver, vcl_synth
+
+	The time when we started preparing the response, just before
+	entering ``vcl_synth {}`` or ``vcl_deliver {}``.
+
 Special variables
 ~~~~~~~~~~~~~~~~~