Take the 2-minute tour ×
Server Fault is a question and answer site for professional system and network administrators. It's 100% free, no registration required.

Hey guys I hope you can help me out here.

I have an Ngingx parsing http and https to a varnish cache(3.0.2). From the varnish it is sent to apache2. Now I have for some time been tracking some strange 503 errors. But I cant seem to find the silver bullet.

Currently I am logging the 503 errors through varnish this way:

sudo varnishlog -c -m TxStatus:503 >> /home/rj/varnishlog503.log

and then referring to the apache access log to see if any 503 requests have been handled.

Today I had a health check from the firewall that failed:

   20 SessionOpen  c 127.0.0.1 34319 :8081
   20 ReqStart     c 127.0.0.1 34319 607335635
   20 RxRequest    c HEAD
   20 RxURL        c /health-check
   20 RxProtocol   c HTTP/1.0
   20 RxHeader     c X-Real-IP: 192.168.3.254
   20 RxHeader     c Host: 192.168.3.189
   20 RxHeader     c X-Forwarded-For: 192.168.3.254
   20 RxHeader     c Connection: close
   20 RxHeader     c User-Agent: Astaro Service Monitor 0.9
   20 RxHeader     c Accept: */*
   20 VCL_call     c recv lookup
   20 VCL_call     c hash
   20 Hash         c /health-check
   20 VCL_return   c hash
   20 VCL_call     c miss fetch
   20 Backend      c 33 aurum aurum
   20 FetchError   c http first read error: -1 11 (No error recorded)
   20 VCL_call     c error deliver
   20 VCL_call     c deliver deliver
   20 TxProtocol   c HTTP/1.1
   20 TxStatus     c 503
   20 TxResponse   c Service Unavailable
   20 TxHeader     c Server: Varnish
   20 TxHeader     c Content-Type: text/html; charset=utf-8
   20 TxHeader     c Retry-After: 5
   20 TxHeader     c Content-Length: 879
   20 TxHeader     c Accept-Ranges: bytes
   20 TxHeader     c Date: Wed, 06 Jun 2012 12:35:12 GMT
   20 TxHeader     c X-Varnish: 607335635
   20 TxHeader     c Age: 60
   20 TxHeader     c Via: 1.1 varnish
   20 TxHeader     c Connection: close
   20 Length       c 879
   20 ReqEnd       c 607335635 1338986052.649786949 1338986112.648169994 0.000160217 59.997980356 0.000402689

Now the backend server (apache) does not have any 503 error in the access log at this point. So I am confused. Is this varnish throwing a 503 because it thinks apache is to slow? There is a lot traffic coming through at this point so I know the server is up and running.

I do have other 503 error codes with posts and gets so there is really no pattern. It seems to be at random times and random requests. Even in the morning when the server dosen't seem to be doing anything.

I do see another pattern in the log:

4 VCL_call     c recv pass
4 VCL_call     c hash
4 Hash         c /?id=412
4 VCL_return   c hash
4 VCL_call     c pass pass
4 FetchError   c no backend connection
4 VCL_call     c error deliver
4 VCL_call     c deliver deliver

Here fetcherror says "no backend connection". A summery of the FetchErrors in todays log:

   16 FetchError   c http first read error: -1 11 (No error recorded)
    5 FetchError   c http first read error: -1 11 (No error recorded)
    4 FetchError   c http first read error: -1 11 (No error recorded)
   19 FetchError   c http first read error: -1 11 (No error recorded)
    5 FetchError   c http first read error: -1 11 (No error recorded)
   23 FetchError   c http first read error: -1 11 (No error recorded)
   24 FetchError   c http first read error: -1 11 (No error recorded)
   16 FetchError   c http first read error: -1 11 (No error recorded)
    6 FetchError   c http first read error: -1 11 (No error recorded)
    4 FetchError   c http first read error: -1 11 (No error recorded)
    5 FetchError   c http first read error: -1 11 (No error recorded)
    4 FetchError   c http first read error: -1 11 (No error recorded)
    4 FetchError   c http first read error: -1 11 (No error recorded)
   22 FetchError   c http first read error: -1 11 (No error recorded)
    6 FetchError   c http first read error: -1 11 (No error recorded)
   21 FetchError   c http first read error: -1 11 (No error recorded)
   26 FetchError   c no backend connection
    4 FetchError   c no backend connection
   20 FetchError   c http first read error: -1 11 (No error recorded)
   39 FetchError   c http first read error: -1 11 (No error recorded)

I haven't changed the default timeout values for varnish. This is my configuration for one of the backend servers.

backend xenon {
        .host = "192.168.3.187";
        .port = "80";
        .probe = {
                .url = "/health-check/";
                .interval = 3s;
                .window = 5;
                .threshold = 2;
        }
}

I'm running prefork module on apache2 with this configuration

<IfModule mpm_prefork_module>
    StartServers          1
    MinSpareServers       2
    MaxSpareServers       5
    MaxClients           200
    MaxRequestsPerChild  75
</IfModule>

and only PHP files is sent to the server. Every other static file is handled by Nginx.

Any ideas?

------- EDIT --------------

Some more debuging information

I have run a varnishadm debug.health

Backend radon is Healthy
Current states  good:  5 threshold:  2 window:  5
Average responsetime of good probes: 0.002560
Oldest                                                    Newest
================================================================
4444444444444444444444444444444444444444444444444444444444444444 Good IPv4
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX Good Xmit
RRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRR Good Recv
HHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHH Happy
Backend xenon is Healthy
Current states  good:  5 threshold:  2 window:  5
Average responsetime of good probes: 0.002760
Oldest                                                    Newest
================================================================
4444444444444444444444444444444444444444444444444444444444444444 Good IPv4
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX Good Xmit
RRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRR Good Recv
HHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHH Happy
Backend iridium is Healthy
Current states  good:  5 threshold:  2 window:  5
Average responsetime of good probes: 0.000849
Oldest                                                    Newest
================================================================
4444444444444444444444444444444444444444444444444444444444444444 Good IPv4
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX Good Xmit
RRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRR Good Recv
HHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHH Happy
Backend aurum is Healthy
Current states  good:  5 threshold:  2 window:  5
Average responsetime of good probes: 0.002100
Oldest                                                    Newest
================================================================
4444444444444444444444444444444444444444444444444444444444444444 Good IPv4
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX Good Xmit
RRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRR Good Recv
HHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHH Happy

And I have been monitoring varnishstat from the two load balancers

 3224774         3.99         2.61 backend_conn - Backend conn. success
      27         0.00         0.00 backend_unhealthy - Backend conn. not attempted
      63         0.00         0.00 backend_fail - Backend conn. failures
  358798         0.00         0.29 backend_reuse - Backend conn. reuses
   21035         0.00         0.02 backend_toolate - Backend conn. was closed
  379834         0.00         0.31 backend_recycle - Backend conn. recycles
      26         0.00         0.00 backend_retry - Backend conn. retry

3217751         5.99         2.61 backend_conn - Backend conn. success
      32         0.00         0.00 backend_fail - Backend conn. failures
  364185         0.00         0.30 backend_reuse - Backend conn. reuses
   27077         0.00         0.02 backend_toolate - Backend conn. was closed
  391263         0.00         0.32 backend_recycle - Backend conn. recycles
      36         0.00         0.00 backend_retry - Backend conn. retry

Notice that none of them have reported backend_fail.

/Ronnie

share|improve this question
add comment

2 Answers

I hope it is a typo, but you mentioned that there were no errors in the access logs? The errors would be in the error log (-: Check there, if you haven't already? The file is called error_log. Also, check your httpd.conf for error log level. Try setting it to debug, and restart to see more details in the error logs. I believe the default is warn. Note, there is a performance overhead with debug, so do did until you have the necessary data and set it back to warn.

Another item to consider is increasing/tuning some of your prefork settings. If you're seeing a lot of traffic" coming through, these are too low -- IMO. Here are defaults on my RHEL 6.1, apache 2.2:

<IfModule prefork.c>
StartServers       8
MinSpareServers    5
MaxSpareServers   20
ServerLimit      256
MaxClients       256
MaxRequestsPerChild  4000
</IfModule>

The optimal settings depend on your install of apache and the hardware you are running -- memory, CPUs etc. I would start by gently increasing the first three. See Apache MPM prefork for more info on these parameters.

share|improve this answer
    
Hey KM01. Yes I didn't mean error :) The access log contains all requests and I was looking for those with the http status code of 503. I cant find any which makes me believe that the requests never get to the apache server but stops in varnish. The current apache configuration is still good considering that apachge don't server any static files. –  Ronnie Jespersen Jun 6 '12 at 14:12
    
Yes, u'r right, I've to remember the apache logs 503s to access_log even though it is an error (-: but we digress ... So, the No backend connection is the part that makes me think that you should have a second look at your prefork settings. Looks like there isn't an apache process available to fulfill the incoming request. –  KM. Jun 6 '12 at 14:27
    
Could you then explain to me how apache works then? Cause I though that apache would spawn new processes to handle the requests. Up to the default value of 256 simultaneous requests. Shouldn't it?? –  Ronnie Jespersen Jun 6 '12 at 21:15
    
By the way I have changed the values to on the 2 backend servers so lets see what happens today :) –  Ronnie Jespersen Jun 7 '12 at 7:15
    
I'm afraid it haven't solved the issue. I still receive 503 error in my varnish log and not in my apache access log even though I have more than doubled my values in the apache configuration. –  Ronnie Jespersen Jun 7 '12 at 11:42
show 5 more comments

If this is a busy server, which I assume it is since you state "There is a lot traffic coming through at this point so I know the server is up and running" Have you evaluated first your apache config to be able to handle the traffic influx? And second you are using nginx to proxy requests to varnish, have you set a retry value for the requests? For instance when using apache proxypass you can do something like this

ProxyPass / http://192.1.1.11:9001/ retry=3 timeout=5

This will have the proxy do n retries for those requests. Find the equivalent to this for nginx. This may help mitigate the amount of 503s however if it is a traffic issue you need to address that ultimately. Also you may want to consider haproxy rather than nginx for proxying in this way since that is what it is made for.

share|improve this answer
add comment

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.