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@xxxxxxxx> 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/aDec 22 18:03:17 axis-b8a44f278c56 systemd[1]: temperature-controller.service: Trying to enqueue job temperature-controller.service/stop/replaceDec 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=canceledDec 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/aDec 22 18:03:17 axis-b8a44f278c56 systemd[1]: temperature-controller.service: Installed new job temperature-controller.service/stop as 721Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: temperature-controller.service: Enqueued job temperature-controller.service/stop as 721Dec 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/aDec 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/aDec 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/aDec 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/aDec 22 18:03:17 axis-b8a44f278c56 systemd[1]: opticsd.service: starting held back, waiting for: temperature-controller.serviceDec 22 18:03:17 axis-b8a44f278c56 systemd[1]: temperature-controller.service: Job 721 temperature-controller.service/stop finished, result=doneDec 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/aDec 22 18:03:17 axis-b8a44f278c56 systemd[1]: Failed to read pids.max attribute of cgroup root, ignoring: No data availableDec 22 18:03:17 axis-b8a44f278c56 systemd[1]: opticsd.service: Forked /usr/bin/udevadm as 561Dec 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/aDec 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/aDec 22 18:03:17 axis-b8a44f278c56 systemd[1]: opticsd.service: Changed dead -> start-preDec 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/startDec 22 18:03:17 axis-b8a44f278c56 systemd[1]: temperature-controller.service: Installed new job temperature-controller.service/start as 722Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: temperature-controller.service: Enqueued job temperature-controller.service/start as 722Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: temperature-controller.service: starting held back, waiting for: coco-wiper-manager.serviceDec 22 18:03:17 axis-b8a44f278c56 systemd[1]: temperature-controller.service: Trying to enqueue job temperature-controller.service/stop/replaceDec 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=canceledDec 22 18:03:17 axis-b8a44f278c56 systemd[1]: temperature-controller.service: Installed new job temperature-controller.service/stop as 809Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: temperature-controller.service: Enqueued job temperature-controller.service/stop as 809Dec 22 18:03:17 axis-b8a44f278c56 systemd[1]: temperature-controller.service: Job 809 temperature-controller.service/stop finished, result=doneDec 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@xxxxxxxxx>
Sent: Tuesday, December 21, 2021 8:24:35 AM
To: Christopher Wong; systemd-devel@xxxxxxxxxxxxxxxxxxxxx
Subject: Re: After= and Wants= doesn't seem to have an effectOn 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@xxxxxxxxxxxxxxxxxxxxx> on behalf of Andrei Borzenkov <arvidjaar@xxxxxxxxx>
> Sent: Monday, December 20, 2021 1:27:42 PM
> To: systemd-devel@xxxxxxxxxxxxxxxxxxxxx
> Subject: Re: 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.
>
