[master] 09a75da Backend_health: report error details

[Nils Goroll]

commit 09a75daaf302eba6c4f81ff30f394f013d93f8c5
Author: Nils Goroll <nils.goroll at uplex.de>
Date:   Mon Jun 11 13:55:01 2018 +0200

    Backend_health: report error details
    
    Previously, tracing the root cause of probe failures was unnecessarily
    complicated by the fact that the probe window bits and timing
    information were the only source of information when no HTTP status
    line was logged and for the case of all the bits being zero, almost
    impossible (e.g. differentiating between a local and remote connection
    open failure).
    
    We now re-use the response field for failing probes also.

diff --git a/bin/varnishd/cache/cache_backend_probe.c b/bin/varnishd/cache/cache_backend_probe.c
index 2c87327..fa823d4 100644
--- a/bin/varnishd/cache/cache_backend_probe.c
+++ b/bin/varnishd/cache/cache_backend_probe.c
@@ -39,6 +39,8 @@
 
 #include <poll.h>
 #include <stdio.h>
+#include <errno.h>
+#include <string.h>
 #include <stdlib.h>
 
 #include "cache_varnishd.h"
@@ -223,8 +225,15 @@ vbp_write(struct vbp_target *vt, int *sock, const void *buf, size_t len)
 
 	i = write(*sock, buf, len);
 	if (i != len) {
-		if (i < 0)
+		if (i < 0) {
 			vt->err_xmit |= 1;
+			bprintf(vt->resp_buf, "Write error %d (%s)",
+				errno, strerror(errno));
+		} else {
+			bprintf(vt->resp_buf,
+				"Short write (%d/%zu) error %d (%s)",
+				i, len, errno, strerror(errno));
+		}
 		VTCP_close(sock);
 		return (-1);
 	}
@@ -275,7 +284,8 @@ vbp_poke(struct vbp_target *vt)
 	s = VTP_Open(vt->tcp_pool, t_end - t_now, (const void **)&sa,
 		vt->backend->vsc);
 	if (s < 0) {
-		/* Got no connection: failed */
+		bprintf(vt->resp_buf, "Open error %d (%s)",
+			errno, strerror(errno));
 		return;
 	}
 
@@ -292,7 +302,9 @@ vbp_poke(struct vbp_target *vt)
 	t_now = VTIM_real();
 	tmo = (int)round((t_end - t_now) * 1e3);
 	if (tmo <= 0) {
-		/* Spent too long time getting it */
+		bprintf(vt->resp_buf,
+			"Open timeout %.3fs exceeded by %.3fs",
+			vt->timeout, t_now - t_end);
 		VTCP_close(&s);
 		return;
 	}
@@ -304,8 +316,10 @@ vbp_poke(struct vbp_target *vt)
 		proxy_header = -1;
 	Lck_Unlock(&vbp_mtx);
 
-	if (proxy_header < 0)
+	if (proxy_header < 0) {
+		bprintf(vt->resp_buf, "%s", "No backend");
 		return;
+	}
 
 	/* Send the PROXY header */
 	assert(proxy_header <= 2);
@@ -329,9 +343,17 @@ vbp_poke(struct vbp_target *vt)
 		tmo = (int)round((t_end - t_now) * 1e3);
 		if (tmo > 0)
 			i = poll(pfd, 1, tmo);
-		if (i == 0 || tmo <= 0) {
-			if (i == 0)
-				vt->err_recv |= 1;
+		if (i == 0) {
+			vt->err_recv |= 1;
+			bprintf(vt->resp_buf, "Poll error %d (%s)",
+				errno, strerror(errno));
+			VTCP_close(&s);
+			return;
+		}
+		if (tmo <= 0) {
+			bprintf(vt->resp_buf,
+				"Poll (read) timeout %.3fs exceeded by %.3fs",
+				vt->timeout, t_now - t_end);
 			VTCP_close(&s);
 			return;
 		}
@@ -340,20 +362,27 @@ vbp_poke(struct vbp_target *vt)
 			    sizeof vt->resp_buf - rlen);
 		else
 			i = read(s, buf, sizeof buf);
-		if (i <= 0)
+		if (i <= 0) {
+			if (i < 0)
+				bprintf(vt->resp_buf, "Read error %d (%s)",
+					errno, strerror(errno));
 			break;
+		}
 		rlen += i;
 	}
 
 	VTCP_close(&s);
 
 	if (i < 0) {
+		/* errno reported above */
 		vt->err_recv |= 1;
 		return;
 	}
 
-	if (rlen == 0)
+	if (rlen == 0) {
+		bprintf(vt->resp_buf, "%s", "Empty response");
 		return;
+	}
 
 	/* So we have a good receive ... */
 	t_now = VTIM_real();
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
index 1bafbf1..e56b7c8 100644
--- a/include/tbl/vsl_tags.h
+++ b/include/tbl/vsl_tags.h
@@ -389,7 +389,7 @@ SLTM(Backend_health, 0, "Backend health check",
 	"The format is::\n\n"
 	"\t%s %s %s %u %u %u %f %f %s\n"
 	"\t|  |  |  |  |  |  |  |  |\n"
-	"\t|  |  |  |  |  |  |  |  +- Probe HTTP response\n"
+	"\t|  |  |  |  |  |  |  |  +- Probe HTTP response / error information\n"
 	"\t|  |  |  |  |  |  |  +---- Average response time\n"
 	"\t|  |  |  |  |  |  +------- Response time\n"
 	"\t|  |  |  |  |  +---------- Probe window size\n"