dhcpcd 9.3.1 timing out on Arch Linux ARM
Adolf Belka
Fri Oct 30 12:10:02 2020
Hi,
I recently updated dhcpcd from 9.2.0 to 9.3.1 on my Raspberry Pi running
Arch Linux ARM. I use a static IP on this machine as I use it for a dhcp
server for my DMZ zone. dhcpcd timed out and the interface was left
disconnected.
As it is a headless machine I logged in locally with a keyboard and
screen and downgraded to 9.2.0 and everything worked again. Repeated and
the same happened.
Attached are the log files for 9.2.0 and for 9.3.1 together with the
systemd status output in both cases.
9.3.1 is working fine on my Arch Linux system, it's only on the ARM
version that I have the problem.
I have seen that other people have had some problems with 9.3.1 but I am
not knowledgeable enough to know if my problem is the same/similar as
theirs and if your patches would also work for me.
Let me know if I need to provide some more input or run further debugging.
Thanks,
Adolf
--
Sent from my netbook.
Oct 30 09:28:49 dione systemd[1]: Starting dhcpcd on eth0...
Oct 30 09:28:49 dione dhcpcd[425]: dhcpcd-9.2.0 starting
Oct 30 09:28:49 dione dhcpcd[427]: DUID 00:01:00:01:22:4b:94:65:b8:27:eb:2d:ce:93
Oct 30 09:28:50 dione dhcpcd[427]: eth0: waiting for carrier
Oct 30 09:28:50 dione dhcpcd[427]: eth0: carrier acquired
Oct 30 09:28:50 dione dhcpcd[427]: eth0: IAID eb:2d:ce:93
Oct 30 09:28:50 dione dhcpcd[427]: eth0: adding address fe80::c26d:2081:6dda:8bd0
Oct 30 09:28:50 dione dhcpcd[427]: eth0: probing address 192.168.128.20/24
Oct 30 09:28:50 dione dhcpcd[427]: eth0: soliciting an IPv6 router
Oct 30 09:28:51 dione dhcpcd[427]: eth0: carrier lost
Oct 30 09:28:51 dione dhcpcd[427]: eth0: deleting address fe80::c26d:2081:6dda:8bd0
Oct 30 09:28:52 dione dhcpcd[427]: eth0: carrier acquired
Oct 30 09:28:52 dione dhcpcd[427]: eth0: IAID eb:2d:ce:93
Oct 30 09:28:52 dione dhcpcd[427]: eth0: adding address fe80::c26d:2081:6dda:8bd0
Oct 30 09:28:52 dione dhcpcd[427]: eth0: probing address 192.168.128.20/24
Oct 30 09:28:52 dione dhcpcd[427]: eth0: soliciting an IPv6 router
Oct 30 09:28:58 dione dhcpcd[427]: eth0: using static address 192.168.128.20/24
Oct 30 09:28:58 dione dhcpcd[427]: eth0: adding route to 192.168.128.0/24
Oct 30 09:28:58 dione dhcpcd[427]: eth0: adding default route via 192.168.128.254
Oct 30 09:28:58 dione systemd[1]: Started dhcpcd on eth0.
Oct 30 09:28:58 dione audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd@eth0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Oct 30 09:28:58 dione kernel: audit: type=1130 audit(1604046538.532:105): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd@eth0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Oct 30 09:29:05 dione dhcpcd[427]: eth0: no IPv6 Routers available
Oct 30 09:29:24 dione dbus-daemon[270]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.14' (uid=0 pid=522 comm="sudo systemctl status dhcpcd@eth0.service ")
Oct 30 09:29:24 dione sudo[522]: ahb : TTY=tty1 ; PWD=/home/ahb ; USER=root ; COMMAND=/usr/bin/systemctl status dhcpcd@eth0.service
● dhcpcd@eth0.service - dhcpcd on eth0
Loaded: loaded (/usr/lib/systemd/system/dhcpcd@.service; enabled; vendor preset: disabled)
Active: active (running) since Fri 2020-10-30 09:28:58 CET; 8min ago
Process: 425 ExecStart=/usr/bin/dhcpcd -q -w eth0 (code=exited, status=0/SUCCESS)
Main PID: 427 (dhcpcd)
Tasks: 7 (limit: 2063)
CGroup: /system.slice/system-dhcpcd.slice/dhcpcd@eth0.service
├─427 dhcpcd: eth0 [ip4] [ip6]
├─428 dhcpcd: [privileged actioneer] eth0 [ip4] [ip6]
├─429 dhcpcd: [network proxy] eth0 [ip4] [ip6]
├─430 dhcpcd: [control proxy] eth0 [ip4] [ip6]
├─459 dhcpcd: [BPF ARP] eth0 192.168.128.20
├─460 dhcpcd: [network proxy] fe80::c26d:2081:6dda:8bd0
└─510 dhcpcd: [network proxy] 192.168.128.20
Oct 30 09:28:52 dione dhcpcd[427]: eth0: carrier acquired
Oct 30 09:28:52 dione dhcpcd[427]: eth0: IAID eb:2d:ce:93
Oct 30 09:28:52 dione dhcpcd[427]: eth0: adding address fe80::c26d:2081:6dda:8bd0
Oct 30 09:28:52 dione dhcpcd[427]: eth0: probing address 192.168.128.20/24
Oct 30 09:28:52 dione dhcpcd[427]: eth0: soliciting an IPv6 router
Oct 30 09:28:58 dione dhcpcd[427]: eth0: using static address 192.168.128.20/24
Oct 30 09:28:58 dione dhcpcd[427]: eth0: adding route to 192.168.128.0/24
Oct 30 09:28:58 dione dhcpcd[427]: eth0: adding default route via 192.168.128.254
Oct 30 09:28:58 dione systemd[1]: Started dhcpcd on eth0.
Oct 30 09:29:05 dione dhcpcd[427]: eth0: no IPv6 Routers available
Oct 30 09:17:27 dione systemd[1]: Starting dhcpcd on eth0...
Oct 30 09:17:27 dione dhcpcd[271]: dhcpcd-9.3.1 starting
Oct 30 09:17:27 dione audit[274]: SECCOMP auid=4294967295 uid=975 gid=975 ses=4294967295 pid=274 comm="dhcpcd" exe="/usr/bin/dhcpcd" sig=31 arch=40000028 syscall=291 compat=0 ip=0x76ecc748 code=0x0
Oct 30 09:17:27 dione audit[274]: ANOM_ABEND auid=4294967295 uid=975 gid=975 ses=4294967295 pid=274 comm="dhcpcd" exe="/usr/bin/dhcpcd" sig=31 res=1
Oct 30 09:17:27 dione dhcpcd[274]: th0 [ip4] [ip6][274]: DUID 00:01:00:01:22:4b:94:65:b8:27:eb:2d:ce:93
Oct 30 09:17:28 dione audit[277]: SECCOMP auid=4294967295 uid=975 gid=975 ses=4294967295 pid=277 comm="dhcpcd" exe="/usr/bin/dhcpcd" sig=31 arch=40000028 syscall=289 compat=0 ip=0x76ecc94c code=0x0
Oct 30 09:17:28 dione dhcpcd[271]: ps_ctl_listen: read: Success
Oct 30 09:17:28 dione kernel: audit: type=1326 audit(1604045848.602:28): auid=4294967295 uid=975 gid=975 ses=4294967295 pid=277 comm="dhcpcd" exe="/usr/bin/dhcpcd" sig=31 arch=40000028 syscall=289 compat=0 ip=0x76ecc94c code=0x0
Oct 30 09:17:28 dione audit[277]: ANOM_ABEND auid=4294967295 uid=975 gid=975 ses=4294967295 pid=277 comm="dhcpcd" exe="/usr/bin/dhcpcd" sig=31 res=1
Oct 30 09:17:28 dione kernel: audit: type=1701 audit(1604045848.602:29): auid=4294967295 uid=975 gid=975 ses=4294967295 pid=277 comm="dhcpcd" exe="/usr/bin/dhcpcd" sig=31 res=1
Oct 30 09:17:28 dione systemd-coredump[279]: Process 274 (dhcpcd) of user 975 dumped core.
Oct 30 09:17:30 dione systemd-coredump[281]: Process 277 (dhcpcd) of user 975 dumped core.
Oct 30 09:18:52 dione systemd[1]: Dependency failed for dhcpcd on etho.
Oct 30 09:18:52 dione systemd[1]: dhcpcd@etho.service: Job dhcpcd@etho.service/start failed with result 'dependency'.
Oct 30 09:18:57 dione systemd[1]: dhcpcd@eth0.service: start operation timed out. Terminating.
Oct 30 09:18:57 dione audit[271]: SECCOMP auid=4294967295 uid=975 gid=975 ses=4294967295 pid=271 comm="dhcpcd" exe="/usr/bin/dhcpcd" sig=31 arch=40000028 syscall=289 compat=0 ip=0x76ecc94c code=0x0
Oct 30 09:18:57 dione dhcpcd[271]: dhcpcd_signal_cb: write: Connection refused
Oct 30 09:18:57 dione audit[271]: ANOM_ABEND auid=4294967295 uid=975 gid=975 ses=4294967295 pid=271 comm="dhcpcd" exe="/usr/bin/dhcpcd" sig=31 res=1
Oct 30 09:18:57 dione kernel: audit: type=1326 audit(1604045937.732:33): auid=4294967295 uid=975 gid=975 ses=4294967295 pid=271 comm="dhcpcd" exe="/usr/bin/dhcpcd" sig=31 arch=40000028 syscall=289 compat=0 ip=0x76ecc94c code=0x0
Oct 30 09:18:57 dione kernel: audit: type=1701 audit(1604045937.732:34): auid=4294967295 uid=975 gid=975 ses=4294967295 pid=271 comm="dhcpcd" exe="/usr/bin/dhcpcd" sig=31 res=1
Oct 30 09:18:58 dione systemd[1]: dhcpcd@eth0.service: Control process exited, code=killed, status=31/SYS
Oct 30 09:18:58 dione systemd-coredump[291]: Process 271 (dhcpcd) of user 975 dumped core.
Oct 30 09:20:28 dione systemd[1]: dhcpcd@eth0.service: State 'final-sigterm' timed out. Killing.
Oct 30 09:20:28 dione systemd[1]: dhcpcd@eth0.service: Killing process 275 (dhcpcd) with signal SIGKILL.
Oct 30 09:20:28 dione systemd[1]: dhcpcd@eth0.service: Killing process 276 (dhcpcd) with signal SIGKILL.
Oct 30 09:20:28 dione systemd[1]: dhcpcd@eth0.service: Failed with result 'timeout'.
Oct 30 09:20:28 dione systemd[1]: dhcpcd@eth0.service: Unit process 276 (dhcpcd) remains running after unit stopped.
Oct 30 09:20:28 dione systemd[1]: Failed to start dhcpcd on eth0.
Oct 30 09:20:28 dione audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd@eth0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Oct 30 09:20:28 dione kernel: audit: type=1130 audit(1604046028.492:37): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd@eth0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Oct 30 09:22:19 dione dbus-daemon[270]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.9' (uid=0 pid=356 comm="sudo systemctl status dhcpcd@eth0.service ")
Oct 30 09:22:19 dione sudo[356]: ahb : TTY=tty1 ; PWD=/home/ahb ; USER=root ; COMMAND=/usr/bin/systemctl status dhcpcd@eth0.service
● dhcpcd@eth0.service - dhcpcd on eth0
Loaded: loaded (/usr/lib/systemd/system/dhcpcd@.service; enabled; vendor preset: disabled)
Active: failed (Result: timeout) since Fri 2020-10-30 09:20:28 CET; 6min ago
Process: 271 ExecStart=/usr/bin/dhcpcd -q -w eth0 (code=killed, signal=SYS)
Oct 30 09:17:28 dione dhcpcd[271]: ps_ctl_listen: read: Success
Oct 30 09:18:57 dione systemd[1]: dhcpcd@eth0.service: start operation timed out. Terminating.
Oct 30 09:18:57 dione dhcpcd[271]: dhcpcd_signal_cb: write: Connection refused
Oct 30 09:18:58 dione systemd[1]: dhcpcd@eth0.service: Control process exited, code=killed, status=31/SYS
Oct 30 09:20:28 dione systemd[1]: dhcpcd@eth0.service: State 'final-sigterm' timed out. Killing.
Oct 30 09:20:28 dione systemd[1]: dhcpcd@eth0.service: Killing process 275 (dhcpcd) with signal SIGKILL.
Oct 30 09:20:28 dione systemd[1]: dhcpcd@eth0.service: Killing process 276 (dhcpcd) with signal SIGKILL.
Oct 30 09:20:28 dione systemd[1]: dhcpcd@eth0.service: Failed with result 'timeout'.
Oct 30 09:20:28 dione systemd[1]: dhcpcd@eth0.service: Unit process 276 (dhcpcd) remains running after unit stopped.
Oct 30 09:20:28 dione systemd[1]: Failed to start dhcpcd on eth0.
Archive administrator: postmaster@marples.name