<div dir="ltr">Hiya all!<div><br></div><div>I've been trying to implement an abtest engine on my varnish. The problem I've come across is related to the manipulation of the original req.url property.</div><div><br></div><div>What I'm experiencing is that when setting a new "req.url" value and after forcing a restart(), the URL that varnishncsa uses to log is just the one it has set when it re-enters recv flow, but not the one it uses from the backend or the last req.URL object either (which will even have much more sense since).</div><div><br></div><div>I've made a sample snippet of what I observe just for the sake of reproducing it and to take away all the abtest logic that may be just confusing.</div><div><br></div><blockquote style="margin:0 0 0 40px;border:none;padding:0px"><div>vcl 4.1;</div><div>backend default {</div><div> .host = "127.0.0.1";</div><div> .port = "8000";</div><div>}</div><div><br></div><div>sub vcl_recv {</div><div>  if (req.restarts == 0) {</div><div>    set req.http.X-Original-URL = req.url;</div><div>    set req.url = "/this_url_does_not_exist";</div><div>    return(restart);</div><div>  }</div><div>  else {</div><div>    #restore original URL</div><div>    set req.url = req.http.X-Original-URL;</div><div>  }</div><div>}</div><div><br></div></blockquote>That vcl just sets an alternative req.url and triggers a flow restart.<div>varnishncsa logs this entry <br></div><div><div><blockquote style="margin:0 0 0 40px;border:none;padding:0px"><div>::1 - - [29/Sep/2020:16:49:08 -0300] "GET <a href="http://localhost:6081/this_url_does_not_exist">http://localhost:6081/this_url_does_not_exist</a> HTTP/1.1" 200 12 "-" "curl/7.72.0"</div></blockquote><div><br></div>Of course that URL does not exist, but since its using the req.URL object from which varnish recv flow started, it just keeps that for logging, and not any later req.URL set.</div></div><div><br></div><div>Here attached is the varnishlog output from a fresh start:</div><div><blockquote style="margin:0 0 0 40px;border:none;padding:0px"><div>*   << Request  >> 2<br>-   Begin          req 1 rxreq<br>-   Timestamp      Start: 1601409664.461391 0.000000 0.000000<br>-   Timestamp      Req: 1601409664.461391 0.000000 0.000000<br>-   VCL_use        boot<br>-   ReqStart       ::1 55180 a0<br>-   ReqMethod      GET<br>-   ReqURL         /this_object_exists<br>-   ReqProtocol    HTTP/1.1<br>-   ReqHeader      Host: localhost:6081<br>-   ReqHeader      User-Agent: curl/7.72.0<br>-   ReqHeader      Accept: */*<br>-   ReqHeader      X-Forwarded-For: ::1<br>-   VCL_call       RECV<br>-   ReqHeader      X-Original-URL: /this_object_exists<br>-   ReqURL         /this_url_does_not_exist<br>-   VCL_return     restart<br>-   VCL_call       HASH<br>-   VCL_return     lookup<br>-   Timestamp      Restart: 1601409664.461429 0.000037 0.000037<br>-   Link           req 3 restart<br>-   End<br><br>*   << BeReq    >> 4<br>-   Begin          bereq 3 fetch<br>-   VCL_use        boot<br>-   Timestamp      Start: 1601409664.461553 0.000000 0.000000<br>-   BereqMethod    GET<br>-   BereqURL       /this_object_exists<br>-   BereqProtocol  HTTP/1.1<br>-   BereqHeader    User-Agent: curl/7.72.0<br>-   BereqHeader    Accept: */*<br>-   BereqHeader    X-Forwarded-For: ::1<br>-   BereqHeader    host: localhost:6081<br>-   BereqHeader    Accept-Encoding: gzip<br>-   BereqHeader    X-Varnish: 4<br>-   VCL_call       BACKEND_FETCH<br>-   VCL_return     fetch<br>-   BackendOpen    26 default 127.0.0.1 8000 127.0.0.1 59480 connect<br>-   Timestamp      Bereq: 1601409664.462196 0.000642 0.000642<br>-   Timestamp      Beresp: 1601409664.463115 0.001561 0.000918<br>-   BerespProtocol HTTP/1.0<br>-   BerespStatus   200<br>-   BerespReason   OK<br>-   BerespHeader   Server: SimpleHTTP/0.6 Python/3.8.6<br>-   BerespHeader   Date: Tue, 29 Sep 2020 20:01:04 GMT<br>-   BerespHeader   Content-type: application/octet-stream<br>-   BerespHeader   Content-Length: 12<br>-   BerespHeader   Last-Modified: Tue, 29 Sep 2020 19:36:31 GMT<br>-   TTL            RFC 120 10 0 1601409664 1601409664 1601409664 0 0 cacheable<br>-   VCL_call       BACKEND_RESPONSE<br>-   VCL_return     deliver<br>-   Filters<br>-   Storage        malloc s0<br>-   Fetch_Body     3 length stream<br>-   BackendClose   26 default close<br>-   Timestamp      BerespBody: 1601409664.463236 0.001682 0.000120<br>-   Length         12<br>-   BereqAcct      155 0 155 199 12 211<br>-   End<br><br>*   << Request  >> 3<br>-   Begin          req 2 restart<br>-   Timestamp      Start: 1601409664.461429 0.000037 0.000000<br>-   ReqStart       ::1 55180 a0<br>-   ReqMethod      GET<br>-   ReqURL         /this_url_does_not_exist<br>-   ReqProtocol    HTTP/1.1<br>-   ReqHeader      Host: localhost:6081<br>-   ReqHeader      User-Agent: curl/7.72.0<br>-   ReqHeader      Accept: */*<br>-   ReqHeader      X-Forwarded-For: ::1<br>-   ReqHeader      X-Original-URL: /this_object_exists<br>-   VCL_call       RECV<br>-   ReqURL         /this_object_exists<br>-   ReqUnset       X-Original-URL: /this_object_exists<br>-   ReqUnset       Host: localhost:6081<br>-   ReqHeader      host: localhost:6081<br>-   VCL_return     hash<br>-   VCL_call       HASH<br>-   VCL_return     lookup<br>-   VCL_call       MISS<br>-   VCL_return     fetch<br>-   Link           bereq 4 fetch<br>-   Timestamp      Fetch: 1601409664.463212 0.001821 0.001783<br>-   RespProtocol   HTTP/1.0<br>-   RespStatus     200<br>-   RespReason     OK<br>-   RespHeader     Server: SimpleHTTP/0.6 Python/3.8.6<br>-   RespHeader     Date: Tue, 29 Sep 2020 20:01:04 GMT<br>-   RespHeader     Content-type: application/octet-stream<br>-   RespHeader     Content-Length: 12<br>-   RespHeader     Last-Modified: Tue, 29 Sep 2020 19:36:31 GMT<br>-   RespProtocol   HTTP/1.1<br>-   RespHeader     X-Varnish: 3<br>-   RespHeader     Age: 0<br>-   RespHeader     Via: 1.1 varnish (Varnish/6.5)<br>-   VCL_call       DELIVER<br>-   VCL_return     deliver<br>-   Timestamp      Process: 1601409664.463225 0.001833 0.000012<br>-   Filters<br>-   RespHeader     Accept-Ranges: bytes<br>-   RespHeader     Connection: keep-alive<br>-   Timestamp      Resp: 1601409664.463286 0.001894 0.000061<br>-   ReqAcct        96 0 96 299 12 311<br>-   End<br><br>*   << Session  >> 1<br>-   Begin          sess 0 HTTP/1<br>-   SessOpen       ::1 55180 a0 ::1 6081 1601409664.461310 18<br>-   Link           req 2 rxreq<br>-   SessClose      REM_CLOSE 0.002<br>-   End</div><div><br></div></blockquote>As you can see from the FETCH block, what it effectively fetches from backend is not what varnishncsa logs. </div><div>I think it has something to do with the order in which the restart affects the flow, since its not replacing the req.url object, just appending a new one. BACKEND FETCH uses the right URL object since it uses the last one, but varnishncsa logs the first it picked up from that restart. </div><div><br></div><div>I've tried setting a blank req.url or unsetting in an attempt to avoid having several req.URL objects introducing problems, but it seems that property is readonly since I get errors like "Variable cannot be unset" or "Setting req.url to empty sting - FAILED".</div><div><br></div><div>Unfortunately I have no other way to implement my abtest engine than by using the restart() order from varnish, but this logging issue is extremely affecting what I can see to debug my stuff. </div><div><br></div><div>Any clue of what trick I could use to workaround this? </div><div><br></div><div>Thanks in advance!</div></div>