[master] 588d5c45b ws: Tie workspace logs to their transactions
Dridi Boukelmoune
dridi.boukelmoune at gmail.com
Wed Dec 1 15:04:05 UTC 2021
commit 588d5c45bd94792f6bd5d113b1fc27efdc1e6d63
Author: Dridi Boukelmoune <dridi.boukelmoune at gmail.com>
Date: Mon Apr 6 20:36:41 2020 +0200
ws: Tie workspace logs to their transactions
That is, when it's a request or backend transaction, otherwise it's
still logged with VXID 0. The goal is to allow a correlation between
VCL statements and their workspace footprint by sharing the same
transaction instead of being split between raw and vxid scopes. That
kind of debugging becomes possible when the workspace debug flag is
used and VCL_trace records are not masked.
Given the verbosity of both workspace and trace logs, we would need
new tools to process transactions for this purpose and until we can
link everything we have a chicken-egg problem.
This change does not go all the way and relies on the thread-local
worker reference to opportunistically log into its VSL buffer when
it has one. When the workspace is initialized, the buffer may not
be ready yet, so some logs may still end up raw. What's likely going
to be missing is workspace early initialization and teardown: in other
words before and after VCL execution, which should be good enough for
the purpose of debugging workspace operations in VCL tasks.
diff --git a/bin/varnishd/cache/cache_ws.c b/bin/varnishd/cache/cache_ws.c
index c709817e1..4f7d5f4f2 100644
--- a/bin/varnishd/cache/cache_ws.c
+++ b/bin/varnishd/cache/cache_ws.c
@@ -44,7 +44,7 @@ WS_Assert(const struct ws *ws)
{
CHECK_OBJ_NOTNULL(ws, WS_MAGIC);
- DSL(DBG_WORKSPACE, 0, "WS(%p) = (%s, %p %zu %zu %zu)",
+ DSLb(DBG_WORKSPACE, "WS(%p) = (%s, %p %zu %zu %zu)",
ws, ws->id, ws->s, pdiff(ws->s, ws->f),
ws->r == NULL ? 0 : pdiff(ws->f, ws->r),
pdiff(ws->s, ws->e));
@@ -84,7 +84,7 @@ WS_Init(struct ws *ws, const char *id, void *space, unsigned len)
{
unsigned l;
- DSL(DBG_WORKSPACE, 0,
+ DSLb(DBG_WORKSPACE,
"WS_Init(%p, \"%s\", %p, %u)", ws, id, space, len);
assert(space != NULL);
INIT_OBJ(ws, WS_MAGIC);
@@ -116,12 +116,12 @@ WS_Reset(struct ws *ws, uintptr_t pp)
WS_Assert(ws);
AN(pp);
if (pp == snap_overflowed) {
- DSL(DBG_WORKSPACE, 0, "WS_Reset(%p, overflowed)", ws);
+ DSLb(DBG_WORKSPACE, "WS_Reset(%p, overflowed)", ws);
AN(WS_Overflowed(ws));
return;
}
p = (char *)pp;
- DSL(DBG_WORKSPACE, 0, "WS_Reset(%p, %p)", ws, p);
+ DSLb(DBG_WORKSPACE, "WS_Reset(%p, %p)", ws, p);
assert(ws->r == NULL);
assert(p >= ws->s);
assert(p <= ws->e);
@@ -176,7 +176,7 @@ WS_Alloc(struct ws *ws, unsigned bytes)
}
r = ws->f;
ws->f += bytes;
- DSL(DBG_WORKSPACE, 0, "WS_Alloc(%p, %u) = %p", ws, bytes, r);
+ DSLb(DBG_WORKSPACE, "WS_Alloc(%p, %u) = %p", ws, bytes, r);
WS_Assert(ws);
return (r);
}
@@ -202,7 +202,7 @@ WS_Copy(struct ws *ws, const void *str, int len)
r = ws->f;
ws->f += bytes;
memcpy(r, str, len);
- DSL(DBG_WORKSPACE, 0, "WS_Copy(%p, %d) = %p", ws, len, r);
+ DSLb(DBG_WORKSPACE, "WS_Copy(%p, %d) = %p", ws, len, r);
WS_Assert(ws);
return (r);
}
@@ -214,10 +214,10 @@ WS_Snapshot(struct ws *ws)
WS_Assert(ws);
assert(ws->r == NULL);
if (WS_Overflowed(ws)) {
- DSL(DBG_WORKSPACE, 0, "WS_Snapshot(%p) = overflowed", ws);
+ DSLb(DBG_WORKSPACE, "WS_Snapshot(%p) = overflowed", ws);
return (snap_overflowed);
}
- DSL(DBG_WORKSPACE, 0, "WS_Snapshot(%p) = %p", ws, ws->f);
+ DSLb(DBG_WORKSPACE, "WS_Snapshot(%p) = %p", ws, ws->f);
return ((uintptr_t)ws->f);
}
@@ -236,7 +236,7 @@ WS_ReserveAll(struct ws *ws)
b = pdiff(ws->f, ws->r);
WS_Assert(ws);
- DSL(DBG_WORKSPACE, 0, "WS_ReserveAll(%p) = %u", ws, b);
+ DSLb(DBG_WORKSPACE, "WS_ReserveAll(%p) = %u", ws, b);
return (b);
}
@@ -259,7 +259,7 @@ WS_ReserveSize(struct ws *ws, unsigned bytes)
return (0);
}
ws->r = ws->f + bytes;
- DSL(DBG_WORKSPACE, 0, "WS_ReserveSize(%p, %u/%u) = %u",
+ DSLb(DBG_WORKSPACE, "WS_ReserveSize(%p, %u/%u) = %u",
ws, bytes, l, bytes);
WS_Assert(ws);
return (bytes);
@@ -270,7 +270,7 @@ WS_Release(struct ws *ws, unsigned bytes)
{
WS_Assert(ws);
assert(bytes <= ws->e - ws->f);
- DSL(DBG_WORKSPACE, 0, "WS_Release(%p, %u)", ws, bytes);
+ DSLb(DBG_WORKSPACE, "WS_Release(%p, %u)", ws, bytes);
assert(ws->r != NULL);
assert(ws->f + bytes <= ws->r);
ws->f += PRNDUP(bytes);
@@ -282,7 +282,7 @@ void
WS_ReleaseP(struct ws *ws, const char *ptr)
{
WS_Assert(ws);
- DSL(DBG_WORKSPACE, 0, "WS_ReleaseP(%p, %p (%zd))", ws, ptr, ptr - ws->f);
+ DSLb(DBG_WORKSPACE, "WS_ReleaseP(%p, %p (%zd))", ws, ptr, ptr - ws->f);
assert(ws->r != NULL);
assert(ptr >= ws->f);
assert(ptr <= ws->r);
diff --git a/bin/varnishd/cache/cache_ws_emu.c b/bin/varnishd/cache/cache_ws_emu.c
index f3d74150e..22e85870c 100644
--- a/bin/varnishd/cache/cache_ws_emu.c
+++ b/bin/varnishd/cache/cache_ws_emu.c
@@ -118,7 +118,7 @@ WS_Assert(const struct ws *ws)
AZ(ws->r);
}
- DSL(DBG_WORKSPACE, 0, "WS(%p) = (%s, %p %zu %zu %zu)",
+ DSLb(DBG_WORKSPACE, "WS(%p) = (%s, %p %zu %zu %zu)",
ws, ws->id, ws->s, wa2 == NULL ? 0 : wa2->off + PRNDUP(wa2->len),
ws->r == NULL ? 0 : pdiff(ws->f, ws->r),
pdiff(ws->s, ws->e));
@@ -159,7 +159,7 @@ WS_Init(struct ws *ws, const char *id, void *space, unsigned len)
{
struct ws_emu *we;
- DSL(DBG_WORKSPACE, 0,
+ DSLb(DBG_WORKSPACE,
"WS_Init(%p, \"%s\", %p, %u)", ws, id, space, len);
assert(space != NULL);
assert(PAOK(space));
@@ -203,12 +203,12 @@ WS_Reset(struct ws *ws, uintptr_t pp)
WS_Assert(ws);
AN(pp);
if (pp == snap_overflowed) {
- DSL(DBG_WORKSPACE, 0, "WS_Reset(%p, overflowed)", ws);
+ DSLb(DBG_WORKSPACE, "WS_Reset(%p, overflowed)", ws);
AN(WS_Overflowed(ws));
return;
}
p = (char *)pp;
- DSL(DBG_WORKSPACE, 0, "WS_Reset(%p, %p)", ws, p);
+ DSLb(DBG_WORKSPACE, "WS_Reset(%p, %p)", ws, p);
AZ(ws->r);
we = ws_emu(ws);
@@ -308,7 +308,7 @@ WS_Alloc(struct ws *ws, unsigned bytes)
WS_Assert(ws);
if (wa != NULL) {
AN(wa->ptr);
- DSL(DBG_WORKSPACE, 0, "WS_Alloc(%p, %u) = %p",
+ DSLb(DBG_WORKSPACE, "WS_Alloc(%p, %u) = %p",
ws, bytes, wa->ptr);
return (wa->ptr);
}
@@ -329,7 +329,7 @@ WS_Copy(struct ws *ws, const void *str, int len)
if (wa != NULL) {
AN(wa->ptr);
memcpy(wa->ptr, str, len);
- DSL(DBG_WORKSPACE, 0, "WS_Copy(%p, %d) = %p",
+ DSLb(DBG_WORKSPACE, "WS_Copy(%p, %d) = %p",
ws, len, wa->ptr);
return (wa->ptr);
}
@@ -346,7 +346,7 @@ WS_Snapshot(struct ws *ws)
WS_Assert(ws);
assert(ws->r == NULL);
if (WS_Overflowed(ws)) {
- DSL(DBG_WORKSPACE, 0, "WS_Snapshot(%p) = overflowed", ws);
+ DSLb(DBG_WORKSPACE, "WS_Snapshot(%p) = overflowed", ws);
return (snap_overflowed);
}
@@ -354,7 +354,7 @@ WS_Snapshot(struct ws *ws)
wa = VTAILQ_LAST(&we->head, ws_alloc_head);
CHECK_OBJ_ORNULL(wa, WS_ALLOC_MAGIC);
p = (wa == NULL ? ws->s : wa->ptr);
- DSL(DBG_WORKSPACE, 0, "WS_Snapshot(%p) = %p", ws, p);
+ DSLb(DBG_WORKSPACE, "WS_Snapshot(%p) = %p", ws, p);
return ((uintptr_t)p);
}
@@ -376,7 +376,7 @@ WS_ReserveAll(struct ws *ws)
}
b = pdiff(ws->f, ws->r);
- DSL(DBG_WORKSPACE, 0, "WS_ReserveAll(%p) = %u", ws, b);
+ DSLb(DBG_WORKSPACE, "WS_ReserveAll(%p) = %u", ws, b);
WS_Assert(ws);
return (b);
}
@@ -397,7 +397,7 @@ WS_ReserveSize(struct ws *ws, unsigned bytes)
ws->f = wa->ptr;
ws->r = ws->f + bytes;
we = ws_emu(ws);
- DSL(DBG_WORKSPACE, 0, "WS_ReserveSize(%p, %u/%u) = %u",
+ DSLb(DBG_WORKSPACE, "WS_ReserveSize(%p, %u/%u) = %u",
ws, bytes, we->len - wa->off, bytes);
WS_Assert(ws);
return (bytes);
@@ -436,7 +436,7 @@ WS_Release(struct ws *ws, unsigned bytes)
{
ws_release(ws, bytes);
- DSL(DBG_WORKSPACE, 0, "WS_Release(%p, %u)", ws, bytes);
+ DSLb(DBG_WORKSPACE, "WS_Release(%p, %u)", ws, bytes);
}
void
@@ -450,7 +450,7 @@ WS_ReleaseP(struct ws *ws, const char *ptr)
assert(ptr <= ws->r);
l = pdiff(ws->f, ptr);
ws_release(ws, l);
- DSL(DBG_WORKSPACE, 0, "WS_ReleaseP(%p, %p (%u))", ws, ptr, l);
+ DSLb(DBG_WORKSPACE, "WS_ReleaseP(%p, %p (%u))", ws, ptr, l);
}
void *
diff --git a/bin/varnishd/fuzzers/esi_parse_fuzzer.c b/bin/varnishd/fuzzers/esi_parse_fuzzer.c
index 5cdb2f449..8d2ff3caa 100644
--- a/bin/varnishd/fuzzers/esi_parse_fuzzer.c
+++ b/bin/varnishd/fuzzers/esi_parse_fuzzer.c
@@ -89,6 +89,14 @@ VSLb_ts(struct vsl_log *l, const char *event, vtim_real first, vtim_real *pprev,
(void)now;
}
+void
+WRK_Log(enum VSL_tag_e tag, const char *fmt, ...)
+{
+
+ (void)tag;
+ (void)fmt;
+}
+
int
LLVMFuzzerTestOneInput(const uint8_t* data, size_t size)
{
diff --git a/bin/varnishtest/tests/c00071.vtc b/bin/varnishtest/tests/c00071.vtc
index b7f8d12fc..09e5ccf8b 100644
--- a/bin/varnishtest/tests/c00071.vtc
+++ b/bin/varnishtest/tests/c00071.vtc
@@ -46,17 +46,14 @@ varnish v1 -vsl_catchup
logexpect l1 -v v1 -g vxid -q "vxid == 1006" {
expect * 1006 VCL_call {^DELIVER$}
- expect 0 = LostHeader {^x-foo:$}
+ expect * = LostHeader {^x-foo:$}
# std.log does not need workspace
expect 0 = VCL_Log {^dummy$}
+ expect * = Debug {^WS_Snapshot.* = overflowed}
+ expect * = Debug {^WS_Reset.*, overflowed}
# the workspace is overflowed, but still has space
- expect 0 = RespHeader {^x-of: true$}
- expect 6 = Error {^workspace_client overflow}
-} -start
-
-logexpect l2 -v v1 -g raw -i Debug {
- expect * 0 Debug {^WS_Snapshot.* = overflowed}
- expect 24 0 Debug {^WS_Reset.*, overflowed}
+ expect * = RespHeader {^x-of: true$}
+ expect * = Error {^workspace_client overflow}
} -start
client c2 {
@@ -67,7 +64,6 @@ client c2 {
} -run
logexpect l1 -wait
-logexpect l2 -wait
varnish v1 -expect client_resp_500 == 2
varnish v1 -expect ws_client_overflow == 2
More information about the varnish-commit
mailing list