Skip to content

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

Bugfix: correctly handle the case where the output formatter specifies a 

tag to be read for a specific header, but also the first occurrence of
the tag. For example when both %{Varnish:first_byte}x (which requires
Timestamp:Resp) and %{tag:Timestamp}x (without a header specifier)
appear in the output format.
parent b7e41523
Hide whitespace changes
Inline Side-by-side
Showing with 47 additions and 18 deletions
src/format.c
View file @ 657d900a
......@@ -1035,6 +1035,7 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
fmt->args[i].hdr_idx = -1;
xids_wanted[type] = 0;
tag_no_hdr[type] = vbit_init(MAX_VSL_TAG);
n = 0;
os = VSB_new_auto();
......@@ -1316,6 +1317,8 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
}
add_hdr(fmt, t, hdr, n);
}
else
vbit_set(tag_no_hdr[type], t);
add_tag(type, t, hdr);
}
else if (strncmp(fname, "vxid", 4) == 0
......@@ -1401,6 +1404,8 @@ FMT_Init(char *err)
VSTAILQ_INIT(&bincl[i]);
VSTAILQ_INIT(&rincl[i]);
}
for (int i = 0; i < VSL_t__MAX; i++)
tag_no_hdr[i] = NULL;
if (!VSB_EMPTY(config.cformat)) {
if (compile_fmt(VSB_data(config.cformat), &cformat, VSL_t_req, err)
......
src/test/ncsa.sh
View file @ 657d900a
......@@ -42,9 +42,7 @@ fi
# Cannot test the %D formatter, because varnishevent gets it more accurately
# (varnishncsa has floating point errors).
# 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: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'
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'
echo "... custom -F format"
$EVENT -r $INPUT -F "$FORMAT" -v | sed 's/-//g' > $EVENT_LOG
......
src/test/regress.sh
View file @ 657d900a
......@@ -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" != "2867579526 419968 $OUT" ]; then
if [ "$CKSUM" != "3021040597 441167 $OUT" ]; then
echo "ERROR: Regression test log output incorrect cksum: $CKSUM"
exit 1
fi
......@@ -23,7 +23,7 @@ fi
# predictable from one run to the next.
CKSUM=$( sed -e 's/\(initializing\) \(.*\)/\1/' $LOG | egrep -v 'Writer: returned|Reader: took|^DEBUG: Allocating' | cksum )
if [ "$CKSUM" != '3629500636 836995' ]; then
if [ "$CKSUM" != '1109151867 836995' ]; then
echo "ERROR: Regression test varnishevent log incorrect cksum: $CKSUM"
exit 1
fi
......
src/test/varnishevent.conf
View file @ 657d900a
......@@ -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 %{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
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 %{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
log.file = test.log
src/test/vslarg.sh
View file @ 657d900a
......@@ -11,7 +11,7 @@ LOG=/dev/null
echo "... no VSL args"
CKSUM=$( ../varnishevent -r ${IN} -f ${CONF} -l ${LOG} | cksum)
if [ "$CKSUM" != '3438827862 420006' ]; then
if [ "$CKSUM" != '141274411 441205' ]; 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" != '3438827862 420006' ]; then
if [ "$CKSUM" != '141274411 441205' ]; 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" != '647265201 421001' ]; then
if [ "$CKSUM" != '1135890450 442200' ]; then
echo "ERROR: -g request unexpected cksum: $CKSUM"
exit 1
fi
......
src/varnishevent.c
View file @ 657d900a
......@@ -305,6 +305,19 @@ submit(tx_t *tx)
submitted++;
}
/*
* True if, for the transaction type, a record for the tag should be saved
* in addition to records for payloads with specific headers. Needed when,
* for example, the output format specifies both %{Varnish:first_byte}x
* (which requires Timestamp:Resp) and also %{tag:Timestamp}x (which
* requires the first Timestamp).
*/
static inline int
no_hdr(enum VSL_transaction_e type, enum VSL_tag_e tag)
{
return tag_no_hdr[type] != NULL && vbit_test(tag_no_hdr[type], tag);
}
static int
event(struct VSL_data *vsl, struct VSL_transaction * const pt[], void *priv)
{
......@@ -343,7 +356,7 @@ event(struct VSL_data *vsl, struct VSL_transaction * const pt[], void *priv)
while ((status = VSL_Next(t->c)) > 0) {
enum VSL_tag_e tag;
int idx, hdr_idx, len, n, nchunk;
rec_t *rec, **rp;
rec_t *rec, **rp, **rp2 = NULL;
chunk_t *chunk;
const char *p;
......@@ -377,18 +390,23 @@ event(struct VSL_data *vsl, struct VSL_transaction * const pt[], void *priv)
}
CHECK_OBJ_NOTNULL(tx->recs[idx], REC_NODE_MAGIC);
if (tx->recs[idx]->rec != NULL)
rp = &tx->recs[idx]->rec;
if (*rp != NULL && tx->recs[idx]->hdrs == NULL)
continue;
if (tx->recs[idx]->hdrs != NULL) {
hdr_idx = HDR_FindIdx(hdr_trie[tag], p);
if (hdr_idx == -1)
continue;
if (tx->recs[idx]->hdrs[hdr_idx] != NULL)
if (hdr_idx == -1) {
if (*rp != NULL || !no_hdr(t->type, tag))
continue;
}
else if (tx->recs[idx]->hdrs[hdr_idx] != NULL)
continue;
rp = &tx->recs[idx]->hdrs[hdr_idx];
else {
if (*rp == NULL && no_hdr(t->type, tag))
rp2 = rp;
rp = &tx->recs[idx]->hdrs[hdr_idx];
}
}
else
rp = &tx->recs[idx]->rec;
if (debug)
LOG_Log(LOG_DEBUG, "Record: [%u %s %.*s]",
......@@ -406,6 +424,8 @@ event(struct VSL_data *vsl, struct VSL_transaction * const pt[], void *priv)
assert(!OCCUPIED(rec));
assert(VSTAILQ_EMPTY(&rec->chunks));
*rp = rec;
if (rp2 != NULL)
*rp2 = rec;
rec->tag = tag;
n = len;
......
src/varnishevent.h
View file @ 657d900a
......@@ -39,12 +39,16 @@
#include <limits.h>
#include <signal.h>
#include <sys/time.h>
#include <string.h>
#include <stdlib.h>
#include "hdrtrie.h"
#include "vapi/vsl.h"
#include "vqueue.h"
#include "vsb.h"
#include "vas.h"
#include "vbm.h"
#define C(txtype) ((txtype) == VSL_t_req)
#define B(txtype) ((txtype) == VSL_t_bereq)
......@@ -160,6 +164,8 @@ 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];
struct vbitmap *tag_no_hdr[VSL_t__MAX];
/* Writer (consumer) waits for this condition when the SPSC queue is empty.
Reader (producer) signals the condition after enqueue. */
pthread_cond_t spscq_ready_cond;
......
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