More untangling of req vs. session state.

Eliminate the t_rx timestamp, I doubt it made anything clearer
for anybody.

Add timestamp to SessOpen VSL record.

bin/varnishd/cache/cache.h

@@ -706,7 +706,6 @@ struct sess {
 	/* Timestamps, all on TIM_real() timescale */
 	double			t_open;		/* fd accepted */
 	double			t_idle;		/* fd accepted or resp sent */
-	double			t_rx;
 
 #if defined(HAVE_EPOLL_CTL)
 	struct epoll_event ev;

bin/varnishd/cache/cache_center.c

@@ -118,14 +118,13 @@ cnt_sess_wait(struct sess *sp, struct worker *wrk, struct req *req)
 
 	assert(req->sp == sp);
 
-	assert(!isnan(sp->t_rx));
 
 	AZ(req->vcl);
 	AZ(req->obj);
 	AZ(req->esi_level);
 	assert(req->xid == 0);
-	req->t_req = sp->t_rx;
-	req->t_resp = NAN;
+	assert(isnan(req->t_req));
+	assert(isnan(req->t_resp));
 
 	tmo = (int)(1e3 * cache_param->timeout_linger);
 	while (1) {
@@ -159,7 +158,7 @@ cnt_sess_wait(struct sess *sp, struct worker *wrk, struct req *req)
 			when = sp->t_idle + cache_param->timeout_linger;
 			tmo = (int)(1e3 * (when - now));
 			if (when < now || tmo == 0) {
-				sp->t_rx = NAN;
+				req->t_req = NAN;
 				wrk->stats.sess_herd++;
 				SES_ReleaseReq(req);
 				WAIT_Enter(sp);
@@ -167,7 +166,9 @@ cnt_sess_wait(struct sess *sp, struct worker *wrk, struct req *req)
 			}
 		} else {
 			/* Working on it */
-			when = sp->t_rx + cache_param->timeout_req;
+			if (isnan(req->t_req))
+				req->t_req = now;
+			when = req->t_req + cache_param->timeout_req;
 			tmo = (int)(1e3 * (when - now));
 			if (when < now || tmo == 0) {
 				why = SC_RX_TIMEOUT;
@@ -224,7 +225,6 @@ cnt_sess_done(struct sess *sp, struct worker *wrk, struct req *req)
 		req->vcl = NULL;
 	}
 
-
 	sp->t_idle = W_TIM_real(wrk);
 	if (req->xid == 0) 
 		req->t_resp = sp->t_idle;
@@ -262,8 +262,6 @@ cnt_sess_done(struct sess *sp, struct worker *wrk, struct req *req)
 		wrk->stats.sess_pipeline++;
 		return (SESS_DONE_RET_START);
 	} else {
-		sp->t_rx = sp->t_idle;
-		req->t_req = NAN;
 		if (Tlen(req->htc->rxbuf))
 			wrk->stats.sess_readahead++;
 		return (SESS_DONE_RET_WAIT);
@@ -303,6 +301,12 @@ CNT_Session(struct worker *wrk, struct req *req)
 		return;
 	}
 
+	if (sp->sess_step == S_STP_NEWREQ) {
+		HTC_Init(req->htc, req->ws, sp->fd, req->vsl,
+		    cache_param->http_req_size,
+		    cache_param->http_req_hdr_len);
+	}
+
 	while (1) {
 		/*
 		 * Possible entrance states

bin/varnishd/cache/cache_session.c

@@ -104,7 +104,6 @@ ses_setup(struct sess *sp)
 	sp->sockaddr.ss_family = sp->mysockaddr.ss_family = PF_UNSPEC;
 	sp->t_open = NAN;
 	sp->t_idle = NAN;
-	sp->t_rx = NAN;
 }
 
 /*--------------------------------------------------------------------
@@ -202,8 +201,8 @@ ses_vsl_socket(struct sess *sp, const char *lsockname)
 		strcpy(laddr, "-");
 		strcpy(lport, "-");
 	}
-	VSL(SLT_SessOpen, sp->vxid, "%s %s %s %s %s",
-	    sp->addr, sp->port, lsockname, laddr, lport);
+	VSL(SLT_SessOpen, sp->vxid, "%s %s %s %s %s %.6f",
+	    sp->addr, sp->port, lsockname, laddr, lport, sp->t_open);
 }
 
 /*--------------------------------------------------------------------
@@ -232,7 +231,6 @@ SES_pool_accept_task(struct worker *wrk, void *arg)
 	wrk->stats.s_sess++;
 
 	sp->t_open = VTIM_real();
-	sp->t_rx = sp->t_open;
 	sp->t_idle = sp->t_open;
 	sp->vxid = VXID_Get(&wrk->vxid_pool);
 
@@ -266,10 +264,9 @@ SES_ScheduleReq(struct req *req)
 
 	if (Pool_Task(pp->pool, &sp->task, POOL_QUEUE_FRONT)) {
 		VSC_C_main->client_drop_late++;
-		sp->t_idle = VTIM_real();
 		AN (req->vcl);
 		VCL_Rel(&req->vcl);
-		SES_Delete(sp, SC_OVERLOAD, sp->t_idle);
+		SES_Delete(sp, SC_OVERLOAD, NAN);
 		return (1);
 	}
 	return (0);
@@ -290,11 +287,9 @@ SES_Handle(struct sess *sp, double now)
 	AN(pp->pool);
 	sp->task.func = ses_sess_pool_task;
 	sp->task.priv = sp;
-	sp->t_rx = now;
 	if (Pool_Task(pp->pool, &sp->task, POOL_QUEUE_FRONT)) {
 		VSC_C_main->client_drop_late++;
-		sp->t_idle = VTIM_real();
-		SES_Delete(sp, SC_OVERLOAD, sp->t_idle);
+		SES_Delete(sp, SC_OVERLOAD, now);
 	}
 }
 
@@ -403,9 +398,8 @@ ses_GetReq(struct sess *sp)
 
 	WS_Init(req->ws, "req", p, e - p);
 
-	HTC_Init(req->htc, req->ws, sp->fd, req->vsl,
-	    cache_param->http_req_size,
-	    cache_param->http_req_hdr_len);
+	req->t_req = NAN;
+	req->t_resp = NAN;
 
 	return (req);
 }
@@ -417,6 +411,7 @@ SES_ReleaseReq(struct req *req)
 	struct sesspool *pp;
 
 	CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
+	AZ(req->vcl);
 #define ACCT(foo)	AZ(req->acct_req.foo);
 #include "tbl/acct_fields.h"
 #undef ACCT