[master] e6f531bc0 Add missing bits of VRT_fail() handling during vcl_init {} / vcl_fini{}

[Nils Goroll]

commit e6f531bc0a82d0f143b050687fd08dbfd50b6575
Author: Nils Goroll <nils.goroll at uplex.de>
Date:   Wed Jan 20 12:15:21 2021 +0100

    Add missing bits of VRT_fail() handling during vcl_init {} / vcl_fini{}
    
    This change is based on the precondition that VRT_fail() should work
    wherever we have a VRT_CTX and DTRT, see also previous.
    
    on vcl_init {}
    --------------
    
    We already handled a "direct" VRT_fail() via a vmod function
    correctly.  This commit adds a test.
    
    Yet we can also VRT_fail() via a PRIV_TASK fini callback and did not
    handle that case (triggered an assertion in VRT_fail()). Notice that
    this case has worked in client / backend tasks for long and a test
    case has been added with 746384b20cbc24ff8afd2df35e1510087404fbf4 . It
    has now gained relevance with 43d9e5fb1a10a88ab6a5a98ad4038438025c4999
    
    on vcl_fini {}
    --------------
    
    By design, vcl_fini {} must not fail, which is also why the only valid
    return() value is "ok" (VCL_RET_OK).
    
    Consequently, we had
    
            if (method && *ctx->handling && *ctx->handling != VCL_RET_OK) {
                    assert(ev == VCL_EVENT_LOAD);
    
    in vcl_send_event().
    
    And then came VRT_fail().
    
    If we wanted to sustain an assertion similar to the above, we would
    need to require vmod authors to never call VRT_fail() from
    VCL_MET_FINI - which would complicate code, be likely overlooked and
    receive little to no test coverage.
    
    So instead we now ignore errors during vcl_fini {} and emit a
    VCL_error log line.
    
    I considered the alternative to check for VCL_MET_FINI in VRT_fail(),
    but decided to handle the exception where it applies, which is in
    vcl_send_event().
    
    I am aware that this part of the change may trigger some controversy
    and I am open to discussing alternatives. If anything, we now avoid
    unmotivated assertion failures triggered for the new tests in
    v00051.vtc for the time being.

diff --git a/bin/varnishd/cache/cache_vcl.c b/bin/varnishd/cache/cache_vcl.c
index 596a26966..abc41de2c 100644
--- a/bin/varnishd/cache/cache_vcl.c
+++ b/bin/varnishd/cache/cache_vcl.c
@@ -172,6 +172,39 @@ VCL_Rel_CliCtx(struct vrt_ctx **ctx)
 
 /*--------------------------------------------------------------------*/
 
+/* VRT_fail() can be called
+ * - from the vcl sub via a vmod
+ * - via a PRIV_TASK .fini callback
+ *
+ * if this happens during init, we fail it
+ * if during fini, we ignore, because otherwise VMOD authors would be forced to
+ * handle VCL_MET_FINI specifically everywhere.
+ */
+
+static int
+vcl_event_handling(VRT_CTX)
+{
+	CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
+
+	if (*ctx->handling == 0)
+		return (0);
+
+	assert(*ctx->handling == VCL_RET_FAIL);
+
+	if (ctx->method == VCL_MET_INIT)
+		return (1);
+
+	/*
+	 * EVENT_WARM / EVENT_COLD: method == 0
+	 * must not set handling
+	 */
+	assert(ctx->method == VCL_MET_FINI);
+
+	*ctx->handling = 0;
+	VRT_fail(ctx, "VRT_fail() from vcl_fini{} has no effect");
+	return (0);
+}
+
 static int
 vcl_send_event(struct vcl *vcl, enum vcl_event_e ev, struct vsb **msg)
 {
@@ -216,13 +249,7 @@ vcl_send_event(struct vcl *vcl, enum vcl_event_e ev, struct vsb **msg)
 	VCL_TaskEnter(cli_task_privs);
 	r = ctx->vcl->conf->event_vcl(ctx, ev);
 	VCL_TaskLeave(ctx, cli_task_privs);
-
-	/* if the warm event did not get to vcl_init, vcl_fini
-	 * won't be run, so handling may be zero */
-	if (method && *ctx->handling && *ctx->handling != VCL_RET_OK) {
-		assert(ev == VCL_EVENT_LOAD);
-		r = 1;
-	}
+	r |= vcl_event_handling(ctx);
 
 	*msg = VCL_Rel_CliCtx(&ctx);
 
diff --git a/bin/varnishtest/tests/v00051.vtc b/bin/varnishtest/tests/v00051.vtc
index 8948d76d5..913932146 100644
--- a/bin/varnishtest/tests/v00051.vtc
+++ b/bin/varnishtest/tests/v00051.vtc
@@ -488,3 +488,71 @@ varnish v1 -expect vcl_fail == 14
 varnish v1 -expect sc_vcl_failure == 11
 
 logexpect l1 -wait
+
+#######################################################################
+# Fail in vcl_init with direct VRT_fail()
+
+varnish v1 -errvcl {Forced failure} {
+	import debug;
+	backend proforma none;
+	sub vcl_init {
+		debug.fail();
+	}
+}
+
+#######################################################################
+# Fail in vcl_init via fini callback
+
+varnish v1 -errvcl {thou shalt not fini} {
+	import debug;
+	backend proforma none;
+	sub vcl_init {
+		debug.fail_task_fini();
+	}
+}
+
+#######################################################################
+# Fail in vcl_fini with direct VRT_fail()
+
+varnish v1 -vcl {
+	import debug;
+	backend proforma none;
+	sub vcl_fini {
+		debug.fail();
+	}
+}
+
+varnish v1 -vcl+backend {
+}
+
+logexpect l1 -v v1 -g raw {
+	expect * 0	CLI		"^Rd vcl.state vcl16 0cold"
+	expect 3 0	VCL_Error	"^Forced failure"
+	expect 0 0	VCL_Error	{^\QVRT_fail() from vcl_fini{} has no effect\E$}
+} -start
+
+varnish v1 -cliok "vcl.discard vcl16"
+logexpect l1 -wait
+
+#######################################################################
+# Fail in vcl_fini via fini callback - ignored but logged as VMOD BUG
+
+varnish v1 -vcl {
+	import debug;
+	backend proforma none;
+	sub vcl_fini {
+		debug.fail_task_fini();
+	}
+}
+
+varnish v1 -vcl+backend {
+}
+
+logexpect l1 -v v1 -g raw {
+	expect * 0	CLI		"^Rd vcl.state vcl18 0cold"
+	expect 3 0	VCL_Error	"^thou shalt not fini"
+	expect 0 0	VCL_Error	{^\QVRT_fail() from vcl_fini{} has no effect\E$}
+} -start
+
+varnish v1 -cliok "vcl.discard vcl18"
+logexpect l1 -wait