[6.0] 46d1ad5c2 Backend_health: report error details

[Dridi Boukelmoune]

commit 46d1ad5c29de427964beac84446a1e1bb3971fbb
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 b45eed1f6..3f3a106ba 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"
@@ -227,8 +229,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);
 	}
@@ -279,7 +288,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;
 	}
 
@@ -296,7 +306,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;
 	}
@@ -308,8 +320,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);
@@ -333,9 +347,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;
 		}
@@ -344,20 +366,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 fa348b39f..ac93f15b7 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"