From 88d927a23e815368a48147c37fab64fa587a40ca Mon Sep 17 00:00:00 2001 From: Stephane Cance Date: Wed, 7 Feb 2024 16:35:32 +0100 Subject: [PATCH] req_fsm: Avoid misleading Timestamp:Process When `vcl_deliver` does not return `deliver` the timestamp ends up being a duplicate of the `synth` equivalent or the `restart` timestamp. --- bin/varnishd/cache/cache_req_fsm.c | 4 ++-- bin/varnishtest/tests/s00004.vtc | 1 - 2 files changed, 2 insertions(+), 3 deletions(-) diff --git a/bin/varnishd/cache/cache_req_fsm.c b/bin/varnishd/cache/cache_req_fsm.c index 3f92d91aaf2..e84407647b0 100644 --- a/bin/varnishd/cache/cache_req_fsm.c +++ b/bin/varnishd/cache/cache_req_fsm.c @@ -233,8 +233,6 @@ cnt_deliver(struct worker *wrk, struct req *req) 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); if (wrk->vpi->handling != VCL_RET_DELIVER) { @@ -259,6 +257,8 @@ cnt_deliver(struct worker *wrk, struct req *req) return (REQ_FSM_MORE); } + VSLb_ts_req(req, "Process", W_TIM_real(wrk)); + assert(wrk->vpi->handling == VCL_RET_DELIVER); if (IS_TOPREQ(req) && RFC2616_Do_Cond(req)) diff --git a/bin/varnishtest/tests/s00004.vtc b/bin/varnishtest/tests/s00004.vtc index d86903f7c84..36775d1d27c 100644 --- a/bin/varnishtest/tests/s00004.vtc +++ b/bin/varnishtest/tests/s00004.vtc @@ -30,7 +30,6 @@ logexpect l1 -v v1 -g request { expect * = Timestamp {Start: \S+ 0\.000000 0\.000000} expect * = Timestamp {Req: \S+ 0\.\d+ 0\.\d+} expect * = Timestamp {Fetch: \S+ [0-4]\.\d+ [0-4]\.\d+} - expect * = Timestamp {Process: \S+ 2\.\d+ 0\.\d+} expect * = Timestamp {Restart: \S+ 2\.\d+ 0\.\d+} expect * = End expect 0 1002 Begin bereq