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 <[email protected]>
Sent: Tuesday, December 21, 2021 8:24:35 AM
To: Christopher Wong; [email protected]
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 <[email protected]> on behalf
> of Andrei Borzenkov <[email protected]>
> Sent: Monday, December 20, 2021 1:27:42 PM
> To: [email protected]
> 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.
>
