[libvirt] [PATCH 1/3] Add method for checking if a string is (probably) a log message
From: "Daniel P. Berrange" <berrange@redhat.com> When reading log output from QEMU/LXC we need to skip over any libvirt log messages. Currently the QEMU driver checks for a fixed string, but this is better done with a regex. Add a method virLogProbablyLogMessage to do a regex check Signed-off-by: Daniel P. Berrange <berrange@redhat.com> --- src/libvirt_private.syms | 1 + src/util/virlog.c | 37 +++++++++++++++++++++++++++++++++++++ src/util/virlog.h | 3 +++ 3 files changed, 41 insertions(+) diff --git a/src/libvirt_private.syms b/src/libvirt_private.syms index ed46479..599b71e 100644 --- a/src/libvirt_private.syms +++ b/src/libvirt_private.syms @@ -1429,6 +1429,7 @@ virLogMessage; virLogParseDefaultPriority; virLogParseFilters; virLogParseOutputs; +virLogProbablyLogMessage; virLogReset; virLogSetBufferSize; virLogSetDefaultPriority; diff --git a/src/util/virlog.c b/src/util/virlog.c index 24ec9d3..6a1adca 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -32,6 +32,7 @@ #include <unistd.h> #include <signal.h> #include <execinfo.h> +#include <regex.h> #if HAVE_SYSLOG_H # include <syslog.h> #endif @@ -75,6 +76,17 @@ static char *virLogBuffer = NULL; static int virLogLen = 0; static int virLogStart = 0; 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_PID_REGEX "[0-9]+" +#define VIR_LOG_LEVEL_REGEX "debug|info|warning|error" + +#define VIR_LOG_REGEX \ + VIR_LOG_DATE_REGEX " " VIR_LOG_TIME_REGEX ": " \ + VIR_LOG_PID_REGEX ": " VIR_LOG_LEVEL_REGEX " : " /* * Filters are used to refine the rules on what to keep or drop @@ -209,6 +221,12 @@ virLogOnceInit(void) virLogStart = 0; virLogEnd = 0; virLogDefaultPriority = VIR_LOG_DEFAULT; + + if (VIR_ALLOC(virLogRegex) >= 0) { + if (regcomp(virLogRegex, VIR_LOG_REGEX, REG_EXTENDED) != 0) + VIR_FREE(virLogRegex); + } + virLogUnlock(); if (pbm) VIR_WARN("%s", pbm); @@ -1587,3 +1605,22 @@ virLogSetFromEnv(void) if (debugEnv && *debugEnv) virLogParseOutputs(debugEnv); } + + +/* + * Returns a true value if the first line in @str is + * probably a log message generated by the libvirt + * logging layer + */ +bool virLogProbablyLogMessage(const char *str) +{ + bool ret = false; + if (!virLogRegex) + return false; + virLogLock(); + if (regexec(virLogRegex, str, 0, NULL, 0) == 0) + ret = true; + virLogUnlock(); + VIR_ERROR("CHeck [%s]", str); + return ret; +} diff --git a/src/util/virlog.h b/src/util/virlog.h index aa81d6a..6b83245 100644 --- a/src/util/virlog.h +++ b/src/util/virlog.h @@ -188,4 +188,7 @@ extern void virLogVMessage(virLogSource src, va_list vargs) ATTRIBUTE_FMT_PRINTF(7, 0); extern int virLogSetBufferSize(int size); extern void virLogEmergencyDumpAll(int signum); + +bool virLogProbablyLogMessage(const char *str); + #endif -- 1.7.11.7
From: "Daniel P. Berrange" <berrange@redhat.com> Currently we rely on a VIR_ERROR message being logged by the virRaiseError function to report LXC startup errors. This gives the right message, but is rather ugly and can be truncated if lots of log messages are written. Change the LXC controller to explicitly print any virErrorPtr message to stderr. Then change the driver to skip over anything that looks like a log message. The result is that this error: Failed to start domain busy error: internal error guest failed to start: 2013-03-04 19:46:42.846+0000: 1734: info : libvirt version: 1.0.2 2013-03-04 19:46:42.846+0000: 1734: error : virFileLoopDeviceAssociate:600 : Unable to open /root/disk.raw: No such file or directory changes to error: Failed to start domain busy error: internal error guest failed to start: Unable to open /root/disk.raw: No such file or directory Signed-off-by: Daniel P. Berrange <berrange@redhat.com> --- src/lxc/lxc_controller.c | 7 ++- src/lxc/lxc_process.c | 130 ++++++++++++++++++++++++++++++++--------------- 2 files changed, 94 insertions(+), 43 deletions(-) diff --git a/src/lxc/lxc_controller.c b/src/lxc/lxc_controller.c index 15aa334..78e8a70 100644 --- a/src/lxc/lxc_controller.c +++ b/src/lxc/lxc_controller.c @@ -1706,7 +1706,6 @@ int main(int argc, char *argv[]) rc = virLXCControllerRun(ctrl); cleanup: - virPidFileDelete(LXC_STATE_DIR, name); if (ctrl) virLXCControllerDeleteInterfaces(ctrl); for (i = 0 ; i < nttyFDs ; i++) @@ -1715,5 +1714,11 @@ cleanup: virLXCControllerFree(ctrl); + if (rc < 0) { + virErrorPtr err = virGetLastError(); + if (err && err->message) + fprintf(stderr, "%s\n", err->message); + } + return rc < 0? EXIT_FAILURE : EXIT_SUCCESS; } diff --git a/src/lxc/lxc_process.c b/src/lxc/lxc_process.c index aaa81a7..6020f6f 100644 --- a/src/lxc/lxc_process.c +++ b/src/lxc/lxc_process.c @@ -24,6 +24,7 @@ #include <unistd.h> #include <fcntl.h> #include <signal.h> +#include <regex.h> #include "lxc_process.h" #include "lxc_domain.h" @@ -690,6 +691,11 @@ int virLXCProcessStop(virLXCDriverPtr driver, VIR_DEBUG("Stopping VM name=%s pid=%d reason=%d", vm->def->name, (int)vm->pid, (int)reason); + if (!virDomainObjIsActive(vm)) { + VIR_DEBUG("VM '%s' not active", vm->def->name); + return 0; + } + if (vm->pid <= 0) { virReportError(VIR_ERR_INTERNAL_ERROR, _("Invalid PID %d for container"), vm->pid); @@ -813,50 +819,27 @@ cleanup: return NULL; } + static int -virLXCProcessReadLogOutput(virDomainObjPtr vm, - char *logfile, - off_t pos, - char *buf, - size_t buflen) +virLXCProcessReadLogOutputData(virDomainObjPtr vm, + int fd, + char *buf, + size_t buflen) { - int fd; - off_t off; - int whence; - int got = 0, ret = -1; int retries = 10; + int got = 0; + int ret = -1; + char *filter_next = buf; - if ((fd = open(logfile, O_RDONLY)) < 0) { - virReportSystemError(errno, _("failed to open logfile %s"), - logfile); - goto cleanup; - } - - 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"), - logfile); - else - virReportSystemError(errno, - _("unable to seek to %lld from start for %s"), - (long long)off, logfile); - goto cleanup; - } + buf[0] = '\0'; while (retries) { ssize_t bytes; int isdead = 0; + char *eol; - if (kill(vm->pid, 0) == -1 && errno == ESRCH) + if (vm->pid <= 0 || + (kill(vm->pid, 0) == -1 && errno == ESRCH)) isdead = 1; /* Any failures should be detected before we read the log, so we @@ -864,28 +847,85 @@ virLXCProcessReadLogOutput(virDomainObjPtr vm, bytes = saferead(fd, buf+got, buflen-got-1); if (bytes < 0) { virReportSystemError(errno, "%s", - _("Failure while reading guest log output")); + _("Failure while reading log output")); goto cleanup; } got += bytes; buf[got] = '\0'; - if ((got == buflen-1) || isdead) { - break; + /* 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, 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 log output: %s"), + buf); + goto cleanup; + } + + if (isdead) { + ret = got; + goto cleanup; } usleep(100*1000); retries--; } + virReportError(VIR_ERR_INTERNAL_ERROR, + _("Timed out while reading log output: %s"), + buf); - ret = got; cleanup: + return ret; +} + + +static int +virLXCProcessReadLogOutput(virDomainObjPtr vm, + char *logfile, + off_t pos, + char *buf, + size_t buflen) +{ + int fd = -1; + int ret; + + if ((fd = open(logfile, O_RDONLY)) < 0) { + virReportSystemError(errno, + _("Unable to open log file %s"), + logfile); + return -1; + } + + if (lseek(fd, pos, SEEK_SET) < 0) { + virReportSystemError(errno, + _("Unable to seek log file %s to %llu"), + logfile, (unsigned long long)pos); + VIR_FORCE_CLOSE(fd); + return -1; + } + + ret = virLXCProcessReadLogOutputData(vm, + fd, + buf, + buflen); + VIR_FORCE_CLOSE(fd); return ret; } + /** * virLXCProcessStart: * @conn: pointer to connection @@ -1124,9 +1164,15 @@ int virLXCProcessStart(virConnectPtr conn, /* And get its pid */ if ((r = virPidFileRead(driver->stateDir, vm->def->name, &vm->pid)) < 0) { - virReportSystemError(-r, - _("Failed to read pid file %s/%s.pid"), - driver->stateDir, vm->def->name); + char out[1024]; + + if (virLXCProcessReadLogOutput(vm, logfile, pos, out, 1024) > 0) + virReportError(VIR_ERR_INTERNAL_ERROR, + _("guest failed to start: %s"), out); + else + virReportSystemError(-r, + _("Failed to read pid file %s/%s.pid"), + driver->stateDir, vm->def->name); goto cleanup; } -- 1.7.11.7
On 03/06/13 17:16, Daniel P. Berrange wrote:
From: "Daniel P. Berrange" <berrange@redhat.com>
Currently we rely on a VIR_ERROR message being logged by the virRaiseError function to report LXC startup errors. This gives the right message, but is rather ugly and can be truncated if lots of log messages are written. Change the LXC controller to explicitly print any virErrorPtr message to stderr. Then change the driver to skip over anything that looks like a log message.
The result is that this
error: Failed to start domain busy error: internal error guest failed to start: 2013-03-04 19:46:42.846+0000: 1734: info : libvirt version: 1.0.2 2013-03-04 19:46:42.846+0000: 1734: error : virFileLoopDeviceAssociate:600 : Unable to open /root/disk.raw: No such file or directory
changes to
error: Failed to start domain busy error: internal error guest failed to start: Unable to open /root/disk.raw: No such file or directory Signed-off-by: Daniel P. Berrange <berrange@redhat.com> --- src/lxc/lxc_controller.c | 7 ++- src/lxc/lxc_process.c | 130 ++++++++++++++++++++++++++++++++--------------- 2 files changed, 94 insertions(+), 43 deletions(-)
diff --git a/src/lxc/lxc_controller.c b/src/lxc/lxc_controller.c index 15aa334..78e8a70 100644 --- a/src/lxc/lxc_controller.c +++ b/src/lxc/lxc_controller.c @@ -1706,7 +1706,6 @@ int main(int argc, char *argv[]) rc = virLXCControllerRun(ctrl);
cleanup: - virPidFileDelete(LXC_STATE_DIR, name);
From the code later on, it doesn't seem you want retain the pid file. If you do so, errors won't be reported later on ... [1]
if (ctrl) virLXCControllerDeleteInterfaces(ctrl); for (i = 0 ; i < nttyFDs ; i++) @@ -1715,5 +1714,11 @@ cleanup:
virLXCControllerFree(ctrl);
+ if (rc < 0) { + virErrorPtr err = virGetLastError(); + if (err && err->message) + fprintf(stderr, "%s\n", err->message); + }
Possible errors from the cleanup steps above this code could shadow the real error message here.
+ return rc < 0? EXIT_FAILURE : EXIT_SUCCESS; } diff --git a/src/lxc/lxc_process.c b/src/lxc/lxc_process.c index aaa81a7..6020f6f 100644 --- a/src/lxc/lxc_process.c +++ b/src/lxc/lxc_process.c @@ -24,6 +24,7 @@ #include <unistd.h> #include <fcntl.h> #include <signal.h> +#include <regex.h>
This doesn't seem to be used anywhere in this patch.
#include "lxc_process.h" #include "lxc_domain.h" @@ -690,6 +691,11 @@ int virLXCProcessStop(virLXCDriverPtr driver,
VIR_DEBUG("Stopping VM name=%s pid=%d reason=%d", vm->def->name, (int)vm->pid, (int)reason); + if (!virDomainObjIsActive(vm)) { + VIR_DEBUG("VM '%s' not active", vm->def->name); + return 0; + } + if (vm->pid <= 0) { virReportError(VIR_ERR_INTERNAL_ERROR, _("Invalid PID %d for container"), vm->pid); @@ -813,50 +819,27 @@ cleanup: return NULL; }
+ static int -virLXCProcessReadLogOutput(virDomainObjPtr vm, - char *logfile, - off_t pos, - char *buf, - size_t buflen) +virLXCProcessReadLogOutputData(virDomainObjPtr vm, + int fd, + char *buf, + size_t buflen) { - int fd; - off_t off; - int whence; - int got = 0, ret = -1; int retries = 10; + int got = 0; + int ret = -1; + char *filter_next = buf;
- if ((fd = open(logfile, O_RDONLY)) < 0) { - virReportSystemError(errno, _("failed to open logfile %s"), - logfile); - goto cleanup; - } - - 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"), - logfile); - else - virReportSystemError(errno, - _("unable to seek to %lld from start for %s"), - (long long)off, logfile); - goto cleanup; - } + buf[0] = '\0';
while (retries) { ssize_t bytes; int isdead = 0; + char *eol;
- if (kill(vm->pid, 0) == -1 && errno == ESRCH) + if (vm->pid <= 0 || + (kill(vm->pid, 0) == -1 && errno == ESRCH)) isdead = 1;
/* Any failures should be detected before we read the log, so we @@ -864,28 +847,85 @@ virLXCProcessReadLogOutput(virDomainObjPtr vm, bytes = saferead(fd, buf+got, buflen-got-1); if (bytes < 0) { virReportSystemError(errno, "%s", - _("Failure while reading guest log output")); + _("Failure while reading log output")); goto cleanup; }
got += bytes; buf[got] = '\0';
- if ((got == buflen-1) || isdead) { - break; + /* 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, 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 log output: %s"), + buf); + goto cleanup; + } + + if (isdead) { + ret = got; + goto cleanup; }
usleep(100*1000); retries--; }
+ virReportError(VIR_ERR_INTERNAL_ERROR, + _("Timed out while reading log output: %s"), + buf);
- ret = got; cleanup: + return ret; +} + + +static int +virLXCProcessReadLogOutput(virDomainObjPtr vm, + char *logfile, + off_t pos, + char *buf, + size_t buflen) +{ + int fd = -1; + int ret; + + if ((fd = open(logfile, O_RDONLY)) < 0) { + virReportSystemError(errno, + _("Unable to open log file %s"), + logfile); + return -1; + } + + if (lseek(fd, pos, SEEK_SET) < 0) { + virReportSystemError(errno, + _("Unable to seek log file %s to %llu"), + logfile, (unsigned long long)pos); + VIR_FORCE_CLOSE(fd); + return -1; + } + + ret = virLXCProcessReadLogOutputData(vm, + fd, + buf, + buflen); + VIR_FORCE_CLOSE(fd); return ret; }
+ /** * virLXCProcessStart: * @conn: pointer to connection @@ -1124,9 +1164,15 @@ int virLXCProcessStart(virConnectPtr conn,
/* And get its pid */ if ((r = virPidFileRead(driver->stateDir, vm->def->name, &vm->pid)) < 0) {
[1] ... here.
- virReportSystemError(-r, - _("Failed to read pid file %s/%s.pid"), - driver->stateDir, vm->def->name); + char out[1024]; + + if (virLXCProcessReadLogOutput(vm, logfile, pos, out, 1024) > 0) + virReportError(VIR_ERR_INTERNAL_ERROR, + _("guest failed to start: %s"), out); + else + virReportSystemError(-r, + _("Failed to read pid file %s/%s.pid"), + driver->stateDir, vm->def->name); goto cleanup; }
Peter
On Thu, Mar 07, 2013 at 04:40:05PM +0100, Peter Krempa wrote:
On 03/06/13 17:16, Daniel P. Berrange wrote:
From: "Daniel P. Berrange" <berrange@redhat.com>
Currently we rely on a VIR_ERROR message being logged by the virRaiseError function to report LXC startup errors. This gives the right message, but is rather ugly and can be truncated if lots of log messages are written. Change the LXC controller to explicitly print any virErrorPtr message to stderr. Then change the driver to skip over anything that looks like a log message.
The result is that this
error: Failed to start domain busy error: internal error guest failed to start: 2013-03-04 19:46:42.846+0000: 1734: info : libvirt version: 1.0.2 2013-03-04 19:46:42.846+0000: 1734: error : virFileLoopDeviceAssociate:600 : Unable to open /root/disk.raw: No such file or directory
changes to
error: Failed to start domain busy error: internal error guest failed to start: Unable to open /root/disk.raw: No such file or directory Signed-off-by: Daniel P. Berrange <berrange@redhat.com> --- src/lxc/lxc_controller.c | 7 ++- src/lxc/lxc_process.c | 130 ++++++++++++++++++++++++++++++++--------------- 2 files changed, 94 insertions(+), 43 deletions(-)
diff --git a/src/lxc/lxc_controller.c b/src/lxc/lxc_controller.c index 15aa334..78e8a70 100644 --- a/src/lxc/lxc_controller.c +++ b/src/lxc/lxc_controller.c @@ -1706,7 +1706,6 @@ int main(int argc, char *argv[]) rc = virLXCControllerRun(ctrl);
cleanup: - virPidFileDelete(LXC_STATE_DIR, name);
From the code later on, it doesn't seem you want retain the pid file. If you do so, errors won't be reported later on ... [1]
+ /** * virLXCProcessStart: * @conn: pointer to connection @@ -1124,9 +1164,15 @@ int virLXCProcessStart(virConnectPtr conn,
/* And get its pid */ if ((r = virPidFileRead(driver->stateDir, vm->def->name, &vm->pid)) < 0) {
[1] ... here.
This handles the case where libvirt_lxc failed to startup at all, so never wrote the pid file. There is aready code later in this method which handles the case where libvirt_lxc started, but then quit early, which still reads the log output.
- virReportSystemError(-r, - _("Failed to read pid file %s/%s.pid"), - driver->stateDir, vm->def->name); + char out[1024]; + + if (virLXCProcessReadLogOutput(vm, logfile, pos, out, 1024) > 0) + virReportError(VIR_ERR_INTERNAL_ERROR, + _("guest failed to start: %s"), out); + else + virReportSystemError(-r, + _("Failed to read pid file %s/%s.pid"), + driver->stateDir, vm->def->name); goto cleanup;
REgards, Daniel -- |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| |: http://libvirt.org -o- http://virt-manager.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: http://entangle-photo.org -o- http://live.gnome.org/gtk-vnc :|
On 03/07/13 16:58, Daniel P. Berrange wrote:
On Thu, Mar 07, 2013 at 04:40:05PM +0100, Peter Krempa wrote:
On 03/06/13 17:16, Daniel P. Berrange wrote:
From: "Daniel P. Berrange" <berrange@redhat.com>
Currently we rely on a VIR_ERROR message being logged by the virRaiseError function to report LXC startup errors. This gives the right message, but is rather ugly and can be truncated if lots of log messages are written. Change the LXC controller to explicitly print any virErrorPtr message to stderr. Then change the driver to skip over anything that looks like a log message.
The result is that this
error: Failed to start domain busy error: internal error guest failed to start: 2013-03-04 19:46:42.846+0000: 1734: info : libvirt version: 1.0.2 2013-03-04 19:46:42.846+0000: 1734: error : virFileLoopDeviceAssociate:600 : Unable to open /root/disk.raw: No such file or directory
changes to
error: Failed to start domain busy error: internal error guest failed to start: Unable to open /root/disk.raw: No such file or directory Signed-off-by: Daniel P. Berrange <berrange@redhat.com> --- src/lxc/lxc_controller.c | 7 ++- src/lxc/lxc_process.c | 130 ++++++++++++++++++++++++++++++++--------------- 2 files changed, 94 insertions(+), 43 deletions(-)
diff --git a/src/lxc/lxc_controller.c b/src/lxc/lxc_controller.c index 15aa334..78e8a70 100644 --- a/src/lxc/lxc_controller.c +++ b/src/lxc/lxc_controller.c @@ -1706,7 +1706,6 @@ int main(int argc, char *argv[]) rc = virLXCControllerRun(ctrl);
cleanup: - virPidFileDelete(LXC_STATE_DIR, name);
From the code later on, it doesn't seem you want retain the pid file. If you do so, errors won't be reported later on ... [1]
+ /** * virLXCProcessStart: * @conn: pointer to connection @@ -1124,9 +1164,15 @@ int virLXCProcessStart(virConnectPtr conn,
/* And get its pid */ if ((r = virPidFileRead(driver->stateDir, vm->def->name, &vm->pid)) < 0) {
[1] ... here.
This handles the case where libvirt_lxc failed to startup at all, so never wrote the pid file. There is aready code later in this method which handles the case where libvirt_lxc started, but then quit early, which still reads the log output.
Ah, okay then. So ACK to the patch if you move the output of the error message in lxc_controller.c right after the cleanup label. Peter
On Thu, Mar 07, 2013 at 05:03:18PM +0100, Peter Krempa wrote:
On 03/07/13 16:58, Daniel P. Berrange wrote:
On Thu, Mar 07, 2013 at 04:40:05PM +0100, Peter Krempa wrote:
On 03/06/13 17:16, Daniel P. Berrange wrote:
From: "Daniel P. Berrange" <berrange@redhat.com>
Currently we rely on a VIR_ERROR message being logged by the virRaiseError function to report LXC startup errors. This gives the right message, but is rather ugly and can be truncated if lots of log messages are written. Change the LXC controller to explicitly print any virErrorPtr message to stderr. Then change the driver to skip over anything that looks like a log message.
The result is that this
error: Failed to start domain busy error: internal error guest failed to start: 2013-03-04 19:46:42.846+0000: 1734: info : libvirt version: 1.0.2 2013-03-04 19:46:42.846+0000: 1734: error : virFileLoopDeviceAssociate:600 : Unable to open /root/disk.raw: No such file or directory
changes to
error: Failed to start domain busy error: internal error guest failed to start: Unable to open /root/disk.raw: No such file or directory Signed-off-by: Daniel P. Berrange <berrange@redhat.com> --- src/lxc/lxc_controller.c | 7 ++- src/lxc/lxc_process.c | 130 ++++++++++++++++++++++++++++++++--------------- 2 files changed, 94 insertions(+), 43 deletions(-)
diff --git a/src/lxc/lxc_controller.c b/src/lxc/lxc_controller.c index 15aa334..78e8a70 100644 --- a/src/lxc/lxc_controller.c +++ b/src/lxc/lxc_controller.c @@ -1706,7 +1706,6 @@ int main(int argc, char *argv[]) rc = virLXCControllerRun(ctrl);
cleanup: - virPidFileDelete(LXC_STATE_DIR, name);
From the code later on, it doesn't seem you want retain the pid file. If you do so, errors won't be reported later on ... [1]
+ /** * virLXCProcessStart: * @conn: pointer to connection @@ -1124,9 +1164,15 @@ int virLXCProcessStart(virConnectPtr conn,
/* And get its pid */ if ((r = virPidFileRead(driver->stateDir, vm->def->name, &vm->pid)) < 0) {
[1] ... here.
This handles the case where libvirt_lxc failed to startup at all, so never wrote the pid file. There is aready code later in this method which handles the case where libvirt_lxc started, but then quit early, which still reads the log output.
Ah, okay then. So ACK to the patch if you move the output of the error message in lxc_controller.c right after the cleanup label.
In fact double checking things, removing that virPidFileDelete line is not required at all, so I've dropped it. Daniel -- |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| |: http://libvirt.org -o- http://virt-manager.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: http://entangle-photo.org -o- http://live.gnome.org/gtk-vnc :|
From: "Daniel P. Berrange" <berrange@redhat.com> The current QEMU code for skipping log messages only skips over 'debug' message, switch to virLogProbablyLogMessage to make sure it skips over all of them --- src/qemu/qemu_process.c | 12 ++---------- 1 file changed, 2 insertions(+), 10 deletions(-) diff --git a/src/qemu/qemu_process.c b/src/qemu/qemu_process.c index 9f1507a..3196dbc 100644 --- a/src/qemu/qemu_process.c +++ b/src/qemu/qemu_process.c @@ -1434,19 +1434,11 @@ 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, bytes; int isdead = 0; @@ -1473,7 +1465,7 @@ qemuProcessReadLogOutput(virDomainObjPtr vm, /* Filter out debug messages from intermediate libvirt process */ while ((eol = strchr(filter_next, '\n'))) { *eol = '\0'; - if (strstr(filter_next, debug)) { + if (virLogProbablyLogMessage(filter_next)) { memmove(filter_next, eol + 1, got - (eol - buf)); got -= eol + 1 - filter_next; } else { @@ -1510,7 +1502,6 @@ qemuProcessReadLogOutput(virDomainObjPtr vm, what, buf); cleanup: - VIR_FREE(debug); return ret; } @@ -3764,6 +3755,7 @@ int qemuProcessStart(virConnectPtr conn, if (unlink(priv->pidfile) < 0 && errno != ENOENT) { + VIR_FREE(priv->pidfile); virReportSystemError(errno, _("Cannot remove stale PID file %s"), priv->pidfile); -- 1.7.11.7
On 03/06/13 17:16, Daniel P. Berrange wrote:
From: "Daniel P. Berrange" <berrange@redhat.com>
The current QEMU code for skipping log messages only skips over 'debug' message, switch to virLogProbablyLogMessage to make sure it skips over all of them --- src/qemu/qemu_process.c | 12 ++---------- 1 file changed, 2 insertions(+), 10 deletions(-)
diff --git a/src/qemu/qemu_process.c b/src/qemu/qemu_process.c index 9f1507a..3196dbc 100644 --- a/src/qemu/qemu_process.c +++ b/src/qemu/qemu_process.c
...
@@ -3764,6 +3755,7 @@ int qemuProcessStart(virConnectPtr conn,
if (unlink(priv->pidfile) < 0 && errno != ENOENT) { + VIR_FREE(priv->pidfile); virReportSystemError(errno, _("Cannot remove stale PID file %s"), priv->pidfile);
This hunk doesn't seem to be related to this patch. Also it would free the priv->pidfile argument right before reporting the error.
ACK with the last hunk removed. Peter
On 03/06/13 17:16, Daniel P. Berrange wrote:
From: "Daniel P. Berrange" <berrange@redhat.com>
When reading log output from QEMU/LXC we need to skip over any libvirt log messages. Currently the QEMU driver checks for a fixed string, but this is better done with a regex. Add a method virLogProbablyLogMessage to do a regex check
Signed-off-by: Daniel P. Berrange <berrange@redhat.com> --- src/libvirt_private.syms | 1 + src/util/virlog.c | 37 +++++++++++++++++++++++++++++++++++++ src/util/virlog.h | 3 +++ 3 files changed, 41 insertions(+)
diff --git a/src/libvirt_private.syms b/src/libvirt_private.syms index ed46479..599b71e 100644 --- a/src/libvirt_private.syms +++ b/src/libvirt_private.syms @@ -1429,6 +1429,7 @@ virLogMessage; virLogParseDefaultPriority; virLogParseFilters; virLogParseOutputs; +virLogProbablyLogMessage; virLogReset; virLogSetBufferSize; virLogSetDefaultPriority; diff --git a/src/util/virlog.c b/src/util/virlog.c index 24ec9d3..6a1adca 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -32,6 +32,7 @@ #include <unistd.h> #include <signal.h> #include <execinfo.h> +#include <regex.h> #if HAVE_SYSLOG_H # include <syslog.h> #endif @@ -75,6 +76,17 @@ static char *virLogBuffer = NULL; static int virLogLen = 0; static int virLogStart = 0; static int virLogEnd = 0; +static regex_t *virLogRegex = NULL;
This pointer will probably need to be whitelisted in coverity/valgrind for leaking it's contents.
+ + +#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_PID_REGEX "[0-9]+" +#define VIR_LOG_LEVEL_REGEX "debug|info|warning|error" + +#define VIR_LOG_REGEX \ + VIR_LOG_DATE_REGEX " " VIR_LOG_TIME_REGEX ": " \ + VIR_LOG_PID_REGEX ": " VIR_LOG_LEVEL_REGEX " : "
/* * Filters are used to refine the rules on what to keep or drop @@ -209,6 +221,12 @@ virLogOnceInit(void) virLogStart = 0; virLogEnd = 0; virLogDefaultPriority = VIR_LOG_DEFAULT; + + if (VIR_ALLOC(virLogRegex) >= 0) { + if (regcomp(virLogRegex, VIR_LOG_REGEX, REG_EXTENDED) != 0) + VIR_FREE(virLogRegex); + } + virLogUnlock(); if (pbm) VIR_WARN("%s", pbm); @@ -1587,3 +1605,22 @@ virLogSetFromEnv(void) if (debugEnv && *debugEnv) virLogParseOutputs(debugEnv); } + + +/* + * Returns a true value if the first line in @str is + * probably a log message generated by the libvirt + * logging layer + */ +bool virLogProbablyLogMessage(const char *str) +{ + bool ret = false; + if (!virLogRegex) + return false; + virLogLock(); + if (regexec(virLogRegex, str, 0, NULL, 0) == 0)
regexec() is touching the compiled regex while processing it? The manpage didn't enlighten me enough to say if we really need the lock. Or is the lock here to protect the moment after the regex memory is allocated but the expression isn't compiled yet? Wouldn't it be possible then to rearrange the initializer to assign the value to the global pointer as the last step to avoid the lock here?
+ ret = true; + virLogUnlock(); + VIR_ERROR("CHeck [%s]", str);
This is probably a leftover debug string.
+ return ret; +} diff --git a/src/util/virlog.h b/src/util/virlog.h index aa81d6a..6b83245 100644 --- a/src/util/virlog.h +++ b/src/util/virlog.h @@ -188,4 +188,7 @@ extern void virLogVMessage(virLogSource src, va_list vargs) ATTRIBUTE_FMT_PRINTF(7, 0); extern int virLogSetBufferSize(int size); extern void virLogEmergencyDumpAll(int signum); + +bool virLogProbablyLogMessage(const char *str); + #endif
ACK if there isn't a way to get rid of the lock and with the leftover debug code removed. Peter
On Thu, Mar 07, 2013 at 03:50:48PM +0100, Peter Krempa wrote:
On 03/06/13 17:16, Daniel P. Berrange wrote:
From: "Daniel P. Berrange" <berrange@redhat.com>
When reading log output from QEMU/LXC we need to skip over any libvirt log messages. Currently the QEMU driver checks for a fixed string, but this is better done with a regex. Add a method virLogProbablyLogMessage to do a regex check
Signed-off-by: Daniel P. Berrange <berrange@redhat.com> --- src/libvirt_private.syms | 1 + src/util/virlog.c | 37 +++++++++++++++++++++++++++++++++++++ src/util/virlog.h | 3 +++ 3 files changed, 41 insertions(+)
diff --git a/src/libvirt_private.syms b/src/libvirt_private.syms index ed46479..599b71e 100644 --- a/src/libvirt_private.syms +++ b/src/libvirt_private.syms @@ -1429,6 +1429,7 @@ virLogMessage; virLogParseDefaultPriority; virLogParseFilters; virLogParseOutputs; +virLogProbablyLogMessage; virLogReset; virLogSetBufferSize; virLogSetDefaultPriority; diff --git a/src/util/virlog.c b/src/util/virlog.c index 24ec9d3..6a1adca 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -32,6 +32,7 @@ #include <unistd.h> #include <signal.h> #include <execinfo.h> +#include <regex.h> #if HAVE_SYSLOG_H # include <syslog.h> #endif @@ -75,6 +76,17 @@ static char *virLogBuffer = NULL; static int virLogLen = 0; static int virLogStart = 0; static int virLogEnd = 0; +static regex_t *virLogRegex = NULL;
This pointer will probably need to be whitelisted in coverity/valgrind for leaking it's contents.
+ + +#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_PID_REGEX "[0-9]+" +#define VIR_LOG_LEVEL_REGEX "debug|info|warning|error" + +#define VIR_LOG_REGEX \ + VIR_LOG_DATE_REGEX " " VIR_LOG_TIME_REGEX ": " \ + VIR_LOG_PID_REGEX ": " VIR_LOG_LEVEL_REGEX " : "
/* * Filters are used to refine the rules on what to keep or drop @@ -209,6 +221,12 @@ virLogOnceInit(void) virLogStart = 0; virLogEnd = 0; virLogDefaultPriority = VIR_LOG_DEFAULT; + + if (VIR_ALLOC(virLogRegex) >= 0) { + if (regcomp(virLogRegex, VIR_LOG_REGEX, REG_EXTENDED) != 0) + VIR_FREE(virLogRegex); + } + virLogUnlock(); if (pbm) VIR_WARN("%s", pbm); @@ -1587,3 +1605,22 @@ virLogSetFromEnv(void) if (debugEnv && *debugEnv) virLogParseOutputs(debugEnv); } + + +/* + * Returns a true value if the first line in @str is + * probably a log message generated by the libvirt + * logging layer + */ +bool virLogProbablyLogMessage(const char *str) +{ + bool ret = false; + if (!virLogRegex) + return false; + virLogLock(); + if (regexec(virLogRegex, str, 0, NULL, 0) == 0)
regexec() is touching the compiled regex while processing it? The manpage didn't enlighten me enough to say if we really need the lock.
Or is the lock here to protect the moment after the regex memory is allocated but the expression isn't compiled yet? Wouldn't it be possible then to rearrange the initializer to assign the value to the global pointer as the last step to avoid the lock here?
Linux manpages didn't say anything about thread safety, but the opengroup docs clarify it "The interface is defined so that the matched substrings rm_sp and rm_ep are in a separate regmatch_t structure instead of in regex_t. This allows a single compiled RE to be used simultaneously in several contexts; in main() and a signal handler, perhaps, or in multiple threads of lightweight processes" so we can remove the lock safely. Daniel -- |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| |: http://libvirt.org -o- http://virt-manager.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: http://entangle-photo.org -o- http://live.gnome.org/gtk-vnc :|
participants (2)
-
Daniel P. Berrange -
Peter Krempa