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

[Pavel Butsykin <pbutsykin@odin.com>]

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.

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