Logging is impossible in `vcl_init`: Assert error in WS_Assert(), cache/cache_ws.c #1924

Closed
kamermans opened this Issue Apr 25, 2016 · 6 comments

Projects

None yet

6 participants

@kamermans
kamermans commented Apr 25, 2016 edited

In previous versions of varnish, std.log and std.syslog were available in vcl_init. At some point this stopped working and is problematic because I am initializing other vmods in vcl_init. If there is a problem with one of those vmods, I need to be able to log that event. In Varnish 3.x I would use panic to kill the entire system, but that was removed in 4.x, so then I would resort to logging the problem. It is worth noting that in my code, std.log was only invoked if a vmod returned an error code, and I cannot confirm that this has ever happened until today, so it's possible that logging from init has never worked in 4.x.

Expected Behavior

Log message is sent to VSL.

Current Behavior

Varnish core-dumps with the following output:

root@52dca29ac81c:/u/apps/site/docker/varnish# varnishd -F -f /tmp/test.vcl
Debug: Platform: Linux,4.2.0-35-generic,x86_64,-junix,-smalloc,-smalloc,-hcritbit

Debug: Child (28) Started
CLI result = 400
Error: Child (28) Pushing vcls failed:
CLI communication error (hdr)
Debug: Stopping Child
Error: Child (28) died signal=6 (core dumped)
Error: Child (28) Last panic at: Mon, 25 Apr 2016 17:57:47 GMT
"Assert error in WS_Assert(), cache/cache_ws.c line 41:
  Condition((ws) != NULL) not true.
thread = (cache-main)
version = varnish-4.1.2 revision 0d7404e
ident = Linux,4.2.0-35-generic,x86_64,-junix,-smalloc,-smalloc,-hcritbit,epoll
Backtrace:
  0x433976: varnishd() [0x433976]
  0x44a58b: varnishd(WS_Assert+0x16b) [0x44a58b]
  0x44ac50: varnishd(WS_Reserve+0x10) [0x44ac50]
  0x7f911f9f8420: libvmod_std.so(vmod_log+0x80) [0x7f911f9f8420]
  0x7f91218efcf7: vgc.so(VGC_function_vcl_init+0x37) [0x7f91218efcf7]
  0x7f91218f01e2: vgc.so(+0x21e2) [0x7f91218f01e2]
  0x43ebd1: varnishd() [0x43ebd1]
  0x7f912e8e15c1: libvarnish.so(+0x65c1) [0x7f912e8e15c1]
  0x7f912e8e19fb: libvarnish.so(+0x69fb) [0x7f912e8e19fb]
  0x7f912e8e6ce8: libvarnish.so(VLU_Fd+0xd8) [0x7f912e8e6ce8]

"
Could not create _.vsm.18: File exists

Possible Solution

Either document that std.log and std.syslog cannot be used in vcl_init, or implement them.
For bonus points, reintroduce panic so we can intentionally crash Varnish if a vmod has no chance of working :)

Steps to Reproduce (for bugs)

Step 1. Create test.vcl:

vcl 4.0;

import std;

backend backend_test {
    .host = "localhost";
    .port = "8080";
}

sub vcl_init {
    std.log("test");
}

Step 2. Run varnishd -F -f /tmp/test.vcl

Context

We use the WURFL InFuze for Varnish-Cache module. This module required rather complex configuration at init time, and could fail for various legitimate reasons, so code like this is common in vcl_init:

wurfl.load();
if (wurfl.error()) {
    std.log(wurfl.error());

    # TODO: Varnish 4.x does not support panic
    #panic wurfl.error();
}

Your Environment

Tested in Ubuntu 14.04 with Varnish 4.0.3 and 4.1.2 from the Varnish Ubuntu repo.

@kamermans

Nice, thanks @rezan!

@fgsch
Member
fgsch commented Apr 25, 2016 edited

We should not crash though.

Should we consider something like this (untested)?

diff --git a/lib/libvmod_std/vmod_std.c b/lib/libvmod_std/vmod_std.c
index 1a8f56b..43f257d 100644
--- a/lib/libvmod_std/vmod_std.c
+++ b/lib/libvmod_std/vmod_std.c
@@ -139,17 +139,20 @@ vmod_log(VRT_CTX, const char *fmt, ...)
    txt t;

    CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
-   u = WS_Reserve(ctx->ws, 0);
-   t.b = ctx->ws->f;
    va_start(ap, fmt);
-   t.e = VRT_StringList(ctx->ws->f, u, fmt, ap);
+   if (ctx->vsl != NULL) {
+       u = WS_Reserve(ctx->ws, 0);
+       t.b = ctx->ws->f;
+       t.e = VRT_StringList(ctx->ws->f, u, fmt, ap);
+       if (t.e != NULL) {
+           assert(t.e > t.b);
+           t.e--;
+           VSLbt(ctx->vsl, SLT_VCL_Log, t);
+       }
+       WS_Release(ctx->ws, 0);
+   } else
+       VSL(SLT_VCL_Log, 0, fmt, ap);
    va_end(ap);
-   if (t.e != NULL) {
-       assert(t.e > t.b);
-       t.e--;
-       VSLbt(ctx->vsl, SLT_VCL_Log, t);
-   }
-   WS_Release(ctx->ws, 0);
 }

 VCL_VOID __match_proto__(td_std_syslog)
@fgsch
Member
fgsch commented Apr 26, 2016

@Dridi For other cases, yes. For std.log() I don't think we should artificially limit it to specific subroutines.

@Dridi
Member
Dridi commented Apr 26, 2016

In this case I'd put an ASSERT_CLI in the else block. Otherwise LGTM

@fgsch fgsch self-assigned this May 4, 2016
@fgsch fgsch added a commit that closed this issue May 16, 2016
@fgsch fgsch Make std.log() work from vcl_{init,fini}
Fixes #1924.
dad7f7d
@fgsch fgsch closed this in dad7f7d May 16, 2016
@fgsch fgsch added a commit that referenced this issue May 16, 2016
@fgsch fgsch Make std.syslog() work from vcl_{init,fini}
Related to #1924.
3740956
@lkarsten lkarsten pushed a commit that referenced this issue Jun 14, 2016
@fgsch fgsch + Lasse Karstensen Make std.log() work from vcl_{init,fini}
Fixes #1924.
8f465d3
@lkarsten lkarsten pushed a commit that referenced this issue Jun 14, 2016
@fgsch fgsch + Lasse Karstensen Make std.syslog() work from vcl_{init,fini}
Related to #1924.
962fe5a
@lkarsten lkarsten pushed a commit that referenced this issue Jun 14, 2016
Lasse Karstensen Add #1924 to changelog.
Ref: #1924
a8d3f1d
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment