Bug#1014277: dhcpcd5: dhcpcd fails to chroot and set PID file on startup, systemd eventually kills it after timeout

Tobias Klausmann

unread,

Jul 3, 2022, 7:30:04 AM7/3/22

to

Package: dhcpcd5
Version: 9.4.1-3
Severity: important

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>

-- System Information:
Debian Release: bookworm/sid
APT prefers testing
APT policy: (500, 'testing')
Architecture: amd64 (x86_64)

Kernel: Linux 5.19.0-rc4 (SMP w/4 CPU threads; PREEMPT)
Locale: LANG=C.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages dhcpcd5 depends on:
ii dhcpcd-base 9.4.1-3
ii lsb-base 11.2

dhcpcd5 recommends no packages.

Versions of packages dhcpcd5 suggests:
pn dhcpcd-gtk <none>
pn openresolv | resolvconf <none>

-- Configuration Files:
/etc/dhcpcd.conf changed:
controlgroup sudo
duid
persistent
allowinterfaces wan1
option rapid_commit
vendorclassid
option interface_mtu
require dhcp_server_identifier
persistent
nohook lookup-hostname, resolv.conf, hostname, ntp, timezone
noipv4ll
noipv6rs
timeout 0
interface lan1
noipv4
interface wlan1
noipv4
interface wg0
noipv4
interface wan1
ipv6
ipv6rs
ia_pd 0 lan1/0/64 wlan1/1/64

-- no debconf information

Pásztor János

unread,

Jul 6, 2022, 7:40:03 AM7/6/22

to

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

Martin-Éric Racine

unread,

Jul 6, 2022, 4:40:04 PM7/6/22

to

Tobias,

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

Martin-Éric

Tobias Klausmann

unread,

Jul 6, 2022, 7:20:04 PM7/6/22

to

Hi!

On Wed, 06 Jul 2022, Martin-Éric Racine wrote:
> Does the fix suggested by János in response to your bug report restore
> normal operation?

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

--
printk(KERN_ERR "happy meal: Fry guys.");
linux-2.6.6/drivers/net/sunhme.c

Pásztor János

unread,

Jul 7, 2022, 3:50:03 AM7/7/22

to

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

Martin-Éric Racine

unread,

Jul 7, 2022, 7:10:03 AM7/7/22

to

On Thu, Jul 7, 2022 at 1:40 AM Tobias Klausmann
<klau...@schwarzvogel.de> wrote:
> On Wed, 06 Jul 2022, Martin-Éric Racine wrote:
> > Does the fix suggested by János in response to your bug report restore
> > normal operation?
>
> 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.

Thanks. PID paths fixed in 9.4.1-4 currently in Git. Pending upload.

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

Martin-Éric