[libvirt] [PATCH] util: ignore SIGPIPE when writing tostderr/stdout

[wang.yechao255 at zte.com.cn]

> 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 at entry=2, buf=buf at entry=0x7fa43800e6e0, count=76) at util/virfile.c:1089
#2  0x00007fa45e53ba85 in virLogOutputToFd (source=source at entry=0x7fa45ea9b8a0 <virLogSelf>, priority=priority at entry=VIR_LOG_DEBUG,
    filename=filename at entry=0x7fa45e7829b8 "util/virfile.c", linenr=linenr at entry=114,
    funcname=funcname at entry=0x7fa45e783d64 <__func__.19089> "virFileClose", timestamp=timestamp at entry=0x7fa44dd23af0 "2019-10-14 09:11:06.087+0000",
    metadata=metadata at entry=0x0, flags=flags at entry=0, rawstr=0x7fa43800ed20 "Closed fd 3",
    str=0x7fa4380108d0 "67788: debug : virFileClose:114 : Closed fd 3\n", data=data at 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 at entry=0x7fa45e782a48 "Closed fd %d",
    vargs=vargs at entry=0x7fa44dd23b70) at util/virlog.c:682
#4  0x00007fa45e53cfc7 in virLogMessage (source=source at entry=0x7fa45ea9b8a0 <virLogSelf>, priority=priority at entry=VIR_LOG_DEBUG,
    filename=filename at entry=0x7fa45e7829b8 "util/virfile.c", linenr=linenr at entry=114,
    funcname=funcname at entry=0x7fa45e783d64 <__func__.19089> "virFileClose", metadata=metadata at entry=0x0, fmt=fmt at entry=0x7fa45e782a48 "Closed fd %d")
    at util/virlog.c:556
#5  0x00007fa45e51ebaa in virFileClose (fdptr=fdptr at entry=0x7fa44dd24148,
    flags=flags at 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 at entry=0x7fa4380119f0) at util/vircommand.c:656
#8  0x00007fa45e50d374 in virCommandRunAsync (cmd=cmd at entry=0x7fa4380119f0, pid=pid at entry=0x0) at util/vircommand.c:2644
#9  0x00007fa45e50d6c6 in virCommandRun (cmd=0x7fa4380119f0, exitstatus=exitstatus at 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 at 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