varnishlog issue with ESI and ReqURL?

[Steve Easley]

When using varnishlog (4.0.1) on CentOS I notice its not grouping identical ReqURL tags together. As far as I can tell this is related to the ReqURL tag of ESI requests being (incorrectly?) associated with the top level request.

For instance here is a request to a page containing one ESI tag (varnish was restarted to start with a clean cache)

$ varnishlog -g request -i "Begin,End,ReqURL,BereqURL,Link"
*   << Request  >> 2         
-   Begin          req 1 rxreq
-   ReqURL         /?foo=3
-   Link           bereq 3 fetch 
-   Link           req 4 esi
-   ReqURL         /esi/csstheme/
-   ReqURL         /esi/csstheme/
-   End            
**  << BeReq    >> 3         
--  Begin          bereq 2 fetch 
--  BereqURL       /?foo=3
--  End            
**  << Request  >> 4         
--  Begin          req 2 esi
--  Link           bereq 5 fetch 
--  End            
*** << BeReq    >> 5         
--- Begin          bereq 4 fetch 
--- BereqURL       /esi/csstheme/
--- End 

Notice the ESI request (Request 4) has no ReqURL tag. Instead 2 tags seems (erroneously?) associated with top level request (Request 2). Here is what varnishtop looks like after hitting the same URL a few times:

$ varnishtop -i ReqURL 
    10.01 ReqURL         /esi/csstheme/
     9.39 ReqURL         /?foo=3
     8.75 ReqURL         /esi/csstheme/

Not sure why its not grouping /esi/csstheme/.

 

Here is my (very simple) VCL:

sub vcl_recv {
    set req.backend_hint = cluster.backend();
    set req.http.Surrogate-Capability = "varnish=ESI/1.0";
}

sub vcl_deliver {
}

sub vcl_backend_response {
    if (beresp.http.Surrogate-Control ~ "ESI/1.0") {
        unset beresp.http.Surrogate-Control;
        set beresp.do_esi = true;
    }
}