SV: req.url modified in restart?

[Jesper Larsen]

Hi Dridi

On Wed, Apr 26, 2017 at 3:46 PM,  Dridi Boukelmoune [dridi at varni.sh] wrote:
>Hello Jesper,
>
>Could you please describe in more details how to reproduce? Ideally
>with just enough VCL. Possibly with the offending transaction's logs.

vcl 4.0;

import std;
import directors;

backend default {
    .host = "yourbackendip";
    .port = "8000";
}

backend special_backend {
    .host = "yourbackendip";
    .port = "8080";
}

sub vcl_recv {
    if (req.url ~ "^\/foo\/") {
        set req.url = regsub(req.url, "^\/foo\/", "/");
        set req.backend_hint = special_backend;
    } else {
        set req.backend_hint = default;
    }
}

For this test I ran:

$ python -m SimpleHTTPServer 8000

on the backend as a default backend and no server on port 8080.

When I do a request for:

http://varnish_server/foo

I get a 404 from the default backend even though I pressume that the request should time out instead.

Output from Python server:
Serving HTTP on 0.0.0.0 port 8000 ...
172.17.0.2 - - [27/Apr/2017 12:58:44] code 404, message File not found
172.17.0.2 - - [27/Apr/2017 12:58:44] "GET /foo HTTP/1.1" 404 -

Varnish output:
*   << BeReq    >> 3         
-   Begin          bereq 2 fetch
-   Timestamp      Start: 1493290724.892610 0.000000 0.000000
-   BereqMethod    GET
-   BereqURL       /foo
-   BereqProtocol  HTTP/1.1
-   BereqHeader    Host: localhost:9090
-   BereqHeader    User-Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:53.0) Gecko/20100101 Firefox/53.0
-   BereqHeader    Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
-   BereqHeader    Accept-Language: en-US,en;q=0.5
-   BereqHeader    Upgrade-Insecure-Requests: 1
-   BereqHeader    X-Forwarded-For: 172.17.0.1
-   BereqHeader    Accept-Encoding: gzip
-   BereqHeader    X-Varnish: 3
-   VCL_call       BACKEND_FETCH
-   VCL_return     fetch
-   BackendOpen    24 boot.default 192.168.1.45 8000 172.17.0.2 40436
-   BackendStart   192.168.1.45 8000
-   Timestamp      Bereq: 1493290724.892916 0.000306 0.000306
-   Timestamp      Beresp: 1493290724.893714 0.001105 0.000799
-   BerespProtocol HTTP/1.0
-   BerespStatus   404
-   BerespReason   File not found
-   BerespHeader   Server: SimpleHTTP/0.6 Python/2.7.12
-   BerespHeader   Date: Thu, 27 Apr 2017 10:58:44 GMT
-   BerespHeader   Connection: close
-   BerespHeader   Content-Type: text/html
-   TTL            RFC 120 10 -1 1493290725 1493290725 1493290724 0 0
-   VCL_call       BACKEND_RESPONSE
-   VCL_return     deliver
-   Storage        malloc s0
-   ObjProtocol    HTTP/1.0
-   ObjStatus      404
-   ObjReason      File not found
-   ObjHeader      Server: SimpleHTTP/0.6 Python/2.7.12
-   ObjHeader      Date: Thu, 27 Apr 2017 10:58:44 GMT
-   ObjHeader      Content-Type: text/html
-   Fetch_Body     4 eof stream
-   BackendClose   24 boot.default
-   Timestamp      BerespBody: 1493290724.893893 0.001284 0.000179
-   Length         195
-   BereqAcct      335 0 335 150 195 345
-   End            

*   << Request  >> 2         
-   Begin          req 1 rxreq
-   Timestamp      Start: 1493290724.892466 0.000000 0.000000
-   Timestamp      Req: 1493290724.892466 0.000000 0.000000
-   ReqStart       172.17.0.1 46312
-   ReqMethod      GET
-   ReqURL         /foo
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Host: localhost:9090
-   ReqHeader      User-Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:53.0) Gecko/20100101 Firefox/53.0
-   ReqHeader      Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
-   ReqHeader      Accept-Language: en-US,en;q=0.5
-   ReqHeader      Accept-Encoding: gzip, deflate
-   ReqHeader      Connection: keep-alive
-   ReqHeader      Upgrade-Insecure-Requests: 1
-   ReqHeader      Cache-Control: max-age=0
-   ReqHeader      X-Forwarded-For: 172.17.0.1
-   VCL_call       RECV
-   VCL_return     hash
-   ReqUnset       Accept-Encoding: gzip, deflate
-   ReqHeader      Accept-Encoding: gzip
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       MISS
-   VCL_return     fetch
-   Link           bereq 3 fetch
-   Timestamp      Fetch: 1493290724.893937 0.001471 0.001471
-   RespProtocol   HTTP/1.0
-   RespStatus     404
-   RespReason     File not found
-   RespHeader     Server: SimpleHTTP/0.6 Python/2.7.12
-   RespHeader     Date: Thu, 27 Apr 2017 10:58:44 GMT
-   RespHeader     Content-Type: text/html
-   RespProtocol   HTTP/1.1
-   RespHeader     X-Varnish: 2
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   VCL_return     deliver
-   Timestamp      Process: 1493290724.894007 0.001541 0.000070
-   RespHeader     Content-Length: 195
-   Debug          "RES_MODE 2"
-   RespHeader     Connection: keep-alive
-   Timestamp      Resp: 1493290724.894064 0.001598 0.000057
-   ReqAcct        351 0 351 219 195 414
-   End            

*   << Session  >> 1         
-   Begin          sess 0 HTTP/1
-   SessOpen       172.17.0.1 46312 :80 172.17.0.2 80 1493290724.892237 16
-   Link           req 2 rxreq
-   SessClose      RX_TIMEOUT 5.007
-   End            

>Please also mention Varnish's version.

varnishd (varnish-4.1.3 revision 5e3b6d2)

>Thanks,
>Dridi

Best regards,
Jesper