GNOME.org
 

[libgnome-keyring/gnome-3-0] Add debugging instrumentation to operations.

commit 32a9851e9dac9f1c1302d9c838512a59d1328ee3
Author: Stef Walter <stefw collabora co uk>
Date:   Thu Mar 31 22:59:51 2011 +0200

    Add debugging instrumentation to operations.
    
     * Run with GKR_DEBUG=all environment variable to display debubugging.
     * Only gkr-operation.c has debugging for now.

 configure.in                    |    2 +-
 library/Makefile.am             |    2 +
 library/gkr-debug.c             |  106 +++++++++++++++++++++++++++++++++++++++
 library/gkr-debug.h             |   85 +++++++++++++++++++++++++++++++
 library/gkr-operation.c         |   56 +++++++++++++++++---
 library/tests/test-any-daemon.c |    1 +
 library/tests/test-keyrings.c   |    1 +
 library/tests/test-memory.c     |    1 +
 library/tests/test-other.c      |    1 +
 library/tests/test-prompting.c  |    1 +
 10 files changed, 246 insertions(+), 10 deletions(-)
---
diff --git a/configure.in b/configure.in
index ce7d1b6..c5aaaee 100644
--- a/configure.in
+++ b/configure.in
@@ -140,7 +140,7 @@ if test "$enable_debug" = "yes"; then
 	CFLAGS="$CFLAGS -g -O0 -Wall"
 	CFLAGS="$CFLAGS -DG_DISABLE_DEPRECATED -DGDK_PIXBUF_DISABLE_DEPRECATED"
 	CFLAGS="$CFLAGS -DGDK_DISABLE_DEPRECATED -DGTK_DISABLE_DEPRECATED"
-	AC_DEFINE_UNQUOTED(_DEBUG, 1, [In debug mode])
+	AC_DEFINE_UNQUOTED(WITH_DEBUG, 1, [In debug mode])
 	echo "enabling debug compile mode"
 	debug_status="yes"
 else
diff --git a/library/Makefile.am b/library/Makefile.am
index 7575601..7d91abd 100644
--- a/library/Makefile.am
+++ b/library/Makefile.am
@@ -7,6 +7,7 @@ INCLUDES= \
 	-DBINDIR=\""$(bindir)"\" \
 	-DLIBEXECDIR=\""$(libexecdir)"\" \
 	-DGNOMELOCALEDIR=\""$(datadir)/locale"\" \
+	-DG_LOG_DOMAIN=\""Gkr"\" \
 	-I$(top_srcdir) \
 	-I$(top_builddir) \
 	$(LIBRARY_CFLAGS) \
@@ -14,6 +15,7 @@ INCLUDES= \
 
 libgnome_keyring_la_SOURCES = \
 	gkr-callback.c gkr-callback.h \
+	gkr-debug.c gkr-debug.h \
 	gkr-misc.c gkr-misc.h \
 	gkr-operation.c gkr-operation.h \
 	gkr-session.c gkr-session.h \
diff --git a/library/gkr-debug.c b/library/gkr-debug.c
new file mode 100644
index 0000000..e43ad24
--- /dev/null
+++ b/library/gkr-debug.c
@@ -0,0 +1,106 @@
+/* -*- Mode: C; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2; -*- */
+/*
+ * Copyright (C) 2007 Collabora Ltd.
+ * Copyright (C) 2007 Nokia Corporation
+ *
+ * This library is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 2.1 of the License, or (at your option) any later version.
+ *
+ * This library is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with this library; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
+ */
+
+#include "config.h"
+
+#include "gkr-debug.h"
+
+#include <errno.h>
+#include <fcntl.h>
+#include <stdarg.h>
+#include <sys/stat.h>
+#include <unistd.h>
+
+#include <glib.h>
+#include <glib/gstdio.h>
+
+#ifdef WITH_DEBUG
+
+static GkrDebugFlags current_flags = 0;
+
+static GDebugKey keys[] = {
+	{ "operation", GKR_DEBUG_OPERATION },
+	{ 0, }
+};
+
+static void
+debug_set_flags (GkrDebugFlags new_flags)
+{
+	current_flags |= new_flags;
+}
+
+void
+gkr_debug_set_flags (const gchar *flags_string)
+{
+	guint nkeys;
+
+	for (nkeys = 0; keys[nkeys].value; nkeys++);
+
+	if (flags_string)
+		debug_set_flags (g_parse_debug_string (flags_string, keys, nkeys));
+}
+
+gboolean
+gkr_debug_flag_is_set (GkrDebugFlags flag)
+{
+	return (flag & current_flags) != 0;
+}
+
+void
+gkr_debug_message (GkrDebugFlags flag, const gchar *format, ...)
+{
+	static gsize initialized_flags = 0;
+	gchar *message;
+	va_list args;
+
+	if (g_once_init_enter (&initialized_flags)) {
+		gkr_debug_set_flags (g_getenv ("GKR_DEBUG"));
+		g_once_init_leave (&initialized_flags, 1);
+	}
+
+	va_start (args, format);
+	message = g_strdup_vprintf (format, args);
+	va_end (args);
+
+	if (flag & current_flags)
+		g_log (G_LOG_DOMAIN, G_LOG_LEVEL_DEBUG, "%s", message);
+
+	g_free (message);
+}
+
+#else /* !WITH_DEBUG */
+
+gboolean
+gkr_debug_flag_is_set (GkrDebugFlags flag)
+{
+	return FALSE;
+}
+
+void
+gkr_debug_message (GkrDebugFlags flag, const gchar *format, ...)
+{
+}
+
+void
+gkr_debug_set_flags (const gchar *flags_string)
+{
+}
+
+#endif /* !WITH_DEBUG */
diff --git a/library/gkr-debug.h b/library/gkr-debug.h
new file mode 100644
index 0000000..757b5cb
--- /dev/null
+++ b/library/gkr-debug.h
@@ -0,0 +1,85 @@
+/*
+ * Copyright (C) 2007 Nokia Corporation
+ * Copyright (C) 2007-2011 Collabora Ltd.
+ *
+ * This library is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 2.1 of the License, or (at your option) any later version.
+ *
+ * This library is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with this library; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
+ */
+
+#ifndef GKR_DEBUG_H
+#define GKR_DEBUG_H
+
+#include "config.h"
+
+#include <glib.h>
+
+G_BEGIN_DECLS
+
+/* Please keep this enum in sync with #keys in gkr-debug.c */
+typedef enum {
+	GKR_DEBUG_OPERATION = 1 << 1,
+} GkrDebugFlags;
+
+gboolean           gkr_debug_flag_is_set               (GkrDebugFlags flag);
+
+void               gkr_debug_set_flags                 (const gchar *flags_string);
+
+void               gkr_debug_message                   (GkrDebugFlags flag,
+                                                        const gchar *format,
+                                                        ...) G_GNUC_PRINTF (2, 3);
+
+G_END_DECLS
+
+#endif /* GKR_DEBUG_H */
+
+/* -----------------------------------------------------------------------------
+ * Below this point is outside the GKR_DEBUG_H guard - so it can take effect
+ * more than once. So you can do:
+ *
+ * #define DEBUG_FLAG GKR_DEBUG_ONE_THING
+ * #include "gkr-debug.h"
+ * ...
+ * DEBUG ("if we're debugging one thing");
+ * ...
+ * #undef DEBUG_FLAG
+ * #define DEBUG_FLAG GKR_DEBUG_OTHER_THING
+ * #include "gkr-debug.h"
+ * ...
+ * DEBUG ("if we're debugging the other thing");
+ * ...
+ */
+
+#ifdef DEBUG_FLAG
+#ifdef WITH_DEBUG
+
+#undef gkr_debug
+#define gkr_debug(format, ...) \
+	gkr_debug_message (DEBUG_FLAG, "%s: " format, G_STRFUNC, ##__VA_ARGS__)
+
+#undef gkr_debugging
+#define gkr_debugging \
+	gkr_debug_flag_is_set (DEBUG_FLAG)
+
+#else /* !defined (WITH_DEBUG) */
+
+#undef gkr_debug
+#define gkr_debug(format, ...) \
+	do {} while (0)
+
+#undef gkr_debugging
+#define gkr_debugging 0
+
+#endif /* !defined (WITH_DEBUG) */
+
+#endif /* defined (DEBUG_FLAG) */
diff --git a/library/gkr-operation.c b/library/gkr-operation.c
index 0fbba4d..92106e9 100644
--- a/library/gkr-operation.c
+++ b/library/gkr-operation.c
@@ -25,9 +25,12 @@
 
 #include "config.h"
 
+#define DEBUG_FLAG GKR_DEBUG_OPERATION
+#include "gkr-debug.h"
 #include "gkr-misc.h"
 #include "gkr-operation.h"
 #include "gkr-session.h"
+
 #include "gnome-keyring.h"
 #include "gnome-keyring-private.h"
 
@@ -68,7 +71,10 @@ static void
 operation_clear_callbacks (GkrOperation *op)
 {
 	GSList *l;
+
 	g_assert (op);
+	gkr_debug ("%p", op);
+
 	while (!g_queue_is_empty (&op->callbacks))
 		gkr_callback_free (g_queue_pop_head (&op->callbacks));
 	g_queue_clear (&op->callbacks);
@@ -88,6 +94,7 @@ operation_unref (gpointer data)
 		return FALSE;
 
 	if (op->pending) {
+		gkr_debug ("%p: cancelling: %p", op, op->pending);
 		dbus_pending_call_cancel (op->pending);
 		dbus_pending_call_unref (op->pending);
 		op->pending = NULL;
@@ -95,6 +102,8 @@ operation_unref (gpointer data)
 
 	operation_clear_callbacks (op);
 
+	gkr_debug ("%p: freeing", op);
+
 	if (op->conn) {
 		dbus_connection_unref (op->conn);
 		op->conn = NULL;
@@ -120,7 +129,7 @@ gkr_operation_pending_and_unref (GkrOperation *op)
 		return op;
 
 	/* Not sure what to do here, but at least we can print a message */
-	g_message ("an libgnome-keyring operation completed unsafely before "
+	g_message ("a libgnome-keyring operation completed unsafely before "
 	           "the function starting the operation returned.");
 	return NULL;
 }
@@ -140,6 +149,7 @@ gkr_operation_new (gpointer callback, GkrCallbackType callback_type,
 	GkrOperation *op;
 
 	op = g_slice_new0 (GkrOperation);
+	gkr_debug ("%p", op);
 
 	op->refs = 1;
 	op->result = INCOMPLETE;
@@ -201,6 +211,8 @@ on_complete (GkrOperation *op)
 	cb = g_queue_pop_tail (&op->callbacks);
 	g_assert (cb);
 
+	gkr_debug ("%p", op);
+
 	/* Free all the other callbacks */
 	operation_clear_callbacks (op);
 
@@ -232,9 +244,11 @@ void
 gkr_operation_complete_later (GkrOperation *op, GnomeKeyringResult res)
 {
 	g_return_if_fail (op);
-	if (gkr_operation_set_result (op, res))
+	if (gkr_operation_set_result (op, res)) {
+		gkr_debug ("%p", op);
 		g_idle_add_full (G_PRIORITY_DEFAULT_IDLE, on_complete_later,
 		                 gkr_operation_ref (op), gkr_operation_unref);
+	}
 }
 
 static DBusHandlerResult
@@ -255,6 +269,7 @@ on_name_changed_filter (DBusConnection *connection, DBusMessage *message, void *
 		    new_owner && g_str_equal ("", new_owner)) {
 
 			/* Clear any session, when the service goes away */
+			gkr_debug ("secret service went away");
 			gkr_session_clear ();
 		}
 
@@ -277,8 +292,10 @@ connect_to_service (void)
 	 */
 
 	if (!dbus_connection) {
-		if (!g_getenv ("DBUS_SESSION_BUS_ADDRESS"))
+		if (!g_getenv ("DBUS_SESSION_BUS_ADDRESS")) {
+			gkr_debug ("no DBUS_SESSION_BUS_ADDRESS var set");
 			return NULL;
+		}
 
 		conn = dbus_bus_get_private (DBUS_BUS_SESSION, &derr);
 		if (conn == NULL) {
@@ -302,9 +319,11 @@ connect_to_service (void)
 		{
 			if (dbus_connection) {
 				dbus_connection_unref (conn);
+				gkr_debug ("race. already have a dbus connection");
 			} else {
 				egg_dbus_connect_with_mainloop (conn, NULL);
 				dbus_connection = conn;
+				gkr_debug ("created and initialized dbus connection");
 			}
 		}
 		G_UNLOCK (dbus_connection);
@@ -339,6 +358,7 @@ on_pending_call_notify (DBusPendingCall *pending, void *user_data)
 	GkrOperation *op = user_data;
 	DBusMessage *reply;
 
+	gkr_debug ("%p: notified: %p", op, pending);
 	g_assert (pending == op->pending);
 
 	reply = dbus_pending_call_steal_reply (pending);
@@ -372,6 +392,7 @@ gkr_operation_request (GkrOperation *op, DBusMessage *req)
 
 	if (op->conn) {
 		g_assert (!op->pending);
+		gkr_debug ("%p: sending request", op);
 		if (!dbus_connection_send_with_reply (op->conn, req, &op->pending, timeout))
 			g_return_if_reached ();
 	}
@@ -379,6 +400,7 @@ gkr_operation_request (GkrOperation *op, DBusMessage *req)
 	if (op->pending) {
 		if (gkr_decode_is_keyring (dbus_message_get_path (req)))
 			gkr_operation_set_keyring_hint (op);
+		gkr_debug ("%p: has pending: %p", op, op->pending);
 		dbus_pending_call_set_notify (op->pending, on_pending_call_notify,
 		                              gkr_operation_ref (op), gkr_operation_unref);
 	} else {
@@ -394,19 +416,24 @@ gkr_operation_block_and_unref (GkrOperation *op)
 
 	while ((int) gkr_operation_get_result (op) == INCOMPLETE) {
 		if (op->pending) {
+			pending = op->pending;
+			gkr_debug ("%p: blocking on pending: %p", op, pending);
+			dbus_pending_call_block (pending);
+
 			/*
 			 * DBus has strange behavior that can complete a pending call
 			 * in another thread and somehow does this without calling our
 			 * on_pending_call_notify. So guard against this brokenness.
 			 */
-			pending = op->pending;
-			dbus_pending_call_block (pending);
 			if (op->pending == pending) {
 				g_return_val_if_fail (dbus_pending_call_get_completed (pending), BROKEN);
+				gkr_debug ("%p: trying to rescue broken dbus threading behavior: %p", op, pending);
 				on_pending_call_notify (pending, op);
 			}
+
 		} else if (op->prompting) {
 			dbus_connection_flush (op->conn);
+			gkr_debug ("%p: blocking on prompt", op);
 			while (op->prompting && (int) gkr_operation_get_result (op) == INCOMPLETE) {
 				if (!dbus_connection_read_write_dispatch (op->conn, 200))
 					break;
@@ -444,6 +471,7 @@ gkr_operation_handle_errors (GkrOperation *op, DBusMessage *reply)
 
 	if (dbus_set_error_from_message (&derr, reply)) {
 		if (dbus_error_has_name (&derr, ERROR_NO_SUCH_OBJECT)) {
+			gkr_debug ("%p: no-such-object", op);
 			if (was_keyring)
 				res = GNOME_KEYRING_RESULT_NO_SUCH_KEYRING;
 			else
@@ -470,7 +498,10 @@ static void
 on_prompt_completed (void *user_data)
 {
 	on_prompt_args *args = user_data;
+
 	g_return_if_fail (args->op->prompting);
+	gkr_debug ("%p", args->op);
+
 	gkr_operation_unref (args->op);
 	args->op->prompting = FALSE;
 }
@@ -488,8 +519,10 @@ on_prompt_signal (DBusConnection *connection, DBusMessage *message, void *user_d
 
 	g_assert (args);
 
-	if (!args->path || !args->op->prompting)
+	if (!args->path || !args->op->prompting) {
+		gkr_debug ("%p: received prompt signal while not prompting", args->op);
 		return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
+	}
 
 	/* org.freedesktop.Secret.Prompt.Completed(BOOLEAN dismissed, VARIANT result) */
 	if (dbus_message_has_path (message, args->path) &&
@@ -506,10 +539,13 @@ on_prompt_signal (DBusConnection *connection, DBusMessage *message, void *user_d
 
 		op = gkr_operation_ref (args->op);
 
-		if (dismissed)
+		if (dismissed) {
+			gkr_debug ("%p: prompt was dismissed", op);
 			gkr_operation_complete (op, GNOME_KEYRING_RESULT_CANCELLED);
-		else
+		} else {
+			gkr_debug ("%p: prompt was completed", op);
 			callback_with_message (op, message);
+		}
 
 		if (op->prompting)
 			dbus_connection_remove_filter (args->op->conn, on_prompt_signal, args);
@@ -528,7 +564,7 @@ on_prompt_signal (DBusConnection *connection, DBusMessage *message, void *user_d
 		if (object_name && g_str_equal (gkr_service_name (), object_name) &&
 		    new_owner && g_str_equal ("", new_owner)) {
 
-			g_message ("Secret service disappeared while waiting for prompt");
+			g_message ("secret service disappeared while waiting for prompt");
 			op = gkr_operation_ref (args->op);
 			gkr_operation_complete (op, GNOME_KEYRING_RESULT_IO_ERROR);
 			if (op->prompting)
@@ -591,6 +627,8 @@ gkr_operation_prompt (GkrOperation *op, const gchar *prompt)
 	window_id = "";
 	dbus_message_append_args (req, DBUS_TYPE_STRING, &window_id, DBUS_TYPE_INVALID);
 
+	gkr_debug ("%p: calling prompt method", op);
+
 	gkr_operation_push (op, on_prompt_result, GKR_CALLBACK_OP_MSG, args, on_prompt_free);
 	gkr_operation_request (op, req);
 	dbus_message_unref (req);
diff --git a/library/tests/test-any-daemon.c b/library/tests/test-any-daemon.c
index 5561fc0..db40e1f 100644
--- a/library/tests/test-any-daemon.c
+++ b/library/tests/test-any-daemon.c
@@ -67,6 +67,7 @@ int
 main (int argc, char **argv)
 {
 	g_test_init (&argc, &argv, NULL);
+	g_set_prgname ("test-any-daemon");
 
 	if (!gnome_keyring_is_available ()) {
 		g_printerr ("skipping any-daemon tests, no daemon is running");
diff --git a/library/tests/test-keyrings.c b/library/tests/test-keyrings.c
index 324ea11..dadf76d 100644
--- a/library/tests/test-keyrings.c
+++ b/library/tests/test-keyrings.c
@@ -722,6 +722,7 @@ main (int argc, char **argv)
 	int ret = 0;
 
 	g_test_init (&argc, &argv, NULL);
+	g_set_prgname ("test-keyrings");
 
 	mainloop = g_main_loop_new (NULL, FALSE);
 
diff --git a/library/tests/test-memory.c b/library/tests/test-memory.c
index 2b12f41..f977ebf 100644
--- a/library/tests/test-memory.c
+++ b/library/tests/test-memory.c
@@ -137,6 +137,7 @@ int
 main (int argc, char **argv)
 {
 	g_test_init (&argc, &argv, NULL);
+	g_set_prgname ("test-memory");
 
 	g_test_add_func ("/memory/alloc-free", test_alloc_free);
 	g_test_add_func ("/memory/alloc-two", test_alloc_two);
diff --git a/library/tests/test-other.c b/library/tests/test-other.c
index f95bcd3..b0844fc 100644
--- a/library/tests/test-other.c
+++ b/library/tests/test-other.c
@@ -73,6 +73,7 @@ int
 main (int argc, char **argv)
 {
 	g_test_init (&argc, &argv, NULL);
+	g_set_prgname ("test-other");
 
 	g_test_add_func ("/other/result-string", test_result_string);
 
diff --git a/library/tests/test-prompting.c b/library/tests/test-prompting.c
index a98862b..9089a8a 100644
--- a/library/tests/test-prompting.c
+++ b/library/tests/test-prompting.c
@@ -50,6 +50,7 @@ int
 main (int argc, char *argv[])
 {
 	g_setenv ("GNOME_KEYRING_TEST_SERVICE", "org.gnome.keyring.Test", TRUE);
+	g_set_prgname ("test-prompting");
 
 	if (argc == 2) {
 		if (g_str_equal (argv[1], "--create-item")) {
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]