10:16 a.m.
From: "Daniel P. Berrange" <berrange(a)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(a)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
10:16 a.m.
New subject: [libvirt] [PATCH 2/3] Improve LXC startup error reporting
From: "Daniel P. Berrange" <berrange(a)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(a)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
9:40 a.m.
New subject: [libvirt] [PATCH 2/3] Improve LXC startup error reporting
On 03/06/13 17:16, Daniel P. Berrange wrote:
From: "Daniel P. Berrange" <berrange(a)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(a)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
9:58 a.m.
New subject: [libvirt] [PATCH 2/3] Improve LXC startup error reporting
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(a)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(a)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 :|
10:03 a.m.
New subject: [libvirt] [PATCH 2/3] Improve LXC startup error reporting
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(a)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(a)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
12:54 p.m.
New subject: [libvirt] [PATCH 2/3] Improve LXC startup error reporting
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(a)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(a)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 :|
10:16 a.m.
New subject: [libvirt] [PATCH 3/3] Convert QEMU driver to use virLogProbablyLogMessage
From: "Daniel P. Berrange" <berrange(a)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
8:55 a.m.
New subject: [libvirt] [PATCH 3/3] Convert QEMU driver to use virLogProbablyLogMessage
On 03/06/13 17:16, Daniel P. Berrange wrote:
ACK with the last hunk removed.
Peter
From: "Daniel P. Berrange" <berrange(a)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.
8:50 a.m.
On 03/06/13 17:16, Daniel P. Berrange wrote:
From: "Daniel P. Berrange" <berrange(a)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(a)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
10:08 a.m.
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(a)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(a)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 :|
4278
days inactive
4279
days old
9 comments
2 participants
participants (2)
-
Daniel P. Berrange -
Peter Krempa