Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Make ctx->vsl not NULL in vcl_init #4046

Open
wants to merge 2 commits into
base: master
Choose a base branch
from
Open

Make ctx->vsl not NULL in vcl_init #4046

wants to merge 2 commits into from

Conversation

walid-git
Copy link
Member

This is a common source of panic when vmods functions/methods that log to vsl get called from housekeeping vcl subroutines.
We currently already have ctx->vsl set in vcl_fini, this will set it in vcl_init too.

@walid-git
vsl: Always flush the buffer outside of transactions
3e5b337 
A buffer with a zero wid is used as a convenience for
non transactional logs, no buffering is actually needed.
@walid-git
vrt_ctx: Make ctx->vsl not NULL in vcl_{init,fini}
0188b94 
This is a common source of panic when vmods functions/methods
logging to vsl get called from housekeeping vcl subroutines.

Refs varnishcache#2998
@nigoroll
Copy link
Member

nigoroll commented Jan 29, 2024 •
edited
Loading

My homework submission after bugwash:

I agree with the problem statement: VMOD functions/methods which could potentially be called from vcl_init{}, can not rely on using buffered VSL. Because most VMOD functions/methods could potentially be called from vcl_init{}, the generalization of this statement was that VMOD functions/methods could not use buffered VSL, unless they wrap VSL logging (which many VMODs do, arguably unnecessarily).

On the other hand, we need to motivate VMOD developers to produce meaningful CLI errors when vcl_init{} fails, and we have no VSL available when VCL is initially loaded.
Based on a little survey of the vmods on my laptop *1), I would conclude that

So I would propose:

  • Add VRT_failv(VRT_CTX, const char *restrict format, va_list ap)
  • Change VRT_fail[v]() to log to vsb with SLT_Error and / or vsl for every invocation (not just the first)
  • Add VRT_error[v]() to do the same, but not fail the VCL
  • Add ctx->vsl for all calls into VCL (including vcl_init{}, maybe similar to proposed here)
  • Rename ctx->msg to ctx->climsg get VMOD authors' attention, document that VRT_fail[v]() / VRT_error[v]() should be used for all error reporting (that is to say, no VSLx(..., SLT_Error) should be used in VMODs at all)

*1)

slink@haggis21:~/Devel/varnish-git$ grep -C 5 'ctx->msg' $(find . -name \*.[ch] | xargs grep -l -- 'ctx->msg' | grep -Ev 'varnish-cache|vtest|EOL|zlib')
./libvmod-soap/src/vmod_soap.c-	CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
./libvmod-soap/src/vmod_soap.c-	if (ctx->vsl != NULL) {
./libvmod-soap/src/vmod_soap.c-		xmlSetGenericErrorFunc(ctx->vsl, soap_vsl_generic_error);
./libvmod-soap/src/vmod_soap.c-		xmlSetStructuredErrorFunc(ctx->vsl, soap_vsl_structured_error);
./libvmod-soap/src/vmod_soap.c-	} else {
./libvmod-soap/src/vmod_soap.c:		AN(ctx->msg);
./libvmod-soap/src/vmod_soap.c:		xmlSetGenericErrorFunc(ctx->msg, soap_vsb_generic_error);
./libvmod-soap/src/vmod_soap.c:		xmlSetStructuredErrorFunc(ctx->msg, soap_vsb_structured_error);
./libvmod-soap/src/vmod_soap.c-	}
./libvmod-soap/src/vmod_soap.c-}
./libvmod-soap/src/vmod_soap.c-
./libvmod-soap/src/vmod_soap.c-struct VPFX(soap_parser) {
./libvmod-soap/src/vmod_soap.c-	unsigned			magic;
--
./libvmod-weightadjust/src/vmod_weightadjust.c-{
./libvmod-weightadjust/src/vmod_weightadjust.c-	va_list args;
./libvmod-weightadjust/src/vmod_weightadjust.c-
./libvmod-weightadjust/src/vmod_weightadjust.c-	va_start(args, fmt);
./libvmod-weightadjust/src/vmod_weightadjust.c-	if (ctx->method == VCL_MET_INIT) {
./libvmod-weightadjust/src/vmod_weightadjust.c:		AN(ctx->msg);
./libvmod-weightadjust/src/vmod_weightadjust.c:		VSB_vprintf(ctx->msg, fmt, args);
./libvmod-weightadjust/src/vmod_weightadjust.c-	}
./libvmod-weightadjust/src/vmod_weightadjust.c-	else if (ctx->vsl)
./libvmod-weightadjust/src/vmod_weightadjust.c-		VSLbv(ctx->vsl, SLT_VCL_Error, fmt, args);
./libvmod-weightadjust/src/vmod_weightadjust.c-	else
./libvmod-weightadjust/src/vmod_weightadjust.c-		/* Should this ever happen in vcl_fini() ... */
--
./libvmod-gcrypt/src/vmod_gcrypt.c-{
./libvmod-gcrypt/src/vmod_gcrypt.c-	va_list args;
./libvmod-gcrypt/src/vmod_gcrypt.c-
./libvmod-gcrypt/src/vmod_gcrypt.c-	va_start(args, fmt);
./libvmod-gcrypt/src/vmod_gcrypt.c-	if (ctx->method == VCL_MET_INIT) {
./libvmod-gcrypt/src/vmod_gcrypt.c:		AN(ctx->msg);
./libvmod-gcrypt/src/vmod_gcrypt.c:		VSB_vprintf(ctx->msg, fmt, args);
./libvmod-gcrypt/src/vmod_gcrypt.c-		VRT_fail(ctx, " ");
./libvmod-gcrypt/src/vmod_gcrypt.c-	}
./libvmod-gcrypt/src/vmod_gcrypt.c-	else if (ctx->vsl)
./libvmod-gcrypt/src/vmod_gcrypt.c-		VSLbv(ctx->vsl, SLT_VCL_Error, fmt, args);
./libvmod-gcrypt/src/vmod_gcrypt.c-	else
--
./libvmod-file/src/vmod_file.c-			rdr->flags |= RDR_WARMUP;
./libvmod-file/src/vmod_file.c-			rdr->flags &= ~(RDR_ERROR | RDR_DELETED);
./libvmod-file/src/vmod_file.c-
./libvmod-file/src/vmod_file.c-			errno = 0;
./libvmod-file/src/vmod_file.c-			if (timer_gettime(rdr->timerid, &timer) != 0) {
./libvmod-file/src/vmod_file.c:				VSB_printf(ctx->msg,
./libvmod-file/src/vmod_file.c-					   "vmod file: reading timer: %s",
./libvmod-file/src/vmod_file.c-					   VAS_errtxt(errno));
./libvmod-file/src/vmod_file.c-				return (-1);
./libvmod-file/src/vmod_file.c-			}
./libvmod-file/src/vmod_file.c-			timer.it_value.tv_sec = 0;
./libvmod-file/src/vmod_file.c-			timer.it_value.tv_nsec = 1;
./libvmod-file/src/vmod_file.c-			if (timer_settime(rdr->timerid, 0, &timer, NULL) != 0) {
./libvmod-file/src/vmod_file.c:				VSB_printf(ctx->msg,
./libvmod-file/src/vmod_file.c-					   "vmod file: restarting timer: %s",
./libvmod-file/src/vmod_file.c-					   VAS_errtxt(errno));
./libvmod-file/src/vmod_file.c-				return (-1);
./libvmod-file/src/vmod_file.c-			}
./libvmod-file/src/vmod_file.c-			VSL(SLT_Debug, NO_VXID, "vmod file: %s.%s: timer restarted",
--
./libvmod-file/src/vmod_file.c-				AZ(pthread_rwlock_unlock(rdr->lock));
./libvmod-file/src/vmod_file.c-			} while (flags & RDR_WARMUP);
./libvmod-file/src/vmod_file.c-
./libvmod-file/src/vmod_file.c-			if (rdr->flags & RDR_ERROR) {
./libvmod-file/src/vmod_file.c-				AN(strcmp(rdr->errbuf, NO_ERR));
./libvmod-file/src/vmod_file.c:				VSB_printf(ctx->msg, "vmod file: %s.%s: %s",
./libvmod-file/src/vmod_file.c-					   rdr->vcl_name, rdr->obj_name,
./libvmod-file/src/vmod_file.c-					   rdr->errbuf);
./libvmod-file/src/vmod_file.c-				return (-1);
./libvmod-file/src/vmod_file.c-			}
./libvmod-file/src/vmod_file.c-
--
./libvmod-querystring/src/vmod_querystring.c-	ALLOC_OBJ(qsf, QS_FILTER_MAGIC);
./libvmod-querystring/src/vmod_querystring.c-	AN(qsf);
./libvmod-querystring/src/vmod_querystring.c-
./libvmod-querystring/src/vmod_querystring.c-	qsf->ptr = VRE_compile(regex, 0, &error, &error_offset);
./libvmod-querystring/src/vmod_querystring.c-	if (qsf->ptr == NULL) {
./libvmod-querystring/src/vmod_querystring.c:		AN(ctx->msg);
./libvmod-querystring/src/vmod_querystring.c-		FREE_OBJ(qsf);
./libvmod-querystring/src/vmod_querystring.c:		msg_len = VSB_len(ctx->msg);
./libvmod-querystring/src/vmod_querystring.c-		VRT_fail(ctx,
./libvmod-querystring/src/vmod_querystring.c-		    "vmod-querystring: regex error (%s): '%s' pos %d",
./libvmod-querystring/src/vmod_querystring.c-		    error, regex, error_offset);
./libvmod-querystring/src/vmod_querystring.c-
./libvmod-querystring/src/vmod_querystring.c-		/* NB: VRT_fail may or may not pass the error message to the
./libvmod-querystring/src/vmod_querystring.c-		 * CLI, deal with it. */
./libvmod-querystring/src/vmod_querystring.c:		if (msg_len == VSB_len(ctx->msg))
./libvmod-querystring/src/vmod_querystring.c:			VSB_printf(ctx->msg, "vmod-querystring: "
./libvmod-querystring/src/vmod_querystring.c-			    "regex error (%s): '%s' pos %d\n",
./libvmod-querystring/src/vmod_querystring.c-			    error, regex, error_offset);
./libvmod-querystring/src/vmod_querystring.c-
./libvmod-querystring/src/vmod_querystring.c-		return;
./libvmod-querystring/src/vmod_querystring.c-	}
--
./libvmod-selector/src/vmod_selector.c-
./libvmod-selector/src/vmod_selector.c-	members = set->members;
./libvmod-selector/src/vmod_selector.c-	if (!set->case_sensitive)
./libvmod-selector/src/vmod_selector.c-		members = set->lomembers;
./libvmod-selector/src/vmod_selector.c-	if (members == NULL || set->nmembers == 0) {
./libvmod-selector/src/vmod_selector.c:		CHECK_OBJ_NOTNULL(ctx->msg, VSB_MAGIC);
./libvmod-selector/src/vmod_selector.c-		VSL(SLT_VCL_Error, NO_VXID, "VCL %s vmod selector %s%s: "
./libvmod-selector/src/vmod_selector.c-		    "no entries were added, nothing to compile, "
./libvmod-selector/src/vmod_selector.c-		    "%s.match() will always fail\n", VCL_Name(ctx->vcl),
./libvmod-selector/src/vmod_selector.c-		    set->vcl_name, method, set->vcl_name);
./libvmod-selector/src/vmod_selector.c-		return 0;
--
./libvmod-blobsha256/src/vmod_blobsha256.c-{
./libvmod-blobsha256/src/vmod_blobsha256.c-	va_list args;
./libvmod-blobsha256/src/vmod_blobsha256.c-
./libvmod-blobsha256/src/vmod_blobsha256.c-	va_start(args, fmt);
./libvmod-blobsha256/src/vmod_blobsha256.c-	if (ctx->method == VCL_MET_INIT) {
./libvmod-blobsha256/src/vmod_blobsha256.c:		AN(ctx->msg);
./libvmod-blobsha256/src/vmod_blobsha256.c:		VSB_vprintf(ctx->msg, fmt, args);
./libvmod-blobsha256/src/vmod_blobsha256.c-		VRT_handling(ctx, VCL_RET_FAIL);
./libvmod-blobsha256/src/vmod_blobsha256.c-	}
./libvmod-blobsha256/src/vmod_blobsha256.c-	else if (ctx->vsl)
./libvmod-blobsha256/src/vmod_blobsha256.c-		VSLbv(ctx->vsl, SLT_VCL_Error, fmt, args);
./libvmod-blobsha256/src/vmod_blobsha256.c-	else
--
./DataDome-VarnishDome-06ea2e42d2df9f00e3808a8341ad732dbd09c3b4/src/vmod_data_dome_shield.c-
./DataDome-VarnishDome-06ea2e42d2df9f00e3808a8341ad732dbd09c3b4/src/vmod_data_dome_shield.c-VCL_VOID
./DataDome-VarnishDome-06ea2e42d2df9f00e3808a8341ad732dbd09c3b4/src/vmod_data_dome_shield.c-vmod_init(VRT_CTX, struct vmod_priv *priv_top, VCL_BACKEND backend, VCL_STRING key)
./DataDome-VarnishDome-06ea2e42d2df9f00e3808a8341ad732dbd09c3b4/src/vmod_data_dome_shield.c-{
./DataDome-VarnishDome-06ea2e42d2df9f00e3808a8341ad732dbd09c3b4/src/vmod_data_dome_shield.c-  CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
./DataDome-VarnishDome-06ea2e42d2df9f00e3808a8341ad732dbd09c3b4/src/vmod_data_dome_shield.c:  AN(ctx->msg);
./DataDome-VarnishDome-06ea2e42d2df9f00e3808a8341ad732dbd09c3b4/src/vmod_data_dome_shield.c-  AN(priv_top);
./DataDome-VarnishDome-06ea2e42d2df9f00e3808a8341ad732dbd09c3b4/src/vmod_data_dome_shield.c-  AZ(priv_top->priv);
./DataDome-VarnishDome-06ea2e42d2df9f00e3808a8341ad732dbd09c3b4/src/vmod_data_dome_shield.c-
./DataDome-VarnishDome-06ea2e42d2df9f00e3808a8341ad732dbd09c3b4/src/vmod_data_dome_shield.c-  struct vmod_data_dome_shield_cfg *cfg;
./DataDome-VarnishDome-06ea2e42d2df9f00e3808a8341ad732dbd09c3b4/src/vmod_data_dome_shield.c-

@dridi
Copy link
Member

dridi commented Jan 30, 2024

./libvmod-querystring/src/vmod_querystring.c- /* NB: VRT_fail may or may not pass the error message to the
./libvmod-querystring/src/vmod_querystring.c- * CLI, deal with it. */

Taking this as an example is a little bit unfair, because vmod_querystring supports Varnish versions both before and after this was formalized.

If I decided to target supported branches only this hack would go away.

@nigoroll
Copy link
Member

Taking this as an example is a little bit unfair

Maybe I have not expressed my intend clearly enough, but I only took your code as an example for the need to log the error messages from all invocations, not just the first.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@walid-git @nigoroll @dridi