[master] 084cd13ed fix when the vcl_synth {} Process timestamp gets emitted

[Nils Goroll]

commit 084cd13eda6063ca761dfda7f45694ca6ef1eb47
Author: Nils Goroll <nils.goroll at uplex.de>
Date:   Fri Oct 11 09:38:12 2019 +0200

    fix when the vcl_synth {} Process timestamp gets emitted
    
    Found by @Dridi

diff --git a/bin/varnishd/cache/cache_req_fsm.c b/bin/varnishd/cache/cache_req_fsm.c
index 977f57e39..e13de2250 100644
--- a/bin/varnishd/cache/cache_req_fsm.c
+++ b/bin/varnishd/cache/cache_req_fsm.c
@@ -294,8 +294,6 @@ cnt_synth(struct worker *wrk, struct req *req)
 
 	wrk->stats->s_synth++;
 
-	VSLb_ts_req(req, "Process", W_TIM_real(wrk));
-
 	if (req->err_code < 100)
 		req->err_code = 501;
 
@@ -308,6 +306,8 @@ cnt_synth(struct worker *wrk, struct req *req)
 
 	AZ(VSB_finish(synth_body));
 
+	VSLb_ts_req(req, "Process", W_TIM_real(wrk));
+
 	if (wrk->handling == VCL_RET_FAIL) {
 		VSB_destroy(&synth_body);
 		req->doclose = SC_VCL_FAILURE;
diff --git a/bin/varnishtest/tests/c00018.vtc b/bin/varnishtest/tests/c00018.vtc
index 10359f758..cff0bebde 100644
--- a/bin/varnishtest/tests/c00018.vtc
+++ b/bin/varnishtest/tests/c00018.vtc
@@ -122,7 +122,6 @@ logexpect l1 -v v1 -g raw {
 	expect 0 1011	VCL_return      {^synth$}
 	expect 0 1011	VCL_call        {^HASH$}
 	expect 0 1011	VCL_return      {^lookup$}
-	expect 0 1011	Timestamp       {^Process:}
 	expect 0 1011	RespProtocol    {^HTTP/1.1$}
 	expect 0 1011	RespStatus      {^405$}
 	expect 0 1011	RespReason      {^Method Not Allowed$}
@@ -130,6 +129,7 @@ logexpect l1 -v v1 -g raw {
 	expect 1 1011	RespHeader      {^Date:}
 	expect 0 1011	RespHeader      {^Server: Varnish$}
 	expect 0 1011	RespHeader      {^X-Varnish: 1011$}
+	expect * 1011	Timestamp       {^Process:}
 
 } -start
 
diff --git a/doc/changes.rst b/doc/changes.rst
index fdc03d521..37c638da8 100644
--- a/doc/changes.rst
+++ b/doc/changes.rst
@@ -45,6 +45,10 @@ NEXT (2020-03-15)
 * The option ``varnishtest -W`` is gone, the same can be achieved with
   ``varnishtest -p debug=+witness``.
 
+* The ``Process`` timestamp for ``vcl_synth {}`` was wrongly issued
+  before the VCL callback, now it gets emitted after VCL returns for
+  consistency with ``vcl_deliver {}``
+
 ================================
 Varnish Cache 6.3.0 (2019-09-15)
 ================================