From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from eggs.gnu.org ([2001:4830:134:3::10]:47748) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Zn1gn-0006mh-J7 for qemu-devel@nongnu.org; Fri, 16 Oct 2015 05:52:42 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1Zn1gk-0001mt-Ak for qemu-devel@nongnu.org; Fri, 16 Oct 2015 05:52:41 -0400 Received: from mx2.parallels.com ([199.115.105.18]:57118) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Zn1gk-0001kN-1d for qemu-devel@nongnu.org; Fri, 16 Oct 2015 05:52:38 -0400 Message-ID: <5620C8BD.9020106@odin.com> Date: Fri, 16 Oct 2015 12:51:57 +0300 From: Pavel Butsykin MIME-Version: 1.0 References: <1444894224-9542-1-git-send-email-den@openvz.org> <1444894224-9542-3-git-send-email-den@openvz.org> <87r3kvs1vf.fsf@blackfin.pond.sub.org> In-Reply-To: <87r3kvs1vf.fsf@blackfin.pond.sub.org> Content-Type: text/plain; charset="windows-1252"; format=flowed Content-Transfer-Encoding: 7bit Subject: Re: [Qemu-devel] [PATCH 2/3] log: report hmp/qmp command and qmp event List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: Markus Armbruster , "Denis V. Lunev" Cc: Peter Maydell , Luiz Capitulino , qemu-devel@nongnu.org, Pavel Butsykin On 16.10.2015 10:34, Markus Armbruster wrote: > "Denis V. Lunev" writes: > >> From: Pavel Butsykin >> >> 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 >> Signed-off-by: Denis V. Lunev >> CC: Markus Armbruster >> CC: Luiz Capitulino >> CC: Eric Blake >> CC: Peter Maydell >> --- >> 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.