qemu: unify code for reporting errors from QEMU log files

There are two pretty similar functions qemuProcessReadLog and
qemuProcessReadChildErrors. Both read from the QEMU log file
and try to strip out libvirt messages. The latter then reports
an error, while the former lets the callers report an error.

Re-write qemuProcessReadLog so that it uses a single read
into a dynamically allocated buffer. Then introduce a new
qemuProcessReportLogError that calls qemuProcessReadLog
and reports an error.

Convert all callers to use qemuProcessReportLogError.

Signed-off-by: Daniel P. Berrange <berrange@redhat.com>

src/qemu/qemu_domain.c

@@ -2318,38 +2318,16 @@ qemuDomainCreateLog(virQEMUDriverPtr driver, virDomainObjPtr vm,
 
 
 int
-qemuDomainOpenLog(virQEMUDriverPtr driver, virDomainObjPtr vm, off_t pos)
+qemuDomainOpenLog(virQEMUDriverPtr driver, virDomainObjPtr vm)
 {
     virQEMUDriverConfigPtr cfg = virQEMUDriverGetConfig(driver);
     int fd;
-    off_t off;
-    int whence;
 
     fd = qemuDomainOpenLogHelper(cfg, vm, O_RDONLY, 0);
     virObjectUnref(cfg);
     if (fd < 0)
         return -1;
 
-    if (pos < 0) {
-        off = 0;
-        whence = SEEK_END;
-    } else {
-        off = pos;
-        whence = SEEK_SET;
-    }
-
-    if (lseek(fd, off, whence) < 0) {
-        if (whence == SEEK_END)
-            virReportSystemError(errno,
-                                 _("unable to seek to end of log for %s"),
-                                 vm->def->name);
-        else
-            virReportSystemError(errno,
-                                 _("unable to seek to %lld from start for %s"),
-                                 (long long)off, vm->def->name);
-        VIR_FORCE_CLOSE(fd);
-    }
-
     return fd;
 }
 

src/qemu/qemu_domain.h

@@ -351,7 +351,7 @@ void qemuDomainObjCheckNetTaint(virQEMUDriverPtr driver,
 
 
 int qemuDomainCreateLog(virQEMUDriverPtr driver, virDomainObjPtr vm, bool append);
-int qemuDomainOpenLog(virQEMUDriverPtr driver, virDomainObjPtr vm, off_t pos);
+int qemuDomainOpenLog(virQEMUDriverPtr driver, virDomainObjPtr vm);
 int qemuDomainAppendLog(virQEMUDriverPtr driver,
                         virDomainObjPtr vm,
                         int logFD,

src/qemu/qemu_migration.c

@@ -5969,7 +5969,7 @@ qemuMigrationFinish(virQEMUDriverPtr driver,
  cleanup:
     virPortAllocatorRelease(driver->migrationPorts, port);
     if (priv->mon)
-        qemuMonitorSetDomainLog(priv->mon, -1);
+        qemuMonitorSetDomainLog(priv->mon, -1, -1);
     VIR_FREE(priv->origname);
     virDomainObjEndAPI(&vm);
     if (mig) {

src/qemu/qemu_monitor.c

@@ -96,6 +96,7 @@ struct _qemuMonitor {
 
     /* Log file fd of the qemu process to dig for usable info */
     int logfd;
+    off_t logpos;
 };
 
 /**
@@ -389,38 +390,6 @@ qemuMonitorOpenPty(const char *monitor)
 }
 
 
-/* Get a possible error from qemu's log. This function closes the
- * corresponding log fd */
-static char *
-qemuMonitorGetErrorFromLog(qemuMonitorPtr mon)
-{
-    int len;
-    char *logbuf = NULL;
-    int orig_errno = errno;
-
-    if (mon->logfd < 0)
-        return NULL;
-
-    if (VIR_ALLOC_N_QUIET(logbuf, 4096) < 0)
-        goto error;
-
-    if ((len = qemuProcessReadLog(mon->logfd, logbuf, 4096 - 1, 0, true)) <= 0)
-        goto error;
-
-    while (len > 0 && logbuf[len - 1] == '\n')
-        logbuf[--len] = '\0';
-
- cleanup:
-    errno = orig_errno;
-    VIR_FORCE_CLOSE(mon->logfd);
-    return logbuf;
-
- error:
-    VIR_FREE(logbuf);
-    goto cleanup;
-}
-
-
 /* This method processes data that has been received
  * from the monitor. Looking for async events and
  * replies/errors.
@@ -737,25 +706,20 @@ qemuMonitorIO(int watch, int fd, int events, void *opaque)
     }
 
     if (error || eof) {
-        if (hangup) {
+        if (hangup && mon->logfd != -1) {
             /* Check if an error message from qemu is available and if so, use
              * it to overwrite the actual message. It's done only in early
              * startup phases or during incoming migration when the message
              * from qemu is certainly more interesting than a
              * "connection reset by peer" message.
              */
-            char *qemuMessage;
+            qemuProcessReportLogError(mon->logfd,
-
+                                      mon->logpos,
-            if ((qemuMessage = qemuMonitorGetErrorFromLog(mon))) {
+                                      _("early end of file from monitor, "
-                virReportError(VIR_ERR_INTERNAL_ERROR,
+                                        "possible problem"));
-                               _("early end of file from monitor: "
+            VIR_FORCE_CLOSE(mon->logfd);
-                                 "possible problem:\n%s"),
+            virCopyLastError(&mon->lastError);
-                               qemuMessage);
+            virResetLastError();
-                virCopyLastError(&mon->lastError);
-                virResetLastError();
-            }
-
-            VIR_FREE(qemuMessage);
         }
 
         if (mon->lastError.code != VIR_ERR_OK) {
@@ -960,7 +924,7 @@ qemuMonitorClose(qemuMonitorPtr mon)
     PROBE(QEMU_MONITOR_CLOSE,
           "mon=%p refs=%d", mon, mon->parent.parent.u.s.refs);
 
-    qemuMonitorSetDomainLog(mon, -1);
+    qemuMonitorSetDomainLog(mon, -1, -1);
 
     if (mon->fd >= 0) {
         if (mon->watch) {
@@ -3694,9 +3658,10 @@ qemuMonitorGetDeviceAliases(qemuMonitorPtr mon,
  *
  * @mon: Monitor object to set the log file reading on
  * @logfd: File descriptor of the already open log file
+ * @pos: position to read errors from
  */
 int
-qemuMonitorSetDomainLog(qemuMonitorPtr mon, int logfd)
+qemuMonitorSetDomainLog(qemuMonitorPtr mon, int logfd, off_t pos)
 {
     VIR_FORCE_CLOSE(mon->logfd);
     if (logfd >= 0 &&
@@ -3704,6 +3669,7 @@ qemuMonitorSetDomainLog(qemuMonitorPtr mon, int logfd)
         virReportSystemError(errno, "%s", _("failed to duplicate log fd"));
         return -1;
     }
+    mon->logpos = pos;
 
     return 0;
 }

src/qemu/qemu_monitor.h

@@ -892,7 +892,7 @@ int qemuMonitorDetachCharDev(qemuMonitorPtr mon,
 int qemuMonitorGetDeviceAliases(qemuMonitorPtr mon,
                                 char ***aliases);
 
-int qemuMonitorSetDomainLog(qemuMonitorPtr mon, int logfd);
+int qemuMonitorSetDomainLog(qemuMonitorPtr mon, int logfd, off_t pos);
 
 int qemuMonitorGetGuestCPU(qemuMonitorPtr mon,
                            virArch arch,

src/qemu/qemu_process.c

@@ -1549,7 +1549,7 @@ static qemuMonitorCallbacks monitorCallbacks = {
 
 static int
 qemuConnectMonitor(virQEMUDriverPtr driver, virDomainObjPtr vm, int asyncJob,
-                   int logfd)
+                   int logfd, off_t pos)
 {
     qemuDomainObjPrivatePtr priv = vm->privateData;
     int ret = -1;
@@ -1575,8 +1575,8 @@ qemuConnectMonitor(virQEMUDriverPtr driver, virDomainObjPtr vm, int asyncJob,
                           &monitorCallbacks,
                           driver);
 
-    if (mon)
+    if (mon && logfd != -1 && pos != -1)
-        ignore_value(qemuMonitorSetDomainLog(mon, logfd));
+        ignore_value(qemuMonitorSetDomainLog(mon, logfd, pos));
 
     virObjectLock(vm);
     virObjectUnref(vm);
@@ -1630,111 +1630,78 @@ qemuConnectMonitor(virQEMUDriverPtr driver, virDomainObjPtr vm, int asyncJob,
 /**
  * qemuProcessReadLog: Read log file of a qemu VM
  * @fd: File descriptor of the log file
- * @buf: buffer to store the read messages
- * @buflen: allocated space available in @buf
  * @off: Offset to start reading from
- * @skipchar: Skip messages about created character devices
+ * @msg: pointer to buffer to store the read messages in
  *
  * Reads log of a qemu VM. Skips messages not produced by qemu or irrelevant
- * messages. Returns length of the message stored in @buf, or -1 on error.
+ * messages. Returns returns 0 on success or -1 on error
- */
-int
-qemuProcessReadLog(int fd, char *buf, int buflen, int off, bool skipchar)
-{
-    char *filter_next = buf;
-    ssize_t bytes;
-    char *eol;
-
-    while (off < buflen - 1) {
-        bytes = saferead(fd, buf + off, buflen - off - 1);
-        if (bytes < 0)
-            return -1;
-
-        off += bytes;
-        buf[off] = '\0';
-
-        if (bytes == 0)
-            break;
-
-        /* Filter out debug messages from intermediate libvirt process */
-        while ((eol = strchr(filter_next, '\n'))) {
-            *eol = '\0';
-            if (virLogProbablyLogMessage(filter_next) ||
-                (skipchar &&
-                 STRPREFIX(filter_next, "char device redirected to"))) {
-                memmove(filter_next, eol + 1, off - (eol - buf));
-                off -= eol + 1 - filter_next;
-            } else {
-                filter_next = eol + 1;
-                *eol = '\n';
-            }
-        }
-    }
-
-    return off;
-}
-
-/*
- * Read domain log and probably overwrite error if there's one in
- * the domain log file. This function exists to cover the small
- * window between fork() and exec() during which child may fail
- * by libvirt's hand, e.g. placing onto a NUMA node failed.
  */
 static int
-qemuProcessReadChildErrors(virQEMUDriverPtr driver,
+qemuProcessReadLog(int fd, off_t offset, char **msg)
-                           virDomainObjPtr vm,
-                           off_t originalOff)
 {
-    int ret = -1;
+    char *buf;
-    int logfd;
+    size_t buflen = 1024 * 128;
-    off_t off = 0;
+    ssize_t got;
-    ssize_t bytes;
+    char *eol;
-    char buf[1024] = {0};
+    char *filter_next;
-    char *eol, *filter_next = buf;
 
-    if ((logfd = qemuDomainOpenLog(driver, vm, originalOff)) < 0)
+    /* Best effort jump to start of messages */
-        goto cleanup;
+    ignore_value(lseek(fd, offset, SEEK_SET));
 
-    while (off < sizeof(buf) - 1) {
+    if (VIR_ALLOC_N(buf, buflen) < 0)
-        bytes = saferead(logfd, buf + off, sizeof(buf) - off - 1);
+        return -1;
-        if (bytes < 0) {
-            VIR_WARN("unable to read from log file: %s",
-                     virStrerror(errno, buf, sizeof(buf)));
-            goto cleanup;
-        }
 
-        off += bytes;
+    got = saferead(fd, buf, buflen - 1);
-        buf[off] = '\0';
+    if (got <= 0) {
-
+        VIR_FREE(buf);
-        if (bytes == 0)
+        virReportSystemError(errno, "%s",
-            break;
+                             _("Unable to read from log file"));
-
+        return -1;
-        while ((eol = strchr(filter_next, '\n'))) {
-            *eol = '\0';
-            if (STRPREFIX(filter_next, "libvirt: ")) {
-                filter_next = eol + 1;
-                *eol = '\n';
-                break;
-            } else {
-                memmove(filter_next, eol + 1, off - (eol - buf));
-                off -= eol + 1 - filter_next;
-            }
-        }
     }
 
-    if (off > 0) {
+    buf[got] = '\0';
-        /* Found an error in the log. Report it */
+
-        virResetLastError();
+    /* Filter out debug messages from intermediate libvirt process */
-        virReportError(VIR_ERR_INTERNAL_ERROR,
+    filter_next = buf;
-                       _("Process exited prior to exec: %s"),
+    while ((eol = strchr(filter_next, '\n'))) {
-                       buf);
+        *eol = '\0';
+        if (virLogProbablyLogMessage(filter_next) ||
+            STRPREFIX(filter_next, "char device redirected to")) {
+            size_t skip = (eol + 1) - filter_next;
+            memmove(filter_next, eol + 1, (got - skip) + 1);
+            got -= skip;
+        } else {
+            filter_next = eol + 1;
+            *eol = '\n';
+        }
     }
+    filter_next = NULL; /* silence false coverity warning */
 
-    ret = 0;
+    if (buf[got - 1] == '\n') {
+        buf[got - 1] = '\0';
+        got--;
+    }
+    VIR_SHRINK_N(buf, buflen, buflen - got - 1);
+    *msg = buf;
+    return 0;
+}
 
- cleanup:
+
-    VIR_FORCE_CLOSE(logfd);
+int
-    return ret;
+qemuProcessReportLogError(int logfd,
+                          off_t offset,
+                          const char *msgprefix)
+{
+    char *logmsg = NULL;
+
+    if (qemuProcessReadLog(logfd, offset, &logmsg) < 0)
+        return -1;
+
+    virResetLastError();
+    virReportError(VIR_ERR_INTERNAL_ERROR,
+                   _("%s: %s"), msgprefix, logmsg);
+    VIR_FREE(logmsg);
+    return 0;
 }
 
 
@@ -1944,20 +1911,17 @@ qemuProcessWaitForMonitor(virQEMUDriverPtr driver,
                           virQEMUCapsPtr qemuCaps,
                           off_t pos)
 {
-    char *buf = NULL;
-    size_t buf_size = 4096; /* Plenty of space to get startup greeting */
-    int logfd = -1;
     int ret = -1;
     virHashTablePtr info = NULL;
     qemuDomainObjPrivatePtr priv;
+    int logfd = -1;
 
-    if (pos != -1 &&
+    if (pos != (off_t)-1 &&
-        (logfd = qemuDomainOpenLog(driver, vm, pos)) < 0)
+        (logfd = qemuDomainOpenLog(driver, vm)) < 0)
-        return -1;
+        goto cleanup;
-
 
     VIR_DEBUG("Connect monitor to %p '%s'", vm, vm->def->name);
-    if (qemuConnectMonitor(driver, vm, asyncJob, logfd) < 0)
+    if (qemuConnectMonitor(driver, vm, asyncJob, logfd, pos) < 0)
         goto cleanup;
 
     /* Try to get the pty path mappings again via the monitor. This is much more
@@ -1985,31 +1949,14 @@ qemuProcessWaitForMonitor(virQEMUDriverPtr driver,
  cleanup:
     virHashFree(info);
 
-    if (pos != -1 && kill(vm->pid, 0) == -1 && errno == ESRCH) {
+    if (pos != (off_t)-1 && kill(vm->pid, 0) == -1 && errno == ESRCH) {
-        /* VM is dead, any other error raised in the interim is probably
+        qemuProcessReportLogError(logfd, pos,
-         * not as important as the qemu cmdline output */
+                                  _("process exited while connecting to monitor"));
-        if (VIR_ALLOC_N(buf, buf_size) < 0)
-            goto closelog;
-
-        /* best effort seek - we need to reset to the original position, so that
-         * a possible read of the fd in the monitor code doesn't influence this
-         * error delivery option */
-        ignore_value(lseek(logfd, pos, SEEK_SET));
-        qemuProcessReadLog(logfd, buf, buf_size - 1, 0, true);
-        virReportError(VIR_ERR_INTERNAL_ERROR,
-                       _("process exited while connecting to monitor: %s"),
-                       buf);
         ret = -1;
     }
 
- closelog:
-    if (VIR_CLOSE(logfd) < 0) {
-        char ebuf[1024];
-        VIR_WARN("Unable to close logfile: %s",
-                 virStrerror(errno, ebuf, sizeof(ebuf)));
-    }
 
-    VIR_FREE(buf);
+    VIR_FORCE_CLOSE(logfd);
 
     return ret;
 }
@@ -3573,7 +3520,7 @@ qemuProcessReconnect(void *opaque)
     VIR_DEBUG("Reconnect monitor to %p '%s'", obj, obj->def->name);
 
     /* XXX check PID liveliness & EXE path */
-    if (qemuConnectMonitor(driver, obj, QEMU_ASYNC_JOB_NONE, -1) < 0)
+    if (qemuConnectMonitor(driver, obj, QEMU_ASYNC_JOB_NONE, -1, -1) < 0)
         goto error;
 
     /* Failure to connect to agent shouldn't be fatal */
@@ -4835,9 +4782,11 @@ qemuProcessLaunch(virConnectPtr conn,
 
     qemuDomainObjCheckTaint(driver, vm, logfile);
 
-    if ((pos = lseek(logfile, 0, SEEK_END)) < 0)
+    if ((pos = lseek(logfile, 0, SEEK_END)) < 0) {
         VIR_WARN("Unable to seek to end of logfile: %s",
                  virStrerror(errno, ebuf, sizeof(ebuf)));
+        pos = 0;
+    }
 
     VIR_DEBUG("Clear emulator capabilities: %d",
               cfg->clearEmulatorCapabilities);
@@ -4891,7 +4840,12 @@ qemuProcessLaunch(virConnectPtr conn,
     VIR_DEBUG("Waiting for handshake from child");
     if (virCommandHandshakeWait(cmd) < 0) {
         /* Read errors from child that occurred between fork and exec. */
-        qemuProcessReadChildErrors(driver, vm, pos);
+        int logfd = qemuDomainOpenLog(driver, vm);
+        if (logfd >= 0) {
+            qemuProcessReportLogError(logfd, pos,
+                                      _("Process exited prior to exec"));
+            VIR_FORCE_CLOSE(logfd);
+        }
         goto cleanup;
     }
 
@@ -5176,7 +5130,7 @@ qemuProcessStart(virConnectPtr conn,
     /* Keep watching qemu log for errors during incoming migration, otherwise
      * unset reporting errors from qemu log. */
     if (!incoming)
-        qemuMonitorSetDomainLog(priv->mon, -1);
+        qemuMonitorSetDomainLog(priv->mon, -1, -1);
 
     ret = 0;
 
@@ -5190,6 +5144,8 @@ qemuProcessStart(virConnectPtr conn,
         stopFlags |= VIR_QEMU_PROCESS_STOP_NO_RELABEL;
     if (migrateFrom)
         stopFlags |= VIR_QEMU_PROCESS_STOP_MIGRATED;
+    if (priv->mon)
+        qemuMonitorSetDomainLog(priv->mon, -1, -1);
     qemuProcessStop(driver, vm, VIR_DOMAIN_SHUTOFF_FAILED, stopFlags);
     goto cleanup;
 }

src/qemu/qemu_process.h

@@ -140,7 +140,9 @@ int qemuProcessAutoDestroyRemove(virQEMUDriverPtr driver,
 bool qemuProcessAutoDestroyActive(virQEMUDriverPtr driver,
                                   virDomainObjPtr vm);
 
-int qemuProcessReadLog(int fd, char *buf, int buflen, int off, bool skipchar);
+int qemuProcessReportLogError(int fd,
+                              off_t offset,
+                              const char *msgprefix);
 
 int qemuProcessSetSchedParams(int id, pid_t pid, size_t nsp,
                               virDomainThreadSchedParamPtr sp);