How to find and fix issue with Pound and HAProxy
Posted
by
javano
on Server Fault
See other posts from Server Fault
or by javano
Published on 2012-11-12T10:41:27Z
Indexed on
2012/11/12
11:05 UTC
Read the original article
Hit count: 1373
Pound sits in front of HAProxy (on the same box) to perform SSL off-load. Requests are passed to 127.0.0.1:80 where HAProxy then balances the requests across backend servers for a hosted ASP .NET web app.
A user is getting HTTP error 500 (Internal Server Error) returned to their browser this morning and I can see it is comming from Pound. They see no log entry in their web app (IIS) server logs, so its not hitting the back end servers. I think the problem is possibly with HAProxy.
Lets review the logs:
Initialy the users (1.2.3.4) hits Pound on the load balancer:
Nov 12 10:02:24 lb1 pound: a-website.com 1.2.3.4 - - [12/Nov/2012:10:02:23 +0000] "POST /eventmanagement/EditEvent.aspx?eventOid=623fc423-2329-4cab-8be5-72a97709570d HTTP/1.1" 200 155721 "https://a-website.com/eventmanagement/EditEvent.aspx?eventOid=623fc423-2329-4cab-8be5-72a97709570d" "Mozilla/5.0 (Windows NT 6.2; WOW64) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.96 Safari/537.4"
Nov 12 10:02:24 lb1 pound: a-website.com 1.2.3.4 - - [12/Nov/2012:10:02:24 +0000] "GET /Controls/ReferringOrganisationLogoImageHandler.ashx HTTP/1.1" 200 142 "https://a-website.com/eventmanagement/EditEvent.aspx?eventOid=623fc423-2329-4cab-8be5-72a97709570d" "Mozilla/5.0 (Windows NT 6.2; WOW64) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.96 Safari/537.4"
Nov 12 10:02:24 lb1 pound: a-website.com 1.2.3.4 - - [12/Nov/2012:10:02:24 +0000] "GET /eventmanagement/WebCoreModule.ashx?__ac=1&__ac_wcmid=RAWCIL&__ac_lib=Radactive.WebControls.ILoad&__ac_key=RAWVCO_11&__ac_sid=fnoz2hmvirfivb2btbubbw45&__ac_cn=&__ac_cp=BVDXDWFLDWFMHDFJBOEGBDFLFOD5EEFD&__ac_fr=634883113445054092&__ac_ssid= HTTP/1.1" 200 11206 "https://a-website.com/eventmanagement/EditEvent.aspx?eventOid=623fc423-2329-4cab-8be5-72a97709570d" "Mozilla/5.0 (Windows NT 6.2; WOW64) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.96 Safari/537.4"
Nov 12 10:02:24 lb1 pound: a-website.com 1.2.3.4 - - [12/Nov/2012:10:02:24 +0000] "GET /eventmanagement/WebCoreModule.ashx?__ac=1&__ac_wcmid=RAWCIL&__ac_lib=Radactive.WebControls.ILoad&__ac_key=RAWCCIL_11&__ac_sid=fnoz2hmvirfivb2btbubbw45&__ac_cn=&__ac_cp=BVDXDWFLDWFMHDFJBOEGBDFLFOD5EEFD&__ac_fr=634883113445054092 HTTP/1.1" 200 43496 "https://a-website.com/eventmanagement/EditEvent.aspx?eventOid=623fc423-2329-4cab-8be5-72a97709570d" "Mozilla/5.0 (Windows NT 6.2; WOW64) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.96 Safari/537.4"
Nov 12 10:02:42 lb1 pound: (7f819fff8700) e500 for 1.2.3.4 response error read from 127.0.0.1:80/POST /eventmanagement/EditEvent.aspx?eventOid=623fc423-2329-4cab-8be5-72a97709570d HTTP/1.1: Connection timed out (15.121 secs)
Above we can see the request comming in from the user at IP address 1.2.3.4, eventually Pound returns error 500 with the message "Connection timed out (15.121 secs)".
Running HAProxy in debug mode, we can see the request come in;
user@box:/var/log$ sudo /etc/init.d/haproxy restart
Restarting haproxy: haproxy[WARNING] 316/100042 (19218) : <debug> mode incompatible with <quiet> and <daemon>. Keeping <debug> only.
Available polling systems :
sepoll : pref=400, test result OK
epoll : pref=300, test result OK
poll : pref=200, test result OK
select : pref=150, test result OK
Total: 4 (4 usable), will use sepoll.
Using sepoll() as the polling mechanism.
.......
00000008:iis-servers.srvrep[0008:0009]: HTTP/1.1 200 OK
00000008:iis-servers.srvhdr[0008:0009]: Cache-Control: private
00000008:iis-servers.srvhdr[0008:0009]: Pragma: no-cache
00000008:iis-servers.srvhdr[0008:0009]: Content-Length: 22211
00000008:iis-servers.srvhdr[0008:0009]: Content-Type: text/plain; charset=utf-8
00000008:iis-servers.srvhdr[0008:0009]: Server: Microsoft-IIS/7.0
00000008:iis-servers.srvhdr[0008:0009]: X-AspNet-Version: 2.0.50727
00000008:iis-servers.srvhdr[0008:0009]: X-Powered-By: ASP.NET
00000008:iis-servers.srvhdr[0008:0009]: Date: Mon, 12 Nov 2012 10:01:25 GMT
00000009:iis-servers.accept(0004)=000a from [127.0.0.1:53556]
00000009:iis-servers.clireq[000a:ffff]: GET /Logoff.aspx HTTP/1.1
00000009:iis-servers.clihdr[000a:ffff]: Host: a-website.com
00000009:iis-servers.clihdr[000a:ffff]: Connection: keep-alive
00000009:iis-servers.clihdr[000a:ffff]: User-Agent: Mozilla/5.0 (Windows NT 6.2; WOW64) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.96 Safari/537.4
00000009:iis-servers.clihdr[000a:ffff]: Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
00000009:iis-servers.clihdr[000a:ffff]: Referer: https://a-website.com/eventmanagement/eventmanagement.aspx
00000009:iis-servers.clihdr[000a:ffff]: Accept-Encoding: gzip,deflate,sdch
00000009:iis-servers.clihdr[000a:ffff]: Accept-Language: en-GB,en;q=0.8,it;q=0.6
00000009:iis-servers.clihdr[000a:ffff]: Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3
00000009:iis-servers.clihdr[000a:ffff]: Cookie: ASP.NET_SessionId=fnoz2hmvirfivb2btbubbw45; apps=apps2; AuthHint=true; __utma=190546871.552451749.1340295610.1352454675.1352711624.159; __utmb=190546871.2.10.1352711624; __utmc=190546871; __utmz=190546871.1349966519.143.3.utmcsr=en.wikipedia.org|utmccn=(referral)|utmcmd=referral|utmcct=/wiki/Single_transferable_vote; Sequence=162; SessionId=80e603f9-7e73-474b-8b7c-e198b2f11218; SecureSessionId=00000000-0000-0000-0000-000000000000; __utma=58336506.1016936529.1332752550.1352454680.1352711626.456; __utmb=58336506.28.10.1352711626; __utmc=58336506; __utmz=58336506.1352711626.456.155.utmcsr=a-website.com|utmccn=(referral)|utmcmd=referral|utmcct=/
00000009:iis-servers.clihdr[000a:ffff]: X-SSL-cipher: RC4-SHA SSLv3 Kx=RSA Au=RSA Enc=RC4(128) Mac=SHA1
00000009:iis-servers.clihdr[000a:ffff]: X-Forwarded-For: 1.2.3.4
00000008:iis-servers.srvcls[0008:0009]
00000008:iis-servers.clicls[0008:0009]
00000008:iis-servers.closed[0008:0009]
.......
0000000e:iis-servers.srvrep[0008:0009]: HTTP/1.1 200 OK
0000000e:iis-servers.srvhdr[0008:0009]: Cache-Control: no-cache
0000000e:iis-servers.srvhdr[0008:0009]: Pragma: no-cache
0000000e:iis-servers.srvhdr[0008:0009]: Content-Length: 12805
0000000e:iis-servers.srvhdr[0008:0009]: Content-Type: text/html; charset=utf-8
0000000e:iis-servers.srvhdr[0008:0009]: Server: Microsoft-IIS/7.0
0000000e:iis-servers.srvhdr[0008:0009]: X-AspNet-Version: 2.0.50727
0000000e:iis-servers.srvhdr[0008:0009]: X-Powered-By: ASP.NET
0000000e:iis-servers.srvhdr[0008:0009]: Date: Mon, 12 Nov 2012 10:02:22 GMT
0000000f:iis-servers.accept(0004)=000c from [127.0.0.1:53609]
0000000f:iis-servers.clireq[000c:ffff]: GET /Controls/ReferringOrganisationLogoImageHandler.ashx HTTP/1.1
0000000f:iis-servers.clihdr[000c:ffff]: Host: a-website.com
0000000f:iis-servers.clihdr[000c:ffff]: Connection: keep-alive
0000000f:iis-servers.clihdr[000c:ffff]: User-Agent: Mozilla/5.0 (Windows NT 6.2; WOW64) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.96 Safari/537.4
0000000f:iis-servers.clihdr[000c:ffff]: Accept: */*
0000000f:iis-servers.clihdr[000c:ffff]: Referer: https://a-website.com/eventmanagement/EditEvent.aspx?eventOid=623fc423-2329-4cab-8be5-72a97709570d
0000000f:iis-servers.clihdr[000c:ffff]: Accept-Encoding: gzip,deflate,sdch
0000000f:iis-servers.clihdr[000c:ffff]: Accept-Language: en-GB,en;q=0.8,it;q=0.6
0000000f:iis-servers.clihdr[000c:ffff]: Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3
0000000f:iis-servers.clihdr[000c:ffff]: Cookie: ASP.NET_SessionId=fnoz2hmvirfivb2btbubbw45; apps=apps2; __utma=190546871.552451749.1340295610.1352454675.1352711624.159; __utmb=190546871.2.10.1352711624; __utmc=190546871; __utmz=190546871.1349966519.143.3.utmcsr=en.wikipedia.org|utmccn=(referral)|utmcmd=referral|utmcct=/wiki/Single_transferable_vote; AuthHint=true; __utma=58336506.1016936529.1332752550.1352454680.1352711626.456; __utmb=58336506.33.10.1352711626; __utmc=58336506; __utmz=58336506.1352711626.456.155.utmcsr=a-website.com|utmccn=(referral)|utmcmd=referral|utmcct=/; SessionId=69cd415c-2f4e-4ace-b8f7-926d054f87c2; SecureSessionId=00000000-0000-0000-0000-000000000000; Sequence=170
0000000f:iis-servers.clihdr[000c:ffff]: X-SSL-cipher: RC4-SHA SSLv3 Kx=RSA Au=RSA Enc=RC4(128) Mac=SHA1
0000000f:iis-servers.clihdr[000c:ffff]: X-Forwarded-For: 1.2.3.4
0000000f:iis-servers.srvrep[000c:000d]: HTTP/1.1 200 OK
0000000f:iis-servers.srvhdr[000c:000d]: Cache-Control: private
0000000f:iis-servers.srvhdr[000c:000d]: Content-Length: 142
0000000f:iis-servers.srvhdr[000c:000d]: Content-Type: image/png
0000000f:iis-servers.srvhdr[000c:000d]: Server: Microsoft-IIS/7.0
0000000f:iis-servers.srvhdr[000c:000d]: X-AspNet-Version: 2.0.50727
0000000f:iis-servers.srvhdr[000c:000d]: Set-Cookie: SessionId=69cd415c-2f4e-4ace-b8f7-926d054f87c2; path=/
0000000f:iis-servers.srvhdr[000c:000d]: Set-Cookie: SecureSessionId=00000000-0000-0000-0000-000000000000; path=/; secure
0000000f:iis-servers.srvhdr[000c:000d]: X-Powered-By: ASP.NET
0000000f:iis-servers.srvhdr[000c:000d]: Date: Mon, 12 Nov 2012 10:02:25 GMT
0000000e:iis-servers.srvcls[0008:0009]
0000000e:iis-servers.clicls[0008:0009]
0000000e:iis-servers.closed[0008:0009]
0000000f:iis-servers.srvcls[000c:000d]
0000000f:iis-servers.clicls[000c:000d]
0000000f:iis-servers.closed[000c:000d]
00000009:iis-servers.srvcls[000a:000b]
00000009:iis-servers.clicls[000a:000b]
00000009:iis-servers.closed[000a:000b]
Where in the chain is the issue here?
© Server Fault or respective owner
