<div dir="ltr">Sounds useful. I have a few things to add.<div><br></div><div style>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".</div>
<div style><br></div><div style>Then we can have all sorts of other fun tracing info in the same tag.</div><div style><br></div><div style>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>.</div>
<div style><br></div><div style>For those wondering wtf I mean by that:</div><div style><br></div><div style>char *mystring = NULL;</div><div style><br></div><div style>vs</div><div style><br></div><div style>char *mystring = "NULL";</div>
<div style><br></div><div style>3) While you're at it, results of if-statements would be nice, possibly with the values of all variable involved.</div><div style><br></div><div style>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. </div>
<div style><br></div><div style>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.</div>
<div style><br></div><div style>I would suggest adding it, and making it default to "on", with the caveats and benefits of turning it off clearly described.</div><div style><br></div><div style>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.</div>
<div style><br></div><div style>Cheers,</div><div style><br></div><div style> Doc</div></div><div class="gmail_extra"><br><br><div class="gmail_quote">On Thu, Feb 14, 2013 at 6:29 PM, Leif Pedersen <span dir="ltr"><<a href="mailto:bilbo@hobbiton.org" target="_blank">bilbo@hobbiton.org</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><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>- Leif</div><div><br></div><div>(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"><div><div class="h5"><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><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" target="_blank">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></div></div><span class="HOEnZb"><font color="#888888">-- <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>
</font></span></div>
<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></blockquote></div><br></div>