[systemd-devel] No rhyme or reason to systemd enabling/disabling service

[Chip]

On 07/29/2016 05:57 AM, Lennart Poettering wrote:
> On Thu, 28.07.16 13:44, Chip (jeffschips at gmail.com) wrote:
>
>> Ubuntu 16.04
>>
>> With no changes to software or anything, on reboot, systemd *sometimes* will
>> start dnscrypt-proxy.service while other times just ignores it and it fails
>> to start. There is no rhyme or reason as to why sometimes it starts and
>> other times fails to start.
>>
>> All files in /etc/systemd/system/multi-user.target.wants look correct.
>>
>> I need help troubleshooting this problem.
>>
>> Following is a successful journalctl -xru dnscrypt-proxy.service, otherwise
>> when it fails, it simply shows "no results":
> My educated guess is that some cyclic dependency or so caused it to
> not be considered for activation at boot.
>
> To check that, look at the full boot-up process with "journalctl -b",
> and see if your service is mentioned there, in particularly by PID 1.
>
> Lennart
>
This is what a successful startup looks like:

Jul 29 11:33:06 blablabla systemd[1]: systemd 229 running in system mode.
Jul 29 11:33:06 blablabla systemd[1]: Detected architecture x86-64.
Jul 29 11:33:06 blablabla systemd[1]: Set hostname to <blablabla>.
Jul 29 11:33:06 blablabla kernel: random: nonblocking pool is initialized
Jul 29 11:33:06 blablabla kernel: clocksource: Switched to clocksource tsc
Jul 29 11:33:06 blablabla systemd[1]: basic.target: Found ordering cycle 
on basic.target/start
Jul 29 11:33:06 blablabla systemd[1]: basic.target: Found dependency on 
sockets.target/start
Jul 29 11:33:06 blablabla systemd[1]: basic.target: Found dependency on 
dnscrypt-proxy.socket/start
Jul 29 11:33:06 blablabla systemd[1]: basic.target: Found dependency on 
network.target/start
Jul 29 11:33:06 blablabla systemd[1]: basic.target: Found dependency on 
NetworkManager.service/start
Jul 29 11:33:06 blablabla systemd[1]: basic.target: Found dependency on 
dbus.service/start
Jul 29 11:33:06 blablabla systemd[1]: basic.target: Found dependency on 
basic.target/start
Jul 29 11:33:06 blablabla systemd[1]: basic.target: Breaking ordering 
cycle by deleting job sockets.target/start
Jul 29 11:33:06 blablabla systemd[1]: sockets.target: Job 
sockets.target/start deleted to break ordering cycle starting with 
basic.target/start
Jul 29 11:33:06 blablabla systemd[1]: Listening on Syslog Socket.
Jul 29 11:33:06 blablabla systemd[1]: Listening on fsck to fsckd 
communication Socket.


And then more specifically for successful startup:

ta at blablabla:~$ journalctl -b | grep dnscrypt

Jul 29 11:33:06 blablabla systemd[1]: basic.target: Found dependency on 
dnscrypt-proxy.socket/start
Jul 29 11:33:11 blablabla audit[755]: AVC apparmor="STATUS" 
operation="profile_load" profile="unconfined" 
name="/usr/sbin/dnscrypt-proxy" pid=755 comm="apparmor_parser"
Jul 29 11:33:12 blablabla ureadahead[282]: 
ureadahead:/var/lib/apt/lists/ppa.launchpad.net_anton+_dnscrypt_ubuntu_dists_xenial_main_binary-amd64_Packages: 
No such file or directory
Jul 29 11:33:17 blablabla systemd[1]: Listening on dnscrypt-proxy 
listening socket.
Jul 29 11:33:17 blablabla dnscrypt-proxy[1008]: [INFO] - [okturtles] 
does not support DNS Security Extensions
Jul 29 11:33:17 blablabla dnscrypt-proxy[1008]: [INFO] + Namecoin 
domains can be resolved
Jul 29 11:33:17 blablabla dnscrypt-proxy[1008]: [INFO] + Provider 
supposedly doesn't keep logs
Jul 29 11:33:17 blablabla dnscrypt-proxy[1008]: [NOTICE] Starting 
dnscrypt-proxy 1.6.7
Jul 29 11:33:17 blablabla dnscrypt-proxy[1008]: [INFO] Generating a new 
session key pair
Jul 29 11:33:17 blablabla dnscrypt-proxy[1008]: [INFO] Done
Jul 29 11:33:22 blablabla dnscrypt-proxy[1008]: [INFO] Server 
certificate #809684433 received
Jul 29 11:33:22 blablabla dnscrypt-proxy[1008]: [INFO] This certificate 
is valid
Jul 29 11:33:22 blablabla dnscrypt-proxy[1008]: [INFO] Chosen 
certificate #809684433 is valid from [2016-01-24] to [2017-01-23]
Jul 29 11:33:22 blablabla dnscrypt-proxy[1008]: [INFO] Server key 
fingerprint is 
CB51:0B61:88Y2:FCEB:27CE:56B5:3567:978A:04FF:D9E7:42A4:6A6B:0943:0F0F:F084:656C
Jul 29 11:33:22 blablabla dnscrypt-proxy[1008]: [NOTICE] Proxying from 
127.0.2.1:53 to 23.226.215.93:443