Skip to content

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

add field selector for %{tag}x formatter

parent f23a3952
Hide whitespace changes
Inline Side-by-side
Showing with 134 additions and 50 deletions
src/format.c
View file @ 7d496cc5
......@@ -191,21 +191,30 @@ get_rec_fld(const logline_t *rec, int n, size_t *len)
}
static inline void
format_slt(const tx_t *tx, enum VSL_tag_e tag, char *hdr, char **s, size_t *len)
format_slt(const tx_t *tx, enum VSL_tag_e tag, char *hdr, int fld, char **s,
size_t *len)
{
logline_t *rec;
if (hdr == NULL) {
rec = get_tag(tx, tag);
if (rec != NULL) {
*s = get_payload(rec);
*len = rec->len - 1;
if (fld == -1) {
*s = get_payload(rec);
*len = rec->len - 1;
}
else
*s = get_rec_fld(rec, fld, len);
}
}
else {
*s = get_hdr(tx, tag, hdr);
if (*s != NULL)
*len = strlen(*s);
if (*s != NULL) {
if (fld == -1)
*len = strlen(*s);
else
*s = get_fld(*s, fld, len);
}
}
}
......@@ -269,14 +278,14 @@ void
format_H_client(const tx_t *tx, const arg_t *args, char **s, size_t *len)
{
(void) args;
format_slt(tx, SLT_ReqProtocol, NULL, s, len);
format_slt(tx, SLT_ReqProtocol, NULL, -1, s, len);
}
void
format_H_backend(const tx_t *tx, const arg_t *args, char **s, size_t *len)
{
(void) args;
format_slt(tx, SLT_BereqProtocol, NULL, s, len);
format_slt(tx, SLT_BereqProtocol, NULL, -1, s, len);
}
static inline void
......@@ -344,14 +353,14 @@ void
format_m_client(const tx_t *tx, const arg_t *args, char **s, size_t *len)
{
(void) args;
format_slt(tx, SLT_ReqMethod, NULL, s, len);
format_slt(tx, SLT_ReqMethod, NULL, -1, s, len);
}
void
format_m_backend(const tx_t *tx, const arg_t *args, char **s, size_t *len)
{
(void) args;
format_slt(tx, SLT_BereqMethod, NULL, s, len);
format_slt(tx, SLT_BereqMethod, NULL, -1, s, len);
}
void
......@@ -457,14 +466,14 @@ void
format_s_client(const tx_t *tx, const arg_t *args, char **s, size_t *len)
{
(void) args;
format_slt(tx, SLT_RespStatus, NULL, s, len);
format_slt(tx, SLT_RespStatus, NULL, -1, s, len);
}
void
format_s_backend(const tx_t *tx, const arg_t *args, char **s, size_t *len)
{
(void) args;
format_slt(tx, SLT_BerespStatus, NULL, s, len);
format_slt(tx, SLT_BerespStatus, NULL, -1, s, len);
}
static inline void
......@@ -707,7 +716,7 @@ format_VCL_Log(const tx_t *tx, const arg_t *args, char **s, size_t *len)
void
format_SLT(const tx_t *tx, const arg_t *args, char **s, size_t *len)
{
format_slt(tx, args->tag, args->name, s, len);
format_slt(tx, args->tag, args->name, args->fld, s, len);
if (VSL_tagflags[args->tag] & SLT_F_BINARY) {
VSB_clear(bintag);
VSB_quote(bintag, *s, (int) *len, 0);
......@@ -719,7 +728,7 @@ format_SLT(const tx_t *tx, const arg_t *args, char **s, size_t *len)
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)
formatter_f formatter, const char *name, enum VSL_tag_e tag, int fld)
{
fmt->str[n] = (char *) malloc(VSB_len(os) + 1);
AN(fmt->str[n]);
......@@ -735,6 +744,21 @@ add_fmt(const compiled_fmt_t *fmt, struct vsb *os, unsigned n,
VSB_clear(os);
fmt->formatter[n] = formatter;
fmt->args[n].tag = tag;
fmt->args[n].fld = fld;
}
static void
add_formatter(const compiled_fmt_t *fmt, struct vsb *os, unsigned n,
formatter_f formatter)
{
add_fmt(fmt, os, n, formatter, NULL, SLT__Bogus, -1);
}
static void
add_fmt_name(const compiled_fmt_t *fmt, struct vsb *os, unsigned n,
formatter_f formatter, const char *name)
{
add_fmt(fmt, os, n, formatter, name, SLT__Bogus, -1);
}
#define FMT(type, format_ltr) \
......@@ -879,7 +903,7 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
switch (*p) {
case 'b':
add_fmt(fmt, os, n, FMT(type, format_b), NULL, SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_b));
add_cb_tag(type, SLT_ReqAcct, SLT_BereqAcct, NULL);
n++;
break;
......@@ -889,25 +913,25 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
break;
case 'D':
add_fmt(fmt, os, n, FMT(type, format_D), NULL, SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_D));
add_cb_tag_incl(type, SLT_Timestamp, "Resp", "BerespBody");
n++;
break;
case 'H':
add_fmt(fmt, os, n, FMT(type, format_H), NULL, SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_H));
add_cb_tag(type, SLT_ReqProtocol, SLT_BereqProtocol, NULL);
n++;
break;
case 'h':
add_fmt(fmt, os, n, FMT(type, format_h), NULL, SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_h));
add_cb_tag(type, SLT_ReqStart, SLT_Backend, NULL);
n++;
break;
case 'I':
add_fmt(fmt, os, n, FMT(type, format_I), NULL, SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_I));
if (C(type)) {
add_tag(type, SLT_ReqAcct, NULL);
add_tag(type, SLT_PipeAcct, NULL);
......@@ -922,13 +946,13 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
break;
case 'm':
add_fmt(fmt, os, n, FMT(type, format_m), NULL, SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_m));
add_cb_tag(type, SLT_ReqMethod, SLT_BereqMethod, NULL);
n++;
break;
case 'O':
add_fmt(fmt, os, n, FMT(type, format_O), NULL, SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_O));
if (C(type)) {
add_tag(type, SLT_ReqAcct, NULL);
add_tag(type, SLT_PipeAcct, NULL);
......@@ -939,13 +963,13 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
break;
case 'q':
add_fmt(fmt, os, n, FMT(type, format_q), NULL, SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_q));
add_cb_tag(type, SLT_ReqURL, SLT_BereqURL, NULL);
n++;
break;
case 'r':
add_fmt(fmt, os, n, FMT(type, format_r), NULL, SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_r));
add_cb_tag(type, SLT_ReqMethod, SLT_BereqMethod, NULL);
add_cb_tag(type, SLT_ReqHeader, SLT_BereqHeader, "Host");
add_cb_tag(type, SLT_ReqURL, SLT_BereqURL, NULL);
......@@ -954,32 +978,32 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
break;
case 's':
add_fmt(fmt, os, n, FMT(type, format_s), NULL, SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_s));
add_cb_tag(type, SLT_RespStatus, SLT_BerespStatus, NULL);
n++;
break;
case 't':
add_fmt(fmt, os, n, format_t, NULL, SLT__Bogus);
add_formatter(fmt, os, n, format_t);
if (type != VSL_t_raw)
add_tag(type, SLT_Timestamp, "Start");
n++;
break;
case 'T':
add_fmt(fmt, os, n, FMT(type, format_T), NULL, SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_T));
add_tag(type, SLT_Timestamp, "Start");
n++;
break;
case 'U':
add_fmt(fmt, os, n, FMT(type, format_U), NULL, SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_U));
add_cb_tag(type, SLT_ReqURL, SLT_BereqURL, NULL);
n++;
break;
case 'u':
add_fmt(fmt, os, n, FMT(type, format_u), NULL, SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_u));
add_cb_tag(type, SLT_ReqHeader, SLT_BereqHeader, "Authorization");
n++;
break;
......@@ -1000,19 +1024,19 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
switch (ltr) {
case 'i':
add_fmt(fmt, os, n, FMT(type, format_Xi), fname, SLT__Bogus);
add_fmt_name(fmt, os, n, FMT(type, format_Xi), fname);
add_cb_tag(type, SLT_ReqHeader, SLT_BereqHeader, fname);
n++;
p = tmp;
break;
case 'o':
add_fmt(fmt, os, n, FMT(type, format_Xo), fname, SLT__Bogus);
add_fmt_name(fmt, os, n, FMT(type, format_Xo), fname);
add_cb_tag(type, SLT_RespHeader, SLT_BerespHeader, fname);
n++;
p = tmp;
break;
case 't':
add_fmt(fmt, os, n, format_Xt, fname, SLT__Bogus);
add_fmt_name(fmt, os, n, format_Xt, fname);
if (type != VSL_t_raw)
add_tag(type, SLT_Timestamp, "Start");
n++;
......@@ -1020,13 +1044,12 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
break;
case 'x':
if (strcmp(fname, "Varnish:time_firstbyte") == 0) {
add_fmt(fmt, os, n, FMT(type, format_Xttfb), NULL,
SLT__Bogus);
add_formatter(fmt, os, n, FMT(type, format_Xttfb));
add_cb_tag_incl(type, SLT_Timestamp, "Process", "Beresp");
}
else if (strcmp(fname, "Varnish:hitmiss") == 0) {
if (C(type)) {
add_fmt(fmt, os, n, format_VCL_disp, "m", SLT__Bogus);
add_fmt_name(fmt, os, n, format_VCL_disp, "m");
add_tag(type, SLT_VCL_call, NULL);
add_tag(type, SLT_VCL_return, NULL);
}
......@@ -1038,7 +1061,7 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
}
else if (strcmp(fname, "Varnish:handling") == 0) {
if (C(type)) {
add_fmt(fmt, os, n, format_VCL_disp, "n", SLT__Bogus);
add_fmt_name(fmt, os, n, format_VCL_disp, "n");
add_tag(type, SLT_VCL_call, NULL);
add_tag(type, SLT_VCL_return, NULL);
}
......@@ -1053,16 +1076,16 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
// output.
// Format: %{VCL_Log:keyname}x
// Logging: std.log("keyname:value")
add_fmt(fmt, os, n, format_VCL_Log, fname+8, SLT__Bogus);
add_fmt_name(fmt, os, n, format_VCL_Log, fname+8);
add_tag(type, SLT_VCL_Log, fname+8);
}
else if (strncmp(fname, "tag:", 4) == 0) {
/* retrieve the tag contents from the log */
char *c, *tagname = fname+4, *hdr = NULL;
int t = 0;
char *c, *tagname = fname+4, *hdr = NULL, *fld = NULL;
int t = 0, fld_nr = -1;
c = tagname + 1;
while (*c != ':' && *c != '\0')
while (*c != ':' && *c != '[' && *c != '\0')
c++;
if ((t = VSL_Name2Tag(tagname, c - tagname)) < 0) {
sprintf(err, "Unknown or non-unique tag %*s",
......@@ -1071,10 +1094,24 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
}
if (*c == ':') {
hdr = c + 1;
while (*c != '\0')
while (*c != '[' && *c != '\0')
c++;
}
if (*c == '[') {
*c = '\0';
c++;
fld = c;
while (isdigit(*c))
c++;
if (*c != ']') {
sprintf(err, "Unterminated field specifier "
"starting at %s", --p);
return 1;
}
*c = '\0';
fld_nr = atoi(fld);
}
add_fmt(fmt, os, n, format_SLT, hdr, t);
add_fmt(fmt, os, n, format_SLT, hdr, t, fld_nr);
add_tag(type, t, hdr);
}
else {
......@@ -1104,7 +1141,7 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
* and the terminating newline
*/
VSB_putc(os, '\n');
add_fmt(fmt, os, n, NULL, NULL, SLT__Bogus);
add_formatter(fmt, os, n, NULL);
VSB_delete(os);
return 0;
}
......
src/format.h
View file @ 7d496cc5
......@@ -34,6 +34,7 @@
typedef struct arg_t {
char *name;
enum VSL_tag_e tag;
int fld;
} arg_t;
typedef void formatter_f(const tx_t *tx, const arg_t *args, char **s,
......
src/test/regress.sh
View file @ 7d496cc5
......@@ -12,7 +12,7 @@ rm -f $LOG $OUT
../varnishevent -f varnishevent.conf -r sw-doc.log -w $OUT -v
CKSUM=$( cksum $OUT )
if [ "$CKSUM" != "4178357783 21920698 $OUT" ]; then
if [ "$CKSUM" != "4053530460 22327728 $OUT" ]; then
echo "ERROR: Regression test log output incorrect cksum: $CKSUM"
exit 1
fi
......
src/test/test_format.c
View file @ 7d496cc5
......@@ -1257,6 +1257,7 @@ static const char
set_record_data(&rec, &chunk, "no backend connection", SLT_FetchError);
args.tag = SLT_FetchError;
args.fld = -1;
format_SLT(&tx, &args, &str, &len);
MASSERT(strncmp(str, "no backend connection", 21) == 0);
MASSERT(len == 21);
......@@ -1292,6 +1293,49 @@ static const char
MASSERT(strncmp(str, substr, strlen(substr)) == 0);
MASSERT(len == strlen(substr));
/* field selector */
set_record_data(&rec, &chunk, TS_RESP_PAYLOAD, SLT_Timestamp);
args.name = NULL;
args.fld = 0;
format_SLT(&tx, &args, &str, &len);
MASSERT(strncmp(str, "Resp:", 5) == 0);
MASSERT(len == 5);
/* header and field selector */
set_record_data(&rec, &chunk, TS_RESP_PAYLOAD, SLT_Timestamp);
args.name = strdup("Resp");
format_SLT(&tx, &args, &str, &len);
MASSERT(strncmp(str, substr, len) == 0);
MASSERT(len == strlen("1427799478.166798"));
/* header not found */
set_record_data(&rec, &chunk, TS_RESP_PAYLOAD, SLT_Timestamp);
args.name = strdup("Foo");
args.fld = -1;
str = NULL;
len = 0;
format_SLT(&tx, &args, &str, &len);
MAZ(str);
MAZ(len);
/* field not found */
set_record_data(&rec, &chunk, TS_RESP_PAYLOAD, SLT_Timestamp);
args.name = NULL;
args.fld = 4;
str = NULL;
len = 0;
format_SLT(&tx, &args, &str, &len);
MAZ(len);
/* header field not found */
set_record_data(&rec, &chunk, TS_RESP_PAYLOAD, SLT_Timestamp);
args.name = strdup("Resp");
args.fld = 3;
str = NULL;
len = 0;
format_SLT(&tx, &args, &str, &len);
MAZ(len);
return NULL;
}
......@@ -1388,7 +1432,8 @@ static const char
#define FULL_CLIENT_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 "\
"%{Varnish:hitmiss}x %{Varnish:handling}x %{VCL_Log:baz}x "\
"%{tag:VCL_acl}x %{tag:Debug}x %{tag:Timestamp:Req}x"
"%{tag:VCL_acl}x %{tag:Debug}x %{tag:Timestamp:Req}x "\
"%{tag:ReqAcct[0]}x %{tag:Timestamp:Resp[2]}x"
strcpy(config.cformat, FULL_CLIENT_FMT);
status = FMT_Init(err);
VMASSERT(status == 0, "FMT_Init: %s", err);
......@@ -1435,7 +1480,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\n"
"1429213569.602005 0.000000 0.000000 60 0.000125\n"
tm = localtime(&t);
MAN(strftime(strftime_s, BUFSIZ, EXP_FULL_CLIENT_OUTPUT, tm));
VMASSERT(strcmp(VSB_data(os), strftime_s) == 0, "'%s' != '%s'",
......@@ -1447,7 +1492,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:Fetch_Body}x %{tag:Debug}x %{tag:Timestamp:Bereq}x "\
"%{tag:BereqAcct[5]}x %{tag:Timestamp:Bereq[1]}x"
strcpy(config.bformat, FULL_BACKEND_FMT);
config.cformat[0] = '\0';
status = FMT_Init(err);
......@@ -1500,7 +1546,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\n"
"1429210777.728290 0.000048 0.000048 283 0.000048\n"
tm = localtime(&t);
MAN(strftime(strftime_s, BUFSIZ, EXP_FULL_BACKEND_OUTPUT, tm));
VMASSERT(strcmp(VSB_data(os), strftime_s) == 0, "'%s' != '%s'",
......
src/test/varnishevent.conf
View file @ 7d496cc5
......@@ -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
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
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
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
log.file = test.log
src/test/vslarg.sh
View file @ 7d496cc5
......@@ -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" != '2669898744 21920736' ]; then
if [ "$CKSUM" != '2110242182 22327766' ]; then
echo "ERROR: -g vxid unexpected cksum: $CKSUM"
exit 1
fi
......@@ -19,7 +19,7 @@ fi
echo "... -g request"
CKSUM=$( ../varnishevent -g request -r sw-doc.log -f varnishevent.conf | cksum)
if [ "$CKSUM" != '1458016223 21920736' ]; then
if [ "$CKSUM" != '1162377575 22327766' ]; 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