[master] 389d7ba28 pipe: Add missing Start and Process timestamps

[Dridi Boukelmoune]

commit 389d7ba28e0d0e3a2d5c30a959aa517e5166b246
Author: Dridi Boukelmoune <dridi.boukelmoune at gmail.com>
Date:   Thu Dec 16 08:19:28 2021 +0100

    pipe: Add missing Start and Process timestamps
    
    And expose bereq.time in vcl_pipe now that we have some.
    
    Refs #3562

diff --git a/bin/varnishd/cache/cache_req_fsm.c b/bin/varnishd/cache/cache_req_fsm.c
index 3538c3e6c..86a74b0cb 100644
--- a/bin/varnishd/cache/cache_req_fsm.c
+++ b/bin/varnishd/cache/cache_req_fsm.c
@@ -766,6 +766,7 @@ cnt_pipe(struct worker *wrk, struct req *req)
 	CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);
 	VSLb(bo->vsl, SLT_Begin, "bereq %u pipe", VXID(req->vsl->wid));
 	VSLb(req->vsl, SLT_Link, "bereq %u pipe", VXID(bo->vsl->wid));
+	VSLb_ts_busyobj(bo, "Start", W_TIM_real(wrk));
 	THR_SetBusyobj(bo);
 	bo->sp = req->sp;
 	SES_Ref(bo->sp);
@@ -792,6 +793,8 @@ cnt_pipe(struct worker *wrk, struct req *req)
 		nxt = REQ_FSM_MORE;
 		break;
 	case VCL_RET_PIPE:
+		VSLb_ts_req(req, "Process", W_TIM_real(wrk));
+		VSLb_ts_busyobj(bo, "Process", wrk->lastused);
 		if (V1P_Enter() == 0) {
 			AZ(bo->req);
 			bo->req = req;
diff --git a/bin/varnishtest/tests/b00030.vtc b/bin/varnishtest/tests/b00030.vtc
index ba6b7c9cb..72abee7da 100644
--- a/bin/varnishtest/tests/b00030.vtc
+++ b/bin/varnishtest/tests/b00030.vtc
@@ -7,7 +7,14 @@ varnishtest "Test timestamps"
 server s1 {
 	rxreq
 	txresp
+
+	rxreq
+	txresp
+
 	rxreq
+	expect req.method == PIPE
+	expect req.http.req-time != <undef>
+	expect req.http.bereq-time != <undef>
 	txresp
 } -start
 
@@ -31,6 +38,10 @@ varnish v1 -vcl+backend {
 			return (fail);
 		}
 	}
+	sub vcl_pipe {
+		set bereq.http.req-time = req.time;
+		set bereq.http.bereq-time = bereq.time;
+	}
 	sub vcl_synth {
 		set resp.http.now-synth = now;
 		if (req.http.req-time != "" + req.time) {
@@ -110,4 +121,7 @@ client c1 {
 	rxresp
 	expect resp.status == 200
 	expect resp.http.now-synth ~ "^..., .. ... .... ..:..:.. GMT"
+
+	txreq -method PIPE
+	rxresp
 } -run
diff --git a/bin/varnishtest/tests/v00051.vtc b/bin/varnishtest/tests/v00051.vtc
index 8f5ffd606..e13dae04b 100644
--- a/bin/varnishtest/tests/v00051.vtc
+++ b/bin/varnishtest/tests/v00051.vtc
@@ -182,6 +182,7 @@ varnish v1 -expect sc_vcl_failure == 4
 
 logexpect l1012 -v v1 -g vxid -q "vxid == 1012" {
 	expect 0 1012	Begin		{^bereq 1011 pipe}
+	expect 0 =	Timestamp	{^Start:}
 	expect 0 =	BereqMethod	{^GET}
 	expect 0 =	BereqURL	{^/}
 	expect 0 =	BereqProtocol	{^HTTP/1.1}
diff --git a/doc/sphinx/reference/vcl_var.rst b/doc/sphinx/reference/vcl_var.rst
index 153d52d33..be15b6448 100644
--- a/doc/sphinx/reference/vcl_var.rst
+++ b/doc/sphinx/reference/vcl_var.rst
@@ -690,7 +690,7 @@ bereq.time
 
 	Type: TIME
 
-	Readable from: backend
+	Readable from: vcl_pipe, backend
 
 	The time when we started preparing the first backend request,
 	remains constant across retries.
diff --git a/doc/sphinx/reference/vsl.rst b/doc/sphinx/reference/vsl.rst
index 3e174a979..e8ea7a36d 100644
--- a/doc/sphinx/reference/vsl.rst
+++ b/doc/sphinx/reference/vsl.rst
@@ -79,12 +79,19 @@ Restart
 Pipe handling timestamps
 ~~~~~~~~~~~~~~~~~~~~~~~~
 
+The following timestamps are client timestamps specific to pipe transactions:
+
 Pipe
 	Opened a pipe to the backend and forwarded the request.
 
 PipeSess
 	The pipe session has finished.
 
+The following timestamps change meaning in a pipe transaction:
+
+Process
+	Processing finished, ready to begin the pipe delivery.
+
 Backend fetch timestamps
 ~~~~~~~~~~~~~~~~~~~~~~~~