Another round, getting closer...

Dan

On Wed, 2017-05-31 at 14:10 +0000, Matthew Starr wrote:
> > -----Original Message-----
> > From: Dan Williams [mailto:d...@redhat.com]
> > Sent: Tuesday, May 30, 2017 1:42 PM
> > To: Matthew Starr; networkmanager-list@gnome.org
> > Subject: Re: Network Manager 1.0.X Wi-Fi Autoconnect Issues
> > 
> > Ok another patch attached.  Same as last patch, but it comments out
> > a bunch
> > of the debug logging.  It should point us in the right direction at
> > least.
> > 
> > Dan
> > 
> 
> Now the issue is occurring again and I was able to capture the
> attached log messages from syslog.  You can see network manager
> detecting the network I want to connect to "HED.Inc.Wifi", it shows
> it as a compatible connection, it lists it under the autoactivate
> candidates, but then never connects.
> 
> -Matt
> 
> > On Tue, 2017-05-30 at 16:19 +0000, Matthew Starr wrote:
> > > > -----Original Message-----
> > > > From: Dan Williams [mailto:d...@redhat.com]
> > > > Sent: Thursday, May 25, 2017 11:25 PM
> > > > To: Matthew Starr; networkmanager-list@gnome.org
> > > > Subject: Re: Network Manager 1.0.X Wi-Fi Autoconnect Issues
> > > > 
> > > > On Thu, 2017-05-25 at 22:00 +0000, Matthew Starr wrote:
> > > > > > -----Original Message-----
> > > > > > From: Dan Williams [mailto:d...@redhat.com]
> > > > > > Sent: Thursday, May 25, 2017 12:49 PM
> > > > > > To: Matthew Starr; networkmanager-list@gnome.org
> > > > > > Subject: Re: Network Manager 1.0.X Wi-Fi Autoconnect Issues
> > > > > > 
> > > > > > On Thu, 2017-05-25 at 13:06 +0000, Matthew Starr wrote:
> > > > > > > > -----Original Message-----
> > > > > > > > From: Dan Williams [mailto:d...@redhat.com]
> > > > > > > > Sent: Wednesday, May 24, 2017 3:26 PM
> > > > > > > > To: Matthew Starr; networkmanager-list@gnome.org
> > > > > > > > Subject: Re: Network Manager 1.0.X Wi-Fi Autoconnect
> > > > > > > > Issues
> > > > > > > > 
> > > > > > > > On Wed, 2017-05-24 at 18:22 +0000, Matthew Starr wrote:
> > > > > > > > > > -----Original Message-----
> > > > > > > > > > From: Dan Williams [mailto:d...@redhat.com]
> > > > > > > > > > Sent: Wednesday, May 24, 2017 12:48 PM
> > > > > > > > > > To: Matthew Starr; networkmanager-list@gnome.org
> > > > > > > > > > Subject: Re: Network Manager 1.0.X Wi-Fi
> > > > > > > > > > Autoconnect
> > > > > > > > > > Issues
> > > > > > > > > > 
> > > > > > > > > > On Thu, 2017-05-18 at 22:25 +0000, Matthew Starr
> > > > > > > > > > wrote:
> > > > > > > > > > > > -----Original Message-----
> > > > > > > > > > > > From: Dan Williams [mailto:d...@redhat.com]
> > > > > > > > > > > > Sent: Thursday, May 18, 2017 4:55 PM
> > > > > > > > > > > > To: Matthew Starr; networkmanager-l...@gnome.or
> > > > > > > > > > > > g
> > > > > > > > > > > > Subject: Re: Network Manager 1.0.X Wi-Fi
> > > > > > > > > > > > Autoconnect
> > > > > > > > > > > > Issues
> > > > > > > > > > > > 
> > > > > > > > > > > > On Thu, 2017-05-18 at 20:23 +0000, Matthew
> > > > > > > > > > > > Starr
> > > > > > > > > > > > wrote:
> > > > > > > > > > > > > > -----Original Message-----
> > > > > > > > > > > > > > From: Dan Williams [mailto:d...@redhat.com]
> > > > > > > > > > > > > > Sent: Thursday, May 18, 2017 2:24 PM
> > > > > > > > > > > > > > To: Matthew Starr; networkmanager-list@gnom
> > > > > > > > > > > > > > e.or
> > > > > > > > > > > > > > g
> > > > > > > > > > > > > > Subject: Re: Network Manager 1.0.X Wi-Fi
> > > > > > > > > > > > > > Autoconnect Issues
> > > > > > > > > > > > > > 
> > > > > > > > > > > > > > On Thu, 2017-05-18 at 18:43 +0000, Matthew
> > > > > > > > > > > > > > Starr
> > > > > > > > > > > > > > wrote:
> > > > > > > > > > > > > > > > -----Original Message-----
> > > > > > > > > > > > > > > > From: Dan Williams [mailto:dcbw@redhat.
> > > > > > > > > > > > > > > > com]
> > > > > > > > > > > > > > > > Sent: Thursday, May 18, 2017 1:31 PM
> > > > > > > > > > > > > > > > To: Matthew Starr; networkmanager-list@
> > > > > > > > > > > > > > > > gnom
> > > > > > > > > > > > > > > > e.or g
> > > > > > > > > > > > > > > > Subject: Re: Network Manager 1.0.X Wi-
> > > > > > > > > > > > > > > > Fi
> > > > > > > > > > > > > > > > Autoconnect Issues
> > > > > > > > > > > > > > > > 
> > > > > > > > > > > > > > > > On Thu, 2017-05-18 at 15:54 +0000,
> > > > > > > > > > > > > > > > Matthew
> > > > > > > > > > > > > > > > Starr
> > > > > > > > > > > > > > > > wrote:
> > > > > > > > > > > > > > > > > I have tried using NetworkManager
> > > > > > > > > > > > > > > > > 1.0.0
> > > > > > > > > > > > > > > > > and
> > > > > > > > > > > > > > > > > 1.0.12 on
> > > > > > > > > > > > > > > > > an embedded device built with
> > > > > > > > > > > > > > > > > buildroot
> > > > > > > > > > > > > > > > > that has Ethernet (eth0), Wi-Fi
> > > > > > > > > > > > > > > > > client
> > > > > > > > > > > > > > > > > (mlan0), Wi-Fi Access Point (uap0),
> > > > > > > > > > > > > > > > > and
> > > > > > > > > > > > > > > > > Cellular interfaces
> > > > > > > > > > > > > > > > > (ttyACM0
> > > > > > > > > > > > > > > > > and ppp0).  The Wi-Fi AP (uap0)
> > > > > > > > > > > > > > > > > interface
> > > > > > > > > > > > > > > > > is ignored by Network Manager based
> > > > > > > > > > > > > > > > > on my
> > > > > > > > > > > > > > > > > NetworkManager.conf file.
> > > > > > > > > > > > > > > > > I am
> > > > > > > > > > > > > > > > > able to boot the device and Network
> > > > > > > > > > > > > > > > > Manager will automatically configure
> > > > > > > > > > > > > > > > > and
> > > > > > > > > > > > > > > > > connect with Ethernet, Wi-Fi Client,
> > > > > > > > > > > > > > > > > and
> > > > > > > > > > > > > > > > > Cellular interfaces every time.
> > > > > > > > > > > > > > > > > 
> > > > > > > > > > > > > > > > > If I move out of range of the Wi-Fi
> > > > > > > > > > > > > > > > > access
> > > > > > > > > > > > > > > > > point the device will disconnect and
> > > > > > > > > > > > > > > > > if I
> > > > > > > > > > > > > > > > > move back into range in under an
> > > > > > > > > > > > > > > > > hour,
> > > > > > > > > > > > > > > > > NetworkManager will reestablish the
> > > > > > > > > > > > > > > > > connection.  If I wait multiple hours
> > > > > > > > > > > > > > > > > before moving back into range of the
> > > > > > > > > > > > > > > > > Wi-Fi
> > > > > > > > > > > > > > > > > access point, Network Manager will
> > > > > > > > > > > > > > > > > not
> > > > > > > > > > > > > > > > > reestablish a connection
> > > > > > > > > > > > > > > > > automatically
> > > > > > > > > > > > > > > > > with the access point (I waited hours
> > > > > > > > > > > > > > > > > with
> > > > > > > > > > > > > > > > > the AP within range and visible in
> > > > > > > > > > > > > > > > > Wi-Fi
> > > > > > > > > > > > > > > > > scan results).
> > > > > > > > > > > > > > > > > When Network Manager is not
> > > > > > > > > > > > > > > > > automatically
> > > > > > > > > > > > > > > > > reestablishing a connection to the
> > > > > > > > > > > > > > > > > access
> > > > > > > > > > > > > > > > > point I can use nmcli to bring up the
> > > > > > > > > > > > > > > > > profile associated with the access
> > > > > > > > > > > > > > > > > point
> > > > > > > > > > > > > > > > > and it connects immediately.
> > > > > > > > > > > > > > > > > 
> > > > > > > > > > > > > > > > > Why is Network Manager not able to
> > > > > > > > > > > > > > > > > auto
> > > > > > > > > > > > > > > > > connect to a
> > > > > > > > > > > > > > > > > Wi-
> > > > > > > > > > > > > > > > > Fi AP after a longer period of time
> > > > > > > > > > > > > > > > > of not
> > > > > > > > > > > > > > > > > seeing the AP?
> > > > > > > > > > > > > > > > > Is there a timeout within Network
> > > > > > > > > > > > > > > > > Manager?
> > > > > > > > > > > > > > > > > Is this a bug?
> > > > > > > > > > > > > > > > 
> > > > > > > > > > > > > > > > Like you say, it does look like NM is
> > > > > > > > > > > > > > > > trying
> > > > > > > > > > > > > > > > to
> > > > > > > > > > > > > > > > auto-
> > > > > > > > > > > > > > > > activate the connection, but it's not
> > > > > > > > > > > > > > > > doing
> > > > > > > > > > > > > > > > it correctly.
> > > > > > > > > > > > > > > > The most likely thing happening is that
> > > > > > > > > > > > > > > > it
> > > > > > > > > > > > > > > > does try to activate, but it's not able
> > > > > > > > > > > > > > > > to
> > > > > > > > > > > > > > > > find the "best"
> > > > > > > > > > > > > > > > connection
> > > > > > > > > > > > > > > > for the device.
> > > > > > > > > > > > > > > > Somehow the existing WiFi connection
> > > > > > > > > > > > > > > > profile
> > > > > > > > > > > > > > > > isn't matching.
> > > > > > > > > > > > > > > > 
> > > > > > > > > > > > > > > > Can you run 'nmcli con show <name of
> > > > > > > > > > > > > > > > connection you expect to
> > > > > > > > > > > > > > > > start>'?
> > > > > > > > > > > > > > > 
> > > > > > > > > > > > > > > Dan,
> > > > > > > > > > > > > > > 
> > > > > > > > > > > > > > > This issue has occurred on several
> > > > > > > > > > > > > > > different
> > > > > > > > > > > > > > > access
> > > > > > > > > > > > > > > point I have attempted to connect to all
> > > > > > > > > > > > > > > from
> > > > > > > > > > > > > > > different vendors (Linksys, Ubiquiti, D-
> > > > > > > > > > > > > > > link).
> > > > > > > > > > > > > > 
> > > > > > > > > > > > > > Ok, that doesn't ellucidate anything.  Are
> > > > > > > > > > > > > > you
> > > > > > > > > > > > > > able
> > > > > > > > > > > > > > to
> > > > > > > > > > > > > > apply a debugging patch to NetworkManager
> > > > > > > > > > > > > > and
> > > > > > > > > > > > > > rebuild
> > > > > > > > > > > > > > it?
> > > > > > > > > > > > > > Alternatively, you could use 'gdb' to step
> > > > > > > > > > > > > > through
> > > > > > > > > > > > > > the
> > > > > > > > > > > > > > code and see where it's not proceeding with
> > > > > > > > > > > > > > the
> > > > > > > > > > > > > > activation in nm-policy.c.
> > > > > > > > > > > > > > 
> > > > > > > > > > > > > > Dan
> > > > > > > > > > > > > > 
> > > > > > > > > > > > > 
> > > > > > > > > > > > > Some additional testing I just finished shows
> > > > > > > > > > > > > that
> > > > > > > > > > > > > version
> > > > > > > > > > > > > 1.6.2
> > > > > > > > > > > > > exhibits the exact same behavior.
> > > > > > > > > > > > > 
> > > > > > > > > > > > > I am able to apply patches easily and
> > > > > > > > > > > > > rebuild.  I
> > > > > > > > > > > > > could
> > > > > > > > > > > > > run gdb but it is not quite as easy on my
> > > > > > > > > > > > > current
> > > > > > > > > > > > > setup.
> > > > > > > > > > > > 
> > > > > > > > > > > > Which version do you prefer patches for?
> > > > > > > > > > > > 
> > > > > > > > > > > > Dan
> > > > > > > > > > > 
> > > > > > > > > > > My more immediate need is with the 1.0.12
> > > > > > > > > > > version,
> > > > > > > > > > > but I
> > > > > > > > > > > plan
> > > > > > > > > > > to do a release within the next 6 months with the
> > > > > > > > > > > 1.6.X
> > > > > > > > > > > or
> > > > > > > > > > > 1.8.X version.
> > > > > > > > > > 
> > > > > > > > > > Patch against upstream 1.0.12 attached.  Hopefully
> > > > > > > > > > applies
> > > > > > > > > > to
> > > > > > > > > > your version.  It should log the right stuff
> > > > > > > > > > without
> > > > > > > > > > touching
> > > > > > > > > > the logging level or domains.  Run with this patch,
> > > > > > > > > > reproduce
> > > > > > > > > > the issue, and lets see what the logs say.
> > > > > > > > > > 
> > > > > > > > > > Dan
> > > > > > > > > 
> > > > > > > > > I was able to cleanly apply the patch, but shortly
> > > > > > > > > after
> > > > > > > > > starting
> > > > > > > > > Network Manager it seems to seg fault (verified by
> > > > > > > > > using
> > > > > > > > > the
> > > > > > > > > -n
> > > > > > > > > option to not run as a daemon). I don't see any error
> > > > > > > > > messages in
> > > > > > > > > the logs. Here is where the logs left off:
> > > > > > > > 
> > > > > > > > You've probably got some hidden-SSID APs, and I didn't
> > > > > > > > account
> > > > > > > > for
> > > > > > > > that.  Can you back out the previous patch, and try the
> > > > > > > > latest
> > > > > > > > attached one?
> > > > > > > > 
> > > > > > > > Dan
> > > > > > > 
> > > > > > > With the new patch I was able to establish a connection,
> > > > > > > put
> > > > > > > the
> > > > > > > module running Network Manager in a faraday cage for an
> > > > > > > hour,
> > > > > > > and
> > > > > > > then
> > > > > > > on removing it from the cage Network Manager connected
> > > > > > > successfully.
> > > > > > > This usually is not the case after an hour of not seeing
> > > > > > > the
> > > > > > > APs.  At
> > > > > > > this point I wanted to test again for a longer period so
> > > > > > > I
> > > > > > > put
> > > > > > > the
> > > > > > > module back in the cage for an overnight test and it
> > > > > > > appears
> > > > > > > as
> > > > > > > soon
> > > > > > > as the module was isolated from all the APs, Network
> > > > > > > Manager
> > > > > > > crashed
> > > > > > > again.  See the attached log for what was going on when
> > > > > > > it
> > > > > > > crashed at
> > > > > > > May 24 22:00:24.
> > > > > > > 
> > > > > > > I will try my setup again after a reboot to get Network
> > > > > > > Manager
> > > > > > > running again.  Let me know if there is another patch you
> > > > > > > want me
> > > > > > > to
> > > > > > > apply to resolve the crashing issue.
> > > > > > 
> > > > > > Again my fault.  Any place you see:
> > > > > > 
> > > > > > g_free (tmp);
> > > > > > 
> > > > > > in the patch, replace that with:
> > > > > > 
> > > > > > if (ssid) g_free (tmp);
> > > > > > 
> > > > > > Or back out the previous patch, and apply the attached one.
> > > > > > 
> > > > > > Dan
> > > > > 
> > > > > It appears I cannot reproduce the issue with the patch you
> > > > > provided
> > > > > that includes the debug statements.  The Wi-Fi reconnects
> > > > > within
> > > > > 1-2
> > > > > minutes or less every time.  I wonder if this is a timing
> > > > > issue
> > > > > that
> > > > > the debug statements are delaying just enough to not make the
> > > > > issue
> > > > > occur.
> > > > > 
> > > > > Before the patch I could reproduce it almost every time on
> > > > > multiple
> > > > > devices running the same software after an hour of no Wi-Fi
> > > > > signal.  The only change on the devices is the updated
> > > > > network
> > > > > manager with your patch. I will continue to test after
> > > > > memorial
> > > > > day.
> > > > > 
> > > > > Is there anything else you want me to check with the
> > > > > unpatched
> > > > > version or any other patches you want me to try out?
> > > > 
> > > > Could you rebuild without the patch and test that version?  eg,
> > > > to
> > > > determine whether it's the debug patch making it work, or
> > > > whether
> > > > for
> > > > some reason the rebuild is doing it.  I can also start removing
> > > > log
> > > > statements to reduce any potential timing issue.
> > > > 
> > > > Dan
> > > 
> > > I rebuilt network manager without the debug patches and after 1
> > > hour
> > > of no Wi-Fi signal, network manager is not attempting to
> > > reconnect
> > > when the Wi-FI AP is visible again (verified using "iw dev mlan0
> > > scan").
> > > 
> > > If you have any other patches you want to try with log statements
> > > removed, I would be happy to test them.
> > > 
> > > -Matt
diff --git a/src/devices/nm-device.c b/src/devices/nm-device.c
index bc7ebcb..423cc74 100644
--- a/src/devices/nm-device.c
+++ b/src/devices/nm-device.c
@@ -2150,7 +2150,10 @@ can_auto_connect (NMDevice *self,
 
 	s_con = nm_connection_get_setting_connection (connection);
 	if (!nm_setting_connection_get_autoconnect (s_con))
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [device] not autoconnect", nm_device_get_iface (self));
 		return FALSE;
+}
 
 	return nm_device_check_connection_available (self, connection, NM_DEVICE_CHECK_CON_AVAILABLE_NONE, NULL);
 }
@@ -7765,24 +7768,40 @@ nm_device_check_connection_available (NMDevice *self,
                                       const char *specific_object)
 {
 	NMDeviceState state;
+	gboolean avail;
 
 	state = nm_device_get_state (self);
 	if (state < NM_DEVICE_STATE_UNMANAGED)
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [device] < unmanaged", nm_device_get_iface (self));
 		return FALSE;
+}
 	if (   state < NM_DEVICE_STATE_UNAVAILABLE
 	    && nm_device_get_unmanaged_flag (self, NM_UNMANAGED_ALL & ~NM_UNMANAGED_DEFAULT))
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [device] < unavailable", nm_device_get_iface (self));
 		return FALSE;
+}
 	if (   state < NM_DEVICE_STATE_DISCONNECTED
 	    && (   (   !NM_FLAGS_HAS (flags, _NM_DEVICE_CHECK_CON_AVAILABLE_FOR_USER_REQUEST_WAITING_CARRIER)
 	            && !nm_device_is_available (self, NM_DEVICE_CHECK_DEV_AVAILABLE_NONE))
 	        || (    NM_FLAGS_HAS (flags, _NM_DEVICE_CHECK_CON_AVAILABLE_FOR_USER_REQUEST_WAITING_CARRIER)
 	            && !nm_device_is_available (self, NM_DEVICE_CHECK_DEV_AVAILABLE_IGNORE_CARRIER))))
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [device] < disconnected", nm_device_get_iface (self));
 		return FALSE;
+}
 
 	if (!nm_device_check_connection_compatible (self, connection))
+{
+	nm_log_info (LOGD_DEVICE, "#### (%s)     [device] incompatible with device", nm_device_get_iface (self));
 		return FALSE;
+}
 
-	return NM_DEVICE_GET_CLASS (self)->check_connection_available (self, connection, flags, specific_object);
+	avail = NM_DEVICE_GET_CLASS (self)->check_connection_available (self, connection, flags, specific_object);
+	if (!avail)
+	nm_log_info (LOGD_DEVICE, "#### (%s)     [device] connection not available", nm_device_get_iface (self));
+	return avail;
 }
 
 static void
diff --git a/src/devices/wifi/nm-device-wifi.c b/src/devices/wifi/nm-device-wifi.c
index 0f7fb6e..0dc53b9 100644
--- a/src/devices/wifi/nm-device-wifi.c
+++ b/src/devices/wifi/nm-device-wifi.c
@@ -777,53 +777,84 @@ check_connection_compatible (NMDevice *device, NMConnection *connection)
 	const char *perm_hw_addr;
 
 	if (!NM_DEVICE_CLASS (nm_device_wifi_parent_class)->check_connection_compatible (device, connection))
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi compat] parent fail", nm_device_get_iface (device));
 		return FALSE;
+}
 
 	s_con = nm_connection_get_setting_connection (connection);
 	g_assert (s_con);
 
 	if (strcmp (nm_setting_connection_get_connection_type (s_con), NM_SETTING_WIRELESS_SETTING_NAME))
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi compat] not wifi", nm_device_get_iface (device));
 		return FALSE;
+}
 
 	s_wireless = nm_connection_get_setting_wireless (connection);
 	if (!s_wireless)
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi compat] no wireless setting", nm_device_get_iface (device));
 		return FALSE;
+}
 
 	perm_hw_addr = nm_device_get_permanent_hw_address (device);
 	mac = nm_setting_wireless_get_mac_address (s_wireless);
 	if (perm_hw_addr) {
 		if (mac && !nm_utils_hwaddr_matches (mac, -1, perm_hw_addr, -1))
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi compat] mac mismatch", nm_device_get_iface (device));
 			return FALSE;
+}
 
 		/* Check for MAC address blacklist */
 		mac_blacklist = nm_setting_wireless_get_mac_address_blacklist (s_wireless);
 		for (i = 0; mac_blacklist[i]; i++) {
 			if (!nm_utils_hwaddr_valid (mac_blacklist[i], ETH_ALEN)) {
 				g_warn_if_reached ();
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi compat] mac blacklist entry invalid", nm_device_get_iface (device));
 				return FALSE;
 			}
 
 			if (nm_utils_hwaddr_matches (mac_blacklist[i], -1, perm_hw_addr, -1))
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi compat] mac blacklisted", nm_device_get_iface (device));
 				return FALSE;
+}
 		}
 	} else if (mac)
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi compat] mac required; no permaddr", nm_device_get_iface (device));
 		return FALSE;
+}
 
 	if (is_adhoc_wpa (connection))
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi compat] adhoc wpa", nm_device_get_iface (device));
 		return FALSE;
+}
 
 	/* Early exit if supplicant or device doesn't support requested mode */
 	mode = nm_setting_wireless_get_mode (s_wireless);
 	if (g_strcmp0 (mode, NM_SETTING_WIRELESS_MODE_ADHOC) == 0) {
 		if (!(priv->capabilities & NM_WIFI_DEVICE_CAP_ADHOC))
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi compat] adhoc unsupported", nm_device_get_iface (device));
 			return FALSE;
+}
 	} else if (g_strcmp0 (mode, NM_SETTING_WIRELESS_MODE_AP) == 0) {
 		if (!(priv->capabilities & NM_WIFI_DEVICE_CAP_AP))
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi compat] ap unsupported", nm_device_get_iface (device));
 			return FALSE;
+}
 
 		if (priv->sup_iface) {
 			if (nm_supplicant_interface_get_ap_support (priv->sup_iface) == AP_SUPPORT_NO)
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi compat] supplicant ap unsupported", nm_device_get_iface (device));
 				return FALSE;
+}
 		}
 	}
 
@@ -856,7 +887,14 @@ check_connection_available (NMDevice *device,
 		NMAccessPoint *ap;
 
 		ap = get_ap_by_path (NM_DEVICE_WIFI (device), specific_object);
-		return ap ? nm_ap_check_compatible (ap, connection) : FALSE;
+		if (ap) {
+			gboolean compat = nm_ap_check_compatible (ap, connection);
+if (!compat)
+	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi avail] specific object AP incompat with connection", nm_device_get_iface (device));
+			return compat;
+		}
+	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi avail] specific object not found", nm_device_get_iface (device));
+		return FALSE;
 	}
 
 	/* Ad-Hoc and AP connections are always available because they may be
@@ -880,10 +918,20 @@ check_connection_available (NMDevice *device,
 
 	/* check if its visible */
 	for (ap_iter = priv->ap_list; ap_iter; ap_iter = g_slist_next (ap_iter)) {
+		const GByteArray *ssid = nm_ap_get_ssid (NM_AP (ap_iter->data));
+		char *tmp = ssid ? nm_utils_ssid_to_utf8 (ssid->data, ssid->len) : "<none>";
+
+	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi avail] checking AP '%s'", nm_device_get_iface (device), tmp);
 		if (nm_ap_check_compatible (NM_AP (ap_iter->data), connection))
+{
+	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi avail]    AP '%s' compatible", nm_device_get_iface (device), tmp);
+if (ssid) g_free (tmp);
 			return TRUE;
+}
+	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi avail]    AP '%s' incompatible with connection", nm_device_get_iface (device), tmp);
 	}
 
+	nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi avail] no compatible AP found", nm_device_get_iface (device));
 	return FALSE;
 }
 
@@ -1140,7 +1188,10 @@ can_auto_connect (NMDevice *device,
 	guint64 timestamp = 0;
 
 	if (!NM_DEVICE_CLASS (nm_device_wifi_parent_class)->can_auto_connect (device, connection, specific_object))
+{
+//nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi] parent can_auto_connect() fail", nm_device_get_iface (device));
 		return FALSE;
+}
 
 	s_wifi = nm_connection_get_setting_wireless (connection);
 	g_return_val_if_fail (s_wifi, FALSE);
@@ -1160,19 +1211,29 @@ can_auto_connect (NMDevice *device,
 	 */
 	if (nm_settings_connection_get_timestamp (NM_SETTINGS_CONNECTION (connection), &timestamp)) {
 		if (timestamp == 0)
+{
+nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi] zero timestamp", nm_device_get_iface (device));
 			return FALSE;
+}
 	}
 
 	for (ap_iter = priv->ap_list; ap_iter; ap_iter = g_slist_next (ap_iter)) {
 		NMAccessPoint *ap = NM_AP (ap_iter->data);
+		const GByteArray *ssid = nm_ap_get_ssid (ap);
+		char *tmp = ssid ? nm_utils_ssid_to_utf8 (ssid->data, ssid->len) : "<none>";
 
+nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi] (checking %s)", nm_device_get_iface (device), tmp);
 		if (nm_ap_check_compatible (ap, connection)) {
 			/* All good; connection is usable */
 			*specific_object = (char *) nm_ap_get_dbus_path (ap);
+		if (ssid) g_free (tmp);
 			return TRUE;
 		}
+nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi] (%s incompatible with connection)", nm_device_get_iface (device), tmp);
+		if (ssid) g_free (tmp);
 	}
 
+nm_log_info (LOGD_DEVICE, "#### (%s)     [wifi] no compatible AP", nm_device_get_iface (device));
 	return FALSE;
 }
 
diff --git a/src/nm-policy.c b/src/nm-policy.c
index fc2a9bf..cb886f0 100644
--- a/src/nm-policy.c
+++ b/src/nm-policy.c
@@ -650,16 +650,24 @@ auto_activate_device (gpointer user_data)
 
 	data->autoactivate_id = 0;
 
+	nm_log_info (LOGD_DEVICE, "#### (%s) autoactivate attempt", nm_device_get_iface (data->device));
+
 	// FIXME: if a device is already activating (or activated) with a connection
 	// but another connection now overrides the current one for that device,
 	// deactivate the device and activate the new connection instead of just
 	// bailing if the device is already active
 	if (nm_device_get_act_request (data->device))
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s) autoactivate fail; already activating", nm_device_get_iface (data->device));
 		goto out;
+}
 
 	connection_list = nm_manager_get_activatable_connections (priv->manager);
 	if (!connection_list)
+{
+//	nm_log_info (LOGD_DEVICE, "#### (%s) autoactivate fail; no activatable connections", nm_device_get_iface (data->device));
 		goto out;
+}
 
 	connections = _nm_utils_copy_slist_to_array (connection_list, NULL, NULL);
 	g_slist_free (connection_list);
@@ -668,17 +676,29 @@ auto_activate_device (gpointer user_data)
 	 * with same priority are still sorted by last-connected-timestamp. */
 	g_ptr_array_sort (connections, (GCompareFunc) nm_utils_cmp_connection_by_autoconnect_priority);
 
+//if (!nm_device_autoconnect_allowed (data->device))
+//	nm_log_info (LOGD_DEVICE, "#### (%s) autoactivate fail; device autoconnect blocked", nm_device_get_iface (data->device));
+
 	/* Find the first connection that should be auto-activated */
 	best_connection = NULL;
 	for (i = 0; i < connections->len; i++) {
 		NMSettingsConnection *candidate = NM_SETTINGS_CONNECTION (connections->pdata[i]);
 
+	nm_log_info (LOGD_DEVICE, "#### (%s) autoactivate candidate '%s'", nm_device_get_iface (data->device), nm_connection_get_id (NM_CONNECTION (candidate)));
+
 		if (!nm_settings_connection_can_autoconnect (candidate))
+{
+	nm_log_info (LOGD_DEVICE, "#### (%s)     not auto-activate", nm_device_get_iface (data->device));
 			continue;
+}
 		if (nm_device_can_auto_connect (data->device, (NMConnection *) candidate, &specific_object)) {
+	nm_log_info (LOGD_DEVICE, "#### (%s)     BEST", nm_device_get_iface (data->device));
 			best_connection = (NMConnection *) candidate;
 			break;
 		}
+//else {
+//	nm_log_info (LOGD_DEVICE, "#### (%s)     can't autoconnect", nm_device_get_iface (data->device));
+//}
 	}
 	g_ptr_array_free (connections, TRUE);
 
@@ -703,6 +723,8 @@ auto_activate_device (gpointer user_data)
 		}
 		g_object_unref (subject);
 	}
+//else
+//	nm_log_info (LOGD_DEVICE, "#### (%s) autoactivate fail; no best connection", nm_device_get_iface (data->device));
 
  out:
 	activate_data_free (data);
_______________________________________________
networkmanager-list mailing list
networkmanager-list@gnome.org
https://mail.gnome.org/mailman/listinfo/networkmanager-list

Reply via email to