Mailing List Archive

Bug Report..can't use Trac tickets
Sorry for the list intrusion. Registered with Trac as "xing" but I don't
have the rights to submit a bug ticket according to Trac: "TICKET_CREATE
privileges are required to perform this operation".

Following asserts are received when varnish was inserted into live test
traffic stream situated in-between litespeed, a web server acting as a
proxy, and the real server.

The default VCL was modified so varnish will cache even with cookies
present in request. No other change made.

I have the communication logged to disk but there was too much data and
I could not figure through the asserts which request was at fault. If a
dev can tell me what to look for, I can research the varnish log.

Xing Li
LiteSpeed Technologies, Inc.


Start Bug Report:
---------------
CentOS 4.4, x86_64, libevent 1.1b,

Varnish 0.9.1 launched with "varnishd -d -d -p 11101 -b 'myip 82'
---------------
Source modification: Line 48 of varnishd/mgt_vcc.c

from

" if (req.http.Authenticate || req.http.Cookie) {\n"

to

" if (req.http.Authenticate) {\n"
---------------

Error Description from varnishd:
---------------
file /tmp/varnish.D85dYM (unlinked) size 83630907392 bytes (20417702
fs-blocks, 20417702 pages)
rolling(1)...
rolling(2)...
start
CLI <start>
start child pid 30671
200 0

Child said (2, 30671): <<Child starts
managed to mmap 83630907392 bytes of 83630907392
Ready
>>
Child said (2, 30671): <<Assert error in fetch_chunked(), cache_fetch.c
line 91:
Condition(isspace(*q)) not true.
errno = 0 (Success)
>>
Cache child died pid=30671 status=0x6
Clean child
Child cleaned
start child pid 31027
Child said (2, 31027): <<Child starts
managed to mmap 83630907392 bytes of 83630907392
Ready
>>
Child said (2, 31027): <<Assert error in fetch_chunked(), cache_fetch.c
line 91:
Condition(isspace(*q)) not true.
errno = 0 (Success)
>>
Cache child died pid=31027 status=0x6
Clean child
Child cleaned
start child pid 31122
Child said (2, 31122): <<Child starts
managed to mmap 83630907392 bytes of 83630907392
Ready
>>
Child said (2, 31122): <<Assert error in fetch_chunked(), cache_fetch.c
line 91:
Condition(isspace(*q)) not true.
errno = 0 (Success)
>>
Cache child died pid=31122 status=0x6
Clean child
Child cleaned
start child pid 31133
Child said (2, 31133): <<Child starts
managed to mmap 83630907392 bytes of 83630907392
Ready
>>
Child said (2, 31133): <<Assert error in fetch_chunked(), cache_fetch.c
line 91:
Condition(isspace(*q)) not true.
errno = 0 (Success)
>>
Cache child died pid=31133 status=0x6
Clean child
Child cleaned
start child pid 31160
Child said (2, 31160): <<Child starts
managed to mmap 83630907392 bytes of 83630907392
Ready
>>
Child said (2, 31160): <<Assert error in FetchHeaders(), cache_fetch.c
line 312:
Condition(i == 0) not true.
errno = 0 (Success)
>>
Cache child died pid=31160 status=0x6
Clean child
Child cleaned
start child pid 31201
Child said (2, 31201): <<Child starts
Bug Report..can't use Trac tickets [ In reply to ]
Sorry for the list intrusion. Registered with Trac as "xing" but I don't
have the rights to submit a bug ticket according to Trac: "TICKET_CREATE
privileges are required to perform this operation".

Following asserts are received when varnish was inserted into live test
traffic stream situated in-between litespeed, a web server acting as a
proxy, and the real server.

The default VCL was modified so varnish will cache even with cookies
present in request. No other change made.

I have the communication logged to disk but there was too much data and
I could not figure through the asserts which request was at fault. If a
dev can tell me what to look for, I can research the varnish log.

Xing Li
LiteSpeed Technologies, Inc.


Start Bug Report:
---------------
CentOS 4.4, x86_64, libevent 1.1b,

Varnish 0.9.1 launched with "varnishd -d -d -p 11101 -b 'myip 82'
---------------
Source modification: Line 48 of varnishd/mgt_vcc.c

from

" if (req.http.Authenticate || req.http.Cookie) {\n"

to

" if (req.http.Authenticate) {\n"
---------------

Error Description from varnishd:
---------------
file /tmp/varnish.D85dYM (unlinked) size 83630907392 bytes (20417702
fs-blocks, 20417702 pages)
rolling(1)...
rolling(2)...
start
CLI <start>
start child pid 30671
200 0

Child said (2, 30671): <<Child starts
managed to mmap 83630907392 bytes of 83630907392
Ready
>>
Child said (2, 30671): <<Assert error in fetch_chunked(), cache_fetch.c
line 91:
Condition(isspace(*q)) not true.
errno = 0 (Success)
>>
Cache child died pid=30671 status=0x6
Clean child
Child cleaned
start child pid 31027
Child said (2, 31027): <<Child starts
managed to mmap 83630907392 bytes of 83630907392
Ready
>>
Child said (2, 31027): <<Assert error in fetch_chunked(), cache_fetch.c
line 91:
Condition(isspace(*q)) not true.
errno = 0 (Success)
>>
Cache child died pid=31027 status=0x6
Clean child
Child cleaned
start child pid 31122
Child said (2, 31122): <<Child starts
managed to mmap 83630907392 bytes of 83630907392
Ready
>>
Child said (2, 31122): <<Assert error in fetch_chunked(), cache_fetch.c
line 91:
Condition(isspace(*q)) not true.
errno = 0 (Success)
>>
Cache child died pid=31122 status=0x6
Clean child
Child cleaned
start child pid 31133
Child said (2, 31133): <<Child starts
managed to mmap 83630907392 bytes of 83630907392
Ready
>>
Child said (2, 31133): <<Assert error in fetch_chunked(), cache_fetch.c
line 91:
Condition(isspace(*q)) not true.
errno = 0 (Success)
>>
Cache child died pid=31133 status=0x6
Clean child
Child cleaned
start child pid 31160
Child said (2, 31160): <<Child starts
managed to mmap 83630907392 bytes of 83630907392
Ready
>>
Child said (2, 31160): <<Assert error in FetchHeaders(), cache_fetch.c
line 312:
Condition(i == 0) not true.
errno = 0 (Success)
>>
Cache child died pid=31160 status=0x6
Clean child
Child cleaned
start child pid 31201
Child said (2, 31201): <<Child starts
Bug Report..can't use Trac tickets [ In reply to ]
In message <44FD0698.7030302 at litespeedtech.com>, Xing Li writes:

Hi Xing,

You get the honour of being the first "outsider" to report an
error. Welcome! :-)


>Sorry for the list intrusion. Registered with Trac as "xing" but I don't
>have the rights to submit a bug ticket according to Trac: "TICKET_CREATE
>privileges are required to perform this operation".

(this is des@ domain, I'll leave it to him)

>I have the communication logged to disk but there was too much data and
>I could not figure through the asserts which request was at fault. If a
>dev can tell me what to look for, I can research the varnish log.

This particular assert indicates protocol trouble with a document
that uses "chunked encoding", usually a CGI script, and the most
likely trouble is that Varnish got out of step with the server somehow.

In theory the transaction should be the last in the varnislog so
if you run:
varnishlog -d -w /tmp/foo
(wait approx 10 seconds, then hit ctrl-C)
varnishlog -r /tmp/foo | tail -200

You should get the information about which URL etc.

The easiest way to debug it from there would be if I could access
the server from here to pick up that URL, then I can see what
happens close up with a debugger, but if that is not possible
we will find another way.

Poul-Henning

--
Poul-Henning Kamp | UNIX since Zilog Zeus 3.20
phk at FreeBSD.ORG | TCP/IP since RFC 956
FreeBSD committer | BSD since 4.3-tahoe
Never attribute to malice what can adequately be explained by incompetence.
Bug Report..can't use Trac tickets [ In reply to ]
In message <44FD0698.7030302 at litespeedtech.com>, Xing Li writes:

Hi Xing,

You get the honour of being the first "outsider" to report an
error. Welcome! :-)


>Sorry for the list intrusion. Registered with Trac as "xing" but I don't
>have the rights to submit a bug ticket according to Trac: "TICKET_CREATE
>privileges are required to perform this operation".

(this is des@ domain, I'll leave it to him)

>I have the communication logged to disk but there was too much data and
>I could not figure through the asserts which request was at fault. If a
>dev can tell me what to look for, I can research the varnish log.

This particular assert indicates protocol trouble with a document
that uses "chunked encoding", usually a CGI script, and the most
likely trouble is that Varnish got out of step with the server somehow.

In theory the transaction should be the last in the varnislog so
if you run:
varnishlog -d -w /tmp/foo
(wait approx 10 seconds, then hit ctrl-C)
varnishlog -r /tmp/foo | tail -200

You should get the information about which URL etc.

The easiest way to debug it from there would be if I could access
the server from here to pick up that URL, then I can see what
happens close up with a debugger, but if that is not possible
we will find another way.

Poul-Henning

--
Poul-Henning Kamp | UNIX since Zilog Zeus 3.20
phk at FreeBSD.ORG | TCP/IP since RFC 956
FreeBSD committer | BSD since 4.3-tahoe
Never attribute to malice what can adequately be explained by incompetence.
Bug Report..can't use Trac tickets [ In reply to ]
Xing Li <xing at litespeedtech.com> writes:
> Sorry for the list intrusion. Registered with Trac as "xing" but I
> don't have the rights to submit a bug ticket according to Trac:
> "TICKET_CREATE privileges are required to perform this operation".

Sorry, should be fixed now.

DES
--
Dag-Erling Sm?rgrav
Senior Software Developer
Linpro AS - www.linpro.no
Bug Report..can't use Trac tickets [ In reply to ]
Xing Li <xing at litespeedtech.com> writes:
> Sorry for the list intrusion. Registered with Trac as "xing" but I
> don't have the rights to submit a bug ticket according to Trac:
> "TICKET_CREATE privileges are required to perform this operation".

Sorry, should be fixed now.

DES
--
Dag-Erling Sm?rgrav
Senior Software Developer
Linpro AS - www.linpro.no