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.

xfce4-session/sm-layer.c

@@ -114,26 +114,28 @@ 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
     }
 
   if (!SmsInitialize (PACKAGE, VERSION, sm_new_client, manager, ice_auth_proc,
                       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);
     }
 

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.

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);

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;
 

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;

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);