[libvirt] [PATCH] util: Remove logging handlers in virExec
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@redhat.com> --- 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); + /* Clear out all signal handlers from parent so nothing unexpected can happen in our child once we unblock signals */ -- 1.6.5.2
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@redhat.com> --- 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 -- |: Red Hat, Engineering, London -o- http://people.redhat.com/berrange/ :| |: http://libvirt.org -o- http://virt-manager.org -o- http://ovirt.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: GnuPG: 7D3B9505 -o- F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 :|
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@redhat.com> --- 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? - Cole
On 01/12/2010 03:54 PM, Cole Robinson wrote:
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@redhat.com> --- 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, ^^^ keeps 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?
- Cole
-- Libvir-list mailing list Libvir-list@redhat.com https://www.redhat.com/mailman/listinfo/libvir-list
On Tue, Jan 12, 2010 at 03:54:39PM -0500, Cole Robinson wrote:
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@redhat.com> --- 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?
Oh of course - can you put a comment to that effect in your patch as a reminder. ACK to the patch Daniel -- |: Red Hat, Engineering, London -o- http://people.redhat.com/berrange/ :| |: http://libvirt.org -o- http://virt-manager.org -o- http://ovirt.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: GnuPG: 7D3B9505 -o- F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 :|
On 01/13/2010 04:20 AM, Daniel P. Berrange wrote:
On Tue, Jan 12, 2010 at 03:54:39PM -0500, Cole Robinson wrote:
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@redhat.com> --- 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?
Oh of course - can you put a comment to that effect in your patch as a reminder. ACK to the patch
Daniel
Thanks, pushed with an updated comment. - Cole
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@redhat.com> --- 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 Regards, Daniel -- |: Red Hat, Engineering, London -o- http://people.redhat.com/berrange/ :| |: http://libvirt.org -o- http://virt-manager.org -o- http://ovirt.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: GnuPG: 7D3B9505 -o- F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 :|
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@redhat.com> --- 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().
Does this look okay? I haven't tested that it fixes the issue (though I haven't reproduced the error either). - Cole
On Tue, Feb 02, 2010 at 12:15:01PM -0500, Cole Robinson wrote:
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@redhat.com> --- 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().
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) {
Yeah, i reckon that this should be sufficient. I'll get the BZ reporter to try this patch Daniel -- |: Red Hat, Engineering, London -o- http://people.redhat.com/berrange/ :| |: http://libvirt.org -o- http://virt-manager.org -o- http://ovirt.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: GnuPG: 7D3B9505 -o- F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505 :|
...
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
On 02/03/2010 03:33 AM, Jiri Denemark wrote:
...
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
Argh, yes, good call. I'll update the patch and resend. Thanks, Cole
On Wed, Feb 03, 2010 at 07:57:42AM -0500, Cole Robinson wrote:
On 02/03/2010 03:33 AM, Jiri Denemark wrote:
...
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
Argh, yes, good call. I'll update the patch and resend.
Thanks, Cole
Okay I did the small change and commited the patch accordingly, Daniel -- Daniel Veillard | libxml Gnome XML XSLT toolkit http://xmlsoft.org/ daniel@veillard.com | Rpmfind RPM search engine http://rpmfind.net/ http://veillard.com/ | virtualization library http://libvirt.org/
participants (4)
-
Cole Robinson -
Daniel P. Berrange -
Daniel Veillard -
Jiri Denemark