The parser allows the XID field, obsolete since Varnish 3, to be left out.

The "legacy" syntax is still tolerated, so a number after "track" is
skipped over. Also add a regression test in which the new syntax is
used, the old regression test is retained as a legacy test.

README.rst

@@ -9,8 +9,8 @@ Tracking Log Reader demon
 -------------------------
 
 :Author: Geoffrey Simmons
-:Date:   2017-03-16
-:Version: 4.1
+:Date:   2017-03-17
+:Version: trunk
 :Manual section: 3
 
 SYNOPSIS
@@ -35,31 +35,32 @@ system, such as ActiveMQ or Kafka.
 in this format by the ``varnishlog`` tool for client request
 transactions::
 
-  VCL_Log        track <XID> <DATA>
+  VCL_Log        track <DATA>
 
-* ``XID``: XID (request identifier) assigned by Varnish
 * ``DATA``: data to be logged
 
 The ``VCL_Log`` entries may also specify a sharding key for the
 message brokers, in this format::
 
-  VCL_Log        track <XID> key <KEY>
+  VCL_Log        track key <KEY>
 
 * ``KEY``: the sharding key
 
 ``VCL_Log`` entries result from use of the ``log()`` function provided
 by the standard vmod ``std`` distributed with Varnish. The ``log()``
-call must include the prefix ``track``, the XID and the data to be
-logged, or a sharding key. These log entries can be created with VCL
-code such as::
+call must include the prefix ``track`` and the data to be logged, or a
+sharding key. Note that DATA entries cannot begin with the word "key"
+followed by a space; these will be interpreted as KEY entries.
+
+These log entries can be created with VCL code such as::
 
   import std;
 
   sub vcl_recv {
       /* ... */
-      std.log("track " + req.xid + " url=" + req.url);
-      std.log("track " + req.xid + " http_Host=" + req.http.Host);
-      std.log("track " + req.xid + " key " + req.http.X-Key);
+      std.log("track url=" + req.url);
+      std.log("track http_Host=" + req.http.Host);
+      std.log("track key " + req.http.X-Key);
       /* ... */
   }
 
@@ -107,9 +108,9 @@ to the data displayed with this ``varnishlog`` command::
 Thus the VCL example shown above may result in log entries such as::
 
   *   << Request  >> 591570    
-  -   VCL_Log        track 591570 url=/index.html
-  -   VCL_Log        track 591570 http_Host=foo.bar.org
-  -   VCL_Log        track 591570 key 12345678
+  -   VCL_Log        track url=/index.html
+  -   VCL_Log        track http_Host=foo.bar.org
+  -   VCL_Log        track key 12345678
   -   Timestamp      Resp: 1430835449.167329 0.000681 0.000352
 
 In this case, ``trackrdrd`` sends this data to message brokers, with

src/child.c

@@ -348,11 +348,12 @@ get_chunk(dataentry *entry)
 }
 
 static unsigned
-append(dataentry *entry, enum VSL_tag_e tag, unsigned xid, char *data,
+append(dataentry *entry, enum VSL_tag_e tag, unsigned xid, const char *data,
        int datalen)
 {
     chunk_t *chunk;
-    char *null, *p;
+    char *null;
+    const char *p;
     unsigned chunks_added = 0;
     int n;
 
@@ -411,7 +412,7 @@ append(dataentry *entry, enum VSL_tag_e tag, unsigned xid, char *data,
 }
 
 static inline void
-addkey(dataentry *entry, enum VSL_tag_e tag, unsigned xid, char *key,
+addkey(dataentry *entry, enum VSL_tag_e tag, unsigned xid, const char *key,
        int keylen)
 {
     CHECK_OBJ_NOTNULL(entry, DATA_MAGIC);
@@ -516,7 +517,7 @@ dispatch(struct VSL_data *vsl, struct VSL_transaction * const pt[], void *priv)
 
             switch (VSL_TAG(t->c->rec.ptr)) {
                 int datalen;
-                char *data;
+                const char *data;
                 vcl_log_t data_type;
                 struct timeval reqend_t;
 

src/parse.c

@@ -58,18 +58,23 @@ parse_UnsignedDec(const char *str, int len, unsigned *num)
    len is length from that char to end of data
 */
 int
-Parse_VCL_Log(const char *ptr, int len, char **data, int *datalen,
+Parse_VCL_Log(const char *ptr, int len, const char **data, int *datalen,
               vcl_log_t *type)
 {
+    const char *c = ptr;
+
     *type = VCL_LOG_DATA;
-    char *blank = memchr(ptr, ' ', len);
-    if (blank == NULL)
-        return EINVAL;
-    if (strncmp(blank + 1, "key ", 4) == 0) {
-        blank += 4;
+    while (isdigit(*c))
+        c++;
+    if (*c == ' ' && (c - ptr + 1 < len))
+        c++;
+    else
+        c = ptr;
+    if (strncmp(c, "key ", 4) == 0) {
+        c += 4;
         *type = VCL_LOG_KEY;
     }
-    *data = blank + 1;
+    *data = c;
     *datalen = ptr + len - *data;
     return(0);
 }

src/test/regress.sh

@@ -3,7 +3,7 @@
 # The regression test reads from a binary dump of the Varnish SHM log
 # obtained from:
 #
-# $ varnishlog -B -w varnish.binlog
+# $ varnishlog -w varnish.binlog
 #
 # The regression runs trackrdrd, reading from the binary dump and
 # logging to stdout in debug mode, and obtains a cksum from stdout. It
@@ -17,38 +17,54 @@ echo '... testing messages & log output at debug level against known checksums'
 LOG=mq_log.log
 MSG=mq_test.log
 
-rm -f $LOG $MSG
-
-../trackrdrd -D -f varnish.binlog -l $LOG -d -c test.conf
-
-# Check ckums of the log with and without logs from the worker thread,
-# since these are written asynchronously.
-
-# the first sed removes the version/revision from the "initializing" line
-# the second sed removes the user under which the child process runs
-# "Not running as root" filtered so that the test is independent of
-# the user running it
-CKSUM=$( grep -v 'Worker 1' $LOG |  sed -e 's/\(initializing\) \(.*\)/\1/' | sed -e 's/\(Running as\) \([a-zA-Z0-9]*\)$/\1/' | grep -v 'Not running as root' | cksum)
-if [ "$CKSUM" != '3352465725 375518' ]; then
-    echo "ERROR: Regression test incorrect reader log cksum: $CKSUM"
-    exit 1
-fi
-
-# Now check the logs from the worker thread
-# Filter the 'returned to free list' messages, since these may be different
-# in different runs.
-# Also filter the version/revision from the "connected" line.
-CKSUM=$( grep 'Worker 1' $LOG | egrep -v 'returned [0-9]+ [^ ]+ to free list' | sed -e 's/\(connected\) \(.*\)/\1/' | cksum)
-if [ "$CKSUM" != '3908916621 57319' ]; then
-    echo "ERROR: Regression test incorrect worker log cksum: $CKSUM"
-    exit 1
-fi
-
-# Check the messages and keys
-CKSUM=$(cksum $MSG)
-if [ "$CKSUM" != "1139478852 48689 $MSG" ]; then
-    echo "ERROR: Regression test incorrect output cksum: $CKSUM"
-    exit 1
-fi
+#
+# $1 the binary log to read
+# $2 the log with Worker entries filtered out
+# $3 the log filtered for Worker entries
+# $4 output of the file mq implementation
+#
+function regress {
+    rm -f $LOG $MSG
+
+    ../trackrdrd -D -f $1 -l $LOG -d -c test.conf
+
+    # Check ckums of the log with and without logs from the worker thread,
+    # since these are written asynchronously.
+
+    # the first sed removes the version/revision from the "initializing" line
+    # the second sed removes the user under which the child process runs
+    # "Not running as root" filtered so that the test is independent of
+    # the user running it
+    CKSUM=$( grep -v 'Worker 1' $LOG |  sed -e 's/\(initializing\) \(.*\)/\1/' | sed -e 's/\(Running as\) \([a-zA-Z0-9]*\)$/\1/' | grep -v 'Not running as root' | cksum)
+    if [ "$CKSUM" != "$2" ]; then
+        echo "ERROR: Regression test incorrect reader log cksum: $CKSUM"
+        exit 1
+    fi
+
+    # Now check the logs from the worker thread
+    # Filter the 'returned to free list' messages, since these may be different
+    # in different runs.
+    # Also filter the version/revision from the "connected" line.
+    CKSUM=$( grep 'Worker 1' $LOG | egrep -v 'returned [0-9]+ [^ ]+ to free list' | sed -e 's/\(connected\) \(.*\)/\1/' | cksum)
+    if [ "$CKSUM" != "$3" ]; then
+        echo "ERROR: Regression test incorrect worker log cksum: $CKSUM"
+        exit 1
+    fi
+
+    # Check the messages and keys
+    CKSUM=$(cksum $MSG)
+    if [ "$CKSUM" != "$4 $MSG" ]; then
+        echo "ERROR: Regression test incorrect output cksum: $CKSUM"
+        exit 1
+    fi
+}
+
+echo '... standard VCL_Log syntax'
+regress 'varnish.binlog' '4116554635 333344' '1274763305 56045' \
+        '1485621276 46141'
+
+echo '... legacy VCL_Log syntax'
+regress 'varnish.legacy.binlog' '3787836061 375539' '3908916621 57319' \
+        '1139478852 48689'
 
 exit 0

src/test/test_parse.c

@@ -46,12 +46,21 @@ static char
 *test_vcl_log(void)
 {
     int err, len;
-    char *data;
+    const char *data;
     vcl_log_t type;
 
     printf("... testing Parse_VCL_Log\n");
 
-    #define VCLLOG "1253687608 url=%2Frdrtestapp%2F"
+    #define VCLLOG_LEGACY "1253687608 url=%2Frdrtestapp%2F"
+    err = Parse_VCL_Log(VCLLOG_LEGACY, strlen(VCLLOG_LEGACY), &data, &len,
+                        &type);
+    VMASSERT(err == 0, "VCL_Log %s: %s", VCLLOG_LEGACY, strerror(err));
+    MASSERT(len == 20);
+    MASSERT(type == VCL_LOG_DATA);
+    VMASSERT(strncmp(data, "url=%2Frdrtestapp%2F", 20) == 0,
+             "VCL_Log %s: returned data=[%.*s]", VCLLOG_LEGACY, len, data);
+
+    #define VCLLOG "url=%2Frdrtestapp%2F"
     err = Parse_VCL_Log(VCLLOG, strlen(VCLLOG), &data, &len, &type);
     VMASSERT(err == 0, "VCL_Log %s: %s", VCLLOG, strerror(err));
     MASSERT(len == 20);
@@ -60,12 +69,26 @@ static char
              "VCL_Log %s: returned data=[%.*s]", VCLLOG, len, data);
 
     err = Parse_VCL_Log("foo", 3, &data, &len, &type);
-    VMASSERT(err == EINVAL, "VCL_Log foo: expected EINVAL, got %d", err);
+    VMASSERT(err == 0, "VCL_Log foo: %s", strerror(err));
+    MASSERT(len == 3);
+    MASSERT(type == VCL_LOG_DATA);
+    VMASSERT(strncmp(data, "foo", 3) == 0,
+             "VCL_Log foo: returned data=[%.*s]", len, data);
 
-    #define VCLLOG_INVALID "foo url=%2Frdrtestapp%2F"
-    err = Parse_VCL_Log(VCLLOG_INVALID, 3, &data, &len, &type);
-    VMASSERT(err == EINVAL, "VCL_Log %s: expected EINVAL, got %d",
-             VCLLOG_INVALID, err);
+    #define VCLLOG_SPACE "foo url=%2Frdrtestapp%2F"
+    err = Parse_VCL_Log(VCLLOG_SPACE, 3, &data, &len, &type);
+    VMASSERT(err == 0, "VCL_Log %s: %s", VCLLOG_SPACE, strerror(err));
+    MASSERT(len == 3);
+    MASSERT(type == VCL_LOG_DATA);
+    VMASSERT(strncmp(data, "foo", 3) == 0,
+             "VCL_Log %s: returned data=[%.*s]", VCLLOG_SPACE, len, data);
+
+    err = Parse_VCL_Log(VCLLOG_SPACE, strlen(VCLLOG_SPACE), &data, &len, &type);
+    VMASSERT(err == 0, "VCL_Log foo: %s", strerror(err));
+    MASSERT(len == strlen(VCLLOG_SPACE));
+    MASSERT(type == VCL_LOG_DATA);
+    VMASSERT(strncmp(data, VCLLOG_SPACE, strlen(VCLLOG_SPACE)) == 0,
+             "VCL_Log %s: returned data=[%.*s]", VCLLOG_SPACE, len, data);
 
     /* 1024 chars */
     #define LONG_STRING \
@@ -85,15 +108,32 @@ static char
         "1234567890123456789012345678901234567890123456789012345678901234" \
         "1234567890123456789012345678901234567890123456789012345678901234" \
         "1234567890123456789012345678901234567890123456789012345678901234"
-    #define VCLLOG_LONG "1253687608 foo=" LONG_STRING
-    err = Parse_VCL_Log(VCLLOG_LONG, 1039, &data, &len, &type);
+    #define VCLLOG_LONG_LEGACY "1253687608 foo=" LONG_STRING
+    err = Parse_VCL_Log(VCLLOG_LONG_LEGACY, 1039, &data, &len, &type);
+    VMASSERT(err == 0, "VCL_Log legacy long string: %s", strerror(err));
+    MASSERT(len == 1028);
+    MASSERT(type == VCL_LOG_DATA);
+    VMASSERT(strncmp(data, "foo=" LONG_STRING, 1028) == 0,
+             "VCL_Log legacy long string: returned data=[%.*s]", len, data);
+
+    #define VCLLOG_LONG "foo=" LONG_STRING
+    err = Parse_VCL_Log(VCLLOG_LONG, strlen(VCLLOG_LONG), &data, &len, &type);
     VMASSERT(err == 0, "VCL_Log long string: %s", strerror(err));
     MASSERT(len == 1028);
     MASSERT(type == VCL_LOG_DATA);
     VMASSERT(strncmp(data, "foo=" LONG_STRING, 1028) == 0,
              "VCL_Log long string: returned data=[%.*s]", len, data);
 
-    #define VCLKEY "1253687608 key foobarbazquux"
+    #define VCLKEY_LEGACY "1253687608 key foobarbazquux"
+    err = Parse_VCL_Log(VCLKEY_LEGACY, strlen(VCLKEY_LEGACY), &data, &len,
+                        &type);
+    VMASSERT(err == 0, "VCL_Log %s: %s", VCLKEY_LEGACY, strerror(err));
+    MASSERT(len == 13);
+    MASSERT(type == VCL_LOG_KEY);
+    VMASSERT(strncmp(data, "foobarbazquux", 13) == 0,
+             "VCL_Log %s: returned data=[%.*s]", VCLKEY_LEGACY, len, data);
+
+    #define VCLKEY "key foobarbazquux"
     err = Parse_VCL_Log(VCLKEY, strlen(VCLKEY), &data, &len, &type);
     VMASSERT(err == 0, "VCL_Log %s: %s", VCLKEY, strerror(err));
     MASSERT(len == 13);
@@ -101,8 +141,17 @@ static char
     VMASSERT(strncmp(data, "foobarbazquux", 13) == 0,
              "VCL_Log %s: returned data=[%.*s]", VCLKEY, len, data);
 
-    #define VCLKEY_LONG "1253687608 key " LONG_STRING
-    err = Parse_VCL_Log(VCLKEY_LONG, 1039, &data, &len, &type);
+    #define VCLKEY_LONG_LEGACY "1253687608 key " LONG_STRING
+    err = Parse_VCL_Log(VCLKEY_LONG_LEGACY, strlen(VCLKEY_LONG_LEGACY), &data,
+                        &len, &type);
+    VMASSERT(err == 0, "VCL_Log legacy long key: %s", strerror(err));
+    MASSERT(len == 1024);
+    MASSERT(type == VCL_LOG_KEY);
+    VMASSERT(strncmp(data, LONG_STRING, 1024) == 0,
+             "VCL_Log legacy long key: returned data=[%.*s]", len, data);
+
+    #define VCLKEY_LONG "key " LONG_STRING
+    err = Parse_VCL_Log(VCLKEY_LONG, 1028, &data, &len, &type);
     VMASSERT(err == 0, "VCL_Log long key: %s", strerror(err));
     MASSERT(len == 1024);
     MASSERT(type == VCL_LOG_KEY);

src/trackrdrd.h

@@ -288,6 +288,6 @@ void MON_StatsUpdate(stats_update_t update, unsigned nchunks, unsigned nbytes);
 /* Whether a VCL_Log entry contains a data payload or a shard key */
 typedef enum { VCL_LOG_DATA, VCL_LOG_KEY } vcl_log_t;
 
-int Parse_VCL_Log(const char *ptr, int len, char **data, int *datalen,
+int Parse_VCL_Log(const char *ptr, int len, const char **data, int *datalen,
                   vcl_log_t *type);
 int Parse_Timestamp(const char *ptr, int len, struct timeval *t);