Scan request looks ignored when wpa_state is in scanning state with dbus interface

[Johannes Berg]

On Thu, 2016-02-25 at 10:36 -0800, Ben Greear wrote:
> On 02/25/2016 10:23 AM, Dan Williams wrote:
> > On Thu, 2016-02-25 at 18:34 +0530, Johncy Bennette wrote:
> > > Hi Jouni,
> > > 
> > > My earlier logs were big in size. So not delivered. So I
> > > recaptured
> > > and attaching only required logs.
> > > 
> > > AP-Problem.log
> > > 
> > > I switched off the router around the time
> > > 1456401394.205710: dbus: flush_object_timeout_handler: Timeout -
> > > sending changed properties of object
> > > /fi/w1/wpa_supplicant1/Interfaces/1
> > > 
> > > Around the time 1456401598.821077: wlan0: Setting scan request:
> > > 1.000000 sec I gave the scan command.
> > > 
> > > The dbus sequence I follow is,
> > > AddNetwork
> > > SelectNetwork
> > > Then I wait for "completed" signal from dbus
> > > udhcpc -iwlan0 to get IP once connected.
> > > 
> > > When there is problem connecting ie at the time of reconnect,
> > > SelectNetwork with the object obtained as part of AddNetwork
> > > Then I wait for "completed" signal from dbus
> > > udhcpc -iwlan0 if connected.
> > > 
> > > I could see from the log,
> > > 1456401549.760162: Fast associate: Old scan results
> > > After this there is continous scan requests ignored.
> > 
> > There are two bugs, it seems.
> > 
> > 1) you don't have this patch:
> > 
> > d38c7be0f013703639568a690af0394ceece1fca
> > "Skip SELECT_NETWORK steps only if already connected or connecting"
> > 
> > which would fix the issue where SelectNetwork doesn't attempt to
> > associate.  Unfortunately this fix is not in a released version,
> > not
> > even hostapd 2.5.
> > 
> > 2) a supplicant SCHED_SCAN never completes.  There is only one
> > enabled
> > network, and this is the first sched_scan, and apparently those are
> > never timed out.  Since the AP is turned off, no scan results for
> > that
> > AP will ever be delivered.
> > 
> > Jouni, this seems like a supplicant bug?  The code is pretty clear,
> > the
> > following block never gets run because ssid==NULL (because there's
> > only
> > one enabled network/SSID and max_sched_scan_ssids >= 1) and this is
> > the
> > first sched_scan:
> 
> At least with ath10k, I've seen cases where scan-complete is never
> sent
> back to supplicant.  I added a timeout at that time that dealt with
> the issue,
> not sure it would fix this problem or not.
> 
> https://github.com/greearb/hostap-ct/commit/913f01e9d0384ed5e99b396f0
> 50233d9204dd041
> 

That won't actually help you much, unless somehow the event got lost
between cfg80211 and wpa_s; if it never arrived you'll never be allowed
to scan again and really need to fix ath10k instead.

There's a very slight chance of us failing to allocate memory when
sending the event; we could attempt to fix that by preallocating? But
it cannot actually happen since small GFP_KERNEL apparently can't
actually fail.

johannes