New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Assert error in VRTPRIV_dynamic_kill(), cache/cache_vrt_priv.c line 111: #2268

Closed
xcir opened this Issue Mar 20, 2017 · 11 comments

Comments

Projects
None yet
6 participants
@xcir
Contributor

xcir commented Mar 20, 2017

Panic at: Mon, 20 Mar 2017 08:39:07 GMT
Assert error in VRTPRIV_dynamic_kill(), cache/cache_vrt_priv.c line 111:
  Condition((vp)->magic == 0x24157a52) not true.
version = varnish-5.1.1 revision de38712, vrt api = 6.0
ident = Linux,4.4.0-24-generic,x86_64,-junix,-smalloc,-sfile,-sfile,-smalloc,-hcritbit,epoll
now = 1956981.218037 (mono), 1489999146.497627 (real)
Backtrace:
  0x438b37: /usr/sbin/varnishd() [0x438b37]
  0x44b290: /usr/sbin/varnishd(VRTPRIV_dynamic_kill+0x160) [0x44b290]
  0x43ae9e: /usr/sbin/varnishd(Req_Cleanup+0xce) [0x43ae9e]
  0x461100: /usr/sbin/varnishd(h2_del_req+0xb0) [0x461100]
  0x461289: /usr/sbin/varnishd(h2_do_req+0x79) [0x461289]
  0x451b69: /usr/sbin/varnishd() [0x451b69]
  0x451feb: /usr/sbin/varnishd() [0x451feb]
  0x7fad689e06ba: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba) [0x7fad689e06ba]
  0x7fad6871682d: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7fad6871682d]
thread = (cache-worker)
thr.req = 0x7fa3549c0020 {
  vxid = 3899727, transport = H2
  step = R_STP_TRANSMIT,
  req_body = R_BODY_NONE,
  restarts = 0, esi_level = 0,
  sp = 0x7fad5c679c20 {
    fd = 218, vxid = 3899722,
    t_open = 1489999146.309901,
    t_idle = 1489999146.497617,
    transport = H2 {
      streams {
        0x00000000 idle
      }
    }
    client = *** ***,
  },
  ws = 0x7fa3549c0208 {
    id = \"req\",
    {s, f, r, e} = {0x7fa3549c2008, +1816, (nil), +122864},
  },
  http_conn = 0x7fa3549c0130 {
    doclose = NULL,
    ws = (nil) {
    },
    {rxbuf_b, rxbuf_e} = {(nil), (nil)},
    {pipeline_b, pipeline_e} = {(nil), (nil)},
    content_length = 0,
    body_status = none,
    first_byte_timeout = 0.000000,
    between_bytes_timeout = 0.000000,
  },
  http[req] = 0x7fa3549c02a0 {
    ws = 0x7fa3549c0208 {
      [Already dumped, see above]
    },
    hdrs {
      \"GET\",
      ***
      \"HTTP/2.0\",
      \"scheme: https\",
      \"user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36\",
      \"accept: text/css,*/*;q=0.1\",
      \"referer: ***",
      \"accept-language: ja-JP,ja;q=0.8,en-US;q=0.6,en;q=0.4\",
      ***
      \"X-Forwarded-Port: 443\",
      \"X-Real-IP: ***
      \"X-Forwarded-Proto: https\",
      \"X-Forwarded-For: ***
      ***
      \"host: ***
      ***
      ***
      ***
      ***
      ***
      \"Accept-Encoding: gzip\",
    },
  },
  vmods = {
    std = {Varnish 5.1.1 de38712, 6.0},
    directors = {Varnish 5.1.1 de38712, 6.0},
    vsthrottle = {Varnish 5.1.1 de38712, 6.0},
    cookie = {Varnish 5.1.1 de38712, 6.0},
    tcp = {Varnish 5.1.1 de38712, 6.0},
    crypto = {Varnish 5.1.1 de38712, 6.0},
  },
  flags = {
    is_hit,
  },
},
thr.busyobj = (nil) {
},

Your Environment

  • Version used: hitch1.4.4 + varnish-5.1.1
  • Operating System and version: Ubuntu 16.04.1 LTS (4.4.0-24-generic)
@xcir

This comment has been minimized.

Show comment
Hide comment
@xcir

xcir Mar 23, 2017

Contributor

Similar error..(vrt_priv_dynamic)

Panic at: Wed, 22 Mar 2017 14:05:23 GMT
Assert error in vrt_priv_dynamic(), cache/cache_vrt_priv.c line 114:
  Condition((vp)->magic == 0x24157a52) not true.
version = varnish-5.1.1 revision 4d3037a, vrt api = 6.0
ident = Linux,4.4.0-24-generic,x86_64,-junix,-smalloc,-sfile,-sfile,-smalloc,-hcritbit,epoll
now = 2149357.291496 (mono), 1490191522.571085 (real)
Backtrace:
  0x438945: /usr/sbin/varnishd() [0x438945]
  0x44ac28: /usr/sbin/varnishd() [0x44ac28]
  0x7f3eb15411ce: vcl_boot.1490188582.198924065/vgc.so(VGC_function_verificationCookie+0x9e) [0x7f3eb15411ce]
  0x7f3eb15424ef: vcl_boot.1490188582.198924065/vgc.so(VGC_function_***_recv+0x1f) [0x7f3eb15424ef]
  0x7f3eb1544d32: vcl_boot.1490188582.198924065/vgc.so(VGC_function_vcl_recv+0x13b2) [0x7f3eb1544d32]
  0x4464f0: /usr/sbin/varnishd() [0x4464f0]
  0x448d0a: /usr/sbin/varnishd(VCL_recv_method+0x5a) [0x448d0a]
  0x43ccd9: /usr/sbin/varnishd(CNT_Request+0xd89) [0x43ccd9]
  0x46130f: /usr/sbin/varnishd(h2_do_req+0x4f) [0x46130f]
  0x451d72: /usr/sbin/varnishd() [0x451d72]
thread = (cache-worker)
thr.req = 0x7f3ea4160020 {
  vxid = 2460465, transport = H2
  step = R_STP_RECV,
  req_body = R_BODY_WITHOUT_LEN,
  restarts = 0, esi_level = 0,
  sp = 0x7f3eab2d6220 {
    fd = 311, vxid = 2459333,
    t_open = 1490190941.064770,
    t_idle = 1490191522.570636,
    transport = H2 {
      streams {
        0x00000000 idle
        0x000008d7 c-rem
      }
    }
    client = *** ***,
    privs = 0x7f3eab2d6288 {
      MAGIC 0x7b86c8a5 (Should:VRT_PRIV_MAGIC/0x24157a52)
      priv {p 0xffffffff l 0 f (nil)} vcl (nil) id 4aaae0 vmod 7f48bede8608
    },
  },
  worker = 0x7f3eade9ec70 {
    stack = {0x7f3eade9f000 -> 0x7f3eade93000},
    ws = 0x7f3eade9ee70 {
      id = \"wrk\",
      {s, f, r, e} = {0x7f3eade9e410, +0, (nil), +2040},
    },
    VCL::method = inside RECV,
    VCL::return = 0x0,
    VCL::methods = {RECV},
  },
  ws = 0x7f3ea4160208 {
    id = \"req\",
    {s, f, r, e} = {0x7f3ea4162008, +2768, (nil), +122864},
  },
  http_conn = 0x7f3ea4160130 {
    doclose = NULL,
    ws = (nil) {
    },
    {rxbuf_b, rxbuf_e} = {(nil), (nil)},
    {pipeline_b, pipeline_e} = {(nil), (nil)},
    content_length = 0,
    body_status = none,
    first_byte_timeout = 0.000000,
    between_bytes_timeout = 0.000000,
  },
  http[req] = 0x7f3ea41602a0 {
    ws = 0x7f3ea4160208 {
      [Already dumped, see above]
    },
    hdrs {
      \"POST\",
      \"***\",
      \"HTTP/2.0\",
      \"scheme: https\",
      \"accept: application/json, text/javascript, */*; q=0.01\",
      \"origin: ***",
      \"x-requested-with: XMLHttpRequest\",
      \"user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.110 Safari/537.36\",
      \"content-type: application/x-www-form-urlencoded; charset=UTF-8\",
      \"referer: ***",
      \"accept-encoding: gzip, deflate, br\",
      \"accept-language: ja,en-US;q=0.8,en;q=0.6\",
      ***
      \"cookie: ***",
      \"X-Forwarded-Port: 443\",
      ***
      \"X-Forwarded-Proto: https\",
      ***
      \"X-SCHEME: https\",
      ***
      \"x-varnish-hash: :https\",
      \"x-v-doesi: 1\",
    },
  },
  vcl = {
    name = \"boot\",
    busy = 235,
    discard = 0,
    state = auto,
    temp = warm,
    conf = {
      srcname = {
        \"/etc/varnish/default.vcl\",
        \"Builtin\",
        \"/etc/varnish/banip.vcl\",
        \"/etc/varnish/define.vcl\",
        \"/etc/varnish/auth.vcl\",
        \"/etc/varnish/prefilter.vcl\",
        \"/etc/varnish/ext.vcl\",
        \"/etc/varnish/***.vcl\",
        \"/etc/varnish/***.vcl\",
        \"/etc/varnish/***.vcl\",
        \"/etc/varnish/***.vcl\",
        \"/etc/varnish/main.vcl\",
      },
    },
  },
  vmods = {
    std = {Varnish 5.1.1 4d3037a, 6.0},
    directors = {Varnish 5.1.1 4d3037a, 6.0},
    vsthrottle = {Varnish 5.1.1 4d3037a, 6.0},
    cookie = {Varnish 5.1.1 4d3037a, 6.0},
    tcp = {Varnish 5.1.1 4d3037a, 6.0},
    crypto = {Varnish 5.1.1 4d3037a, 6.0},
  },
  flags = {
  },
},
thr.busyobj = (nil) {
},
Contributor

xcir commented Mar 23, 2017

Similar error..(vrt_priv_dynamic)

Panic at: Wed, 22 Mar 2017 14:05:23 GMT
Assert error in vrt_priv_dynamic(), cache/cache_vrt_priv.c line 114:
  Condition((vp)->magic == 0x24157a52) not true.
version = varnish-5.1.1 revision 4d3037a, vrt api = 6.0
ident = Linux,4.4.0-24-generic,x86_64,-junix,-smalloc,-sfile,-sfile,-smalloc,-hcritbit,epoll
now = 2149357.291496 (mono), 1490191522.571085 (real)
Backtrace:
  0x438945: /usr/sbin/varnishd() [0x438945]
  0x44ac28: /usr/sbin/varnishd() [0x44ac28]
  0x7f3eb15411ce: vcl_boot.1490188582.198924065/vgc.so(VGC_function_verificationCookie+0x9e) [0x7f3eb15411ce]
  0x7f3eb15424ef: vcl_boot.1490188582.198924065/vgc.so(VGC_function_***_recv+0x1f) [0x7f3eb15424ef]
  0x7f3eb1544d32: vcl_boot.1490188582.198924065/vgc.so(VGC_function_vcl_recv+0x13b2) [0x7f3eb1544d32]
  0x4464f0: /usr/sbin/varnishd() [0x4464f0]
  0x448d0a: /usr/sbin/varnishd(VCL_recv_method+0x5a) [0x448d0a]
  0x43ccd9: /usr/sbin/varnishd(CNT_Request+0xd89) [0x43ccd9]
  0x46130f: /usr/sbin/varnishd(h2_do_req+0x4f) [0x46130f]
  0x451d72: /usr/sbin/varnishd() [0x451d72]
thread = (cache-worker)
thr.req = 0x7f3ea4160020 {
  vxid = 2460465, transport = H2
  step = R_STP_RECV,
  req_body = R_BODY_WITHOUT_LEN,
  restarts = 0, esi_level = 0,
  sp = 0x7f3eab2d6220 {
    fd = 311, vxid = 2459333,
    t_open = 1490190941.064770,
    t_idle = 1490191522.570636,
    transport = H2 {
      streams {
        0x00000000 idle
        0x000008d7 c-rem
      }
    }
    client = *** ***,
    privs = 0x7f3eab2d6288 {
      MAGIC 0x7b86c8a5 (Should:VRT_PRIV_MAGIC/0x24157a52)
      priv {p 0xffffffff l 0 f (nil)} vcl (nil) id 4aaae0 vmod 7f48bede8608
    },
  },
  worker = 0x7f3eade9ec70 {
    stack = {0x7f3eade9f000 -> 0x7f3eade93000},
    ws = 0x7f3eade9ee70 {
      id = \"wrk\",
      {s, f, r, e} = {0x7f3eade9e410, +0, (nil), +2040},
    },
    VCL::method = inside RECV,
    VCL::return = 0x0,
    VCL::methods = {RECV},
  },
  ws = 0x7f3ea4160208 {
    id = \"req\",
    {s, f, r, e} = {0x7f3ea4162008, +2768, (nil), +122864},
  },
  http_conn = 0x7f3ea4160130 {
    doclose = NULL,
    ws = (nil) {
    },
    {rxbuf_b, rxbuf_e} = {(nil), (nil)},
    {pipeline_b, pipeline_e} = {(nil), (nil)},
    content_length = 0,
    body_status = none,
    first_byte_timeout = 0.000000,
    between_bytes_timeout = 0.000000,
  },
  http[req] = 0x7f3ea41602a0 {
    ws = 0x7f3ea4160208 {
      [Already dumped, see above]
    },
    hdrs {
      \"POST\",
      \"***\",
      \"HTTP/2.0\",
      \"scheme: https\",
      \"accept: application/json, text/javascript, */*; q=0.01\",
      \"origin: ***",
      \"x-requested-with: XMLHttpRequest\",
      \"user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.110 Safari/537.36\",
      \"content-type: application/x-www-form-urlencoded; charset=UTF-8\",
      \"referer: ***",
      \"accept-encoding: gzip, deflate, br\",
      \"accept-language: ja,en-US;q=0.8,en;q=0.6\",
      ***
      \"cookie: ***",
      \"X-Forwarded-Port: 443\",
      ***
      \"X-Forwarded-Proto: https\",
      ***
      \"X-SCHEME: https\",
      ***
      \"x-varnish-hash: :https\",
      \"x-v-doesi: 1\",
    },
  },
  vcl = {
    name = \"boot\",
    busy = 235,
    discard = 0,
    state = auto,
    temp = warm,
    conf = {
      srcname = {
        \"/etc/varnish/default.vcl\",
        \"Builtin\",
        \"/etc/varnish/banip.vcl\",
        \"/etc/varnish/define.vcl\",
        \"/etc/varnish/auth.vcl\",
        \"/etc/varnish/prefilter.vcl\",
        \"/etc/varnish/ext.vcl\",
        \"/etc/varnish/***.vcl\",
        \"/etc/varnish/***.vcl\",
        \"/etc/varnish/***.vcl\",
        \"/etc/varnish/***.vcl\",
        \"/etc/varnish/main.vcl\",
      },
    },
  },
  vmods = {
    std = {Varnish 5.1.1 4d3037a, 6.0},
    directors = {Varnish 5.1.1 4d3037a, 6.0},
    vsthrottle = {Varnish 5.1.1 4d3037a, 6.0},
    cookie = {Varnish 5.1.1 4d3037a, 6.0},
    tcp = {Varnish 5.1.1 4d3037a, 6.0},
    crypto = {Varnish 5.1.1 4d3037a, 6.0},
  },
  flags = {
  },
},
thr.busyobj = (nil) {
},
@xcir

This comment has been minimized.

Show comment
Hide comment
@xcir

xcir Mar 23, 2017

Contributor

I think vrt_priv_dynamic/VRTPRIV_dynamic_kill have race condition at H2, but I could be wrong.
(I still don't understand the working for H2 by Varnish.)

key of PRIV_TASK/TOP are vmod_id and req/bo pointer id.

if (ctx->req) {
CHECK_OBJ_NOTNULL(ctx->req, REQ_MAGIC);
id = (uintptr_t)ctx->req;
} else if (ctx->bo) {
CHECK_OBJ_NOTNULL(ctx->bo, BUSYOBJ_MAGIC);
id = (uintptr_t)ctx->bo;
} else {
ASSERT_CLI();
return (&cli_task_priv);
}
return (vrt_priv_dynamic(ctx, id, (uintptr_t)vmod_id));

req/bo pointer is same in the same session.
H1 is sequential, there was no problem.
But H/2 is multiplexing, so there is a possibility of conflict.
It might be a good idea to adding vxid(or stream id) to key.

Contributor

xcir commented Mar 23, 2017

I think vrt_priv_dynamic/VRTPRIV_dynamic_kill have race condition at H2, but I could be wrong.
(I still don't understand the working for H2 by Varnish.)

key of PRIV_TASK/TOP are vmod_id and req/bo pointer id.

if (ctx->req) {
CHECK_OBJ_NOTNULL(ctx->req, REQ_MAGIC);
id = (uintptr_t)ctx->req;
} else if (ctx->bo) {
CHECK_OBJ_NOTNULL(ctx->bo, BUSYOBJ_MAGIC);
id = (uintptr_t)ctx->bo;
} else {
ASSERT_CLI();
return (&cli_task_priv);
}
return (vrt_priv_dynamic(ctx, id, (uintptr_t)vmod_id));

req/bo pointer is same in the same session.
H1 is sequential, there was no problem.
But H/2 is multiplexing, so there is a possibility of conflict.
It might be a good idea to adding vxid(or stream id) to key.

@xcir

This comment has been minimized.

Show comment
Hide comment
@xcir

xcir Apr 4, 2017

Contributor

I got same error at 6d1fb08

Apr  4 20:21:59 px01 varnishd[21519]: Child (21529) Panic at: Tue, 04 Apr 2017 11:21:59 GMT
Assert error in VRTPRIV_dynamic_kill(), cache/cache_vrt_priv.c line 143:
  Condition((vp)->magic == 0x24157a52) not true.
version = varnish-5.1.1 revision 6d1fb08, vrt api = 6.0
ident = Linux,4.4.0-24-generic,x86_64,-junix,-smalloc,-sfile,-sfile,-smalloc,-hcritbit,epoll
now = 418055.080128 (mono), 1491304917.802742 (real)
Backtrace:
  0x438c35: /usr/sbin/varnishd() [0x438c35] (pan_ic + 373 by gdb)
  0x44b2e6: /usr/sbin/varnishd(VRTPRIV_dynamic_kill+0x126) [0x44b2e6]
  0x43aefe: /usr/sbin/varnishd(Req_Cleanup+0xce) [0x43aefe]
  0x46128c: /usr/sbin/varnishd(h2_del_req+0xcc) [0x46128c]
  0x462495: /usr/sbin/varnishd(h2_rxframe+0x445) [0x462495]
  0x462b8e: /usr/sbin/varnishd() [0x462b8e] (h2_new_session + 494 by gdb)
  0x4520c2: /usr/sbin/varnishd() [0x4520c2] (WRK_Thread + 1218 by gdb)
  0x45256b: /usr/sbin/varnishd() [0x45256b] (pool_thread + 43 by gdb)
  0x7f7f4b9d76ba: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba) [0x7f7f4b9d76ba]
  0x7f7f4b70d82d: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f7f4b70d82d]
thread = (cache-worker)
thr.req = 0x7f7518160020 {
  vxid = 11440188, transport = H2
  step = 0x0,
  req_body = R_BODY_INIT,
  err_code = 1, err_reason = (null),
  restarts = 0, esi_level = 0,
  sp = 0x7f751f2e1620 {
    fd = 141, vxid = 11440188,
    t_open = 1491304913.218457,
    t_idle = 1491304913.780059,
    transport = H2 {
      streams {
        0x00000000 idle  
        0x00000003 idle  
        0x00000005 idle  
        0x00000007 idle  
        0x00000009 idle  
        0x0000000b idle  
        0x0000000f closed
        0x00000011 closed
      }
    }
    client = 220.100.39.247 62821,
    privs = 0x7f751f2e1688 {
      priv {p 0x7f7525503b20 l 0 f 0x7f753cd19180} vcl 0x7f7f4c976080 id 7f751c160020 vmod 7f753759f048
      priv {p 0x7f752d378ba0 l 0 f 0x7f753cd19180} vcl 0x7f7f4c976080 id 7f751bf40020 vmod 7f753759f048
      MAGIC 0x7b86c8a5 (Should:VRT_PRIV_MAGIC/0x24157a52)
      priv {p 0x2 l 0 f (nil)} vcl (nil) id 4a664a vmod 7f7f4acd8488
    },
  },
  ws = 0x7f7518160208 {
    id = \"req\",
    {s, f, r, e} = {0x7f7518162008, +1872, (nil), +122864},
  },
  http_conn = 0x7f7518160130 {
    fd = 141 (@0x7f751f2e1638),
    doclose = NULL,
    ws = 0x7f7518160208 {
      [Already dumped, see above]
    },
    {rxbuf_b, rxbuf_e} = {0x7f75181621c8, 0x7f7518162754},
    {pipeline_b, pipeline_e} = {0x7f7518162232, 0x7f7518162754},
    content_length = 0,
    body_status = none,
    first_byte_timeout = 0.000000,
    between_bytes_timeout = 0.000000,
  },
  http[req] = 0x7f75181602a0 {
    ws = (nil) {
    },
    hdrs {
    },
  },
  vmods = {
    std = {Varnish 5.1.1 6d1fb08, 6.0},
    directors = {Varnish 5.1.1 6d1fb08, 6.0},
    vsthrottle = {Varnish 5.1.1 6d1fb08, 6.0},
    cookie = {Varnish 5.1.1 6d1fb08, 6.0},
    tcp = {Varnish 5.1.1 6d1fb08, 6.0},
    crypto = {Varnish 5.1.1 6d1fb08, 6.0},
  },
  flags = {
  },
},
thr.busyobj = (nil) {
},
Contributor

xcir commented Apr 4, 2017

I got same error at 6d1fb08

Apr  4 20:21:59 px01 varnishd[21519]: Child (21529) Panic at: Tue, 04 Apr 2017 11:21:59 GMT
Assert error in VRTPRIV_dynamic_kill(), cache/cache_vrt_priv.c line 143:
  Condition((vp)->magic == 0x24157a52) not true.
version = varnish-5.1.1 revision 6d1fb08, vrt api = 6.0
ident = Linux,4.4.0-24-generic,x86_64,-junix,-smalloc,-sfile,-sfile,-smalloc,-hcritbit,epoll
now = 418055.080128 (mono), 1491304917.802742 (real)
Backtrace:
  0x438c35: /usr/sbin/varnishd() [0x438c35] (pan_ic + 373 by gdb)
  0x44b2e6: /usr/sbin/varnishd(VRTPRIV_dynamic_kill+0x126) [0x44b2e6]
  0x43aefe: /usr/sbin/varnishd(Req_Cleanup+0xce) [0x43aefe]
  0x46128c: /usr/sbin/varnishd(h2_del_req+0xcc) [0x46128c]
  0x462495: /usr/sbin/varnishd(h2_rxframe+0x445) [0x462495]
  0x462b8e: /usr/sbin/varnishd() [0x462b8e] (h2_new_session + 494 by gdb)
  0x4520c2: /usr/sbin/varnishd() [0x4520c2] (WRK_Thread + 1218 by gdb)
  0x45256b: /usr/sbin/varnishd() [0x45256b] (pool_thread + 43 by gdb)
  0x7f7f4b9d76ba: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba) [0x7f7f4b9d76ba]
  0x7f7f4b70d82d: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f7f4b70d82d]
thread = (cache-worker)
thr.req = 0x7f7518160020 {
  vxid = 11440188, transport = H2
  step = 0x0,
  req_body = R_BODY_INIT,
  err_code = 1, err_reason = (null),
  restarts = 0, esi_level = 0,
  sp = 0x7f751f2e1620 {
    fd = 141, vxid = 11440188,
    t_open = 1491304913.218457,
    t_idle = 1491304913.780059,
    transport = H2 {
      streams {
        0x00000000 idle  
        0x00000003 idle  
        0x00000005 idle  
        0x00000007 idle  
        0x00000009 idle  
        0x0000000b idle  
        0x0000000f closed
        0x00000011 closed
      }
    }
    client = 220.100.39.247 62821,
    privs = 0x7f751f2e1688 {
      priv {p 0x7f7525503b20 l 0 f 0x7f753cd19180} vcl 0x7f7f4c976080 id 7f751c160020 vmod 7f753759f048
      priv {p 0x7f752d378ba0 l 0 f 0x7f753cd19180} vcl 0x7f7f4c976080 id 7f751bf40020 vmod 7f753759f048
      MAGIC 0x7b86c8a5 (Should:VRT_PRIV_MAGIC/0x24157a52)
      priv {p 0x2 l 0 f (nil)} vcl (nil) id 4a664a vmod 7f7f4acd8488
    },
  },
  ws = 0x7f7518160208 {
    id = \"req\",
    {s, f, r, e} = {0x7f7518162008, +1872, (nil), +122864},
  },
  http_conn = 0x7f7518160130 {
    fd = 141 (@0x7f751f2e1638),
    doclose = NULL,
    ws = 0x7f7518160208 {
      [Already dumped, see above]
    },
    {rxbuf_b, rxbuf_e} = {0x7f75181621c8, 0x7f7518162754},
    {pipeline_b, pipeline_e} = {0x7f7518162232, 0x7f7518162754},
    content_length = 0,
    body_status = none,
    first_byte_timeout = 0.000000,
    between_bytes_timeout = 0.000000,
  },
  http[req] = 0x7f75181602a0 {
    ws = (nil) {
    },
    hdrs {
    },
  },
  vmods = {
    std = {Varnish 5.1.1 6d1fb08, 6.0},
    directors = {Varnish 5.1.1 6d1fb08, 6.0},
    vsthrottle = {Varnish 5.1.1 6d1fb08, 6.0},
    cookie = {Varnish 5.1.1 6d1fb08, 6.0},
    tcp = {Varnish 5.1.1 6d1fb08, 6.0},
    crypto = {Varnish 5.1.1 6d1fb08, 6.0},
  },
  flags = {
  },
},
thr.busyobj = (nil) {
},
@daghf

This comment has been minimized.

Show comment
Hide comment
@daghf

daghf Sep 29, 2017

Member

Hi @xcir

Sorry for the long wait.

I attempted to recreate this with the cookie VMOD, and was not successful. Have you tested this in a more recent version? Several things around stream management and cleanup have changed since this crash, so it might be that the crash you saw has been overtaken by events.

Would it be possible for you to try again on 5.2.0?

Member

daghf commented Sep 29, 2017

Hi @xcir

Sorry for the long wait.

I attempted to recreate this with the cookie VMOD, and was not successful. Have you tested this in a more recent version? Several things around stream management and cleanup have changed since this crash, so it might be that the crash you saw has been overtaken by events.

Would it be possible for you to try again on 5.2.0?

@xcir

This comment has been minimized.

Show comment
Hide comment
@xcir

xcir Sep 29, 2017

Contributor

OK, I'll test again!

Contributor

xcir commented Sep 29, 2017

OK, I'll test again!

@xcir

This comment has been minimized.

Show comment
Hide comment
@xcir

xcir Oct 8, 2017

Contributor

I got same error at 5.2.0

Panic at: Sat, 07 Oct 2017 21:54:25 GMT
Assert error in VRTPRIV_dynamic_kill(), cache/cache_vrt_priv.c line 143:
  Condition((vp)->magic == 0x24157a52) not true.
version = varnish-5.2.0 revision 4c4875cbf, vrt api = 6.1
ident = Linux,4.4.0-77-generic,x86_64,-junix,-smalloc,-sfile,-sfile,-smalloc,-hcritbit,epoll
now = 13526811.596553 (mono), 1507413264.016472 (real)
Backtrace:
  0x438bd7: /usr/sbin/varnishd() [0x438bd7]
  0x47da60: /usr/sbin/varnishd(VAS_Fail+0x40) [0x47da60]
  0x44ac85: /usr/sbin/varnishd(VRTPRIV_dynamic_kill+0x125) [0x44ac85]
  0x43ad4e: /usr/sbin/varnishd(Req_Cleanup+0xce) [0x43ad4e]
  0x45ff1c: /usr/sbin/varnishd(h2_del_req+0xcc) [0x45ff1c]
  0x461315: /usr/sbin/varnishd(h2_rxframe+0x475) [0x461315]
  0x461976: /usr/sbin/varnishd() [0x461976]
  0x451a5f: /usr/sbin/varnishd() [0x451a5f]
  0x451f00: /usr/sbin/varnishd() [0x451f00]
  0x7f4e3f97f6ba: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba) [0x7f4e3f97f6ba]
thread = (cache-worker)
thr.req = 0x7f4467fc6020 {
  vxid = 7864440, transport = H2
  step = 0x0,
  req_body = R_BODY_INIT,
  err_code = 1, err_reason = (null),
  restarts = 0, esi_level = 0,
  sp = 0x7f4e33c2ee20 {
    fd = 27, vxid = 7864440,
    t_open = 1507413261.820546,
    t_idle = 1507413262.405356,
    transport = H2 {
      streams {
        0x00000000 idle
        0x00000003 closed
        0x00000007 closed
        0x00000009 closed
        0x0000000b closed
        0x0000000d closed
      }
    }
    client = **** ****,
    privs = 0x7f4e33c2ee88 {
      priv {p 0x7f445ef2ee20 l 0 f 0x7f446f5d34f0} vcl 0x7f4e3ecda8c0 id 7f4467ec6020 vmod 7f446e1ac2c8
      priv {p 0x7f4461cad400 l 0 f 0x7f446f5d34f0} vcl 0x7f4e3ecda8c0 id 7f4468c47020 vmod 7f446e1ac2c8
      priv {p 0x7f4460deecc0 l 0 f 0x7f446f5d34f0} vcl 0x7f4e3ecda8c0 id 7f44600c6020 vmod 7f446e1ac2c8
      MAGIC 0x7b86c8a5 (Should:VRT_PRIV_MAGIC/0x24157a52)
      priv {p 0x2 l 0 f (nil)} vcl (nil) id 4a6e72 vmod 7f4e408cb008
    },
  },
  ws = 0x7f4467fc6208 {
    id = \"req\",
    {s, f, r, e} = {0x7f4467fc8008, +1344, (nil), +122864},
  },
  http_conn = 0x7f4467fc6130 {
    fd = 27 (@0x7f4e33c2ee38),
    doclose = NULL,
    ws = 0x7f4467fc6208 {
      [Already dumped, see above]
    },
    {rxbuf_b, rxbuf_e} = {0x7f4467fc8130, 0x7f4467fc8545},
    {pipeline_b, pipeline_e} = {0x7f4467fc8194, 0x7f4467fc8545},
    content_length = 0,
    body_status = none,
    first_byte_timeout = 0.000000,
    between_bytes_timeout = 0.000000,
  },
  http[req] = 0x7f4467fc62a0 {
    ws = (nil) {
    },
    hdrs {
    },
  },
  vmods = {
    std = {Varnish 5.2.0 4c4875cbf, 0.0},
    directors = {Varnish 5.2.0 4c4875cbf, 0.0},
    vsthrottle = {Varnish 5.2.0 4c4875cbf, 0.0},
    cookie = {Varnish 5.2.0 4c4875cbf, 0.0},
    tcp = {Varnish 5.2.0 4c4875cbf, 0.0},
    crypto = {Varnish 5.2.0 4c4875cbf, 0.0},
  },
  flags = {
  },
},
thr.busyobj = (nil) {
},

Contributor

xcir commented Oct 8, 2017

I got same error at 5.2.0

Panic at: Sat, 07 Oct 2017 21:54:25 GMT
Assert error in VRTPRIV_dynamic_kill(), cache/cache_vrt_priv.c line 143:
  Condition((vp)->magic == 0x24157a52) not true.
version = varnish-5.2.0 revision 4c4875cbf, vrt api = 6.1
ident = Linux,4.4.0-77-generic,x86_64,-junix,-smalloc,-sfile,-sfile,-smalloc,-hcritbit,epoll
now = 13526811.596553 (mono), 1507413264.016472 (real)
Backtrace:
  0x438bd7: /usr/sbin/varnishd() [0x438bd7]
  0x47da60: /usr/sbin/varnishd(VAS_Fail+0x40) [0x47da60]
  0x44ac85: /usr/sbin/varnishd(VRTPRIV_dynamic_kill+0x125) [0x44ac85]
  0x43ad4e: /usr/sbin/varnishd(Req_Cleanup+0xce) [0x43ad4e]
  0x45ff1c: /usr/sbin/varnishd(h2_del_req+0xcc) [0x45ff1c]
  0x461315: /usr/sbin/varnishd(h2_rxframe+0x475) [0x461315]
  0x461976: /usr/sbin/varnishd() [0x461976]
  0x451a5f: /usr/sbin/varnishd() [0x451a5f]
  0x451f00: /usr/sbin/varnishd() [0x451f00]
  0x7f4e3f97f6ba: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba) [0x7f4e3f97f6ba]
thread = (cache-worker)
thr.req = 0x7f4467fc6020 {
  vxid = 7864440, transport = H2
  step = 0x0,
  req_body = R_BODY_INIT,
  err_code = 1, err_reason = (null),
  restarts = 0, esi_level = 0,
  sp = 0x7f4e33c2ee20 {
    fd = 27, vxid = 7864440,
    t_open = 1507413261.820546,
    t_idle = 1507413262.405356,
    transport = H2 {
      streams {
        0x00000000 idle
        0x00000003 closed
        0x00000007 closed
        0x00000009 closed
        0x0000000b closed
        0x0000000d closed
      }
    }
    client = **** ****,
    privs = 0x7f4e33c2ee88 {
      priv {p 0x7f445ef2ee20 l 0 f 0x7f446f5d34f0} vcl 0x7f4e3ecda8c0 id 7f4467ec6020 vmod 7f446e1ac2c8
      priv {p 0x7f4461cad400 l 0 f 0x7f446f5d34f0} vcl 0x7f4e3ecda8c0 id 7f4468c47020 vmod 7f446e1ac2c8
      priv {p 0x7f4460deecc0 l 0 f 0x7f446f5d34f0} vcl 0x7f4e3ecda8c0 id 7f44600c6020 vmod 7f446e1ac2c8
      MAGIC 0x7b86c8a5 (Should:VRT_PRIV_MAGIC/0x24157a52)
      priv {p 0x2 l 0 f (nil)} vcl (nil) id 4a6e72 vmod 7f4e408cb008
    },
  },
  ws = 0x7f4467fc6208 {
    id = \"req\",
    {s, f, r, e} = {0x7f4467fc8008, +1344, (nil), +122864},
  },
  http_conn = 0x7f4467fc6130 {
    fd = 27 (@0x7f4e33c2ee38),
    doclose = NULL,
    ws = 0x7f4467fc6208 {
      [Already dumped, see above]
    },
    {rxbuf_b, rxbuf_e} = {0x7f4467fc8130, 0x7f4467fc8545},
    {pipeline_b, pipeline_e} = {0x7f4467fc8194, 0x7f4467fc8545},
    content_length = 0,
    body_status = none,
    first_byte_timeout = 0.000000,
    between_bytes_timeout = 0.000000,
  },
  http[req] = 0x7f4467fc62a0 {
    ws = (nil) {
    },
    hdrs {
    },
  },
  vmods = {
    std = {Varnish 5.2.0 4c4875cbf, 0.0},
    directors = {Varnish 5.2.0 4c4875cbf, 0.0},
    vsthrottle = {Varnish 5.2.0 4c4875cbf, 0.0},
    cookie = {Varnish 5.2.0 4c4875cbf, 0.0},
    tcp = {Varnish 5.2.0 4c4875cbf, 0.0},
    crypto = {Varnish 5.2.0 4c4875cbf, 0.0},
  },
  flags = {
  },
},
thr.busyobj = (nil) {
},

@xcir

This comment has been minimized.

Show comment
Hide comment
@xcir

xcir Oct 8, 2017

Contributor

and got a similar error.

Panic at: Sun, 08 Oct 2017 12:26:58 GMT
Wrong turn at mgt/mgt_child.c:287:
Signal 11 (Segmentation fault) received at (nil) si_code 128
version = varnish-5.2.0 revision 4c4875cbf, vrt api = 6.1
ident = Linux,4.4.0-77-generic,x86_64,-junix,-smalloc,-sfile,-sfile,-smalloc,-hcritbit,epoll
now = 13579165.255535 (mono), 1507465617.675453 (real)
Backtrace:
  0x438bd7: /usr/sbin/varnishd() [0x438bd7]
  0x47da60: /usr/sbin/varnishd(VAS_Fail+0x40) [0x47da60]
  0x463757: /usr/sbin/varnishd() [0x463757]
  0x7f4e3f989390: /lib/x86_64-linux-gnu/libpthread.so.0(+0x11390) [0x7f4e3f989390]
  0x7f4e40527e79: /usr/lib/x86_64-linux-gnu/libjemalloc.so.1(+0xde79) [0x7f4e40527e79]
  0x7f4e40543243: /usr/lib/x86_64-linux-gnu/libjemalloc.so.1(+0x29243) [0x7f4e40543243]
  0x7f4e4051e412: /usr/lib/x86_64-linux-gnu/libjemalloc.so.1(free+0x362) [0x7f4e4051e412]
  0x44ac5d: /usr/sbin/varnishd(VRTPRIV_dynamic_kill+0xfd) [0x44ac5d]
  0x422625: /usr/sbin/varnishd(VDP_ESI+0x955) [0x422625]
  0x41fd59: /usr/sbin/varnishd(VDP_bytes+0x79) [0x41fd59]
thread = (cache-worker)
thr.req = 0x7f4455771020 {
  vxid = 20328799, transport = ESI_INCLUDE
  step = R_STP_TRANSMIT,
  req_body = R_BODY_NONE,
  restarts = 0, esi_level = 1,
  sp = 0x7f44471c8c20 {
    fd = 256, vxid = 21050944,
    t_open = 1507465426.890840,
    t_idle = 1507465617.574545,
    transport = H2 {
      streams {
        0x00000000 idle
        0x000001ad c-rem
        0x000001af c-rem
      }
    }
    client = ***,
    privs = 0x7f44471c8c88 {
      priv {p 0x7f4455fe4080 l 0 f 0x7f446f5d34f0} vcl 0x7f4e3ecda8c0 id 7f445d646020 vmod 7f446e1942c8
      priv {p 0x7f44576c9140 l 0 f 0x7f446f5d34f0} vcl 0x7f4e3ecda8c0 id 7f4455a34020 vmod 7f446e1942c8
      priv {p 0x7f446ce2a360 l 0 f 0x7f446f5d34f0} vcl 0x7f4e3ecda8c0 id 7f444d866020 vmod 7f446e1942c8
      MAGIC 0x5eaf4838 (Should:VRT_PRIV_MAGIC/0x24157a52)
      priv {p 0x625f504456286468 l 1936028793 f 0x313478305b202939} vcl 0x5d39356466 id 7f4455771020 vmod 7f446e1942c8

Contributor

xcir commented Oct 8, 2017

and got a similar error.

Panic at: Sun, 08 Oct 2017 12:26:58 GMT
Wrong turn at mgt/mgt_child.c:287:
Signal 11 (Segmentation fault) received at (nil) si_code 128
version = varnish-5.2.0 revision 4c4875cbf, vrt api = 6.1
ident = Linux,4.4.0-77-generic,x86_64,-junix,-smalloc,-sfile,-sfile,-smalloc,-hcritbit,epoll
now = 13579165.255535 (mono), 1507465617.675453 (real)
Backtrace:
  0x438bd7: /usr/sbin/varnishd() [0x438bd7]
  0x47da60: /usr/sbin/varnishd(VAS_Fail+0x40) [0x47da60]
  0x463757: /usr/sbin/varnishd() [0x463757]
  0x7f4e3f989390: /lib/x86_64-linux-gnu/libpthread.so.0(+0x11390) [0x7f4e3f989390]
  0x7f4e40527e79: /usr/lib/x86_64-linux-gnu/libjemalloc.so.1(+0xde79) [0x7f4e40527e79]
  0x7f4e40543243: /usr/lib/x86_64-linux-gnu/libjemalloc.so.1(+0x29243) [0x7f4e40543243]
  0x7f4e4051e412: /usr/lib/x86_64-linux-gnu/libjemalloc.so.1(free+0x362) [0x7f4e4051e412]
  0x44ac5d: /usr/sbin/varnishd(VRTPRIV_dynamic_kill+0xfd) [0x44ac5d]
  0x422625: /usr/sbin/varnishd(VDP_ESI+0x955) [0x422625]
  0x41fd59: /usr/sbin/varnishd(VDP_bytes+0x79) [0x41fd59]
thread = (cache-worker)
thr.req = 0x7f4455771020 {
  vxid = 20328799, transport = ESI_INCLUDE
  step = R_STP_TRANSMIT,
  req_body = R_BODY_NONE,
  restarts = 0, esi_level = 1,
  sp = 0x7f44471c8c20 {
    fd = 256, vxid = 21050944,
    t_open = 1507465426.890840,
    t_idle = 1507465617.574545,
    transport = H2 {
      streams {
        0x00000000 idle
        0x000001ad c-rem
        0x000001af c-rem
      }
    }
    client = ***,
    privs = 0x7f44471c8c88 {
      priv {p 0x7f4455fe4080 l 0 f 0x7f446f5d34f0} vcl 0x7f4e3ecda8c0 id 7f445d646020 vmod 7f446e1942c8
      priv {p 0x7f44576c9140 l 0 f 0x7f446f5d34f0} vcl 0x7f4e3ecda8c0 id 7f4455a34020 vmod 7f446e1942c8
      priv {p 0x7f446ce2a360 l 0 f 0x7f446f5d34f0} vcl 0x7f4e3ecda8c0 id 7f444d866020 vmod 7f446e1942c8
      MAGIC 0x5eaf4838 (Should:VRT_PRIV_MAGIC/0x24157a52)
      priv {p 0x625f504456286468 l 1936028793 f 0x313478305b202939} vcl 0x5d39356466 id 7f4455771020 vmod 7f446e1942c8

@daghf

This comment has been minimized.

Show comment
Hide comment
@daghf

daghf Oct 11, 2017

Member

Thanks @xcir, looking at this again it's obvious it happens due to missing locking around the privs list. H/2 brings concurrent access to that list, which opens up to a race where one request is iterating over that list while another request is freeing up its objects from it.

I'll do a patch for this.

Member

daghf commented Oct 11, 2017

Thanks @xcir, looking at this again it's obvious it happens due to missing locking around the privs list. H/2 brings concurrent access to that list, which opens up to a race where one request is iterating over that list while another request is freeing up its objects from it.

I'll do a patch for this.

daghf added a commit to daghf/varnish-cache that referenced this issue Oct 11, 2017

Add locking around client-side PRIV handling
With H/2 we now have multiple requests in flight concurrently for the
same session, so we need to synchronize access to the sp->privs list.

Fixes: #2268

daghf added a commit to daghf/varnish-cache that referenced this issue Oct 12, 2017

Move the req-specific PRIV pointers to struct req
Keeping these in struct sess would necessitate extra locking for h/2
where we have multiple reqs in flight concurrently.

Fixes: #2268
@Dridi

This comment has been minimized.

Show comment
Hide comment
@Dridi

Dridi Oct 17, 2017

Member

@xcir, since this panic seems to happen frequently, can you try running 5.2 or current master with #2458 included?

Member

Dridi commented Oct 17, 2017

@xcir, since this panic seems to happen frequently, can you try running 5.2 or current master with #2458 included?

@xcir

This comment has been minimized.

Show comment
Hide comment
@xcir

xcir Oct 17, 2017

Contributor

Yes, I try it.

Contributor

xcir commented Oct 17, 2017

Yes, I try it.

@xcir

This comment has been minimized.

Show comment
Hide comment
@xcir

xcir Oct 23, 2017

Contributor

Before apply patch I got segfault everyday.
But, rev6547893 is running stable for 4days in production.
I think this issue fixed by #2458.
Thanks!

Contributor

xcir commented Oct 23, 2017

Before apply patch I got segfault everyday.
But, rev6547893 is running stable for 4days in production.
I think this issue fixed by #2458.
Thanks!

@daghf daghf closed this in #2458 Oct 23, 2017

daghf added a commit that referenced this issue Oct 23, 2017

Move the req-specific PRIV pointers to struct req
Keeping these in struct sess would necessitate extra locking for h/2
where we have multiple reqs in flight concurrently.

Fixes: #2268
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment