Don't discard entire transactions on length overflow or chunk exhaustion.

src/child.c

@@ -356,14 +356,7 @@ append(dataentry *entry, enum VSL_tag_e tag, unsigned xid, char *data,
     int n;
 
     CHECK_OBJ_NOTNULL(entry, DATA_MAGIC);
-    /* Data overflow */
-    if (entry->end + datalen + 1 > config.max_reclen) {
-        LOG_Log(LOG_ERR, "%s: Data too long, XID=%d, current length=%d, "
-            "DISCARDING data=[%.*s]", VSL_tags[tag], xid, entry->end,
-            datalen, data);
-        len_overflows++;
-        return -1;
-    }
+
     /* Null chars in the payload means that the data was truncated in the
        log, due to exceeding shm_reclen. */
     if ((null = memchr(data, '\0', datalen)) != NULL) {
@@ -486,9 +479,8 @@ dispatch(struct VSL_data *vsl, struct VSL_transaction * const pt[], void *priv)
 
                 chunk = get_chunk(de);
                 if (chunk == NULL) {
-                    if (debug)
-                        LOG_Log(LOG_DEBUG, "Free chunks exhausted, "
-                                "DATA DISCARDED: [Tx %d]", t->vxid);
+                    LOG_Log(LOG_ERR, "Free chunks exhausted, DATA DISCARDED: "
+                            "[Tx %d]", t->vxid);
                     data_free(de);
                     return status;
                 }
@@ -538,13 +530,19 @@ dispatch(struct VSL_data *vsl, struct VSL_transaction * const pt[], void *priv)
                             datalen, data);
 
                 if (data_type == VCL_LOG_DATA) {
+                    if (de->end + datalen + 1 > config.max_reclen) {
+                        /* Data overflow */
+                        LOG_Log(LOG_ERR, "%s: Data too long, XID=%d, current "
+                                "length=%d, DISCARDING data=[%.*s]",
+                                VSL_tags[tag], xid, de->end, datalen, data);
+                        len_overflows++;
+                        continue;
+                    }
                     chunks = append(de, tag, xid, data, datalen);
                     if (chunks < 0) {
-                        if (debug)
-                            LOG_Log(LOG_DEBUG, "Chunks exhausted, DATA "
-                                    "DISCARDED: %.*s", datalen, data);
-                        data_free(de);
-                        return status;
+                        LOG_Log(LOG_DEBUG, "Chunks exhausted, DATA DISCARDED "
+                                "XID=%d: %.*s", xid, datalen, data);
+                        continue;
                     }
                     chunks_added += chunks;
                     hasdata = 1;
@@ -594,12 +592,11 @@ dispatch(struct VSL_data *vsl, struct VSL_transaction * const pt[], void *priv)
              (unsigned) latest_t.tv_sec, latest_t.tv_usec);
     chunks = append(de, SLT_Timestamp, vxid, reqend_str, REQEND_T_LEN - 1);
     if (chunks < 0) {
-        if (debug)
-            LOG_Log(LOG_DEBUG, "Chunks exhausted, DATA DISCARDED: Tx %u", vxid);
-        data_free(de);
-        return status;
+        LOG_Log(LOG_ERR, "Chunks exhausted, DATA DISCARDED XID=%u: %s", vxid,
+            reqend_str);
     }
-    chunks_added += chunks;
+    else
+        chunks_added += chunks;
     de->occupied = 1;
     MON_StatsUpdate(STATS_OCCUPANCY, chunks_added, 0);
     data_submit(de);

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 toolong.sh
 
 check_PROGRAMS = test_parse test_data test_append test_mq	\
 	test_spmcq test_config test_worker

src/test/toolong.conf

+# Test configuration for the test of length overflow and chunk exhaustion
+log.file = /tmp/trackrdrd.log
+pid.file = trackrdrd.pid
+max.reclen = 64
+max.records = 1
+chunk.size = 64
+monitor.interval = 0
+nworkers = 1
+mq.module = ../mq/file/.libs/libtrackrdr-file.so
+mq.config_file = file_mq.conf

src/test/toolong.sh

+#!/bin/bash
+
+# Test length overflow and chunk exhaustion.
+#
+# When the tracking reader is unable to write to a data entry, either
+# because max.reclen would be exceeded (length overflow) or because
+# the chunk table is exhausted, then it doesn't append the data, logs
+# the discarded data, and continues reading. At the end of the log
+# transaction, it sends data it was able to read into the entry.
+#
+# This tests runs similarly to regress.sh, see the comments there for
+# details.
+
+echo
+echo "TEST: $0"
+echo '... testing recovery from length overflow and chunk exhaustion'
+
+LOG=mq_log.log
+MSG=mq_test.log
+
+rm -f $LOG $MSG
+
+../trackrdrd -D -f toolong.log -l $LOG -d -c toolong.conf
+
+# Just filter out the worker thread entries, and the read the last 18 lines
+# in which the data read was logged, as well as the error messages.
+CKSUM=$( grep -v 'Worker 1' $LOG |  tail -18 | cksum)
+if [ "$CKSUM" != '921644137 1188' ]; then
+    echo "ERROR: Too long test incorrect reader log cksum: $CKSUM"
+    exit 1
+fi
+
+# Just check the whole contents of the file MQ output.
+MSGS=$(cat $MSG)
+if [ "$MSGS" != 'key=32772: XID=32772&foo=bar&foo=bar&foo=bar&foo=bar&' ]; then
+    echo "ERROR: Too long test incorrect output: $MSGS"
+    exit 1
+fi
+
+exit 0