I killed the autopkgtests as they cause trouble: Shutdown hangs with

[[0;32m  OK  [0m] Stopped target Encrypted Volumes.
[[0;32m  OK  [0m] Stopped Forward Password Requests to Wall Directory Watch.
[[0;32m  OK  [0m] Stopped Dispatch Password Requests to Console Directory Watch.
[[0;32m  OK  [0m] Stopped target Swap.
[[0;32m  OK  [0m] Stopped Load/Save Random Seed.
[[0;32m  OK  [0m] Stopped Update UTMP about System Boot/Shutdown.
[[0;32m  OK  [0m] Stopped Network Time Synchronization.
[[0;32m  OK  [0m] Stopped Create Volatile Files and Directories.
[[0;32m  OK  [0m] Stopped target Local File Systems.
         Unmounting /run/lock...
         Unmounting /run/user/1000...
[[0;32m  OK  [0m] Unmounted /run/lock.
[[0;32m  OK  [0m] Unmounted /run/user/1000.
[[0;32m  OK  [0m] Reached target Unmount All Filesystems.
[[0;32m  OK  [0m] Stopped target Local File Systems (Pre).
         Stopping Monitoring of LVM2 mirrors?ng dmeventd or progress polling...
[[0;32m  OK  [0m] Stopped Remount Root and Kernel File Systems.
[[0;32m  OK  [0m] Stopped Create Static Device Nodes in /dev.
[[0;1;33mDEPEND[0m] Dependency failed for Shutdown.

and the testbed never actually reboots, thus it times out waiting for ssh. Looks like the "default" test on Fedora suffers from the same, although the output is a bit hard to read.

@martinpitt hmm, that failure is really interesting... Any chance we can get debug logging turned on for such tests? That would be very helpful for tracking down the issue here...

It's not so obvious why BindsTo= requires After=

It doesn't really actually.

BindsTo= just means: whatever happens, don't permit A running if it has BindsTo=B and B isn't running. The man page doesn't say that overly clearly, but it's kinda what already was in place, except in a racy fashion: we'd not detect this at all the right times, but only if a service dies, but not when it is in the process of being started. That was a mistake, and is highly racy: we'd check for bindsto on service exit, but not on service start, so if you combined multiple bindsto on a single service and then have some of them exit and some of them start, then we'd notice that the start wasn't complete yet, just becaus eof the eixt, if you follow at all what I am saying here...

Now, BindsTo= doesn't "require" After=, but it makes a lot of sense to use them together. If you don't then no ordering is applied, and that means if you have A BindsTo= B, and start both, then A might be started before B is ready which would then fail... If you add in the order however it's clear that A shouldn't be started anyway before B is up, hence all is good.

i'll extend the docs a bit, to make clear what "bindsto" really means: i.e. that a Unit is actually really "Bound" to another one, and will never be up without it...

@poettering , well, I see the point. But

a) warn if BindsTo= is used without ordering
b) add in After= if BindsTo= is used without ordering
c) if a unit is upped that bindsto another unit, fail it immediately is the requirements aren't met, with a proper error message in the logs.

Why not b) ?
Why should we break all services with BindsTo= and without After=?

Why not c) ?
Why should we break all services with BindsTo= and without After=?

Well, they are already broken, it's just harder to trigger. There's code in place that shuts down a unit if any of its BindsTo= deps are not up. This code got called under a number of conditions before, but not in all of them, we the device GC case we call it at one more occasion, so it suddenly detects some corner case quicker. Now, the code could also get invoked due to other reasons, hence there was always a race: things were safe only as long as this piece of code never got invoked, but that's a special case really...

Essentially, the GC patch really just made the race more visible, it was always there, and it always was due to user misconfig...

Essentially, the GC patch really just made the race more visible, it was always there, and it always was due to user misconfig...

Right. But [email protected] worked (most of the time) :-)

Anyway, I think you're right.

i'll extend the docs a bit, to make clear what "bindsto" really means

Did you mean the man page? Or the NEWS too?

Did you mean the man page? Or the NEWS too?

I meant the man page, but I figure we can mention this in the NEWS file, too

@poettering

whatever happens, don't permit A running if it has BindsTo=B and B isn't running

Do you mean that if A Requires B it is permissible to start A even if B is not up or cannot be brought up? I am afraid I am rather lost now in actual semantic of both Requires and BindsTo.

@evverx

add in After= if BindsTo= is used without ordering

I think that absolutely makes sense. If both is expected behavior - BindsTo triggers start of depending unit (being variant of Requires) and unit cannot even be started without dependent unit being started, then lone BindsTo with After is simply useless.

@arvidjaar ,

I think that absolutely makes sense

I just quote

I am afraid I am rather lost now in actual semantic of both Requires and BindsTo

:-)

@poettering

hmm, that failure is really interesting..

I added some logging

index 854da96..a3100fe 100644
--- a/src/core/unit.c
+++ b/src/core/unit.c
@@ -1540,13 +1540,17 @@ static bool unit_verify_deps(Unit *u) {
          * the job processing, but do not have any effect afterwards. */

         SET_FOREACH(other, u->dependencies[UNIT_BINDS_TO], j)
-                if (!UNIT_IS_ACTIVE_OR_RELOADING(unit_active_state(other)))
+                if (!UNIT_IS_ACTIVE_OR_RELOADING(unit_active_state(other))) {
+                        log_unit_warning(u, "BindsTo=%s is not in active state", other->id);
                         return false;
+                }

         for (i = 0; i < ELEMENTSOF(negative); i++)
                 SET_FOREACH(other, u->dependencies[negative[i]], j)
-                        if (!UNIT_IS_INACTIVE_OR_FAILED(unit_active_state(other)))
+                        if (!UNIT_IS_INACTIVE_OR_FAILED(unit_active_state(other))) {
+                                log_unit_warning(u, "Conflicts or ConflictedBy %s is not in active state", other->id);
                                 return false;
+                        }

         return true;
 }

Logs (updated):

$ sudo journalctl -D /var/tmp/systemd-test.FjzuB8/journal/222ff1a8f8004b15a3a87e2e653e887e/ | grep -E '(swap|shutdown).target'
Nov 25 06:30:08 systemd-testsuite systemd[1]: swap.target: Installed new job swap.target/stop as 208
Nov 25 06:30:08 systemd-testsuite systemd[1]: shutdown.target: Installed new job shutdown.target/start as 142
Nov 25 06:30:09 systemd-testsuite systemd[1]: swap.target: Merged into installed job swap.target/stop as 208
Nov 25 06:30:09 systemd-testsuite systemd[1]: shutdown.target: Merged into installed job shutdown.target/start as 142
Nov 25 06:32:10 systemd-testsuite systemd[1]: shutdown.target: Installed new job shutdown.target/start as 142
Nov 25 06:32:10 systemd-testsuite systemd[1]: swap.target: Installed new job swap.target/stop as 154
Nov 25 06:32:14 systemd-testsuite systemd[1]: shutdown.target: Conflicts or ConflictedBy swap.target is not in active state
Nov 25 06:32:14 systemd-testsuite systemd[1]: shutdown.target: Job shutdown.target/start finished, result=dependency
Nov 25 06:32:14 systemd-testsuite systemd[1]: shutdown.target: Job shutdown.target/start failed with result 'dependency'.
Nov 25 06:32:15 systemd-testsuite systemd[1]: swap.target changed active -> dead
Nov 25 06:32:15 systemd-testsuite systemd[1]: swap.target: Job swap.target/stop finished, result=done

@poettering

whatever happens, don't permit A running if it has BindsTo=B and B isn't running

Do you mean that if A Requires B it is permissible to start A even if B is not up or cannot be brought up? I am afraid I am rather lost now in actual semantic of both Requires and BindsTo.

A unit A with Requires=B doesn't actually care if B is up or not. All that matters is that the start job for it succeeded. But that can succeed even without B actually being up if some ConditionXYZ= failed for the service. After all conditoins are considered "non-fatal". They permit a unit's job to succeed cleanly even if the condition doesn't hold, but of course the unit won't be up afterwards.

@evverx hmm, interesting! apparently we are not having an After= dep between swap.target and shutdown.target, but really should. The patch just made this visible. Will fix.

I force pushed a new version now, that adds more docs, adds the suggested log message, and fixes the umount issues. Please have a look!

Execution failed! See logfile for details: Timeout waiting for ping

CentOS failed to reboot

BTW: systemd-centos-ci: Manually running the tests

OK, I force pushed a new version, that hopefully fixes the issue at hand. Let's see if the CI agrees.

I read (most of) your mail on the mailing list... but it was really long. Too long ;). Sorry.

Still, thanks for taking a look.

for example the binding unit would be pulled in by the same event which creates the bound-to unit, there'd be race between them both being started, and sometimes the start would succeed, and sometimes not.

To understand the mechanism of your race, I have to understand the mechanism of your BindsTo= dependency, and I do not. I have been considering different possible mechanisms, in the form of specific examples. This is my third attempt, writing and re-writing this post.

It is confusing for me, and paramount to keep in mind, what thing is the subject and object of "After". After what? "After" could refer to 1) queuing a unit for start, or to 2) "successfully" executing the service section of a unit. In practice, it seems that "After" is referring to the "successful" execution of the service section, rather than merely the enqueuing of a unit for start.

If there is no After= dependency between the two units, then both units would have the exact same one start dependency - the event. Both units would be enqueued for start simultaneously. There is no race there.

I might then imagine that your race must operate as a result of some event which occurs after these two units are enqueued for start, and be related to your definition of the BindsTo= dependency.

If BindsTo= is seen as an "edge triggered" reverse stop mechanism, then there is no context for a start race. So then, I will infer that your BindsTo= provides also a forward start mechanism, where, supposing "Unit B Binds To Unit A", then this means that Unit B will be enqueued for start when Unit A has successfully executed its service section.

But that would be of no matter in your example, which assumes that both units have a start dependency on the "same event". The Unit B start dependency will have already been satisfied by that event, and the "activation" of Unit A will cause no change to the activation state of Unit B.

I am still at a loss, trying to hypothesize the mechanism for a start race. Could you please provide a more detailed and precise description of your race?

I am still at a loss, trying to hypothesize the mechanism for a start race. Could you please provide a more detailed and precise description of your race?

The archetypical example is when a device detected by udev has a SYSTEMD_WANTS tag, and the service unit it pulls in has BindTo= on the device. The .device unit is not created immediately, and (at least I think so), the .service unit can be created before the .device unit appears in systemd.

Thanks Zbyszek. That sounds like my use case - plug in a network device, recognized by udev, and have systemd generate a master device, using a .service file, where the network device is then dependent upon that master device. I have run this on half a dozen machines - from laptops to desktops, 32 bit and 64 bit - but I have never seen anything that looks like a "race", in the sense that the results are different, from event to event, or from machine to machine. Of course, it may be that the "race" always comes-out the same, but that would be an unnecessary and over-complicating assumption.

Why did you think there was a race condition, originally? Was that based upon your knowledge of the code? It may be that perusing the code is required here, and I have only skimmed through it, trying to understand the structure.

If there really is a race here, then that's a problem, and it should be identified. But what evidence are we working with, for now?

See #4725, in particular #4725 (comment).

Ok, thanks. Looking at that comment:

... The service is bound to the device but not ordered against it. This means startup of the service will not be delayed, as there's nothing to wait for. But as soon as it is up we notice that the device isn't around yet, and are stopped again. This is because at the time the udev rule is run the .device is not yet visible to PID 1. The fix for that is easy: just add After= in additoin to BindsTo= on the device.

That obviously is the wrong interpretation for BindsTo= and the wrong "fix". BindsTo= is an "edge sensitive" sort of dependency, according to the documentation. The behavior of BindsTo= is perhaps being confused with the behavior of Requisite= here. Even then, Requisite= itself would not cause this kind of start-then-stop behavior, because the condition - a requirement that the device already exist - would not have been satisfied in the first place. If BindsTo= is really producing that kind of start-then-stop state sequence, then the systemd logic needs to be corrected.

So, I do not see this as an example of, or evidence of, a race condition. What has been described is simply a logical sequence of states, even though it is a faulty sequence, since the BindsTo= logic has, apparently, been "broken" by the commit at c5a97ed.

I force pushed a new, rebased version now. it's much more conservative than the previous ones, and will only recheck the dependencies that have BindsTo= in combination with After=. This also permitted me to drop the cryptsetup change part, as its use of BindsTo= is no longer problematic.

This means, as a net result:

1. BindsTo= alone (or in combination with Before=): the main effect is that if the dependent unit suddenly goes away, then we will go away too. Also, it will act like Requires=: when the start job for a bindsto unit fails our start job will fail.
2. BindsTo= in combination with After=: behaviour like in 1. However, on top of that: we'll recheck right before starting that the dependent unit is actually really running.

Note that a start job for a unit where a ConditionXYZ= doesn't hold will not fail, but succeed. This means, if you dependent on such a unit with BindsTo= without After=, then you will still be started and stay running. However, if you depend on it with BindsTo= and with After=, then you will fail to start.

I force pushed a new version now, with all @keszybz points fixed! Thanks for the review!

Is the new version the git Master branch now, if I want to test this?

@thx1111 no, it isn't. This PR is still open. It gets merged only after this PR is merged into master, which hasn't happened yet.

systemd-git 232.r1130.g293b16734-1
libsystemd-git 232.r1130.g293b16734-1

Here, the physical devices enp3s0 and wlp2s0 exist, and the usb devices, wlp0s26u1u1, wlp0s26u1u2, and enp0s26u1u6, are not installed. The virtual network devices, bond0 and bridge0, must be created.

The unit file file for the "enslaved" devices does not have "After=", and has, literally:

BindsTo= sys-subsystem-net-devices-%i.device
BindsTo= sys-subsystem-net-devices-%p.device

Here, adding Requisite=sys-subsystem-net-devices-%p.device makes no difference.

With this patched version of systemd, while the network devices are, eventually, created properly, systemd still runs the service unit files for the nonexistent devices, and so, the patch completely and utterly fails to address or resolve the original problem. These unit files for the nonexistent devices still run and still result in "Unit entered failed state."

In the log, notice that jobs for both existing and non-existing devices are "removed", and then all of these same jobs are started, nonetheless. From the number of log entries, compared to the normal log entries before the patch, there seems to be a lot of "do nothing" work being done in the job scheduling.

On a systemctl restart ..., the log is less chatty, without the Unnecessary job ... was removed messages.

...
Feb 27 13:21:28 lapis systemd[1]: Started bond0 Interface Master.
Feb 27 13:21:28 lapis systemd[1]: [email protected]: Unit is bound to inactive unit sys-subsystem-net-devices-bond0.device. Stopping, too
Feb 27 13:21:28 lapis systemd[1]: Requested transaction contradicts existing jobs: Transaction is destructive.
Feb 27 13:21:28 lapis systemd[1]: [email protected]: Failed to enqueue stop job, ignoring: Transaction is destructive.
Feb 27 13:21:28 lapis systemd[1]: Started bridge0 Interface Master.
Feb 27 13:21:28 lapis systemd[1]: [email protected]: Unit is bound to inactive unit sys-subsystem-net-devices-bridge0.device. Stopping,
Feb 27 13:21:28 lapis systemd[1]: Requested transaction contradicts existing jobs: Transaction is destructive.
Feb 27 13:21:28 lapis systemd[1]: [email protected]: Failed to enqueue stop job, ignoring: Transaction is destructive.
Feb 27 13:21:28 lapis systemd[1]: Unnecessary job for sys-subsystem-net-devices-wlp0s26u1u1.device was removed.
Feb 27 13:21:28 lapis systemd[1]: Unnecessary job for sys-subsystem-net-devices-enp0s26u1u6.device was removed.
Feb 27 13:21:28 lapis systemd[1]: Unnecessary job for sys-subsystem-net-devices-bond0.device was removed.
Feb 27 13:21:28 lapis systemd[1]: Unnecessary job for sys-subsystem-net-devices-wlp0s26u1u2.device was removed.
Feb 27 13:21:28 lapis systemd[1]: Unnecessary job for sys-subsystem-net-devices-wlp0s26u1u2.device was removed.
Feb 27 13:21:28 lapis systemd[1]: Unnecessary job for sys-subsystem-net-devices-wlp0s26u1u1.device was removed.
Feb 27 13:21:28 lapis systemd[1]: Unnecessary job for sys-subsystem-net-devices-enp0s26u1u6.device was removed.
Feb 27 13:21:28 lapis systemd[1]: Starting Enslaved bond0@bridge0...
Feb 27 13:21:28 lapis systemd[1]: Starting Enslaved wlp0s26u1u1@bond0...
Feb 27 13:21:28 lapis systemd[1]: Starting Enslaved wlp2s0@bond0...
Feb 27 13:21:28 lapis systemd[1]: Starting Enslaved enp0s26u1u6@bridge0...
Feb 27 13:21:28 lapis systemd[1]: Starting Enslaved enp3s0@bond0...
Feb 27 13:21:28 lapis systemd[1]: Starting wpa_supplicant on wlp2s0...
Feb 27 13:21:28 lapis systemd[1]: Starting Enslaved wlp0s26u1u2@bond0...
Feb 27 13:21:28 lapis systemd[1]: [email protected]: Main process exited, code=exited, status=1/FAILURE
Feb 27 13:21:28 lapis systemd[1]: Failed to start Enslaved wlp0s26u1u1@bond0.
Feb 27 13:21:28 lapis systemd[1]: [email protected]: Unit entered failed state.
Feb 27 13:21:28 lapis systemd[1]: [email protected]: Failed with result 'exit-code'.
...
Feb 27 13:21:29 lapis systemd[1]: Started Enslaved bond0@bridge0.
Feb 27 13:21:29 lapis systemd[1]: Started Enslaved wlp2s0@bond0.
Feb 27 13:21:29 lapis systemd[1]: Started Enslaved enp3s0@bond0.
Feb 27 13:21:29 lapis ip[394]: Cannot find device "enp0s26u1u6"
Feb 27 13:21:29 lapis systemd[1]: [email protected]: Main process exited, code=exited, status=1/FAILURE
Feb 27 13:21:29 lapis systemd[1]: Failed to start Enslaved enp0s26u1u6@bridge0.
Feb 27 13:21:29 lapis ip[386]: Cannot find device "wlp0s26u1u2"
Feb 27 13:21:29 lapis systemd[1]: [email protected]: Unit entered failed state.
Feb 27 13:21:29 lapis systemd[1]: [email protected]: Failed with result 'exit-code'.
Feb 27 13:21:29 lapis systemd[1]: [email protected]: Main process exited, code=exited, status=1/FAILURE
Feb 27 13:21:29 lapis systemd[1]: Failed to start Enslaved wlp0s26u1u2@bond0.
Feb 27 13:21:29 lapis systemd[1]: [email protected]: Unit entered failed state.
Feb 27 13:21:29 lapis systemd[1]: [email protected]: Failed with result 'exit-code'.
...

And then, was there any useful change in functionality actually provided by commit cd8e857 ?

Do you want to close-out this pull request, and also close-out the bug reports,

"Requisite" dependency fails with "device" units - and with "After" ordering, produces "crazy" errors
#4756

"BindsTo=" must confirm that a device exists before enqueuing a start job on that device.
#4413

and open a new bug report for systemd 233? Or do we continue in this pull request? Or do we continue in one of the other bug reports?