A few users see a blank page
Marco Molinari
marco.molinari at gmail.com
Tue Feb 12 15:01:37 CET 2008
I can now reproduce it and I found a lot of info.
I wrote a simple script that keeps on reloading itself, adding some
chars each time; I disabled compression both in Apache and in PHP and
I connect my browser through a 2.6 Squid proxy; and now I can't see
PHP pages larger than 8000 bytes. I also found an interesting
connection with cookies.
Here are the log lines for Varnish requesting two pages to Apache:
Apache:
127.0.0.1, 10.0.2.2 - - [12/Feb/2008:14:24:26 +0100] "GET
/test_varnish2.php?n=10&t=1202822659 HTTP/1.0" 200 8000 "-"
"{MY-USER-AGENT}"
127.0.0.1, 10.0.2.2 - - [12/Feb/2008:14:24:29 +0100] "GET
/test_varnish2.php?n=11&t=1202822659 HTTP/1.0" 200 8001 "-"
"{MY-USER-AGENT}"
Varnish:
10.0.2.2 - - [12/Feb/2008:14:24:26 +0100] "GET
http://dev.{MY-SITE}:2280/test_varnish2.php?n=10&t=1202822659
HTTP/1.0" 200 8000 "-" "{MY-USER-AGENT}"
10.0.2.2 - - [12/Feb/2008:14:24:29 +0100] "GET
http://dev.{MY-SITE}:2280/test_varnish2.php?n=11&t=1202822659
HTTP/1.0" 200 0 "-" "{MY-USER-AGENT}"
As you can see Varnish logs a 0 size for the 8001 bytes request.
Here is the extended log (as per varnishlog) for those requests (sorry
for the length):
15 ReqStart c 10.0.2.2 43859 67671826
15 RxRequest c GET
15 RxURL c /test_varnish2.php?n=10&t=1202822659
15 RxProtocol c HTTP/1.0
15 RxHeader c Host: dev.{MY-SITE}:2280
15 RxHeader c User-Agent: {MY-USER-AGENT}
15 RxHeader c Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
15 RxHeader c Accept-Language: en-us,en;q=0.5
15 RxHeader c Accept-Encoding: gzip,deflate
15 RxHeader c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
15 RxHeader c Cookie:
__utma=xxxxxxxx.xxxxxxxxxx.xxxxxxxxxx.xxxxxxxxxx.xxxxxxxxxx.23;
__utmz=xxxxxxxx.xxxxxxxxxx.21.5.utmcsr=mail.google.com|utmccn=(referral)|utmcmd=referral|utmcct=%2Fmail%2F;
__utmz=xxxxxxxx.xxxxxxxxxx.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(non
15 RxHeader c Via: 1.1 virtual:3129 (squid/2.6.STABLE14)
15 RxHeader c X-Forwarded-For: 127.0.0.1
15 RxHeader c Cache-Control: max-age=259200
15 RxHeader c Connection: keep-alive
15 VCL_call c recv
15 VCL_return c pass
15 VCL_call c pass
15 VCL_return c pass
18 BackendOpen b default 127.0.0.1 32988 127.0.0.1 8080
18 BackendXID b 67671826
15 Backend c 18 default
18 TxRequest b GET
18 TxURL b /test_varnish2.php?n=10&t=1202822659
18 TxProtocol b HTTP/1.0
18 TxHeader b Host: dev.{MY-SITE}:2280
18 TxHeader b User-Agent: {MY-USER-AGENT}
18 TxHeader b Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
18 TxHeader b Accept-Language: en-us,en;q=0.5
18 TxHeader b Accept-Encoding: gzip,deflate
18 TxHeader b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
18 TxHeader b Cookie:
__utma=xxxxxxxx.xxxxxxxxxx.xxxxxxxxxx.xxxxxxxxxx.xxxxxxxxxx.23;
__utmz=xxxxxxxx.xxxxxxxxxx.21.5.utmcsr=mail.google.com|utmccn=(referral)|utmcmd=referral|utmcct=%2Fmail%2F;
__utmz=xxxxxxxxxx.xxxxxxxxxx.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(non
18 TxHeader b Via: 1.1 virtual:3129 (squid/2.6.STABLE14)
18 TxHeader b X-Forwarded-For: 127.0.0.1
18 TxHeader b X-Varnish: 67671826
18 TxHeader b X-Forwarded-for: 10.0.2.2
18 RxProtocol b HTTP/1.1
18 RxStatus b 200
18 RxResponse b OK
18 RxHeader b Date: Tue, 12 Feb 2008 13:24:26 GMT
18 RxHeader b Server: Apache/2.0.52 (CentOS)
18 RxHeader b X-Powered-By: PHP/4.3.9
18 RxHeader b Content-Length: 8000
18 RxHeader b Connection: close
18 RxHeader b Content-Type: text/html; charset=UTF-8
15 ObjProtocol c HTTP/1.1
15 ObjStatus c 200
15 ObjResponse c OK
15 ObjHeader c Date: Tue, 12 Feb 2008 13:24:26 GMT
15 ObjHeader c Server: Apache/2.0.52 (CentOS)
15 ObjHeader c X-Powered-By: PHP/4.3.9
15 ObjHeader c Content-Type: text/html; charset=UTF-8
18 BackendClose b default
15 TTL c 67671826 RFC 120 1202822666 1202822666 0 0 0
15 VCL_call c fetch
15 VCL_return c insert
15 Length c 8000
15 VCL_call c deliver
15 VCL_return c deliver
15 TxProtocol c HTTP/1.1
15 TxStatus c 200
15 TxResponse c OK
15 TxHeader c Server: Apache/2.0.52 (CentOS)
15 TxHeader c X-Powered-By: PHP/4.3.9
15 TxHeader c Content-Type: text/html; charset=UTF-8
15 TxHeader c Content-Length: 8000
15 TxHeader c Date: Tue, 12 Feb 2008 13:24:26 GMT
15 TxHeader c X-Varnish: 67671826
15 TxHeader c Age: 0
15 TxHeader c Via: 1.1 varnish
15 TxHeader c Connection: keep-alive
15 ReqEnd c 67671826 1202822666.438220024
1202822666.440738916 3.759930134 0.002374887 0.000144005
0 StatAddr 10.0.2.2 0 4217 31 171 0 0 171 41937 1114752
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1202822669
second request:
15 ReqStart c 10.0.2.2 43859 67671827
15 RxRequest c GET
15 RxURL c /test_varnish2.php?n=11&t=1202822659
15 RxProtocol c HTTP/1.0
15 RxHeader c Host: dev.{MY-SITE}:2280
15 RxHeader c User-Agent: {MY-USER-AGENT}
15 RxHeader c Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
15 RxHeader c Accept-Language: en-us,en;q=0.5
15 RxHeader c Accept-Encoding: gzip,deflate
15 RxHeader c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
15 RxHeader c Cookie:
__utma=xxxxxxxx.xxxxxxxxxx.xxxxxxxxxx.xxxxxxxxxx.xxxxxxxxxx.23;
__utmz=xxxxxxxx.xxxxxxxxxx.21.5.utmcsr=mail.google.com|utmccn=(referral)|utmcmd=referral|utmcct=%2Fmail%2F;
__utmz=xxxxxxxxxx.xxxxxxxxxx.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(non
15 RxHeader c Via: 1.1 virtual:3129 (squid/2.6.STABLE14)
15 RxHeader c X-Forwarded-For: 127.0.0.1
15 RxHeader c Cache-Control: max-age=259200
15 RxHeader c Connection: keep-alive
15 VCL_call c recv
15 VCL_return c pass
15 VCL_call c pass
15 VCL_return c pass
18 BackendOpen b default 127.0.0.1 32989 127.0.0.1 8080
18 BackendXID b 67671827
15 Backend c 18 default
18 TxRequest b GET
18 TxURL b /test_varnish2.php?n=11&t=1202822659
18 TxProtocol b HTTP/1.0
18 TxHeader b Host: dev.{MY-SITE}:2280
18 TxHeader b User-Agent: {MY-USER-AGENT}
18 TxHeader b Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
18 TxHeader b Accept-Language: en-us,en;q=0.5
18 TxHeader b Accept-Encoding: gzip,deflate
18 TxHeader b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
18 TxHeader b Cookie:
__utma=xxxxxxxx.xxxxxxxxxx.xxxxxxxxxx.xxxxxxxxxx.xxxxxxxxxx.23;
__utmz=xxxxxxxx.xxxxxxxxxx.21.5.utmcsr=mail.google.com|utmccn=(referral)|utmcmd=referral|utmcct=%2Fmail%2F;
__utmz=xxxxxxxxxx.xxxxxxxxxx.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(non
18 TxHeader b Via: 1.1 virtual:3129 (squid/2.6.STABLE14)
18 TxHeader b X-Forwarded-For: 127.0.0.1
18 TxHeader b X-Varnish: 67671827
18 TxHeader b X-Forwarded-for: 10.0.2.2
18 RxProtocol b HTTP/1.1
18 RxStatus b 200
18 RxResponse b OK
18 RxHeader b Date: Tue, 12 Feb 2008 13:24:29 GMT
18 RxHeader b Server: Apache/2.0.52 (CentOS)
18 RxHeader b X-Powered-By: PHP/4.3.9
18 RxHeader b Connection: close
18 RxHeader b Content-Type: text/html; charset=UTF-8
15 ObjProtocol c HTTP/1.1
15 ObjStatus c 200
15 ObjResponse c OK
15 ObjHeader c Date: Tue, 12 Feb 2008 13:24:29 GMT
15 ObjHeader c Server: Apache/2.0.52 (CentOS)
15 ObjHeader c X-Powered-By: PHP/4.3.9
15 ObjHeader c Content-Type: text/html; charset=UTF-8
18 BackendClose b default
15 TTL c 67671827 RFC 120 1202822669 1202822669 0 0 0
15 VCL_call c fetch
15 VCL_return c insert
15 Length c 0
15 VCL_call c deliver
15 VCL_return c deliver
15 TxProtocol c HTTP/1.1
15 TxStatus c 200
15 TxResponse c OK
15 TxHeader c Server: Apache/2.0.52 (CentOS)
15 TxHeader c X-Powered-By: PHP/4.3.9
15 TxHeader c Content-Type: text/html; charset=UTF-8
15 TxHeader c Date: Tue, 12 Feb 2008 13:24:29 GMT
15 TxHeader c X-Varnish: 67671827
15 TxHeader c Age: 0
15 TxHeader c Via: 1.1 varnish
15 TxHeader c Connection: keep-alive
15 ReqEnd c 67671827 1202822669.762167931
1202822669.765445948 3.321429014 0.003173113 0.000104904
0 StatAddr 10.0.2.2 0 4221 31 172 0 0 172 42161 1114752
0 CLI Rd ping
0 CLI Wr 0 200 PONG 1202822672
15 SessionClose c timeout
15 StatSess c 10.0.2.2 43859 11 1 4 0 0 4 962 23995
As you can see in the 8001 bytes request there seems to be no
Content-Length header in the Apache response, but I checked with
LiveHttpHeaders (without Squid) and the header is there.
You can also notice that cookies in the extended logs are cut (I
replaced the numbers with "xxx"); so I tried to disable the cookies in
the browser, and everything works!
15 ReqStart c 10.0.2.2 57522 67671865
15 RxRequest c GET
15 RxURL c /test_varnish2.php?n=11&t=1202823345
15 RxProtocol c HTTP/1.0
15 RxHeader c Host: dev.{MY-SITE}:2280
15 RxHeader c User-Agent: {MY-USER-AGENT}
15 RxHeader c Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
15 RxHeader c Accept-Language: en-us,en;q=0.5
15 RxHeader c Accept-Encoding: gzip,deflate
15 RxHeader c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
15 RxHeader c Via: 1.1 virtual:3129 (squid/2.6.STABLE14)
15 RxHeader c X-Forwarded-For: 127.0.0.1
15 RxHeader c Cache-Control: max-age=259200
15 RxHeader c Connection: keep-alive
15 VCL_call c recv
15 VCL_return c lookup
15 VCL_call c hash
15 VCL_return c hash
15 VCL_call c miss
15 VCL_return c fetch
18 BackendOpen b default 127.0.0.1 33028 127.0.0.1 8080
18 BackendXID b 67671865
15 Backend c 18 default
18 TxRequest b GET
18 TxURL b /test_varnish2.php?n=11&t=1202823345
18 TxProtocol b HTTP/1.1
18 TxHeader b Host: dev.{MY-SITE}:2280
18 TxHeader b User-Agent: {MY-USER-AGENT}
18 TxHeader b Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
18 TxHeader b Accept-Language: en-us,en;q=0.5
18 TxHeader b Accept-Encoding: gzip,deflate
18 TxHeader b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
18 TxHeader b Via: 1.1 virtual:3129 (squid/2.6.STABLE14)
18 TxHeader b X-Forwarded-For: 127.0.0.1
18 TxHeader b X-Varnish: 67671865
18 TxHeader b X-Forwarded-for: 10.0.2.2
18 RxProtocol b HTTP/1.1
18 RxStatus b 200
18 RxResponse b OK
18 RxHeader b Date: Tue, 12 Feb 2008 13:35:57 GMT
18 RxHeader b Server: Apache/2.0.52 (CentOS)
18 RxHeader b X-Powered-By: PHP/4.3.9
18 RxHeader b Connection: close
18 RxHeader b Transfer-Encoding: chunked
18 RxHeader b Content-Type: text/html; charset=UTF-8
15 ObjProtocol c HTTP/1.1
15 ObjStatus c 200
15 ObjResponse c OK
15 ObjHeader c Date: Tue, 12 Feb 2008 13:35:57 GMT
15 ObjHeader c Server: Apache/2.0.52 (CentOS)
15 ObjHeader c X-Powered-By: PHP/4.3.9
15 ObjHeader c Content-Type: text/html; charset=UTF-8
18 BackendClose b default
15 TTL c 67671865 RFC 120 1202823357 1202823357 0 0 0
15 VCL_call c fetch
15 VCL_return c insert
15 Length c 8001
15 VCL_call c deliver
15 VCL_return c deliver
15 TxProtocol c HTTP/1.1
15 TxStatus c 200
15 TxResponse c OK
15 TxHeader c Server: Apache/2.0.52 (CentOS)
15 TxHeader c X-Powered-By: PHP/4.3.9
15 TxHeader c Content-Type: text/html; charset=UTF-8
15 TxHeader c Content-Length: 8001
15 TxHeader c Date: Tue, 12 Feb 2008 13:35:57 GMT
15 TxHeader c X-Varnish: 67671865
15 TxHeader c Age: 0
15 TxHeader c Via: 1.1 varnish
15 TxHeader c Connection: keep-alive
15 ReqEnd c 67671865 1202823357.593729973
1202823357.596472979 3.786515951 0.002630949 0.000112057
0 StatAddr 10.0.2.2 0 4908 34 210 0 0 210 52216 1395936
This could explain why the problem seems so erratic, as a user can see
a page or not depending on the page length and their cookies.
My configuration:
- web server: Centos 4 + Apache 2.0.52 + PHP 4.3.9 + Varnish 1.1.2
(everything installed through rpms)
- proxy server: Ubuntu 7.10 + Squid 2.6
- client: Ubuntu 7.10 + Firefox (actually it's the same pc that runs
the proxy server)
Uncommented parts in my vcl:
backend default {
set backend.host = "127.0.0.1";
set backend.port = "8080";
}
sub vcl_recv {
if (req.http.Pragma == "no-cache") {
pipe;
}
if (req.request == "GET" && req.url ~
"\.(gif|jpg|swf|css|js|swf|flv|png|jpeg)$") {
lookup;
}
if (req.request != "GET" && req.request != "HEAD") {
pipe;
}
if (req.http.Expect) {
pipe;
}
if (req.http.Authenticate || req.http.Cookie) {
pass;
}
lookup;
}
Is this enough to post a bug report?
Thanks
Marco
More information about the varnish-misc
mailing list