Паунд сидит перед HAProxy (на том же самом поле), чтобы выполнить разгрузку SSL. Запросы передаются на 127.0.0.1:80, где HAProxy затем балансирует запросы между внутренними серверами для размещенного веб-приложения ASP .NET.
Сегодня утром в браузере возвращается ошибка HTTP 500 (внутренняя ошибка сервера), и я вижу, что она исходит от Паунда. Они не видят никаких записей в журналах серверов своих веб-приложений (IIS), поэтому они не попадают на внутренние серверы. Думаю, проблема, возможно, в HAProxy.
Рассмотрим журналы:
Первоначально пользователи (1.2.3.4) нажимают Pound на балансировщике нагрузки:
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]
Где в цепочке проблема?
Оказывается, ответ все время смотрел мне в глаза: Connection timed out (15.121 secs)
Таймаут по умолчанию для связи с серверной частью Pound составляет 15 секунд. Если пользователь выполняет длинный запрос (например, длительный POST), этот таймаут будет превышен, да!
Изменили это и теперь исправили.