[Qemu-devel] [PATCH 1/1] log hmp/qmp command

[Qemu-devel] [PATCH 1/1] log hmp/qmp command

[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).

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

diff --git a/include/qemu/log.h b/include/qemu/log.h
index f880e66..dfb587e 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -41,6 +41,7 @@ static inline bool qemu_log_enabled(void)
 #define LOG_UNIMP          (1 << 10)
 #define LOG_GUEST_ERROR    (1 << 11)
 #define CPU_LOG_MMU        (1 << 12)
+#define LOG_CMD            (1 << 13)
 
 /* Returns true if a bit is set in the current loglevel mask
  */
diff --git a/monitor.c b/monitor.c
index 4f1ba2f..a22a798 100644
--- a/monitor.c
+++ b/monitor.c
@@ -2848,6 +2848,8 @@ static void handle_hmp_command(Monitor *mon, const char *cmdline)
     QDict *qdict;
     const mon_cmd_t *cmd;
 
+    qemu_log_mask(LOG_CMD, "hmp \"%s\" requested\n", cmdline);
+
     cmd = monitor_parse_command(mon, &cmdline, mon->cmd_table);
     if (!cmd) {
         return;
@@ -3822,6 +3824,8 @@ static void handle_qmp_command(JSONMessageParser *parser, QList *tokens)
         error_setg(&local_err, QERR_JSON_PARSING);
         goto err_out;
     }
+    qemu_log_mask(LOG_CMD, "qmp \"%s\" requested\n",
+                  qobject_to_json(obj)->string);
 
     input = qmp_check_input_obj(obj, &local_err);
     if (!input) {
diff --git a/qemu-log.c b/qemu-log.c
index 13f3813..66b15ec 100644
--- a/qemu-log.c
+++ b/qemu-log.c
@@ -119,6 +119,7 @@ const QEMULogItem qemu_log_items[] = {
     { LOG_GUEST_ERROR, "guest_errors",
       "log when the guest OS does something invalid (eg accessing a\n"
       "non-existent register)" },
+    { LOG_CMD, "cmd", "log the hmp/qmp commands execution" },
     { 0, NULL, NULL },
 };
 
-- 
2.1.4

Re: [Qemu-devel] [PATCH 1/1] log hmp/qmp command

[Denis V. Lunev]

On 10/12/2015 11:41 AM, 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).
>
> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: Markus Armbruster <armbru@redhat.com>
> CC: Luiz Capitulino <lcapitulino@redhat.com>
> CC: Eric Blake <eblake@redhat.com>
> ---
>   include/qemu/log.h | 1 +
>   monitor.c          | 4 ++++
>   qemu-log.c         | 1 +
>   3 files changed, 6 insertions(+)
>
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index f880e66..dfb587e 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -41,6 +41,7 @@ static inline bool qemu_log_enabled(void)
>   #define LOG_UNIMP          (1 << 10)
>   #define LOG_GUEST_ERROR    (1 << 11)
>   #define CPU_LOG_MMU        (1 << 12)
> +#define LOG_CMD            (1 << 13)
>   
>   /* Returns true if a bit is set in the current loglevel mask
>    */
> diff --git a/monitor.c b/monitor.c
> index 4f1ba2f..a22a798 100644
> --- a/monitor.c
> +++ b/monitor.c
> @@ -2848,6 +2848,8 @@ static void handle_hmp_command(Monitor *mon, const char *cmdline)
>       QDict *qdict;
>       const mon_cmd_t *cmd;
>   
> +    qemu_log_mask(LOG_CMD, "hmp \"%s\" requested\n", cmdline);
> +
>       cmd = monitor_parse_command(mon, &cmdline, mon->cmd_table);
>       if (!cmd) {
>           return;
> @@ -3822,6 +3824,8 @@ static void handle_qmp_command(JSONMessageParser *parser, QList *tokens)
>           error_setg(&local_err, QERR_JSON_PARSING);
>           goto err_out;
>       }
> +    qemu_log_mask(LOG_CMD, "qmp \"%s\" requested\n",
> +                  qobject_to_json(obj)->string);
it seems that QString here is leaked

>   
>       input = qmp_check_input_obj(obj, &local_err);
>       if (!input) {
> diff --git a/qemu-log.c b/qemu-log.c
> index 13f3813..66b15ec 100644
> --- a/qemu-log.c
> +++ b/qemu-log.c
> @@ -119,6 +119,7 @@ const QEMULogItem qemu_log_items[] = {
>       { LOG_GUEST_ERROR, "guest_errors",
>         "log when the guest OS does something invalid (eg accessing a\n"
>         "non-existent register)" },
> +    { LOG_CMD, "cmd", "log the hmp/qmp commands execution" },
>       { 0, NULL, NULL },
>   };
>   

Re: [Qemu-devel] [PATCH 1/1] log hmp/qmp command

[Eric Blake]

[-- Attachment #1: Type: text/plain, Size: 1289 bytes --]

On 10/12/2015 02:41 AM, 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).
> 
> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: Markus Armbruster <armbru@redhat.com>
> CC: Luiz Capitulino <lcapitulino@redhat.com>
> CC: Eric Blake <eblake@redhat.com>
> ---

> @@ -3822,6 +3824,8 @@ static void handle_qmp_command(JSONMessageParser *parser, QList *tokens)
>          error_setg(&local_err, QERR_JSON_PARSING);
>          goto err_out;
>      }
> +    qemu_log_mask(LOG_CMD, "qmp \"%s\" requested\n",
> +                  qobject_to_json(obj)->string);
>  

In addition to the leak already pointed out, qobject_to_json() can be
expensive, and it looks like we are doing that work unconditionally even
if the logging is not turned on. Is there a way to optimize so that the
conversion is only done when logging is enabled?

-- 
Eric Blake   eblake redhat com    +1-919-301-3266
Libvirt virtualization library http://libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

Re: [Qemu-devel] [PATCH 1/1] log hmp/qmp command

[Denis V. Lunev]

On 10/12/2015 04:49 PM, Eric Blake wrote:
> On 10/12/2015 02:41 AM, 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).
>>
>> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>> CC: Markus Armbruster <armbru@redhat.com>
>> CC: Luiz Capitulino <lcapitulino@redhat.com>
>> CC: Eric Blake <eblake@redhat.com>
>> ---
>> @@ -3822,6 +3824,8 @@ static void handle_qmp_command(JSONMessageParser *parser, QList *tokens)
>>           error_setg(&local_err, QERR_JSON_PARSING);
>>           goto err_out;
>>       }
>> +    qemu_log_mask(LOG_CMD, "qmp \"%s\" requested\n",
>> +                  qobject_to_json(obj)->string);
>>   
> In addition to the leak already pointed out, qobject_to_json() can be
> expensive, and it looks like we are doing that work unconditionally even
> if the logging is not turned on. Is there a way to optimize so that the
> conversion is only done when logging is enabled?
>
this seems quite reasonable.

Will it be good if we'll change logging implementation to
use macros, something like

#define qemu_log_mask(int mask, const char *ftp, ...) \
do { \
va_list ap; \
   \
if (!(qemu_loglevel & mask) || !qemu_logfile) {\
       break;\
   }\
   qemu_log(ftp, __VA_ARGS__); \
} while (0)

This IMHO makes sense even out of the scope of this patch.

Den

Re: [Qemu-devel] [PATCH 1/1] log hmp/qmp command

[Luiz Capitulino]

On Mon, 12 Oct 2015 11:41:35 +0300
"Denis V. Lunev" <den@openvz.org> 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).

This is good to have, and probably we should have had it since day one.
But I have the following considerations:

 - libvirt would need support for this to use it the way you describe,
   although libvirt already has its logging facility (well, one could
   wrap qemu in bash and pass this by default but this is not ideal)

 - A true logging facility would also log responses and events

 - I don't think it's important to log HMP

> 
> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: Markus Armbruster <armbru@redhat.com>
> CC: Luiz Capitulino <lcapitulino@redhat.com>
> CC: Eric Blake <eblake@redhat.com>
> ---
>  include/qemu/log.h | 1 +
>  monitor.c          | 4 ++++
>  qemu-log.c         | 1 +
>  3 files changed, 6 insertions(+)
> 
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index f880e66..dfb587e 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -41,6 +41,7 @@ static inline bool qemu_log_enabled(void)
>  #define LOG_UNIMP          (1 << 10)
>  #define LOG_GUEST_ERROR    (1 << 11)
>  #define CPU_LOG_MMU        (1 << 12)
> +#define LOG_CMD            (1 << 13)
>  
>  /* Returns true if a bit is set in the current loglevel mask
>   */
> diff --git a/monitor.c b/monitor.c
> index 4f1ba2f..a22a798 100644
> --- a/monitor.c
> +++ b/monitor.c
> @@ -2848,6 +2848,8 @@ static void handle_hmp_command(Monitor *mon, const char *cmdline)
>      QDict *qdict;
>      const mon_cmd_t *cmd;
>  
> +    qemu_log_mask(LOG_CMD, "hmp \"%s\" requested\n", cmdline);
> +
>      cmd = monitor_parse_command(mon, &cmdline, mon->cmd_table);
>      if (!cmd) {
>          return;
> @@ -3822,6 +3824,8 @@ static void handle_qmp_command(JSONMessageParser *parser, QList *tokens)
>          error_setg(&local_err, QERR_JSON_PARSING);
>          goto err_out;
>      }
> +    qemu_log_mask(LOG_CMD, "qmp \"%s\" requested\n",
> +                  qobject_to_json(obj)->string);
>  
>      input = qmp_check_input_obj(obj, &local_err);
>      if (!input) {
> diff --git a/qemu-log.c b/qemu-log.c
> index 13f3813..66b15ec 100644
> --- a/qemu-log.c
> +++ b/qemu-log.c
> @@ -119,6 +119,7 @@ const QEMULogItem qemu_log_items[] = {
>      { LOG_GUEST_ERROR, "guest_errors",
>        "log when the guest OS does something invalid (eg accessing a\n"
>        "non-existent register)" },
> +    { LOG_CMD, "cmd", "log the hmp/qmp commands execution" },
>      { 0, NULL, NULL },
>  };
>  

Re: [Qemu-devel] [PATCH 1/1] log hmp/qmp command

[Denis V. Lunev]

On 10/13/2015 04:05 PM, Luiz Capitulino wrote:
> On Mon, 12 Oct 2015 11:41:35 +0300
> "Denis V. Lunev" <den@openvz.org> 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).
> This is good to have, and probably we should have had it since day one.
> But I have the following considerations:
>
>   - libvirt would need support for this to use it the way you describe,
>     although libvirt already has its logging facility (well, one could
>     wrap qemu in bash and pass this by default but this is not ideal)
OK, I'll add task to the queue for our libvirt guys

>   - A true logging facility would also log responses and events
responses are done alreade internally in the scope of preparations
to the next submission, events are missed. Thank you for pointing
this out

>   - I don't think it's important to log HMP

OK, but I do not that that this will hurt us :)

Den

>> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>> CC: Markus Armbruster <armbru@redhat.com>
>> CC: Luiz Capitulino <lcapitulino@redhat.com>
>> CC: Eric Blake <eblake@redhat.com>
>> ---
>>   include/qemu/log.h | 1 +
>>   monitor.c          | 4 ++++
>>   qemu-log.c         | 1 +
>>   3 files changed, 6 insertions(+)
>>
>> diff --git a/include/qemu/log.h b/include/qemu/log.h
>> index f880e66..dfb587e 100644
>> --- a/include/qemu/log.h
>> +++ b/include/qemu/log.h
>> @@ -41,6 +41,7 @@ static inline bool qemu_log_enabled(void)
>>   #define LOG_UNIMP          (1 << 10)
>>   #define LOG_GUEST_ERROR    (1 << 11)
>>   #define CPU_LOG_MMU        (1 << 12)
>> +#define LOG_CMD            (1 << 13)
>>   
>>   /* Returns true if a bit is set in the current loglevel mask
>>    */
>> diff --git a/monitor.c b/monitor.c
>> index 4f1ba2f..a22a798 100644
>> --- a/monitor.c
>> +++ b/monitor.c
>> @@ -2848,6 +2848,8 @@ static void handle_hmp_command(Monitor *mon, const char *cmdline)
>>       QDict *qdict;
>>       const mon_cmd_t *cmd;
>>   
>> +    qemu_log_mask(LOG_CMD, "hmp \"%s\" requested\n", cmdline);
>> +
>>       cmd = monitor_parse_command(mon, &cmdline, mon->cmd_table);
>>       if (!cmd) {
>>           return;
>> @@ -3822,6 +3824,8 @@ static void handle_qmp_command(JSONMessageParser *parser, QList *tokens)
>>           error_setg(&local_err, QERR_JSON_PARSING);
>>           goto err_out;
>>       }
>> +    qemu_log_mask(LOG_CMD, "qmp \"%s\" requested\n",
>> +                  qobject_to_json(obj)->string);
>>   
>>       input = qmp_check_input_obj(obj, &local_err);
>>       if (!input) {
>> diff --git a/qemu-log.c b/qemu-log.c
>> index 13f3813..66b15ec 100644
>> --- a/qemu-log.c
>> +++ b/qemu-log.c
>> @@ -119,6 +119,7 @@ const QEMULogItem qemu_log_items[] = {
>>       { LOG_GUEST_ERROR, "guest_errors",
>>         "log when the guest OS does something invalid (eg accessing a\n"
>>         "non-existent register)" },
>> +    { LOG_CMD, "cmd", "log the hmp/qmp commands execution" },
>>       { 0, NULL, NULL },
>>   };
>>