[Qemu-devel] [PATCH v2 0/9] log: assorted improvements

[Qemu-devel] [PATCH v2 0/9] log: assorted improvements

[Denis V. Lunev]

This patchset accumulates old patchset sent in the middle of October 2015
and recent simple changes changes.

The following is done:
- QMP/HMP/QAPI events are now logged
- timestamp is added to the log message
- arguments of qemu_log/qemu_log_mask are not calculated now if the log
  is disabled

These patches are sent in the hope that it is not too late for QEMU 2.6.

Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: Pavel Butsykin <pbutsykin@virtuozzo.com>
CC: Markus Armbruster <armbru@redhat.com>
CC: Luiz Capitulino <lcapitulino@redhat.com>
CC: Eric Blake <eblake@redhat.com>
CC: Stefan Hajnoczi <stefanha@redhat.com>
CC: Paolo Bonzini <pbonzini@redhat.com>

Changes from v1:
- added logging of QMP/HMP events
- added logging of QAPI events
- format of the timestamp is now taken out of the g_time_val_to_iso8601
- checking the timestamp flag is moved from the macro
- separate patches for QMP, HMP and QAPI.
- new fixes as patches 1-4

Denis V. Lunev (4):
  trace: do not always call exit() in trace_enable_events
  log: improve code in do_qemu_set_log
  log: move qemu_log_close/qemu_log_flush from header to log.c
  log: improve performance of qemu_log and qemu_log_mask if disabled

Pavel Butsykin (4):
  log: log QMP commands and replies
  log: report HMP command and event
  log: report QAPI event
  log: adds a timestamp to each log entry

Vladimir Sementsov-Ogievskiy (1):
  qemu-log: fix cpu_reset log target

 include/qemu/log.h | 43 +++++++++++++++++++-----------------
 monitor.c          | 23 ++++++++++++++++++++
 os-posix.c         |  2 +-
 qom/cpu.c          |  3 ++-
 trace/control.c    |  5 ++++-
 util/log.c         | 64 ++++++++++++++++++++++++++++++++++++++----------------
 6 files changed, 98 insertions(+), 42 deletions(-)

-- 
2.5.0

[Qemu-devel] [PATCH 1/9] trace: do not always call exit() in trace_enable_events

[Denis V. Lunev]

The problem is that
  virsh qemu-monitor-command --hmp VM log trace:help
forces QEMU to exit even when running VM normally.

Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: Stefan Hajnoczi <stefanha@redhat.com>
CC: Paolo Bonzini <pbonzini@redhat.com>
---
 trace/control.c | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/trace/control.c b/trace/control.c
index 20d3370..2d404c3 100644
--- a/trace/control.c
+++ b/trace/control.c
@@ -19,6 +19,7 @@
 #include "qemu/log.h"
 #endif
 #include "qemu/error-report.h"
+#include "monitor/monitor.h"
 
 int trace_events_enabled_count;
 bool trace_events_dstate[TRACE_EVENT_COUNT];
@@ -131,7 +132,9 @@ void trace_enable_events(const char *line_buf)
 {
     if (is_help_option(line_buf)) {
         trace_list_events();
-        exit(0);
+        if (cur_mon == NULL) {
+            exit(0);
+        }
     } else {
         do_trace_enable_events(line_buf);
     }
-- 
2.5.0

Re: [Qemu-devel] [PATCH 1/9] trace: do not always call exit() in trace_enable_events

[Paolo Bonzini]

On 14/03/2016 12:21, Denis V. Lunev wrote:
> The problem is that
>   virsh qemu-monitor-command --hmp VM log trace:help
> forces QEMU to exit even when running VM normally.
> 
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: Stefan Hajnoczi <stefanha@redhat.com>
> CC: Paolo Bonzini <pbonzini@redhat.com>
> ---
>  trace/control.c | 5 ++++-
>  1 file changed, 4 insertions(+), 1 deletion(-)
> 
> diff --git a/trace/control.c b/trace/control.c
> index 20d3370..2d404c3 100644
> --- a/trace/control.c
> +++ b/trace/control.c
> @@ -19,6 +19,7 @@
>  #include "qemu/log.h"
>  #endif
>  #include "qemu/error-report.h"
> +#include "monitor/monitor.h"
>  
>  int trace_events_enabled_count;
>  bool trace_events_dstate[TRACE_EVENT_COUNT];
> @@ -131,7 +132,9 @@ void trace_enable_events(const char *line_buf)
>  {
>      if (is_help_option(line_buf)) {
>          trace_list_events();
> -        exit(0);
> +        if (cur_mon == NULL) {
> +            exit(0);
> +        }
>      } else {
>          do_trace_enable_events(line_buf);
>      }
> 

Ouch. :)

Reviewed-by: Paolo Bonzini <pbonzini@redhat.com>

Paolo

[Qemu-devel] [PATCH 2/9] qemu-log: fix cpu_reset log target

[Denis V. Lunev]

From: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>

Do not print superfluous zero cpu state on vm start with -d cpu_reset

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: Stefan Hajnoczi <stefanha@redhat.com>
CC: Paolo Bonzini <pbonzini@redhat.com>
CC: Andreas Färber <afaerber@suse.de>
---
 qom/cpu.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/qom/cpu.c b/qom/cpu.c
index c45d0bb..69e3b87 100644
--- a/qom/cpu.c
+++ b/qom/cpu.c
@@ -247,7 +247,8 @@ static void cpu_common_reset(CPUState *cpu)
 {
     CPUClass *cc = CPU_GET_CLASS(cpu);
 
-    if (qemu_loglevel_mask(CPU_LOG_RESET)) {
+    if (qemu_loglevel_mask(CPU_LOG_RESET) &&
+            !runstate_check(RUN_STATE_PRELAUNCH)) {
         qemu_log("CPU Reset (CPU %d)\n", cpu->cpu_index);
         log_cpu_state(cpu, cc->reset_dump_flags);
     }
-- 
2.5.0

Re: [Qemu-devel] [PATCH 2/9] qemu-log: fix cpu_reset log target

[Paolo Bonzini]

On 14/03/2016 12:21, Denis V. Lunev wrote:
> From: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> 
> Do not print superfluous zero cpu state on vm start with -d cpu_reset

It's really just the very first reset that is all zeroes.  If you
use "-S", you can be in prelaunch state and have a meaningful state.

Overall I'm not sure that this patch provides a big benefit, but
I'll defer to Andreas and others that may want to chime in.

Paolo


> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: Stefan Hajnoczi <stefanha@redhat.com>
> CC: Paolo Bonzini <pbonzini@redhat.com>
> CC: Andreas Färber <afaerber@suse.de>
> ---
>  qom/cpu.c | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
> 
> diff --git a/qom/cpu.c b/qom/cpu.c
> index c45d0bb..69e3b87 100644
> --- a/qom/cpu.c
> +++ b/qom/cpu.c
> @@ -247,7 +247,8 @@ static void cpu_common_reset(CPUState *cpu)
>  {
>      CPUClass *cc = CPU_GET_CLASS(cpu);
>  
> -    if (qemu_loglevel_mask(CPU_LOG_RESET)) {
> +    if (qemu_loglevel_mask(CPU_LOG_RESET) &&
> +            !runstate_check(RUN_STATE_PRELAUNCH)) {
>          qemu_log("CPU Reset (CPU %d)\n", cpu->cpu_index);
>          log_cpu_state(cpu, cc->reset_dump_flags);
>      }
> 

[Qemu-devel] [PATCH 3/9] log: improve code in do_qemu_set_log

[Denis V. Lunev]

The following commit
    commit 96c33a4523ee1abe382ce4ff3e82b90ba78aa186
    Author: Dimitris Aragiorgis <dimara@arrikto.com>
    Date:   Thu Feb 18 13:38:38 2016 +0200

    log: Redirect stderr to logfile if deamonized
was created with unnecessary side effect - connect from libvirt starts
to hang. This, in turn, was fixed by
    commit c586eac33670c198c6c9ceb1419aa99dafcce907
    Author: Paolo Bonzini <pbonzini@redhat.com>
    Date:   Mon Feb 29 12:18:40 2016 +0100

    log: do not log if QEMU is daemonized but without -D
but the fix seems a bit awkward to me.

This patch fixes the problem with a bit more readable approach and makes the
code closer to the original state.

Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: Stefan Hajnoczi <stefanha@redhat.com>
CC: Paolo Bonzini <pbonzini@redhat.com>
---
 include/qemu/log.h |  4 ++++
 os-posix.c         |  2 +-
 util/log.c         | 10 ++--------
 3 files changed, 7 insertions(+), 9 deletions(-)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index 40c24fd..be20811 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -88,6 +88,10 @@ static inline void qemu_log_close(void)
         }
         qemu_logfile = NULL;
     }
+
+    if (is_daemonized()) {
+        dup2(STDOUT_FILENO, STDERR_FILENO); /* dup /dev/null to stderr */
+    }
 }
 
 /* define log items */
diff --git a/os-posix.c b/os-posix.c
index 92fa3ba..d4b2a91 100644
--- a/os-posix.c
+++ b/os-posix.c
@@ -277,7 +277,7 @@ void os_setup_post(void)
         dup2(fd, 0);
         dup2(fd, 1);
         /* In case -D is given do not redirect stderr to /dev/null */
-        if (!qemu_logfile) {
+        if (!qemu_logfile || qemu_logfile == stderr) {
             dup2(fd, 2);
         }
 
diff --git a/util/log.c b/util/log.c
index 8b921de..a06aa14 100644
--- a/util/log.c
+++ b/util/log.c
@@ -56,8 +56,7 @@ void do_qemu_set_log(int log_flags, bool use_own_buffers)
 #ifdef CONFIG_TRACE_LOG
     qemu_loglevel |= LOG_TRACE;
 #endif
-    if (!qemu_logfile &&
-        (is_daemonized() ? logfilename != NULL : qemu_loglevel)) {
+    if (qemu_loglevel && !qemu_logfile) {
         if (logfilename) {
             qemu_logfile = fopen(logfilename, log_append ? "a" : "w");
             if (!qemu_logfile) {
@@ -67,13 +66,9 @@ void do_qemu_set_log(int log_flags, bool use_own_buffers)
             /* In case we are a daemon redirect stderr to logfile */
             if (is_daemonized()) {
                 dup2(fileno(qemu_logfile), STDERR_FILENO);
-                fclose(qemu_logfile);
-                /* This will skip closing logfile in qemu_log_close() */
-                qemu_logfile = stderr;
             }
         } else {
             /* Default to stderr if no log file specified */
-            assert(!is_daemonized());
             qemu_logfile = stderr;
         }
         /* must avoid mmap() usage of glibc by setting a buffer "by hand" */
@@ -91,8 +86,7 @@ void do_qemu_set_log(int log_flags, bool use_own_buffers)
             log_append = 1;
         }
     }
-    if (qemu_logfile &&
-        (is_daemonized() ? logfilename == NULL : !qemu_loglevel)) {
+    if (!qemu_loglevel && qemu_logfile) {
         qemu_log_close();
     }
 }
-- 
2.5.0

Re: [Qemu-devel] [PATCH 3/9] log: improve code in do_qemu_set_log

[Paolo Bonzini]

On 14/03/2016 12:21, Denis V. Lunev wrote:
>          /* In case -D is given do not redirect stderr to /dev/null */
> -        if (!qemu_logfile) {
> +        if (!qemu_logfile || qemu_logfile == stderr) {
>              dup2(fd, 2);

This relies on knowledge that fileno(qemu_logfile) is dup-ed to stderr.
 I'm not sure what's the problem in commit c586eac33; the idea is that,
if -daemonize is given, a named logfile should always be open (so that
stderr is redirected) but stderr should not be used as log destination
(because that's just /dev/null).  That's clear from the condition:

   is_daemonized() ? logfilename != NULL : qemu_loglevel

Paolo

Re: [Qemu-devel] [PATCH 3/9] log: improve code in do_qemu_set_log

[Denis V. Lunev]

On 03/14/2016 05:28 PM, Paolo Bonzini wrote:
>
> On 14/03/2016 12:21, Denis V. Lunev wrote:
>>           /* In case -D is given do not redirect stderr to /dev/null */
>> -        if (!qemu_logfile) {
>> +        if (!qemu_logfile || qemu_logfile == stderr) {
>>               dup2(fd, 2);
> This relies on knowledge that fileno(qemu_logfile) is dup-ed to stderr.
actually the comment 2 lines above is exactly about this :))))))

>   I'm not sure what's the problem in commit c586eac33; the idea is that,
> if -daemonize is given, a named logfile should always be open (so that
> stderr is redirected) but stderr should not be used as log destination
> (because that's just /dev/null).  That's clear from the condition:
>
>     is_daemonized() ? logfilename != NULL : qemu_loglevel
>
> Paolo
The question here is the following actually.

Should we continue to keep writing 'stderr' output to the log file
when we have cleared all log levels. If the answer is 'yes',
original == your code is correct while my is wrong. In the
other case - the situation becomes mirrored.

Den

Re: [Qemu-devel] [PATCH 3/9] log: improve code in do_qemu_set_log

[Paolo Bonzini]

On 16/03/2016 12:20, Denis V. Lunev wrote:
> The question here is the following actually.
> 
> Should we continue to keep writing 'stderr' output to the log file
> when we have cleared all log levels. If the answer is 'yes',
> original == your code is correct while my is wrong. In the
> other case - the situation becomes mirrored.

You're right about the actual question to answer.

I think the answer is yes, given the original purpose of Dimitris's
patch.  The behavior of "-daemonize -D foo" should be the same if QEMU
is configured with or without the "log" trace backend.

Paolo

[Qemu-devel] [PATCH 4/9] log: move qemu_log_close/qemu_log_flush from header to log.c

[Denis V. Lunev]

There is no particular reason to keep these functions in the header.
Suggested by Paolo.

Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: Stefan Hajnoczi <stefanha@redhat.com>
CC: Paolo Bonzini <pbonzini@redhat.com>
---
 include/qemu/log.h | 26 +++++---------------------
 util/log.c         | 21 +++++++++++++++++++++
 2 files changed, 26 insertions(+), 21 deletions(-)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index be20811..2c2c220 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -73,27 +73,6 @@ void GCC_FMT_ATTR(2, 3) qemu_log_mask(int mask, const char *fmt, ...);
 
 /* Maintenance: */
 
-/* fflush() the log file */
-static inline void qemu_log_flush(void)
-{
-    fflush(qemu_logfile);
-}
-
-/* Close the log file */
-static inline void qemu_log_close(void)
-{
-    if (qemu_logfile) {
-        if (qemu_logfile != stderr) {
-            fclose(qemu_logfile);
-        }
-        qemu_logfile = NULL;
-    }
-
-    if (is_daemonized()) {
-        dup2(STDOUT_FILENO, STDERR_FILENO); /* dup /dev/null to stderr */
-    }
-}
-
 /* define log items */
 typedef struct QEMULogItem {
     int mask;
@@ -126,4 +105,9 @@ int qemu_str_to_log_mask(const char *str);
  */
 void qemu_print_log_usage(FILE *f);
 
+/* fflush() the log file */
+void qemu_log_flush(void);
+/* Close the log file */
+void qemu_log_close(void);
+
 #endif
diff --git a/util/log.c b/util/log.c
index a06aa14..df672cc 100644
--- a/util/log.c
+++ b/util/log.c
@@ -99,6 +99,27 @@ void qemu_set_log_filename(const char *filename)
     qemu_set_log(qemu_loglevel);
 }
 
+/* fflush() the log file */
+void qemu_log_flush(void)
+{
+    fflush(qemu_logfile);
+}
+
+/* Close the log file */
+void qemu_log_close(void)
+{
+    if (qemu_logfile) {
+        if (qemu_logfile != stderr) {
+            fclose(qemu_logfile);
+        }
+        qemu_logfile = NULL;
+    }
+
+    if (is_daemonized()) {
+        dup2(STDOUT_FILENO, STDERR_FILENO); /* dup /dev/null to stderr */
+    }
+}
+
 const QEMULogItem qemu_log_items[] = {
     { CPU_LOG_TB_OUT_ASM, "out_asm",
       "show generated host assembly code for each compiled TB" },
-- 
2.5.0

Re: [Qemu-devel] [PATCH 4/9] log: move qemu_log_close/qemu_log_flush from header to log.c

[Paolo Bonzini]

On 14/03/2016 12:21, Denis V. Lunev wrote:
> There is no particular reason to keep these functions in the header.
> Suggested by Paolo.
> 
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: Stefan Hajnoczi <stefanha@redhat.com>
> CC: Paolo Bonzini <pbonzini@redhat.com>
> ---
>  include/qemu/log.h | 26 +++++---------------------
>  util/log.c         | 21 +++++++++++++++++++++
>  2 files changed, 26 insertions(+), 21 deletions(-)
> 
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index be20811..2c2c220 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -73,27 +73,6 @@ void GCC_FMT_ATTR(2, 3) qemu_log_mask(int mask, const char *fmt, ...);
>  
>  /* Maintenance: */
>  
> -/* fflush() the log file */
> -static inline void qemu_log_flush(void)
> -{
> -    fflush(qemu_logfile);
> -}
> -
> -/* Close the log file */
> -static inline void qemu_log_close(void)
> -{
> -    if (qemu_logfile) {
> -        if (qemu_logfile != stderr) {
> -            fclose(qemu_logfile);
> -        }
> -        qemu_logfile = NULL;
> -    }
> -
> -    if (is_daemonized()) {
> -        dup2(STDOUT_FILENO, STDERR_FILENO); /* dup /dev/null to stderr */
> -    }
> -}
> -
>  /* define log items */
>  typedef struct QEMULogItem {
>      int mask;
> @@ -126,4 +105,9 @@ int qemu_str_to_log_mask(const char *str);
>   */
>  void qemu_print_log_usage(FILE *f);
>  
> +/* fflush() the log file */
> +void qemu_log_flush(void);
> +/* Close the log file */
> +void qemu_log_close(void);
> +
>  #endif
> diff --git a/util/log.c b/util/log.c
> index a06aa14..df672cc 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -99,6 +99,27 @@ void qemu_set_log_filename(const char *filename)
>      qemu_set_log(qemu_loglevel);
>  }
>  
> +/* fflush() the log file */
> +void qemu_log_flush(void)
> +{
> +    fflush(qemu_logfile);
> +}
> +
> +/* Close the log file */
> +void qemu_log_close(void)
> +{
> +    if (qemu_logfile) {
> +        if (qemu_logfile != stderr) {
> +            fclose(qemu_logfile);
> +        }
> +        qemu_logfile = NULL;
> +    }
> +
> +    if (is_daemonized()) {
> +        dup2(STDOUT_FILENO, STDERR_FILENO); /* dup /dev/null to stderr */
> +    }
> +}
> +
>  const QEMULogItem qemu_log_items[] = {
>      { CPU_LOG_TB_OUT_ASM, "out_asm",
>        "show generated host assembly code for each compiled TB" },
> 

Looks good, but it depends on patch 3.  It's always better to put the
obvious/uncontroversial patches first.

Paolo

[Qemu-devel] [PATCH 5/9] log: improve performance of qemu_log and qemu_log_mask if disabled

[Denis V. Lunev]

The patch is intended to avoid to perform any operation including
calculation of log function arguments when the log is not enabled due to
various reasons.

Functions qemu_log and qemu_log_mask are replaced with variadic macros.

Format checking performed by compiler will not suffer by this patch. It
will be done inside in fprintf arguments checking.

Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: Stefan Hajnoczi <stefanha@redhat.com>
CC: Paolo Bonzini <pbonzini@redhat.com>
---
 include/qemu/log.h | 15 ++++++++++++---
 util/log.c         | 21 ---------------------
 2 files changed, 12 insertions(+), 24 deletions(-)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index 2c2c220..a05c7dc 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -54,7 +54,12 @@ static inline bool qemu_loglevel_mask(int mask)
 
 /* main logging function
  */
-void GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);
+#define qemu_log(...)                          \
+    do {                                       \
+        if (qemu_log_enabled()) {              \
+           fprintf(qemu_logfile, __VA_ARGS__); \
+        }                                      \
+    } while (0)
 
 /* vfprintf-like logging function
  */
@@ -68,8 +73,12 @@ qemu_log_vprintf(const char *fmt, va_list va)
 
 /* log only if a bit is set on the current loglevel mask
  */
-void GCC_FMT_ATTR(2, 3) qemu_log_mask(int mask, const char *fmt, ...);
-
+#define qemu_log_mask(mask, ...)                                \
+    do {                                                        \
+        if ((qemu_loglevel & (mask)) && qemu_log_enabled()) {   \
+           fprintf(qemu_logfile, __VA_ARGS__);                  \
+        }                                                       \
+    } while (0)
 
 /* Maintenance: */
 
diff --git a/util/log.c b/util/log.c
index df672cc..65d46e2 100644
--- a/util/log.c
+++ b/util/log.c
@@ -27,27 +27,6 @@ FILE *qemu_logfile;
 int qemu_loglevel;
 static int log_append = 0;
 
-void qemu_log(const char *fmt, ...)
-{
-    va_list ap;
-
-    va_start(ap, fmt);
-    if (qemu_logfile) {
-        vfprintf(qemu_logfile, fmt, ap);
-    }
-    va_end(ap);
-}
-
-void qemu_log_mask(int mask, const char *fmt, ...)
-{
-    va_list ap;
-
-    va_start(ap, fmt);
-    if ((qemu_loglevel & mask) && qemu_logfile) {
-        vfprintf(qemu_logfile, fmt, ap);
-    }
-    va_end(ap);
-}
 
 /* enable or disable low levels log */
 void do_qemu_set_log(int log_flags, bool use_own_buffers)
-- 
2.5.0

Re: [Qemu-devel] [PATCH 5/9] log: improve performance of qemu_log and qemu_log_mask if disabled

[Paolo Bonzini]

On 14/03/2016 12:21, Denis V. Lunev wrote:
> The patch is intended to avoid to perform any operation including
> calculation of log function arguments when the log is not enabled due to
> various reasons.
> 
> Functions qemu_log and qemu_log_mask are replaced with variadic macros.
> 
> Format checking performed by compiler will not suffer by this patch. It
> will be done inside in fprintf arguments checking.

Have you encountered a place that was calling them so hard that it
caused performance problem?  If so, the logging should probably be
replaced by a tracepoint.

Paolo

> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: Stefan Hajnoczi <stefanha@redhat.com>
> CC: Paolo Bonzini <pbonzini@redhat.com>
> ---
>  include/qemu/log.h | 15 ++++++++++++---
>  util/log.c         | 21 ---------------------
>  2 files changed, 12 insertions(+), 24 deletions(-)
> 
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index 2c2c220..a05c7dc 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -54,7 +54,12 @@ static inline bool qemu_loglevel_mask(int mask)
>  
>  /* main logging function
>   */
> -void GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);
> +#define qemu_log(...)                          \
> +    do {                                       \
> +        if (qemu_log_enabled()) {              \
> +           fprintf(qemu_logfile, __VA_ARGS__); \
> +        }                                      \
> +    } while (0)
>  
>  /* vfprintf-like logging function
>   */
> @@ -68,8 +73,12 @@ qemu_log_vprintf(const char *fmt, va_list va)
>  
>  /* log only if a bit is set on the current loglevel mask
>   */
> -void GCC_FMT_ATTR(2, 3) qemu_log_mask(int mask, const char *fmt, ...);
> -
> +#define qemu_log_mask(mask, ...)                                \
> +    do {                                                        \
> +        if ((qemu_loglevel & (mask)) && qemu_log_enabled()) {   \
> +           fprintf(qemu_logfile, __VA_ARGS__);                  \
> +        }                                                       \
> +    } while (0)
>  
>  /* Maintenance: */
>  
> diff --git a/util/log.c b/util/log.c
> index df672cc..65d46e2 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -27,27 +27,6 @@ FILE *qemu_logfile;
>  int qemu_loglevel;
>  static int log_append = 0;
>  
> -void qemu_log(const char *fmt, ...)
> -{
> -    va_list ap;
> -
> -    va_start(ap, fmt);
> -    if (qemu_logfile) {
> -        vfprintf(qemu_logfile, fmt, ap);
> -    }
> -    va_end(ap);
> -}
> -
> -void qemu_log_mask(int mask, const char *fmt, ...)
> -{
> -    va_list ap;
> -
> -    va_start(ap, fmt);
> -    if ((qemu_loglevel & mask) && qemu_logfile) {
> -        vfprintf(qemu_logfile, fmt, ap);
> -    }
> -    va_end(ap);
> -}
>  
>  /* enable or disable low levels log */
>  void do_qemu_set_log(int log_flags, bool use_own_buffers)
> 

Re: [Qemu-devel] [PATCH 5/9] log: improve performance of qemu_log and qemu_log_mask if disabled

[Denis V. Lunev]

On 03/14/2016 05:30 PM, Paolo Bonzini wrote:
>
> On 14/03/2016 12:21, Denis V. Lunev wrote:
>> The patch is intended to avoid to perform any operation including
>> calculation of log function arguments when the log is not enabled due to
>> various reasons.
>>
>> Functions qemu_log and qemu_log_mask are replaced with variadic macros.
>>
>> Format checking performed by compiler will not suffer by this patch. It
>> will be done inside in fprintf arguments checking.
> Have you encountered a place that was calling them so hard that it
> caused performance problem?  If so, the logging should probably be
> replaced by a tracepoint.
>
> Paolo
>

inline functions can have side-effects, i.e. the arguments of them
can be evaluated depending on the compiler. with this approach
we are sure that this will not happen, ever.

Den

[Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Denis V. Lunev]

From: Pavel Butsykin <pbutsykin@virtuozzo.com>

This log would be very welcome for long-term diagnostics of the system
in the production. This log is at least necessary to understand what
has been happened on the system and to identify issues at higher-level
subsystems (libvirt, etc).

These messages will be quite useful to understand how things are going.

Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: Stefan Hajnoczi <stefanha@redhat.com>
CC: Paolo Bonzini <pbonzini@redhat.com>
CC: Luiz Capitulino <lcapitulino@redhat.com>
CC: Markus Armbruster <armbru@redhat.com>
CC: Eric Blake <eblake@redhat.com>
---
 include/qemu/log.h |  1 +
 monitor.c          | 13 +++++++++++++
 util/log.c         |  2 ++
 3 files changed, 16 insertions(+)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index a05c7dc..55bceae 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -42,6 +42,7 @@ static inline bool qemu_log_separate(void)
 #define CPU_LOG_TB_NOCHAIN (1 << 13)
 #define CPU_LOG_PAGE       (1 << 14)
 #define LOG_TRACE          (1 << 15)
+#define LOG_QMP            (1 << 16)
 
 /* Returns true if a bit is set in the current loglevel mask
  */
diff --git a/monitor.c b/monitor.c
index e99ca8c..eec4e58 100644
--- a/monitor.c
+++ b/monitor.c
@@ -437,6 +437,12 @@ static void monitor_protocol_emitter(Monitor *mon, QObject *data,
     }
 
     monitor_json_emitter(mon, QOBJECT(qmp));
+    if (qemu_loglevel_mask(LOG_QMP)) {
+        QString *output_json = qobject_to_json(QOBJECT(qmp));
+        qemu_log_mask(LOG_QMP, "QMP reply: %s\n", output_json->string);
+        QDECREF(output_json);
+    }
+
     QDECREF(qmp);
 }
 
@@ -3867,6 +3873,11 @@ static void handle_qmp_command(JSONMessageParser *parser, GQueue *tokens)
         goto err_out;
     }
 
+    if (qemu_loglevel_mask(LOG_QMP)) {
+        QString *output_json = qobject_to_json(obj);
+        qemu_log_mask(LOG_QMP, "QMP command: %s\n", output_json->string);
+        QDECREF(output_json);
+    }
     input = qmp_check_input_obj(obj, &local_err);
     if (!input) {
         qobject_decref(obj);
@@ -3988,12 +3999,14 @@ static void monitor_qmp_event(void *opaque, int event)
         monitor_json_emitter(mon, data);
         qobject_decref(data);
         mon_refcount++;
+        qemu_log_mask(LOG_QMP, "QMP: new connection established\n");
         break;
     case CHR_EVENT_CLOSED:
         json_message_parser_destroy(&mon->qmp.parser);
         json_message_parser_init(&mon->qmp.parser, handle_qmp_command);
         mon_refcount--;
         monitor_fdsets_cleanup();
+        qemu_log_mask(LOG_QMP, "QMP: connection closed\n");
         break;
     }
 }
diff --git a/util/log.c b/util/log.c
index 65d46e2..5fc517b 100644
--- a/util/log.c
+++ b/util/log.c
@@ -131,6 +131,8 @@ const QEMULogItem qemu_log_items[] = {
     { CPU_LOG_TB_NOCHAIN, "nochain",
       "do not chain compiled TBs so that \"exec\" and \"cpu\" show\n"
       "complete traces" },
+    { LOG_QMP, "qmp",
+      "log the QMP commands and events" },
     { 0, NULL, NULL },
 };
 
-- 
2.5.0

Re: [Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Paolo Bonzini]

On 14/03/2016 12:21, Denis V. Lunev wrote:
> From: Pavel Butsykin <pbutsykin@virtuozzo.com>
> 
> This log would be very welcome for long-term diagnostics of the system
> in the production. This log is at least necessary to understand what
> has been happened on the system and to identify issues at higher-level
> subsystems (libvirt, etc).
> 
> These messages will be quite useful to understand how things are going.

There is now a logging mechanism for qemu-char.c.  Have you looked into
making libvirt provide a QMP log based on it?

The timestamping of patch 9 could be useful for character devices as well.

Paolo

Re: [Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Daniel P. Berrange]

On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote:
> 
> 
> On 14/03/2016 12:21, Denis V. Lunev wrote:
> > From: Pavel Butsykin <pbutsykin@virtuozzo.com>
> > 
> > This log would be very welcome for long-term diagnostics of the system
> > in the production. This log is at least necessary to understand what
> > has been happened on the system and to identify issues at higher-level
> > subsystems (libvirt, etc).
> > 
> > These messages will be quite useful to understand how things are going.
> 
> There is now a logging mechanism for qemu-char.c.  Have you looked into
> making libvirt provide a QMP log based on it?
> 
> The timestamping of patch 9 could be useful for character devices as well.

libvirt QEMU driver already has logging support for recording all the data
it both sends and receives over QMP, which should be sufficient for any
day to day troubleshooting of QMP issues. So I doubt duplicating that
info from QEMU side too is really beneficial for debugging issues when
libvirt is in use.

In libvirtd set

  log_filters="1:qemu_monitor"

and it'll capture everything on the QMP monitor in the default libvirtd
log file.

The QMP data is also fed into the libvirt tracing backend, so you can
write systemtap scripts that hook on any QMP message, reply or event.
We ship a sample monitoring script examples/systemtap/qemu-monitor.stp
for this too.

Regards,
Daniel
-- 
|: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org              -o-             http://virt-manager.org :|
|: http://autobuild.org       -o-         http://search.cpan.org/~danberr/ :|
|: http://entangle-photo.org       -o-       http://live.gnome.org/gtk-vnc :|

Re: [Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Denis V. Lunev]

On 03/14/2016 05:38 PM, Daniel P. Berrange wrote:
> On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote:
>>
>> On 14/03/2016 12:21, Denis V. Lunev wrote:
>>> From: Pavel Butsykin <pbutsykin@virtuozzo.com>
>>>
>>> This log would be very welcome for long-term diagnostics of the system
>>> in the production. This log is at least necessary to understand what
>>> has been happened on the system and to identify issues at higher-level
>>> subsystems (libvirt, etc).
>>>
>>> These messages will be quite useful to understand how things are going.
>> There is now a logging mechanism for qemu-char.c.  Have you looked into
>> making libvirt provide a QMP log based on it?
>>
>> The timestamping of patch 9 could be useful for character devices as well.
> libvirt QEMU driver already has logging support for recording all the data
> it both sends and receives over QMP, which should be sufficient for any
> day to day troubleshooting of QMP issues. So I doubt duplicating that
> info from QEMU side too is really beneficial for debugging issues when
> libvirt is in use.
>
> In libvirtd set
>
>    log_filters="1:qemu_monitor"
>
> and it'll capture everything on the QMP monitor in the default libvirtd
> log file.
>
> The QMP data is also fed into the libvirt tracing backend, so you can
> write systemtap scripts that hook on any QMP message, reply or event.
> We ship a sample monitoring script examples/systemtap/qemu-monitor.stp
> for this too.
>
> Regards,
> Daniel
you definitely sold this to me :) Thank you for pointing this out.

OK. This means that patches 5-9 are not that necessary.

Den

Re: [Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Denis V. Lunev]

On 03/14/2016 05:38 PM, Daniel P. Berrange wrote:
> On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote:
>>
>> On 14/03/2016 12:21, Denis V. Lunev wrote:
>>> From: Pavel Butsykin <pbutsykin@virtuozzo.com>
>>>
>>> This log would be very welcome for long-term diagnostics of the system
>>> in the production. This log is at least necessary to understand what
>>> has been happened on the system and to identify issues at higher-level
>>> subsystems (libvirt, etc).
>>>
>>> These messages will be quite useful to understand how things are going.
>> There is now a logging mechanism for qemu-char.c.  Have you looked into
>> making libvirt provide a QMP log based on it?
>>
>> The timestamping of patch 9 could be useful for character devices as well.
> libvirt QEMU driver already has logging support for recording all the data
> it both sends and receives over QMP, which should be sufficient for any
> day to day troubleshooting of QMP issues. So I doubt duplicating that
> info from QEMU side too is really beneficial for debugging issues when
> libvirt is in use.
>
> In libvirtd set
>
>    log_filters="1:qemu_monitor"
>
> and it'll capture everything on the QMP monitor in the default libvirtd
> log file.
>
> The QMP data is also fed into the libvirt tracing backend, so you can
> write systemtap scripts that hook on any QMP message, reply or event.
> We ship a sample monitoring script examples/systemtap/qemu-monitor.stp
> for this too.
>
> Regards,
> Daniel
you definitely sold this to me :) Thank you for pointing this out.

There is the only differences in the approaches:
- for example you have 20-50 VMs on the node
- you have 1 problematic VM to be debugged by support (not development)

In this case with my approach the load to the host IO subsystem will
be less (logs from 1 VM will be written only).

I can drop patches 5-9 if this is not important :)

Den

Re: [Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Daniel P. Berrange]

On Mon, Mar 14, 2016 at 06:05:07PM +0300, Denis V. Lunev wrote:
> On 03/14/2016 05:38 PM, Daniel P. Berrange wrote:
> >On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote:
> >>
> >>On 14/03/2016 12:21, Denis V. Lunev wrote:
> >>>From: Pavel Butsykin <pbutsykin@virtuozzo.com>
> >>>
> >>>This log would be very welcome for long-term diagnostics of the system
> >>>in the production. This log is at least necessary to understand what
> >>>has been happened on the system and to identify issues at higher-level
> >>>subsystems (libvirt, etc).
> >>>
> >>>These messages will be quite useful to understand how things are going.
> >>There is now a logging mechanism for qemu-char.c.  Have you looked into
> >>making libvirt provide a QMP log based on it?
> >>
> >>The timestamping of patch 9 could be useful for character devices as well.
> >libvirt QEMU driver already has logging support for recording all the data
> >it both sends and receives over QMP, which should be sufficient for any
> >day to day troubleshooting of QMP issues. So I doubt duplicating that
> >info from QEMU side too is really beneficial for debugging issues when
> >libvirt is in use.
> >
> >In libvirtd set
> >
> >   log_filters="1:qemu_monitor"
> >
> >and it'll capture everything on the QMP monitor in the default libvirtd
> >log file.
> >
> >The QMP data is also fed into the libvirt tracing backend, so you can
> >write systemtap scripts that hook on any QMP message, reply or event.
> >We ship a sample monitoring script examples/systemtap/qemu-monitor.stp
> >for this too.
> >
> you definitely sold this to me :) Thank you for pointing this out.
> 
> There is the only differences in the approaches:
> - for example you have 20-50 VMs on the node
> - you have 1 problematic VM to be debugged by support (not development)
> 
> In this case with my approach the load to the host IO subsystem will
> be less (logs from 1 VM will be written only).

Yep I can see your point but not sure how critical it is in practice. In
my experiance people often tend to just enable libvirt's QEMU debugging
permanently on the basis that by the time you notice a fault with a VM
it is too late to enable it. You often can't reproduce it, so can't just
turn it on for 1 VM once a probem occurs, you have to proactively collect
the data. In case where you do want to target a single VM though, there
is the systemtap approach to collect info which may be sufficient

Regards,
Daniel
-- 
|: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org              -o-             http://virt-manager.org :|
|: http://autobuild.org       -o-         http://search.cpan.org/~danberr/ :|
|: http://entangle-photo.org       -o-       http://live.gnome.org/gtk-vnc :|

Re: [Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Denis V. Lunev]

On 03/14/2016 06:26 PM, Daniel P. Berrange wrote:
> On Mon, Mar 14, 2016 at 06:05:07PM +0300, Denis V. Lunev wrote:
>> On 03/14/2016 05:38 PM, Daniel P. Berrange wrote:
>>> On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote:
>>>> On 14/03/2016 12:21, Denis V. Lunev wrote:
>>>>> From: Pavel Butsykin <pbutsykin@virtuozzo.com>
>>>>>
>>>>> This log would be very welcome for long-term diagnostics of the system
>>>>> in the production. This log is at least necessary to understand what
>>>>> has been happened on the system and to identify issues at higher-level
>>>>> subsystems (libvirt, etc).
>>>>>
>>>>> These messages will be quite useful to understand how things are going.
>>>> There is now a logging mechanism for qemu-char.c.  Have you looked into
>>>> making libvirt provide a QMP log based on it?
>>>>
>>>> The timestamping of patch 9 could be useful for character devices as well.
>>> libvirt QEMU driver already has logging support for recording all the data
>>> it both sends and receives over QMP, which should be sufficient for any
>>> day to day troubleshooting of QMP issues. So I doubt duplicating that
>>> info from QEMU side too is really beneficial for debugging issues when
>>> libvirt is in use.
>>>
>>> In libvirtd set
>>>
>>>    log_filters="1:qemu_monitor"
>>>
>>> and it'll capture everything on the QMP monitor in the default libvirtd
>>> log file.
>>>
>>> The QMP data is also fed into the libvirt tracing backend, so you can
>>> write systemtap scripts that hook on any QMP message, reply or event.
>>> We ship a sample monitoring script examples/systemtap/qemu-monitor.stp
>>> for this too.
>>>
>> you definitely sold this to me :) Thank you for pointing this out.
>>
>> There is the only differences in the approaches:
>> - for example you have 20-50 VMs on the node
>> - you have 1 problematic VM to be debugged by support (not development)
>>
>> In this case with my approach the load to the host IO subsystem will
>> be less (logs from 1 VM will be written only).
> Yep I can see your point but not sure how critical it is in practice. In
> my experiance people often tend to just enable libvirt's QEMU debugging
> permanently on the basis that by the time you notice a fault with a VM
> it is too late to enable it. You often can't reproduce it, so can't just
> turn it on for 1 VM once a probem occurs, you have to proactively collect
> the data. In case where you do want to target a single VM though, there
> is the systemtap approach to collect info which may be sufficient
>
> Regards,
> Daniel
Paolo,

do you have any opinion on this?

Den

Re: [Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Paolo Bonzini]

On 14/03/2016 17:10, Denis V. Lunev wrote:
> On 03/14/2016 06:26 PM, Daniel P. Berrange wrote:
>> On Mon, Mar 14, 2016 at 06:05:07PM +0300, Denis V. Lunev wrote:
>>> On 03/14/2016 05:38 PM, Daniel P. Berrange wrote:
>>>> On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote:
>>>>> On 14/03/2016 12:21, Denis V. Lunev wrote:
>>>>>> From: Pavel Butsykin <pbutsykin@virtuozzo.com>
>>>>>>
>>>>>> This log would be very welcome for long-term diagnostics of the
>>>>>> system
>>>>>> in the production. This log is at least necessary to understand what
>>>>>> has been happened on the system and to identify issues at
>>>>>> higher-level
>>>>>> subsystems (libvirt, etc).
>>>>>>
>>>>>> These messages will be quite useful to understand how things are
>>>>>> going.
>>>>> There is now a logging mechanism for qemu-char.c.  Have you looked
>>>>> into
>>>>> making libvirt provide a QMP log based on it?
>>>>>
>>>>> The timestamping of patch 9 could be useful for character devices
>>>>> as well.
>>>> libvirt QEMU driver already has logging support for recording all
>>>> the data
>>>> it both sends and receives over QMP, which should be sufficient for any
>>>> day to day troubleshooting of QMP issues. So I doubt duplicating that
>>>> info from QEMU side too is really beneficial for debugging issues when
>>>> libvirt is in use.
>>>>
>>>> In libvirtd set
>>>>
>>>>    log_filters="1:qemu_monitor"
>>>>
>>>> and it'll capture everything on the QMP monitor in the default libvirtd
>>>> log file.
>>>>
>>>> The QMP data is also fed into the libvirt tracing backend, so you can
>>>> write systemtap scripts that hook on any QMP message, reply or event.
>>>> We ship a sample monitoring script examples/systemtap/qemu-monitor.stp
>>>> for this too.
>>>>
>>> you definitely sold this to me :) Thank you for pointing this out.
>>>
>>> There is the only differences in the approaches:
>>> - for example you have 20-50 VMs on the node
>>> - you have 1 problematic VM to be debugged by support (not development)
>>>
>>> In this case with my approach the load to the host IO subsystem will
>>> be less (logs from 1 VM will be written only).
>> Yep I can see your point but not sure how critical it is in practice. In
>> my experiance people often tend to just enable libvirt's QEMU debugging
>> permanently on the basis that by the time you notice a fault with a VM
>> it is too late to enable it. You often can't reproduce it, so can't just
>> turn it on for 1 VM once a probem occurs, you have to proactively collect
>> the data. In case where you do want to target a single VM though, there
>> is the systemtap approach to collect info which may be sufficient
> 
> do you have any opinion on this?

Daniel is usually very convincing to me as well. :)

Paolo

Re: [Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Daniel P. Berrange]

On Mon, Mar 14, 2016 at 03:26:04PM +0000, Daniel P. Berrange wrote:
> On Mon, Mar 14, 2016 at 06:05:07PM +0300, Denis V. Lunev wrote:
> > On 03/14/2016 05:38 PM, Daniel P. Berrange wrote:
> > >On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote:
> > >>
> > >>On 14/03/2016 12:21, Denis V. Lunev wrote:
> > >>>From: Pavel Butsykin <pbutsykin@virtuozzo.com>
> > >>>
> > >>>This log would be very welcome for long-term diagnostics of the system
> > >>>in the production. This log is at least necessary to understand what
> > >>>has been happened on the system and to identify issues at higher-level
> > >>>subsystems (libvirt, etc).
> > >>>
> > >>>These messages will be quite useful to understand how things are going.
> > >>There is now a logging mechanism for qemu-char.c.  Have you looked into
> > >>making libvirt provide a QMP log based on it?
> > >>
> > >>The timestamping of patch 9 could be useful for character devices as well.
> > >libvirt QEMU driver already has logging support for recording all the data
> > >it both sends and receives over QMP, which should be sufficient for any
> > >day to day troubleshooting of QMP issues. So I doubt duplicating that
> > >info from QEMU side too is really beneficial for debugging issues when
> > >libvirt is in use.
> > >
> > >In libvirtd set
> > >
> > >   log_filters="1:qemu_monitor"
> > >
> > >and it'll capture everything on the QMP monitor in the default libvirtd
> > >log file.
> > >
> > >The QMP data is also fed into the libvirt tracing backend, so you can
> > >write systemtap scripts that hook on any QMP message, reply or event.
> > >We ship a sample monitoring script examples/systemtap/qemu-monitor.stp
> > >for this too.
> > >
> > you definitely sold this to me :) Thank you for pointing this out.
> > 
> > There is the only differences in the approaches:
> > - for example you have 20-50 VMs on the node
> > - you have 1 problematic VM to be debugged by support (not development)
> > 
> > In this case with my approach the load to the host IO subsystem will
> > be less (logs from 1 VM will be written only).
> 
> Yep I can see your point but not sure how critical it is in practice. In
> my experiance people often tend to just enable libvirt's QEMU debugging
> permanently on the basis that by the time you notice a fault with a VM
> it is too late to enable it. You often can't reproduce it, so can't just
> turn it on for 1 VM once a probem occurs, you have to proactively collect
> the data. In case where you do want to target a single VM though, there
> is the systemtap approach to collect info which may be sufficient

BTW, I'm not against adding this to QEMU in general - just pointing out
that in the context of libvirt usage reference in the commit message,
it is not really needed. I'm totally ambivalent wrt adding this to QEMU
for benefit of non-libvirt usage.

Regards,
Daniel
-- 
|: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org              -o-             http://virt-manager.org :|
|: http://autobuild.org       -o-         http://search.cpan.org/~danberr/ :|
|: http://entangle-photo.org       -o-       http://live.gnome.org/gtk-vnc :|

Re: [Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Denis V. Lunev]

On 03/14/2016 07:11 PM, Daniel P. Berrange wrote:
> On Mon, Mar 14, 2016 at 03:26:04PM +0000, Daniel P. Berrange wrote:
>> On Mon, Mar 14, 2016 at 06:05:07PM +0300, Denis V. Lunev wrote:
>>> On 03/14/2016 05:38 PM, Daniel P. Berrange wrote:
>>>> On Mon, Mar 14, 2016 at 03:33:53PM +0100, Paolo Bonzini wrote:
>>>>> On 14/03/2016 12:21, Denis V. Lunev wrote:
>>>>>> From: Pavel Butsykin <pbutsykin@virtuozzo.com>
>>>>>>
>>>>>> This log would be very welcome for long-term diagnostics of the system
>>>>>> in the production. This log is at least necessary to understand what
>>>>>> has been happened on the system and to identify issues at higher-level
>>>>>> subsystems (libvirt, etc).
>>>>>>
>>>>>> These messages will be quite useful to understand how things are going.
>>>>> There is now a logging mechanism for qemu-char.c.  Have you looked into
>>>>> making libvirt provide a QMP log based on it?
>>>>>
>>>>> The timestamping of patch 9 could be useful for character devices as well.
>>>> libvirt QEMU driver already has logging support for recording all the data
>>>> it both sends and receives over QMP, which should be sufficient for any
>>>> day to day troubleshooting of QMP issues. So I doubt duplicating that
>>>> info from QEMU side too is really beneficial for debugging issues when
>>>> libvirt is in use.
>>>>
>>>> In libvirtd set
>>>>
>>>>    log_filters="1:qemu_monitor"
>>>>
>>>> and it'll capture everything on the QMP monitor in the default libvirtd
>>>> log file.
>>>>
>>>> The QMP data is also fed into the libvirt tracing backend, so you can
>>>> write systemtap scripts that hook on any QMP message, reply or event.
>>>> We ship a sample monitoring script examples/systemtap/qemu-monitor.stp
>>>> for this too.
>>>>
>>> you definitely sold this to me :) Thank you for pointing this out.
>>>
>>> There is the only differences in the approaches:
>>> - for example you have 20-50 VMs on the node
>>> - you have 1 problematic VM to be debugged by support (not development)
>>>
>>> In this case with my approach the load to the host IO subsystem will
>>> be less (logs from 1 VM will be written only).
>> Yep I can see your point but not sure how critical it is in practice. In
>> my experiance people often tend to just enable libvirt's QEMU debugging
>> permanently on the basis that by the time you notice a fault with a VM
>> it is too late to enable it. You often can't reproduce it, so can't just
>> turn it on for 1 VM once a probem occurs, you have to proactively collect
>> the data. In case where you do want to target a single VM though, there
>> is the systemtap approach to collect info which may be sufficient
> BTW, I'm not against adding this to QEMU in general - just pointing out
> that in the context of libvirt usage reference in the commit message,
> it is not really needed. I'm totally ambivalent wrt adding this to QEMU
> for benefit of non-libvirt usage.
>
> Regards,
> Daniel
I see. This just requires very clear commit message from my side.
Thank you for a discussion.

Den

Re: [Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Paolo Bonzini]

On 14/03/2016 17:16, Denis V. Lunev wrote:
>> BTW, I'm not against adding this to QEMU in general - just pointing out
>> that in the context of libvirt usage reference in the commit message,
>> it is not really needed. I'm totally ambivalent wrt adding this to QEMU
>> for benefit of non-libvirt usage.
>
> I see. This just requires very clear commit message from my side.
> Thank you for a discussion.

I think this is not a compelling usage of the logging subsystem; QMP is
always used through a character device, and character devices already
have a logging mechanism.

Adding a mechanism that looks for '\n' in the data written to a
character device and emits a timestamp on the next character would be a
useful addition.  I'd be entirely happy with adding it now, it should be
safe enough that we can do it during soft freeze.

Paolo

Re: [Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Denis V. Lunev]

On 03/14/2016 07:40 PM, Paolo Bonzini wrote:
>
> On 14/03/2016 17:16, Denis V. Lunev wrote:
>>> BTW, I'm not against adding this to QEMU in general - just pointing out
>>> that in the context of libvirt usage reference in the commit message,
>>> it is not really needed. I'm totally ambivalent wrt adding this to QEMU
>>> for benefit of non-libvirt usage.
>> I see. This just requires very clear commit message from my side.
>> Thank you for a discussion.
> I think this is not a compelling usage of the logging subsystem; QMP is
> always used through a character device, and character devices already
> have a logging mechanism.
>
> Adding a mechanism that looks for '\n' in the data written to a
> character device and emits a timestamp on the next character would be a
> useful addition.  I'd be entirely happy with adding it now, it should be
> safe enough that we can do it during soft freeze.
>
> Paolo
really interesting approach with a good place to get in.
But we will need to modify this a infrastructure a bit.
Af far as I can see only data from VM to outside world
is logged. Data being 'read' should be logged too as far
as I could understand.

Den

Re: [Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Paolo Bonzini]

On 16/03/2016 14:09, Denis V. Lunev wrote:
> really interesting approach with a good place to get in.
> But we will need to modify this a infrastructure a bit.
> Af far as I can see only data from VM to outside world
> is logged. Data being 'read' should be logged too as far
> as I could understand.

Hmm, you're right.  As a start, let's document in the release notes that
the format of the log file is subject to change.

Paolo

Re: [Qemu-devel] [PATCH 6/9] log: log QMP commands and replies

[Daniel P. Berrange]

On Wed, Mar 16, 2016 at 02:11:31PM +0100, Paolo Bonzini wrote:
> 
> 
> On 16/03/2016 14:09, Denis V. Lunev wrote:
> > really interesting approach with a good place to get in.
> > But we will need to modify this a infrastructure a bit.
> > Af far as I can see only data from VM to outside world
> > is logged. Data being 'read' should be logged too as far
> > as I could understand.
> 
> Hmm, you're right.  As a start, let's document in the release notes that
> the format of the log file is subject to change.

When logging terminal consoles (which motivated the feature) you don't
really want to log input, since the terminal will echo text back already
and you don't want to expose passwords sent in input either.

None the less I can see the value in logging input too for other use
cases. I could perhaps imagine a logdirection=in|out|both parameter
being added to the -chardev to control this.

Regards,
Daniel
-- 
|: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org              -o-             http://virt-manager.org :|
|: http://autobuild.org       -o-         http://search.cpan.org/~danberr/ :|
|: http://entangle-photo.org       -o-       http://live.gnome.org/gtk-vnc :|

[Qemu-devel] [PATCH 7/9] log: report HMP command and event

[Denis V. Lunev]

From: Pavel Butsykin <pbutsykin@virtuozzo.com>

Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: Stefan Hajnoczi <stefanha@redhat.com>
CC: Paolo Bonzini <pbonzini@redhat.com>
CC: Luiz Capitulino <lcapitulino@redhat.com>
CC: Markus Armbruster <armbru@redhat.com>
CC: Eric Blake <eblake@redhat.com>
---
 include/qemu/log.h | 1 +
 monitor.c          | 4 ++++
 util/log.c         | 2 ++
 3 files changed, 7 insertions(+)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index 55bceae..9264bbf 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -43,6 +43,7 @@ static inline bool qemu_log_separate(void)
 #define CPU_LOG_PAGE       (1 << 14)
 #define LOG_TRACE          (1 << 15)
 #define LOG_QMP            (1 << 16)
+#define LOG_HMP            (1 << 17)
 
 /* Returns true if a bit is set in the current loglevel mask
  */
diff --git a/monitor.c b/monitor.c
index eec4e58..4bf4f31 100644
--- a/monitor.c
+++ b/monitor.c
@@ -2893,6 +2893,8 @@ static void handle_hmp_command(Monitor *mon, const char *cmdline)
     QDict *qdict;
     const mon_cmd_t *cmd;
 
+    qemu_log_mask(LOG_HMP, "HMP command: %s\n", cmdline);
+
     cmd = monitor_parse_command(mon, &cmdline, mon->cmd_table);
     if (!cmd) {
         return;
@@ -4053,11 +4055,13 @@ static void monitor_event(void *opaque, int event)
         }
         mon->reset_seen = 1;
         mon_refcount++;
+        qemu_log_mask(LOG_HMP, "HMP: new connection established\n");
         break;
 
     case CHR_EVENT_CLOSED:
         mon_refcount--;
         monitor_fdsets_cleanup();
+        qemu_log_mask(LOG_HMP, "HMP: connection closed\n");
         break;
     }
 }
diff --git a/util/log.c b/util/log.c
index 5fc517b..795aaea 100644
--- a/util/log.c
+++ b/util/log.c
@@ -133,6 +133,8 @@ const QEMULogItem qemu_log_items[] = {
       "complete traces" },
     { LOG_QMP, "qmp",
       "log the QMP commands and events" },
+    { LOG_HMP, "hmp",
+      "log the HMP commands and events" },
     { 0, NULL, NULL },
 };
 
-- 
2.5.0

Re: [Qemu-devel] [PATCH 7/9] log: report HMP command and event

[Paolo Bonzini]

On 14/03/2016 12:21, Denis V. Lunev wrote:
> From: Pavel Butsykin <pbutsykin@virtuozzo.com>

Please explain the usecase here.  Is it for debugging the hypervisor or
for something else?

Paolo

> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: Stefan Hajnoczi <stefanha@redhat.com>
> CC: Paolo Bonzini <pbonzini@redhat.com>
> CC: Luiz Capitulino <lcapitulino@redhat.com>
> CC: Markus Armbruster <armbru@redhat.com>
> CC: Eric Blake <eblake@redhat.com>
> ---
>  include/qemu/log.h | 1 +
>  monitor.c          | 4 ++++
>  util/log.c         | 2 ++
>  3 files changed, 7 insertions(+)
> 
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index 55bceae..9264bbf 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -43,6 +43,7 @@ static inline bool qemu_log_separate(void)
>  #define CPU_LOG_PAGE       (1 << 14)
>  #define LOG_TRACE          (1 << 15)
>  #define LOG_QMP            (1 << 16)
> +#define LOG_HMP            (1 << 17)
>  
>  /* Returns true if a bit is set in the current loglevel mask
>   */
> diff --git a/monitor.c b/monitor.c
> index eec4e58..4bf4f31 100644
> --- a/monitor.c
> +++ b/monitor.c
> @@ -2893,6 +2893,8 @@ static void handle_hmp_command(Monitor *mon, const char *cmdline)
>      QDict *qdict;
>      const mon_cmd_t *cmd;
>  
> +    qemu_log_mask(LOG_HMP, "HMP command: %s\n", cmdline);
> +
>      cmd = monitor_parse_command(mon, &cmdline, mon->cmd_table);
>      if (!cmd) {
>          return;
> @@ -4053,11 +4055,13 @@ static void monitor_event(void *opaque, int event)
>          }
>          mon->reset_seen = 1;
>          mon_refcount++;
> +        qemu_log_mask(LOG_HMP, "HMP: new connection established\n");
>          break;
>  
>      case CHR_EVENT_CLOSED:
>          mon_refcount--;
>          monitor_fdsets_cleanup();
> +        qemu_log_mask(LOG_HMP, "HMP: connection closed\n");
>          break;
>      }
>  }
> diff --git a/util/log.c b/util/log.c
> index 5fc517b..795aaea 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -133,6 +133,8 @@ const QEMULogItem qemu_log_items[] = {
>        "complete traces" },
>      { LOG_QMP, "qmp",
>        "log the QMP commands and events" },
> +    { LOG_HMP, "hmp",
> +      "log the HMP commands and events" },
>      { 0, NULL, NULL },
>  };
>  
> 

Re: [Qemu-devel] [PATCH 7/9] log: report HMP command and event

[Denis V. Lunev]

On 03/14/2016 05:36 PM, Paolo Bonzini wrote:
> On 14/03/2016 12:21, Denis V. Lunev wrote:
>> From: Pavel Butsykin <pbutsykin@virtuozzo.com>
> Please explain the usecase here.  Is it for debugging the hypervisor or
> for something else?
>
> Paolo
yes. There are important HMP-only commands like switch to snapshot,
which should be logged. The rest is the same as I have answered to
Daniel to patch 6.

Den

Re: [Qemu-devel] [PATCH 7/9] log: report HMP command and event

[Paolo Bonzini]

On 14/03/2016 16:08, Denis V. Lunev wrote:
>> Please explain the usecase here.  Is it for debugging the hypervisor or
>> for something else?
>
> yes. There are important HMP-only commands like switch to snapshot,
> which should be logged. The rest is the same as I have answered to
> Daniel to patch 6.

Wouldn't they be logged through the human-monitor-command QMP command?

Paolo

[Qemu-devel] [PATCH 8/9] log: report QAPI event

[Denis V. Lunev]

From: Pavel Butsykin <pbutsykin@virtuozzo.com>

Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: Stefan Hajnoczi <stefanha@redhat.com>
CC: Paolo Bonzini <pbonzini@redhat.com>
CC: Luiz Capitulino <lcapitulino@redhat.com>
CC: Markus Armbruster <armbru@redhat.com>
---
 include/qemu/log.h | 1 +
 monitor.c          | 6 ++++++
 util/log.c         | 2 ++
 3 files changed, 9 insertions(+)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index 9264bbf..0c7a564 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -44,6 +44,7 @@ static inline bool qemu_log_separate(void)
 #define LOG_TRACE          (1 << 15)
 #define LOG_QMP            (1 << 16)
 #define LOG_HMP            (1 << 17)
+#define LOG_QAPI           (1 << 18)
 
 /* Returns true if a bit is set in the current loglevel mask
  */
diff --git a/monitor.c b/monitor.c
index 4bf4f31..751e754 100644
--- a/monitor.c
+++ b/monitor.c
@@ -467,6 +467,12 @@ static void monitor_qapi_event_emit(QAPIEvent event, QDict *qdict)
 {
     Monitor *mon;
 
+    if (qemu_loglevel_mask(LOG_QAPI)) {
+        QString *output_json = qobject_to_json(QOBJECT(qdict));
+        qemu_log_mask(LOG_QAPI, "QAPI event: %s\n", output_json->string);
+        QDECREF(output_json);
+    }
+
     trace_monitor_protocol_event_emit(event, qdict);
     QLIST_FOREACH(mon, &mon_list, entry) {
         if (monitor_is_qmp(mon) && mon->qmp.in_command_mode) {
diff --git a/util/log.c b/util/log.c
index 795aaea..572f005 100644
--- a/util/log.c
+++ b/util/log.c
@@ -135,6 +135,8 @@ const QEMULogItem qemu_log_items[] = {
       "log the QMP commands and events" },
     { LOG_HMP, "hmp",
       "log the HMP commands and events" },
+    { LOG_QAPI, "qapi",
+      "log the QAPI events"},
     { 0, NULL, NULL },
 };
 
-- 
2.5.0

Re: [Qemu-devel] [PATCH 8/9] log: report QAPI event

[Paolo Bonzini]

On 14/03/2016 12:21, Denis V. Lunev wrote:
> From: Pavel Butsykin <pbutsykin@virtuozzo.com>
> 
> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: Stefan Hajnoczi <stefanha@redhat.com>
> CC: Paolo Bonzini <pbonzini@redhat.com>
> CC: Luiz Capitulino <lcapitulino@redhat.com>
> CC: Markus Armbruster <armbru@redhat.com>
> ---
>  include/qemu/log.h | 1 +
>  monitor.c          | 6 ++++++
>  util/log.c         | 2 ++
>  3 files changed, 9 insertions(+)
> 
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index 9264bbf..0c7a564 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -44,6 +44,7 @@ static inline bool qemu_log_separate(void)
>  #define LOG_TRACE          (1 << 15)
>  #define LOG_QMP            (1 << 16)
>  #define LOG_HMP            (1 << 17)
> +#define LOG_QAPI           (1 << 18)

This should just reuse LOG_QMP (but see reply to patch 6).

Paolo

>  /* Returns true if a bit is set in the current loglevel mask
>   */
> diff --git a/monitor.c b/monitor.c
> index 4bf4f31..751e754 100644
> --- a/monitor.c
> +++ b/monitor.c
> @@ -467,6 +467,12 @@ static void monitor_qapi_event_emit(QAPIEvent event, QDict *qdict)
>  {
>      Monitor *mon;
>  
> +    if (qemu_loglevel_mask(LOG_QAPI)) {
> +        QString *output_json = qobject_to_json(QOBJECT(qdict));
> +        qemu_log_mask(LOG_QAPI, "QAPI event: %s\n", output_json->string);
> +        QDECREF(output_json);
> +    }
> +
>      trace_monitor_protocol_event_emit(event, qdict);
>      QLIST_FOREACH(mon, &mon_list, entry) {
>          if (monitor_is_qmp(mon) && mon->qmp.in_command_mode) {
> diff --git a/util/log.c b/util/log.c
> index 795aaea..572f005 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -135,6 +135,8 @@ const QEMULogItem qemu_log_items[] = {
>        "log the QMP commands and events" },
>      { LOG_HMP, "hmp",
>        "log the HMP commands and events" },
> +    { LOG_QAPI, "qapi",
> +      "log the QAPI events"},
>      { 0, NULL, NULL },
>  };
>  
> 

[Qemu-devel] [PATCH 9/9] log: adds a timestamp to each log entry

[Denis V. Lunev]

From: Pavel Butsykin <pbutsykin@virtuozzo.com>

This patch is written as an addition to the previous one with logging of
QPM commands. This information (the moment of the event) is very useful
to match guest problems with actions performing by management software.

example:
2015-10-19T08:52:57.859786Z QAPI event: { "timestamp":{"seconds":
        1445244777, "microseconds": 859721}, "event": "RESUME" }
2015-10-19T08:53:03.524088Z QMP event: new connection established
2015-10-19T08:53:11.816711Z QMP command request: {
        "execute": "qmp_capabilities" }
2015-10-19T08:53:11.816791Z QMP command response: { "return": {}}

Using timestamp for qemu_log_vprintf(), log_cpu_state() it is not advisable,
because that will lead to previously unexpected results.
Excessive conclusions timestamps for all that use qemu_log_vprintf:
    qemu_log("qemu: fatal: ");
    qemu_log_vprintf(fmt, ap2);
    ...
The distortion of the output format for log_cpu_state:
    qemu_log_mask(CPU_LOG_INT, "SMM: enter\n");
    log_cpu_state_mask(CPU_LOG_INT, CPU(cpu), CPU_DUMP_CCOP);
    ...
In all variants qemu_log invoked as the design and the timestamp will
be present.

This patch is not perfect as messages from different threads could
interleave but this is not a big deal, timestamps are nearly the
same.

Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: Stefan Hajnoczi <stefanha@redhat.com>
CC: Paolo Bonzini <pbonzini@redhat.com>
CC: Markus Armbruster <armbru@redhat.com>
---
 include/qemu/log.h |  5 ++++-
 util/log.c         | 26 ++++++++++++++++++++++++++
 2 files changed, 30 insertions(+), 1 deletion(-)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index 0c7a564..5fe1962 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -45,6 +45,7 @@ static inline bool qemu_log_separate(void)
 #define LOG_QMP            (1 << 16)
 #define LOG_HMP            (1 << 17)
 #define LOG_QAPI           (1 << 18)
+#define LOG_TIME           (1 << 19)
 
 /* Returns true if a bit is set in the current loglevel mask
  */
@@ -55,6 +56,8 @@ static inline bool qemu_loglevel_mask(int mask)
 
 /* Logging functions: */
 
+void qemu_do_log(const char *fmt, ...) GCC_FMT_ATTR(1, 2);
+
 /* main logging function
  */
 #define qemu_log(...)                          \
@@ -79,7 +82,7 @@ qemu_log_vprintf(const char *fmt, va_list va)
 #define qemu_log_mask(mask, ...)                                \
     do {                                                        \
         if ((qemu_loglevel & (mask)) && qemu_log_enabled()) {   \
-           fprintf(qemu_logfile, __VA_ARGS__);                  \
+           qemu_do_log(__VA_ARGS__);                            \
         }                                                       \
     } while (0)
 
diff --git a/util/log.c b/util/log.c
index 572f005..fb562c1 100644
--- a/util/log.c
+++ b/util/log.c
@@ -28,6 +28,30 @@ int qemu_loglevel;
 static int log_append = 0;
 
 
+static void qemu_log_time(void)
+{
+    GTimeVal tv;
+    gchar *timestr;
+
+    g_get_current_time(&tv);
+
+    timestr = g_time_val_to_iso8601(&tv);
+    fprintf(qemu_logfile, "%s ", timestr);
+    g_free(timestr);
+}
+
+void qemu_do_log(const char *fmt, ...)
+{
+    va_list ap;
+
+    if (qemu_loglevel & LOG_TIME) {
+        qemu_log_time();
+    }
+    va_start(ap, fmt);
+    vfprintf(qemu_logfile, fmt, ap);
+    va_end(ap);
+}
+
 /* enable or disable low levels log */
 void do_qemu_set_log(int log_flags, bool use_own_buffers)
 {
@@ -137,6 +161,8 @@ const QEMULogItem qemu_log_items[] = {
       "log the HMP commands and events" },
     { LOG_QAPI, "qapi",
       "log the QAPI events"},
+    { LOG_TIME, "time",
+      "add a timestamp to each log entry" },
     { 0, NULL, NULL },
 };
 
-- 
2.5.0

Re: [Qemu-devel] [PATCH 9/9] log: adds a timestamp to each log entry

[Paolo Bonzini]

On 14/03/2016 12:21, Denis V. Lunev wrote:
> This patch is not perfect as messages from different threads could
> interleave but this is not a big deal, timestamps are nearly the
> same.

You could use flockfile and funlockfile to avoid this.

Paolo