Re: HTTP Basic Authorisation requests failing with HAProxy 1.7.2
On 10 March 2017 at 20:40:11, Christopher Faulet (cfau...@haproxy.com) wrote: Hi Jon, Here is a patch that should fix your bug. It was trickier than expected. Could you confirm that it fix your bug ? -- Christopher Faulet Hi Christopher, The patch does seem to fix the bug in my testing - I can’t reproduce the 503 errors with your patch on 1.8. Sorry for taking a few days to get around to looking at this & thanks for the fix! Jon
Re: HTTP Basic Authorisation requests failing with HAProxy 1.7.2
On 7 March 2017 at 08:48:37, Christopher Faulet (cfau...@haproxy.com) wrote: Thanks for these info. By checking how you named your trace filters, I guess you use the HTTP compression. If I'm right, I think I found a bug with the help of your logs. The bug is triggered when your HTTP server replies before the end of the request. I guess it always sends its 401 responses just after reading requests headers. So it is timing issue from the HAProxy point of view. This should work of course. If I'm right, the bug only appears when a filter is used. So a temporary workaround, waiting my fix, is to disable the HTTP compression. I'll try to fix it very soon, I just need to talk with Willy to do it the right way. I will keep you informed. -- Christopher Faulet Hi Christopher, Yes - you’re right, in our normal configuration the compression filter is enabled. I was able to continue replicating the issue even without the compression filter when testing/generating those logs, but that was with the trace filter enabled - so there was always a filter. When I remove all filters (both trace & compression) the issue doesn’t reproduce in my test environment any more, so I think your theory is correct. Thanks for tracking it down - much appreciated :) Jon
Re: HTTP Basic Authorisation requests failing with HAProxy 1.7.2
On 2 March 2017 at 20:56:37, Christopher Faulet (cfau...@haproxy.com) wrote: Le 02/03/2017 à 16:46, Jon Simpson a écrit : > Hi all, > > Further to my previous message to the list I can now reliably reproduce > the behaviour where certain requests using authentication headers > receive 503 responses from HAProxy 1.7.3. > > We’re making a request twice, once without basic auth (checking that > basic auth is prompted on the URL) and then a second, identical, request > but with the the basic auth Authorization header set. The request body > is textual file content, so these requests are larger than average > GET/POST requests (Content-Length > 3500). We don't see this problem > with smaller requests. > > The two requests happen on a single connection to HAProxy as we have > keepalive enabled. The first request is always sent to the backend > successfully and but the second request receives a 503 status from > HAProxy whenever the request size is over a Content-Length of 3500. Just > below this size the 503’s are sporadic and at very small body sizes it > doesn’t happen at all - the request is sent to the backend succesfully. > > There are no errors visible by catting the stats socket, and the second > request/503 response is not present in logs at all (using option httplog). > > We don't get this behaviour when keeping all other variables the same > (client, request body & HAProxy configuration) using HAProxy 1.6.11. > > Thanks in advance for any help anyone can provide. Hi, I've quickly tried to reproduce your bug without success. Please, share you configuration to be sure to do test in the same situation. It could also be helpful to have a tcpdump for data exchanged between your client and HAProxy and another one for data exchanged between HAProxy and your webserver. If you cannot do a tcpdump, you can use the trace filter by adding the following line in your frontend/listener section: filer trace Then run HAProxy in foreground. -- Christopher Faulet Hi Christopher, Thanks for your response. I’ve attached the requested configuration and HAProxy trace logs below (TCPdump appeared to be much noisier). I have an input file which reproduces the 503 case but not predictably, so I’ve included one log which generated the correct 401 response from HAProxy and one which returned a 503 response. The 503 response comes back every time with larger requests than this. I’ve stripped down the configuration to a minimum which reproduces the issue. The behaviour only seems to occur with proxy-protocol enabled (accept-proxy). I initially tested directly sending requests directly to HAProxy and that works without the 503 responses. We run this HAProxy configuration behind Amazon ELB - a TCP load balancer with proxy protocol enabled, where the issue occurs (and it occurred in my test environment once proxy protocol was enabled and connections went through the TCP load balancer). Thanks, Jon 1488550830.939713 [FE-BEFORE-COMP/https-in] [strm 0x55ec556ab060(6) 0x 0x] trace_attach : filter-type=frontend 1488550830.939713 [FE-BEFORE-COMP/https-in] [strm 0x55ec556ab060(6) 0x 0x] trace_stream_start 0006:https-in.accept(0005)=0008 from [34.250.167.137:38280] 1488550830.939713 [FE-BEFORE-COMP/https-in] [strm 0x55ec556ab060(6) 0x00034035 0x] trace_chn_start_analyze : channel=REQUEST- mode=HTTP (frontend) 1488550830.939713 [FE-BEFORE-COMP/https-in] [strm 0x55ec556ab060(6) 0x00034034 0x] trace_chn_analyze: channel=REQUEST- mode=HTTP (frontend) - analyzer=AN_REQ_WAIT_HTTP - step=PRE 1488550830.976938 [FE-BEFORE-COMP/https-in] [strm 0x55ec556ab060(6) 0x00034034 0x] trace_chn_analyze: channel=REQUEST- mode=HTTP (frontend) - analyzer=AN_REQ_WAIT_HTTP - step=PRE 0006:https-in.clireq[0008:]: POST /v1/expost/check HTTP/1.1 0006:https-in.clihdr[0008:]: Content-Length: 3632 0006:https-in.clihdr[0008:]: Content-Type: application/xml 0006:https-in.clihdr[0008:]: Host: [REDACTED] 0006:https-in.clihdr[0008:]: Connection: Keep-Alive 0006:https-in.clihdr[0008:]: User-Agent: Apache-HttpClient/4.2.3 (java 1.5) 1488550830.976938 [FE-BEFORE-COMP/https-in] [strm 0x55ec556ab060(6) 0x00034030 0x] trace_chn_analyze: channel=REQUEST- mode=HTTP (frontend) - analyzer=AN_REQ_WAIT_HTTP - step=POST 1488550830.976938 [FE-BEFORE-COMP/https-in] [strm 0x55ec556ab060(6) 0x00034030 0x] trace_chn_analyze: channel=REQUEST- mode=HTTP (frontend) - analyzer=AN_REQ_HTTP_PROCESS_FE - step=PRE 1488550830.976938 [FE-BEFORE-COMP/https-in] [strm 0x55ec556ab060(6) 0x00034020 0x] trace_chn_analyze: channel=REQUEST- mode=HTTP (frontend) - analyzer=AN_REQ_HTTP_PROCESS_FE - step=POST 1488550830.976938 [FE-BEFORE-COMP/https-in] [strm 0x55ec
Re: HTTP Basic Authorisation requests failing with HAProxy 1.7.2
Hi all, Further to my previous message to the list I can now reliably reproduce the behaviour where certain requests using authentication headers receive 503 responses from HAProxy 1.7.3. We’re making a request twice, once without basic auth (checking that basic auth is prompted on the URL) and then a second, identical, request but with the the basic auth Authorization header set. The request body is textual file content, so these requests are larger than average GET/POST requests (Content-Length > 3500). We don't see this problem with smaller requests. The two requests happen on a single connection to HAProxy as we have keepalive enabled. The first request is always sent to the backend successfully and but the second request receives a 503 status from HAProxy whenever the request size is over a Content-Length of 3500. Just below this size the 503’s are sporadic and at very small body sizes it doesn’t happen at all - the request is sent to the backend succesfully. There are no errors visible by catting the stats socket, and the second request/503 response is not present in logs at all (using option httplog). We don't get this behaviour when keeping all other variables the same (client, request body & HAProxy configuration) using HAProxy 1.6.11. Thanks in advance for any help anyone can provide. Jon Relevant parts of a client log. Our app server runs IIS/8.5, the 503 Service Unavailable is from our HAProxy 503 template. 2017/03/02 12:14:02:133 UTC [DEBUG] DefaultHttpClient - Attempt 1 to execute request 2017/03/02 12:14:02:133 UTC [DEBUG] DefaultClientConnection - Sending request: POST /v1/expost/check HTTP/1.1 2017/03/02 12:14:02:134 UTC [DEBUG] wire - >> "POST /v1/expost/check HTTP/1.1[\r][\n]" 2017/03/02 12:14:02:134 UTC [DEBUG] wire - >> "Content-Length: 3634[\r][\n]" 2017/03/02 12:14:02:151 UTC [DEBUG] wire - << "HTTP/1.1 401 Unauthorized[\r][\n]" 2017/03/02 12:14:02:152 UTC [DEBUG] wire - << "Server: Microsoft-IIS/8.5[\r][\n]” 2017/03/02 12:14:02:157 UTC [DEBUG] DefaultHttpClient - Connection can be kept alive indefinitely 2017/03/02 12:14:02:158 UTC [DEBUG] DefaultHttpClient - Authentication required 2017/03/02 12:14:02:159 UTC [DEBUG] DefaultHttpClient - XXX:443 requested authentication 2017/03/02 12:14:02:170 UTC [DEBUG] RequestTargetAuthentication - Target auth state: CHALLENGED 2017/03/02 12:14:02:171 UTC [DEBUG] RequestTargetAuthentication - Generating response to an authentication challenge using basic scheme 2017/03/02 12:14:02:179 UTC [DEBUG] DefaultHttpClient - Attempt 2 to execute request 2017/03/02 12:14:02:179 UTC [DEBUG] DefaultClientConnection - Sending request: POST /v1/expost/check HTTP/1.1 2017/03/02 12:14:02:179 UTC [DEBUG] wire - >> "POST /v1/expost/check HTTP/1.1[\r][\n]" 2017/03/02 12:14:02:182 UTC [DEBUG] wire - >> "Content-Length: 3634[\r][\n]" 2017/03/02 12:14:02:196 UTC [DEBUG] wire - << "HTTP/1.0 503 Service Unavailable[\r][\n]" 2017/03/02 12:14:02:196 UTC [DEBUG] wire - << "Cache-Control: no-cache[\r][\n]" 2017/03/02 12:14:02:196 UTC [DEBUG] wire - << "Connection: close[\r][\n]" On 21 February 2017 at 18:36:21, Jon Simpson (j...@fundapps.co) wrote: Hi all, We’re experiencing a problem with clients receiving 503 responses when making a request to a backend with a Authorisation header set (basic authentication) using HAProxy 1.7.2. We didn't experience this with HAProxy 1.6.11. The HAProxy stats page shows that the backends in question have no downtime (what I would usually expect to see in cases where 503 statuses are returned). Only certain clients are affected by this behaviour - a number have been completely unaffected. The behaviour we're seeing shares some similarities to one that reported in 1.7.1 ( https://www.mail-archive.com/haproxy@formilux.org/msg24613.html) but we're not seeing any useful output from show errors and the code is 503. We do know that packet reordering/retranmission is happening in at least one case. Our clients can retry these requests and occasionally get them to succeed. Additionally, they found putting delays between the post of data and close of the connection did lead to successes in making the connection. We're sure HAProxy is the source of our client's 503 errors as the clients are getting the text of our custom 503 page (rather than a 503 from the IIS service behind). For context - we have an ELB in TCP-only mode in front of the HAProxy (to distribute connections across multiple HAProxy instances) if that's relevant. We're using the latest HAProxy 1.7 Ubuntu PPA's ( https://launchpad.net/~vbernat/+archive/ubuntu/haproxy-1.7). Logging is enabled, with the following format string (we capture the Host request header with a len of 64 for +Q) - log-format %ci:%cp\ [%t]\ %ft\ %b/%s\ %Tq/%Tw/%Tc/%Tr/%Tt\ %ST\ %B\ %CC\ %CS\ %tsc\ %ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %hr\ %hs\ %{+Q}r\ %ID but
HTTP Basic Authorisation requests failing with HAProxy 1.7.2
Hi all, We’re experiencing a problem with clients receiving 503 responses when making a request to a backend with a Authorisation header set (basic authentication) using HAProxy 1.7.2. We didn't experience this with HAProxy 1.6.11. The HAProxy stats page shows that the backends in question have no downtime (what I would usually expect to see in cases where 503 statuses are returned). Only certain clients are affected by this behaviour - a number have been completely unaffected. The behaviour we're seeing shares some similarities to one that reported in 1.7.1 ( https://www.mail-archive.com/haproxy@formilux.org/msg24613.html) but we're not seeing any useful output from show errors and the code is 503. We do know that packet reordering/retranmission is happening in at least one case. Our clients can retry these requests and occasionally get them to succeed. Additionally, they found putting delays between the post of data and close of the connection did lead to successes in making the connection. We're sure HAProxy is the source of our client's 503 errors as the clients are getting the text of our custom 503 page (rather than a 503 from the IIS service behind). For context - we have an ELB in TCP-only mode in front of the HAProxy (to distribute connections across multiple HAProxy instances) if that's relevant. We're using the latest HAProxy 1.7 Ubuntu PPA's ( https://launchpad.net/~vbernat/+archive/ubuntu/haproxy-1.7). Logging is enabled, with the following format string (we capture the Host request header with a len of 64 for +Q) - log-format %ci:%cp\ [%t]\ %ft\ %b/%s\ %Tq/%Tw/%Tc/%Tr/%Tt\ %ST\ %B\ %CC\ %CS\ %tsc\ %ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %hr\ %hs\ %{+Q}r\ %ID but we don't appear to be seeing the requests that are receiving 503 responses being logged. We do use 'option dontlognull' as these HAProxy instances are behind ELB, and hence get checked for TCP liveness but as these are valid HTTPS requests being returned 503 I would expect them to be in our main haproxy log. I'd really appreciate any input you could give on further triage steps (especially being able to identify in log when clients are receiving 503 responses) or potential causes we can look at. Thanks, Jon