Allocate request VXID only when it's needed and delay all logging

until it's been allocated.

This patch delays the VXID allocation until the time we know that we
will actually be logging anything for this request (not completely all
whitespace noise). This keeps the code in one place only (plus the ESI
mock request handling), instead of separated between the linger wait,
cache acceptor and pipelining code paths.

Coincidentally fixes the logging of timestamps problem in #1588.

Test case by daghf.

Fixes: #1581 #1588

Conflicts:
	bin/varnishd/cache/cache_esi_deliver.c
	bin/varnishd/cache/cache_fetch.c
	bin/varnishd/cache/cache_http1_fsm.c
	bin/varnishd/cache/cache_session.c

bin/varnishd/cache/cache_esi_deliver.c

@@ -62,7 +62,8 @@ ved_include(struct req *preq, const char *src, const char *host)
 
 	req = SES_GetReq(wrk, preq->sp);
 	req->req_body_status = REQ_BODY_NONE;
-	AN(req->vsl->wid & VSL_CLIENTMARKER);
+	AZ(req->vsl->wid);
+	req->vsl->wid = VXID_Get(&wrk->vxid_pool) | VSL_CLIENTMARKER;
 	VSLb(req->vsl, SLT_Begin, "req %u esi", preq->vsl->wid & VSL_IDENTMASK);
 	VSLb(preq->vsl, SLT_Link, "req %u esi", req->vsl->wid & VSL_IDENTMASK);
 	req->esi_level = preq->esi_level + 1;

bin/varnishd/cache/cache_fetch.c

@@ -873,9 +873,9 @@ VBF_Fetch(struct worker *wrk, struct req *req, struct objcore *oc,
 	default:		WRONG("Wrong fetch mode");
 	}
 
-	VSLb(bo->vsl, SLT_Begin, "bereq %u %s ",
+	VSLb(bo->vsl, SLT_Begin, "bereq %u %s",
 	    req->vsl->wid & VSL_IDENTMASK, how);
-	VSLb(req->vsl, SLT_Link, "bereq %u %s ",
+	VSLb(req->vsl, SLT_Link, "bereq %u %s",
 	    bo->vsl->wid & VSL_IDENTMASK, how);
 
 	bo->refcount = 2;

bin/varnishd/cache/cache_http1_fsm.c

@@ -123,9 +123,9 @@ http1_wait(struct sess *sp, struct worker *wrk, struct req *req)
 		if (hs == HTTP1_COMPLETE) {
 			/* Got it, run with it */
 			if (isnan(req->t_first))
-				VSLb_ts_req(req, "Start", now);
-			VSLb_ts_req(req, "Req", now);
-			req->t_req = req->t_prev;
+				req->t_first = now;
+			if (isnan(req->t_req))
+				req->t_req = now;
 			req->acct.req_hdrbytes += Tlen(req->htc->rxbuf);
 			return (REQ_FSM_MORE);
 		} else if (hs == HTTP1_ERROR_EOF) {
@@ -152,8 +152,8 @@ http1_wait(struct sess *sp, struct worker *wrk, struct req *req)
 		} else {
 			/* Working on it */
 			if (isnan(req->t_first))
-				/* Timestamp Start on first byte received */
-				VSLb_ts_req(req, "Start", now);
+				/* Record first byte received time stamp */
+				req->t_first = now;
 			when = sp->t_idle + cache_param->timeout_req;
 			tmo = (int)(1e3 * (when - now));
 			if (when < now || tmo == 0) {
@@ -245,14 +245,7 @@ http1_cleanup(struct sess *sp, struct worker *wrk, struct req *req)
 
 	if (HTTP1_Reinit(req->htc) == HTTP1_COMPLETE) {
 		AZ(req->vsl->wid);
-		req->vsl->wid = VXID_Get(&wrk->vxid_pool) | VSL_CLIENTMARKER;
-		VSLb(req->vsl, SLT_Begin, "req %u rxreq",
-		    req->sp->vxid & VSL_IDENTMASK);
-		VSL(SLT_Link, req->sp->vxid, "req %u rxreq",
-		    req->vsl->wid & VSL_IDENTMASK);
-		VSLb_ts_req(req, "Start", sp->t_idle);
-		VSLb_ts_req(req, "Req", sp->t_idle);
-		req->t_req = req->t_prev;
+		req->t_first = req->t_req = sp->t_idle;
 		wrk->stats.sess_pipeline++;
 		req->acct.req_hdrbytes += Tlen(req->htc->rxbuf);
 		return (SESS_DONE_RET_START);
@@ -312,17 +305,19 @@ http1_dissect(struct worker *wrk, struct req *req)
 
 	memset(&req->h1, 0, sizeof req->h1);
 
-	/*
-	 * Cache_req_fsm zeros the vxid once a requests is processed.
-	 * Allocate a new one only now that we know will need it.
-	 */
-	if (req->vsl->wid == 0) {
-		req->vsl->wid = VXID_Get(&wrk->vxid_pool) | VSL_CLIENTMARKER;
-		VSLb(req->vsl, SLT_Begin, "req %u rxreq",
-		    req->sp->vxid & VSL_IDENTMASK);
-		VSL(SLT_Link, req->sp->vxid, "req %u rxreq",
-		    req->vsl->wid & VSL_IDENTMASK);
-	}
+	/* Allocate a new vxid now that we know we'll need it. */
+	AZ(req->vsl->wid);
+	req->vsl->wid = VXID_Get(&wrk->vxid_pool) | VSL_CLIENTMARKER;
+
+	VSLb(req->vsl, SLT_Begin, "req %u rxreq",
+	    req->sp->vxid & VSL_IDENTMASK);
+	VSL(SLT_Link, req->sp->vxid, "req %u rxreq",
+	    req->vsl->wid & VSL_IDENTMASK);
+	AZ(isnan(req->t_first)); /* First byte timestamp set by http1_wait */
+	AZ(isnan(req->t_req));	 /* Complete req rcvd set by http1_wait */
+	req->t_prev = req->t_first;
+	VSLb_ts_req(req, "Start", req->t_first);
+	VSLb_ts_req(req, "Req", req->t_req);
 
 	/* Borrow VCL reference from worker thread */
 	VCL_Refresh(&wrk->vcl);

bin/varnishd/cache/cache_session.c

@@ -133,9 +133,6 @@ ses_sess_pool_task(struct worker *wrk, void *arg)
 
 	req = SES_GetReq(wrk, sp);
 	CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
-	AN(req->vsl->wid & VSL_CLIENTMARKER);
-	VSLb(req->vsl, SLT_Begin, "req %u rxreq", sp->vxid & VSL_IDENTMASK);
-	VSL(SLT_Link, sp->vxid, "req %u rxreq", req->vsl->wid & VSL_IDENTMASK);
 
 	sp->sess_step = S_STP_NEWREQ;
 	ses_req_pool_task(wrk, req);
@@ -362,7 +359,6 @@ SES_GetReq(struct worker *wrk, struct sess *sp)
 
 	sz = cache_param->vsl_buffer;
 	VSL_Setup(req->vsl, p, sz);
-	req->vsl->wid = VXID_Get(&wrk->vxid_pool) | VSL_CLIENTMARKER;
 	p += sz;
 	p = (void*)PRNDUP(p);
 

bin/varnishtest/tests/r01581.vtc

+varnishtest "Duplcate SLT_Begin"
+
+server s1 {
+	rxreq
+	txresp
+} -start
+
+varnish v1 -vcl+backend {
+} -start
+
+logexpect l1 -v v1 -g request {
+	  expect 0 1001 Begin
+	  expect * =	ReqStart
+	  expect * = 	End
+} -start
+
+client c1 {
+	delay 0.1
+	send "GET / HTTP/1.1\r\nHost: example.com\r\n\r\n"
+	rxresp
+} -run
+
+logexpect l1 -wait