503s for a non-cached host / Re: [SOLVED] Varnish stops waiting backend after 1 second
Garau Simone
S.Garau at liguriadigitale.it
Fri May 13 09:48:10 CEST 2016
Hi guys,
Thank you guys for the help.
I solved the main issue with another configuration that works…ish.
I have two virtual host for the same site: one is cached, one is not. It
is a Joomla site, so the frontend is the one cached and the backend is not.
I still have an issue I can’t understand: I get some random 503 from the
backend where Varnish isn’t caching.
After a couple of refresh of the page is properly served.
The Apache logs shows no activity when Varnish sends a 503, like Varnish
doesn’t send the request.. Or why isn’t Apache logging?
Can someone please give any hints?
Thank you so much, this how the logs looks like:
* << Request >> 2788942
- Begin req 2788933 rxreq
- Timestamp Start: 1463124819.989770 0.000000 0.000000
- Timestamp Req: 1463124819.989770 0.000000 0.000000
- ReqStart 10.10.6.109 50229
- ReqMethod GET
- ReqURL
/administrator/index.php?option=com_installer&view=update&task=update.ajax&
1fb62ce4bf63027725460be31f1da764=1&eid=0&skip=700
- ReqProtocol HTTP/1.1
- ReqHeader Host: admin.not-the-real-url.it
- ReqHeader Connection: keep-alive
- ReqHeader Cache-Control: max-age=0
- ReqHeader Accept: */*
- ReqHeader X-Requested-With: XMLHttpRequest
- ReqHeader User-Agent: Mozilla/5.0 (Windows NT 6.1)
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/50.0.2661.94 Safari/537.36
- ReqHeader Referer: http://admin.regione.liguria.it/administrator/
- ReqHeader Accept-Encoding: gzip, deflate, sdch
- ReqHeader Accept-Language:
it-IT,it;q=0.8,en-US;q=0.6,en;q=0.4,de;q=0.2,ru;q=0.2
- ReqHeader Cookie: fc_screen_resolution=1680x925;
fc_uid=8e6c108858f91e4ca99ff688ce5f7638;
ff607e18ab6c715f4bb35b5bbcbe1c56=9tv90q2et61f7l3kvff4d56v55;
c25a506e7cbaa1047d8cf6231f8b6d85=atk1fmpnt3jlokc0jgar2foo23;
smart_varnish_bypass=1
- ReqHeader X-Forwarded-For: 10.10.6.109
- VCL_call RECV
- VCL_return pass
- VCL_call HASH
- VCL_return lookup
- VCL_call PASS
- VCL_return fetch
- Link bereq 2788943 pass
- Timestamp Fetch: 1463124824.986856 4.997086 4.997086
- RespProtocol HTTP/1.1
- RespStatus 503
- RespReason Backend fetch failed
- RespHeader Date: Fri, 13 May 2016 07:33:44 GMT
- RespHeader Server: Varnish
- RespHeader Content-Type: text/html; charset=utf-8
- RespHeader Retry-After: 5
- RespHeader X-Varnish: 2788942
- RespHeader Age: 0
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespHeader X-Domain-Status: EXCLUDED
- RespHeader X-Cache: NOCACHE
- VCL_return deliver
- Timestamp Process: 1463124824.986913 4.997143 0.000057
- RespHeader Content-Length: 284
- Debug "RES_MODE 2"
- RespHeader Connection: keep-alive
- Timestamp Resp: 1463124824.986965 4.997195 0.000052
- ReqAcct 778 0 778 286 284 570
- End
* << BeReq >> 1115881
- Begin bereq 1115880 pass
- Timestamp Start: 1463124821.994498 0.000000 0.000000
- BereqMethod GET
- BereqURL
/administrator/index.php?option=com_installer&view=update&task=update.ajax&
1fb62ce4bf63027725460be31f1da764=1&eid=700&cache_timeout=3600
- BereqProtocol HTTP/1.1
- BereqHeader Host: admin.not-the-real-url.it
- BereqHeader Accept: */*
- BereqHeader X-Requested-With: XMLHttpRequest
- BereqHeader User-Agent: Mozilla/5.0 (Windows NT 6.1)
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/50.0.2661.94 Safari/537.36
- BereqHeader Referer: http://admin.regione.liguria.it/administrator/
- BereqHeader Accept-Encoding: gzip, deflate, sdch
- BereqHeader Accept-Language:
it-IT,it;q=0.8,en-US;q=0.6,en;q=0.4,de;q=0.2,ru;q=0.2
- BereqHeader Cookie: fc_screen_resolution=1680x925;
fc_uid=8e6c108858f91e4ca99ff688ce5f7638;
ff607e18ab6c715f4bb35b5bbcbe1c56=9tv90q2et61f7l3kvff4d56v55;
c25a506e7cbaa1047d8cf6231f8b6d85=atk1fmpnt3jlokc0jgar2foo23;
smart_varnish_bypass=1
- BereqHeader X-Forwarded-For: 10.10.6.109
- BereqHeader X-Varnish: 1115881
- VCL_call BACKEND_FETCH
- VCL_return fetch
- BackendOpen 46 boot.default 127.0.0.1 8080 127.0.0.1 52937
- Timestamp Bereq: 1463124821.994727 0.000229 0.000229
- FetchError http first read error: EOF
- BackendClose 46 boot.default
- Timestamp Beresp: 1463124826.994768 5.000270 5.000041
- Timestamp Error: 1463124826.994777 5.000279 0.000009
- BerespProtocol HTTP/1.1
- BerespStatus 503
- BerespReason Service Unavailable
- BerespReason Backend fetch failed
- BerespHeader Date: Fri, 13 May 2016 07:33:46 GMT
- BerespHeader Server: Varnish
- VCL_call BACKEND_ERROR
- BerespHeader Content-Type: text/html; charset=utf-8
- BerespHeader Retry-After: 5
- VCL_return deliver
- Storage malloc Transient
- ObjProtocol HTTP/1.1
- ObjStatus 503
- ObjReason Backend fetch failed
- ObjHeader Date: Fri, 13 May 2016 07:33:46 GMT
- ObjHeader Server: Varnish
- ObjHeader Content-Type: text/html; charset=utf-8
- ObjHeader Retry-After: 5
- Length 284
- BereqAcct 790 0 790 0 0 0
- End
Il giorno 09/05/16, 11:56, "Jaroslav Mitáš" <jaroslav.mitas at avg.com> ha
scritto:
>Hi Simone,
>1. try if you backend is realy working: put to your browser
>127.0.0.1:8080/ - if there is no problem, check how long it takes to
>response
>2. if 1yes, try to call varnish admin console "varnishadm -T
>localhost:6082 -S /etc/varnish/secret" and then use command
>"backend.list" -> there you can see, if your backend(origin) is for
>varnish valid and healthy backend.
>
>3. If your result will be 1yes and 2 sick, try to update your probe for
>backend:
>.timeout = 1s; #this is too strict, you can set 5s e.g.
>.interval = 1s; #this is probably too often, I think every 60s is
>enought.
>-more info about setting probe
>https://www.varnish-cache.org/trac/wiki/BackendPolling
>
>4. don't forget to restart varnish after probe changes.
>
>Hope it will help you.
>jaroslav
>
>-----Original Message-----
>From: varnish-misc-bounces+jaroslav.mitas=avg.com at varnish-cache.org
>[mailto:varnish-misc-bounces+jaroslav.mitas=avg.com at varnish-cache.org] On
>Behalf Of Garau Simone
>Sent: 9. května 2016 10:38
>To: varnish-misc at varnish-cache.org
>Subject: [NEED HELP] Varnish stops waiting backend after 1 second
>
>this problem is gonna make me crazy: my varnish istance stops waiting for
>a backend response after exactly 1 second.
>Every first call to a page is a 503 Backend
>
>Daemon is configured this way:
>DAEMON_OPTS="-a :80 \
> -T localhost:6082 \
> -f /etc/varnish/default.vcl \
> -S /etc/varnish/secret \
> -p thread_pool_add_delay=2 \
> -p thread_pools=4 \
> -p thread_pool_min=200 \
> -p thread_pool_max=4000 \
> -p timeout_linger=50 \
> -p connect_timeout=300 \
> -p first_byte_timeout=300 \
> -p between_bytes_timeout=300 \
> -p send_timeout=900 \
> -s malloc,3G²
>
>and the VCL backend:
>backend default { # Define one backend
>.host = "127.0.0.1"; # IP or Hostname of backend
>.port = "8080"; # Port Apache or whatever is listening
>.probe = {
> .url = "/";
> .timeout = 1s;
> .interval = 1s;
> .window = 10;
> .threshold = 8;
> }
> .first_byte_timeout = 60s; # How long to wait before we receive a
>first byte from our backend?
> .connect_timeout = 60s; # How long to wait for a backend
>connection?
> .between_bytes_timeout = 60s; # How long to wait between bytes
>received from our backend?
>}
>
>
>Here is the one call in the log:
>* << Request >> 3440734
>- Begin req 3440733 rxreq
>- Timestamp Start: 1462781837.623325 0.000000 0.000000
>- Timestamp Req: 1462781837.623325 0.000000 0.000000
>- ReqStart 10.20.129.118 58572
>- ReqMethod GET
>- ReqURL xxxxx.html
>- ReqProtocol HTTP/1.1
>- ReqHeader Accept: image/jpeg, application/x-ms-application,
>image/gif, application/xaml+xml, image/pjpeg, application/x-ms-xbap,
>application/vnd.ms-excel, application/vnd.ms-powerpoint,
>application/msword, image/pjpeg, application/x-shockwave-flash, */*
>- ReqHeader Referer: http://xxxxxx.html
>- ReqHeader Accept-Language: it-IT
>- ReqHeader User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows
>NT 6.1; Trident/7.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET
>CLR 3.0.30729; Media Center PC 6.0; .NET4.0C; .NET4.0E)
>- ReqHeader Accept-Encoding: gzip, deflate
>- ReqHeader Host: xxxxxx
>- ReqHeader DNT: 1
>- ReqHeader Connection: Keep-Alive
>- ReqHeader Cookie: fc_uid=p;
>__utma=127650066.830977012.1423064118.1426582505.1426588086.20;
>_ga=GA1.3.830977012.1423064118; _gat_UA-13041322-1=1;
>ZNPCQ003-38303300=71a0f671;
>ff607e18ab6c715f4bb35b5bbcbe1c56=d82989olp2v0ur3gpl2ouprko6;
>_ga=GA1.2.830977012.142306411
>- ReqHeader X-Forwarded-For: 10.20.129.118
>- VCL_call RECV
>- ReqUnset Host: xxx
>- ReqHeader Host: xxx
>- ReqURL /xxxx.html
>- ReqUnset Cookie: fc_uid=p;
>__utma=127650066.830977012.1423064118.1426582505.1426588086.20;
>_ga=GA1.3.830977012.1423064118; _gat_UA-13041322-1=1;
>ZNPCQ003-38303300=71a0f671;
>ff607e18ab6c715f4bb35b5bbcbe1c56=d82989olp2v0ur3gpl2ouprko6;
>_ga=GA1.2.830977012.142306411
>- ReqHeader Cookie: fc_uid=p;
>__utma=127650066.830977012.1423064118.1426582505.1426588086.20;
>_ga=GA1.3.830977012.1423064118; _gat_UA-13041322-1=1;
>ZNPCQ003-38303300=71a0f671;
>ff607e18ab6c715f4bb35b5bbcbe1c56=d82989olp2v0ur3gpl2ouprko6;
>_ga=GA1.2.830977012.142306411
>- ReqUnset Cookie: fc_uid=p;
>__utma=127650066.830977012.1423064118.1426582505.1426588086.20;
>_ga=GA1.3.830977012.1423064118; _gat_UA-13041322-1=1;
>ZNPCQ003-38303300=71a0f671;
>ff607e18ab6c715f4bb35b5bbcbe1c56=d82989olp2v0ur3gpl2ouprko6;
>_ga=GA1.2.830977012.142306411
>- ReqHeader Cookie: fc_uid=p;
>__utma=127650066.830977012.1423064118.1426582505.1426588086.20;
>_ga=GA1.3.830977012.1423064118; _gat_UA-13041322-1=1;
>ZNPCQ003-38303300=71a0f671;
>ff607e18ab6c715f4bb35b5bbcbe1c56=d82989olp2v0ur3gpl2ouprko6;
>_ga=GA1.2.830977012.142306411
>- ReqHeader Surrogate-Capability: key=ESI/1.0
>- VCL_return hash
>- ReqUnset Accept-Encoding: gzip, deflate
>- ReqHeader Accept-Encoding: gzip
>- VCL_call HASH
>- VCL_return lookup
>- VCL_call MISS
>- VCL_return fetch
>- Link bereq 3440735 fetch
>- Timestamp Fetch: 1462781838.492085 0.868760 0.868760
>- Timestamp Process: 1462781838.492101 0.868776 0.000016
>- RespHeader Date: Mon, 09 May 2016 08:17:18 GMT
>- RespHeader Server: Varnish
>- RespHeader X-Varnish: 3440734
>- RespProtocol HTTP/1.1
>- RespStatus 503
>- RespReason Service Unavailable
>- RespReason Service Unavailable
>- VCL_call SYNTH
>- VCL_return deliver
>- RespHeader Content-Length: 0
>- Storage malloc Transient
>- Debug "RES_MODE 2"
>- RespHeader Connection: keep-alive
>- Timestamp Resp: 1462781838.492145 0.868820 0.000044
>- ReqAcct 985 0 985 153 0 153
>- End
>
>Any precious help? Suggestion?
>
>
>_______________________________________________
>varnish-misc mailing list
>varnish-misc at varnish-cache.org
>https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
More information about the varnish-misc
mailing list