Debian Bug report logs - #998088
ifupdown: Please use Wants=ifupdown-pre.service instead of Requires in networking.service

Toggle useless messages

Message #5 received at submit@bugs.debian.org (full text, mbox, reply):

From: Ron <ron@debian.org>

To: Debian Bug Tracking System <submit@bugs.debian.org>

Subject: ifupdown: Please use Wants=ifupdown-pre.service instead of Requires in networking.service

Date: Sat, 30 Oct 2021 16:22:19 +1030

Package: ifupdown
Version: 0.8.36
Severity: important
Tags: patch

Hi!

Systemd has a class of boot-time races which can result in deadlock
while the ifupdown-pre.service is waiting for udevadm settle - in most
of the cases where that occurs ifupdown is an innocent victim of the
interactions between other things with poorly specified or insufficient
dependency and ordering relationships - but when those get trapped on
either side of ifupdown (reasonably enough) waiting for the initial
set of network devices to become available, people get locked out of
their remote machines after udevadm settle times out, ifupdown-pre
'fails', and then the networking.service is simply not started.


It seems there have been many instances, and many permutations, of
people effected by this class of systemd race-to-deadlock bugs, they
can be intermittent, very hard to get to the bottom of, and in almost
all of the reported cases I've found so far, people just gave up
trying to diagnose them and masked the ifupdown-pre.service as a
workaround.

But in almost all of those cases that's the wrong kludge as there was
nothing which had actually failed about waiting for the network devices
to be available, and nothing which would have subsequently prevented
networking.service from successfully starting ...

So I'd like to suggest a much better workaround, which should be the
default in ifupdown instead, is simply to change:

diff --git a/debian/networking.service b/debian/networking.service
index 593172b..b645409 100644
--- a/debian/networking.service
+++ b/debian/networking.service
@@ -2,7 +2,7 @@
 Description=Raise network interfaces
 Documentation=man:interfaces(5)
 DefaultDependencies=no
-Requires=ifupdown-pre.service
+Wants=ifupdown-pre.service
 Wants=network.target
 After=local-fs.target network-pre.target apparmor.service systemd-sysctl.service systemd-modules-load.service ifupdown-pre.service
 Before=network.target shutdown.target network-online.target


With this, networking.service will still wait for ifupdown-pre to
complete, either normally or by systemd's "bug fixing" timeout
when other services deadlock around it - and then in either case
the networking.service will independently either succeed (in the
probable case where networking devices were not part of the race
that deadlocked), or fail to bring up only the network devices
that were effected by that problem.  But it will be *much* less
likely for people to get locked out of remote access to fix the
real problem when the next dist-upgrade brings some change to the
set of unit files on their system which introduces this race in a
way their machine will lose (which was how I hit this on Buster
to Bullseye upgrades).


As a side note to all that, the TimeoutSec=180 in ifupdown-pre
is a bit misleading, as udevadm settle will itself time out in
120 seconds unless it is told to do otherwise.

  Cheers,
  Ron


As a postscript for anyone who might be interested, here is the
details of the particular race instance that first bit me and
got me digging into this:

 The BitBabbler package has udev rules and configuration for assigning
 hardware RNG devices directly to VM instances instead of to the host.

 It does this with a call to virsh, which in normal use (or prior to
 Bullseye) will 'immediately' either:

  - succeed
  - fail because the desired VM is not active
  - or fail because libvirtd has not yet started (or is not running)
    and its communication socket is not present.

 In no case was that operation ever expected to block for any extended
 duration, nor does it have any reason to.

 But in Bullseye, libvirt changed from managing its control socket
 itself to using a "socket activation" unit, which is created (aiui
 on the naive advice of systemd advocates) very early in the boot
 process - long before it would be able to start the service, as the
 service's own dependencies are not yet satisfied, and those are not
 applied transitively to the .socket unit which would be requesting
 the (as yet unstartable) service.

 So now we have a race where the kernel or a udev cold-plug trigger
 for an already attached BitBabbler triggers a call to virsh which
 is racing with the creation of the libvirtd.socket, if the socket
 unit has not yet created it, that fails (as expected) and everything
 runs normally, with the device being attached to the VM later when
 it is eventually started.

 But if the socket unit has already created a zombie socket, virsh
 will send its request to it and then wait for a response, which is
 never going to come because libvirtd being started is trapped on
 the other side of network.target being reached.

 And then ifupdown-pre innocently stumbles into this crime scene
 because calling udevadm settle at this point will in turn block
 until the call to virsh completes, and even though the network
 device events have probably been processed normally, probably
 before this whole chain of events even started, we now have a
 mexican standoff that has brought the whole show to a halt until
 systemd pulls its timeout trigger, and everyone loses in the
 resulting carnage.

The problem is fixable, but it requires fixes and mitigations in many
different places (at least while the systemd folk continue to insist
that "starting sockets as early as possible magically resolves all
dependencies" and don't make the dependencies of the service units
that sockets ultimately want to start be automatically transitive).
As long as there are zombie sockets things can block on, these sort
of circular races will always continue to exist.  No amount of
"deprecating" the use of udevadm settle, or other workarounds for
deadlocking will actually change that, they just sweep the problem
under a different rug that someone will eventually lift again.

ifupdown can make itself more resilient to this by using Wants to wait
for ifupdown-pre, but not failing to even try to start in this case as
it does when Requires is used.

I've tried to narrow the window for this race by testing earlier (in the
BitBabbler udev rule) for the presence of the libvirtd control socket
instead of waiting until virsh gets to the point where it does.  That
alone can't fix this problem, but it makes it harder and rarer to lose
on the slower machines where this was first seen.

And the next bug I'll file is for libvirt to defer the creation of its
.socket until the daemon's dependencies can be met so that the time
which this could block will become finite instead of an indefinite
deadlock - which will (aside from *very* slow machines still timing out,
which will always be a problem as long as systemd relies on timeouts to
resolve design and implementation bugs) actually fix this for this
particular permutation of participants ...


But until we've found and worked through all the possible permutations
of things that can create this situation, having ifupdown assume that
a timeout failure of ifupdown-pre is unlikely to mean networking.service
will also fail after that 2 minute delay, will give people the best
chance of still being able to access effected machines until it can be
traced and debugged in their particular case.

I have tested the patch above, prior to taking further actions to
prevent the race entirely, and after waiting for the timeout to fire
network does come up normally on all the machines I've had subjected
to this problem after a Bullseye upgrade.

Message #10 received at 998088@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: 998090@bugs.debian.org

Cc: 998088@bugs.debian.org

Subject: Re: libvirt-daemon-system: Please defer starting libvirtd.socket until libvirtd.service dependencies can be met

Date: Tue, 02 Nov 2021 15:34:01 +0100

[Message part 1 (text/plain, inline)]

On Sat, 30 Oct 2021 17:39:45 +1030 Ron <ron@debian.org> wrote:
> Package: libvirt-daemon-system
> Version: 7.0.0-3
> Severity: important
> 
> Hi,
> 
> Systemd has a class of boot-time races which can result in deadlock,
> which I learned more than I ever wanted to know about when Buster to
> Bullseye upgrades started leaving me with machines that were off the
> network when they were rebooted ...  The reason for that is a bit of a
> tangle of otherwise unrelated packages, and there are many ways this
> *could* happen, but the root of it in my particular case was the libvirt
> package switching to use socket activation instead of letting the daemon
> create its own socket when it is ready to respond to requests on it.
> 
> The race occurs because the .socket unit creates the libvirt control
> socket very early in the boot, before even the network-pre target is
> reached, and so long before the libvirtd.service dependencies are
> satisfied and the daemon itself can be started to handle requests.

There is nothing to fix on the libvirt / ifupdown side here.

The bug is in bit-babbler which triggers the start of a long running process
from a udev rules file (which it shouldn't do), which causes the dead lock
in the end.

I tried to explain this to Ron on IRC, but he decided to ignore my advice.

Please ignore this bug report.
If you have further questions, feel free to contact me.

Regards,
Michael

[signature.asc (application/pgp-signature, inline)]

Message #15 received at 998088@bugs.debian.org (full text, mbox, reply):

From: Ron <ron@debian.org>

To: 998088@bugs.debian.org, 998090@bugs.debian.org

Subject: Re: why bugs involving systemd are so hard to get fixed ...

Date: Wed, 3 Nov 2021 09:47:24 +1030

On Tue, 02 Nov 2021 15:34:01 +0100 Michael Biebl <biebl@debian.org> wrote:
> I tried to explain this to Ron on IRC, but he decided to ignore my advice.

Oh Please Michael, now you're just sounding like a child whose lolly has
fallen in the dirt ...

I did run the issue with (some) socket units and circular dependencies
past #systemd hoping for some sensible analysis of the problem, but all
I got was the same penchant to just sweep it under the nearest handy
rug.  What you seem to call "advice" was the same as here, just an
apparently willful effort to completely ignore everything I actually
wrote about the (several) problems here, and instead invent your own
problem that fit the answers in your standard divert blame kit ...

If you genuinely want to help here, actually read what I wrote, and
actually address the problems which should be very clear from the
analysis I wrote of it (or if they are not, I'll gladly clarify).

None of what I reported for libvirt or ifupdown are problems which
depend the bit-babbler udev rules to occur.  A quick search will find
you many people whose systems fell into the same holes these problems
create.  The problem space that each is separately subject to is created
in the domain of those packages.  There is no "one problem with one
quick answer" here (unless you count how easy it appears to still be
for people to accidentally create problems with systemd units, but I'm
not ranting about that, I'm trying to get concrete instances fixed).

I'm not going to give a long list of links here because I'm not
interested in rolling in the mud with you, I'm interested in making
packages I use a lot as robust and bug free as possible.  Except I
will highlight https://bugs.debian.org/899002 ...  In which you
showed the same complete lack of understanding of the problem - and
amusingly even argued *against* the very change to ifupdown, which
I've pointed out the one small rough edge that needs polishing, that
you now have flipped your position to say "Is perfect, don't touch it".

So can we please stop this side-show and actually look at the bugs
which I *did* report, not the invented one which I didn't ...

  Thanks,
  Ron

Message #20 received at 998088@bugs.debian.org (full text, mbox, reply):

From: Frédéric MASSOT <frederic@juliana-multimedia.com>

To: 998088@bugs.debian.org

Subject: Same issue when moving from kernel 5.17 to 5.18

Date: Wed, 29 Jun 2022 15:03:31 +0200

Hi,

I have a local server that uses Debian testing. I updated the server, it 
went from a kernel 5.17 to 5.18. After the reboot, the network was no 
longer active. The network interfaces were down.

In the logs I had these error messages:

systemd-udevd[396]: 0000:01:00.0: Worker [425] processing SEQNUM=2140 is 
taking a long time
systemd[1]: systemd-udev-settle.service: Main process exited, 
code=exited, status=1/FAILURE
systemd[1]: systemd-udev-settle.service: Failed with result 'exit-code'.
systemd[1]: Failed to start Wait for udev To Complete Device Initialization.
systemd[1]: systemd-udev-settle.service: Consumed 4.055s CPU time.
[...]
systemd[1]: ifupdown-pre.service: Main process exited, code=exited, 
status=1/FAILURE
systemd[1]: ifupdown-pre.service: Failed with result 'exit-code'.
systemd[1]: Failed to start Helper to synchronize boot up for ifupdown.
systemd[1]: Dependency failed for Raise network interfaces.
systemd[1]: networking.service: Job networking.service/start failed with 
result 'dependency'.
ithaqua systemd[1]: ifupdown-pre.service: Consumed 3.807s CPU time.


I found this bug report and replaced the line 
"Requires=ifupdown-pre.service" with "Wants=ifupdown-pre.service" in 
"/lib/systemd/system/networking.service".

During boot there is a delay, but the network interfaces were up and the 
network is active.


Regards.
-- 
==============================================
|              FRÉDÉRIC MASSOT               |
|     http://www.juliana-multimedia.com      |
|   mailto:frederic@juliana-multimedia.com   |
| +33.(0)2.97.54.77.94  +33.(0)6.67.19.95.69 |
===========================Debian=GNU/Linux===

Message #25 received at 998088@bugs.debian.org (full text, mbox, reply):

From: Bogdan Veringioiu <bogdan.veringioiu@amano.eu>

To: 998088@bugs.debian.org

Subject: hitting this issue on a dell t150 server on bullseye

Date: Wed, 17 Aug 2022 14:41:24 +0200

Hi,

I have encountered the same issue described in this bug.

Aug 16 06:13:14 v802limat1 systemd-udevd[296]: sdb1: Spawned process 
'checkScript.sh' [350] is taking longer than 59s to complete
Aug 16 06:13:14 v802limat1 systemd-udevd[279]: sdb1: Worker [296] 
processing SEQNUM=2164 is taking a long time
Aug 16 06:14:12 v802limat1 systemd[1]: ifupdown-pre.service: Main 
process exited, code=exited, status=1/FAILURE
Aug 16 06:14:12 v802limat1 systemd[1]: ifupdown-pre.service: Failed with 
result 'exit-code'.
Aug 16 06:14:12 v802limat1 systemd[1]: Failed to start Helper to 
synchronize boot up for ifupdown.
Aug 16 06:14:12 v802limat1 systemd[1]: Dependency failed for Raise 
network interfaces.
Aug 16 06:14:12 v802limat1 systemd[1]: networking.service: Job 
networking.service/start failed with result 'dependency'.
Aug 16 06:14:12 v802limat1 systemd[1]: ifupdown-pre.service: Consumed 
4.534s CPU time.

It seems to happen when udev is waiting on a custom script (triggered by 
custom udev rule when USB stick insert is detected).

This did not happen under buster.

-- 
Bogdan Veringioiu

Amano Parking Europe N.V.
Uersfeld 24
52072 Aachen, Germany

e-mail:   bogdan.veringioiu@amano.eu
web:      www.amano.eu

Message #30 received at 998088@bugs.debian.org (full text, mbox, reply):

From: Paul Leiber <paul@onlineschubla.de>

To: 998088@bugs.debian.org

Subject: Re: Same issue when moving from kernel 5.17 to 5.18

Date: Sat, 22 Oct 2022 15:56:15 +0200

On Wed, 29 Jun 2022 15:03:31 +0200 =?UTF-8?B?RnLDqWTDqXJpYyBNQVNTT1Q=?= 
<frederic@juliana-multimedia.com> wrote:
> Hi,
>
> I have a local server that uses Debian testing. I updated the server, it
> went from a kernel 5.17 to 5.18. After the reboot, the network was no
> longer active. The network interfaces were down.
>
> In the logs I had these error messages:
>
> systemd-udevd[396]: 0000:01:00.0: Worker [425] processing SEQNUM=2140 is
> taking a long time
> systemd[1]: systemd-udev-settle.service: Main process exited,
> code=exited, status=1/FAILURE
> systemd[1]: systemd-udev-settle.service: Failed with result 'exit-code'.
> systemd[1]: Failed to start Wait for udev To Complete Device 
Initialization.
> systemd[1]: systemd-udev-settle.service: Consumed 4.055s CPU time.
> [...]
> systemd[1]: ifupdown-pre.service: Main process exited, code=exited,
> status=1/FAILURE
> systemd[1]: ifupdown-pre.service: Failed with result 'exit-code'.
> systemd[1]: Failed to start Helper to synchronize boot up for ifupdown.
> systemd[1]: Dependency failed for Raise network interfaces.
> systemd[1]: networking.service: Job networking.service/start failed with
> result 'dependency'.
> ithaqua systemd[1]: ifupdown-pre.service: Consumed 3.807s CPU time.
>
>
> I found this bug report and replaced the line
> "Requires=ifupdown-pre.service" with "Wants=ifupdown-pre.service" in
> "/lib/systemd/system/networking.service".
>
> During boot there is a delay, but the network interfaces were up and the
> network is active.
>
>
> Regards.
> --
> ==============================================
> | FRÉDÉRIC MASSOT |
> | http://www.juliana-multimedia.com |
> | mailto:frederic@juliana-multimedia.com |
> | +33.(0)2.97.54.77.94 +33.(0)6.67.19.95.69 |
> ===========================Debian=GNU/Linux===
>
>

I have the same issue as described by Frédéric in an up-to-date Debian 
Bullseye 11.5, kernel 5.10.0-19-amd64. Manually starting the network via 
ifconfig works. The workaround described by Ron mitigates the error. 
However, the delay during boot exists also in my system.

Paul

Message #35 received at 998088@bugs.debian.org (full text, mbox, reply):

From: Santiago Ruano Rincón <santiagorr@riseup.net>

To: Paul Leiber <paul@onlineschubla.de>, 998088@bugs.debian.org, 998088-submitter@bugs.debian.org, Michael Biebl <biebl@debian.org>

Cc: josue@debian.org

Subject: Re: Bug#998088: Same issue when moving from kernel 5.17 to 5.18

Date: Fri, 4 Nov 2022 15:04:25 +0100

[Message part 1 (text/plain, inline)]

El 22/10/22 a las 15:56, Paul Leiber escribió:
> On Wed, 29 Jun 2022 15:03:31 +0200 =?UTF-8?B?RnLDqWTDqXJpYyBNQVNTT1Q=?=
> <frederic@juliana-multimedia.com> wrote:
> > Hi,
> >
> > I have a local server that uses Debian testing. I updated the server, it
> > went from a kernel 5.17 to 5.18. After the reboot, the network was no
> > longer active. The network interfaces were down.
> >
> > In the logs I had these error messages:
> >
> > systemd-udevd[396]: 0000:01:00.0: Worker [425] processing SEQNUM=2140 is
> > taking a long time
> > systemd[1]: systemd-udev-settle.service: Main process exited,
> > code=exited, status=1/FAILURE
> > systemd[1]: systemd-udev-settle.service: Failed with result 'exit-code'.
> > systemd[1]: Failed to start Wait for udev To Complete Device
> Initialization.
> > systemd[1]: systemd-udev-settle.service: Consumed 4.055s CPU time.
> > [...]
> > systemd[1]: ifupdown-pre.service: Main process exited, code=exited,
> > status=1/FAILURE
> > systemd[1]: ifupdown-pre.service: Failed with result 'exit-code'.
> > systemd[1]: Failed to start Helper to synchronize boot up for ifupdown.
> > systemd[1]: Dependency failed for Raise network interfaces.
> > systemd[1]: networking.service: Job networking.service/start failed with
> > result 'dependency'.
> > ithaqua systemd[1]: ifupdown-pre.service: Consumed 3.807s CPU time.
> >
> >
> > I found this bug report and replaced the line
> > "Requires=ifupdown-pre.service" with "Wants=ifupdown-pre.service" in
> > "/lib/systemd/system/networking.service".
> >
> > During boot there is a delay, but the network interfaces were up and the
> > network is active.
> >
> >
> > Regards.
> > --
> > ==============================================
> > | FRÉDÉRIC MASSOT |
> > | http://www.juliana-multimedia.com |
> > | mailto:frederic@juliana-multimedia.com |
> > | +33.(0)2.97.54.77.94 +33.(0)6.67.19.95.69 |
> > ===========================Debian=GNU/Linux===
> >
> >
> 
> I have the same issue as described by Frédéric in an up-to-date Debian
> Bullseye 11.5, kernel 5.10.0-19-amd64. Manually starting the network via
> ifconfig works. The workaround described by Ron mitigates the error.
> However, the delay during boot exists also in my system.
> 
> Paul
> 

Sorry for the delay to answer on this.

For the moment, it seems replacing the dependency for Wants seems to be
the more suitable solution. Also, from systemd.unit(5):

    Wants= … This is the recommended way to hook the start-up of one
    unit to the start-up of another unit.

    Requires= … Often, it is a better choice to use Wants= instead of
    Requires= in order to achieve a system that is more robust when
    dealing with failing services.

Happy to learn if there would be a better fix.

Cheers,

 -- Santiago

[signature.asc (application/pgp-signature, inline)]

Message #43 received at 998088-close@bugs.debian.org (full text, mbox, reply):

From: Debian FTP Masters <ftpmaster@ftp-master.debian.org>

To: 998088-close@bugs.debian.org

Subject: Bug#998088: fixed in ifupdown 0.8.40

Date: Mon, 16 Jan 2023 15:05:05 +0000

Source: ifupdown
Source-Version: 0.8.40
Done: Santiago Ruano Rincón <santiago@debian.org>

We believe that the bug you reported is fixed in the latest version of
ifupdown, which is due to be installed in the Debian FTP archive.

A summary of the changes between this version and the previous one is
attached.

Thank you for reporting the bug, which will now be closed.  If you
have further comments please address them to 998088@bugs.debian.org,
and the maintainer will reopen the bug report if appropriate.

Debian distribution maintenance software
pp.
Santiago Ruano Rincón <santiago@debian.org> (supplier of updated ifupdown package)

(This message was generated automatically at their request; if you
believe that there is a problem with it please contact the archive
administrators by mailing ftpmaster@ftp-master.debian.org)


-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

Format: 1.8
Date: Mon, 16 Jan 2023 14:57:59 +0100
Source: ifupdown
Architecture: source
Version: 0.8.40
Distribution: unstable
Urgency: medium
Maintainer: Josué Ortega <josue@debian.org>
Changed-By: Santiago Ruano Rincón <santiago@debian.org>
Closes: 998088 1000180 1022843
Changes:
 ifupdown (0.8.40) unstable; urgency=medium
 .
   [ Colin Watson ]
   * Clarify formatting of post-up and pre-down aliases in interfaces(5).
 .
   [ Vincent Bernat ]
   * Kill dhclient on down for inet6 auto method. (Closes: #1000180)
 .
   [ Santiago Ruano Rincón ]
   * networking.service: Wants ifupdown-pre.service instead of Requiring it.
     Patch by Ron <ron@debian.org>
     (Closes: #998088)
   * networking.service: Add ExecStart=/sbin/ifup -a --allow=hotplug. Patch by
     "Oleg A. Arkhangelsky" <sysoleg@yandex.ru>
     (Closes: #1022843)
   * Update d/copyright and fix Source URL
 .
   [ Marek Vasut ]
   * Add short -f option for --force long option
 .
   [ Simon Arlott ]
   * Support IPv6 tunnels (ip6ip6 and ip6gre)
   * Support encaplimit on IPv6 tunnels
   * Document and test support for ipip6 tunnels too (IPv4 in IPv6)
 .
   [ Guillem Jover ]
   * Rework execable() function to accept a filename instead of a pathname
   * Do not use absolute pathnames when executing commands
Checksums-Sha1:
 5a3eabb2c09df73c91e4897c7ea4aaa1cee77c27 986 ifupdown_0.8.40.dsc
 18278238383d710f0a6cf142c66b751418aff5d5 81808 ifupdown_0.8.40.tar.xz
 73d459bc51777bb8b4b55a1ae7da474ea42b6621 5404 ifupdown_0.8.40_amd64.buildinfo
Checksums-Sha256:
 100d47fdb21e3a34950b067134e31f99ad649f2ade537cc65777e909a0954c79 986 ifupdown_0.8.40.dsc
 0e9b0fedb6828db8352e0f0ca8f164aec55f98a2ea3db6c4c514381a2fb1edfe 81808 ifupdown_0.8.40.tar.xz
 723cf7ec365e3a447298d2c4c627afbdae91d82b29deefd6d3c2f897ef359b99 5404 ifupdown_0.8.40_amd64.buildinfo
Files:
 ca9b9247545e98068ff2726d520ad858 986 admin important ifupdown_0.8.40.dsc
 6bd2c47a721a984d82cce50486ed6dfa 81808 admin important ifupdown_0.8.40.tar.xz
 02dde7d1b0c6cb8a360dbfe0551993ee 5404 admin important ifupdown_0.8.40_amd64.buildinfo

-----BEGIN PGP SIGNATURE-----

iHUEARYIAB0WIQRZVjztY8b+Ty43oH1itBCJKh26HQUCY8ViGQAKCRBitBCJKh26
HZwhAQDsYZPuya81nDRRJOcNVQEUqXTSETEHbn7RTkAfFiy3DAEAgdJHErz5wHRK
WZVpeus7lXpxmAD/ZVepr3ANsFAjmAY=
=JW3C
-----END PGP SIGNATURE-----

Send a report that this bug log contains spam.