[master] 5963b6dc0 expire: New EXP_Removed log statement

[Dridi Boukelmoune]

commit 5963b6dc0e146d03bdfc7ed0d4cc39fb1053f122
Author: AlveElde <alve_elde at hotmail.com>
Date:   Tue Jan 3 03:04:08 2023 +0100

    expire: New EXP_Removed log statement
    
    It is generally useful to know when an object leaves the cache and while
    it may sometimes be logged by call sites (like bans) it is more helpful
    centralize it in ExpKill records to get a (more) complete view of what
    goes in and out of (durable) storage.
    
    The hits attribute is especially useful, as it can give an indication of
    the popularity of objects being removed before they expire.

diff --git a/bin/varnishd/cache/cache_expire.c b/bin/varnishd/cache/cache_expire.c
index c179f94f8..240dc99f0 100644
--- a/bin/varnishd/cache/cache_expire.c
+++ b/bin/varnishd/cache/cache_expire.c
@@ -261,7 +261,7 @@ EXP_Rearm(struct objcore *oc, vtim_real now,
  */
 
 static void
-exp_inbox(struct exp_priv *ep, struct objcore *oc, unsigned flags)
+exp_inbox(struct exp_priv *ep, struct objcore *oc, unsigned flags, double now)
 {
 
 	CHECK_OBJ_NOTNULL(ep, EXP_PRIV_MAGIC);
@@ -279,6 +279,9 @@ exp_inbox(struct exp_priv *ep, struct objcore *oc, unsigned flags)
 		assert(oc->timer_idx == VBH_NOIDX);
 		assert(oc->refcnt > 0);
 		AZ(oc->exp_flags);
+		VSLb(&ep->vsl, SLT_ExpKill, "EXP_Removed x=%ju t=%.0f h=%ld",
+		    VXID(ObjGetXID(ep->wrk, oc)), EXP_Ttl(NULL, oc) - now,
+		    oc->hits);
 		ObjSendEvent(ep->wrk, oc, OEV_EXPIRE);
 		(void)HSH_DerefObjCore(ep->wrk, &oc, 0);
 		return;
@@ -427,7 +430,7 @@ exp_thread(struct worker *wrk, void *priv)
 		t = VTIM_real();
 
 		if (oc != NULL)
-			exp_inbox(ep, oc, flags);
+			exp_inbox(ep, oc, flags, t);
 		else
 			tnext = exp_expire(ep, t);
 	}
diff --git a/bin/varnishtest/tests/c00126.vtc b/bin/varnishtest/tests/c00126.vtc
new file mode 100644
index 000000000..7403f7585
--- /dev/null
+++ b/bin/varnishtest/tests/c00126.vtc
@@ -0,0 +1,42 @@
+varnishtest "Make sure EXP_Removed is logged correctly"
+
+server s1 -repeat 4 {
+	rxreq
+	txresp -bodylen 500000
+} -start
+
+varnish v1 -arg "-ss1=default,1m" -vcl+backend { } -start
+varnish v1 -cliok "param.set vsl_mask +ExpKill"
+
+logexpect l1 -v v1 -g raw {
+	expect * 0 ExpKill "EXP_Removed x=1002 t=.* h=1"
+	expect * 0 ExpKill "EXP_Removed x=1005 t=.* h=0"
+} -start
+
+client c1 {
+	loop 2 {
+		txreq -url "/1"
+		rxresp
+		expect resp.status == 200
+	}
+
+	txreq -url "/2"
+	rxresp
+	expect resp.status == 200
+
+	txreq -url "/3"
+	rxresp
+	expect resp.status == 200
+
+	txreq -url "/4"
+	rxresp
+	expect resp.status == 200
+} -run
+
+# NOTE: Nuked objects are mailed twice
+varnish v1 -expect n_lru_nuked == 2
+varnish v1 -expect MAIN.n_object == 2
+varnish v1 -expect MAIN.exp_mailed == 6
+varnish v1 -expect MAIN.exp_received == 6
+
+logexpect l1 -wait
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
index c65257dcc..84632b861 100644
--- a/include/tbl/vsl_tags.h
+++ b/include/tbl/vsl_tags.h
@@ -355,6 +355,8 @@ SLTM(ExpKill, 0, "Object expiry event",
 	"\tLogged when the expiry thread moves an object on the binheap.\n\n"
 	"EXP_Expired\n"
 	"\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"
 	"LRU_Cand\n"
 	"\tLogged when an object is evaluated for LRU force expiry.\n\n"
 	"LRU\n"
@@ -368,6 +370,7 @@ SLTM(ExpKill, 0, "Object expiry event",
 	"\tEXP_Kill p=%p e=%f f=0x%x\n"
 	"\tEXP_When 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"
 	"\tLRU_Cand p=%p f=0x%x r=%d\n"
 	"\tLRU x=%u\n"
 	"\tLRU_Fail\n"