<div dir="ltr">Lasse,<div><br></div><div>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.</div>
<div><br></div><div>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.</div>
<div><div><br></div><div style>- Leif</div><div style><br></div><div style>(PS. I'm a long-time user, but until now I've only been lurking on the list. Hi, all.)</div></div></div><div class="gmail_extra"><br><br>
<div class="gmail_quote">
On Thu, Feb 14, 2013 at 9:51 AM, Lasse Karstensen <span dir="ltr"><<a href="mailto:lkarsten@varnish-software.com" target="_blank">lkarsten@varnish-software.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Hello.<br>
<br>
A long standing todo item of ours (VS) is that we should make some sort<br>
of VCL debugger or execution tracer.<br>
<br>
Many new users find it difficult to read the verbose output of varnishlog, and<br>
some hand-holding might be in place.<br>
<br>
I've been looking at the VCL trace function, which is a varnish parameter to enable<br>
log lines in varnishlog. The output says that the execution is now on line x<br>
char y of the VCL line, logged whenever there is a function call.<br>
In our experience, this feature is rarely or never used.<br>
<br>
My thinking is that this VCL_trace can be extended to log the previous and new<br>
value whenever an assignment is done in VCL. This would enable us to write<br>
software that takes the VCL and varnishlog as inputs, and let the user step<br>
through the VCL execution and see what the different headers/values are at each<br>
step.<br>
<br>
I think this should be possible to turn on per request in addition to the<br>
Varnish wide parameter it is now. This enables us to do "online debugging"; a<br>
Varnish user is having trouble with a distinct URL and can input that into the<br>
tool and have it run just once without affecting other requests or site<br>
performance.<br>
<br>
>From a VCL perspective it can look like this:<br>
<br>
5 sub vcl_recv {<br>
6 if (req.http.x-trace-request == "yes")<br>
7 {<br>
8 set req.trace = true; <br>
9 }<br>
10 set req.http.x-tmp = "foo";<br>
11 set req.http.x-tmp = "bar";<br>
12 }<br>
<br>
The obvious drawback is of course that any VCL executed before this won't get<br>
trace information. I think this can be accepted in this case.<br>
<br>
In the shmlog the output can be:<br>
<br>
11 RxHeader c Host: localhost<br>
11 RxHeader c User-Agent: lwp-request/6.03 libwww-perl/6.04<br>
11 VCL_ValueTrace c 13 10.13 "<undef>" "foo"<br>
11 VCL_ValueTrace c 14 11.13 "foo" "bar"<br>
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<br>
11 VCL_call c hash 15 85.5<br>
11 Hash c /<br>
11 VCL_trace c 16 87.9<br>
11 Hash c localhost<br>
<br>
<br>
Implementation wise this can be done via a small patch to VRT_SetHdr(), which<br>
check if tracing is on and writes VCL_ValueTrace to VSL. There must be a<br>
flag somewhere (struct req?) that indicates if this connection/session has<br>
tracing set to true.<br>
<br>
<br>
I think this should be a fairly quick win, little effort needed to get great<br>
debugging value out of. I can prepare a patch if there is consensus on how to<br>
proceed.<br>
<br>
Any input is appreciated.<br>
<span class="HOEnZb"><font color="#888888"><br>
--<br>
With regards,<br>
Lasse Karstensen<br>
Varnish Software AS<br>
<br>
_______________________________________________<br>
varnish-dev mailing list<br>
<a href="mailto:varnish-dev@varnish-cache.org">varnish-dev@varnish-cache.org</a><br>
<a href="https://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev" target="_blank">https://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev</a><br>
</font></span></blockquote></div><br><br clear="all"><div><br></div>-- <br>
<p>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.</p>
<p><a href="http://bilbo.hobbiton.org/wiki/Eat_My_Sig" target="_blank">http://bilbo.hobbiton.org/wiki/Eat_My_Sig</a></p>
</div>