Re: [Qemu-devel] [PATCH 2/3] log: report hmp/qmp command and qmp event

[Markus Armbruster]

"Denis V. Lunev" <address@hidden> writes:

> From: Pavel Butsykin <address@hidden>
>
> 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 <address@hidden>
> Signed-off-by: Denis V. Lunev <address@hidden>
> CC: Markus Armbruster <address@hidden>
> CC: Luiz Capitulino <address@hidden>
> CC: Eric Blake <address@hidden>
> CC: Peter Maydell <address@hidden>
> ---
>  include/qemu/log.h |  1 +
>  monitor.c          | 18 ++++++++++++++++++
>  qemu-log.c         |  1 +
>  3 files changed, 20 insertions(+)
>
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index 57b8c96..ba86606 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..71810bb 100644
> --- a/monitor.c
> +++ b/monitor.c
> @@ -434,6 +434,12 @@ static void monitor_protocol_emitter(Monitor *mon, 
> QObject *data,
>      }
>  
>      monitor_json_emitter(mon, QOBJECT(qmp));
> +    if (qemu_loglevel_mask(LOG_CMD)) {
> +        QString *output_json = qobject_to_json_pretty(QOBJECT(qmp));
> +        qemu_log("qmp response:\n%s\n", output_json->string);
> +        QDECREF(output_json);
> +    }
> +

Uh, _pretty makes this multiple lines.  Is this appropriate for the log
file?  Finding log message boundaries goes from regular to
context-free...

Nitpick: we generally spell it QMP.

>      QDECREF(qmp);
>  }
>  
> @@ -474,6 +480,11 @@ monitor_qapi_event_queue(QAPIEvent event, QDict *data, 
> Error **errp)
>                                         evstate->last,
>                                         now);
>  
> +    if (qemu_loglevel_mask(LOG_CMD)) {
> +        QString *output_json = qobject_to_json_pretty(QOBJECT(data));
> +        qemu_log("qmp event:\n%s\n", output_json->string);
> +        QDECREF(output_json);
> +    }

This does *not* log QMP events (the ones put on the wire), it logs
*QAPI* events, which may or may not put on the wire due to rate
limiting.

Are you sure we don't want to rate-limit log messages?

If you really want to log QAPI events rather than QMP events, you get to
explain why in the commit message, and you get to document the
difference between the log and the actual wire.

But I suspect you merely put this in the wrong place :)

>      /* Rate limit of 0 indicates no throttling */
>      qemu_mutex_lock(&monitor_lock);
>      if (!evstate->rate) {

Not logged: the QMP greeting.  If you want to log QMP, log all of QMP.

You can either put the logging of the transmit direction in
monitor_json_emitter(), or you put it in each of its callers.

> @@ -2848,6 +2859,8 @@ static void handle_hmp_command(Monitor *mon, const char 
> *cmdline)
>      QDict *qdict;
>      const mon_cmd_t *cmd;
>  
> +    qemu_log_mask(LOG_CMD, "hmp request:\n%s\n", cmdline);
> +
>      cmd = monitor_parse_command(mon, &cmdline, mon->cmd_table);
>      if (!cmd) {
>          return;
> @@ -3823,6 +3836,11 @@ static void handle_qmp_command(JSONMessageParser 
> *parser, QList *tokens)
>          goto err_out;
>      }
>  
> +    if (qemu_loglevel_mask(LOG_CMD)) {
> +        QString *output_json = output_json = qobject_to_json_pretty(obj);
> +        qemu_log("qmp request:\n%s\n", output_json->string);
> +        QDECREF(output_json);
> +    }
>      input = qmp_check_input_obj(obj, &local_err);
>      if (!input) {
>          qobject_decref(obj);

Nitpick: QMP calls this a command, not a request.

> diff --git a/qemu-log.c b/qemu-log.c
> index e6d2b3f..ba7b34c 100644
> --- a/qemu-log.c
> +++ b/qemu-log.c
> @@ -98,6 +98,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 },
>  };

I can't quite see the use case for logging HMP, but since you wrote it,
I assume you got one.

Regardless, separate flags and patches for QMP and HMP, please.