backend: add VSCs for backend errors

bin/varnishd/cache/cache.h

@@ -95,7 +95,7 @@ struct stream_close {
 	const char		*desc;
 };
     extern const struct stream_close SC_NULL[1];
-#define SESS_CLOSE(nm, stat, err, desc) \
+#define SESS_CLOSE_C(nm, stat, err, desc) \
     extern const struct stream_close SC_##nm[1];
 #include "tbl/sess_close.h"
 

bin/varnishd/cache/cache_backend.c

@@ -181,6 +181,87 @@ vbe_connwait_fini(struct connwait *cw)
 	FINI_OBJ(cw);
 }
 
+/*--------------------------------------------------------------------
+ * Update bc_ counters by reason (implementing ses_close_acct for backends)
+ *
+ * assuming that the approximation of non-atomic global counters is sufficient.
+ * if not: update to per-wrk
+ */
+
+static void
+vbe_close_acct(const struct pfd *pfd, struct VSC_vbe *vsc,
+    const stream_close_t reason)
+{
+
+	if (reason == SC_NULL) {
+		assert(PFD_State(pfd) == PFD_STATE_USED);
+		VSC_C_main->bc_tx_proxy++;
+		vsc->tx_proxy++;
+		return;
+	}
+
+#define SESS_CLOSE(U, l, err, desc)					\
+	if (reason == SC_ ## U) {					\
+		VSC_C_main->bc_ ## l++;					\
+		vsc->l++;					\
+		if (err) {						\
+			VSC_C_main->backend_closed_err++;		\
+			vsc->closed_err++;				\
+		}							\
+		return;							\
+	}
+#include "tbl/sess_close.h"
+
+	WRONG("Wrong event in vbe_close_acct");
+}
+
+static void v_matchproto_(vdi_finish_f)
+vbe_dir_finish(VRT_CTX, VCL_BACKEND d)
+{
+	struct backend *bp;
+	struct busyobj *bo;
+	struct pfd *pfd;
+
+	CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
+	CHECK_OBJ_NOTNULL(d, DIRECTOR_MAGIC);
+	bo = ctx->bo;
+	CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);
+	CAST_OBJ_NOTNULL(bp, d->priv, BACKEND_MAGIC);
+	AN(bp->vsc);
+
+	CHECK_OBJ_NOTNULL(bo->htc, HTTP_CONN_MAGIC);
+	CHECK_OBJ_NOTNULL(bo->htc->doclose, STREAM_CLOSE_MAGIC);
+
+	pfd = bo->htc->priv;
+	bo->htc->priv = NULL;
+	if (bo->htc->doclose != SC_NULL || bp->proxy_header != 0) {
+		vbe_close_acct(pfd, bp->vsc, bo->htc->doclose);
+		VSLb(bo->vsl, SLT_BackendClose, "%d %s close %s", *PFD_Fd(pfd),
+		    VRT_BACKEND_string(d), bo->htc->doclose->name);
+		VCP_Close(&pfd);
+		AZ(pfd);
+		Lck_Lock(bp->director->mtx);
+		VSC_C_main->backend_closed++;
+		bp->vsc->closed++;
+	} else {
+		assert (PFD_State(pfd) == PFD_STATE_USED);
+		VSLb(bo->vsl, SLT_BackendClose, "%d %s recycle", *PFD_Fd(pfd),
+		    VRT_BACKEND_string(d));
+		Lck_Lock(bp->director->mtx);
+		VSC_C_main->backend_recycle++;
+		VCP_Recycle(bo->wrk, &pfd);
+	}
+	assert(bp->n_conn > 0);
+	bp->n_conn--;
+	AN(bp->vsc);
+	bp->vsc->conn--;
+#define ACCT(foo)	bp->vsc->foo += bo->acct.foo;
+#include "tbl/acct_fields_bereq.h"
+	vbe_connwait_signal_locked(bp);
+	Lck_Unlock(bp->director->mtx);
+	bo->htc = NULL;
+}
+
 /*--------------------------------------------------------------------
  * Get a connection to the backend
  *
@@ -306,27 +387,26 @@ vbe_dir_getfd(VRT_CTX, struct worker *wrk, VCL_BACKEND dir, struct backend *bp,
 	bp->vsc->req++;
 	Lck_Unlock(bp->director->mtx);
 
+	INIT_OBJ(bo->htc, HTTP_CONN_MAGIC);
+	bo->htc->priv = pfd;
+	bo->htc->rfd = fdp;
+	bo->htc->doclose = SC_NULL;
 	CHECK_OBJ_NOTNULL(bo->htc->doclose, STREAM_CLOSE_MAGIC);
 
 	err = 0;
 	if (bp->proxy_header != 0)
-		err += VPX_Send_Proxy(*fdp, bp->proxy_header, bo->sp);
+		err = VPX_Send_Proxy(*fdp, bp->proxy_header, bo->sp);
 	if (err < 0) {
 		VSLb(bo->vsl, SLT_FetchError,
 		     "backend %s: proxy write errno %d (%s)",
 		     VRT_BACKEND_string(dir),
 		     errno, VAS_errtxt(errno));
-		// account as if connect failed - good idea?
-		VSC_C_main->backend_fail++;
-		bo->htc = NULL;
-		VCP_Close(&pfd);
-		AZ(pfd);
+		bo->htc->doclose = SC_TX_ERROR;
 		Lck_Lock(bp->director->mtx);
-		bp->n_conn--;
-		bp->vsc->conn--;
+		VSC_C_main->backend_fail++;
 		bp->vsc->req--;
-		vbe_connwait_signal_locked(bp);
 		Lck_Unlock(bp->director->mtx);
+		vbe_dir_finish(ctx, dir);
 		vbe_connwait_fini(cw);
 		return (NULL);
 	}
@@ -338,10 +418,6 @@ vbe_dir_getfd(VRT_CTX, struct worker *wrk, VCL_BACKEND dir, struct backend *bp,
 	    *fdp, VRT_BACKEND_string(dir), abuf2, pbuf2, abuf1, pbuf1,
 	    PFD_State(pfd) == PFD_STATE_STOLEN ? "reuse" : "connect");
 
-	INIT_OBJ(bo->htc, HTTP_CONN_MAGIC);
-	bo->htc->priv = pfd;
-	bo->htc->rfd = fdp;
-	bo->htc->doclose = SC_NULL;
 	FIND_TMO(first_byte_timeout,
 	    bo->htc->first_byte_timeout, bo, bp);
 	FIND_TMO(between_bytes_timeout,
@@ -350,49 +426,6 @@ vbe_dir_getfd(VRT_CTX, struct worker *wrk, VCL_BACKEND dir, struct backend *bp,
 	return (pfd);
 }
 
-static void v_matchproto_(vdi_finish_f)
-vbe_dir_finish(VRT_CTX, VCL_BACKEND d)
-{
-	struct backend *bp;
-	struct busyobj *bo;
-	struct pfd *pfd;
-
-	CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
-	CHECK_OBJ_NOTNULL(d, DIRECTOR_MAGIC);
-	bo = ctx->bo;
-	CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);
-	CAST_OBJ_NOTNULL(bp, d->priv, BACKEND_MAGIC);
-
-	CHECK_OBJ_NOTNULL(bo->htc, HTTP_CONN_MAGIC);
-	CHECK_OBJ_NOTNULL(bo->htc->doclose, STREAM_CLOSE_MAGIC);
-
-	pfd = bo->htc->priv;
-	bo->htc->priv = NULL;
-	if (bo->htc->doclose != SC_NULL || bp->proxy_header != 0) {
-		VSLb(bo->vsl, SLT_BackendClose, "%d %s close %s", *PFD_Fd(pfd),
-		    VRT_BACKEND_string(d), bo->htc->doclose->name);
-		VCP_Close(&pfd);
-		AZ(pfd);
-		Lck_Lock(bp->director->mtx);
-	} else {
-		assert (PFD_State(pfd) == PFD_STATE_USED);
-		VSLb(bo->vsl, SLT_BackendClose, "%d %s recycle", *PFD_Fd(pfd),
-		    VRT_BACKEND_string(d));
-		Lck_Lock(bp->director->mtx);
-		VSC_C_main->backend_recycle++;
-		VCP_Recycle(bo->wrk, &pfd);
-	}
-	assert(bp->n_conn > 0);
-	bp->n_conn--;
-	AN(bp->vsc);
-	bp->vsc->conn--;
-#define ACCT(foo)	bp->vsc->foo += bo->acct.foo;
-#include "tbl/acct_fields_bereq.h"
-	vbe_connwait_signal_locked(bp);
-	Lck_Unlock(bp->director->mtx);
-	bo->htc = NULL;
-}
-
 static int v_matchproto_(vdi_gethdrs_f)
 vbe_dir_gethdrs(VRT_CTX, VCL_BACKEND d)
 {

bin/varnishd/cache/cache_session.c

@@ -61,7 +61,7 @@ static const struct {
 
 enum sess_close {
 	SCE_NULL = 0,
-#define SESS_CLOSE(nm, stat, err, desc) SCE_##nm,
+#define SESS_CLOSE_C(nm, stat, err, desc) SCE_##nm,
 #include "tbl/sess_close.h"
 	SCE_MAX,
 };
@@ -74,7 +74,7 @@ const struct stream_close SC_NULL[1] = {{
 	.desc = "Not Closing",
 }};
 
-#define SESS_CLOSE(nm, stat, err, text) \
+#define SESS_CLOSE_C(nm, stat, err, text) \
 	const struct stream_close SC_##nm[1] = {{ \
 		.magic = STREAM_CLOSE_MAGIC, \
 		.idx = SCE_##nm, \
@@ -86,7 +86,7 @@ const struct stream_close SC_NULL[1] = {{
 
 static const stream_close_t sc_lookup[SCE_MAX] = {
 	[SCE_NULL] = SC_NULL,
-#define SESS_CLOSE(nm, stat, err, desc) \
+#define SESS_CLOSE_C(nm, stat, err, desc) \
 	[SCE_##nm] = SC_##nm,
 #include "tbl/sess_close.h"
 };
@@ -556,7 +556,7 @@ ses_close_acct(stream_close_t reason)
 
 	CHECK_OBJ_NOTNULL(reason, STREAM_CLOSE_MAGIC);
 	switch (reason->idx) {
-#define SESS_CLOSE(reason, stat, err, desc)		\
+#define SESS_CLOSE_C(reason, stat, err, desc)		\
 	case SCE_ ## reason:				\
 		VSC_C_main->sc_ ## stat++;		\
 		break;

bin/varnishd/http1/cache_http1_fetch.c

@@ -229,9 +229,9 @@ V1F_FetchRespHdr(struct busyobj *bo)
 			VSLb(bo->vsl, SLT_FetchError, "Received junk");
 			htc->doclose = SC_RX_JUNK;
 			break;
-		case HTC_S_CLOSE:
+		case HTC_S_EOF:
 			VSLb(bo->vsl, SLT_FetchError, "backend closed");
-			htc->doclose = SC_RESP_CLOSE;
+			htc->doclose = SC_REM_CLOSE;
 			break;
 		case HTC_S_TIMEOUT:
 			VSLb(bo->vsl, SLT_FetchError, "timeout");

bin/varnishd/proxy/cache_proxy_proto.c

@@ -757,6 +757,11 @@ VPX_Send_Proxy(int fd, int version, const struct sess *sp)
 	r = write(fd, VSB_data(vsb), VSB_len(vsb));
 	VTCP_Assert(r);
 
+	if (DO_DEBUG(DBG_PROXY_ERROR)) {
+		errno = EINTR;
+		return (-1);
+	}
+
 	if (!DO_DEBUG(DBG_PROTOCOL))
 		return (r);
 

bin/varnishtest/tests/c00036.vtc

@@ -27,7 +27,7 @@ logexpect l1 -v v1 -q "vxid == 1004" {
 
 	# purpose of this vtc: test the internal retry when the
 	# backend goes away on a keepalive TCP connection:
-	expect 0 1004 FetchError      {^HTC eof .Unexpected end of input.}
+	expect 0 1004 FetchError      {^backend closed}
 	expect 0 1004 BackendClose    {^\d+ s1}
 	expect 0 1004 Timestamp       {^Connected:}
 	expect 0 1004 BackendOpen     {^\d+ s1}
@@ -53,4 +53,10 @@ client c1 {
 } -run
 
 varnish v1 -expect backend_retry == 1
+varnish v1 -expect MAIN.backend_closed == 1
+varnish v1 -expect MAIN.backend_closed_err == 0
+varnish v1 -expect MAIN.bc_rx_bad == 0
+varnish v1 -expect MAIN.bc_rx_timeout == 0
+varnish v1 -expect MAIN.bc_rem_close == 1
+
 logexpect l1 -wait

bin/varnishtest/tests/o00007.vtc

@@ -0,0 +1,50 @@
+varnishtest "Failing to send proxy headers to backend"
+
+server s1 {} -start
+
+varnish v1 -vcl {
+	backend default {
+		.host = "${s1_addr}";
+		.port = "${s1_port}";
+		.proxy_header = 2;
+	}
+} -start
+
+varnish v1 -cliok "param.set debug +proxy_error"
+
+logexpect l1 -v v1 {
+	expect * 1002 Timestamp {^Connected:}
+	expect * 1002 FetchError {^backend default: proxy write errno}
+	expect * 1002 BackendClose {default close TX_ERROR}
+} -start
+
+client c1 {
+	txreq
+	rxresphdrs
+	expect resp.status == 503
+} -run
+
+logexpect l1 -wait
+
+varnish v1 -expect MAIN.backend_conn == 1
+varnish v1 -expect MAIN.backend_req == 0
+varnish v1 -expect MAIN.backend_closed == 1
+varnish v1 -expect MAIN.backend_closed_err == 1
+
+varnish v1 -expect MAIN.bc_rx_bad == 0
+varnish v1 -expect MAIN.bc_rem_close == 0
+varnish v1 -expect MAIN.bc_rx_timeout == 0
+varnish v1 -expect MAIN.bc_tx_error == 1
+varnish v1 -expect MAIN.bc_tx_proxy == 0
+
+varnish v1 -expect VBE.vcl1.default.conn == 0
+varnish v1 -expect VBE.vcl1.default.req == 0
+varnish v1 -expect VBE.vcl1.default.fail == 0
+varnish v1 -expect VBE.vcl1.default.closed == 1
+varnish v1 -expect VBE.vcl1.default.closed_err == 1
+
+varnish v1 -expect VBE.vcl1.default.rx_bad == 0
+varnish v1 -expect VBE.vcl1.default.rem_close == 0
+varnish v1 -expect VBE.vcl1.default.rx_timeout == 0
+varnish v1 -expect VBE.vcl1.default.tx_error == 1
+varnish v1 -expect VBE.vcl1.default.tx_proxy == 0

bin/varnishtest/tests/u00008.vtc

@@ -70,10 +70,12 @@ process p1 -winsz 25 132
 process p1 -expect-text 4 124 "AVG_1000"
 process p1 -expect-text 22 108 "UNSEEN  DIAG"
 
+process p1 -key NPAGE
 process p1 -key NPAGE
 process p1 -expect-text 0 0 "VBE.vcl1.s1.helddown"
 process p1 -screen_dump
 
+process p1 -key PPAGE
 process p1 -key PPAGE
 process p1 -expect-text 0 0 "VBE.vcl1.s1.happy"
 process p1 -screen_dump

include/tbl/debug_bits.h

@@ -52,6 +52,7 @@ DEBUG_BIT(PROCESSORS,		processors,	"Fetch/Deliver processors")
 DEBUG_BIT(PROTOCOL,		protocol,	"Protocol debugging")
 DEBUG_BIT(VCL_KEEP,		vcl_keep,	"Keep VCL C and so files")
 DEBUG_BIT(LCK,			lck,		"Additional lock statistics")
+DEBUG_BIT(PROXY_ERROR,		proxy_error,	"Proxy send error to backend")
 #undef DEBUG_BIT
 
 /*lint -restore */

include/tbl/sess_close.h

@@ -31,6 +31,10 @@
 
 /*lint -save -e525 -e539 */
 
+#ifdef SESS_CLOSE_C
+  #define SESS_CLOSE(nm, stat, err, desc) SESS_CLOSE_C(nm, stat, err, desc)
+#endif
+
 // stream_close_t	  sc_* stat	is_err	Description
 SESS_CLOSE(REM_CLOSE,	  rem_close,	0,	"Peer Closed")
 SESS_CLOSE(REQ_CLOSE,	  req_close,	0,	"Peer requested close")
@@ -40,18 +44,21 @@ SESS_CLOSE(RX_BODY,	  rx_body,	1,	"Failure receiving body")
 SESS_CLOSE(RX_JUNK,	  rx_junk,	1,	"Received junk data")
 SESS_CLOSE(RX_OVERFLOW,   rx_overflow,	1,	"Received buffer overflow")
 SESS_CLOSE(RX_TIMEOUT,	  rx_timeout,	1,	"Receive timeout")
-SESS_CLOSE(RX_CLOSE_IDLE, rx_close_idle,0,	"timeout_idle reached")
 SESS_CLOSE(TX_PIPE,	  tx_pipe,	0,	"Piped transaction")
 SESS_CLOSE(TX_ERROR,	  tx_error,	1,	"Error transaction")
 SESS_CLOSE(TX_EOF,	  tx_eof,	0,	"EOF transmission")
 SESS_CLOSE(RESP_CLOSE,	  resp_close,	0,	"Backend/VCL requested close")
 SESS_CLOSE(OVERLOAD,	  overload,	1,	"Out of some resource")
-SESS_CLOSE(PIPE_OVERFLOW, pipe_overflow,1,	"Session pipe overflow")
-SESS_CLOSE(RANGE_SHORT,   range_short,	1,	"Insufficient data for range")
-SESS_CLOSE(REQ_HTTP20,	  req_http20,	1,	"HTTP2 not accepted")
-SESS_CLOSE(VCL_FAILURE,	  vcl_failure,	1,	"VCL failure")
-SESS_CLOSE(RAPID_RESET,	  rapid_reset,  1,      "HTTP2 rapid reset")
-SESS_CLOSE(BANKRUPT,	  bankrupt,	1,      "HTTP2 credit bankruptcy")
+#ifdef SESS_CLOSE_C
+  SESS_CLOSE(RX_CLOSE_IDLE,	rx_close_idle,	0,	"timeout_idle reached")
+  SESS_CLOSE(PIPE_OVERFLOW,	pipe_overflow,	1,	"Session pipe overflow")
+  SESS_CLOSE(RANGE_SHORT,	range_short,	1,	"Insufficient data for range")
+  SESS_CLOSE(REQ_HTTP20,	req_http20,	1,	"HTTP2 not accepted")
+  SESS_CLOSE(VCL_FAILURE,	vcl_failure,	1,	"VCL failure")
+  SESS_CLOSE(RAPID_RESET,	rapid_reset,	1,	"HTTP2 rapid reset")
+  SESS_CLOSE(BANKRUPT,		bankrupt,	1,	"HTTP2 credit bankruptcy")
+  #undef SESS_CLOSE_C
+#endif
 #undef SESS_CLOSE
 
 /*lint -restore */