Pound 位于 HAProxy 前面(在同一个盒子上),用于执行 SSL 卸载。请求被传递到 127.0.0.1:80,然后 HAProxy 会在托管的 ASP .NET Web 应用程序的后端服务器之间平衡请求。
今天早上,一位用户的浏览器返回了 HTTP 错误 500(内部服务器错误),我发现这是来自 Pound 的。他们在 Web 应用程序(IIS)服务器日志中没有看到任何日志条目,因此它没有影响后端服务器。我认为问题可能出在 HAProxy 上。
让我们回顾一下日志:
最初,用户(1.2.3.4)点击负载均衡器:
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)
上面我们可以看到来自 IP 地址为 1.2.3.4 的用户的请求,最终 Pound 返回错误 500,并显示消息“连接超时(15.121 秒)”。
在调试模式下运行HAProxy,我们可以看到请求进来;
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]
问题出在链条的哪个部分?
答案1
原来答案就在我眼前:Connection timed out (15.121 secs)
Pound 与后端通信的默认超时时间为 15 秒。如果用户正在执行长查询(例如长时间运行的 POST),则会超出此超时时间,呵呵!
已改变此问题并已修复。