Truncated messages in journald since systemd v244

Truncated messages can be seen on this screenshot.

Hi Laurent,
this is very odd - it is a service that just has a start/end action.
I wonder how we could call this thrice on shutdown.

First of all - is this reproducible and showing every time so that we can try to debug it a bit - or is it only sometimes? I'm assuming it is reproducible since you had the time to pick a camera ...

Could you check (and report here) what these report for you:

$ systemctl status libvirt-guests
$ systemctl cat libvirt-guests
$ journalctl -u libvirt-guests

The truncated messages might just be an issue due to output buffering, but lets analyze this one by one. First of all I'm wondering more about the different PIDs in the output ...

I think I can see the same when I make the guests in a way that it runs a bit longer:
from journalctl -u:
Apr 22 12:51:29 Keschdeichel systemd[1]: Stopping Suspend/Resume Running libvirt Guests...
Apr 22 12:51:31 Keschdeichel libvirt-guests.sh[1239032]: Running guests on default URI:
Apr 22 12:51:31 Keschdeichel libvirt-guests.sh[1238005]: Running guest
Apr 22 12:51:31 Keschdeichel libvirt-guests.sh[1239381]: Running guest
Apr 22 12:51:31 Keschdeichel libvirt-guests.sh[1239381]: hutting down guests on d
Apr 22 12:51:32 Keschdeichel libvirt-guests.sh[1238005]: h
Apr 22 12:51:32 Keschdeichel libvirt-guests.sh[1239976]: h
Apr 22 12:51:32 Keschdeichel libvirt-guests.sh[1239976]: tarting shutdown on guest: focal-nvdim
Apr 22 12:51:32 Keschdeichel libvirt-guests.sh[1238005]: t
Apr 22 12:51:32 Keschdeichel libvirt-guests.sh[1240170]: t
Apr 22 12:51:32 Keschdeichel libvirt-guests.sh[1240170]: rror: Failed to shutdown domain 3bf3fe9c-9bf6-40a6-bbca-5ebb16837165
Apr 22 12:51:33 Keschdeichel libvirt-guests.sh[1240170]: error: Requested operation is not valid: domain is not running
Apr 22 12:51:38 Keschdeichel libvirt-guests.sh[1238005]: error: Requested operation is not valid: domain is nWaiting for 1 guests to shut down, 115 seconds left
Apr 22 12:51:43 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 110 seconds left
Apr 22 12:51:48 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 105 seconds left
Apr 22 12:51:54 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 100 seconds left
Apr 22 12:51:59 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 95 seconds left
Apr 22 12:52:04 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 90 seconds left
Apr 22 12:52:09 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 85 seconds left
Apr 22 12:52:14 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 80 seconds left
Apr 22 12:52:19 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 75 seconds left
Apr 22 12:52:24 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 70 seconds left
Apr 22 12:52:29 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 65 seconds left
Apr 22 12:52:35 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 60 seconds left
Apr 22 12:52:40 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 55 seconds left
Apr 22 12:52:45 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 50 seconds left
Apr 22 12:52:50 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 45 seconds left
Apr 22 12:52:55 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 40 seconds left
Apr 22 12:53:00 Keschdeichel libvirt-guests.sh[1238005]: Waiting for 1 guests to shut down, 35 seconds left
Apr 22 12:53:05 Keschdeichel libvirt-gue...

Ok I can reproduce this in a container without much setup (no guests needed):
Watching the journal when running starr/stop:

root@f:~# systemctl start libvirt-guests
Apr 30 05:45:55 f systemd[1]: Starting Suspend/Resume Running libvirt Guests...
Apr 30 05:45:55 f systemd[1]: Finished Suspend/Resume Running libvirt Guests.

root@f:~# systemctl stop libvirt-guests
Apr 30 05:46:12 f systemd[1]: Stopping Suspend/Resume Running libvirt Guests...
Apr 30 05:46:12 f libvirt-guests.sh[37141]: Running guests on default URI:
Apr 30 05:46:12 f libvirt-guests.sh[37150]: Running guests on
Apr 30 05:46:12 f libvirt-guests.sh[37132]: R
Apr 30 05:46:12 f systemd[1]: libvirt-guests.service: Succeeded.
Apr 30 05:46:12 f systemd[1]: Stopped Suspend/Resume Running libvirt Guests.

My gut feeling is that this is about the buffering through eval_gettext that is used for translation - but I need more time.

Since it is not functionally impacted the severity is low (for now until we know more).

Thanks for the report Laurent, you don't need to add the data I asked in comment #3 anymore.

OK, thank you for looking at this bug!

It is indeed cosmetic, but some users with more serious problems with libvirt may be sent to wrong paths if they see those messages.

This seems to be a combination of two effects in new systemd.
- The changing PID is due to the output reporting the PIDs of the gettext calls used for translation.
- The gettext output is buffered and that output might be clobbered if programs end too soon for systemd logging to pick it up correctly.

We can fix this rather easily (IMHO) by:
a) making all calls to use a wrapper function
b) get the output and report it from the script itself
c) set output buffers to zero (probably too much - o let me put that in an extra commit)

Yeah tests show (c) isn't really needed so let me skip that.

Note: happens with systemd 245.4

Fix submitted upstream, let's see what comments on that will be
=> https://www.redhat.com/archives/libvir-list/2020-April/msg01474.html

Reported to systemd https://github.com/systemd/systemd/issues/15654

The discussion in the systemd bug made it clear that this isn't a libvirt-bug.
It is a systemd issue since v~244.

[1] has a proposed fix, that if accepted we should backport to Focal.

This issue has the chance to clobber any output to journald, the libvirt case just happened to be a nice trigger to see it more easily.

I'm rephrasing the bug as needed, but we have to wait until upstream accepts it anyway and I'd leave it to the usual systemd-package uploaders as most often there are other changes to bundle.

[1]: https://github.com/systemd/systemd/pull/15685

FYI: the fixes will also need a minor backport change due to [1], but cmsg isn't touched in the new changes so no backport of [1] itself is needed (which would in turn change more than we want and affect other subsystems)

[1]: https://github.com/systemd/systemd/commit/371d72e05b7e2c2b7850cb04d8d4c18be1e60421

I have a branch [1] and a PPA [2] based on the upstream suggested fix.
For now these are only meant to test&verification to provide feedback to [3]

[1]: https://code.launchpad.net/~paelzer/ubuntu/+source/systemd/+git/systemd/+merge/383390
[2]: https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/4046/+packages
[3]: https://github.com/systemd/systemd/pull/15685

The upstream submission is still being discussed (now got tests added and some more questions answered), but it is still on its way.

Thanks a lot for your efforts to analyze and fix this bug!

FYI reworked by L. Poettering in https://github.com/systemd/systemd/pull/15801 now

This is now merged upstream.
Eventually https://github.com/systemd/systemd/pull/15801 was the PR that got merged.

I'd ask to backport those to Groovy/Focal to fix this kind of output truncation.

This bug was fixed in the package systemd - 245.5-3ubuntu1

---------------
systemd (245.5-3ubuntu1) groovy; urgency=medium

  [ Dan Streetman ]
  * Hotadd only offline memory and CPUs (LP: #1876018)
    File: debian/extra/rules-ubuntu/40-vm-hotadd.rules
    https://git.launchpad.net/~ubuntu-core-dev/ubuntu/+source/systemd/commit/?id=dc68569fb46b04791202a40326003799becae859

  [ Balint Reczey ]
  * Merge to Ubuntu from Debian unstable
  - Dropped changes:
    * Cherry-pick fix from upstream master to adjust UseGateway= default
  * journald: stream pid change newline fix (LP: #1875708)
    Files:
    - debian/patches/debian/fsckd-daemon-for-inter-fsckd-communication.patch
    - debian/patches/lp1875708/journald-Increase-stdout-buffer-size-sooner-when-almost-f.patch
    - debian/patches/lp1875708/journald-rework-end-of-line-marker-handling-to-use-a-fiel.patch
    - debian/patches/lp1875708/journald-rework-pid-change-handling.patch
    - debian/patches/lp1875708/journald-use-log_warning_errno-where-appropriate.patch
    - debian/patches/lp1875708/journald-use-the-fact-that-client_context_release-returns.patch
    - debian/patches/lp1875708/man-document-the-new-_LINE_BREAK-type.patch
    - debian/patches/lp1875708/socket-util-introduce-type-safe-dereferencing-wrapper-CMS.patch
    - debian/patches/lp1875708/test-Add-a-test-case-for-15654.patch
    https://git.launchpad.net/~ubuntu-core-dev/ubuntu/+source/systemd/commit/?id=95302fbe53202bdac33f86031aa56026444a92d3

  [ Dimitri John Ledkov ]
  * meson: initialize time-epoch to reproducible builds compatible value
    (LP: #1878969)
    File: debian/patches/meson-initialize-time-epoch-to-reproducible-builds-compat.patch
    https://git.launchpad.net/~ubuntu-core-dev/ubuntu/+source/systemd/commit/?id=6785dfd98f81dfe3e3d5273511ec33b196ddb0c3

systemd (245.5-3) unstable; urgency=medium

  [ Michael Biebl ]
  * Bump priority of libnss-systemd to standard
  * logind: avoid shadow lookups when doing userdb client side
  * Disable DNSSEC support by default in resolved.
    The upstream default, DNSSEC=allow-downgrade can lead to compatibility
    issues with certain network access points. Previously, DNSSEC support
    was only turned off when built for a stable Debian release, but it is
    safer and more consistent to just generally change the default to
    DNSSEC=no. (Closes: #959996)
  * Bump debhelper compatibility level to 13.
    Use the debhelper-compat package to declare the compatibility level and
    drop debian/compat.
  * Convert to dh_installsystemd and disable dh_installsystemduser
  * Drop custom initramfs update code.
    Now handled by dh_installinitramfs which is enabled by default in compat
    level 12 and above.

  [ Dan Streetman ]
  * Cherry-pick fix from upstream master to adjust UseGateway= default
    - network: change UseGateway= default to UseRoutes= setting
    - network: honor SetDNSRoutes= even if UseGateway=False
    (LP: #1867375)

  [ Topi Miettinen ]
  * Delete empty lines at end of file.
    Upstream commit hooks don't allow empty lines and of course they serve no
    purpose.

 -- Balint Reczey <email address hidden> Tue, 19 May 2020 19:43:50 +0200

Status changed to 'Confirmed' because the bug affects multiple users.

A SRU to Focal would be greatly appreciated as dehydrated (Let's Encrypt client) is also affected, probably because it's in essence just a bash script. Here are the logs where it seems to indicate the certificate doesn't need to to be renewed just yet:

Jun 25 00:26:10 rproxy dehydrated[21256]: + Valid till Aug 4 03:20:48 2020 GMT
Jun 25 00:26:10 rproxy dehydrated[21407]: + Valid till Aug 4 03:20:4
Jun 25 00:26:10 rproxy dehydrated[21256]: + Valid till Aug 4 03:20:4
Jun 25 00:26:10 rproxy dehydrated[21256]: Longer tha

Having the full output would be nice :) Count on me for a focal-proposed verification if you agree on a SRU ;)

I'll upload early next week, sorry for the delay.

Hello Laurent, or anyone else affected,

Accepted systemd into focal-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/systemd/245.4-4ubuntu3.2 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-focal to verification-done-focal. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-focal. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

All autopkgtests for the newly accepted systemd (245.4-4ubuntu3.2) for focal have finished running.
The following regressions have been reported in tests triggered by the package:

apt/unknown (armhf)
indicator-session/17.3.20+19.10.20190921-0ubuntu1 (arm64)
dovecot/1:2.3.7.2-1ubuntu3.1 (armhf)
postgresql-12/unknown (armhf)
mir/unknown (armhf)
systemd/245.4-4ubuntu3.2 (amd64)
umockdev/unknown (armhf)
policykit-1/unknown (armhf)
asterisk/unknown (armhf)
anbox/unknown (armhf)
php7.4/unknown (armhf)
ksystemlog/unknown (armhf)
polkit-qt-1/unknown (armhf)

Please visit the excuses page listed below and investigate the failures, proceeding afterwards as per the StableReleaseUpdates policy regarding autopkgtest regressions [1].

https://people.canonical.com/~ubuntu-archive/proposed-migration/focal/update_excuses.html#systemd

[1] https://wiki.ubuntu.com/StableReleaseUpdates#Autopkgtest_Regressions

Thank you!

Reproducing the issue *before* the patch:

root@foo:~# dpkg -l| grep -wF ' systemd '
ii systemd 245.4-4ubuntu3.1 amd64 system and service manager
root@foo:~# systemctl status test.service
● test.service - Test Truncate
     Loaded: loaded (/etc/systemd/system/test.service; enabled; vendor preset: enabled)
     Active: active (exited) since Mon 2020-07-20 18:08:56 UTC; 53s ago
    Process: 228 ExecStart=/usr/lib/test.sh long-test-for-start (code=exited, status=0/SUCCESS)
   Main PID: 228 (code=exited, status=0/SUCCESS)

Jul 20 18:08:56 foo systemd[1]: Starting Test Truncate...
Jul 20 18:08:56 foo test.sh[229]: This will
Jul 20 18:08:56 foo test.sh[228]: T
Jul 20 18:08:56 foo test.sh[230]: T
Jul 20 18:08:56 foo test.sh[230]: sually fai
Jul 20 18:08:56 foo test.sh[228]: s
Jul 20 18:08:56 foo test.sh[231]: s
Jul 20 18:08:56 foo test.sh[231]: nd be truncate
Jul 20 18:08:56 foo test.sh[228]: n
Jul 20 18:08:56 foo systemd[1]: Finished Test Truncate.

Upgrading to focal-proposed version:

root@foo:~# apt-get dist-upgrade -V
Reading package lists... Done
Building dependency tree
Reading state information... Done
Calculating upgrade... Done
The following packages will be upgraded:
   ...
   libnss-systemd (245.4-4ubuntu3.1 => 245.4-4ubuntu3.2)
   libpam-systemd (245.4-4ubuntu3.1 => 245.4-4ubuntu3.2)
   libseccomp2 (2.4.3-1ubuntu3.20.04.2 => 2.4.3-1ubuntu3.20.04.3)
   libsystemd0 (245.4-4ubuntu3.1 => 245.4-4ubuntu3.2)
   libudev1 (245.4-4ubuntu3.1 => 245.4-4ubuntu3.2)
   systemd (245.4-4ubuntu3.1 => 245.4-4ubuntu3.2)
   systemd-sysv (245.4-4ubuntu3.1 => 245.4-4ubuntu3.2)
   systemd-timesyncd (245.4-4ubuntu3.1 => 245.4-4ubuntu3.2)
   udev (245.4-4ubuntu3.1 => 245.4-4ubuntu3.2)
   ...
17 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.

root@foo:~# reboot

Verifying the bug is fixed:

root@foo:~# systemctl status test.service
● test.service - Test Truncate
     Loaded: loaded (/etc/systemd/system/test.service; enabled; vendor preset: enabled)
     Active: active (exited) since Mon 2020-07-20 18:12:09 UTC; 1s ago
    Process: 139 ExecStart=/usr/lib/test.sh long-test-for-start (code=exited, status=0/SUCCESS)
   Main PID: 139 (code=exited, status=0/SUCCESS)

Jul 20 18:12:09 foo systemd[1]: Starting Test Truncate...
Jul 20 18:12:09 foo test.sh[140]: This will
Jul 20 18:12:09 foo test.sh[141]: usually fail
Jul 20 18:12:09 foo test.sh[142]: and be truncated
Jul 20 18:12:09 foo systemd[1]: Finished Test Truncate.

It is so marking as such, thanks!

This bug was fixed in the package systemd - 245.4-4ubuntu3.2

---------------
systemd (245.4-4ubuntu3.2) focal; urgency=medium

   [ Dan Streetman ]
   * Hotadd only offline memory and CPUs (LP: #1876018)
     File: debian/extra/rules-ubuntu/40-vm-hotadd.rules
     https://git.launchpad.net/~ubuntu-core-dev/ubuntu/+source/systemd/commit/?id=72d815471596056b7727be5b10f87513ff1d5757
   * Lock swap blockdevice while calling mkswap (LP: #1838329)
     Files:
     - d/p/lp1838329/0001-blockdev-propagate-one-more-unexpected-error.patch
     - d/p/lp1838329/0002-makefs-log-about-OOM-condition.patch
     - d/p/lp1838329/0003-dissect-use-log_debug_errno-where-appropriate.patch
     - d/p/lp1838329/0004-blockdev-add-helper-for-locking-whole-block-device.patch
     - d/p/lp1838329/0005-makefs-lock-device-while-we-operate.patch
     - d/p/lp1838329/0006-makefs-normalize-logging-a-bit.patch
     - d/p/lp1838329/0007-cryptsetup-generator-use-systemd-makefs-for-implemen.patch
     https://git.launchpad.net/~ubuntu-core-dev/ubuntu/+source/systemd/commit/?id=c81b75c4297cbb04554488b070b6f79996b8cceb

   [ Balint Reczey ]
   * debian/udev.postinst: Allow kvm to be an already present non-system group
     (LP: #1880541)
     File: debian/udev.postinst
     https://git.launchpad.net/~ubuntu-core-dev/ubuntu/+source/systemd/commit/?id=8b5c31828d4323ddb719326b1316c179b7cdbdef
   * d/p/hwdb-Mask-rfkill-event-from-intel-hid-on-HP-platforms.patch:
     hwdb: Mask rfkill event from intel-hid on HP platforms
     (LP: #1883846)
     https://git.launchpad.net/~ubuntu-core-dev/ubuntu/+source/systemd/commit/?id=164c016b466210c7d6d05963fd753eccf4679844
   * journald: stream pid change newline fix (LP: #1875708)
     Files:
     - debian/patches/lp1875708/journald-Increase-stdout-buffer-size-sooner-when-almost-f.patch
     - debian/patches/lp1875708/journald-rework-end-of-line-marker-handling-to-use-a-fiel.patch
     - debian/patches/lp1875708/journald-rework-pid-change-handling.patch
     - debian/patches/lp1875708/journald-use-log_warning_errno-where-appropriate.patch
     - debian/patches/lp1875708/journald-use-the-fact-that-client_context_release-returns.patch
     - debian/patches/lp1875708/man-document-the-new-_LINE_BREAK-type.patch
     - debian/patches/lp1875708/socket-util-introduce-type-safe-dereferencing-wrapper-CMS.patch
     - debian/patches/lp1875708/test-Add-a-test-case-for-15654.patch
     https://git.launchpad.net/~ubuntu-core-dev/ubuntu/+source/systemd/commit/?id=2dc19f7ae4aad7277e9d89849182453ff1d046dc

 -- Dan Streetman <email address hidden> Mon, 06 Jul 2020 17:38:31 -0400

The verification of the Stable Release Update for systemd has completed successfully and the package is now being released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.