Mailing List Archive: Delay when fetching a page without Content-Length

Delay when fetching a page without Content-Length

asjo at koldfront

Mar 31, 2007, 9:35 AM

Post #1 of 9 (1268 views)

In my experiments, I've run into a long(ish) delay when I ask for a
url behind http auth:

$ time wget -S http://www.koldfront.local/stats/
[...?]
real 0m16.799s
[...]

Going directly to Apache:

$ time wget -S http://www.koldfront.local:8080/stats/
[...?]
real 0m0.013s
[...]

I have previously observed such delays on pages where I didn't return
a Content-Length header (or, embarrassingly, did it wrong) - is this
related, or should it just work when Apache sends 'Transfer-Encoding:
chunked'?

(I have configured Varnish to 'pass' if there is an WWW-Authenticate
or Authorization-header? - I hope that is correct).

Best regards,

Adam

? --18:27:24-- http://www.koldfront.local/stats/
=> `index.html'
Resolving www.koldfront.local... 192.168.1.111
Connecting to www.koldfront.local|192.168.1.111|:80... connected.
HTTP request sent, awaiting response...
HTTP/1.1 401 Authorization Required
Date: Sat, 31 Mar 2007 16:27:26 GMT
Server: Apache/1.3.33 (Debian GNU/Linux) mod_fastcgi/2.4.2 mod_perl/1.29
WWW-Authenticate: Basic realm="Statistics"
Content-Type: text/html; charset=iso-8859-1
X-Varnish: 1997136530
X-Forwarded-for: 192.168.1.160
Transfer-Encoding: chunked
Authorization failed.

? --18:28:14-- http://www.koldfront.local:8080/stats/
=> `index.html'
Resolving www.koldfront.local... 192.168.1.111
Connecting to www.koldfront.local|192.168.1.111|:8080... connected.
HTTP request sent, awaiting response...
HTTP/1.1 401 Authorization Required
Date: Sat, 31 Mar 2007 16:28:17 GMT
Server: Apache/1.3.33 (Debian GNU/Linux) mod_fastcgi/2.4.2 mod_perl/1.29
WWW-Authenticate: Basic realm="Statistics"
Connection: close
Content-Type: text/html; charset=iso-8859-1
X-Pad: avoid browser bug
Authorization failed.

? <http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=416940>

--
"Subdued flamboyance" Adam Sj?gren
asjo at koldfront.dk

Delay when fetching a page without Content-Length [ In reply to ]

Mar 31, 2007, 10:17 AM

Post #2 of 9 (1248 views)

Hi Adam,

Which version of Varnish are you running ?

Can you send me the output from varnishlog for the transaction ?

--
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.

Delay when fetching a page without Content-Length [ In reply to ]

asjo at koldfront

Mar 31, 2007, 11:11 AM

Post #3 of 9 (1284 views)

On Sat, 31 Mar 2007 17:17:10 +0000, Poul-Henning wrote:

> Which version of Varnish are you running ?

The one from Debian unstable backported to stable, i.e. 1.0.3:

$ /usr/sbin/varnishd -V
varnishd (varnish-1.0.3)
Copyright (c) 2006 Linpro AS / Verdens Gang AS
$

> Can you send me the output from varnishlog for the transaction ?

Sure:

$ varnishlog
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1175364221
13 SessionOpen c 192.168.1.160 52579
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1175364224
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1175364227
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1175364230
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1175364233
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1175364236
13 ReqStart c 192.168.1.160 52579 1997137143
13 RxRequest c GET
13 RxURL c /stats/
13 RxProtocol c HTTP/1.0
13 RxHeader c User-Agent: Wget/1.10.2
13 RxHeader c Accept: */*
13 RxHeader c Host: www.koldfront.local
13 RxHeader c Connection: Keep-Alive
13 VCL_call c recv
13 VCL_return c lookup
13 VCL_call c miss
13 VCL_return c fetch
17 BackendOpen b default 127.0.0.1 1027 127.0.0.1 8080
17 BackendXID b 1997137143
13 Backend c 17 default
17 TxRequest b GET
17 TxURL b /stats/
17 TxProtocol b HTTP/1.1
17 TxHeader b User-Agent: Wget/1.10.2
17 TxHeader b Accept: */*
17 TxHeader b Host: www.koldfront.local
17 TxHeader b X-Varnish: 1997137143
17 TxHeader b X-Forwarded-for: 192.168.1.160
17 RxProtocol b HTTP/1.1
17 RxStatus b 401
17 RxResponse b Authorization Required
17 RxHeader b Date: Sat, 31 Mar 2007 18:03:42 GMT
17 RxHeader b Server: Apache/1.3.33 (Debian GNU/Linux) mod_fastcgi/2.4.2 mod_perl/1.29
17 RxHeader b WWW-Authenticate: Basic realm="Statistics"
17 RxHeader b Transfer-Encoding: chunked
17 RxHeader b Content-Type: text/html; charset=iso-8859-1
13 TTL c 1997137143 RFC 120 1175364222 1175364222 0 0 0
13 VCL_call c fetch
13 VCL_return c pass
13 RxProtocol c HTTP/1.1
13 RxStatus c 401
13 RxResponse c Authorization Required
13 RxHeader c Date: Sat, 31 Mar 2007 18:03:42 GMT
13 RxHeader c Server: Apache/1.3.33 (Debian GNU/Linux) mod_fastcgi/2.4.2 mod_perl/1.29
13 RxHeader c WWW-Authenticate: Basic realm="Statistics"
13 RxHeader c Content-Type: text/html; charset=iso-8859-1
13 RxHeader c X-Varnish: 1997137143
13 RxHeader c X-Forwarded-for: 192.168.1.160
13 RxHeader c Transfer-Encoding: chunked
17 BackendReuse b default
13 ReqEnd c 1997137143 1175364222.294967044 1175364238.516689601 0.000751112 0.001383653 16.220338904
0 StatAddr 192.168.1.160 0 8161 36 37 0 20 11 11486 92507
13 HttpError c Received errno 104
13 SessionClose c no request
13 StatSess c 192.168.1.160 52579 16 1 1 0 1 0 322 529
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1175364239
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1175364242
^C
$

(If I run ngrep I see the request being sent to Apache and the reply
back immediately, and then the pause).

Let me know if I should supply more information.

Best regards,

Adam

--
"we push onward. to you, it is 2005, to us, it is Adam Sj?gren
2011. we are always far ahead." asjo at koldfront.dk

Delay when fetching a page without Content-Length [ In reply to ]

Mar 31, 2007, 11:18 AM

Post #4 of 9 (1246 views)

In message <87648hffku.fsf at topper.koldfront.dk>, Adam =?iso-8859-1?Q?Sj=F8gren?= writes:
>On Sat, 31 Mar 2007 17:17:10 +0000, Poul-Henning wrote:
>
>> Which version of Varnish are you running ?
>
>The one from Debian unstable backported to stable, i.e. 1.0.3:
>
> 13 VCL_call c fetch
> 13 VCL_return c pass

Hmm, you're running into a bug in the pass implementation which
have since been fixed.

Try using pipe mode for authenticated requests instead, by putting
this in your vcl_recv function:

if (req.http.Authenticate || req.http.Cookie) {
pipe;
}

--
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.

Delay when fetching a page without Content-Length [ In reply to ]

asjo at koldfront

Mar 31, 2007, 11:35 AM

Post #5 of 9 (1253 views)

On Sat, 31 Mar 2007 18:18:36 +0000, Poul-Henning wrote:

> Hmm, you're running into a bug in the pass implementation which
> have since been fixed.

Ah, great.

(Where can I read about meaning of these? I have scanned through
vcl(7), varnishd(1) and the FAQ).

> Try using pipe mode for authenticated requests instead, by putting
> this in your vcl_recv function:

> if (req.http.Authenticate || req.http.Cookie) {
> pipe;
> }

Hm. I think I have done something wrong, because that made it worse:

$ time wget -S http://www.koldfront.dk/stats/
--20:28:26-- http://www.koldfront.dk/stats/
=> `index.html'
Resolving www.koldfront.dk... 192.168.1.111
Connecting to www.koldfront.dk|192.168.1.111|:80... connected.
HTTP request sent, awaiting response... No data received.
Retrying.

--20:28:27-- http://www.koldfront.dk/stats/
(try: 2) => `index.html'
Connecting to www.koldfront.dk|192.168.1.111|:80... connected.
HTTP request sent, awaiting response... No data received.
Retrying.
[...]

$ varnishlog
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1175365706
0 WorkThread 0xb4391830 start
13 SessionOpen c 192.168.1.160 40834
0 Debug "INCOMPLETE AT: cnt_fetch(332)"
0 CLI Rd vcl.load boot /tmp/vcl.XXZGJC2j
0 CLI Wr 0 200 Loaded "/tmp/vcl.XXZGJC2j" as "boot"

0 CLI Rd vcl.use boot
0 CLI Wr 0 200
0 CLI Rd start
0 CLI Wr 0 200
0 WorkThread 0xb4391830 start
13 SessionOpen c 192.168.1.160 40835
0 Debug "INCOMPLETE AT: cnt_fetch(332)"
0 CLI Rd vcl.load boot /tmp/vcl.XXZGJC2j
0 CLI Wr 0 200 Loaded "/tmp/vcl.XXZGJC2j" as "boot"

The modified vcl.conf I was using looks like this:

# This is a basic vcl.conf file for varnish.
# Modifying this file should be where you store your modifications to
# varnish. Settnigs here will override defaults.

backend default {
set backend.host = "127.0.0.1";
set backend.port = "8080";
}

sub vcl_recv {
if (req.http.authorization) {
# pass;
pipe;
}

if (req.request == "POST") {
pipe;
}

# force lookup even when cookies are present
#if (req.request == "GET" && req.http.cookie) {
# lookup;
#}
}

sub vcl_fetch {
if (resp.http.www-authenticate) {
# pass;
pipe;
}

# force minimum ttl of 180 seconds
if (obj.ttl < 180s) {
set obj.ttl = 180s;
}
}

I will check out from svn and give that a spin...

Best regards,

Adam

--
"Fr?n och med nu s? ?r 's? snart som m?jligt' 53 Adam Sj?gren
timmar!" asjo at koldfront.dk

Delay when fetching a page without Content-Length [ In reply to ]

Mar 31, 2007, 12:22 PM

Post #6 of 9 (1246 views)

In message <87veghdzw0.fsf at topper.koldfront.dk>, Adam =?iso-8859-1?Q?Sj=F8gren?= writes:
>On Sat, 31 Mar 2007 18:18:36 +0000, Poul-Henning wrote:
>
>> Hmm, you're running into a bug in the pass implementation which
>> have since been fixed.
>
>Ah, great.
>
>(Where can I read about meaning of these? I have scanned through
>vcl(7), varnishd(1) and the FAQ).
>
>> Try using pipe mode for authenticated requests instead, by putting
>> this in your vcl_recv function:
>
>> if (req.http.Authenticate || req.http.Cookie) {
>> pipe;
>> }
>
>Hm. I think I have done something wrong, because that made it worse:
>
> sub vcl_recv {
> if (req.http.authorization) {

Should have been: req.http.authenticate

--
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.

Delay when fetching a page without Content-Length [ In reply to ]

asjo at koldfront

Mar 31, 2007, 12:44 PM

Post #7 of 9 (1253 views)

On Sat, 31 Mar 2007 19:22:37 +0000, Poul-Henning wrote:

>> if (req.http.authorization) {

> Should have been: req.http.authenticate

Well, no such header is ever sent, from what I can see, but I'll give
it a go.

No difference - still ~16s delay.

First the browser asks for the page and the server answers with
WWW-Authenticate: Basic realm="...". The browser then asks me for
username and password, and goes on to retry the request, this time
with an Authorization: Basic ... header added.

The delay occurs on the first request.

Best regards,

Adam

--
"Yakka foob mog. Grug pubbawup zink wattoom gazork. Adam Sj?gren
Chumble spuzz." asjo at koldfront.dk

Delay when fetching a page without Content-Length [ In reply to ]

dwetzel at nerim

Mar 31, 2007, 11:55 PM

Post #8 of 9 (1259 views)

Hello,
I had a smilar issue testing varnish last friday,
the backend was sending a 302 with a Transfert-Encoding:chunked,
Using tcpdump i noticed that varnish was trying to open a new tcp
connection with the backend, 3 attempts were made (delay ~15s) before
varnish
gave up and forwarded back the 302 to the client.
there were no authorisation header.
Best Regards,

> On Sat, 31 Mar 2007 17:17:10 +0000, Poul-Henning wrote:
>
>> Which version of Varnish are you running ?
>
> The one from Debian unstable backported to stable, i.e. 1.0.3:
>
> $ /usr/sbin/varnishd -V
> varnishd (varnish-1.0.3)
> Copyright (c) 2006 Linpro AS / Verdens Gang AS
> $
>
>> Can you send me the output from varnishlog for the transaction ?
>
> Sure:
>
> $ varnishlog
> 0 CLI Rd ping
> 0 CLI Wr 0 200 PONG 1175364221
> 13 SessionOpen c 192.168.1.160 52579
> 0 CLI Rd ping
> 0 CLI Wr 0 200 PONG 1175364224
> 0 CLI Rd ping
> 0 CLI Wr 0 200 PONG 1175364227
> 0 CLI Rd ping
> 0 CLI Wr 0 200 PONG 1175364230
> 0 CLI Rd ping
> 0 CLI Wr 0 200 PONG 1175364233
> 0 CLI Rd ping
> 0 CLI Wr 0 200 PONG 1175364236
> 13 ReqStart c 192.168.1.160 52579 1997137143
> 13 RxRequest c GET
> 13 RxURL c /stats/
> 13 RxProtocol c HTTP/1.0
> 13 RxHeader c User-Agent: Wget/1.10.2
> 13 RxHeader c Accept: */*
> 13 RxHeader c Host: www.koldfront.local
> 13 RxHeader c Connection: Keep-Alive
> 13 VCL_call c recv
> 13 VCL_return c lookup
> 13 VCL_call c miss
> 13 VCL_return c fetch
> 17 BackendOpen b default 127.0.0.1 1027 127.0.0.1 8080
> 17 BackendXID b 1997137143
> 13 Backend c 17 default
> 17 TxRequest b GET
> 17 TxURL b /stats/
> 17 TxProtocol b HTTP/1.1
> 17 TxHeader b User-Agent: Wget/1.10.2
> 17 TxHeader b Accept: */*
> 17 TxHeader b Host: www.koldfront.local
> 17 TxHeader b X-Varnish: 1997137143
> 17 TxHeader b X-Forwarded-for: 192.168.1.160
> 17 RxProtocol b HTTP/1.1
> 17 RxStatus b 401
> 17 RxResponse b Authorization Required
> 17 RxHeader b Date: Sat, 31 Mar 2007 18:03:42 GMT
> 17 RxHeader b Server: Apache/1.3.33 (Debian GNU/Linux)
> mod_fastcgi/2.4.2 mod_perl/1.29
> 17 RxHeader b WWW-Authenticate: Basic realm="Statistics"
> 17 RxHeader b Transfer-Encoding: chunked
> 17 RxHeader b Content-Type: text/html; charset=iso-8859-1
> 13 TTL c 1997137143 RFC 120 1175364222 1175364222 0 0 0
> 13 VCL_call c fetch
> 13 VCL_return c pass
> 13 RxProtocol c HTTP/1.1
> 13 RxStatus c 401
> 13 RxResponse c Authorization Required
> 13 RxHeader c Date: Sat, 31 Mar 2007 18:03:42 GMT
> 13 RxHeader c Server: Apache/1.3.33 (Debian GNU/Linux)
> mod_fastcgi/2.4.2 mod_perl/1.29
> 13 RxHeader c WWW-Authenticate: Basic realm="Statistics"
> 13 RxHeader c Content-Type: text/html; charset=iso-8859-1
> 13 RxHeader c X-Varnish: 1997137143
> 13 RxHeader c X-Forwarded-for: 192.168.1.160
> 13 RxHeader c Transfer-Encoding: chunked
> 17 BackendReuse b default
> 13 ReqEnd c 1997137143 1175364222.294967044 1175364238.516689601
> 0.000751112 0.001383653 16.220338904
> 0 StatAddr 192.168.1.160 0 8161 36 37 0 20 11 11486 92507
> 13 HttpError c Received errno 104
> 13 SessionClose c no request
> 13 StatSess c 192.168.1.160 52579 16 1 1 0 1 0 322 529
> 0 CLI Rd ping
> 0 CLI Wr 0 200 PONG 1175364239
> 0 CLI Rd ping
> 0 CLI Wr 0 200 PONG 1175364242
> ^C
> $
>
> (If I run ngrep I see the request being sent to Apache and the reply
> back immediately, and then the pause).
>
>
> Let me know if I should supply more information.
>
>
> Best regards,
>
> Adam
>
> --
> "we push onward. to you, it is 2005, to us, it is Adam Sj?gren
> 2011. we are always far ahead." asjo at koldfront.dk
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc at projects.linpro.no
> http://projects.linpro.no/mailman/listinfo/varnish-misc
>

Delay when fetching a page without Content-Length [ In reply to ]

Apr 4, 2007, 2:31 AM

Post #9 of 9 (1242 views)

asjo at koldfront.dk (Adam Sj?gren) writes:
> (Where can I read about meaning of these? I have scanned through
> vcl(7), varnishd(1) and the FAQ).

The latest version of vcl(7) in Subversion describes this in far
better detail than the version in 1.0.3:

http://varnish.projects.linpro.no/svn/trunk/varnish-cache/man/vcl.7

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