2005-02-02 Dan Williams <dcbw@redhat.com>

* src/NetworkManagerAPList.c
		- (nm_ap_list_merge_scanned_ap): merge strength too

	* src/NetworkManagerUtils.c
		- (nm_lock_mutex, nm_register_mutex_desc): new calls to facilitate debugging
			of locking issues by printing out prettier information than g_mutex_lock
		- Print out names of mutexes registered with nm_register_mutex_desc()
		- (nm_try_lock_mutex): don't do the waiting thing when trying to lock, causes
			us to seemingly block here for too long

	* src/NetworkManager.c
	  src/NetworkManagerAPList.c
	  src/NetworkManagerDevice.c
		- Convert to using nm_lock_mutex/nm_unlock_mutex rather than the glib variants
			so we get better debug information printed

	* src/NetworkManagerDbus.c
		- (nm_dbus_devices_handle_request): reduce usage of nm_device_need_ap_switch()
			since it sometimes has locking side effects
		- (nm_device_get_association_pause_value): Reduce 802.11a card pause value to 8s
			from 10s
		- (nm_device_need_ap_switch): If we can't acquire the scan lock, return saying
			we don't need a switch.  This gets called often enough that we can't block
			until the scan mutex is acquired, because we'll block on device activation
			and a few other things, which hangs main thread for too long.

	* src/NetworkManagerPolicy.c
		- (nm_policy_auto_get_best_device): reduce the possiblity that
			nm_device_need_ap_switch() will be called


git-svn-id: http://svn-archive.gnome.org/svn/NetworkManager/trunk@407 4912f4e0-d625-0410-9fb7-b9a5a253dbdc

ChangeLog

@@ -1,3 +1,35 @@
+2005-02-02  Dan Williams  <dcbw@redhat.com>
+
+	* src/NetworkManagerAPList.c
+		- (nm_ap_list_merge_scanned_ap): merge strength too
+
+	* src/NetworkManagerUtils.c
+		- (nm_lock_mutex, nm_register_mutex_desc): new calls to facilitate debugging
+			of locking issues by printing out prettier information than g_mutex_lock
+		- Print out names of mutexes registered with nm_register_mutex_desc()
+		- (nm_try_lock_mutex): don't do the waiting thing when trying to lock, causes
+			us to seemingly block here for too long
+
+	* src/NetworkManager.c
+	  src/NetworkManagerAPList.c
+	  src/NetworkManagerDevice.c
+		- Convert to using nm_lock_mutex/nm_unlock_mutex rather than the glib variants
+			so we get better debug information printed
+
+	* src/NetworkManagerDbus.c
+		- (nm_dbus_devices_handle_request): reduce usage of nm_device_need_ap_switch()
+			since it sometimes has locking side effects
+		- (nm_device_get_association_pause_value): Reduce 802.11a card pause value to 8s
+			from 10s
+		- (nm_device_need_ap_switch): If we can't acquire the scan lock, return saying
+			we don't need a switch.  This gets called often enough that we can't block
+			until the scan mutex is acquired, because we'll block on device activation
+			and a few other things, which hangs main thread for too long.
+
+	* src/NetworkManagerPolicy.c
+		- (nm_policy_auto_get_best_device): reduce the possiblity that
+			nm_device_need_ap_switch() will be called		
+
 2005-02-02  Dan Williams  <dcbw@redhat.com>
 
 	* panel-applet/NMWirelessApplet.c

src/NetworkManager.c

@@ -548,6 +548,7 @@ static NMData *nm_data_new (gboolean enable_test_devices)
 		syslog (LOG_ERR, "Could not initialize data structure locks.");
 		return (NULL);
 	}
+	nm_register_mutex_desc (data->dev_list_mutex, "Device List Mutex");
 
 	/* Initialize the access point lists */
 	data->allowed_ap_list = nm_ap_list_new (NETWORK_TYPE_ALLOWED);

src/NetworkManagerAPList.c

@@ -58,6 +58,7 @@ NMAccessPointList *nm_ap_list_new (NMNetworkType type)
 		syslog (LOG_ERR, "nm_ap_list_new() could not create list mutex");
 		return (NULL);
 	}
+	nm_register_mutex_desc (list->mutex, "AP List Mutex");
 
 	return (list);
 }
@@ -394,6 +395,7 @@ gboolean nm_ap_list_merge_scanned_ap (NMAccessPointList *list, NMAccessPoint *me
 		nm_ap_set_encrypted (list_ap, nm_ap_get_encrypted (merge_ap));
 		nm_ap_set_auth_method (list_ap, nm_ap_get_auth_method (merge_ap));
 		nm_ap_set_last_seen (list_ap, nm_ap_get_last_seen (merge_ap));
+		nm_ap_set_strength (list_ap, nm_ap_get_strength (merge_ap));
 	}
 	else
 	{

src/NetworkManagerDbus.c

@@ -1359,7 +1359,7 @@ static DBusMessage *nm_dbus_devices_handle_request (DBusConnection *connection,
 	}
 	else if (strcmp ("getActiveNetwork", request) == 0)
 	{
-		NMAccessPoint	*ap;
+		NMAccessPoint	*best_ap;
 		gboolean		 success = FALSE;
 
 		/* Only wireless devices have an active network */
@@ -1374,14 +1374,19 @@ static DBusMessage *nm_dbus_devices_handle_request (DBusConnection *connection,
 		/* Return the network associated with the ESSID the card is currently associated with,
 		 * if any, and only if that network is the "best" network.
 		 */
-		if (    (ap = nm_device_ap_list_get_ap_by_essid (dev, nm_device_get_essid (dev)))
+		if ((best_ap = nm_device_get_best_ap (dev)))
-			&& (!nm_device_need_ap_switch (dev))
+		{
-			&& (object_path = nm_device_get_path_for_ap (dev, ap)))
+			NMAccessPoint	*tmp_ap;
+
+			if (    (tmp_ap = nm_device_ap_list_get_ap_by_essid (dev, nm_ap_get_essid (best_ap)))
+				&& (object_path = nm_device_get_path_for_ap (dev, tmp_ap)))
 			{
 				dbus_message_append_args (reply_message, DBUS_TYPE_STRING, object_path, DBUS_TYPE_INVALID);
 				g_free (object_path);
 				success = TRUE;
 			}
+			nm_ap_unref (best_ap);
+		}
 
 		if (!success)
 		{
@@ -1505,6 +1510,7 @@ static DBusHandlerResult nm_dbus_nm_message_handler (DBusConnection *connection,
 	else if (strcmp ("status", method) == 0)
 	{
 		char *status = nm_dbus_network_status_from_data (data);
+
 		if (status && (reply_message = dbus_message_new_method_return (message)))
 				dbus_message_append_args (reply_message, DBUS_TYPE_STRING, status, DBUS_TYPE_INVALID);
 		g_free (status);

src/NetworkManagerDevice.c

@@ -263,6 +263,7 @@ NMDevice *nm_device_new (const char *iface, const char *udi, gboolean test_dev,
 			g_free (dev);
 			return (NULL);
 		}
+		nm_register_mutex_desc (dev->options.wireless.scan_mutex, "Scan Mutex");
 
 		if (!(dev->options.wireless.best_ap_mutex = g_mutex_new ()))
 		{
@@ -271,6 +272,7 @@ NMDevice *nm_device_new (const char *iface, const char *udi, gboolean test_dev,
 			g_free (dev);
 			return (NULL);
 		}
+		nm_register_mutex_desc (dev->options.wireless.best_ap_mutex, "Best AP Mutex");
 
 		if (!(dev->options.wireless.ap_list = nm_ap_list_new (NETWORK_TYPE_DEVICE)))
 		{
@@ -540,7 +542,7 @@ gint nm_device_get_association_pause_value (NMDevice *dev)
 	 * if it is an A/B/G chipset like the Atheros 5212, for example).
 	 */
 	if (dev->options.wireless.num_freqs > 14)
-		return 10;
+		return 8;
 	else
 		return 5;
 }
@@ -2083,7 +2085,7 @@ static gboolean nm_device_activate_wireless (NMDevice *dev)
 	/* Grab the scan mutex, we don't want the scan thread to mess up our settings
 	 * during activation and link detection.
 	 */
-	g_mutex_lock (dev->options.wireless.scan_mutex);
+	nm_lock_mutex (dev->options.wireless.scan_mutex, __FUNCTION__);
 
 	if (!nm_device_is_up (dev))
 		nm_device_bring_up (dev);
@@ -2097,7 +2099,7 @@ get_ap:
 	/* Get a valid "best" access point we should connect to.  We don't hold the scan
 	 * lock here because this might take a while.
 	 */
-	g_mutex_unlock (dev->options.wireless.scan_mutex);
+	nm_unlock_mutex (dev->options.wireless.scan_mutex, __FUNCTION__);
 	while (!(best_ap = nm_device_get_best_ap (dev)))
 	{
 		nm_device_set_now_scanning (dev, TRUE);
@@ -2109,7 +2111,7 @@ get_ap:
 		if (nm_device_activation_handle_cancel (dev))
 		{
 			/* Wierd as it may seem, we lock here to balance the unlock in "out:" */
-			g_mutex_lock (dev->options.wireless.scan_mutex);
+			nm_lock_mutex (dev->options.wireless.scan_mutex, __FUNCTION__);
 			goto out;
 		}
 		found_ap = TRUE;
@@ -2124,7 +2126,7 @@ get_ap:
 	nm_device_set_essid (dev, nm_ap_get_essid (best_ap));
 
 	nm_device_set_now_scanning (dev, FALSE);
-	g_mutex_lock (dev->options.wireless.scan_mutex);
+	nm_lock_mutex (dev->options.wireless.scan_mutex, __FUNCTION__);
 
 	if (nm_ap_get_artificial (best_ap))
 	{
@@ -2150,7 +2152,7 @@ need_key:
 		strncpy (&last_essid[0], essid, 49);
 
 		/* Don't hold the mutex while waiting for a key */
-		g_mutex_unlock (dev->options.wireless.scan_mutex);
+		nm_unlock_mutex (dev->options.wireless.scan_mutex, __FUNCTION__);
 
 		/* Get a wireless key */
 		dev->options.wireless.user_key_received = FALSE;
@@ -2166,7 +2168,7 @@ need_key:
 		syslog (LOG_DEBUG, "Activation (%s/wireless): user key received.", nm_device_get_iface (dev));
 
 		/* Done waiting, grab lock again */
-		g_mutex_lock (dev->options.wireless.scan_mutex);
+		nm_lock_mutex (dev->options.wireless.scan_mutex, __FUNCTION__);
 
 		/* User may have cancelled the key request, so we need to update our best AP again. */
 		nm_ap_unref (best_ap);
@@ -2290,7 +2292,7 @@ connect_done:
 
 out:
 	nm_device_set_now_scanning (dev, FALSE);
-	g_mutex_unlock (dev->options.wireless.scan_mutex);
+	nm_unlock_mutex (dev->options.wireless.scan_mutex, __FUNCTION__);
 	return (success);
 }
 
@@ -2686,11 +2688,11 @@ NMAccessPoint *nm_device_get_best_ap (NMDevice *dev)
 	g_return_val_if_fail (dev != NULL, NULL);
 	g_return_val_if_fail (nm_device_is_wireless (dev), NULL);
 
-	g_mutex_lock (dev->options.wireless.best_ap_mutex);
+	nm_lock_mutex (dev->options.wireless.best_ap_mutex, __FUNCTION__);
 	best_ap = dev->options.wireless.best_ap;
 	/* Callers get a reffed AP */
 	if (best_ap) nm_ap_ref (best_ap);
-	g_mutex_unlock (dev->options.wireless.best_ap_mutex);
+	nm_unlock_mutex (dev->options.wireless.best_ap_mutex, __FUNCTION__);
 	
 	return (best_ap);
 }
@@ -2700,7 +2702,7 @@ void nm_device_set_best_ap (NMDevice *dev, NMAccessPoint *ap)
 	g_return_if_fail (dev != NULL);
 	g_return_if_fail (nm_device_is_wireless (dev));
 
-	g_mutex_lock (dev->options.wireless.best_ap_mutex);
+	nm_lock_mutex (dev->options.wireless.best_ap_mutex, __FUNCTION__);
 
 	if (dev->options.wireless.best_ap)
 		nm_ap_unref (dev->options.wireless.best_ap);
@@ -2710,7 +2712,7 @@ void nm_device_set_best_ap (NMDevice *dev, NMAccessPoint *ap)
 
 	dev->options.wireless.best_ap = ap;
 	nm_device_unfreeze_best_ap (dev);
-	g_mutex_unlock (dev->options.wireless.best_ap_mutex);
+	nm_unlock_mutex (dev->options.wireless.best_ap_mutex, __FUNCTION__);
 }
 
 
@@ -2806,10 +2808,11 @@ gboolean nm_device_need_ap_switch (NMDevice *dev)
 	g_return_val_if_fail (nm_device_is_wireless (dev), FALSE);
 
 
-	/* Since the card's ESSID may change during a scan, we need to
+	/* Since the card's ESSID may change during a scan, we can't really
-	 * wait until the scan is done, if one is in-progress.
+	 * rely on checking the ESSID during that time.
 	 */
-	g_mutex_lock (dev->options.wireless.scan_mutex);
+	if (!nm_try_acquire_mutex (dev->options.wireless.scan_mutex, __FUNCTION__))
+		return FALSE;
 
 	ap = nm_device_get_best_ap (dev);
 	if (nm_null_safe_strcmp (nm_device_get_essid (dev), (ap ? nm_ap_get_essid (ap) : NULL)) != 0)
@@ -2817,7 +2820,7 @@ gboolean nm_device_need_ap_switch (NMDevice *dev)
 
 	if (ap)
 		nm_ap_unref (ap);
-	g_mutex_unlock (dev->options.wireless.scan_mutex);
+	nm_unlock_mutex (dev->options.wireless.scan_mutex, __FUNCTION__);
 
 	return (need_switch);
 }
@@ -2862,7 +2865,7 @@ void nm_device_update_best_ap (NMDevice *dev)
 		/* If its in the device's ap list still, don't change the
 		 * best ap, since its frozen.
 		 */
-		g_mutex_lock (dev->options.wireless.best_ap_mutex);
+		nm_lock_mutex (dev->options.wireless.best_ap_mutex, __FUNCTION__);
 		if (best_ap)
 		{
 			char *essid = nm_ap_get_essid (best_ap);
@@ -2875,7 +2878,7 @@ void nm_device_update_best_ap (NMDevice *dev)
 				|| nm_ap_get_user_created (best_ap))
 			{
 				nm_ap_unref (best_ap);
-				g_mutex_unlock (dev->options.wireless.best_ap_mutex);
+				nm_unlock_mutex (dev->options.wireless.best_ap_mutex, __FUNCTION__);
 				return;
 			}
 			nm_ap_unref (best_ap);
@@ -2883,7 +2886,7 @@ void nm_device_update_best_ap (NMDevice *dev)
 
 		/* Otherwise, its gone away and we don't care about it anymore */
 		nm_device_unfreeze_best_ap (dev);
-		g_mutex_unlock (dev->options.wireless.best_ap_mutex);
+		nm_unlock_mutex (dev->options.wireless.best_ap_mutex, __FUNCTION__);
 	}
 
 	if (!(iter = nm_ap_list_iter_new (ap_list)))

src/NetworkManagerPolicy.c

@@ -100,9 +100,9 @@ static NMDevice * nm_policy_auto_get_best_device (NMData *data)
 			 * WEP key from the user via NetworkManagerInfo.
 			 */
 			if (    !link_active
-				&& !nm_device_need_ap_switch (dev)
 				&& best_ap
-				&& nm_ap_get_encrypted (best_ap))
+				&& nm_ap_get_encrypted (best_ap)
+				&& !nm_device_need_ap_switch (dev))
 				link_active = TRUE;
 
 			if (link_active)

src/NetworkManagerUtils.c

@@ -30,8 +30,51 @@
 #include "NetworkManagerUtils.h"
 
 
+typedef struct MutexDesc
+{
+	GMutex	*mutex;
+	char		*desc;
+} MutexDesc;
+
+GSList	*mutex_descs = NULL;
+
 /*#define LOCKING_DEBUG*/
 
+
+static MutexDesc *nm_find_mutex_desc (GMutex *mutex)
+{
+	GSList	*elt;
+	gboolean	 found = FALSE;
+
+	for (elt = mutex_descs; elt; elt = g_slist_next (elt))
+	{
+		MutexDesc	*desc = (MutexDesc *)(elt->data);
+		if (desc && (desc->mutex == mutex))
+			return desc;
+	}
+
+	return NULL;
+}
+
+
+/*
+ * nm_register_mutex_desc
+ * 
+ * Associate a description with a particular mutex.
+ *
+ */
+void nm_register_mutex_desc (GMutex *mutex, char *string)
+{
+	if (!(nm_find_mutex_desc (mutex)))
+	{
+		MutexDesc	*desc = g_malloc0 (sizeof (MutexDesc));
+		desc->mutex = mutex;
+		desc->desc = g_strdup (string);
+		mutex_descs = g_slist_append (mutex_descs, desc);
+	}
+}
+
+
 /*
  * nm_try_acquire_mutex
  *
@@ -42,30 +85,50 @@
  */
 gboolean nm_try_acquire_mutex (GMutex *mutex, const char *func)
 {
-	gint	i = 5;
-
 	g_return_val_if_fail (mutex != NULL, FALSE);
 
-	while (i > 0)
-	{
 	if (g_mutex_trylock (mutex))
 	{
 #ifdef LOCKING_DEBUG
-			if (func) syslog (LOG_DEBUG, "MUTEX: %s got mutex 0x%X", func, mutex);
+		if (func)
+		{
+			MutexDesc	*desc = nm_find_mutex_desc (mutex);
+			syslog (LOG_DEBUG, "MUTEX: <%s %p> acquired by %s", desc ? desc->desc : "(none)", mutex, func);
+		}
 #endif
 		return (TRUE);
 	}
-		g_usleep (G_USEC_PER_SEC / 2);
-		i++;
-	}
 
 #ifdef LOCKING_DEBUG
-	if (func) syslog (LOG_DEBUG, "MUTEX: %s FAILED to get mutex 0x%X", func, mutex);
+	if (func)
+	{
+		MutexDesc	*desc = nm_find_mutex_desc (mutex);
+		syslog (LOG_DEBUG, "MUTEX: <%s %p> FAILED to be acquired by %s", desc ? desc->desc : "(none)", mutex, func);
+	}
 #endif
 	return (FALSE);
 }
 
 
+/*
+ * nm_lock_mutex
+ *
+ * Blocks until a mutex is grabbed, with debugging.
+ *
+ */
+void nm_lock_mutex (GMutex *mutex, const char *func)
+{
+#ifdef LOCKING_DEBUG
+	if (func)
+	{
+		MutexDesc	*desc = nm_find_mutex_desc (mutex);
+		syslog (LOG_DEBUG, "MUTEX: <%s %p> being acquired by %s", desc ? desc->desc : "(none)", mutex, func);
+	}
+#endif
+	g_mutex_lock (mutex);
+}
+
+
 /*
  * nm_unlock_mutex
  *
@@ -77,7 +140,11 @@ void nm_unlock_mutex (GMutex *mutex, const char *func)
 	g_return_if_fail (mutex != NULL);
 
 #ifdef LOCKING_DEBUG	
-	if (func) syslog (LOG_DEBUG, "MUTEX: %s released mutex 0x%X", func, mutex);
+	if (func)
+	{
+		MutexDesc	*desc = nm_find_mutex_desc (mutex);
+		syslog (LOG_DEBUG, "MUTEX: <%s %p> released by %s", desc ? desc->desc : "(none)", mutex, func);
+	}
 #endif
 
 	g_mutex_unlock (mutex);

src/NetworkManagerUtils.h

@@ -34,7 +34,9 @@
 
 
 gboolean				nm_try_acquire_mutex			(GMutex *mutex, const char *func);
+void					nm_lock_mutex					(GMutex *mutex, const char *func);
 void					nm_unlock_mutex				(GMutex *mutex, const char *func);
+void					nm_register_mutex_desc			(GMutex *mutex, char *string);
 
 int					nm_null_safe_strcmp				(const char *s1, const char *s2);