qemu: Ignore libvirt debug messages in qemu log

qemu driver uses a 4K buffer for reading qemu log file. This is enough
when only qemu's output is present in the log file. However, when
debugging messages are turned on, intermediate libvirt process fills the
log with a bunch of debugging messages before it executes qemu binary.
In such a case the buffer may become too small. However, we are not
really interested in libvirt messages so they can be filtered out from
the buffer.

src/qemu/qemu_process.c

@@ -762,11 +762,23 @@ qemuProcessReadLogOutput(virDomainObjPtr vm,
 {
     int retries = (timeout*10);
     int got = 0;
+    char *debug = NULL;
+    int ret = -1;
+    char *filter_next = buf;
+
     buf[0] = '\0';
 
+    /* This relies on log message format generated by virLogFormatString() and
+     * might need to be modified when message format changes. */
+    if (virAsprintf(&debug, ": %d: debug : ", vm->pid) < 0) {
+        virReportOOMError();
+        return -1;
+    }
+
     while (retries) {
-        ssize_t func_ret, ret;
+        ssize_t func_ret, bytes;
         int isdead = 0;
+        char *eol;
 
         func_ret = func(vm, buf, fd);
 
@@ -775,32 +787,47 @@ qemuProcessReadLogOutput(virDomainObjPtr vm,
 
         /* Any failures should be detected before we read the log, so we
          * always have something useful to report on failure. */
-        ret = saferead(fd, buf+got, buflen-got-1);
-        if (ret < 0) {
+        bytes = saferead(fd, buf+got, buflen-got-1);
+        if (bytes < 0) {
             virReportSystemError(errno,
                                  _("Failure while reading %s log output"),
                                  what);
-            return -1;
+            goto cleanup;
         }
 
-        got += ret;
+        got += bytes;
         buf[got] = '\0';
+
+        /* Filter out debug messages from intermediate libvirt process */
+        while ((eol = strchr(filter_next, '\n'))) {
+            *eol = '\0';
+            if (strstr(filter_next, debug)) {
+                memmove(filter_next, eol + 1, got - (eol - buf));
+                got -= eol + 1 - filter_next;
+            } else {
+                filter_next = eol + 1;
+                *eol = '\n';
+            }
+        }
+
         if (got == buflen-1) {
             qemuReportError(VIR_ERR_INTERNAL_ERROR,
                             _("Out of space while reading %s log output: %s"),
                             what, buf);
-            return -1;
+            goto cleanup;
         }
 
         if (isdead) {
             qemuReportError(VIR_ERR_INTERNAL_ERROR,
                             _("Process exited while reading %s log output: %s"),
                             what, buf);
-            return -1;
+            goto cleanup;
         }
 
-        if (func_ret <= 0)
-            return func_ret;
+        if (func_ret <= 0) {
+            ret = func_ret;
+            goto cleanup;
+        }
 
         usleep(100*1000);
         retries--;
@@ -809,7 +836,10 @@ qemuProcessReadLogOutput(virDomainObjPtr vm,
     qemuReportError(VIR_ERR_INTERNAL_ERROR,
                     _("Timed out while reading %s log output: %s"),
                     what, buf);
-    return -1;
+
+cleanup:
+    VIR_FREE(debug);
+    return ret;
 }
 
 

src/util/logging.c

@@ -660,6 +660,14 @@ virLogFormatString(char **msg,
                    const char *str)
 {
     int ret;
+
+    /*
+     * Be careful when changing the following log message formatting, we rely
+     * on it when stripping libvirt debug messages from qemu log files. So when
+     * changing this, you might also need to change the code there.
+     * virLogFormatString() function name is mentioned there so it's sufficient
+     * to just grep for it to find the right place.
+     */
     if ((funcname != NULL)) {
         ret = virAsprintf(msg, "%02d:%02d:%02d.%03d: %d: %s : %s:%lld : %s\n",
                           time_info->tm_hour, time_info->tm_min,