Re: haproxy processing request of a disconnected client
On Thu, Aug 09, 2018 at 01:00:04PM -0400, Patrick Hemmer wrote:
> So I just noticed the behavior that when a request is queued and the
> client closes the connection, once a server slot frees up that request
> is still sent to the server which processes it and sends a response back.
> What's even more interesting is that the log indicates that everything
> was processed normally. It basically says the response was sent back to
> the client just fine.
>
> Example config:
> global
> stats socket /tmp/haproxy.sock level admin
> defaults
> log 127.0.0.1:1234 daemon
> mode http
> option httplog
> timeout queue 5s
> frontend f1
> bind :8001
> default_backend b1
> backend b1
> server s1 127.0.0.1:8081 maxconn 1
>
> Log output:
> <30>Aug 9 12:50:40 haproxy[12384]: 127.0.0.1:64723
> [09/Aug/2018:12:50:35.167] f1 b1/s1 0/0/0/5106/5106 200 118 - -
> 2/2/1/1/0 0/0 "GET /y HTTP/1.1"
> <30>Aug 9 12:50:45 haproxy[12384]: 127.0.0.1:64726
> [09/Aug/2018:12:50:35.526] f1 b1/s1 0/4749/0/5102/9851 200 118 - -
> 1/1/0/1/0 0/1 "GET /x HTTP/1.1"
>
> ^ In this, the server sleeps for 5 seconds, and then replies. I sent the
> request for /y, and then a request for /x, but killed the client on the
> /x request after 1 second. The request for /y was processed, but then so
> was the request for /x. The close flags ("") indicate everything
> went fine.
Yes, and it's definitely intentional, so that scripts doing stuff like
echo -e "GET /check HTTP/1.1\r\nHost: bar\r\n\r\n" | nc 127.0.0.1 80
work properly. I've seen quite a bunch of these in monitoring scripts
over the years. Sometimes it's even more obvious as the response is
really not needed :
echo -e "GET /set-var?name=X=Y HTTP/1.0\r\n\r\n" > /dev/tcp/127.0.0.1/80
If you want to abort processing of a pending request when the client
closes, you simply need to add "option abortonclose". It's generally
recommended on public-facing configs. In this case you'll see something
like "CQ", "CC" or "CH" in the logs.
Regards
Willy
Re: haproxy processing request of a disconnected client
On 2018/8/9 13:00, Patrick Hemmer wrote:
> So I just noticed the behavior that when a request is queued and the
> client closes the connection, once a server slot frees up that request
> is still sent to the server which processes it and sends a response back.
> What's even more interesting is that the log indicates that everything
> was processed normally. It basically says the response was sent back
> to the client just fine.
>
> Example config:
> global
> stats socket /tmp/haproxy.sock level admin
> defaults
> log 127.0.0.1:1234 daemon
> mode http
> option httplog
> timeout queue 5s
> frontend f1
> bind :8001
> default_backend b1
> backend b1
> server s1 127.0.0.1:8081 maxconn 1
>
> Log output:
> <30>Aug 9 12:50:40 haproxy[12384]: 127.0.0.1:64723
> [09/Aug/2018:12:50:35.167] f1 b1/s1 0/0/0/5106/5106 200 118 - -
> 2/2/1/1/0 0/0 "GET /y HTTP/1.1"
> <30>Aug 9 12:50:45 haproxy[12384]: 127.0.0.1:64726
> [09/Aug/2018:12:50:35.526] f1 b1/s1 0/4749/0/5102/9851 200 118 - -
> 1/1/0/1/0 0/1 "GET /x HTTP/1.1"
>
> ^ In this, the server sleeps for 5 seconds, and then replies. I sent
> the request for /y, and then a request for /x, but killed the client
> on the /x request after 1 second. The request for /y was processed,
> but then so was the request for /x. The close flags ("") indicate
> everything went fine.
>
> Information:
>
> lsof:
> COMMAND PIDUSER FD TYPE DEVICE
> SIZE/OFFNODE NAME
> ...
> haproxy 12384 phemmer0u CHR 16,5
> 0x140daf691797 /dev/ttys005
> haproxy 12384 phemmer1u CHR 16,5
> 0x140daf691797 /dev/ttys005
> haproxy 12384 phemmer2u CHR 16,5
> 0x140daf691797 /dev/ttys005
> haproxy 12384 phemmer3u
> KQUEUE count=0, state=0xa
> haproxy 12384 phemmer4uunix 0x933b1c4c8f54438f
> 0t0 /tmp/haproxy.sock.12384.tmp
> haproxy 12384 phemmer5uIPv4 0x933b1c4cc16309ff
> 0t0 TCP *:8001 (LISTEN)
> haproxy 12384 phemmer6uIPv4 0x933b1c4c8fef8977
> 0t0 UDP *:62112
> haproxy 12384 phemmer7uIPv4 0x933b1c4cbf5fd9ff
> 0t0 TCP 127.0.0.1:8001->127.0.0.1:64723 (ESTABLISHED)
> haproxy 12384 phemmer8uIPv4 0x933b1c4cc1546ddf
> 0t0 TCP 127.0.0.1:64724->127.0.0.1:8081 (ESTABLISHED)
> haproxy 12384 phemmer9uIPv4 0x933b1c4cc1c6209f
> 0t0 TCP 127.0.0.1:8001->127.0.0.1:64726 (CLOSE_WAIT)
>
> admin socket 'show fd':
> 4 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlc] cache=0
> owner=0x7f93f3705010 iocb=0x107f82c40(listener_accept)
> tmask=0x umask=0xfffe l.st=RDY fe=GLOBAL
> 5 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlc] cache=0
> owner=0x7f93f3705650 iocb=0x107f82c40(listener_accept)
> tmask=0x umask=0xfffe l.st=RDY fe=f1
> 7 : st=0x25(R:PrA W:pRa) ev=0x00(heopi) [nlc] cache=0
> owner=0x7f93f3708280 iocb=0x107f9e2e0(conn_fd_handler) tmask=0x1
> umask=0x0 cflg=0x80201306 fe=f1 mux=PASS mux_ctx=0x7f93f3708490
> 8 : st=0x25(R:PrA W:pRa) ev=0x00(heopi) [nLc] cache=0
> owner=0x7f93f340ede0 iocb=0x107f9e2e0(conn_fd_handler) tmask=0x1
> umask=0x0 cflg=0x00202306 sv=s1/b1 mux=PASS mux_ctx=0x7f93f350d0e0
> 9 : st=0x22(R:pRa W:pRa) ev=0x10(Heopi) [nlc] cache=0
> owner=0x7f93f510 iocb=0x107f9e2e0(conn_fd_handler) tmask=0x1
> umask=0x0 cflg=0x80241300 fe=f1 mux=PASS mux_ctx=0x7f93f5100210
> 10 : st=0x25(R:PrA W:pRa) ev=0x00(heopi) [nlc] cache=0
> owner=0x7f93f3708100 iocb=0x107f9e2e0(conn_fd_handler) tmask=0x1
> umask=0x0 cflg=0x00201306 fe=GLOBAL mux=PASS mux_ctx=0x7f93f350d1a0
>
> admin socket 'show sess':
> 0x7f93f37084c0: proto=tcpv4 src=127.0.0.1:64723 fe=f1 be=b1 srv=s1
> ts=08 age=2s calls=3 rq[f=48840200h,i=0,an=8000h,rx=,wx=,ax=]
> rp[f=8040h,i=0,an=a0h,rx=,wx=,ax=] s0=[7,8h,fd=7,ex=]
> s1=[7,118h,fd=8,ex=] exp=
> 0x7f93f5100240: proto=tcpv4 src=127.0.0.1:64726 fe=f1 be=b1
> srv= ts=08 age=2s calls=3
> rq[f=c800020h,i=0,an=8000h,rx=,wx=,ax=]
> rp[f=8000h,i=0,an=00h,rx=,wx=,ax=] s0=[7,8h,fd=9,ex=]
> s1=[2,110h,fd=-1,ex=2s] exp=2s
> 0x7f93f350d1d0: proto=unix_stream src=unix:1 fe=GLOBAL be=
> srv= ts=02 age=0s calls=1
> rq[f=40c08202h,i=0,an=00h,rx=10s,wx=,ax=]
> rp[f=80008002h,i=0,an=00h,rx=,wx=,ax=] s0=[7,8h,fd=10,ex=]
> s1=[7,4018h,fd=-1,ex=] exp=10s
>
> Version info:
> # ./haproxy -vv
> HA-Proxy version 1.8.13 2018/07/30
> Copyright 2000-2018 Willy Tarreau
>
> Build options :
> TARGET = osx
> CPU = generic
> CC = gcc
> CFLAGS = -O0 -g -fno-strict-aliasing
> -Wdeclaration-after-statement -fwrapv -fno-strict-overflow
> -Wno-address-of-packed-member -Wno-null-dereference -Wno-unused-label
> OPTIONS = USE_ZLIB=1 USE_OPENSSL=1 USE_LUA=1 USE_PCRE=1
haproxy processing request of a disconnected client
So I just noticed the behavior that when a request is queued and the
client closes the connection, once a server slot frees up that request
is still sent to the server which processes it and sends a response back.
What's even more interesting is that the log indicates that everything
was processed normally. It basically says the response was sent back to
the client just fine.
Example config:
global
stats socket /tmp/haproxy.sock level admin
defaults
log 127.0.0.1:1234 daemon
mode http
option httplog
timeout queue 5s
frontend f1
bind :8001
default_backend b1
backend b1
server s1 127.0.0.1:8081 maxconn 1
Log output:
<30>Aug 9 12:50:40 haproxy[12384]: 127.0.0.1:64723
[09/Aug/2018:12:50:35.167] f1 b1/s1 0/0/0/5106/5106 200 118 - -
2/2/1/1/0 0/0 "GET /y HTTP/1.1"
<30>Aug 9 12:50:45 haproxy[12384]: 127.0.0.1:64726
[09/Aug/2018:12:50:35.526] f1 b1/s1 0/4749/0/5102/9851 200 118 - -
1/1/0/1/0 0/1 "GET /x HTTP/1.1"
^ In this, the server sleeps for 5 seconds, and then replies. I sent the
request for /y, and then a request for /x, but killed the client on the
/x request after 1 second. The request for /y was processed, but then so
was the request for /x. The close flags ("") indicate everything
went fine.
Information:
lsof:
COMMAND PIDUSER FD TYPE DEVICE SIZE/OFF
NODE NAME
...
haproxy 12384 phemmer0u CHR 16,5 0x140daf69
1797 /dev/ttys005
haproxy 12384 phemmer1u CHR 16,5 0x140daf69
1797 /dev/ttys005
haproxy 12384 phemmer2u CHR 16,5 0x140daf69
1797 /dev/ttys005
haproxy 12384 phemmer3u
KQUEUE count=0, state=0xa
haproxy 12384 phemmer4uunix 0x933b1c4c8f54438f
0t0 /tmp/haproxy.sock.12384.tmp
haproxy 12384 phemmer5uIPv4 0x933b1c4cc16309ff
0t0 TCP *:8001 (LISTEN)
haproxy 12384 phemmer6uIPv4 0x933b1c4c8fef8977
0t0 UDP *:62112
haproxy 12384 phemmer7uIPv4 0x933b1c4cbf5fd9ff
0t0 TCP 127.0.0.1:8001->127.0.0.1:64723 (ESTABLISHED)
haproxy 12384 phemmer8uIPv4 0x933b1c4cc1546ddf
0t0 TCP 127.0.0.1:64724->127.0.0.1:8081 (ESTABLISHED)
haproxy 12384 phemmer9uIPv4 0x933b1c4cc1c6209f
0t0 TCP 127.0.0.1:8001->127.0.0.1:64726 (CLOSE_WAIT)
admin socket 'show fd':
4 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlc] cache=0
owner=0x7f93f3705010 iocb=0x107f82c40(listener_accept)
tmask=0x umask=0xfffe l.st=RDY fe=GLOBAL
5 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlc] cache=0
owner=0x7f93f3705650 iocb=0x107f82c40(listener_accept)
tmask=0x umask=0xfffe l.st=RDY fe=f1
7 : st=0x25(R:PrA W:pRa) ev=0x00(heopi) [nlc] cache=0
owner=0x7f93f3708280 iocb=0x107f9e2e0(conn_fd_handler) tmask=0x1
umask=0x0 cflg=0x80201306 fe=f1 mux=PASS mux_ctx=0x7f93f3708490
8 : st=0x25(R:PrA W:pRa) ev=0x00(heopi) [nLc] cache=0
owner=0x7f93f340ede0 iocb=0x107f9e2e0(conn_fd_handler) tmask=0x1
umask=0x0 cflg=0x00202306 sv=s1/b1 mux=PASS mux_ctx=0x7f93f350d0e0
9 : st=0x22(R:pRa W:pRa) ev=0x10(Heopi) [nlc] cache=0
owner=0x7f93f510 iocb=0x107f9e2e0(conn_fd_handler) tmask=0x1
umask=0x0 cflg=0x80241300 fe=f1 mux=PASS mux_ctx=0x7f93f5100210
10 : st=0x25(R:PrA W:pRa) ev=0x00(heopi) [nlc] cache=0
owner=0x7f93f3708100 iocb=0x107f9e2e0(conn_fd_handler) tmask=0x1
umask=0x0 cflg=0x00201306 fe=GLOBAL mux=PASS mux_ctx=0x7f93f350d1a0
admin socket 'show sess':
0x7f93f37084c0: proto=tcpv4 src=127.0.0.1:64723 fe=f1 be=b1 srv=s1
ts=08 age=2s calls=3 rq[f=48840200h,i=0,an=8000h,rx=,wx=,ax=]
rp[f=8040h,i=0,an=a0h,rx=,wx=,ax=] s0=[7,8h,fd=7,ex=]
s1=[7,118h,fd=8,ex=] exp=
0x7f93f5100240: proto=tcpv4 src=127.0.0.1:64726 fe=f1 be=b1
srv= ts=08 age=2s calls=3 rq[f=c800020h,i=0,an=8000h,rx=,wx=,ax=]
rp[f=8000h,i=0,an=00h,rx=,wx=,ax=] s0=[7,8h,fd=9,ex=]
s1=[2,110h,fd=-1,ex=2s] exp=2s
0x7f93f350d1d0: proto=unix_stream src=unix:1 fe=GLOBAL be=
srv= ts=02 age=0s calls=1
rq[f=40c08202h,i=0,an=00h,rx=10s,wx=,ax=]
rp[f=80008002h,i=0,an=00h,rx=,wx=,ax=] s0=[7,8h,fd=10,ex=]
s1=[7,4018h,fd=-1,ex=] exp=10s
Version info:
# ./haproxy -vv
HA-Proxy version 1.8.13 2018/07/30
Copyright 2000-2018 Willy Tarreau
Build options :
TARGET = osx
CPU = generic
CC = gcc
CFLAGS = -O0 -g -fno-strict-aliasing
-Wdeclaration-after-statement -fwrapv -fno-strict-overflow
-Wno-address-of-packed-member -Wno-null-dereference -Wno-unused-label
OPTIONS = USE_ZLIB=1 USE_OPENSSL=1 USE_LUA=1 USE_PCRE=1
Default settings :
maxconn = 2000, bufsize = 16384, maxrewrite = 1024,
maxpollevents = 200
Built with OpenSSL version : OpenSSL 1.1.0h 27 Mar 2018
Running on OpenSSL version : OpenSSL 1.1.0h 27 Mar 2018
OpenSSL library supports
