Re: [PATCH 059/104] virtiofsd: Add ID to the log with FUSE_LOG_DEBUG level

[Dr. David Alan Gilbert]

* Daniel P. Berrangé (address@hidden) wrote:
> On Thu, Dec 12, 2019 at 04:38:19PM +0000, Dr. David Alan Gilbert (git) wrote:
> > From: Masayoshi Mizuma <address@hidden>
> > 
> > virtiofsd has some threads, so we see a lot of logs with debug option.
> > It would be useful for debugging if we can identify the specific thread
> > from the log.
> > 
> > Add ID, which is got by gettid(), to the log with FUSE_LOG_DEBUG level
> > so that we can grep the specific thread.
> > 
> > The log is like as:
> > 
> >   ]# ./virtiofsd -d -o vhost_user_socket=/tmp/vhostqemu0 -o 
> > source=/tmp/share0 -o cache=auto
> >   ...
> >   [ID: 00000097]    unique: 12696, success, outsize: 120
> >   [ID: 00000097] virtio_send_msg: elem 18: with 2 in desc of length 120
> >   [ID: 00000003] fv_queue_thread: Got queue event on Queue 1
> >   [ID: 00000003] fv_queue_thread: Queue 1 gave evalue: 1 available: in: 
> > 65552 out: 80
> >   [ID: 00000003] fv_queue_thread: Waiting for Queue 1 event
> >   [ID: 00000071] fv_queue_worker: elem 33: with 2 out desc of length 80 
> > bad_in_num=0 bad_out_num=0
> >   [ID: 00000071] unique: 12694, opcode: READ (15), nodeid: 2, insize: 80, 
> > pid: 2014
> >   [ID: 00000071] lo_read(ino=2, size=65536, off=131072)
> > 
> > Signed-off-by: Masayoshi Mizuma <address@hidden>
> > ---
> >  tools/virtiofsd/passthrough_ll.c | 13 ++++++++++++-
> >  1 file changed, 12 insertions(+), 1 deletion(-)
> 
> > 
> > diff --git a/tools/virtiofsd/passthrough_ll.c 
> > b/tools/virtiofsd/passthrough_ll.c
> > index 6f398a7ff2..8e00a90e6f 100644
> > --- a/tools/virtiofsd/passthrough_ll.c
> > +++ b/tools/virtiofsd/passthrough_ll.c
> > @@ -42,6 +42,7 @@
> >  #include <cap-ng.h>
> >  #include <dirent.h>
> >  #include <errno.h>
> > +#include <glib.h>
> >  #include <inttypes.h>
> >  #include <limits.h>
> >  #include <pthread.h>
> > @@ -2248,12 +2249,18 @@ static void setup_nofile_rlimit(void)
> >      }
> >  }
> >  
> > -static void log_func(enum fuse_log_level level, const char *fmt, va_list 
> > ap)
> > +static void log_func(enum fuse_log_level level, const char *_fmt, va_list 
> > ap)
> >  {
> > +    char *fmt = (char *)_fmt;
> 
> Reusing a variable for data that may be const from stack or
> non-const from heap is really gross & asking for trouble.

Yeh, that is a bit of a hack.

> If instead it does:
> 
>     g_autofree *localfmt = NULL;

                 ^ char

> > +
> >      if (current_log_level < level) {
> >          return;
> >      }
> >  
> > +    if (current_log_level == FUSE_LOG_DEBUG) {
> > +        fmt = g_strdup_printf("[ID: %08ld] %s", syscall(__NR_gettid), 
> > _fmt);
> 
> Then:
> 
>            localfmt = g_strdup_printf(....)
>          fmt = localfmt;
> 
> > +    }
> > +
> >      if (use_syslog) {
> >          int priority = LOG_ERR;
> >          switch (level) {
> > @@ -2286,6 +2293,10 @@ static void log_func(enum fuse_log_level level, 
> > const char *fmt, va_list ap)
> >      } else {
> >          vfprintf(stderr, fmt, ap);
> >      }
> > +
> > +    if (current_log_level == FUSE_LOG_DEBUG) {
> > +        g_free(fmt);
> > +    }
> 
> This can then be deleted.

Yes, that works nicely.

Dave

> >  }
> 
> Regards,
> Daniel
> -- 
> |: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
> |: https://libvirt.org         -o-            https://fstop138.berrange.com :|
> |: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|
--
Dr. David Alan Gilbert / address@hidden / Manchester, UK