Re: HTTP Basic Authorisation requests failing with HAProxy 1.7.2

[Willy Tarreau]

Hi Jon,

On Wed, Mar 15, 2017 at 12:38:38PM -0500, Jon Simpson wrote:
> 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!

Much appreciated, thanks for the feedback. I'll queue it tomorrow.
Don't worry about the delay, a late confirmation is always better
than none.

Thanks!
Willy

Re: HTTP Basic Authorisation requests failing with HAProxy 1.7.2

[Jon Simpson]

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

[Christopher Faulet]

Le 07/03/2017 à 20:51, Jon Simpson a écrit :

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 :)



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
>From 0e47d5db9cca60d3633fd4e1183948298a3fe07e Mon Sep 17 00:00:00 2001
From: Christopher Faulet 
Date: Fri, 10 Mar 2017 11:52:44 +0100
Subject: [PATCH] BUG/MEDIUM: filters: Fix channels synchronization in
 flt_end_analyze
X-Bogosity: Ham, tests=bogofilter, spamicity=0.00, version=1.2.4

When a filter is used, there are 2 channel's analyzers to surround all the
others, flt_start_analyze and flt_end_analyze. This is the good place to acquire
and release resources used by filters, when needed. In addition, the last one is
used to synchronize the both channels, especially for HTTP streams. We must wait
that the analyze is finished for the both channels for an HTTP transaction
before restarting it for the next one.

But this part was buggy, leading to unexpected behaviours. First, depending on
which channel ends first, the request or the response can be switch in a
"forward forever" mode. Then, the HTTP transaction can be cleaned up too early,
while a processing is still in progress on a channel.

To fix the bug, the flag CF_FLT_ANALYZE has been added. It is set on channels in
flt_start_analyze and is kept if at least one filter is still analyzing the
channel. So, we can trigger the channel syncrhonization if this flag was removed
on the both channels. In addition, the flag TX_WAIT_CLEANUP has been added on
the transaction to know if the transaction must be cleaned up or not during
channels syncrhonization. This way, we are sure to reset everything once all the
processings are finished.

This patch should be backported in 1.7.
---
 include/types/channel.h|  3 ++-
 include/types/proto_http.h |  7 ++-
 src/filters.c  | 52 --
 src/proto_http.c   | 19 +++--
 4 files changed, 48 insertions(+), 33 deletions(-)

diff --git a/include/types/channel.h b/include/types/channel.h
index 76f1ca0..03bb4e2 100644
--- a/include/types/channel.h
+++ b/include/types/channel.h
@@ -116,7 +116,8 @@
 #define CF_NEVER_WAIT 0x0800  /* never wait for sending data (permanent) */
 
 #define CF_WAKE_ONCE  0x1000  /* pretend there is activity on this channel (one-shoot) */
-/* unused: 0x2000, 0x4000 */
+#define CF_FLT_ANALYZE0x2000  /* at least one filter is still analyzing this channel */
+/* unused: 0x4000 */
 #define CF_ISRESP 0x8000  /* 0 = request channel, 1 = response channel */
 
 /* Masks which define input events for stream analysers */
diff --git a/include/types/proto_http.h b/include/types/proto_http.h
index 66f7397..9987c33 100644
--- a/include/types/proto_http.h
+++ b/include/types/proto_http.h
@@ -68,7 +68,12 @@
 #define TX_CACHE_COOK	0x2000	/* a cookie in the response is cacheable */
 #define TX_CACHE_SHIFT	12		/* bit shift */
 
-/* Unused: 0x4000, 0x8000, 0x1, 0x2, 0x8 */
+/* Unused: 0x4000, 0x8000 */
+
+#define TX_WAIT_CLEANUP	0x001	/* this transaction is waiting for a clean up */
+
+/* Unused: 0x2, 0x8 */
+
 
 /* indicate how we *want* the connection to behave, regardless of what is in
  * the headers. We have 4 possible values right now :
diff --git a/src/filters.c b/src/filters.c
index 9ec794a..fa63991 100644
--- a/src/filters.c
+++ b/src/filters.c
@@ -693,6 +693,9 @@ flt_start_analyze(struct stream *s, struct channel *chn, unsigned int an_bit)
 	/* If this function is called, this means there is at least one filter,
 	 * so we do not need to check the filter list's emptiness. */
 

Re: HTTP Basic Authorisation requests failing with HAProxy 1.7.2

[Jon Simpson]

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

[Christopher Faulet]

Le 03/03/2017 à 15:44, Jon Simpson a écrit :


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).



Hi Jon,

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

Re: HTTP Basic Authorisation requests failing with HAProxy 1.7.2

[Jon Simpson]

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 0x55ec556ab060(6) 0x00034020 
0x] trace_chn_analyze: channel=REQUEST- 

Re: HTTP Basic Authorisation requests failing with HAProxy 1.7.2

[Christopher Faulet]

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

Re: HTTP Basic Authorisation requests failing with HAProxy 1.7.2

[Jon Simpson]

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 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 

HTTP Basic Authorisation requests failing with HAProxy 1.7.2

[Jon Simpson]

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