[Bug 1875708] Re: Truncated messages during shutdown

Christian Ehrhardt  1875708 at bugs.launchpad.net
Tue May 5 05:08:44 UTC 2020 

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

** Also affects: systemd (Ubuntu)
   Importance: Undecided
       Status: New

** Changed in: libvirt (Ubuntu)
       Status: Triaged => Invalid

** Summary changed:

- Truncated messages during shutdown
+ Truncated messages in journald since systemd v244

** Description changed:

+ [Impact]
+ 
+  * since 09d0b46a "journal: refresh cached credentials of stdout streams"
+    in ~244 output may be trincated.
+ 
+  * Upstream has a fix in https://github.com/systemd/systemd/pull/15685
+ 
+  * Backporting the fix will avoid truncation of log output to journald
+ 
+ [Test Case]
+ 
+  * This could happen in any case, but is more likely when a program that 
+    has output going to journald is spawning short-lived sub-programs often.
+    Therefore the test emphasizes on that:
+ 
+    - Use a test service like /etc/systemd/system/test.service:
+ [Unit]
+ Description=Test Truncate
+ After=network.target
+ 
+ [Service]
+ ExecStart=/usr/lib/test.sh long-test-for-start
+ ExecStop=/usr/lib/test.sh long-test-for-stop
+ Type=oneshot
+ RemainAfterExit=yes
+ StandardOutput=journal+console
+ TimeoutStopSec=0
+ 
+ [Install]
+ WantedBy=multi-user.target
+ 
+    - And a test script like /usr/lib/test.sh:
+ #!/bin/sh
+ gettext "This will"
+ echo
+ gettext "usually fail"
+ echo
+ gettext "and be truncated"
+ echo 
+ 
+ Start/Stopping that service without the fix will look like:
+ Apr 30 18:56:40 f systemd[1]: Stopping Test Truncate...
+ Apr 30 18:56:40 f test.sh[1165]: T
+ Apr 30 18:56:40 f test.sh[1167]: T
+ Apr 30 18:56:40 f test.sh[1167]: sually fai
+ Apr 30 18:56:40 f test.sh[1165]: s
+ Apr 30 18:56:40 f test.sh[1168]: s
+ Apr 30 18:56:40 f test.sh[1168]: nd be truncate
+ Apr 30 18:56:40 f test.sh[1165]: n
+ Apr 30 18:56:40 f systemd[1]: test.service: Succeeded.
+ Apr 30 18:56:40 f systemd[1]: Stopped Test Truncate.
+ 
+ 
+ [Regression Potential] 
+ 
+  * The patches are rather small, but there might be a slightly increased 
+    memory consumption of journald for output buffers. 
+  * Issues (if any and I couldn't find any so far) should be only to 
+    journald output handling. Systemd is huge, this at least narrows
+    down the potential places of a regression a lot.
+ 
+ [Other Info]
+  
+  * n/a
+ 
+ --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
+ 
+ Originally reported against libvirt which happens to be one of the
+ example-triggers
+ 
  Hi,
  
  when I shut down my machine I see messages from /usr/lib/libvirt
  /libvirt-guests.sh but there are 2 anomalies:
  
-  - 3 libvirt-guests.sh processes are run
-  - messages are truncated
+  - 3 libvirt-guests.sh processes are run
+  - messages are truncated
  
  ProblemType: Bug
  DistroRelease: Ubuntu 20.04
  Package: libvirt-daemon 6.0.0-0ubuntu8
  Uname: Linux 5.6.7-050607-generic x86_64
  ApportVersion: 2.20.11-0ubuntu27
  Architecture: amd64
  CasperMD5CheckResult: skip
  CurrentDesktop: KDE
  Date: Tue Apr 28 19:42:56 2020
  SourcePackage: libvirt
  UpgradeStatus: No upgrade log present (probably fresh install)
  modified.conffile..etc.libvirt.nwfilter.allow-arp.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/allow-arp.xml']
  modified.conffile..etc.libvirt.nwfilter.allow-dhcp-server.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/allow-dhcp-server.xml']
  modified.conffile..etc.libvirt.nwfilter.allow-dhcp.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/allow-dhcp.xml']
  modified.conffile..etc.libvirt.nwfilter.allow-incoming-ipv4.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/allow-incoming-ipv4.xml']
  modified.conffile..etc.libvirt.nwfilter.allow-ipv4.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/allow-ipv4.xml']
  modified.conffile..etc.libvirt.nwfilter.clean-traffic-gateway.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/clean-traffic-gateway.xml']
  modified.conffile..etc.libvirt.nwfilter.clean-traffic.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/clean-traffic.xml']
  modified.conffile..etc.libvirt.nwfilter.no-arp-ip-spoofing.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-arp-ip-spoofing.xml']
  modified.conffile..etc.libvirt.nwfilter.no-arp-mac-spoofing.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-arp-mac-spoofing.xml']
  modified.conffile..etc.libvirt.nwfilter.no-arp-spoofing.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-arp-spoofing.xml']
  modified.conffile..etc.libvirt.nwfilter.no-ip-multicast.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-ip-multicast.xml']
  modified.conffile..etc.libvirt.nwfilter.no-ip-spoofing.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-ip-spoofing.xml']
  modified.conffile..etc.libvirt.nwfilter.no-mac-broadcast.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-mac-broadcast.xml']
  modified.conffile..etc.libvirt.nwfilter.no-mac-spoofing.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-mac-spoofing.xml']
  modified.conffile..etc.libvirt.nwfilter.no-other-l2-traffic.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-other-l2-traffic.xml']
  modified.conffile..etc.libvirt.nwfilter.no-other-rarp-traffic.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-other-rarp-traffic.xml']
  modified.conffile..etc.libvirt.nwfilter.qemu-announce-self-rarp.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/qemu-announce-self-rarp.xml']
  modified.conffile..etc.libvirt.nwfilter.qemu-announce-self.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/qemu-announce-self.xml']
  modified.conffile..etc.libvirt.qemu.conf: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/qemu.conf']
  modified.conffile..etc.libvirt.qemu.networks.default.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/qemu/networks/default.xml']

** Changed in: libvirt (Ubuntu)
     Assignee: Christian Ehrhardt  (paelzer) => (unassigned)

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to systemd in Ubuntu.
https://bugs.launchpad.net/bugs/1875708

Title:
  Truncated messages in journald since systemd v244

Status in libvirt package in Ubuntu:
  Invalid
Status in systemd package in Ubuntu:
  New

Bug description:
  [Impact]

   * since 09d0b46a "journal: refresh cached credentials of stdout streams"
     in ~244 output may be trincated.

   * Upstream has a fix in https://github.com/systemd/systemd/pull/15685

   * Backporting the fix will avoid truncation of log output to journald

  [Test Case]

   * This could happen in any case, but is more likely when a program that 
     has output going to journald is spawning short-lived sub-programs often.
     Therefore the test emphasizes on that:

     - Use a test service like /etc/systemd/system/test.service:
  [Unit]
  Description=Test Truncate
  After=network.target

  [Service]
  ExecStart=/usr/lib/test.sh long-test-for-start
  ExecStop=/usr/lib/test.sh long-test-for-stop
  Type=oneshot
  RemainAfterExit=yes
  StandardOutput=journal+console
  TimeoutStopSec=0

  [Install]
  WantedBy=multi-user.target

     - And a test script like /usr/lib/test.sh:
  #!/bin/sh
  gettext "This will"
  echo
  gettext "usually fail"
  echo
  gettext "and be truncated"
  echo 

  Start/Stopping that service without the fix will look like:
  Apr 30 18:56:40 f systemd[1]: Stopping Test Truncate...
  Apr 30 18:56:40 f test.sh[1165]: T
  Apr 30 18:56:40 f test.sh[1167]: T
  Apr 30 18:56:40 f test.sh[1167]: sually fai
  Apr 30 18:56:40 f test.sh[1165]: s
  Apr 30 18:56:40 f test.sh[1168]: s
  Apr 30 18:56:40 f test.sh[1168]: nd be truncate
  Apr 30 18:56:40 f test.sh[1165]: n
  Apr 30 18:56:40 f systemd[1]: test.service: Succeeded.
  Apr 30 18:56:40 f systemd[1]: Stopped Test Truncate.

  
  [Regression Potential] 

   * The patches are rather small, but there might be a slightly increased 
     memory consumption of journald for output buffers. 
   * Issues (if any and I couldn't find any so far) should be only to 
     journald output handling. Systemd is huge, this at least narrows
     down the potential places of a regression a lot.

  [Other Info]
   
   * n/a

  --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---

  Originally reported against libvirt which happens to be one of the
  example-triggers

  Hi,

  when I shut down my machine I see messages from /usr/lib/libvirt
  /libvirt-guests.sh but there are 2 anomalies:

   - 3 libvirt-guests.sh processes are run
   - messages are truncated

  ProblemType: Bug
  DistroRelease: Ubuntu 20.04
  Package: libvirt-daemon 6.0.0-0ubuntu8
  Uname: Linux 5.6.7-050607-generic x86_64
  ApportVersion: 2.20.11-0ubuntu27
  Architecture: amd64
  CasperMD5CheckResult: skip
  CurrentDesktop: KDE
  Date: Tue Apr 28 19:42:56 2020
  SourcePackage: libvirt
  UpgradeStatus: No upgrade log present (probably fresh install)
  modified.conffile..etc.libvirt.nwfilter.allow-arp.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/allow-arp.xml']
  modified.conffile..etc.libvirt.nwfilter.allow-dhcp-server.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/allow-dhcp-server.xml']
  modified.conffile..etc.libvirt.nwfilter.allow-dhcp.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/allow-dhcp.xml']
  modified.conffile..etc.libvirt.nwfilter.allow-incoming-ipv4.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/allow-incoming-ipv4.xml']
  modified.conffile..etc.libvirt.nwfilter.allow-ipv4.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/allow-ipv4.xml']
  modified.conffile..etc.libvirt.nwfilter.clean-traffic-gateway.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/clean-traffic-gateway.xml']
  modified.conffile..etc.libvirt.nwfilter.clean-traffic.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/clean-traffic.xml']
  modified.conffile..etc.libvirt.nwfilter.no-arp-ip-spoofing.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-arp-ip-spoofing.xml']
  modified.conffile..etc.libvirt.nwfilter.no-arp-mac-spoofing.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-arp-mac-spoofing.xml']
  modified.conffile..etc.libvirt.nwfilter.no-arp-spoofing.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-arp-spoofing.xml']
  modified.conffile..etc.libvirt.nwfilter.no-ip-multicast.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-ip-multicast.xml']
  modified.conffile..etc.libvirt.nwfilter.no-ip-spoofing.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-ip-spoofing.xml']
  modified.conffile..etc.libvirt.nwfilter.no-mac-broadcast.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-mac-broadcast.xml']
  modified.conffile..etc.libvirt.nwfilter.no-mac-spoofing.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-mac-spoofing.xml']
  modified.conffile..etc.libvirt.nwfilter.no-other-l2-traffic.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-other-l2-traffic.xml']
  modified.conffile..etc.libvirt.nwfilter.no-other-rarp-traffic.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/no-other-rarp-traffic.xml']
  modified.conffile..etc.libvirt.nwfilter.qemu-announce-self-rarp.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/qemu-announce-self-rarp.xml']
  modified.conffile..etc.libvirt.nwfilter.qemu-announce-self.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/nwfilter/qemu-announce-self.xml']
  modified.conffile..etc.libvirt.qemu.conf: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/qemu.conf']
  modified.conffile..etc.libvirt.qemu.networks.default.xml: [inaccessible: [Errno 13] Permission denied: '/etc/libvirt/qemu/networks/default.xml']

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/libvirt/+bug/1875708/+subscriptions

More information about the foundations-bugs mailing list