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

[Dan Williams]

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:

	/* If we have more SSIDs to scan, add a timeout so we scan them too */
	if (ssid || !wpa_s->first_sched_scan) {
		wpa_s->sched_scan_timed_out = 0;
		eloop_register_timeout(wpa_s->sched_scan_timeout, 0,
				       wpa_supplicant_sched_scan_timeout,
				       wpa_s, NULL);
		wpa_s->first_sched_scan = 0;
		wpa_s->sched_scan_timeout /= 2;
		wpa_s->sched_scan_interval *= 2;
		if (wpa_s->sched_scan_timeout < wpa_s->sched_scan_interval) {
			wpa_s->sched_scan_interval = 10;
			wpa_s->sched_scan_timeout = max_sched_scan_ssids * 2;
		}
	}

It seems like all scans should have a timeout.

Dan


> How to handle this case?
> 
> Regards,
> Johncy.
> 
> On 25 February 2016 at 14:42, Johncy Bennette <johncyrr at gmail.com>
> wrote:
> > Hi Jouni,
> > 
> > Attached the logs as zip files due to size limitation.
> > 
> > DeviceConnectedToAp_APSwitchedOff_DeviceAttemptToReConnect.txt -
> > The
> > scenario is, I connected to access point "Controls". After a while
> > switched off the AP. Then while reconnecting in process, sent a
> > scan
> > request.
> > 
> > APSwitchedOff_DeviceAttemptToConnect.txt - The scenario is, I
> > connected to access point "Controls". After a while switched off
> > the
> > AP. Restarted my process. While my process tries to reconnect to
> > access point, sent a scan request.
> > 
> > Regards,
> > Johncy
> > 
> > On 25 February 2016 at 13:10, Johncy Bennette <johncyrr at gmail.com>
> > wrote:
> > > Hi Jouni,
> > > 
> > > Attached the logs.
> > > 
> > > DeviceConnectedToAp_APSwitchedOff_DeviceAttemptToReConnect.txt -
> > > The
> > > scenario is, I connected to access point "Controls". After a
> > > while
> > > switched off the AP. Then while reconnecting in process, sent a
> > > scan
> > > request.
> > > 
> > > APSwitchedOff_DeviceAttemptToConnect.txt - The scenario is, I
> > > connected to access point "Controls". After a while switched off
> > > the
> > > AP. Restarted my process. While my process tries to reconnect to
> > > access point, sent a scan request.
> > > 
> > > Regards,
> > > Johncy
> > > 
> > > On 24 February 2016 at 18:36, Jouni Malinen <j at w1.fi> wrote:
> > > > On Wed, Feb 24, 2016 at 05:27:09PM +0530, Johncy Bennette
> > > > wrote:
> > > > > I am using wpa_supplicant + dbus to connect my device to
> > > > > Access point,
> > > > > scan access points, disconnect from access points. If I send
> > > > > a scan
> > > > > command, when there is a problem connecting to the access
> > > > > points, My
> > > > > scan list is empty.
> > > > > 
> > > > > The sequence is as below,
> > > > > 
> > > > > My device connected to a access point successfully.
> > > > > After a while, switched off the access point, and my software
> > > > > tries to
> > > > > reconnect when there is a disconnect signal at 30 seconds
> > > > > interval
> > > > > (unless user has disabled wifi). At this period if I try to
> > > > > scan the
> > > > > wifi networks my scan list is empty.
> > > > > When i send wpa_cli -iwlan0 status it shows the wpa_state as
> > > > > SCANNING.
> > > > > I could see there is no scan_done signal received from dbus
> > > > > with dbus-monitor
> > > > 
> > > > Could you please share a wpa_supplicant debug log with -dt on
> > > > command
> > > > line showing this?
> > > > 
> > > > --
> > > > Jouni Malinen                                            PGP id
> > > > EFC895FA
> _______________________________________________
> Hostap mailing list
> Hostap at lists.infradead.org
> http://lists.infradead.org/mailman/listinfo/hostap