[PATCH] libvirt-guests.sh: fix log output with new systemd

[Christian Ehrhardt]

On Thu, Apr 30, 2020 at 2:51 PM Daniel P. Berrangé <berrange at redhat.com> wrote:
>
> On Thu, Apr 30, 2020 at 02:42:21PM +0200, Christian Ehrhardt wrote:
> > On Thu, Apr 30, 2020 at 2:10 PM Michal Privoznik <mprivozn at redhat.com> wrote:
> > >
> > > On 4/30/20 11:59 AM, Christian Ehrhardt wrote:
> > > > Newer systemd is too smart, it detects the PIDs of the gettext calls
> > > > and due to that a log lists libvirt-guests.sh with many different PIDs.
> > > >
> > > > Furthermore it struggles to collect the output in time, so it can be
> > > > truncated and overall looks like:
> > > >     libvirt-guests.sh[37986]: Running guests on default URI:
> > > >     libvirt-guests.sh[37995]: Running guests on
> > > >     libvirt-guests.sh[37977]: R
> > > >
> > > > Gather the gettext result into a local variable and printing
> > > > the value from libvirt-guests.sh itself fixes both issues.
> > > >
> > > > Fixes: https://bugs.launchpad.net/ubuntu/+source/libvirt/+bug/1875708
> > > >
> > > > Signed-off-by: Christian Ehrhardt <christian.ehrhardt at canonical.com>
> > > > ---
> > > >   tools/libvirt-guests.sh.in | 74 +++++++++++++++++++++-----------------
> > > >   1 file changed, 42 insertions(+), 32 deletions(-)
> > > >
> > > > diff --git a/tools/libvirt-guests.sh.in b/tools/libvirt-guests.sh.in
> > > > index 7af24dab3b..324abe3623 100644
> > > > --- a/tools/libvirt-guests.sh.in
> > > > +++ b/tools/libvirt-guests.sh.in
> > > > @@ -28,6 +28,16 @@ test ! -r "$sysconfdir"/rc.d/init.d/functions ||
> > > >   # Make sure this file is recognized as having translations: _("dummy")
> > > >   . "@bindir@"/gettext.sh
> > > >
> > > > +# Avoid output being listed under gettext PID and being truncated
> > > > +unbuffered_gettext () {
> > > > +    msg="$(gettext "$1")"
> > > > +    echo "$msg"
> > > > +}
> > > > +unbuffered_eval_gettext () {
> > > > +    msg="$(eval_gettext "$1")"
> > > > +    echo "$msg"
> > > > +}
> > > > +
> > >
> > > Ah, is this the case where gettext prints the text in many sequences
> > > whereas echo does it all at once? Or what do you think is happening
> > > here? I don't quite understand how buffering steps into this.
> >
> > You have two effects:
> > - systemd tries to detect and report which PID the output is from when
> >   something it printed. Therefore it appears to a user as if the script
> >   itself would have been invoked multiple times while actually is will be
> >   the PIDs of the different gettext calls
> > - I assume that to get this content it is hitchhiking the output streams
> >   somehow - the gettext processes are very very short lived and it seems
> >   when they are exiting some output of them might be lost.
>
> This doesn't pass a sniff test to me.
>
> systemd is reading stdout/stderr of the libvirt-guests script. How
> would it ever tell that certain lines from stdout/err are coming from
> different PIDs. Systemd isn't involved in spawning the gettext processes.
> It can see they come & go via cgroups pids, but that's about it.

Well it seems I have a reproducible symptom and a fix, but not the
explanation why the latter fixes the former.
I'll need to dive into some debug & analysis myself to explain it better.
I'll be back here once I got time to do that in depth check.

Until then whoever is affected (should be everyone) can give it a
thought as well.
Repro is as easy as
One console:
$ journalctl -f -u libvirt-guests
Other console:
$ systemctl stop libvirt-guests
$ systemctl start libvirt-guests

I see it with 245.4-4ubuntu3 (18.04) I'm not seeing it on
237-3ubuntu10.39 (20.04).
Maybe it is a systemd bug after all?
I'd be interested to hear if that is/isn't clobbering output for
anyone else and what your systemd versions are?

> 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 :|
>


-- 
Christian Ehrhardt
Staff Engineer, Ubuntu Server
Canonical Ltd