On Thu, Apr 30, 2020 at 06:22:28PM +0100, Daniel P. Berrangé wrote:
On Thu, Apr 30, 2020 at 06:28:08PM +0200, Christian Ehrhardt wrote:
> On Thu, Apr 30, 2020 at 5:10 PM Daniel P. Berrangé <berrange(a)redhat.com>
wrote:
> >
> > On Thu, Apr 30, 2020 at 04:58:25PM +0200, Christian Ehrhardt wrote:
> > > On Thu, Apr 30, 2020 at 2:51 PM Daniel P. Berrangé
<berrange(a)redhat.com> wrote:
> > > 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?
> >
> > FWIW, it works correctly on Fedora 31 with systemd 243.
>
> Eoan with 242-7ubuntu3.7 is good as well.
> I might need to try to get some interim versions from somewhere.
I've reproduced on Fedora 33 rawhide with systemd 245 - the first
place where it lists running guests is screwed up slightly:
I strace'd libvirt-guests.sh and the data sent looks fine.
I strace'd systemd-journald and the data it receives looks fine,
but the data systemd-journald writes into the journal, however, is
completely fubar:
recvmsg(32, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="Resuming guest core1:
", iov_len=2054}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET,
cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=70624, uid=0, gid=0}}], msg_controllen=32,
msg_flags=MSG_CTRUNC|MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 22
writev(33, [{iov_base="[ 2741.146550] ", iov_len=15},
{iov_base="libvirt-guests.sh", iov_len=17}, {iov_base="[70605]: ",
iov_len=9}, {iov_base="R", iov_len=1}, {iov_base="\n", iov_len=1}], 5)
= 43
writev(33, [{iov_base="[ 2741.163787] ", iov_len=15},
{iov_base="libvirt-guests.sh", iov_len=17}, {iov_base="[70624]: ",
iov_len=9}, {iov_base="R", iov_len=1}, {iov_base="\n", iov_len=1}], 5)
= 43
writev(33, [{iov_base="[ 2742.518626] ", iov_len=15},
{iov_base="libvirt-guests.sh", iov_len=17}, {iov_base="[70624]: ",
iov_len=9}, {iov_base="esuming guest core1:", iov_len=20},
{iov_base="\n", iov_len=1}], 5) = 62
writev(33, [{iov_base="[ 2742.531644] ", iov_len=15},
{iov_base="libvirt-guests.sh", iov_len=17}, {iov_base="[70655]: ",
iov_len=9}, {iov_base="esum", iov_len=4}, {iov_base="\n", iov_len=1}],
5) = 46
recvmsg(32, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="Resuming guest core2:
", iov_len=2054}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET,
cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=70662, uid=0, gid=0}}], msg_controllen=32,
msg_flags=MSG_CTRUNC|MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 22
writev(33, [{iov_base="[ 2742.687436] ", iov_len=15},
{iov_base="libvirt-guests.sh", iov_len=17}, {iov_base="[70605]: ",
iov_len=9}, {iov_base="e", iov_len=1}, {iov_base="\n", iov_len=1}], 5)
= 43
writev(33, [{iov_base="[ 2742.690716] ", iov_len=15},
{iov_base="libvirt-guests.sh", iov_len=17}, {iov_base="[70662]: ",
iov_len=9}, {iov_base="e", iov_len=1}, {iov_base="\n", iov_len=1}], 5)
= 43
writev(33, [{iov_base="[ 2744.015012] ", iov_len=15},
{iov_base="libvirt-guests.sh", iov_len=17}, {iov_base="[70662]: ",
iov_len=9}, {iov_base="esuming guest core2:", iov_len=20},
{iov_base="\n", iov_len=1}], 5) = 62
writev(33, [{iov_base="[ 2744.019848] ", iov_len=15},
{iov_base="libvirt-guests.sh", iov_len=17}, {iov_base="[70694]: ",
iov_len=9}, {iov_base="esum", iov_len=4}, {iov_base="\n", iov_len=1}],
5) = 46
writev(33, [{iov_base="[ 2744.036819] ", iov_len=15},
{iov_base="libvirt-guests.sh", iov_len=17}, {iov_base="[70605]: ",
iov_len=9}, {iov_base="e", iov_len=1}, {iov_base="\n", iov_len=1}], 5)
= 43
So I think we found a regression in journald making it mangle log
messages. I smells like it is corrupting some buffers somewhere.
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 :|