Libguestfs - Oct 2017 - [PATCH v2] daemon: proto: Make the guestfsd main loop messages consistent and useful.

After this change the debugging output looks like this:

  guestfsd: enter: mount (0x1) request length 64 bytes
  commandrvf: stdout=n stderr=y flags=0x0
  commandrvf: udevadm --debug settle -E /dev/sda1
  calling: settle
  command: mount '/dev/sda1' '/sysroot//'
  [    0.951731] EXT4-fs (sda1): mounting ext2 file system using the ext4
subsystem
  [    0.954585] EXT4-fs (sda1): mounted filesystem without journal. Opts:
(null)
  guestfsd: leave: mount (0x1) took 0.01 secs
  guestfsd: enter: touch (0x3) request length 52 bytes
  guestfsd: leave: touch (0x3) took 0.00 secs
---
 daemon/proto.c | 16 +++++++++-------
 1 file changed, 9 insertions(+), 7 deletions(-)

diff --git a/daemon/proto.c b/daemon/proto.c
index 14f7efe94..9abc46962 100644
--- a/daemon/proto.c
+++ b/daemon/proto.c
@@ -96,11 +96,6 @@ main_loop (int _sock)
     xdr_u_int (&xdr, &len);
     xdr_destroy (&xdr);
 
-    if (verbose)
-      fprintf (stderr,
-	       "guestfsd: main_loop: new request, len 0x%" PRIx32
"\n",
-	       len);
-
     /* Cancellation sent from the library and received after the
      * previous request has finished processing.  Just ignore it.
      */
@@ -175,6 +170,13 @@ main_loop (int _sock)
     progress_hint = hdr.progress_hint;
     optargs_bitmask = hdr.optargs_bitmask;
 
+    if (verbose)
+      fprintf (stderr,
+	       "guestfsd: enter: %s (0x%x) request length %" PRIu32 "
bytes\n",
+               proc_nr >= 0 && proc_nr <= GUESTFS_MAX_PROC_NR
+               ? function_names[proc_nr] : "UNKNOWN PROCEDURE",
+               (unsigned) proc_nr, len);
+
     /* Clear errors before we call the stub functions.  This is just
      * to ensure that we can accurately report errors in cases where
      * error handling paths don't set errno correctly.
@@ -200,10 +202,10 @@ main_loop (int _sock)
       elapsed_us = end_us - start_us;
 
       fprintf (stderr,
-	       "guestfsd: main_loop: proc %d (%s) took %d.%02d seconds\n",
-               proc_nr,
+	       "guestfsd: leave: %s (0x%x) took %d.%02d secs\n",
                proc_nr >= 0 && proc_nr <= GUESTFS_MAX_PROC_NR
                ? function_names[proc_nr] : "UNKNOWN PROCEDURE",
+               (unsigned) proc_nr,
                (int) (elapsed_us / 1000000),
                (int) ((elapsed_us / 10000) % 100));
     }
-- 
2.13.2

On Thursday, 12 October 2017 16:30:09 CEST Richard W.M. Jones
wrote:
> After this change the debugging output looks like this:
> 
>   guestfsd: enter: mount (0x1) request length 64 bytes
>   commandrvf: stdout=n stderr=y flags=0x0
>   commandrvf: udevadm --debug settle -E /dev/sda1
>   calling: settle
>   command: mount '/dev/sda1' '/sysroot//'
>   [    0.951731] EXT4-fs (sda1): mounting ext2 file system using the ext4
subsystem
>   [    0.954585] EXT4-fs (sda1): mounted filesystem without journal. Opts:
(null)
>   guestfsd: leave: mount (0x1) took 0.01 secs
>   guestfsd: enter: touch (0x3) request length 52 bytes
>   guestfsd: leave: touch (0x3) took 0.00 secs
> ---
LGTM.

Maybe a small visual improvements could be replacing the "enter" and
"leave" texts with ASCII arrows, e.g.
"<="/"<-" and "=>"/"->":

  guestfsd: [->] touch (0x3) request length 52 bytes
  guestfsd: [<-] touch (0x3) took 0.00 secs

This may make the output slightly more eye-friendly, but YMMV.

-- 
Pino Toscano