[master] e8264aaf2 fetch: New VBF_Superseded entry for ExpKill records

[Dridi Boukelmoune]

commit e8264aaf2cec981e246347b88afbe7e7e101fc81
Author: Dridi Boukelmoune <dridi.boukelmoune at gmail.com>
Date:   Wed Jan 10 13:51:40 2024 +0100

    fetch: New VBF_Superseded entry for ExpKill records

diff --git a/bin/varnishd/cache/cache_fetch.c b/bin/varnishd/cache/cache_fetch.c
index 9a6ed4ec6..c6c26ada0 100644
--- a/bin/varnishd/cache/cache_fetch.c
+++ b/bin/varnishd/cache/cache_fetch.c
@@ -752,8 +752,12 @@ vbf_stp_fetchend(struct worker *wrk, struct busyobj *bo)
 
 	ObjSetState(wrk, oc, BOS_FINISHED);
 	VSLb_ts_busyobj(bo, "BerespBody", W_TIM_real(wrk));
-	if (bo->stale_oc != NULL)
+	if (bo->stale_oc != NULL) {
+		VSL(SLT_ExpKill, NO_VXID, "VBF_Superseded x=%ju n=%ju",
+		    VXID(ObjGetXID(wrk, bo->stale_oc)),
+		    VXID(ObjGetXID(wrk, bo->fetch_objcore)));
 		HSH_Kill(bo->stale_oc);
+	}
 	return (F_STP_DONE);
 }
 
diff --git a/bin/varnishtest/tests/b00039.vtc b/bin/varnishtest/tests/b00039.vtc
index ba4285369..3a316c3a8 100644
--- a/bin/varnishtest/tests/b00039.vtc
+++ b/bin/varnishtest/tests/b00039.vtc
@@ -11,6 +11,7 @@ server s1 {
 	txresp -status 304
 } -start
 
+varnish v1 -cliok "param.set vsl_mask +ExpKill"
 varnish v1 -vcl+backend {
 	sub vcl_backend_response {
 		set beresp.ttl = 2s;
@@ -20,6 +21,13 @@ varnish v1 -vcl+backend {
 	}
 } -start
 
+logexpect l1 -v v1 -g raw -q ExpKill {
+	expect * 0 ExpKill "VBF_Superseded x=1002 n=1005"
+	expect * 0 ExpKill "EXP_Removed x=1002"
+	expect * 0 ExpKill "VBF_Superseded x=1005 n=1010"
+	expect * 0 ExpKill "EXP_Removed x=1005"
+} -start
+
 client c1 {
 	txreq
 	rxresp
@@ -57,3 +65,5 @@ client c1 {
 	expect resp.body == "Geoff Rules"
 	expect resp.http.was-304 == "true"
 } -run
+
+logexpect l1 -wait
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
index b5a3596c0..858256f26 100644
--- a/include/tbl/vsl_tags.h
+++ b/include/tbl/vsl_tags.h
@@ -367,6 +367,8 @@ SLTM(ExpKill, 0, "Object expiry event",
 	"\tLogged when the expiry thread expires an object.\n\n"
 	"EXP_Removed\n"
 	"\tLogged when the expiry thread removes an object before expiry.\n\n"
+	"VBF_Superseded\n"
+	"\tLogged when an object supersedes another.\n\n"
 	"LRU_Cand\n"
 	"\tLogged when an object is evaluated for LRU force expiry.\n\n"
 	"LRU\n"
@@ -382,6 +384,7 @@ SLTM(ExpKill, 0, "Object expiry event",
 	"\tEXP_Inspect p=%p e=%f f=0x%x\n"
 	"\tEXP_Expired x=%u t=%f h=%u\n"
 	"\tEXP_Removed x=%u t=%f h=%u\n"
+	"\tVBF_Superseded x=%u n=%u\n"
 	"\tLRU_Cand p=%p f=0x%x r=%d\n"
 	"\tLRU x=%u\n"
 	"\tLRU_Fail\n"
@@ -394,6 +397,7 @@ SLTM(ExpKill, 0, "Object expiry event",
 	"\tf=0x%x       Objcore flags\n"
 	"\tr=%d         Objcore refcount\n"
 	"\tx=%u         Object VXID\n"
+	"\tn=%u         New object VXID\n"
 	"\th=%u         Objcore hits\n"
 	"\n"
 )