Dear Maintainer,


   * What led up to the situation?

Recent system update, probably.

   * What exactly did you do (or not do) that was effective (or
     ineffective)?

Restart dhcpcd, reboot the machine.

   * What was the outcome of this action?

systemd kills dhcpcd after 90s, despite it working correctly (mostly).

   * What outcome did you expect instead?

A working, running dhcpcd

Log:

Jul 03 12:20:07 felka systemd[1]: Starting DHCP Client Daemon on all interfaces...
░░ Subject: A start job for unit dhcpcd.service has begun execution
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░
░░ A start job for unit dhcpcd.service has begun execution.
░░
░░ The job identifier is 165.
Jul 03 12:20:07 felka dhcpcd[624]: dhcpcd-9.4.1 starting
Jul 03 12:20:07 felka dhcpcd[643]: ps_dropprivs: chroot: /usr/lib/dhcpcd: Operation not permitted
Jul 03 12:20:07 felka dhcpcd[643]: ps_dropprivs: chroot: /usr/lib/dhcpcd: Operation not permitted
Jul 03 12:20:07 felka dhcpcd[624]: ps_dropprivs: chroot: /usr/lib/dhcpcd: Operation not permitted
Jul 03 12:20:07 felka dhcpcd[624]: ps_dropprivs: chroot: /usr/lib/dhcpcd: Operation not permitted
Jul 03 12:20:07 felka dhcpcd[643]: DUID 00:04:03:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
Jul 03 12:20:07 felka systemd[1]: dhcpcd.service: Can't open PID file /run/dhcpcd.pid (yet?) after start: Operation not permi>
Jul 03 12:20:08 felka dhcpcd[643]: wan1: waiting for carrier
Jul 03 12:20:11 felka dhcpcd[643]: wan1: carrier acquired
Jul 03 12:20:11 felka dhcpcd[643]: wan1: IAID 99:ab:XXXXX
Jul 03 12:20:11 felka dhcpcd[643]: wan1: IA type 25 IAID 00:00:00:00
Jul 03 12:20:11 felka dhcpcd[643]: wan1: adding address fe80::b62e:XXXXXXXXXXXXf2
Jul 03 12:20:11 felka dhcpcd[643]: wan1: soliciting an IPv6 router
Jul 03 12:20:11 felka dhcpcd[643]: wan1: rebinding lease of 185.XXXXXXXXXX
Jul 03 12:20:11 felka dhcpcd[2012]: ps_dropprivs: chroot: /usr/lib/dhcpcd: Operation not permitted
Jul 03 12:20:11 felka dhcpcd[2013]: ps_dropprivs: chroot: /usr/lib/dhcpcd: Operation not permitted
Jul 03 12:20:11 felka dhcpcd[643]: wan1: probing address 185.1XXXXXXXXX/24
Jul 03 12:20:12 felka dhcpcd[643]: wan1: rebinding prior DHCPv6 lease
Jul 03 12:20:12 felka dhcpcd[643]: lan1: activating for delegation
Jul 03 12:20:12 felka dhcpcd[643]: lan1: IAID 99:ab:XXXXX
Jul 03 12:20:12 felka dhcpcd[643]: wlan1: activating for delegation
Jul 03 12:20:12 felka dhcpcd[643]: wlan1: waiting for carrier
Jul 03 12:20:13 felka dhcpcd[643]: wlan1: carrier acquired
Jul 03 12:20:13 felka dhcpcd[643]: wlan1: IAID 85:f5:XXXXX
Jul 03 12:20:13 felka dhcpcd[643]: wlan1: adding address fe80::52e0:XXXXXXXXXXXXXX
Jul 03 12:20:16 felka dhcpcd[643]: wan1: leased 185.XXXXXXXXXX for 4000 seconds
Jul 03 12:20:16 felka dhcpcd[643]: wan1: adding route to 185.XXXXXXXXX/24
Jul 03 12:20:16 felka dhcpcd[643]: wan1: adding default route via 185.XXXXXXXXX
Jul 03 12:20:18 felka dhcpcd[643]: wan1: Router Advertisement from fe80::200:XXXXXXXXXXXXX
Jul 03 12:20:18 felka dhcpcd[643]: wan1: adding address 2a02:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX/64
Jul 03 12:20:18 felka dhcpcd[643]: wan1: adding route to 2a02:XXXXXXXXXXXXX/64
Jul 03 12:20:18 felka dhcpcd[643]: wan1: adding default route via fe80::200:XXXXXXXXXXXXX
Jul 03 12:20:21 felka dhcpcd[643]: wan1: fe80::200:XXXXXXXXXXXXX is unreachable
Jul 03 12:20:21 felka dhcpcd[643]: wan1: fe80::200:XXXXXXXXXXXXX is reachable again
Jul 03 12:20:22 felka dhcpcd[643]: wan1: failed to rebind prior DHCPv6 delegation
Jul 03 12:20:22 felka dhcpcd[643]: wan1: soliciting an IPv6 router
Jul 03 12:20:25 felka dhcpcd[643]: wan1: ADV 2a02:XXXXXXXX::/48 from fe80::200:XXXXXXXXXXXXX
Jul 03 12:20:25 felka dhcpcd[643]: wan1: REPLY6 received from fe80::200:XXXXXXXXXXXXX
Jul 03 12:20:25 felka dhcpcd[643]: wan1: renew in 1000, rebind in 2000, expire in 4000 seconds
Jul 03 12:20:25 felka dhcpcd[643]: lo: adding reject route to 2a02:XXXXXXXXXX/48
Jul 03 12:20:25 felka dhcpcd[643]: wan1: delegated prefix 2a02:XXXXXXXXXX/48
Jul 03 12:20:25 felka dhcpcd[643]: lan1: adding address 2a02:XXXXXXXXXXX/64
Jul 03 12:20:25 felka dhcpcd[643]: wlan1: adding address 2a02:XXXXXXXXXXXXX/64
Jul 03 12:20:25 felka dhcpcd[643]: lan1: adding route to 2a02:XXXXXXXXXX/64
Jul 03 12:20:25 felka dhcpcd[643]: wlan1: adding route to 2a02:XXXXXXXXXXXX/64
Jul 03 12:21:38 felka systemd[1]: dhcpcd.service: start operation timed out. Terminating.
Jul 03 12:21:38 felka dhcpcd[643]: received SIGTERM, stopping
Jul 03 12:21:38 felka dhcpcd[643]: wlan1: removing interface
Jul 03 12:21:38 felka dhcpcd[643]: lan1: removing interface
Jul 03 12:21:38 felka dhcpcd[643]: wan1: removing interface
Jul 03 12:21:38 felka systemd[1]: dhcpcd.service: Failed with result 'timeout'.
░░ Subject: Unit failed
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░
░░ The unit dhcpcd.service has entered the 'failed' state with result 'timeout'.
Jul 03 12:21:38 felka systemd[1]: Failed to start DHCP Client Daemon on all interfaces.
░░ Subject: A start job for unit dhcpcd.service has failed
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░
░░ A start job for unit dhcpcd.service has finished with a failure.
░░
░░ The job identifier is 165 and the job result is failed.
<F29>

Dear Colleagues,

I have faced this issue as well, and managed to find the root cause of this issue.

It seems that the culprit is caused by the systemd unit file, as systemd itself can not found the configured pid file and eventually kills dhcpcd.
dhcpcd works just fine if you are starting it in foreground mode.

To check where dhcpcd put its pidfile, run 'dhcpcd -P' in the cli.
On my system it prints this: '/run/dhcpcd/pid'

After changing the PIDFile stanza in the unit file from '/run/dhcpcd.pid' to '/run/dhcpcd/pid' and do the necessary 'systemctl daemon-reload' dance, dhcpcd starts just fine.

Some troubling logs are still there, like:

ps_dropprivs: chroot: /usr/lib/dhcpcd: Operation not permitted

which might need further actions, but the basic functionality has been restored with this small change.

Regards,
János Pásztor

Tobias,

Does the fix suggested by János in response to your bug report restore
normal operation?

Martin-Éric

Hi!

Yes that seems to do the trick

Specifically, in /usr/lib/systemd/system/dhcpcd.service

```
PIDFile=/run/dhcpcd/pid
```

instead of

```
PIDFile=/run/dhcpcd.pid
```

and in /lib/systemd/system/dhcpcd@.service

```
PIDFile=/run/dhcpcd/%I.pid
```

instead of

```
PIDFile=/run/dhcpcd-%I.pid
```

I have switched to the @interface style of service/unit config now, and
that works fine as well.


Best,
Tobias

Dear Colleagues,

After some further investigation I think I have found the solution for the chroot error as well.

In the unit file the syscall filtering is a little bit too strict. Besides the already configured list of '@system-service' for the 'SystemCallFilter' stanza, the 'chroot' syscall has to be added as well.
After having a cursory glance over the source code (and mind you, I am not a C developer :-) ) I have found 'src/privsep.c' where the design details are documented in the beginning.
Based on that I think it is a fair thing to grant that extra syscall for the service.

With that I have managed to reduce the number of errors in the dhcpcd unit logs to one on my machine, namely

control_free: No such file or directory

which might not fit the scope of this ticket.

Regards,
János Pásztor

On Thu, Jul 7, 2022 at 1:40 AM Tobias Klausmann <klausman@schwarzvogel.de> wrote:

János: Do you want to submit your findings to upstream?

Martin-Éric

We believe that the bug you reported is fixed in the latest version of
dhcpcd5, which is due to be installed in the Debian FTP archive.

A summary of the changes between this version and the previous one is
attached.

Thank you for reporting the bug, which will now be closed.  If you
have further comments please address them to 1014277@bugs.debian.org,
and the maintainer will reopen the bug report if appropriate.

Debian distribution maintenance software
pp.
Martin-Éric Racine <martin-eric.racine@iki.fi> (supplier of updated dhcpcd5 package)

(This message was generated automatically at their request; if you
believe that there is a problem with it please contact the archive
administrators by mailing ftpmaster@ftp-master.debian.org)
Format: 1.8
Date: Thu, 07 Jul 2022 08:31:37 +0300
Source: dhcpcd5
Architecture: source
Version: 9.4.1-4
Distribution: unstable
Urgency: medium
Maintainer: Martin-Éric Racine <martin-eric.racine@iki.fi>
Changed-By: Martin-Éric Racine <martin-eric.racine@iki.fi>
Closes: 1014277
Changes:
 dhcpcd5 (9.4.1-4) unstable; urgency=medium
 .
   * [service]
     = Update pid paths in both systemd service units (Closes: #1014277).
Checksums-Sha1:
 453532e0b752b54104b070195f6279e0ce06a219 1866 dhcpcd5_9.4.1-4.dsc
 9fb93293ad75ba4794ebe8d8ccf9e7c6c9d568ee 14788 dhcpcd5_9.4.1-4.debian.tar.xz
 3c97388946bc93bb4b6d8372189d5a42d1e0037a 5510 dhcpcd5_9.4.1-4_source.buildinfo
Checksums-Sha256:
 9d3eabe0d89ce332d8dfca26160ff60096d8243aee9eca738a164f7dadfe9ba8 1866 dhcpcd5_9.4.1-4.dsc
 15ec4a381d7484a220ea3c94e6c9117a954056969337d3fd4faaf3cd02e8c89c 14788 dhcpcd5_9.4.1-4.debian.tar.xz
 22605c1b9a086ec2ff4a03741a63facf2e70b5ffbc07b39ade85902fa91fb2c7 5510 dhcpcd5_9.4.1-4_source.buildinfo
Files:
 a685396471385eabf13904b7403c2a7d 1866 net optional dhcpcd5_9.4.1-4.dsc
 a14e3762f6999b9748e39d499df716a1 14788 net optional dhcpcd5_9.4.1-4.debian.tar.xz
 82aa90d5207ceb0e554b797d44ae8ce6 5510 net optional dhcpcd5_9.4.1-4_source.buildinfo
-----BEGIN PGP SIGNATURE-----

iQHEBAEBCgAuFiEEQGIgyLhVKAI3jM5BH1x6i0VWQxQFAmLHMmQQHGJhZ2VAZGVi
aWFuLm9yZwAKCRAfXHqLRVZDFLUcC/0QRKMNcjXY5osY+QAeZMf2WLZzzpgQxDyX
GPXC+fUvh6yWmuLkZnK6I2FqaZdLcmYzgkgpFijsPnJeOF9EkO/6m39dxkxkrjPB
J8zgK5OS3nV1l6XBRmF2ZsYZjYhyDx6PD65QY3YhlzQAxEhB0/iqtzU5FbmJfUW7
z8KKzUyd6EIPIGVQ0kcdQ5ZSJjfJc05RntX3lbQsxfaRsguZLTpBMnpBjcAuyjKY
TDwfQr+NMTO8oqZzYrph7J3m+AJwZunVDMWj0zOFcjOzDlGr793tQW9F7p6KKFd8
+MSKJl+xhhys+0fBAc0n58jO3iVTBrc6lUczSGC+v+R8f1KdXyaHe5NS/gNiC3/D
/Ga+sENd5AnLiyE0FJEM0/3w9BSBE1Wj4K8+/ioVk9J+uvmNwRN/i8UWk4DKTzDZ
Wr2CGaKWeSqCLUD/F6EZ2G4wuKH1/uCt/5rNCFcJvautxv3BVXB6lk2l601Rj+uK
wlnay/QoO8bZJAako2FrrID7wKkr5OI=
=vwT1
-----END PGP SIGNATURE-----