Extending vcl_trace to log VCL value assignments

[Lasse Karstensen]

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