[libvirt] [PATCH] util: ignore SIGPIPE when writing to stderr/stdout
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@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
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@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
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@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
On Mon, Oct 14, 2019 at 06:46:54PM +0800, wang.yechao255@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 :|
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
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@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 :|
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@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
participants (4)
-
Daniel P. Berrangé -
Peter Krempa -
Wang Yechao -
wang.yechao255＠zte.com.cn