Bug : Assert error in exp_timer() | (same bug, different log)

[Benjamin Sonntag]

Hi all,

I just had another crash on the same varnish server with the following
log :

Needless to say that I'm quite lost ...

I hope that all this log means nothing and that the really important
issue here is "not responding to ping, killing it." Maybe all the rest
is only a consequence of the killing of the child ?

As I put fairly big values for the child check timeouts and counts, I
guess it's not normal that a child stayed like that, waiting for
anything ...

Is there a way to debug it properly ?

Regards,

Benjamin Sonntag


Dec 15 19:39:46 cache1b varnishd[63966]: Child (30657) not responding to
ping, killing it.
Dec 15 19:39:46 cache1b varnishd[63966]: Child (30657) died signal=6
Dec 15 19:39:46 cache1b varnishd[63966]: Child (30657) Panic message:
Assert error in EXP_Rearm(), cache_expire.c line 242:  
Condition(oe->timer_idx != BINHEAP_NOIDX) not true.  t
hread = (cache-worker)sp = 0x7f25cc591008 {   fd = 1135, id = 1135, xid
= 714117855,   client = 192.168.131.9:33717,   step = STP_LOOKUP,  
handling = HASH,   ws = 0x7f25cc591078 {
      id = "sess",     {s,f,r,e} = {0x7f25cc5917b0,,+388,(nil),+8192},  
},     worker = 0x7f26168fdcb0 {     },     vcl = {       srcname =
{         "/etc/varnish/default.vcl", 
       "Default",       },     }, }, 
Dec 15 19:39:46 cache1b varnishd[63966]: Child cleanup complete
Dec 15 19:39:46 cache1b varnishd[63966]: child (24332) Started
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said Closed fds:
4 5 6 10 11 13 14
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said Child starts
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said managed to
mmap 68719476736 bytes of 68719476736
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said Ready
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said Probe("GET
/search/C=?definition=homepage HTTP/1.1^M
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said Host:
192.168.131.102^M
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said Connection:
close^M
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said ^M
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said ", 4, 1)
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said Probe("GET
/search/C=?definition=homepage HTTP/1.1^M
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said Host:
192.168.131.101^M
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said Connection:
close^M
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said ^M
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said ", 4, 1)
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said Probe("GET
/search/C=?definition=homepage HTTP/1.1^M
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said Host:
192.168.131.107^M
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said Connection:
close^M
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said ^M
Dec 15 19:39:46 cache1b varnishd[63966]: Child (24332) said ", 4, 1)