Hello Willy,
Thank you for your input. After you mentioned the potential "999 limit"
I found out that uname -n showed a value of 1024. I increased the value
to 200000 and thought that this would be enough to tackle the problem.
It wasn't. The problem returned two days later. However, now it's the Tc
that's always -1, not the Tw.
Once it happens, the phenomenon goes on forever (I truncated the log
output) until I restart haproxy. I filtered the log file so it only
shows the output of the affected proxy. All other proxies are not
affected once it happens, it's just this one. I will capture the tcpdump
next time it happens.
Cheers,
Roland
---------------- -vv
HA-Proxy version 1.5-dev21-6b07bf7 +2013/12/17
Copyright 2000-2013 Willy Tarreau <[email protected]>
Build options :
TARGET = linux2628
CPU = generic
CC = gcc
CFLAGS = -O2 -g -fno-strict-aliasing
OPTIONS = USE_STATIC_PCRE=1
Default settings :
maxconn = 2000, bufsize = 16384, maxrewrite = 8192, maxpollevents =
200
Encrypted password support via crypt(3): yes
Built without zlib support (USE_ZLIB not set)
Compression algorithms supported : identity
Built without OpenSSL support (USE_OPENSSL not set)
Built with PCRE version : 8.31 2012-07-06
PCRE library supports JIT : no (USE_PCRE_JIT not set)
Built with transparent proxy support using: IP_TRANSPARENT
IPV6_TRANSPARENT IP_FREEBIND
Available polling systems :
epoll : pref=300, test result OK
poll : pref=200, test result OK
select : pref=150, test result OK
Total: 3 (3 usable), will use epoll.
---------------- os limits
core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 15861
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 200000
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 8192
cpu time (seconds, -t) unlimited
max user processes (-u) 15861
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited
---------------- config
global
daemon
maxconn 30000
log /dev/log local0 debug
user haproxy
group haproxy
pidfile /var/run/haproxy.pid
stats socket /var/run/haproxy.socket
defaults
maxconn 29500
retries 1
option abortonclose
timeout client 90s
timeout server 90s
timeout connect 20s
listen stats
bind 127.0.0.1:4711
mode http
stats enable
stats realm Bling\ Area
stats uri /
stats auth suggardaddy:whosyourdaddy
frontend frontend4711
log global
option tcplog
bind 23.23.23.23:8181
mode tcp
default_backend backend4711
backend backend4711
log global
option tcplog
mode tcp
server backend4711 server1:8282
---------------- it starts around 23:27
Jan 27 23:04:45 sugardaddy haproxy[13710]: 123.245.211.21:60156
[27/Jan/2014:23:04:45.220] frontend4711 backend4711/server1 1/67/163
3850 -- 950/0/0/0/0 0/0
Jan 27 23:06:35 sugardaddy haproxy[13710]: 123.192.183.144:51380
[27/Jan/2014:23:05:21.243] frontend4711 backend4711/server1 1/60/73773
55702 -- 976/4/4/4/0 0/0
Jan 27 23:06:35 sugardaddy haproxy[13710]: 123.192.183.144:51382
[27/Jan/2014:23:05:22.837] frontend4711 backend4711/server1 1/61/72179
7568 -- 975/3/3/3/0 0/0
Jan 27 23:06:35 sugardaddy haproxy[13710]: 123.192.183.144:51381
[27/Jan/2014:23:05:21.552] frontend4711 backend4711/server1 1/54/73464
110232 -- 974/2/2/2/0 0/0
Jan 27 23:06:35 sugardaddy haproxy[13710]: 123.192.183.144:51391
[27/Jan/2014:23:05:25.431] frontend4711 backend4711/server1 1/60/69585
182 -- 973/1/1/1/0 0/0
Jan 27 23:06:35 sugardaddy haproxy[13710]: 123.192.183.144:51383
[27/Jan/2014:23:05:22.847] frontend4711 backend4711/server1 1/54/72174
8698 -- 972/0/0/0/0 0/0
Jan 27 23:08:40 sugardaddy haproxy[13710]: 123.148.139.232:50145
[27/Jan/2014:23:08:36.267] frontend4711 backend4711/server1 1/60/4376
22039 -- 989/3/3/3/0 0/0
Jan 27 23:09:45 sugardaddy haproxy[13710]: 123.148.139.232:50160
[27/Jan/2014:23:08:41.934] frontend4711 backend4711/server1 1/83/63489
182 -- 966/4/4/4/0 0/0
Jan 27 23:09:45 sugardaddy haproxy[13710]: 123.148.139.232:50159
[27/Jan/2014:23:08:41.933] frontend4711 backend4711/server1 1/84/63498
182 -- 965/3/3/3/0 0/0
Jan 27 23:09:55 sugardaddy haproxy[13710]: 123.148.139.232:50149
[27/Jan/2014:23:08:38.497] frontend4711 backend4711/server1 1/54/76872
113320 -- 956/2/2/2/0 0/0
Jan 27 23:09:55 sugardaddy haproxy[13710]: 123.148.139.232:50150
[27/Jan/2014:23:08:38.503] frontend4711 backend4711/server1 1/67/76867
14138 -- 955/1/1/1/0 0/0
Jan 27 23:10:05 sugardaddy haproxy[13710]: 123.148.139.232:50148
[27/Jan/2014:23:08:38.491] frontend4711 backend4711/server1 1/67/86880
51795 -- 971/0/0/0/0 0/0
Jan 27 23:14:05 sugardaddy haproxy[13710]: 123.249.213.14:50622
[27/Jan/2014:23:13:23.657] frontend4711 backend4711/server1 1/66/42337
6148 -- 988/0/0/0/0 0/0
Jan 27 23:17:02 sugardaddy haproxy[13710]: 123.77.214.47:55668
[27/Jan/2014:23:16:00.577] frontend4711 backend4711/server1 1/60/61843
3946 CD 916/1/1/1/0 0/0
Jan 27 23:17:02 sugardaddy haproxy[13710]: 123.77.214.47:55669
[27/Jan/2014:23:16:00.573] frontend4711 backend4711/server1 1/61/61847
5647 CD 915/0/0/0/0 0/0
Jan 27 23:17:46 sugardaddy haproxy[13710]: 123.245.211.21:54605
[27/Jan/2014:23:17:46.568] frontend4711 backend4711/server1 1/-1/231 0
CC 977/0/0/0/0 0/0
Jan 27 23:26:30 sugardaddy haproxy[13710]: 123.217.161.171:43686
[27/Jan/2014:23:26:25.464] frontend4711 backend4711/server1 1/-1/5410 0
CC 899/0/0/0/0 0/0
Jan 27 23:27:08 sugardaddy haproxy[13710]: 123.217.161.171:43690
[27/Jan/2014:23:26:37.935] frontend4711 backend4711/server1 1/-1/30251 0
CC 898/0/0/0/1 0/0
Jan 27 23:27:48 sugardaddy haproxy[13710]: 123.217.161.171:43692
[27/Jan/2014:23:27:08.739] frontend4711 backend4711/server1 1/-1/40001 0
sC 885/0/0/0/1 0/0
Jan 27 23:28:03 sugardaddy haproxy[13710]: 123.217.161.171:43736
[27/Jan/2014:23:27:49.123] frontend4711 backend4711/server1 1/-1/14822 0
CC 880/0/0/0/0 0/0
Jan 27 23:28:07 sugardaddy haproxy[13710]: 123.217.161.171:43737
[27/Jan/2014:23:28:04.399] frontend4711 backend4711/server1 1/-1/3123 0
CC 885/0/0/0/0 0/0
Jan 27 23:28:14 sugardaddy haproxy[13710]: 123.217.161.171:43739
[27/Jan/2014:23:28:08.428] frontend4711 backend4711/server1 1/-1/6173 0
CC 894/0/0/0/0 0/0
Jan 27 23:28:42 sugardaddy haproxy[13710]: 123.217.161.171:43755
[27/Jan/2014:23:28:26.057] frontend4711 backend4711/server1 1/-1/16758 0
CC 931/8/8/8/0 0/0
Jan 27 23:28:44 sugardaddy haproxy[13710]: 123.217.161.171:43754
[27/Jan/2014:23:28:25.999] frontend4711 backend4711/server1 1/-1/18864 0
CC 919/7/7/7/0 0/0
Jan 27 23:28:44 sugardaddy haproxy[13710]: 123.217.161.171:43753
[27/Jan/2014:23:28:26.017] frontend4711 backend4711/server1 1/-1/18854 0
CC 917/6/6/6/0 0/0
Jan 27 23:29:00 sugardaddy haproxy[13710]: 123.166.36.116:57256
[27/Jan/2014:23:28:20.344] frontend4711 backend4711/server1 1/-1/40002 0
sC 906/10/10/10/1 0/0
Jan 27 23:29:00 sugardaddy haproxy[13710]: 123.166.36.116:57257
[27/Jan/2014:23:28:20.345] frontend4711 backend4711/server1 1/-1/40001 0
sC 905/9/9/9/1 0/0
Jan 27 23:29:00 sugardaddy haproxy[13710]: 123.166.36.116:57259
[27/Jan/2014:23:28:20.475] frontend4711 backend4711/server1 1/-1/40002 0
sC 905/8/8/8/1 0/0
Jan 27 23:29:00 sugardaddy haproxy[13710]: 123.166.36.116:57267
[27/Jan/2014:23:28:20.529] frontend4711 backend4711/server1 1/-1/40001 0
sC 903/7/7/7/1 0/0
Jan 27 23:29:00 sugardaddy haproxy[13710]: 123.166.36.116:57266
[27/Jan/2014:23:28:20.532] frontend4711 backend4711/server1 1/-1/40002 0
sC 902/6/6/6/1 0/0
Jan 27 23:29:00 sugardaddy haproxy[13710]: 123.166.36.116:57268
[27/Jan/2014:23:28:20.537] frontend4711 backend4711/server1 1/-1/40002 0
sC 901/5/5/5/1 0/0
Jan 27 23:29:32 sugardaddy haproxy[13710]: 123.166.36.116:57323
[27/Jan/2014:23:28:52.264] frontend4711 backend4711/server1 1/-1/40001 0
sC 925/8/8/8/1 0/0
Jan 27 23:29:39 sugardaddy haproxy[13710]: 123.166.36.116:57339
[27/Jan/2014:23:28:59.870] frontend4711 backend4711/server1 1/-1/40002 0
sC 933/7/7/7/1 0/0
Jan 27 23:29:40 sugardaddy haproxy[13710]: 123.166.36.116:57343
[27/Jan/2014:23:29:00.044] frontend4711 backend4711/server1 1/-1/40001 0
sC 929/6/6/6/1 0/0
Jan 27 23:29:40 sugardaddy haproxy[13710]: 123.166.36.116:57344
[27/Jan/2014:23:29:00.045] frontend4711 backend4711/server1 1/-1/40000 0
sC 928/5/5/5/1 0/0
Jan 27 23:29:40 sugardaddy haproxy[13710]: 123.166.36.116:57342
[27/Jan/2014:23:29:00.046] frontend4711 backend4711/server1 1/-1/40002 0
sC 927/4/4/4/1 0/0
Jan 27 23:30:11 sugardaddy haproxy[13710]: 123.166.36.116:57433
[27/Jan/2014:23:29:31.168] frontend4711 backend4711/server1 1/-1/40002 0
sC 895/3/3/3/1 0/0
Jan 27 23:30:11 sugardaddy haproxy[13710]: 123.166.36.116:57439
[27/Jan/2014:23:29:31.814] frontend4711 backend4711/server1 1/-1/40002 0
sC 895/2/2/2/1 0/0
Jan 27 23:30:11 sugardaddy haproxy[13710]: 123.166.36.116:57438
[27/Jan/2014:23:29:31.820] frontend4711 backend4711/server1 1/-1/40003 0
sC 894/1/1/1/1 0/0
Jan 27 23:30:11 sugardaddy haproxy[13710]: 123.166.36.116:57440
[27/Jan/2014:23:29:31.826] frontend4711 backend4711/server1 1/-1/40001 0
sC 893/0/0/0/1 0/0
Jan 27 23:31:25 sugardaddy haproxy[13710]: 123.135.196.148:40992
[27/Jan/2014:23:31:07.871] frontend4711 backend4711/server1 1/-1/17784 0
CC 864/2/2/2/0 0/0
Jan 27 23:31:37 sugardaddy haproxy[13710]: 123.135.196.148:35933
[27/Jan/2014:23:31:07.772] frontend4711 backend4711/server1 1/-1/29990 0
CC 876/1/1/1/1 0/0
Jan 27 23:31:37 sugardaddy haproxy[13710]: 123.135.196.148:36367
[27/Jan/2014:23:31:07.768] frontend4711 backend4711/server1 1/-1/29995 0
CC 875/0/0/0/1 0/0
Jan 27 23:32:36 sugardaddy haproxy[13710]: 123.135.196.148:34028
[27/Jan/2014:23:32:06.306] frontend4711 backend4711/server1 1/-1/29999 0
CC 885/0/0/0/1 0/0
Jan 27 23:33:14 sugardaddy haproxy[13710]: 123.135.196.148:34969
[27/Jan/2014:23:32:44.585] frontend4711 backend4711/server1 1/-1/30000 0
CC 893/0/0/0/1 0/0
Jan 27 23:35:09 sugardaddy haproxy[13710]: 123.135.196.148:48426
[27/Jan/2014:23:34:58.685] frontend4711 backend4711/server1 1/-1/11090 0
CC 906/2/2/2/0 0/0
Jan 27 23:35:28 sugardaddy haproxy[13710]: 123.135.196.148:35411
[27/Jan/2014:23:34:58.593] frontend4711 backend4711/server1 1/-1/29997 0
CC 894/2/2/2/1 0/0
Jan 27 23:35:28 sugardaddy haproxy[13710]: 123.55.127.101:59092
[27/Jan/2014:23:35:20.143] frontend4711 backend4711/server1 1/-1/8833 0
CC 896/1/1/1/0 0/0
Jan 27 23:35:30 sugardaddy haproxy[13710]: 123.135.196.148:44005
[27/Jan/2014:23:34:50.426] frontend4711 backend4711/server1 1/-1/40001 0
sC 897/0/0/0/1 0/0
Jan 27 23:36:09 sugardaddy haproxy[13710]: 123.164.22.194:56737
[27/Jan/2014:23:35:39.033] frontend4711 backend4711/server1 1/-1/30005 0
CC 897/3/3/3/1 0/0
Jan 27 23:36:10 sugardaddy haproxy[13710]: 123.135.196.148:47061
[27/Jan/2014:23:35:30.724] frontend4711 backend4711/server1 1/-1/40000 0
sC 894/2/2/2/1 0/0
Jan 27 23:36:14 sugardaddy haproxy[13710]: 123.164.22.194:56738
[27/Jan/2014:23:35:39.252] frontend4711 backend4711/server1 1/-1/35567 0
CC 891/2/2/2/1 0/0
Jan 27 23:36:32 sugardaddy haproxy[13710]: 123.164.22.194:56740
[27/Jan/2014:23:36:02.919] frontend4711 backend4711/server1 1/-1/30000 0
CC 906/3/3/3/1 0/0
Jan 27 23:36:43 sugardaddy haproxy[13710]: 123.164.22.194:56741
[27/Jan/2014:23:36:13.409] frontend4711 backend4711/server1 1/-1/30001 0
CC 933/2/2/2/1 0/0
Jan 27 23:37:00 sugardaddy haproxy[13710]: 123.164.22.194:56743
[27/Jan/2014:23:36:20.192] frontend4711 backend4711/server1 1/-1/40002 0
sC 918/2/2/2/1 0/0
Hi,
On Sat, Jan 25, 2014 at 10:12:50AM +0100, pechspilz wrote:
Hi,
I'm seeing a very sporadic issue (every few days) in a TCP mode proxy
and I'm at loss what could be causing it.
After some time, haproxy is unable to establish a connection with the
backend server. 20000 is the configured connect timeout. I can't see
any
exhausted resources in haproxy or on the frontend or backend server.
Jan 25 06:29:17 sugardaddy haproxy[14013]: 123.123.123.123:55698
[25/Jan/2014:06:28:57.210] f1/server1 1/-1/20000 0 sC 999/7/7/7/0 0/0
This "999" makes me think there's a 1000 file descriptors limit
somewhere
in your setup. However it should not cause a timeout, it should
immediately
fail. Is it always 999 or does the value change ? Are you running with
long
connections or short ones ?
And could you please show the output of "haproxy -vv" ? Ideally your
config
as well (without private information), just to see the maxconns,
timeouts,
etc...
Once this happens, every other connection attempt to this proxy will
be
met with the same timeout. Restarting haproxy instantly makes it all
work again.
With long connections, this could be explained by a server which would
not
accept more than a certain number of concurrent connections. When you
stop
haproxy, all connections are destroyed so the server starts to accept
them
again. But 7 connections per server seems so low...
Other frontend/backend proxy configurations running in the
same haproxy instance are not affected, it just happens to one proxy.
That could confirm the theory of a per-server limitation.
I could be wrong but since the problem vanishes after restarting
haproxy, I don't think it's an issue with the backend server.
Restarting
haproxy every hour "fixes" the problem but I'd prefer to keep haproxy
running all day/night.
Well, I'd say that it's totally unacceptable to have to restart it if
it's
not for a configuration change, so we need to sort this out to find if
it's
a configuration issue, and environment issue or a bug.
I tried the last 3 released 1.5 dev versions, it didn't make a
difference.
OK that's very useful information.
I think that at some point, an strace of the process and a tcpdump on
the interface when the problem appears will significantly help. I
noticed
that you changed your IPs in the log, and I understand you don't want
to
publish internal information. So if you have such traces available,
feel
free to send them to me off-list or to provide me with a link to
download
them.
Thanks,
Willy
