Imporove debug messages

src/vmod_zipflow.c

@@ -479,8 +479,11 @@ fill_meta(VRT_CTX, struct zipflow_request *zfr)
 		zfr->atime = ctx->now;
 	if (zfr->mtime < 0)
 		zfr->mtime = get_lm(ctx);
-	VSLb(ctx->vsl, SLT_Debug, "%s %o %f %f", zfr->name, zfr->mode,
-	    zfr->atime, zfr->mtime);
+	if (DO_DEBUG(DBG_PROCESSORS)) {
+		VSLb(ctx->vsl, SLT_Debug, "zipflow meta "
+		    "%s %o %f %f", zfr->name, zfr->mode,
+		    zfr->atime, zfr->mtime);
+	}
 }
 
 int
@@ -566,9 +569,20 @@ zft_iter_req_body(struct zipflow_top *zft)
 static int
 vdp_zipflow_put(void *priv, void const *ptr, size_t len)
 {
+	int r;
+
+	if (ptr != NULL && len == 0)
+		return (0);
 
-	return (VDP_bytes(priv, ptr == NULL ? VDP_END : VDP_FLUSH,
-	    ptr, (ssize_t)len));
+	r = VDP_bytes(priv, ptr == NULL ? VDP_END : VDP_FLUSH,
+	    ptr, (ssize_t)len);
+
+	if (DO_DEBUG(DBG_PROCESSORS)) {
+		VSL(SLT_Debug, NO_VXID,
+		    "zipflow put r=%d priv=%p ptr=%p len=%zu",
+		    r, priv, ptr, len);
+	}
+	return (r);
 }
 
 static void
@@ -752,6 +766,11 @@ vdp_zipsub_bytes(struct vdp_ctx *vdc, enum vdp_action act, void **priv,
 
 	assert(len >= 0);
 	r = zip_data(zft->zip, ptr, (size_t)len, act == VDP_END ? 1 : 0);
+	if (DO_DEBUG(DBG_PROCESSORS)) {
+		VSL(SLT_Debug, NO_VXID,
+		    "zipflow zip_data r=%d ptr=%p, len=%zd, end=%d",
+		    r, ptr, len, act == VDP_END ? 1 : 0);
+	}
 	if (r) {
 		VSLb(vdc->vsl, SLT_Error, "zip_data returned %d", r);
 		return (-1);
@@ -934,7 +953,7 @@ zfr_include(struct req *preq, struct zipflow_request *zfr)
 		if (s == REQ_FSM_DONE)
 			break;
 		DSL(DBG_WAITINGLIST, req->vsl->wid,
-		    "waiting for zipflow (%d)", (int)s);
+		    "waiting for zipflow %p", zfr);
 		assert(s == REQ_FSM_DISEMBARK);
 
 		AN(zfr->cond);

src/vtc/sub-coalesce.vtc

@@ -12,7 +12,7 @@ server s1 {
 	txresp -bodylen 20480
 } -start
 
-varnish v1 -vcl+backend {
+varnish v1 -arg "-p debug=+waitinglist" -vcl+backend {
 	import zipflow;
 
 	sub vcl_recv {