Skip to content

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

The SLT formatter, when formatting a tag with the SLT_F_BINARY flag, 

only calls VSB_quote() for the payload if the payload contains a
non-printable character (for somewhat better compatibility with
varnishncsa).
parent faa2a86a
Hide whitespace changes
Inline Side-by-side
Showing with 52 additions and 16 deletions
README.rst
View file @ b7e41523
......@@ -334,6 +334,23 @@ So for example:
same as ``%{tag:Timestamp:Resp[1]}``, but it may not be used in
varnishncsa.
varnishevent and varnishncsa format non-printable characters from the
log differently. What varnishevent does is similar to varnishlog: for
the tags classified by the logging API as potentially containing
binary data (such as ``Debug``), if the payload contains non-printable
characters, then the output is enclosed in quotation marks, and the
non-printables are escaped, using common sequences such as ``\n`` and
``\t``, and ``\%o`` for other bytes, where ``%o`` is the octal
representation of the value. For example, byte value 255 is formatted
as ``\377``. (varnishlog always encloses the payload in quotation
marks for a tag such as ``Debug``, regardless of whether any of its
contents need escaping, whereas varnishevent uses the quotation marks
only when escaping is necessary.)
varnishncsa escapes any non-printable character, also using ``\n`` and
``\t`` and so forth, and two-digit hex representations for other
values (for example ``\xff`` for byte value 255). varnishncsa does
this for all log payloads, regardless of the tag.
REQUIREMENTS
============
......
src/format.c
View file @ b7e41523
......@@ -800,13 +800,16 @@ void
format_SLT(const tx_t *tx, const arg_t *args, char **s, size_t *len)
{
format_slt(tx, args->tag, args->hdr_idx, args->fld, s, len);
if (VSL_tagflags[args->tag] & SLT_F_BINARY && *s != NULL && *len > 0) {
VSB_clear(scratch);
VSB_quote(scratch, *s, (int) *len, 0);
VSB_finish(scratch);
*s = VSB_data(scratch);
*len = VSB_len(scratch);
}
if (VSL_tagflags[args->tag] & SLT_F_BINARY && *s != NULL && *len > 0)
for (int i = 0; i < *len; i++)
if (!isprint(*(*s + i))) {
VSB_clear(scratch);
VSB_quote(scratch, *s, (int) *len, 0);
VSB_finish(scratch);
*s = VSB_data(scratch);
*len = VSB_len(scratch);
break;
}
}
static inline void
......
src/test/ncsa.sh
View file @ b7e41523
......@@ -42,9 +42,9 @@ fi
# Cannot test the %D formatter, because varnishevent gets it more accurately
# (varnishncsa has floating point errors).
# XXX: WIP -- bugs discovered with Debug and VSL:Timestamp
# XXX: WIP -- bugs discovered with VSL:Timestamp
#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: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 %{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 %{Varnish:vxid}x'
echo "... custom -F format"
$EVENT -r $INPUT -F "$FORMAT" -v | sed 's/-//g' > $EVENT_LOG
......
src/test/regress.sh
View file @ b7e41523
......@@ -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" != "1152556760 421144 $OUT" ]; then
if [ "$CKSUM" != "2867579526 419968 $OUT" ]; then
echo "ERROR: Regression test log output incorrect cksum: $CKSUM"
exit 1
fi
......
src/test/test_format.c
View file @ b7e41523
......@@ -1608,19 +1608,35 @@ static const char
MASSERT(max_idx == 1);
init_tx(&tx, node, nptr);
add_record_data(&tx, SLT_Debug, &rec, &chunk, "");
memcpy(chunk.data, "foo\0\xFF bar\0", 10);
rec.len = 10;
memcpy(chunk.data, "foo\0\xFF bar\0\\\"\n\r\t", 16);
rec.len = 16;
str = NULL;
len = 0;
args.tag = SLT_Debug;
format_SLT(&tx, &args, &str, &len);
MAN(str);
#define EXP_SLT_BINARY "\"foo\\0\\377 bar\""
#define EXP_SLT_BINARY "\"foo\\0\\377 bar\\0\\\\\\\"\\n\\r\\t\""
VMASSERT(strncmp(str, EXP_SLT_BINARY, strlen(EXP_SLT_BINARY)) == 0,
"format_SLT with binary data: Expected '%s', got '%s'",
EXP_SLT_BINARY, str);
MASSERT(len == strlen(EXP_SLT_BINARY));
/* Binary tag with no non-printables in the payload */
reset_tag2idx(1, SLT_Debug);
MASSERT(max_idx == 1);
init_tx(&tx, node, nptr);
add_record_data(&tx, SLT_Debug, &rec, &chunk, "RES_MODE 2");
str = NULL;
len = 0;
args.tag = SLT_Debug;
format_SLT(&tx, &args, &str, &len);
MAN(str);
#define EXP_SLT "RES_MODE 2"
VMASSERT(strcmp(str, EXP_SLT) == 0,
"format_SLT with no binary data: Expected '%s', got '%s'",
EXP_SLT, str);
MASSERT(len == strlen(EXP_SLT));
/* header selector */
reset_tag2idx(1, SLT_Timestamp);
MASSERT(max_idx == 1);
......
src/test/vslarg.sh
View file @ b7e41523
......@@ -11,7 +11,7 @@ LOG=/dev/null
echo "... no VSL args"
CKSUM=$( ../varnishevent -r ${IN} -f ${CONF} -l ${LOG} | cksum)
if [ "$CKSUM" != '529173277 421182' ]; then
if [ "$CKSUM" != '3438827862 420006' ]; 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" != '529173277 421182' ]; then
if [ "$CKSUM" != '3438827862 420006' ]; 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" != '2424281468 422177' ]; then
if [ "$CKSUM" != '647265201 421001' ]; then
echo "ERROR: -g request 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