Welcome! Log In Create A New Profile

Advanced

time wrap caused kevent infinite loop

Posted by Slawa Olhovchenkov 
Slawa Olhovchenkov
time wrap caused kevent infinite loop
April 18, 2017 03:00PM
now_ms posible wrap (by design).
As result delta_ms calcultaed as `TICKS_TO_MS(tick_remain(now_ms,
exp)) + 1` can be negative. This caused negative
timeout.tv_sec/timeout.tv_nsec, failed kevent() (EINVAL) and infinite
loop.
Willy Tarreau
Re: time wrap caused kevent infinite loop
April 18, 2017 03:10PM
On Tue, Apr 18, 2017 at 03:53:29PM +0300, Slawa Olhovchenkov wrote:
> now_ms posible wrap (by design).
> As result delta_ms calcultaed as `TICKS_TO_MS(tick_remain(now_ms,
> exp)) + 1` can be negative. This caused negative
> timeout.tv_sec/timeout.tv_nsec, failed kevent() (EINVAL) and infinite
> loop.

That's an interesting case that we've contemplated already a few weeks
ago and didn't see how to make it fail. The only case where it could
happen would be when there's a timeout larger than 24.3 days (2147483647
ms to be precise) in the configuration so that a task is scheduled further
in the future. But even with such an exact value in the config, the issue
would last a single millisecond, as on the next millisecond the difference
is reduced by one millisecond and doesn't overflow anymore.

We still need to keep it in mind as a corner case to reproduce the bug
though.

Willy
Slawa Olhovchenkov
Re: time wrap caused kevent infinite loop
April 18, 2017 03:30PM
On Tue, Apr 18, 2017 at 03:06:08PM +0200, Willy Tarreau wrote:

> On Tue, Apr 18, 2017 at 03:53:29PM +0300, Slawa Olhovchenkov wrote:
> > now_ms posible wrap (by design).
> > As result delta_ms calcultaed as `TICKS_TO_MS(tick_remain(now_ms,
> > exp)) + 1` can be negative. This caused negative
> > timeout.tv_sec/timeout.tv_nsec, failed kevent() (EINVAL) and infinite
> > loop.
>
> That's an interesting case that we've contemplated already a few weeks
> ago and didn't see how to make it fail. The only case where it could
> happen would be when there's a timeout larger than 24.3 days (2147483647
> ms to be precise) in the configuration so that a task is scheduled further
> in the future. But even with such an exact value in the config, the issue
> would last a single millisecond, as on the next millisecond the difference
> is reduced by one millisecond and doesn't overflow anymore.
>
> We still need to keep it in mind as a corner case to reproduce the bug
> though.

Today I am got this issuse on all 3 haproxy different hosts
simultaneously (about 07:38:57 UTC I am got 'kernel: sonewconn: pcb
0xfffff80040f781d0: Listen queue overflow: 1537 already in queue
awaiting acceptance (564 occurrences)').

2017-04-18 07:38:57 UTC = 1492501137 unix time.
1492501137 unix time = 1640 now_ms, i.e. issues cused around now_ms
wraps.

Track down by dtrace show negative timeout.tv_sec/timeout.tv_nsec.

I am don't know how to add loging to ev_kqueue.c for print
now_ms/exp/other stuff.

# grep time /usr/local/etc/haproxy.conf | sort | uniq
timeout client 100s
timeout client 50000
timeout client 50000ms
timeout connect 100s
timeout connect 5000
timeout connect 500ms
timeout queue 100s
timeout server 100s
timeout server 50000
timeout server 2000ms
timeout server 30s
Willy Tarreau
Re: time wrap caused kevent infinite loop
April 18, 2017 04:00PM
On Tue, Apr 18, 2017 at 04:19:44PM +0300, Slawa Olhovchenkov wrote:
> Today I am got this issuse on all 3 haproxy different hosts
> simultaneously (about 07:38:57 UTC I am got 'kernel: sonewconn: pcb
> 0xfffff80040f781d0: Listen queue overflow: 1537 already in queue
> awaiting acceptance (564 occurrences)').

OK so you're one of those who got this as well! Cool! (not for you I
know). Till now we only got a few reports from other users who started
to meet the issue after upgrading from FBSD 10 to 11, and all of them
die at the same time. It was 09:38 in our last "prediction" and reported
as such by another person, so I think it was local time probably on UTC+2.

> 2017-04-18 07:38:57 UTC = 1492501137 unix time.
> 1492501137 unix time = 1640 now_ms, i.e. issues cused around now_ms
> wraps.

In fact it's -2147482008 ms, 1640 is if you round it to 31 bits, but
anyway I get your point and we see the relation with the wrapping that
we imagined but still couldn't catch.

> Track down by dtrace show negative timeout.tv_sec/timeout.tv_nsec.

Nice! All truss outputs we got so far were truncated to 3 args so we
could never see the contents of the timeout field.

Now the remaining questions are :
- how is it possible to have such a large timeout in the timer queue
- why doesn't the situation fix by itself on the next millisecond when
it's not supposed anymore to be possible to have such a large timeout ;
- why doesn't it affect other pollers
- why some users experienced a kernel panic quickly after the issue

But at least we're leaning towards something so your report is *very*
valuable, thanks a lot.

> I am don't know how to add loging to ev_kqueue.c for print
> now_ms/exp/other stuff.

Just after assignment of timeout.tv_sec/nsec, you could do something
like this :

if (timeout.tv_sec < 0 || timeout.tv_nsec < 0 || timeout.tv_nsec >= 1000000000)
fprintf(stderr, "sec=%u nsec=%u\n", (unsigned)timeout.tv_sec, (unsigned)timeout.tv_nsec);

There's also fddebug() to emit this output on fd -1 so that it can be
debugged with strace/truss instead of polluting the stderr.

> # grep time /usr/local/etc/haproxy.conf | sort | uniq
> timeout client 100s
> timeout client 50000
> timeout client 50000ms
> timeout connect 100s
> timeout connect 5000
> timeout connect 500ms
> timeout queue 100s
> timeout server 100s
> timeout server 50000
> timeout server 2000ms
> timeout server 30s

Again nothing in nature of causing such a timeout to occur :-/

Thanks,
Willy
Willy Tarreau
Re: time wrap caused kevent infinite loop
April 18, 2017 04:10PM
On Tue, Apr 18, 2017 at 03:48:12PM +0200, Willy Tarreau wrote:
> > I am don't know how to add loging to ev_kqueue.c for print
> > now_ms/exp/other stuff.
>
> Just after assignment of timeout.tv_sec/nsec, you could do something
> like this :
>
> if (timeout.tv_sec < 0 || timeout.tv_nsec < 0 || timeout.tv_nsec >= 1000000000)
> fprintf(stderr, "sec=%u nsec=%u\n", (unsigned)timeout.tv_sec, (unsigned)timeout.tv_nsec);
>
> There's also fddebug() to emit this output on fd -1 so that it can be
> debugged with strace/truss instead of polluting the stderr.

By the way feel free to use the attached patch to force the date to wrap
5s after boot, we've used it to try to reproduce the issue in vain :-/

Willy
From aefa4214292a08d0b91dfab57213c971e0f1ce00 Mon Sep 17 00:00:00 2001
From: Willy Tarreau <[email protected]>
Date: Mon, 13 Mar 2017 19:59:26 +0100
Subject: WIP/DEBUG: force date to wrap at -5 seconds

---
src/time.c | 6 +++++-
1 file changed, 5 insertions(+), 1 deletion(-)

diff --git a/src/time.c b/src/time.c
index 6118762..4f3c03b 100644
--- a/src/time.c
+++ b/src/time.c
@@ -168,8 +168,11 @@ REGPRM2 void tv_update_date(int max_wait, int interrupted)

gettimeofday(&date, NULL);
if (unlikely(max_wait < 0)) {
+ //tv_zero(&tv_offset);
+ //adjusted = date;
tv_zero(&tv_offset);
- adjusted = date;
+ tv_offset.tv_sec = 4294962 - date.tv_sec; // -5 seconds
+ __tv_add(&adjusted, &date, &tv_offset);
after_poll = date;
samp_time = idle_time = 0;
idle_pct = 100;
@@ -215,6 +218,7 @@ REGPRM2 void tv_update_date(int max_wait, int interrupted)
*/
ms_left_scaled = (999U - curr_sec_ms) * 4294967U;
now_ms = now.tv_sec * 1000 + curr_sec_ms;
+fddebug("date=%u\n", now_ms);
return;
}

--
1.7.12.1
Slawa Olhovchenkov
Re: time wrap caused kevent infinite loop
April 18, 2017 04:30PM
On Tue, Apr 18, 2017 at 03:48:12PM +0200, Willy Tarreau wrote:

> On Tue, Apr 18, 2017 at 04:19:44PM +0300, Slawa Olhovchenkov wrote:
> > Today I am got this issuse on all 3 haproxy different hosts
> > simultaneously (about 07:38:57 UTC I am got 'kernel: sonewconn: pcb
> > 0xfffff80040f781d0: Listen queue overflow: 1537 already in queue
> > awaiting acceptance (564 occurrences)').
>
> OK so you're one of those who got this as well! Cool! (not for you I
> know). Till now we only got a few reports from other users who started
> to meet the issue after upgrading from FBSD 10 to 11, and all of them
> die at the same time. It was 09:38 in our last "prediction" and reported
> as such by another person, so I think it was local time probably on UTC+2.
>
> > 2017-04-18 07:38:57 UTC = 1492501137 unix time.
> > 1492501137 unix time = 1640 now_ms, i.e. issues cused around now_ms
> > wraps.
>
> In fact it's -2147482008 ms, 1640 is if you round it to 31 bits, but
> anyway I get your point and we see the relation with the wrapping that
> we imagined but still couldn't catch.
>
> > Track down by dtrace show negative timeout.tv_sec/timeout.tv_nsec.
>
> Nice! All truss outputs we got so far were truncated to 3 args so we
> could never see the contents of the timeout field.
>
> Now the remaining questions are :
> - how is it possible to have such a large timeout in the timer queue
> - why doesn't the situation fix by itself on the next millisecond when
> it's not supposed anymore to be possible to have such a large timeout ;

May be tv_update_date(delta_ms, status) for negative status do nothing.

> - why doesn't it affect other pollers

What you mean?

> - why some users experienced a kernel panic quickly after the issue
>
> But at least we're leaning towards something so your report is *very*
> valuable, thanks a lot.
>
> > I am don't know how to add loging to ev_kqueue.c for print
> > now_ms/exp/other stuff.
>
> Just after assignment of timeout.tv_sec/nsec, you could do something
> like this :
>
> if (timeout.tv_sec < 0 || timeout.tv_nsec < 0 || timeout.tv_nsec >= 1000000000)
> fprintf(stderr, "sec=%u nsec=%u\n", (unsigned)timeout.tv_sec, (unsigned)timeout.tv_nsec);
>
> There's also fddebug() to emit this output on fd -1 so that it can be
> debugged with strace/truss instead of polluting the stderr.

Not nice logging for production systems. I am expect next trouble
around 2-3 month, this is to long and complex for strace/truss
collecting. And for 2K RPS on production system.

Also, logging only timeout.tv_sec/timeout.tv_nsec don't help you: I am
already see this negative values (timeout.tv_sec is about -10700 at
10:38 UTC, timeout.tv_nsec very large negative and changed, don't
record, sorry).

May be logging some more data can be help?
now_ms and exp, for example?
Willy Tarreau
Re: time wrap caused kevent infinite loop
April 18, 2017 04:30PM
On Tue, Apr 18, 2017 at 05:18:13PM +0300, Slawa Olhovchenkov wrote:
> > Now the remaining questions are :
> > - how is it possible to have such a large timeout in the timer queue
> > - why doesn't the situation fix by itself on the next millisecond when
> > it's not supposed anymore to be possible to have such a large timeout ;
>
> May be tv_update_date(delta_ms, status) for negative status do nothing.

Yes it does, it reinitializes the offset to zero so that now_ms is the
exact copy of the output of gettimeofday(). It's normally used at
initialization (I've checked this as well).

> > - why doesn't it affect other pollers
>
> What you mean?

Only kqueue on freebsd 11 reports an issue for now. It could be due to
an API difference or anything but for now that's an element to keep in
mind.

> Also, logging only timeout.tv_sec/timeout.tv_nsec don't help you: I am
> already see this negative values (timeout.tv_sec is about -10700 at
> 10:38 UTC, timeout.tv_nsec very large negative and changed, don't
> record, sorry).

Olivier just told me he managed to reproduce so we'll save some production
now :-)

Cheers,
Willy
Mark S
Re: time wrap caused kevent infinite loop
April 18, 2017 09:00PM
On Tue, 18 Apr 2017 09:19:44 -0400, Slawa Olhovchenkov <[email protected]>
wrote:

> Today I am got this issuse on all 3 haproxy different hosts
> simultaneously (about 07:38:57 UTC I am got 'kernel: sonewconn: pcb
> 0xfffff80040f781d0: Listen queue overflow: 1537 already in queue
> awaiting acceptance (564 occurrences)').


Just to chime in on this, I had this issue re-occur once again in the same
time frame.

Apr 18 07:49:20

I still have the old process running in the event that any truss/dtrace
output might be helpful for diagnosis.

Best,
-=Mark
Willy Tarreau
Re: time wrap caused kevent infinite loop
April 18, 2017 11:00PM
On Tue, Apr 18, 2017 at 02:50:45PM -0400, Mark S wrote:
> On Tue, 18 Apr 2017 09:19:44 -0400, Slawa Olhovchenkov <[email protected]>
> wrote:
>
> > Today I am got this issuse on all 3 haproxy different hosts
> > simultaneously (about 07:38:57 UTC I am got 'kernel: sonewconn: pcb
> > 0xfffff80040f781d0: Listen queue overflow: 1537 already in queue
> > awaiting acceptance (564 occurrences)').
>
>
> Just to chime in on this, I had this issue re-occur once again in the same
> time frame.
>
> Apr 18 07:49:20
>
> I still have the old process running in the event that any truss/dtrace
> output might be helpful for diagnosis.

Olivier told me he managed to reproduce it now. We're waiting for some
confirmation but what he found is... hmmm... scary :-) What's nice is
that we should be able to provide a workaround soon and that next
wraparound should not be an issue. More on this tomorrow.

Cheers,
Willy
Sorry, only registered users may post in this forum.

Click here to login