search

varnishcache / varnish-cache

Varnish Cache source code repository
https://www.varnish-cache.org
Other
3.68k stars 377 forks source link

Assert error in H2_Send(), http2/cache_http2_send.c line 293: #2931

Closed simonvik closed 5 years ago

simonvik commented 5 years ago 
Assert error in H2_Send(), http2/cache_http2_send.c line 293:
  Condition(h2->open_streams > 0) not true.
version = varnish-trunk revision bf55b2fcdb544bb8c2c95a992e3111123c820723, vrt api = 9.0
ident = Linux,4.4.79-20170906-1335-7b4d138,x86_64,-junix,-smalloc,-sdefault,-hcritbit,epoll
now = 41140155.228798 (mono), 1551950295.747337 (real)
Backtrace:
  0x43c5b8: /usr/sbin/varnishd() [0x43c5b8]
  0x49eb80: /usr/sbin/varnishd(VAS_Fail+0x40) [0x49eb80]
  0x46faac: /usr/sbin/varnishd(H2_Send+0x52c) [0x46faac]
  0x468e50: /usr/sbin/varnishd() [0x468e50]
  0x421ee6: /usr/sbin/varnishd(VDP_close+0x66) [0x421ee6]
  0x469bbe: /usr/sbin/varnishd(h2_deliver+0x46e) [0x469bbe]
  0x44144a: /usr/sbin/varnishd(CNT_Request+0x12da) [0x44144a]
  0x46b248: /usr/sbin/varnishd(h2_do_req+0x68) [0x46b248]
  0x45baec: /usr/sbin/varnishd() [0x45baec]
  0x45bfb0: /usr/sbin/varnishd() [0x45bfb0]
thread = (cache-worker)
pthread.attr = {
  guard = 4096,
  stack_bottom = 0x7f6a64152000,
  stack_top = 0x7f6a64183000,
  stack_size = 200704,
}
thr.req = 0x7f6a4e73d020 {
  vxid = 3473690, transport = H2
  step = R_STP_TRANSMIT,
  req_body = R_BODY_NONE,
  restarts = 0, esi_level = 0,
  sp = 0x7f6a6ec2fc20 {
    fd = 317, vxid = 3473625,
    t_open = 1551950291.901002,
    t_idle = 1551950295.739829,
    ws = 0x7f6a6ec2fc60 {
      id = \"ses\",
      {s, f, r, e} = {0x7f6a6ec2fc98, +248, (nil), +352},
    },
    transport = H2 {
      streams {
        0x00000000 idle  
        0x00000043 closed
        0x00000045 closed
        0x00000047 closed
        0x00000049 closed
        0x0000004b closed
        0x00000051 closed
        0x00000053 closed
        0x00000057 closed
        0x00000059 closed
        0x0000005b closed
        0x0000005d closed
        0x0000005f closed
        0x00000061 closed
        0x00000063 closed
        0x00000065 closed
        0x00000067 closed
        0x00000069 closed
        0x0000006b closed
        0x0000006d closed
        0x0000006f closed
        0x00000071 closed
        0x00000073 closed
        0x00000075 closed
        0x00000077 closed
        0x00000079 closed
        0x0000007b closed
        0x0000007d closed
        0x0000007f closed
        0x00000081 c-rem 
        0x00000083 closed
        0x00000085 closed
      }
    }
    client = ************** 54272 127.0.0.1:81,
  },
  worker = 0x7f6a64181de0 {
    ws = 0x7f6a64181e88 {
      id = \"wrk\",
      {s, f, r, e} = {0x7f6a641813d0, +0, (nil), +2040},
    },
    VCL::method = DELIVER,
    VCL::return = deliver,
    VCL::methods = {RECV, PASS, HASH, DELIVER},
  },
  ws = 0x7f6a4e73d170 {
    id = \"req\",
    {s, f, r, e} = {0x7f6a4e73f0b0, +1248, (nil), +122696},
  },
  http_conn = 0x7f6a4e73f050 {
    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] = 0x7f6a4e73d218 {
    ws = 0x7f6a4e73d170 {
      [Already dumped, see above]
    },
    hdrs {
      \"GET\",
      \"**************",
      \"HTTP/2.0\",
      \"scheme: https\",
      \"host: **************\",
      \"cookie: PHPSESSID=**************\",
      \"accept: text/css,*/*;q=0.1\",
      \"accept-encoding: br, gzip, deflate\",
      \"**************",
      \"accept-language: nl-be\",
      \"referer: **************/\",
      \"X-Forwarded-For: **************\",
      \"X-Onecom-Forwarded-IP: **************\",
      \"X-Onecom-Forwarded-Proto: https\",
      \"X-Forwarded-Proto: https\",
      \"X-Onecom-Host: **************\",
    },
  },
  http[resp] = 0x7f6a4e73db08 {
    ws = 0x7f6a4e73d170 {
      [Already dumped, see above]
    },
    hdrs {
      \"HTTP/1.1\",
      \"200\",
      \"OK\",
      \"Date: Thu, 07 Mar 2019 09:18:15 GMT\",
      \"Server: Apache\",
      \"Last-Modified: Wed, 29 Aug 2018 15:15:11 GMT\",
      \"**************\"\",
      \"Accept-Ranges: bytes\",
      \"Vary: Accept-Encoding\",
      \"Content-Encoding: gzip\",
      \"Content-Length: 19876\",
      \"Content-Type: text/css\",
      \"X-Varnish: 3473690\",
      \"Age: 0\",
      \"Via: 1.1 varnish (Varnish/6.1)\",
    },
  },
  vdc = 0x7f6a4e73f028 {
    nxt = 0x7f6a4e73f568,
    retval = 0,
    filters = {
      H2B = 0x7f6a4e73f568 { priv = 0x7f6a4e73f0b0 }
    },
  },
  vcl = {
    name = \"boot\",
    busy = 609,
    discard = 0,
    state = auto,
    temp = warm,
    conf = {
      syntax = \"41\",
      srcname = {
        \"/etc/varnish/onecom.vcl\",
        \"Builtin\",
        \"/etc/varnish/vmods.vcl\",
        \"/etc/varnish/backends/backends.vcl\",
        \"/etc/varnish/backends/directors.vcl\",
        \"/etc/varnish/core/ext_log.vcl\",
        \"/etc/varnish/core/error.vcl\",
        \"/etc/varnish/core/core.vcl\",
        \"/etc/varnish/core/modules.vcl\",
        \"/etc/varnish/core/modules/purge.vcl\",
        \"/etc/varnish/core/modules/security.vcl\",
        \"/etc/varnish/core/modules/mailconfig.vcl\",
        \"/etc/varnish/core/modules/remove_cookies.vcl\",
        \"/etc/varnish/core/modules/debug.vcl\",
        \"/etc/varnish/core/modules/devicedetect.vcl\",
        \"/etc/varnish/core/modules/subs.vcl\",
        \"/etc/varnish/app.vcl\",
        \"/etc/varnish/apps/apps_recv.vcl\",
        \"/etc/varnish/apps_status.vcl\",
        \"/etc/varnish/apps/diagnostics/recv.vcl\",
        \"/etc/varnish/apps_status.vcl\",
        \"/etc/varnish/apps/iloapp/recv.vcl\",
        \"/etc/varnish/apps_status.vcl\",
        \"/etc/varnish/apps/iloapps/recv.vcl\",
        \"/etc/varnish/apps_status.vcl\",
        \"/etc/varnish/apps/gallery/recv.vcl\",
        \"/etc/varnish/apps_status.vcl\",
        \"/etc/varnish/apps/cookies/recv.vcl\",
        \"/etc/varnish/apps_status.vcl\",
        \"/etc/varnish/apps/impro/recv.vcl\",
        \"/etc/varnish/apps_status.vcl\",
        \"/etc/varnish/apps/webcluster/recv.vcl\",
        \"/etc/varnish/customer_rules/customer_recv.vcl\",
        \"/etc/varnish/apps/apps_backend_response.vcl\",
        \"/etc/varnish/apps/iloapps/backend_response.vcl\",
        \"/etc/varnish/apps/webcluster/backend_response.vcl\",
        \"/etc/varnish/customer_rules/customer_backend_response.vcl\",
        \"/etc/varnish/apps/apps_hash.vcl\",
        \"/etc/varnish/apps/iloapps/hash.vcl\",
        \"/etc/varnish/apps/webcluster/hash.vcl\",
        \"/etc/varnish/apps/apps_synth.vcl\",
        \"/etc/varnish/apps/cookies/synth.vcl\",
        \"/etc/varnish/apps/apps_backend_error.vcl\",
        \"/etc/varnish/apps/webcluster/backend_error.vcl\",
        \"/etc/varnish/apps/apps_deliver.vcl\",
        \"/etc/varnish/apps/webcluster/deliver.vcl\",
      },
    },
  },
  objcore[REQ] = 0x7f6a7f4d8dc0 {
    refcnt = 1,
    flags = {hfm, private},
    exp_flags = {},
    boc = 0x7f6a7f4d95c0 {
      refcnt = 1,
      state = finished,
      vary = (nil),
      stevedore_priv = (nil),
    },
    exp = {1551950295.746464, 3600.000000, 0.000000, 0.000000},
    objhead = 0x7f6abe910080,
    stevedore = 0x7f6abe8d73c0 (malloc Transient) {
      Simple = 0x7f6a375c6000,
      Obj = 0x7f6957045568 {priv=0x7f6957045560, ptr=0x7f6a375c6000, len=504, space=504},
      LEN = 0x0000000000004da4,
      VXID = 0x008b80f1,
      FLAGS = 0x02,
      GZIPBITS = 0x000000000000005000000000000000500000000000026cd90000000000027de3,
      LASTMODIFIED = 0x41d6e1ae1fc00000,
      VARY = {len=0, ptr=(nil)},
      HEADERS = {len=384, ptr=0x7f6a375c6078},
      Body = 0x7f69573fd1a8 {priv=0x7f69573fd1a0, ptr=0x7f6a6fe17000, len=19876, space=19876},
    },
  },
  flags = {
  },
  privs = 0x7f6a4e73d200 {
  },
  topreq = {
    req = 0x7f6a4e73d020 {
      [Already dumped, see above]
    },
  },
},
thr.busyobj = (nil) {
},
vmods = {
  std = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 0.0},
  one = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 0.0},
  maxminddb = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 0.0},
  directors = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 0.0},
  xkey = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 0.0},
  header = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 9.0},
  cookie = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 9.0},
  vsthrottle = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 9.0},
  tcp = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 0.0},
  bodyaccess = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 0.0},
  blob = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 0.0},
},

Varnish running from revision : bf55b2fcdb544bb8c2c95a992e3111123c820723 Varnish running on ubuntu bionic userspace, custom kernel.

nm -an /usr/sbin/varnishd : nm_bf55b2fcdb544bb8c2c95a992e3111123c820723.txt

simonvik commented 5 years ago

I saw this across all our servers, now downgraded.

xcir commented 5 years ago

I got same problem.

Panic at: Thu, 07 Mar 2019 14:24:37 GMT
Assert error in H2_Send(), http2/cache_http2_send.c line 293:
  Condition(h2->open_streams > 0) not true.
version = varnish-trunk revision bf55b2fcdb544bb8c2c95a992e3111123c820723, vrt api = 9.0
ident = Linux,4.13.0-19-generic,x86_64,-junix,-smalloc,-sfile,-sfile,-sdefault,-hcritbit,epoll
now = 16357838.273350 (mono), 1551968677.509470 (real)
Backtrace:
  0x43c5b8: /usr/sbin/varnishd() [0x43c5b8]
  0x49eb80: /usr/sbin/varnishd(VAS_Fail+0x40) [0x49eb80]
  0x46faac: /usr/sbin/varnishd(H2_Send+0x52c) [0x46faac]
  0x468e50: /usr/sbin/varnishd() [0x468e50]
  0x421ee6: /usr/sbin/varnishd(VDP_close+0x66) [0x421ee6]
  0x469bbe: /usr/sbin/varnishd(h2_deliver+0x46e) [0x469bbe]
  0x44144a: /usr/sbin/varnishd(CNT_Request+0x12da) [0x44144a]
  0x46b248: /usr/sbin/varnishd(h2_do_req+0x68) [0x46b248]
  0x45baec: /usr/sbin/varnishd() [0x45baec]
  0x45bfb0: /usr/sbin/varnishd() [0x45bfb0]
thread = (cache-worker)
pthread.attr = {
  guard = 4096,
  stack_bottom = 0x7f6b888f3000,
  stack_top = 0x7f6b888ff000,
  stack_size = 49152,
}
thr.req = 0x7f61e916a020 {
  vxid = 5676775, transport = H2
  step = R_STP_TRANSMIT,
  req_body = R_BODY_NONE,
  restarts = 0, esi_level = 0,
  sp = 0x7f61edf22a20 {
    fd = 136, vxid = 5676739,
    t_open = 1551968672.555521,
    t_idle = 1551968677.488201,
    ws = 0x7f61edf22a60 {
      id = \"ses\",
      {s, f, r, e} = {0x7f61edf22a98, +224, (nil), +352},
    },
    transport = H2 {
      streams {
        0x00000000 idle
        0x00000043 closed
        0x00000045 closed
        0x00000047 c-rem
      }
    }
    client = *** 57478 127.0.0.1:88,
  },
  worker = 0x7f6b888fdde0 {
    ws = 0x7f6b888fde88 {
      id = \"wrk\",
      {s, f, r, e} = {0x7f6b888fd3d0, +0, (nil), +2040},
    },
    VCL::method = DELIVER,
    VCL::return = deliver,
    VCL::methods = {RECV, HASH, MISS, DELIVER},
  },
  ws = 0x7f61e916a170 {
    id = \"req\",
    {s, f, r, e} = {0x7f61e916c0b0, +1776, (nil), +122696},
  },
  http_conn = 0x7f61e916c050 {
    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] = 0x7f61e916a218 {
    ws = 0x7f61e916a170 {
      [Already dumped, see above]
    },
    hdrs {
      \"GET\",
     ...
      \"Accept-Encoding: gzip\",
    },
  },
  http[resp] = 0x7f61e916ab08 {
    ws = 0x7f61e916a170 {
      [Already dumped, see above]
    },
    hdrs {
      \"HTTP/1.1\",
      \"200\",
      \"OK\",
      ...
      \"Accept-Ranges: bytes\",
    },
  },
  vdc = 0x7f61e916c028 {
    nxt = 0x7f61e916c778,
    retval = 0,
    filters = {
      H2B = 0x7f61e916c778 { priv = 0x7f61e916c0b0 }
    },
  },
  vcl = {
    name = \"reload_20190307_130923_21089\",
    busy = 137,
    discard = 0,
    state = auto,
    temp = warm,
    conf = {
      syntax = \"40\",
      srcname = {
        \"/etc/varnish/default.vcl\",
        \"Builtin\",
        \"/etc/varnish/health.vcl\",
        \"/etc/varnish/banip.vcl\",
        \"/etc/varnish/define.vcl\",
        \"/etc/varnish/auth.vcl\",
        \"/etc/varnish/prefilter.vcl\",
        \"/etc/varnish/ext.vcl\",
        \"/etc/varnish/ext_**.vcl\",
        \"/etc/varnish/ext_**.vcl\",
        \"/etc/varnish/ext_**.vcl\",
        \"/etc/varnish/ext_**.vcl\",
        \"/etc/varnish/main.vcl\",
      },
    },
  },
  objcore[REQ] = 0x7f61ee22e200 {
    refcnt = 2,
    flags = {},
    exp_flags = {refd},
    exp = {1551968677.493840, 2419200.000000, 3600.000000, 0.000000},
    objhead = 0x7f61e1be5940,
    stevedore = 0x7f6b90cd7480 (file file2) {
      Simple = 0x7f6808019000,
      Obj = 0x7f61e75c5c48 {priv=0x7f61e75c5c40, ptr=0x7f6808019000, len=611, space=4096},
      LEN = 0x000000000004cd48,
      VXID = 0x008d19de,
      FLAGS = 0x18,
      GZIPBITS = 0x0...0,
      LASTMODIFIED = 0x41d6c077b2800000,
      VARY = {len=27, ptr=0x7f6808019078},
      HEADERS = {len=464, ptr=0x7f6808019093},
      Body = 0x7f61f2d371a8 {priv=0x7f61f2d371a0, ptr=0x7f6813a70000, len=314696, space=315392},
    },
  },
  flags = {
  },
  privs = 0x7f61e916a200 {
  },
  topreq = {
    req = 0x7f61e916a020 {
      [Already dumped, see above]
    },
  },
},
thr.busyobj = (nil) {
},
vmods = {
  std = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 0.0},
  directors = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 0.0},
  vsthrottle = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 9.0},
  cookie = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 9.0},
  tcp = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 0.0},
  digest = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 0.0},
  xcounter = {Varnish trunk bf55b2fcdb544bb8c2c95a992e3111123c820723, 0.0},
},
xcir commented 5 years ago

I added lock to h2_rx_headers. https://gist.github.com/xcir/c7ecc6d68fbbfae5ad0e1d747f24873c 11 hours have passed since apply to the production. But not down. I'll try and see what happens a little more.

simonvik commented 5 years ago

Been running that patch for 1h, no assert, looks a lot better right now