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
