add the VSL output formatter for almost-but-not-quite compatibility

with varnishncsa

README.rst

@@ -271,6 +271,11 @@ transactions, only the formatters ``%t``, ``%{X}t``, ``%{tag}x`` and
     e.g. ``%{tag:ReqEnd}x``.  The contents of the payload may be
     restricted by header or field specifiers, as explained below.
 
+  VSL:tagname{:header}{[field]}
+    Identical to the ``tag`` formatter. This is similar to the
+    ``%{VSL:tag}x`` formatter used by varnishncsa, but is not fully
+    compatible.  Details are given below.
+
   vxid
     The transaction XID (an ID set by Varnish).
 		     
@@ -304,12 +309,34 @@ then:
 
   ``%{tag:Timestamp:Resp[1]}`` yields ``0.000195``
 
+The ``%{VSL:tagname}x`` formatter is just an alias for
+``%{tag:tagname}x``.  It is compatible with the ``VSL`` formatter of
+varnishncsa if neither the header nor the field syntax is used. The
+varnishncsa formatter does not support the header specifier, and its
+field specifiers count from 1, while in varnishevent they count
+from 0.
+
+So for example:
+
+* The formatter ``%{VSL:Backend}x`` has the same effect in both
+  varnishevent and varnishncsa, and is equivalent to
+  ``%{tag:Backend}x`` in varnishevent.
+* ``%{VSL:Timestamp:Resp}`` may be used in varnishevent but not in
+  varnishncsa. It has the same effect as ``%{tag:Timestamp:Resp}`` in
+  varnishevent.
+* ``%{VSL:Backend[2]}x`` in varnishevent (the same as
+  ``%{tag:Backend[2]}x``) is equivalent to ``%{VSL:Backend[3]}x`` in
+  varnishncsa.
+* ``%{VSL:Timestamp:Resp[1]}`` may be used in varnishevent and is the
+  same as ``%{tag:Timestamp:Resp[1]}``, but it may not be used in
+  varnishncsa.
+
 
 REQUIREMENTS
 ============
 
 This version of varnishevent requires Varnish 4.1.3 through 5.0.0.
-See the project repository for version that are compatible with other
+See the project repository for versions that are compatible with other
 versions of Varnish.
 
 

src/format.c

@@ -1055,6 +1055,7 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
            format (neither client nor backend) */
         if (R(type)
             && sscanf(p, "{tag:%s}x", buf) != 1
+            && sscanf(p, "{VSL:%s}x", buf) != 1
             && sscanf(p, "{vxid}x") != 1
             && *p != 't'
             && sscanf(p, "{%s}t", buf) != 1) {
@@ -1269,7 +1270,8 @@ compile_fmt(char * const format, compiled_fmt_t * const fmt,
                                 fname+8);
                     add_tag(type, SLT_VCL_Log, fname+8);
                 }
-                else if (strncmp(fname, "tag:", 4) == 0) {
+                else if (strncmp(fname, "tag:", 4) == 0
+                         || strncmp(fname, "VSL:", 4) == 0) {
                     /* retrieve the tag contents from the log */
                     char *c, *tagname = fname+4, *hdr = NULL, *fld = NULL;
                     int t = 0, fld_nr = -1;

src/test/ncsa.sh

@@ -58,4 +58,38 @@ if [ "$RC" -ne "0" ]; then
     exit 1
 fi
 
+FORMAT_EVENT='%{VSL:Timestamp[1]}x'
+FORMAT_NCSA='%{VSL:Timestamp[2]}x'
+
+echo "... VSL formatter"
+$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: outputs of varnishevent/varnishncsa VSL formatter differ"
+    exit 1
+fi
+
+FORMAT_EVENT='%{tag:Timestamp[1]}x'
+FORMAT_NCSA='%{VSL:Timestamp[2]}x'
+
+echo "... compatibility of tag and VSL formatter"
+$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: tag and VSL formatters for varnishevent and varnishncsa differ"
+    exit 1
+fi
+
 exit 0

src/test/raw.conf

@@ -3,4 +3,4 @@
 monitor.interval = 0
 
 cformat=
-rformat=%t %{%F-%T.%i}t %{tag:Begin}x %{vxid}x
+rformat=%t %{%F-%T.%i}t %{tag:Begin}x %{VSL:Begin}x %{vxid}x

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" != "1792530013 308464 $OUT" ]; then
+if [ "$CKSUM" != "1934695075 417693 $OUT" ]; then
     echo "ERROR: Regression test log output incorrect cksum: $CKSUM"
     exit 1
 fi

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 %{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 %{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 %{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
 
 log.file = test.log

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" != '3212026326 308502' ]; then
+if [ "$CKSUM" != '2003023342 417731' ]; 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" != '3212026326 308502' ]; then
+if [ "$CKSUM" != '2003023342 417731' ]; 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" != '2902279681 309497' ]; then
+if [ "$CKSUM" != '2546462943 418726' ]; then
     echo "ERROR: -g request unexpected cksum: $CKSUM"
     exit 1
 fi
@@ -36,9 +36,9 @@ 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} | awk '{print $(NF-3), $(NF-2), $(NF-1), $NF}' | cksum)
+CKSUM=$( ../varnishevent -g raw -r ${IN} -f raw.conf -l ${LOG} | cut -d' ' -f4- | cksum)
 
-if [ "$CKSUM" != '3568791840 12280' ]; then
+if [ "$CKSUM" != '3267477005 21053' ]; then
     echo "ERROR: -g raw unexpected cksum: $CKSUM"
     exit 1
 fi