Bug 1089411

Summary:	[RFE] qemu logs for VMs do not have timestamps for most events - QEMU
Product:	Red Hat Enterprise Linux Advanced Virtualization	Reporter:	Jake Hunsaker <jhunsaker>
Component:	qemu-kvm	Assignee:	Markus Armbruster <armbru>
Status:	CLOSED ERRATA	QA Contact:	Guo, Zhiyi <zhguo>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	8.0	CC:	cfergeau, chayang, coli, dblechte, ddepaula, fziglio, gveitmic, jjongsma, juzhang, knoel, marcandre.lureau, mkenneth, mtessun, qzhang, rbalakri, rduda, tpelka, uril, victortoso, virt-maint, zhguo
Target Milestone:	rc	Keywords:	FutureFeature
Target Release:	---
Hardware:	All
OS:	Linux
Whiteboard:
Fixed In Version:	qemu-kvm-4.1.0-1.module+el8.1.0+3966+4a23dca1	Doc Type:	Enhancement
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2019-11-06 07:10:39 UTC	Type:	Feature Request
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:	1562123
Bug Blocks:

Description Jake Hunsaker 2014-04-18 19:55:01 UTC

Description of problem:

For the qemu logs for each VM running on host (/var/log/libvirt/qemu/$vm_name) most logged events do not have timestamps, aside from the start up and shutdown of the VM. 

This makes it very difficult to correlate qemu log events with basically anything else within the guest or happening on the hypervisor


How reproducible:

Always


Actual results:

Only the start/shutdown of a VM has a timestamp with the logged message


Expected results:

All logged messages should have timestamps

Additional info:


As an example, here is an excerpt from a qemu log for a VM running in RHEV:

red_dispatcher_disconnect_display_peer: 
red_dispatcher_disconnect_cursor_peer: 
qemu: terminating on signal 15 from pid 8632
red_channel_client_disconnect: rcc=0x7f6914243930 (channel=0x7f691421f920 type=4 id=0)
2014-04-17 10:04:35.414+0000: shutting down
2014-04-17 10:58:26.912+0000: starting up

main_channel_link: add main channel client
main_channel_handle_parsed: net test: latency 14.158000 ms, bitrate 30507515 bps (29.094234 Mbps)




As you can see, the shutdown and start up timestamps, but nothing else does.

Comment 2 Ademar Reis 2014-05-27 22:19:24 UTC

Errors are time-stamped since RHEL-6.5 (Bug 906931)

Comment 4 Stefan Hajnoczi 2015-01-15 14:01:58 UTC

(In reply to Jake Hunsaker from comment #0)
> As an example, here is an excerpt from a qemu log for a VM running in RHEV:
> 
> red_dispatcher_disconnect_display_peer: 
> red_dispatcher_disconnect_cursor_peer: 
> qemu: terminating on signal 15 from pid 8632
> red_channel_client_disconnect: rcc=0x7f6914243930 (channel=0x7f691421f920
> type=4 id=0)
> 2014-04-17 10:04:35.414+0000: shutting down
> 2014-04-17 10:58:26.912+0000: starting up
> 
> main_channel_link: add main channel client
> main_channel_handle_parsed: net test: latency 14.158000 ms, bitrate 30507515
> bps (29.094234 Mbps)

These messages come from the SPICE server library and not directly from QEMU.

Ademar mentioned that QEMU does timestamp error messages (since RHEL 6.5).

I have added this BZ to my todo list but do not expect full coverage of all log messages soon.

Marking deferred to RHEL 6.8 to set the expectation that timestamping all messages will take time.

Comment 6 Stefan Hajnoczi 2015-12-08 06:54:37 UTC

The most practical way to make progress here is to extend spice-common's logging so that QEMU can provide a log callback function.  This way QEMU can prepend a timestamp and write to the correct log file descriptor.

SPICE folks: Is this a reasonable enhancement to spice-server?  It allows SPICE logging to integrate with the application.

Comment 7 Marc-Andre Lureau 2015-12-08 10:47:31 UTC

(In reply to Stefan Hajnoczi from comment #6)
> SPICE folks: Is this a reasonable enhancement to spice-server?  It allows
> SPICE logging to integrate with the application.

Once Spice server starts using glib logging, qemu will be able to change the log handler. There are already some patches being discussed in the ML.

Comment 10 Victor Toso 2016-09-01 12:23:42 UTC

Logging with glib is supported upstream [0]. As suggested, qemu can change the log handler then. I would like to confirm that this is still desirable for rhel6..

[0] https://cgit.freedesktop.org/spice/spice-common/commit/?id=efd1d3cb4d8eee5e5aff61a796daf2dcf980e3c2

Comment 11 Victor Toso 2016-09-01 13:07:39 UTC

Unless we have a strong reason to have this on RHEL 6, let's focus on RHEL 7.
Moving the bug.

Comment 12 Victor Toso 2018-01-26 16:13:27 UTC

Should be doable now that we rebased spice-server, I think. Moving to 7.6

Comment 13 Christophe Fergeau 2018-06-20 14:41:20 UTC

A bit more work is needed on spice-side:

- make spice_printerr() calls go through g_log (but most of them should be changed to g_debug/g_warning depending on their severity)
- get rid of spice_logger() in spice-common/common/log.c. https://lists.freedesktop.org/archives/spice-devel/2018-June/044177.html should help with that
- add a call to g_log_set_default_handler() to qemu to route spice logging calls through qemu log functions

Comment 14 David Blechter 2018-12-10 16:24:14 UTC

Let's finalize this improvement in rhel 8.x, moving!

Comment 15 Christophe Fergeau 2018-12-10 16:24:41 UTC

(In reply to Christophe Fergeau from comment #13)
> A bit more work is needed on spice-side:
> 
> - make spice_printerr() calls go through g_log (but most of them should be
> changed to g_debug/g_warning depending on their severity)

spice_printerr is gone from spice 0.14.1

> - get rid of spice_logger() in spice-common/common/log.c.
> https://lists.freedesktop.org/archives/spice-devel/2018-June/044177.html
> should help with that

This is also fixed in spice 0.14.1

> - add a call to g_log_set_default_handler() to qemu to route spice logging
> calls through qemu log functions

Still missing

Comment 16 Christophe Fergeau 2018-12-17 10:30:42 UTC

(In reply to Christophe Fergeau from comment #15)
> (In reply to Christophe Fergeau from comment #13)
> > A bit more work is needed on spice-side:
> > 
> > - make spice_printerr() calls go through g_log (but most of them should be
> > changed to g_debug/g_warning depending on their severity)
> 
> spice_printerr is gone from spice 0.14.1
> 
> > - get rid of spice_logger() in spice-common/common/log.c.
> > https://lists.freedesktop.org/archives/spice-devel/2018-June/044177.html
> > should help with that
> 
> This is also fixed in spice 0.14.1
> 
> > - add a call to g_log_set_default_handler() to qemu to route spice logging
> > calls through qemu log functions
> 
> Still missing

I sent https://lists.nongnu.org/archive/html/qemu-devel/2018-12/msg03570.html
To fix this we'll need to:
- rebase spice to 0.14.1, or backport https://gitlab.freedesktop.org/spice/spice-common/commit/82a5f19d998b88b7e1f7c89672f986f88ff7be31 (and maybe related patches)
- backport the QEMU patch above

Comment 17 Christophe Fergeau 2018-12-18 16:03:10 UTC


> To fix this we'll need to:
> - rebase spice to 0.14.1, or backport
> https://gitlab.freedesktop.org/spice/spice-common/commit/82a5f19d998b88b7e1f7c89672f986f88ff7be31 (and maybe related patches)

spice rebase is rhbz#1562123

> - backport the QEMU patch above

Moving this bug to qemu so that https://lists.nongnu.org/archive/html/qemu-devel/2018-12/msg03570.html can be backported.

Comment 21 Christophe Fergeau 2019-03-28 09:32:05 UTC

Latest status on the qemu patches:
https://lists.nongnu.org/archive/html/qemu-devel/2019-03/msg07341.html
« Reviewed-by: Markus Armbruster <address@hidden>

Queued for 4.1, thanks! »

Comment 25 Guo, Zhiyi 2019-08-28 06:06:25 UTC

Test against qemu-kvm-4.0.0-6.module+el8.1.0+3736+a2aefea3.x86_64

Check the qemu log prompted by qemu cli:
#export G_MESSAGES_DEBUG=Spice
#/usr/libexec/qemu-kvm -device qxl-vga -spice port=5900,disable-ticketing -device virtio-serial -chardev spicevmc,id=vdagent,debug=0,name=vdagent -device virtserialport,chardev=vdagent,name=com.redhat.spice.0 -monitor stdio -msg timestamp=on
(process:11814): Spice-DEBUG: 01:52:40.773: reds.c:4387:spice_server_set_seamless_migration: seamless migration enabled=0
(process:11814): Spice-DEBUG: 01:52:40.773: reds.c:3548:do_spice_init: starting 0.14.2
(process:11814): Spice-DEBUG: 01:52:40.773: char-device.c:693:red_char_device_reset_dev_instance: sin (nil), char device 0x562b333b51a0
(process:11814): Spice-DEBUG: 01:52:40.774: reds.c:2705:reds_init_socket: bound to 0.0.0.0:5900
(process:11814): Spice-DEBUG: 01:52:40.786: main:0 (0x562b333b9890): thread_id 0x7f3f74f97ec0
(process:11814): Spice-DEBUG: 01:52:40.786: inputs:0 (0x562b333bb0a0): thread_id 0x7f3f74f97ec0
(process:11814): Spice-DEBUG: 01:52:40.786: reds.c:3486:spice_server_add_interface: SPICE_INTERFACE_MIGRATION
(process:11814): Spice-DEBUG: 01:52:40.786: reds.c:3393:spice_server_add_interface: SPICE_INTERFACE_KEYBOARD
(process:11814): Spice-DEBUG: 01:52:40.786: reds.c:3404:spice_server_add_interface: SPICE_INTERFACE_MOUSE
QEMU 4.0.0 monitor - type 'help' for more information
(qemu) (process:11814): Spice-DEBUG: 01:52:40.818: reds.c:3417:spice_server_add_interface: SPICE_INTERFACE_QXL
(process:11814): Spice-DEBUG: 01:52:40.819: cursor-channel.c:234:cursor_channel_new: create cursor channel
(process:11814): Spice-DEBUG: 01:52:40.819: cursor:0 (0x562b333b7130): thread_id 0x7f3f74f97ec0
(process:11814): Spice-DEBUG: 01:52:40.819: display-channel.c:2244:display_channel_new: create display channel
(process:11814): Spice-DEBUG: 01:52:40.819: display:0 (0x562b333b9940): thread_id 0x7f3f74f97ec0
(process:11814): Spice-DEBUG: 01:52:40.819: display-channel.c:243:display_channel_set_stream_video: sv off
(process:11814): Spice-DEBUG: 01:52:40.820: QXL Instance 0 setting device address "pci/0000/03.0" and monitor -> device display mapping:
(process:11814): Spice-DEBUG: 01:52:40.820: red-worker.c:1130:red_worker_main: begin
(process:11814): Spice-DEBUG: 01:52:40.836: display-channel.c:2098:display_channel_destroy_surfaces: trace
(process:11814): Spice-DEBUG: 01:52:40.836: red-worker.c:407:dev_create_primary_surface: trace
(process:11814): Spice-DEBUG: 01:52:40.838: display-channel.c:187:monitors_config_debug: monitors config count:1 max:1
(process:11814): Spice-DEBUG: 01:52:40.838: display-channel.c:191:monitors_config_debug: head #0 +0+0 640x480
(process:11814): Spice-DEBUG: 01:52:40.838: cursor-channel.c:315:cursor_channel_init_client: during_target_migrate: skip init
(process:11814): Spice-DEBUG: 01:52:40.838: red-worker.c:407:dev_create_primary_surface: trace
(process:11814): Spice-DEBUG: 01:52:40.838: display-channel.c:179:monitors_config_unref: freeing monitors config
(process:11814): Spice-DEBUG: 01:52:40.838: display-channel.c:187:monitors_config_debug: monitors config count:1 max:1
(process:11814): Spice-DEBUG: 01:52:40.839: display-channel.c:191:monitors_config_debug: head #0 +0+0 640x480
(process:11814): Spice-DEBUG: 01:52:40.839: cursor-channel.c:315:cursor_channel_init_client: during_target_migrate: skip init
(process:11814): Spice-DEBUG: 01:52:40.929: red-worker.c:407:dev_create_primary_surface: trace
(process:11814): Spice-DEBUG: 01:52:40.930: display-channel.c:179:monitors_config_unref: freeing monitors config
(process:11814): Spice-DEBUG: 01:52:40.930: display-channel.c:187:monitors_config_debug: monitors config count:1 max:1
(process:11814): Spice-DEBUG: 01:52:40.930: display-channel.c:191:monitors_config_debug: head #0 +0+0 720x400
(process:11814): Spice-DEBUG: 01:52:40.930: cursor-channel.c:315:cursor_channel_init_client: during_target_migrate: skip init
(qemu) quit
(process:11814): Spice-DEBUG: 01:54:12.513: red-worker.c:519:handle_dev_stop: stop

Test against qemu-kvm-4.1.0-4.module+el8.1.0+4020+16089f93.x86_64, the output:
# /usr/libexec/qemu-kvm -device qxl-vga -spice port=5900,disable-ticketing -device virtio-serial -chardev spicevmc,id=vdagent,debug=0,name=vdagent -device virtserialport,chardev=vdagent,name=com.redhat.spice.0 -monitor stdio -msg timestamp=on
2019-08-28T05:56:34.141124Z qemu-kvm: info: Spice: reds.c:4387:spice_server_set_seamless_migration: seamless migration enabled=0
2019-08-28T05:56:34.141214Z qemu-kvm: info: Spice: reds.c:3548:do_spice_init: starting 0.14.2
2019-08-28T05:56:34.141304Z qemu-kvm: info: Spice: char-device.c:693:red_char_device_reset_dev_instance: sin (nil), char device 0x556a11a5e140
2019-08-28T05:56:34.141501Z qemu-kvm: info: Spice: reds.c:2705:reds_init_socket: bound to 0.0.0.0:5900
2019-08-28T05:56:34.144699Z qemu-kvm: info: Spice: main:0 (0x556a11a62060): thread_id 0x7f165939dec0
2019-08-28T05:56:34.144747Z qemu-kvm: info: Spice: inputs:0 (0x556a11a63070): thread_id 0x7f165939dec0
2019-08-28T05:56:34.144805Z qemu-kvm: info: Spice: reds.c:3486:spice_server_add_interface: SPICE_INTERFACE_MIGRATION
2019-08-28T05:56:34.144819Z qemu-kvm: info: Spice: reds.c:3393:spice_server_add_interface: SPICE_INTERFACE_KEYBOARD
2019-08-28T05:56:34.144831Z qemu-kvm: info: Spice: reds.c:3404:spice_server_add_interface: SPICE_INTERFACE_MOUSE
QEMU 4.1.0 monitor - type 'help' for more information
(qemu) 2019-08-28T05:56:34.154320Z qemu-kvm: -device qxl-vga: info: Spice: reds.c:3417:spice_server_add_interface: SPICE_INTERFACE_QXL
2019-08-28T05:56:34.154466Z qemu-kvm: -device qxl-vga: info: Spice: cursor-channel.c:234:cursor_channel_new: create cursor channel
2019-08-28T05:56:34.154526Z qemu-kvm: -device qxl-vga: info: Spice: cursor:0 (0x556a11a5f920): thread_id 0x7f165939dec0
2019-08-28T05:56:34.154547Z qemu-kvm: -device qxl-vga: info: Spice: display-channel.c:2244:display_channel_new: create display channel
2019-08-28T05:56:34.154775Z qemu-kvm: -device qxl-vga: info: Spice: display:0 (0x556a11a62110): thread_id 0x7f165939dec0
2019-08-28T05:56:34.154813Z qemu-kvm: -device qxl-vga: info: Spice: display-channel.c:243:display_channel_set_stream_video: sv off
2019-08-28T05:56:34.155111Z qemu-kvm: -device2019-08-28T05:56:34.155114Z qemu-kvm: -device qxl-vga:  qxl-vga: info: Spice: QXL Instance 0 setting device address "pci/0000/03.0" and monitor -> device display mapping:
info: Spice: red-worker.c:1130:red_worker_main: begin
2019-08-28T05:56:34.159863Z qemu-kvm: info: Spice: display-channel.c:2098:display_channel_destroy_surfaces: trace
2019-08-28T05:56:34.160229Z qemu-kvm: info: Spice: red-worker.c:407:dev_create_primary_surface: trace
2019-08-28T05:56:34.160807Z qemu-kvm: info: Spice: display-channel.c:187:monitors_config_debug: monitors config count:1 max:1
2019-08-28T05:56:34.160818Z qemu-kvm: info: Spice: display-channel.c:191:monitors_config_debug: head #0 +0+0 640x480
2019-08-28T05:56:34.160826Z qemu-kvm: info: Spice: cursor-channel.c:315:cursor_channel_init_client: during_target_migrate: skip init
2019-08-28T05:56:34.161210Z qemu-kvm: info: Spice: red-worker.c:407:dev_create_primary_surface: trace
2019-08-28T05:56:34.161320Z qemu-kvm: info: Spice: display-channel.c:179:monitors_config_unref: freeing monitors config
2019-08-28T05:56:34.161346Z qemu-kvm: info: Spice: display-channel.c:187:monitors_config_debug: monitors config count:1 max:1
2019-08-28T05:56:34.161373Z qemu-kvm: info: Spice: display-channel.c:191:monitors_config_debug: head #0 +0+0 640x480
2019-08-28T05:56:34.161386Z qemu-kvm: info: Spice: cursor-channel.c:315:cursor_channel_init_client: during_target_migrate: skip init
2019-08-28T05:56:34.192181Z qemu-kvm: info: Spice: red-worker.c:407:dev_create_primary_surface: trace
2019-08-28T05:56:34.192375Z qemu-kvm: info: Spice: display-channel.c:179:monitors_config_unref: freeing monitors config
2019-08-28T05:56:34.192482Z qemu-kvm: info: Spice: display-channel.c:187:monitors_config_debug: monitors config count:1 max:1
2019-08-28T05:56:34.192533Z qemu-kvm: info: Spice: display-channel.c:191:monitors_config_debug: head #0 +0+0 720x400
2019-08-28T05:56:34.192572Z qemu-kvm: info: Spice: cursor-channel.c:315:cursor_channel_init_client: during_target_migrate: skip init
2019-08-28T05:56:39.354339Z qemu-kvm: terminating on signal 2
2019-08-28T05:56:39.354605Z qemu-kvm: info: Spice: red-worker.c:519:handle_dev_stop: stop

Comment 26 Guo, Zhiyi 2019-08-28 06:08:57 UTC

Hi Christophe,

   Could you help to confirm whether this bug can be verified per comment 25? Thanks!

BR/
Zhiyi

Comment 27 Christophe Fergeau 2019-08-28 08:36:07 UTC

Yes, the latter is the intended result of the changes this bug is about.

Comment 28 Guo, Zhiyi 2019-08-28 08:39:07 UTC

Thanks! Verified per comment 25 - 27

Comment 30 errata-xmlrpc 2019-11-06 07:10:39 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2019:3723