vca: Log the outcome of sockopt inheritance

bin/varnishd/cache/cache_acceptor.c

@@ -234,15 +234,27 @@ vca_sock_opt_test(const struct listen_sock *ls, const struct sess *sp)
 	for (n = 0; n < n_sock_opts; n++) {
 		so = &sock_opts[n];
 		ch = &ls->conn_heritage[n];
-		if (ch->sess_set)
-			continue; /* Already set, no need to retest */
-		if (so->level == IPPROTO_TCP && ls->uds)
+		if (ch->sess_set) {
+			VSL(SLT_Debug, sp->vxid,
+			    "sockopt: Not testing nonhereditary %s for %s=%s",
+			    so->strname, ls->name, ls->endpoint);
 			continue;
+		}
+		if (so->level == IPPROTO_TCP && ls->uds) {
+			VSL(SLT_Debug, sp->vxid,
+			    "sockopt: Not testing incompatible %s for %s=%s",
+			    so->strname, ls->name, ls->endpoint);
+			continue;
+		}
 		memset(&tmp, 0, sizeof tmp);
 		l = so->sz;
 		i = getsockopt(sp->fd, so->level, so->optname, &tmp, &l);
-		if (i == 0 && memcmp(&tmp, so->arg, so->sz))
+		if (i == 0 && memcmp(&tmp, so->arg, so->sz)) {
+			VSL(SLT_Debug, sp->vxid,
+			    "sockopt: Test confirmed %s non heredity for %s=%s",
+			    so->strname, ls->name, ls->endpoint);
 			ch->sess_set = 1;
+		}
 		if (i && errno != ENOPROTOOPT)
 			VTCP_Assert(i);
 	}
@@ -253,21 +265,44 @@ vca_sock_opt_set(const struct listen_sock *ls, const struct sess *sp)
 {
 	struct conn_heritage *ch;
 	struct sock_opt *so;
+	unsigned vxid;
 	int n, sock;
 
 	CHECK_OBJ_NOTNULL(ls, LISTEN_SOCK_MAGIC);
-	CHECK_OBJ_ORNULL(sp, SESS_MAGIC);
-	sock = sp != NULL ? sp->fd : ls->sock;
+
+	if (sp != NULL) {
+		CHECK_OBJ(sp, SESS_MAGIC);
+		sock = sp->fd;
+		vxid = sp->vxid;
+	} else {
+		sock = ls->sock;
+		vxid = 0;
+	}
 
 	for (n = 0; n < n_sock_opts; n++) {
 		so = &sock_opts[n];
 		ch = &ls->conn_heritage[n];
-		if (so->level == IPPROTO_TCP && ls->uds)
+		if (so->level == IPPROTO_TCP && ls->uds) {
+			VSL(SLT_Debug, vxid,
+			    "sockopt: Not setting incompatible %s for %s=%s",
+			    so->strname, ls->name, ls->endpoint);
 			continue;
-		if (sp == NULL && ch->listen_mod == so->mod)
+		}
+		if (sp == NULL && ch->listen_mod == so->mod) {
+			VSL(SLT_Debug, vxid,
+			    "sockopt: Not setting unmodified %s for %s=%s",
+			    so->strname, ls->name, ls->endpoint);
 			continue;
-		if  (sp != NULL && !ch->sess_set)
+		}
+		if  (sp != NULL && !ch->sess_set) {
+			VSL(SLT_Debug, sp->vxid,
+			    "sockopt: %s may be inherited for %s=%s",
+			    so->strname, ls->name, ls->endpoint);
 			continue;
+		}
+		VSL(SLT_Debug, vxid,
+		    "sockopt: Setting %s for %s=%s",
+		    so->strname, ls->name, ls->endpoint);
 		VTCP_Assert(setsockopt(sock,
 		    so->level, so->optname, so->arg, so->sz));
 		if (sp == NULL)

bin/varnishtest/tests/l00000.vtc

@@ -11,7 +11,7 @@ varnish v1 -vcl+backend {
 logexpect l1 -v v1 -g session {
 	expect 0 1000	Begin		sess
 	expect 0 =	SessOpen
-	expect 0 =	Link		"req 1001"
+	expect * =	Link		"req 1001"
 	expect 0 =	SessClose
 	expect 0 =	End
 

bin/varnishtest/tests/r01804.vtc

@@ -9,15 +9,11 @@ server s1 {
 varnish v1 -arg "-afoo=127.0.0.1:0,PROXY" -vcl+backend {
 } -start
 
-logexpect l1 -v v1 -d 0 -g session {
-	expect * *	Begin	{^sess .* PROXY$}
-	expect * =	SessOpen	{^.* foo .*}
+logexpect l1 -v v1 -g session {
+	expect * 1000	Begin		{^sess .* PROXY$}
+	expect 0 =	SessOpen	{^.* foo .*}
 	expect * =	Proxy		{^1 }
-	expect * *	Begin	{^req}
-	expect * *	Begin	{^sess .* PROXY$}
-	expect * =	SessOpen	{^.* foo .*}
-	expect * =	Proxy	{^2 }
-	expect * *	Begin	{^req}
+	expect * 1001	Begin		{^req}
 } -start
 
 client c1 {
@@ -26,6 +22,15 @@ client c1 {
 	rxresp
 } -run
 
+logexpect l1 -wait
+
+logexpect l2 -v v1 -g session {
+	expect * 1003	Begin		{^sess .* PROXY$}
+	expect 0 =	SessOpen	{^.* foo .*}
+	expect * =	Proxy		{^2 }
+	expect * 1004	Begin		{^req}
+} -start
+
 client c2 {
 	# good IPv4
 	sendhex "0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a"
@@ -38,4 +43,4 @@ client c2 {
 	rxresp
 } -run
 
-logexpect l1 -wait
+logexpect l2 -wait

bin/varnishtest/tests/r02722.vtc

@@ -9,7 +9,7 @@ server s0 {
         txresp
 } -dispatch
 
-varnish v1 -arg {-a :0 -a "${tmpdir}/v1.sock"}
+varnish v1 -arg {-a TCP=:0 -a "UDS=${tmpdir}/v1.sock"}
 varnish v1 -cliok "param.set debug +flush_head"
 varnish v1 -cliok "param.set timeout_idle 1"
 varnish v1 -vcl+backend { } -start