[systemd-devel] After= and Wants= doesn't seem to have an effect

[Anita Zhang]

I think the telling part is "temperature-controller.service/start finished,
result=canceled". When another job for the same unit comes in
(e.g. "temperature-controller.service: Trying to enqueue job
temperature-controller.service/stop/replace") then the first job gets
canceled and replaced by the new one (this is the default behavior which I
think can be overridden). The bad part is systemd doesn't have logs to tell
you why the stop transaction was issued. Maybe you can use `systemctl show
temperature-controller.service` to see if there are BindsTo= or Conflicts=
dependencies that are not listed in the unit files and causing the stop job
to get issued.

As for your other point about why opticsd.service runs after
temperature-controller.service's stop job, I think this is by design.
According to
https://github.com/systemd/systemd/blob/4d484e14bb9864cef1d124885e625f33bf31e91c/src/core/job.c#L1659-L1698
if  "b" starts after "a", but "a" has a stop job queued, then "a" will
stop, then "b" will start. Substitute opticsd for "b" and
temperature-controller for "a". The Wants= property issued a start job so
what you're expecting is "a" starts, then "b" starts. But due to the
canceled job mentioned above, you're instead left with "a" stops, then "b"
starts.

Hope that helps,
Anita

On Wed, Dec 22, 2021 at 10:15 AM Christopher Wong <Christopher.Wong at axis.com>
wrote:

> The code is being run on systemd 247.6. I finally got some debug logs to
> share (see below). The starting of opticsd.service is held back, waiting
> for temperature-controller.service, which is good. However, the line right
> after: Job 721, which is a stop job for temperature-controller finished
> with result=done. That seems to trigger the continuation of
> opticsd.service. I don't have the logs for when Job 107 was started and why
> Job 721 is created. My guess is that temperature-controller is waiting for
> coco-wiper-manager as indicated in Job 722 and Job 809. Could this really
> be a bug and I am that lucky to stumble into it?
>
>
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Got message type=method_call
> sender=n/a destination=org.freedesktop.systemd1
> path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager
> member=StopUnit cookie=1 reply_cookie=0 signature=ss error-name=n/a
> error-message=n/a
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: Trying to enqueue job
> temperature-controller.service/stop/replace
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Added job
> temperature-controller.service/stop to transaction.
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: Job 107
> temperature-controller.service/start finished, result=canceled
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Sent message type=signal
> sender=org.freedesktop.systemd1 destination=n/a
> path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager
> member=JobRemoved cookie=1 reply_cookie=0 signature=uoss error-name=n/a
> error-message=n/a
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: Installed new job
> temperature-controller.service/stop as 721
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: Enqueued job
> temperature-controller.service/stop as 721
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Sent message type=signal
> sender=org.freedesktop.systemd1 destination=n/a
> path=/org/freedesktop/systemd1/unit/temperature_2dcontroller_2eservice
> interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=2
> reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Sent message type=signal
> sender=org.freedesktop.systemd1 destination=n/a
> path=/org/freedesktop/systemd1/unit/temperature_2dcontroller_2eservice
> interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=3
> reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Sent message type=signal
> sender=org.freedesktop.systemd1 destination=n/a
> path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager
> member=JobNew cookie=4 reply_cookie=0 signature=uos error-name=n/a
> error-message=n/a
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Sent message
> type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a
> interface=n/a member=n/a cookie=5 reply_cookie=1 signature=o error-name=n/a
> error-message=n/a
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: opticsd.service: starting
> held back, waiting for: temperature-controller.service
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: Job 721 temperature-controller.service/stop
> finished, result=done
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Sent message type=signal
> sender=org.freedesktop.systemd1 destination=n/a
> path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager
> member=JobRemoved cookie=6 reply_cookie=0 signature=uoss error-name=n/a
> error-message=n/a
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Failed to read pids.max
> attribute of cgroup root, ignoring: No data available
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: opticsd.service: Forked
> /usr/bin/udevadm as 561
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Sent message type=signal
> sender=org.freedesktop.systemd1 destination=n/a
> path=/org/freedesktop/systemd1/unit/opticsd_2eservice
> interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7
> reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Sent message type=signal
> sender=org.freedesktop.systemd1 destination=n/a
> path=/org/freedesktop/systemd1/unit/opticsd_2eservice
> interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=8
> reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: opticsd.service: Changed
> dead -> start-pre
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Starting Optics daemon...
> ...
>
>
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Keeping job
> coco-wiper-manager.service/start because of
> temperature-controller.service/start
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: Installed new job
> temperature-controller.service/start as 722
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: Enqueued job
> temperature-controller.service/start as 722
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: starting held back, waiting for:
> coco-wiper-manager.service
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: Trying to enqueue job
> temperature-controller.service/stop/replace
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Added job
> temperature-controller.service/stop to transaction.
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: Job 722
> temperature-controller.service/start finished, result=canceled
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: Installed new job
> temperature-controller.service/stop as 809
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: Enqueued job
> temperature-controller.service/stop as 809
> Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: Job 809 temperature-controller.service/stop
> finished, result=done
> Dec 22 18:03:18 axis-b8a44f278c56 systemd[1]:
> temperature-controller.service: Trying to enqueue job
> temperature-controller.service/start/replace
>
>
> Best Regards,
> Christopher Wong
>
> ------------------------------
> *From:* Andrei Borzenkov <arvidjaar at gmail.com>
> *Sent:* Tuesday, December 21, 2021 8:24:35 AM
> *To:* Christopher Wong; systemd-devel at lists.freedesktop.org
> *Subject:* Re: [systemd-devel] After= and Wants= doesn't seem to have an
> effect
>
> On 20.12.2021 17:05, Christopher Wong wrote:
> >> # /etc/systemd/system/iris-detection.service
> >> [Unit]
> >> Description=Iris detection
> >> PartOf=opticsd.service
> >
> >
> > How can you tell that it is a loop? iris-detection.service doesn't have
> any After= as you stated below.
>
> Yes, sorry, you are right.
>
> > Is it due to the PartOf=opticsd.service?
> >
>
> I do not think so. Still, loop is possible due to some other dependencies,
> it is also
> possible that actual unit definitions are different (e.g. units files have
> been changed
> after systemd read them).
>
> Running with debig log level may give some more hints.
>
> >
> > Best Regards,
> >
> > Christopher Wong
> >
> > ________________________________
> > From: systemd-devel <systemd-devel-bounces at lists.freedesktop.org> on
> behalf of Andrei Borzenkov <arvidjaar at gmail.com>
> > Sent: Monday, December 20, 2021 1:27:42 PM
> > To: systemd-devel at lists.freedesktop.org
> > Subject: Re: [systemd-devel] After= and Wants= doesn't seem to have an
> effect
> >
> > On 20.12.2021 15:06, Christopher Wong wrote:
> >> # /etc/systemd/system/iris-detection.service
> >> After=temperature-controller.service
> >>
> >> # /usr/lib/systemd/system/temperature-controller.service
> >> After=iris-detection.service
> >
> > This is loop and systemd is free to break it by ignoring some dependency.
> >
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20211223/21588ec7/attachment.htm>