nigoroll
commented
5 months ago 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
- we need a way to report also non-fatal errors to the CLI
- both this new interface and
VRT_fail()need to work everywhere in VCL-callable VMOD code VRT_fail()should log, even if the VCL has already failed.- we should have v(a_list) variants of both interfaces
So I would propose:
- Add
VRT_failv(VRT_CTX, const char *restrict format, va_list ap) - Change
VRT_fail[v]()to log to vsb withSLT_Errorand / or vsl for every invocation (not just the first) - Add
VRT_error[v]()to do the same, but not fail the VCL - Add
ctx->vslfor all calls into VCL (includingvcl_init{}, maybe similar to proposed here) - Rename
ctx->msgtoctx->climsgget VMOD authors' attention, document thatVRT_fail[v]()/VRT_error[v]()should be used for all error reporting (that is to say, noVSLx(..., 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
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->vslset invcl_fini, this will set it invcl_inittoo.