[Libvir] PATCH: Create a logfile for each QEMU vm

Most of the error reporting the QEMU daemon is focused on sending errors wrt to RPC ops to the client. There is no provision currently for getting info about the QEMU vm itself when problems occur. The most common problem is some mis-configurable in the XML causes qemu to fail to start up. This results in the completely accurate & completely useless (mea-culpa) error message libvirt.libvirtError: virDomainCreateLinux() failed internal error End-of-file while reading PTY startup output' What this means is that qemu crashed/exited at startup. Now this patch does not (yet) directly address that stupid error message, but what it does do is provide a way to diagnose the real problem. For every VM we start it will create a logfile /etc/libvirt/qemu/logs/[vmname].log Or $HOME/.libvirt/qemu/logs/[vmname].log And all output from QEMU's stderr/stdout will get written to this file. So # virsh --connect qemu:///system start wizz libvir: QEMU error : internal error End-of-file while reading PTY startup output error: Failed to start domain wizz # cat /etc/libvirt/qemu/logs/wizz.log qemu: could not open hard disk image '/home/berrange/src/xen/virtinst--devel/demo' Next up I'm going to work on a) Improving the error message b) Adding validation that disk images actually exist before launching QEMU since that's the most common error we're seeing Regards, Dan. -- |=- Red Hat, Engineering, Emerging Technologies, Boston. +1 978 392 2496 -=| |=- Perl modules: http://search.cpan.org/~danberr/ -=| |=- Projects: http://freshmeat.net/~danielpb/ -=| |=- GnuPG: 7D3B9505 F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 -=|

On Tue, 2007-05-15 at 17:04 +0100, Daniel P. Berrange wrote:
For every VM we start it will create a logfile
/etc/libvirt/qemu/logs/[vmname].log
Why not /var/log? /etc/ isn't the place for this kind of stuff, surely. (Putting them in their own directory is nice, though - that way we can use tmpwatch to clean them up ... logrotate isn't really suitable) Cheers, Mark.

On Tue, May 15, 2007 at 05:09:56PM +0100, Mark McLoughlin wrote:
On Tue, 2007-05-15 at 17:04 +0100, Daniel P. Berrange wrote:
For every VM we start it will create a logfile
/etc/libvirt/qemu/logs/[vmname].log
Why not /var/log? /etc/ isn't the place for this kind of stuff, surely.
True - though we'd have to code different behaviour when running as an unprivileged user. Shouldn't complicate things too much i guess.
(Putting them in their own directory is nice, though - that way we can use tmpwatch to clean them up ... logrotate isn't really suitable)
Yep, I also explicitly did *not* follow the Xen insanity of including the PID in the filename. So we have a finite number of logs files instead of ever growing set Dan. -- |=- Red Hat, Engineering, Emerging Technologies, Boston. +1 978 392 2496 -=| |=- Perl modules: http://search.cpan.org/~danberr/ -=| |=- Projects: http://freshmeat.net/~danielpb/ -=| |=- GnuPG: 7D3B9505 F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 -=|

On Tue, May 15, 2007 at 05:15:04PM +0100, Daniel P. Berrange wrote:
On Tue, May 15, 2007 at 05:09:56PM +0100, Mark McLoughlin wrote:
On Tue, 2007-05-15 at 17:04 +0100, Daniel P. Berrange wrote:
For every VM we start it will create a logfile
/etc/libvirt/qemu/logs/[vmname].log
Why not /var/log? /etc/ isn't the place for this kind of stuff, surely.
True - though we'd have to code different behaviour when running as an unprivileged user. Shouldn't complicate things too much i guess.
Attached a new version which does this. If using qemu:///system they get put into /var/log/libvirt/qemu, while if using qemu://session they go into $HOME/.libvirt/qemu/log Dan. -- |=- Red Hat, Engineering, Emerging Technologies, Boston. +1 978 392 2496 -=| |=- Perl modules: http://search.cpan.org/~danberr/ -=| |=- Projects: http://freshmeat.net/~danielpb/ -=| |=- GnuPG: 7D3B9505 F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 -=|

The problem I'm having with respect to QEMU is that qemu:///system doesn't form a connection. What has to be running before I start the virsh command below? I know my images are okay, I just can't manage them with virt-manager/virt-install/virsh->libvirt. Thanks, smoyer On Tuesday 15 May 2007 13:37, Daniel P. Berrange wrote:
On Tue, May 15, 2007 at 05:15:04PM +0100, Daniel P. Berrange wrote:
On Tue, May 15, 2007 at 05:09:56PM +0100, Mark McLoughlin wrote:
On Tue, 2007-05-15 at 17:04 +0100, Daniel P. Berrange wrote:
For every VM we start it will create a logfile
/etc/libvirt/qemu/logs/[vmname].log
Why not /var/log? /etc/ isn't the place for this kind of stuff, surely.
True - though we'd have to code different behaviour when running as an unprivileged user. Shouldn't complicate things too much i guess.
Attached a new version which does this. If using qemu:///system they get put into /var/log/libvirt/qemu, while if using qemu://session they go into $HOME/.libvirt/qemu/log
Dan.
-- Steven W. Moyer Principle Architect, Assurance Applications C-COR Solutions, LLC 60 Decibel Road State College, PA 16801 Office Phone: 814-231-4408 Front Desk: 814-238-2461 Cell Phone: 814-883-0391 Fax: 814-278-6540 E-mail: smoyer@c-cor.com AIM: StevenWMoyer ICQ: 349680381 Jabber: smoyer1@jabber.jcware.org MSN: smoyer64 Yahoo: smoyer64

On Tue, May 15, 2007 at 06:37:40PM +0100, Daniel P. Berrange wrote:
On Tue, May 15, 2007 at 05:15:04PM +0100, Daniel P. Berrange wrote:
On Tue, May 15, 2007 at 05:09:56PM +0100, Mark McLoughlin wrote:
On Tue, 2007-05-15 at 17:04 +0100, Daniel P. Berrange wrote:
For every VM we start it will create a logfile
/etc/libvirt/qemu/logs/[vmname].log
Why not /var/log? /etc/ isn't the place for this kind of stuff, surely.
True - though we'd have to code different behaviour when running as an unprivileged user. Shouldn't complicate things too much i guess.
Attached a new version which does this. If using qemu:///system they get put into /var/log/libvirt/qemu, while if using qemu://session they go into $HOME/.libvirt/qemu/log
Ok, attached is my final version. - qemu:///system per-VM logs are created in /var/log/libvirt/qemu/[vmname].log - qemu:///session per-VM logs are created in $HOME/.libvirt/qemu/log/[vmname].log - The exact QEMU command line argv is logged in aforementioned files - All data written to stderr/out by QEMU is logged in aforementioned files - There is a qemudValidateConfig() method we call before starting a VM which checks the path for kernel, initrd, each disk, and any script given for a network device setup. - The horrible 'End-of-file while reading PTY startup output' is replaced with less horrible 'QEMU quit during console startup'. Though I might reword that a little more - If QEMU fails during startup, we capture the contents of stderr and include them in the libvirt error message reported. I'm not entirely happy with this because this can make messages quite verbose, but at the same time we really need to feed this info back to the user. This is even more important with remote management where there's no easy access to log files. So, here's some examples: - Starting a guest with mem set to 8 G - in this case QEMU provides zero useful error message, so we get the generic: # virsh --connect qemu:///system start wizz libvir: QEMU error : internal error QEMU shutdown while reading console startup output error: Failed to start domain wizz - Starting a guest with mem set to 1.9 G - this this case there is not enough free ram: # virsh --connect qemu:///system start wizz libvir: QEMU error : internal error QEMU shutdown while reading console startup output You do not have enough space in '/dev/shm' for the 1503 MB of QEMU virtual RAM. To have more space available provided you have enough RAM and swap, do as root: umount /dev/shm mount -t tmpfs -o size=1519m none /dev/shm Or disable the accelerator module with -no-kqemu error: Failed to start domain wizz - Starting a guest with a disk which doesn't exist: # virsh --connect qemu:///system start wizz libvir: QEMU error : internal error Cannot access disk hda at /home/berrange/src/xen/virtinst--devel/demo2: No such file or directory error: Failed to start domain wizz Regards, Dan. -- |=- Red Hat, Engineering, Emerging Technologies, Boston. +1 978 392 2496 -=| |=- Perl modules: http://search.cpan.org/~danberr/ -=| |=- Projects: http://freshmeat.net/~danielpb/ -=| |=- GnuPG: 7D3B9505 F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 -=|

"If QEMU fails during startup" ... please tell me how to start QEMU as a service! Thanks, smoyer -----Original Message----- From: libvir-list-bounces@redhat.com on behalf of Daniel P. Berrange Sent: Tue 5/15/2007 6:27 PM To: Mark McLoughlin Cc: libvir-list@redhat.com Subject: Re: [Libvir] PATCH: Create a logfile for each QEMU vm On Tue, May 15, 2007 at 06:37:40PM +0100, Daniel P. Berrange wrote:
On Tue, May 15, 2007 at 05:15:04PM +0100, Daniel P. Berrange wrote:
On Tue, May 15, 2007 at 05:09:56PM +0100, Mark McLoughlin wrote:
On Tue, 2007-05-15 at 17:04 +0100, Daniel P. Berrange wrote:
For every VM we start it will create a logfile
/etc/libvirt/qemu/logs/[vmname].log
Why not /var/log? /etc/ isn't the place for this kind of stuff, surely.
True - though we'd have to code different behaviour when running as an unprivileged user. Shouldn't complicate things too much i guess.
Attached a new version which does this. If using qemu:///system they get put into /var/log/libvirt/qemu, while if using qemu://session they go into $HOME/.libvirt/qemu/log
Ok, attached is my final version. - qemu:///system per-VM logs are created in /var/log/libvirt/qemu/[vmname].log - qemu:///session per-VM logs are created in $HOME/.libvirt/qemu/log/[vmname].log - The exact QEMU command line argv is logged in aforementioned files - All data written to stderr/out by QEMU is logged in aforementioned files - There is a qemudValidateConfig() method we call before starting a VM which checks the path for kernel, initrd, each disk, and any script given for a network device setup. - The horrible 'End-of-file while reading PTY startup output' is replaced with less horrible 'QEMU quit during console startup'. Though I might reword that a little more - If QEMU fails during startup, we capture the contents of stderr and include them in the libvirt error message reported. I'm not entirely happy with this because this can make messages quite verbose, but at the same time we really need to feed this info back to the user. This is even more important with remote management where there's no easy access to log files. So, here's some examples: - Starting a guest with mem set to 8 G - in this case QEMU provides zero useful error message, so we get the generic: # virsh --connect qemu:///system start wizz libvir: QEMU error : internal error QEMU shutdown while reading console startup output error: Failed to start domain wizz - Starting a guest with mem set to 1.9 G - this this case there is not enough free ram: # virsh --connect qemu:///system start wizz libvir: QEMU error : internal error QEMU shutdown while reading console startup output You do not have enough space in '/dev/shm' for the 1503 MB of QEMU virtual RAM. To have more space available provided you have enough RAM and swap, do as root: umount /dev/shm mount -t tmpfs -o size=1519m none /dev/shm Or disable the accelerator module with -no-kqemu error: Failed to start domain wizz - Starting a guest with a disk which doesn't exist: # virsh --connect qemu:///system start wizz libvir: QEMU error : internal error Cannot access disk hda at /home/berrange/src/xen/virtinst--devel/demo2: No such file or directory error: Failed to start domain wizz Regards, Dan. -- |=- Red Hat, Engineering, Emerging Technologies, Boston. +1 978 392 2496 -=| |=- Perl modules: http://search.cpan.org/~danberr/ -=| |=- Projects: http://freshmeat.net/~danielpb/ -=| |=- GnuPG: 7D3B9505 F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 -=|

Daniel P. Berrange wrote:
Ok, attached is my final version.
Looks OK, although it'll have some conflicts with the remote patch -- the patch itself, not the concept. Rich. -- Emerging Technologies, Red Hat - http://et.redhat.com/~rjones/ Registered Address: Red Hat UK Ltd, Amberley Place, 107-111 Peascod Street, Windsor, Berkshire, SL4 1TE, United Kingdom. Registered in England and Wales under Company Registration No. 03798903

On Tue, May 15, 2007 at 11:27:11PM +0100, Daniel P. Berrange wrote:
On Tue, May 15, 2007 at 06:37:40PM +0100, Daniel P. Berrange wrote:
On Tue, May 15, 2007 at 05:15:04PM +0100, Daniel P. Berrange wrote:
On Tue, May 15, 2007 at 05:09:56PM +0100, Mark McLoughlin wrote:
On Tue, 2007-05-15 at 17:04 +0100, Daniel P. Berrange wrote:
For every VM we start it will create a logfile
/etc/libvirt/qemu/logs/[vmname].log
Why not /var/log? /etc/ isn't the place for this kind of stuff, surely.
True - though we'd have to code different behaviour when running as an unprivileged user. Shouldn't complicate things too much i guess.
Attached a new version which does this. If using qemu:///system they get put into /var/log/libvirt/qemu, while if using qemu://session they go into $HOME/.libvirt/qemu/log
Ok, attached is my final version.
Bah, discovered a really nasty issue. The (existing) code assumed that the revents field in poll struct would be POLLIN *or* POLLHUP. 70% of the time that was true, but sometimes it was POLLIN & POLLHUP in which case we were throwing away valuable log output.
- qemu:///system per-VM logs are created in /var/log/libvirt/qemu/[vmname].log
- qemu:///session per-VM logs are created in $HOME/.libvirt/qemu/log/[vmname].log
- The exact QEMU command line argv is logged in aforementioned files
- All data written to stderr/out by QEMU is logged in aforementioned files
- There is a qemudValidateConfig() method we call before starting a VM which checks the path for kernel, initrd, each disk, and any script given for a network device setup.
With my fix to deal with poll we can actually reliably get this info from QEMU directly. Also having libvirt do stat() was failing with disk > 2GB since we don't currently build with LFS enabled. So I've riped this out of my latest patch.
- The horrible 'End-of-file while reading PTY startup output' is replaced with less horrible 'QEMU quit during console startup'. Though I might reword that a little more
- If QEMU fails during startup, we capture the contents of stderr and include them in the libvirt error message reported. I'm not entirely happy with this because this can make messages quite verbose, but at the same time we really need to feed this info back to the user. This is even more important with remote management where there's no easy access to log files.
This lets us also catch errors about missing files
So, here's some examples:
- Starting a guest with mem set to 8 G - in this case QEMU provides zero useful error message, so we get the generic:
# virsh --connect qemu:///system start wizz libvir: QEMU error : internal error QEMU shutdown while reading console startup output error: Failed to start domain wizz
- Starting a guest with mem set to 1.9 G - this this case there is not enough free ram:
# virsh --connect qemu:///system start wizz libvir: QEMU error : internal error QEMU shutdown while reading console startup output You do not have enough space in '/dev/shm' for the 1503 MB of QEMU virtual RAM. To have more space available provided you have enough RAM and swap, do as root: umount /dev/shm mount -t tmpfs -o size=1519m none /dev/shm Or disable the accelerator module with -no-kqemu error: Failed to start domain wizz
- Starting a guest with a disk which doesn't exist:
# virsh --connect qemu:///system start wizz libvir: QEMU error : internal error Cannot access disk hda at /home/berrange/src/xen/virtinst--devel/demo2: No such file or directory error: Failed to start domain wizz
This now loooks like # virsh --connect qemu:///system start wizz libvir: QEMU error : internal error QEMU quit during console startup qemu: could not open hard disk image '/home/berrange/src/xen/virtinst--devel/demo2' error: Failed to start domain wizz Regards, Dan. -- |=- Red Hat, Engineering, Emerging Technologies, Boston. +1 978 392 2496 -=| |=- Perl modules: http://search.cpan.org/~danberr/ -=| |=- Projects: http://freshmeat.net/~danielpb/ -=| |=- GnuPG: 7D3B9505 F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 -=|

On Wed, May 16, 2007 at 07:09:16PM +0100, Daniel P. Berrange wrote:
This now loooks like
# virsh --connect qemu:///system start wizz libvir: QEMU error : internal error QEMU quit during console startup qemu: could not open hard disk image '/home/berrange/src/xen/virtinst--devel/demo2' error: Failed to start domain wizz
patch looks fine to me, apparently it was commited on the 18th :-) Daniel -- Red Hat Virtualization group http://redhat.com/virtualization/ Daniel Veillard | virtualization library http://libvirt.org/ veillard@redhat.com | libxml GNOME XML XSLT toolkit http://xmlsoft.org/ http://veillard.com/ | Rpmfind RPM search engine http://rpmfind.net/
participants (6)
-
Daniel P. Berrange
-
Daniel Veillard
-
Mark McLoughlin
-
Moyer, Steven
-
Richard W.M. Jones
-
Steven W. Moyer