[master] 706330867 fetch: Backends are in charge of printing headers

[Dridi Boukelmoune]

commit 7063308676415010da5f7b70f571a22a62c66c4b
Author: Guillaume Quintard <guillaume.quintard at gmail.com>
Date:   Sat Dec 24 23:13:35 2022 -0800

    fetch: Backends are in charge of printing headers
    
    The current backend implementation reads the headers all at once, as a
    big buffer, then manually chops them up, and later on, in the startfetch
    step, Varnish loops through all the headers and prints them.
    
    This is inconvenient for custom backends that are most likely going to
    use http_SetH() (directly or via http_SetHeader(), http_PrinfHeader() or
    others), which also prints the headers being added. As a result, those
    implementations end up logging the header twice.
    
    To work around the issue we can push the burden of logging the beresp
    headers onto the backend implementation. It does change one test, as
    now the Timestamp:Beresp log record appears after the headers instead
    of before.

diff --git a/bin/varnishd/cache/cache_backend.c b/bin/varnishd/cache/cache_backend.c
index 7ac117cc4..4802c05fc 100644
--- a/bin/varnishd/cache/cache_backend.c
+++ b/bin/varnishd/cache/cache_backend.c
@@ -273,6 +273,7 @@ vbe_dir_gethdrs(VRT_CTX, VCL_BACKEND d)
 	CHECK_OBJ_NOTNULL(d, DIRECTOR_MAGIC);
 	bo = ctx->bo;
 	CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);
+	CHECK_OBJ_NOTNULL(bo->bereq, HTTP_MAGIC);
 	if (bo->htc != NULL)
 		CHECK_OBJ_NOTNULL(bo->htc->doclose, STREAM_CLOSE_MAGIC);
 	wrk = ctx->bo->wrk;
@@ -317,6 +318,7 @@ vbe_dir_gethdrs(VRT_CTX, VCL_BACKEND d)
 				i = V1F_FetchRespHdr(bo);
 			if (i == 0) {
 				AN(bo->htc->priv);
+				http_VSL_log(bo->beresp);
 				return (0);
 			}
 		}
diff --git a/bin/varnishd/cache/cache_fetch.c b/bin/varnishd/cache/cache_fetch.c
index 343a28102..0af5c0d54 100644
--- a/bin/varnishd/cache/cache_fetch.c
+++ b/bin/varnishd/cache/cache_fetch.c
@@ -442,8 +442,6 @@ vbf_stp_startfetch(struct worker *wrk, struct busyobj *bo)
 		return (F_STP_ERROR);
 	}
 
-	http_VSL_log(bo->beresp);
-
 	if (bo->htc != NULL && bo->htc->body_status == BS_ERROR) {
 		bo->htc->doclose = SC_RX_BODY;
 		vbf_cleanup(bo);
diff --git a/bin/varnishtest/tests/c00036.vtc b/bin/varnishtest/tests/c00036.vtc
index adec31ab0..514fe08a9 100644
--- a/bin/varnishtest/tests/c00036.vtc
+++ b/bin/varnishtest/tests/c00036.vtc
@@ -33,11 +33,11 @@ logexpect l1 -v v1 -q "vxid == 1004" {
 	expect 0 1004 BackendOpen     {^\d+ s1}
 
 	expect 0 1004 Timestamp       {^Bereq:}
-	expect 0 1004 Timestamp       {^Beresp:}
 	expect 0 1004 BerespProtocol  {^HTTP/1.1}
 	expect 0 1004 BerespStatus    {^200}
 	expect 0 1004 BerespReason    {^OK}
 	expect 0 1004 BerespHeader    {^Content-Length: 6}
+	expect 0 1004 Timestamp       {^Beresp:}
 } -start
 
 client c1 {
diff --git a/doc/changes.rst b/doc/changes.rst
index 979857f08..4d0012a5d 100644
--- a/doc/changes.rst
+++ b/doc/changes.rst
@@ -75,6 +75,8 @@ Varnish Cache NEXT (2023-03-15)
 * The ``debug.xid`` CLI command now sets the next XID to be used,
   rather than "one less than the next XID to be used"
 
+* Backend implementations are in charge of logging their headers.
+
 ================================
 Varnish Cache 7.2.0 (2022-09-15)
 ================================
diff --git a/doc/sphinx/reference/directors.rst b/doc/sphinx/reference/directors.rst
index 66c0f406c..450515df7 100644
--- a/doc/sphinx/reference/directors.rst
+++ b/doc/sphinx/reference/directors.rst
@@ -204,6 +204,11 @@ to implement the whole probing infrastructure from scratch.
 You may also consider making your custom backend compliant with regards to the
 VCL state (see :ref:`ref-vmod-event-functions`).
 
+If you are implementing the `gethdrs` method of your backend (i.e. your
+backend is able to generate a backend response to be manipulated in
+`vcl_backend_response`), you will want to log the response code, protocol and
+the various headers it'll create for easier debugging. For this, you can look
+at the `VSL*` family of functions, listed in `cache/cache.h`.
 
 Data structure considerations
 -----------------------------