Re: haproxy duplicate http_request_counter values (BUG)

[Willy Tarreau]

Hi guys,

On Wed, Aug 28, 2013 at 04:41:57PM +0200, William Lallemand wrote:
 On Tue, Aug 20, 2013 at 04:14:05PM -0400, Patrick Hemmer wrote:
  I see 2 ways of handling this.
  1) Move the code that populates the session unique_id member to
  http_process_req_common (or to http_wait_for_request where it's
  allocated). This will let requests terminated by an `errorfile`
  directive log out a request ID.
  2) Initialize the unique_id member upon allocation.
  
  I've attached a patch which does option 2, but I'm not sure if option 1
  would be preferable so that even `errorfile` requests will get a request ID.
  
  -Patrick
 
 Hello Patrick,
 
 Thanks for reporting the bug, I implemented something more relevant, the
 unique-id is now generated when a request failed.

Applied, thanks!

Willy

Re: haproxy duplicate http_request_counter values (BUG)

[William Lallemand]

On Tue, Aug 20, 2013 at 04:14:05PM -0400, Patrick Hemmer wrote:
 I see 2 ways of handling this.
 1) Move the code that populates the session unique_id member to
 http_process_req_common (or to http_wait_for_request where it's
 allocated). This will let requests terminated by an `errorfile`
 directive log out a request ID.
 2) Initialize the unique_id member upon allocation.
 
 I've attached a patch which does option 2, but I'm not sure if option 1
 would be preferable so that even `errorfile` requests will get a request ID.
 
 -Patrick

Hello Patrick,

Thanks for reporting the bug, I implemented something more relevant, the
unique-id is now generated when a request failed.

-- 
William Lallemand
From 6c2adb543c54df657e37836fc484a7f4e97ef7e1 Mon Sep 17 00:00:00 2001
From: William Lallemand wlallem...@exceliance.fr
Date: Wed, 28 Aug 2013 15:44:19 +0200
Subject: [PATCH] BUG/MEDIUM: unique_id: junk in log on empty unique_id

When a request fail, the unique_id was allocated but not generated.
The string was not initialized and junk was printed in the log with %ID.

This patch changes the behavior of the unique_id. The unique_id is now
generated when a request failed.

This bug was reported by Patrick Hemmer.
---
 src/log.c| 10 +-
 src/proto_http.c |  9 +
 2 files changed, 14 insertions(+), 5 deletions(-)

diff --git a/src/log.c b/src/log.c
index 369dc34..f1fe40c 100644
--- a/src/log.c
+++ b/src/log.c
@@ -1488,8 +1488,10 @@ int build_logline(struct session *s, char *dst, size_t maxsize, struct list *lis
 break;
 
 			case LOG_FMT_UNIQUEID: // %ID
+ret = NULL;
 src = s-unique_id;
-ret = lf_text(tmplog, src, maxsize - (tmplog - dst), tmp);
+if (src)
+	ret = lf_text(tmplog, src, maxsize - (tmplog - dst), tmp);
 if (ret == NULL)
 	goto out;
 tmplog = ret;
@@ -1541,6 +1543,12 @@ void sess_log(struct session *s)
 			level = LOG_ERR;
 	}
 
+	/* if unique-id was not generated */
+	if (!s-unique_id  !LIST_ISEMPTY(s-fe-format_unique_id)) {
+		if ((s-unique_id = pool_alloc2(pool2_uniqueid)) != NULL)
+			build_logline(s, s-unique_id, UNIQUEID_LEN, s-fe-format_unique_id);
+	}
+
 	tmplog = update_log_hdr();
 	size = tmplog - logline;
 	size += build_logline(s, tmplog, sizeof(logline) - size, s-fe-logformat);
diff --git a/src/proto_http.c b/src/proto_http.c
index 8d6eaf5..6ab2676 100644
--- a/src/proto_http.c
+++ b/src/proto_http.c
@@ -2635,9 +2635,6 @@ int http_wait_for_request(struct session *s, struct channel *req, int an_bit)
 		}
 	}
 
-	if (!LIST_ISEMPTY(s-fe-format_unique_id))
-		s-unique_id = pool_alloc2(pool2_uniqueid);
-
 	/* 4. We may have to convert HTTP/0.9 requests to HTTP/1.0 */
 	if (unlikely(msg-sl.rq.v_l == 0)  !http_upgrade_v09_to_v10(txn))
 		goto return_bad_req;
@@ -3950,8 +3947,12 @@ int http_process_request(struct session *s, struct channel *req, int an_bit)
 
 	/* add unique-id if header-unique-id is specified */
 
-	if (!LIST_ISEMPTY(s-fe-format_unique_id))
+	if (!LIST_ISEMPTY(s-fe-format_unique_id)) {
+		if ((s-unique_id = pool_alloc2(pool2_uniqueid)) == NULL)
+			goto return_bad_req;
+		s-unique_id[0] = '\0';
 		build_logline(s, s-unique_id, UNIQUEID_LEN, s-fe-format_unique_id);
+	}
 
 	if (s-fe-header_unique_id  s-unique_id) {
 		chunk_printf(trash, %s: %s, s-fe-header_unique_id, s-unique_id);
-- 
1.8.1.5

Re: haproxy duplicate http_request_counter values (BUG)

[Patrick Hemmer]

On 2013/08/11 15:45, Patrick Hemmer wrote:
 I'm using the %rt field in the unique-id-format config parameter
 (the full value is %{+X}o%pid-%rt), and am getting lots of
 duplicates. In one specific case, haproxy added the same
 http_request_counter value to 70 different http requests within a span
 of 61 seconds (from various client hosts too). Does the
 http_request_counter only increment under certain conditions, or is
 this a bug?

 This is with haproxy 1.5-dev19

 -Patrick


This appears to be part of a bug. I just experienced a scenario where
haproxy stopped responding. When I went into the log I found binary
garbage in place of the request ID. I have haproxy configured to route
certain URLs, and to respond with a `errorfile` when a request comes in
that doesn't match any of the configure paths. It seems whenever I
request an invalid URL and get the `errorfile` response, the request ID
gets screwed up and becomes jumbled binary data.

For example: haproxy[28645]: 207.178.167.185:49560 api bad_url/NOSRV
71/-1/-1/-1/71 3/3/0/0/3 0/0 127/242 403 PR-- Á + GET / HTTP/1.1
Notice the Á, that's supposed to be the process ID and request ID
separated by a hyphen. When I pipe it into xxd, I get this:

000: 6861 7072 6f78 795b 3238 3634 355d 3a20  haproxy[28645]:
010: 3230 372e 3137 382e 3136 372e 3138 353a  207.178.167.185:
020: 3439 3536 3020 6170 6920 6261 645f 7572  49560 api bad_ur
030: 6c2f 3c4e 4f53 5256 3e20 3731 2f2d 312f  l/NOSRV 71/-1/
040: 2d31 2f2d 312f 3731 2033 2f33 2f30 2f30  -1/-1/71 3/3/0/0
050: 2f33 2030 2f30 2031 3237 2f32 3432 2034  /3 0/0 127/242 4
060: 3033 2050 522d 2d20 90c1 8220 2b20 4745  03 PR-- ... + GE
070: 5420 2f20 4854 5450 2f31 2e31 0a T / HTTP/1.1.


I won't post my entire config as it's over 300 lines, but here's the
juicy stuff:


global
log 127.0.0.1   local0
maxconn 20480
user haproxy
group haproxy
daemon

defaults
log global
modehttp
option  httplog
option  dontlognull
retries 3
option  redispatch
timeout connect 5000
timeout client 6
timeout server 17
option  clitcpka
option  srvtcpka

stats   enable
stats   uri /haproxy/stats
stats   refresh 5
stats   auth my:secret

listen stats
bind 0.0.0.0:90
mode http
stats enable
stats uri /
stats refresh 5

frontend api
  bind *:80
  bind *:81 accept-proxy

  option httpclose
  option forwardfor
  http-request add-header X-Request-Timestamp %Ts.%ms
  unique-id-format %{+X}o%pid-%rt
  unique-id-header X-Request-Id
  rspadd X-Api-Host:\ i-a22932d9

  reqrep ^([^\ ]*)\ ([^\?\ ]*)(\?[^\ ]*)?\ HTTP.*  \0\r\nX-API-URL:\ \2


  acl is_1_1 path_dir /1/my/path
  use_backend 1_1 if is_1_1

  acl is_1_2 path_dir /1/my/other_path
  use_backend 1_2 if is_1_2

  ...

  default_backend bad_url

  log-format %ci:%cp\ %ft\ %b/%s\ %Tq/%Tw/%Tc/%Tr/%Tt\
%ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %U/%B\ %ST\ %tsc\ %ID\ +\ %r

backend bad_url
  block if TRUE
  errorfile 403 /etc/haproxy/bad_url.http

Re: haproxy duplicate http_request_counter values (BUG)

[haproxy]

Oh, for some reason my mail client wasn't showing the response from
Willy when I made this reply. Not sure if this info is really necessary
any more. Will try the patch on that email and report back to it.

-Patrick

On 08/13/2013 07:13 PM, Patrick Hemmer wrote:

 On 2013/08/11 15:45, Patrick Hemmer wrote:
 I'm using the %rt field in the unique-id-format config parameter
 (the full value is %{+X}o%pid-%rt), and am getting lots of
 duplicates. In one specific case, haproxy added the same
 http_request_counter value to 70 different http requests within a
 span of 61 seconds (from various client hosts too). Does the
 http_request_counter only increment under certain conditions, or is
 this a bug?

 This is with haproxy 1.5-dev19

 -Patrick


 This appears to be part of a bug. I just experienced a scenario where
 haproxy stopped responding. When I went into the log I found binary
 garbage in place of the request ID. I have haproxy configured to route
 certain URLs, and to respond with a `errorfile` when a request comes
 in that doesn't match any of the configure paths. It seems whenever I
 request an invalid URL and get the `errorfile` response, the request
 ID gets screwed up and becomes jumbled binary data.

 For example: haproxy[28645]: 207.178.167.185:49560 api bad_url/NOSRV
 71/-1/-1/-1/71 3/3/0/0/3 0/0 127/242 403 PR-- Á + GET / HTTP/1.1
 Notice the Á, that's supposed to be the process ID and request ID
 separated by a hyphen. When I pipe it into xxd, I get this:

 000: 6861 7072 6f78 795b 3238 3634 355d 3a20  haproxy[28645]:
 010: 3230 372e 3137 382e 3136 372e 3138 353a  207.178.167.185:
 020: 3439 3536 3020 6170 6920 6261 645f 7572  49560 api bad_ur
 030: 6c2f 3c4e 4f53 5256 3e20 3731 2f2d 312f  l/NOSRV 71/-1/
 040: 2d31 2f2d 312f 3731 2033 2f33 2f30 2f30  -1/-1/71 3/3/0/0
 050: 2f33 2030 2f30 2031 3237 2f32 3432 2034  /3 0/0 127/242 4
 060: 3033 2050 522d 2d20 90c1 8220 2b20 4745  03 PR-- ... + GE
 070: 5420 2f20 4854 5450 2f31 2e31 0a T / HTTP/1.1.


 I won't post my entire config as it's over 300 lines, but here's the
 juicy stuff:


 global
 log 127.0.0.1   local0
 maxconn 20480
 user haproxy
 group haproxy
 daemon

 defaults
 log global
 modehttp
 option  httplog
 option  dontlognull
 retries 3
 option  redispatch
 timeout connect 5000
 timeout client 6
 timeout server 17
 option  clitcpka
 option  srvtcpka

 stats   enable
 stats   uri /haproxy/stats
 stats   refresh 5
 stats   auth my:secret

 listen stats
 bind 0.0.0.0:90
 mode http
 stats enable
 stats uri /
 stats refresh 5

 frontend api
   bind *:80
   bind *:81 accept-proxy

   option httpclose
   option forwardfor
   http-request add-header X-Request-Timestamp %Ts.%ms
   unique-id-format %{+X}o%pid-%rt
   unique-id-header X-Request-Id
   rspadd X-Api-Host:\ i-a22932d9

   reqrep ^([^\ ]*)\ ([^\?\ ]*)(\?[^\ ]*)?\ HTTP.*  \0\r\nX-API-URL:\ \2


   acl is_1_1 path_dir /1/my/path
   use_backend 1_1 if is_1_1

   acl is_1_2 path_dir /1/my/other_path
   use_backend 1_2 if is_1_2

   ...

   default_backend bad_url

   log-format %ci:%cp\ %ft\ %b/%s\ %Tq/%Tw/%Tc/%Tr/%Tt\
 %ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %U/%B\ %ST\ %tsc\ %ID\ +\ %r

 backend bad_url
   block if TRUE
   errorfile 403 /etc/haproxy/bad_url.http