add the Varnish:vxid formatter for varnishncsa compatibility

faa2a86a · Geoff Simmons · 0819983b · faa2a86a · faa2a86a · faa2a86a
Commit faa2a86a authored Dec 09, 2016 by Geoff Simmons
8 changed files
--- a/README.rst
+++ b/README.rst
@@ -7,7 +7,7 @@ Display Varnish log contents in formats for client, backend and other events
 ----------------------------------------------------------------------------

 :Author: Geoffrey Simmons
-:Date:   2016-12-08
+:Date:   2016-12-09
 :Version: trunk
 :Manual section: 1

@@ -279,6 +279,9 @@ transactions, only the formatters ``%t``, ``%{X}t``, ``%{tag}x`` and
  vxid
    The transaction XID (an ID set by Varnish).
 		     
+  Varnish:vxid
+    Same as the ``vxid`` formatter (for varnishncsa compatibility)
+		     
  pvxid
    The parent transaction XID. Always 0 except when request grouping
    is specified.

--- a/src/format.c
+++ b/src/format.c
@@ -1031,6 +1031,8 @@ 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;
+
    n = 0;
    os = VSB_new_auto();
    
@@ -1313,11 +1315,14 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
                    }
                    add_tag(type, t, hdr);
                }
-                else if (strncmp(fname, "vxid", 4) == 0) {
+                else if (strncmp(fname, "vxid", 4) == 0
+                         || strncmp(fname, "Varnish:vxid", 12) == 0) {
                    add_formatter(fmt, os, n, format_vxid);
+                    xids_wanted[type] = 1;
                }
                else if (strncmp(fname, "pvxid", 5) == 0) {
                    add_formatter(fmt, os, n, format_pvxid);
+                    xids_wanted[type] = 1;
                }
                else {
                    sprintf(err, "Unknown format starting at: %s", fname);

--- a/src/test/ncsa.sh
+++ b/src/test/ncsa.sh
@@ -42,10 +42,12 @@ 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'
+# XXX: WIP -- bugs discovered with Debug and 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'

 echo "... custom -F format"
-$EVENT -r $INPUT -F "$FORMAT" | sed 's/-//g' > $EVENT_LOG
+$EVENT -r $INPUT -F "$FORMAT" -v | sed 's/-//g' > $EVENT_LOG
 $NCSA -r $INPUT -F "$FORMAT" | sed 's/-//g' > $NCSA_LOG

 $DIFF_CMD
@@ -92,4 +94,21 @@ if [ "$RC" -ne "0" ]; then
    exit 1
 fi

+FORMAT_EVENT='%{vxid}x'
+FORMAT_NCSA='%{Varnish:vxid}x'
+
+echo "... compatibility of the vxid and Varnish:vxid formatters"
+$EVENT -r $INPUT -F "$FORMAT_EVENT" > $EVENT_LOG
+$NCSA -r $INPUT -F "$FORMAT_NCSA" > $NCSA_LOG
+
+$DIFF_CMD
+RC=$?
+rm $EVENT_LOG
+rm $NCSA_LOG
+
+if [ "$RC" -ne "0" ]; then
+    echo "ERROR: vxid and Varnish:vxid formatters for varnishevent and varnishncsa differ"
+    exit 1
+fi
+
 exit 0
--- a/src/test/regress.sh
+++ b/src/test/regress.sh
@@ -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" != "1934695075 417693 $OUT" ]; then
+if [ "$CKSUM" != "1152556760 421144 $OUT" ]; then
    echo "ERROR: Regression test log output incorrect cksum: $CKSUM"
    exit 1
 fi

--- a/src/test/varnishevent.conf
+++ b/src/test/varnishevent.conf
@@ -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 %{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 %{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 %{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

 log.file = test.log
--- a/src/test/vslarg.sh
+++ b/src/test/vslarg.sh
@@ -11,7 +11,7 @@ LOG=/dev/null
 echo "... no VSL args"
 CKSUM=$( ../varnishevent -r ${IN} -f ${CONF} -l ${LOG} | cksum)

-if [ "$CKSUM" != '2003023342 417731' ]; then
+if [ "$CKSUM" != '529173277 421182' ]; 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" != '2003023342 417731' ]; then
+if [ "$CKSUM" != '529173277 421182' ]; 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" != '2546462943 418726' ]; then
+if [ "$CKSUM" != '2424281468 422177' ]; then
    echo "ERROR: -g request unexpected cksum: $CKSUM"
    exit 1
 fi
@@ -36,10 +36,12 @@ 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 four columns.
-CKSUM=$( ../varnishevent -g raw -r ${IN} -f raw.conf -l ${LOG} | cut -d' ' -f4- | cksum)
+# The query restricts output to Begin records; the previous invocation
+# rendered every record with just the VXIDs.
+CKSUM=$( ../varnishevent -g raw -r ${IN} -f raw.conf -l ${LOG} -q 'Begin' | cut -d' ' -f4- | cksum)

 if [ "$CKSUM" != '3267477005 21053' ]; then
-    echo "ERROR: -g raw unexpected cksum: $CKSUM"
+    echo "ERROR: -g raw with query unexpected cksum: $CKSUM"
    exit 1
 fi


--- a/src/varnishevent.c
+++ b/src/varnishevent.c
@@ -446,7 +446,7 @@ event(struct VSL_data *vsl, struct VSL_transaction * const pt[], void *priv)
            nrec++;
        }

-        if (nrec == 0) {
+        if (nrec == 0 && !xids_wanted[t->type]) {
            tx->state = TX_FREE;
            tx->type = VSL_t_unknown;
            tx->vxid = -1;
@@ -903,9 +903,19 @@ main(int argc, char *argv[])
    assert(!VSTAILQ_EMPTY(&rdr_tx_freelist));
    assert(rdr_tx_free == config.max_data);
    rdr_rec_free = DATA_Take_Freerec(&rdr_rec_freelist);
-    assert(!VSTAILQ_EMPTY(&rdr_rec_freelist));
+    /*
+     * Either the record and chunk lists are non-empty, or (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]));
    rdr_chunk_free = DATA_Take_Freechunk(&rdr_chunk_freelist);
-    assert(!VSTAILQ_EMPTY(&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]));

    tx_thresh = config.max_data >> 1;
    rec_thresh = nrecords >> 1;

--- a/src/varnishevent.h
+++ b/src/varnishevent.h
@@ -157,6 +157,9 @@ 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];
+
 /* 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;