Consistent locking when logging to H2 session vsl

bin/varnishd/http2/cache_http2.h

@@ -274,3 +274,7 @@ task_func_t h2_do_req;
 #ifdef TRANSPORT_MAGIC
 vtr_req_fail_f h2_req_fail;
 #endif
+
+/* cache_http2_session.c */
+void
+H2S_Lock_VSLb(const struct h2_sess *, enum VSL_tag_e, const char *, ...);

bin/varnishd/http2/cache_http2_hpack.c

@@ -325,7 +325,7 @@ h2h_decode_hdr_fini(const struct h2_sess *h2)
 		    "HPACK compression error/fini (%s)", VHD_Error(d->vhd_ret));
 		ret = H2CE_COMPRESSION_ERROR;
 	} else if (d->error == NULL && !d->has_scheme) {
-		VSLb(h2->vsl, SLT_Debug, "Missing :scheme");
+		H2S_Lock_VSLb(h2, SLT_Debug, "Missing :scheme");
 		ret = H2SE_MISSING_SCHEME; //rfc7540,l,3087,3090
 	} else
 		ret = d->error;
@@ -377,7 +377,7 @@ h2h_decode_bytes(struct h2_sess *h2, const uint8_t *in, size_t in_l)
 		    d->out, d->out_l, &d->out_u);
 
 		if (d->vhd_ret < 0) {
-			VSLb(hp->vsl, SLT_BogoHeader,
+			H2S_Lock_VSLb(h2, SLT_BogoHeader,
 			    "HPACK compression error (%s)",
 			    VHD_Error(d->vhd_ret));
 			d->error = H2CE_COMPRESSION_ERROR;
@@ -449,7 +449,7 @@ h2h_decode_bytes(struct h2_sess *h2, const uint8_t *in, size_t in_l)
 	if (d->limit < 0) {
 		/* Fatal error, the client exceeded both http_req_size
 		 * and h2_max_header_list_size. */
-		VSLb(h2->vsl, SLT_SessError, "Header list too large");
+		H2S_Lock_VSLb(h2, SLT_SessError, "Header list too large");
 		return (H2CE_ENHANCE_YOUR_CALM);
 	}
 

bin/varnishd/http2/cache_http2_proto.c

@@ -232,11 +232,12 @@ h2_kill_req(struct worker *wrk, struct h2_sess *h2,
 		if (r2->cond != NULL)
 			PTOK(pthread_cond_signal(r2->cond));
 		r2 = NULL;
+		Lck_Unlock(&h2->sess->mtx);
 	} else {
+		Lck_Unlock(&h2->sess->mtx);
 		if (r2->state == H2_S_OPEN && h2->new_req == r2->req)
 			(void)h2h_decode_hdr_fini(h2);
 	}
-	Lck_Unlock(&h2->sess->mtx);
 	if (r2 != NULL)
 		h2_del_req(wrk, r2);
 }
@@ -356,9 +357,7 @@ h2_rapid_reset(struct worker *wrk, struct h2_sess *h2, struct h2_req *r2)
 	h2->last_rst = now;
 
 	if (h2->rst_budget < 1.0) {
-		Lck_Lock(&h2->sess->mtx);
-		VSLb(h2->vsl, SLT_Error, "H2: Hit RST limit. Closing session.");
-		Lck_Unlock(&h2->sess->mtx);
+		H2S_Lock_VSLb(h2, SLT_Error, "H2: Hit RST limit. Closing session.");
 		return (H2CE_RAPID_RESET);
 	}
 	h2->rst_budget -= 1.0;
@@ -398,9 +397,7 @@ h2_rx_goaway(struct worker *wrk, struct h2_sess *h2, struct h2_req *r2)
 	h2->goaway = 1;
 	h2->goaway_last_stream = vbe32dec(h2->rxf_data);
 	h2->error = h2_connectionerror(vbe32dec(h2->rxf_data + 4));
-	Lck_Lock(&h2->sess->mtx);
-	VSLb(h2->vsl, SLT_Debug, "GOAWAY %s", h2->error->name);
-	Lck_Unlock(&h2->sess->mtx);
+	H2S_Lock_VSLb(h2, SLT_Debug, "GOAWAY %s", h2->error->name);
 	return (h2->error);
 }
 
@@ -533,19 +530,15 @@ h2_set_setting(struct h2_sess *h2, const uint8_t *d)
 	y = vbe32dec(d + 2);
 	if (x >= H2_SETTING_TBL_LEN || h2_setting_tbl[x] == NULL) {
 		// rfc7540,l,2181,2182
-		Lck_Lock(&h2->sess->mtx);
-		VSLb(h2->vsl, SLT_Debug,
+		H2S_Lock_VSLb(h2, SLT_Debug,
 		    "H2SETTING unknown setting 0x%04x=%08x (ignored)", x, y);
-		Lck_Unlock(&h2->sess->mtx);
 		return (0);
 	}
 	s = h2_setting_tbl[x];
 	AN(s);
 	if (y < s->minval || y > s->maxval) {
-		Lck_Lock(&h2->sess->mtx);
-		VSLb(h2->vsl, SLT_Debug, "H2SETTING invalid %s=0x%08x",
+		H2S_Lock_VSLb(h2, SLT_Debug, "H2SETTING invalid %s=0x%08x",
 		    s->name, y);
-		Lck_Unlock(&h2->sess->mtx);
 		AN(s->range_error);
 		if (!DO_DEBUG(DBG_H2_NOCHECK))
 			return (s->range_error);
@@ -637,9 +630,7 @@ h2_end_headers(struct worker *wrk, struct h2_sess *h2,
 	h2e = h2h_decode_hdr_fini(h2);
 	h2->new_req = NULL;
 	if (h2e != NULL) {
-		Lck_Lock(&h2->sess->mtx);
-		VSLb(h2->vsl, SLT_Debug, "HPACK/FINI %s", h2e->name);
-		Lck_Unlock(&h2->sess->mtx);
+		H2S_Lock_VSLb(h2, SLT_Debug, "HPACK/FINI %s", h2e->name);
 		assert(!WS_IsReserved(r2->req->ws));
 		h2_del_req(wrk, r2);
 		return (h2e);
@@ -654,7 +645,7 @@ h2_end_headers(struct worker *wrk, struct h2_sess *h2,
 	cl = http_GetContentLength(req->http);
 	assert(cl >= -2);
 	if (cl == -2) {
-		VSLb(h2->vsl, SLT_Debug, "Non-parseable Content-Length");
+		H2S_Lock_VSLb(h2, SLT_Debug, "Non-parseable Content-Length");
 		return (H2SE_PROTOCOL_ERROR);
 	}
 
@@ -681,12 +672,12 @@ h2_end_headers(struct worker *wrk, struct h2_sess *h2,
 	}
 
 	if (req->http->hd[HTTP_HDR_METHOD].b == NULL) {
-		VSLb(h2->vsl, SLT_Debug, "Missing :method");
+		H2S_Lock_VSLb(h2, SLT_Debug, "Missing :method");
 		return (H2SE_PROTOCOL_ERROR); //rfc7540,l,3087,3090
 	}
 
 	if (req->http->hd[HTTP_HDR_URL].b == NULL) {
-		VSLb(h2->vsl, SLT_Debug, "Missing :path");
+		H2S_Lock_VSLb(h2, SLT_Debug, "Missing :path");
 		return (H2SE_PROTOCOL_ERROR); //rfc7540,l,3087,3090
 	}
 
@@ -695,7 +686,7 @@ h2_end_headers(struct worker *wrk, struct h2_sess *h2,
 	if (*req->http->hd[HTTP_HDR_URL].b == '*' &&
 	    (Tlen(req->http->hd[HTTP_HDR_METHOD]) != 7 ||
 	    strncmp(req->http->hd[HTTP_HDR_METHOD].b, "OPTIONS", 7))) {
-		VSLb(h2->vsl, SLT_BogoHeader, "Illegal :path pseudo-header");
+		H2S_Lock_VSLb(h2, SLT_BogoHeader, "Illegal :path pseudo-header");
 		return (H2SE_PROTOCOL_ERROR); //rfc7540,l,3068,3071
 	}
 
@@ -733,7 +724,7 @@ h2_rx_headers(struct worker *wrk, struct h2_sess *h2, struct h2_req *r2)
 		 */
 		if (h2->open_streams >=
 		    (int)h2->local_settings.max_concurrent_streams) {
-			VSLb(h2->vsl, SLT_Debug,
+			H2S_Lock_VSLb(h2, SLT_Debug,
 			     "H2: stream %u: Hit maximum number of "
 			     "concurrent streams", h2->rxf_stream);
 			return (H2SE_REFUSED_STREAM);	// rfc7540,l,1200,1205
@@ -785,9 +776,7 @@ h2_rx_headers(struct worker *wrk, struct h2_sess *h2, struct h2_req *r2)
 	}
 	h2e = h2h_decode_bytes(h2, p, l);
 	if (h2e != NULL) {
-		Lck_Lock(&h2->sess->mtx);
-		VSLb(h2->vsl, SLT_Debug, "HPACK(hdr) %s", h2e->name);
-		Lck_Unlock(&h2->sess->mtx);
+		H2S_Lock_VSLb(h2, SLT_Debug, "HPACK(hdr) %s", h2e->name);
 		(void)h2h_decode_hdr_fini(h2);
 		assert(!WS_IsReserved(r2->req->ws));
 		h2_del_req(wrk, r2);
@@ -820,9 +809,7 @@ h2_rx_continuation(struct worker *wrk, struct h2_sess *h2, struct h2_req *r2)
 	h2e = h2h_decode_bytes(h2, h2->rxf_data, h2->rxf_len);
 	r2->req->acct.req_hdrbytes += h2->rxf_len;
 	if (h2e != NULL) {
-		Lck_Lock(&h2->sess->mtx);
-		VSLb(h2->vsl, SLT_Debug, "HPACK(cont) %s", h2e->name);
-		Lck_Unlock(&h2->sess->mtx);
+		H2S_Lock_VSLb(h2, SLT_Debug, "HPACK(cont) %s", h2e->name);
 		(void)h2h_decode_hdr_fini(h2);
 		assert(!WS_IsReserved(r2->req->ws));
 		h2_del_req(wrk, r2);
@@ -1007,11 +994,11 @@ h2_rx_data(struct worker *wrk, struct h2_sess *h2, struct h2_req *r2)
 		stvbuf = STV_AllocBuf(wrk, stv_h2_rxbuf,
 		    bufsize + sizeof *rxbuf);
 		if (stvbuf == NULL) {
+			Lck_Lock(&h2->sess->mtx);
 			VSLb(h2->vsl, SLT_Debug,
 			    "H2: stream %u: Failed to allocate request body"
 			    " buffer",
 			    h2->rxf_stream);
-			Lck_Lock(&h2->sess->mtx);
 			r2->error = H2SE_INTERNAL_ERROR;
 			if (r2->cond)
 				PTOK(pthread_cond_signal(r2->cond));
@@ -1284,10 +1271,8 @@ h2_procframe(struct worker *wrk, struct h2_sess *h2, h2_frame h2f)
 		// rfc7540,l,1140,1145
 		// rfc7540,l,1153,1158
 		/* No even streams, we don't do PUSH_PROMISE */
-		Lck_Lock(&h2->sess->mtx);
-		VSLb(h2->vsl, SLT_Debug, "H2: illegal stream (=%u)",
+		H2S_Lock_VSLb(h2, SLT_Debug, "H2: illegal stream (=%u)",
 		    h2->rxf_stream);
-		Lck_Unlock(&h2->sess->mtx);
 		return (H2CE_PROTOCOL_ERROR);
 	}
 
@@ -1491,11 +1476,9 @@ h2_rxframe(struct worker *wrk, struct h2_sess *h2)
 		// rfc7540,l,679,681
 		// XXX: later, drain rest of frame
 		h2->bogosity++;
-		Lck_Lock(&h2->sess->mtx);
-		VSLb(h2->vsl, SLT_Debug,
+		H2S_Lock_VSLb(h2, SLT_Debug,
 		    "H2: Unknown frame type 0x%02x (ignored)",
 		    (uint8_t)h2->rxf_type);
-		Lck_Unlock(&h2->sess->mtx);
 		h2->srq->acct.req_bodybytes += h2->rxf_len;
 		return (1);
 	}
@@ -1509,11 +1492,9 @@ h2_rxframe(struct worker *wrk, struct h2_sess *h2)
 	if (h2->rxf_flags & ~h2f->flags) {
 		// rfc7540,l,687,688
 		h2->bogosity++;
-		Lck_Lock(&h2->sess->mtx);
-		VSLb(h2->vsl, SLT_Debug,
+		H2S_Lock_VSLb(h2, SLT_Debug,
 		    "H2: Unknown flags 0x%02x on %s (ignored)",
 		    (uint8_t)h2->rxf_flags & ~h2f->flags, h2f->name);
-		Lck_Unlock(&h2->sess->mtx);
 		h2->rxf_flags &= h2f->flags;
 	}
 

bin/varnishd/http2/cache_http2_send.c

@@ -209,7 +209,7 @@ H2_Send_Frame(struct worker *wrk, struct h2_sess *h2,
 	s = writev(h2->sess->fd, iov, len == 0 ? 1 : 2);
 	if (s != sizeof hdr + len) {
 		if (errno == EWOULDBLOCK) {
-			VSLb(h2->vsl, SLT_Debug,
+			H2S_Lock_VSLb(h2, SLT_Debug,
 			     "H2: stream %u: Hit idle_send_timeout", stream);
 		}
 		/*
@@ -414,9 +414,7 @@ H2_Send_RST(struct worker *wrk, struct h2_sess *h2, const struct h2_req *r2,
 	AN(H2_SEND_HELD(h2, r2));
 	AN(h2e);
 
-	Lck_Lock(&h2->sess->mtx);
-	VSLb(h2->vsl, SLT_Debug, "H2: stream %u: %s", stream, h2e->txt);
-	Lck_Unlock(&h2->sess->mtx);
+	H2S_Lock_VSLb(h2, SLT_Debug, "H2: stream %u: %s", stream, h2e->txt);
 	vbe32enc(b, h2e->val);
 
 	H2_Send_Frame(wrk, h2, H2_F_RST_STREAM, 0, sizeof b, stream, b);

bin/varnishd/http2/cache_http2_session.c

@@ -88,6 +88,30 @@ h2_local_settings(struct h2_settings *h2s)
 	h2s->max_header_list_size = cache_param->http_req_size;
 }
 
+void
+H2S_Lock_VSLb(const struct h2_sess *h2, enum VSL_tag_e tag, const char *fmt, ...)
+{
+	va_list ap;
+	int held = 0;
+
+	AN(h2);
+
+	if (VSL_tag_is_masked(tag))
+		return;
+
+	if (h2->highest_stream > 0) {
+		held = 1;
+		Lck_Lock(&h2->sess->mtx);
+	}
+
+	va_start(ap, fmt);
+	VSLbv(h2->vsl, tag, fmt, ap);
+	va_end(ap);
+
+	if (held)
+		Lck_Unlock(&h2->sess->mtx);
+}
+
 /**********************************************************************
  * The h2_sess struct needs many of the same things as a request,
  * WS, VSL, HTC &c,  but rather than implement all that stuff over, we
@@ -405,7 +429,7 @@ h2_new_session(struct worker *wrk, void *arg)
 	while (h2_rxframe(wrk, h2)) {
 		HTC_RxInit(h2->htc, h2->ws);
 		if (WS_Overflowed(h2->ws)) {
-			VSLb(h2->vsl, SLT_Debug, "H2: Empty Rx Workspace");
+			H2S_Lock_VSLb(h2, SLT_SessError, "H2: Empty Rx Workspace");
 			h2->error = H2CE_INTERNAL_ERROR;
 			break;
 		}
@@ -415,8 +439,8 @@ h2_new_session(struct worker *wrk, void *arg)
 	AN(h2->error);
 
 	/* Delete all idle streams */
-	VSLb(h2->vsl, SLT_Debug, "H2 CLEANUP %s", h2->error->name);
 	Lck_Lock(&h2->sess->mtx);
+	VSLb(h2->vsl, SLT_Debug, "H2 CLEANUP %s", h2->error->name);
 	VTAILQ_FOREACH(r2, &h2->streams, list) {
 		if (r2->error == 0)
 			r2->error = h2->error;