[master] 598b13d7f Add a strands interface to VSL and use it for std.log

Nils Goroll nils.goroll at uplex.de
Mon Jan 27 15:22:07 UTC 2020


commit 598b13d7fb96e65346e25ab5fdbe1810a3dd93d7
Author: Nils Goroll <nils.goroll at uplex.de>
Date:   Mon Jan 20 18:48:21 2020 +0100

    Add a strands interface to VSL and use it for std.log
    
    Since 8baf4a690fdb699923dd8438d0088f34fcb24365 we lost information about
    an overflowed workspace by calling std.log(), which resulted from use of
    the workspace for construction of a contiguous string from the argument
    constituents.
    
    Since then, we have changed the interface to STRANDS, but this issue
    remained.
    
    We now solve the case for real by pushing the string concatenation down
    to VSL: New versions of VSL and VSLb (coded by example of VSLv() and
    VSLbt()) take a strands argument and create a log record without
    additional copy overhead.
    
    These solve #3194 for std.log(), make logging more efficient and, in
    particular, allow use of std.log() in low workspace conditions (because
    they do not require any).
    
    Also improve test coverage for std.log()
    
    Ref #3194

diff --git a/bin/varnishd/cache/cache.h b/bin/varnishd/cache/cache.h
index ecf14cf41..360855e44 100644
--- a/bin/varnishd/cache/cache.h
+++ b/bin/varnishd/cache/cache.h
@@ -727,10 +727,12 @@ const char *SES_Get_String_Attr(const struct sess *sp, enum sess_attr a);
 void VSLv(enum VSL_tag_e tag, uint32_t vxid, const char *fmt, va_list va);
 void VSL(enum VSL_tag_e tag, uint32_t vxid, const char *fmt, ...)
     v_printflike_(3, 4);
+void VSLs(enum VSL_tag_e tag, uint32_t vxid, const struct strands *s);
 void VSLbv(struct vsl_log *, enum VSL_tag_e tag, const char *fmt, va_list va);
 void VSLb(struct vsl_log *, enum VSL_tag_e tag, const char *fmt, ...)
     v_printflike_(3, 4);
 void VSLbt(struct vsl_log *, enum VSL_tag_e tag, txt t);
+void VSLbs(struct vsl_log *, enum VSL_tag_e tag, const struct strands *s);
 void VSLb_ts(struct vsl_log *, const char *event, vtim_real first,
     vtim_real *pprev, vtim_real now);
 void VSLb_bin(struct vsl_log *, enum VSL_tag_e, ssize_t, const void*);
diff --git a/bin/varnishd/cache/cache_shmlog.c b/bin/varnishd/cache/cache_shmlog.c
index 9590d284f..4fc746eee 100644
--- a/bin/varnishd/cache/cache_shmlog.c
+++ b/bin/varnishd/cache/cache_shmlog.c
@@ -43,6 +43,55 @@
 #include "common/heritage.h"
 #include "common/vsmw.h"
 
+/* ------------------------------------------------------------
+ * strands helpers - move elsewhere?
+ */
+
+static unsigned
+strands_len(const struct strands *s)
+{
+	unsigned r = 0;
+	int i;
+
+	for (i = 0; i < s->n; i++) {
+		if (s->p[i] == NULL || *s->p[i] == '\0')
+			continue;
+		r += strlen(s->p[i]);
+	}
+
+	return (r);
+}
+
+/*
+ * like VRT_Strands(), but truncating instead of failing for end of buffer
+ *
+ * returns number of bytes including NUL
+ */
+static unsigned
+strands_cat(char *buf, unsigned bufl, const struct strands *s)
+{
+	unsigned l = 0, ll;
+	int i;
+
+	/* NUL-terminated */
+	assert(bufl > 0);
+	bufl--;
+
+	for (i = 0; i < s->n && bufl > 0; i++) {
+		if (s->p[i] == NULL || *s->p[i] == '\0')
+			continue;
+		ll = strlen(s->p[i]);
+		if (ll > bufl)
+			ll = bufl;
+		memcpy(buf, s->p[i], ll);
+		l += ll;
+		buf += ll;
+		bufl -= ll;
+	}
+	*buf = '\0';	/* NUL-terminated */
+	return (l + 1);
+}
+
 /* These cannot be struct lock, which depends on vsm/vsl working */
 static pthread_mutex_t vsl_mtx;
 static pthread_mutex_t vsc_mtx;
@@ -231,6 +280,20 @@ VSLv(enum VSL_tag_e tag, uint32_t vxid, const char *fmt, va_list ap)
 
 }
 
+void
+VSLs(enum VSL_tag_e tag, uint32_t vxid, const struct strands *s)
+{
+	unsigned n, mlen = cache_param->vsl_reclen;
+	char buf[mlen];
+
+	if (vsl_tag_is_masked(tag))
+		return;
+
+	n = strands_cat(buf, mlen, s);
+
+	vslr(tag, vxid, buf, n);
+}
+
 void
 VSL(enum VSL_tag_e tag, uint32_t vxid, const char *fmt, ...)
 {
@@ -304,6 +367,42 @@ VSLbt(struct vsl_log *vsl, enum VSL_tag_e tag, txt t)
 		VSL_Flush(vsl, 0);
 }
 
+/*--------------------------------------------------------------------
+ * VSL-buffered-strands
+ */
+void
+VSLbs(struct vsl_log *vsl, enum VSL_tag_e tag, const struct strands *s)
+{
+	unsigned l, mlen;
+
+	vsl_sanity(vsl);
+	if (vsl_tag_is_masked(tag))
+		return;
+	mlen = cache_param->vsl_reclen;
+
+	/* including NUL */
+	l = strands_len(s) + 1;
+	if (l > mlen)
+		l = mlen;
+
+	assert(vsl->wlp < vsl->wle);
+
+	/* Flush if necessary */
+	if (VSL_END(vsl->wlp, l) >= vsl->wle)
+		VSL_Flush(vsl, 1);
+	assert(VSL_END(vsl->wlp, l) < vsl->wle);
+
+	mlen = strands_cat(VSL_DATA(vsl->wlp), l, s);
+	assert(l == mlen);
+
+	vsl->wlp = vsl_hdr(tag, vsl->wlp, l, vsl->wid);
+	assert(vsl->wlp < vsl->wle);
+	vsl->wlr++;
+
+	if (DO_DEBUG(DBG_SYNCVSL))
+		VSL_Flush(vsl, 0);
+}
+
 /*--------------------------------------------------------------------
  * VSL-buffered
  */
diff --git a/bin/varnishtest/tests/m00000.vtc b/bin/varnishtest/tests/m00000.vtc
index 342a861e3..5a861c680 100644
--- a/bin/varnishtest/tests/m00000.vtc
+++ b/bin/varnishtest/tests/m00000.vtc
@@ -14,9 +14,30 @@ varnish v1 -vcl+backend {
 	import debug as dbg;
 	import debug as dbg;	// again
 
+	sub log {
+		std.log("VCL" + " initiated " + "log");
+		std.log("01030507090b0d0f" +
+			"11131517191b1d1f" +
+			"21232527292b2d2f" +
+			"31333537393b3d3f" +
+			"41434547494b4d4f" +
+			"51535557595b5d5f" +
+			"61636567696b6d6f" +
+			"71737577797b7d7f" +
+			"81838587898b8d8f" +
+			"91939597999b9d9f" +
+			"a1a3a5a7a9abadaf" +
+			"b1b3b5b7b9bbbdbf" +
+			"c1c3c5c7c9cbcdcf" +
+			"d1d3d5d7d9dbdddf" +
+			"e1e3e5e7e9ebedef" +
+			"f1f3f5f7f9fbfdff");
+	}
+
 	sub vcl_init {
 		new objx = dbg.obj();
 		dbg.vsc_new();
+		call log;
 	}
 
 	sub vcl_synth {
@@ -54,7 +75,7 @@ varnish v1 -vcl+backend {
 		debug.test_priv_vcl();
 		objx.test_priv_call();
 		objx.test_priv_vcl();
-		std.log("VCL" + " initiated " + "log");
+		call log;
 		std.syslog(8 + 7, "Somebody runs varnishtest");
 		debug.rot52(resp);
 	}
@@ -89,6 +110,12 @@ client c1 {
 varnish v1 -expect DEBUG.count == 1
 
 logexpect l1 -v v1 -g raw -d 1 {
+	expect * 0    CLI		{^Rd vcl.load}
+	expect 0 0    VCL_Log		{^VCL initiated log}
+	# vsl_reclen = 255b minus NUL byte (last "ff" missing)
+	expect 0 0    VCL_Log		{^01030507090b0d0f11131517191b1d1f21232527292b2d2f31333537393b3d3f41434547494b4d4f51535557595b5d5f61636567696b6d6f71737577797b7d7f81838587898b8d8f91939597999b9d9fa1a3a5a7a9abadafb1b3b5b7b9bbbdbfc1c3c5c7c9cbcdcfd1d3d5d7d9dbdddfe1e3e5e7e9ebedeff1f3f5f7f9fbfd$}
+	expect 0 0    Debug		{VCL_EVENT_WARM}
+
 	expect * 1001 VCL_call		{^DELIVER}
 	expect 0 =    RespUnset	{^foo: bAr}
 	expect 0 =    RespHeader	{^foo: BAR}
@@ -100,6 +127,7 @@ logexpect l1 -v v1 -g raw -d 1 {
 	expect 0 =    RespHeader	{^what: [1-9][0-9]}
 	expect 0 =    RespHeader	{^not: -1}
 	expect 0 =    VCL_Log		{^VCL initiated log}
+	expect 0 =    VCL_Log		{^01030507090b0d0f11131517191b1d1f21232527292b2d2f31333537393b3d3f41434547494b4d4f51535557595b5d5f61636567696b6d6f71737577797b7d7f81838587898b8d8f91939597999b9d9fa1a3a5a7a9abadafb1b3b5b7b9bbbdbfc1c3c5c7c9cbcdcfd1d3d5d7d9dbdddfe1e3e5e7e9ebedeff1f3f5f7f9fbfd$}
 	expect 0 =    RespHeader	{^Encrypted: ROT52}
 	expect 0 =    VCL_return	{^deliver}
 } -start
diff --git a/bin/varnishtest/tests/r03131.vtc b/bin/varnishtest/tests/r03131.vtc
index 5dda251fb..c70f6500f 100644
--- a/bin/varnishtest/tests/r03131.vtc
+++ b/bin/varnishtest/tests/r03131.vtc
@@ -11,11 +11,6 @@ varnish v1 -vcl {
 	}
 
 	sub vcl_synth {
-		set resp.http.res1 = vtc.workspace_reserve(client, 1024 * 1024);
-
-		# XXX overflow gets cleared by WS_Reset called from std.log()
-		# -> do we want this ?
-
 		vtc.workspace_alloc(session, -16);
 		std.log("res(8) = " + vtc.workspace_reserve(session, 8));
 		std.log("res(15) = " + vtc.workspace_reserve(session, 15));
diff --git a/lib/libvmod_std/vmod_std.c b/lib/libvmod_std/vmod_std.c
index b3233d827..51a9b7e16 100644
--- a/lib/libvmod_std/vmod_std.c
+++ b/lib/libvmod_std/vmod_std.c
@@ -133,19 +133,12 @@ vmod_random(VRT_CTX, VCL_REAL lo, VCL_REAL hi)
 VCL_VOID v_matchproto_(td_std_log)
 vmod_log(VRT_CTX, VCL_STRANDS s)
 {
-	const char *p;
-	uintptr_t sn;
-
 	CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
-	sn = WS_Snapshot(ctx->ws);
-	p = VRT_StrandsWS(ctx->ws, NULL, s);
-	if (p != NULL) {
-		if (ctx->vsl != NULL)
-			VSLb(ctx->vsl, SLT_VCL_Log, "%s", p);
-		else
-			VSL(SLT_VCL_Log, 0, "%s", p);
-	}
-	WS_Reset(ctx->ws, sn);
+
+	if (ctx->vsl != NULL)
+		VSLbs(ctx->vsl, SLT_VCL_Log, s);
+	else
+		VSLs(SLT_VCL_Log, 0, s);
 }
 
 /* XXX use vsyslog() ? */


More information about the varnish-commit mailing list