Skip to content

V
varnishevent
Commit 342756c9 authored by Geoff Simmons's avatar Geoff Simmons
Browse files
Options

add %{vxid}x formatter

parent 7d496cc5
Hide whitespace changes
Inline Side-by-side
Showing with 63 additions and 17 deletions
src/format.c
View file @ 342756c9
......@@ -726,6 +726,26 @@ format_SLT(const tx_t *tx, const arg_t *args, char **s, size_t *len)
}
}
void
format_vxid(const tx_t *tx, const arg_t *args, char **s, size_t *len)
{
(void) args;
sprintf(scratch, "%d", tx->vxid);
*s = scratch;
*len = strlen(*s);
}
#if 0
void
format_pvxid(const tx_t *tx, const arg_t *args, char **s, size_t *len)
{
(void) args;
sprintf(scratch, "%d", tx->pvxid);
*s = scratch;
*len = strlen(*s);
}
#endif
static void
add_fmt(const compiled_fmt_t *fmt, struct vsb *os, unsigned n,
formatter_f formatter, const char *name, enum VSL_tag_e tag, int fld)
......@@ -890,10 +910,11 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
p++;
/* Only the SLT or time formatters permitted for the "zero" format
(neither client nor backend) */
/* Only the SLT, vxid or time formatters permitted for the "raw"
format (neither client nor backend) */
if (R(type)
&& sscanf(p, "{tag:%s}x", scratch) != 1
&& sscanf(p, "{vxid}x") != 1
&& *p != 't'
&& sscanf(p, "{%s}t", scratch) != 1) {
sprintf(err, "Unknown format starting at: %s", --p);
......@@ -1114,6 +1135,9 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
add_fmt(fmt, os, n, format_SLT, hdr, t, fld_nr);
add_tag(type, t, hdr);
}
else if (strncmp(fname, "vxid", 4) == 0) {
add_formatter(fmt, os, n, format_vxid);
}
else {
sprintf(err, "Unknown format starting at: %s", fname);
return 1;
......
src/format.h
View file @ 342756c9
......@@ -102,3 +102,5 @@ formatter_f format_VCL_disp;
formatter_f format_VCL_Log;
formatter_f format_SLT;
formatter_f format_vxid;
src/test/raw.conf
View file @ 342756c9
......@@ -3,4 +3,4 @@
monitor.interval = 0
cformat=
rformat=%t %{%F-%T.%i}t %{tag:Begin}x
rformat=%t %{%F-%T.%i}t %{tag:Begin}x %{vxid}x
src/test/regress.sh
View file @ 342756c9
......@@ -12,7 +12,7 @@ rm -f $LOG $OUT
../varnishevent -f varnishevent.conf -r sw-doc.log -w $OUT -v
CKSUM=$( cksum $OUT )
if [ "$CKSUM" != "4053530460 22327728 $OUT" ]; then
if [ "$CKSUM" != "481068350 22573437 $OUT" ]; then
echo "ERROR: Regression test log output incorrect cksum: $CKSUM"
exit 1
fi
......
src/test/test_format.c
View file @ 342756c9
......@@ -1339,6 +1339,24 @@ static const char
return NULL;
}
static const char
*test_format_vxid(void)
{
tx_t tx;
arg_t args;
char *str;
size_t len;
printf("... testing format_vxid()\n");
tx.vxid = 4711;
format_vxid(&tx, &args, &str, &len);
MASSERT(strncmp(str, "4711", 4) == 0);
MASSERT(len == 4);
return NULL;
}
static const char
*test_FMT_Fini(void)
{
......@@ -1373,6 +1391,7 @@ static const char
tx.magic = TX_MAGIC;
tx.occupied = 1;
tx.vxid = 4711;
VSTAILQ_INIT(&tx.lines);
for (int i = 0; i < NRECS; i++) {
recs[i] = (logline_t *) calloc(1, sizeof(logline_t));
......@@ -1433,7 +1452,7 @@ static const char
"%t %T %{%F-%T.%i}t %U %u %{Varnish:time_firstbyte}x "\
"%{Varnish:hitmiss}x %{Varnish:handling}x %{VCL_Log:baz}x "\
"%{tag:VCL_acl}x %{tag:Debug}x %{tag:Timestamp:Req}x "\
"%{tag:ReqAcct[0]}x %{tag:Timestamp:Resp[2]}x"
"%{tag:ReqAcct[0]}x %{tag:Timestamp:Resp[2]}x %{vxid}x"
strcpy(config.cformat, FULL_CLIENT_FMT);
status = FMT_Init(err);
VMASSERT(status == 0, "FMT_Init: %s", err);
......@@ -1480,7 +1499,7 @@ static const char
"http://bazquux.com/foo?bar=baz&quux=wilco HTTP/1.1 200 "\
"[%d/%b/%Y:%T %z] 0 %F-%T.529143 /foo varnish 0.000166 hit hit "\
"logload MATCH ACL \"10.0.0.0\"/8 \"foo\\0\\377 bar\" " \
"1429213569.602005 0.000000 0.000000 60 0.000125\n"
"1429213569.602005 0.000000 0.000000 60 0.000125 4711\n"
tm = localtime(&t);
MAN(strftime(strftime_s, BUFSIZ, EXP_FULL_CLIENT_OUTPUT, tm));
VMASSERT(strcmp(VSB_data(os), strftime_s) == 0, "'%s' != '%s'",
......@@ -1493,7 +1512,7 @@ static const char
#define FULL_BACKEND_FMT "%b %d %D %H %h %I %{Foo}i %{Bar}o %l %m %O %q %r %s "\
"%t %T %{%F-%T.%i}t %U %u %{Varnish:time_firstbyte}x %{VCL_Log:baz}x "\
"%{tag:Fetch_Body}x %{tag:Debug}x %{tag:Timestamp:Bereq}x "\
"%{tag:BereqAcct[5]}x %{tag:Timestamp:Bereq[1]}x"
"%{tag:BereqAcct[5]}x %{tag:Timestamp:Bereq[1]}x %{vxid}x"
strcpy(config.bformat, FULL_BACKEND_FMT);
config.cformat[0] = '\0';
status = FMT_Init(err);
......@@ -1546,7 +1565,7 @@ static const char
"http://bazquux.com/foo?bar=baz&quux=wilco HTTP/1.1 200 "\
"[%d/%b/%Y:%T %z] 0 %F-%T.529143 /foo varnish 0.002837 logload "\
"2 chunked stream \"foo\\0\\377 bar\" "\
"1429210777.728290 0.000048 0.000048 283 0.000048\n"
"1429210777.728290 0.000048 0.000048 283 0.000048 4711\n"
tm = localtime(&t);
MAN(strftime(strftime_s, BUFSIZ, EXP_FULL_BACKEND_OUTPUT, tm));
VMASSERT(strcmp(VSB_data(os), strftime_s) == 0, "'%s' != '%s'",
......@@ -1556,7 +1575,7 @@ static const char
FMT_Fini();
VSB_clear(os);
#define FULL_RAW_FMT "%t %{%F-%T.%i}t %{tag:Backend_health}x"
#define FULL_RAW_FMT "%t %{%F-%T.%i}t %{tag:Backend_health}x %{vxid}x"
strcpy(config.rformat, FULL_RAW_FMT);
config.bformat[0] = '\0';
status = FMT_Init(err);
......@@ -1583,7 +1602,7 @@ static const char
FMT_Format(&tx, os);
VSB_finish(os);
#define EXP_FULL_RAW_OUTPUT "[%d/%b/%Y:%T %z] %F-%T.529143 "\
"b Still healthy 4--X-RH 5 4 5 0.032728 0.035774 HTTP/1.1 200 OK\n"
"b Still healthy 4--X-RH 5 4 5 0.032728 0.035774 HTTP/1.1 200 OK 4711\n"
tm = localtime(&t);
MAN(strftime(strftime_s, BUFSIZ, EXP_FULL_RAW_OUTPUT, tm));
VMASSERT(strcmp(VSB_data(os), strftime_s) == 0, "'%s' != '%s'",
......@@ -1654,6 +1673,7 @@ static const char
mu_run_test(test_format_VCL_disp);
mu_run_test(test_format_VCL_Log);
mu_run_test(test_format_SLT);
mu_run_test(test_format_vxid);
mu_run_test(test_FMT_Fini);
mu_run_test(test_FMT_interface);
......
src/test/varnishevent.conf
View file @ 342756c9
......@@ -2,8 +2,8 @@
monitor.interval = 0
cformat=%b %d %D %H %h %I %{Host}i %{Connection}i %{User-Agent}i %{X-Forwarded-For}i %{Accept-Ranges}o %{Age}o %{Connection}o %{Content-Encoding}o %{Content-Length}o %{Content-Type}o %{Date}o %{Last-Modified}o %{Server}o %{Transfer-Encoding}o %{Via}o %{X-Varnish}o %l %m %O %q %r %s %t %{%F-%T}t %U %u %{Varnish:time_firstbyte}x %{Varnish:hitmiss}x %{Varnish:handling}x %{tag:Begin}x %{tag:Debug}x %{tag:End}x %{tag:Gzip}x %{tag:Hit}x %{tag:Length}x %{tag:Link}x %{tag:ReqAcct}x %{tag:ReqStart}x %{tag:RespProtocol}x %{tag:ReqMethod}x %{tag:ReqURL}x %{tag:ReqProtocol}x %{tag:RespReason}x %{tag:RespStatus}x %{tag:Timestamp:Req}x %{tag:ReqAcct[5]}x %{tag:Timestamp:Req[2]}x
cformat=%b %d %D %H %h %I %{Host}i %{Connection}i %{User-Agent}i %{X-Forwarded-For}i %{Accept-Ranges}o %{Age}o %{Connection}o %{Content-Encoding}o %{Content-Length}o %{Content-Type}o %{Date}o %{Last-Modified}o %{Server}o %{Transfer-Encoding}o %{Via}o %{X-Varnish}o %l %m %O %q %r %s %t %{%F-%T}t %U %u %{Varnish:time_firstbyte}x %{Varnish:hitmiss}x %{Varnish:handling}x %{tag:Begin}x %{tag:Debug}x %{tag:End}x %{tag:Gzip}x %{tag:Hit}x %{tag:Length}x %{tag:Link}x %{tag:ReqAcct}x %{tag:ReqStart}x %{tag:RespProtocol}x %{tag:ReqMethod}x %{tag:ReqURL}x %{tag:ReqProtocol}x %{tag:RespReason}x %{tag:RespStatus}x %{tag:Timestamp:Req}x %{tag:ReqAcct[5]}x %{tag:Timestamp:Req[2]}x %{vxid}x
bformat=%b %d %D %H %h %I %{Accept-Encoding}i %{Host}i %{User-Agent}i %{X-Forwarded-For}i %{X-Varnish}i %{Accept-Ranges}o %{Connection}o %{Content-Encoding}o %{Content-Length}o %{Content-Type}o %{Date}o %{ETag}o %{Last-Modified}o %{Server}o %{Transfer-Encoding}o %{Vary}o %l %m %O %q %r %s %t %{%F-%T}t %U %u %{Varnish:time_firstbyte}x %{tag:Backend}x %{tag:BackendOpen}x %{tag:BackendClose}x %{tag:BackendReuse}x %{tag:Begin}x %{tag:BereqAcct}x %{tag:Length}x %{tag:BerespProtocol}x %{tag:BerespReason}x %{tag:BerespStatus}x %{tag:BereqProtocol}x %{tag:BereqMethod}x %{tag:BereqURL}x %{tag:Debug}x %{tag:End}x %{tag:Timestamp:Bereq}x %{tag:BereqAcct[5]}x %{tag:Timestamp:Bereq[2]}x
bformat=%b %d %D %H %h %I %{Accept-Encoding}i %{Host}i %{User-Agent}i %{X-Forwarded-For}i %{X-Varnish}i %{Accept-Ranges}o %{Connection}o %{Content-Encoding}o %{Content-Length}o %{Content-Type}o %{Date}o %{ETag}o %{Last-Modified}o %{Server}o %{Transfer-Encoding}o %{Vary}o %l %m %O %q %r %s %t %{%F-%T}t %U %u %{Varnish:time_firstbyte}x %{tag:Backend}x %{tag:BackendOpen}x %{tag:BackendClose}x %{tag:BackendReuse}x %{tag:Begin}x %{tag:BereqAcct}x %{tag:Length}x %{tag:BerespProtocol}x %{tag:BerespReason}x %{tag:BerespStatus}x %{tag:BereqProtocol}x %{tag:BereqMethod}x %{tag:BereqURL}x %{tag:Debug}x %{tag:End}x %{tag:Timestamp:Bereq}x %{tag:BereqAcct[5]}x %{tag:Timestamp:Bereq[2]}x %{vxid}x
log.file = test.log
src/test/vslarg.sh
View file @ 342756c9
......@@ -11,7 +11,7 @@ echo "... -g vxid"
CKSUM=$( ../varnishevent -g vxid -r sw-doc.log -f varnishevent.conf | cksum)
# Same as default (no -g arg)
if [ "$CKSUM" != '2110242182 22327766' ]; then
if [ "$CKSUM" != '1569412425 22573475' ]; then
echo "ERROR: -g vxid unexpected cksum: $CKSUM"
exit 1
fi
......@@ -19,17 +19,17 @@ fi
echo "... -g request"
CKSUM=$( ../varnishevent -g request -r sw-doc.log -f varnishevent.conf | cksum)
if [ "$CKSUM" != '1162377575 22327766' ]; then
if [ "$CKSUM" != '157371635 22573475' ]; then
echo "ERROR: -g request unexpected cksum: $CKSUM"
exit 1
fi
echo "... -g raw"
# Timestamps for raw grouping are always the time at which the tx was read,
# even for binary file reads. So we check against the last three columns.
CKSUM=$( ../varnishevent -g raw -r varnish-doc.log -f raw.conf | awk '{print $(NF-2), $(NF-1), $NF}' | cksum)
# even for binary file reads. So we check against the last four columns.
CKSUM=$( ../varnishevent -g raw -r varnish-doc.log -f raw.conf | awk '{print $(NF-3), $(NF-2), $(NF-1), $NF}' | cksum)
if [ "$CKSUM" != '2652535054 3311' ]; then
if [ "$CKSUM" != '4287974290 4744' ]; then
echo "ERROR: -g raw unexpected cksum: $CKSUM"
exit 1
fi
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment