Bug#945002: systemd: Dependencies not honoured at boot, so a service doesn't start

[Fred Boiteux]

Package: systemd
Version: 241-7~deb10u2
Severity: normal

Dear Maintainer,

On a Debian Buster system, I've installed the Squid package. It doesn't
start on every boot. On my system, the /var directory is on a separate
partition, mounted at boot. I've updated the squid.service to add a
dependency on this /var mount (see also #932593) :

$ diff  -u /lib/systemd/system/squid.service
/etc/systemd/system/squid.service
--- /lib/systemd/system/squid.service   2019-02-19 06:29:20.000000000 +0100
+++ /etc/systemd/system/squid.service   2019-09-06 11:22:00.385894559 +0200
@@ -8,7 +8,8 @@
 [Unit]
 Description=Squid Web Proxy Server
 Documentation=man:squid(8)
-After=network.target network-online.target nss-lookup.target
+Requires=var.mount network.target network-online.target nss-lookup.target
+After=   var.mount network.target network-online.target nss-lookup.target

 [Service]
 Type=forking


But even with this modification, the squid.service fails at boot :

# systemctl status squid --no-pager -l
● squid.service - Squid Web Proxy Server
   Loaded: loaded (/etc/systemd/system/squid.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Mon 2019-11-18 09:30:26 CET; 46min ago
     Docs: man:squid(8)
  Process: 431 ExecStartPre=/usr/sbin/squid --foreground -z (code=exited, status=255/EXCEPTION)

nov. 18 09:30:26 Deve2m squid[431]: WARNING: Cannot write log file: /var/log/squid/cache.log
nov. 18 09:30:26 Deve2m squid[431]: /var/log/squid/cache.log: No such file or directory
nov. 18 09:30:26 Deve2m squid[431]:          messages will be sent to 'stderr'.
nov. 18 09:30:26 Deve2m squid[431]: 2019/11/18 09:30:26| FATAL: Squid is already running: Found fresh instance PID file (/var/run/squid.pid) with PID 541
nov. 18 09:30:26 Deve2m squid[431]:     exception location: Instance.cc(121) ThrowIfAlreadyRunningWith
nov. 18 09:30:26 Deve2m systemd[1]: squid.service: Control process exited, code=exited, status=255/EXCEPTION
nov. 18 09:30:26 Deve2m systemd[1]: squid.service: Failed with result 'exit-code'.
nov. 18 09:30:26 Deve2m systemd[1]: Failed to start Squid Web Proxy Server.
nov. 18 09:30:27 Deve2m systemd[1]: squid.service: Unit cannot be reloaded because it is inactive.
nov. 18 09:30:28 Deve2m systemd[1]: squid.service: Unit cannot be reloaded because it is inactive.

When looking at the journal of var.mount and squid units, I can see that
SystemD seems to try squid before var.mount is up :


# journalctl -b -u squid.service -u var.mount -o short-precise --no-pager -l
-- Logs begin at Mon 2019-11-18 09:30:25 CET, end at Mon 2019-11-18 10:17:33 CET. --
nov. 18 09:30:26.295333 Deve2m squid[431]: WARNING: Cannot write log file: /var/log/squid/cache.log
nov. 18 09:30:26.296148 Deve2m squid[431]: /var/log/squid/cache.log: No such file or directory
nov. 18 09:30:26.297190 Deve2m squid[431]:          messages will be sent to 'stderr'.
nov. 18 09:30:26.304463 Deve2m squid[431]: 2019/11/18 09:30:26| FATAL: Squid is already running: Found fresh instance PID file (/var/run/squid.pid) with PID 541
nov. 18 09:30:26.304463 Deve2m squid[431]:     exception location: Instance.cc(121) ThrowIfAlreadyRunningWith
nov. 18 09:30:26.324920 Deve2m systemd[1]: squid.service: Control process exited, code=exited, status=255/EXCEPTION
nov. 18 09:30:26.324973 Deve2m systemd[1]: squid.service: Failed with result 'exit-code'.
nov. 18 09:30:26.325294 Deve2m systemd[1]: Failed to start Squid Web Proxy Server.
nov. 18 09:30:26.696846 Deve2m systemd[1]: var.mount: Directory /var to mount over is not empty, mounting anyway.
nov. 18 09:30:26.697820 Deve2m systemd[1]: Mounting /var...
nov. 18 09:30:26.733644 Deve2m systemd[1]: Mounted /var.
nov. 18 09:30:27.432368 Deve2m systemd[1]: squid.service: Unit cannot be reloaded because it is inactive.
nov. 18 09:30:28.177452 Deve2m systemd[1]: squid.service: Unit cannot be reloaded because it is inactive.



Note that starting the squid service once the whole system has booted works.


I had this strange behaviour on Debian 10.1 and tried also recent 10.2, with
the same result.


    With regards,
        Fred.

-- Package-specific info:

-- System Information:
Debian Release: 10.2
  APT prefers stable
  APT policy: (990, 'stable'), (985, 'stable-updates'), (800, 'unstable'), (1, 'experimental')
Architecture: amd64 (x86_64)

Kernel: Linux 4.19.0-6-amd64 (SMP w/1 CPU core)
Kernel taint flags: TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=fr_FR.utf8, LC_CTYPE=fr_FR.utf8 (charmap=UTF-8), LANGUAGE=fr_FR.utf8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages systemd depends on:
ii  adduser          3.118
ii  libacl1          2.2.53-4
ii  libapparmor1     2.13.2-10
ii  libaudit1        1:2.8.4-3
ii  libblkid1        2.33.1-0.1
ii  libc6            2.28-10
ii  libcap2          1:2.25-2
ii  libcryptsetup12  2:2.1.0-5+deb10u2
ii  libgcrypt20      1.8.4-5
ii  libgnutls30      3.6.7-4
ii  libgpg-error0    1.35-1
ii  libidn11         1.33-2.2
ii  libip4tc0        1.8.2-4
ii  libkmod2         26-1
ii  liblz4-1         1.8.3-1
ii  liblzma5         5.2.4-1
ii  libmount1        2.33.1-0.1
ii  libpam0g         1.3.1-5
ii  libseccomp2      2.3.3-4
ii  libselinux1      2.8-1+b1
ii  libsystemd0      241-7~deb10u2
ii  mount            2.33.1-0.1
ii  util-linux       2.33.1-0.1

Versions of packages systemd recommends:
ii  dbus            1.12.16-1
ii  libpam-systemd  241-7~deb10u2

Versions of packages systemd suggests:
ii  policykit-1        0.105-25
pn  systemd-container  <none>

Versions of packages systemd is related to:
pn  dracut           <none>
ii  initramfs-tools  0.133+deb10u1
ii  udev             241-7~deb10u2

-- no debconf information