Extending vcl_trace to log VCL value assignments

[Leif Pedersen]

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-dev/attachments/20130214/fbe61e36/attachment.html>