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

[Pavel Butsykin]

On 16.10.2015 10:34, Markus Armbruster wrote:
> "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...
I think so much more convenient to read the log, for example:
qmp requested:
{
    "execute": "query-block"
}
qmp responsed:
{
    "return": [
        {
            "io-status": "ok",
            "device": "drive-virtio-disk0",
            "locked": false,
            "removable": false,
            "inserted": {
                "iops_rd": 0,
                "detect_zeroes": "off",
                "image": {
                    "snapshots": [
                        {
                            "vm-clock-nsec": 235120743,
                            "name": "snap4",
                            "date-sec": 1444402741,
                            "date-nsec": 246561000,
                            "vm-clock-sec": 42,
                            "id": "2",
                            "vm-state-size": 247252333
                        },
...

if we just use qobject_to_json(), it will be a long string, which may be 
difficult to understand.

> Nitpick: we generally spell it QMP.
Ok.

> >       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.
I agree, just missed this point. In this case, we are interested in 
logging QAPI and QMP events. For QAPI events point logging can be put in 
monitor_qapi_event_emit(), it should solve the problem with rate-limit. 
For QMP(and monitor_json_emitter) more suitable put it in each of its 
callers, because it is not known what is this call(it the request, 
response or event).

> > @@ -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.
It is understood that the request came to execute the command.

> > 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.
Ok.