Skip to content

V
varnishevent
Commit 460b4f22 authored by Geoff Simmons's avatar Geoff Simmons
Browse files
Options

support the %{Varnish:side}x formatter (varnishncsa compatibility)

parent 657d900a
Hide whitespace changes
Inline Side-by-side
Showing with 37 additions and 25 deletions
README.rst
View file @ 460b4f22
......@@ -187,7 +187,7 @@ transactions, only the formatters ``%t``, ``%{X}t``, ``%{tag}x`` and
%d
The 'direction' of the logged event: ``c`` for client transactions,
``b`` for backend transactions, and the empty string otherwise.
``b`` for backend transactions. Not permitted for raw transactions.
%H
The request protocol. Defaults to HTTP/1.0 if not known.
......@@ -263,6 +263,9 @@ transactions, only the formatters ``%t``, ``%{X}t``, ``%{tag}x`` and
pass, pipe or error. This formatter is only permitted for client
transactions.
Varnish:side
Equivalent to ``%d``, for compatibility with varnishncsa.
VCL_Log:key
Output value set by std.log("key: value") in VCL.
......
src/format.c
View file @ 460b4f22
......@@ -1034,7 +1034,7 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
for (int i = 0; i < n; i++)
fmt->args[i].hdr_idx = -1;
xids_wanted[type] = 0;
nonrecs_wanted[type] = 0;
tag_no_hdr[type] = vbit_init(MAX_VSL_TAG);
n = 0;
......@@ -1079,6 +1079,7 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
case 'd':
VSB_putc(os, C(type) ? 'c' : 'b');
nonrecs_wanted[type] = 1;
break;
case 'D':
......@@ -1324,11 +1325,16 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
else if (strncmp(fname, "vxid", 4) == 0
|| strncmp(fname, "Varnish:vxid", 12) == 0) {
add_formatter(fmt, os, n, format_vxid);
xids_wanted[type] = 1;
nonrecs_wanted[type] = 1;
}
else if (strncmp(fname, "pvxid", 5) == 0) {
add_formatter(fmt, os, n, format_pvxid);
xids_wanted[type] = 1;
nonrecs_wanted[type] = 1;
}
else if (strncmp(fname, "Varnish:side", 12) == 0) {
/* same as %d */
VSB_putc(os, C(type) ? 'c' : 'b');
nonrecs_wanted[type] = 1;
}
else {
sprintf(err, "Unknown format starting at: %s", fname);
......
src/test/ncsa.sh
View file @ 460b4f22
......@@ -42,7 +42,7 @@ fi
# Cannot test the %D formatter, because varnishevent gets it more accurately
# (varnishncsa has floating point errors).
FORMAT='%b %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 %{VSL:Begin}x %{VSL:Debug}x %{VSL:End}x %{VSL:Gzip}x %{VSL:Hit}x %{VSL:Length}x %{VSL:Link}x %{VSL:ReqAcct}x %{VSL:ReqStart}x %{VSL:RespProtocol}x %{VSL:ReqMethod}x %{VSL:ReqURL}x %{VSL:ReqProtocol}x %{VSL:RespReason}x %{VSL:RespStatus}x %{VSL:Timestamp}x %{Varnish:vxid}x'
FORMAT='%b %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 %{VSL:Begin}x %{VSL:Debug}x %{VSL:End}x %{VSL:Gzip}x %{VSL:Hit}x %{VSL:Length}x %{VSL:Link}x %{VSL:ReqAcct}x %{VSL:ReqStart}x %{VSL:RespProtocol}x %{VSL:ReqMethod}x %{VSL:ReqURL}x %{VSL:ReqProtocol}x %{VSL:RespReason}x %{VSL:RespStatus}x %{VSL:Timestamp}x %{Varnish:vxid}x %{Varnish:side}x'
echo "... custom -F format"
$EVENT -r $INPUT -F "$FORMAT" -v | sed 's/-//g' > $EVENT_LOG
......
src/test/regress.sh
View file @ 460b4f22
......@@ -12,7 +12,7 @@ rm -f $LOG $OUT
../varnishevent -f varnishevent.conf -r varnish-4.1.0-doc.log -w $OUT -v
CKSUM=$( cksum $OUT )
if [ "$CKSUM" != "3021040597 441167 $OUT" ]; then
if [ "$CKSUM" != "3634051132 442153 $OUT" ]; then
echo "ERROR: Regression test log output incorrect cksum: $CKSUM"
exit 1
fi
......
src/test/test_format.c
View file @ 460b4f22
......@@ -1979,7 +1979,8 @@ 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 %{vxid}x %{pvxid}x"
"%{tag:ReqAcct[0]}x %{tag:Timestamp:Resp[2]}x %{vxid}x %{pvxid}x "\
"%{Varnish:side}x"
VSB_clear(config.cformat);
VSB_cat(config.cformat, FULL_CLIENT_FMT);
VSB_finish(config.cformat);
......@@ -2052,7 +2053,7 @@ static const char
"http://foobar.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 4711 1147\n"
"1429213569.602005 0.000000 0.000000 60 0.000125 4711 1147 c\n"
tm = localtime(&t);
MAN(strftime(strftime_s, BUFSIZ, EXP_FULL_CLIENT_OUTPUT, tm));
VMASSERT(strcmp(os, strftime_s) == 0, "'%s' != '%s'", os, strftime_s);
......@@ -2064,7 +2065,8 @@ 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 %{vxid}x %{pvxid}x"
"%{tag:BereqAcct[5]}x %{tag:Timestamp:Bereq[1]}x %{vxid}x %{pvxid}x "\
"%{Varnish:side}x"
VSB_clear(config.bformat);
VSB_cat(config.bformat, FULL_BACKEND_FMT);
VSB_finish(config.bformat);
......@@ -2129,7 +2131,7 @@ static const char
"http://foobar.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 4711 1147\n"
"1429210777.728290 0.000048 0.000048 283 0.000048 4711 1147 b\n"
tm = localtime(&t);
MAN(strftime(strftime_s, BUFSIZ, EXP_FULL_BACKEND_OUTPUT, tm));
VMASSERT(strcmp(os, strftime_s) == 0, "'%s' != '%s'", os, strftime_s);
......
src/test/varnishevent.conf
View file @ 460b4f22
......@@ -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 %{VSL:Begin}x %{VSL:Debug}x %{VSL:End}x %{VSL:Gzip}x %{VSL:Hit}x %{VSL:Length}x %{VSL:Link}x %{VSL:ReqAcct}x %{VSL:ReqStart}x %{VSL:RespProtocol}x %{VSL:ReqMethod}x %{VSL:ReqURL}x %{VSL:ReqProtocol}x %{VSL:RespReason}x %{VSL:RespStatus}x %{VSL:Timestamp:Req}x %{VSL:ReqAcct[5]}x %{VSL:Timestamp:Req[2]}x %{VSL:Timestamp}x %{vxid}x %{Varnish:vxid}x %{pvxid}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 %{VSL:Begin}x %{VSL:Debug}x %{VSL:End}x %{VSL:Gzip}x %{VSL:Hit}x %{VSL:Length}x %{VSL:Link}x %{VSL:ReqAcct}x %{VSL:ReqStart}x %{VSL:RespProtocol}x %{VSL:ReqMethod}x %{VSL:ReqURL}x %{VSL:ReqProtocol}x %{VSL:RespReason}x %{VSL:RespStatus}x %{VSL:Timestamp:Req}x %{VSL:ReqAcct[5]}x %{VSL:Timestamp:Req[2]}x %{VSL:Timestamp}x %{vxid}x %{Varnish:vxid}x %{pvxid}x %{Varnish:side}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 %{VSL:Backend}x %{VSL:BackendOpen}x %{VSL:BackendClose}x %{VSL:BackendReuse}x %{VSL:Begin}x %{VSL:BereqAcct}x %{VSL:Length}x %{VSL:BerespProtocol}x %{VSL:BerespReason}x %{VSL:BerespStatus}x %{VSL:BereqProtocol}x %{VSL:BereqMethod}x %{VSL:BereqURL}x %{VSL:Debug}x %{VSL:End}x %{VSL:Timestamp:Bereq}x %{VSL:BereqAcct[5]}x %{VSL:Timestamp:Bereq[2]}x %{VSL:Timestamp}x %{vxid}x %{Varnish:vxid}x %{pvxid}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 %{VSL:Backend}x %{VSL:BackendOpen}x %{VSL:BackendClose}x %{VSL:BackendReuse}x %{VSL:Begin}x %{VSL:BereqAcct}x %{VSL:Length}x %{VSL:BerespProtocol}x %{VSL:BerespReason}x %{VSL:BerespStatus}x %{VSL:BereqProtocol}x %{VSL:BereqMethod}x %{VSL:BereqURL}x %{VSL:Debug}x %{VSL:End}x %{VSL:Timestamp:Bereq}x %{VSL:BereqAcct[5]}x %{VSL:Timestamp:Bereq[2]}x %{VSL:Timestamp}x %{vxid}x %{Varnish:vxid}x %{pvxid}x %{Varnish:side}x
log.file = test.log
src/test/vslarg.sh
View file @ 460b4f22
......@@ -11,7 +11,7 @@ LOG=/dev/null
echo "... no VSL args"
CKSUM=$( ../varnishevent -r ${IN} -f ${CONF} -l ${LOG} | cksum)
if [ "$CKSUM" != '141274411 441205' ]; then
if [ "$CKSUM" != '1280332296 442191' ]; then
echo "ERROR: no VSL args unexpected cksum: $CKSUM"
exit 1
fi
......@@ -20,7 +20,7 @@ echo "... -g vxid"
CKSUM=$( ../varnishevent -g vxid -r ${IN} -f ${CONF} -l ${LOG} | cksum)
# Same as default (no -g arg)
if [ "$CKSUM" != '141274411 441205' ]; then
if [ "$CKSUM" != '1280332296 442191' ]; then
echo "ERROR: -g vxid unexpected cksum: $CKSUM"
exit 1
fi
......@@ -28,7 +28,7 @@ fi
echo "... -g request"
CKSUM=$( ../varnishevent -g request -r ${IN} -f ${CONF} -l ${LOG} | cksum)
if [ "$CKSUM" != '1135890450 442200' ]; then
if [ "$CKSUM" != '202886188 443186' ]; then
echo "ERROR: -g request unexpected cksum: $CKSUM"
exit 1
fi
......
src/varnishevent.c
View file @ 460b4f22
......@@ -466,7 +466,7 @@ event(struct VSL_data *vsl, struct VSL_transaction * const pt[], void *priv)
nrec++;
}
if (nrec == 0 && !xids_wanted[t->type]) {
if (nrec == 0 && !nonrecs_wanted[t->type]) {
tx->state = TX_FREE;
tx->type = VSL_t_unknown;
tx->vxid = -1;
......@@ -924,18 +924,19 @@ main(int argc, char *argv[])
assert(rdr_tx_free == config.max_data);
rdr_rec_free = DATA_Take_Freerec(&rdr_rec_freelist);
/*
* Either the record and chunk lists are non-empty, or (p)vxids are
* all that we're looking for.
* Either the record and chunk lists are non-empty, or formatters that
* don't require records, such as (p)vxids, are all that we're looking
* for.
*/
assert(!VSTAILQ_EMPTY(&rdr_rec_freelist)
|| (!VSB_EMPTY(config.cformat) && xids_wanted[VSL_t_req])
|| (!VSB_EMPTY(config.bformat) && xids_wanted[VSL_t_bereq])
|| (!VSB_EMPTY(config.rformat) && xids_wanted[VSL_t_raw]));
|| (!VSB_EMPTY(config.cformat) && nonrecs_wanted[VSL_t_req])
|| (!VSB_EMPTY(config.bformat) && nonrecs_wanted[VSL_t_bereq])
|| (!VSB_EMPTY(config.rformat) && nonrecs_wanted[VSL_t_raw]));
rdr_chunk_free = DATA_Take_Freechunk(&rdr_chunk_freelist);
assert(!VSTAILQ_EMPTY(&rdr_chunk_freelist)
|| (!VSB_EMPTY(config.cformat) && xids_wanted[VSL_t_req])
|| (!VSB_EMPTY(config.bformat) && xids_wanted[VSL_t_bereq])
|| (!VSB_EMPTY(config.rformat) && xids_wanted[VSL_t_raw]));
|| (!VSB_EMPTY(config.cformat) && nonrecs_wanted[VSL_t_req])
|| (!VSB_EMPTY(config.bformat) && nonrecs_wanted[VSL_t_bereq])
|| (!VSB_EMPTY(config.rformat) && nonrecs_wanted[VSL_t_raw]));
tx_thresh = config.max_data >> 1;
rec_thresh = nrecords >> 1;
......
src/varnishevent.h
View file @ 460b4f22
......@@ -162,7 +162,7 @@ unsigned tx_occ, rec_occ, chunk_occ, tx_occ_hi, rec_occ_hi, chunk_occ_hi,
struct hdrt_node *hdr_trie[MAX_VSL_TAG];
/* non-zero if vxid or pvxid outputs are requested for a transaction type */
int xids_wanted[VSL_t__MAX];
int nonrecs_wanted[VSL_t__MAX];
struct vbitmap *tag_no_hdr[VSL_t__MAX];
......
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