Re: Logging user actions, updated

[Federico Mena Quintero <federico ximian com>]

On Thu, 2006-11-23 at 15:00 +0100, Alexander Larsson wrote:

> I commited this to head (which is 2.17 now), as it seems useful. Has it
> worked out for you with debugging customer problems?

Sweet, thanks for committing it [I added nautilus-debug-log.[ch] which
were not on CVS, BTW].

So far, the logging has been useful for two things:

1. Figure out that something was weird in the views, which led me to
look at HEAD for your ref-the-file-list patches.

2. Figure out that we had a bunch of roundtrips to gnome-vfs-daemon.
But you had fixed this first, too!

So the general strategy is to add more logging code, and then wait for
Alex to preemptively fix the stuff which I was looking for.

> Some comments:
> What is "is_milestone" used for. It seems like we always ignore anything
> that doesn't set that.

I've started using it now.  The idea is that you don't want certain
things to be purged from the ring buffer:  logs from initialization
("did we discover the right drives/volumes?"), major errors (GLog
warnings and criticals), and other things which you really need to know
about.

The logging paper describes their use quite nicely:
http://visibleworkings.com/trace/Documentation/ring-buffer.pdf

Now, the debug log doesn't keep a separate buffer for the milestone
events.  I intend to add that quite soon.  It's just the caller code
that does use the is_milestone flag.

> +static void
> +sigusr1_handler (int sig)
> +{
> +	g_idle_add (dump_debug_log_idle_cb, NULL);
> +}
> 
> g_idle_add is not signal safe. It really should do the pipe-write trick.

Thanks.  I've committed a patch that does this; it's attached.

> Did you do any performance measurements on this? It seems like
> especially the async stuff can be costly, being called a lot. Also, the
> async stuff printing all changed/added/removed file will quickly fill
> out the ring buffer, throwing away important history. Maybe async
> logging shouldn't be enabled by default?

Ah, yes; logging that by default was a temporary state of the patch :)

The attached patch (on CVS now) lets you create a
~/nautilus-debug-log.conf (it's a GKeyFile) to configure what domains
get logged and the size of the ring buffer.  The default is to log only
"USER" messages now.

I haven't done performance measurements (shame on me!).  But since async
calls are not logged by default, it shouldn't matter for normal runs.

In any case, the logging API does let you avoid calling the logging
functions; you could check nautilus_debug_log_is_domain_enabled() before
generating expensive strings.

One thing I'd really like, but have no idea how to do it, is to dump the
bug-buddy stack traces directly in the debug log.  Right now asking
users to "please send me the stack trace, ~/nautilus-debug-log.txt and
~/.xsession-errors" is quite cumbersome :)

  Federico

? libnautilus-private/nautilus-debug-log.c
? libnautilus-private/nautilus-debug-log.h
Index: ChangeLog
===================================================================
RCS file: /cvs/gnome/nautilus/ChangeLog,v
retrieving revision 1.6976
diff -u -p -r1.6976 ChangeLog
--- ChangeLog	23 Nov 2006 15:18:44 -0000	1.6976
+++ ChangeLog	23 Nov 2006 16:20:33 -0000
@@ -1,3 +1,47 @@
+2006-11-23  Federico Mena Quintero  <federico novell com>
+
+	Use the write-to-a-pipe trick from the signal handler instead of
+	queueing an idle handler from there.
+
+	* src/nautilus-main.c (setup_debug_log_signals): Set up a pair of
+	pipes for the SIGUSR1 handler; set up a GIOChannel on them.
+	(sigusr1_handler): Write a byte to our pipe instead of queueing an
+	idle handler.
+	(debug_log_io_cb): Replaces dump_debug_log_idle_cb().  Read from
+	the pipe, and dump the debug log.
+
+	Add a configuration file for the logging mechanism.  You create
+	~/nautilus-debug-log.conf as a GKeyFile.
+
+	* libnautilus-private/nautilus-debug-log.c
+	(nautilus_debug_log_load_configuration): New function; loads the
+	configuration from a key file like this:
+
+		[debug log]
+		enable domains = foo; bar; baz
+		max lines = 1000
+
+	* libnautilus-private/nautilus-debug-log.c (dump_configuration):
+	New utility function.
+	(nautilus_debug_log_dump): At the end of the log, dump the
+	configuration used for the debug log so that the user can
+	re-create it later.
+
+	* libnautilus-private/nautilus-debug-log.h: New prototype for
+	nautilus_debug_log_load_configuration().
+
+	* src/nautilus-main.c (setup_debug_log): Load the debug log's
+	configuration from ~/nautilus-debug-log.conf
+	(setup_debug_log_domains): Removed.
+
+	* src/nautilus-main.c (log_override_cb): If the log level of the
+	message is G_LOG_LEVEL_DEBUG, don't log it as a milestone.  We'll
+	use this log level for miscellaneous debugging messages from
+	gnome-vfs.  Also, don't send G_LOG_LEVEL_DEBUG messages to the
+	default log handler, to avoid a huge ~/.xsession-errors.
+	(setup_debug_log_domains): Enable logging for 
+	NAUTILUS_DEBUG_LOG_DOMAIN_GLOG.
+
 2006-11-23  Christian Persch  <chpe cvs gnome org>
 
 	* src/nautilus-search-bar.c: (nautilus_search_bar_init):
Index: src/nautilus-main.c
===================================================================
RCS file: /cvs/gnome/nautilus/src/nautilus-main.c,v
retrieving revision 1.163
diff -u -p -r1.163 nautilus-main.c
--- src/nautilus-main.c	23 Nov 2006 13:56:54 -0000	1.163
+++ src/nautilus-main.c	23 Nov 2006 16:20:33 -0000
@@ -210,9 +210,16 @@ dump_debug_log (void)
 	g_free (filename);
 }
 
+static int debug_log_pipes[2];
+
 static gboolean
-dump_debug_log_idle_cb (gpointer data)
+debug_log_io_cb (GIOChannel *io, GIOCondition condition, gpointer data)
 {
+	char a;
+
+	while (read (debug_log_pipes[0], &a, 1) != 1)
+		;
+
 	nautilus_debug_log (TRUE, NAUTILUS_DEBUG_LOG_DOMAIN_USER,
 			    "user requested dump of debug log");
 
@@ -230,7 +237,8 @@ static struct sigaction old_bus_sa;
 static void
 sigusr1_handler (int sig)
 {
-	g_idle_add (dump_debug_log_idle_cb, NULL);
+	while (write (debug_log_pipes[1], "a", 1) != 1)
+		;
 }
 
 static void
@@ -280,6 +288,13 @@ static void
 setup_debug_log_signals (void)
 {
 	struct sigaction sa;
+	GIOChannel *io;
+
+	if (pipe (debug_log_pipes) == -1)
+		g_error ("Could not create pipe() for debug log");
+
+	io = g_io_channel_unix_new (debug_log_pipes[0]);
+	g_io_add_watch (io, G_IO_IN, debug_log_io_cb, NULL);
 
 	sa.sa_handler = sigusr1_handler;
 	sigemptyset (&sa.sa_mask);
@@ -297,16 +312,6 @@ setup_debug_log_signals (void)
 	sigaction(SIGBUS,  &sa, &old_bus_sa);
 }
 
-static void
-setup_debug_log_domains (void)
-{
-	const char *domains[] = {
-		NAUTILUS_DEBUG_LOG_DOMAIN_ASYNC
-	};
-
-	nautilus_debug_log_enable_domains (domains, G_N_ELEMENTS (domains));
-}
-
 static GLogFunc default_log_handler;
 
 static void
@@ -315,9 +320,16 @@ log_override_cb (const gchar   *log_doma
 		 const gchar   *message,
 		 gpointer       user_data)
 {
-	nautilus_debug_log (TRUE, NAUTILUS_DEBUG_LOG_DOMAIN_GLOG, "%s", message);
+	gboolean is_debug;
+	gboolean is_milestone;
+
+	is_debug = ((log_level & G_LOG_LEVEL_DEBUG) != 0);
+	is_milestone = !is_debug;
 
-	(* default_log_handler) (log_domain, log_level, message, user_data);
+	nautilus_debug_log (is_milestone, NAUTILUS_DEBUG_LOG_DOMAIN_GLOG, "%s", message);
+
+	if (!is_debug)
+		(* default_log_handler) (log_domain, log_level, message, user_data);
 }
 
 static void
@@ -329,7 +341,12 @@ setup_debug_log_glog (void)
 static void
 setup_debug_log (void)
 {
-	setup_debug_log_domains ();
+	char *config_filename;
+
+	config_filename = g_build_filename (g_get_home_dir (), "nautilus-debug-log.conf", NULL);
+	nautilus_debug_log_load_configuration (config_filename, NULL); /* NULL GError */
+	g_free (config_filename);
+
 	setup_debug_log_signals ();
 	setup_debug_log_glog ();
 }