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.

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);
 			}
 		}

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);

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 {

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)
 ================================

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
 -----------------------------