[libvirt] PATCH: Fix infinite loop when QEMU quits at startup

The recent refactoring of the QEMU startup process now reads the monitor TTY from the logfile. Unfortunately in this refactoring we lost the check for the 'ret == 0' scenario in the read() return value. So if QEMU quits at startup, eg due to missing disk image, we loop forever on read() == 0 because we hit end-of-file and QEMU has quit. This patch adds back handling for this scenario, and takes care to propagate the contents of the log to the user as an error message # start demo libvir: QEMU error : internal error unable to start guest: qemu: could not open disk image /home/berrange/Fedora-9-i686-Live.iso error: Failed to start domain demo In addition, there were a couple of other bugs - a memory leak where we set the 'monitorpath' variable, even though we'd just set it moments before. - a missing check for whether the driver VNC password was present when initializing passwords at VM startupo - missing initialization of the monitor_watch field, and missing checking for whether the watch was set before removing it. - a gratuitous LOG_INFO when shutting down any VM, which could just be LOG_DEBUG. Daniel diff -r 826e6ed70ee0 src/domain_conf.c --- a/src/domain_conf.c Fri Jan 30 10:58:34 2009 +0000 +++ b/src/domain_conf.c Fri Jan 30 11:00:43 2009 +0000 @@ -497,6 +497,7 @@ virDomainObjPtr virDomainAssignDef(virCo virDomainObjLock(domain); domain->state = VIR_DOMAIN_SHUTOFF; domain->def = def; + domain->monitor_watch = -1; if (VIR_REALLOC_N(doms->objs, doms->count + 1) < 0) { virReportOOMError(conn); diff -r 826e6ed70ee0 src/qemu_driver.c --- a/src/qemu_driver.c Fri Jan 30 10:58:34 2009 +0000 +++ b/src/qemu_driver.c Fri Jan 30 11:00:43 2009 +0000 @@ -355,10 +355,9 @@ qemudReconnectVMs(struct qemud_driver *d qemudLog(QEMUD_ERR, _("Failed to reconnect monitor for %s: %d\n"), vm->def->name, rc); goto next_error; - } else - vm->monitorpath = status->monitorpath; - - if((vm->logfile = qemudLogFD(NULL, driver->logDir, vm->def->name)) < 0) + } + + if ((vm->logfile = qemudLogFD(NULL, driver->logDir, vm->def->name)) < 0) return -1; if (vm->def->id >= driver->nextvmid) @@ -376,6 +375,8 @@ next_error: vm->newDef = NULL; next: virDomainObjUnlock(vm); + if (status) + VIR_FREE(status->monitorpath); VIR_FREE(status); VIR_FREE(config); } @@ -617,6 +618,9 @@ typedef int qemudHandlerMonitorOutput(vi const char *output, int fd); +/* + * Returns -1 for error, 0 on end-of-file, 1 for success + */ static int qemudReadMonitorOutput(virConnectPtr conn, virDomainObjPtr vm, @@ -630,7 +634,7 @@ qemudReadMonitorOutput(virConnectPtr con int got = 0; buf[0] = '\0'; - /* Consume & discard the initial greeting */ + /* Consume & discard the initial greeting */ while (got < (buflen-1)) { int ret; @@ -670,11 +674,17 @@ qemudReadMonitorOutput(virConnectPtr con _("Failure while reading %s startup output"), what); return -1; } + } else if (ret == 0) { + return 0; } else { got += ret; buf[got] = '\0'; - if ((ret = func(conn, vm, buf, fd)) != 1) - return ret; + ret = func(conn, vm, buf, fd); + if (ret == -1) + return -1; + if (ret == 1) + continue; + return 1; } } @@ -724,11 +734,14 @@ static int qemudOpenMonitor(virConnectPt } if (!reconnect) { - ret = qemudReadMonitorOutput(conn, - vm, monfd, - buf, sizeof(buf), - qemudCheckMonitorPrompt, - "monitor", 10000); + if (qemudReadMonitorOutput(conn, + vm, monfd, + buf, sizeof(buf), + qemudCheckMonitorPrompt, + "monitor", 10000) <= 0) + ret = -1; + else + ret = 0; } else { vm->monitor = monfd; ret = 0; @@ -858,7 +871,7 @@ static int qemudWaitForMonitor(virConnec if ((logfd = qemudLogReadFD(conn, driver->logDir, vm->def->name, pos)) < 0) - return logfd; + return -1; ret = qemudReadMonitorOutput(conn, vm, logfd, buf, sizeof(buf), qemudFindCharDevicePTYs, @@ -866,7 +879,17 @@ static int qemudWaitForMonitor(virConnec if (close(logfd) < 0) qemudLog(QEMUD_WARN, _("Unable to close logfile: %s\n"), strerror(errno)); - return ret; + + if (ret == 1) /* Success */ + return 0; + + if (ret == -1) + return -1; + + /* Unexpected end of file - inform user of QEMU log data */ + qemudReportError(conn, NULL, NULL, VIR_ERR_INTERNAL_ERROR, + _("unable to start guest: %s"), buf); + return -1; } static int @@ -1033,7 +1056,7 @@ qemudInitPasswords(virConnectPtr conn, if (vm->def->graphics && vm->def->graphics->type == VIR_DOMAIN_GRAPHICS_TYPE_VNC && - vm->def->graphics->data.vnc.passwd) { + (vm->def->graphics->data.vnc.passwd || driver->vncPassword)) { if (qemudMonitorCommandExtra(vm, "change vnc password", vm->def->graphics->data.vnc.passwd ? @@ -1212,14 +1235,25 @@ static int qemudStartVMDaemon(virConnect /* wait for qemu process to to show up */ if (ret == 0) { int retries = 100; - while (retries) { - if ((ret = virFileReadPid(driver->stateDir, vm->def->name, &vm->pid)) == 0) - break; - usleep(100*1000); - retries--; - } - if (ret) - qemudLog(QEMUD_WARN, _("Domain %s didn't show up\n"), vm->def->name); + int childstat; + + while (waitpid(child, &childstat, 0) == -1 && + errno == EINTR); + + if (childstat == 0) { + while (retries) { + if ((ret = virFileReadPid(driver->stateDir, vm->def->name, &vm->pid)) == 0) + break; + usleep(100*1000); + retries--; + } + if (ret) + qemudLog(QEMUD_WARN, _("Domain %s didn't show up\n"), vm->def->name); + } else { + qemudReportError(conn, NULL, NULL, VIR_ERR_INTERNAL_ERROR, + _("Unable to daemonize QEMU process")); + ret = -1; + } } if (ret == 0) { @@ -1262,14 +1296,17 @@ static void qemudShutdownVMDaemon(virCon if (!virDomainIsActive(vm)) return; - qemudLog(QEMUD_INFO, _("Shutting down VM '%s'\n"), vm->def->name); + qemudLog(QEMUD_DEBUG, _("Shutting down VM '%s'\n"), vm->def->name); if (virKillProcess(vm->pid, 0) == 0 && virKillProcess(vm->pid, SIGTERM) < 0) qemudLog(QEMUD_ERROR, _("Failed to send SIGTERM to %s (%d): %s\n"), vm->def->name, vm->pid, strerror(errno)); - virEventRemoveHandle(vm->monitor_watch); + if (vm->monitor_watch != -1) { + virEventRemoveHandle(vm->monitor_watch); + vm->monitor_watch = -1; + } if (close(vm->logfile) < 0) qemudLog(QEMUD_WARN, _("Unable to close logfile %d: %s\n"), -- |: 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 Fri, Jan 30, 2009 at 11:37:35AM +0000, Daniel P. Berrange wrote:
The recent refactoring of the QEMU startup process now reads the monitor TTY from the logfile. Unfortunately in this refactoring we lost the check for the 'ret == 0' scenario in the read() return value. So if QEMU quits at startup, eg due to missing disk image, we loop forever on read() == 0 because we hit end-of-file and QEMU has quit.
This patch adds back handling for this scenario, and takes care to propagate the contents of the log to the user as an error message
# start demo libvir: QEMU error : internal error unable to start guest: qemu: could not open disk image /home/berrange/Fedora-9-i686-Live.iso error: Failed to start domain demo
In addition, there were a couple of other bugs
- a memory leak where we set the 'monitorpath' variable, even though we'd just set it moments before.
- a missing check for whether the driver VNC password was present when initializing passwords at VM startupo
- missing initialization of the monitor_watch field, and missing checking for whether the watch was set before removing it.
- a gratuitous LOG_INFO when shutting down any VM, which could just be LOG_DEBUG.
Patch looks reasonnable to me, +1 Daniel -- Daniel Veillard | libxml Gnome XML XSLT toolkit http://xmlsoft.org/ daniel@veillard.com | Rpmfind RPM search engine http://rpmfind.net/ http://veillard.com/ | virtualization library http://libvirt.org/

On Fri, Jan 30, 2009 at 11:37:35AM +0000, Daniel P. Berrange wrote:
diff -r 826e6ed70ee0 src/qemu_driver.c --- a/src/qemu_driver.c Fri Jan 30 10:58:34 2009 +0000 +++ b/src/qemu_driver.c Fri Jan 30 11:00:43 2009 +0000 @@ -355,10 +355,9 @@ qemudReconnectVMs(struct qemud_driver *d qemudLog(QEMUD_ERR, _("Failed to reconnect monitor for %s: %d\n"), vm->def->name, rc); goto next_error; - } else - vm->monitorpath = status->monitorpath; Don't we loose initializing vm->monitorpath on reconnect this way?
The rest of the patch looks fine to me. -- Guido
- - if((vm->logfile = qemudLogFD(NULL, driver->logDir, vm->def->name)) < 0) + } + + if ((vm->logfile = qemudLogFD(NULL, driver->logDir, vm->def->name)) < 0) return -1;

On Fri, Jan 30, 2009 at 04:20:59PM +0100, Guido Günther wrote:
On Fri, Jan 30, 2009 at 11:37:35AM +0000, Daniel P. Berrange wrote:
diff -r 826e6ed70ee0 src/qemu_driver.c --- a/src/qemu_driver.c Fri Jan 30 10:58:34 2009 +0000 +++ b/src/qemu_driver.c Fri Jan 30 11:00:43 2009 +0000 @@ -355,10 +355,9 @@ qemudReconnectVMs(struct qemud_driver *d qemudLog(QEMUD_ERR, _("Failed to reconnect monitor for %s: %d\n"), vm->def->name, rc); goto next_error; - } else - vm->monitorpath = status->monitorpath; Don't we loose initializing vm->monitorpath on reconnect this way? qemudOpenMonitor already does that so everythings fine. Sorry for the noise. -- Guido

"Daniel P. Berrange" <berrange@redhat.com> wrote:
The recent refactoring of the QEMU startup process now reads the monitor TTY from the logfile. Unfortunately in this refactoring we lost the check for the 'ret == 0' scenario in the read() return value. So if QEMU quits at startup, eg due to missing disk image, we loop forever on read() == 0 because we hit end-of-file and QEMU has quit.
This patch adds back handling for this scenario, and takes care to propagate the contents of the log to the user as an error message
# start demo libvir: QEMU error : internal error unable to start guest: qemu: could not open disk image /home/berrange/Fedora-9-i686-Live.iso error: Failed to start domain demo
In addition, there were a couple of other bugs
- a memory leak where we set the 'monitorpath' variable, even though we'd just set it moments before.
- a missing check for whether the driver VNC password was present when initializing passwords at VM startupo
- missing initialization of the monitor_watch field, and missing checking for whether the watch was set before removing it.
- a gratuitous LOG_INFO when shutting down any VM, which could just be LOG_DEBUG.
FYI, I reproduced the infloop with the following: cat <<\EOF > d.xml <domain type='qemu'> <name>D</name> <uuid>c7a5fdbd-cdaf-9455-926a-d65c16db1809</uuid> <memory>219200</memory> <currentMemory>219200</currentMemory> <vcpu>2</vcpu> <os> <type arch='i686' machine='pc'>hvm</type> <boot dev='cdrom'/> </os> <devices> <emulator>/usr/bin/qemu-system-x86_64</emulator> <disk type='file' device='cdrom'> <source file='no-such-file'/> <target dev='hdc'/> <readonly/> </disk> <disk type='file' device='disk'> <source file='no-such-file'/> <target dev='hda'/> </disk> <graphics type='vnc' port='-1'/> </devices> </domain> EOF Before, this use of virsh would hang: qemud/libvirtd & src/virsh -c qemu:///session "define d.xml; start D" Now, it fails with a diagnostic, as you'd expect. Somehow, while testing this, I got numerous segfaults from libvirtd (due to dereferencing NULL doms->objs[i]->def, but those should never be NULL), yet when I went to set up a reproducer, it stopped happening altogether. So not only does the infloop-fix look like it does the right thing, I confirmed it with the above. The rest looks fine, too. Once we have something like my unix_sock_dir patch or an improved testing framework, I'll add a test like the above. Or maybe you know how to reproduce the infloop using the test driver? ACK.

On Fri, Jan 30, 2009 at 07:00:07PM +0100, Jim Meyering wrote:
"Daniel P. Berrange" <berrange@redhat.com> wrote:
The recent refactoring of the QEMU startup process now reads the monitor TTY from the logfile. Unfortunately in this refactoring we lost the check for the 'ret == 0' scenario in the read() return value. So if QEMU quits at startup, eg due to missing disk image, we loop forever on read() == 0 because we hit end-of-file and QEMU has quit.
This patch adds back handling for this scenario, and takes care to propagate the contents of the log to the user as an error message
# start demo libvir: QEMU error : internal error unable to start guest: qemu: could not open disk image /home/berrange/Fedora-9-i686-Live.iso error: Failed to start domain demo
In addition, there were a couple of other bugs
- a memory leak where we set the 'monitorpath' variable, even though we'd just set it moments before.
- a missing check for whether the driver VNC password was present when initializing passwords at VM startupo
- missing initialization of the monitor_watch field, and missing checking for whether the watch was set before removing it.
- a gratuitous LOG_INFO when shutting down any VM, which could just be LOG_DEBUG.
FYI, I reproduced the infloop with the following:
cat <<\EOF > d.xml <domain type='qemu'> <name>D</name> <uuid>c7a5fdbd-cdaf-9455-926a-d65c16db1809</uuid> <memory>219200</memory> <currentMemory>219200</currentMemory> <vcpu>2</vcpu> <os> <type arch='i686' machine='pc'>hvm</type> <boot dev='cdrom'/> </os> <devices> <emulator>/usr/bin/qemu-system-x86_64</emulator> <disk type='file' device='cdrom'> <source file='no-such-file'/> <target dev='hdc'/> <readonly/> </disk> <disk type='file' device='disk'> <source file='no-such-file'/> <target dev='hda'/> </disk> <graphics type='vnc' port='-1'/> </devices> </domain> EOF
Before, this use of virsh would hang:
qemud/libvirtd & src/virsh -c qemu:///session "define d.xml; start D"
Now, it fails with a diagnostic, as you'd expect.
FWIW, any scenario where the XML points to a disk image that doesn't exist should hit the codepath I did. That said it wasn't 100% reliable but I put that down to the LXC corruption in valgrind i posted.
Somehow, while testing this, I got numerous segfaults from libvirtd (due to dereferencing NULL doms->objs[i]->def, but those should never be NULL), yet when I went to set up a reproducer, it stopped happening altogether.
It shouldn't be possible to allocate a virDomainObjPtr instance without having a valid virDomainDefPtr instance. That said, it could be the case that the doms->objs[i] access is doing an array out of bounds access, due to inadequate thread locking, or a bogus re-allocation This patch is applied to CVS. 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 :|

@@ -670,11 +674,17 @@ qemudReadMonitorOutput(virConnectPtr con _("Failure while reading %s startup output"), what); return -1; } + } else if (ret == 0) { + return 0; This part causes problems for me if qemu didn't get a chance to dump it's output yet and so we hit EOF immediately since we don't respect the
Hi Daniel, On Fri, Jan 30, 2009 at 11:37:35AM +0000, Daniel P. Berrange wrote: poll timeout. Reverting this one hunk works around the issue. I can look into fixing this properly but it will be a couple of days until I get round to. Cheers, -- Guido
participants (4)
-
Daniel P. Berrange
-
Daniel Veillard
-
Guido Günther
-
Jim Meyering