[Varnish] #1668: Assertion error in vmod_ip()

[Varnish]

#1668: Assertion error in vmod_ip()
-----------------------------+----------------------
 Reporter:  lisachenko.it@…  |       Type:  defect
   Status:  new              |   Priority:  normal
Milestone:                   |  Component:  varnishd
  Version:  4.0.2            |   Severity:  normal
 Keywords:                   |
-----------------------------+----------------------
 We switched to the new version of Varnish on production and noticed that
 sometimes connection from nginx to varnish is refused:


 {{{
 2015/02/03 10:21:45 [error] 18100#0: *267573 connect() failed (111:
 Connection refused) while connecting to upstream, client: x.x.x.x, server:
 xx.yy.ru, request: "GET /xxxx HTTP/1.1", upstream:
 "http://127.0.0.1:8080/xxxx/", host: "xx.yy.ru"
 }}}

 panic.show contains an error about assert violation


 {{{
 Assert error in vmod_ip(), vmod_std_conversions.c line 144:
   Condition((p) != 0) not true.
 thread = (cache-worker)
 ident = Linux,3.2.0-4-amd64,x86_64,-smalloc,-smalloc,-hcritbit,epoll
 Backtrace:
   0x434225: /usr/sbin/varnishd() [0x434225]
   0x7fbdcdfea053: /usr/lib/varnish/vmods/libvmod_std.so(vmod_ip+0x143)
 [0x7fbdcdfea053]
   0x7fbdcf1f2cbb: ./vcl.bDW3Ts2n.so(VGC_function_vcl_deliver+0x8b)
 [0x7fbdcf1f2cbb]
   0x440cec: /usr/sbin/varnishd() [0x440cec]
   0x441bd8: /usr/sbin/varnishd(VCL_deliver_method+0x48) [0x441bd8]
   0x43806e: /usr/sbin/varnishd() [0x43806e]
   0x4387d1: /usr/sbin/varnishd(CNT_Request+0x111) [0x4387d1]
   0x41a778: /usr/sbin/varnishd(ESI_Deliver+0x7e8) [0x41a778]
   0x43b5a8: /usr/sbin/varnishd(V1D_Deliver+0x368) [0x43b5a8]
   0x438136: /usr/sbin/varnishd() [0x438136]
 req = 0x7fbdb85ac020 {
   sp = 0x7fbdc4810860, vxid = 1076822325,  step = R_STP_DELIVER,
   req_body = R_BODY_NONE,
   restarts = 0, esi_level = 1
   sp = 0x7fbdc4810860 {
     fd = 17, vxid = 3080488,
     client = 127.0.0.1 35703,
     step = S_STP_WORKING,
   },
   worker = 0x7fbddc926c50 {
     ws = 0x7fbddc926e68 {
       id = "wrk",
       {s,f,r,e} = {0x7fbddc926450,0x7fbddc926450,(nil),+2048},
     },
   VCL::method = DELIVER,
   VCL::return = abandon,
   },
   ws = 0x7fbdb85ac1b8 {
     id = "req",
     {s,f,r,e} = {0x7fbdb85ae010,+40,(nil),+57360},
   },
   http[req] = {
     ws = 0x7fbdb84771b8[2eq]
       "GET",
       "/some/url/here",
       "HTTP/1.1",
       "Connection: close",
       " some headers here "
       "Cache-Control: max-age=259200",
       "X-Forwarded-For: 178.255.200.61",
       "X-ESI-Level: 1",
   },
   http[resp] = {
     ws = 0x7fbdb85ac1b8[req]
       "HTTP/1.1",
       "200",
       "OK",
       "Server: nginx/1.6.2",
       "Content-Type: text/html; charset=UTF-8",
       "cache-control: public, s-maxage=60",
       "date: Tue, 03 Feb 2015 08:25:27 GMT",
       "X-UA-Compatible: IE=edge",
       "Content-Encoding: gzip",
       "X-Varnish: 3080501 2162830",
       "Age: 34",
       "Via: 1.1 varnish-v4",
   },
   vcl = {
     srcname = {
       "input",
       "Builtin",
       "acl.vcl",
       "probes.vcl",
       "backends.vcl",
     },
   },
   obj (REQ) = 0x7fbdba03b380 {
     vxid = 2149646478,
     http[obj] = {
       ws = (nil)[]
         "HTTP/1.1",
         "200",
         "OK",
         "Server: nginx/1.6.2",
         "Content-Type: text/html; charset=UTF-8",
         "cache-control: public, s-maxage=60",
         "date: Tue, 03 Feb 2015 08:25:27 GMT",
         "X-UA-Compatible: IE=edge",
         "Content-Encoding: gzip",
     },
     len = 639,
     store = {
       639 {
         1f 8b 08 00 00 00 00 00 00 03 bd 95 5d 6e 13 31 |............]n.1|
         10 c7 af 62 f6 7d 63 41 03 55 ab 4d b8 01 07 e0 |...b.}cA.U.M....|
         65 e5 6c 9c c4 92 e3 8d bc de 06 fa 14 82 f8 90 |e.l.............|
         52 09 11 55 e2 89 0f 89 0b 84 42 20 d0 26 5c 61 |R..U......B .&\a|
         [575 more]
       },
     },
   },
 },
 }}}


 From the assertion name and trace, I found a possible root causes in my
 VCL file, in the vcl_deliver routine:

 First line:
 {{{
     # Enable debug headers only for developers
     if (!std.ip(regsub(req.http.X-Forwarded-For, "[, ].*$", ""),
 client.ip) ~ developers) {
         // add headers to the response
     }
 }}}

 Second line:
 {{{
     std.log("Developer IP: " + std.ip(regsub(req.http.X-Forwarded-For, "[,
 ].*$", ""), client.ip) + " will see additional headers from Varnish");
 }}}

 This assertions is not present all the time, but occurs periodically.

-- 
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1668>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator