Expand usage of xfsm_verbose for debugging

This patch:
1) Documents the XFSM_VERBOSE environment variable in the
   man page.
2) Changes xfsm_verbose's output from a timestamp to the usual func,
   file, line, message format used in other Xfce programs.
3) Uses xfsm_verbose in more places to help aid in debugging.
4) Saves the last xfsm run in a .last extension, so there's always
   the current session log and the last one to compare to.

7 files changed, 154 insertions, 36 deletions

diff --git a/xfce4-session/sm-layer.c b/xfce4-session/sm-layer.c
index 313172fe..54285693 100644
--- a/xfce4-session/sm-layer.c
+++ b/xfce4-session/sm-layer.c
@@ -114,13 +114,11 @@ sm_init (XfconfChannel *channel,
 #ifdef HAVE__ICETRANSNOLISTEN
       _IceTransNoListen ("tcp");
 #else
-      if (G_UNLIKELY (verbose))
-        {
-          fprintf (stderr,
-                   "xfce4-session: Requested to disable tcp connections, but "
-                   "_IceTransNoListen is not available on this plattform. "
-                   "Request will be ignored.\n");
-        }
+      fprintf (stderr,
+               "xfce4-session: Requested to disable tcp connections, but "
+               "_IceTransNoListen is not available on this plattform. "
+               "Request will be ignored.\n");
+      xfsm_verbose ("_IceTransNoListen unavailable on this platform");
 #endif
     }
 
@@ -128,12 +126,16 @@ sm_init (XfconfChannel *channel,
                       2048, error))
     {
       fprintf (stderr, "xfce4-session: Unable to register XSM protocol: %s\n", error);
+      /* log to verbose so we don't have to look at both files */
+      xfsm_verbose ("xfce4-session: Unable to register XSM protocol: %s\n", error);
       exit (EXIT_FAILURE);
     }
 
   if (!IceListenForConnections (&num_listeners, &listen_objs, 2048, error))
     {
       fprintf (stderr, "xfce4-session: Unable to establish ICE listeners: %s\n", error);
+      /* log to verbose so we don't have to look at both files */
+      xfsm_verbose ("xfce4-session: Unable to establish ICE listeners: %s\n", error);
       exit (EXIT_FAILURE);
     }
 
diff --git a/xfce4-session/xfce4-session.1 b/xfce4-session/xfce4-session.1
index 2892bf8a..47cc1351 100644
--- a/xfce4-session/xfce4-session.1
+++ b/xfce4-session/xfce4-session.1
@@ -1,4 +1,4 @@
-.TH xfce4-session 1 "Nov 01, 2004"
+.TH xfce4-session 1 "Sep 28, 2014"
 .SH NAME
 xfce4-session \- Starts up the Xfce Desktop Environment
 .SH SYNOPSIS
@@ -56,6 +56,15 @@ base directory. The directories should be separated with a colon.
 Specifies the root for all user-specific cache data. If this environment
 variable is unset, it defaults to
 .I ~/.cache/
+.TP
+.B XFSM_VERBOSE
+When defined, this environment variable enables debugging messages to be
+saved to
+.I ~/.xfce4-session.verbose-log
+The log file from the last session run with this environment variable
+set is retained at
+.I ~/.xfce4-session.verbose-log.last
+These debugging messages are useful for troubleshooting and development.
 
 .SH FILES
 \fBxfce4-session\fP reads its configuration from Xfconf.
@@ -72,4 +81,4 @@ and Benedikt Meurer <benny@xfce.org>.
 Report bugs to http://bugzilla.xfce.org/.
 
 .SH COPYRIGHT
-Copyright \(co 2003-2004 Benedikt Meurer.
+Copyright \(co 2003-2014 Benedikt Meurer.
diff --git a/xfce4-session/xfsm-global.c b/xfce4-session/xfsm-global.c
index 05f8d80a..6368a9a7 100644
--- a/xfce4-session/xfsm-global.c
+++ b/xfce4-session/xfsm-global.c
@@ -73,25 +73,44 @@ xfsm_enable_verbose (void)
     }
 }
 
+gboolean
+xfsm_is_verbose_enabled (void)
+{
+  return verbose;
+}
 
 void
-xfsm_verbose_real (const gchar *format, ...)
+xfsm_verbose_real (const char *func,
+                   const char *file,
+                   int line,
+                   const char *format,
+                   ...)
 {
   static FILE *fp = NULL;
   gchar       *logfile;
   va_list      valist;
-  GTimeVal     tv;
 
   if (G_UNLIKELY (fp == NULL))
     {
       logfile = xfce_get_homefile (".xfce4-session.verbose-log", NULL);
+
+      /* rename an existing log file to -log.last */
+      if (logfile && g_file_test (logfile, G_FILE_TEST_EXISTS))
+        {
+          gchar *oldlogfile = g_strdup_printf ("%s.last", logfile);
+          if (oldlogfile)
+            {
+              rename (logfile, oldlogfile);
+              g_free (oldlogfile);
+            }
+        }
+
       fp = fopen (logfile, "w");
       g_free (logfile);
+      fprintf(fp, "log file opened\n");
     }
 
-  g_get_current_time(&tv);
-  fprintf(fp, "[%10lu] ", tv.tv_sec);
-
+  fprintf (fp, "TRACE[%s:%d] %s(): ", file, line, func);
   va_start (valist, format);
   vfprintf (fp, format, valist);
   fflush (fp);
diff --git a/xfce4-session/xfsm-global.h b/xfce4-session/xfsm-global.h
index 273361fe..d2e0c294 100644
--- a/xfce4-session/xfsm-global.h
+++ b/xfce4-session/xfsm-global.h
@@ -48,24 +48,22 @@ extern XfsmSplashScreen *splash_screen;
 
 #if defined(G_HAVE_ISO_VARARGS)
 
-#define xfsm_verbose(...)             \
-G_STMT_START{                         \
-  if (G_UNLIKELY (verbose))           \
-    xfsm_verbose_real (__VA_ARGS__);  \
-}G_STMT_END
+#define xfsm_verbose(...)\
+    xfsm_verbose_real (__func__, __FILE__, __LINE__, __VA_ARGS__)
 
-#elif defined(G_HAVE_GNUC_VARARGS)
+#else
 
-#define xfsm_verbose(format, ...)     \
-G_STMT_START{                         \
-  if (G_UNLIKELY (verbose))           \
-    xfsm_verbose_real ( ## format);   \
-}G_STMT_END
+#define xfsm_verbose(...)
 
 #endif
 
 void xfsm_enable_verbose (void);
-void xfsm_verbose_real (const gchar *format, ...) G_GNUC_PRINTF (1, 2);
+gboolean xfsm_is_verbose_enabled (void);
+void xfsm_verbose_real (const char *func,
+                        const char *file,
+                        int line,
+                        const char *format,
+                        ...) G_GNUC_PRINTF (4, 5);
 
 gchar *xfsm_generate_client_id (SmsConn sms_conn) G_GNUC_PURE;
 
diff --git a/xfce4-session/xfsm-legacy.c b/xfce4-session/xfsm-legacy.c
index 88c3ee06..932aeaf4 100644
--- a/xfce4-session/xfsm-legacy.c
+++ b/xfce4-session/xfsm-legacy.c
@@ -74,6 +74,7 @@
 
 #include <libwnck/libwnck.h>
 
+#include <xfce4-session/xfsm-global.h>
 #include <xfce4-session/xfsm-legacy.h>
 #include <libxfsm/xfsm-util.h>
 
@@ -344,7 +345,10 @@ xfsm_legacy_perform_session_save (void)
           leader = get_clientleader (window);
           if (leader == None || sm_window_list_contains (leader)
               || has_xsmp_support (window) || has_xsmp_support (leader))
-            continue;
+            {
+              xfsm_verbose ("window has no client leader or supports xspm, skipping\n");
+              continue;
+            }
 
           type = SM_WMCOMMAND;
           wmclass1 = NULL;
@@ -513,6 +517,16 @@ xfsm_legacy_store_session (XfceRc *rc)
               || sm_window->wm_client_machine == NULL)
             continue;
 
+          if (xfsm_is_verbose_enabled ())
+            {
+              gchar *command = g_strjoinv (" ", sm_window->wm_command);
+              xfsm_verbose ("saving screen %d, command %s, machine %s\n",
+                            sm_window->screen_num,
+                            command,
+                            sm_window->wm_client_machine);
+              g_free (command);
+            }
+
           g_snprintf (buffer, 256, "Legacy%d_Screen", count);
           xfce_rc_write_int_entry (rc, buffer, sm_window->screen_num);
 
@@ -551,7 +565,16 @@ xfsm_legacy_load_session (XfceRc *rc)
       g_snprintf (buffer, 256, "Legacy%d_Command", i);
       command = xfce_rc_read_list_entry (rc, buffer, NULL);
       if (command == NULL)
-        continue;
+        {
+          xfsm_verbose ("legacy command == NULL\n");
+          continue;
+        }
+      else if (xfsm_is_verbose_enabled ())
+        {
+          gchar *dbg_command = g_strjoinv (" ", command);
+          xfsm_verbose ("legacy command %s\n", dbg_command);
+          g_free (dbg_command);
+        }
 
       app = g_new0 (SmRestartApp, 1);
       app->screen_num = screen_num;
diff --git a/xfce4-session/xfsm-manager.c b/xfce4-session/xfsm-manager.c
index 35811c56..dc2960e7 100644
--- a/xfce4-session/xfsm-manager.c
+++ b/xfce4-session/xfsm-manager.c
@@ -294,6 +294,14 @@ xfsm_manager_set_state (XfsmManager     *manager,
   old_state = manager->state;
   manager->state = state;
 
+  xfsm_verbose ("\nstate is now %s\n",
+                state == XFSM_MANAGER_STARTUP ? "XFSM_MANAGER_STARTUP" :
+                state == XFSM_MANAGER_IDLE ?  "XFSM_MANAGER_IDLE" :
+                state == XFSM_MANAGER_CHECKPOINT ? "XFSM_MANAGER_CHECKPOINT" :
+                state == XFSM_MANAGER_SHUTDOWN ? "XFSM_MANAGER_SHUTDOWN" :
+                state == XFSM_MANAGER_SHUTDOWNPHASE2 ? "XFSM_MANAGER_SHUTDOWNPHASE2" :
+                "unknown");
+
   g_signal_emit (manager, signals[SIG_STATE_CHANGED], 0, old_state, state);
 }
 
@@ -333,8 +341,13 @@ xfsm_manager_restore_active_workspace (XfsmManager *manager,
   for (n = 0; n < gdk_display_get_n_screens (display); ++n)
     {
       g_snprintf (buffer, 1024, "Screen%d_ActiveWorkspace", n);
+      xfsm_verbose ("Attempting to restore %s\n", buffer);
       if (!xfce_rc_has_entry (rc, buffer))
-        continue;
+        {
+          xfsm_verbose ("no entry found\n");
+          continue;
+        }
+
       m = xfce_rc_read_int_entry (rc, buffer, 0);
 
       screen = wnck_screen_get (n);
@@ -372,6 +385,7 @@ xfsm_manager_handle_failed_properties (XfsmManager    *manager,
 
   if (restart_style_hint == SmRestartAnyway)
     {
+      xfsm_verbose ("Client id %s died or failed to start, restarting anyway\n", properties->client_id);
       g_queue_push_tail (manager->restart_properties, properties);
     }
   else if (restart_style_hint == SmRestartImmediately)
@@ -545,19 +559,27 @@ xfsm_manager_load_session (XfsmManager *manager)
   gint            count;
 
   if (!g_file_test (manager->session_file, G_FILE_TEST_IS_REGULAR))
-    return FALSE;
+    {
+      g_warning ("xfsm_manager_load_session: Something wrong with %s, Does it exist? Permissions issue?", manager->session_file);
+      return FALSE;
+    }
 
   rc = xfce_rc_simple_open (manager->session_file, FALSE);
   if (G_UNLIKELY (rc == NULL))
+  {
+    g_warning ("xfsm_manager_load_session: unable to open %s", manager->session_file);
     return FALSE;
+  }
 
   if (manager->session_chooser && !xfsm_manager_choose_session (manager, rc))
     {
+      g_warning ("xfsm_manager_load_session: failed to choose session");
       xfce_rc_close (rc);
       return FALSE;
     }
 
   g_snprintf (buffer, 1024, "Session: %s", manager->session_name);
+  xfsm_verbose ("loading %s\n", buffer);
 
   xfce_rc_set_group (rc, buffer);
   count = xfce_rc_read_int_entry (rc, "Count", 0);
@@ -572,13 +594,21 @@ xfsm_manager_load_session (XfsmManager *manager)
       g_snprintf (buffer, 1024, "Client%d_", count);
       properties = xfsm_properties_load (rc, buffer);
       if (G_UNLIKELY (properties == NULL))
-        continue;
+        {
+          xfsm_verbose ("%s has no properties. Skipping\n", buffer);
+          continue;
+        }
       if (xfsm_properties_check (properties))
         g_queue_push_tail (manager->pending_properties, properties);
       else
-        xfsm_properties_free (properties);
+        {
+          xfsm_verbose ("%s has invalid properties. Skipping\n", buffer);
+          xfsm_properties_free (properties);
+        }
     }
 
+  xfsm_verbose ("Finished loading clients from rc file\n");
+
   /* load legacy applications */
   xfsm_legacy_load_session (rc);
 
@@ -1097,6 +1127,8 @@ xfsm_manager_save_yourself_global (XfsmManager     *manager,
   GList    *lp;
   GError   *error = NULL;
 
+  xfsm_verbose ("entering");
+
   if (shutdown)
     {
       if (!fast && shutdown_type == XFSM_SHUTDOWN_ASK)
@@ -1196,6 +1228,8 @@ xfsm_manager_save_yourself (XfsmManager *manager,
                             gboolean     fast,
                             gboolean     global)
 {
+  xfsm_verbose ("entering");
+
   if (G_UNLIKELY (xfsm_client_get_state (client) != XFSM_CLIENT_IDLE))
     {
 
@@ -1234,6 +1268,8 @@ void
 xfsm_manager_save_yourself_phase2 (XfsmManager *manager,
                                    XfsmClient *client)
 {
+  xfsm_verbose ("entering");
+
   if (manager->state != XFSM_MANAGER_CHECKPOINT && manager->state != XFSM_MANAGER_SHUTDOWN)
     {
       SmsSaveYourselfPhase2 (xfsm_client_get_sms_connection (client));
@@ -1256,6 +1292,8 @@ xfsm_manager_save_yourself_done (XfsmManager *manager,
                                  XfsmClient  *client,
                                  gboolean     success)
 {
+  xfsm_verbose ("entering");
+
   /* In xfsm_manager_interact_done we send SmsShutdownCancelled to clients in
      XFSM_CLIENT_WAITFORINTERACT state. They respond with SmcSaveYourselfDone
      (xsmp_shutdown_cancelled in libxfce4ui library) so we allow it here. */
@@ -1418,6 +1456,8 @@ xfsm_manager_perform_shutdown (XfsmManager *manager)
 {
   GList *lp;
 
+  xfsm_verbose ("entering");
+
   /* send SmDie message to all clients */
   xfsm_manager_set_state (manager, XFSM_MANAGER_SHUTDOWNPHASE2);
   for (lp = g_queue_peek_nth_link (manager->running_clients, 0);
diff --git a/xfce4-session/xfsm-startup.c b/xfce4-session/xfsm-startup.c
index 321fc8f7..76eef86f 100644
--- a/xfce4-session/xfsm-startup.c
+++ b/xfce4-session/xfsm-startup.c
@@ -626,10 +626,13 @@ xfsm_startup_autostart_xdg (XfsmManager *manager,
       skip = xfce_rc_read_bool_entry (rc, "Hidden", FALSE);
       if (G_LIKELY (!skip))
         {
+          xfsm_verbose("hidden set\n");
+
           if (xfce_rc_read_bool_entry (rc, "X-XFCE-Autostart-Override", FALSE))
             {
               /* override the OnlyShowIn check */
               skip = FALSE;
+              xfsm_verbose ("X-XFCE-Autostart-Override set, launching\n");
             }
           else
             {
@@ -643,6 +646,7 @@ xfsm_startup_autostart_xdg (XfsmManager *manager,
                       if (g_ascii_strcasecmp (only_show_in[m], "XFCE") == 0)
                         {
                           skip = FALSE;
+                          xfsm_verbose ("only show in XFCE set, launching\n");
                           break;
                         }
                     }
@@ -660,6 +664,7 @@ xfsm_startup_autostart_xdg (XfsmManager *manager,
                 if (g_ascii_strcasecmp (not_show_in[m], "XFCE") == 0)
                   {
                     skip = TRUE;
+                    xfsm_verbose ("NotShowIn Xfce set, skipping\n");
                     break;
                   }
 
@@ -671,19 +676,29 @@ xfsm_startup_autostart_xdg (XfsmManager *manager,
            * launching at-spi */
           filename = g_path_get_basename (files[n]);
           if (g_str_has_prefix (filename, "at-spi-"))
-            skip = !start_at_spi;
+            {
+              skip = !start_at_spi;
+              xfsm_verbose ("start_at_spi (a11y support), %s\n", skip ? "skipping" : "showing");
+            }
           g_free (filename);
         }
 
       /* check the "Type" key */
       type = xfce_rc_read_entry (rc, "Type", NULL);
       if (G_UNLIKELY (!skip && type != NULL && g_ascii_strcasecmp (type, "Application") != 0))
-        skip = TRUE;
+        {
+          skip = TRUE;
+          xfsm_verbose ("Type == Application, skipping\n");
+        }
 
       /* check the "TryExec" key */
       try_exec = xfce_rc_read_entry (rc, "TryExec", NULL);
       if (G_UNLIKELY (!skip && try_exec != NULL))
-        skip = !xfsm_check_valid_exec (try_exec);
+        {
+          skip = !xfsm_check_valid_exec (try_exec);
+          if (skip)
+            xfsm_verbose ("TryExec set and xfsm_check_valid_exec failed, skipping\n");
+        }
 
       /* execute the item */
       exec = xfce_rc_read_entry (rc, "Exec", NULL);
@@ -702,6 +717,7 @@ xfsm_startup_autostart_xdg (XfsmManager *manager,
                                                   &error))
             {
               g_warning ("Unable to launch \"%s\" (specified by %s): %s", exec, files[n], error->message);
+              xfsm_verbose ("Unable to launch \"%s\" (specified by %s): %s\n", exec, files[n], error->message);
               g_error_free (error);
               error = NULL;
             }
@@ -943,7 +959,14 @@ xfsm_startup_start_properties (XfsmProperties *properties,
       return FALSE;
     }
 
-  xfsm_verbose ("Launched command \"%s\" with PID %dn", *argv, (gint) pid);
+  /* Don't waste time if we're not debugging, but if we are print the
+   * command + the arguments */
+  if (xfsm_is_verbose_enabled ())
+    {
+      gchar *command = g_strjoinv (" ", argv);
+      xfsm_verbose ("Launched command \"%s\" with PID %d\n", command, (gint) pid);
+      g_free (command);
+    }
 
   g_strfreev (argv);
 
@@ -991,6 +1014,7 @@ xfsm_startup_session_continue (XfsmManager *manager)
       /* we failed to start anything, and we don't have anything else,
        * to start, so just move on to the autostart items and signal
        * the manager that we're finished */
+      xfsm_verbose ("Nothing started and nothing to start, moving to autostart items\n");
       xfsm_startup_autostart (manager);
       xfsm_manager_signal_startup_done (manager);
     }
@@ -1062,6 +1086,7 @@ xfsm_startup_session_next_prio_group (XfsmManager *manager)
         {
           g_queue_push_tail (starting_properties, properties);
           client_started = TRUE;
+          xfsm_verbose ("client id %s started\n", properties->client_id);
         }
       else
         {
@@ -1134,6 +1159,8 @@ xfsm_startup_handle_failed_startup (XfsmProperties *properties,
 {
   GQueue *starting_properties = xfsm_manager_get_queue (manager, XFSM_MANAGER_QUEUE_STARTING_PROPS);
 
+  xfsm_verbose ("Client Id = %s failed to start\n", properties->client_id);
+
   /* if our timer hasn't run out yet, kill it */
   if (properties->startup_timeout_id > 0)
     {