Hi again,
CCing Richard who reported client-fin not always working in the past.
Updates below.
On Wed, Mar 08, 2017 at 09:21:37PM +0100, Willy Tarreau wrote:
> Hi,
>
> On Wed, Mar 08, 2017 at 10:09:25PM +0800, longhb wrote:
> > [PATCH] BUG/MAJOR: stream: fix tcp half connection expire causes cpu 100%
> >
> > Repetition condition:
> > haproxy config:
> > global:
> > tune.bufsize 10485760
> > defaults
> > timeout server-fin 90s
> > timeout client-fin 90s
> > backend node2
> > mode tcp
> > timeout server 900s
> > timeout connect 10s
> > server def 127.0.0.1:3333
> > frontend fe_api
> > mode tcp
> > timeout client 900s
> > bind :1990
> > use_backend node2
> > timeout server-fin shorter than timeout server, the backend server
> > sends data, this package is left in the cache of haproxy, the backend
> > server continue sending fin package, haproxy recv fin package. this
> > time the session information is as follows:
> > 0x2373470: proto=tcpv4 src=127.0.0.1:39513 fe=fe_api be=node2
> > srv=def ts=08 age=1s calls=3
> > rq[f=848000h,i=0,an=00h,rx=14m58s,wx=,ax=]
> > rp[f=8004c020h,i=0,an=00h,rx=,wx=14m58s,ax=] s0=[7,0h,fd=6,ex=]
> > s1=[7,18h,fd=7,ex=] exp=14m58s
> > rp has set the CF_SHUTR state, next, the client sends the fin package,
> > session information is as follows:
> > 0x2373470: proto=tcpv4 src=127.0.0.1:39513 fe=fe_api be=node2
> > srv=def ts=08 age=38s calls=4 rq[f=84a020h,i=0,an=00h,rx=,wx=,ax=]
> > rp[f=8004c020h,i=0,an=00h,rx=1m11s,wx=14m21s,ax=] s0=[7,0h,fd=6,ex=]
> > s1=[9,10h,fd=7,ex=] exp=1m11s
> > After waiting 90s, session information is as follows:
> > 0x2373470: proto=tcpv4 src=127.0.0.1:39513 fe=fe_api be=node2
> > srv=def ts=04 age=4m11s calls=718074391
> > rq[f=84a020h,i=0,an=00h,rx=,wx=,ax=]
> > rp[f=8004c020h,i=0,an=00h,rx=?,wx=10m49s,ax=] s0=[7,0h,fd=6,ex=]
> > s1=[9,10h,fd=7,ex=] exp=? run(nice=0)
> > cpu information:
> > 6899 root 20 0 112224 21408 4260 R 100.0 0.7 3:04.96
> > haproxy
> > Buffering is set to ensure that there is data in the haproxy buffer,
> > and haproxy can receive the fin package, set the CF_SHUTR flag, If the
> > CF_SHUTR
> > flag has been set, The following code does not clear the timeout
> > message,
> > causing cpu 100%:
> > stream.c:process_stream:
> > if (unlikely((res->flags & (CF_SHUTR|CF_READ_TIMEOUT)) ==
> > CF_READ_TIMEOUT)) {
> > if (si_b->flags & SI_FL_NOHALF)
> > si_b->flags |= SI_FL_NOLINGER;
> > si_shutr(si_b);
> > }
> > If you have closed the read, set the read timeout does not make sense.
> > With or without cf_shutr, read timeout is set:
> > if (tick_isset(s->be->timeout.serverfin)) {
> > res->rto = s->be->timeout.serverfin;
> > res->rex = tick_add(now_ms, res->rto);
> > }
> > ---
> > src/stream.c | 4 ++--
> > 1 file changed, 2 insertions(+), 2 deletions(-)
> >
> > diff --git a/src/stream.c b/src/stream.c
> > index b333dec..ab07505 100644
> > --- a/src/stream.c
> > +++ b/src/stream.c
> > @@ -2095,7 +2095,7 @@ struct task *process_stream(struct task *t)
> > if (req->flags & CF_READ_ERROR)
> > si_b->flags |= SI_FL_NOLINGER;
> > si_shutw(si_b);
> > - if (tick_isset(s->be->timeout.serverfin)) {
> > + if (tick_isset(s->be->timeout.serverfin) && !(res->flags &
> > CF_SHUTR)) {
> > res->rto = s->be->timeout.serverfin;
> > res->rex = tick_add(now_ms, res->rto);
> > }
> > @@ -2278,7 +2278,7 @@ struct task *process_stream(struct task *t)
> > if (unlikely((res->flags & (CF_SHUTW|CF_SHUTW_NOW)) == CF_SHUTW_NOW &&
> > channel_is_empty(res))) {
> > si_shutw(si_f);
> > - if (tick_isset(sess->fe->timeout.clientfin)) {
> > + if (tick_isset(sess->fe->timeout.clientfin) && !(req->flags &
> > CF_SHUTR)) {
> > req->rto = sess->fe->timeout.clientfin;
> > req->rex = tick_add(now_ms, req->rto);
> > }
>
> I think the patch is fine but I'm worried because I think we changed
> this recently (in 1.6 or so), so I'd like to investigate the cause of
> the change (if any) and see what the motives were because I suspect
> we possibly broke something else at the same time.
So I looked at process_stream() and in fact I don't like the way we handle
client-fin and server-fin at the moment. The issue you found is real but is
not unique. We have the same in the "timeout tunnel" handling in combination
with client-fin/server-fin because the timeouts are changed even if one side
is closed.
The problem as you indicated is that we should not change timeouts on a
direction which is already closed. That makes me think we should thus
automatically update these timeouts upon si_shutw() but there are quite
a few, and I think I found in stream_interface.c why Richard was having
these issues (two si_shutw() calls in pure forward mode not changing the
channel's timeout).
So I thought about dealing with it inside shutw() itself, but at most
places we don't know what side to use nor if the tunnel timeout should
be used instead. I'm now starting to think that we should probably have
an "fto" for FIN timeout in each channel that's automatically set when
doing a half-way close, or maybe have it in the stream interface.
That's definitely an ugly stuff that I created myself 3 years ago without
spotting some possible corner cases and I'm not proud of it :-(
At the moment I have no idea how to *reliably* fix this. Your patch
addresses a part of it but I'd rather kill the bug as a whole :-/
Still thinking about it, any ideas welcome.
Cheers,
Willy
