all unit tests succeed, including the regression test

src/child.c

@@ -72,7 +72,7 @@
 #define TRACKLOG_PREFIX "track "
 #define TRACKLOG_PREFIX_LEN (sizeof(TRACKLOG_PREFIX)-1)
 #define REQEND_T_VAR "req_endt"
-#define REQEND_T_LEN (sizeof(REQEND_T_VAR "=1430176881.682097")-1)
+#define REQEND_T_LEN (sizeof(REQEND_T_VAR "=1430176881.682097"))
 
 #define DISPATCH_EOL 0
 #define DISPATCH_RETURN_OK 0
@@ -312,7 +312,7 @@ dispatch(struct VSL_data *vsl, struct VSL_transaction * const pt[], void *priv)
             assert(t->type == VSL_t_req);
             assert(VSL_CLIENT(t->c->rec.ptr));
 
-            if (t == pt[0]) {
+            if (de->end == 0) {
                 de->xid = t->vxid;
                 snprintf(de->data, config.maxdata, "XID=%u", t->vxid);
                 de->end = strlen(de->data);
@@ -320,7 +320,7 @@ dispatch(struct VSL_data *vsl, struct VSL_transaction * const pt[], void *priv)
                     len_hi = de->end;
             }
 
-            len = VSL_LEN(t->c->rec.ptr);
+            len = VSL_LEN(t->c->rec.ptr) - 1;
             payload = VSL_CDATA(t->c->rec.ptr);
             xid = VSL_ID(t->c->rec.ptr);
             tag = VSL_TAG(t->c->rec.ptr);
@@ -392,7 +392,7 @@ dispatch(struct VSL_data *vsl, struct VSL_transaction * const pt[], void *priv)
 
     snprintf(reqend_str, REQEND_T_LEN, "%s=%u.%06lu", REQEND_T_VAR,
              (unsigned) de->reqend_t.tv_sec, de->reqend_t.tv_usec);
-    append(de, SLT_Timestamp, de->xid, reqend_str, REQEND_T_LEN);
+    append(de, SLT_Timestamp, de->xid, reqend_str, REQEND_T_LEN - 1);
     de->occupied = 1;
     MON_StatsUpdate(STATS_OCCUPANCY);
     data_submit(de);
@@ -420,6 +420,7 @@ CHILD_Main(int readconfig)
     struct VSL_cursor *cursor;
 
     MON_StatsInit();
+    debug = (LOG_GetLevel() == LOG_DEBUG);
         
     LOG_Log0(LOG_NOTICE, "Worker process starting");
 

src/log.c

@@ -44,6 +44,7 @@ static const char *level2name[LOG_DEBUG+1];
 static void
 syslog_setlevel(int level)
 {
+    logconf.level = level;
     setlogmask(LOG_UPTO(level));
 }
 
@@ -68,11 +69,13 @@ stdio_log(int level, const char *msg, ...)
     
     if (level > logconf.level)
         return;
+    flockfile(logconf.out);
     fprintf(logconf.out, "%s: ", level2name[level]);
     va_start(ap, msg);
     (void) vfprintf(logconf.out, msg, ap);
     va_end(ap);
     fprintf(logconf.out, "\n");
+    funlockfile(logconf.out);
     fflush(logconf.out);
 }
 
@@ -97,6 +100,7 @@ int LOG_Open(const char *progname)
         logconf.close = closelog;
         openlog(progname, LOG_PID | LOG_CONS | LOG_NDELAY | LOG_NOWAIT,
                 config.syslog_facility);
+        logconf.level = LOG_INFO;
         setlogmask(LOG_UPTO(LOG_INFO));
         atexit(closelog);
         return(0);
@@ -119,3 +123,9 @@ int LOG_Open(const char *progname)
     
     return(0);
 }
+
+int
+LOG_GetLevel(void)
+{
+    return logconf.level;
+}

src/test/Makefile.am

 AM_CPPFLAGS = @VARNISH_CFLAGS@ -I$(top_srcdir)/include
 
 TESTS = test_parse test_data test_append test_mq test_spmcq	\
-	test_config test_spmcq_loop.sh test_worker # regress.sh
+	test_config test_spmcq_loop.sh test_worker regress.sh
 
 check_PROGRAMS = test_parse test_data test_append test_mq	\
 	test_spmcq test_config test_worker

src/test/regress.sh

@@ -3,13 +3,12 @@
 # The regression test reads from a binary dump of the Varnish SHM log
 # obtained from:
 #
-# $ varnishlog -w varnish.binlog
-#
-# Load was created from JMeter running 50 request in 100 threads.
+# $ varnishlog -B -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. The cksum must match an expected value.
+# logging to stdout in debug mode, and obtains a cksum from stdout. It
+# uses the file MQ implementation to write an output file. The cksums
+# from the log and the output file must match expected values.
 
 echo
 echo "TEST: $0"
@@ -22,8 +21,14 @@ CMD="../trackrdrd -D -f varnish.binlog -l - -d -c test.conf"
 # the user running it
 CKSUM=$( $CMD | sed -e 's/\(initializing\) \(.*\)/\1/' | sed -e 's/\(Running as\) \([a-zA-Z0-9]*\)$/\1/' | grep -v 'Not running as root' | cksum)
 
-if [ "$CKSUM" != '422255173 234182' ]; then
-    echo "ERROR: Regression test incorrect cksum: $CKSUM"
+if [ "$CKSUM" != '3547423616 248886' ]; then
+    echo "ERROR: Regression test incorrect log cksum: $CKSUM"
+    exit 1
+fi
+
+CKSUM=$(cksum mq_test.log)
+if [ "$CKSUM" != '3675018591 29491 mq_test.log' ]; then
+    echo "ERROR: Regression test incorrect output cksum: $CKSUM"
     exit 1
 fi
 

src/test/test.conf

@@ -4,6 +4,6 @@ pid.file = trackrdrd.pid
 maxdata = 4096
 maxdone = 1024
 monitor.interval = 0
-nworkers = 0
+nworkers = 1
 mq.module = ../mq/file/.libs/libtrackrdr-file.so
 mq.config_file = file_mq.conf

src/trackrdrd.h

@@ -289,6 +289,7 @@ struct logconf {
 } logconf;
 
 int LOG_Open(const char *progname);
+int LOG_GetLevel(void);
 /* XXX: __VA_ARGS__ can't be empty ... */
 #define LOG_Log0(level, msg) logconf.log(level, msg)
 #define LOG_Log(level, msg, ...) logconf.log(level, msg, __VA_ARGS__)