Re: nice +19

[Dan Williams <dcbw redhat com>]

Bill,

Please apply the following patch (in base NetworkManager CVS directory,
use 'patch -p0 < /path/to/bill-moss-debug.patch'), 'make', 'sudo make
install', and then reboot.

You should probably forward the logs directly to me, as they will
contain fairly private information such as wireless networks that exist
(including frequency, WEP passphrase, etc) and returned DHCP options.
You may xxxx out any info you don't want shared if you like.

Dan

On Mon, 2005-01-24 at 11:14 -0500, Bill Moss wrote:
> Re: CVS-1-22-05:
> At work this morning, NM failed to find the AP on boot. I let the debug 
> message " ... waiting for an access point" repeat about a dozen times 
> then plugged in the wire and immediately got a connection. I unplugged 
> the wire and immediately got a wireless connection. I repeated this a 
> couple of time successfully. nice +19 in the init script is apparently 
> not nice enough to always get the worker thread and the main thread 
> communicating at boot.
> 
> NM is the last service started by the rc system. NM runs through its 
> initial setup and then the window manager comes up which is the last 
> process in inittab. After that NM starts looking for a access point. 
> Without the nice +19 NM looses it way. With nice +19 is sometimes looses 
> its way. When started after boot, NM works fine.
> 

? bill-moss-debug.patch
? foo.patch
Index: src/NetworkManagerAPList.c
===================================================================
RCS file: /cvs/gnome/NetworkManager/src/NetworkManagerAPList.c,v
retrieving revision 1.27
diff -u -r1.27 NetworkManagerAPList.c
--- src/NetworkManagerAPList.c	21 Jan 2005 19:32:08 -0000	1.27
+++ src/NetworkManagerAPList.c	24 Jan 2005 19:11:51 -0000
@@ -649,22 +649,26 @@
 	NMAPListIter	*iter;
 	int			 i = 0;
 
+syslog (LOG_ERR, "list = %p, name = %p\n", list, name);
 	g_return_if_fail (list != NULL);
 	g_return_if_fail (name != NULL);
 
 	if (!(iter = nm_ap_list_iter_new (list)))
+{
+syslog (LOG_ERR, "foobar\n");
 		return;
+}
 
-	syslog (LOG_DEBUG, "AP_LIST_PRINT: printing members of '%s'", name);
+	syslog (LOG_ERR, "AP_LIST_PRINT: printing members of '%s'", name);
 	while ((ap = nm_ap_list_iter_next (iter)))
 	{
 		const GTimeVal *timestamp = nm_ap_get_timestamp (ap);
-		syslog (LOG_DEBUG, "\t%d)\tobj=%p, essid='%s', timestamp=%ld, key='%s', enc=%d, addr=%p, strength=%d, freq=%f, rate=%d, inval=%d, mode=%d",
+		syslog (LOG_ERR, "\t%d) obj=%p, essid='%s', timestamp=%ld, key='%s', enc=%d, addr=%p, strength=%d, freq=%f, rate=%d, inval=%d, mode=%d",
 				i, ap, nm_ap_get_essid (ap), timestamp->tv_sec, nm_ap_get_enc_key_source (ap), nm_ap_get_encrypted (ap),
 				nm_ap_get_address (ap), nm_ap_get_strength (ap), nm_ap_get_freq (ap), nm_ap_get_rate (ap),
 				nm_ap_get_invalid (ap), nm_ap_get_mode (ap));
 		i++;
 	}
-	syslog (LOG_DEBUG, "AP_LIST_PRINT: done");
+	syslog (LOG_ERR, "AP_LIST_PRINT: done");
 	nm_ap_list_iter_free (iter);
 }
Index: src/NetworkManagerDevice.c
===================================================================
RCS file: /cvs/gnome/NetworkManager/src/NetworkManagerDevice.c,v
retrieving revision 1.84
diff -u -r1.84 NetworkManagerDevice.c
--- src/NetworkManagerDevice.c	21 Jan 2005 19:54:18 -0000	1.84
+++ src/NetworkManagerDevice.c	24 Jan 2005 19:11:51 -0000
@@ -396,6 +396,8 @@
 	dev->context = g_main_context_new ();
 	dev->loop = g_main_loop_new (dev->context, FALSE);
 
+syslog (LOG_ERR, "nm_device_worker() thread started\n");
+
 	/* Do an initial wireless scan */
 	if (nm_device_is_wireless (dev))
 	{
@@ -404,6 +406,7 @@
 
 		g_source_set_callback (source, nm_device_wireless_scan, dev, NULL);
 		source_id = g_source_attach (source, dev->context);
+syslog (LOG_ERR, "nm_device_worker() thread scheduled initial wireless scan (id = %d)\n", source_id);
 		g_source_unref (source);
 	}
 
@@ -428,6 +431,7 @@
 	dev->worker_done = TRUE;
 	nm_device_unref (dev);
 
+syslog (LOG_ERR, "nm_device_worker() thread ended\n");
 	return NULL;
 }
 
@@ -1736,6 +1740,7 @@
 	g_source_set_callback (source, nm_device_activate, dev, NULL);
 	g_source_attach (source, dev->context);
 	g_source_unref (source);
+syslog (LOG_ERR, "nm_device_activation_schedule_start() added idle function to device context.\n");
 
 	nm_dbus_signal_device_status_change (data->dbus_connection, dev, DEVICE_ACTIVATING);
 
@@ -3215,6 +3220,8 @@
 	wscan_source = g_timeout_source_new (dev->options.wireless.scan_interval * 1000);
 	g_source_set_callback (wscan_source, nm_device_wireless_scan, dev, NULL);
 	wscan_source_id = g_source_attach (wscan_source, dev->context);
+syslog (LOG_ERR, "nm_device_wireless_schedule_scan() scheduled wireless scan in %d seconds. (id = %d)", dev->options.wireless.scan_interval, wscan_source_id);
+
 	g_source_unref (wscan_source);
 }
 
@@ -3259,6 +3266,7 @@
 		return FALSE;
 	}
 
+syslog (LOG_ERR, "nm_device_wireless_process_scan_results() starting.");
 	/* Translate iwlib scan results to NM access point list */
 	tmp_ap = results->scan_head.result;
 	while (tmp_ap)
@@ -3391,6 +3399,7 @@
 		}
 		g_slist_free (outdated_list);
 	}
+nm_ap_list_print_members (nm_device_ap_list_get (dev), "Normalized Scan Results");
 
 	/* If the list changed, decrease our wireless scanning interval */
 	if (list_changed)
@@ -3398,6 +3407,7 @@
 	else
 		dev->options.wireless.scan_interval = MIN (60, dev->options.wireless.scan_interval + 10);
 
+syslog (LOG_ERR, "nm_device_wireless_process_scan_results() done, scan interval updated to %d seconds.", dev->options.wireless.scan_interval);
 	return FALSE;
 }
 
@@ -3437,6 +3447,7 @@
 			double			 orig_freq = 0;
 			int				 orig_rate = 0;
 
+syslog (LOG_ERR, "nm_device_wireless_scan() about to trigger scan.");
 			orig_mode = nm_device_get_mode (dev);
 			if (orig_mode == NETWORK_MODE_ADHOC)
 			{
@@ -3475,6 +3486,7 @@
 			}
 
 			close (sk);
+syslog (LOG_ERR, "nm_device_wireless_scan() scan triggered.");
 		}
 		nm_unlock_mutex (dev->options.wireless.scan_mutex, __FUNCTION__);
 	}
@@ -3492,6 +3504,7 @@
 		g_source_set_callback (scan_process_source, nm_device_wireless_process_scan_results, scan_results, NULL);
 		scan_process_source_id = g_source_attach (scan_process_source, dev->app_data->main_context);
 		g_source_unref (scan_process_source);
+syslog (LOG_ERR, "nm_device_wireless_scan() scheduled nm_device_wireless_process_scan_results() in main thread. (id = %d)", scan_process_source_id);
 	}
 
 	/* Make sure we reschedule ourselves so we keep scanning */
Index: src/NetworkManagerPolicy.c
===================================================================
RCS file: /cvs/gnome/NetworkManager/src/NetworkManagerPolicy.c,v
retrieving revision 1.35
diff -u -r1.35 NetworkManagerPolicy.c
--- src/NetworkManagerPolicy.c	21 Jan 2005 19:32:08 -0000	1.35
+++ src/NetworkManagerPolicy.c	24 Jan 2005 19:11:51 -0000
@@ -130,10 +130,8 @@
 		element = g_slist_next (element);
 	}
 
-#if 0
 	syslog (LOG_NOTICE, "AUTO: Best wired device = %s, best wireless device = %s (%s)", best_wired_dev ? nm_device_get_iface (best_wired_dev) : "(null)",
 			best_wireless_dev ? nm_device_get_iface (best_wireless_dev) : "(null)", best_wireless_dev ? nm_device_get_essid (best_wireless_dev) : "null" );
-#endif
 
 	if (best_wireless_dev || best_wired_dev)
 	{
@@ -236,6 +234,7 @@
 
 	g_return_val_if_fail (result != NULL, FALSE);
 
+syslog (LOG_ERR, "nm_policy_activation_finish() called.\n");
 	if (!(dev = result->dev))
 		goto out;
 
@@ -384,8 +383,10 @@
 				app_data->active_device = NULL;
 			}
 
+syslog (LOG_ERR, "nm_policy_state_update() about to switch device to %p (%s).\n", best_dev, best_dev ? nm_device_get_iface (best_dev) : "(NULL)");
 			if (best_dev)
 			{
+syslog (LOG_ERR, "nm_policy_state_update() switching device.\n");
 				/* Begin activation on the new device */
 				nm_device_ref (best_dev);
 				app_data->active_device = best_dev;
@@ -440,6 +441,8 @@
 
 	g_static_mutex_lock (&mutex);
 
+syslog (LOG_ERR, "nm_policy_schedule_device_switch() called.");
+
 	/* Don't queue the idle handler if switch_to_dev is NULL and there's already
 	 * an idle handler queued.  Always queue the idle handler if we were passed
 	 * a switch_to_dev.
@@ -455,7 +458,7 @@
 		g_source_set_callback (source, nm_policy_state_update, cb_data, NULL);
 		app_data->state_modified_idle_id = g_source_attach (source, app_data->main_context);
 		g_source_unref (source);
-
+syslog (LOG_ERR, "nm_policy_schedule_device_switch() actually scheduled state update (id = %d)  (switch_to_dev = %p).", app_data->state_modified_idle_id, switch_to_dev);
 	}
 
 	g_static_mutex_unlock (&mutex);