Arch Linux

Just to confirm that I am getting (pretty much?) the same.

Started happening with the upgrade to dhcpcd 9.0.1-2 and continues unchanged with dhcpcd 9.0.2-1.

About 3/4 of the time when shutting down I need to wait for the 90 second timeout. (Neither netctl nor networkmanager in use - forum posts have pointed to issues with these).

extract of journalctl -b-1 after slow shutdown:
Apr 26 02:04:52 helium dhcpcd[6452]: sending commands to dhcpcd process
Apr 26 02:04:52 helium dhcpcd[6452]: sending commands to dhcpcd process
Apr 26 02:04:52 helium dhcpcd[476]: control command: /usr/bin/dhcpcd -x en
Apr 26 02:04:52 helium dhcpcd[476]: en: removing interface
Apr 26 02:04:52 helium dhcpcd[477]: process 477 unexpectedly terminating on signal 15
Apr 26 02:06:22 helium systemd[1]: dhcpcd@en.service: State 'stop-sigterm' timed out. Killing.
Apr 26 02:06:22 helium systemd[1]: dhcpcd@en.service: Killing process 476 (dhcpcd) with signal SIGKILL.
Apr 26 02:06:22 helium systemd[1]: dhcpcd@en.service: Main process exited, code=killed, status=9/KILL
Apr 26 02:06:22 helium systemd[1]: dhcpcd@en.service: Failed with result 'timeout'.
Apr 26 02:06:22 helium systemd[1]: Stopped dhcpcd on en.

Yeah, just for the record, I don't use netctl or networkmanager or anything else like that either. Just plain "systemctl enable dhcpcd@en" (and it manages /etc/resolv.conf via openresolv).

(But I don't think it matters. The problem is in Arch's unit file, IIUC. Running "/usr/bin/dhcpcd -x en" manually stops the daemon cleanly. This command just doesn't do what systemd expects, so systemd randomly kills whatever processes are left in the cgroup.)

(- edit: Well, yes, it might matter if those other managers don't start the systemd unit ... Then it probably works for them.)

Same problem for me. Not using any manager.
See https://bbs.archlinux.org/viewtopic.php?id=254961

I can confirm this issue. I'm not sure yet why this is happening, but I suspect we'll have to rework the systemd unit files.

As @peter said sometimes its delaying the shutdown, my journals with and without delay:

My dhcpcd 9.0.2-1 on 5.4.36-1-lts, when shutting down and no delay (journalctl -b -1):
May 03 06:29:19 archz800 systemd[1]: Stopping dhcpcd on enp1s0...
May 03 06:29:19 archz800 systemd[1]: dbus.service: Succeeded.
May 03 06:29:19 archz800 systemd[1]: Stopped D-Bus System Message Bus.
May 03 06:29:19 archz800 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dbus comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 03 06:29:19 archz800 dhcpcd[2668]: sending commands to dhcpcd process
May 03 06:29:19 archz800 dhcpcd[2668]: sending commands to dhcpcd process
May 03 06:29:19 archz800 dhcpcd[712]: control command: /usr/bin/dhcpcd -x enp1s0
May 03 06:29:19 archz800 dhcpcd[712]: enp1s0: removing interface
May 03 06:29:19 archz800 dhcpcd[713]: process 713 unexpectedly terminating on signal 15
May 03 06:29:19 archz800 dhcpcd[712]: main: control_stop: Broken pipe
May 03 06:29:19 archz800 dhcpcd[712]: ps_dostop: Connection refused
May 03 06:29:19 archz800 dhcpcd[712]: ps_dostop: Broken pipe
May 03 06:29:19 archz800 dhcpcd[712]: dhcpcd exited
May 03 06:29:19 archz800 systemd[1]: dhcpcd@enp1s0.service: Main process exited, code=exited, status=1/FAILURE
May 03 06:29:19 archz800 systemd[1]: dhcpcd@enp1s0.service: Failed with result 'exit-code'.
May 03 06:29:19 archz800 systemd[1]: Stopped dhcpcd on enp1s0.


But when shutting down with delay (journalctl -b -2):
May 02 13:34:20 archz800 dhcpcd[40172]: sending commands to dhcpcd process
May 02 13:34:20 archz800 dhcpcd[40172]: sending commands to dhcpcd process
May 02 13:34:20 archz800 dhcpcd[701]: control command: /usr/bin/dhcpcd -x enp1s0
May 02 13:34:20 archz800 dhcpcd[701]: enp1s0: removing interface
May 02 13:34:20 archz800 dhcpcd[702]: process 702 unexpectedly terminating on signal 15
May 02 13:34:20 archz800 systemd[1]: systemd-logind.service: Succeeded.
May 02 13:34:20 archz800 systemd[1]: Stopped Login Service.
May 02 13:34:20 archz800 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-logind comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 02 13:35:50 archz800 systemd[1]: dhcpcd@enp1s0.service: State 'stop-sigterm' timed out. Killing.
May 02 13:35:50 archz800 systemd[1]: dhcpcd@enp1s0.service: Killing process 701 (dhcpcd) with signal SIGKILL.
May 02 13:35:50 archz800 systemd[1]: dhcpcd@enp1s0.service: Main process exited, code=killed, status=9/KILL
May 02 13:35:50 archz800 systemd[1]: dhcpcd@enp1s0.service: Failed with result 'timeout'.
May 02 13:35:50 archz800 systemd[1]: Stopped dhcpcd on enp1s0.
May 02 13:35:50 archz800 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd@enp1s0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
May 02 13:35:50 archz800 systemd[1]: Removed slice system-dhcpcd.slice.

Same here. No managers in use. Just a plain systemd service for the interface.

systemd 244.4
dhcpcd 9.0.2

Let me know if I can provide any useful information.

I can confirm this too.

I have the same problem on my system. Pure dhcpcd. problem disappears when I downgrade.
For me the problem is happening at every shutdown/reboot.

Here is the journalctl output via:-
journalctl -b -1 | grep dhcpcd

May 07 16:18:06 hyperion systemd[1]: Stopping dhcpcd on enp1s0...
May 07 16:18:06 hyperion dhcpcd[3763]: sending commands to dhcpcd process
May 07 16:18:06 hyperion dhcpcd[3763]: sending commands to dhcpcd process
May 07 16:18:06 hyperion dhcpcd[550]: control command: /usr/bin/dhcpcd -x enp1s0
May 07 16:18:06 hyperion dhcpcd[550]: enp1s0: removing interface
May 07 16:18:06 hyperion dhcpcd[551]: process 551 unexpectedly terminating on signal 15
May 07 16:19:36 hyperion systemd[1]: dhcpcd@enp1s0.service: State 'stop-sigterm' timed out. Killing.
May 07 16:19:36 hyperion systemd[1]: dhcpcd@enp1s0.service: Killing process 550 (dhcpcd) with signal SIGKILL.
May 07 16:19:36 hyperion systemd[1]: dhcpcd@enp1s0.service: Main process exited, code=killed, status=9/KILL
May 07 16:19:36 hyperion systemd[1]: dhcpcd@enp1s0.service: Failed with result 'timeout'.
May 07 16:19:36 hyperion systemd[1]: Stopped dhcpcd on enp1s0.
May 07 16:19:36 hyperion audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd@enp1s0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
May 07 16:19:36 hyperion systemd[1]: Removed slice system-dhcpcd.slice.
May 07 16:19:36 hyperion kernel: audit: type=1131 audit(1588861176.352:112): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd@enp1s0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
May 07 16:19:36 hyperion systemd[1]: Unmounting /var/lib/dhcpcd/dev...
May 07 16:19:36 hyperion systemd[1]: Unmounting /var/lib/dhcpcd/proc...
May 07 16:19:36 hyperion systemd[1]: Unmounting /var/lib/dhcpcd/run/systemd/journal...
May 07 16:19:36 hyperion systemd[1]: Unmounting /var/lib/dhcpcd/run/udev...
May 07 16:19:36 hyperion systemd[1]: Unmounting /var/lib/dhcpcd/sys/fs/fuse/connections...
May 07 16:19:36 hyperion systemd[1]: var-lib-dhcpcd-dev.mount: Succeeded.
May 07 16:19:36 hyperion systemd[1]: Unmounted /var/lib/dhcpcd/dev.

The key is the line 'process NNNNN unexpectedly terminating on signal 15' -- what happens is that the `ExecStop=` line executes `dhcpcd -x %I`, and then it is implied that the daemon has exited, and systemd starts to send the configured KillSignal (SIGTERM by default) according to KillMode (control-group by default) to any remaining processes in the cgroup, which dhcpcd does not like.

See ExecStop= in systemd.service(5) and KillMode in systemd.kill(5) manpages.

The fix is to add the line KillMode=none to the unit file, I tested this using a drop-in and dhcpcd@.service now exits cleanly.

Another way would be the attached patch: Replace the ExecStop= line with KillMode=process. This sends a SIGTERM to dhcpcd’s main process and then waits for it to exit. If I read dhcpcd’s source correctly, this main process will tell all its children to perform a shutdown, wait for them to die, and then exit itself. (I’m not 100% sure, though.)

I think this would be better than setting KillMode=none, because now the systemd unit is only considered as stopped when dhcpcd actually is stopped. With KillMode=none, the unit is considered stopped while some dhcpcd processes might still be hanging around (even if just for a brief moment).

We need to make sure this works for both unit files. I'm not a fan of using KillMode=none, because it might leave processes behind.

Just a confirmation note. I see this on all my Arch installs (both hardware and virtual guests).

There is a new release, 9.1.0 that's on [testing]. If you can test, it would be great.

The testing version seems to work fine, will report back if any issues arise.
Thanks.

I just tried the testing version and didn't have the shutdown problem but had a systemd-coredump problem on reboot.
This went away when I reverted to the stable version and came back again when I re-installed the testing version.

Here is the output from command
journalctl -b -1 | grep dhcpcd

Jun 01 12:04:39 hyperion systemd[1]: Starting dhcpcd on enp1s0...
Jun 01 12:04:39 hyperion dhcpcd[817]: dhcpcd-9.1.0 starting
Jun 01 12:04:39 hyperion dhcpcd[820]: ps_root_start: Address family not supported by protocol
Jun 01 12:04:39 hyperion audit[819]: ANOM_ABEND auid=4294967295 uid=0 gid=0 ses=4294967295 pid=819 comm="dhcpcd" exe="/usr/bin/dhcpcd" sig=11 res=1
Jun 01 12:04:39 hyperion dhcpcd[820]: ps_root_start: Address family not supported by protocol
Jun 01 12:04:39 hyperion dhcpcd[821]: ps_inet_startcb: ipv6nd_open: Address family not supported by protocol
Jun 01 12:04:39 hyperion dhcpcd[821]: ps_inet_startcb: ipv6nd_open: Address family not supported by protocol
Jun 01 12:04:39 hyperion dhcpcd[820]: ps_start: Address family not supported by protocol
Jun 01 12:04:39 hyperion dhcpcd[820]: ps_start: Address family not supported by protocol
Jun 01 12:04:39 hyperion kernel: dhcpcd[819]: segfault at 7ffd1ba799b0 ip 00005632225525fb sp 00007ffd1ba719b0 error 6 in dhcpcd[56322253f000+3b000]
Jun 01 12:04:39 hyperion kernel: audit: type=1701 audit(1591005879.805:90): auid=4294967295 uid=0 gid=0 ses=4294967295 pid=819 comm="dhcpcd" exe="/usr/bin/dhcpcd" sig=11 res=1
Jun 01 12:04:40 hyperion dhcpcd[817]: dhcpcd_fork_cb: truncated read 0 (expected 4)
Jun 01 12:04:40 hyperion dhcpcd[817]: dhcpcd_fork_cb: truncated read 0 (expected 4)
Jun 01 12:04:40 hyperion systemd[1]: dhcpcd@enp1s0.service: Control process exited, code=exited, status=1/FAILURE
Jun 01 12:04:40 hyperion systemd[1]: dhcpcd@enp1s0.service: Failed with result 'exit-code'.
Jun 01 12:04:40 hyperion systemd[1]: Failed to start dhcpcd on enp1s0.
Jun 01 12:04:40 hyperion audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd@enp1s0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Jun 01 12:04:40 hyperion kernel: audit: type=1130 audit(1591005880.045:94): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd@enp1s0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Jun 01 12:04:40 hyperion systemd-coredump[825]: Process 819 (dhcpcd) of user 0 dumped core.
#0 0x00005632225525fb dhcp_read_hwaddr_aton (dhcpcd + 0x1c5fb)
#1 0x000056322254517d duid_init (dhcpcd + 0xf17d)
#2 0x0000563222541f81 dhcpcd_initduid (dhcpcd + 0xbf81)
#3 0x00005632225402a4 main (dhcpcd + 0xa2a4)
#5 0x00005632225408fe _start (dhcpcd + 0xa8fe)

Yes, the original bug appears to be fixed with 9.1.0. Thank you!

Adolf's bug can be reproduced by disabling IPv6 via kernel parameter "ipv6.disable=1". Looks unrelated, though.

Yes, I do have ipv6.disable=1 set on my system but that has been there for a long time.

There was a problem previously with ipv6 being disabled when dhcpcd was upgraded from 8.1.7-1 to 9.0.1-2 but the systemd-coredump didn't occur.
That was fixed by the testing version 9.0.1-4. ( FS#66313 )

This bug hopefully can be fixed without introducing another problem if ipv6 is disabled.

@Adolf,

I suggest you rebuild the package with debug and without strip to see exactly where it fails. I'll try to reproduce as well. Perhaps you can send a bug report upstream as well.

I tested the inverse of P.H. by removing "ipv6.disable=1" from my kernel line and 9.1.0 started fine.
I will look at sending a bug report to upstream.

I built dhcpcd 9.1.0 with debug and without strip and following is the output I got.
Hopefully I did things right and got the info that is required as I have not done a lot of debugging before.

Here is the output of coredumpctl gdb "PID" after installing and running dhcpcd 9.1.0 under gdb.

sudo coredumpctl gdb 15759
PID: 15759 (dhcpcd)
UID: 0 (root)
GID: 0 (root)
Signal: 7 (BUS)
Timestamp: Mon 2020-06-01 15:53:15 CEST (1min 34s ago)
Command Line: dhcpcd: enp1s0 [ip4] [ip6]
Executable: /usr/bin/dhcpcd
Control Group: /user.slice/user-1000.slice/session-1.scope
Unit: session-1.scope
Slice: user-1000.slice
Session: 1
Owner UID: 1000 (ahb)
Boot ID: 2e8a1853c4314cd299865767f8d69c2a
Machine ID: 15f2b88bfb664c6e92d4b3d5a3f75a7a
Hostname: hyperion
Storage: /var/lib/systemd/coredump/core.dhcpcd.0.2e8a1853c4314cd299865767f8d69c2a.15759.1591019595000000000000.lz4
Message: Process 15759 (dhcpcd) of user 0 dumped core.

Stack trace of thread 15759:
#0 0x0000555555570e2b dhcp_read_hwaddr_aton (dhcpcd + 0x1ce2b)
#1 0x000055555556317d duid_get (dhcpcd + 0xf17d)
#2 0x000055555555ff81 dhcpcd_initduid (dhcpcd + 0xbf81)
#3 0x000055555555e2a4 main (dhcpcd + 0xa2a4)
#4 0x00007ffff7df6002 __libc_start_main (libc.so.6 + 0x27002)
#5 0x000055555555e8fe _start (dhcpcd + 0xa8fe)

GNU gdb (GDB) 9.2
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-pc-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/bin/dhcpcd...
[New LWP 15759]
Core was generated by `dhcpcd: enp1s0 [ip4] [ip6]'.
Program terminated with signal SIGBUS, Bus error.
#0 dhcp_read_hwaddr_aton (ctx=ctx@entry=0x7fffffffe6b0, data=data@entry=0x7fffffffe4d8,
file=file@entry=0x55555559a1c4 "/var/lib/dhcpcd/duid") at dhcp-common.c:1020
1020 dhcp-common.c: No such file or directory.



Then I got the following backtrace with bt full

(gdb) bt full
#0 dhcp_read_hwaddr_aton (ctx=ctx@entry=0x7fffffffe6b0, data=data@entry=0x7fffffffe4d8, file=file@entry=0x55555559a1c4 "/var/lib/dhcpcd/duid") at dhcp-common.c:1020
buf = '\000' <repeats 192 times>, "\061\065\067\065\071 (d"...
bytes = 32768
len = <optimized out>
#1 0x000055555556317d in duid_get (ifp=0x0, ctx=0x7fffffffe6b0) at duid.c:227
data = 0x7ffff7e59220 <_int_malloc+2544> "\351\r\367\377\377\017\037"
len = <optimized out>
slen = <optimized out>
line = "\260\346\377\377\377\177\000\000\000\000\000\000\000\000\000\000\002\000\000\000\000\000\000\000 \222\345\367\377\177\000\000@", '\000' <repeats 23 times>, "\a\000\000\000\000\000\000\000 \000\000\000\000\000\000\000\b\000\000\000\000\000\000\000\002\000\000\000\061\000\000\000\020\000\000\000\000\000\000\000@", '\000' <repeats 15 times>, "\002\000\000\000\060\000\000\000n\000\000\000|\000\000\000\000\000\000\000\000"
ifp2 = <optimized out>
data = <optimized out>
len = <optimized out>
slen = <optimized out>
line = <optimized out>
ifp2 = <optimized out>
__func__ = "duid_get"
#2 duid_init (ctx=0x7fffffffe6b0, ifp=0x0) at duid.c:227
No locals.
#3 0x000055555555ff81 in dhcpcd_initduid (ctx=0x7fffffffe6b0, ifp=<optimized out>) at dhcpcd.c:855
buf = "\260\346\377\377\377\177\000\000\345\261\345\367\377\177\000\000\000\000\000\000\000\000\000\000\260\346\377\377\377\177\000\000\r\000\000\000\000\000\000\000\374\345\377\377\377\177\000\000\260\346\377\377\377\177\000\000\226BWUUU\000\000\274\301\363n\f\000\000\000\001\000\000\000\020\000\000\000\375C7\217\000\000\000\000\000\346-O\236\253\071\326\330\353\377\377\377\177\000\000\260\346\377\377\377\177\000\000\260\033[UUU\000\000\004\000\000\000\000\000\000\000\330\353\377\377\377\177"
#4 0x000055555555e2a4 in main (argc=4, argv=0x7fffffffebd8) at dhcpcd.c:2277
ctx = {pidfile = "/run/dhcpcd/enp1s0.pid", '\000' <repeats 16 times>, vendor = '\000' <repeats 255 times>, fork_fd = 7, cffile = 0x555555599abd "/etc/dhcpcd.conf",
options = 310326623634741257, logfile = 0x0, argc = 4, argv = 0x7fffffffebd8, ifac = 0, ifav = 0x0, ifdc = 0, ifdv = 0x0, ifc = 1, ifv = 0x7fffffffebf0, ifcc = 0, ifcv = 0x0,
duid = 0x0, duid_len = 0, ifaces = 0x0, routes = {rbt_root = 0x0, rbt_ops = 0x5555555ad5e0 <rt_compare_os_ops>, rbt_minmax = {0x0, 0x0}}, froutes = {rbt_root = 0x0,
rbt_ops = 0x5555555ad580 <rt_compare_free_ops>, rbt_minmax = {0x0, 0x0}}, rt_order = 0, pf_inet_fd = 15, priv = 0x5555555cd960, link_fd = 13, link_rcvbuf = 0, seq = 0,
sseq = 0, sigset = {__val = {0 <repeats 16 times>}}, eloop = 0x5555555c4ea0, script = 0x5555555997a8 "/usr/lib/dhcpcd/dhcpcd-run-hooks", script_fp = 0x0, script_buf = 0x0,
script_buflen = 0, script_env = 0x0, script_envlen = 0, control_fd = 12, control_unpriv_fd = -1, control_fds = {tqh_first = 0x0, tqh_last = 0x7fffffffe988},
control_sock = "/run/dhcpcd/enp1s0.sock", '\000' <repeats 15 times>, control_group = 0, vivso = 0x0, vivso_len = 0, randomstate = 0x0, ps_user = 0x7ffff7f93340 <resbuf>,
ps_root_pid = 15760, ps_root_fd = 9, ps_data_fd = 6, ps_eloop = 0x5555555cd770, ps_processes = {tqh_first = 0x0, tqh_last = 0x7fffffffea00}, ps_inet_pid = 15761, ps_inet_fd = 10,
dhcp_opts = 0x5555555c22e0, dhcp_opts_len = 124, udp_rfd = -1, udp_wfd = -1, opt_buffer = 0x0, opt_buffer_len = 0, secret = 0x0, secret_len = 0, nd_fd = -1, ra_routers = 0x0,
nd_opts = 0x5555555b0580, nd_opts_len = 6, dhcp6_rfd = -1, dhcp6_wfd = -1, dhcp6_opts = 0x5555555cb9b0, dhcp6_opts_len = 79, dev_load = 0x0, dev_fd = -1, dev = 0x0,
dev_handle = 0x0}
ifaddrs = 0x0
ifo = 0x5555555b1bb0
ifp = <optimized out>
family = 0
opt = <optimized out>
oi = 0
i = 0
logopts = 2136192
t = <optimized out>
len = <optimized out>
pid = 0
sigpipe = {6, 7}
sig = <optimized out>
siga = 0x0
si = 1
__func__ = "main"

Someone else has already posted to upstream about it being broken again for an ipv4 only host and it is being worked on.
Will wait to see what comes from that.

Ok, thanks for your report. I'll keep this bug open a while longer until I move 9.1.0 out of [testing].

So Roy Marples has made a patch for this problem which I have tested and dhcpcd starts with ipv6 disabled in the kernel. Also confirmed fix by another person having the same problem.

He has also just fixed a critical bug with handling failed processes. There are a couple of other patches pending.
He expects that he will have a new dhcpcd release by the end of this week if not sooner.

Will keep an eye for it. But, since I've moved this out of testing, I'm closing this bug.