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

[Markus Armbruster <armbru@redhat.com>]

Pavel Butsykin <pbutsykin@odin.com> writes:

> On 16.10.2015 10:34, Markus Armbruster wrote:
>> "Denis V. Lunev" <den@openvz.org> writes:
>>
>>> 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>
>>> CC: Peter Maydell <peter.maydell@linaro.org>
>>> ---
>>>   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.

Log files should be utterly trivial to parse.  That means a rigid
format.

The traditional format is one line per entry, prefixed with a timestamp.

Extracting JSON from such lines and feeding it to a pretty-printer is
bothersome, but it's at least feasible.

Reliably finding log message boundaries in a log file without rules on
message format generally isn't.

I'm not sure how the log.h interface is currently used.  Are there any
rules, or is it a "barf whatever text you like to the log file" thing?

If there are rules, we should stick to them.

If there are none, I'd seriously consider giving up on this log file and
create a new one that's actually parseable.

See also "What's the intended use of log.h logging?"

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

It's just terminology, but I like *consistent* terminology.
docs/qmp-spec.txt calls it 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.
>>
> Ok.