Varnish panic: Assert error in ved_stripgzip(), cache/cache_esi_deliver.c line 774

jonhattan commented 5 years ago

It seems the same as #1953. We're experiencing panics on stress load.

Running varnish:amd64/stretch 6.0.3-1~stretch uptodate. This is the trace:

● varnish.service - Varnish HTTP accelerator
   Loaded: loaded (/etc/systemd/system/varnish.service; enabled; vendor preset: enabled)
  Drop-In: /etc/systemd/system/varnish.service.d
           └─overrides.conf
   Active: active (running) since Wed 2019-02-27 17:27:51 CET; 1h 5min ago
 Main PID: 27028 (varnishd)
   CGroup: /system.slice/varnish.service
           ├─27028 /usr/sbin/varnishd -j unix,user=varnish,ccgroup=varnish -P /var/run/varnish.pid -t 120 -f /etc/varnish/puppet.vcl -a 0.0.0.0:6081 -a 0.0.0.0:6083,PROXY -T 127.0.0.1:6082 -p thread_pool_min=50 -p thread_pool_max=1000 -p thread_pool_timeout=120 -p workspace_backend=128k -S /etc/varnish/secret -s malloc,20G
           └─59276 /usr/sbin/varnishd -j unix,user=varnish,ccgroup=varnish -P /var/run/varnish.pid -t 120 -f /etc/varnish/puppet.vcl -a 0.0.0.0:6081 -a 0.0.0.0:6083,PROXY -T 127.0.0.1:6082 -p thread_pool_min=50 -p thread_pool_max=1000 -p thread_pool_timeout=120 -p workspace_backend=128k -S /etc/varnish/secret -s malloc,20G

Feb 27 17:37:27 cc02 varnishd[27028]: Child (27047) died signal=6
Feb 27 17:37:27 cc02 varnishd[27028]: Child (27047) Panic at: Wed, 27 Feb 2019 16:37:27 GMT
                                      Assert error in ved_stripgzip(), cache/cache_esi_deliver.c line 774:
                                        Condition((dbits) != 0) not true.
                                      version = varnish-6.0.3 revision 7d1ded3aa033a018317dbafc61587026ea2ef8a3, vrt api = 7.0
                                      ident = Linux,4.9.0-8-amd64,x86_64,-junix,-smalloc,-sdefault,-hcritbit,epoll
                                      now = 2502772.181094 (mono), 1551285446.681061 (real)
                                      Backtrace:
                                        0x55759298e987: /usr/sbin/varnishd(+0x4c987) [0x55759298e987]
                                        0x5575929f64b0: /usr/sbin/varnishd(VAS_Fail+0x40) [0x5575929f64b0]
                                        0x557592975af0: /usr/sbin/varnishd(+0x33af0) [0x557592975af0]
                                        0x557592992a09: /usr/sbin/varnishd(CNT_Request+0x2f9) [0x557592992a09]
                                        0x557592975071: /usr/sbin/varnishd(+0x33071) [0x557592975071]
                                        0x557592972246: /usr/sbin/varnishd(VDP_bytes+0x76) [0x557592972246]
                                        0x5575929dbbc1: /usr/sbin/varnishd(+0x99bc1) [0x5575929dbbc1]
                                        0x557592972798: /usr/sbin/varnishd(VDP_DeliverObj+0x38) [0x557592972798]
                                        0x5575929b740e: /usr/sbin/varnishd(V1D_Deliver+0x42e) [0x5575929b740e]
                                        0x557592992a09: /usr/sbin/varnishd(CNT_Request+0x2f9) [0x557592992a09]
                                      thread = (cache-worker)
                                      thr.req = 0x7fd4d32f2020 {
                                        vxid = 984191, transport = ESI_INCLUDE
                                        step = R_STP_TRANSMIT,
                                        req_body = R_BODY_NONE,
                                        restarts = 0, esi_level = 1,
                                        sp = 0x7fd4d95cd220 {
                                          fd = 31, vxid = 984188,
                                          t_open = 1551285445.891885,
                                          t_idle = 1551285445.891885,
                                          ws = 0x7fd4d95cd260 {
                                            id = \"ses\",
                                            {s, f, r, e} = {0x7fd4d95cd298, +216, (nil), +352},
                                          },
                                          transport = HTTP/1 {
                                            state = HTTP1::Proc
                                          }
                                          client = 11.22.33.44 31352 0.0.0.0:6083,
                                        },
                                        worker = 0x7fd4f84efde0 {
                                          ws = 0x7fd4f84efe88 {
                                            id = \"wrk\",
                                            {s, f, r, e} = {0x7fd4f84ef3e0, +264, (nil), +2040},
                                          },
                                          VCL::method = DELIVER,
                                          VCL::return = deliver,
                                          VCL::methods = {RECV, PASS, HASH, DELIVER},
                                        },
                                        ws = 0x7fd4d32f2170 {
                                          OVERFLOWED id = \"Req\",
                                          {s, f, r, e} = {0x7fd4d32f40a8, +57168, (nil), +57168},
                                        },
                                        http_conn = 0x7fd4d32f4048 {
                                          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] = 0x7fd4d32f2210 {
                                          ws = 0x7fd4d32f2170 {
                                            [Already dumped, see above]
                                          },
                                          hdrs {
                                            \"GET\",
                                            \"/index.php?r=Menu/Header\",
                                            \"HTTP/1.1\",
                                            \"cache-control: max-age=0\",
                                            \"origin: https://www.example.com\",
                                            \"upgrade-insecure-requests: 1\",
                                            \"content-type: application/x-www-form-urlencoded\",
                                            \"user-agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.119 Safari/537.36\",
                                            \"accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8\",
                                            \"referer: https://www.example.com/ocasion-land+rover-range+rover+evoque-evoque-22l-ed4-pure-4x2-en-madrid.htm?id=3751304\",
                                            \"accept-language: es-ES,es;q=0.9\",
                                            \"X-Forwarded-Proto: https\",
                                            \"X-Unique-ID: 512B6E4D:7A78_5DBD261E:01BB_5C76BCAE_787F99:2DC5\",
                                            \"Host: www.example.com\",
                                            \"Accept-Encoding: gzip\",
                                            \"X-Varnish-Type-Site: example_site\",
                                            \"X-Forwarded-For: 11.22.33.44\",
                                            \"PS-CapabilityList: fully general optimizations only\",
                                            \"Cookie: cmpCCOM=1; cpolicy=true; AAMC_smc_0=REGION%7C6; aamqualified=seg%3Dtestactivation;\",
                                          },
                                        },
                                        http[resp] = 0x7fd4d32f2b00 {
                                          ws = 0x7fd4d32f2170 {
                                            [Already dumped, see above]
                                          },
                                          hdrs {
                                            \"HTTP/1.1\",
                                            \"200\",
                                            \"OK\",
                                            \"Date: Wed, 27 Feb 2019 16:37:26 GMT\",
                                            \"Server: Apache\",
                                            \"Expires: Thu, 19 Nov 1981 08:52:00 GMT\",
                                            \"Pragma: no-cache\",
                                            \"Vary: Accept-Encoding\",
                                            \"X-Mod-Pagespeed: 1.13.35.2-0\",
                                            \"Content-Type: text/html; charset=UTF-8\",
                                            \"X-Varnish-Cache-Control-Original: no-store, no-cache, must-revalidate, post-check=0, pre-check=0, s-maxage=10\",
                                            \"X-Varnish-Forwarded-Proto: https\",
                                            \"X-Varnish-Ttl-Detected: 0.000\",
                                            \"X-Varnish-Was-304: false\",
                                            \"X-Varnish-Ttl-Processed: 0.000\",
                                            \"X-Varnish-Backend: cc05\",
                                            \"X-Varnish-Cacheable: no:Not Cacheable\",
                                            \"Content-Encoding: gzip\",
                                            \"Via: 1.1 varnish (Varnish/6.0)\",
                                          },
                                        },
                                        vcl = {
                                          name = \"boot\",
                                          busy = 56,
                                          discard = 0,
                                          state = auto,
                                          temp = warm,
                                          conf = {
                                            syntax = \"40\",
                                            srcname = {
                                              \"/etc/varnish/puppet.vcl\",
                                              \"Builtin\",
                                            },
                                          },
                                        },
                                        objcore[REQ] = 0x7fd4cc5d2b00 {
                                          refcnt = 1,
                                          flags = {hfm, private},
                                          exp_flags = {},
                                          exp = {1551285446.680870, -1.000000, 3600.000000, 0.000000},
                                          objhead = 0x7fd4f68de080,
                                          stevedore = 0x7fd4f68d9300 (malloc Transient) {
                                            Simple = 0x7fd4e08e7080,
                                            Obj = 0x7fd4e090bba8 {priv=0x7fd4e090bba0, ptr=0x7fd4e08e7080, len=800, space=800},
                                            LEN = 0x0000000000000284,
                                            VXID = 0x000f0480,
                                            FLAGS = 0x16,
                                            GZIPBITS = 0x000000000000005000000000000013d000000000000013da0000000000000502,
                                            LASTMODIFIED = 0x41d71daf31800000,
                                            VARY = {len=0, ptr=(nil)},
                                            HEADERS = {len=680, ptr=0x7fd4e08e70f8},
                                            Body = 0x7fd4e090bbf8 {priv=0x7fd4e090bbf0, ptr=0x7fd4c7465580, len=628, space=628},
                                            Body = 0x7fd4e090bc98 {priv=0x7fd4e090bc90, ptr=0x7fd4e2ccfd90, len=16, space=16},
                                          },
                                        },
                                        flags = {
                                        },
                                        privs = 0x7fd4d32f21f8 {
                                        },
                                      },
                                      thr.busyobj = (nil) {
                                      },
                                      vmods = {
                                        std = {Varnish 6.0.3 7d1ded3aa033a018317dbafc61587026ea2ef8a3, 0.0},
                                        directors = {Varnish 6.0.3 7d1ded3aa033a018317dbafc61587026ea2ef8a3, 0.0},
                                      },
Feb 27 17:37:27 cc02 varnishd[27028]: Child cleanup complete
Feb 27 17:37:27 cc02 varnishd[27028]: Child (33569) Started
Feb 27 17:37:27 cc02 varnishd[27028]: Child (33569) said Child starts
Feb 27 18:24:11 cc02 varnishd[27028]: Child (33569) died signal=6
Feb 27 18:24:11 cc02 varnishd[27028]: Child (33569) Panic at: Wed, 27 Feb 2019 17:24:11 GMT
                                      Assert error in ved_stripgzip(), cache/cache_esi_deliver.c line 774:
                                        Condition((dbits) != 0) not true.
                                      version = varnish-6.0.3 revision 7d1ded3aa033a018317dbafc61587026ea2ef8a3, vrt api = 7.0
                                      ident = Linux,4.9.0-8-amd64,x86_64,-junix,-smalloc,-sdefault,-hcritbit,epoll
                                      now = 2505577.002426 (mono), 1551288251.502393 (real)
                                      Backtrace:
                                        0x55759298e987: /usr/sbin/varnishd(+0x4c987) [0x55759298e987]
                                        0x5575929f64b0: /usr/sbin/varnishd(VAS_Fail+0x40) [0x5575929f64b0]
                                        0x557592975af0: /usr/sbin/varnishd(+0x33af0) [0x557592975af0]
                                        0x557592992a09: /usr/sbin/varnishd(CNT_Request+0x2f9) [0x557592992a09]
                                        0x557592975071: /usr/sbin/varnishd(+0x33071) [0x557592975071]
                                        0x557592972246: /usr/sbin/varnishd(VDP_bytes+0x76) [0x557592972246]
                                        0x5575929dbbc1: /usr/sbin/varnishd(+0x99bc1) [0x5575929dbbc1]
                                        0x557592972798: /usr/sbin/varnishd(VDP_DeliverObj+0x38) [0x557592972798]
                                        0x5575929b740e: /usr/sbin/varnishd(V1D_Deliver+0x42e) [0x5575929b740e]
                                        0x557592992a09: /usr/sbin/varnishd(CNT_Request+0x2f9) [0x557592992a09]
                                      thread = (cache-worker)
                                      thr.req = 0x7fd479dae020 {
                                        vxid = 4755685, transport = ESI_INCLUDE
                                        step = R_STP_TRANSMIT,
                                        req_body = R_BODY_NONE,
                                        restarts = 0, esi_level = 1,
                                        sp = 0x7fd4d66fa620 {
                                          fd = 22, vxid = 4755682,
                                          t_open = 1551288251.232370,
                                          t_idle = 1551288251.232370,
                                          ws = 0x7fd4d66fa660 {
                                            id = \"ses\",
                                            {s, f, r, e} = {0x7fd4d66fa698, +216, (nil), +352},
                                          },
                                          transport = HTTP/1 {
                                            state = HTTP1::Proc
                                          }
                                          client = 11.22.33.44 39043 0.0.0.0:6083,
                                        },
                                        worker = 0x7fd4f85b6de0 {
                                          ws = 0x7fd4f85b6e88 {
                                            id = \"wrk\",
                                            {s, f, r, e} = {0x7fd4f85b63e0, +264, (nil), +2040},
                                          },
                                          VCL::method = DELIVER,
                                          VCL::return = deliver,
                                          VCL::methods = {RECV, PASS, HASH, MISS, DELIVER},
                                        },
                                        ws = 0x7fd479dae170 {
                                          OVERFLOWED id = \"Req\",
                                          {s, f, r, e} = {0x7fd479db00a8, +57168, (nil), +57168},
                                        },
                                        http_conn = 0x7fd479db0048 {
                                          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] = 0x7fd479dae210 {
                                          ws = 0x7fd479dae170 {
                                            [Already dumped, see above]
                                          },
                                          hdrs {
                                            \"GET\",
                                            \"/index.php?r=Menu/Header\",
                                            \"HTTP/1.1\",
                                            \"upgrade-insecure-requests: 1\",
                                            \"user-agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.119 Safari/537.36\",
                                            \"accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8\",
                                            \"referer: https://office.example.com/index.php?r=used/stock/showStock&Car%5Bid%5D=&Car%5Busuario_id%5D=&Car%5Bperfil_concesionario_id%5D=2512&Car%5Btipo_usuario%5D=&Car%5BsearchByPack%5D=&Car%5Boferta%5D=0&Car%5BsearchByStatus%5D=2&Car%5BsearchFeeders%5D=&Car%5BsearchTypeStatusCar%5D=&Car%5BsearchMake%5D=25&Car%5BsearchModel%5D=Corsa&Car%5BsearchFuel%5D=&Car%5BsearchProvince%5D=&Car%5BsearchKmsMin%5D=&Car%5BsearchKmsMax%5D=&Car%5BsearchPriceMin%5D=&Car%5BsearchPriceMax%5D=&Car%5BsearchDealerEnableRequestCRM%5D=&Car%5BsearchYearMin%5D=&Car%5BsearchYearMax%5D=&Car%5BsearchEntryDateMin%5D=&Car%5BsearchEntryDateMax%5D=&Car%5BsearchDaysToDie%5D=&yt0=&Province_page=1&Car_sort=precio\",
                                            \"accept-language: es-ES,es;q=0.9\",
                                            \"X-Forwarded-Proto: https\",
                                            \"X-Unique-ID: 512B6E4D:9883_5DBD261E:01BB_5C76C7B5_852BDA:2DC5\",
                                            \"Host: www.example.com\",
                                            \"Accept-Encoding: gzip\",
                                            \"X-Varnish-Type-Site: example_site\",
                                            \"X-Forwarded-For: 11.22.33.44\",
                                            \"PS-CapabilityList: fully general optimizations only\",
                                            \"Cookie: cmpCCOM=1; cpolicy=true; AAMC_smc_0=REGION%7C6; aamqualified=seg%3Dtestactivation; _fbp=fb.1.1549287885689.1467746805; hblid=slCcS1IxvzjOYXWU2Z4zU0OaoAaQX2zK; olfsk=olfsk1597248023120641; _gaexp=GAX1.2.0sgkuM1hQfyr85ZjHeY07Q.18041.1; _gid=GA1.2.2144829004.1551105418; user_transaction_ids=VO635769,VO635770,VO635772,VO635773,VO635787,VO635790,VO635792,VO635824,VO635825,VO636086,VO636088,VO636160; AMCVS_5E9632D35B153B730A495C32%40AdobeOrg=1; AMCV_5E9632D35B153B730A495C32%40AdobeOrg=-1007959592%7CMCIDTS%7C17955%7CMCMID%7C73194777901148220712861269403888614777%7CMCAAMLH-1551880279%7C6%7CMCAAMB-1551880279%7CRKhpRz8krg2tLO6pguXWp5olkAcUniQYPHaMWWgdJ3xzPWQmdj0y%7CMCOPTOUT-1551282679s%7CNONE%7CvVersion%7C4.0.0; SESSID=eb2ar9rcf92ictejaa6uklare0; _gat_UA-1183189-9=1\",
                                          },
                                        },
                                        http[resp] = 0x7fd479daeb00 {
                                          ws = 0x7fd479dae170 {
                                            [Already dumped, see above]
                                          },
                                          hdrs {
                                            \"HTTP/1.1\",
                                            \"200\",
                                            \"OK\",
                                            \"Date: Wed, 27 Feb 2019 17:24:11 GMT\",
                                            \"Server: Apache\",
                                            \"Expires: Thu, 19 Nov 1981 08:52:00 GMT\",
                                            \"Pragma: no-cache\",
                                            \"Vary: Accept-Encoding\",
                                            \"X-Mod-Pagespeed: 1.13.35.2-0\",
                                            \"Content-Type: text/html; charset=UTF-8\",
                                            \"X-Varnish-Cache-Control-Original: no-store, no-cache, must-revalidate, post-check=0, pre-check=0, s-maxage=10\",
                                            \"X-Varnish-Forwarded-Proto: https\",
                                            \"X-Varnish-Ttl-Detected: 0.000\",
                                            \"X-Varnish-Was-304: false\",
                                            \"X-Varnish-Ttl-Processed: 0.000\",
                                            \"X-Varnish-Backend: cc05\",
                                            \"X-Varnish-Cacheable: no:Not Cacheable\",
                                            \"Content-Encoding: gzip\",
                                            \"Via: 1.1 varnish (Varnish/6.0)\",
                                          },
                                        },
                                        vcl = {
                                          name = \"boot\",
                                          busy = 74,
                                          discard = 0,
                                          state = auto,
                                          temp = warm,
                                          conf = {
                                            syntax = \"40\",
                                            srcname = {
                                              \"/etc/varnish/puppet.vcl\",
                                              \"Builtin\",
                                            },
                                          },
                                        },
                                        objcore[REQ] = 0x7fd4915d6e80 {
                                          refcnt = 1,
                                          flags = {hfm, private},
                                          exp_flags = {},
                                          exp = {1551288251.502208, -1.000000, 3600.000000, 0.000000},
                                          objhead = 0x7fd4f68de080,
                                          stevedore = 0x7fd4f68d9300 (malloc Transient) {
                                            Simple = 0x7fd48e8b5800,
                                            Obj = 0x7fd47fa3d568 {priv=0x7fd47fa3d560, ptr=0x7fd48e8b5800, len=800, space=800},
                                            LEN = 0x0000000000000284,
                                            VXID = 0x004890e6,
                                            FLAGS = 0x16,
                                            GZIPBITS = 0x000000000000005000000000000013d000000000000013da0000000000000502,
                                            LASTMODIFIED = 0x41d71db1eec00000,
                                            VARY = {len=0, ptr=(nil)},
                                            HEADERS = {len=680, ptr=0x7fd48e8b5878},
                                            Body = 0x7fd47fa3d5b8 {priv=0x7fd47fa3d5b0, ptr=0x7fd48c8a8980, len=628, space=628},
                                            Body = 0x7fd47fa3d4c8 {priv=0x7fd47fa3d4c0, ptr=0x7fd4ef420800, len=16, space=16},
                                          },
                                        },
                                        flags = {
                                        },
                                        privs = 0x7fd479dae1f8 {
                                        },
                                      },
                                      thr.busyobj = (nil) {
                                      },
                                      vmods = {
                                        std = {Varnish 6.0.3 7d1ded3aa033a018317dbafc61587026ea2ef8a3, 0.0},
                                        directors = {Varnish 6.0.3 7d1ded3aa033a018317dbafc61587026ea2ef8a3, 0.0},
                                      },
Feb 27 18:24:11 cc02 varnishd[27028]: Child cleanup complete
Feb 27 18:24:11 cc02 varnishd[27028]: Child (59276) Started
Feb 27 18:24:11 cc02 varnishd[27028]: Child (59276) said Child starts

jonhattan commented 5 years ago

This is the relevant part of our systemd unit:

ExecStart=/usr/sbin/varnishd -j unix,user=varnish,ccgroup=varnish \
  -P /var/run/varnish.pid \
  -t 120 \
  -f /etc/varnish/puppet.vcl \
    -a 0.0.0.0:6081 -a 0.0.0.0:6083,PROXY \
    -T 127.0.0.1:6082 \
  -p thread_pool_min=50 \
  -p thread_pool_max=1000 \
  -p thread_pool_timeout=120 \
  -p workspace_backend=128k \
  -S /etc/varnish/secret \
  -s malloc,20G \

Upon more investigation on the code, the assert that fails is

773   dbits = WS_Alloc(req->ws, 8);
774   AN(dbits);

And the backtrace says:

ws = 0x7fd4d32f2170 {
  OVERFLOWED id = \"Req\",
  {s, f, r, e} = {0x7fd4d32f40a8, +57168, (nil), +57168},

We already have workspace_backend=128k. We'll increase its size to test again and report back.

nigoroll commented 5 years ago

notice this is workspace_client overflowing.

nigoroll commented 5 years ago

Also the panic is fixed in 3fbdda3d7335e806dd22ebde49a6fb7ceda6e14a, so not relevant for master

jonhattan commented 5 years ago

@nigoroll thanks! With workspace_client at 128KB we've not seen panics in three hours of stress load.

Is it planned to backport 3fbdda3 to 6.x?

nigoroll commented 5 years ago

@Dridi can you answer the backport question

rezan commented 4 years ago

Kind of on the fence if this meets the threshold for backporting, which is currently bug fixes and features. This looks like a workspace issue. Do we have more data on how problematic this exact workspace allocation is?

nigoroll commented 4 years ago

@rezan @jonhattan can we close this issue?

rezan commented 4 years ago

yes, ok to close. I have marked this as a possible backport candidate, but no final decision has been made.

jonhattan commented 4 years ago

Thanks both! We've not experienced any problem since we increased workspace_client to 128KB

varnishcache / varnish-cache

Varnish panic: Assert error in ved_stripgzip(), cache/cache_esi_deliver.c line 774 #2922