On Tue, Jan 12, 2010 at 03:26:26PM -0500, Cole Robinson wrote: > This allows debug statements and raised errors in hook functions to > actually be logged somewhere (stderr). Users can enable debugging in the > daemon and now see more info in /var/log/libvirt/... > > Signed-off-by: Cole Robinson <crobinso(a)redhat.com&gt; > --- > src/util/util.c | 6 ++++++ > 1 files changed, 6 insertions(+), 0 deletions(-) > > diff --git a/src/util/util.c b/src/util/util.c > index 44a4b2f..23d781d 100644 > --- a/src/util/util.c > +++ b/src/util/util.c > @@ -334,6 +334,7 @@ __virExec(virConnectPtr conn, > int pipeerr[2] = {-1,-1}; > int childout = -1; > int childerr = -1; > + int logprio; > sigset_t oldmask, newmask; > struct sigaction sig_action; > > @@ -452,6 +453,11 @@ __virExec(virConnectPtr conn, > of being seen / logged */ > virSetErrorFunc(NULL, NULL); > > + /* Make sure any hook logging is sent to stderr */ > + logprio = virLogGetDefaultPriority(); > + virLogReset(); > + virLogSetDefaultPriority(logprio); > + I'm not sure that I understand this - surely the child process is already inheriting this setup from the parent libvirtd ? Daniel

On 01/12/2010 03:46 PM, Daniel P. Berrange wrote: > On Tue, Jan 12, 2010 at 03:26:26PM -0500, Cole Robinson wrote: >> This allows debug statements and raised errors in hook functions to >> actually be logged somewhere (stderr). Users can enable debugging in the >> daemon and now see more info in /var/log/libvirt/... >> >> Signed-off-by: Cole Robinson <crobinso(a)redhat.com&gt; >> --- >> src/util/util.c | 6 ++++++ >> 1 files changed, 6 insertions(+), 0 deletions(-) >> >> diff --git a/src/util/util.c b/src/util/util.c >> index 44a4b2f..23d781d 100644 >> --- a/src/util/util.c >> +++ b/src/util/util.c >> @@ -334,6 +334,7 @@ __virExec(virConnectPtr conn, >> int pipeerr[2] = {-1,-1}; >> int childout = -1; >> int childerr = -1; >> + int logprio; >> sigset_t oldmask, newmask; >> struct sigaction sig_action; >> >> @@ -452,6 +453,11 @@ __virExec(virConnectPtr conn, >> of being seen / logged */ >> virSetErrorFunc(NULL, NULL); >> >> + /* Make sure any hook logging is sent to stderr */ >> + logprio = virLogGetDefaultPriority(); >> + virLogReset(); >> + virLogSetDefaultPriority(logprio); >> + > > I'm not sure that I understand this - surely the child process is already > inheriting this setup from the parent libvirtd ? > > Daniel Problem is that virExec closes only the file descriptors it is using, which means it will close the file descriptors for any nontrivial logging handlers. I could add some internal logging API to get the relevant fds and keep them from being closed, but not sure if we necessarily want to preserve those for a daemonized process?

This allows debug statements and raised errors in hook functions to actually be logged somewhere (stderr). Users can enable debugging in the daemon and now see more info in /var/log/libvirt/... Signed-off-by: Cole Robinson <crobinso(a)redhat.com&gt; --- src/util/util.c | 6 ++++++ 1 files changed, 6 insertions(+), 0 deletions(-) diff --git a/src/util/util.c b/src/util/util.c index 44a4b2f..23d781d 100644 --- a/src/util/util.c +++ b/src/util/util.c @@ -334,6 +334,7 @@ __virExec(virConnectPtr conn, int pipeerr[2] = {-1,-1}; int childout = -1; int childerr = -1; + int logprio; sigset_t oldmask, newmask; struct sigaction sig_action; @@ -452,6 +453,11 @@ __virExec(virConnectPtr conn, of being seen / logged */ virSetErrorFunc(NULL, NULL); + /* Make sure any hook logging is sent to stderr */ + logprio = virLogGetDefaultPriority(); + virLogReset(); + virLogSetDefaultPriority(logprio); +

On 02/02/2010 11:54 AM, Daniel P. Berrange wrote: > On Tue, Jan 12, 2010 at 03:26:26PM -0500, Cole Robinson wrote: >> This allows debug statements and raised errors in hook functions to >> actually be logged somewhere (stderr). Users can enable debugging in the >> daemon and now see more info in /var/log/libvirt/... >> >> Signed-off-by: Cole Robinson <crobinso(a)redhat.com&gt; >> --- >> src/util/util.c | 6 ++++++ >> 1 files changed, 6 insertions(+), 0 deletions(-) >> >> diff --git a/src/util/util.c b/src/util/util.c >> index 44a4b2f..23d781d 100644 >> --- a/src/util/util.c >> +++ b/src/util/util.c >> @@ -334,6 +334,7 @@ __virExec(virConnectPtr conn, >> int pipeerr[2] = {-1,-1}; >> int childout = -1; >> int childerr = -1; >> + int logprio; >> sigset_t oldmask, newmask; >> struct sigaction sig_action; >> >> @@ -452,6 +453,11 @@ __virExec(virConnectPtr conn, >> of being seen / logged */ >> virSetErrorFunc(NULL, NULL); >> >> + /* Make sure any hook logging is sent to stderr */ >> + logprio = virLogGetDefaultPriority(); >> + virLogReset(); >> + virLogSetDefaultPriority(logprio); >> + > > This patch turns out to cause a deadlock in libvirtd. The problem is > that fork() preserves the state of any mutexes which are locked. > > So if some thread in libvirtd is currently executing a logging call, > while another thread calls virExec(), that other thread no longer > exists in the child, but its lock is never released. So when the > child then does virLogReset() it deadlocks. > > I'm actuall surprised we've not hit this problem before, since any call > to virRaiseError in the child will also eventually run a logging function > which will in turn acquire a lock. > > The only way I see to address this, is for the parent process to call > virLogLock(), immediately before fork(), and then virLogUnlock() > afterwards in both parent & child. This will ensure that no other thread > can be holding the lock across fork(). > > https://bugzilla.redhat.com/show_bug.cgi?id=561066 > Does this look okay? I haven't tested that it fixes the issue (though I haven't reproduced the error either). - Cole

diff --git a/src/libvirt_private.syms b/src/libvirt_private.syms index e5e8860..7573af3 100644 --- a/src/libvirt_private.syms +++ b/src/libvirt_private.syms @@ -366,6 +366,8 @@ virLogParseOutputs; virLogStartup; virLogShutdown; virLogReset; +virLogLock; +virLogUnlock; # memory.h diff --git a/src/util/logging.c b/src/util/logging.c index 3b3c309..11a4b06 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -133,11 +133,11 @@ static int virLogResetOutputs(void); */ virMutex virLogMutex; -static void virLogLock(void) +void virLogLock(void) { virMutexLock(&virLogMutex); } -static void virLogUnlock(void) +void virLogUnlock(void) { virMutexUnlock(&virLogMutex); } diff --git a/src/util/logging.h b/src/util/logging.h index 49e2f6d..5f61f59 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -128,6 +128,8 @@ extern int virLogDefineOutput(virLogOutputFunc f, virLogCloseFunc c, void *data, * Internal logging API */ +extern void virLogLock(void); +extern void virLogUnlock(void); extern int virLogStartup(void); extern int virLogReset(void); extern void virLogShutdown(void); diff --git a/src/util/util.c b/src/util/util.c index cf1290d..901c0d2 100644 --- a/src/util/util.c +++ b/src/util/util.c @@ -415,12 +415,19 @@ __virExec(virConnectPtr conn, childerr = null; } + /* Ensure we hold the logging lock, to protect child processes + * from deadlocking on another threads inheirited mutex state */ + virLogLock(); + if ((pid = fork()) < 0) { virReportSystemError(conn, errno, "%s", _("cannot fork child process")); goto cleanup; } + /* Unlock for both parent and child process */ + virLogUnlock(); + if (pid) { /* parent */ close(null); if (outfd && *outfd == -1) {

... > diff --git a/src/util/util.c b/src/util/util.c > index cf1290d..901c0d2 100644 > --- a/src/util/util.c > +++ b/src/util/util.c > @@ -415,12 +415,19 @@ __virExec(virConnectPtr conn, > childerr = null; > } > > + /* Ensure we hold the logging lock, to protect child processes > + * from deadlocking on another threads inheirited mutex state */ > + virLogLock(); > + > if ((pid = fork()) < 0) { > virReportSystemError(conn, errno, > "%s", _("cannot fork child process")); > goto cleanup; > } > > + /* Unlock for both parent and child process */ > + virLogUnlock(); > + > if (pid) { /* parent */ > close(null); > if (outfd && *outfd == -1) { Hmm, shouldn't we virLogUnlock() even if fork() fails? That is, something like: virLogLock(); pid = fork(); virLogUnlock(); if (pid < 0) error; else if (pid) parent; ... Jirka