Hi all,
I am having an issue on a load-balancer running Pound and HAProxy. I
believe the error is with HAProxy but it doesn't give an error.
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 coming 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?
Many thanks,
James.
