Extending vcl_trace to log VCL value assignments

Rogier 'DocWilco' Mulhuijzen varnish at bsdchicks.com
Mon Feb 18 12:21:36 CET 2013


Sounds useful. I have a few things to add.

1) We probably shouldn't exhaust VSL tags too fast, so I'd suggest using
either VCL_trace, or VCL_trace_ext(ended), and then putting a keyword at
the front, like "value" or "assign".

Then we can have all sorts of other fun tracing info in the same tag.

2) If there's no value, don't put <undef> between quotes, but put <undef>
on its own. That way it's very clear that it's undefined, instead of a
string that happens to be the characters <undef>.

For those wondering wtf I mean by that:

char *mystring = NULL;

vs

char *mystring = "NULL";

3) While you're at it, results of if-statements would be nice, possibly
with the values of all variable involved.

4) In our private fork, we've added a parameter to influence the compiling
of VCL (well, a few, but I digress) so that based on the parameter, calls
to VRT_trace are added or not. It's called vcl_trace_support.

The reason we put it in is that calls to VCL_trace, as short as they may be
with tracing disabled, were so numerous that they were eating up a lot of
CPU time. If you're adding more VCL tracing functions to VRT, this wastage
only increases.

I would suggest adding it, and making it default to "on", with the caveats
and benefits of turning it off clearly described.

To turn on tracing, one would simply have to reload the VCL after switching
the support back on. But people new to Varnish might have trouble with
that, hence defaulting to on.

Cheers,

      Doc


On Thu, Feb 14, 2013 at 6:29 PM, Leif Pedersen <bilbo at hobbiton.org> wrote:

> Lasse,
>
> This sounds pretty useful. I do a lot of work with VCL and I can usually
> track what's happened pretty easily, but when my coworkers have to look
> through it, they tend to get lost since their focus is on other parts of
> our servers. This could really help them trace what's going on in the VCL
> code that I write.
>
> I have a suggestion. How about emitting an explicit log message when
> tracing is enabled or disabled? This way a log processor can quickly
> identify a request when it turns on tracing and automatically filter only
> those from the log to display.
>
> - Leif
>
> (PS. I'm a long-time user, but until now I've only been lurking on the
> list. Hi, all.)
>
>
>  On Thu, Feb 14, 2013 at 9:51 AM, Lasse Karstensen <
> lkarsten at varnish-software.com> wrote:
>
>> Hello.
>>
>> A long standing todo item of ours (VS) is that we should make some sort
>> of VCL debugger or execution tracer.
>>
>> Many new users find it difficult to read the verbose output of
>> varnishlog, and
>> some hand-holding might be in place.
>>
>> I've been looking at the VCL trace function, which is a varnish parameter
>> to enable
>> log lines in varnishlog. The output says that the execution is now on
>> line x
>> char y of the VCL line, logged whenever there is a function call.
>> In our experience, this feature is rarely or never used.
>>
>> My thinking is that this VCL_trace can be extended to log the previous
>> and new
>> value whenever an assignment is done in VCL. This would enable us to write
>> software that takes the VCL and varnishlog as inputs, and let the user
>> step
>> through the VCL execution and see what the different headers/values are
>> at each
>> step.
>>
>> I think this should be possible to turn on per request in addition to the
>> Varnish wide parameter it is now. This enables us to do "online
>> debugging"; a
>> Varnish user is having trouble with a distinct URL and can input that
>> into the
>> tool and have it run just once without affecting other requests or site
>> performance.
>>
>> From a VCL perspective it can look like this:
>>
>> 5       sub vcl_recv {
>> 6           if (req.http.x-trace-request == "yes")
>> 7           {
>> 8               set req.trace = true;
>> 9           }
>> 10          set req.http.x-tmp = "foo";
>> 11          set req.http.x-tmp = "bar";
>> 12      }
>>
>> The obvious drawback is of course that any VCL executed before this won't
>> get
>> trace information. I think this can be accepted in this case.
>>
>> In the shmlog the output can be:
>>
>>    11 RxHeader     c Host: localhost
>>    11 RxHeader     c User-Agent: lwp-request/6.03 libwww-perl/6.04
>>    11 VCL_ValueTrace c 13 10.13 "<undef>" "foo"
>>    11 VCL_ValueTrace c 14 11.13 "foo" "bar"
>>    11 VCL_call     c recv 1 42.5 2 41.5 3 42.9 5 46.13 6 49.5 8 59.5 10
>> 63.5 12 67.5 lookup
>>    11 VCL_call     c hash 15 85.5
>>    11 Hash         c /
>>    11 VCL_trace    c 16 87.9
>>    11 Hash         c localhost
>>
>>
>> Implementation wise this can be done via a small patch to VRT_SetHdr(),
>> which
>> check if tracing is on and writes VCL_ValueTrace to VSL. There must be a
>> flag somewhere (struct req?) that indicates if this connection/session has
>> tracing set to true.
>>
>>
>> I think this should be a fairly quick win, little effort needed to get
>> great
>> debugging value out of. I can prepare a patch if there is consensus on
>> how to
>> proceed.
>>
>> Any input is appreciated.
>>
>> --
>> With regards,
>> Lasse Karstensen
>> Varnish Software AS
>>
>> _______________________________________________
>> varnish-dev mailing list
>> varnish-dev at varnish-cache.org
>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev
>>
>
>
>
> --
>
> As implied by email protocols, the information in this message is
> not confidential.  Any middle-man or recipient may inspect, modify,
> copy, forward, reply to, delete, or filter email for any purpose unless
> said parties are otherwise obligated.  As the sender, I acknowledge that
> I have a lower expectation of the control and privacy of this message
> than I would a post-card.  Further, nothing in this message is
> legally binding without cryptographic evidence of its integrity.
>
> http://bilbo.hobbiton.org/wiki/Eat_My_Sig
>
> _______________________________________________
> varnish-dev mailing list
> varnish-dev at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-dev/attachments/20130218/c094bb6a/attachment.html>


More information about the varnish-dev mailing list