[libvirt] Problem in handling fast prints from QEMU to stderr

Hi, I think I spotted a bug in the way libvirtd handles stderr output from QEMU VMs. When starting a VM and QEMU outputs too much output data to stderr (during a given time period), libvirtd will fail and report the following error to /var/log/messages: libvirtd: 13:44:40.695: error : internal error Out of space while reading console log output I looked at the libvirt code a bit and it seems like the stderr-handling code (I think its in qemudReadLogOutput()) is time-dependent and if a 4K buffer overflows it will stop running this VM. As a workaround I added some usleep(250000) near the fprintf() calls (inside QEMU) and I now manage to get the VM running. Is this the way libvirtd is supposed to behave? Thanks, Saul p.s. This was tested on FC11 and libvirtd is version 0.6.2

On Wed, Nov 25, 2009 at 06:49:24PM +0200, Saul Tamari wrote:
Hi,
I think I spotted a bug in the way libvirtd handles stderr output from QEMU VMs.
When starting a VM and QEMU outputs too much output data to stderr (during a given time period), libvirtd will fail and report the following error to /var/log/messages: libvirtd: 13:44:40.695: error : internal error Out of space while reading console log output
I looked at the libvirt code a bit and it seems like the stderr-handling code (I think its in qemudReadLogOutput()) is time-dependent and if a 4K buffer overflows it will stop running this VM. As a workaround I added some usleep(250000) near the fprintf() calls (inside QEMU) and I now manage to get the VM running.
Is this the way libvirtd is supposed to behave?
We only look at stdout to find the path for the PTY based char devices. This is the first thing QEMU prints out to stderr when operating normally and easily fits in 4K. So the real question is why is your QEMU binary spewing so much junk to stdout/stderr before the PTY paths ? Is there anything of interest in /var/log/libvirt/qemu/$GUESTNAME.log Regards, Daniel -- |: Red Hat, Engineering, London -o- http://people.redhat.com/berrange/ :| |: http://libvirt.org -o- http://virt-manager.org -o- http://ovirt.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: GnuPG: 7D3B9505 -o- F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 :|

Hi, QEMU is spewing this junk because I'm debugging it and added debug prints to code in its initialization code. Thanks, Saul On Thu, Nov 26, 2009 at 1:51 PM, Daniel P. Berrange <berrange@redhat.com> wrote:
On Wed, Nov 25, 2009 at 06:49:24PM +0200, Saul Tamari wrote:
Hi,
I think I spotted a bug in the way libvirtd handles stderr output from QEMU VMs.
When starting a VM and QEMU outputs too much output data to stderr (during a given time period), libvirtd will fail and report the following error to /var/log/messages: libvirtd: 13:44:40.695: error : internal error Out of space while reading console log output
I looked at the libvirt code a bit and it seems like the stderr-handling code (I think its in qemudReadLogOutput()) is time-dependent and if a 4K buffer overflows it will stop running this VM. As a workaround I added some usleep(250000) near the fprintf() calls (inside QEMU) and I now manage to get the VM running.
Is this the way libvirtd is supposed to behave?
We only look at stdout to find the path for the PTY based char devices. This is the first thing QEMU prints out to stderr when operating normally and easily fits in 4K. So the real question is why is your QEMU binary spewing so much junk to stdout/stderr before the PTY paths ? Is there anything of interest in /var/log/libvirt/qemu/$GUESTNAME.log
Regards, Daniel -- |: Red Hat, Engineering, London -o- http://people.redhat.com/berrange/ :| |: http://libvirt.org -o- http://virt-manager.org -o- http://ovirt.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: GnuPG: 7D3B9505 -o- F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 :|

On Thu, Nov 26, 2009 at 11:51:48AM +0000, Daniel P. Berrange wrote:
On Wed, Nov 25, 2009 at 06:49:24PM +0200, Saul Tamari wrote:
Hi,
I think I spotted a bug in the way libvirtd handles stderr output from QEMU VMs.
When starting a VM and QEMU outputs too much output data to stderr (during a given time period), libvirtd will fail and report the following error to /var/log/messages: libvirtd: 13:44:40.695: error : internal error Out of space while reading console log output
I looked at the libvirt code a bit and it seems like the stderr-handling code (I think its in qemudReadLogOutput()) is time-dependent and if a 4K buffer overflows it will stop running this VM. As a workaround I added some usleep(250000) near the fprintf() calls (inside QEMU) and I now manage to get the VM running.
Is this the way libvirtd is supposed to behave?
We only look at stdout to find the path for the PTY based char devices. This is the first thing QEMU prints out to stderr when operating normally and easily fits in 4K. So the real question is why is your QEMU binary spewing so much junk to stdout/stderr before the PTY paths ? Is there anything of interest in /var/log/libvirt/qemu/$GUESTNAME.log
Could it be related to the Nov 26 06:59:30 white-vdsa libvirtd: 06:59:30.456: error : qemudReadLogOutput:1185 : internal error Timed out while reading console log output Nov 26 06:59:30 white-vdsa libvirtd: 06:59:30.456: error : qemudWaitForMonitor:1304 : internal error unable to start guest: I'm seeing once in a while? I, too, have non-standard debug info spewing from qemu.

The two errors I'm seeing are: Nov 25 10:27:18 localhost libvirtd: 10:27:18.248: error : internal error Out of space while reading console log output Nov 25 10:27:18 localhost libvirtd: 10:27:18.248: error : internal error unable to start guest: My current understanding is that libvirtd is sensitive to the amount and speed of stderr prints coming out of QEMU. During startup of a QEMU VM, libvirtd parses the stderr output and if it doesn't like what it sees it kills the VM. This doesn't sound like a good behaviour. Thanks, Saul On Thu, Nov 26, 2009 at 4:40 PM, Dan Kenigsberg <danken@redhat.com> wrote:
On Thu, Nov 26, 2009 at 11:51:48AM +0000, Daniel P. Berrange wrote:
On Wed, Nov 25, 2009 at 06:49:24PM +0200, Saul Tamari wrote:
Hi,
I think I spotted a bug in the way libvirtd handles stderr output from QEMU VMs.
When starting a VM and QEMU outputs too much output data to stderr (during a given time period), libvirtd will fail and report the following error to /var/log/messages: libvirtd: 13:44:40.695: error : internal error Out of space while reading console log output
I looked at the libvirt code a bit and it seems like the stderr-handling code (I think its in qemudReadLogOutput()) is time-dependent and if a 4K buffer overflows it will stop running this VM. As a workaround I added some usleep(250000) near the fprintf() calls (inside QEMU) and I now manage to get the VM running.
Is this the way libvirtd is supposed to behave?
We only look at stdout to find the path for the PTY based char devices. This is the first thing QEMU prints out to stderr when operating normally and easily fits in 4K. So the real question is why is your QEMU binary spewing so much junk to stdout/stderr before the PTY paths ? Is there anything of interest in /var/log/libvirt/qemu/$GUESTNAME.log
Could it be related to the
Nov 26 06:59:30 white-vdsa libvirtd: 06:59:30.456: error : qemudReadLogOutput:1185 : internal error Timed out while reading console log output Nov 26 06:59:30 white-vdsa libvirtd: 06:59:30.456: error : qemudWaitForMonitor:1304 : internal error unable to start guest:
I'm seeing once in a while? I, too, have non-standard debug info spewing from qemu.
participants (3)
-
Dan Kenigsberg
-
Daniel P. Berrange
-
Saul Tamari