HAProxy: Display a "BADREQ" | BADREQ's by the thousands

Posted by GruffTech on Server Fault See other posts from Server Fault or by GruffTech
Published on 2011-06-30T16:29:28Z Indexed on 2012/10/29 11:04 UTC
Read the original article Hit count: 1064

My HAProxy Configuration.

#HA-Proxy version 1.3.22 2009/10/14  Copyright 2000-2009 Willy Tarreau <[email protected]>
global
    maxconn 10000
    spread-checks 50
    user haproxy
    group haproxy
    daemon
    stats socket /tmp/haproxy
    log localhost   local0
    log localhost   local1 notice

defaults
    mode    http
    maxconn 50000
    timeout client 10000
    option forwardfor except 127.0.0.1
    option httpclose
    option httplog

listen dcaustin 0.0.0.0:80
    mode http
    timeout connect 12000
    timeout server 60000
    timeout queue 120000
    balance roundrobin
    option httpchk GET /index.html
    log global
    option httplog
    option dontlog-normal
    server web1 10.10.10.101:80 maxconn 300 check fall 1
    server web2 10.10.10.102:80 maxconn 300 check fall 1
    server web3 10.10.10.103:80 maxconn 300 check fall 1
    server web4 10.10.10.104:80 maxconn 300 check fall 1

listen stats 0.0.0.0:9000
    mode http
    balance
    log global
    timeout client 5000
    timeout connect 4000
    timeout server 30000
    stats uri /haproxy

HAProxy is running, and the socket is working...

adam@dcaustin:/etc/haproxy# echo "show info" | socat stdio /tmp/haproxy 
Name: HAProxy
Version: 1.3.22
Release_date: 2009/10/14
Nbproc: 1
Process_num: 1
Pid: 6320
Uptime: 0d 0h14m58s
Uptime_sec: 898
Memmax_MB: 0
Ulimit-n: 20017
Maxsock: 20017
Maxconn: 10000
Maxpipes: 0
CurrConns: 47
PipesUsed: 0
PipesFree: 0
Tasks: 51
Run_queue: 1
node: dcaustin
desiption: 

Errors show nothing from socket...

adam@dcaustin:/etc/haproxy# echo "show errors" | socat stdio /tmp/haproxy 
adam@dcaustin:/etc/haproxy# 

However...

My Error log is exploding with "badrequests" with the Error code cR. cR (according to 1.3 documentation) is The "timeout http-request" stroke before the client sent a full HTTP request. This is sometimes caused by too large TCP MSS values on the client side for PPPoE networks which cannot transport full-sized packets, or by clients sending requests by hand and not typing fast enough, or forgetting to enter the empty line at the end of the request. The HTTP status code is likely a 408 here.

Correct on the 408, but we're getting literally thousands of these requests every hour. (This log snippet is an clip for about 10 seconds of time...)

Jun 30 11:08:52 localhost haproxy[6320]: 92.22.213.32:26448 [30/Jun/2011:11:08:42.384] dcaustin dcaustin/<NOSRV> -1/-1/-1/-1/10002 408 212 - - cR-- 35/35/18/0/0 0/0 "<BADREQ>"
Jun 30 11:08:54 localhost haproxy[6320]: 71.62.130.24:62818 [30/Jun/2011:11:08:44.457] dcaustin dcaustin/<NOSRV> -1/-1/-1/-1/10001 408 212 - - cR-- 39/39/16/0/0 0/0 "<BADREQ>"
Jun 30 11:08:55 localhost haproxy[6320]: 84.73.75.236:3589 [30/Jun/2011:11:08:45.021] dcaustin dcaustin/<NOSRV> -1/-1/-1/-1/10008 408 212 - - cR-- 35/35/15/0/0 0/0 "<BADREQ>"
Jun 30 11:08:55 localhost haproxy[6320]: 69.39.20.190:49969 [30/Jun/2011:11:08:45.709] dcaustin dcaustin/<NOSRV> -1/-1/-1/-1/10000 408 212 - - cR-- 37/37/16/0/0 0/0 "<BADREQ>"
Jun 30 11:08:56 localhost haproxy[6320]: 2.29.0.9:58772 [30/Jun/2011:11:08:46.846] dcaustin dcaustin/<NOSRV> -1/-1/-1/-1/10001 408 212 - - cR-- 43/43/22/0/0 0/0 "<BADREQ>"
Jun 30 11:08:57 localhost haproxy[6320]: 212.139.250.242:57537 [30/Jun/2011:11:08:47.568] dcaustin dcaustin/<NOSRV> -1/-1/-1/-1/10000 408 212 - - cR-- 42/42/21/0/0 0/0 "<BADREQ>"
Jun 30 11:08:58 localhost haproxy[6320]: 74.79.195.75:55046 [30/Jun/2011:11:08:48.559] dcaustin dcaustin/<NOSRV> -1/-1/-1/-1/10000 408 212 - - cR-- 46/46/24/0/0 0/0 "<BADREQ>"
Jun 30 11:08:58 localhost haproxy[6320]: 74.79.195.75:55044 [30/Jun/2011:11:08:48.554] dcaustin dcaustin/<NOSRV> -1/-1/-1/-1/10004 408 212 - - cR-- 45/45/24/0/0 0/0 "<BADREQ>"
Jun 30 11:08:58 localhost haproxy[6320]: 74.79.195.75:55045 [30/Jun/2011:11:08:48.554] dcaustin dcaustin/<NOSRV> -1/-1/-1/-1/10005 408 212 - - cR-- 44/44/24/0/0 0/0 "<BADREQ>"
Jun 30 11:09:00 localhost haproxy[6320]: 68.197.56.2:52781 [30/Jun/2011:11:08:50.975] dcaustin dcaustin/<NOSRV> -1/-1/-1/-1/10000 408 212 - - cR-- 49/49/28/0/0 0/0 "<BADREQ>"

From what I read on google, if i wanted to see what the bad requests are, I can show errors to the socket and it will spit them out. We do run a pretty heavily trafficed website and the percentage of "BADREQS" to normal requests is quite low, but I'd like to be able to get ahold of what that request WAS so I can debug it.

stats

# pxname,svname,qcur,qmax,scur,smax,slim,stot,bin,bout,dreq,dresp,ereq,econ,eresp,wretr,wredis,status,weight,act,bck,chkfail,chkdown,lastchg,downtime,qlimit,pid,iid,sid,throttle,lbtot,tracked,type,rate,rate_lim,rate_max,
dcaustin,FRONTEND,,,64,120,50000,88433,105889100,2553809875,0,0,4641,,,,,OPEN,,,,,,,,,1,1,0,,,,0,45,0,128,
dcaustin,web1,0,0,10,28,300,20941,25402112,633143416,,0,,0,3,0,0,UP,1,1,0,0,0,2208,0,,1,1,1,,20941,,2,11,,30,
dcaustin,web2,0,0,9,30,300,20941,25026691,641475169,,0,,0,3,0,0,UP,1,1,0,0,0,2208,0,,1,1,2,,20941,,2,11,,30,
dcaustin,web3,0,0,10,27,300,20940,30116527,635015040,,0,,0,9,0,0,UP,1,1,0,0,0,2208,0,,1,1,3,,20940,,2,10,,31,
dcaustin,web4,0,0,5,28,300,20940,25343770,643209546,,0,,0,8,0,0,UP,1,1,0,0,0,2208,0,,1,1,4,,20940,,2,11,,31,
dcaustin,BACKEND,0,0,34,95,50000,83762,105889100,2553809875,0,0,,0,34,0,0,UP,4,4,0,,0,2208,0,,1,1,0,,83762,,1,43,,122,

88500 "Sessions" and 4500 errors. in the last 20 minutes.

© Server Fault or respective owner

Related posts about load-balancing

Related posts about ubuntu-10.04