[Varnish] #1369: Spinning thread while esi+gzip fetch

[Varnish]

#1369: Spinning thread while esi+gzip fetch
----------------------+-------------------
 Reporter:  lkarsten  |      Owner:
     Type:  defect    |     Status:  new
 Priority:  normal    |  Milestone:
Component:  varnishd  |    Version:  3.0.4
 Severity:  normal    |   Keywords:
----------------------+-------------------
 We've recently seen that a backend fetch for ESI enabled Gzip-ed content
 can get stuck and consume 100% CPU.
 Remaining threads are working fine, but this fetch never finishes.

 GDB backtrace of the spinning thread:

 {{{
 Thread 102 (Thread 0x7eff6149c700 (LWP 2664)):
 #0  inflate (strm=0x7effabb049f8, flush=0) at inflate.c:1233
         next = 0x7eff614813e8 "[ -- CUT -- ]"...
         put = 0x0
         have = 2199
         left = 32768
         hold = <value optimized out>
         bits = <value optimized out>
         in = 0
         out = 0
         copy = 28932
         from = 0x7eff614782b0 "[ -- CUT -- ]"...
         len = 0
         ret = 1
         hbuf = "ȺHa"
         order = {16, 17, 18, 0, 8, 7, 9, 6, 10, 5, 11, 4, 12, 3, 13, 2,
 14, 1, 15}
 #1  0x0000000000424998 in VGZ_Gunzip (vg=0x7effabb049c0,
 pptr=0x7eff61488300, plen=0x7eff61488308) at cache_gzip.c:290
         i = <value optimized out>
         l = <value optimized out>
         before = 0x7eff614782b0 "[ -- CUT -- ]"...
         __func__ = "VGZ_Gunzip"
 #2  0x000000000041cb4e in vfp_esi_bytes_gg (sp=0x7eff20e02008,
 htc=0x7eff6149bc90, bytes=6591) at cache_esi_fetch.c:275
         w = 6591
         vef = 0x7eff210d7040
         dl = 0
         dp = 0x0
         i = <value optimized out>
         __func__ = "vfp_esi_bytes_gg"
 #3  0x000000000041d64e in vfp_esi_bytes (sp=0x7eff20e02008,
 htc=0x7eff6149bc90, bytes=6591) at cache_esi_fetch.c:348
         i = <value optimized out>
         i = <value optimized out>
         __func__ = "vfp_esi_bytes"
 #4  0x000000000042329e in fetch_chunked (sp=0x7eff20e02008) at
 cache_fetch.c:335
         __func__ = "fetch_chunked"
 #5  FetchBody (sp=0x7eff20e02008) at cache_fetch.c:570
         cls = 0
         st = <value optimized out>
         w = 0x7eff6149ba90
         mklen = <value optimized out>
         cl = <value optimized out>
         __func__ = "FetchBody"
 #6  0x00000000004166b8 in cnt_fetchbody (sp=0x7eff20e02008) at
 cache_center.c:868
         i = <value optimized out>
         hp = 0x7eff61489140
         hp2 = <value optimized out>
         b = 0x7eff61489bae "Thu, 31 Oct 2013 03:00:27 +0000"
         nhttp = 20
         l = <value optimized out>
         vary = 0x0
         varyl = 0
         pass = 1
         __func__ = "cnt_fetchbody"
 #7  0x0000000000418d50 in CNT_Session (sp=0x7eff20e02008) at steps.h:42
         done = 0
         __func__ = "CNT_Session"
 }}}

 Three backtraces are available. The second is similar with the thread at
 line 1232 in inflate.c, the third follows:

 {{{
 Thread 102 (Thread 0x7eff6149c700 (LWP 2664)):
 #0  vfp_esi_bytes_gg (sp=0x7eff20e02008, htc=0x7eff6149bc90, bytes=6591)
 at cache_esi_fetch.c:279
         w = 6591
         vef = 0x7eff210d7040
         dl = 0
         dp = 0x7eff614782b0
         i = 1
         __func__ = "vfp_esi_bytes_gg"
 #1  0x000000000041d64e in vfp_esi_bytes (sp=0x7eff20e02008,
 htc=0x7eff6149bc90, bytes=6591) at cache_esi_fetch.c:348
         i = <value optimized out>
         __func__ = "vfp_esi_bytes"
 #2  0x000000000042329e in fetch_chunked (sp=0x7eff20e02008) at
 cache_fetch.c:335
         __func__ = "fetch_chunked"
 #3  FetchBody (sp=0x7eff20e02008) at cache_fetch.c:570
         cls = 0
         st = <value optimized out>
         w = 0x7eff6149ba90
         mklen = <value optimized out>
         cl = <value optimized out>
         __func__ = "FetchBody"
 [..]
 }}}

 A PCAP of the bitstream is available on request.

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