[master] 49d52eb Introduce a new SLT_F_BINARY flag which hexdumps the VSL record.
Poul-Henning Kamp
phk at FreeBSD.org
Mon Mar 5 10:09:08 UTC 2018
commit 49d52ebdfd8cdf96817cc2758155ff4adc989bfb
Author: Poul-Henning Kamp <phk at FreeBSD.org>
Date: Mon Mar 5 09:40:32 2018 +0000
Introduce a new SLT_F_BINARY flag which hexdumps the VSL record.
Set this on the H2 'raw' records.
Move the hexdumping to the API side.
diff --git a/bin/varnishd/cache/cache_shmlog.c b/bin/varnishd/cache/cache_shmlog.c
index 754c8f6..04e425c 100644
--- a/bin/varnishd/cache/cache_shmlog.c
+++ b/bin/varnishd/cache/cache_shmlog.c
@@ -392,37 +392,33 @@ VSLb_ts(struct vsl_log *vsl, const char *event, double first, double *pprev,
void
VSLb_bin(struct vsl_log *vsl, enum VSL_tag_e tag, ssize_t len, const void *ptr)
{
+ unsigned mlen;
char *p;
- const uint8_t *pp = ptr;
- int suff = 0;
- size_t tl, ll;
- assert(len >= 0);
- AN(pp);
+ vsl_sanity(vsl);
+ AN(ptr);
if (vsl_tag_is_masked(tag))
return;
- vsl_sanity(vsl);
- tl = len * 2 + 1;
- if (tl > cache_param->vsl_reclen) {
- len = (cache_param->vsl_reclen - 2) / 2;
- tl = len * 2 + 2;
- suff = 1;
- }
- if (VSL_END(vsl->wlp, tl) >= vsl->wle)
+ mlen = cache_param->vsl_reclen;
+
+ /* Truncate */
+ if (len > mlen)
+ len = mlen;
+
+ assert(vsl->wlp < vsl->wle);
+
+ /* Flush if necessary */
+ if (VSL_END(vsl->wlp, len) >= vsl->wle)
VSL_Flush(vsl, 1);
- assert(VSL_END(vsl->wlp, tl) < vsl->wle);
+ assert(VSL_END(vsl->wlp, len) < vsl->wle);
p = VSL_DATA(vsl->wlp);
- for (ll = 0; ll < len; ll++) {
- assert(snprintf(p, 3, "%02x", *pp) == 2);
- pp++;
- p += 2;
- }
- if (suff)
- *p++ = '-';
- *p = '\0';
- vsl->wlp = vsl_hdr(tag, vsl->wlp, tl, vsl->wid);
+ memcpy(p, ptr, len);
+ vsl->wlp = vsl_hdr(tag, vsl->wlp, len, vsl->wid);
assert(vsl->wlp < vsl->wle);
vsl->wlr++;
+
+ if (DO_DEBUG(DBG_SYNCVSL))
+ VSL_Flush(vsl, 0);
}
/*--------------------------------------------------------------------
diff --git a/bin/varnishtest/tests/t02000.vtc b/bin/varnishtest/tests/t02000.vtc
index 6062a3a..c2a1b0a 100644
--- a/bin/varnishtest/tests/t02000.vtc
+++ b/bin/varnishtest/tests/t02000.vtc
@@ -19,6 +19,8 @@ varnish v1 -cliok "param.set debug +syncvsl"
varnish v1 -cliok "param.set vsl_mask +H2RxHdr,+H2RxBody,+H2TxHdr,+H2TxBody"
+process p1 {exec varnishlog -n ${v1_name} -g raw -w ${tmpdir}/vlog -A} -start
+
client c1 {
txpri
expect_close
@@ -56,3 +58,8 @@ varnish v1 -expect MEMPOOL.req0.live == 0
varnish v1 -expect MEMPOOL.req1.live == 0
varnish v1 -expect MEMPOOL.sess0.live == 0
varnish v1 -expect MEMPOOL.sess1.live == 0
+
+process p1 -stop
+# shell {cat ${tmpdir}/vlog}
+shell -match {1001 H2TxHdr c \[000006040000000000\]} \
+ {cat ${tmpdir}/vlog}
diff --git a/bin/varnishtest/vtc_varnish.c b/bin/varnishtest/vtc_varnish.c
index 1ba5e7c..12e4244 100644
--- a/bin/varnishtest/vtc_varnish.c
+++ b/bin/varnishtest/vtc_varnish.c
@@ -214,6 +214,7 @@ varnishlog_thread(void *priv)
unsigned len;
const char *tagname, *data;
int type, i, opt;
+ struct vsb *vsb = NULL;
CAST_OBJ_NOTNULL(v, priv, VARNISH_MAGIC);
@@ -258,8 +259,19 @@ varnishlog_thread(void *priv)
'b' : '-';
data = VSL_CDATA(c->rec.ptr);
v->vsl_tag_count[tag]++;
- vtc_log(v->vl, 4, "vsl| %10u %-15s %c %.*s",
- vxid, tagname, type, (int)len, data);
+ if (VSL_tagflags[tag] & SLT_F_BINARY) {
+ if (vsb == NULL)
+ vsb = VSB_new_auto();
+ VSB_clear(vsb);
+ VSB_quote(vsb, data, len, VSB_QUOTE_HEX);
+ AZ(VSB_finish(vsb));
+ /* +2 to skip "0x" */
+ vtc_log(v->vl, 4, "vsl| %10u %-15s %c [%s]",
+ vxid, tagname, type, VSB_data(vsb) + 2);
+ } else {
+ vtc_log(v->vl, 4, "vsl| %10u %-15s %c %.*s",
+ vxid, tagname, type, (int)len, data);
+ }
}
if (i == 0) {
/* Nothing to do but wait */
@@ -282,6 +294,8 @@ varnishlog_thread(void *priv)
if (c)
VSL_DeleteCursor(c);
VSL_Delete(vsl);
+ if (vsb != NULL)
+ VSB_destroy(&vsb);
return (NULL);
}
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
index c80c135..728011b 100644
--- a/include/tbl/vsl_tags.h
+++ b/include/tbl/vsl_tags.h
@@ -545,19 +545,19 @@ SLTM(BackendStart, 0, "Backend request start",
"\n"
)
-SLTM(H2RxHdr, 0, "Received HTTP2 frame header",
+SLTM(H2RxHdr, SLT_F_BINARY, "Received HTTP2 frame header",
"Binary data"
)
-SLTM(H2RxBody, 0, "Received HTTP2 frame body",
+SLTM(H2RxBody, SLT_F_BINARY, "Received HTTP2 frame body",
"Binary data"
)
-SLTM(H2TxHdr, 0, "Transmitted HTTP2 frame header",
+SLTM(H2TxHdr, SLT_F_BINARY, "Transmitted HTTP2 frame header",
"Binary data"
)
-SLTM(H2TxBody, 0, "Transmitted HTTP2 frame body",
+SLTM(H2TxBody, SLT_F_BINARY, "Transmitted HTTP2 frame body",
"Binary data"
)
diff --git a/include/vapi/vsl_int.h b/include/vapi/vsl_int.h
index 57986cd..589a966 100644
--- a/include/vapi/vsl_int.h
+++ b/include/vapi/vsl_int.h
@@ -98,5 +98,6 @@ enum VSL_tag_e {
/* VSL tag flags */
#define SLT_F_UNUSED (1 << 0)
#define SLT_F_UNSAFE (1 << 1)
+#define SLT_F_BINARY (1 << 2)
#endif /* VAPI_VSL_INT_H_INCLUDED */
diff --git a/lib/libvarnishapi/vsl.c b/lib/libvarnishapi/vsl.c
index af23e92..970c175 100644
--- a/lib/libvarnishapi/vsl.c
+++ b/lib/libvarnishapi/vsl.c
@@ -223,8 +223,39 @@ static const char * const VSL_transactions[VSL_t__MAX] = {
return (-5); \
} while (0)
-int
-VSL_Print(const struct VSL_data *vsl, const struct VSL_cursor *c, void *fo)
+static int
+vsl_print_unsafe(FILE *fo, unsigned len, const char *data)
+{
+
+ VSL_PRINT(fo, "\"");
+ while (len-- > 0) {
+ if (*data >= ' ' && *data <= '~')
+ VSL_PRINT(fo, "%c", *data);
+ else
+ VSL_PRINT(fo, "%%%02x", (unsigned char)*data);
+ data++;
+ }
+ VSL_PRINT(fo, "\"\n");
+ return (0);
+}
+
+
+static int
+vsl_print_binary(FILE *fo, unsigned len, const char *data)
+{
+
+ VSL_PRINT(fo, "[");
+ while (len-- > 0) {
+ VSL_PRINT(fo, "%02x", (unsigned char)*data);
+ data++;
+ }
+ VSL_PRINT(fo, "]\n");
+ return (0);
+}
+
+static int
+vsl_print(const struct VSL_data *vsl, const struct VSL_cursor *c, void *fo,
+ int terse)
{
enum VSL_tag_e tag;
uint32_t vxid;
@@ -244,57 +275,34 @@ VSL_Print(const struct VSL_data *vsl, const struct VSL_cursor *c, void *fo)
'b' : '-';
data = VSL_CDATA(c->rec.ptr);
- if (VSL_tagflags[tag] & SLT_F_UNSAFE) {
- VSL_PRINT(fo, "%10u %-14s %c \"", vxid, VSL_tags[tag], type);
- while (len-- > 0) {
- if (len == 0 && tag == SLT_Debug && *data == '\0')
- break;
- if (*data >= ' ' && *data <= '~')
- VSL_PRINT(fo, "%c", *data);
- else
- VSL_PRINT(fo, "%%%02x", (unsigned char)*data);
- data++;
- }
- VSL_PRINT(fo, "\"\n");
- } else
- VSL_PRINT(fo, "%10u %-14s %c %.*s\n", vxid, VSL_tags[tag],
- type, (int)len, data);
+ if (!terse)
+ VSL_PRINT(fo, "%10u ", vxid);
+ VSL_PRINT(fo, "%-14s ", VSL_tags[tag]);
+ if (!terse)
+ VSL_PRINT(fo, "%c ", type);
+
+ if (VSL_tagflags[tag] & SLT_F_UNSAFE)
+ (void)vsl_print_unsafe(fo, len, data);
+ else if (VSL_tagflags[tag] & SLT_F_BINARY)
+ (void)vsl_print_binary(fo, len, data);
+ else
+ VSL_PRINT(fo, "%.*s\n", (int)len, data);
return (0);
}
int
-VSL_PrintTerse(const struct VSL_data *vsl, const struct VSL_cursor *c, void *fo)
+VSL_Print(const struct VSL_data *vsl, const struct VSL_cursor *c, void *fo)
{
- enum VSL_tag_e tag;
- unsigned len;
- const char *data;
- CHECK_OBJ_NOTNULL(vsl, VSL_MAGIC);
- if (c == NULL || c->rec.ptr == NULL)
- return (0);
- if (fo == NULL)
- fo = stdout;
- tag = VSL_TAG(c->rec.ptr);
- len = VSL_LEN(c->rec.ptr);
- data = VSL_CDATA(c->rec.ptr);
+ return (vsl_print(vsl, c, fo, 0));
+}
- if (VSL_tagflags[tag] & SLT_F_UNSAFE) {
- VSL_PRINT(fo, "%-14s \"", VSL_tags[tag]);
- while (len-- > 0) {
- if (len == 0 && tag == SLT_Debug && *data == '\0')
- break;
- if (*data >= ' ' && *data <= '~')
- VSL_PRINT(fo, "%c", *data);
- else
- VSL_PRINT(fo, "%%%02x", (unsigned char)*data);
- data++;
- }
- VSL_PRINT(fo, "\"\n");
- } else
- VSL_PRINT(fo, "%-14s %.*s\n", VSL_tags[tag], (int)len, data);
+int
+VSL_PrintTerse(const struct VSL_data *vsl, const struct VSL_cursor *c, void *fo)
+{
- return (0);
+ return (vsl_print(vsl, c, fo, 1));
}
int
More information about the varnish-commit
mailing list