[libvirt] [PATCH 0/3] Ignore libvirt logs when reading QEMU error output

Jiri Denemark (3): qemu: Move QEMU log reading into a separate function qemu: Ignore libvirt logs when reading QEMU error output logging: Make log regexp more compact (and readable) src/qemu/qemu_process.c | 81 +++++++++++++++++++++++++------------------------ src/util/virlog.c | 4 +-- 2 files changed, 44 insertions(+), 41 deletions(-) -- 1.8.2.1

--- src/qemu/qemu_process.c | 61 ++++++++++++++++++++++++++++++------------------- 1 file changed, 38 insertions(+), 23 deletions(-) diff --git a/src/qemu/qemu_process.c b/src/qemu/qemu_process.c index ce9f501..a1fbd5f 100644 --- a/src/qemu/qemu_process.c +++ b/src/qemu/qemu_process.c @@ -1346,6 +1346,41 @@ error: return ret; } +static int +qemuProcessReadLog(int fd, char *buf, int buflen, int off) +{ + char *filter_next = buf; + ssize_t bytes; + char *eol; + + buf[0] = '\0'; + + while (off < buflen - 1) { + bytes = saferead(fd, buf + off, buflen - off - 1); + if (bytes < 0) + return -1; + else if (bytes == 0) + break; + + off += bytes; + buf[off] = '\0'; + + /* Filter out debug messages from intermediate libvirt process */ + while ((eol = strchr(filter_next, '\n'))) { + *eol = '\0'; + if (virLogProbablyLogMessage(filter_next)) { + memmove(filter_next, eol + 1, off - (eol - buf)); + off -= eol + 1 - filter_next; + } else { + filter_next = eol + 1; + *eol = '\n'; + } + } + } + + return off; +} + typedef int qemuProcessLogHandleOutput(virDomainObjPtr vm, const char *output, int fd); @@ -1365,46 +1400,26 @@ qemuProcessReadLogOutput(virDomainObjPtr vm, int retries = (timeout*10); int got = 0; int ret = -1; - char *filter_next = buf; buf[0] = '\0'; while (retries) { - ssize_t func_ret, bytes; + ssize_t func_ret; int isdead = 0; - char *eol; func_ret = func(vm, buf, fd); if (kill(vm->pid, 0) == -1 && errno == ESRCH) isdead = 1; - /* Any failures should be detected before we read the log, so we - * always have something useful to report on failure. */ - bytes = saferead(fd, buf+got, buflen-got-1); - if (bytes < 0) { + got = qemuProcessReadLog(fd, buf, buflen, got); + if (got < 0) { virReportSystemError(errno, _("Failure while reading %s log output"), what); goto cleanup; } - got += bytes; - buf[got] = '\0'; - - /* Filter out debug messages from intermediate libvirt process */ - while ((eol = strchr(filter_next, '\n'))) { - *eol = '\0'; - VIR_ERROR("<<<<<<<<<<<<%s>>>>>>>>>>", filter_next); - if (virLogProbablyLogMessage(filter_next)) { - memmove(filter_next, eol + 1, got - (eol - buf)); - got -= eol + 1 - filter_next; - } else { - filter_next = eol + 1; - *eol = '\n'; - } - } - if (got == buflen-1) { virReportError(VIR_ERR_INTERNAL_ERROR, _("Out of space while reading %s log output: %s"), -- 1.8.2.1

On 23/04/13 00:40, Jiri Denemark wrote:
--- src/qemu/qemu_process.c | 61 ++++++++++++++++++++++++++++++------------------- 1 file changed, 38 insertions(+), 23 deletions(-)
diff --git a/src/qemu/qemu_process.c b/src/qemu/qemu_process.c index ce9f501..a1fbd5f 100644 --- a/src/qemu/qemu_process.c +++ b/src/qemu/qemu_process.c @@ -1346,6 +1346,41 @@ error: return ret; }
+static int +qemuProcessReadLog(int fd, char *buf, int buflen, int off) +{ + char *filter_next = buf; + ssize_t bytes; + char *eol; + + buf[0] = '\0'; + + while (off < buflen - 1) { + bytes = saferead(fd, buf + off, buflen - off - 1); + if (bytes < 0) + return -1; + else if (bytes == 0) + break; + + off += bytes; + buf[off] = '\0'; + + /* Filter out debug messages from intermediate libvirt process */ + while ((eol = strchr(filter_next, '\n'))) { + *eol = '\0'; + if (virLogProbablyLogMessage(filter_next)) { + memmove(filter_next, eol + 1, off - (eol - buf)); + off -= eol + 1 - filter_next; + } else { + filter_next = eol + 1; + *eol = '\n'; + } + } + } + + return off; +} + typedef int qemuProcessLogHandleOutput(virDomainObjPtr vm, const char *output, int fd); @@ -1365,46 +1400,26 @@ qemuProcessReadLogOutput(virDomainObjPtr vm, int retries = (timeout*10); int got = 0; int ret = -1; - char *filter_next = buf;
buf[0] = '\0';
while (retries) { - ssize_t func_ret, bytes; + ssize_t func_ret; int isdead = 0; - char *eol;
func_ret = func(vm, buf, fd);
if (kill(vm->pid, 0) == -1 && errno == ESRCH) isdead = 1;
- /* Any failures should be detected before we read the log, so we - * always have something useful to report on failure. */ - bytes = saferead(fd, buf+got, buflen-got-1); - if (bytes < 0) { + got = qemuProcessReadLog(fd, buf, buflen, got); + if (got < 0) { virReportSystemError(errno, _("Failure while reading %s log output"), what); goto cleanup; }
- got += bytes; - buf[got] = '\0'; - - /* Filter out debug messages from intermediate libvirt process */ - while ((eol = strchr(filter_next, '\n'))) { - *eol = '\0'; - VIR_ERROR("<<<<<<<<<<<<%s>>>>>>>>>>", filter_next); - if (virLogProbablyLogMessage(filter_next)) { - memmove(filter_next, eol + 1, got - (eol - buf)); - got -= eol + 1 - filter_next; - } else { - filter_next = eol + 1; - *eol = '\n'; - } - } - if (got == buflen-1) { virReportError(VIR_ERR_INTERNAL_ERROR, _("Out of space while reading %s log output: %s"),
ACK

When QEMU fails to start, libvirt read its error output and reports it back in an error message. However, when libvirtd is configured to log debug messages, one would get the following unhelpful garbage: virsh # start cd error: Failed to start domain cd error: internal error process exited while connecting to monitor: \ 2013-04-22 14:24:54.214+0000: 2194219: debug : virFileClose:72 : \ Closed fd 21 2013-04-22 14:24:54.214+0000: 2194219: debug : virFileClose:72 : \ Closed fd 27 2013-04-22 14:24:54.215+0000: 2194219: debug : virFileClose:72 : \ Closed fd 3 2013-04-22 14:24:54.215+0000: 2194220: debug : virExec:602 : Run \ hook 0x7feb8f600bf0 0x7feb86ef9300 2013-04-22 14:24:54.215+0000: 2194220: debug : qemuProcessHook:2507 \ : Obtaining domain lock 2013-04-22 14:24:54.216+0000: 2194220: debug : \ virDomainLockProcessStart:170 : plugin=0x7feb780261f0 \ dom=0x7feb7802a360 paused=1 fd=0x7feb86ef8ec4 2013-04-22 14:24:54.216+0000: 2194220: debug : \ virDomainLockManagerNew:128 : plugin=0x7feb780261f0 \ dom=0x7feb7802a360 withResources=1 2013-04-22 14:24:54.216+0000: 2194220: debug : \ virLockManagerPluginGetDriver:297 : plugin=0x7feb780261f0 2013-04-22 14:24:54.216+0000: 2194220: debug : \ virLockManagerNew:321 : driver=0x7feb8ef08640 type=0 nparams=5 \ params=0x7feb86ef8d60 flags=0 2013-04-22 14:24:54.216+000 instead of (the output with this patch applied): virsh # start cd error: Reconnected to the hypervisor error: Failed to start domain cd error: internal error process exited while connecting to monitor: \ char device redirected to /dev/pts/33 (label charserial0) qemu-system-x86_64: -drive file=/home/vm/systemrescuecd-x86-1.2.0.\ iso,if=none,id=drive-ide0-1-0,readonly=on,format=raw,cache=none: \ could not open disk image /home/vm/systemrescuecd-x86-1.2.0.iso: \ Permission denied --- src/qemu/qemu_process.c | 20 ++++---------------- 1 file changed, 4 insertions(+), 16 deletions(-) diff --git a/src/qemu/qemu_process.c b/src/qemu/qemu_process.c index a1fbd5f..4988d9b 100644 --- a/src/qemu/qemu_process.c +++ b/src/qemu/qemu_process.c @@ -1665,21 +1665,6 @@ static void qemuProcessFreePtyPath(void *payload, const void *name ATTRIBUTE_UNU VIR_FREE(payload); } -static void -qemuProcessReadLogFD(int logfd, char *buf, int maxlen, int off) -{ - int ret; - char *tmpbuf = buf + off; - - ret = saferead(logfd, tmpbuf, maxlen - off - 1); - if (ret < 0) { - ret = 0; - } - - tmpbuf[ret] = '\0'; -} - - static int qemuProcessWaitForMonitor(virQEMUDriverPtr driver, virDomainObjPtr vm, @@ -1734,6 +1719,7 @@ cleanup: virHashFree(paths); if (pos != -1 && kill(vm->pid, 0) == -1 && errno == ESRCH) { + int len; /* VM is dead, any other error raised in the interim is probably * not as important as the qemu cmdline output */ if (virQEMUCapsUsedQMP(qemuCaps)) { @@ -1745,7 +1731,9 @@ cleanup: goto closelog; } } - qemuProcessReadLogFD(logfd, buf, buf_size, strlen(buf)); + + len = strlen(buf); + qemuProcessReadLog(logfd, buf + len, buf_size - len - 1, 0); virReportError(VIR_ERR_INTERNAL_ERROR, _("process exited while connecting to monitor: %s"), buf); -- 1.8.2.1

On 23/04/13 00:40, Jiri Denemark wrote:
When QEMU fails to start, libvirt read its error output and reports it back in an error message. However, when libvirtd is configured to log debug messages, one would get the following unhelpful garbage:
virsh # start cd error: Failed to start domain cd error: internal error process exited while connecting to monitor: \ 2013-04-22 14:24:54.214+0000: 2194219: debug : virFileClose:72 : \ Closed fd 21 2013-04-22 14:24:54.214+0000: 2194219: debug : virFileClose:72 : \ Closed fd 27 2013-04-22 14:24:54.215+0000: 2194219: debug : virFileClose:72 : \ Closed fd 3 2013-04-22 14:24:54.215+0000: 2194220: debug : virExec:602 : Run \ hook 0x7feb8f600bf0 0x7feb86ef9300 2013-04-22 14:24:54.215+0000: 2194220: debug : qemuProcessHook:2507 \ : Obtaining domain lock 2013-04-22 14:24:54.216+0000: 2194220: debug : \ virDomainLockProcessStart:170 : plugin=0x7feb780261f0 \ dom=0x7feb7802a360 paused=1 fd=0x7feb86ef8ec4 2013-04-22 14:24:54.216+0000: 2194220: debug : \ virDomainLockManagerNew:128 : plugin=0x7feb780261f0 \ dom=0x7feb7802a360 withResources=1 2013-04-22 14:24:54.216+0000: 2194220: debug : \ virLockManagerPluginGetDriver:297 : plugin=0x7feb780261f0 2013-04-22 14:24:54.216+0000: 2194220: debug : \ virLockManagerNew:321 : driver=0x7feb8ef08640 type=0 nparams=5 \ params=0x7feb86ef8d60 flags=0 2013-04-22 14:24:54.216+000
instead of (the output with this patch applied):
virsh # start cd error: Reconnected to the hypervisor error: Failed to start domain cd error: internal error process exited while connecting to monitor: \ char device redirected to /dev/pts/33 (label charserial0) qemu-system-x86_64: -drive file=/home/vm/systemrescuecd-x86-1.2.0.\ iso,if=none,id=drive-ide0-1-0,readonly=on,format=raw,cache=none: \ could not open disk image /home/vm/systemrescuecd-x86-1.2.0.iso: \ Permission denied --- src/qemu/qemu_process.c | 20 ++++---------------- 1 file changed, 4 insertions(+), 16 deletions(-)
diff --git a/src/qemu/qemu_process.c b/src/qemu/qemu_process.c index a1fbd5f..4988d9b 100644 --- a/src/qemu/qemu_process.c +++ b/src/qemu/qemu_process.c @@ -1665,21 +1665,6 @@ static void qemuProcessFreePtyPath(void *payload, const void *name ATTRIBUTE_UNU VIR_FREE(payload); }
-static void -qemuProcessReadLogFD(int logfd, char *buf, int maxlen, int off) -{ - int ret; - char *tmpbuf = buf + off; - - ret = saferead(logfd, tmpbuf, maxlen - off - 1); - if (ret < 0) { - ret = 0; - } - - tmpbuf[ret] = '\0'; -} - - static int qemuProcessWaitForMonitor(virQEMUDriverPtr driver, virDomainObjPtr vm, @@ -1734,6 +1719,7 @@ cleanup: virHashFree(paths);
if (pos != -1 && kill(vm->pid, 0) == -1 && errno == ESRCH) { + int len; /* VM is dead, any other error raised in the interim is probably * not as important as the qemu cmdline output */ if (virQEMUCapsUsedQMP(qemuCaps)) { @@ -1745,7 +1731,9 @@ cleanup: goto closelog; } } - qemuProcessReadLogFD(logfd, buf, buf_size, strlen(buf)); + + len = strlen(buf); + qemuProcessReadLog(logfd, buf + len, buf_size - len - 1, 0); virReportError(VIR_ERR_INTERNAL_ERROR, _("process exited while connecting to monitor: %s"), buf);
ACK

--- src/util/virlog.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/util/virlog.c b/src/util/virlog.c index 721c9bd..e31abb0 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -79,8 +79,8 @@ static int virLogEnd = 0; static regex_t *virLogRegex = NULL; -#define VIR_LOG_DATE_REGEX "[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9]" -#define VIR_LOG_TIME_REGEX "[0-9][0-9]:[0-9][0-9]:[0-9][0-9]\\.[0-9][0-9][0-9]\\+[0-9][0-9][0-9][0-9]" +#define VIR_LOG_DATE_REGEX "[0-9]{4}-[0-9]{2}-[0-9]{2}" +#define VIR_LOG_TIME_REGEX "[0-9]{2}:[0-9]{2}:[0-9]{2}\\.[0-9]{3}\\+[0-9]{4}" #define VIR_LOG_PID_REGEX "[0-9]+" #define VIR_LOG_LEVEL_REGEX "debug|info|warning|error" -- 1.8.2.1

On 23/04/13 00:40, Jiri Denemark wrote:
--- src/util/virlog.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/src/util/virlog.c b/src/util/virlog.c index 721c9bd..e31abb0 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -79,8 +79,8 @@ static int virLogEnd = 0; static regex_t *virLogRegex = NULL;
-#define VIR_LOG_DATE_REGEX "[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9]" -#define VIR_LOG_TIME_REGEX "[0-9][0-9]:[0-9][0-9]:[0-9][0-9]\\.[0-9][0-9][0-9]\\+[0-9][0-9][0-9][0-9]" +#define VIR_LOG_DATE_REGEX "[0-9]{4}-[0-9]{2}-[0-9]{2}" +#define VIR_LOG_TIME_REGEX "[0-9]{2}:[0-9]{2}:[0-9]{2}\\.[0-9]{3}\\+[0-9]{4}" #define VIR_LOG_PID_REGEX "[0-9]+" #define VIR_LOG_LEVEL_REGEX "debug|info|warning|error"
ACK

On Mon, Apr 22, 2013 at 18:40:07 +0200, Jiri Denemark wrote:
Jiri Denemark (3): qemu: Move QEMU log reading into a separate function qemu: Ignore libvirt logs when reading QEMU error output logging: Make log regexp more compact (and readable)
src/qemu/qemu_process.c | 81 +++++++++++++++++++++++++------------------------ src/util/virlog.c | 4 +-- 2 files changed, 44 insertions(+), 41 deletions(-)
Pushed, thanks for the review. Jirka
participants (2)
-
Jiri Denemark
-
Osier Yang