'iw events' stops receiving events after a while on 4.9 + hacks

'iw events' stops receiving events after a while on 4.9 + hacks

[Ben Greear]

I have been keeping an 'iw events' program running with a perl script gathering its
output and post-processing it.  This has been working for several years on 4.7 and earlier
kernels, but when testing on 4.9 overnight, I notice that 'iw events' is not showing any input.  'strace' shows
that it is waiting on recvmsg.  If I start a second 'iw events' then it will get
wifi events as expected.

Are there any known issues in this area?

Thanks,
Ben

-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: 'iw events' stops receiving events after a while on 4.9 + hacks

[Bastian Bittorf]

* Ben Greear <greearb@candelatech.com> [17.05.2017 11:51]:
> I have been keeping an 'iw events' program running with a perl script gathering its
> output and post-processing it.  This has been working for several years on 4.7 and earlier
> kernels, but when testing on 4.9 overnight, I notice that 'iw events' is not showing any input.  'strace' shows
> that it is waiting on recvmsg.  If I start a second 'iw events' then it will get
> wifi events as expected.

me too, also seen on 4.4 - i'am happy for debug ideas.

bye, bastian

Re: 'iw events' stops receiving events after a while on 4.9 + hacks

[Bastian Bittorf]

* Ben Greear <greearb-my8/4N5VtI7c+919tysfdA@public.gmane.org> [17.05.2017 11:51]:
> I have been keeping an 'iw events' program running with a perl script gathering its
> output and post-processing it.  This has been working for several years on 4.7 and earlier
> kernels, but when testing on 4.9 overnight, I notice that 'iw events' is not showing any input.  'strace' shows
> that it is waiting on recvmsg.  If I start a second 'iw events' then it will get
> wifi events as expected.

me too, also seen on 4.4 - i'am happy for debug ideas.

bye, bastian

Re: 'iw events' stops receiving events after a while on 4.9 + hacks

[Johannes Berg]

On Wed, 2017-05-17 at 12:08 +0200, Bastian Bittorf wrote:
> * Ben Greear <greearb@candelatech.com> [17.05.2017 11:51]:
> > I have been keeping an 'iw events' program running with a perl
> > script gathering its
> > output and post-processing it.  This has been working for several
> > years on 4.7 and earlier
> > kernels, but when testing on 4.9 overnight, I notice that 'iw
> > events' is not showing any input.  'strace' shows
> > that it is waiting on recvmsg.  If I start a second 'iw events'
> > then it will get
> > wifi events as expected.
> 
> me too, also seen on 4.4 - i'am happy for debug ideas.

I've never seen this.

Does it happen when it's very long-running? Or when there are lots of
events?

Perhaps something in the socket buffer accounting is going wrong, so
that it's slowly decreasing to 0?

johannes

Re: 'iw events' stops receiving events after a while on 4.9 + hacks

[Ben Greear]

On 05/17/2017 06:30 AM, Johannes Berg wrote:
> On Wed, 2017-05-17 at 12:08 +0200, Bastian Bittorf wrote:
>> * Ben Greear <greearb@candelatech.com> [17.05.2017 11:51]:
>>> I have been keeping an 'iw events' program running with a perl
>>> script gathering its
>>> output and post-processing it.  This has been working for several
>>> years on 4.7 and earlier
>>> kernels, but when testing on 4.9 overnight, I notice that 'iw
>>> events' is not showing any input.  'strace' shows
>>> that it is waiting on recvmsg.  If I start a second 'iw events'
>>> then it will get
>>> wifi events as expected.
>>
>> me too, also seen on 4.4 - i'am happy for debug ideas.
>
> I've never seen this.
>
> Does it happen when it's very long-running? Or when there are lots of
> events?
>
> Perhaps something in the socket buffer accounting is going wrong, so
> that it's slowly decreasing to 0?

I saw it exactly once so far, and it happened overnight,
but we have not been doing a lot of work with the 4.9 kernel until recently.

I don't think there were many messages on this system, and certainly
others have run much longer on systems that should be generating many more
events without trouble.

Is there any way to dump out the socket information if we reproduce
the problem?

Thanks,
Ben

-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: 'iw events' stops receiving events after a while on 4.9 + hacks

[Johannes Berg]

On Wed, 2017-05-17 at 08:22 -0700, Ben Greear wrote:
> 
> I saw it exactly once so far, and it happened overnight,
> but we have not been doing a lot of work with the 4.9 kernel until
> recently.
> 
> I don't think there were many messages on this system, and certainly
> others have run much longer on systems that should be generating many
> more events without trouble.

Ok.

> Is there any way to dump out the socket information if we reproduce
> the problem?

I have no idea, sorry.

If you or Bastian can tell me how to reproduce the problem, I can try
to investigate it.

johannes

Re: 'iw events' stops receiving events after a while on 4.9 + hacks

[Bastian Bittorf]

* Johannes Berg <johannes@sipsolutions.net> [31.05.2017 10:09]:
> > Is there any way to dump out the socket information if we reproduce
> > the problem?
> 
> I have no idea, sorry.
> 
> If you or Bastian can tell me how to reproduce the problem, I can try
> to investigate it.

there was an interesting fix regarding the shell-builtin 'read' in
busybox[1]. I will retest again and report if this changes anything.

bye, bastian

PS: @ben: are you also using 'iw event | while read -r LINE ...'?

[1]
https://git.busybox.net/busybox/commit/?id=f5470419404d643070db99d058405b714695b817

Re: 'iw events' stops receiving events after a while on 4.9 + hacks

[Bastian Bittorf]

* Johannes Berg <johannes-cdvu00un1VgdHxzADdlk8Q@public.gmane.org> [31.05.2017 10:09]:
> > Is there any way to dump out the socket information if we reproduce
> > the problem?
> 
> I have no idea, sorry.
> 
> If you or Bastian can tell me how to reproduce the problem, I can try
> to investigate it.

there was an interesting fix regarding the shell-builtin 'read' in
busybox[1]. I will retest again and report if this changes anything.

bye, bastian

PS: @ben: are you also using 'iw event | while read -r LINE ...'?

[1]
https://git.busybox.net/busybox/commit/?id=f5470419404d643070db99d058405b714695b817

Re: 'iw events' stops receiving events after a while on 4.9 + hacks

[Ben Greear]

On 05/31/2017 01:18 AM, Bastian Bittorf wrote:
> * Johannes Berg <johannes@sipsolutions.net> [31.05.2017 10:09]:
>>> Is there any way to dump out the socket information if we reproduce
>>> the problem?
>>
>> I have no idea, sorry.
>>
>> If you or Bastian can tell me how to reproduce the problem, I can try
>> to investigate it.
>
> there was an interesting fix regarding the shell-builtin 'read' in
> busybox[1]. I will retest again and report if this changes anything.
>
> bye, bastian
>
> PS: @ben: are you also using 'iw event | while read -r LINE ...'?

I'm using a perl script to read the output, and not using busybox.

I have not seen the problem again, so it is not easy for me to reproduce.

If you reproduce it, maybe check 'strace' on the 'iw' process to see if it is
hung on writing output to the pipe or reading input?  In my case, it appeared
to be hung reading input from netlink, input that never arrived.

Thanks,
Ben


-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: 'iw events' stops receiving events after a while on 4.9 + hacks

[Bastian Bittorf]

* Johannes Berg <johannes@sipsolutions.net> [17.05.2017 20:18]:
> On Wed, 2017-05-17 at 12:08 +0200, Bastian Bittorf wrote:
> > * Ben Greear <greearb@candelatech.com> [17.05.2017 11:51]:

[...]

> > > kernels, but when testing on 4.9 overnight, I notice that 'iw
> > > events' is not showing any input.  'strace' shows
> > > that it is waiting on recvmsg.  If I start a second 'iw events'
> > > then it will get
> > > wifi events as expected.
> > 
> > me too, also seen on 4.4 - i'am happy for debug ideas.
> 
> I've never seen this.
> 
> Does it happen when it's very long-running? Or when there are lots of
> events?

only a couple of hours. hard to say which is the culprit. here
i run it like:

#!/bin/sh
iw event | while read -r LINE; do
 case "$LINE" in
  *': new station '*) ... ;;
  *': del station '*) ... ;;
 esac
done


The script marks new stations with "touch /tmp/$mac"
and removes this file during 'del station'.

What is interesting: i can recognize, that sometimes and
somehow i have stations in 'iw dev wlanX station dump' which
the script has not seen. When debugging this, the script
does not get any new events. A new started 'iw event' can
see further events without problems.

Hard to say where the error happens. I'am on busybox here.

bye, Bastian