On 2013/08/15 16:35, Patrick Hemmer wrote:
>
> On 08/13/2013 08:46 PM, hapr...@stormcloud9.net wrote:
>> 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:
>>>
>>> 0000000: 6861 7072 6f78 795b 3238 3634 355d 3a20 haproxy[28645]:
>>> 0000010: 3230 372e 3137 382e 3136 372e 3138 353a 207.178.167.185:
>>> 0000020: 3439 3536 3020 6170 6920 6261 645f 7572 49560 api bad_ur
>>> 0000030: 6c2f 3c4e 4f53 5256 3e20 3731 2f2d 312f l/<NOSRV> 71/-1/
>>> 0000040: 2d31 2f2d 312f 3731 2033 2f33 2f30 2f30 -1/-1/71 3/3/0/0
>>> 0000050: 2f33 2030 2f30 2031 3237 2f32 3432 2034 /3 0/0 127/242 4
>>> 0000060: 3033 2050 522d 2d20 90c1 8220 2b20 4745 03 PR-- ... + GE
>>> 0000070: 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
>>> mode http
>>> option httplog
>>> option dontlognull
>>> retries 3
>>> option redispatch
>>> timeout connect 5000
>>> timeout client 60000
>>> timeout server 170000
>>> 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
>>
> Ok, so as mentioned in the other email I just sent, the patch for the
> duplicate counter solves that issue, but it turns out the issue with
> binary garbage in the logs is unrelated and still persists.
> Just to provide a few more examples of the what I'm referring to, here
> are some more log entries:
>
> 2013-08-15T20:20:44.171+00:00 local0/info(6) haproxy[834]:
> 10.230.134.42:58555 api bad_url/<NOSRV> 0/-1/-1/-1/0 9/9/7/0/3 0/0
> 76/242 403 PR-- °I + GET / HTTP/1.1
> 2013-08-15T20:20:44.171+00:00 local0/info(6) haproxy[834]:
> 10.230.134.42:58556 api bad_url/<NOSRV> 0/-1/-1/-1/0 8/8/6/0/3 0/0
> 76/242 403 PR-- 0¥ + GET / HTTP/1.1
> 2013-08-15T20:20:44.171+00:00 local0/info(6) haproxy[834]:
> 10.230.134.42:58554 api bad_url/<NOSRV> 0/-1/-1/-1/0 7/7/5/0/3 0/0
> 76/242 403 PR-- E + GET / HTTP/1.1
> 2013-08-15T20:20:44.171+00:00 local0/info(6) haproxy[834]:
> 10.230.134.42:58561 api bad_url/<NOSRV> 0/-1/-1/-1/0 6/6/4/0/3 0/0
> 76/242 403 PR-- W + GET / HTTP/1.1
> 2013-08-15T20:20:44.171+00:00 local0/info(6) haproxy[834]:
> 10.230.134.42:58559 api bad_url/<NOSRV> 0/-1/-1/-1/0 5/5/3/0/3 0/0
> 76/242 403 PR-- j + GET / HTTP/1.1
> 2013-08-15T20:20:44.171+00:00 local0/info(6) haproxy[834]:
> 10.230.134.42:58560 api bad_url/<NOSRV> 0/-1/-1/-1/0 4/4/2/0/3 0/0
> 76/242 403 PR-- pe + GET / HTTP/1.1
> 2013-08-15T20:20:44.171+00:00 local0/info(6) haproxy[834]:
> 10.230.134.42:58558 api bad_url/<NOSRV> 0/-1/-1/-1/0 3/3/1/0/3 0/0
> 76/242 403 PR-- Ð` + GET / HTTP/1.1
> 2013-08-15T20:20:44.171+00:00 local0/info(6) haproxy[834]:
> 10.230.134.42:58563 api bad_url/<NOSRV> 0/-1/-1/-1/0 2/2/0/0/3 0/0
> 76/242 403 PR-- 0\ + GET / HTTP/1.1
> 2013-08-15T20:20:44.178+00:00 local0/info(6) haproxy[834]:
> 10.230.134.42:58562 api bad_url/<NOSRV> 7/-1/-1/-1/7 1/1/1/0/3 0/0
> 76/242 403 PR-- 0\ + GET / HTTP/1.1
> 2013-08-15T20:20:44.178+00:00 local0/info(6) haproxy[834]:
> 10.230.134.42:58564 api bad_url/<NOSRV> 7/-1/-1/-1/7 0/0/0/0/3 0/0
> 76/242 403 PR-- Ð` + GET / HTTP/1.1
>
> -Patrick
So I took a look at this issue, and what's happening is that the
session's unique ID is getting defined in http_process_request. However
in this case, the request is being terminated in
http_process_req_common, and never gets to http_process_request. So at
the time of logging, the session's unique_id member is unitialized, and
so whatever happens to be sitting in memory at that location gets
written to the log.
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
--- src/proto_http.c.orig 2013-08-20 20:09:01.775122042 +0000
+++ src/proto_http.c 2013-08-20 20:09:04.367130390 +0000
@@ -2635,8 +2635,10 @@
}
}
- if (!LIST_ISEMPTY(&s->fe->format_unique_id))
+ if (!LIST_ISEMPTY(&s->fe->format_unique_id)) {
s->unique_id = pool_alloc2(pool2_uniqueid);
+ s->unique_id[0] = '\0';
+ }
/* 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))
