3:04 a.m.
libvirtd's stderr/stdout redirected to journald by default, so if
the journald has stopped, libvirtd and libvirtd's child process
will receive SIGPIPE signal when writing logs to stderr/stdout.
journald stopped reasons:
1. manual command "systemctl stop systemd-journald.service"
2. oom killer kill it.
...
Signed-off-by: Wang Yechao <wang.yechao255(a)zte.com.cn>
---
src/util/virlog.c | 8 ++++++++
1 file changed, 8 insertions(+)
diff --git a/src/util/virlog.c b/src/util/virlog.c
index 4c76fbc..127e121 100644
--- a/src/util/virlog.c
+++ b/src/util/virlog.c
@@ -39,6 +39,7 @@
# include <sys/un.h>
#endif
#include <fnmatch.h>
+#include <signal.h>
#include "virerror.h"
#include "virlog.h"
@@ -732,6 +733,9 @@ virLogOutputToFd(virLogSourcePtr source ATTRIBUTE_UNUSED,
if (fd < 0)
return;
+ if (fd == STDERR_FILENO || fd == STDOUT_FILENO)
+ signal(SIGPIPE, SIG_IGN);
+
if (virAsprintfQuiet(&msg, "%s: %s", timestamp, str) < 0)
return;
@@ -740,6 +744,10 @@ virLogOutputToFd(virLogSourcePtr source ATTRIBUTE_UNUSED,
if (flags & VIR_LOG_STACK_TRACE)
virLogStackTraceToFd(fd);
+
+ if (fd == STDERR_FILENO || fd == STDOUT_FILENO)
+ signal(SIGPIPE, SIG_DFL);
+
}
--
1.8.3.1
1:57 a.m.
On Sat, Oct 12, 2019 at 16:04:11 +0800, Wang Yechao wrote:
libvirtd's stderr/stdout redirected to journald by default, so
if
the journald has stopped, libvirtd and libvirtd's child process
will receive SIGPIPE signal when writing logs to stderr/stdout.
journald stopped reasons:
1. manual command "systemctl stop systemd-journald.service"
2. oom killer kill it.
What is configuration of logging for libvirtd? Libvirtd should not log
to stdout by default so I think this is more of a misconfiguration than
something needing fix in code.
For logging to the journal we use different means.
...
Signed-off-by: Wang Yechao <wang.yechao255(a)zte.com.cn>
---
src/util/virlog.c | 8 ++++++++
1 file changed, 8 insertions(+)
diff --git a/src/util/virlog.c b/src/util/virlog.c
index 4c76fbc..127e121 100644
--- a/src/util/virlog.c
+++ b/src/util/virlog.c
@@ -39,6 +39,7 @@
# include <sys/un.h>
#endif
#include <fnmatch.h>
+#include <signal.h>
#include "virerror.h"
#include "virlog.h"
@@ -732,6 +733,9 @@ virLogOutputToFd(virLogSourcePtr source ATTRIBUTE_UNUSED,
if (fd < 0)
return;
+ if (fd == STDERR_FILENO || fd == STDOUT_FILENO)
+ signal(SIGPIPE, SIG_IGN);
man signal says:
The effects of signal() in a multithreaded process are unspecified.
NACK
6:46 p.m.
New subject: [libvirt] [PATCH] util: ignore SIGPIPE when writing tostderr/stdout
On Sat, Oct 12, 2019 at 16:04:11 +0800, Wang Yechao wrote:
> libvirtd's stderr/stdout redirected to journald by default, so if
> the journald has stopped, libvirtd and libvirtd's child process
> will receive SIGPIPE signal when writing logs to stderr/stdout.
>
> journald stopped reasons:
> 1. manual command "systemctl stop systemd-journald.service"
> 2. oom killer kill it.
What is configuration of logging for libvirtd? Libvirtd should not log
to stdout by default so I think this is more of a misconfiguration than
something needing fix in code.
In my env, the libvirtd.conf like that:
"
log_level = 1
log_outputs="2:file:/var/log/libvirt/libvirtd.log"
"
Libvirtd works fine in this configuration, if i stop the journald.serivce.
But the child process that forked by libvirtd, will face this problem:
# virsh create vm.xml
error: Failed to create domain from vm.xml
error: internal error: Child process (LC_ALL=C
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin /usr/libexec/qemu-kvm -S
-no-user-config -nodefaults -nographic -machine none,accel=kvm:tcg -qmp
unix:/usr/local/var/lib/libvirt/qemu/qmp-vtKZqu/qmp.monitor,server,nowait -pidfile
/usr/local/var/lib/libvirt/qemu/qmp-vtKZqu/qmp.pid -daemonize) unexpected fatal signal 13
The version of libvirt that i test:
# virsh version
Compiled against library: libvirt 5.9.0
Using library: libvirt 5.9.0
Using API: QEMU 5.9.0
The child process recieve signal SIGPIPE, backtrace as follows:
Program received signal SIGPIPE, Broken pipe.
[Switching to Thread 0x7fa44dd25700 (LWP 67788)]
0x00007fa45b63779d in write () from /lib64/libpthread.so.0
(gdb) bt
#0 0x00007fa45b63779d in write () from /lib64/libpthread.so.0
#1 0x00007fa45e51f6ae in safewrite (fd=fd@entry=2, buf=buf@entry=0x7fa43800e6e0,
count=76) at util/virfile.c:1089
#2 0x00007fa45e53ba85 in virLogOutputToFd (source=source@entry=0x7fa45ea9b8a0
<virLogSelf>, priority=priority@entry=VIR_LOG_DEBUG,
filename=filename@entry=0x7fa45e7829b8 "util/virfile.c",
linenr=linenr@entry=114,
funcname=funcname@entry=0x7fa45e783d64 <__func__.19089>
"virFileClose", timestamp=timestamp@entry=0x7fa44dd23af0 "2019-10-14
09:11:06.087+0000",
metadata=metadata@entry=0x0, flags=flags@entry=0, rawstr=0x7fa43800ed20 "Closed
fd 3",
str=0x7fa4380108d0 "67788: debug : virFileClose:114 : Closed fd 3\n",
data=data@entry=0x2) at util/virlog.c:738
#3 0x00007fa45e53cdae in virLogVMessage (source=0x7fa45ea9b8a0 <virLogSelf>,
priority=VIR_LOG_DEBUG, filename=0x7fa45e7829b8 "util/virfile.c",
linenr=114, funcname=0x7fa45e783d64 <__func__.19089> "virFileClose",
metadata=0x0, fmt=fmt@entry=0x7fa45e782a48 "Closed fd %d",
vargs=vargs@entry=0x7fa44dd23b70) at util/virlog.c:682
#4 0x00007fa45e53cfc7 in virLogMessage (source=source@entry=0x7fa45ea9b8a0
<virLogSelf>, priority=priority@entry=VIR_LOG_DEBUG,
filename=filename@entry=0x7fa45e7829b8 "util/virfile.c",
linenr=linenr@entry=114,
funcname=funcname@entry=0x7fa45e783d64 <__func__.19089>
"virFileClose", metadata=metadata@entry=0x0, fmt=fmt@entry=0x7fa45e782a48
"Closed fd %d")
at util/virlog.c:556
#5 0x00007fa45e51ebaa in virFileClose (fdptr=fdptr@entry=0x7fa44dd24148,
flags=flags@entry=(VIR_FILE_CLOSE_PRESERVE_ERRNO | VIR_FILE_CLOSE_IGNORE_EBADF)) at
util/virfile.c:114
#6 0x00007fa45e4efae7 in virCommandMassClose (childerr=<optimized out>,
childout=33, childin=31, cmd=0x7fa4380119f0) at util/vircommand.c:525
#7 virExec (cmd=cmd@entry=0x7fa4380119f0) at util/vircommand.c:656
#8 0x00007fa45e50d374 in virCommandRunAsync (cmd=cmd@entry=0x7fa4380119f0,
pid=pid@entry=0x0) at util/vircommand.c:2644
#9 0x00007fa45e50d6c6 in virCommandRun (cmd=0x7fa4380119f0,
exitstatus=exitstatus@entry=0x7fa44dd24490) at util/vircommand.c:2463
#10 0x00007fa418bcc9b9 in qemuProcessQMPLaunch (proc=0x7fa43800f0e0) at
qemu/qemu_process.c:8605
If i change the log_level to 3, it can avoid this scene. But i want INFO messages in my
logfile.
For logging to the journal we use different means.
> ...
>
> Signed-off-by: Wang Yechao <wang.yechao255(a)zte.com.cn>
> ---
> src/util/virlog.c | 8 ++++++++
> 1 file changed, 8 insertions(+)
>
> diff --git a/src/util/virlog.c b/src/util/virlog.c
> index 4c76fbc..127e121 100644
> --- a/src/util/virlog.c
> +++ b/src/util/virlog.c
> @@ -39,6 +39,7 @@
> # include <sys/un.h>
> #endif
> #include <fnmatch.h>
> +#include <signal.h>
>
> #include "virerror.h"
> #include "virlog.h"
> @@ -732,6 +733,9 @@ virLogOutputToFd(virLogSourcePtr source ATTRIBUTE_UNUSED,
> if (fd < 0)
> return;
>
> + if (fd == STDERR_FILENO || fd == STDOUT_FILENO)
> + signal(SIGPIPE, SIG_IGN);
man signal says:
The effects of signal() in a multithreaded process are unspecified.
I didn't notice the effects of signal, thank you for pointing out.
And is there any good way to avoid this other than change the log_level ?
---
Best wishes
Wang Yechao
6:06 a.m.
New subject: [libvirt] [PATCH] util: ignore SIGPIPE when writing tostderr/stdout
On Mon, Oct 14, 2019 at 06:46:54PM +0800, wang.yechao255(a)zte.com.cn wrote:
> On Sat, Oct 12, 2019 at 16:04:11 +0800, Wang Yechao wrote:
> > libvirtd's stderr/stdout redirected to journald by default, so if
> > the journald has stopped, libvirtd and libvirtd's child process
> > will receive SIGPIPE signal when writing logs to stderr/stdout.
> >
> > journald stopped reasons:
> > 1. manual command "systemctl stop systemd-journald.service"
> > 2. oom killer kill it.
>
> What is configuration of logging for libvirtd? Libvirtd should not log
> to stdout by default so I think this is more of a misconfiguration than
> something needing fix in code.
>
In my env, the libvirtd.conf like that:
"
log_level = 1
log_outputs="2:file:/var/log/libvirt/libvirtd.log"
"
Libvirtd works fine in this configuration, if i stop the journald.serivce.
But the child process that forked by libvirtd, will face this problem:
# virsh create vm.xml
error: Failed to create domain from vm.xml
error: internal error: Child process (LC_ALL=C
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin /usr/libexec/qemu-kvm -S
-no-user-config -nodefaults -nographic -machine none,accel=kvm:tcg -qmp
unix:/usr/local/var/lib/libvirt/qemu/qmp-vtKZqu/qmp.monitor,server,nowait -pidfile
/usr/local/var/lib/libvirt/qemu/qmp-vtKZqu/qmp.pid -daemonize) unexpected fatal signal 13
The version of libvirt that i test:
# virsh version
Compiled against library: libvirt 5.9.0
Using library: libvirt 5.9.0
Using API: QEMU 5.9.0
The child process recieve signal SIGPIPE, backtrace as follows:
Program received signal SIGPIPE, Broken pipe.
[Switching to Thread 0x7fa44dd25700 (LWP 67788)]
0x00007fa45b63779d in write () from /lib64/libpthread.so.0
(gdb) bt
#0 0x00007fa45b63779d in write () from /lib64/libpthread.so.0
#1 0x00007fa45e51f6ae in safewrite (fd=fd@entry=2, buf=buf@entry=0x7fa43800e6e0,
count=76) at util/virfile.c:1089
#2 0x00007fa45e53ba85 in virLogOutputToFd (source=source@entry=0x7fa45ea9b8a0
<virLogSelf>, priority=priority@entry=VIR_LOG_DEBUG,
filename=filename@entry=0x7fa45e7829b8 "util/virfile.c",
linenr=linenr@entry=114,
funcname=funcname@entry=0x7fa45e783d64 <__func__.19089>
"virFileClose", timestamp=timestamp@entry=0x7fa44dd23af0 "2019-10-14
09:11:06.087+0000",
metadata=metadata@entry=0x0, flags=flags@entry=0, rawstr=0x7fa43800ed20 "Closed
fd 3",
str=0x7fa4380108d0 "67788: debug : virFileClose:114 : Closed fd 3\n",
data=data@entry=0x2) at util/virlog.c:738
#3 0x00007fa45e53cdae in virLogVMessage (source=0x7fa45ea9b8a0 <virLogSelf>,
priority=VIR_LOG_DEBUG, filename=0x7fa45e7829b8 "util/virfile.c",
linenr=114, funcname=0x7fa45e783d64 <__func__.19089> "virFileClose",
metadata=0x0, fmt=fmt@entry=0x7fa45e782a48 "Closed fd %d",
vargs=vargs@entry=0x7fa44dd23b70) at util/virlog.c:682
#4 0x00007fa45e53cfc7 in virLogMessage (source=source@entry=0x7fa45ea9b8a0
<virLogSelf>, priority=priority@entry=VIR_LOG_DEBUG,
filename=filename@entry=0x7fa45e7829b8 "util/virfile.c",
linenr=linenr@entry=114,
funcname=funcname@entry=0x7fa45e783d64 <__func__.19089>
"virFileClose", metadata=metadata@entry=0x0, fmt=fmt@entry=0x7fa45e782a48
"Closed fd %d")
at util/virlog.c:556
#5 0x00007fa45e51ebaa in virFileClose (fdptr=fdptr@entry=0x7fa44dd24148,
flags=flags@entry=(VIR_FILE_CLOSE_PRESERVE_ERRNO | VIR_FILE_CLOSE_IGNORE_EBADF)) at
util/virfile.c:114
#6 0x00007fa45e4efae7 in virCommandMassClose (childerr=<optimized out>,
childout=33, childin=31, cmd=0x7fa4380119f0) at util/vircommand.c:525
#7 virExec (cmd=cmd@entry=0x7fa4380119f0) at util/vircommand.c:656
At this point you are int he child QEMU process.
virFork resets all signal handlers back to their default setting so that
libvirtd's choice of signals doesn't impact the child process.
Perhaps the right answer is to use pthread_sigmask to block SIGPIPE
until just before we execve
Regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
8:03 p.m.
New subject: [libvirt] [PATCH] util: ignore SIGPIPE when writingtostderr/stdout
At this point you are int he child QEMU process.
virFork resets all signal handlers back to their default setting so that
libvirtd's choice of signals doesn't impact the child process.
Perhaps the right answer is to use pthread_sigmask to block SIGPIPE
until just before we execve
Thanks, I'll push another patch later.
---
Best wishes
Wang Yechao
4:24 a.m.
On Sat, Oct 12, 2019 at 04:04:11PM +0800, Wang Yechao wrote:
libvirtd's stderr/stdout redirected to journald by default, so
if
the journald has stopped, libvirtd and libvirtd's child process
will receive SIGPIPE signal when writing logs to stderr/stdout.
journald stopped reasons:
1. manual command "systemctl stop systemd-journald.service"
Don't do that then IMHO.
2. oom killer kill it.
...
If OOM killer picked journald, then it is game over for the host IMHO
and thed right answer is a reboot. This would be very surprising though.
OOM killer is more likely to pick QEMU or libvirtd as they're bigger
targets.
Signed-off-by: Wang Yechao <wang.yechao255(a)zte.com.cn>
---
src/util/virlog.c | 8 ++++++++
1 file changed, 8 insertions(+)
diff --git a/src/util/virlog.c b/src/util/virlog.c
index 4c76fbc..127e121 100644
--- a/src/util/virlog.c
+++ b/src/util/virlog.c
@@ -39,6 +39,7 @@
# include <sys/un.h>
#endif
#include <fnmatch.h>
+#include <signal.h>
#include "virerror.h"
#include "virlog.h"
@@ -732,6 +733,9 @@ virLogOutputToFd(virLogSourcePtr source ATTRIBUTE_UNUSED,
if (fd < 0)
return;
+ if (fd == STDERR_FILENO || fd == STDOUT_FILENO)
+ signal(SIGPIPE, SIG_IGN);
This is very wrong....
This code is run in both client & server, so we're messing with SIGPIPE
in applications that link to libvirt.so.
The use of signal() is not safe in multi-threaded applications.
In libvirtd we have set SIGPIPE to ignored already when starting up
libvirtd.
Regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
6:48 p.m.
New subject: [libvirt] [PATCH] util: ignore SIGPIPE when writing tostderr/stdout
On Sat, Oct 12, 2019 at 04:04:11PM +0800, Wang Yechao wrote:
> libvirtd's stderr/stdout redirected to journald by default, so if
> the journald has stopped, libvirtd and libvirtd's child process
> will receive SIGPIPE signal when writing logs to stderr/stdout.
>
> journald stopped reasons:
> 1. manual command "systemctl stop systemd-journald.service"
Don't do that then IMHO.
I just do it to reproduce this scenes.
> 2. oom killer kill it.
> ...
If OOM killer picked journald, then it is game over for the host IMHO
and thed right answer is a reboot. This would be very surprising though.
OOM killer is more likely to pick QEMU or libvirtd as they're bigger
targets.
Reboot is the best way. But sometimes, the oom is caused by a abnormal process,
if we stop it, the system's free memory will back to normal. And i think it's
no need to reboot.
>
> Signed-off-by: Wang Yechao <wang.yechao255(a)zte.com.cn>
> ---
> src/util/virlog.c | 8 ++++++++
> 1 file changed, 8 insertions(+)
>
> diff --git a/src/util/virlog.c b/src/util/virlog.c
> index 4c76fbc..127e121 100644
> --- a/src/util/virlog.c
> +++ b/src/util/virlog.c
> @@ -39,6 +39,7 @@
> # include <sys/un.h>
> #endif
> #include <fnmatch.h>
> +#include <signal.h>
>
> #include "virerror.h"
> #include "virlog.h"
> @@ -732,6 +733,9 @@ virLogOutputToFd(virLogSourcePtr source ATTRIBUTE_UNUSED,
> if (fd < 0)
> return;
>
> + if (fd == STDERR_FILENO || fd == STDOUT_FILENO)
> + signal(SIGPIPE, SIG_IGN);
This is very wrong....
This code is run in both client & server, so we're messing with SIGPIPE
in applications that link to libvirt.so.
Thanks to point my fault.
The use of signal() is not safe in multi-threaded applications.
In libvirtd we have set SIGPIPE to ignored already when starting up
libvirtd.
Can set SIGPIPE to ignored in the child process that forked by libvirtd ?
---
Best wishes
Wang Yechao
1861
days inactive
1864
days old
6 comments
4 participants
participants (4)
-
Daniel P. Berrangé -
Peter Krempa -
Wang Yechao -
wang.yechao255＠zte.com.cn