[Virtio-fs] debug log timestamp idea

[Laszlo Ersek]

Hi again :)

I find the current debug log hard to associate with actions I perform in
the client; primarily because the timestamps are not human-readable, and
so I can't easily notice time boundaries between actions.

For comparison:

[2020-12-07 18:11:35.51+0100] [ID: 00000003] fv_queue_thread: Got queue event on Queue 1
[2020-12-07 18:11:35.51+0100] [ID: 00000003] fv_queue_thread: Queue 1 gave evalue: 1 available: in: 16 out: 64
[2020-12-07 18:11:35.51+0100] [ID: 00000003] fv_queue_thread: Waiting for Queue 1 event
[2020-12-07 18:11:35.51+0100] [ID: 00000006] fv_queue_worker: elem 0: with 2 out desc of length 64
[2020-12-07 18:11:35.51+0100] [ID: 00000006] unique: 108, opcode: RELEASEDIR (29), nodeid: 1, insize: 64, pid: 1
[2020-12-07 18:11:35.51+0100] [ID: 00000006]    unique: 108, success, outsize: 16
[2020-12-07 18:11:35.51+0100] [ID: 00000006] virtio_send_msg: elem 0: with 1 in desc of length 16
[2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Got VU event
[2020-12-07 18:17:54.82+0100] [ID: 00000001] fv_queue_set_started: qidx=1 started=0
[2020-12-07 18:17:54.82+0100] [ID: 00000003] fv_queue_thread: kill event on queue 1 - quitting
[2020-12-07 18:17:54.82+0100] [ID: 00000001] fv_remove_watch: TODO! fd=9
[2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Waiting for VU event
[2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Got VU event
[2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Waiting for VU event
[2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Got VU event
[2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Waiting for VU event
[2020-12-07 18:17:54.85+0100] [ID: 00000001] virtio_loop: Unexpected poll revents 11
[2020-12-07 18:17:54.85+0100] [ID: 00000001] virtio_loop: Exit

I think this is nicer; note the clear visual jump between "18:11:35" and
"18:17:54"

The patch:

> diff --git a/tools/virtiofsd/passthrough_ll.c b/tools/virtiofsd/passthrough_ll.c
> index 0e4c7ddce0a8..5522f96d33d0 100644
> --- a/tools/virtiofsd/passthrough_ll.c
> +++ b/tools/virtiofsd/passthrough_ll.c
> @@ -3302,9 +3302,19 @@ static void log_func(enum fuse_log_level level, const char *fmt, va_list ap)
>      }
>
>      if (current_log_level == FUSE_LOG_DEBUG) {
> -        if (!use_syslog) {
> -            localfmt = g_strdup_printf("[%" PRId64 "] [ID: %08ld] %s",
> -                                       get_clock(), syscall(__NR_gettid), fmt);
> +        struct timespec ts;
> +        if (!use_syslog && clock_gettime (CLOCK_REALTIME, &ts) == 0) {
> +            struct tm tm;
> +            char sec_fmt[20];
> +            char zone_fmt[6];
> +
> +            localtime_r(&ts.tv_sec, &tm);
> +            strftime(sec_fmt, sizeof sec_fmt, "%Y-%m-%d %H:%M:%S", &tm);
> +            strftime(zone_fmt, sizeof zone_fmt, "%z", &tm);
> +
> +            localfmt = g_strdup_printf("[%s.%02ld%s] [ID: %08ld] %s", sec_fmt,
> +                                       ts.tv_nsec / (10L * 1000 * 1000),
> +                                       zone_fmt, syscall(__NR_gettid), fmt);
>          } else {
>              localfmt = g_strdup_printf("[ID: %08ld] %s", syscall(__NR_gettid),
>                                         fmt);
> @@ -3428,6 +3438,8 @@ int main(int argc, char *argv[])
>      struct lo_map_elem *reserve_elem;
>      int ret = -1;
>
> +    tzset();
> +
>      /* Don't mask creation mode, kernel already did that */
>      umask(0);

The patch probably violates a bunch of QEMU standards (such as referring
to CLOCK_REALTIME, using localtime_r() which may not be available on
Windows (?), etc). I'm OK to carry it myself for debugging, I just
thought I'd ask for opinions.

Thanks
Laszlo