trackrdrd: now parsing the request end time from ReqEnd and submitting

           it with the data

src/parse.c

@@ -32,9 +32,12 @@
 #include <errno.h>
 #include <ctype.h>
 #include <string.h>
+#include <time.h>
 
 #include "trackrdrd.h"
 
+#define Parse_UnsignedDec(str,len,xid) Parse_XID((str),(len),(xid))
+
 int
 Parse_XID(const char *str, int len, unsigned *xid)
 {
@@ -63,12 +66,41 @@ Parse_ReqStart(const char *ptr, int len, unsigned *xid)
 }
 
 int
-Parse_ReqEnd(const char *ptr, unsigned len, unsigned *xid)
+Parse_ReqEnd(const char *ptr, unsigned len, unsigned *xid,
+    struct timespec *reqend_t)
 {
-    char *blank = memchr(ptr, ' ', len);
+    int err;
+    char *blank, *reqend_tstr, *dot;
+    
+    blank = memchr(ptr, ' ', len);
+    if (blank == NULL)
+        return EINVAL;
+    err = Parse_XID(ptr, blank-ptr, xid);
+    if (err != 0)
+        return err;
+    
+    reqend_tstr = memchr(blank + 1, ' ', len-(blank-ptr));
+    if (reqend_tstr == NULL)
+        return EINVAL;
+    else
+        reqend_tstr++;
+    dot = memchr(reqend_tstr, '.', len-(reqend_tstr-ptr));
+    if (dot == NULL)
+        return EINVAL;
+    blank = memchr(dot + 1, ' ', len-(dot-ptr));
     if (blank == NULL)
         return EINVAL;
-    return Parse_XID(ptr, blank-ptr, xid);
+    err = Parse_UnsignedDec(reqend_tstr, dot-reqend_tstr,
+        (unsigned *)&reqend_t->tv_sec);
+    reqend_t->tv_sec &= 0x0ffffffff;
+    if (err != 0)
+        return err;
+    err = Parse_UnsignedDec(dot+1, blank-dot-1,
+        (unsigned *) &reqend_t->tv_nsec);
+    if (err != 0)
+        return err;
+    reqend_t->tv_nsec &= 0x0ffffffff;
+    return 0;
 }
 
 /* ptr points to the first char after "track "

src/test/regress.sh

@@ -20,7 +20,7 @@ CMD="../trackrdrd -D -f varnish.binlog -l - -d -c test.conf"
 # the second sed removes the user under which the child process runs
 CKSUM=$( $CMD | sed -e 's/\(initializing\) \(.*\)/\1/' | sed -e 's/\(, running as\) \(.*\)/\1/' | cksum)
 
-if [ "$CKSUM" != '646018814 229297' ]; then
+if [ "$CKSUM" != '4048021999 232297' ]; then
     echo "ERROR: Regression test incorrect cksum: $CKSUM"
     exit 1
 fi

src/test/test_parse.c

@@ -148,18 +148,23 @@ static char
 {
     unsigned xid;
     int err;
+    struct timespec reqend_t;
 
     printf("... testing Parse_ReqEnd\n");
 
     #define REQEND "1253687608 1348291555.658257008 1348291555.670388222 -0.012122154 NaN NaN"
 
-    err = Parse_ReqEnd(REQEND, strlen(REQEND), &xid);
+    err = Parse_ReqEnd(REQEND, strlen(REQEND), &xid, &reqend_t);
     sprintf(errmsg, "ReqEnd %s: %s", REQEND, strerror(err));
     mu_assert(errmsg, err == 0);
     sprintf(errmsg, "ReqEnd %s: returned XID=%d", REQEND, xid);
     mu_assert(errmsg, xid == 1253687608);
+    sprintf(errmsg, "ReqEnd %s: returned end_t=%d.%lu", REQEND,
+        (int) reqend_t.tv_sec, reqend_t.tv_nsec);
+    mu_assert(errmsg, reqend_t.tv_sec == 1348291555
+        && reqend_t.tv_nsec == 670388222);
 
-    err = Parse_ReqEnd("1253687608", 10, &xid);
+    err = Parse_ReqEnd("1253687608", 10, &xid, &reqend_t);
     sprintf(errmsg, "ReqEnd 1253687608: expected EINVAL, got %d", err);
     mu_assert(errmsg, err == EINVAL);
 

src/trackrdrd.c

@@ -76,8 +76,9 @@
 
 #define DEFAULT_CONFIG "/etc/trackrdrd.conf"
 
-/* XXX: should this be configurable ? */
+/* XXX: should these be configurable ? */
 #define MAX_STACK_DEPTH 100
+#define REQEND_T_VAR "req_endt"
 
 /* Hack, because we cannot have #ifdef in the macro definition SIGDISP */
 #define _UNDEFINED(SIG) ((#SIG)[0] == 0)
@@ -171,6 +172,30 @@ static inline dataentry
     return entry;
 }
 
+static inline void
+append(dataentry *entry, enum VSL_tag_e tag, unsigned xid, char *data,
+    int datalen)
+{
+    /* Data overflow */
+    /* XXX: Encapsulate (1 << (config.maxdata_scale+10)) */
+    if (entry->end + datalen + 1 > (1 << (config.maxdata_scale+10))) {
+        LOG_Log(LOG_ALERT,
+            "%s: Data too long, XID=%d, current length=%d, "
+            "DISCARDING data=[%.*s]", VSL_tags[tag], xid, entry->end,
+            datalen, data);
+        tbl.data_overflows++;
+        return;
+    }
+        
+    entry->data[entry->end] = '&';
+    entry->end++;
+    memcpy(&entry->data[entry->end], data, datalen);
+    entry->end += datalen;
+    if (entry->end > tbl.data_hi)
+        tbl.data_hi = entry->end;
+    return;
+}
+
 static int
 OSL_Track(void *priv, enum VSL_tag_e tag, unsigned fd, unsigned len,
           unsigned spec, const char *ptr, uint64_t bitmap)
@@ -178,7 +203,8 @@ OSL_Track(void *priv, enum VSL_tag_e tag, unsigned fd, unsigned len,
     unsigned xid;
     dataentry *entry;
     int err, datalen;
-    char *data;
+    char *data, reqend_str[strlen(REQEND_T_VAR)+22];
+    struct timespec reqend_t;
 
     (void) priv;
     (void) bitmap;
@@ -217,34 +243,22 @@ OSL_Track(void *priv, enum VSL_tag_e tag, unsigned fd, unsigned len,
         if (entry == NULL)
             break;
 
-        /* Data overflow */
-        /* XXX: Encapsulate (1 << (config.maxdata_scale+10)) */
-        if (entry->end + datalen + 1 > (1 << (config.maxdata_scale+10))) {
-            LOG_Log(LOG_ALERT,
-                "%s: Data too long, XID=%d, current length=%d, "
-                "DISCARDING data=[%.*s]", VSL_tags[tag], xid, entry->end,
-                datalen, data);
-            tbl.data_overflows++;
-            break;
-        }
-        
-        entry->data[entry->end] = '&';
-        entry->end++;
-        memcpy(&entry->data[entry->end], data, datalen);
-        entry->end += datalen;
-        if (entry->end > tbl.data_hi)
-            tbl.data_hi = entry->end;
+        append(entry, tag, xid, data, datalen);
         break;
 
     case SLT_ReqEnd:
 
-        err = Parse_ReqEnd(ptr, len, &xid);
+        err = Parse_ReqEnd(ptr, len, &xid, &reqend_t);
         AZ(err);
-        LOG_Log(LOG_DEBUG, "%s: XID=%d", VSL_tags[tag], xid);
+        LOG_Log(LOG_DEBUG, "%s: XID=%d req_endt=%u.%09lu", VSL_tags[tag], xid,
+            (unsigned) reqend_t.tv_sec, reqend_t.tv_nsec);
 
         entry = find_or_insert(xid, tag, fd);
         if (entry == NULL)
             break;
+        sprintf(reqend_str, "%s=%u.%09lu", REQEND_T_VAR,
+            (unsigned) reqend_t.tv_sec, reqend_t.tv_nsec);
+        append(entry, tag, xid, reqend_str, strlen(reqend_str));
         entry->state = DATA_DONE;
         MON_StatsUpdate(STATS_DONE);
         submit(xid);

src/trackrdrd.h

@@ -33,6 +33,7 @@
 #include <stdbool.h>
 #include <pthread.h>
 #include <sys/types.h>
+#include <time.h>
 
 #define MIN_TABLE_SCALE 10
 
@@ -209,7 +210,8 @@ pthread_mutex_t stats_update_lock;
 /* parse.c */
 int Parse_XID(const char *str, int len, unsigned *xid);
 int Parse_ReqStart(const char *ptr, int len, unsigned *xid);
-int Parse_ReqEnd(const char *ptr, unsigned len, unsigned *xid);
+int Parse_ReqEnd(const char *ptr, unsigned len, unsigned *xid,
+    struct timespec *reqend_t);
 int Parse_VCL_Log(const char *ptr, int len, unsigned *xid,
     char **data, int *datalen);